day 15 對 todo-api 連打 5 個會出錯的請求，伺服器的 ERROR log 完全沒有紀錄，StatusPages 把例外接走之後 handleFailure 不再執行，記 log 的 logFailure 跟著沒被呼叫，client 收到的 400 跟 404 在伺服器端一點痕跡都沒有
這篇會裝上 3 個東西，CallLogging 是 Ktor 的請求記錄 plugin，每個請求記一行「回應了什麼」，CallId 替每個請求發一個識別碼，client 自己帶的就沿用，沒帶的就產生一個，MDC 是 Mapped Diagnostic Context 的縮寫，SLF4J 提供的一張掛在執行緒上的 key-value 表，log 的 pattern 寫 %X{key} 就會把值印出來，不用每一行訊息自己串，call id 靠它才能出現在每一行 log 上
裝完之後還有 3 件事要確認，CallLogging 到底掛在哪一個 phase，day 09 給過一個答案，這篇翻原始碼再對一次，day 15 自己補的那行 log.error 現在還需不需要，它寫進 log 的東西適不適合留在檔案裡，還有 MDC 跨不跨得過 thread，界線在哪裡
withMDC、logError
logback.xml 的 pattern 加 %X{callId}
log.error 用的 uri 改成 path()，query string 不再進 loglog.error 裝完 CallLogging 之後還需不需要2 個相依套件，build.gradle.kts 的 dependencies 區塊裡接在 statusPages 後面
implementation(ktorLibs.server.callLogging)
implementation(ktorLibs.server.callId)
Application.kt 先只加一行 install(CallLogging)，完全不設定，跑起來打 3 個請求
curl -s -o /dev/null localhost:8080/
curl -s -o /dev/null localhost:8080/todos/999
curl -s -o /dev/null -X POST -H "Content-Type: application/json" \
-d '{"title":" "}' localhost:8080/todos
伺服器那邊多了 3 行
[eventLoopGroupProxy-4-1] INFO io.ktor.server.Application -- 200 OK: GET - / in 13ms
[eventLoopGroupProxy-4-2] INFO io.ktor.server.Application -- 404 Not Found: GET - /todos/999 in 28ms
[eventLoopGroupProxy-4-3] INFO io.ktor.server.Application -- 400 Bad Request: POST - /todos in 9ms
前面時間戳省略了，狀態碼、method、路徑、耗時 4 樣一次到齊，格式來自 CallLoggingConfig 的 defaultFormat，這就是 day 15 缺的那一塊，第 3 行那個 400 正是驗證失敗的請求，StatusPages 接走例外之後它在 log 裡消失，現在回來了
這一輪還帶出 2 個要處理的東西，第 1 個是這 3 行以外還有 53 行 netty 的 DEBUG 訊息，因為專案裡沒有 logback.xml，logback 找不到設定就用預設值，root level 是 DEBUG，全開，第 2 個是顏色
defaultFormat 用 jansi 上色，狀態碼綠、黃或紅，method 青色，輸出到終端機才會有色碼，重導到檔案 jansi 就把碼拿掉，顏色本身不會污染 log 檔，但它讓 log 的內容取決於「輸出到哪裡」，這種不確定性在正式環境不是很好，等一下會用 disableDefaultColors() 關掉
這篇的實作繞著 4 份原始碼打轉，CallLogging 的 2 個 hook、CallId 的取值流程、withMDC 的跨 thread 機制，還有 engine 那支 logError，所以先一次看完，後面就不用再回頭
day 09 拆 5 個 phase 的時候，Monitoring 那一段寫的是「觀測用，原始碼註解直接點名 logging、metrics、錯誤處理，day 16 裝 CallLogging 時會再回來看這一段」，後面講 plugin 順序的時候又寫了一次，「CallLogging 說我是 Monitoring、routing 說我是 Call」。現在回來了，而答案跟當時的預期有出入
CallLogging.kt 的主體，跟這件事有關的只有幾行
createApplicationPlugin("CallLogging", ::CallLoggingConfig) {
setupMDCProvider()
on(CallSetup) { call ->
call.attributes.put(CALL_START_TIME, clock())
}
if (pluginConfig.mdcEntries.isEmpty()) {
logCompletedCalls(::logSuccess)
return@createApplicationPlugin
}
logCallsWithMDC(::logSuccess)
}
CallSetup 這個 hook 掛的是 ApplicationCallPipeline.Setup，跟 day 09 說的 Monitoring 不同段，它做的事也很單純，把開始時間放進 call.attributes，跟 day 10 的 RequestTiming 一模一樣的手法
記 log 那一半在 2 個私有函式裡，沒有設定任何 mdc(...) 的時候走 logCompletedCalls，內容只有 on(ResponseSent) { logSuccess(it) } 一行，整個 plugin 就是 Setup 記時間、ResponseSent 記一行，Monitoring phase 從頭到尾沒出現，設了 MDC 才走另一個
private fun PluginBuilder<CallLoggingConfig>.logCallsWithMDC(logSuccess: (ApplicationCall) -> Unit) {
val entries = pluginConfig.mdcEntries
on(MDCHook(ApplicationCallPipeline.Monitoring)) { call, proceed ->
withMDC(entries, call, proceed)
}
on(MDCHook(ApplicationCallPipeline.Call)) { call, proceed ->
withMDC(entries, call, proceed)
}
on(ResponseSent) { call ->
withMDC(entries, call) { logSuccess(call) }
}
}
這時候才有 2 個 MDCHook，一個指向 Monitoring、一個指向 Call
就算走到那條，MDCHook 也不是掛進 Monitoring 裡面
internal fun MDCHook(phase: PipelinePhase) = object : Hook<...> {
override fun install(pipeline: ApplicationCallPipeline, handler: ...) {
val mdcPhase = PipelinePhase("${phase.name}MDC")
pipeline.insertPhaseBefore(phase, mdcPhase)
pipeline.intercept(mdcPhase) { handler(call, ::proceed) }
}
}
它開一個叫 MonitoringMDC 的新 phase 插在 Monitoring 前面，這跟 day 15 看 StatusPages 的 CallFailed 是同一招，那邊叫 BeforeSetup、插在 Setup 前面
所以 day 09 那句預告的正確版本是這樣，CallLogging 的 2 個主要動作分別在 Setup phase 跟 send pipeline，只有 MDC 模式會在 Monitoring 跟 Call 前面各插一個自己的 phase，Monitoring 的官方註解點名了 logging 跟 metrics，CommonHooks.kt 裡的 Metrics hook 確實 intercept(ApplicationCallPipeline.Monitoring) 住了進去，logging 這個沒有
ResponseSent 掛的位置也要看一下
pipeline.sendPipeline.intercept(ApplicationSendPipeline.Engine) {
if (call.attributes.contains(responseSentMarker)) return@intercept
call.attributes.put(responseSentMarker, Unit)
proceed()
handler(call)
}
send pipeline 的最後一段 Engine phase，先 proceed() 讓 engine 把回應寫出去，回來才記 log，那個 responseSentMarker 跟 day 15 的 statusPageMarker 是同一種東西，防止同一個請求被記 2 次，day 15 修 X-Response-Time 出現 2 次的時候是自己加了一行 if 判斷，Ktor 官方的 plugin 用的是 attributes 蓋章，做法一致
day 09 介紹 Setup phase 的時候點名過 CallId 是典型住戶，CallIdSetup 這個 hook 兌現了那句話，它 intercept 的正是 ApplicationCallPipeline.Setup
plugin 的主體有 2 個 hook，主要的邏輯都在第 1 個
on(CallIdSetup) { call ->
for (provider in providers) {
val callId = provider(call) ?: continue
if (!verifier(callId)) continue
call.attributes.put(CallIdKey, callId)
repliers.forEach { replier -> replier(call, callId) }
withCallId(callId) { proceed() }
break
}
}
providers 是 retrievers + generators 串起來的陣列，順序就是優先順序，先問 header 有沒有，沒有才輪到產生器，verifier 沒過就 continue 換下一個 provider，所以 client 送了一個不合格的 id，結果不是被拒絕，是被安靜換成產生的那一個
第 2 個 hook 是 on(CallFailed)，只處理 RejectedCallIdException，那是 verify(dictionary, reject = true) 才會丟的例外，這篇用的是預設的 reject = false，所以走不到那裡
那個 withCallId(callId) { proceed() } 把 id 放進 coroutine context 的 KtorCallIdContextElement，要注意的是 MDC 那條路不走這裡，callIdMdc 讀的是 call.callId，也就是上面那行 attributes.put 放進去的東西
預設的 verifier 是一張白名單，CallIdConfig 的 init 區塊是 verify(CALL_ID_DEFAULT_DICTIONARY)，而那個字典住在 io.ktor.callid 這個 shared 模組，不是 plugin 自己的套件
public const val CALL_ID_DEFAULT_DICTIONARY: String = "abcdefghijklmnopqrstuvwxyz0123456789+/=-"
沒有大寫字母，client 送一個大寫的 request id 過來會直接被丟掉，預設的版本對長度也沒有意見，理論上可以塞一個十萬字元的 id 進你的 log，所以等一下自訂的 verify 會沿用同一張字典再多加一個長度上限
白名單這個設計比較嚴僅一點，call id 是一段 client 完全控制的字串，最後會原封不動出現在 log 檔裡，字典擋掉的空白、控制字元、換行，正好都是偽造 log 行所需要的材料
MDC 底層是 ThreadLocal，而 Ktor 的 handler 是 coroutine，隨時可能換執行緒，這 2 件事天生打架，Ktor 的解法在 withMDC
internal suspend inline fun withMDC(...) {
withContext(MDCContext(mdcEntries.setup(call))) {
try {
block()
} finally {
mdcEntries.cleanup()
}
}
}
MDCContext 來自 kotlinx-coroutines-slf4j，它是一個 ThreadContextElement，coroutine 每次被排到某個執行緒上跑之前，它負責把那張表寫進該執行緒的 MDC，離開時再還原，CallLogging 把它包在 Monitoring 跟 Call 2 段前面，等於整個 handler 的執行期間都在這個 context 裡
mdcEntries.setup(call) 還有一個細節，取到的值會存進 call.attributes，第 2 次第 3 次進來直接拿現成的，同一個請求的 call id 只會計算一次
engine 的 logError 是這樣寫的
public suspend fun logError(call: ApplicationCall, error: Throwable) {
call.application.mdcProvider.withMDCBlock(call) {
call.application.environment.logFailure(call, error)
}
}
mdcProvider 是 io.ktor.server.logging 底下的 public API，會從 plugin registry 裡找出實作了 MDCProvider 的 plugin，找不到就用一個什麼都不做的空實作，CallLogging 的 setupMDCProvider() 註冊的就是它，CallLogging 自己的 ResponseSent hook 也一樣，明明前面已經包過 withMDC 了，記 log 之前還是再包一次
day 10 寫 RequestTiming 的時候已經把界線畫過一次，一個寫 header 給 client、一個寫 log 給開發者，現在 2 個並存，可以看得更細一點
CallSetup interceptor (Setup phase) 開始算，到 send pipeline 的 Engine phase proceed() 回來為止onCall (Plugins phase) 開始算，到 onCallRespond 為止前者的起點一定早於 Plugins，終點也在回應真正寫進網路之後，所以區間包住 RequestTiming
時鐘也不一樣，CallLogging 的 processingTimeMillis 底下是 getTimeMillis()，JVM 上就是 System.currentTimeMillis()，那是系統時鐘，會被 NTP 校時往前往後跳，RequestTiming 用的 System.nanoTime() 是單調時鐘，只保證往前走，Relix day 15 選 TimeSource.Monotonic 的理由就是這個
Ktor 這裡選系統時鐘，看起來是因為 processingTimeMillis 的 clock 參數開放給使用者換掉，換成可控的假時鐘測試才好寫，nanoTime 那種沒有絕對意義的數字反而不好偽造，以 request log 的精度來說，NTP 那點誤差不會改變「這個請求跑了 300 毫秒」這個結論
設定放在新檔案 src/main/kotlin/com/cashwu/todo/Logging.kt
const val REQUEST_ID_HEADER = "X-Request-Id"
const val CALL_ID_MDC_KEY = "callId"
const val CALL_ID_LENGTH = 12
const val CALL_ID_MAX_LENGTH = 64
fun CallIdConfig.todoCallId() {
header(REQUEST_ID_HEADER)
generate(length = CALL_ID_LENGTH)
verify { callId ->
callId.length in 1..CALL_ID_MAX_LENGTH && callId.all { it in CALL_ID_DEFAULT_DICTIONARY }
}
}
3 個設定分別是 3 件事。header(...) 等於 retrieveFromHeader 加 replyToHeader，從 X-Request-Id 讀進來、也用同一個 header 回出去，generate(12) 是讀不到的時候自己產一個，verify 沿用預設那張字典，只是多加一個長度的上限，4 個常數都是 const val，測試那邊會直接拿來用，不會再抄一次字面值
CALL_ID_DEFAULT_DICTIONARY 的 import 要注意，它在 io.ktor.callid 而不是 io.ktor.server.plugins.callid，IDE 的自動 import 第 1 次會找不到
CallLogging 的設定接在同一個檔案下面
fun CallLoggingConfig.todoCallLogging() {
level = Level.INFO
disableDefaultColors()
callIdMdc(CALL_ID_MDC_KEY)
format { call ->
val status = call.response.status()?.value ?: "Unhandled"
val method = call.request.httpMethod.value
"$status $method ${call.request.path()} ${call.processingTimeMillis()}ms"
}
}
callIdMdc 是 CallId 那個模組提供的 extension function，實作只有 1 行 mdc(name) { it.callId }，它的參數有預設值，但預設的 key 是大寫開頭的 CallId，而 %X{} 的 key 有分大小寫，兩邊寫不一致就會印出空的，這裡明確傳一個常數進去，設定跟 pattern 共用同一個名字
format 換掉預設格式的理由是預設那個把狀態碼的 reason phrase 也印出來 (200 OK、404 Not Found)，而狀態碼本來就是給機器看的，數字就夠了，順便把中間那個 - 拿掉，欄位之間只留空白，之後要用 awk 之類的東西切欄位比較單純
Application.kt 把 2 個 plugin 裝上，放在最前面
fun Application.module() {
install(CallId) {
todoCallId()
}
install(CallLogging) {
todoCallLogging()
}
install(RequestTiming)
// ... 其餘三個 plugin 不變
}
CallId 跟 CallLogging 的開始計時都在 Setup，同 phase 內仍看註冊順序，所以 2 個 install 的先後會改變計時是否包含 call id 的取得，這篇把 CallId 放前面，id 先進 attributes，接著才走到 CallLogging 的開始時間，MDC hook 在 Monitoring 前面，不管 2 個 Setup interceptor 誰先執行，走到 MDC 時都已經有 id，安裝順序影響的是計時邊界，不是 MDC 能不能取到值
接下來是 pattern，專案還沒有 logback 設定檔，開一個 src/main/resources/logback.xml
<configuration>
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>%d{HH:mm:ss.SSS} %-5level [%X{callId:-no-call-id}] %logger{20} -- %msg%n</pattern>
</encoder>
</appender>
<root level="INFO">
<appender-ref ref="STDOUT"/>
</root>
<logger name="io.netty" level="INFO"/>
</configuration>
%X{callId:-no-call-id} 的 :- 後面是預設值，MDC 裡沒有這個 key 的時候印 no-call-id
啟動階段那 3 行 log 不屬於任何請求，就會是這個樣子
15:52:09.134 INFO [no-call-id] i.k.s.Application -- Autoreload is disabled because the development mode is off.
15:52:09.215 INFO [no-call-id] i.k.s.Application -- Application started in 0.175 seconds.
15:52:09.287 INFO [no-call-id] i.k.s.Application -- Responding at http://0.0.0.0:8080
一眼看得出來它跟請求無關，root level 從預設的 DEBUG 改成 INFO，前面那 53 行 netty 訊息一次消失
這個檔案放在 src/main/resources，測試也會讀到它，因為 main 的資源目錄本來就在測試的 classpath 上
最後還有一行要改，day 15 那行 log.error 用的是 call.request.uri，打一個帶 query string 的請求就知道問題在哪，day 15 為了看未預期例外臨時加在 Application.kt 的 routing { } 裡那條 /boom 就留著不拿掉了，這篇後面的測試跟實測都還要用它
curl -s -o /dev/null "localhost:8080/boom?token=super-secret"
15:52:59.030 ERROR [0m0ckd3capc6] i.k.s.Application -- Unhandled exception on /boom?token=super-secret
15:52:59.050 INFO [0m0ckd3capc6] i.k.s.Application -- 500 GET /boom 40ms
同一個請求 2 行，下面那行乾淨，上面那行把 query string 整串寫進 log 檔。差別在 uri 回傳的是路徑加 query string，而 CallLogging 用的 path() 實作是 origin.uri.substringBefore('?')，? 後面的東西根本沒機會進來
token 放 query string 本來就不是好習慣，但 log 這一層不該假設上游都很乖，ErrorHandling.kt 那行改成 call.request.path()
call.application.log.error("Unhandled exception on ${call.request.path()}", cause)
同一個檔案上面那行 import io.ktor.server.request.uri 也要換成 import io.ktor.server.request.path，2 個都是 extension，少換一個編譯不過
改完再打一次同一個請求，2 行從此一致
15:52:39.677 ERROR [wxr-0hj-hrj3] i.k.s.Application -- Unhandled exception on /boom
15:52:39.679 INFO [wxr-0hj-hrj3] i.k.s.Application -- 500 GET /boom 7ms
實作到齊了，先寫測試把行為固定下來，再開伺服器看實際的輸出
測 log 的難處是要拿到輸出，直接攔 stdout 很脆弱，logback 有現成的東西，新開 src/test/kotlin/com/cashwu/todo/CallLoggingTest.kt，import 一次列完，後面每一組只貼 class 裡面的部分
package com.cashwu.todo
import ch.qos.logback.classic.spi.ILoggingEvent
import ch.qos.logback.core.read.ListAppender
import io.ktor.client.request.get
import io.ktor.client.request.header
import io.ktor.client.request.post
import io.ktor.client.request.setBody
import io.ktor.http.ContentType
import io.ktor.http.HttpHeaders
import io.ktor.http.HttpStatusCode
import io.ktor.server.application.log
import io.ktor.server.response.respondText
import io.ktor.server.routing.get
import io.ktor.server.routing.routing
import io.ktor.server.testing.ApplicationTestBuilder
import io.ktor.server.testing.testApplication
import kotlinx.coroutines.delay
import org.slf4j.LoggerFactory
import kotlin.test.AfterTest
import kotlin.test.BeforeTest
import kotlin.test.Test
import kotlin.test.assertEquals
import kotlin.test.assertNotEquals
import kotlin.test.assertNotNull
import kotlin.test.assertNull
import kotlin.test.assertTrue
先是測試共用的那一套
class CallLoggingTest {
private val appender = ListAppender<ILoggingEvent>()
private val root =
LoggerFactory.getLogger(org.slf4j.Logger.ROOT_LOGGER_NAME) as ch.qos.logback.classic.Logger
@BeforeTest
fun attachAppender() {
todos.clear()
todos.addAll(defaultTodos)
appender.list.clear()
appender.start()
root.addAppender(appender)
}
@AfterTest
fun detachAppender() {
root.detachAppender(appender)
appender.stop()
}
// 底下四組測試都放進這個 class
}
todos 那 2 行是 day 12 開始的慣例，全域的可變清單每個測試前要復原，ListAppender 接到 root logger 之後，每一筆 ILoggingEvent 都會進到 appender.list，這比攔 stdout 好的地方在於拿到的是結構化的事件，訊息、level、例外、MDC 都是分開的欄位，pattern 怎麼改都不影響測試
接著是挑出 CallLogging 那幾行的工具
private val requestLine =
Regex("""^(\d{3}|Unhandled) (GET|POST|PUT|DELETE) (\S+) (\d+)ms$""")
private fun requestLines(): List<MatchResult> =
appender.list.mapNotNull { requestLine.matchEntire(it.formattedMessage) }
private fun requestEvents(): List<ILoggingEvent> =
appender.list.filter { requestLine.matches(it.formattedMessage) }
// ResponseSent 先 proceed() 才記 log，client 收到回應時那行可能還沒寫進 appender
private suspend fun awaitRequestLines(count: Int): List<MatchResult> {
repeat(200) {
val lines = requestLines()
if (lines.size >= count) return lines
delay(10)
}
return requestLines()
}
private fun ApplicationTestBuilder.todoApp() = application { module() }
那個 regex 順便把 4 個欄位切開，斷言直接對 group 比，awaitRequestLines 處理的是一個 timing 問題，ResponseSent 是先 proceed() 才記 log，client 收到回應的時候那行可能還沒寫進去，所以輪詢，每 10 毫秒看一次，湊到指定筆數才回來
第 1 組驗證「每個請求都有一行」
@Test
fun `a successful request is logged as one line`() = testApplication {
todoApp()
client.get("/")
val lines = awaitRequestLines(1)
assertEquals(1, lines.size)
val (status, method, path, _) = lines.single().destructured
assertEquals("200", status)
assertEquals("GET", method)
assertEquals("/", path)
}
@Test
fun `a client error is logged even though status pages handled it`() = testApplication {
todoApp()
val response = client.post("/todos") {
header(HttpHeaders.ContentType, ContentType.Application.Json)
setBody("""{"title":" "}""")
}
assertEquals(HttpStatusCode.BadRequest, response.status)
val lines = awaitRequestLines(1)
assertEquals(1, lines.size)
val (status, method, path, _) = lines.single().destructured
assertEquals("400", status)
assertEquals("POST", method)
assertEquals("/todos", path)
}
@Test
fun `a path with no route is logged too`() = testApplication {
todoApp()
client.get("/nothing-here")
val lines = awaitRequestLines(1)
assertEquals(1, lines.size)
val (status, _, path, _) = lines.single().destructured
assertEquals("404", status)
assertEquals("/nothing-here", path)
}
中間那個就是 day 15 那個缺口的守門員，驗證失敗的請求被 StatusPages 接走之後，log 裡還是要有一行，第 3 個確認 Fallback phase 回的東西也記得到
第 2 組驗證 call id 跟 MDC
@Test
fun `the log line carries the call id that went back to the client`() = testApplication {
todoApp()
val response = client.get("/")
val replied = response.headers[REQUEST_ID_HEADER]
assertNotNull(replied)
awaitRequestLines(1)
val event = requestEvents().single()
assertEquals(replied, event.mdcPropertyMap[CALL_ID_MDC_KEY])
}
@Test
fun `a log written inside the handler shares the call id`() = testApplication {
application {
module()
routing {
get("/inside") {
call.application.log.info("handler 裡面記的一行")
call.respondText("ok")
}
}
}
client.get("/inside")
awaitRequestLines(1)
val handlerLine = appender.list.single { it.formattedMessage == "handler 裡面記的一行" }
val requestLine = requestEvents().single()
assertNotNull(handlerLine.mdcPropertyMap[CALL_ID_MDC_KEY])
assertEquals(
handlerLine.mdcPropertyMap[CALL_ID_MDC_KEY],
requestLine.mdcPropertyMap[CALL_ID_MDC_KEY],
)
}
@Test
fun `the request line has no exception but the error log does`() = testApplication {
todoApp()
val response = client.get("/boom")
assertEquals(HttpStatusCode.InternalServerError, response.status)
awaitRequestLines(1)
val requestLine = requestEvents().single()
val errorLine = appender.list.single {
it.formattedMessage.startsWith("Unhandled exception on ")
}
assertNull(requestLine.throwableProxy)
assertNotNull(errorLine.throwableProxy)
assertEquals(
errorLine.mdcPropertyMap[CALL_ID_MDC_KEY],
requestLine.mdcPropertyMap[CALL_ID_MDC_KEY],
)
}
@Test
fun `no log line carries the query string`() = testApplication {
todoApp()
client.get("/boom?token=super-secret")
awaitRequestLines(1)
assertTrue(appender.list.none { "super-secret" in it.formattedMessage })
}
第 1 個比對 event.mdcPropertyMap["callId"] 跟回應的 X-Request-Id，兩邊要是同一個字串，第 2 個開一條自己記 log 的路由，證明 handler 內部寫的 log 也有 call id，第 3 個把「2 行分工」這件事固定下來，CallLogging 那行的 throwableProxy 是 null、ERROR 那行不是，而 2 行的 call id 一樣，最後一個是剛才那個 path() 修正的守門員
第 3 組驗證 CallId 的取值與驗證
@Test
fun `a call id sent by the client comes back unchanged`() = testApplication {
todoApp()
val response = client.get("/") { header(REQUEST_ID_HEADER, "my-trace-001") }
assertEquals("my-trace-001", response.headers[REQUEST_ID_HEADER])
}
@Test
fun `a call id with upper case letters is replaced`() = testApplication {
todoApp()
val response = client.get("/") { header(REQUEST_ID_HEADER, "ABC123") }
val replied = response.headers[REQUEST_ID_HEADER]
assertNotEquals("ABC123", replied)
assertEquals(CALL_ID_LENGTH, replied?.length)
}
@Test
fun `a call id longer than the limit is replaced`() = testApplication {
todoApp()
val tooLong = "a".repeat(CALL_ID_MAX_LENGTH + 1)
val response = client.get("/") { header(REQUEST_ID_HEADER, tooLong) }
val replied = response.headers[REQUEST_ID_HEADER]
assertNotEquals(tooLong, replied)
assertEquals(CALL_ID_LENGTH, replied?.length)
}
@Test
fun `two requests without a call id get different generated ones`() = testApplication {
todoApp()
val first = client.get("/").headers[REQUEST_ID_HEADER]
val second = client.get("/").headers[REQUEST_ID_HEADER]
assertNotNull(first)
assertNotNull(second)
assertNotEquals(first, second)
}
中間 2 個確認的是「被安靜換掉」而不是「被拒絕」，回的都是 200，只是 header 換成產生的那個。CALL_ID_LENGTH 跟 CALL_ID_MAX_LENGTH 直接引用 Logging.kt 的常數，設定改了測試會跟著動
最後一個驗證 2 個時鐘
@Test
fun `call logging and timing header both report millisecond durations`() = testApplication {
todoApp()
val response = client.get("/")
val header = response.headers["X-Response-Time"]
assertNotNull(header)
assertNotNull(header.removeSuffix("ms").toLongOrNull())
val lines = awaitRequestLines(1)
assertNotNull(lines.single().groupValues[4].toLongOrNull())
}
}
只確認兩邊都有可解析的毫秒值，不比較大小，CallLogging 的區間雖然包住 RequestTiming，但兩邊分別用 currentTimeMillis() 跟 nanoTime()，系統時鐘被校正、兩邊的解析度也不一樣，logged >= header 偶爾就是會不成立，2 個時鐘量出來的數字，不適合拿相對大小當測試的斷言
測試都通過了，回到伺服器打一輪完整的，7 個請求，第 1 個是會成功的 /todos/1，第 2 個是自己帶 id 的 /todos/999，後面 5 個就是 day 15 那 5 個失敗的請求，驗證失敗、少欄位、JSON 壞掉、找不到路由、找不到資料
curl -i localhost:8080/todos/1
curl -i -H "X-Request-Id: my-trace-001" localhost:8080/todos/999
curl -s -o /dev/null -X POST -H "Content-Type: application/json" \
-d '{"title":" "}' localhost:8080/todos
curl -s -o /dev/null -X POST -H "Content-Type: application/json" \
-d '{"done":true}' localhost:8080/todos
curl -s -o /dev/null -X POST -H "Content-Type: application/json" \
-d 'not json' localhost:8080/todos
curl -s -o /dev/null localhost:8080/nope
curl -s -o /dev/null localhost:8080/todos/999
前 2 個用 -i 把回應整份印出來，後面 5 個只看 log 就好
第 1 個是成功的那個
HTTP/1.1 200 OK
X-Request-Id: 0gt3iqk3bdd=
X-Response-Time: 8ms
Content-Length: 76
Content-Type: application/json
{"id":1,"title":"買牛奶","done":true,"created_at":"2026-08-27T08:00:00Z"}
沒帶 id 進去，X-Request-Id 是產生的那 12 個字元
第 2 個自己帶了 id
HTTP/1.1 404 Not Found
X-Request-Id: my-trace-001
X-Response-Time: 12ms
Content-Length: 66
Content-Type: application/json
{"status":404,"message":"找不到 id 999 的待辦","details":[]}
帶進去的 id 原樣回來了
最後的結果，伺服器那邊會多了 7 行
16:41:03.533 INFO [0gt3iqk3bdd=] i.k.s.Application -- 200 GET /todos/1 31ms
16:41:03.556 INFO [my-trace-001] i.k.s.Application -- 404 GET /todos/999 13ms
16:41:03.575 INFO [ncsgdam33kfe] i.k.s.Application -- 400 POST /todos 8ms
16:41:03.591 INFO [wnmvsn=3-0vp] i.k.s.Application -- 400 POST /todos 3ms
16:41:03.602 INFO [40obqjsg4yk6] i.k.s.Application -- 400 POST /todos 2ms
16:41:03.612 INFO [l/638vn0odak] i.k.s.Application -- 404 GET /nope 2ms
16:41:03.622 INFO [bwddw4jse2yi] i.k.s.Application -- 404 GET /todos/999 1ms
2 個計時的差別在第 2 行看得到，同一個請求 header 是 12ms、log 那行是 13ms，CallLogging 的區間包住 RequestTiming 這件事在數字上對得上，第 1 行差得更多，200 GET /todos/1 31ms 對應的 header 只有 8ms，因為那是 JVM 剛起來的第 1 個請求，Setup 到 Plugins 之間要載入的 class 都算在 CallLogging 頭上，第 2 個請求以後兩邊就貼得很近了
再開一次伺服器看 id 的 3 種情況，不帶 id 打 /todos/1，回應的 header 是 X-Request-Id: bfnqgtzpv6br，12 個字元都在字典裡，送 X-Request-Id: ABC123 的話，回來的是 944hbe7qen3s 這種東西，大寫那個被字典擋下來了，送 65 個 a 過去，回來的是 idov9quq/1b8，長度那條規則生效，這 3 個回的都是 200，不合格的 id 是被安靜換掉，不是被拒絕
withMDC 那段原始碼講的是機制，實測最直接
logback.xml 的 pattern 暫時加上 %thread，擺在 call id 前面，一眼就看得出哪一行跑在哪個執行緒
<pattern>%d{HH:mm:ss.SSS} %-5level [%thread] [%X{callId:-no-call-id}] %logger{20} -- %msg%n</pattern>
接著在 Application.kt 的 routing { } 裡暫時開一條路由，處理過程中把工作丟到 Dispatchers.IO，前中後各記一行
get("/io") {
call.application.log.info("查資料庫之前")
withContext(Dispatchers.IO) {
call.application.log.info("查資料庫")
}
call.application.log.info("查資料庫之後")
call.respondText("io done")
}
打一次，只看 log 就好
curl -s -o /dev/null localhost:8080/io
15:52:21.819 INFO [eventLoopGroupProxy-4-1] [e9=4ca7c2/dk] i.k.s.Application -- 查資料庫之前
15:52:21.820 INFO [DefaultDispatcher-worker-1] [e9=4ca7c2/dk] i.k.s.Application -- 查資料庫
15:52:21.820 INFO [eventLoopGroupProxy-4-1] [e9=4ca7c2/dk] i.k.s.Application -- 查資料庫之後
15:52:21.826 INFO [eventLoopGroupProxy-4-1] [e9=4ca7c2/dk] i.k.s.Application -- 200 GET /io 13ms
一個請求 4 行 log，2 個執行緒，同一個 call id，想靠執行緒名稱把這 4 行串起來會漏掉中間那行，靠 call id 就不會，這也是最後 pattern 裡沒有留 %thread 的原因，它在 coroutine 的世界裡回答不了「這幾行是同一個請求嗎」
界線在哪裡 ? MDCContext 是 coroutine context 的一個元素，子 coroutine 會繼承父 coroutine 的 context，所以 withContext、launch、async 都帶得過去，自己 new 一個 scope 就不繼承了
get("/detached") {
CoroutineScope(Dispatchers.IO).launch {
call.application.log.info("另開 scope 記的一行")
}
delay(20.milliseconds)
call.respondText("detached done")
}
curl -s -o /dev/null localhost:8080/detached
16:58:33.013 INFO [DefaultDispatcher-worker-1] [no-call-id] i.k.s.Application -- 另開 scope 記的一行
16:58:33.045 INFO [eventLoopGroupProxy-4-1] [k62croq7lgrz] i.k.s.Application -- 200 GET /detached 38ms
裡面記的那行沒有 call id，原因不是「另開 scope」這個動作本身，而是這個 scope 只拿了 Dispatchers.IO，沒有父 coroutine 的 context，同一個請求的 2 行 log，一行串得起來一行串不起來
要修的話，把 MDCContext() 一起放進那個 scope 的 context 就好
CoroutineScope(Dispatchers.IO + MDCContext()).launch {
call.application.log.info("帶著 MDCContext 記的一行")
}
16:58:34.071 INFO [DefaultDispatcher-worker-1] [dtvutzsb6w7t] i.k.s.Application -- 帶著 MDCContext 記的一行
16:58:34.096 INFO [eventLoopGroupProxy-4-2] [dtvutzsb6w7t] i.k.s.Application -- 200 GET /detached-mdc 27ms
call id 就會回來了，MDCContext() 不帶參數的時候，建構的當下就把 MDC.getCopyOfContextMap() 抄一份存起來，而建構這個動作發生在 handler 的執行緒上，那裡的 MDC 是有值的，所以抄到的就是這個請求的 call id，之後這個 coroutine 被排到哪個執行緒都帶著走
這裡有個坑，MDCContext 來自 kotlinx-coroutines-slf4j，CallLogging 內部用的就是它，但它在 ktor-server-call-logging 底下只是 runtime 的相依，沒有傳遞到 compile classpath，自己要用得在 build.gradle.kts 明確加一行
implementation("org.jetbrains.kotlinx:kotlinx-coroutines-slf4j:1.11.0")
CoroutineScope(...) 這個寫法本身還有另一個問題，它的 Job 沒有父節點，沒有人在等它、也沒有人會取消它，例外還會直接吃掉，真的要在請求結束後繼續跑的工作，Application 本身就是一個 CoroutineScope，交給它比較合理，一樣把 MDCContext() 放進 context 就帶得過去
一句話總結，跟請求生命週期綁在一起的工作，用 handler 底下的 structured concurrency 就會繼承，要在請求結束後繼續跑的，交給 application-owned scope 並自己把 MDCContext() 放進去，不要為了保住 MDC 硬留在 request scope
這幾條路由跟 pattern 裡的 %thread 都是為了看這件事才加的，看完就拿掉
day 15 在 exception<Throwable> 裡自己補了一行 log.error，理由是 StatusPages 接走例外之後 handleFailure 不會執行，現在 CallLogging 每個請求都記一行了，那行還有存在的意義嗎 ?
打 /boom
curl -s -o /dev/null localhost:8080/boom
2 行 log 都在
16:13:52.602 ERROR [ovyqb69r4swq] i.k.s.Application -- Unhandled exception on /boom
java.lang.RuntimeException: 資料庫密碼是 hunter2
at com.cashwu.todo.ApplicationKt$module$6$2.invokeSuspend(Application.kt:60)
...
16:13:52.606 INFO [ovyqb69r4swq] i.k.s.Application -- 500 GET /boom 16ms
答案是需要，CallLogging 那行只知道結果是 500，它從頭到尾沒碰過那個例外，也沒有 stack trace，要查是哪一行程式炸的，只能靠上面那行 ERROR，2 行的分工正好就是 day 15 說的那個拆法，一行講「回應了什麼」，一行講「發生了什麼例外」，靠同一個 call id 綁在一起
那個訊息是 day 15 故意寫成這樣的，它留在 log 裡，沒有跟著回應出去
順便一提，MDC 在 StatusPages 的 handler 裡還在，上面那行 ERROR 的 [ovyqb69r4swq] 是實測結果，在 log.error 前面加一行 delay(50) 讓它真的跨一次排程再打一次，2 行的 call id 還是一樣
15:53:15.113 ERROR [k32-d4vj707s] i.k.s.Application -- Unhandled exception on /boom
15:53:15.130 INFO [k32-d4vj707s] i.k.s.Application -- 500 GET /boom 89ms
不過框架自己不假設這件事，前面看過的 logError 每次都用 mdcProvider.withMDCBlock 重新包一次，要在自己寫的地方拿到有保證的 MDC，用同一支 API 就好
query string 那一項前面已經動過手了，剩下幾項是取捨，一起講清楚
request body 不記，CallLogging 沒有提供記 body 的設定，要記得自己在 format 裡讀，而那會是個坑，body 是一次性的串流，day 12 說過 converter 拿到的就是一條 ByteReadChannel，就算技術上做得到也不該做，POST 進來的 body 裡什麼都有，密碼、信用卡號、個資
header 不整包記，Authorization、Cookie 這 2 個一定不能進 log，真的需要記 header，用白名單挑幾個出來，不要用黑名單排除，黑名單永遠會漏
level 跟格式，這裡設 level = Level.INFO，每個請求一行，流量大的服務這會很吵，CallLoggingConfig 有 filter { } 可以只留特定路徑，也可以把 level 降到 DEBUG 讓正式環境的 root level 自然擋掉，另一個方向是輸出 JSON，logstash-logback-encoder 這類 encoder 換上去，MDC 的內容會變成 JSON 的欄位，ELK、Datadog 那些系統就能直接用 call id 當條件查，這件事只動 logback.xml，Kotlin 程式碼一行都不用改，也是把 call id 放進 MDC 而不是串進訊息字串的好處
Relix day 15 手刻過同一件事，loggingMiddleware 是一個工廠函式，用 TimeSource.Monotonic.markNow() 前後包夾算耗時，輸出 [Relix] GET /hello -> 200 (3ms)，裝在 pipeline 最外層才記得到所有 request，Ktor 的 CallLogging 骨架跟它一樣，差別在 Relix 用洋蔥模型的前後包夾，Ktor 拆成 Setup 記時間、send pipeline 記 log 2 個不相連的 hook
實際路徑還是路由樣板這件事，兩邊的答案一樣，Relix 那篇記的是 request.path 也就是 /users/42，理由是 logging 裝在最外層，next() 還沒呼叫，router 根本還沒比對，Ktor 的 path() 記的也是實際路徑，但理由不同，ResponseSent 在 send pipeline 上，那時候 routing 早就跑完了，樣板拿得到卻沒有拿，這是刻意的分工，那篇也寫過，Ktor 把樣板留給 MicrometerMetrics，metrics 要的是有限的集合，log 要的是「到底是哪一筆」
差最多的是 trace id，Relix day 15 有一句話講得很明白，「至於 SLF4J、JSON 結構化輸出，trace ID 這些正式環境該有的東西，整個系列都不會做」，這句話不是偷懶，是手刻的規模到此為止。要做 trace id 得補 3 塊，產生器加驗證、跨 coroutine 的傳遞、log 輸出端的欄位，而中間那塊在 Relix 的架構下沒得抄，RelixLogger 是同步介面、middleware 是普通函式，沒有 coroutine context 這種東西可以掛，Ktor 這邊 3 塊各由現成的零件負責，CallId、MDCContext、logback 的 %X{}，我們寫的只有把它們接起來的 10 幾行設定
CallLogging 的主要動作分成 2 段，CallSetup 在 Setup phase 記開始時間，ResponseSent 在 send pipeline 的 Engine phase 先送回應再記一行 log，Monitoring phase 只有在設了 MDC 的時候才會被插入一個 MonitoringMDC 的新 phase，day 09 那句預告在這裡修正，它量的區間包住 day 10 的 RequestTiming，但兩邊時鐘分別是 currentTimeMillis 跟 nanoTime，測試不拿數字比較大小
CallId 也掛在 Setup phase，同 phase 內的順序由註冊先後決定，這篇把它裝在 CallLogging 前面，所以 call id 的取得不算在 log 的耗時裡，retrievers + generators 依序取值、verifier 用一張沒有大寫的白名單把關，不合格的 id 會被安靜換掉
callIdMdc 把 id 放進 MDC，logback.xml 的 pattern 加 %X{callId} 就印得出來，structured child coroutine 會繼承，從零建立的 scope 則要明確傳遞，day 15 那行 log.error 還是需要，CallLogging 只知道結果是 500、不帶 stack trace，2 行靠同一個 call id 綁在一起，順便把它用的 uri 改成 path()
現在有 3 個東西寫死在程式碼裡，port 8080、log level、call id 的長度，day 15 講 exception<Throwable> 的時候還欠一個「開發模式才回傳例外訊息」，當時說 todo-api 還沒有環境的概念所以先不做
下一篇處理設定管理，application.yaml 的寫法、環境變數怎麼蓋掉、developmentMode 到底改變了什麼，把這些散在各處的常數集中到一個地方
同步刊登於 Blog
圖片來源：AI 產生
iThome鐵人賽
看影片追技術