diff --git a/backend/CLAUDE.md b/backend/CLAUDE.md index b375b4b9..5184a6fc 100644 --- a/backend/CLAUDE.md +++ b/backend/CLAUDE.md @@ -220,8 +220,16 @@ spring.jpa.hibernate.ddl-auto=validate # Flyway 사용 → validate ## 14. 로깅 -- Logback JSON 포맷 (운영) / human-readable (로컬) -- MDC에 `traceId`, `userId` +- **평문 포맷** (`application.yml` 의 `logging.pattern.console`). JSON 아니다 — 로그 수집기가 + 없고 실제로 읽는 경로가 `docker logs` 라서. 문서가 오래 JSON 이라고 적어 뒀는데 그런 설정이 + 존재한 적이 없다(2026-09-28 정정). +- **MDC `traceId` 는 로그 패턴에 포함된다** (`%X{traceId:-no-trace}`). 2026-09-28 이전에는 + MDC 만 채우고 패턴이 참조하지 않아 **로그 어디에도 traceId 가 없었다.** +- `TraceIdFilter` 는 `@Order(HIGHEST_PRECEDENCE)` — 없으면 Spring Security 체인(-100) 뒤로 + 밀려 **인증 실패 로그의 traceId 가 null 이 된다**(운영에서 실제로 그랬다). +- RabbitMQ 컨슈머 5개는 `TraceContext.runWithTraceId(envelope.traceId(), …)` 로 감싼다 — + 이게 없으면 큐를 건널 때마다 발행부가 새 traceId 를 만들어 추적이 끊긴다. +- `userId` 는 아직 MDC 에 넣지 않는다. - 민감정보 마스킹 유틸: `common/log/PiiMasker.java` — **자동 적용 아님**(호출부에서만 동작, 현재 호출부 없음). 전역 필터로 꽂으면 트레이스 ID 가 뭉개진다: [`/docs/observability.md §9`](../docs/observability.md) - 자세한 정책: [`/docs/observability.md`](../docs/observability.md) diff --git a/backend/src/main/java/com/stackup/stackup/common/trace/TraceContext.java b/backend/src/main/java/com/stackup/stackup/common/trace/TraceContext.java index 89ac3f52..6f294b74 100644 --- a/backend/src/main/java/com/stackup/stackup/common/trace/TraceContext.java +++ b/backend/src/main/java/com/stackup/stackup/common/trace/TraceContext.java @@ -21,4 +21,29 @@ public static void setTraceId(String traceId) { public static void clear() { MDC.remove(MDC_TRACE_ID); } + + /** + * 비동기 처리(RabbitMQ 컨슈머)를 원 요청의 traceId 아래에서 실행한다. + * + *

엔벨로프는 처음부터 traceId 를 실어 왔지만 컨슈머가 그걸 MDC 로 되돌리지 + * 않았다. 그래서 콜백 처리 로그는 traceId 없이 남고, 이어서 발행하는 메시지는 + * {@code RabbitMessagePublisher} 가 새 traceId 를 만들어 붙였다(그 코드의 주석도 + * "RabbitListener / EventListener 등에서 MDC 미주입 흐름" 이라고 적고 있다). + * 결과적으로 큐를 한 번 건널 때마다 추적이 끊겨, "한 요청의 모든 후속 처리에 동일 + * traceId 전파"(docs/observability.md §1)가 실제로는 성립하지 않았다. + * + *

