エラーログにトラッキングIDをつけてみた

takahiko tominaga
nextbeat-engineering
12 min readApr 19, 2022

目次

  1. はじめに
  2. 概要
  3. エラーログにトラッキングIDを付与
  4. Fluent Bitの設定
  5. Slack通知の設定
  6. 確認
  7. おわりに

1. はじめに

こんにちは、ネクストビートの富永です。

今回はアプリケーションでエラーが発生した場合に、Slackなどに通知はされますが、そのログや前後のアクセスを確認するのがとても面倒だったので、エラーログ自体にトラッキングIDを付与して追跡できないかと考え、実際にやってみました。

2. 概要

今回はエラーログにトラッキングIDを付与し、Fluent Bitコンテナを使用してログの振り分けを行なっていきます。

今回の構成は以下図のようになります。

構成図

Fluent Bitでフィルタリングしたログを、CloudWatchとKinesisに送っていますが、今回はCloudWatchをメインに実装を行いました。
(Kinesisは複数箇所にログを送信できるか確かめたかったので使用しています)

また今回はログを追跡できるかをメインで行いますので、Fluent Bitコンテナでのログの振り分け等の詳細な設定は行いません。

3. エラーログにトラッキングIDを付与

アプリケーションは、いつもと同じようにPlay Framework(Scala)を使用します。

今回はPlay Framework (以下Play)の標準設定のログではなく、SLF4Jを使用してログをカスタマイズし実装を行います。

以下コードが、トラッキングIDを付与している処理になります。
トラッキングIDはJavaのUUIDを、出力はSLF4Jのマーカーを使用して実装を行いました。
- (ハイフン)を取り除く処理をしていますが、これはCloudWatch上でハイフンありだとうまく検索ができなかったので、除外しています。
(ULIDに置き換えた方が良かったかも)

MarkerFactory.getMarker(UUID.randomUUID.toString().replace(“-”, “”))

トラッキングIDを付与したログのコード

最後にLogbackの設定です。
今回エラーログをJSONで見やすくしたかったためLogstash Logback Encoderを使用しました。

<configuration>
<!-- 標準出力用設定 -->
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<
encoder class="net.logstash.logback.encoder.LogstashEncoder" />
</
appender>

<!-- アクセスログ用設定 -->
<appender name="ACCESS-LOG" class="ch.qos.logback.core.ConsoleAppender">
<
encoder>
<
pattern>
%d{yyyy-MM-dd HH:mm:ss} %marker %msg %n
</pattern>
</
encoder>
</
appender>

<
root level="WARN">
<
appender-ref ref="STDOUT" />
</
root>

<
logger name="play" level="WARN" />
<
logger name="application" level="WARN" />
<
logger name="mvc.util.AccessLogFilter" level="INFO" additivity="false">
<
appender-ref ref="ACCESS-LOG" />
</
logger>
</
configuration>

本当はこんな感じで、Logbackのエンコードも自作したかったのですがどうもできないみたいです。Playじゃなければ使えるのかな…

object LogbackJsonEncoder extends LayoutBase[ILoggingEvent] {
def doLayout(event: ILoggingEvent): String = {
Json.obj(
"timeStamp" -> event.getTimeStamp,
"level" -> event.getLevel.toString,
"maker" -> event.getMarker.toString,
"thread" -> event.getThreadName,
"message" -> event.getMessage,
"throwable" -> event.getThrowableProxy.toString,
"class" -> event.getClass.toString,
"argument" -> event.getArgumentArray.toString,
"callerData" -> event.getCallerData.toString,
"loggerContextVO" -> event.getLoggerContextVO.toString,
"formattedMessage" -> event.getFormattedMessage,
"mdcPropertyMap" -> event.getMDCPropertyMap.toString,
"loggerName" -> event.getLoggerName,
"coreConstants" -> CoreConstants.LINE_SEPARATOR
).toString()
}
}

Logback Issues: https://github.com/qos-ch/logback/pull/255

4. Fluent Bitの設定

今回はamazon/aws-for-fluent-bitコンテナをベースに使い、ログ振り分けの設定をコピーして実装しました。

// Dockerfileの設定
FROM amazon/aws-for-fluent-bit:latest
COPY fluent-bit-custom.conf /fluent-bit/configs/fluent-bit-custom.conf

以下振り分けの設定です。
今回はトラッキングIDでログの追跡、前後のアクセスログの確認を行いたかったので、全てのログをCloudWatchとKinesis Firehoseに送っています。

[SERVICE]
Flush 1
Grace 30
Log_Level info
Parsers_File parsers-custom.conf

[OUTPUT]
Name cloudwatch_logs
Match *
log_key log
region ap-northeast-1
log_group_name /ecs/logs/stg
log_stream_prefix firelens-fluent-bit-log-
auto_create_group true

[OUTPUT]
Name kinesis_firehose
Match *
region ap-northeast-1
delivery_stream stg-fluentbit-delivery-stream

5. Slack通知の設定

今回ErrorやWarnのログがCloudWatchに吐かれた時に、CloudWatch Alarmをアラーム状態にしてSlack通知用のLambdaをSNS経由で実行します。

Slackに以下の内容を通知させます。
エラー発生時のExceptionも送ろうかと考えたのですが、今回は送らないようにしました。
理由は、Slackはエラーが発生したかどうかがわかれば良いのと、エラーの内容調査はちゃんとマネコン上などで行うようにしたかったからです。

  • アラートの種類
  • ERROR/WARNの発生場所
  • ERROR/WARNの発生時のスレッド
  • ERROR/WARNの発生時間
  • ERROR/WARNのメッセージ
  • CloudWatch Logsへのリンク
  • CloudWatch Alarmへのリンク

コードは長くなるので、こちらを参照してください。

6. 確認

実際にエラーを発生させてみます。

意図してエラーを発生させているパスにアクセスすると、以下のようにSlackに無事通知を送ることができました。

次はCloudWatchにアクセスして、エラーログを追跡できているかを確認してみます。

トラッキングIDでフィルタリングされて、一件だけが表示されているので、ちゃんと追跡できていました。

JSONへのエンコードもいい感じです。

検索BoxのトラッキングIDを削除して、前後のアクセスログもフィルタリングできているか確認してみます。

指定している期間内のログだけが表示されているので、いい感じにできてそう。

最後にアラームにもアクセスしてみましょう。

ちゃんと確認できました。

Kinesis Firehose経由でS3にもデータの格納を確認できました。

7. おわりに

結構ログの追跡はしやすくなったのかなと思います。
あとは、今エラーログ以外は消えてしまっているので、S3とかKinesisとかも使用してログを保存しておくとよさそうです。
ここら辺はFluent Bitの設定でうまくやれば良さそうです。

本当はエラーが発生した(ログを仕込んだ)箇所にも飛んで行きたかったんですが、結構難しそうだったので断念しました。。。

今回はログにトラッキングIDを付与して追跡できるところまでやりましたが、ログに関してはもっと色々と試してみたいです。

また機会があれば色々試して、ブログにしようと思います。

最後まで読んでいただきありがとうございました。

参考文献

We are hiring!

株式会社ネクストビートでは

「人口減少社会において必要とされるインターネット事業を創造し、ニッポンを元気にする。」
を理念に掲げ一緒に働く仲間を募集しております。

https://www.nextbeat.co.jp/recruit

--

--