PlayFramework(Scala)における構造化ロギングとトレーシング

こんにちは！こんにちは！
こちらは FOLIO Advent Calendar 2024 9日目の記事です。
この記事では、PlayFrameworkでの構造化ロギングとトレーシングについて検証を行いましたので実例を交えて紹介します。

　前提条件

PlayFramework 3.0.5
Scala 3.3.3

サンプルプロジェクトはこちらです。
https://github.com/stoneream/play-logging-sandbox

構造化ロギングって何？

アプリケーションのログは単純なテキストで出力されていることがままあるかと思います。
以下はアクセスログの出力例です。(commit)

INFO  f.AccessLog - Request: POST /widgets
INFO  f.AccessLog - Response: POST /widgets (400)
INFO  f.AccessLog - Request: GET /assets/stylesheets/main.css
INFO  f.AccessLog - Request: GET /assets/javascripts/hello.js
INFO  f.AccessLog - Response: GET /assets/stylesheets/main.css (304)
INFO  f.AccessLog - Response: GET /assets/javascripts/hello.js (304)
INFO  f.AccessLog - Request: POST /widgets
INFO  f.AccessLog - Response: POST /widgets (303)
INFO  f.AccessLog - Request: GET /widgets
INFO  f.AccessLog - Response: GET /widgets (200)
...

これはこれで人の目にはわかりやすいのですが、いくつか課題があります。
ここ最近はDatadogやElasticsearchなどにログを集め、可視化や分析することが一般的になってきています。そうした中でフリーフォーマットのログから目的の情報を抽出するために、何らかの形に変換したりパーサーや正規表現を記述することがあります。
ですが、ログを出力する段階でJSONのような構造化された形式にしておくと変換が用意で扱いやすいよね、というのが構造化ロギングです。

構造化ログが必要な理由 | New Relic

Scalaで構造化ロギングをやりたい！

JavaやScalaのロギングライブラリとして広く使われている Logback の場合、 logstash-logback-encoder を組み合わせることで簡単にJSON形式でログを出力することができます。

導入方法についてはリポジトリもしくはこちらの記事で詳しく解説されています。

以下は、logstash-logback-encoderを使ってログをJSON形式で出力した例です。(commit)
ログがJSON形式で各項目がフィールドに分かれていることがわかります。

{"@timestamp":"2024-11-07T22:55:43.195563898+09:00","@version":"1","message":"Slf4jLogger started","logger_name":"org.apache.pekko.event.slf4j.Slf4jLogger","thread_name":"application-pekko.actor.default-dispatcher-5","level":"INFO","level_value":20000}
{"@timestamp":"2024-11-07T22:55:43.249130565+09:00","@version":"1","message":"Application started (Dev) (no global state)","logger_name":"play.api.Play","thread_name":"play-dev-mode-pekko.actor.default-dispatcher-8","level":"INFO","level_value":20000}
{"@timestamp":"2024-11-07T22:55:43.293556771+09:00","@version":"1","message":"Request: GET /widgets","logger_name":"filters.AccessLog","thread_name":"application-pekko.actor.default-dispatcher-5","level":"INFO","level_value":20000}
{"@timestamp":"2024-11-07T22:55:43.382018947+09:00","@version":"1","message":"Response: GET /widgets (200)","logger_name":"filters.AccessLog","thread_name":"application-pekko.actor.default-dispatcher-8","level":"INFO","level_value":20000}
{"@timestamp":"2024-11-07T22:55:43.426615795+09:00","@version":"1","message":"Request: GET /assets/javascripts/hello.js","logger_name":"filters.AccessLog","thread_name":"application-pekko.actor.default-dispatcher-5","level":"INFO","level_value":20000}
...

さて、ログ中には単純なメッセージだけではなくプログラムの実行時の変数の内容を出力していることがあります。（前述のケースでは、Request: GET /widgets など）

logstash-logback-encoder では StructuredArguments を使うことでログにフィールドを追加しつつ、値を展開することができます。
以下は、HTTPメソッド名(method)とURI(uri)をフィールドに追加した例です。(commit)

{"@timestamp":"2024-11-07T23:08:29.675166652+09:00","@version":"1","message":"Request: method=GET uri=/assets/stylesheets/main.css","logger_name":"filters.AccessLog","thread_name":"application-pekko.actor.default-dispatcher-9","level":"INFO","level_value":20000,"method":"GET","uri":"/assets/stylesheets/main.css"}
{"@timestamp":"2024-11-07T23:08:29.675166702+09:00","@version":"1","message":"Request: method=GET uri=/assets/javascripts/hello.js","logger_name":"filters.AccessLog","thread_name":"application-pekko.actor.default-dispatcher-6","level":"INFO","level_value":20000,"method":"GET","uri":"/assets/javascripts/hello.js"}
{"@timestamp":"2024-11-07T23:08:29.709823419+09:00","@version":"1","message":"Response: method=GET uri=/assets/javascripts/hello.js (status=304)","logger_name":"filters.AccessLog","thread_name":"application-pekko.actor.default-dispatcher-12","level":"INFO","level_value":20000,"method":"GET","uri":"/assets/javascripts/hello.js","status":304}
{"@timestamp":"2024-11-07T23:08:29.709821669+09:00","@version":"1","message":"Response: method=GET uri=/assets/stylesheets/main.css (status=304)","logger_name":"filters.AccessLog","thread_name":"application-pekko.actor.default-dispatcher-13","level":"INFO","level_value":20000,"method":"GET","uri":"/assets/stylesheets/main.css","status":304}
{"@timestamp":"2024-11-07T23:08:29.79536314+09:00","@version":"1","message":"Request: method=GET uri=/assets/images/favicon.png","logger_name":"filters.AccessLog","thread_name":"application-pekko.actor.default-dispatcher-12","level":"INFO","level_value":20000,"method":"GET","uri":"/assets/images/favicon.png"}
...

