Ktorのログ出力をJsonに変える

Kotlin

はじめに

まえにQuarkusで同じようなことをやったのですが、Ktorだとどうなるんだろうとふと思ってやってみようと思います。
先にお伝えしておくと、タイトル詐欺ではないですが、ほぼLogbackの設定の話になりKtor特有のものはなさそうでした。
主題とは関係ないですが、KtorにはCallLoggingと呼ばれるようなリクエストのロギングを行ってれるモジュール？は用意されているみたいなのでそちらもおまけとして使ってみようと思います。

やってみる

実行環境

アプリの実行環境は以下のようになっています。

$ uname -srvmpio
Linux 5.4.0-72-generic #80-Ubuntu SMP Mon Apr 12 17:35:00 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux

$ lsb_release -a
LSB Version:    core-11.1.0ubuntu2-noarch:security-11.1.0ubuntu2-noarch
Distributor ID: Ubuntu
Description:    Ubuntu 20.04.2 LTS
Release:    20.04
Codename:   focal

$ java -version
openjdk version "1.8.0_292"
OpenJDK Runtime Environment (build 1.8.0_292-b10)
OpenJDK 64-Bit Server VM (build 25.292-b10, mixed mode)

$ mvn --version
Apache Maven 3.6.3
Maven home: /usr/share/maven
Java version: 1.8.0_292, vendor: Oracle Corporation, runtime: /home/yuya-hirooka/.sdkman/candidates/java/8.0.292-open/jre
Default locale: ja_JP, platform encoding: UTF-8
OS name: "linux", version: "5.4.0-73-generic", arch: "amd64", family: "unix"

プロジェクトを作成する

Ktor Project Generatorを使ってプロジェクトを作成します。
設定は以下のとおりにします。

f:id:yuya_hirooka:20210521115755p:plain

プロジェクトは個人の趣味でMavenで作成してます。
プロジェクトをダウンロードして解答し、適当なIDEなり何なりで開きます。

起動してみる

デフォルトでは以下のようなApplication.ktというクラスがされています。

fun main(args: Array<String>): Unit = io.ktor.server.netty.EngineMain.main(args)

@Suppress("unused") // Referenced in application.conf
@kotlin.jvm.JvmOverloads
fun Application.module(testing: Boolean = false) {
    routing {
        get("/") {
            call.respondText("HELLO WORLD!", contentType = ContentType.Text.Plain)
        }
    }
}

localhost:8080/でHELLO WORLD!の文字列を返すハンドラーが用意されているみたいです。
起動してみます。

$ mvn compile exec:java -Dexec.mainClass=dev.hirooka.ApplicationKt

現段階では起動時に以下のようなログが出力されます。

2021-05-21 20:22:32.657 [dev.hirooka.ApplicationKt.main()] TRACE Application - {
    # application.conf @ file:/home/yuya-hirooka/source/kotlin/ktor-sandbox/logging/target/classes/application.conf: 6
    "application" : {
        # application.conf @ file:/home/yuya-hirooka/source/kotlin/ktor-sandbox/logging/target/classes/application.conf: 7
        "modules" : [
            # application.conf @ file:/home/yuya-hirooka/source/kotlin/ktor-sandbox/logging/target/classes/application.conf: 7
            "dev.hirooka.ApplicationKt.module"
        ]
    },
    # application.conf @ file:/home/yuya-hirooka/source/kotlin/ktor-sandbox/logging/target/classes/application.conf: 2
    "deployment" : {
        # application.conf @ file:/home/yuya-hirooka/source/kotlin/ktor-sandbox/logging/target/classes/application.conf: 3
        "port" : 8080
    },
    # Content hidden
    "security" : "***"
}

2021-05-21 20:22:32.690 [dev.hirooka.ApplicationKt.main()] INFO  Application - Autoreload is disabled because the development mode is off.
2021-05-21 20:22:32.901 [dev.hirooka.ApplicationKt.main()] INFO  Application - Responding at http://0.0.0.0:8080

