最近、がっつり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

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

そもそもだが、Redmine標準のログ出力のフォーマットがわからなかった
意味上は1つのログレコードだが途中に改行が含まれるためCloudWatch Logs上は複数の（個別の）ログレコードとして扱われてしまうものがある
ログの中にログレベルやプロセス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のログフォーマットの理解

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

あれこれ調べた結果：

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

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

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

公式リファレンスのこちらのセクション「CloudWatch エージェント設定ファイル: Logs セクション」や、CloudWatch Logsで複数行をひとまとめにする【Laravel】が参考になります。

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

{
    "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+\\] "
                    },
                    ...
                ]
            }
        }
    }
}

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

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

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

すると：

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

すると、こんなふうに：

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

（おしまい）

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