Spring Boot + Kotlin で RESTful API のログ出力

## TL; DR
- Logbackでログ形式設定
- Filterでリクエスト/レスポンスのログをJSON形式で出力
- MultipartRequestには非対応

ソースはこちら
https://github.com/OskaMathis/spring-boot-sample/tree/restful_api

## 環境
- Kotlin: `1.3.50`
- Spring boot: `2.3.1.RELEASE`

## [logstash-logback-encoder][encoder]を依存に追加
### Gradle
```text:build.gradle.kts
dependencies {
    ...

    implementation("net.logstash.logback:logstash-logback-encoder:6.4")
}
```

### Maven
```text:pom.xml
<dependencies>
    ...

    <dependency>
        <groupId>net.logstash.logback</groupId>
        <artifactId>logstash-logback-encoder</artifactId>
        <version>6.4</version>
    </dependency>
</dependencies>
```


## Logbackの設定
`spring-boot-starter-web` にはLogbackが内蔵されているので、`logback-spring.xml` を書くだけでログの諸々の設定ができます。
今回はローカル環境以外ではログがJSON形式で出力されるように設定してみました。

```text:/src/main/resources
.
├── application.yml
├── logback
│   └── json-layout.xml
└── logback-spring.xml
```

```xml:logback-spring.xml
<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <property resource="application.yml"/>
    <contextName>com.example.demo.DemoApplication</contextName>

    <springProfile name="local">
        <include resource="org/springframework/boot/logging/logback/base.xml" />
        <root level="INFO">
            <appender-ref ref="CONSOLE"/>
        </root>
    </springProfile>

    <springProfile name="dev, stg, prod">
        <include resource="logback/json-layout.xml" />
        <root level="INFO">
            <appender-ref ref="CONSOLE"/>
        </root>
    </springProfile>
</configuration>

```

```xml:json_layout.xml
<included>
    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <encoder class="net.logstash.logback.encoder.LoggingEventCompositeJsonEncoder">
            <jsonGeneratorDecorator class="net.logstash.logback.decorate.PrettyPrintingJsonGeneratorDecorator"/>
            <providers>
                <timestamp>
                    <fieldName>timeStamp</fieldName>
                    <timeZone>UTC</timeZone>
                </timestamp>
                <loggerName>
                    <fieldName>logger</fieldName>
                </loggerName>
                <logLevel>
                    <fieldName>level</fieldName>
                </logLevel>
                <threadName>
                    <fieldName>thread</fieldName>
                </threadName>
                <pattern>
                    <pattern>{ "message": "#tryJson{%message}" }</pattern>
                </pattern>
                <arguments>
                    <includeNonStructuredArguments>false</includeNonStructuredArguments>
                </arguments>
                <stackTrace>
                    <fieldName>stack</fieldName>
                </stackTrace>
            </providers>
        </encoder>
    </appender>
</included>
```


`#tryJson{}` は中括弧内のパターン文字列を評価して、結果の文字列をJSONに変換します。
JSONへの変換に失敗したときはそのまま文字列になります。

```xml
<pattern>
    <pattern>{ "message": "#tryJson{%message}" }</pattern>
</pattern>
```


## Filterの設定
そのままFilterやInterceptor内でサーブレットからリクエストボディを取得するとController側でリクエストボディが見つからないと言われるので、FilterChainを通過する前に`HttpServletRequest`をラップしてリクエストボディをキャッシュしておく必要があります。
`HttpServletRequestWrapper`を拡張してキャッシュしてもいいですが、今回は`ContentCachingRequestWrapper`でラップします。
`ContentCachingRequestWrapper`を使用する場合は、InputStreamが読み込まれるまではキャッシュされないので、Controllerの処理完了後にログ出力するようにします。

レスポンスボディも、ストリームに書き込む前に`ContentCachingResponseWrapper`でキャッシュします。

