[gateway] 접근 로그 JSON 출력과 요청 추적 MDC 추가

gradle/libs.versions.toml

@@ -31,6 +31,7 @@ jjwt-api = { module = "io.jsonwebtoken:jjwt-api", version.ref = "jjwt" }
 jjwt-impl = { module = "io.jsonwebtoken:jjwt-impl", version.ref = "jjwt" }
 jjwt-jackson = { module = "io.jsonwebtoken:jjwt-jackson", version.ref = "jjwt" }
 springdoc-openapi-webmvc-ui = { module = "org.springdoc:springdoc-openapi-starter-webmvc-ui", version.ref = "springdoc" }
+micrometer-context-propagation = { module = "io.micrometer:context-propagation" }
 mockk = { module = "io.mockk:mockk", version.ref = "mockk" }
 
 [plugins]

rush-gateway/README.md

@@ -39,6 +39,16 @@ WebSocket을 제외한 라우트는 서킷브레이커를 거칩니다. 서비
 - WebSocket용 `?token=`은 검증이 끝나면 지우고 서비스로 넘깁니다.
 - 각 서비스의 `/{prefix}/v3/api-docs`는 토큰 없이 접근할 수 있습니다.
 
+## 로그
+
+로그는 JSON 한 줄(logstash 형식)로 stdout에 남깁니다. 요청마다 `X-Request-Id`를 새로 만들어 서비스와 응답에 넘깁니다. 접근 로그는 요청이 끝날 때 한 줄씩 남깁니다.
+
+```json
+{"message":"GET /user/ping 200 4ms","requestId":"18e0…","userId":"42","clientIp":"127.0.0.1","method":"GET","path":"/user/ping","status":200,"latencyMs":4,"routeId":"rush-user"}
+```
+
+`requestId`, `userId`, `clientIp`는 MDC로 이어지므로, 요청 처리 중 남긴 다른 로그에도 들어갑니다.
+
 | 환경변수 | 기본값 | 설명 |
 |---|---|---|
 | `GATEWAY_ADMIN_ALLOWED_IPS` | `127.0.0.1/32,::1/128` | 관리용 actuator 허용 대역 |

rush-gateway/build.gradle.kts

