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

Spring Bootでリクエストとレスポンスのログを出力するフィルターを書いたので共有します。

オリジナル

オリジナルとの違い

• ログの形式をJSONにした
• GETなどでBodyが無い場合も、要素を追加
• Multipartやアップロードファイルに対応
• ロギングフィルターなので可能な限り Exception をキャッチ
  • RuntimeException も回収している
• APIのログなのでリクエストやレスポンスのJSONをパース
• slf4jやlombokは使っていない
• ロガーは GenericFilterBean のものを使用した

AbstractRequestLoggingFilter や CommonsRequestLoggingFilter を参考にしている

ログファイルはZabbixで拾ってフィルターしてほしい

import java.io.IOException;
import java.util.ArrayList;
import java.util.Arrays;
import java.util.Collection;
import java.util.Collections;
import java.util.LinkedHashMap;
import java.util.List;
import java.util.Map;

import javax.servlet.FilterChain;
import javax.servlet.ServletException;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
import javax.servlet.http.Part;

import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.http.HttpStatus;
import org.springframework.http.MediaType;
import org.springframework.security.core.context.SecurityContext;
import org.springframework.security.core.context.SecurityContextHolder;
import org.springframework.util.FileCopyUtils;
import org.springframework.util.StringUtils;
import org.springframework.web.filter.OncePerRequestFilter;
import org.springframework.web.util.ContentCachingRequestWrapper;
import org.springframework.web.util.ContentCachingResponseWrapper;

import com.fasterxml.jackson.core.JsonProcessingException;
import com.fasterxml.jackson.databind.JsonNode;
import com.fasterxml.jackson.databind.ObjectMapper;
import com.fasterxml.jackson.databind.node.NullNode;

public class RequestResponseLoggingFilter extends OncePerRequestFilter {
    private static final List<MediaType> VISIBLE_TYPES = Arrays.asList(
                    MediaType.valueOf("text/*"),
                    MediaType.APPLICATION_FORM_URLENCODED,
                    MediaType.APPLICATION_JSON,
                    MediaType.APPLICATION_XML,
                    MediaType.valueOf("application/*+json"),
                    MediaType.valueOf("application/*+xml"),
                    MediaType.MULTIPART_FORM_DATA
                );
    private static final List<MediaType> FORM_TYPES = Arrays.asList(
                    MediaType.APPLICATION_FORM_URLENCODED,
                    MediaType.MULTIPART_FORM_DATA
                    );
    private final ThreadLocal<Map<String, Object>> localParams = ThreadLocal.withInitial(() -> new LinkedHashMap<>());

    @Autowired
    private ObjectMapper mapper;

