Skip to main content

Server log

Overview

サーバーに実装するログやトレーシングについてまとめているセクション。

「ログ」は、組織のシステムおよびネットワーク内で発生するイベント(事象)の記録である。ログは複数のログ項目から構成される記録であり、個々のログ項目は、システムまたはネットワークにおいて発生する特定の1件のイベント(事象)に関連した情報を含む。組織におけるログの多くは、コンピュータセキュリティに関する記録を含む。これらのコンピュータセキュリティのログは、数多くの情報源によって生成される。たとえば、ウイルス対策ソフトウェア、ファイアウォール、侵入検知および防止システムなどのセキュリティソフトウェアや、サーバ、ワークステーション、ネットワーク装置上のオペレーティングシステム、およびアプリケーションなどである。 コンピュータセキュリティログ管理が必要となっている。コンピュータセキュリティログ管理とは、コンピュータセキュリティログデータの生成、通信、格納、分析、廃棄するプロセスのことである。

ログとトレースの違い

  • ログ: 離散的なイベントの記録(構造化JSON推奨)。検索・集計・監査に強い。
  • トレース: リクエスト/ジョブの時系列。スパンの集合で遅延や依存関係を可視化。
観点ログトレース
主目的事実の記録・監査証跡・検索経路の可視化・遅延/失敗の特定
単位ログ行(イベント)トレース(TraceId)とスパンの集合
ひも付けrequest_id/user_id 等で後付け集約TraceId/SpanId による自動関連付け
粒度任意(INFO/ERROR 等)。多すぎると騒音サービス境界/外部I/O/重要な業務イベント中心
可視化/クエリgrep/SQL/ログ基盤(CloudWatch Logs, Loki など)トレーサー/ビューア(Jaeger, Tempo, X-Ray など)
保管の性質長期保管(監査/法令対応)しやすい高コストのため短期+サンプリングが基本

使い分けの指針

  • 監査・会計・セキュリティ証跡 → ログ
  • 遅延/失敗の経路を素早く特定 → トレース
  • エラー時は 両方: エラーログに trace_id を必ず出す(相関可能にする)

実装メモ(例)

  • ログ: 構造化JSON+相関ID(request_id, event_id, user_id など)を一貫出力
  • トレース: OpenTelemetry の自動計装+“境界”だけ in_span を追加(外部I/O・重要な状態遷移)
# Rails 例: エラーログに trace_id を含める
trace_id = OpenTelemetry::Trace.current_span.context.trace_id
Rails.logger.error(base_ctx(event: "payment.failed").merge(trace_id: trace_id, message: e.message))
// Node.js 例: pino のログに trace_id を混ぜる
import pino from 'pino'
import { context, trace } from '@opentelemetry/api'

const logger = pino()
const span = trace.getSpan(context.active())
const traceId = span?.spanContext().traceId
logger.error({ event: 'payment.failed', trace_id: traceId, err }, 'payment failed')

ユビキタス

  • メトリクス(測定・基準・尺度・計量)などを意味する。 metrics

ログの適切な取得と保管

総務省が書いているやつ

  • ログの保管とバックアップ

    • ログは、収集した機器の本体内ではなく、ログ取得のために別途ログ管理システムなどを設計し、そこで保管を行うことが推奨されます。そうすることで、ログの改ざんなどの不正行為からの保護だけでなく、ログ解析プログラムによる可視化処理を行ったり、保存期間の制御なども行いやすくなります。
      また、一定期間を経過したログの保管方法として、コストや保存期間を考慮し、外部記憶媒体等に保管する運用も検討しましょう。通常のデータのバックアップと同様に、ログのバックアップも重要になります。
  • ログの取り扱いの注意

    • ログには、誰と誰がいつどのような内容の通信を行ったか、という情報が記録されています。また、企業秘密に関する情報や、電子メールの内容、利用者が入力した個人情報などがそのまま含まれている場合もあります。ログは機密情報であるということを理解し、取り扱いには十分な注意が必要です。
    • たとえば、外部のセキュリティ調査会社にログを開示して調査を依頼する際にはログの内容に関して秘密保持契約を結んだり、ログを外部に持ち出さなければならない際にはデータの暗号化を検討するなど、秘密の保全に関する対応が必要であることを理解しましょう。

監査とコンプライアンスに適合するための要件

