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

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

```bash:ログ出力例
... リクエストボディ = param1=value1&param2=value2
... レスポンスボディ = This is reponse body
```

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

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

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

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

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

[後者のJavadoc](https://docs.spring.io/spring-framework/docs/current/javadoc-api/org/springframework/web/util/ContentCachingResponseWrapper.html)には

> 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`の場合、下記のいずれか（ソースは[ここらへん](https://github.com/spring-projects/spring-framework/blob/9f7a94058a4bbc967fe47bfe6a82d88cb3feddfb/spring-web/src/main/java/org/springframework/web/util/ContentCachingRequestWrapper.java#L160)）
    - `getParameter()`
    - `getParameterNames()`
    - `getParameterMap()`
    - `getParameterValues()`
- `ContentCachingResponseWrapper`の場合、下記のメソッド（ソースは[ここらへん](https://github.com/spring-projects/spring-framework/blob/9f7a94058a4bbc967fe47bfe6a82d88cb3feddfb/spring-web/src/main/java/org/springframework/web/util/ContentCachingResponseWrapper.java#L199)）
    - `copyBodyToResponse()`

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

```java
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）に書き込みます。