以下の記事で共通処理を挟むタイミングを調べたので、ここでは Spring log4j2 をベースに、API実行時に共通的な情報を残す方法の調査です。
出力内容
今回は以下の情報を出力させています。
本当はユーザIDなどもあればいいのかもしれませんが、今回は認証はやってないので含めていません。
| 出力項目 | 出力例 |
|---|---|
| 日付 | 2023/01/28 22:58:30 |
| ログレベル | INFO |
| ロガークラス | com.example.springlog4j2.MyLoggingFilter |
| リクエスト UUID | ea0f1b86-09e1-49f1-ba6b-bb09b7304434 |
| クライアント IP | 0:0:0:0:0:0:0:1 |
| クライアント User-Agent | Mozilla/5.0 (Macintosh; … |
| リクエスト HTTP Method | GET |
| リクエスト URL | /hello?query=343&foo=bar |
| リクエスト body | {“test”:”foo”} ※ POST の場合のみ |
| レスポンス HTTP Status | 200 |
| レスポンス body | foo |
準備
プロジェクトベース
- Java 17
- Spring Boot 2.7.7
以下をベースにすすめています。
検証用API
GET でも POST でも確認できるようそれぞれを用意。
@Slf4j
@RestController
public class MyRestController {
@GetMapping("/hello")
public String hello() {
return "foo";
}
@PostMapping("/hello2")
public String hello2(@RequestBody Object params) { // 検証なのでパラメータは適当です
return "foo2";
}
}アプリケーションの main は、上のベースの状態では exit するコードを書いていたのでデフォルト状態に戻して起きます。
public static void main(String[] args) {
SpringApplication.run(SpringLog4j2Application.class, args);
}ログ出力
やることは以下３点です。
- ログ出力用の Filter クラスを作成する
- 作成した Filter を登録する
- ログの出力フォーマットを変更する
ログ出力用の Filter クラスを作成する
1つ目ですが、ここがキモです。
@Slf4j
public class MyLoggingFilter extends OncePerRequestFilter {
@Override
protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain) throws IOException, ServletException {
ContentCachingRequestWrapper reqW = new ContentCachingRequestWrapper(request);
ContentCachingResponseWrapper resW = new ContentCachingResponseWrapper(response);
// メインの処理
filterChain.doFilter(reqW, resW);
// リクエスト
ThreadContext.put("requestId", UUID.randomUUID().toString());
ThreadContext.put("remoteAddr", request.getRemoteAddr());
ThreadContext.put("userAgent", request.getHeader("User-Agent"));
ThreadContext.put("method", request.getMethod());
reqW.getParameterMap();
String requestBody = new String(reqW.getContentAsByteArray(), reqW.getCharacterEncoding());
ThreadContext.put("requestParams", requestBody);
// レスポンス
String responseBody = new String(resW.getContentAsByteArray(), resW.getCharacterEncoding());
ThreadContext.put("responseStatus", String.valueOf(response.getStatus()));
ThreadContext.put("responseBody", responseBody);
String qString = request.getQueryString() != null ? "?" + request.getQueryString() : "";
ThreadContext.put("url", request.getRequestURI() + qString);
log.info("[Request]");
resW.copyBodyToResponse();
}
}確実に1回実行されることが保証されている OncePerRequestFilter を使用した Filter を作成しています。
冒頭で記載した情報が出力されるよう、各種情報を request / response から取得しています。
リクエスト, レスポンスオブジェクトに対して Wrapper クラスを使用しているのは Spring MVCで、Filterでリクエストボディとレスポンスボディをログ出力するときの落とし穴と対策 を参考にさせていただきました。
ThreadContext を使ってデータをセットしています。これは後ほどでてくるログフォーマットで使えるようにするためです。ここでしか使わないなら ThreadContext を使わなくてもよい部分もありますが、フォーマットの変更に柔軟に対応できる点を考え一旦こうしています（パフォーマンス面で微妙なら見直したほうがよいところ）。
作成した Filter を登録する
これは冒頭でも言及した以下の記事の通りです。Filter を登録するためのもので、今回は全 api を対象にしています。
@Configuration
public class FilterConfiguration implements WebMvcConfigurer {
@Bean
public FilterRegistrationBean<?> myOncePerRequestFilter() {
FilterRegistrationBean<MyLoggingFilter> registrationBean = new FilterRegistrationBean<>(new MyOncePerRequestFilter());
registrationBean.addUrlPatterns("/*");
return registrationBean;
}
}ログの出力フォーマットを変更する
今回は横着しましたが、証跡ログ用のフォーマットは専用に定義するのが良いと思います。
フォーマット部分は以下ハイライト部分で %X{<ThreadContextに登録したキー名>} を指定することで、紐付けて情報を出すことができます。ほんと便利ですね。
<Properties>
<Property name="logFilePath">./</Property>
<Property name="logFormat">%d{yyyy/MM/dd HH:mm:ss}, %-5level, %logger{36}, %X{requestId}, %X{remoteAddr}, %X{userAgent}, %X{method}, %X{url}, %msg, %X{responseStatus}, %X{requestParams}, %X{responseBody} %n</Property>
...
</Properties>
<Appenders>
<Console name="Console" target="SYSTEM_OUT" follow="true">
<PatternLayout pattern="${sys:logFormat}" charset="UTF-8"/>
</Console>
....動作確認
GET /hello 実行時
2023/01/28 22:58:30, INFO , com.example.springlog4j2.MyLoggingFilter, ea0f1b86-09e1-49f1-ba6b-bb09b7304434, 0:0:0:0:0:0:0:1, Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/107.0.0.0 Safari/537.36, GET, /hello?query=343&foo=bar, [Request], 200, , foo POST /hello2 実行時
2023/01/28 22:58:37, INFO , com.example.springlog4j2.MyLoggingFilter, 5c2c2d41-38e6-4e67-8d8f-e5e4565a9f7c, 0:0:0:0:0:0:0:1, Mozilla/5.0 (Windows NT 6.1; Win64; x64; rv:47.0) Gecko/20100101 Firefox/47.0, POST, /hello2, [Request], 200, {"test":"foo"}, foo2 ちゃんと出ていますね。ユーザIDやその他追加でだした情報も ThreadContext 等を使用することで追加できます。こんな短いコードで実現できるなんでありがたいですね。
コメント