[Day 19] 實作 Ktor Request Logging

2021 iThome 鐵人賽

DAY 19

Modern Web

基於 Kotlin Ktor 建構支援模組化開發的 Web 框架系列第 19 篇

13th鐵人賽 ktor kotlin logging

林俊宏

團隊Kotlin 愛台灣 2021

2021-09-24 21:54:41

1557 瀏覽

分享至

Request Logging 是非常重要的必備功能，不僅可以用來系統監控、除錯，還可以進一步分析使用者行為…等，存在著廣泛的應用情境，所以每個 Web 框架都會有解決方案，在此我先簡介 Spring 與 Ktor 的作法，再來說明為何我不用 Ktor 的 CallLogging Plugin 就好，需要實作自己的 Plugin。

Request Logging 的作法

Spring CommonsRequestLoggingFilter

以 Spring 框架來說，我們可以自行實作 filter、interceptor、aspect，以不同的方式攔截請求來記錄 log，甚至直接使用預設實作 CommonsRequestLoggingFilter 即可。然而上述這些方式，或多或多都存在許多限制及不便，例如 CommonsRequestLoggingFilter只能拿到 HttpServletRequest 物件，所以無法記錄 Response 資料。如果改用 Interceptor 實作，則會受到只能讀取一次 request input stream 的限制，所以必須要使用 ContentCachingRequestWrapper and ContentCachingResponseWrapper 暫存資料，也就是需要自行處理許多實作細節，讀者可以參考 Baeldung 的這篇文章 Spring – Log Incoming Requests。

@Configuration
public class RequestLoggingFilterConfig {

    @Bean
    public CommonsRequestLoggingFilter logFilter() {
        CommonsRequestLoggingFilter filter = new CommonsRequestLoggingFilter();
        filter.setIncludeQueryString(true);
        filter.setIncludePayload(true);
        filter.setMaxPayloadLength(10000);
        filter.setIncludeHeaders(false);
        filter.setAfterMessagePrefix("REQUEST DATA : ");
        return filter;
    }
}

Ktor CallLogging Plugin

Ktor CallLogging Plugin 與 Spring CommonsRequestLoggingFilter 一樣，都只能記錄 Request 資料，而且也會有不能重複讀取 request input stream 的問題，所以需要再安裝 Ktor DoubleReceive Plugin 解決。CallLogging Plugin 需要自行實作 filter 與 format 2個 configure function，雖然不像 CommonsRequestLoggingFilter 可以直接呼叫 setIncludeQueryString …之類的方法進行設定，但是可以依自己的需求實作，所以使用上較為彈性。

install(CallLogging) {
    filter { call ->
        call.request.path().startsWith("/api/v1")
    }
    format { call ->
        val status = call.response.status()
        val httpMethod = call.request.httpMethod.value
        val userAgent = call.request.headers["User-Agent"]
        "Status: $status, HTTP method: $httpMethod, User agent: $userAgent"
    }
}

install(DoubleReceive) {
    receiveEntireContent = true
}

實作目標

由於 Ktor CallLogging Plugin 只能記錄 Request 資料，而且內部實作是使用 SLF4J Logger，並沒有提供 write configure function 讓我客製化實作如何寫入 log，所以我想自己寫 MyCallLogging Plugin 達成以下目標

除了記錄 Request 資料之外，還要能記錄 Response 資料，包括 Response Body 及 HTTP Status Code
要能同時記錄 Request 與 Response 為一筆 log，不可拆開為2筆記錄
實作自訂 filter 完全控制寫 log 的行為，而且可以透過 Ktor 設定檔進行設定。
不使用字串型態寫入 Log，而是定義自己的 RequestLog 資料類別，再根據寫入的目的地，轉換為特定的資料格式，例如 JSON
寫入 RequestLog 的目的地不限於檔案，可以自行實作 LogWriter 以非同步方式寫到任意目的地，例如資料庫，或是轉為 JSON 傳送到 AWS Kinesis Data Firehose。

改寫 Ktor CallLogging Plugin 實作 MyCallLogging Plugin

雖然 Ktor CallLogging Plugin 不合我所用，但可以拿它的原始碼，當作樣版來修改會比較簡單。我實作的 MyCallLoggingPlugin 多了 RequestLogConfig 及 LogWriter 物件。RequestLogConfig 是讀取 Ktor application.conf 設定檔的 logging config，包含了許多 filter 設定，LogWriter 則是根據設定檔 writer 設定從 Koin DI 拿到的物件

class MyCallLoggingFeature private constructor(
    private val monitor: ApplicationEvents,
    private val mdcEntries: List<MDCEntry>,
    private val config: RequestLogConfig,
    private val logWriter: LogWriter
)

logging {
    request {
        enabled = true
        destination = "AwsKinesis" # File(default), Database, AwsKinesis
        includeHeaders = false
        includeQueryString = false
        includeResponseBody = false
        includeGetMethod = false
        excludePaths = ["/ops/sysstat/healthCheck"]
        excludeRequestBodyPaths = ["/login", "/myPassword"]
    }
    writer {
        awsKinesis {
            streamName = "logging"
            nettyClient {
                #maxConcurrency = 50 # => aws default value = 50
                #maxPendingConnectionAcquires = 10000 => aws default value = 10000
                #maxIdleConnectionTimeout = 60s => aws default value = 60s
            }
            threadPool {
                fixedPoolSize = 3
            }
        }
    }
}