```kotlin:RequestResponseLoggingFilter.kt
class RequestAndResponseLoggingFilter : OncePerRequestFilter() {
    companion object {
        private val log = LoggerFactory.getLogger(RequestAndResponseLoggingInterceptor::class.java)
        private val mapper = jacksonObjectMapper()

        private val VISIBLE_TYPES = listOf(
            MediaType.valueOf("text/*"),
            MediaType.APPLICATION_JSON,
            MediaType.APPLICATION_XML,
            MediaType.valueOf("application/*+json"),
            MediaType.valueOf("application/*+xml")
        )
    }

    override fun doFilterInternal(
        request: HttpServletRequest,
        response: HttpServletResponse,
        filterChain: FilterChain
    ) {
        if (isAsyncDispatch(request)) {
            filterChain.doFilter(request, response)
        } else {
            doFilterWrapped(wrapRequest(request), wrapResponse(response), filterChain)
        }
    }

    private fun doFilterWrapped(
        request: ContentCachingRequestWrapper,
        response: ContentCachingResponseWrapper,
        filterChain: FilterChain
    ) {
        try {
            filterChain.doFilter(request, response)
        } finally {
            val endpoint = logRequest(request)
            logResponse(response, endpoint)
            response.copyBodyToResponse()
        }
    }

    private fun logRequest(request: ContentCachingRequestWrapper): String {
        val queryString = request.queryString?.let { "?$it" } ?: ""
        val endpoint = "${request.method} ${request.requestURI}$queryString"

        val requestHeaders = request.headerNames.asSequence().associateWith { headerName ->
            request.getHeader(headerName)
        }

        val content = request.contentAsByteArray
        val requestBody = if (content.isNotEmpty()) {
            getContentByte(content, request.contentType, request.characterEncoding)
        } else ""

        val json = mapper.writeValueAsString(
            object {
                val endpoint = endpoint
                val request = object {
                    val header = requestHeaders
                    val body: Any? = if (requestBody.isNotBlank() && request.contentType.contains(MediaType.APPLICATION_JSON_VALUE)) {
                        mapper.readTree(requestBody)
                    } else {
                        requestBody
                    }
                }
            }
        )

        log.info(json)
        return endpoint
    }

    private fun logResponse(response: ContentCachingResponseWrapper, endpoint: String) {
        val status = response.status
        val statusPhrase = HttpStatus.valueOf(status).reasonPhrase
        val responseHeaders = response.headerNames.asSequence().associateWith { headerName ->
            response.getHeader(headerName)
        }

        val content = response.contentAsByteArray
        val responseBody = if (content.isNotEmpty()) {
            getContentByte(response.contentAsByteArray, response.contentType, response.characterEncoding)
        } else ""

        val json = mapper.writeValueAsString(
            object {
                val endpoint = endpoint
                val response = object {
                    val status = "$status $statusPhrase"
                    val header = responseHeaders
                    val body: Any? = if (responseBody.isNotBlank() && response.contentType.contains(MediaType.APPLICATION_JSON_VALUE)) {
                        mapper.readTree(responseBody)
                    } else {
                        responseBody
                    }
                }
            }
        )

        log.info(json)
    }

    private fun getContentByte(content: ByteArray, contentType: String, contentEncoding: String): String {
        val mediaType = MediaType.valueOf(contentType)
        val visible = VISIBLE_TYPES.stream().anyMatch { visibleType -> visibleType.includes(mediaType) }

        return if (visible) {
            var contentStr = ""
            contentStr += try {
                String(content, charset(contentEncoding))
            } catch (e: UnsupportedEncodingException) {
                val contentSize = content.size
                "$contentSize bytes content"
            }
            contentStr
        } else {
            val contentSize = content.size
            "$contentSize bytes content"
        }
    }

    private fun wrapRequest(request: HttpServletRequest): ContentCachingRequestWrapper {
        return request as? ContentCachingRequestWrapper ?: ContentCachingRequestWrapper(request)
    }

    private fun wrapResponse(response: HttpServletResponse): ContentCachingResponseWrapper {
        return response as? ContentCachingResponseWrapper ?: ContentCachingResponseWrapper(response)
    }
}
```

作成したFilterが読み込まれるように設定します。