監査とコンプライアンスに適合するための要件

  • 関連するログを集中して記録すること
  • 適時にログを閲覧できること
  • ログの重要度等に応じて保存すること
保存期間法令・ガイドライン等
1か月間刑事訴訟法 第百九十七条 3「通信履歴の電磁的記録のうち必要なものを特定し、三十日を超えない期間を定めて、これを消去しないよう、書面で求めることができる。」
3か月間サイバー犯罪に関する条約 第十六条 2「必要な期間(九十日を限度とする。)、当該コンピューター・データの完全性を保全しおよび維持することを当該者に義務付けるため、必要な立法その他の措置をとる。」
1年間PCI DSS 監査証跡の履歴を少なくとも 1 年間保持する。少なくとも3 か月はすぐに分析できる状態にしておく。
3 年間不正アクセス禁止法違反の時効。
5年間内部統制関連文書、有価証券報告書とその付属文書の保存期間に合わせて。電子計算機損壊等業務妨害罪の時効。

ログの保存期間

「結局アクセスログってどれくらい保存しておけばいいの?」に答える関係法令
セキュマカ: アクセスログを取得することの重要性とは?保存期間やポイントも解説

出力レベルの考え方

log level log perfectガイド

ロギングはプログラムで何が起こっているかを把握するためのもっとも効果的な手法の1つ。
さらに、構造化ログにより、トレースとフィルタリングが改善される。

log監視ツールが色々あるためそれをまとめる。

ログと言っても色々ある

  • メトリクス収集
  • ロギング
  • 可視化
  • アラート通知

ロギング行為の基本

参考URL

開発環境では許可されることが、実稼働環境では許可されないことがあります。例えば、開発環境ではデバッグのためにエラーの詳細なロギングを実行できますが、同じ動作が実稼働環境ではセキュリティー上の問題となります。

  • 開発環境と本番環境で分ける。
  • 本番で出すことはセキュリティー状の問題となってしまう場合がある

ログレベル

おそらくほとんどのライブラリで使用するのではないか。 all < trace < debug < info < warn < error < fatal < mark < off

開発者のためのロギング

参考URL

一般的に、ある時点で起こったイベントとその時刻を記録することをロギングと呼びます。Web アプリケーションの場合は、Web サーバーのアクセスログやアプリケーションサーバーの実行ログ、及びエラーログなどを記録して、ストレージやログ集約サービスに永続化し、活用する仕組み全体を指していることが多いです。

ログを収集する目的はさまざまですが、いくつか例をあげると次の通りです。 セキュリティ要件を満たすためにアクセスログを長期間保存したい 不具合を調査するためにアプリケーションのエラーログを検索したい アクセスログの統計情報をとってダッシュボードに表示したい

ログの出し方

基本的にログを出す時は流れでわかるようにせず1行で完結する形が好ましいです (DB: liver id: xx、DB: token: xx、みたいに、あと行を分けず全部1行で出していいと思います) 現在は複数プロセスが一つのログに前後混ざることがないですが そういう処理を作る場合にこの書き方に慣れていると処理を追いにくい、追えないログになってしまいます またgrepなどで検索する際にも前後を出さないといけなくなってしまいます

細かいところはリファクタリングのフェーズでいいと思いますが loggerの機能でできる部分と合わせて日時、ログ種別(info,warning,error)、PID、ログ内容、あとはログ発生タスクやUtilなどがわかるようになっていると検索性も良くなるので意識してもらえるといいと思います

ログ出力の設計において、「いつ」ログを出力するかは、アプリケーションのデバッグや監視のニーズに依存します。関数(またはアクション)の先頭でログを出力する場合と、処理の終了時や重要なイベント発生後にログを出力する場合があります。各アプローチには、それぞれ利点と適用シナリオがあります。

関数の先頭でのログ出力

  • 利点: 関数が呼び出されたという事実を記録できます。また、関数への入力パラメーターをログに記録することで、デバッグ時に何が関数に渡されたかを容易に追跡できます。
  • 適用シナリオ: デバッグ時やシステムの挙動を理解するために、関数の呼び出しパターンや呼び出し頻度を知りたい場合に適しています。