    @Override
    protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain)
                    throws ServletException, IOException {
        if (isAsyncDispatch(request)) {
            filterChain.doFilter(request, response);
        } else {
            doFilterWrapped(wrapRequest(request), wrapResponse(response), filterChain);
        }
    }

    protected void doFilterWrapped(ContentCachingRequestWrapper request, ContentCachingResponseWrapper response, FilterChain filterChain) throws ServletException, IOException {
        try {
            beforeRequest(request, response);
            filterChain.doFilter(request, response);
        }
        finally {
            afterRequest(request, response);
            outputParams();
            localParams.remove();
            response.copyBodyToResponse();
        }
    }

    protected void beforeRequest(ContentCachingRequestWrapper request, ContentCachingResponseWrapper response) {
        if (logger.isDebugEnabled()) {
            throwable("logRequestHeader", () -> logRequestHeader(request));
        }
    }

    protected void afterRequest(ContentCachingRequestWrapper request, ContentCachingResponseWrapper response) {
        if (logger.isDebugEnabled()) {
            throwable("logRequestBody", () -> logRequestBody(request));
            throwable("logResponse", () -> logResponse(response));
        }
    }

    private void logRequestHeader(ContentCachingRequestWrapper request) {
        localParams.get().put("client", request.getRemoteAddr());
        String queryString = request.getQueryString();
        if (queryString == null) {
            localParams.get().put("request", request.getMethod() + " " + request.getRequestURI());
        }
        else {
            localParams.get().put("request", request.getMethod() + " " + request.getRequestURI() + "?" + queryString);
        }
        Map<String, List<String>> headers = new LinkedHashMap<>();
        Collections.list(request.getHeaderNames()).forEach(headerName ->
            Collections.list(request.getHeaders(headerName)).forEach(headerValue -> {
                if (headers.containsKey(headerName)) {
                    headers.get(headerName).add(headerValue);
                }
                else {
                    headers.put(headerName, new ArrayList<>());
                    headers.get(headerName).add(headerValue);
                }
            }));
        localParams.get().put("requestHeaders", headers);
        SecurityContext ctx = SecurityContextHolder.getContext();
        if (null != ctx) {
            localParams.get().put("authentication", convertTo(ctx.getAuthentication()));
        }
     }

    private void logRequestBody(ContentCachingRequestWrapper request) throws ServletException, IOException {
        Collection<Part> parts = getRequestParts(request);
        if (parts.isEmpty()) {
            byte[] content = request.getContentAsByteArray();
            if (content.length > 0) {
                logContent(content, request.getContentType(), request.getCharacterEncoding(), "requestBody");
            }
            else {
                localParams.get().put("requestBody", "[empty body]");
            }
        }
        else {
            Map<String, Object> contents = new LinkedHashMap<>();
            parts.stream().forEach(p -> {
                String name = p.getName();
                try {
                    byte[] content = FileCopyUtils.copyToByteArray(p.getInputStream());
                    contents.put(name, logContent(content, p.getContentType(), "UTF-8"));
                }
                catch (IOException e) {
                    String fileName = p.getSubmittedFileName();
                    if (StringUtils.hasText(fileName)) {
                        contents.put(name, String.format("fileName[%s]", fileName));
                    }
                    else {
                        contents.put(name, String.format("IOException[%s]", e.getMessage()));
                    }
                }
            });
            localParams.get().put("requestBody", contents);
        }
    }

    private Collection<Part> getRequestParts(ContentCachingRequestWrapper request) throws ServletException, IOException {
        MediaType mediaType = getMediaType(request.getContentType());
        boolean isPost = FORM_TYPES.stream().anyMatch(formType -> formType.includes(mediaType));
        return isPost ? request.getParts() : Collections.emptyList();
    }

    private void logResponse(ContentCachingResponseWrapper response) {
        int status = response.getStatus();
        localParams.get().put("response", status + " " + HttpStatus.valueOf(status).getReasonPhrase());
        Map<String, List<String>> headers = new LinkedHashMap<>();
        response.getHeaderNames().forEach(headerName ->
            response.getHeaders(headerName).forEach(headerValue -> {
                if (headers.containsKey(headerName)) {
                    headers.get(headerName).add(headerValue);
                }
                else {
                    headers.put(headerName, new ArrayList<>());
                    headers.get(headerName).add(headerValue);
                }
            }));
        localParams.get().put("responseHeaders", headers);
        byte[] content = response.getContentAsByteArray();
        if (content.length > 0) {
            logContent(content, response.getContentType(), response.getCharacterEncoding(), "responseBody");
        }
    }

    private void logContent(byte[] content, String contentType, String contentEncoding, String key) {
        localParams.get().put(key, logContent(content, contentType, contentEncoding));
    }

    private Object logContent(byte[] content, String contentType, String contentEncoding) {
        MediaType mediaType = getMediaType(contentType);
        boolean visible = VISIBLE_TYPES.stream().anyMatch(visibleType -> visibleType.includes(mediaType));
        boolean json = mediaType.getSubtype().contains("json");
        if (visible) {
            try {
                String contentString = new String(content, contentEncoding);
                if (json) {
                    return mapper.readTree(contentString);
                }
                else {
                    return contentString;
                }
            }
            catch (IOException e) {
                return String.format("[%d bytes content]", content.length);
            }
        }
        else {
            return String.format("[%d bytes content]", content.length);
        }
    }

    private MediaType getMediaType(String contentType) {
        try {
            return MediaType.valueOf(contentType);
        }
        catch (IllegalArgumentException e) {
            return null;
        }
    }

    private void outputParams() {
        logger.debug(unparse(mapper, localParams.get()));
    }

    private JsonNode convertTo(Object obj) {
        NullNode node = mapper.getDeserializationConfig().getNodeFactory().nullNode();
        if (null == obj) {
            return node;
        }
        try {
            return mapper.readTree(mapper.writeValueAsString(obj));
        }
        catch (IOException e) {
            return node;
        }
    }

    private void throwable(String key, ThrowableExecutor method) {
        try {
            method.apply();
        }
        catch (Exception e) {
            localParams.get().put(key, String.format("%s[%s]", e.getClass().getSimpleName(), e.getMessage()));
        }
    }

    public static String unparse(ObjectMapper mapper, Object obj) {
        if (null == obj) {
            return "null";
        }
        if (null == mapper) {
            return String.valueOf(obj);
        }
        try {
            return mapper.writeValueAsString(obj);
        } catch (JsonProcessingException e) {
            return e.getMessage();
        }
    }

    private static ContentCachingRequestWrapper wrapRequest(HttpServletRequest request) {
        if (request instanceof ContentCachingRequestWrapper) {
            return (ContentCachingRequestWrapper) request;
        } else {
            return new ContentCachingRequestWrapper(request);
        }
    }

    private static ContentCachingResponseWrapper wrapResponse(HttpServletResponse response) {
        if (response instanceof ContentCachingResponseWrapper) {
            return (ContentCachingResponseWrapper) response;
        } else {
            return new ContentCachingResponseWrapper(response);
        }
    }

    public static interface ThrowableExecutor {
        void apply() throws Exception;
    }
}