curlでエンドポイントにアクセスしてみます。

$ curl localhost:8080
HELLO WORLD!

アクセスログを出すようにしてみる

前述の通り、Ktorでは流入するリクエストの情報を出力してくれるCallLogging言うのものを用意してくれています。
使い方は簡単でただinstallするだけでOkです。 Application.ktを以下のように書き換えます。

@Suppress("unused") // Referenced in application.conf
@kotlin.jvm.JvmOverloads
fun Application.module(testing: Boolean = false) {
    routing {
        get("/") {
            call.respondText("HELLO WORLD!", contentType = ContentType.Text.Plain)
        }
    }
    // 追加した部分
    install(CallLogging)
}

アプリケーションを再起動して先ほどと同様のリクエストを送ると以下のようなログ出力が行われるようになります。

2021-05-21 20:46:37.840 [eventLoopGroupProxy-4-1] TRACE Application - 200 OK: GET - /

ログをJsonで出力するように変更

KtorはSLF4Jを利用したロギングが行えるようで、Project Generatorでアプリを作成した場合その実装はlogback-classicになるようです。
なので、Ktorのログ出力を変えたい場合をLogbackの出力をJsonに変える方法と同様な方法で行えます。
今回は、Logstashを使ってみたいと思います。
まずはpomの依存に以下を追加します。

<dependency>
    <groupId>net.logstash.logback</groupId>
    <artifactId>logstash-logback-encoder</artifactId>
    <version>6.6</version>
</dependency>

バージョンは最新を確認して入れるようにしてください。
次にLogbackの設定を変更してエンコーダーをLogstashのものを使うようにします。
resourceディレクトリ配下にあるlogback.xmlを以下のように修正します。

