5
2

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?

@hirashima-gmoconnectinGMOコネクト株式会社

Cloud Run の severity が ERROR 一色になる罠と、Terraform 監視まで含めて整合させる構造化JSONログにたどり着いた話

5
Posted at

はじめに

GMOコネクトの平島です。

Cloud Run で Node.js のワーカーを動かしていて、こんな経験はありませんか 😇

  • 設計書には「これは CRITICAL、これは WARNING」と書いた
  • 実装も console.error / console.warn / console.info で出し分けた
  • でも Cloud Monitoring のダッシュボードでは ERROR 一色で、WARNING も CRITICAL も区別がつかない

これ、console.* をそのまま Cloud Logging に流したときの「あるある」です。さらに監視ダッシュボードを Terraform で IaC 管理していると、アプリ側のログ実装が壊れていても CI ではまったく検知できません。

本記事では、Cloud Run Worker Pool で動く監視ワーカーの console.* 18箇所を構造化 JSON ログに置き換えた経験をもとに、原因・最小実装・Terraform との整合性の取り方・踏んだ落とし穴まで整理します。

何が起きていたか:「ログは出ているのに監視が動かない」

監視ワーカーには、以下のような設計書（log-level.md 的なもの）がありました。

レベル 定義 監視への影響
CRITICAL Worker 継続不能、または通知の完全消失 全件即時通知
ERROR 人が確認すべき異常。通知欠損・データ不整合につながる 30分20件でアラート
WARNING 自動リカバリ可能な一時的問題・設定上の懸念 監視対象外
INFO 正常処理のトレース 監視対象外

実装側を見ると、各事象に対して console.error / console.warn / console.info がそれっぽく使い分けられていました。

// 必須環境変数の未設定
console.error('FATAL: required env var not set');

// JSON パースエラー
console.error('Failed to decode message data');

// Pub/Sub Subscription の error イベント
console.error('Subscription error:', error.message);
console.error(error);

// 受信時のトレース
console.info(`Received message: ${message.id}`);

一見、何の問題もなさそうですよね。でも、Cloud Logging のエクスプローラで Worker Pool のログを見ると、

  • ほぼ全部が severity = ERROR、もしくは無印（DEFAULT）
  • CRITICAL も WARNING も INFO も一切ない

という状態でした。結果、ダッシュボード上の「ERROR エントリ数」グラフはひたすら横ばい、「重大度 600 以上の全件通知アラート」も発火しない。設計書のレベル定義が Cloud Logging まで届いていなかったわけです。

原因: Node.js の console.* と Cloud Logging severity のすれ違い

Cloud Run のログ取り込み仕様を改めて確認すると、公式ドキュメントにこう書かれています。

When you write logs, you can send a simple text string or send a single line of serialized JSON.

When you provide a structured log as a JSON dictionary, some special fields are stripped from the jsonPayload and are written to the corresponding field in the generated LogEntry.

... if your JSON includes a severity property, it is removed from the jsonPayload and appears instead as the log entry's severity.

要点をまとめると、

  • プレーンテキストで出力した場合、Cloud Logging は severity をストリームから推定するしかありません。stderr → ERROR、stdout → INFO 程度の判定で、CRITICAL / WARNING の区別はつきません
  • JSON 形式で severity フィールド付きで出力した場合、そのフィールドが jsonPayload から取り出され、LogEntry の severity として書き込まれます

Node.js の console.error も console.warn も、内部的にはどちらも stderr に書き出します。そのため、Cloud Logging から見れば「stderr に書かれた何か」でしかなく、ERROR と WARNING を分ける手がかりが存在しません。

stdout/stderr に「JSON 形式で severity フィールドを含めた文字列」を書き出すのが正攻法、ということになります。

console.error(
  JSON.stringify({
    severity: 'CRITICAL',
    message: 'DLQ notification failed. Acknowledged to avoid loop.',
  })
);

これを Cloud Logging が受け取ると、severity を CRITICAL として認識し、ダッシュボードのメトリクスフィルタにもきちんと引っかかるようになります。

設計: ログレベル定義を Single Source of Truth に据える

実装に入る前に、「どの事象がどの severity か」を1箇所にまとめたドキュメントを用意しておくと、その後の作業が一気にラクになります。今回のワーカーでは log-level.md という設計書に下記のような表を置きました。

