サービス運用に必要なサーバログの設定概要の一例。
ログの出力対象を考える
ここでは下記を対象とする。サービスの初期段階ではログを多めに出しておいて、安定稼働の実績が出来次第ログを減らす方針でいく。
- 受信したHTTP Request
- リクエストheader(user-agent, x-forwarded-for)
- リクエストbody(controllerの引数のみ)
- 返答したHTTPレスポンス
- レスポンスタイム
- レスポンスbody(JSONの場合)
- vmの情報(process数)
- サーバ内での予期しない例外
各ログ出力には、下記の情報を付加させる
- ユーザーID
- そのログ出力が、どのユーザーのHTTPリクエストによって発生したのかがわかるようにする
- リクエストID
- そのログ出力が、どのHTTPリクエストによって発生したのかがわかるようにする
各ログ出力を設定する
リクエストheader(user-agent, x-forwarded-for), レスポンスタイム, レスポンスbody(JSONの場合)の出力
デフォルトのPlug.Loggerの代わりになるPlugを作成し、EndPointに設定する。
https://github.com/ndruger/hello_phoenix/blob/logger/web/plugs/logger.ex
https://github.com/ndruger/hello_phoenix/blob/logger/lib/hello_phoenix/endpoint.ex#L23
Plugは、Railsのafter_actionなどのように外部からコントローラーのアクションの後の処理を設定することはできない(以前はPhoenixでできたができなくなった。参考: [phoenix][elixir] Phoenixのログ周りの調査 - 最高のコンピューティング環境とは？)。
そのため、Plug内でレスポンス時のログを出力する場合、register_before_send()を使ってコールバックで行う。
必要なリクエストheaderはレスポンス時にレスポンスタイムと合わせて出力させる。なぜなら、後でログの集計などをする時に1行にまとまっていた方が扱いやすいため。
レスポンスタイムの単位も合わせておく。
ログが最大長で切られることを考慮して、切られてもいいresp_bodyを最後にする。
リクエストbody(controllerの引数のみ)の出力
dev環境ではcontrollerの引数などのログはdebugレベルでログ出力される。prdはデフォルトでinfo以上がログ出力されるのでdebugレベルは出力されない。
controllerのログ出力レベルをinfoに変更する。
https://github.com/ndruger/hello_phoenix/blob/logger/web/web.ex#L27
サーバ内での予期しない例外の出力
Phoenixはcatchされなかった例外をerrorレベルで下記のようにログ出力するので特別な修正は必要ない。ただし、td-agentでログを処理する時、multilineでのパースが必要なことに注意する。
2016-01-03 03:20:22.808 [error] #PID<0.327.0> running HelloPhoenix.Endpoint terminated
Server: localhost:3000 (http)
Request: GET /api/v1/books
** (exit) an exception was raised:
** (RuntimeError) test_error
(hello_phoenix) web/controllers/books_controller.ex:10: HelloPhoenix.BooksController.index/2
(hello_phoenix) web/controllers/books_controller.ex:1: HelloPhoenix.BooksController.action/2
(hello_phoenix) web/controllers/books_controller.ex:1: HelloPhoenix.BooksController.phoenix_controller_pipeline/2
(hello_phoenix) lib/phoenix/router.ex:261: HelloPhoenix.Router.dispatch/2
(hello_phoenix) web/router.ex:1: HelloPhoenix.Router.do_call/2
(hello_phoenix) lib/hello_phoenix/endpoint.ex:1: HelloPhoenix.Endpoint.phoenix_pipeline/1
(hello_phoenix) lib/plug/debugger.ex:92: HelloPhoenix.Endpoint."call (overridable 3)"/2
(hello_phoenix) lib/phoenix/endpoint/render_errors.ex:34: HelloPhoenix.Endpoint.call/2
このような予期せぬ例外は発生を開発者に通知したい。
Railsならばsmartinez87/exception_notificationを使うがPhoenixに相当するものがないので、fluentdにログを流すのならば、fluentdのmail pluginでするのがよさそう。
vmの情報(process数)の出力
1分毎にprocess数を出力する。一定数を超えた場合、processリークが発生していると判断してエラーログを出力する。
- Workerを作成する
- supervisorの設定＆start_linkの呼び出す
もっとがっつりvmの情報をログに出しておきたい場合、boundary/folsomで情報を取得して出力する。
リクエストIDとユーザーIDを付加する
request_idに関しては、Phoenixのデフォルトのprod.exsにて設定がされている(Plug.RequestIdとconfig.exsを参照。デフォルトだとdev.exsでLogger設定が上書きされていることに注意する)。
ユーザーIDに関して、request_idと同じく、Loggerのmetadataに設定することで、そのリクエスト(正確にはprocess)内でログ出力した場合に、自動的にユーザーIDを付加させることができる。
注意: processの再利用？
このrequest_id等はprocess dictionary(Process)に保存されており、そのため、同じprocessからログ出力をするときに、Loggerがそこから読み込んでログに付加している。
しかし、試した限り、Phoenixでは特定のリクエストのprocess dictionaryに入れた値が、その後の別のリクエストのprocess dictionaryから取得できてしまった。
Phoenixはprocessを再利用しているのかもしれない。
そのため、Logger.metadata()に特定のkeyで設定する場合、すべてのリクエストに関して、それを利用する場所の前で、必ず設定もしくは初期化をする必要が有る。
こちらもPlug( https://github.com/ndruger/hello_phoenix/blob/logger/web/plugs/user_logger.ex )で実装する。
- ログイン時にsessionにuser_idを入れる(このソースはダミーのログインコントローラー)
- endpointにて、すべてのログ出力の前の段階でLoggerのmetadataをクリアする(process再利用時の考慮)
- endpointにて、sessionからuser_idを取り出してLoggerのmetadataに設定する
-
https://github.com/ndruger/hello_phoenix/blob/logger/lib/hello_phoenix/endpoint.ex#L39
- Plug.Sessonの前だとまだcookieが使えないのでその後に呼び出す
- config.exsにて、user_idをLoggerのmetadataとして出力する対象に設定する
日付を追加する
デフォルトだと$timeのみなので$dateを追加する。必要ならutc_logも設定する。
https://github.com/ndruger/hello_phoenix/blob/logger/config/config.exs#L18
特定の情報をフィルタする
filter_parametersを利用する。
https://github.com/ndruger/hello_phoenix/blob/logger/config/config.exs#L8
最大長を設定する
loggerのtruncateで設定できる。デフォルトは8149byte(Logger – Logger v1.3.0-dev)。
https://github.com/ndruger/hello_phoenix/blob/logger/config/config.exs#L22
ログをファイル出力する
デフォルトだとリリースパッケージでログ出力すると"rel/<プロジェクト名>/log/erlang.log.<1〜5>"にログが出力される。
このログ周りの挙動は下記を読むと理解できるが、正直使いづらいので別の方法を考える必要が有る。
http://www.erlang.org/doc/man/run_erl.html
Erlangの場合はLogライブラリとしてLagerが有名で、khia/exlagerというElixir用のラッパーもあるようだが、今回はonkel-dirtus/logger_file_backendを利用する。
logger_file_backendは名前の通りログをファイルに書き出してくれる。
特徴として、書き込む時にログファイルのパスとinode番号をチェックして、異なっていたら再度ファイルを生成する挙動になっている。
この挙動のため、書き込み時のコストは少し高くなるが、別のプログラムがログローテーションのためにログファイルをrenameしても問題が起きないようになっている。
- mix.exsへ追加する
- prodのみファイルに書き出したいのでprod.exsに設定を追加する
後はlogrotateでログローテーションして、fluentdで収集してAWS S3にでも保存すればいい。
レスポンスのログはBigQueryにも流しておくとWebAPIごとのリクエスト数などを保存したクエリで簡単に確認できるようになる。
通常サーバは冗長化のため複数存在するため、複数のサーバのログを見る場合、brockgr/csshxなどを利用する。ただ、この方法だとサーバが12台を超えるときびしくなってくるので、その場合はリモートサーバのログ確認用のスクリプトを作成する。
コードにログ出力を追加してない場所をトレースする
prod環境でのみ起こる問題が発生し、コードの修正なしで、特定の関数のトレースログを見たくなった時には、ferd/reconが使える。
mixにreconを追加する。
https://github.com/ndruger/hello_phoenix/blob/logger/mix.exs#L47
reconでトレースをしてみる。
> rel/hello_phoenix/bin/hello_phoenix remote_console # リモートコンソールでアタッチ
...
iex(hello_phoenix@127.0.0.1)1> :recon_trace.calls({HelloPhoenix.BooksController, :index, :_}, 50) # "HelloPhoenix.BooksController"モジュールの、index関数を、最大50メッセージまで、トレースする
1 # 見つかった関数の数が返る
# リクエストで対象の関数が呼ばれると、下記のように引数などが全て含まれた形でトレースが出力される
15:24:08.025413 <0.316.0> 'Elixir.HelloPhoenix.BooksController':index(#{'__struct__' => 'Elixir.Plug.Conn',
adapter => {'Elixir.Plug.Adapters.Cowboy.Conn',{http_req,#Port<0.5333>,ranch_tcp,
keepalive,<0.316.0>,<<"GET">>,
'HTTP/1.1',
{{127,0,0,1},50405},
<<"localhost">>,undefined,
3000,<<"/api/v1/books">>,
undefined,<<>>,undefined,[],
[{<<"host">>,
<<"localhost:3000">>},
...
iex(hello_phoenix@127.0.0.1)2>:recon_trace.clear # 不要になったらトレースをはずす