Spring MVCで、Filterでリクエストボディとレスポンスボディをログ出力するときの落とし穴と対策

やりたいこと

リクエストボディとレスポンスボディの内容を、Filterでログ出力したい。

ログ出力例

... リクエストボディ = param1=value1&param2=value2
... レスポンスボディ = This is reponse body

本来は秘匿情報のマスクなどが必要になりますが、この記事ではその説明を省いています。

問題

HttpServletRequest や HttpServletResponse には、ボディを String で取得するようなメソッドは存在しません。前者には getInputStream() 、後者には getOutputStream() というメソッドがあり、これを使えばボディを取得することはできます（ String にするにはゴニョゴニョ処理が必要なのですが）。

しかし、 getXxxStream() メソッドを使ってしまうとボディが消費されてしまい、その後はボディが取得できなくなってしまいます。

なので HttpServletRequestWrapper などを利用して、ボディをどこかにキャッシュしたりする必要があります。

Spring MVCの便利クラス

この問題を解決するのが、Spring MVCで提供されている ContentCachingRequestWrapper クラス・ ContentCachingResponseWrapper クラスです。

後者のJavadocには

HttpServletResponse wrapper that caches all content written to the output stream and writer, and allows this content to be retrieved via a byte array.
訳： OutputStreamやWriterに書かれる全内容をキャッシュするHttpServletResponseラッパーです。内容はbyte配列として取得できます。

と書いてあるので、まさに前述の問題を解決してくれそうです。

利用と注意点

実はこれらのクラスは自動的にボディをキャッシュしてくれるわけではなく、特定のメソッドを呼ぶとキャッシュしてくれます。

• ContentCachingRequestWrapperの場合、下記のいずれか（ソースはここらへん）
  • getParameter()
  • getParameterNames()
  • getParameterMap()
  • getParameterValues()
• ContentCachingResponseWrapperの場合、下記のメソッド（ソースはここらへん）
  • copyBodyToResponse()

特に前者が落とし穴でした・・・

public class LoggingFilter extends OncePerRequestFilter {

    private static Logger logger = LoggerFactory.getLogger(LoggingFilter.class);

    @Override
    protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain) throws ServletException, IOException {
        ContentCachingRequestWrapper requestWrapper = new ContentCachingRequestWrapper(request);
        ContentCachingResponseWrapper responseWrapper = new ContentCachingResponseWrapper(response);
        // このメソッドを呼ぶとリクエストボディがキャッシュされる
        requestWrapper.getParameterNames();
        String requestBody = new String(requestWrapper.getContentAsByteArray(), requestWrapper.getCharacterEncoding());
        logger.info("リクエストボディ = {}", requestBody);
        try {
            filterChain.doFilter(requestWrapper, responseWrapper);
        } finally {
            String responseBody = new String(responseWrapper.getContentAsByteArray(), responseWrapper.getCharacterEncoding());;
            logger.info("レスポンス = {}", responseBody);
            // このメソッドを呼ぶと、キャッシュされたレスポンスボディが元のレスポンス（ラップされた内側のHttpServletResponse）に書き込まれる
            responseWrapper.copyBodyToResponse();
        }
    }
}

正確に言うと、 ContentCachingResponseWrapper はサーブレットで PrintWriter#println() などで書き込まれた内容をキャッシュしていて、そのキャッシュ内容を copyBodyToResponse() で元のレスポンス（ラップされた内側のHttpServletResponse）に書き込みます。