事象 severity 理由
必須環境変数未設定 CRITICAL Worker 起動不能
起動時の設定値が不正 CRITICAL Worker 起動不能
main() catch のプロセス異常終了 CRITICAL Worker 完全停止
DLQ で non-retryable 失敗を ack して破棄 CRITICAL 通知が永久に失われる
JSON パースエラーで nack ERROR 送信元・メッセージ内容の調査が必要
JSON 以外の処理例外で nack ERROR アプリ不具合または不明な処理失敗
通知送信 retryable 失敗で nack WARNING Pub/Sub 再配信で自己回復期待
Subscription error イベント WARNING Pub/Sub client が自動再接続する想定
受信エンベロープ、ack 成功、スキップ INFO 正常系・調査用トレース

このドキュメントがないと、「これって ERROR でしたっけ WARNING でしたっけ？」が実装者ごとにブレて、結局 Cloud Logging を見て一覧で揃わない、という事態が再発します。実装時もレビュー時も「設計書のこの行を根拠に CRITICAL」と言える状態を作るのが先です。

実装1: 構造化ログヘルパー

各 console.* を毎回 JSON.stringify で囲むのは現実的ではないので、薄いヘルパーを切り出します。

// src/worker/log.ts
export type Severity = 'CRITICAL' | 'ERROR' | 'WARNING' | 'INFO';

export function log(
  severity: Severity,
  message: string,
  fields?: Record<string, unknown>,
): void {
  const entry: Record<string, unknown> = { severity, message };
  if (fields) {
    for (const [k, v] of Object.entries(fields)) {
      if (v !== undefined) entry[k] = v;
    }
  }
  const line = JSON.stringify(entry);

  // Cloud Logging への severity 伝達は JSON フィールドが Single Source of Truth。
  // ただし stream を分けておくと、stdout/stderr を直接 tail したときの可読性も維持できる。
  if (severity === 'CRITICAL' || severity === 'ERROR') {
    console.error(line);
  } else if (severity === 'WARNING') {
    console.warn(line);
  } else {
    console.info(line);
  }
}

export const logCritical = (msg: string, fields?: Record<string, unknown>) =>
  log('CRITICAL', msg, fields);
export const logError = (msg: string, fields?: Record<string, unknown>) =>
  log('ERROR', msg, fields);
export const logWarning = (msg: string, fields?: Record<string, unknown>) =>
  log('WARNING', msg, fields);
export const logInfo = (msg: string, fields?: Record<string, unknown>) =>
  log('INFO', msg, fields);

設計判断のポイント

地味ですが効いてくる判断がいくつかあります。

severity ごとに console.error / warn / info を出し分ける

Cloud Logging の severity 判定は JSON 内の severity フィールドが効くので、極論すべて console.log に流しても監視は機能します。それでもストリームを分けているのは、

  • ローカルで node ./dist/index.js 2>err.log のように stderr だけ拾ったときに、想定通り CRITICAL/ERROR だけ取れる
  • Cloud Run の Logs Explorer 側でも logName のサフィックスが stderr か stdout かで補助的にフィルタできる

という運用上の理由です。「JSON があるから stream は何でもいい」というのは正論ですが、運用に入ると stream の意味が効いてくる場面が必ず出てきます。

undefined のフィールドは出力から除外する

JSON 上に "messageId": null のようなノイズが乗ると、ダッシュボードのログ表示が読みづらくなります。undefined を黙って落とす実装にしておくと、呼び出し側で「ある時だけ付ける」フィールドを気軽に渡せます。

第2引数 fields の運用ルールを決めておく

ここは長期で効いてくるところです。fields を使うと自由にキーが増やせるので、つい「検索に便利だから」と event / workerRole / deliveryAttempt のような属性をどんどん詰めたくなります。

しかし「設計書で明示要求されているフィールドだけ載せる」というルールを引かないと、

  • 設計書 / 実装 / テスト / メトリクスフィルタ の4箇所で同じキーを管理する羽目になる
  • 「Pub/Sub の payload 全文を入れたい」「いや個人情報が乗るから入れない」という議論が後を絶たない

ことになりがちです。今回のワーカーでも、最初は気を利かせて event や workerRole を入れていましたが、レビューで「その根拠はどこ？」と突っ込まれて、最終的に「設計書で payload 必須と書かれた3箇所のみ fields を使う、それ以外は severity + message のみ」というルールに収束しました。

実装2: Error オブジェクトの情報損失を避ける

console.error を機械的に logError に置き換えるときに、もう1つ落とし穴があります。

Before:

subscription.on('error', (error) => {
  console.error('Subscription error:', error.message);
  console.error(error);  // ← これが地味に効いている
  healthServer.setError(`Subscription error: ${error.message}`);
});