関数の結果や処理の終了時でのログ出力

  • 利点: 関数の実行結果や処理の成否を記録できます。エラーハンドリングや成功した操作の詳細をログに記録でき、システムの正常性や問題の診断に役立ちます。
  • 適用シナリオ: エラーの診断、処理の成否の監視、特定のイベント後のシステムの状態を把握したい場合に適しています。

あなたのシナリオ

あなたが示したコードでは、関数の途中でログを出力しています。これは、特定の処理ポイントでの情報収集や状態の記録を目的としている可能性があります。関数内でのログ出力は、次のような目的で有用です:

  • 関数の実行フローの追跡: とくに複雑なロジックや条件分岐が多い関数では、どのパスが実行されているかを確認するためにログを出力することが有効です。
  • 重要なイベントの記録: 処理の途中で特定の条件が満たされた場合や、重要な処理ステップが完了した場合にログを出力して記録します。

関数内でログを出力する際は、ログの量と質を適切に管理することが重要です。不必要に多いログは情報の洪水を引き起こし、本当に重要な情報を見落とす原因になり得ます。また、ログには実行コンテキストに関連する十分な情報を含めることが望ましいです(ただし、セキュリティやプライバシーに配慮して)。最終的に、ログ出力戦略は、アプリケーションの要件、開発および運用チームのニーズ、そして利用可能な監視・分析ツールによって形成されるべきです。

3つのフェーズで導入する

  • ログ出力 アプリケーションがどういう形でログを出力して、どう記録されるか
  • ログローテート 無尽蔵に増えるログに対してどう対処するか
  • ログ集約 どうやってストレージや外部サービスにログを永続化するか

RestAPIでのログの出しかた。

アプリケーション全体で繰り返したくないログ行がある。
HTTP APIを提供するアプリケーションの場合、着信要求ごとに常にログ行があると便利です。
このようにして、一部のエンドポイントでこのログ行が忘れられたり、ログが構造的に異なったりすることを回避します。

これを実現するために、Express.js ミドルウェアをプレリクエスト ハンドラーとして定義する。

※デフォルトでは、すべてのヘッダーとクエリパラメーターがログに記録されます。 そのため、アクセストークンを送信する際には注意してください。認証に関する後の投稿で、デフォルトのシリアル化を変更して、ログからアクセス トークンを除外します。

logでのトランスポート

ログでのトランスポートは、ログメッセージを処理して出力するための外部プログラムやサービスを指す。
通常、ログメッセージは標準出力(stdout)に送られますが、トランスポートを使用することで、これらのログメッセージをさまざまな形式で加工したり、異なる出力先(たとえば、ファイル、リモートのログ収集サービスなど)に送ったりできる。

Pinoでは、pino-prettyのようなトランスポートを使用して、ログの出力を読みやすくフォーマットすることが一般的な使用例です。しかし、Pino v7以降では、トランスポートの扱いが変更され、子プロセスとして実行されるようになりました。これにより、メインのアプリケーションプロセスのパフォーマンスに影響を与えずに、ログ処理を行うことができます。

const pino = require('pino');

const logger = pino({
name: 'nid-backend',
level: process.env.NODE_ENV === 'production' ? 'info' : 'debug',
});

logger.info('This is an info message');

この方法では、ログメッセージは標準出力に送られ、トランスポートを使用する場合に見られる子プロセスの起動は行われません。これにより、特定の実行環境での互換性の問題を避けることができます。

シングルトレーシング

モノリスなアプリケーションの対してトレーシングすること(一枚岩)

分散トレーシング

参考URL(Goでの実装)

分散トレーシングとは分散されたアーキテクチャアプリケーションを監視するための手法。 マイクロサービスのような複数システムから構成されるアーキテクチャでは複数のサービスを跨いで処理が動くため、全体の振る舞いを把握することが難しい課題。 。 また、障害発生時に原因を特定することも困難です。 分散トレーシングの手法を用いることで、サービス間をまたいだ処理の計測や可視化が可能になり、それら課題の解決に繋がります。

用語

  • トレース(Trace) トレースはアプリケーションがリクエストを処理するのに費やした時間と、このリクエストのステータスを追跡するために使用されます。各トレースは、ひとつまたは複数のスパンで構成されます。

  • スパン(span) スパンは、特定の期間における分散システムの論理的な作業単位を表します。複数のスパンでトレースが構成されます。

各サービスにおける処理の単位がスパンで表され、複数のスパンで構成される一連の全体処理がトレースで表されます。

