RedmineのログをCloudWatch Logsで分析する

最近、がっつりRedmine構築＆運用に触れる機会があり、その中で今更ですがRailsやAWSに関する知見を深めています。
そうした知見の中からのTipsのご紹介。

# Background

今回はRedmineはAWSのEC2上で動かしています。OSはAmazon Linux 2023。Rubyのバージョンは3.1。Redmineのバージョンは5.x。
そのRedmineのログをCloudWatch Agentで採取し、CloudWatch LogsのVPCエンドポイントを経由して、CloudWatch Logsに送信します。

# Problem

送信したログを分析する中で、次のような課題が発生しました：

1. そもそもだが、Redmine標準のログ出力のフォーマットがわからなかった
1. 意味上は1つのログレコードだが途中に改行が含まれるためCloudWatch Logs上は複数の（個別の）ログレコードとして扱われてしまうものがある
1. ログの中にログレベルやプロセスID、リクエストIDが埋め込まれているが、CloudWatch Logsの通常のフィルターではこれらを使った分析がしづらい

ログメッセージのイメージ（L6～8などが課題 #2 に該当）：

```
I, [2023-11-28T15:56:12.075951 #179445]  INFO -- : [e0bf091f-1478-4ce8-809a-27f6907624a5]   Current user: xxxx.xxxx (id=0000)
I, [2023-11-28T15:56:12.283748 #179445]  INFO -- : [e0bf091f-1478-4ce8-809a-27f6907624a5]   Rendered issues/show.html.erb within layouts/base (Duration: 105.5ms | Allocations: 78778)
I, [2023-11-28T15:56:12.300063 #179445]  INFO -- : [e0bf091f-1478-4ce8-809a-27f6907624a5]   Rendered layout plugins/xxxx/app/views/layouts/base.html.erb (Duration: 121.8ms | Alloca
I, [2023-11-28T15:56:12.300307 #179445]  INFO -- : [e0bf091f-1478-4ce8-809a-27f6907624a5] Completed 200 OK in 227ms (Views: 89.6ms | ActiveRecord: 109.3ms | Allocations: 114286)
I, [2023-11-28T15:56:12.421519 #179445]  INFO -- : [701a4c87-9540-4cfb-9657-f840206c6400] Started GET "/images/xxxx.png" for 10.58.3.24 at 2023-11-28 15:56:12 +0900
F, [2023-11-28T15:56:12.421922 #179445] FATAL -- : [701a4c87-9540-4cfb-9657-f840206c6400]   
[701a4c87-9540-4cfb-9657-f840206c6400] ActionController::RoutingError (No route matches [GET] "/images/xxxx.png"):
[701a4c87-9540-4cfb-9657-f840206c6400]   
I, [2023-11-28T15:56:12.431614 #179445]  INFO -- : [592b68a1-be28-4005-90e3-95c50ddd8c6a] Started GET "/images/xxxx.png" for 10.58.3.24 at 2023-11-28 15:56:12 +0900
F, [2023-11-28T15:56:12.431922 #179445] FATAL -- : [592b68a1-be28-4005-90e3-95c50ddd8c6a]   
[592b68a1-be28-4005-90e3-95c50ddd8c6a] ActionController::RoutingError (No route matches [GET] "/images/xxxx.png"):
[592b68a1-be28-4005-90e3-95c50ddd8c6a]   
I, [2023-11-28T15:56:14.778901 #179445]  INFO -- : [7bce6ba7-2cec-4326-a4b4-21ffad5b92d7] Started GET "/issues/0000" for 10.247.46.218 at 2023-11-28 15:56:14 +0900
I, [2023-11-28T15:56:14.779521 #179445]  INFO -- : [7bce6ba7-2cec-4326-a4b4-21ffad5b92d7] Processing by IssuesController#show as HTML
I, [2023-11-28T15:56:14.779572 #179445]  INFO -- : [7bce6ba7-2cec-4326-a4b4-21ffad5b92d7]   Parameters: {"id"=>"0000"}
I, [2023-11-28T16:00:07.302318 #460267]  INFO -- : [ActiveJob] [ActionMailer::MailDeliveryJob] [176a3f6e-7758-49d5-ae37-c35350703570]   Rendered layout layouts/mailer.html.erb (Duration: 2.3ms 
I, [2023-11-28T16:00:07.330316 #460267]  INFO -- : MailHandler: issue #971700 created by Anonymous
I, [2023-11-28T16:00:07.330821 #460267]  INFO -- : [ActiveJob] [ActionMailer::MailDeliveryJob] [176a3f6e-7758-49d5-ae37-c35350703570] Performed ActionMailer::MailDeliveryJob (Job ID: 176a3f6e-7
I, [2023-11-28T16:00:07.331655 #460267]  INFO -- : [ActiveJob] [ActionMailer::MailDeliveryJob] [4b7ad22d-a8f3-4abe-971f-80130c392bfb] Performed ActionMailer::MailDeliveryJob (Job ID: 4b7ad22d-a
I, [2023-11-28T16:00:07.331819 #460267]  INFO -- : [ActiveJob] [ActionMailer::MailDeliveryJob] [56a7f653-d264-4a8a-b495-24790f830fc2] Performed ActionMailer::MailDeliveryJob (Job ID: 56a7f653-d
E, [2023-11-28T16:00:07.333909 #460267] ERROR -- : [ActiveJob] [ActionMailer::MailDeliveryJob] [ba290c8e-569d-4e39-ae60-750f1ac0b6a0] Email delivery error: 354 go ahead

I, [2023-11-28T16:00:07.333981 #460267]  INFO -- : [ActiveJob] [ActionMailer::MailDeliveryJob] [ba290c8e-569d-4e39-ae60-750f1ac0b6a0] Performed ActionMailer::MailDeliveryJob (Job ID: ba290c8e-5
I, [2023-11-28T16:00:07.896226 #179445]  INFO -- : [f778ad27-d218-4a26-b7c8-efb4e333370c] Started POST "/login" for 10.246.73.44 at 2023-11-28 16:00:07 +0900
I, [2023-11-28T16:00:07.897003 #179445]  INFO -- : [f778ad27-d218-4a26-b7c8-efb4e333370c] Processing by AccountController#login as HTML
I, [2023-11-28T16:00:07.897075 #179445]  INFO -- : [f778ad27-d218-4a26-b7c8-efb4e333370c]   Parameters: {"utf8"=>"✓", "authenticity_token"=>"94d3Y42at2SEUCMYqb9/H6g5EmrM0dsO65Tt7to+8SESjIB9Iq8
```

