LoginSignup
4
3

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?

More than 3 years have passed since last update.

@oskamathis(Yushi Sako)in株式会社ゆめみ

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

Last updated at Posted at 2020-07-05

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を依存に追加

Gradle

build.gradle.kts
dependencies {
    ...

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

Maven

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形式で出力されるように設定してみました。

/src/main/resources
.
├── application.yml
├── logback
│   └── json-layout.xml
└── logback-spring.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>
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への変換に失敗したときはそのまま文字列になります。

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

Filterの設定

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

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

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が読み込まれるように設定します。

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

ログ出力のイメージ

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

{
  "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を使おうと思います。

参考

4
3
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
4
3

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?