上一篇把 pipeline 拆開了，5 個 phase、intercept、proceed() 的前後包夾，也用測試驗證過，結尾也說了，intercept 是底層 API，Ktor 給我們寫 plugin 用的是更高階的 createApplicationPlugin，這篇就來寫一個自己的 plugin 掛進 todo-api，量每個請求處理了多久，把耗時放進 response header，用 curl 就看得到
createApplicationPlugin 寫一個 RequestTiming plugin，量請求的處理時間，附在 response header 上onCall、onCallRespond 這些鉤子跟上一篇的 phase 怎麼對應install 時可以改 header 名稱createApplicationPlugin 多接手了什麼上一篇看過 IgnoreTrailingSlash 的完整原始碼，再貼一次，因為這 5 行就是自訂 plugin 的範本
public val IgnoreTrailingSlash: ApplicationPlugin<Unit> = createApplicationPlugin("IgnoreTrailingSlash") {
onCall { call ->
call.ignoreTrailingSlash = true
}
}
拆開看重點只有 2 個部份，第 1 個是名字，上一篇拆 install 時看到它拿 plugin 的 key 找看看有沒有重複，這個字串就是 key 的來源，基底 plugin 裝 2 次會拿回原本那份，但像 IgnoreTrailingSlash 這種 createApplicationPlugin 產生的 plugin，重複安裝會直接丟 DuplicatePluginException，不會直接沿用舊設定，第 2 個是後面的 lambda，裡面用 onCall 這類 hook 描述「什麼時機做什麼事」
hook 跟 phase 的關係，上一篇其實已經在原始碼裡確認過了，onCall 的實作就是 intercept(ApplicationCallPipeline.Plugins)，plugin 的世界裡沒有 phase 也沒有 intercept，只有時機點，常用的有 3 個
onCall，請求進來時執行，掛在 Plugins phase，就是上一篇測過「一定比 routing 早」的那個位置onCallReceive，handler 讀取 request body 時執行onCallRespond，handler 呼叫 call.respond 系列函式回應時執行後 2 個掛的地方比較特別，不在主 pipeline 上，Ktor 除了主幹的 ApplicationCallPipeline，收 body 和送 response 各自還有一條小 pipeline，onCallReceive 和 onCallRespond 分別掛進那 2 條，這正是「不用面對 phase」的意思，我們只要宣告時機，框架負責翻譯成「哪條 pipeline 的哪個 phase」
todo-api 現在回應都快，但後面會接 JSON 序列化、驗證、資料庫，想要請求變慢時，要有辦法看出慢多少，最直接的做法是把處理耗時放進 response header，發請求的人用 curl -i 就看得到，不需要翻 server log
先把界線畫清楚，day 16 會裝的 CallLogging 是現成的 plugin，把請求資訊寫進 server log 給開發者看，這篇的 RequestTiming 是把耗時寫進 header 給 client 看，用途不同，而且重點本來就不一樣，那篇是裝現成的，這篇是自己寫一個，把上一篇看懂的機制變成手感
不過有件事要先講，把耗時寫進 response header，正式環境通常不會這樣一路開給所有人，這個數字對真正的使用者沒有意義，卻等於免費告訴外面的人哪個 endpoint 比較慢，哪個路徑背後有查資料庫，想找弱點的人拿它當線索很方便，實務上常見的是 2 種處理，一種是只在開發環境裝這個 plugin，用設定檔或環境變數決定要不要 install，正式環境根本不掛上去，另一種是量測照做，但數字寫進 server log 或 metrics 系統，header 就不給了，真的要留也會限制成內部網路或帶了特定 header 才出現，這篇一律附在 header 上，是因為 curl -i 打完就看得到，理解 hook 機制最快，要上線再依環境切換
量時間需要跨 hook 傳資料，onCall 記下開始時間，onCallRespond 算差值，那資料放哪裡 ? 放 call.attributes，這就是 IgnoreTrailingSlash 蓋章用的同一個地方，原始碼裡 ignoreTrailingSlash 那個 property 的背後就是對 attributes 做 put 和 contains，attributes 是每個 call 自己帶的型別安全的鍵值，用 AttributeKey<T> 當鑰匙，請求結束就跟著 call 一起消失，正好適合這種「同一個請求內、跨階段傳話」的需求
開一個新檔案 src/main/kotlin/com/cashwu/todo/RequestTiming.kt
package com.cashwu.todo
import io.ktor.server.application.createApplicationPlugin
import io.ktor.util.AttributeKey
private val startTimeKey = AttributeKey<Long>("RequestTimingStart")
val RequestTiming = createApplicationPlugin("RequestTiming") {
onCall { call ->
call.attributes.put(startTimeKey, System.nanoTime())
}
onCallRespond { call ->
val start = call.attributes.getOrNull(startTimeKey) ?: return@onCallRespond
val elapsedMs = (System.nanoTime() - start) / 1_000_000
call.response.headers.append("X-Response-Time", "${elapsedMs}ms")
}
}
跟 IgnoreTrailingSlash 同一個形狀，只是用了 2 個 hook
onCall 在請求進來時把 System.nanoTime() 放進 attributes，onCallRespond 在回應要出去時取出來算差值，換算成毫秒塞進 header，getOrNull 那行是保守寫法，Plugins phase 一定比 respond 早，正常情況拿得到，但拿不到時直接跳過，比丟例外把整個回應炸掉好
然後在 Application.kt 的 module 裡裝上它，跟裝官方 plugin 一模一樣
fun Application.module() {
install(RequestTiming)
routing {
get("/") {
call.respondText("Hello, Ktor!")
}
todoRoutes()
}
}
寫的時候是 createApplicationPlugin，用的時候是 install，自己寫的 plugin 跟官方的在使用端長得一樣，這就是走同一套機制的好處
./gradlew run 起 server
curl -i http://localhost:8080/todos
HTTP/1.1 200 OK
X-Response-Time: 7ms
Content-Length: 40
Content-Type: text/plain; charset=UTF-8
買牛奶
繳電費
寫 day 05 的文章
header 出現了，7ms 是 JVM 剛起來、JIT 還沒熱身的數字，同一個路徑再打一次就變成 X-Response-Time: 0ms，純記憶體 list 的查詢連 1ms 都不到，這 2 個數字都是實測結果
再打一個不存在的路徑
curl -i http://localhost:8080/nothing-here
HTTP/1.1 404 Not Found
X-Response-Time: 1ms
Content-Length: 0
404 也有 header，這呼應了上一篇的發現，Fallback 的 404 也是走 call.respond 出去的，而 onCall 和 onCallRespond 掛在 application 層級，routing 有沒有接走這個請求都會執行，所以每一個回應都會被量到，不管是誰回的
header 名稱現在寫死在 plugin 裡，想讓使用者換名稱，就要用 createApplicationPlugin 的另一個多載，它收 3 個東西，名字、一個建 config 的函式、原本的 body
修改 RequestTiming.kt，加一個 config class，讓 plugin 從 pluginConfig 讀設定
class RequestTimingConfig {
var headerName: String = "X-Response-Time"
}
val RequestTiming = createApplicationPlugin("RequestTiming", ::RequestTimingConfig) {
val headerName = pluginConfig.headerName
onCall { call ->
call.attributes.put(startTimeKey, System.nanoTime())
}
onCallRespond { call ->
val start = call.attributes.getOrNull(startTimeKey) ?: return@onCallRespond
val elapsedMs = (System.nanoTime() - start) / 1_000_000
call.response.headers.append(headerName, "${elapsedMs}ms")
}
}
使用端就有了跟官方 plugin 一樣的設定入口
install(RequestTiming) {
headerName = "X-Elapsed"
}
install 的當下，Ktor 先呼叫 ::RequestTimingConfig 建出帶預設值的 config，再把使用者 install 帶的 lambda 套上去，最後才執行 plugin 的 body，3.5.2 原始碼裡就一行，val config = pipeline.createConfiguration().apply(configure)
所以 body 開頭讀 pluginConfig.headerName 時，讀到的已經是套用完使用者設定的最終值，設定在 install 當下定案，之後每個請求都用同一份
這篇的測試位置跟 day 05、day 06 不太一樣，那 2 篇加的是新端點，回應長什麼樣事先就知道，測試寫在前面當規格剛剛好，自訂 plugin 反過來，要先把預設行為做出來，看清楚它攔到哪幾個時間點、給了哪些東西，才知道哪些行為該固定，所以測試放在實作後面
開一個新檔案 src/test/kotlin/com/cashwu/todo/RequestTimingTest.kt
package com.cashwu.todo
import io.ktor.client.request.get
import io.ktor.http.HttpStatusCode
import io.ktor.server.application.install
import io.ktor.server.response.respondText
import io.ktor.server.routing.get
import io.ktor.server.routing.routing
import io.ktor.server.testing.testApplication
import kotlin.test.Test
import kotlin.test.assertEquals
import kotlin.test.assertNotNull
import kotlin.test.assertNull
import kotlin.test.assertTrue
class RequestTimingTest {
@Test
fun `response carries timing header in ms format`() = testApplication {
application {
module()
}
val response = client.get("/todos")
val header = response.headers["X-Response-Time"]
assertNotNull(header)
assertTrue(header.matches(Regex("""\d+ms""")), "header 格式應該是數字加 ms，實際是 $header")
}
@Test
fun `header name can be customized via install config`() = testApplication {
application {
install(RequestTiming) {
headerName = "X-Elapsed"
}
routing {
get("/") {
call.respondText("ok")
}
}
}
val response = client.get("/")
assertNotNull(response.headers["X-Elapsed"])
assertNull(response.headers["X-Response-Time"])
}
@Test
fun `unmatched route still gets timing header`() = testApplication {
application {
module()
}
val response = client.get("/nothing-here")
assertEquals(HttpStatusCode.NotFound, response.status)
assertNotNull(response.headers["X-Response-Time"])
}
}
第 1 個驗 header 存在而且格式是數字加 ms，耗時本身每次都不同，測格式不測數值，第 3 個驗 404 也帶 header，把「application 層級的 plugin 量得到每一個回應」這個理解變成斷言，第 2 個測 config，注意它自己建了一個最小的 application，沒有走 module()，因為 module 已經裝過 RequestTiming，createApplicationPlugin 建出來的 plugin 在同一個 application 重複安裝會直接丟 DuplicatePluginException，想測不同設定就得起一個乾淨的 application
跑 ./gradlew test，實測的結果，既有測試加 3 個新測試，18 個全部通過
RequestTimingTest > response carries timing header in ms format() PASSED
RequestTimingTest > header name can be customized via install config() PASSED
RequestTimingTest > unmatched route still gets timing header() PASSED
RequestTiming 對這個專案有實際用處，檔案和測試都留下來，之後接上資料庫還會回來看它的數字
onCallReceive 這次沒上場，原因很單純，todo-api 目前全是 GET，沒有 request body 可讀，硬湊一個用不到的範例沒有意義，等後面幾篇加上 JSON body 之後再讓它上場
另外 hook 也不是只有這 3 個具名方法，PluginBuilder 還有一個通用的 on(hook, handler)，收具名的 hook 物件，例如 CallSetup 掛在 Setup phase，比 onCall 更早，CallFailed 在請求丟出例外時觸發，ResponseSent 則在回應真的送到 client 之後，原始碼註解說它適合 finishing measurements，這順便暴露了 RequestTiming 的量測邊界，我們量的是「請求進來」到「respond 被呼叫」，不含最後寫進網路的時間，真想量到位元組送完得用 ResponseSent，但那個時間點 header 早就送出去了，量到的數字只能記 log，塞不回這次的回應，這是把耗時做成 header 天生的取捨
還有一個對照上一篇的細節，PluginBuilder 裡真的有一個 internal 的 onCallValidators，對應上一篇提過的 internal Validators phase，註解直接點名 authentication、rate limiting、CORS，它是 internal，我們自己寫 plugin 時用不到，先知道有這個位置就好，下一篇裝的現成 plugin 正好就掛在這裡
Relix day 18 手刻的 install() 做 4 件事，擋重複安裝、建預設 config、套用使用者的 lambda、呼叫 plugin 自己的 install() 註冊 middleware
前 3 件 Ktor 全部對得上，擋重複安裝和登記上一篇拆 install 時看過了，建 config 加套 lambda 這篇也看到了，就是 createConfiguration().apply(configure) 那一行，連 Relix 的 RelixPlugin interface 都是同一個形狀，一個 createDefaultConfig()、一個 install()，兩邊面對同一組問題，給出的答案幾乎一樣，這部分算是殊途同歸
差別在第 4 件事，Relix 的 plugin 拿到 application 之後，自己把 middleware 塞進 queue，塞進去的位置就是「排隊的下一格」，所以那篇有一個測試叫 install order is middleware order，結論寫得很直白，「plugin 系統沒有幫你排順序，也沒辦法幫你排」
Ktor 這邊寫 plugin 根本不用碰註冊位置，宣告的是時機，onCall、onCallRespond，hook 把時機翻譯成「哪條 pipeline 的哪個 phase」，排序問題就這樣被 hook 一起接手了
回頭看這篇寫的 RequestTiming，全程沒有出現 Plugins、Transform 這些 phase 的名字，但它們都在，上一篇拆開看的機制一個都沒消失，只是被 hook 包成日常不用面對的形狀，好的抽象常常就是這樣，想看的時候原始碼裡看得懂，寫的時候可以不用想
createApplicationPlugin 收一個名字當擋重複安裝的 key、一個可選的 config 建構函式、一個描述行為的 body，body 裡用 onCall、onCallReceive、onCallRespond 宣告時機，跨 hook 的資料放 call.attributes
config 在 install 當下建預設值、套用使用者 lambda、定案，RequestTiming 用 2 個 hook 把每個回應的耗時寫進 header，3 個測試分別固定了格式、config 客製、404 也量得到，自己寫的 plugin 跟官方的走同一套機制，使用端看不出差別
RequestTiming 是我們自己寫的第 1 個 plugin，下一篇換個方向，裝 2 個現成的守門 plugin，CORS 和 RateLimit，它們處理的是「這個請求該不該放行」，掛的位置就是上一篇和這篇都點過名的 Validators phase 那一帶，看 Ktor 怎麼處理跨網域請求和流量限制
同步刊登於 Blog
圖片來源：AI 產生
iThome鐵人賽
看影片追技術