スタックトレースが長すぎてDatadogでログがパースできない問題の解消(Log4j2)

最近、仕事で開発しているKotlinアプリケーションでDatadogに送信されるログが崩れるという問題に遭遇し、原因を調べていくと巨大なスタックトレースによるものだった。

やったことなどメモしておく。

問題の背景

Spring WebFluxベースのWebアプリケーションで、アプリケーションログをLog4j2で吐き出してDatadogに送信し、監視やデバッグに活用している。ログはJSON形式で出力され、Datadogで構造化されたデータとして扱えるようにしている。

ところが、例外が発生したときのログがDatadog上で正しくパースされず、単なるテキストとして表示される事象が発生した。調査してみると、スタックトレースが非常に長い場合にJSONファイルの文字列長が長くなりDatadog側で途中で切ってしまい、切ったログを無理くりパースしようとして崩れていることがわかった。

なお、なぜログが長くなってしまうかはそこまで追えてないが、長いスタックトレースの大半がWebFlux系だったのとぱっと調べた感じそのあたりをアプリケーション側で短くするのがむずそうだったので考えるのをやめた。

修正前のロギング設定

もともとはNewRelic用のログフォーマッターである NewRelicLayout を使っていた：

// build.gradle.kts
implementation("com.newrelic.logging:log4j2:3.1.0")

<!-- log4j2.xml -->
<Console name="Console" target="SYSTEM_OUT">
    <NewRelicLayout/>
</Console>

このレイアウトは、スタックトレースの長さに関する制御ができず、深いスタックトレースがそのまま出力されてしまう。結果として、Datadogのログパーサーが処理しきれない長さのJSONログとなっていた。

修正内容

Log4j2標準の JsonTemplateLayout を使うことで、この問題を解決した。

まず、依存関係を変更。

// build.gradle.kts
// implementation("com.newrelic.logging:log4j2:3.1.0") を削除
runtimeOnly("org.apache.logging.log4j:log4j-layout-template-json")

次に、ログ設定を更新。

<!-- log4j2.xml -->
<Console name="Console" target="SYSTEM_OUT">
    <JsonTemplateLayout
            eventTemplateUri="classpath:logging-template.json"
            maxStringLength="5000"
            truncatedStringSuffix=" ...[truncated because of maxStringLength]"
    />
</Console>

ログのテンプレートを定義。

// logging-template.json
{
  "instant": {
    "$resolver": "timestamp",
    "pattern": {
      "format": "yyyy-MM-dd'T'HH:mm:ss.SSS'Z'",
      "timeZone": "UTC"
    }
  },
  "thrown": {
    "$resolver": "exception",
    "field": "stackTrace",
    "stackTrace": {
      "stringified": true
    }
  },
  // ... 他のフィールド定義
}

maxStringLengthの設定

この件のポイントは log4j2.xmlに記載したJsonTemplateLayoutの maxStringLength="5000" の設定。
これによりスタックトレースを含むすべての文字列フィールドが最大5000文字で切り詰められる。

出力されるスタックトレースはこのようになっている。

java.lang.RuntimeException: Example error happens
    at com.jsoizo.example.controller.Example$get$2.invokeSuspend(Example.kt:38)
        
        (...中略)

    at reactor.core.publisher.FluxConcatArray$ConcatArraySubscriber.onSubscribe(FluxConcatArray.java:172)
    at reactor.core.publisher.MonoNext$NextSubscriber.onSubscribe(MonoNext.java:70)
    at reactor.core.publisher.FluxConcatMapN ...[truncated because of maxStringLength]

切り詰められた場合は ...[truncated because of maxStringLength] というサフィックスが付くので、ログを見たときに切り詰めが発生したことがわかる。

Appendix: Datadogのログサイズ制限

Datadogのログ収集ドキュメントによるとHTTP APIで1MBまでのログを送れると書いてある。ただ実際のところ、1MBということは100万文字くらいってことになるのだがそんな大きなログを送ってはいなくて、ログのJSONが切られてしまう上限は数万文字とかのところにあるっぽそうな挙動だった。

そのあたりは実際にちゃんと追わないとわからないが面倒くさかったので調べられてない。

あと、今回の5000文字という設定は、Datadogの制限内に収まるように、かつスタックトレースの重要な部分が確認できるバランスを考慮して決定した。

/var/log/jsoizo

メモ帳技術とか趣味とか