素朴に置き換えた After:

subscription.on('error', (error) => {
  logWarning(`Subscription error: ${error.stack ?? error.message}`);
  healthServer.setError(`Subscription error: ${error.message}`);
});

console.error(error) を消すと、error.cause や AggregateError の errors 配列など、Node.js が console.error 経由で自動展開してくれていた情報がごっそり消えます。error.stack だけだと、Pub/Sub クライアントが投げる「内部で別エラーをラップしている」系の不具合が追えなくなります。

正解 After:

import { inspect } from 'node:util';

subscription.on('error', (error) => {
  // util.inspect は error.cause / AggregateError の sub-errors も展開するため、
  // 元の console.error(error) と同等の情報量を保てる。
  logWarning(`Subscription error: ${inspect(error, { depth: null })}`);
  healthServer.setError(`Subscription error: ${error.message}`);
});

util.inspect(error, { depth: null }) を1行にまとめれば、改行混じりの情報量を保ちつつ JSON ログの message に格納できます。Cloud Logging はこの message をクリックすると改行込みで展開してくれるので、可読性も問題ありません。

Terraform 側との突き合わせ:「IaC のフィルタが何を見ているか」を確認する

ここまでがアプリ側の話で、ここからは Terraform 側との整合性の話です。

監視ワーカーのダッシュボードは Terraform で IaC 管理されていて、*.tf および参照される dashboard 定義 JSON にこんなメトリクスフィルタが書かれていました。

# 例: ERROR エントリ数の集計ウィジェット
filter = <<-EOT
  metric.type="logging.googleapis.com/log_entry_count"
  resource.type="cloud_run_worker_pool"
  metric.label."severity"="ERROR"
EOT

# 例: severity >= 600 全件通知用ウィジェット
filter = <<-EOT
  metric.type="logging.googleapis.com/log_entry_count"
  resource.type="cloud_run_worker_pool"
  metric.label."severity"=monitoring.regex.full_match("(CRITICAL|ALERT|EMERGENCY)")
EOT

ポイントは、metric.label."severity"="ERROR" のラベルが LogEntry の severity フィールドそのものを参照していることです。つまり、

  • アプリ側のログが {"severity": "ERROR", ...} を出力していれば、このフィルタにヒットする
  • アプリ側が console.error('...') のままだと、severity は推定任せになるので、フィルタが拾えるかは Cloud Logging の気分次第

そして、アプリ側のログ実装が壊れていても Terraform はそれを検知できません。terraform plan / validate / tflint は通るし、CI も普通にパスします。

突合の手順

実装変更時にやるべき突合チェックは、最低でも次の3点です。

1. ダッシュボード/アラート定義の中の severity フィルタを列挙する

# tf 定義と、参照される dashboard JSON の両方から拾う
grep -RnE 'metric\.label\."severity"' infra/terraform/

「どの severity が監視されているか」を最初に確認すれば、アプリ側が出すべき severity の集合が決まります。今回の例なら ERROR と CRITICAL 以上の数値範囲、の2つです。

2. アプリのログ出力が、その severity を実際に出すかをユニットテストで検証する

vi.spyOn(console, 'error') で文字列マッチしていた既存テストは、構造化JSONに変更すると軒並み落ちます。これは悪いことではなく、「アプリの出力フォーマットが変わったらテストが落ちる」という防壁がちゃんと機能している証拠です。

テスト側は exact-string 一致ではなく、JSON.parse でフィールドの存在と値を検証する形に書き換えます。

it('logCritical は severity=CRITICAL の JSON を console.error に出す', () => {
  const spy = vi.spyOn(console, 'error').mockImplementation(() => {});
  logCritical('boom');
  expect(spy).toHaveBeenCalledOnce();
  const parsed = JSON.parse(spy.mock.calls[0][0]);
  expect(parsed).toEqual({ severity: 'CRITICAL', message: 'boom' });
});

こうしておくと、誰かがうっかり severity の綴りを変えたり、JSON 形式を崩したりした場合に即座に CI で落とせます。

3. ステージング環境で実際にメトリクスが動くことを確認する

これが意外と抜けがちです。ローカルでテストが通っても、Cloud Run にデプロイした実環境で、

  • アプリのログが Cloud Logging エクスプローラで severity: ERROR として表示されるか
  • ダッシュボードのウィジェットがそのログを拾って数値が増えるか