# Solution

## 1. Redmineのログフォーマットの理解

コレはもう本当にそもそもなのですが、「この文字列は何を示しているんだ」というのが疑問になって調べても、意外にも全然情報が出てきません。
それくらいわかるでしょ？ということなのかもしれませんが、「なんとなく想像はできても～」止まりな項目がいくつかありました。

あれこれ調べた結果：

1. `I,` とか `E, `： ログレベルのイニシャル
1. `[2023-11-28T16:00:07.896226...`みたいなの： 日時
1. `...#179445]`みたいなの： プロセスID。RubyランタイムのプロセスID
1. `INFO` とか `FATAL`： ログレベル
1. `--`： ？？
1. `[f778ad27-d218-4a26-b7c8-efb4e333370c]`みたいなの： リクエストID
1. それ以降： ログメッセージ
1. #1～6で始まるログレコードが意味上のログレコードの開始で、#1～6で始まらないログレコードはその #7 の続き

## 2. 意味上1つのログレコードとして認識させる

CloudWatch Agentの設定を行います。
設定項目名は `multi_line_start_pattern` です。

公式リファレンスのこちらのセクション「[CloudWatch エージェント設定ファイル: Logs セクション](https://docs.aws.amazon.com/ja_jp/AmazonCloudWatch/latest/monitoring/CloudWatch-Agent-Configuration-File-Details.html#CloudWatch-Agent-Configuration-File-Logssection)」や、[CloudWatch Logsで複数行をひとまとめにする【Laravel】](https://qiita.com/YujiHamada3/items/ea7e73582c1ebf309d94)が参考になります。

以下のように、Redmineのログファイルの情報を記述する箇所に、 `multi_line_start_pattern` という項目名で複数行からなるログレコードの先頭にマッチする正規表現パターンを追加します：

```json
{
    "agent": {
        ...
    },
    "metrics": {
        ...
    },
    "logs": {
        "endpoint_override": "...",
        "logs_collected": {
            "files": {
                "collect_list": [
                    {
                        "file_path": "/path/to/production.log",
                        "log_group_name": "...",
                        "log_stream_name": "...",
                        "retention_in_days": ...,
                        "multi_line_start_pattern": "\\w, \\[\\d{4}-\\d{2}-\\d{2}T\\d{2}:\\d{2}:\\d{2}\\.\\d{6} #\\d+\\] "
                    },
                    ...
                ]
            }
        }
    }
}
```

:::note warn
正規表現は文字列型で指定するため、正規表現におけるエスケープに、JavaScript（JSON）におけるエスケープを重ね掛けして考えなくてはならない点に注意してください。
記述を誤り不正な正規表現となるとCloudWatch Agentが起動しません。
:::

設定ファイルを修正して、Agentに読み込ませます：

```sh
vi /path/to/amazon-cloudwatch-agent.json #ファイルを修正
/path/to/amazon-cloudwatch-agent-ctl -a stop
/path/to/amazon-cloudwatch-agent-ctl -a fetch-config -m ec2 -c file:/path/to/amazon-cloudwatch-agent.json -s
```

すると：

![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/50571/1fff3aa9-5e96-8fde-55ec-ca77615a8a74.png)

CloudWatch Logsで、意味上の1レコードが、実際に1レコードとして扱われるようになりました🙌

## 3. ログレベルやプロセスID、リクエストIDを括り出す

CloudWatch Logs Insightsを利用します。
Insightsはフィルタリングや集計はもちろん、与えられたログメッセージからglob記法や正規表現で項目を抽出して、それらをフィルタリングや集計に利用することができます。
これには `parse` を使用します。

例えば以下のようにして：

```
filter @logStream = 'xxxx'
 | fields @timestamp, @message
 | filter @message like /^[EF],/
 | parse @message /\w, \[(?<Date>\d{4}-\d{2}-\d{2}?)T(?<Time>\d{2}:\d{2}:\d{2}?)\.\d{6} #(?<Proc>\d+?)\] +(?<Level>\w+?) +[^ ]+ +: +\[(?<Request>[a-z0-9\-]+?)\]/ 
 | display @timestamp, Date, Time, Proc, Request, Level, @message
```

すると、こんなふうに：

![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/50571/b130c669-4c2a-3dc1-9993-0fe47200f2cb.png)

これでリクエストIDやログレベルなどを使ったフィルタや集計ができるようになりました🙌

（おしまい）