はじめに
2024年6月からASTにジョインしたテックリードチームの石川(@h0r4k)です。
この記事は、以下アドベントカレンダーの16日目です。
AEON Advent Calendar 2024
今回の記事ではLaravelプロジェクトへのNewRelic導入に際して、いくつか発生していた問題と、それらの原因・解決方法のご紹介をしていきたいと思います。
どんな問題が発生していたか？
1. 特定のアプリケーションログがNewRelicに連携されない
まず1つ目の問題は、既存のアプリケーションログの中で、特定のアプリケーションログがNewRelicへ連携されなかったことです。
特定のアプリケーションログについて、ログファイル出力はされているものの、NewRelic側のLogにはなぜか連携されない・・・という事象が発生していました。
ただし、こちらの問題に関しては、どのアプリケーションログが出力されていないかが実装箇所レベルで把握できていたため、調査は比較的容易でした。
2. 時々アプリケーションログがロストする
2つ目の問題は、LaravelのアプリケーションログがNewRelicに連携されたりされなかったりするという事象でした。
こちらの問題はお察しの通り非常に厄介なタイプの問題であり、
同じ出力箇所のログなのに、ログ出力の挙動が一貫しておらず、なんでなんだ！わからん！と大変頭を抱えました。
問題の原因と解決方法
1. 特定のアプリケーションログがNewRelicに連携されない
こちらの事象については、結論、下記の既存実装が原因となっていました。
\Illuminate\Support\Facades\Log::info(
message: '',
context: ['hoge' => 'fuga']
);
このアプリケーションログをみるとmessage部が空文字となっており、context部のみを記載する実装となっていることが分かります。
そして、NewRelicの挙動から見るにアプリケーションログの連携はmessage部が空文字の場合には行われないようで、今回のようにmessage部が空文字となっているアプリケーションログはcontext部の情報も含めてログ連携されなかったようです。
ということで、こちらの問題については、message部に適切な値を設定することで無事解消されました。
2. 時々アプリケーションログがロストする
こちらの問題についてはなかなか原因がわからず調査が難航していたのですが、結果的には下記の公式ドキュメントの情報をもとに解決に至りました。
エージェントとデーモンを同じコンテナにインストール
注意
デフォルトでは、最初のトランザクションにより、エージェントはデーモンの開始とアプリケーション接続の初期化をトリガーします。パフォーマンス上の理由から、エージェントは接続を初期化する前にこれらの操作が完了するのを待ちません。これにより、コンテナーの開始後の最初のいくつかのトランザクションが失われる可能性があります。この損失を防ぐには、 newrelic.iniファイルのnewrelic.daemon.start_timeout }エントリとnewrelic.daemon.app_connect_timeoutエントリの両方を推奨値の5秒と15秒にそれぞれ設定します。
要約すると、上記の設定をしないとコンテナ起動直後の最初のいくつかのトランザクションのデータについては失われる可能性があるということなのですが、初期のNewRelicの導入時にはこちらの記載が見落とされていたようでした。
こちらについては、そもそも利用しているAzureのAppServiceが内部的にどういった構成になっているかの把握ができていないと見逃してしまう設定となるため、意外なハマりポイントとなっていました。
かくいう私自身も入社したてでAzureにも慣れていなかったため、
この問題の解決に至るためのAppService自体の知識も乏しく、調査に難航してしまいました。
おまけ
個人的に推奨したい設定とその活用方法
現状NewRelicのデフォルトでは、アプリケーションログのコンテキスト情報の連携はOFFになっているため、こちらの設定はONにすることをおすすめします。
newrelic.application_logging.forwarding.context_data.enabled Monologからのコンテキストデータをログ属性に追加する
オススメする一つの目の理由としては、すでに既存のアプリケーションログでコンテキスト情報を出力している場合には、この設定を行わないと必要な情報をロストしてしまうという点です。（この場合はむしろ設定必須ですね）
もう一つの理由としては、NRQLでログを集計する場合、コンテキスト情報を利用して集計すれば容易に集計可能でも、メッセージ情報だけで集計を行う場合には非常にややこしくなってしまう場合があるからです。
コンテキストを利用せず集計を行う場合
例えば、下記のようなバッチの実行開始を記録するアプリケーションログを複数のバッチ処理で呼び出しているとします。
\Illuminate\Support\Facades\Log::info(
message: "[{$this->batchName}]の実行を開始しました。",
context: []
);
// Log Output:
// [更新バッチ]の実行を開始しました
// [削除バッチ]の実行を開始しました
そして、NRQLを利用して時間単位で何のバッチが何回実行されたかを集計する場合には、下記のようなクエリを組む必要があります。
SELECT count(*) FROM Log WITH
substring(message, 1, position(message, ']') - 1) AS batch_name
WHERE message LIKE '%の実行を開始しました。' FACET batch_name TIMESERIES
このNRQLではFACETで指定したいbatch_nameがどこにも定義されていないため、一度messageからsubstring()やposition()等を利用してバッチ名の情報を取り出してからbatch_nameを定義し集計に利用する、という手間のかかる状態となっています。
また、すでにややこしいクエリとなっていますが、このバッチ名がメッセージ部のどの位置に記載されているかや、バッチごとのログの表記揺れ等によって、このクエリは更に複雑化されることも考えられます。
コンテキストを利用して集計を行う場合
では、コンテキストを利用した場合はどうでしょうか。
この場合、アプリケーション側の実装は下記のようになり、
\Illuminate\Support\Facades\Log::info(
message: 'バッチの実行を開始しました。',
context: ['batch_name' => $this->batchName]
);
// Log Output:
// バッチの実行を開始しました
集計用のNRQLは下記の記述のみになります。
SELECT count(*) FROM Log
WHERE message = 'バッチの実行を開始しました。' FACET context.batch_name TIMESERIES
このように、先ほどのsubstring()やposition()などが消えており、同じ情報量のログから集計を行うにしても、コンテキスト情報の有無によって集計の難易度が大きく変化していることがわかります。
そのため、せっかくNewRelicを利用するようになるのであれば、コンテキストの活用を強くオススメいたします！
おわり
ASTでは現在新規メンバーを募集中です！
ご興味のある方はぜひ下記からご連絡ください。