express@4 から express@5 へのアップグレードを試みた際に、Cloud loggingに保存されたlogがトレースに紐づいていないことが発覚しました。
その原因を調査したので、記録しておきます。
結論
@google-cloud/trace-agent が提供するexpress用のプラグインがexpress 5になると読み込まれないようになるのが原因でした。
もし @google-cloud/trace-agent のTraceAgent を用いてCloud Loggingにtrace_idを付与しているとこの問題が起きるようです。
仕組みはTraceAgentが起動している状態で、expressが読み込まれたときにバージョンを確認してバージョンが4系の場合にexpressにmiddleware追加するという形になっています。そのため express@5 ではtrace_idが取得できなくなり、logからtrace_idが消えてしまったのでしょう。
とはいえ、 @google-cloud/trace-agent は stackdriver時代のトレースツールで、現在ではopen-telemetry経由でCloud Traceにトレースを送るほうが一般的なようです。それもあって活発に開発メンテナンスされてないようです。そのため、辞めれるなら辞めてしまって、OTLP経由で同様の動作をさせたほうがよさそうです。
また、最初にTraceAgentを起動しておいてから express を require する必要があり、なかなか黒魔術的なので、ES Moduleを使う現代ではダイナミックimportをしたりしないと期待どおりに動かすのに一手間かかる場面がありそうです。
とはいえ、express@5 でも読み込まれるように細工してあげることで継続利用できそうです。
以下は express@5 でも動作するようにして、確認したときのスクリーンショット。
ログにtrace属性が付与できている。
同じトレース属性を持つログだけに絞り込みができる。
Cloud Traceでもログといっしょにトレースが見える。
具体的な手順
@google-cloud/trace-agent をcloneしていじっても良いのですが、pluginを自作して対応してみることにしました。
plugin-express.cjs のようなファイルを用意し、@google-cloud/trace-agent からexpressのpluginの情報を取り出し、versionsには 4.x が入っていたため 5.xに置き換えてpluginにします。
const { patch, unpatch, versions } = require('@google-cloud/trace-agent/build/src/plugins/plugin-express')[0]
module.exports = [{ versions: '5.x', patch , unpatch }]
書いたpulginを TraceAgent に渡す必要があります。
TraceAgent を開始するときにこのファイルをplugins にわたすことでできます。
const tracer = TraceAgent.start({
plugins: {
...Config.defaultConfig.plugins,
'express': path.join(__dirname, 'plugin-express5.cjs')
}
})
なお、ES Modules を利用してもよいのですが、TraceAgentが起動下あとのexpressのrequireを検知して動作するようなので、動作が環境依存にならないようにCommonJSで検証しています。
もうちょっと詳しく
@google-cloud/trace-agent の実装を確認してみると、以下のようになっています。
SUPPORTED_VERSIONS は "4.x" が束縛されています。この情報を使って読み込みしたバージョンで利用可能か判断することでpluginの読み込みを管理しています。
具体的な処理はこのあたり。
warnやerrorログがでるようなので、ログレベルを変更して express@5 を使った場合、以下の様な出力がでていることが確認できます。
@google-cloud/trace-agent DEBUG PluginLoader#onRequire: [express@5.1.0] This module is not supported by the configured set of plugins.
ちなみに TraceAgent のログレベルを変更するにはコンストラクタで指定するとできます。
const tracer = TraceAgent.start({
logLevel: 4,
})
わかりにくいですが、4 より大きい値を設定しておくと debug レベルのログまで出力できます。
あとは plugin api を確認してexpress5でも使えるように誤魔化してあげるだけです。
ただし、pluginsを指定するとdefalutのpluginが読まれなくなったので、defaultConfigも一緒に設定してあげているのが、結論で上げた例です。
うまく設定できていると以下の様な出力がでてきました。
@google-cloud/trace-agent DEBUG PluginWrapper#applyPlugin: [express@5.1.0] Applying plugin.
実装をみてみると、TraceContextの引き継ぎ処理をやっているようで、loggingに関することはやっていません。おそらくtraceの情報があればloggingライブラリ側でよしなにしてくれるのでしょう。(未確認)
とすると、@google-cloud/trace-agent を使わずとも OpenTelemetry を利用できるようにして、必要なmiddlewareをexpressに指定することで @google-cloud/trace-agent を辞めることができるのではないか、という仮説が立ちそうでした。
検証コード
Discussion