From 231561713ea97448d0beeb50e0aeb06625087d1a Mon Sep 17 00:00:00 2001 From: Geonwoo Park Date: Wed, 16 Sep 2026 17:56:58 +0900 Subject: [PATCH 1/2] =?UTF-8?q?feat:=20TRACE-6=20Outbox=20=EB=9F=B0?= =?UTF-8?q?=ED=83=80=EC=9E=84=20span=20=EA=B3=84=EC=B8=A1?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - dispatch, 알림 조회, FCM 전송, 상태 갱신 child span과 결과 속성을 추가 - 처리된 FCM 실패는 자식 span에 정제해 기록하고 기존 상태 전이 및 상위 span 상태를 유지 - JDBC 오류 정제 핸들러 이름을 책임에 맞게 변경하고 tracing 회귀 테스트를 보강 - 검증: gradlew.bat --no-daemon spotlessApply check --console=plain 통과 --- ...eryErrorSanitizingObservationHandler.java} | 6 +- .../outbox/config/OutboxFirebaseConfig.java | 6 +- .../outbox/service/OutboxEventDispatcher.java | 146 +++++++++++++++--- .../JdbcTracingAutoConfigurationTest.java | 2 +- .../OutboxFirebaseConditionContextTest.java | 4 +- .../OutboxPublisherIntegrationTest.java | 109 ++++++++++++- .../service/OutboxEventDispatcherTest.java | 37 ++++- 7 files changed, 276 insertions(+), 34 deletions(-) rename src/main/java/com/beachcheck/global/tracing/{SanitizingQueryTracingObservationHandler.java => JdbcQueryErrorSanitizingObservationHandler.java} (81%) diff --git a/src/main/java/com/beachcheck/global/tracing/SanitizingQueryTracingObservationHandler.java b/src/main/java/com/beachcheck/global/tracing/JdbcQueryErrorSanitizingObservationHandler.java similarity index 81% rename from src/main/java/com/beachcheck/global/tracing/SanitizingQueryTracingObservationHandler.java rename to src/main/java/com/beachcheck/global/tracing/JdbcQueryErrorSanitizingObservationHandler.java index 5b3beb57..e0b593c6 100644 --- a/src/main/java/com/beachcheck/global/tracing/SanitizingQueryTracingObservationHandler.java +++ b/src/main/java/com/beachcheck/global/tracing/JdbcQueryErrorSanitizingObservationHandler.java @@ -16,16 +16,16 @@ * *

Contract(Input): datasource-micrometer가 생성한 QueryContext * - *

Contract(Output): ERROR span에는 원래 예외 클래스명과 민감정보가 제거된 exception event만 기록 + *