<configuration>
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<!--        <encoder>-->
<!--            <pattern>%d{YYYY-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>-->
<!--        </encoder>-->
        <encoder class="net.logstash.logback.encoder.LogstashEncoder" />
    </appender>
    <root level="trace">
        <appender-ref ref="STDOUT"/>
    </root>
    <logger name="org.eclipse.jetty" level="INFO"/>
    <logger name="io.netty" level="INFO"/>
</configuration>

もともとあったencoderタグの部分をコメントアウトして、net.logstash.logback.encoder.LogstashEncoderをエンコーダーとして使用するようにしてます。
これで設定は完了です。 プロジェクトを再起動してみると今度はLogがJson形式で出力されるようになったのがわかります。

{"@timestamp":"2021-05-21T20:40:48.994+09:00","@version":"1","message":"{\n    # application.conf @ file:/home/yuya-hirooka/source/kotlin/ktor-sandbox/logging/target/classes/application.conf: 6\n    \"application\" : {\n        # application.conf @ file:/home/yuya-hirooka/source/kotlin/ktor-sandbox/logging/target/classes/application.conf: 7\n        \"modules\" : [\n            # application.conf @ file:/home/yuya-hirooka/source/kotlin/ktor-sandbox/logging/target/classes/application.conf: 7\n            \"dev.hirooka.ApplicationKt.module\"\n        ]\n    },\n    # application.conf @ file:/home/yuya-hirooka/source/kotlin/ktor-sandbox/logging/target/classes/application.conf: 2\n    \"deployment\" : {\n        # application.conf @ file:/home/yuya-hirooka/source/kotlin/ktor-sandbox/logging/target/classes/application.conf: 3\n        \"port\" : 8080\n    },\n    # Content hidden\n    \"security\" : \"***\"\n}\n","logger_name":"Application","thread_name":"dev.hirooka.ApplicationKt.main()","level":"TRACE","level_value":5000}
{"@timestamp":"2021-05-21T20:40:49.038+09:00","@version":"1","message":"Autoreload is disabled because the development mode is off.","logger_name":"Application","thread_name":"dev.hirooka.ApplicationKt.main()","level":"INFO","level_value":20000}
{"@timestamp":"2021-05-21T20:40:49.339+09:00","@version":"1","message":"Responding at http://0.0.0.0:8080","logger_name":"Application","thread_name":"dev.hirooka.ApplicationKt.main()","level":"INFO","level_value":20000}

スタックトレースを出力する

上記の設定ではスタックトレースの出力がされず別途設定が必要のようです。
logback.xmlを以下のように書き換えます。

<configuration>
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <!--    <appender name="STDOUT" class="net.logstash.logback.appender.AccessEventAsyncDisruptorAppender">-->
        <!--        <encoder>-->
        <!--            <pattern>%d{YYYY-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>-->
        <!--        </encoder>-->
        <encoder class="net.logstash.logback.encoder.LogstashEncoder">
            <throwableConverter class="net.logstash.logback.stacktrace.ShortenedThrowableConverter">
                <maxDepthPerThrowable>30</maxDepthPerThrowable>
                <maxLength>2048</maxLength>
                <shortenedClassNameLength>20</shortenedClassNameLength>
                <exclude>sun\.reflect\..*\.invoke.*</exclude>
                <exclude>net\.sf\.cglib\.proxy\.MethodProxy\.invoke</exclude>
                <rootCauseFirst>true</rootCauseFirst>
                <inlineHash>true</inlineHash>
            </throwableConverter>
        </encoder>
    </appender>
    <root level="trace">
        <appender-ref ref="STDOUT"/>
    </root>
    <logger name="org.eclipse.jetty" level="INFO"/>
    <logger name="io.netty" level="INFO"/>
</configuration>

これでスタックトレースの情報もログ出力されるようになります。
Application.ktを以下のように書き換えます。

@Suppress("unused") // Referenced in application.conf
@kotlin.jvm.JvmOverloads
fun Application.module(testing: Boolean = false) {
    routing {
        get("/") {
            throw RuntimeException("opps!!")
            //call.respondText("HELLO WORLD!", contentType = ContentType.Text.Plain)
        }
    }
    install(CallLogging)
}

curlでリクエストを送ると以下のようなログが出力されます。

{"@timestamp":"2021-05-21T21:38:19.628+09:00","@version":"1","message":"{\n    # application.conf @ file:/home/yuya-hirooka/source/kotlin/ktor-sandbox/logging/target/classes/application.conf: 6\n    \"application\" : {\n        # application.conf @ file:/home/yuya-hirooka/source/kotlin/ktor-sandbox/logging/target/classes/application.conf: 7\n        \"modules\" : [\n            # application.conf @ file:/home/yuya-hirooka/source/kotlin/ktor-sandbox/logging/target/classes/application.conf: 7\n            \"dev.hirooka.ApplicationKt.module\"\n        ]\n    },\n    # application.conf @ file:/home/yuya-hirooka/source/kotlin/ktor-sandbox/logging/target/classes/application.conf: 2\n    \"deployment\" : {\n        # application.conf @ file:/home/yuya-hirooka/source/kotlin/ktor-sandbox/logging/target/classes/application.conf: 3\n        \"port\" : 8080\n    },\n    # Content hidden\n    \"security\" : \"***\"\n}\n","logger_name":"Application","thread_name":"main","level":"TRACE","level_value":5000}
{"@timestamp":"2021-05-21T21:38:19.670+09:00","@version":"1","message":"Autoreload is disabled because the development mode is off.","logger_name":"Application","thread_name":"main","level":"INFO","level_value":20000}
{"@timestamp":"2021-05-21T21:38:19.957+09:00","@version":"1","message":"Responding at http://0.0.0.0:8080","logger_name":"Application","thread_name":"main","level":"INFO","level_value":20000}
{"@timestamp":"2021-05-21T21:38:19.957+09:00","@version":"1","message":"Application started: io.ktor.application.Application@39d9314d","logger_name":"Application","thread_name":"main","level":"TRACE","level_value":5000}
{"@timestamp":"2021-05-21T21:38:21.593+09:00","@version":"1","message":"hello","logger_name":"Application","thread_name":"eventLoopGroupProxy-4-1","level":"INFO","level_value":20000}
{"@timestamp":"2021-05-21T21:38:21.597+09:00","@version":"1","message":"Unhandled: GET - /","logger_name":"Application","thread_name":"eventLoopGroupProxy-4-1","level":"ERROR","level_value":40000,"stack_trace":"<#f0019090> j.l.RuntimeException: hello\n\tat d.h.ApplicationKt$module$1$1.invokeSuspend(Application.kt:17)\n\tat d.h.ApplicationKt$module$1$1.invoke(Application.kt)\n\tat i.k.u.p.SuspendFunctionGun.loop(SuspendFunctionGun.kt:246)\n\tat i.k.u.p.SuspendFunctionGun.proceed(SuspendFunctionGun.kt:116)\n\tat i.k.u.p.SuspendFunctionGun.execute(SuspendFunctionGun.kt:136)\n\tat i.k.u.p.Pipeline.execute(Pipeline.kt:79)\n\tat i.k.routing.Routing.executeResult(Routing.kt:155)\n\tat i.k.routing.Routing.interceptor(Routing.kt:39)\n\tat i.k.r.Routing$Feature$install$1.invokeSuspend(Routing.kt:107)\n\tat i.k.r.Routing$Feature$install$1.invoke(Routing.kt)\n\tat i.k.u.p.SuspendFunctionGun.loop(SuspendFunctionGun.kt:246)\n\tat i.k.u.p.SuspendFunctionGun.proceed(SuspendFunctionGun.kt:116)\n\tat i.k.f.CallLogging$Feature$install$2.invokeSuspend(CallLogging.kt:139)\n\tat i.k.f.CallLogging$Feature$install$2.invoke(CallLogging.kt)\n\tat i.k.u.p.SuspendFunctionGun.loop(SuspendFunctionGun.kt:246)\n\tat i.k.u.p.SuspendFunctionGun.proceed(SuspendFunctionGun.kt:116)\n\tat i.k.u.p.SuspendFunctionGun.execute(SuspendFunctionGun.kt:136)\n\tat i.k.u.p.Pipeline.execute(Pipeline.kt:79)\n\tat i.k.s.e.DefaultEnginePipelineKt$defaultEnginePipeline$2.invokeSuspend(DefaultEnginePipeline.kt:124)\n\tat i.k.s.e.DefaultEnginePipelineKt$defaultEnginePipeline$2.invoke(DefaultEnginePipeline.kt)\n\tat i.k.u.p.SuspendFunctionGun.loop(SuspendFunctionGun.kt:246)\n\tat i.k.u.p.SuspendFunctionGun.proceed(SuspendFunctionGun.kt:116)\n\tat i.k.u.p.SuspendFunctionGun.execute(SuspendFunctionGun.kt:136)\n\tat i.k.u.p.Pipeline.execute(Pipeline.kt:79)\n\tat i.k.s.n.NettyApplicationCallHandler$handleRequest$1.invokeSuspend(NettyApplicationCallHandler.kt:123)\n\tat i.k.s.n.NettyApplicationCallHandler$handleRequest$1.invoke(NettyApplicationCallHandler.kt)\n\tat k.c.i.UndispatchedKt.startCoroutineUndispatched(Undispatched.kt:55)\n\tat k.c.BuildersKt__Builders_commonKt.startCoroutineImpl(Builders.common.kt:194)\n\tat k.c.BuildersKt.startCoroutineImpl(Unknown Source:1)\n\tat k.c.AbstractCoroutine.start(AbstractCoroutine.kt:145)\n\t... 1..."}