```kotlin:FilterConfig.kt
@Configuration
class FilterConfig {
    @Bean
    fun requestAndResponseLoggingFilter(): FilterRegistrationBean<RequestAndResponseLoggingFilter> {
        return FilterRegistrationBean(RequestAndResponseLoggingFilter())
            .apply {
                this.order = Int.MIN_VALUE
            }
    }
}

```

## ログ出力のイメージ

`spring.profiles.active`を`dev`にして実行してみました。

```json
{
  "timeStamp" : "2020-07-05T03:28:40.867Z",
  "logger" : "com.example.demo.interceptor.RequestAndResponseLoggingInterceptor",
  "level" : "INFO",
  "thread" : "http-nio-8080-exec-6",
  "message" : {
    "endpoint" : "GET /?limit=15&offset=0",
    "request" : {
      "header" : {
        "user-agent" : "vscode-restclient",
        "accept-encoding" : "gzip, deflate",
        "host" : "localhost:8080",
        "connection" : "close"
      },
      "body" : ""
    }
  }
}
{
  "timeStamp" : "2020-07-05T03:28:40.868Z",
  "logger" : "com.example.demo.interceptor.RequestAndResponseLoggingInterceptor",
  "level" : "INFO",
  "thread" : "http-nio-8080-exec-6",
  "message" : {
    "endpoint" : "GET /?limit=15&offset=0",
    "response" : {
      "status" : "200 OK",
      "header" : { },
      "body" : {
        "limit" : "15",
        "offset" : "0"
      }
    }
  }
}
{
  "timeStamp" : "2020-07-05T03:28:42.924Z",
  "logger" : "com.example.demo.interceptor.RequestAndResponseLoggingInterceptor",
  "level" : "INFO",
  "thread" : "http-nio-8080-exec-7",
  "message" : {
    "endpoint" : "POST /",
    "request" : {
      "header" : {
        "user-agent" : "vscode-restclient",
        "content-type" : "application/json",
        "accept-encoding" : "gzip, deflate",
        "content-length" : "112",
        "host" : "localhost:8080",
        "connection" : "close"
      },
      "body" : {
        "string" : "",
        "number" : 0,
        "boolean" : false,
        "null" : null,
        "object" : { },
        "array" : [ ]
      }
    }
  }
}
{
  "timeStamp" : "2020-07-05T03:28:42.925Z",
  "logger" : "com.example.demo.interceptor.RequestAndResponseLoggingInterceptor",
  "level" : "INFO",
  "thread" : "http-nio-8080-exec-7",
  "message" : {
    "endpoint" : "POST /",
    "response" : {
      "status" : "200 OK",
      "header" : { },
      "body" : {
        "string" : "",
        "number" : 0,
        "boolean" : false,
        "null" : null,
        "object" : { },
        "array" : [ ]
      }
    }
  }
}
```

## 余談
`ContentCachingRequestWrapper`の代わりに`HttpServletRequestWrapper`を拡張して、Interceptor内でリクエストボディをログ出力するのにも挑戦してみたのですが、MultipartRequestを受け取ったときにControllerで正常に処理できなくなったりしたので断念しました。
影響範囲も分からないですし、ログ出力のためにアプリケーションの動作がおかしくなっては本末転倒なので、内部実装に詳しくなるまではおとなしく`ContentCachingRequestWrapper`を使おうと思います。


## 参考
- [Spring BootでRequest Bodyをログに出力する][request-logging]
- [How to read request body in HandlerInterceptor in Spring boot?][how-to-read]
- [Springでリクエストとレスポンスのログを出力する][spring-logging]
- [Spring Bootでサーブレットフィルターを使う [Spring Boot 1.x, 2.x両対応]][filter]

[encoder]:https://github.com/logstash/logstash-logback-encoder
[request-logging]:http://kissybnts.hatenablog.com/entry/2017/03/11/121228
[how-to-read]:https://stackoverflow.com/questions/60556148/how-to-read-request-body-in-handlerinterceptor-in-spring-boot
[spring-logging]:https://int128.hatenablog.com/entry/2017/10/31/192913
[filter]:https://qiita.com/suke_masa/items/7bdfab8e974931afdac5