Contract(Output): 오류가 발생한 JDBC query span에는 원래 예외 클래스명과 민감정보가 제거된 exception event만 기록 */ @Component @Order(MicrometerTracingAutoConfiguration.DEFAULT_TRACING_OBSERVATION_HANDLER_ORDER - 1000) -public class SanitizingQueryTracingObservationHandler extends QueryTracingObservationHandler { +public class JdbcQueryErrorSanitizingObservationHandler extends QueryTracingObservationHandler { private static final String ERROR_TYPE = "error.type"; private static final String SANITIZED_ERROR_MESSAGE = "JDBC 쿼리 실행 실패"; - public SanitizingQueryTracingObservationHandler(Tracer tracer) { + public JdbcQueryErrorSanitizingObservationHandler(Tracer tracer) { super(tracer); } diff --git a/src/main/java/com/beachcheck/outbox/config/OutboxFirebaseConfig.java b/src/main/java/com/beachcheck/outbox/config/OutboxFirebaseConfig.java index d5c81d5d..f82c51a6 100644 --- a/src/main/java/com/beachcheck/outbox/config/OutboxFirebaseConfig.java +++ b/src/main/java/com/beachcheck/outbox/config/OutboxFirebaseConfig.java @@ -6,6 +6,7 @@ import com.beachcheck.outbox.service.OutboxPublisher; import com.beachcheck.outbox.tracing.OutboxTracing; import com.google.firebase.messaging.FirebaseMessaging; +import io.micrometer.tracing.Tracer; import org.springframework.beans.factory.annotation.Value; import org.springframework.boot.autoconfigure.condition.ConditionalOnProperty; import org.springframework.context.annotation.Bean; @@ -33,9 +34,10 @@ public class OutboxFirebaseConfig { public OutboxEventDispatcher outboxEventDispatcher( OutboxEventRepository outboxEventRepository, NotificationRepository notificationRepository, - FirebaseMessaging firebaseMessaging) { + FirebaseMessaging firebaseMessaging, + Tracer tracer) { return new OutboxEventDispatcher( - outboxEventRepository, notificationRepository, firebaseMessaging); + outboxEventRepository, notificationRepository, firebaseMessaging, tracer); } @Bean diff --git a/src/main/java/com/beachcheck/outbox/service/OutboxEventDispatcher.java b/src/main/java/com/beachcheck/outbox/service/OutboxEventDispatcher.java index 6289a5d9..2bc651d1 100644 --- a/src/main/java/com/beachcheck/outbox/service/OutboxEventDispatcher.java +++ b/src/main/java/com/beachcheck/outbox/service/OutboxEventDispatcher.java @@ -11,8 +11,11 @@ import com.google.firebase.messaging.FirebaseMessagingException; import com.google.firebase.messaging.Message; import com.google.firebase.messaging.MessagingErrorCode; +import io.micrometer.tracing.Span; +import io.micrometer.tracing.Tracer; import java.time.Duration; import java.time.Instant; +import java.util.function.Supplier; import org.slf4j.Logger; import org.slf4j.LoggerFactory; import org.springframework.transaction.annotation.Propagation; @@ -31,14 +34,17 @@ public class OutboxEventDispatcher { private final OutboxEventRepository outboxEventRepository; private final NotificationRepository notificationRepository; private final FirebaseMessaging firebaseMessaging; + private final Tracer tracer; public OutboxEventDispatcher( OutboxEventRepository outboxEventRepository, NotificationRepository notificationRepository, - FirebaseMessaging firebaseMessaging) { + FirebaseMessaging firebaseMessaging, + Tracer tracer) { this.outboxEventRepository = outboxEventRepository; this.notificationRepository = notificationRepository; this.firebaseMessaging = firebaseMessaging; + this.tracer = tracer; } /** @@ -48,16 +54,38 @@ public OutboxEventDispatcher( */ @Transactional(propagation = Propagation.REQUIRES_NEW) public void dispatch(OutboxEvent event) { + Span span = startSpan("outbox dispatch"); + try (Tracer.SpanInScope ignored = tracer.withSpan(span)) { + dispatchEvent(event, span); + } catch (RuntimeException | Error exception) { + span.tag("outbox.item.outcome", "error"); + span.tag("outbox.failure.class", exception.getClass().getName()); + span.error(new IllegalStateException("Outbox dispatch 실패")); + throw exception; + } finally { + span.end(); + } + } + + private void dispatchEvent(OutboxEvent event, Span dispatchSpan) { // 1. Notification 조회 Notification notification = - notificationRepository - .findById(event.getNotificationId()) - .orElseThrow(() -> new IllegalArgumentException("Notification을 찾을 수 없습니다")); + traceChild( + "outbox notification lookup", + () -> + notificationRepository + .findById(event.getNotificationId()) + .orElseThrow(() -> new IllegalArgumentException("Notification을 찾을 수 없습니다"))); // 2. 멱등성: 이미 SENT 상태면 OutboxEvent만 SENT로 전이하고 스킵 if (notification.getStatus() == NotificationStatus.SENT) { - event.markAsSent(); - outboxEventRepository.save(event); + traceStateUpdate( + () -> { + event.markAsSent(); + outboxEventRepository.save(event); + }); + dispatchSpan.tag("outbox.item.outcome", "skipped"); + dispatchSpan.tag("outbox.item.skip.reason", "already_sent"); log.info( "Outbox 이벤트 멱등 스킵 (이미 발송됨)", kv("outboxEventId", event.getId()), @@ -69,16 +97,20 @@ public void dispatch(OutboxEvent event) { // 3. FCM 전송 try { Message message = notification.toFcmMessage(); - firebaseMessaging.send(message); + sendFcm(message, event); - // 4. Notification 상태 업데이트 - notification.setStatus(NotificationStatus.SENT); - notification.setSentAt(Instant.now()); - notificationRepository.save(notification); + traceStateUpdate( + () -> { + // 4. Notification 상태 업데이트 + notification.setStatus(NotificationStatus.SENT); + notification.setSentAt(Instant.now()); + notificationRepository.save(notification); - // 5. OutboxEvent 상태 업데이트 - event.markAsSent(); - outboxEventRepository.save(event); + // 5. OutboxEvent 상태 업데이트 + event.markAsSent(); + outboxEventRepository.save(event); + }); + dispatchSpan.tag("outbox.item.outcome", "success"); log.info( "Outbox 이벤트 발송 성공", @@ -89,10 +121,14 @@ public void dispatch(OutboxEvent event) { } catch (FirebaseMessagingException e) { // Exponential Backoff 재시도 로직 if (isPermanentFcmError(e)) { - event.markAsFailedPermanent(); - notification.markAsFailed("errorCode: " + e.getMessagingErrorCode()); - notificationRepository.save(notification); - outboxEventRepository.save(event); + traceStateUpdate( + () -> { + event.markAsFailedPermanent(); + notification.markAsFailed("errorCode: " + e.getMessagingErrorCode()); + notificationRepository.save(notification); + outboxEventRepository.save(event); + }); + tagFailureOutcome(dispatchSpan, "permanent_failure", event.getRetryCount()); log.warn( "Outbox 이벤트 발송 영구 실패", kv("outboxEventId", event.getId()), @@ -103,10 +139,14 @@ public void dispatch(OutboxEvent event) { Duration backoff = Duration.ofSeconds(1L << event.getRetryCount()); // 1s, 2s, 4s if (event.getRetryCount() >= 3) { // 최대 재시도 횟수 초과 시 영구 실패로 전이 - event.markAsFailedPermanent(); - notification.markAsFailed("errorCode: " + e.getMessagingErrorCode()); - notificationRepository.save(notification); - outboxEventRepository.save(event); + traceStateUpdate( + () -> { + event.markAsFailedPermanent(); + notification.markAsFailed("errorCode: " + e.getMessagingErrorCode()); + notificationRepository.save(notification); + outboxEventRepository.save(event); + }); + tagFailureOutcome(dispatchSpan, "permanent_failure", event.getRetryCount()); log.warn( "Outbox 이벤트 발송 영구 실패 (최대 재시도 초과)", kv("outboxEventId", event.getId()), @@ -114,8 +154,12 @@ public void dispatch(OutboxEvent event) { kv("retryCount", event.getRetryCount()), kv("messagingErrorCode", e.getMessagingErrorCode())); } else { - event.markAsFailedRetriable(backoff); - outboxEventRepository.save(event); + traceStateUpdate( + () -> { + event.markAsFailedRetriable(backoff); + outboxEventRepository.save(event); + }); + tagFailureOutcome(dispatchSpan, "retryable_failure", event.getRetryCount()); log.warn( "Outbox 이벤트 발송 실패 (재시도 예정)", kv("outboxEventId", event.getId()), @@ -126,6 +170,60 @@ public void dispatch(OutboxEvent event) { } } + private void sendFcm(Message message, OutboxEvent event) throws FirebaseMessagingException { + Span span = startClientSpan("outbox fcm send"); + try (Tracer.SpanInScope ignored = tracer.withSpan(span)) { + firebaseMessaging.send(message); + span.tag("outbox.fcm.outcome", "success"); + } catch (FirebaseMessagingException exception) { + String outcome = + isPermanentFcmError(exception) || event.getRetryCount() >= 3 + ? "permanent_failure" + : "retryable_failure"; + span.tag("outbox.fcm.outcome", outcome); + span.error(new IllegalStateException("FCM 전송 실패")); + throw exception; + } finally { + span.end(); + } + } + + private void traceStateUpdate(Runnable action) { + traceChild( + "outbox state update", + () -> { + action.run(); + return null; + }); + } + + private T traceChild(String name, Supplier action) { + Span span = startSpan(name); + try (Tracer.SpanInScope ignored = tracer.withSpan(span)) { + return action.get(); + } finally { + span.end(); + } + } + + private Span startSpan(String name) { + return tracer.nextSpan().name(name).start(); + } + + private Span startClientSpan(String name) { + return tracer + .spanBuilder() + .setParent(tracer.currentSpan().context()) + .name(name) + .kind(Span.Kind.CLIENT) + .start(); + } + + private void tagFailureOutcome(Span span, String outcome, int retryCount) { + span.tag("outbox.item.outcome", outcome); + span.tag("outbox.retry.count", retryCount); + } + private boolean isPermanentFcmError(FirebaseMessagingException e) { MessagingErrorCode errorCode = e.getMessagingErrorCode(); return errorCode == MessagingErrorCode.UNREGISTERED diff --git a/src/test/java/com/beachcheck/global/tracing/JdbcTracingAutoConfigurationTest.java b/src/test/java/com/beachcheck/global/tracing/JdbcTracingAutoConfigurationTest.java index 405f23ff..82b28d23 100644 --- a/src/test/java/com/beachcheck/global/tracing/JdbcTracingAutoConfigurationTest.java +++ b/src/test/java/com/beachcheck/global/tracing/JdbcTracingAutoConfigurationTest.java @@ -48,7 +48,7 @@ void autoConfiguration_wrapsDataSourceAndEnablesQuerySpansOnly() { .hasSize(1) .allSatisfy( (name, handler) -> - assertThat(handler).isInstanceOf(SanitizingQueryTracingObservationHandler.class)); + assertThat(handler).isInstanceOf(JdbcQueryErrorSanitizingObservationHandler.class)); assertThat(context.getBeansOfType(OpenTelemetryMeterObservationHandler.class)).isEmpty(); } } diff --git a/src/test/java/com/beachcheck/outbox/config/OutboxFirebaseConditionContextTest.java b/src/test/java/com/beachcheck/outbox/config/OutboxFirebaseConditionContextTest.java index 4589dc38..4986af9e 100644 --- a/src/test/java/com/beachcheck/outbox/config/OutboxFirebaseConditionContextTest.java +++ b/src/test/java/com/beachcheck/outbox/config/OutboxFirebaseConditionContextTest.java @@ -15,6 +15,7 @@ import com.google.firebase.FirebaseApp; import com.google.firebase.FirebaseOptions; import com.google.firebase.messaging.FirebaseMessaging; +import io.micrometer.tracing.Tracer; import java.io.InputStream; import org.junit.jupiter.api.DisplayName; import org.junit.jupiter.api.Test; @@ -31,7 +32,8 @@ class OutboxFirebaseConditionContextTest { .withPropertyValues("app.outbox.polling.enabled=true", "app.outbox.polling.batch-size=10") .withBean(OutboxEventRepository.class, () -> mock(OutboxEventRepository.class)) .withBean(NotificationRepository.class, () -> mock(NotificationRepository.class)) - .withBean(OutboxTracing.class, () -> mock(OutboxTracing.class)); + .withBean(OutboxTracing.class, () -> mock(OutboxTracing.class)) + .withBean(Tracer.class, () -> mock(Tracer.class)); @Test @DisplayName("Firebase가 비활성화되면 Outbox 관련 빈 없이도 컨텍스트가 정상 기동된다") diff --git a/src/test/java/com/beachcheck/outbox/integration/OutboxPublisherIntegrationTest.java b/src/test/java/com/beachcheck/outbox/integration/OutboxPublisherIntegrationTest.java index d7202956..03ab3746 100644 --- a/src/test/java/com/beachcheck/outbox/integration/OutboxPublisherIntegrationTest.java +++ b/src/test/java/com/beachcheck/outbox/integration/OutboxPublisherIntegrationTest.java @@ -31,7 +31,10 @@ import com.google.firebase.messaging.FirebaseMessagingException; import com.google.firebase.messaging.Message; import com.google.firebase.messaging.MessagingErrorCode; +import io.micrometer.tracing.Tracer; +import io.opentelemetry.api.common.AttributeKey; import io.opentelemetry.api.trace.SpanKind; +import io.opentelemetry.api.trace.StatusCode; import io.opentelemetry.sdk.trace.SdkTracerProvider; import io.opentelemetry.sdk.trace.data.SpanData; import java.time.Instant; @@ -90,6 +93,8 @@ class OutboxPublisherIntegrationTest extends IntegrationTest { @Autowired private SdkTracerProvider tracerProvider; + @Autowired private Tracer tracer; + @TestConfiguration(proxyBeanMethods = false) static class OutboxTestConfig { @@ -97,9 +102,10 @@ static class OutboxTestConfig { OutboxEventDispatcher outboxEventDispatcher( OutboxEventRepository outboxEventRepository, NotificationRepository notificationRepository, - FirebaseMessaging firebaseMessaging) { + FirebaseMessaging firebaseMessaging, + Tracer tracer) { return new OutboxEventDispatcher( - outboxEventRepository, notificationRepository, firebaseMessaging); + outboxEventRepository, notificationRepository, firebaseMessaging, tracer); } @Bean @@ -138,6 +144,7 @@ void shouldProcessPendingEventAndMarkAsSent() throws FirebaseMessagingException // Given: 실제 DB에 Notification + OutboxEvent 저장 Notification notification = createAndSaveNotification(NotificationStatus.PENDING); OutboxEvent event = createAndSaveOutboxEvent(notification.getId()); + resetSpans(); // When: OutboxPublisher 수동 실행 (스케줄러 대신 직접 호출하여 테스트 제어) outboxPublisher.processPendingOutboxEvents(); @@ -160,6 +167,29 @@ void shouldProcessPendingEventAndMarkAsSent() throws FirebaseMessagingException // Then: FCM 전송 확인 then(firebaseMessaging).should().send(any(Message.class)); + + // Then: runtime trace 구조와 성공 결과 확인 + List spans = awaitSpans(exporter, tracerProvider, 5); + SpanData processSpan = onlySpanNamed(spans, "outbox process"); + SpanData dispatchSpan = onlySpanNamed(spans, "outbox dispatch"); + SpanData lookupSpan = onlySpanNamed(spans, "outbox notification lookup"); + SpanData fcmSpan = onlySpanNamed(spans, "outbox fcm send"); + SpanData stateSpan = onlySpanNamed(spans, "outbox state update"); + + assertThat(dispatchSpan.getParentSpanId()).isEqualTo(processSpan.getSpanId()); + assertThat(lookupSpan.getParentSpanId()).isEqualTo(dispatchSpan.getSpanId()); + assertThat(fcmSpan.getParentSpanId()).isEqualTo(dispatchSpan.getSpanId()); + assertThat(stateSpan.getParentSpanId()).isEqualTo(dispatchSpan.getSpanId()); + assertThat(dispatchSpan.getKind()).isEqualTo(SpanKind.INTERNAL); + assertThat(lookupSpan.getKind()).isEqualTo(SpanKind.INTERNAL); + assertThat(fcmSpan.getKind()).isEqualTo(SpanKind.CLIENT); + assertThat(stateSpan.getKind()).isEqualTo(SpanKind.INTERNAL); + assertThat(dispatchSpan.getAttributes().get(AttributeKey.stringKey("outbox.item.outcome"))) + .isEqualTo("success"); + assertThat(fcmSpan.getAttributes().get(AttributeKey.stringKey("outbox.fcm.outcome"))) + .isEqualTo("success"); + assertThat(tracer.currentSpan()).isNull(); + assertNoSensitiveTraceData(spans, notification); } @Test @@ -212,6 +242,7 @@ void shouldSkipAlreadySentNotification() throws FirebaseMessagingException { // Given: SENT 상태의 Notification + PENDING OutboxEvent Notification notification = createAndSaveNotification(NotificationStatus.SENT); OutboxEvent event = createAndSaveOutboxEvent(notification.getId()); + resetSpans(); // When: OutboxPublisher 실행 outboxPublisher.processPendingOutboxEvents(); @@ -225,6 +256,15 @@ void shouldSkipAlreadySentNotification() throws FirebaseMessagingException { // Then: FCM 전송 안 됨 then(firebaseMessaging).should(never()).send(any(Message.class)); + + List spans = awaitSpans(exporter, tracerProvider, 4); + SpanData dispatchSpan = onlySpanNamed(spans, "outbox dispatch"); + assertThat(dispatchSpan.getAttributes().get(AttributeKey.stringKey("outbox.item.outcome"))) + .isEqualTo("skipped"); + assertThat(dispatchSpan.getAttributes().get(AttributeKey.stringKey("outbox.item.skip.reason"))) + .isEqualTo("already_sent"); + assertThat(spans).noneMatch(span -> span.getName().equals("outbox fcm send")); + assertNoSensitiveTraceData(spans, notification); } @Test @@ -236,6 +276,7 @@ void shouldPersistFailedRetriableToDb_whenFcmThrows() throws FirebaseMessagingEx OutboxEvent event = createAndSaveOutboxEvent(notification.getId()); given(firebaseMessaging.send(any(Message.class))).willThrow(FirebaseMessagingException.class); + resetSpans(); // When: OutboxPublisher 실행 @@ -254,6 +295,13 @@ void shouldPersistFailedRetriableToDb_whenFcmThrows() throws FirebaseMessagingEx assertThat(processedEvent.getRetryCount()).isEqualTo(1); assertThat(processedEvent.getNextRetryAt()) .isBetween(before.plusSeconds(1), after.plusSeconds(1)); + + List spans = awaitSpans(exporter, tracerProvider, 5); + assertFailureTrace(spans, "retryable_failure", 1); + assertThat(onlySpanNamed(spans, "outbox process").getStatus().getStatusCode()) + .isEqualTo(StatusCode.UNSET); + assertThat(tracer.currentSpan()).isNull(); + assertNoSensitiveTraceData(spans, notification); } @Test @@ -266,6 +314,7 @@ void shouldPersistFailedPermanentToDb_whenRetryCountExceedsMax() event.setRetryCount(3); // 이미 3번 실패한 상태로 세팅 outboxEventRepository.save(event); given(firebaseMessaging.send(any(Message.class))).willThrow(FirebaseMessagingException.class); + resetSpans(); // When outboxPublisher.processPendingOutboxEvents(); @@ -276,6 +325,11 @@ void shouldPersistFailedPermanentToDb_whenRetryCountExceedsMax() .findById(event.getId()) .orElseThrow(() -> new IllegalStateException("OutboxEvent를 찾을 수 없습니다")); assertThat(saved.getStatus()).isEqualTo(OutboxEventStatus.FAILED_PERMANENT); + + List spans = awaitSpans(exporter, tracerProvider, 5); + assertFailureTrace(spans, "permanent_failure", 3); + assertThat(onlySpanNamed(spans, "outbox process").getStatus().getStatusCode()) + .isEqualTo(StatusCode.UNSET); } @Test @@ -393,6 +447,7 @@ void shouldPersistFailedPermanent_whenFcmReturnsUnregistered() throws FirebaseMe FirebaseMessagingException exception = mock(FirebaseMessagingException.class); given(exception.getMessagingErrorCode()).willReturn(MessagingErrorCode.UNREGISTERED); given(firebaseMessaging.send(any(Message.class))).willThrow(exception); + resetSpans(); // When outboxPublisher.processPendingOutboxEvents(); @@ -405,6 +460,11 @@ void shouldPersistFailedPermanent_whenFcmReturnsUnregistered() throws FirebaseMe assertThat(saved.getStatus()).isEqualTo(OutboxEventStatus.FAILED_PERMANENT); assertThat(saved.getRetryCount()).isEqualTo(0); assertThat(saved.getProcessedAt()).isNotNull(); + + List spans = awaitSpans(exporter, tracerProvider, 5); + assertFailureTrace(spans, "permanent_failure", 0); + assertThat(onlySpanNamed(spans, "outbox process").getStatus().getStatusCode()) + .isEqualTo(StatusCode.UNSET); } @Test @@ -519,6 +579,51 @@ private SpanData onlyProcessSpan(List spans) { return processSpans.getFirst(); } + private SpanData onlySpanNamed(List spans, String name) { + List namedSpans = spans.stream().filter(span -> span.getName().equals(name)).toList(); + assertThat(namedSpans).hasSize(1); + return namedSpans.getFirst(); + } + + private void resetSpans() { + flushSpans(tracerProvider); + exporter.clear(); + } + + private void assertFailureTrace(List spans, String outcome, long retryCount) { + SpanData dispatchSpan = onlySpanNamed(spans, "outbox dispatch"); + SpanData fcmSpan = onlySpanNamed(spans, "outbox fcm send"); + assertThat(dispatchSpan.getAttributes().get(AttributeKey.stringKey("outbox.item.outcome"))) + .isEqualTo(outcome); + assertThat(dispatchSpan.getAttributes().get(AttributeKey.longKey("outbox.retry.count"))) + .isEqualTo(retryCount); + assertThat(fcmSpan.getAttributes().get(AttributeKey.stringKey("outbox.fcm.outcome"))) + .isEqualTo(outcome); + } + + private void assertNoSensitiveTraceData(List spans, Notification notification) { + List runtimeSpans = + spans.stream().filter(span -> span.getName().startsWith("outbox ")).toList(); + assertThat(runtimeSpans) + .allSatisfy( + span -> { + String attributeKeys = span.getAttributes().asMap().keySet().toString(); + String attributeValues = span.getAttributes().asMap().values().toString(); + String eventValues = span.getEvents().toString(); + assertThat(attributeKeys) + .doesNotContainIgnoringCase("notificationId") + .doesNotContainIgnoringCase("outboxEventId") + .doesNotContainIgnoringCase("userId") + .doesNotContainIgnoringCase("token"); + assertThat(attributeValues) + .doesNotContain(notification.getId().toString()) + .doesNotContain(notification.getRecipientToken()); + assertThat(eventValues) + .doesNotContain(notification.getId().toString()) + .doesNotContain(notification.getRecipientToken()); + }); + } + private List processSpans(List spans) { return spans.stream().filter(span -> span.getName().equals("outbox process")).toList(); } diff --git a/src/test/java/com/beachcheck/outbox/service/OutboxEventDispatcherTest.java b/src/test/java/com/beachcheck/outbox/service/OutboxEventDispatcherTest.java index 7295a26c..894bcdda 100644 --- a/src/test/java/com/beachcheck/outbox/service/OutboxEventDispatcherTest.java +++ b/src/test/java/com/beachcheck/outbox/service/OutboxEventDispatcherTest.java @@ -9,6 +9,7 @@ import static org.mockito.ArgumentMatchers.any; import static org.mockito.BDDMockito.given; import static org.mockito.BDDMockito.then; +import static org.mockito.Mockito.atLeast; import static org.mockito.Mockito.mock; import static org.mockito.Mockito.never; @@ -20,6 +21,9 @@ import com.google.firebase.messaging.FirebaseMessagingException; import com.google.firebase.messaging.Message; import com.google.firebase.messaging.MessagingErrorCode; +import io.micrometer.tracing.Span; +import io.micrometer.tracing.TraceContext; +import io.micrometer.tracing.Tracer; import java.time.Instant; import java.util.Optional; import java.util.UUID; @@ -49,13 +53,23 @@ class OutboxEventDispatcherTest { @Mock private OutboxEventRepository outboxEventRepository; @Mock private NotificationRepository notificationRepository; @Mock private FirebaseMessaging firebaseMessaging; + @Mock private Tracer tracer; + @Mock private Span span; + @Mock private Span.Builder spanBuilder; + @Mock private TraceContext traceContext; + @Mock private Tracer.SpanInScope spanInScope; private OutboxEventDispatcher dispatcher; @BeforeEach void setUp() { + given(tracer.nextSpan()).willReturn(span); + given(span.name(any())).willReturn(span); + given(span.start()).willReturn(span); + given(tracer.withSpan(any())).willReturn(spanInScope); dispatcher = - new OutboxEventDispatcher(outboxEventRepository, notificationRepository, firebaseMessaging); + new OutboxEventDispatcher( + outboxEventRepository, notificationRepository, firebaseMessaging, tracer); } @Nested @@ -72,6 +86,7 @@ void shouldSendFcmAndMarkAsSent_whenPendingEventExists() throws FirebaseMessagin given(notificationRepository.findById(notificationId)).willReturn(Optional.of(notification)); given(firebaseMessaging.send(any(Message.class))).willReturn("message-id-12345"); + givenClientSpan(); // When dispatcher.dispatch(event); @@ -120,6 +135,11 @@ void shouldThrowException_whenNotificationNotFound() { assertThatThrownBy(() -> dispatcher.dispatch(event)) .isInstanceOf(IllegalArgumentException.class) .hasMessageContaining("Notification을 찾을 수 없습니다"); + then(span).should().tag("outbox.item.outcome", "error"); + then(span).should().tag("outbox.failure.class", IllegalArgumentException.class.getName()); + then(span).should().error(any(IllegalStateException.class)); + then(spanInScope).should(atLeast(2)).close(); + then(span).should(atLeast(2)).end(); } @Test @@ -133,6 +153,7 @@ void shouldMarkAsFailedRetriable_whenFcmFails() throws FirebaseMessagingExceptio given(notificationRepository.findById(notificationId)).willReturn(Optional.of(notification)); given(firebaseMessaging.send(any(Message.class))) .willThrow(mock(FirebaseMessagingException.class)); + givenClientSpan(); // When Instant before = Instant.now(); @@ -160,6 +181,7 @@ void shouldMarkAsFailedPermanent_whenRetryCountExceeded() throws FirebaseMessagi given(notificationRepository.findById(notificationId)).willReturn(Optional.of(notification)); given(firebaseMessaging.send(any(Message.class))) .willThrow(mock(FirebaseMessagingException.class)); + givenClientSpan(); // When dispatcher.dispatch(event); @@ -184,6 +206,7 @@ void shouldApplyDoubledBackoff_whenRetryCountIsOne() throws FirebaseMessagingExc given(notificationRepository.findById(notificationId)).willReturn(Optional.of(notification)); given(firebaseMessaging.send(any(Message.class))) .willThrow(mock(FirebaseMessagingException.class)); + givenClientSpan(); // When Instant before = Instant.now(); @@ -210,6 +233,7 @@ void shouldMarkAsFailedPermanent_whenFcmErrorIsUnregistered() given(exception.getMessagingErrorCode()).willReturn(MessagingErrorCode.UNREGISTERED); given(notificationRepository.findById(notificationId)).willReturn(Optional.of(notification)); given(firebaseMessaging.send(any(Message.class))).willThrow(exception); + givenClientSpan(); // When dispatcher.dispatch(event); @@ -236,6 +260,7 @@ void shouldMarkAsFailedPermanent_whenFcmErrorIsInvalidArgument() given(exception.getMessagingErrorCode()).willReturn(MessagingErrorCode.INVALID_ARGUMENT); given(notificationRepository.findById(notificationId)).willReturn(Optional.of(notification)); given(firebaseMessaging.send(any(Message.class))).willThrow(exception); + givenClientSpan(); // When dispatcher.dispatch(event); @@ -250,6 +275,16 @@ void shouldMarkAsFailedPermanent_whenFcmErrorIsInvalidArgument() } } + private void givenClientSpan() { + given(span.context()).willReturn(traceContext); + given(tracer.currentSpan()).willReturn(span); + given(tracer.spanBuilder()).willReturn(spanBuilder); + given(spanBuilder.setParent(any())).willReturn(spanBuilder); + given(spanBuilder.name(any())).willReturn(spanBuilder); + given(spanBuilder.kind(any())).willReturn(spanBuilder); + given(spanBuilder.start()).willReturn(span); + } + private Notification createNotification(UUID notificationId, NotificationStatus status) { Notification notification = Notification.createPending( From b9bcf261ee6d9739d2037dfc6891bae8244058da Mon Sep 17 00:00:00 2001 From: Geonwoo Park Date: Thu, 17 Sep 2026 21:57:23 +0900 Subject: [PATCH 2/2] =?UTF-8?q?fix:=20Outbox=20=EC=84=B1=EA=B3=B5=20?= =?UTF-8?q?=EA=B2=B0=EA=B3=BC=EB=A5=BC=20=EC=BB=A4=EB=B0=8B=20=EC=9D=B4?= =?UTF-8?q?=ED=9B=84=20=EA=B8=B0=EB=A1=9D?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - DB 커밋 전 success span 결과와 성공 로그 기록을 지연 - 롤백 시 dispatch span을 error로 기록하고 트랜잭션 완료 후 종료 - 커밋 전 성공 및 롤백 오류 결과 회귀 테스트 추가 - 검증: gradlew.bat --no-daemon spotlessApply check --console=plain --- .../outbox/service/OutboxEventDispatcher.java | 102 ++++++++++++++---- .../service/OutboxEventDispatcherTest.java | 62 +++++++++++ 2 files changed, 142 insertions(+), 22 deletions(-) diff --git a/src/main/java/com/beachcheck/outbox/service/OutboxEventDispatcher.java b/src/main/java/com/beachcheck/outbox/service/OutboxEventDispatcher.java index 2bc651d1..93ed9531 100644 --- a/src/main/java/com/beachcheck/outbox/service/OutboxEventDispatcher.java +++ b/src/main/java/com/beachcheck/outbox/service/OutboxEventDispatcher.java @@ -15,11 +15,14 @@ import io.micrometer.tracing.Tracer; import java.time.Duration; import java.time.Instant; +import java.util.concurrent.atomic.AtomicBoolean; import java.util.function.Supplier; import org.slf4j.Logger; import org.slf4j.LoggerFactory; import org.springframework.transaction.annotation.Propagation; import org.springframework.transaction.annotation.Transactional; +import org.springframework.transaction.support.TransactionSynchronization; +import org.springframework.transaction.support.TransactionSynchronizationManager; /** * Why: OutboxPublisher의 self-invocation 문제로 @Transactional(REQUIRES_NEW)가 프록시를 우회하는 것을 방지하기 위해 별도 @@ -55,19 +58,28 @@ public OutboxEventDispatcher( @Transactional(propagation = Propagation.REQUIRES_NEW) public void dispatch(OutboxEvent event) { Span span = startSpan("outbox dispatch"); + AtomicBoolean outcomeRecorded = new AtomicBoolean(false); + boolean transactionSynchronizationActive = + TransactionSynchronizationManager.isSynchronizationActive(); + if (transactionSynchronizationActive) { + registerCompletionCallback(span, outcomeRecorded, event); + } try (Tracer.SpanInScope ignored = tracer.withSpan(span)) { - dispatchEvent(event, span); + dispatchEvent(event, span, outcomeRecorded); } catch (RuntimeException | Error exception) { + outcomeRecorded.set(true); span.tag("outbox.item.outcome", "error"); span.tag("outbox.failure.class", exception.getClass().getName()); span.error(new IllegalStateException("Outbox dispatch 실패")); throw exception; } finally { - span.end(); + if (!transactionSynchronizationActive) { + span.end(); + } } } - private void dispatchEvent(OutboxEvent event, Span dispatchSpan) { + private void dispatchEvent(OutboxEvent event, Span dispatchSpan, AtomicBoolean outcomeRecorded) { // 1. Notification 조회 Notification notification = traceChild( @@ -84,13 +96,17 @@ private void dispatchEvent(OutboxEvent event, Span dispatchSpan) { event.markAsSent(); outboxEventRepository.save(event); }); - dispatchSpan.tag("outbox.item.outcome", "skipped"); - dispatchSpan.tag("outbox.item.skip.reason", "already_sent"); - log.info( - "Outbox 이벤트 멱등 스킵 (이미 발송됨)", - kv("outboxEventId", event.getId()), - kv("notificationId", event.getNotificationId()), - kv("outboxEventType", event.getEventType())); + recordAfterCommit( + () -> { + outcomeRecorded.set(true); + dispatchSpan.tag("outbox.item.outcome", "skipped"); + dispatchSpan.tag("outbox.item.skip.reason", "already_sent"); + log.info( + "Outbox 이벤트 멱등 스킵 (이미 발송됨)", + kv("outboxEventId", event.getId()), + kv("notificationId", event.getNotificationId()), + kv("outboxEventType", event.getEventType())); + }); return; } @@ -110,14 +126,17 @@ private void dispatchEvent(OutboxEvent event, Span dispatchSpan) { event.markAsSent(); outboxEventRepository.save(event); }); - dispatchSpan.tag("outbox.item.outcome", "success"); - - log.info( - "Outbox 이벤트 발송 성공", - kv("outboxEventId", event.getId()), - kv("notificationId", event.getNotificationId()), - kv("outboxEventType", event.getEventType()), - kv("retryCount", event.getRetryCount())); + recordAfterCommit( + () -> { + outcomeRecorded.set(true); + dispatchSpan.tag("outbox.item.outcome", "success"); + log.info( + "Outbox 이벤트 발송 성공", + kv("outboxEventId", event.getId()), + kv("notificationId", event.getNotificationId()), + kv("outboxEventType", event.getEventType()), + kv("retryCount", event.getRetryCount())); + }); } catch (FirebaseMessagingException e) { // Exponential Backoff 재시도 로직 if (isPermanentFcmError(e)) { @@ -128,7 +147,8 @@ private void dispatchEvent(OutboxEvent event, Span dispatchSpan) { notificationRepository.save(notification); outboxEventRepository.save(event); }); - tagFailureOutcome(dispatchSpan, "permanent_failure", event.getRetryCount()); + tagFailureOutcome( + dispatchSpan, outcomeRecorded, "permanent_failure", event.getRetryCount()); log.warn( "Outbox 이벤트 발송 영구 실패", kv("outboxEventId", event.getId()), @@ -146,7 +166,8 @@ private void dispatchEvent(OutboxEvent event, Span dispatchSpan) { notificationRepository.save(notification); outboxEventRepository.save(event); }); - tagFailureOutcome(dispatchSpan, "permanent_failure", event.getRetryCount()); + tagFailureOutcome( + dispatchSpan, outcomeRecorded, "permanent_failure", event.getRetryCount()); log.warn( "Outbox 이벤트 발송 영구 실패 (최대 재시도 초과)", kv("outboxEventId", event.getId()), @@ -159,7 +180,8 @@ private void dispatchEvent(OutboxEvent event, Span dispatchSpan) { event.markAsFailedRetriable(backoff); outboxEventRepository.save(event); }); - tagFailureOutcome(dispatchSpan, "retryable_failure", event.getRetryCount()); + tagFailureOutcome( + dispatchSpan, outcomeRecorded, "retryable_failure", event.getRetryCount()); log.warn( "Outbox 이벤트 발송 실패 (재시도 예정)", kv("outboxEventId", event.getId()), @@ -219,11 +241,47 @@ private Span startClientSpan(String name) { .start(); } - private void tagFailureOutcome(Span span, String outcome, int retryCount) { + private void tagFailureOutcome( + Span span, AtomicBoolean outcomeRecorded, String outcome, int retryCount) { + outcomeRecorded.set(true); span.tag("outbox.item.outcome", outcome); span.tag("outbox.retry.count", retryCount); } + private void recordAfterCommit(Runnable action) { + if (TransactionSynchronizationManager.isSynchronizationActive()) { + TransactionSynchronizationManager.registerSynchronization( + new TransactionSynchronization() { + @Override + public void afterCommit() { + action.run(); + } + }); + return; + } + action.run(); + } + + private void registerCompletionCallback( + Span span, AtomicBoolean outcomeRecorded, OutboxEvent event) { + TransactionSynchronizationManager.registerSynchronization( + new TransactionSynchronization() { + @Override + public void afterCompletion(int status) { + if (status != TransactionSynchronization.STATUS_COMMITTED + && outcomeRecorded.compareAndSet(false, true)) { + span.tag("outbox.item.outcome", "error"); + span.error(new IllegalStateException("Outbox dispatch 커밋 실패")); + log.warn( + "Outbox 이벤트 상태 저장 커밋 실패", + kv("outboxEventId", event.getId()), + kv("notificationId", event.getNotificationId())); + } + span.end(); + } + }); + } + private boolean isPermanentFcmError(FirebaseMessagingException e) { MessagingErrorCode errorCode = e.getMessagingErrorCode(); return errorCode == MessagingErrorCode.UNREGISTERED diff --git a/src/test/java/com/beachcheck/outbox/service/OutboxEventDispatcherTest.java b/src/test/java/com/beachcheck/outbox/service/OutboxEventDispatcherTest.java index 894bcdda..407c1e72 100644 --- a/src/test/java/com/beachcheck/outbox/service/OutboxEventDispatcherTest.java +++ b/src/test/java/com/beachcheck/outbox/service/OutboxEventDispatcherTest.java @@ -12,6 +12,8 @@ import static org.mockito.Mockito.atLeast; import static org.mockito.Mockito.mock; import static org.mockito.Mockito.never; +import static org.springframework.transaction.support.TransactionSynchronization.STATUS_COMMITTED; +import static org.springframework.transaction.support.TransactionSynchronization.STATUS_ROLLED_BACK; import com.beachcheck.notification.domain.Notification; import com.beachcheck.notification.repository.NotificationRepository; @@ -34,6 +36,8 @@ import org.junit.jupiter.api.extension.ExtendWith; import org.mockito.Mock; import org.mockito.junit.jupiter.MockitoExtension; +import org.springframework.transaction.support.TransactionSynchronizationManager; +import org.springframework.transaction.support.TransactionSynchronizationUtils; /** * Why: OutboxEventDispatcher.dispatch()의 FCM 전송 및 상태 전이 로직 검증 @@ -101,6 +105,64 @@ void shouldSendFcmAndMarkAsSent_whenPendingEventExists() throws FirebaseMessagin then(outboxEventRepository).should().save(event); } + @Test + @DisplayName("TC1-1 - DB 커밋 전에는 성공 결과를 기록하지 않음") + void shouldRecordSuccessOnlyAfterTransactionCommit() throws FirebaseMessagingException { + // Given + UUID notificationId = UUID.randomUUID(); + Notification notification = createNotification(notificationId, NotificationStatus.PENDING); + OutboxEvent event = createPendingEvent(notificationId); + + given(notificationRepository.findById(notificationId)).willReturn(Optional.of(notification)); + given(firebaseMessaging.send(any(Message.class))).willReturn("message-id-12345"); + givenClientSpan(); + TransactionSynchronizationManager.initSynchronization(); + + try { + // When + dispatcher.dispatch(event); + + // Then: dispatch() 반환 시점에는 아직 커밋 전이므로 성공 결과를 기록하지 않음 + then(span).should(never()).tag("outbox.item.outcome", "success"); + + // When: 트랜잭션 커밋 완료 콜백 실행 + TransactionSynchronizationUtils.triggerAfterCommit(); + + // Then + then(span).should().tag("outbox.item.outcome", "success"); + TransactionSynchronizationUtils.triggerAfterCompletion(STATUS_COMMITTED); + } finally { + TransactionSynchronizationManager.clearSynchronization(); + } + } + + @Test + @DisplayName("TC1-2 - DB 롤백 시 성공 대신 오류 결과를 기록") + void shouldRecordErrorWhenTransactionRollsBack() throws FirebaseMessagingException { + // Given + UUID notificationId = UUID.randomUUID(); + Notification notification = createNotification(notificationId, NotificationStatus.PENDING); + OutboxEvent event = createPendingEvent(notificationId); + + given(notificationRepository.findById(notificationId)).willReturn(Optional.of(notification)); + given(firebaseMessaging.send(any(Message.class))).willReturn("message-id-12345"); + givenClientSpan(); + TransactionSynchronizationManager.initSynchronization(); + + try { + // When + dispatcher.dispatch(event); + TransactionSynchronizationUtils.triggerAfterCompletion(STATUS_ROLLED_BACK); + + // Then + then(span).should().tag("outbox.item.outcome", "error"); + then(span).should().error(any(IllegalStateException.class)); + then(span).should(never()).tag("outbox.item.outcome", "success"); + } finally { + TransactionSynchronizationManager.clearSynchronization(); + } + } + @Test @DisplayName("TC2 - 멱등성: 이미 SENT 상태인 Notification은 FCM 전송 스킵") void shouldSkipFcmSend_whenNotificationAlreadySent() throws FirebaseMessagingException {