DatadogとSentryの違い

両方導入している会社の話

Datadogはアラートモニタリングサービス。 Sentryはアプリケーションモニタリング&エラートラッキングサービス。 一部重複する機能はあるが、Sentryを導入することでユーザー体験や開発効率を向上させることができると思う。

Correlation ID

Correlation IDは、1つのリクエストやトランザクションを通してログを追跡可能にするための一意の識別子
分散アーキテクチャやマイクロサービス構成のシステムにおいて、各サービス間のログを関連付ける目的で使用される。

たとえば、ユーザーのリクエストがサービスA → サービスB → サービスC と渡る場合、Correlation IDがすべてのサービスのログに含まれていれば、「この3つのログは同一リクエストに属している」と特定できる。

主な特徴と利点

  • ログトレースの簡素化:1つのIDで関連ログを簡単に抽出可能
  • 障害調査の効率化:障害の発生箇所と流れを追いやすくなる
  • モニタリングツールとの統合:Datadog や Sentry、OpenTelemetry などと併用することで、トレーシングとログの相関が取れる

一般的な実装方法

  • HTTPヘッダー(例:x-correlation-id)でリクエスト間にIDを伝搬
  • リクエスト開始時にIDを生成し、レスポンスや内部ログにも添付
  • Node.js(ExpressやNestJS)では、pino-httpnestjs-pino を使うと簡単に実現可能
// NestJS + pino-http での例
pinoHttp: {
genReqId: (req) => req.headers['x-correlation-id'] || uuidv4(),
customProps: (req) => ({
correlationId: req.headers['x-correlation-id'] || req.id,
}),
}

注意点

  • セキュリティとプライバシーの観点から、Correlation IDにはユーザー識別子や機密情報を含めない
  • 開発と本番で出力先や記録対象を適切に切り替える

Pino v7以降のtransportの詳細解説

Pino v7からは、ログ出力の柔軟性とパフォーマンスを両立するために、transportという新しい構成が導入された。
これはログ処理を子プロセスにオフロードすることで、アプリケーションのメインスレッドのブロッキングを回避する仕組み。

tip

ここでの「オフロード(offload)」という表現は、**処理の一部をメインの実行単位(この場合はNode.jsのメインスレッド)から分離して、別の実行単位(=子プロセス)に“肩代わりさせる”**という意味。

transport: {
target: 'pino-pretty',
options: { translateTime: true },
}

この設定を使うと、pino-pretty は子プロセスとして実行される。
つまり「logger.info(...) は非同期的に整形されて出力される」=ログ出力がバックグラウンド化される、という意味。

基本構成

import pino from 'pino';

const logger = pino({
transport: {
target: 'pino-pretty',
options: {
translateTime: true,
colorize: true,
},
},
});

各プロパティの意味

  • target: 使用するトランスポートモジュール名。たとえば 'pino-pretty''pino/file' など。
  • options: トランスポートに渡す構成オプション。整形や出力先の制御に使う。

よく使う target の例

target名説明
pino-pretty人間が読みやすい整形ログ。開発用。
pino/filestdout や stderr に出力するトランスポート。
カスタムモジュール自作の変換処理を含むトランスポートも指定可能。

本番環境(Docker + ECS)のおすすめ構成

ECSなどのコンテナ環境では、標準出力(stdout)にJSONログを出してCloudWatch Logsに連携するのが一般的。
そのため、以下のように pino/file を使って、非同期で stdout に出力するのが推奨される。

transport: {
target: 'pino/file',
options: {
destination: 1, // stdout
sync: false, // 非同期で高速処理
},
}

なぜ sync: false にするのか?

  • ログ出力をバッファリングして非同期で行うことで、レスポンス処理への影響を抑える
  • 高頻度アクセス時でもログI/Oがボトルネックになりにくくなる

注意点

  • トランスポートを使うと、内部的に子プロセスが起動する。これは監視対象のプロセス数が制限される環境では注意が必要。
  • pino-pretty は開発用。本番ではJSONログ+stdoutが基本

このように、Pinoの transport は、環境ごとに適切な出力形式・出力方法を選択し、ログのパフォーマンスと可観測性を両立させるための重要な構成要素である。

ログどこに置くべきか(実用ガイド)