攔截 Ktor ApplicationSendPipeline.Render PipelinePhase 取得 Response 資料

Ktor CallLogging 原本只在 ApplicationCallPipeline.Monitoring 插入 loggingPhase，當 proceed() 執行完請求後，呼叫 logSuccess() 寫入 log。為了拿到 Response 資料，我在 ApplicationSendPipeline.Render 之後插入 PipelinePhase，如果 message 是 OutgoingContent 的子類別 TextContent 物件，則把它儲存在 ApplicationCall 的 attribute 裡面。未來 logSuccess() 呼叫 logWriter 寫入 log 時，就可以透過 call.attributes.getOrNull(ATTRIBUTE_KEY_RSP_BODY) 拿到 response body，把 request 與 response 資料寫到同一筆 log。

pipeline.insertPhaseBefore(ApplicationCallPipeline.Monitoring, loggingPhase)
pipeline.intercept(loggingPhase) {
    proceed()
    feature.logSuccess(call)
}

if (requestConfig.includeResponseBody) {
    pipeline.sendPipeline.insertPhaseAfter(ApplicationSendPipeline.Render, afterRenderResponsePhase)
    pipeline.sendPipeline.intercept(afterRenderResponsePhase) { message ->
        if (message is TextContent) {
            call.attributes.put(ATTRIBUTE_KEY_RSP_BODY, message.text)
        }
    }
}

使用自己的 LogWriter 替換 Ktor CallLogging Plugin 預設的 SLF4j Logger

原本 Ktor CallLogging Plugin 的 logSuccess 方法的內部實作是使用 SLF4j Logger

private val log: Logger // SLF4j Logger

private fun logSuccess(call: ApplicationCall) {
    if (filters.isEmpty() || filters.any { it(call) }) {
        log(formatCall(call))
    }
}
private fun log(message: String) = when (level) {
    Level.ERROR -> log.error(message)
    Level.WARN -> log.warn(message)
    Level.INFO -> log.info(message)
    Level.DEBUG -> log.debug(message)
    Level.TRACE -> log.trace(message)
}

改寫為使用 LogWriter 寫入由 buildLogMessage(call) 方法建立的 RequestLog 物件

private fun logSuccess(call: ApplicationCall) {
    if (config.enabled) {
        if (filter(call)) {
            logWriter.write(buildLogMessage(call))
        }
    }
}

定義 RequestLog 資料類別結構化 Log 資料

RequestLog 類別除了一般 Request Logging 記錄的 http request 資料之外，我還多記錄了許多自定義欄位。此外，還要標註 @Serializable，kotlinx.serialization library 才能序列化為 JSON。

reqId => 使用 Ktor CallId Plugin 產生的亂數作為請求 id，方便 trace & debug
project => 在多專案架構下，記錄這個 request 是屬於那個子專案
tag => 處理請求的時候，視需要可以填入字串，未來作為搜尋 log 的條件
source, principal => 客戶端驗證資訊
clientId, clientVersion, ip => 客戶端裝置資訊

@Serializable
data class RequestLog(
    val reqId: String,
    @Serializable(with = InstantSerializer::class) val reqAt: Instant,
    val api: String,
    val headers: String? = null,
    val querystring: String? = null,
    val reqBody: String?,
    val project: String,
    val function: String,
    val tag: String? = null,
    val source: PrincipalSource,
    val tenantId: TenantId? = null,
    val principal: String,
    val runAs: Boolean,
    val clientId: String? = null,
    val clientVersion: String? = null,
    val ip: String? = null,
    @Serializable(with = InstantSerializer::class) val rspAt: Instant,
    val rspTime: Long,
    val rspStatus: Int,
    val rspBody: String?
) : LogMessage()

實作各種 LogWriter 寫入 RequestLog 到不同目的地

目前 RequestLog 可以使用以下3個 LogWriter 寫到不同目的地

RequestLogDBWriter => 使用 Exposed ORM 寫到資料庫
FileLogWriter => 使用 KotlinLogging 函式庫寫到檔案
AwsKinesisLogWriter => 轉為 JSON 傳送到 AWS Kinesis Stream

interface LogWriter {

    fun write(message: LogMessage)
}

class RequestLogDBWriter : LogWriter {

    override fun write(message: LogMessage) {
        val dto = message as RequestLog
        transaction {
            RequestLogTable.insert {
                it[reqId] = dto.reqId
                it[reqAt] = dto.reqAt
                it[api] = dto.api
                it[headers] = dto.headers
                it[querystring] = dto.querystring
                it[reqBody] = dto.reqBody
                it[project] = dto.project
                it[function] = dto.function
                it[tag] = dto.tag
                it[sourceId] = dto.source
                it[tenantId] = dto.tenantId?.value
                it[principal] = dto.principal
                it[runAs] = dto.runAs
                it[clientId] = dto.clientId
                it[clientVersion] = dto.clientVersion
                it[ip] = dto.ip
                it[rspAt] = dto.rspAt
                it[rspTime] = dto.rspTime
                it[rspStatus] = dto.rspStatus
                it[rspBody] = dto.rspBody
            }
        }
    }
}

結語

今天說明如何實作自己的 MyCallLogging Plugin 取代 Ktor CallLogging Plugin，滿足許多更複雜進階的需求，但是系統的 log 絕對不只有 Request Log 而已，還有系統錯誤的 Error Log, 使用者登入的 Login Log…等，所以明天的主題是如何建立系統的 Logging 機制，以非同步方式寫入各種類型的 log。