@@ -9,6 +9,7 @@ dependencies {
     implementation(libs.spring.cloud.starter.netflix.eureka.client)
     implementation(libs.spring.boot.starter.actuator)
     implementation(libs.spring.boot.starter.security)
+    implementation(libs.micrometer.context.propagation)
     implementation(libs.jjwt.api)
     runtimeOnly(libs.jjwt.impl)
     runtimeOnly(libs.jjwt.jackson)

rush-gateway/src/main/kotlin/com/rush/gateway/error/GlobalErrorHandler.kt

@@ -1,5 +1,6 @@
 package com.rush.gateway.error
 
+import com.rush.gateway.logging.RequestContext
 import org.slf4j.LoggerFactory
 import org.springframework.boot.web.reactive.error.ErrorWebExceptionHandler
 import org.springframework.core.annotation.Order
@@ -26,7 +27,10 @@ class GlobalErrorHandler(
 
         val status = statusOf(ex)
         if (status.is5xxServerError) {
-            log.error("요청 처리 실패 {} {}", exchange.request.method, exchange.request.path, ex)
+            // 이 핸들러는 WebFilter 체인 바깥이라 Reactor context가 없으므로 exchange에서 MDC를 채웁니다.
+            RequestContext.withMdc(exchange) {
+                log.error("요청 처리 실패 {} {}", exchange.request.method, exchange.request.path, ex)
+            }
         }
         return writer.write(exchange, status)
     }

rush-gateway/src/main/kotlin/com/rush/gateway/filter/AccessLogFilter.kt

@@ -1,17 +1,27 @@
 package com.rush.gateway.filter
 
+import com.rush.gateway.logging.RequestContext
+import com.rush.gateway.security.ClientIpResolver
 import org.slf4j.LoggerFactory
+import org.springframework.cloud.gateway.route.Route
+import org.springframework.cloud.gateway.support.ServerWebExchangeUtils.GATEWAY_ROUTE_ATTR
 import org.springframework.core.Ordered
 import org.springframework.stereotype.Component
 import org.springframework.web.server.ServerWebExchange
 import org.springframework.web.server.WebFilter
 import org.springframework.web.server.WebFilterChain
 import reactor.core.publisher.Mono
+import reactor.util.context.Context
 import java.util.UUID
 
+/**
+ * 가장 바깥 필터입니다. 요청마다 X-Request-Id를 새로 만들어 서비스와 응답에 넘기고,
+ * 요청이 끝나면 접근 로그를 한 줄 남깁니다. 400·401·403 같은 게이트웨이 응답도 기록됩니다.
+ */
 @Component
-class AccessLogFilter :
-    WebFilter,
+class AccessLogFilter(
+    private val clientIpResolver: ClientIpResolver,
+) : WebFilter,
     Ordered {
     private val log = LoggerFactory.getLogger(javaClass)
 
@@ -20,27 +30,46 @@ class AccessLogFilter :
         chain: WebFilterChain,
     ): Mono<Void> {
         val requestId = UUID.randomUUID().toString()
+        val clientIp = clientIpResolver.resolve(exchange.request)
+        RequestContext.put(exchange, RequestContext.REQUEST_ID, requestId)
+        RequestContext.put(exchange, RequestContext.CLIENT_IP, clientIp)
+
         val request =
             exchange.request
                 .mutate()
                 .headers { it.set(REQUEST_ID_HEADER, requestId) }
                 .build()
         exchange.response.headers.set(REQUEST_ID_HEADER, requestId)
+        val mutated = exchange.mutate().request(request).build()
+        val context = Context.of(RequestContext.REQUEST_ID, requestId, RequestContext.CLIENT_IP, clientIp)
 
         val path = exchange.request.path.value()
-        if (path.startsWith("/actuator/")) return chain.filter(exchange.mutate().request(request).build())
+        if (path.startsWith("/actuator/")) return chain.filter(mutated).contextWrite(context)
 
         val start = System.nanoTime()
-        return chain.filter(exchange.mutate().request(request).build()).doFinally {
-            log.info(
-                "{} {} {} {}ms requestId={} userId={}",
-                exchange.request.method,
-                path,
-                exchange.response.statusCode?.value(),
-                (System.nanoTime() - start) / 1_000_000,
-                requestId,
-                exchange.getAttribute<String>(JwtAuthenticationFilter.USER_ID_HEADER) ?: "-",
-            )
+        return chain
+            .filter(mutated)
+            .doFinally { log(exchange, path, start) }
+            .contextWrite(context)
+    }
+
+    private fun log(
+        exchange: ServerWebExchange,
+        path: String,
+        start: Long,
+    ) {
+        val status = exchange.response.statusCode?.value()
+        val latencyMs = (System.nanoTime() - start) / 1_000_000
+        val routeId = exchange.getAttribute<Route>(GATEWAY_ROUTE_ATTR)?.id
+        RequestContext.withMdc(exchange) {
+            log
+                .atInfo()
+                .addKeyValue("method", exchange.request.method.name())
+                .addKeyValue("path", path)
+                .addKeyValue("status", status)
+                .addKeyValue("latencyMs", latencyMs)
+                .addKeyValue("routeId", routeId ?: "-")
+                .log("{} {} {} {}ms", exchange.request.method, path, status, latencyMs)
         }
     }
 

rush-gateway/src/main/kotlin/com/rush/gateway/filter/JwtAuthenticationFilter.kt

@@ -1,6 +1,7 @@
 package com.rush.gateway.filter
 
 import com.rush.gateway.error.ErrorResponseWriter
+import com.rush.gateway.logging.RequestContext
 import io.jsonwebtoken.Jwts
 import io.jsonwebtoken.security.Keys
 import org.springframework.beans.factory.annotation.Value
@@ -63,14 +64,17 @@ class JwtAuthenticationFilter(
             }.getOrNull() ?: return unauthorized(exchange)
 
         exchange.attributes[USER_ID_HEADER] = userId
+        RequestContext.put(exchange, RequestContext.USER_ID, userId)
         // 쿼리로 받은 토큰은 검증이 끝났으므로 서비스 쪽 로그에 남지 않게 지웁니다.
         val authed =
             sanitized
                 .mutate()
                 .uri(withoutTokenQuery(request.uri))
                 .header(USER_ID_HEADER, userId)
                 .build()
-        return chain.filter(exchange.mutate().request(authed).build())
+        return chain
+            .filter(exchange.mutate().request(authed).build())
+            .contextWrite { it.put(RequestContext.USER_ID, userId) }
     }
 
     // 인증은 디코딩된 키로 토큰을 읽으므로, ?%74oken=처럼 인코딩된 키도 디코딩한 뒤 비교해 지웁니다.

rush-gateway/src/main/kotlin/com/rush/gateway/logging/MdcContextPropagationConfig.kt

@@ -0,0 +1,23 @@
+package com.rush.gateway.logging
+
+import io.micrometer.context.ContextRegistry
+import org.slf4j.MDC
+import org.springframework.context.annotation.Configuration
+
+/**
+ * Reactor context에 넣은 요청 추적 값을 로그 MDC로 옮기도록 등록합니다.
+ * spring.reactor.context-propagation=auto와 함께 쓰여, 스레드가 바뀌어도 MDC가 이어집니다.
+ */
+@Configuration(proxyBeanMethods = false)
+class MdcContextPropagationConfig {
+    init {
+        RequestContext.KEYS.forEach { key ->
+            ContextRegistry.getInstance().registerThreadLocalAccessor(
+                key,
+                { MDC.get(key) },
+                { value: String -> MDC.put(key, value) },
+                { MDC.remove(key) },
+            )
+        }
+    }
+}

rush-gateway/src/main/kotlin/com/rush/gateway/logging/RequestContext.kt

@@ -0,0 +1,47 @@
+package com.rush.gateway.logging
+
+import org.slf4j.MDC
+import org.springframework.web.server.ServerWebExchange
+
+/**
+ * 요청 하나를 추적하는 값(requestId, userId, clientIp)의 키와 보관 방법을 모아 둡니다.
+ *
+ * WebFilter 체인 안의 로그는 Reactor context → MDC 전파로 이 값을 자동으로 갖습니다.
+ * 체인 바깥(ErrorWebExceptionHandler 등)에서는 exchange attribute를 읽어 [withMdc]로 남깁니다.
+ */
+object RequestContext {
+    const val REQUEST_ID = "requestId"
+    const val USER_ID = "userId"
+    const val CLIENT_IP = "clientIp"
+
+    val KEYS = listOf(REQUEST_ID, USER_ID, CLIENT_IP)
+
+    private fun attribute(key: String) = "rush.gateway.$key"
+
+    fun put(
+        exchange: ServerWebExchange,
+        key: String,
+        value: String,
+    ) {
+        exchange.attributes[attribute(key)] = value
+    }
+
+    fun get(
+        exchange: ServerWebExchange,
+        key: String,
+    ): String? = exchange.getAttribute<String>(attribute(key))
+
+    /** exchange에 저장된 값을 MDC에 넣은 채로 [block]을 실행합니다. */
+    fun <T> withMdc(
+        exchange: ServerWebExchange,
+        block: () -> T,
+    ): T {
+        val previous = MDC.getCopyOfContextMap()
+        KEYS.forEach { key -> get(exchange, key)?.let { MDC.put(key, it) } }
+        try {
+            return block()
+        } finally {
+            if (previous == null) MDC.clear() else MDC.setContextMap(previous)
+        }
+    }
+}

rush-gateway/src/main/resources/application.yml

@@ -8,6 +8,9 @@ spring:
     name: rush-gateway
   config:
     import: optional:configserver:${CONFIG_URL:http://localhost:8888}
+  reactor:
+    # Reactor context의 requestId·userId·clientIp를 로그 MDC로 이어 줍니다.
+    context-propagation: auto
   autoconfigure:
     # 로그인 사용자가 없으므로 기본 사용자와 임시 비밀번호를 만들지 않습니다.
     exclude: org.springframework.boot.autoconfigure.security.reactive.ReactiveUserDetailsServiceAutoConfiguration
@@ -110,3 +113,9 @@ management:
     gateway:
       # SCG 기본값은 none(꺼짐)입니다. 라우트 조회만 열고 생성·삭제·refresh는 막습니다.
       access: read-only
+
+# 로그를 JSON 한 줄로 남깁니다. MDC(requestId, userId, clientIp)와 접근 로그 필드가 그대로 들어갑니다.
+logging:
+  structured:
+    format:
+      console: logstash

rush-gateway/src/test/kotlin/com/rush/gateway/logging/AccessLogTest.kt

@@ -0,0 +1,139 @@
+package com.rush.gateway.logging
+
+import com.fasterxml.jackson.databind.JsonNode
+import com.fasterxml.jackson.databind.ObjectMapper
+import com.sun.net.httpserver.HttpServer
+import io.jsonwebtoken.Jwts
+import io.jsonwebtoken.security.Keys
+import org.assertj.core.api.Assertions.assertThat
+import org.junit.jupiter.api.AfterAll
+import org.junit.jupiter.api.Test
+import org.junit.jupiter.api.extension.ExtendWith
+import org.springframework.beans.factory.annotation.Autowired
+import org.springframework.boot.test.context.SpringBootTest
+import org.springframework.boot.test.system.CapturedOutput
+import org.springframework.boot.test.system.OutputCaptureExtension
+import org.springframework.test.context.DynamicPropertyRegistry
+import org.springframework.test.context.DynamicPropertySource
+import org.springframework.test.web.reactive.server.WebTestClient
+import java.net.InetSocketAddress
+import java.net.ServerSocket
+import java.time.Duration
+
+private const val SECRET = "test-secret-key-for-gateway-access-log-test-0123456789"
+
+// clientIp를 확인하려면 remoteAddress가 필요하므로 실제 서버(RANDOM_PORT)로 요청합니다.
+@ExtendWith(OutputCaptureExtension::class)
+@SpringBootTest(
+    webEnvironment = SpringBootTest.WebEnvironment.RANDOM_PORT,
+    properties = [
+        "spring.cloud.config.enabled=false",
+        "eureka.client.enabled=false",
+        "jwt.secret=$SECRET",
+    ],
+)
+class AccessLogTest {
+    @Autowired
+    lateinit var client: WebTestClient
+
+    private val objectMapper = ObjectMapper()
+
+    @Test
+    fun `요청마다 JSON 접근 로그를 한 줄 남긴다`(output: CapturedOutput) {
+        val requestId = requestIdOf("/user/ping", token("42"))
+
+        val line =
+            awaitLine(output) {
+                it.path("requestId").asText() == requestId &&
+                    it.path("logger_name").asText().endsWith("AccessLogFilter")
+            }
+        assertThat(line.path("userId").asText()).isEqualTo("42")
+        assertThat(line.path("clientIp").asText()).isEqualTo("127.0.0.1")
+        assertThat(line.path("routeId").asText()).isEqualTo("rush-user")
+        assertThat(line.path("status").asInt()).isEqualTo(200)
+        assertThat(line.path("method").asText()).isEqualTo("GET")
+        assertThat(line.path("path").asText()).isEqualTo("/user/ping")
+    }
+
+    @Test
+    fun `게이트웨이가 거절한 요청도 접근 로그에 남는다`(output: CapturedOutput) {
+        val requestId = requestIdOf("/user/ping", token = null)
+
+        val line = awaitLine(output) { it.path("requestId").asText() == requestId && it.has("status") }
+        assertThat(line.path("status").asInt()).isEqualTo(401)
+    }
+
+    @Test
+    fun `라우트 처리 중 남긴 로그에도 MDC가 이어진다`(output: CapturedOutput) {
+        val requestId = requestIdOf("/sp/ping", token("7"))
+
+        val fallbackLog = awaitLine(output) { it.path("logger_name").asText().endsWith("FallbackController") }
+        assertThat(fallbackLog.path("requestId").asText()).isEqualTo(requestId)
+        assertThat(fallbackLog.path("userId").asText()).isEqualTo("7")
+    }
+
+    private fun requestIdOf(
+        uri: String,
+        token: String?,
+    ): String =
+        client
+            .get()
+            .uri(uri)
+            .apply { if (token != null) header("Authorization", "Bearer $token") }
+            .exchange()
+            .returnResult(String::class.java)
+            .responseHeaders
+            .getFirst("X-Request-Id")!!
+
+    // 접근 로그는 응답을 보낸 뒤 doFinally에서 남으므로, 나타날 때까지 잠시 기다립니다.
+    private fun awaitLine(
+        output: CapturedOutput,
+        predicate: (JsonNode) -> Boolean,
+    ): JsonNode {
+        val deadline = System.nanoTime() + Duration.ofSeconds(2).toNanos()
+        while (true) {
+            jsonLines(output).singleOrNull(predicate)?.let { return it }
+            if (System.nanoTime() > deadline) return jsonLines(output).single(predicate)
+            Thread.sleep(20)
+        }
+    }
+
+    private fun jsonLines(output: CapturedOutput): List<JsonNode> =
+        output.out
+            .lines()
+            .filter { it.startsWith("{") }
+            .map { objectMapper.readTree(it) }
+
+    companion object {
+        private val okServer =
+            HttpServer.create(InetSocketAddress("localhost", 0), 0).apply {
+                createContext("/") { exchange ->
+                    exchange.sendResponseHeaders(200, -1)
+                    exchange.close()
+                }
+                start()
+            }
+
+        private val closedPort = ServerSocket(0).use { it.localPort }
+
+        @JvmStatic
+        @DynamicPropertySource
+        fun routes(registry: DynamicPropertyRegistry) {
+            registry.add("USER_URL") { "http://localhost:${okServer.address.port}" }
+            registry.add("SP_URL") { "http://localhost:$closedPort" }
+        }
+
+        @JvmStatic
+        @AfterAll
+        fun stopServer() {
+            okServer.stop(0)
+        }
+
+        private fun token(subject: String): String =
+            Jwts
+                .builder()
+                .subject(subject)
+                .signWith(Keys.hmacShaKeyFor(SECRET.toByteArray()))
+                .compact()
+    }
+}