まずは INFO/ERROR で回し、必要時に DEBUG を一時的に入れる”運用が騒音を抑えつつデバッグもしやすいです

まとめ • すべての関数に start/success は不要。“境界”だけスパンを置く。 • 共通ヘルパで start/success/error+duration を一貫出力。 • 追跡は 相関ID を必ず付与。 • さらに可視化したければ OpenTelemetry を併用。

この方針でいけば、ログのノイズを抑えつつ“追える”状態になります。パッチ化して入れたい場合は言ってくれれば、既存コードに合わせて差分つくるよ。

  • 全部の関数で start/success を出す必要はない。
  • “境界”にだけスパン(start/end)を置くのが実務的なベストプラクティス。
  • 入口(外部からの呼び出し点=publicメソッド)
  • 外部I/O(DB、外部API、ロック、キュー投入)
  • 重要な状態遷移(課金確定・ライセンス発行などビジネスイベント)
  • それ以外の細かいヘルパーはスパンは不要。必要なら DEBUG で一時的に出す。
tip

深いスタックを全部 start/success で埋めるより、上記の“境界”にスパンを置けば実運用で十分に追える。
細部の可視化が必要になったら、その時だけ一段下の関数にスパンを追加する“段階的深掘り”が良い。

caution

小さな純ロジック:条件分岐や小さなパーサーは基本ログ不要(ノイズ増える)

実装パターン(最小ヘルパー)

def with_span(event:, extra: {})
started = Process.clock_gettime(Process::CLOCK_MONOTONIC)
Rails.logger.info(info_to_hash("start", extra.merge(event:)))
yield.tap do |result|
dur = ((Process.clock_gettime(Process::CLOCK_MONOTONIC) - started) *1000).round
Rails.logger.info(info_to_hash("success", extra.merge(event:, duration_ms: dur)))
result
end
rescue => e
dur = ((Process.clock_gettime(Process::CLOCK_MONOTONIC) - started)* 1000).round
Rails.logger.error(error_to_hash(e, extra.merge(event:, duration_ms: dur)))
raise
end

# 共通の文脈(kind, request_id, event_id, user_id, など)は別ヘルパで束ねると楽です。
def base_ctx(extra = {})
{
kind: self.class.name,
request_id: Current.request_id,
user_id: webhook_data.dig(:event, :app_user_id),
event_id: webhook_data.dig(:event, :id),
product_id: webhook_data.dig(:event, :product_id),
}.compact.merge(extra)
end

# 使い方
def call
with_span(event: "subscription_extended.call", extra: base_ctx) do
handle_subscription_extended
end
rescue ::RevenueCat::InvalidEventError => e

W3C Trace Context(traceparent) or X-Request-Id

結論:W3C Trace Context(traceparent) or X-Request-Id を“共通の相関ID”として全経路で伝搬、Rails/ジョブ/外部HTTP/フロントすべてに仕込むのが王道です。まずは“ログ相関”で導入→あとでAPM(Datadog/OpenTelemetry)接続に拡張しやすい形にしておくのが良い。

推奨アーキテクチャ(段階導入)

Phase 1: ログ相関(最短で効果出す) • ID形式: UUID v4(将来OTel移行なら traceparent も同送) • 共通ヘッダ: X-Request-Id(既存Rails互換)+余力があれば traceparent • 生成ポリシー: • クライアント(Web/モバイル)が生成 → すべてのAPI/GraphQL/gRPCにヘッダ添付 • 無い場合はエッジ or Railsが生成(どこかで必ず付く) • ログ整形: すべてのログに correlation_id を必ず入れる

Phase 2: 伝搬の徹底 • Web→Rails: ミドルウェアで受け取り、Current.correlation_id に格納、レスポンスにも返す • Rails→外部HTTP: Faraday/Net::HTTP にインターセプタを入れてヘッダを必ず付与 • 非同期(Sidekiq/ActiveJob): エンキュー時にIDをメタに入れて、ジョブ側で Current に復元 • Webhook(Stripe等): 外部からはID来ないので、受信時に生成。以後は全ログに付与

Phase 3: トレーシング(任意) • OpenTelemetry SDK + Datadog Exporter を入れると trace_id/span_id が traceparent と連動 • ログ→トレースの相互リンク(ログ側に trace_id を出す、Datadogでワンクリック)

