• Home
• ブログ
• Redmine（Rails）のログをAthenaで「1アクセス1行」にして解析する

こんにちは。開発グループの吉岡です。

今回は、Redmine（Ruby on Rails）のログを Amazon Athena で分析できるようにしました。Redmine（Ruby on Rails）のログは1回のアクセスが Started・Processing・Completed などの複数行に分かれるため、そのままではSQLで「どのページが遅いか」「どのアクセスがエラーになったか」を調べにくい状態です。

そこで、各行に付いているリクエスト ID（request_id）をキーにログを集約するビューを作成し、1アクセス1行の形にしました。

環境

My Redmine では、コンテナ化した Redmine を AWS の ECS Service で動かしています。ログは同じタスク内の Fluentd コンテナ（サイドカー）が S3 へ転送し、Redmine インスタンスごとのプレフィックスに gzip 形式のファイルとして保存されます（バケット名とプレフィックスはサンプルです）。

s3://example-redmine-logs/log.sample01/
  20261007-052530_e63c57d4-1978-463e-8759-8f15283f4905.gz
  20261007-052700_0d9039e2-1476-46ba-8bb0-b23c300df2eb.gz
  ...

ログのフォーマット

S3 上のログは「時刻（S3 への送信時刻）」「タグ（インスタンス名）」「JSON」の3列をタブで区切った TSV です。Rails が出力した1行が JSON の message に入っています（IP アドレスとユーザ名はサンプルの値に置き換えています）。

2026-10-07T05:25:38+00:00  log.sample01  {"message":"I, [2026-10-07T05:25:15.989463 #478]  INFO -- : [9dda73be-e2d0-474e-a47b-b98e0c50636a] Started GET \"/projects\" for 203.0.113.10 at 2026-10-07 05:25:15 +0000"}
2026-10-07T05:25:38+00:00  log.sample01  {"message":"I, [2026-10-07T05:25:15.990412 #478]  INFO -- : [9dda73be-e2d0-474e-a47b-b98e0c50636a] Processing by ProjectsController#index as HTML"}

message だけを並べると、/projects への1回のアクセスが次の6行になります。