ログのトレーシングとは？

プロダクション環境では大量のリクエストを捌くケースがあります。また、PlayFrameworkでは処理が非同期で行われています。
リクエストを受け付け、何らかの処理を行い、レスポンスを返すという一連の流れで出力されるログが入り乱れると、どの文脈で発生したログであるかを追いかけるることは困難です。
このような場合にリクエストごとに一意なIDを付与し、同じ文脈で発生したログにはそのIDを含めることで解決できます。

Scalaでログのトレーシングをやりたい!

Logbackを使用している場合は、MDC(Mapped Diagnostic Context)という機能を使うことが一般的です。しかし、MDCはスレッドごとに値を保持するため、スレッドを細かく切り替えながら処理を行うPlayFrameworkではひと工夫必要です。

以下は、リクエストを受け付けたタイミングでセットしたID(traceId)がレスポンスを返すタイミングで出力したログで出力されていない様子です。thread_nameからスレッドが切り替わっている様子もわかります。(commit)

{"@timestamp":"2024-11-11T23:51:21.247108788+09:00","@version":"1","message":"Request: method=GET, uri=/widgets","logger_name":"action.TraceableLoggingAction","thread_name":"application-pekko.actor.default-dispatcher-4","level":"INFO","level_value":20000,"traceId":"jfeK57QJ","method":"GET","uri":"/widgets"}
{"@timestamp":"2024-11-11T23:51:21.252257058+09:00","@version":"1","message":"Response: method=GET, uri=/widgets (status=200)","logger_name":"action.TraceableLoggingAction","thread_name":"application-pekko.actor.default-dispatcher-7","level":"INFO","level_value":20000,"method":"GET","uri":"/widgets","status":200}

ログを出力するたびにMDCに値をセットする処理やトレース用のIDをコード中で引き回し続ける処理を書くのはやや大変です。
以下の記事を参考にしながら、スレッドが切り替わる際にMDCの値を引き継ぐような仕組みを作ります。

ThreadPoolExecutorを拡張してスレッドプールを使いつつもMDCを引き回すようなExecutorを作ってみる - 京都行きたい

また、ExecutorServiceConfigurator を実装すると自前で用意したスレッドプールも設定ファイル上で指定して使えるようになります。
以下は、実装とログの出力例です。スレッドプールが切り替わってもトレースIDが引き継がれていることがわかります。(commit)

{"@timestamp":"2024-11-12T01:09:19.910970744+09:00","@version":"1","message":"Application started (Dev) (no global state)","logger_name":"play.api.Play","thread_name":"play-dev-mode-pekko.actor.default-dispatcher-7","level":"INFO","level_value":20000}
{"@timestamp":"2024-11-12T01:09:19.986438596+09:00","@version":"1","message":"Request: method=GET, uri=/widgets","logger_name":"actions.TraceableLoggingAction","thread_name":"pool-189-thread-5","level":"INFO","level_value":20000,"traceId":"5zOBLNHL","method":"GET","uri":"/widgets"}
{"@timestamp":"2024-11-12T01:09:20.041030994+09:00","@version":"1","message":"Response: method=GET, uri=/widgets (status=200)","logger_name":"actions.TraceableLoggingAction","thread_name":"pool-189-thread-6","level":"INFO","level_value":20000,"traceId":"5zOBLNHL","method":"GET","uri":"/widgets","status":200}
{"@timestamp":"2024-11-12T01:09:40.674878885+09:00","@version":"1","message":"Request: method=POST, uri=/widgets","logger_name":"actions.TraceableLoggingAction","thread_name":"pool-189-thread-3","level":"INFO","level_value":20000,"traceId":"4l1jg2Vl","method":"POST","uri":"/widgets"}
{"@timestamp":"2024-11-12T01:09:40.678931201+09:00","@version":"1","message":"Widget added name=YOYO, price=1234","logger_name":"controllers.WidgetController","thread_name":"pool-189-thread-3","level":"INFO","level_value":20000,"traceId":"4l1jg2Vl","name":"YOYO","price":1234}
{"@timestamp":"2024-11-12T01:09:40.679341438+09:00","@version":"1","message":"Response: method=POST, uri=/widgets (status=303)","logger_name":"actions.TraceableLoggingAction","thread_name":"pool-189-thread-3","level":"INFO","level_value":20000,"traceId":"4l1jg2Vl","method":"POST","uri":"/widgets","status":303}
...

おわり

上記の実装では、他のMDCを伝搬する仕組みを持たないスレッドプールには値を引き継ぐことができない問題が残ります。
以前は、Kamonというライブラリを使用していたのですが、最新のPlayFrameworkに対応していない（パッと見で対応方法もよくわからなかった;;）ため、色々とやり方を検証していた次第でした...。もっと良い方法があるよ！という方はぜひ教えていただけると幸いです。

stoneream.hatenablog.jp

書き損じ