Phoenix でエラーログをファイルに出力したりメールで送信したりする

エラーログのハンドリングはサービスを運用する上で欠かせません。
今回は Elixir の Logger を使って、ログのファイル出力とメール送信をやってみます。

Phoenix アプリケーションでの外部 API リクエストについては[コチラ](http://qiita.com/mserizawa/items/3ac483aca4f2926fa1a9)を参照してください。

# 事前知識: Elixir の Logger について

Elixir Logger - http://elixir-lang.org/docs/v1.0/logger/Logger.html

Elixir には標準でロギングライブラリが組み込まれています。
一般的なロギングと同様に、`:debug` `:info` `:warn` `:error` という出力レベルの分類（ちょっと少ない？）があったり、出力フォーマットのカスタマイズが可能です。

ただし、標準ままではコンソールへの出力しかサポートしていなくて、それ以上のことをする場合は各自で実装してね、というスタンスのようです。

なぜコンソール出力だけなのか...という気持ちをグッと抑えつつ、まずはファイル出力から作ってみましょう。

# Phoenix アプリケーションをセットアップする

`logging_sample` というアプリケーションを作ります。
ファイル出力に関しては（さすがに）[ライブラリがありました](https://github.com/onkel-dirtus/logger_file_backend)ので、mix.exs に以下のように追記してありがたく利用させていただきましょう。

```bash
$ mix phoenix.new logging_sample
```

```ex:mix.exs
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
```

ライブラリのダウンロードをして完了です。

```bash
$ mix deps.get
```

# ファイル出力の設定をする

Logger の設定は `config/config.exs` に書かれています。
ファイル出力をするにあたり、以下のように修正を加えます。

```ex: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 を発動させてみましょう。

```ex:router.ex
defmodule LoggingSample.Router do
  ...
  scope "/logging", LoggingSample do
    pipe_through :api

    get "/error", PageController, :do_error
  end
  ...
end
```

```ex:page_controller.ex
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 がログファイルに出力されるようにしてみました。
早速試してみましょう。

```bash
$ curl "localhost:4000/logging/error?message=helloworld"
```

```text:log/error.log
00:28:08.762 request_id=ccs8d79s6u5hf3h728436m28n8ppp8j6 [error] helloworld
```

想定通りに出力されました。
ちなみに、`$ curl "localhost:4000/logging/error` でガチのエラーメッセージが出力されます。

# メール送信の設定をする

次はメール送信です。
今回は SMTP を使ってメールを送信してみます。
[mailer](https://github.com/antp/mailer) というライブラリでシンプルにメールが送れそうなので、これを使ってみます。

まずは `mix.exs` に追記しましょう。

```ex: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 の設定を追記します。

```ex:config.exs
...
# Configures Mailer
config :mailer,
  # templates ディレクトリの指定
  templates: "priv/templates"

config :mailer, :smtp_client, # smtp クライアントの設定
  transport: :smtp,
  # サーバ名
  server: "localhost",
  # ポート番号
  port: 4040,
  # ユーザ名
  username: "hoge",
  # パスワード
  password: "piyo"
...
```

ちなみに、今回は [FakeSMTP](https://nilhcem.github.io/FakeSMTP/) というソフトウェアを使って擬似的な SMTP サーバをローカルに立てていて、そのポートの指定を 4040 にしてあります。リアルな SMTP サーバがある場合は、そちらの設定をしていただいて問題ありません。

`templates` というのは mailer がメールの文面を生成する際に使うテンプレートファイルを保管しておくディレクトリです。
今回は簡易的なプレーンテキストのみを送信してみますので、`priv/templates/plain` というディレクトリを作り、その中に `plain.txt` というファイルを下記の内容で作りましょう。

```bash
$ 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` というファイルを作り、以下のように実装しましょう。

```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` のことです

```ex:config.exs
...
config :logger,
  backends: [{LoggerFileBackend, :error_log}]
...
```

この `name` をもとに、設定を構築して返却します。ここで構築した設定は Logger が発動するたびに送られてきます。
実際に設定を構築する `configure/2` では、`Application.get_env/3` で `config.exs` の内容を読み込み、キーワードから必要な情報を取り出して、マップに詰めて返却しています。
この実装では、`config.exs` に以下のように書かれることを想定しています。

```ex: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` に以下のように追記します。

```ex: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` にリクエストしてみましょう。今度はログファイルへの出力に加えて、メールも送信されるハズです。

```bash
$ curl "localhost:4000/logging/error?message=helloworld"
```

![スクリーンショット 2015-09-17 2.02.11.png](https://qiita-image-store.s3.amazonaws.com/0/77513/691043ea-d71d-e6fb-410f-136b78b68fb2.png)

メールが来ました！

ちなみに、`logger_email_backend.ex` のメール送信処理手前にスリープ `:timer.sleep(5000)` を入れてみると分かるのですが、Backend は別プロセスで処理されていて、リクエスト自体は Backend の処理を待たずに完了するようです。さすがプロセス指向。

# 感想

* Backend をカスタマイズできるのは良いかも。例えば Slack へ通知とか、そういったこともできそう
* mailer は HTML メールや i18n にも対応しているので、結構凝ったことができそう
* 設定ファイルのデータを読み込む処理は覚えておいて損はしないはず
* logger_email_backend、もっとちゃんと作って Hex にあげてみようかな...
* スタックトレースを出力するようなサンプルの方が良かった気がする