本記事で扱う内容
一般的なインターネットWEBシステムにおけるログ出力方針を考えてみました。システム基盤で共通的に出力する項目、業務アプリケーション側のログ出力方針について記載しています。
具体的な実装方法についてはSpringFrameworkを利用している前提で記載していますが、基本的な考え方は技術基盤に関係ないため、参考にしていただけると幸いです。
前提
・具体的な実装方法はSpringBoot利用を想定
・ログ出力にはSLF4J + Logbackを利用
基本方針
1. トレーサビリティの確保
システム全体の可観測性(Observability)を向上させるため、HTTPリクエストやバッチジョブの実行単位といった要求単位ごとに一意の「独自のトレースID」を発行する。
「独自のトレースID」はMDC (Mapped Diagnostic Context) に保持することで、すべてのログレコードで出力する。
・トレースIDは「UUID + “_” + timestamp」で生成する
・加えて、スレッド名(Java標準)もLogback設定により自動出力する。
2.外部インターフェース呼び出しの可視化
業務上重要な予約確定等の外部通信(SOAP/REST)については、障害発生時の迅速な切り分けのため、以下の項目を必ずログ出力する。
出力項目: 処理開始・終了、処理時間、処理結果、リトライ回数、サーキットブレーカー状態。
3.ログレベルの定義
INFO:処理の正常な開始・終了、および主要なチェックポイント。
WARN:業務例外や、リトライによる回復が見込まれる一時的なエラー。
ERROR:システム例外(例:DB接続不能、外部IFダウン、予期せぬRuntimeException)等、管理者による確認や対応が必要な事象。
4.コンテキストの伝搬(非同期処理への対応)
MDCはスレッドローカルを利用するため、スレッドを跨ぐ処理ではコンテキストが消失する。@Async等の非同期実行やマルチスレッド処理を行う箇所においてはTaskDecoratorを実装し、スレッド間でMDCの内容をコピーして引き継ぐこと。
5.セキュリティとプライバシー保護
個人情報保護およびセキュリティの観点から、ログには機密性の高い情報を出力しないこと。送受信されるHTTPリクエスト/レスポンスのペイロードは、個人情報や秘匿情報(パスワード、決済情報等)が含まれる可能性が高いため、原則として出力禁止とする。
共通定義
開始、終了ログの識別子
開始、終了ログの識別子は以下とする。
| 処理種別 | 識別子(開始) | 識別子(終了) |
|---|---|---|
| HTTPリクエスト(画面遷移/Ajax) | REQ-BEG | REQ-END |
| Controller(画面遷移/Ajaxエントリポイント) | CTL-BEG | CTL-END |
| Service | SRV-BEG | SRV-END |
| 外部通信(REST/SOAPクライアント) | EXT-BEG | EXT-END |
| バッチ(ジョブ単位) | JOB-BEG | JOB-END |
| バッチ(ステップ単位) | STP-BEG | STP-END |
| トランザクション | TXN-BEG | TXN-END |
HTTPリクエスト(画面遷移/Ajax)
ログ出力内容
| 出力 タイミング | ログレベル | ログ出力内容 | 実装方式 | 具体的な実装方法 |
|---|---|---|---|---|
| 開始 | INFO | ①トレースID(発行) ②スレッド情報 ③識別子 ④HTTPメソッド ⑤URI | Filterクラス | ・OncePerRequestFilterを拡張・ doFilterInternalのリクエスト処理開始前に出力 |
| 終了 | INFO | ③識別子 ⑥HTTPステータス ※その他は開始ログと同じ | Filterクラス | ・OncePerRequestFilterを拡張・ doFilterInternalのリクエスト処理終了後に出力 |
| 例外発生時 | ERROR | ①トレースID ②スレッド情報 ③例外情報 | Filterクラス | ・OncePerRequestFilterを拡張・例外処理部で出力 |
ログ出力サンプル
[2026-01-24 10:00:00] INFO [TRACE-ID: 123e4567-e89b-12d3-a456-426614174000] [THREAD: main] [REQ-BEG] Method: GET, URI: /api/v1/reservations
[2026-01-24 10:00:01] INFO [TRACE-ID: 123e4567-e89b-12d3-a456-426614174000] [THREAD: main] [REQ-END] Method: GET, URI: /api/v1/reservations, Status: 200Controller(画面遷移/Ajaxエントリポイント)
ログ出力内容
| 出力タイミング | ログレベル | ログ出力内容 | 実装方式 | 具体的な実装方法 |
|---|---|---|---|---|
| 開始 | INFO | ①トレースID ②スレッド情報 ③識別子 ④実行クラス名 ④実行メソッド名 | AOP | 「@Pointcut」と「@Around」を利用し、全てのControllerと RestController を対象にした独自のロギングクラスを作成する。 <例> @Pointcut(“within(@org.springframework.stereotype.Controller *) || within(@org.springframework.web.bind.annotation.RestController *)”) public void controllerMethods() {} @Around(“controllerMethods()”) |
| 終了 | INFO | ③識別子 ※その他は開始ログと同じ | AOP | 同上 |
| 例外発生時 | ERROR | ①トレースID ②スレッド情報 ③例外情報 | AOP | @AfterThrowingで全てのControllerを対象とした独自ログインロギングクラスを作成例: |
ログ出力サンプル
[2026-01-24 10:01:00] INFO [TRACE-ID: 123e4567-e89b-12d3-a456-426614174001] [THREAD: main] [CTRL-BEG] Class: ReservationController, Method: getReservation
[2026-01-24 10:01:01] INFO [TRACE-ID: 123e4567-e89b-12d3-a456-426614174001] [THREAD: main] [CTRL-END] Class: ReservationController, Method: getReservationService
ログ出力内容
| 出力タイミング | ログレベル | ログ出力内容 | 実装方式 | 具体的な実装方法 |
|---|---|---|---|---|
| 開始 | INFO | ①トレースID ②スレッド情報 ③識別子 ④実行クラス名 ⑤実行メソッド名 | AOP | 「@Pointcut」と「@Around」を利用し、全てのServiceを対象にした独自のロギングクラスを作成する。 <例> @Pointcut(“within(@org.springframework.stereotype.Service *)”) public void serviceMethods() {} @Around(“serviceMethods()”) |
| 終了 | INFO | ③識別子 ※その他は開始ログと同じ | AOP | 同上 |
| 例外発生時 | ERROR | ①トレースID ②スレッド情報 ③例外情報 | AOP | @AfterThrowingで全てのControllerを対象とした独自ログインロギングクラスを作成例: |
ログ出力サンプル
[2026-01-24 10:01:00] INFO [TRACE-ID: 123e456...4001] [THREAD: http-nio-8080-exec-1] [SRV-BEG] Class: ReservationService, Method: findBooking
[2026-01-24 10:01:00] INFO [TRACE-ID: 123e456...4001] [THREAD: http-nio-8080-exec-1] [SRV-END] Class: ReservationService, Method: findBooking外部通信(RESTクライアント-WebClient)
ログ出力内容
| 出力タイミング | ログレベル | ログ出力内容 | 実装方式 | 具体的な実装方法 |
|---|---|---|---|---|
| 開始 | INFO | ①トレースID ②スレッド情報 ③識別子 ④通信プロトコル⑤呼び出し先URL ⑥HTTPメソッド⑦エンドポイント名 | ExchangeFilterFunction | WebClientにExchangeFilterFunctionを適用し、リクエスト送信前にログ出力する。 |
| 終了(成功 | INFO | ①トレースID ③識別子 ⑧HTTPステータスコード ⑨処理時間(秒) ⑩処理結果ステータス | ExchangeFilterFunction | 上記と同じExchangeFilterFunction内で、next.exchange(request)の戻り値MonoにdoOnSuccess()を適用。開始時刻との差分から処理時間を算出する。 結果ステータスには「SUCCESS」を出力 |
| 終了(タイムアウト・同時実行数制限・サーキットブレーカー) | WARN | ①トレースID ②スレッド情報 ③識別子 ⑨処理時間(秒) ⑩処理結果ステータス ⑪例外種別 ⑫例外メッセージ ⑬スタックトレース | ExchangeFilterFunction | 上記と同じExchangeFilterFunction内で、MonoにdoOnError()を適用。 「⑩処理結果ステータス」は例外のインスタンス種別によって “TIMEOUT”などを出力 |
| リトライ | WARN | ①トレースID ②スレッド情報 ③識別子 ⑭リトライ要因 | RESTクライアントラッパー内でエラーハンドリング | io.github.resilience4j.retry.RetryRegistry でResilience4jのRetryを監視。 ⑭リトライ要因には、リトライの発生原因となった例外のクラス名(シンプル名) と例外メッセージを出力 |
ログ出力サンプル
[2026-01-24 10:01:00.123] INFO [TRACE-ID: 123e4567-e89b-12d3-a456-426614174001] [THREAD: http-nio-8080-exec-1] [REST-BEG] Protocol: HTTPS, TargetURL: https://api.example.com/booking/search, HttpMethod: POST, EndpointName: /booking/search
[2026-01-24 10:01:00.456] INFO [TRACE-ID: 123e4567-e89b-12d3-a456-426614174001] [THREAD: http-nio-8080-exec-1] [REST-END] TargetURL: https://api.example.com/booking/search, HttpStatus: 200, ProcessingTime: 333ms, ResultStatus: SUCCESSWebClientのトレースID伝播
WebClientのリクエストとレスポンスではスレッドが異なるためReactor Contextを利用してトレースIDを伝搬します。
①FilterでMDCからReactor Contextへ移行
@Component
@Order(Ordered.HIGHEST_PRECEDENCE)
public class TraceIdFilter extends OncePerRequestFilter {
@Override
protected void doFilterInternal(HttpServletRequest request,
HttpServletResponse response,
FilterChain filterChain) {
String traceId = UUID.randomUUID().toString();
// ThreadLocal(MDC)に設定
MDC.put("appTraceId", traceId);
try {
filterChain.doFilter(request, response);
} finally {
MDC.clear();
}
}
}②WebClientでReactor Contextへ伝播
@Configuration
public class WebClientConfig {
@Bean
public WebClient webClient() {
return WebClient.builder()
.filter((request, next) -> {
// MDCから取得
String traceId = MDC.get("appTraceId");
// Reactor Contextに設定して伝播
return next.exchange(request)
.contextWrite(context ->
context.put("appTraceId", traceId)
);
})
.build();
}
}③WebClientLoggingInterceptorでReactor Contextから取得
public class WebClientLoggingInterceptor implements ExchangeFilterFunction {
@Override
public Mono<ClientResponse> filter(ClientRequest request, ExchangeFunction next) {
return Mono.deferContextual(contextView -> {
// Reactor Contextから取得(スレッドが切り替わっても取得可能)
String traceId = contextView.getOrDefault("appTraceId", "UNKNOWN");
log.info("REST Call Start: traceId={}", traceId);
return next.exchange(request);
})
.doOnSuccess(response -> {
// ここは別スレッドで実行される可能性があるので
// Reactor Contextから取得する。
Mono.deferContextual(contextView -> {
String traceId = contextView.getOrDefault("appTraceId", "UNKNOWN");
log.info("REST Call Success: traceId={}", traceId);
return Mono.empty();
}).subscribe();
});
}
}外部通信(SOAPクライアント-Apache CXF)
ログ出力内容
| 出力タイミング | ログレベル | ログ出力内容 | 実装方式 | 具体的な実装方法 |
|---|---|---|---|---|
| 開始 | INFO | ①トレースID ②スレッド情報 ③識別子 ④通信プロトコル ⑤呼び出し先URL ⑥HTTPメソッド ⑦エンドポイント名 | CXF Interceptor (Out) | AbstractPhaseInterceptorを継承したCxfLoggingOutInterceptorを作成。コンストラクタでPhase.PRE_STREAMを指定。 |
| 終了(成功 | INFO | ①トレースID ③識別子 ⑧HTTPステータスコード ⑨処理時間(秒) ⑩処理結果ステータス | CXF Interceptor (In) | AbstractPhaseInterceptorを継承したCxfLoggingInInterceptorを作成。コンストラクタでPhase.RECEIVEを指定。 結果ステータスには「SUCCESS」を出力 |
| 終了(SOAP Fault) | ERROR | ①トレースID ②スレッド情報 ③識別子 ⑨処理時間(秒) ⑩処理結果ステータス(ERROR) ⑪SOAP FaultCod ⑫SOAP FaultString ⑬スタックトレース | CXF Interceptor (InFault) | AbstractPhaseInterceptorを継承したCxfLoggingFaultInterceptorを作成。コンストラクタでPhase.RECEIVEを指定。 結果ステータスには「ERROR」を出力 |
| 終了(タイムアウト・同時実行数制限・サーキットブレーカー) | WARN | ①トレースID ②スレッド情報 ③識別子 ⑨処理時間(秒) ⑩処理結果ステータス ⑪例外種別 ⑫例外メッセージ ⑬スタックトレース | ExchangeFilterFunction | CxfLoggingFaultInterceptor内で、例外種別によって処理結果ステータスを設定。TimeoutException系の場合は”TIMEOUT”、BulkheadFullException(同時実行数制限)の場合は”BULKHEAD_FULL”、CallNotPermittedException(サーキットブレーカー)の場合は”CIRCUIT_OPEN”、それ以外は”ERROR”を設定。 Resilience4jのBulkheadおよびCircuitBreakerについては、Resilience4jEventLoggerクラスで別途イベントリスナーを登録し、BulkheadFullEventやCircuitBreakerOnErrorEventを検知してログ出力。 |
| リトライ | WARN | ①トレースID ②スレッド情報 ③識別子 ⑯リトライ回数 ⑰リトライ理由(例外種別) ⑱リトライ理由(例外メッセージ) | Resilience4j EventListener | RESTクライアントと同じResilience4jEventLoggerクラスで統合管理。RetryRegistryから取得したRetryインスタンスのEventPublisherにonRetry()リスナーを登録。 |
バッチ(ジョブ単位)
ログ出力内容
| 出力タイミング | ログレベル | ログ出力内容 | 実装方式 | 具体的な実装方法 |
|---|---|---|---|---|
| ジョブ開始 | INFO | ①トレースID ②スレッド情報 ③識別子 ④ジョブ名 ⑤ジョブインスタンスID ⑥ジョブ実行ID ⑦ジョブパラメータ | JobExecutionListener | JobExecutionListenerインターフェースを実装したBatchJobLoggingListenerクラスを作成。 |
| ジョブ終了(成功) | INFO | ①トレースID ②スレッド情報 ③識別 ④ジョブ名 ⑥ジョブ実行ID ⑧終了ステータス ⑨処理件数 | JobExecutionListener | JobExecutionListenerインターフェースを実装したBatchJobLoggingListenerクラスを作成 |
| ジョブ終了(失敗) | ERROR | ①トレースID ②スレッド情報 ③識別子 ④ジョブ名 ⑥ジョブ実行ID ⑧終了ステータス ⑫失敗理由 ⑬例外種別 ⑭例外メッセー | JobExecutionListener | JobExecutionListenerインターフェースを実装したBatchJobLoggingListenerクラスを作成。 jobExecution.getAllFailureExceptions()で全ての失敗例外リストを取得。例外リストが空でない場合、最初の例外からexception.getClass().getSimpleName()で例外種別、exception.getMessage()で例外メッセージを取得。jobExecution.getStatus()で失敗理由(FAILED/ABANDONED)を取得。 |
ログ出力サンプル
[2026-01-24 10:00:00.123] INFO [TRACE-ID: 123e4567-e89b-12d3-a456-426614174001] [THREAD: main] [BATCH-JOB-BEG] JobName: bookingProcessJob, JobInstanceId: 1, JobExecutionId: 1, JobParameters: {targetDate=2026-01-24, processType=DAILY}
[2026-01-24 10:05:30.567] INFO [TRACE-ID: 123e4567-e89b-12d3-a456-426614174001] [THREAD: main] [BATCH-JOB-END] JobName: bookingProcessJob, JobExecutionId: 1, ExitStatus: COMPLETED, ProcessedCount: 10000バッチ(ステップ単位)
ログ出力内容
| 出力タイミング | ログレベル | ログ出力内容 | 実装方式 | 具体的な実装方法 |
|---|---|---|---|---|
| ステップ開始 | INFO | ①トレースID、②スレッド情報、③識別子、④ジョブ名、⑥ジョブ実行ID、⑯ステップ名、⑰ステップ実行ID | StepExecutionListener | StepExecutionListenerインターフェースを実装したBatchStepLoggingListenerクラスを作成。 |
| ステップ終了(成功) | INFO | ①トレースID ②スレッド情報 ③識別子 ④ジョブ名 ⑥ジョブ実行ID ⑯ステップ名 ⑧終了ステータス ⑱読込件数 ⑲書込件数 ⑳スキップ件数 ㉑コミット件数 | StepExecutionListener | StepExecutionListenerインターフェースを実装したBatchStepLoggingListenerクラスを作成 |
| ステップ終了(失敗) | ERROR | ①トレースID ②スレッド情報 ③識別子 ④ジョブ名 ⑥ジョブ実行ID ⑯ステップ名 ⑧終了ステータス ⑫失敗理由 ⑬例外種別 ⑭例外メッセージ ⑮スタックトレース | StepExecutionListener | StepExecutionListenerインターフェースを実装したBatchStepLoggingListenerクラスを作成。 |
ログ出力サンプル
[2026-01-24 10:00:00.234] INFO [TRACE-ID: 123e4567-e89b-12d3-a456-426614174001] [THREAD: main] [BATCH-STEP-BEG] JobName: bookingProcessJob, JobExecutionId: 1, StepName: bookingProcessStep, StepExecutionId: 1
[2026-01-24 10:05:30.456] INFO [TRACE-ID: 123e4567-e89b-12d3-a456-426614174001] [THREAD: main] [BATCH-STEP-END] JobName: bookingProcessJob, JobExecutionId: 1, StepName: bookingProcessStep, ExitStatus: COMPLETED, ReadCount: 10000, WriteCount: 9985, SkipCount: 15, CommitCount: 100以上
