Edited at

Spring Boot(Spring,Servlet)でリクエスト毎のログを残したい


環境


  • spring boot 2.2.0.M4

  • io.spring.dependency-management 1.0.7.RELEASE

  • plugin spring 1.3.31

  • kotlin 1.3.31


経緯

SpringMVCでリクエスト毎に受信したリクエストと返したレスポンスのログを残したい気持ちが高まったために色々とあーだこーだした際の防備録を兼ねて残す


手法


  • Servlet Request Listenerを実装

  • OncePerRequestFilterを継承したクラスを実装


結論

後者


そもそも

springやplay frameworkが色々と拡張しているが基本的には下記画像の通りにservletが飛んでいる

Spring MVC(+Spring Boot)上でのリクエスト共通処理の実装方法を理解する

処理シーケンス link:img


Servlet Request Listenerを実装

上記URLのQiita記事を見てこれでいけんじゃねと思い下記を実装した

ServletRequestEventをHttpRequestにキャストすることでリモートIPやメソッドを取得することができる

単にリクエストの開始と終了をServletの大元部分で拾いたい場合は下記実装で必要十分となる


@Component
@Order(Ordered.HIGHEST_PRECEDENCE)
class CustomServletRequestListener : ServletRequestListener {

val logger by LoggerDelegate()

override fun requestInitialized(sre : ServletRequestEvent?) {
// request開始時処理
logger.info("request initialized")
val httpServletRequest = sre?.servletRequest as HttpServletRequest
logRequest(httpServletRequest)
super.requestInitialized(sre)
}

override fun requestDestroyed(sre : ServletRequestEvent?) {
// request終了時処理
logger.info("request destroyed")
val httpServletRequest = sre?.servletRequest as HttpServletRequest
logRequest(httpServletRequest)
super.requestDestroyed(sre)
}

private fun logRequest(request : HttpServletRequest) {
val params : String = request.parameterMap.entries.stream().map { entry -> entry.key + ":" + Arrays.toString(entry.value) }.collect(Collectors.joining(", "))

val queryString = request.queryString
val queryClause = if (StringUtils.hasLength(queryString)) "?$queryString" else ""
val dispatchType = if (request.dispatcherType != DispatcherType.REQUEST) {
"\"" + request.dispatcherType.name + "\" dispatch for "
} else {
""
}

val message = dispatchType + request.method + " \"" + getRequestUri(request) +
queryClause + "\", parameters={" + params + "}"

val values = Collections.list(request.headerNames)
val headers = values.stream().map { name -> name + ":" + Collections.list(request.getHeaders(name)) }.collect(Collectors.joining(", "))
logger.info(message)
}

private fun getRequestUri(request : HttpServletRequest) : String? {
var uri : String? = request.getAttribute(WebUtils.INCLUDE_REQUEST_URI_ATTRIBUTE) as String?
if (uri == null) {
uri = request.requestURI
}
return uri
}
}

だが問題点があった

レスポンスのデータが拾えない

悩んだ挙げ句、デメリットを受け入れて次の実装に切り替えた


OncePerRequestFilterを継承したクラスを実装

OncePerRequestFilet自体はSpring Frameworkが提供している抽象クラスで、servletがDispatchされるたびに処理が行われるFilterクラス


Filter base class that aims to guarantee a single execution per request dispatch, on any servlet


このFilterクラス内でハッシュマップを保持してレスポンスの情報も保持するという算段

Javaでの実装は下記引用

Springでリクエストとレスポンスのログを出力する

NTT DATAがSpring FrameworkをカスタマイズしているTerasoLunaでは下記のように記載されている

Teraso Luna MDCの使用

以下Kotlinでの実装例

class CustomRequestResponseLogFilter : OncePerRequestFilter() {

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

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

@Throws(ServletException::class, IOException::class)
private fun doFilterWrapped(request : ContentCachingRequestWrapper, response : ContentCachingResponseWrapper, filterChain : FilterChain) {
try {
beforeRequest(request, response)
filterChain.doFilter(request, response)
} finally {
afterRequest(request, response)
response.copyBodyToResponse()
}
}

private fun beforeRequest(request : ContentCachingRequestWrapper, response : ContentCachingResponseWrapper) {
logRequestHeader(request, request.remoteAddr + "|>")
}

private fun afterRequest(request : ContentCachingRequestWrapper, response : ContentCachingResponseWrapper) {
logRequestBody(request, request.remoteAddr + "|>")
logResponse(response, request.remoteAddr + "|<")
}

private fun logRequestHeader(request : ContentCachingRequestWrapper, prefix : String) {
val queryString = request.queryString
if (queryString.isNullOrEmpty()) {
logger.info("$prefix ${request.method} ${request.requestURI}")
} else {
logger.info("$prefix ${request.method} ${request.requestURI}?$queryString")
}
Collections.list(request.headerNames).forEach { headerName -> Collections.list(request.getHeaders(headerName)).forEach { headerValue -> logger.info("$prefix $headerName: $headerValue") } }
logger.info(prefix)
}

private fun logRequestBody(request : ContentCachingRequestWrapper, prefix : String) {
val content = request.contentAsByteArray
if (content.isNotEmpty()) {
logContent(content, request.contentType, request.characterEncoding, prefix)
}
}

private fun logResponse(response : ContentCachingResponseWrapper, prefix : String) {
val status = response.status
logger.info("$prefix $status ${HttpStatus.valueOf(status).reasonPhrase}")
response.headerNames.forEach { headerName -> response.getHeaders(headerName).forEach { headerValue -> logger.info("$prefix $headerName: $headerValue") } }
logger.info(prefix)
val content = response.contentAsByteArray
if (content.isNotEmpty()) {
logContent(content, response.contentType, response.characterEncoding, prefix)
}
}

private fun logContent(content : ByteArray, contentType : String, contentEncoding : String, prefix : String) {
val mediaType = MediaType.valueOf(contentType)
val visible = VISIBLE_TYPES.stream().anyMatch({ visibleType -> visibleType.includes(mediaType) })
if (visible) {
try {
val contentString = String(content)
Stream.of(contentString.split("\r\n|\r|\n")).forEach { line -> logger.info("$prefix $line") }
} catch (e : UnsupportedEncodingException) {
logger.info("$prefix [${content.size} bytes content]")
}

} else {
logger.info("$prefix [${content.size} 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)
}

}


補足

トレーサビリティを考えるとリクエストを受けた段階でtracerIDを発行してログに残しておいたほうがよさそう


終わりに

間違い等あれば指摘ください 5km走って出直してきます(修正します)


引用元

Spring MVC(+Spring Boot)上でのリクエスト共通処理の実装方法を理解する

Springでリクエストとレスポンスのログを出力する

TerasoLuna Reference