traceId 가 비어 있으면 새로 만든다 — 없는 것보다 낫고, 적어도 그 처리 한 건은 + * 묶인다. 끝나면 반드시 지운다(스레드 풀 재사용 시 남은 값이 다음 메시지에 묻는다). + */ + public static void runWithTraceId(String traceId, Runnable work) { + String effective = (traceId == null || traceId.isBlank()) + ? java.util.UUID.randomUUID().toString() + : traceId; + try { + setTraceId(effective); + work.run(); + } finally { + clear(); + } + } } diff --git a/backend/src/main/java/com/stackup/stackup/common/trace/TraceIdFilter.java b/backend/src/main/java/com/stackup/stackup/common/trace/TraceIdFilter.java index f48ff013..0e3deccc 100644 --- a/backend/src/main/java/com/stackup/stackup/common/trace/TraceIdFilter.java +++ b/backend/src/main/java/com/stackup/stackup/common/trace/TraceIdFilter.java @@ -6,10 +6,25 @@ import jakarta.servlet.http.HttpServletResponse; import java.io.IOException; import java.util.UUID; +import org.springframework.core.Ordered; +import org.springframework.core.annotation.Order; import org.springframework.stereotype.Component; import org.springframework.web.filter.OncePerRequestFilter; +/** + * 모든 요청에 traceId 를 붙인다. + * + *

순서가 중요하다. {@code @Order} 가 없으면 Spring Boot 는 이 필터를 + * LOWEST_PRECEDENCE 로 등록하는데, Spring Security 체인은 -100 이라 보안 체인이 먼저 + * 돈다. 그러면 인증 실패처럼 보안 체인 안에서 끝나는 요청은 이 필터에 닿지 못하고 + * traceId 가 null 이 된다 — 운영 로그에 실제로 그렇게 찍혀 있었다: + * + * 

Authentication failed. code=AUTH_INVALID_TOKEN, traceId=null, uri=/api/.env
+ * + * 추적 ID 가 가장 필요한 순간(인증 실패·공격 스캔)에 정확히 빠져 있었다. + */ @Component +@Order(Ordered.HIGHEST_PRECEDENCE) public class TraceIdFilter extends OncePerRequestFilter { @Override diff --git a/backend/src/main/java/com/stackup/stackup/document/infrastructure/AnalysisCallbackHandler.java b/backend/src/main/java/com/stackup/stackup/document/infrastructure/AnalysisCallbackHandler.java index d6c97cf9..3dc20e10 100644 --- a/backend/src/main/java/com/stackup/stackup/document/infrastructure/AnalysisCallbackHandler.java +++ b/backend/src/main/java/com/stackup/stackup/document/infrastructure/AnalysisCallbackHandler.java @@ -1,5 +1,6 @@ package com.stackup.stackup.document.infrastructure; +import com.stackup.stackup.common.trace.TraceContext; import com.stackup.stackup.document.application.AnalysisCallbackService; import com.stackup.stackup.document.application.dto.AnalysisCallbackEnvelope; import lombok.RequiredArgsConstructor; @@ -19,12 +20,16 @@ public class AnalysisCallbackHandler { @RabbitListener(queues = "${app.messaging.rabbitmq.queues.names.core-callback-analysis}") public void handle(AnalysisCallbackEnvelope envelope) { - try { - callbackService.apply(envelope); - } catch (RuntimeException e) { - log.error("callback.analysis processing failed. messageId={}", - envelope == null ? null : envelope.messageId(), e); - throw e; - } + TraceContext.runWithTraceId( + envelope == null ? null : envelope.traceId(), + () -> { + try { + callbackService.apply(envelope); + } catch (RuntimeException e) { + log.error("callback.analysis processing failed. messageId={}", + envelope == null ? null : envelope.messageId(), e); + throw e; + } + }); } } diff --git a/backend/src/main/java/com/stackup/stackup/session/infrastructure/FeedbackCallbackHandler.java b/backend/src/main/java/com/stackup/stackup/session/infrastructure/FeedbackCallbackHandler.java index 9ff878d6..d3e537bd 100644 --- a/backend/src/main/java/com/stackup/stackup/session/infrastructure/FeedbackCallbackHandler.java +++ b/backend/src/main/java/com/stackup/stackup/session/infrastructure/FeedbackCallbackHandler.java @@ -1,5 +1,6 @@ package com.stackup.stackup.session.infrastructure; +import com.stackup.stackup.common.trace.TraceContext; import com.stackup.stackup.session.application.FeedbackCallbackService; import com.stackup.stackup.session.application.dto.FeedbackCallbackEnvelope; import lombok.RequiredArgsConstructor; @@ -19,12 +20,16 @@ public class FeedbackCallbackHandler { @RabbitListener(queues = "${app.messaging.rabbitmq.queues.names.core-callback-feedback}") public void handle(FeedbackCallbackEnvelope envelope) { - try { - callbackService.apply(envelope); - } catch (RuntimeException e) { - log.error("callback.feedback processing failed. messageId={}", - envelope == null ? null : envelope.messageId(), e); - throw e; - } + TraceContext.runWithTraceId( + envelope == null ? null : envelope.traceId(), + () -> { + try { + callbackService.apply(envelope); + } catch (RuntimeException e) { + log.error("callback.feedback processing failed. messageId={}", + envelope == null ? null : envelope.messageId(), e); + throw e; + } + }); } } diff --git a/backend/src/main/java/com/stackup/stackup/session/infrastructure/QuestionsCallbackHandler.java b/backend/src/main/java/com/stackup/stackup/session/infrastructure/QuestionsCallbackHandler.java index 7d4cd6f7..b51eb188 100644 --- a/backend/src/main/java/com/stackup/stackup/session/infrastructure/QuestionsCallbackHandler.java +++ b/backend/src/main/java/com/stackup/stackup/session/infrastructure/QuestionsCallbackHandler.java @@ -1,5 +1,6 @@ package com.stackup.stackup.session.infrastructure; +import com.stackup.stackup.common.trace.TraceContext; import com.stackup.stackup.session.application.QuestionsCallbackService; import com.stackup.stackup.session.application.dto.QuestionsCallbackEnvelope; import lombok.RequiredArgsConstructor; @@ -19,12 +20,16 @@ public class QuestionsCallbackHandler { @RabbitListener(queues = "${app.messaging.rabbitmq.queues.names.core-callback-questions}") public void handle(QuestionsCallbackEnvelope envelope) { - try { - callbackService.apply(envelope); - } catch (RuntimeException e) { - log.error("callback.questions processing failed. messageId={}", - envelope == null ? null : envelope.messageId(), e); - throw e; - } + TraceContext.runWithTraceId( + envelope == null ? null : envelope.traceId(), + () -> { + try { + callbackService.apply(envelope); + } catch (RuntimeException e) { + log.error("callback.questions processing failed. messageId={}", + envelope == null ? null : envelope.messageId(), e); + throw e; + } + }); } } diff --git a/backend/src/main/java/com/stackup/stackup/session/infrastructure/TtsCallbackHandler.java b/backend/src/main/java/com/stackup/stackup/session/infrastructure/TtsCallbackHandler.java index 6caa40ec..8a6276c3 100644 --- a/backend/src/main/java/com/stackup/stackup/session/infrastructure/TtsCallbackHandler.java +++ b/backend/src/main/java/com/stackup/stackup/session/infrastructure/TtsCallbackHandler.java @@ -1,5 +1,6 @@ package com.stackup.stackup.session.infrastructure; +import com.stackup.stackup.common.trace.TraceContext; import com.stackup.stackup.session.application.TtsCallbackService; import com.stackup.stackup.session.application.dto.TtsCallbackEnvelope; import lombok.RequiredArgsConstructor; @@ -18,12 +19,16 @@ public class TtsCallbackHandler { @RabbitListener(queues = "${app.messaging.rabbitmq.queues.names.core-callback-tts}") public void handle(TtsCallbackEnvelope envelope) { - try { - callbackService.apply(envelope); - } catch (RuntimeException e) { - log.error("callback.tts processing failed. messageId={}", - envelope == null ? null : envelope.messageId(), e); - throw e; - } + TraceContext.runWithTraceId( + envelope == null ? null : envelope.traceId(), + () -> { + try { + callbackService.apply(envelope); + } catch (RuntimeException e) { + log.error("callback.tts processing failed. messageId={}", + envelope == null ? null : envelope.messageId(), e); + throw e; + } + }); } } diff --git a/backend/src/main/java/com/stackup/stackup/session/infrastructure/VoiceCallbackHandler.java b/backend/src/main/java/com/stackup/stackup/session/infrastructure/VoiceCallbackHandler.java index 0ecb605d..c79ff737 100644 --- a/backend/src/main/java/com/stackup/stackup/session/infrastructure/VoiceCallbackHandler.java +++ b/backend/src/main/java/com/stackup/stackup/session/infrastructure/VoiceCallbackHandler.java @@ -1,5 +1,6 @@ package com.stackup.stackup.session.infrastructure; +import com.stackup.stackup.common.trace.TraceContext; import com.stackup.stackup.session.application.VoiceCallbackService; import com.stackup.stackup.session.application.dto.VoiceCallbackEnvelope; import lombok.RequiredArgsConstructor; @@ -19,12 +20,16 @@ public class VoiceCallbackHandler { @RabbitListener(queues = "${app.messaging.rabbitmq.queues.names.core-callback-voice}") public void handle(VoiceCallbackEnvelope envelope) { - try { - callbackService.apply(envelope); - } catch (RuntimeException e) { - log.error("callback.voice processing failed. messageId={}", - envelope == null ? null : envelope.messageId(), e); - throw e; - } + TraceContext.runWithTraceId( + envelope == null ? null : envelope.traceId(), + () -> { + try { + callbackService.apply(envelope); + } catch (RuntimeException e) { + log.error("callback.voice processing failed. messageId={}", + envelope == null ? null : envelope.messageId(), e); + throw e; + } + }); } } diff --git a/backend/src/main/resources/application.yml b/backend/src/main/resources/application.yml index 138e2709..98f070a9 100644 --- a/backend/src/main/resources/application.yml +++ b/backend/src/main/resources/application.yml @@ -26,6 +26,20 @@ spring: server: port: ${SERVER_PORT:38010} +# traceId 를 **로그 줄에** 싣는다. +# +# TraceIdFilter 가 MDC 에 넣고 엔벨로프가 큐 너머로 실어 나르는데도, 지금까지 운영 로그에는 +# traceId 가 없었다 — 로그 패턴이 MDC 를 참조하지 않아서다. SecurityConfig· +# GlobalExceptionHandler 처럼 **메시지 문자열에 직접 박아 넣은 몇 줄만** 보였고, 나머지는 +# 전부 추적 불가였다. 즉 MDC 를 채우는 코드가 사실상 아무 일도 하지 않고 있었다. +# +# JSON 포맷은 쓰지 않는다. docs/observability.md §2.1 이 JSON 을 적어 뒀지만 로그를 모아 가는 +# 수집기가 없고, 실제로 읽는 경로는 `docker logs` 다 — 거기서는 평문이 더 낫다. +# 수집기를 도입할 때 encoder 를 바꾸면 된다(문서도 그렇게 정정했다). +logging: + pattern: + console: "%d{yyyy-MM-dd'T'HH:mm:ss.SSSXXX} %5p [%X{traceId:-no-trace}] [%t] %-40.40logger{39} : %m%n%wEx" + management: endpoints: web: diff --git a/backend/src/test/java/com/stackup/stackup/common/trace/TraceContextTest.java b/backend/src/test/java/com/stackup/stackup/common/trace/TraceContextTest.java new file mode 100644 index 00000000..2beab377 --- /dev/null +++ b/backend/src/test/java/com/stackup/stackup/common/trace/TraceContextTest.java @@ -0,0 +1,67 @@ +package com.stackup.stackup.common.trace; + +import static org.assertj.core.api.Assertions.assertThat; + +import java.util.ArrayList; +import java.util.List; +import org.junit.jupiter.api.AfterEach; +import org.junit.jupiter.api.Test; +import org.slf4j.MDC; + +/** + * 엔벨로프는 처음부터 traceId 를 실어 왔지만 컨슈머가 MDC 로 되돌리지 않아, + * 큐를 한 번 건널 때마다 추적이 끊겼다(발행 시점에 새 traceId 가 생성됐다). + */ +class TraceContextTest { + + @AfterEach + void cleanup() { + MDC.clear(); + } + + @Test + void runWithTraceId_작업_중에는_MDC에_있고_끝나면_지워진다() { + List seen = new ArrayList<>(); + + TraceContext.runWithTraceId("trace-from-envelope", () -> seen.add(TraceContext.getTraceId())); + + assertThat(seen).containsExactly("trace-from-envelope"); + // 스레드 풀이 재사용되므로 남기면 다음 메시지 로그에 엉뚱한 traceId 가 묻는다. + assertThat(TraceContext.getTraceId()).isNull(); + } + + @Test + void runWithTraceId_예외가_나도_MDC를_지운다() { + try { + TraceContext.runWithTraceId("t", () -> { + throw new IllegalStateException("boom"); + }); + } catch (IllegalStateException expected) { + // 컨슈머는 예외를 다시 던져 DLQ 로 보낸다 — 그 경로에서도 정리돼야 한다. + } + + assertThat(TraceContext.getTraceId()).isNull(); + } + + @Test + void runWithTraceId_예외를_그대로_전파한다() { + // 삼키면 메시지가 ack 되어 DLQ 로 가지 않는다. + org.assertj.core.api.Assertions + .assertThatThrownBy(() -> TraceContext.runWithTraceId("t", () -> { + throw new IllegalStateException("boom"); + })) + .isInstanceOf(IllegalStateException.class); + } + + @Test + void runWithTraceId_비어있으면_새로_만든다() { + List seen = new ArrayList<>(); + + TraceContext.runWithTraceId(null, () -> seen.add(TraceContext.getTraceId())); + TraceContext.runWithTraceId(" ", () -> seen.add(TraceContext.getTraceId())); + + // 없는 것보다 낫다 — 적어도 그 처리 한 건은 묶인다. + assertThat(seen).hasSize(2).doesNotContainNull(); + assertThat(seen.get(0)).isNotEqualTo(seen.get(1)); + } +} diff --git a/backend/src/test/java/com/stackup/stackup/common/trace/TraceIdFilterOrderTest.java b/backend/src/test/java/com/stackup/stackup/common/trace/TraceIdFilterOrderTest.java new file mode 100644 index 00000000..03b1ca29 --- /dev/null +++ b/backend/src/test/java/com/stackup/stackup/common/trace/TraceIdFilterOrderTest.java @@ -0,0 +1,35 @@ +package com.stackup.stackup.common.trace; + +import static org.assertj.core.api.Assertions.assertThat; + +import org.junit.jupiter.api.Test; +import org.springframework.core.Ordered; +import org.springframework.core.annotation.AnnotationUtils; +import org.springframework.core.annotation.Order; + +/** + * 필터 순서가 틀리면 **인증 실패 로그에 traceId 가 없다.** + * + *

@Order 가 없으면 Spring Boot 는 LOWEST_PRECEDENCE 로 등록하는데 Spring Security 체인은 + * -100 이라 보안 체인이 먼저 돈다. 인증 실패는 보안 체인 안에서 끝나므로 TraceIdFilter 에 + * 닿지 못한다. 운영 로그에 실제로 그렇게 찍혀 있었다: + * {@code Authentication failed. code=AUTH_INVALID_TOKEN, traceId=null, uri=/api/.env} + * + *

추적 ID 가 가장 필요한 순간(인증 실패·공격 스캔)에 정확히 빠져 있었고, 이 순서는 + * 애노테이션 한 줄이 지워져도 컴파일·테스트가 통과하며 운영에서도 조용하다. + */ +class TraceIdFilterOrderTest { + + @Test + void 보안_필터체인보다_먼저_돈다() { + Order order = AnnotationUtils.findAnnotation(TraceIdFilter.class, Order.class); + + assertThat(order) + .as("@Order 가 없으면 Spring Security(-100) 뒤로 밀려 인증 실패에 traceId 가 없다") + .isNotNull(); + assertThat(order.value()) + .as("Spring Security 기본 필터 순서(-100)보다 앞서야 한다") + .isEqualTo(Ordered.HIGHEST_PRECEDENCE) + .isLessThan(-100); + } +} diff --git a/docs/observability.md b/docs/observability.md index 92c714e6..7e850e85 100644 --- a/docs/observability.md +++ b/docs/observability.md @@ -9,6 +9,11 @@ ### 1.1 ID 생성 - 클라이언트 또는 Nginx Gateway가 부여 (UUID v4) - 한 요청의 모든 후속 처리(REST/Queue/SSE)에 동일 traceId 전파 + - **2026-09-28 이전에는 큐를 건너면 끊겼다.** 컨슈머가 엔벨로프의 traceId 를 MDC 로 + 되돌리지 않아, 이어서 발행하는 메시지에 `RabbitMessagePublisher` 가 **새 traceId** 를 + 붙였다. 지금은 5개 `@RabbitListener` 가 `TraceContext.runWithTraceId` 로 감싸 원 요청의 + id 아래에서 실행된다. + - AI 서버 로그에는 아직 traceId 가 없다(uvicorn 기본 액세스 로그). 남은 과제. ### 1.2 전파 규약 @@ -56,48 +61,28 @@ async def trace_middleware(request, call_next): ## 2. 로깅 -### 2.1 출력 포맷 (JSON) -```json -{ - "ts": "2026-04-27T15:00:00.123Z", - "level": "INFO", - "service": "core-server", - "traceId": "9f4e5b...", - "userId": 42, - "logger": "c.s.s.session.SessionService", - "msg": "session created", - "sessionId": 99 -} +### 2.1 출력 포맷 + +**평문이다. JSON 이 아니다.** (2026-09-28 정정 — 이 절은 원래 JSON 예시를 싣고 있었지만 +그런 설정이 존재한 적이 없다. `logback-spring.xml` 도 없고 인코더 의존성도 없다.) + +JSON 을 도입하지 않은 이유: 로그를 모아 가는 수집기가 없고 실제로 읽는 경로는 `docker logs` +다 — 거기서는 평문이 더 낫다. 수집기를 도입할 때 encoder 를 바꾸면 된다. + +패턴은 `application.yml` 의 `logging.pattern.console` 이고 **traceId 를 포함한다**: + +``` +2026-09-28T13:50:01.123Z INFO [3f2a…-9c1b] [io-38010-exec-5] c.s.s.session.application.SessionService : ... +2026-09-28T13:50:02.004Z WARN [no-trace] [scheduling-2] c.s.s.s.a.StaleFollowupSweeper : ... ``` -### 2.2 레벨 정책 - -| Level | 용도 | 예시 | -|-------|------|------| -| `ERROR` | 사용자 영향 + 운영자 조치 필요 | RabbitMQ 발행 실패, 외부 API 5xx | -| `WARN` | 회복 가능, 주시 필요 | retry 발생, fallback 발동, slow query | -| `INFO` | 도메인 이벤트 (감사 가능) | 회원가입, 세션 생성/종료, 분석 완료 | -| `DEBUG` | 개발용 (운영 OFF) | 메서드 진입, 파라미터 | -| `TRACE` | 트레이스 상세 | (거의 사용 X) | - -### 2.3 로거별 권장 레벨 -- 운영: 루트 INFO, `org.springframework`, `io.netty` WARN -- 개발: 루트 DEBUG, 기타 INFO - -### 2.4 무엇을 로깅할 것인가 -| Yes | No | -|-----|-----| -| domain event 발생 (entity ID 동봉) | 메서드 진입/종료 (DEBUG 이하) | -| 외부 API 호출 시작/완료/실패 | 사용자 답변 본문 (민감) | -| 비동기 작업 발행/소비 | API 키, 토큰 (보안) | -| 인증 실패 (rate-limit·alert 대상) | request body 전체 (volume) | - -### 2.5 구조화 필드 컨벤션 -- 모든 ID는 별도 필드 (`userId`, `sessionId`, `messageId`)로 -- 외부 API 호출은 `external.service`, `external.endpoint`, `external.latencyMs`, `external.status` -- 에러는 `error.code`, `error.message`, `error.stack` (stack은 짧게) +`%X{traceId:-no-trace}` 라서 traceId 가 없는 흐름(스케줄러 스위퍼 등)은 `no-trace` 로 뜬다 — +빈칸으로 두면 "추적이 끊긴 것"과 "원래 요청이 없는 것"이 구분되지 않는다. ---- +> **2026-09-28 이전에는 traceId 가 로그에 아예 없었다.** `TraceIdFilter` 가 MDC 를 채우고 +> 엔벨로프가 큐 너머로 실어 날랐는데 **로그 패턴이 MDC 를 참조하지 않았다.** 메시지 문자열에 +> 직접 박아 넣은 몇 줄(`SecurityConfig`, `GlobalExceptionHandler`)만 보였다. MDC 를 채우는 +> 코드가 사실상 아무 일도 하지 않고 있었던 셈이다. ## 3. AI 요청 로깅 (US-30)