を必ず目視確認します。今回は、デプロイ後に意図的に JSON_PAYLOAD 不正の Pub/Sub メッセージを1件流して、ERROR メトリクスがインクリメントされる様子を確認しました。

落とし穴チェックリスト

実際にやってみて踏んだ穴をまとめておきます。

ハマり1: console.warn を残しても WARNING にはならない

「console.warn なら WARNING になるでしょ」と思いがちですが、Cloud Run の stderr 推定では WARNING にならないケースがほとんどです。severity フィールド付き JSON で出さない限り、WARNING と ERROR の区別はつきません。console.warn を残すと、ダッシュボードの ERROR グラフを汚し続けます。

ハマり2: payload に envelope を全部入れると個人情報が漏れる

「検索のために Pub/Sub の message 全体を JSON にぶち込もう」というアイデアは便利そうに見えますが、ackId や data に個人情報・顧客情報が乗っているケースがあります。Cloud Logging の _Default ログバケットは LogEntry をデフォルトで 30 日保持します（カスタム設定で 1〜3650 日に変更可能）。そのため、ログに個人情報を吐き出した時点で、保持期間中ずっとそのまま残り続けるという点は意識しておく必要があります。

回避策としては、

  • payload 出力は明確に必要な箇所（DLQ で破棄するときの監査ログなど）に限定する
  • payload を載せる場合はマスキングルールを別関数で定義し、必ず通す
  • 本番環境では payload 出力を環境変数でオフにできる仕様にしておく

など、運用ポリシーごと決めてから実装します。

ハマり3: テスト依存の更新を見落とすと、テストファイル全部書き換えに巻き込まれる

vi.spyOn(console, 'error') で toHaveBeenCalledWith('expected literal string') のような exact-string match をしているテストは、構造化JSONへの移行で全件落ちます。事前にどのテストファイルが console をスパイしているか、grep で洗い出してから着手するのが安全です。

grep -RnE "vi\.spyOn\(console" src/

ハマり4: 「設計書根拠のないフィールドを増やさない」運用を最初から決める

これは設計判断のところでも書きましたが、実装ヘルパーに fields を生やしてしまうと、つい便利フィールドが増えていきます。レビュー時に「このキーは設計書のどこに書かれていますか？」を問う習慣を作っておくと、長期で見たログフォーマットの肥大化を防げます。

運用フロー: ログ変更を「監視が壊れない」状態で出すには

今回の作業で固まった運用フローは次の6ステップです。

  1. 設計書を先に直す: severity マッピング表を更新する。実装より先に Single Source of Truth を確定させる
  2. 構造化ログヘルパーを用意する: log() + 薄いラッパ。severity ごとに console.error/warn/info を出し分け
  3. 既存 console.* を機械的に置換: ただし console.error(error) 系は util.inspect への置換を別途検討
  4. テストを JSON.parse ベースに書き換える: exact-string match からの脱却
  5. Terraform 側のメトリクスフィルタを grep: アプリ側が出すべき severity の集合と整合しているかを目視確認
  6. ステージングで E2E 確認: 実際にダッシュボードが反応することを確認してから本番へ

このフローで進めれば、「ログは出ているのに監視は動かない」状態に戻ることはなくなります。

おわりに

「Cloud Run + Node.js でログが ERROR 一色になる」問題は、Cloud Logging のドキュメントを読めば書かれている話で、知っている人にとっては当たり前です。ただ、

  • 設計書では severity を分けている
  • 実装では console.* を分けている
  • 監視は Terraform で IaC 化されている

の3つが揃っている現場でも、severity が分かれていないことに気づくのは、ダッシュボードを見て「あれ？」と思った瞬間まで遅延しがちです。CI も terraform plan も tflint も、このズレを教えてくれません。

似た構成のチームには、まず console.* を構造化ログヘルパーに巻き取るところから始めるのがおすすめです。Terraform 側のフィルタを書き直す必要がないので、影響範囲がアプリレイヤーに閉じてくれます。今回のケースでも、Terraform 側の修正は 0 行で監視が動き出しました。

最後に、次のアクションをひとつだけ挙げるなら、自分のプロジェクトの Terraform / dashboard JSON を grep 'severity' してみることです。そこに書かれている severity の集合と、アプリが実際に出している severity の集合が一致しているか — それが「監視が動いているかどうか」の最初のチェックポイントです。

最後に、GMOコネクトではサービス開発支援や技術支援をはじめ、幅広い支援を行っておりますので、何かありましたらお気軽にお問合せください。

お問合せ：https://gmo-connect.jp/contactus/

5
2
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
5
2

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?