エラーログのハンドリングはサービスを運用する上で欠かせません。
今回は Elixir の Logger を使って、ログのファイル出力とメール送信をやってみます。
Phoenix アプリケーションでの外部 API リクエストについてはコチラを参照してください。
事前知識: Elixir の Logger について
Elixir Logger - http://elixir-lang.org/docs/v1.0/logger/Logger.html
Elixir には標準でロギングライブラリが組み込まれています。
一般的なロギングと同様に、:debug :info :warn :error という出力レベルの分類（ちょっと少ない？）があったり、出力フォーマットのカスタマイズが可能です。
ただし、標準ままではコンソールへの出力しかサポートしていなくて、それ以上のことをする場合は各自で実装してね、というスタンスのようです。
なぜコンソール出力だけなのか...という気持ちをグッと抑えつつ、まずはファイル出力から作ってみましょう。
Phoenix アプリケーションをセットアップする
logging_sample というアプリケーションを作ります。
ファイル出力に関しては（さすがに）ライブラリがありましたので、mix.exs に以下のように追記してありがたく利用させていただきましょう。
$ mix phoenix.new logging_sample
defmodule LoggingSample.Mixfile do
...
def application do
[mod: {LoggingSample, []},
applications: [:phoenix, :phoenix_html, :cowboy, :logger,
:phoenix_ecto, :postgrex,
# logger_file_backend を追記
:logger_file_backend]]
end
...
defp deps do
[{:phoenix, "~> 0.17"},
{:phoenix_ecto, "~> 1.1"},
{:postgrex, ">= 0.0.0"},
{:phoenix_html, "~> 2.1"},
{:phoenix_live_reload, "~> 1.0", only: :dev},
{:cowboy, "~> 1.0"},
# logger_file_backend を追記
{:logger_file_backend, "~> 0.0.4"}]
end
end
ライブラリのダウンロードをして完了です。
$ mix deps.get
ファイル出力の設定をする
Logger の設定は config/config.exs に書かれています。
ファイル出力をするにあたり、以下のように修正を加えます。
...
# Configures Elixir's Logger
# 古い設定は一旦コメントアウトします
# config :logger, :console,
# format: "$time $metadata[$level] $message\n",
# metadata: [:request_id]
config :logger,
# :error_log というキーに対して、LoggerFileBackend を紐付けます
backends: [{LoggerFileBackend, :error_log}]
# :error_log の設定
config :logger, :error_log,
# ログの保存先, ファイル名
path: "log/error.log",
# 対象とするレベル
level: :error,
# ログフォーマット
format: "$time $metadata[$level] $message\n",
# メタデータの要素
metadata: [:request_id]
...
config :logger というのが2箇所出てきて、パッと見違和感があるかもしれません。
1つ目は、Logger に対してバックエンドに LoggerFileBackend を読み込みように指定しています。backends: の指定が Array になっているのがミソで、例えば、「エラーの場合はこっち、デバッグの場合はこっち」と言ったような設定ができるようになっています。
2つ目は、1つ目で指定したキー（:error_log）の具体的な設定内容となっています。
:path については、指定したディレクトリ・ファイルが存在しない場合は自動で生成されるようになっています。ログローテーションも一安心でしょうか。また、相対パス・絶対パスの両方に対応しています。相対パスの場合は Phoenix アプリケーションのルートディレクトリが起点となります。
以上の設定で、エラーレベルのログがファイルに出力されるようになります。
ファイル出力を試してみる
適当にルートを作って Logger を発動させてみましょう。
defmodule LoggingSample.Router do
...
scope "/logging", LoggingSample do
pipe_through :api
get "/error", PageController, :do_error
end
...
end
defmodule LoggingSample.PageController do
use LoggingSample.Web, :controller
# 以下を忘れずに追記します
require Logger
...
def do_error(conn, %{"message" => message}) do
Logger.error message
json conn, nil
end
end
/logging/error?message=xxxx で xxxx がログファイルに出力されるようにしてみました。
早速試してみましょう。
$ curl "localhost:4000/logging/error?message=helloworld"
00:28:08.762 request_id=ccs8d79s6u5hf3h728436m28n8ppp8j6 [error] helloworld
想定通りに出力されました。
ちなみに、$ curl "localhost:4000/logging/error でガチのエラーメッセージが出力されます。
メール送信の設定をする
次はメール送信です。
今回は SMTP を使ってメールを送信してみます。
mailer というライブラリでシンプルにメールが送れそうなので、これを使ってみます。
まずは mix.exs に追記しましょう。
defmodule LoggingSample.Mixfile do
...
def application do
[mod: {LoggingSample, []},
applications: [:phoenix, :phoenix_html, :cowboy, :logger,
:phoenix_ecto, :postgrex, :logger_file_backend,
# tzdata を追記
:tzdata]]
end
...
defp deps do
[{:phoenix, "~> 0.17"},
{:phoenix_ecto, "~> 1.1"},
{:postgrex, ">= 0.0.0"},
{:phoenix_html, "~> 2.1"},
{:phoenix_live_reload, "~> 1.0", only: :dev},
{:cowboy, "~> 1.0"},
{:logger_file_backend, "~> 0.0.4"},
# mailer を追記
{:mailer, github: "antp/mailer"}]
end
end
mailer ですが、現状だとちょっとした罠があるようでして、まず、Download 先は GitHub を指定しないとダメです。一応 Hex にも登録されていたのですが、それだとうまくコンパイルできませんでした。
あと、applications に tzdata を追記する必要があります。これは mailer の内部で日付を扱う際に使われているものなのですが、きちんと動作させるためには親元の applications にも追記が必須のようです。
次に、config.exs に mailer の設定を追記します。
...
# Configures Mailer
config :mailer,
# templates ディレクトリの指定
templates: "priv/templates"
config :mailer, :smtp_client, # smtp クライアントの設定
transport: :smtp,
# サーバ名
server: "localhost",
# ポート番号
port: 4040,
# ユーザ名
username: "hoge",
# パスワード
password: "piyo"
...
ちなみに、今回は FakeSMTP というソフトウェアを使って擬似的な SMTP サーバをローカルに立てていて、そのポートの指定を 4040 にしてあります。リアルな SMTP サーバがある場合は、そちらの設定をしていただいて問題ありません。
templates というのは mailer がメールの文面を生成する際に使うテンプレートファイルを保管しておくディレクトリです。
今回は簡易的なプレーンテキストのみを送信してみますので、priv/templates/plain というディレクトリを作り、その中に plain.txt というファイルを下記の内容で作りましょう。
$ mkdir -p priv/templates/plain
$ echo "<%= @message %>" > priv/templates/plain/plain.txt
この template 機能、予想以上にきめ細やかな指定ができますので、よろしければ mailer のドキュメントをご参照ください。
メール送信 Backend を実装する
さて、いよいよ Backend の実装です。
logger_file_backend を参考にしつつ、最小限の構成でやってみます。
lib/logging_sample 配下に logger_email_backend.ex というファイルを作り、以下のように実装しましょう。
defmodule LoggerSample.LoggerEmailBackend do
use GenEvent
# 初期化処理
def init({__MODULE__, name}) do
{:ok, configure(name, [])}
end
# Logger 発動時の処理
def handle_event({level, _gl, {Logger, msg, _ts, _md}}, %{level: min_level, from: from, to: to, title: title} = state) do
# 設定されている発動レベルに達しているかどうかを確認
if is_nil(min_level) or Logger.compare_levels(level, min_level) != :lt do
# Email 情報を構成
email = Mailer.compose_email(from, to, title, "plain", [message: msg])
# メール送信
Mailer.send(email)
{:ok, state}
else
{:ok, state}
end
end
# helper
# 設定の読み込み
defp configure(name, opts) do
env = Application.get_env(:logger, name, [])
opts = Keyword.merge(env, opts)
Application.put_env(:logger, name, opts)
# config.exs に書かれている内容を読み込みます
level = Keyword.get(opts, :level)
from = Keyword.get(opts, :from)
to = Keyword.get(opts, :to)
title = Keyword.get(opts, :title)
%{level: level, from: from, to: to, title: title}
end
end
削りに削って、ここまで短くできました。
とりあえずは LoggerBackend 実装の雰囲気がつかめればと思います。
まず、アプリケーション起動時に init/1 が呼ばれます。
ここで送られくる name とは、下記 config.exs でいう :error_log のことです
...
config :logger,
backends: [{LoggerFileBackend, :error_log}]
...
この name をもとに、設定を構築して返却します。ここで構築した設定は Logger が発動するたびに送られてきます。
実際に設定を構築する configure/2 では、Application.get_env/3 で config.exs の内容を読み込み、キーワードから必要な情報を取り出して、マップに詰めて返却しています。
この実装では、config.exs に以下のように書かれることを想定しています。
...
config :logger, :ham_spam_egg,
from: "xxx@example.com",
to: "xxx@example.com",
title: "this is title",
level: :error
...
この場合、name に相当するのは :ham_spam_egg です。
これと照らし合わせると、それとなく実装内容も理解できますね。
Logger が発動した時に呼ばれるのが handle_event/2 です。
なにやら引数が大量にありますが、今回はほとんど使いません。ちなみに、Elixir では使わない引数に対してはアンダースコア _ を頭につけることで、コンパイル時の警告が出ないようになります。
if 文ではレベルの比較を行い、指定されたレベルよりも低いものについては処理しないようにします。Logger.compare_levels/2 という便利関数が用意されていますので、これを使いましょう。
if 文の中は Email 送信処理のみです。mailer の仕様に則って mail オブジェクトの作成をするのですが、この時指定する「送信元メールアドレス」「送信先メールアドレス」「メールタイトル」は設定ファイルに書かれたもの、「本文」は送信されてきた文字列にしています。
本文の内容はキーワードリストの形式で渡して、先ほど作成したテンプレートにレンダリングさせます。
本来であれば Logger.Formatter を使って、リクエストパスや時刻といった情報も整形して出力すべきなのですが...今回は割愛させていただきます。
最後に Mailer.send/1 を呼び出して、メールを送信します。
Logger に設定を追加する
では、実装した LoggerEmailBackend を Logger に読み込ませてみましょう。
config.exs に以下のように追記します。
...
# Configures Elixir's Logger
#config :logger, :console,
# format: "$time $metadata[$level] $message\n",
# metadata: [:request_id]
config :logger,
backends: [{LoggerFileBackend, :error_log},
# LoggerSampleLoggerEmailBackend を読み込ませます
{LoggerSample.LoggerEmailBackend, :error_mail}]
config :logger, :error_log,
...
# LoggerEmailBackend の設定を追記します
config :logger, :error_mail,
from: "from@example.com",
to: "to@example.com",
title: "Logging Error Email Test",
# ログレベルは :error
level: :error
# Configures Mailer
...
以上で実装は完了です。
メール送信を試してみる
もう一度 /logging/error?message=helloworld にリクエストしてみましょう。今度はログファイルへの出力に加えて、メールも送信されるハズです。
$ curl "localhost:4000/logging/error?message=helloworld"
メールが来ました！
ちなみに、logger_email_backend.ex のメール送信処理手前にスリープ :timer.sleep(5000) を入れてみると分かるのですが、Backend は別プロセスで処理されていて、リクエスト自体は Backend の処理を待たずに完了するようです。さすがプロセス指向。
感想
- Backend をカスタマイズできるのは良いかも。例えば Slack へ通知とか、そういったこともできそう
- mailer は HTML メールや i18n にも対応しているので、結構凝ったことができそう
- 設定ファイルのデータを読み込む処理は覚えておいて損はしないはず
- logger_email_backend、もっとちゃんと作って Hex にあげてみようかな...
- スタックトレースを出力するようなサンプルの方が良かった気がする