MVC 요청 관찰

rootProject.name = 'mvc-request-observation'

plugins {
    id 'java'
}

java {
    toolchain {
        languageVersion = JavaLanguageVersion.of(25)
    }
}

repositories {
    mavenCentral()
}

dependencies {
    implementation platform(
            'org.springframework.boot:spring-boot-dependencies:4.1.2')
    implementation 'org.springframework.boot:spring-boot-starter-webmvc'
    testImplementation platform(
            'org.springframework.boot:spring-boot-dependencies:4.1.2')
    testImplementation 'org.springframework.boot:spring-boot-starter-test'
    testImplementation 'org.springframework.boot:spring-boot-starter-webmvc-test'
    testRuntimeOnly 'org.junit.platform:junit-platform-launcher'
}

tasks.named('test') {
    useJUnitPlatform()
}

package board.web;

import jakarta.servlet.FilterChain;
import jakarta.servlet.ServletException;
import jakarta.servlet.http.HttpServletRequest;
import jakarta.servlet.http.HttpServletResponse;
import java.io.IOException;
import java.util.Objects;
import java.util.UUID;
import java.util.function.Supplier;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;
import org.springframework.web.filter.OncePerRequestFilter;

public final class RequestTraceFilter extends OncePerRequestFilter {
    public static final String RESPONSE_HEADER = "X-Request-Id";
    static final String MDC_KEY = "requestId";

    private static final Logger log =
            LoggerFactory.getLogger(RequestTraceFilter.class);

    private final Supplier<UUID> idGenerator;

    public RequestTraceFilter(Supplier<UUID> idGenerator) {
        this.idGenerator = Objects.requireNonNull(idGenerator);
    }

    @Override
    protected void doFilterInternal(
            HttpServletRequest request,
            HttpServletResponse response,
            FilterChain chain)
            throws ServletException, IOException {
        var requestId = Objects.requireNonNull(
                        idGenerator.get(),
                        "idGenerator must return a UUID")
                .toString();
        var dispatcher = request.getDispatcherType();
        var previousRequestId = MDC.get(MDC_KEY);

        response.setHeader(RESPONSE_HEADER, requestId);
        MDC.put(MDC_KEY, requestId);

        try {
            try {
                chain.doFilter(request, response);
            } catch (ServletException
                    | IOException
                    | RuntimeException
                    | Error failure) {
                log.debug(
                        "mvc.request outcome=thrown dispatcher={} requestId={}",
                        dispatcher,
                        requestId);
                throw failure;
            }

            log.debug(
                    "mvc.request outcome=returned dispatcher={} dispatchStatus={} requestId={}",
                    dispatcher,
                    response.getStatus(),
                    requestId);
        } finally {
            if (previousRequestId == null) {
                MDC.remove(MDC_KEY);
            } else {
                MDC.put(MDC_KEY, previousRequestId);
            }
        }
    }
}

package board.config;

import board.web.RequestTraceFilter;
import jakarta.servlet.DispatcherType;
import java.util.UUID;
import org.springframework.boot.web.servlet.FilterRegistrationBean;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;

@Configuration(proxyBeanMethods = false)
public class WebFilterConfig {
    @Bean
    public FilterRegistrationBean<RequestTraceFilter>
            requestTraceFilter() {
        var registration = new FilterRegistrationBean<>(
                new RequestTraceFilter(UUID::randomUUID));
        registration.setName("requestTraceFilter");
        registration.setOrder(10);
        registration.setDispatcherTypes(DispatcherType.REQUEST);
        registration.addUrlPatterns("/*");
        return registration;
    }
}

logging:
  pattern:
    level: "%5p requestId=%X{requestId}"
  level:
    board.web.RequestTraceFilter: DEBUG
    org.springframework.web.servlet.DispatcherServlet: DEBUG
    org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerMapping: DEBUG

package board.web;

import static org.assertj.core.api.Assertions.assertThat;
import static org.assertj.core.api.Assertions.catchThrowable;

import board.config.WebFilterConfig;
import ch.qos.logback.classic.Level;
import ch.qos.logback.classic.Logger;
import ch.qos.logback.classic.spi.ILoggingEvent;
import ch.qos.logback.core.read.ListAppender;
import jakarta.servlet.DispatcherType;
import jakarta.servlet.ServletException;
import java.util.List;
import java.util.UUID;
import java.util.concurrent.atomic.AtomicInteger;
import java.util.concurrent.atomic.AtomicReference;
import org.junit.jupiter.api.AfterEach;
import org.junit.jupiter.api.Test;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;
import org.springframework.mock.web.MockHttpServletRequest;
import org.springframework.mock.web.MockHttpServletResponse;
import org.springframework.test.web.servlet.client.RestTestClient;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;

class RequestTraceFilterTest {
    private static final UUID INTERNAL_ID = UUID.fromString(
            "123e4567-e89b-12d3-a456-426614174000");

    @AfterEach
    void clearMdc() {
        MDC.clear();
    }

    @RestController
    static class PingController {
        @GetMapping("/api/ping")
        TraceResponse ping() {
            return new TraceResponse(MDC.get(RequestTraceFilter.MDC_KEY));
        }
    }

    record TraceResponse(String requestId) {}