実装スニペット

1) Rails: ミドルウェア(相関IDの受け取り&生成)

# config/initializers/correlation_id.rb

module Correlation
HEADER = "X-Request-Id" # まずはこれ。将来 traceparent 併用もOK
end

# app/middleware/correlation_id_middleware.rb

class CorrelationIdMiddleware
def initialize(app)
@app = app
end

def call(env)
req = Rack::Request.new(env)

incoming = req.get_header("HTTP_#{Correlation::HEADER.tr('-', '_').upcase}")
# traceparent優先したい場合はここでW3Cフォーマットを検証・復元してもOK
correlation_id = (incoming.presence || SecureRandom.uuid).to_s

# CurrentはRequestStore等でスレッドローカル管理
Current.correlation_id = correlation_id

# Railsの既定X-Request-Idにも合わせておくと各種ミドルウェア互換性が高い
env["action_dispatch.request_id"] ||= correlation_id

status, headers, body = @app.call(env)
headers[Correlation::HEADER] ||= correlation_id
[status, headers, body]
ensure
Current.reset # 後始末
end
end

config/application.rb

config.middleware.insert_before ActionDispatch::RequestId, CorrelationIdMiddleware
# app/models/current.rb
class Current < ActiveSupport::CurrentAttributes
attribute :correlation_id, :user_id
end
# 2) ログ出力に必ず載せる(構造化ログ)
# info_to_hash/error_to_hash で correlation_id を自動混入:

module Logs
module Utils
def self.info_to_hash(event, detail = {})
base = { event:, correlation_id: Current.correlation_id }.compact
base.merge(Hash(detail))
end

def self.error_to_hash(error, detail = {})
{
level: "error",
correlation_id: Current.correlation_id,
error_class: error.class.name,
error_message: error.message,
backtrace: Array(error.backtrace)&.first(5),
}.merge(Hash(detail))
end
end
end
with_span との連携
• 既に with_span で event_id を扱っているなら、デフォルトは Current.correlation_id を採用し、extra[:event_id] があればそれを上書き。

def with_span(event:, extra: {}, start_level: :info, success_level: :info)
started = Process.clock_gettime(Process::CLOCK_MONOTONIC)

correlation = extra[:event_id] || extra[:correlation_id] || Current.correlation_id || SecureRandom.uuid
Current.correlation_id = correlation # ここで確実にセット(ネスト時は同一IDで継続)

base = Hash(extra).merge(event:, event_id: correlation)

Logs::Utils.log_with_level(start_level, info_to_hash("start", base))

yield(correlation).tap do
dur = ((Process.clock_gettime(Process::CLOCK_MONOTONIC) - started) *1000).round
Logs::Utils.log_with_level(success_level, info_to_hash("success", base.merge(duration_ms: dur)))
end
rescue => e
dur = ((Process.clock_gettime(Process::CLOCK_MONOTONIC) - started)* 1000).round
Logs::Utils.log_with_level(:error, error_to_hash(e, base.merge(stage: "error", duration_ms: dur)))
raise
end
3) 外部HTTP(例: Faraday)
Faraday.new(url: base_url) do |f|
f.request :json
f.response :json
f.request :retry
f.request :instrumentation

# 伝搬

f.request :authorization, "Bearer", token
f.use ->(app) {
Class.new(Faraday::Middleware) {
def call(env)
cid = Current.correlation_id || SecureRandom.uuid
env.request_headers["X-Request-Id"] = cid
@app.call(env)
end
}.new(app)
}
end
# config/initializers/sidekiq.rb
# 4) Sidekiq/ActiveJob(入出キューで伝搬)
module Sidekiq
class CorrelationClient
def call(_worker_class, job, _queue,_redis_pool)
job["correlation_id"] ||= Current.correlation_id || SecureRandom.uuid
yield
end
end

class CorrelationServer
def call(_worker, job,_queue)
Current.correlation_id = job["correlation_id"] || SecureRandom.uuid
yield
ensure
Current.reset
end
end
end

Sidekiq.configure_client { |c| c.client_middleware { |m| m.add Sidekiq::CorrelationClient } }
Sidekiq.configure_server do |c|
c.client_middleware { |m| m.add Sidekiq::CorrelationClient }
c.server_middleware { |m| m.add Sidekiq::CorrelationServer }
end

Resource