logback-spring.xml

logback-spring.xml

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <include resource="org/springframework/boot/logging/logback/base.xml" />

    <appender name="REQUEST_LOGGING_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${LOG_PATH}/requestLogging.log</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>${LOG_PATH}/requestLogging.log.%d{yyyyMMdd}.gz</fileNamePattern>
            <maxHistory>30</maxHistory>
        </rollingPolicy>
        <encoder>
            <charset>UTF-8</charset>
            <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level [%t]%X{request_thread} %logger{45}:%L - %msg %n</pattern>
        </encoder>
    </appender>

    <logger name="RequestResponseLoggingFilter" level="DEBUG">
        <appender-ref ref="REQUEST_LOGGING_FILE"/>
    </logger>
</configuration>

spring-boot:run の設定とか

pom.xml

<plugin>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-maven-plugin</artifactId>
    <configuration>
        <executable>true</executable>
        <mainClass>Application</mainClass>
        <jvmArguments>
            -Dlogging.config=file:${project.build.outputDirectory}/logback-spring.xml
            -Dlogging.path=${project.build.directory}/log
        </jvmArguments>
        <includeSystemScope>true</includeSystemScope>
    </configuration>
</plugin>

形式がJSON なので jq でフォーマットできる

% tail -n 20 requestLogging.log|grep '/v1/info'|tail -n 1 |cut -d" " -f 7- |jq .

{
  "client": "0:0:0:0:0:0:0:1",
  "request": "GET /v1/info",
  "requestHeaders": {
    "host": [
      "localhost:8080"
    ],
    "user-agent": [
      "curl/7.54.0"
    ],
    "accept": [
      "*/*"
    ]
  },
  "authentication": {
    "authorities": [
      {
        "authority": "ROLE_ANONYMOUS"
      }
    ],
    "details": {
      "remoteAddress": "0:0:0:0:0:0:0:1",
      "sessionId": null
    },
    "authenticated": true,
    "principal": "anonymousUser",
    "keyHash": -184817062,
    "credentials": "",
    "name": "anonymousUser"
  },
  "requestBody": "[empty body]",
  "response": "200 OK",
  "responseHeaders": {
    "X-Content-Type-Options": [
      "nosniff"
    ],
    "X-XSS-Protection": [
      "1; mode=block"
    ],
    "Cache-Control": [
      "no-cache, no-store, max-age=0, must-revalidate"
    ],
    "Pragma": [
      "no-cache"
    ],
    "Expires": [
      "0"
    ],
    "X-Frame-Options": [
      "DENY"
    ]
  },
  "responseBody": "git info\n commit\n   branch: setup-logger\n   id: <commit>\n   time: 2018-04-05T21:27:51+09:00\n build\n   host: Macmini.local\n   time: 2018-04-05T23:29:45+09:00\n"
}

パフォーマンス!?

このフィルタを適用するとレスポンスボディが一時的にメモリに保持されるため、メモリの消費量が大きくなります。また、大きいレスポンスを返す場合はパフォーマンスが悪化します。そのため、デバッグ用途に限定した方がよいでしょう。

バックエンド Rest API の現状は ログ >>> (越えられない壁) >>> メモリやパフォーマンス