    @Test
    void internalIdIsSharedAndClientSpoofIsIgnored() {
        var filter = new RequestTraceFilter(() -> INTERNAL_ID);
        var client = RestTestClient
                .bindToController(new PingController())
                .configureServer(builder -> builder.addFilters(filter))
                .build();

        try (var logs = CapturedFilterLogs.open()) {
            client.get()
                    .uri("/api/[email protected]")
                    .header(RequestTraceFilter.RESPONSE_HEADER, "client-spoof")
                    .header("Authorization", "Bearer secret-token")
                    .exchange()
                    .expectStatus().isOk()
                    .expectHeader()
                    .valueEquals(
                            RequestTraceFilter.RESPONSE_HEADER,
                            INTERNAL_ID.toString())
                    .expectBody()
                    .jsonPath("$.requestId")
                    .isEqualTo(INTERNAL_ID.toString());

            assertThat(MDC.get(RequestTraceFilter.MDC_KEY)).isNull();
            assertThat(logs.messages()).containsExactly(
                    "mvc.request outcome=returned dispatcher=REQUEST "
                            + "dispatchStatus=200 requestId="
                            + INTERNAL_ID);
            assertThat(logs.messages().getFirst())
                    .doesNotContain(
                            "client-spoof",
                            "[email protected]",
                            "secret-token",
                            "/api/ping");
        }
    }

    @Test
    void priorMdcValueIsRestored() throws Exception {
        var filter = new RequestTraceFilter(() -> INTERNAL_ID);
        var request = request();
        var response = new MockHttpServletResponse();
        var observed = new AtomicReference<String>();
        MDC.put(RequestTraceFilter.MDC_KEY, "outer-request");

        try {
            filter.doFilter(
                    request,
                    response,
                    (ignoredRequest, ignoredResponse) -> observed.set(
                            MDC.get(RequestTraceFilter.MDC_KEY)));

            assertThat(observed.get()).isEqualTo(INTERNAL_ID.toString());
            assertThat(MDC.get(RequestTraceFilter.MDC_KEY))
                    .isEqualTo("outer-request");
        } finally {
            MDC.remove(RequestTraceFilter.MDC_KEY);
        }
    }

    @Test
    void originalFailureIsRethrownAndMdcIsCleaned() {
        var filter = new RequestTraceFilter(() -> INTERNAL_ID);
        var request = request();
        var response = new MockHttpServletResponse();
        var failure = new ServletException("database-password-must-not-leak");

        try (var logs = CapturedFilterLogs.open()) {
            var thrown = catchThrowable(() -> filter.doFilter(
                    request,
                    response,
                    (ignoredRequest, ignoredResponse) -> {
                        throw failure;
                    }));

            assertThat(thrown).isSameAs(failure);
            assertThat(MDC.get(RequestTraceFilter.MDC_KEY)).isNull();
            assertThat(response.getHeader(RequestTraceFilter.RESPONSE_HEADER))
                    .isEqualTo(INTERNAL_ID.toString());
            assertThat(logs.messages()).containsExactly(
                    "mvc.request outcome=thrown dispatcher=REQUEST requestId="
                            + INTERNAL_ID);
            assertThat(logs.messages().getFirst())
                    .doesNotContain(
                            "dispatchStatus",
                            "database-password-must-not-leak");
        }
    }

    @Test
    void internalIdGeneratorRunsOnce() throws Exception {
        var calls = new AtomicInteger();
        var observed = new AtomicReference<String>();
        var filter = new RequestTraceFilter(() -> {
            calls.incrementAndGet();
            return INTERNAL_ID;
        });
        var response = new MockHttpServletResponse();

        filter.doFilter(
                request(),
                response,
                (ignoredRequest, ignoredResponse) -> observed.set(
                        MDC.get(RequestTraceFilter.MDC_KEY)));

        assertThat(calls).hasValue(1);
        assertThat(observed.get()).isEqualTo(INTERNAL_ID.toString());
        assertThat(response.getHeader(RequestTraceFilter.RESPONSE_HEADER))
                .isEqualTo(INTERNAL_ID.toString());
        assertThat(MDC.get(RequestTraceFilter.MDC_KEY)).isNull();
    }

    @Test
    void registrationMetadataIsExplicit() {
        var registration = new WebFilterConfig().requestTraceFilter();

        assertThat(registration.getFilterName())
                .isEqualTo("requestTraceFilter");
        assertThat(registration.getOrder()).isEqualTo(10);
        assertThat(registration.getUrlPatterns()).containsExactly("/*");
        assertThat(registration.determineDispatcherTypes())
                .containsExactly(DispatcherType.REQUEST);
        assertThat(registration.getFilter())
                .isInstanceOf(RequestTraceFilter.class);
    }

    private static MockHttpServletRequest request() {
        var request = new MockHttpServletRequest("GET", "/api/ping");
        request.setDispatcherType(DispatcherType.REQUEST);
        return request;
    }

    private static final class CapturedFilterLogs implements AutoCloseable {
        private final Logger logger;
        private final Level previousLevel;
        private final ListAppender<ILoggingEvent> appender;

        private CapturedFilterLogs(
                Logger logger,
                Level previousLevel,
                ListAppender<ILoggingEvent> appender) {
            this.logger = logger;
            this.previousLevel = previousLevel;
            this.appender = appender;
        }

        static CapturedFilterLogs open() {
            var logger = (Logger) LoggerFactory.getLogger(
                    RequestTraceFilter.class);
            var appender = new ListAppender<ILoggingEvent>();
            appender.setContext(logger.getLoggerContext());
            appender.start();
            var previousLevel = logger.getLevel();
            logger.setLevel(Level.DEBUG);
            logger.addAppender(appender);
            return new CapturedFilterLogs(
                    logger,
                    previousLevel,
                    appender);
        }

        List<String> messages() {
            return appender.list.stream()
                    .map(ILoggingEvent::getFormattedMessage)
                    .toList();
        }

        @Override
        public void close() {
            logger.detachAppender(appender);
            appender.stop();
            logger.setLevel(previousLevel);
        }
    }
}