I, [2026-10-07T05:25:15.989463 #478]  INFO -- : [9dda73be-e2d0-474e-a47b-b98e0c50636a] Started GET "/projects" for 203.0.113.10 at 2026-10-07 05:25:15 +0000
I, [2026-10-07T05:25:15.990412 #478]  INFO -- : [9dda73be-e2d0-474e-a47b-b98e0c50636a] Processing by ProjectsController#index as HTML
I, [2026-10-07T05:25:15.995439 #478]  INFO -- : [9dda73be-e2d0-474e-a47b-b98e0c50636a]   Current user: user1 (id=6)
I, [2026-10-07T05:25:16.088145 #478]  INFO -- : [9dda73be-e2d0-474e-a47b-b98e0c50636a] [Aws::DynamoDB::Client 200 0.014451] scan
I, [2026-10-07T05:25:16.089137 #478]  INFO -- : [9dda73be-e2d0-474e-a47b-b98e0c50636a]   Rendered layout layouts/base.html.erb (Duration: 65.8ms | GC: 0.9ms)
I, [2026-10-07T05:25:16.089445 #478]  INFO -- : [9dda73be-e2d0-474e-a47b-b98e0c50636a] Completed 200 OK in 99ms (Views: 54.1ms | ActiveRecord: 21.8ms (30 queries, 1 cached) | GC: 1.0ms)

各行は Logger の書式 I, [時刻 #プロセスID] INFO -- : で始まり、その後ろに [request_id] と本文が続きます。この request_id をキーに集約します。

全体の流れ

Athena 側は、生ログテーブル → 行ビュー → アクセスビューの3段構成です。図中の件数は検証用インスタンスのサンプル（10ファイル）での実測値です。

手順

Athena のクエリエディタで、上から順に1文ずつ実行します。

1. データベースと生ログテーブル

TSV の3列を文字列のまま読み込みます。gzip は Athena がそのまま読めます。

CREATE DATABASE IF NOT EXISTS test_redmine_logs;

CREATE EXTERNAL TABLE IF NOT EXISTS test_redmine_logs.raw_sample01 (
  fluentd_time string,
  tag          string,
  record       string
)
ROW FORMAT DELIMITED
  FIELDS TERMINATED BY '\t'
STORED AS TEXTFILE
LOCATION 's3://example-redmine-logs/log.sample01/';

2. 行ビュー（1行1レコード）

message を取り出し、Logger のヘッダ部分を正規表現で分解します。今回の環境では、例外ログにLoggerのヘッダが付かないため、ヘッダ部分は省略可能にしています。

CREATE OR REPLACE VIEW test_redmine_logs.rails_log_lines AS
WITH src AS (
  SELECT
    tag,
    json_extract_scalar(record, '$.message') AS message
  FROM test_redmine_logs.raw_sample01
)
SELECT
  tag,
  NULLIF(regexp_extract(message, '^[A-Z], \[(\S+) #\d+\] +[A-Z]+ -- : ', 1), '') AS logged_at_str,
  TRY_CAST(NULLIF(regexp_extract(message, '^[A-Z], \[\S+ #(\d+)\]', 1), '') AS integer) AS pid,
  NULLIF(regexp_extract(message, '^[A-Z], \[\S+ #\d+\] +([A-Z]+) -- : ', 1), '') AS severity,
  NULLIF(regexp_extract(message, '^(?:[A-Z], \[\S+ #\d+\] +[A-Z]+ -- : )?\[([0-9a-f-]{36})\] ', 1), '') AS request_id,
  regexp_extract(message, '^(?:[A-Z], \[\S+ #\d+\] +[A-Z]+ -- : )?(?:\[[0-9a-f-]{36}\] )?(.*)$', 1) AS body,
  message
FROM src
WHERE message <> '';

3. アクセスビュー（1アクセス1レコード）

行ビューを request_id で GROUP BY します。各列は max(regexp_extract(...)) で、パターンに一致する行から値を取り出して集約します。 404（RoutingError）は Completed 行が出ないので、例外行から判定します。

CREATE OR REPLACE VIEW test_redmine_logs.rails_access AS
SELECT
  tag,
  request_id,
  max(pid) AS pid,
  min(CAST(from_iso8601_timestamp(logged_at_str) AS timestamp)) AS started_at,  -- UTC
  max(NULLIF(regexp_extract(body, '^Started (\S+) ', 1), '')) AS http_method,
  max(NULLIF(regexp_extract(body, '^Started \S+ "(.*)" for ', 1), '')) AS path,
  max(NULLIF(regexp_extract(body, '^Started .* for (\S+) at ', 1), '')) AS client_ip,
  max(NULLIF(regexp_extract(body, '^Processing by (\S+)#\S+ as ', 1), '')) AS controller,
  max(NULLIF(regexp_extract(body, '^Processing by \S+#(\S+) as ', 1), '')) AS action,
  max(NULLIF(regexp_extract(body, '^Processing by \S+ as (\S+)', 1), '')) AS format,
  max(NULLIF(regexp_extract(body, '^  Parameters: (.*)$', 1), '')) AS params,
  max(NULLIF(regexp_extract(body, '^  Current user: (\S+)', 1), '')) AS user_login,
  max(TRY_CAST(NULLIF(regexp_extract(body, '^  Current user: \S+ \(id=(\d+)\)', 1), '') AS integer)) AS user_id,
  coalesce(
    max(TRY_CAST(NULLIF(regexp_extract(body, '^Completed (\d{3}) ', 1), '') AS integer)),
    max(CASE WHEN body LIKE 'ActionController::RoutingError %' THEN 404 END)
  ) AS status,
  coalesce(
    max(NULLIF(regexp_extract(body, '^Completed \d{3} (.*?) in \d+ms', 1), '')),
    max(CASE WHEN body LIKE 'ActionController::RoutingError %' THEN 'Not Found' END)
  ) AS status_text,
  max(NULLIF(regexp_extract(body, '^([A-Z]\w*(?:::\w+)+) \(', 1), '')) AS exception_class,
  max(NULLIF(regexp_extract(body, '^[A-Z]\w*(?:::\w+)+ \((.*)\):?$', 1), '')) AS exception_message,
  max(TRY_CAST(NULLIF(regexp_extract(body, '^Completed .* in (\d+)ms', 1), '') AS integer)) AS duration_ms,
  max(TRY_CAST(NULLIF(regexp_extract(body, '^Completed .*Views: ([\d.]+)ms', 1), '') AS double)) AS views_ms,
  max(TRY_CAST(NULLIF(regexp_extract(body, '^Completed .*ActiveRecord: ([\d.]+)ms', 1), '') AS double)) AS activerecord_ms,
  max(TRY_CAST(NULLIF(regexp_extract(body, '^Completed .*\((\d+) queries', 1), '') AS integer)) AS db_queries,
  max(TRY_CAST(NULLIF(regexp_extract(body, '^Completed .* (\d+) cached\)', 1), '') AS integer)) AS db_cached,
  max(TRY_CAST(NULLIF(regexp_extract(body, '^Completed .*GC: ([\d.]+)ms', 1), '') AS double)) AS gc_ms,
  max(NULLIF(regexp_extract(body, '^Redirected to (\S+)', 1), '')) AS redirected_to,
  max(NULLIF(regexp_extract(body, '^Filter chain halted as (\S+)', 1), '')) AS halted_by,
  count_if(regexp_like(body, '^(\[ActiveJob\] )?\[Aws::')) AS aws_calls,
  sum(TRY_CAST(NULLIF(regexp_extract(body, '^(?:\[ActiveJob\] )?\[Aws::\S+ \d{3} ([\d.]+)', 1), '') AS double)) * 1000 AS aws_ms,
  count_if(body LIKE '[ActiveJob] Enqueued %') AS enqueued_jobs,
  count(*) AS log_lines
FROM test_redmine_logs.rails_log_lines
WHERE request_id IS NOT NULL
GROUP BY tag, request_id;

使ってみる

1アクセス1行になれば、あとは普通の SQL で集計できます。たとえばコントローラ・アクションごとの応答時間です。今回は、開発環境のログを使って試しました。

SELECT controller || '#' || action AS endpoint,
       count(*) AS hits, avg(duration_ms) AS avg_ms, max(duration_ms) AS max_ms
FROM test_redmine_logs.rails_access
GROUP BY 1
ORDER BY avg_ms DESC;

endpoint	hits	avg_ms	max_ms
AccountController#login	2	484	920
IssuesController#index	7	299	1350
IssuesController#show	4	236	268

サンプルでは 305 行のログが 38 アクセスにまとまりました。応答時間が最も長かった1,350msのアクセスは、プロセス起動直後の初回アクセスで、こうした傾向も数字で確認できます。

エラーの探し方

アクセスビューでエラーになったアクセスを見つけ、その request_id で行ビューを引きます。

-- エラーになったアクセス（404 は除外）
SELECT started_at, request_id, path, status, exception_class, exception_message
FROM test_redmine_logs.rails_access
WHERE status >= 400 AND status <> 404
ORDER BY started_at DESC;

-- そのアクセスのログを全部読む
SELECT logged_at_str, severity, body
FROM test_redmine_logs.rails_log_lines
WHERE request_id = ''
ORDER BY logged_at_str NULLS LAST;

例外行はタイムスタンプを持たないので、NULLS LAST で末尾に並べています。

ハマったところ

• ビューにタイムゾーン付きタイムスタンプを保存できない：from_iso8601_timestamp の結果をそのまま列にすると、Unsupported Hive type: timestamp(3) with time zone で失敗します。CAST(... AS timestamp) でタイムゾーンなしにして解決しました（値は UTC）。

• 例外ログに Logger のヘッダが付かない：[request_id] ActionController::RoutingError (...) のようにヘッダなしで出るため、最初の正規表現では 404 のアクセスが集約から漏れていました。ビューを作ったら、request_id IS NULL の行を確認すると取りこぼしに気づけます。

片付け

DROP で消えるのは定義だけで、S3 上のログは残ります。

DROP DATABASE test_redmine_logs CASCADE;

まとめ

Rails のログは1アクセスが複数行に分かれますが、request_id で集約するビューを用意すれば、Athena で普通のアクセスログとして扱えます。 テーブル1つとビュー2つで、応答時間の集計もエラー調査も SQL だけでできるようになりました。

今後は、S3 のパスに日付を入れてパーティションプロジェクションでスキャン量を減らすことや、複数インスタンスを横断して分析することが課題です。

---