Нормализуем логи OpenFeign

Стандартный логгер OpenFeign предоставляет весьма неудобный подход в логировании коммуникаций — он записывает запрос отдельно от ответа, причём каждый заголовок и тело - это отдельная строка логов.

Очень неудобно разбирать такие логи в приложении с высоким уровнем коммуникаций, особенно в многопоточной среде.

Решение ‘Normalized Logger’ нацелено исправить этот изъян - этот логгер собирает в одну запись будущего лога запрос и ответ - теперь они не будут разбросаны.

Старый плохой логгер

2022-07-25 14:12:43.572 DEBUG 1032530 --- [Executor] feign.Logger : [AuthApi#login] ---> POST https://example.com/api/v1/login HTTP/1.1
2022-07-25 14:12:43.573 DEBUG 1032530 --- [Executor] feign.Logger : [AuthApi#login] Content-Length: 23
2022-07-25 14:12:43.573 DEBUG 1032530 --- [Executor] feign.Logger : [AuthApi#login] Content-Type: application/json
2022-07-25 14:12:43.574 DEBUG 1032530 --- [Executor] feign.Logger : [AuthApi#login] user-agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/91.0.4464.5 Safari/537.36
2022-07-25 14:12:43.575 DEBUG 1032530 --- [Executor] feign.Logger : [AuthApi#login] 
2022-07-25 14:12:43.576 DEBUG 1032530 --- [Executor] feign.Logger : [AuthApi#login] {"login":"123456789"}
2022-07-25 14:12:43.576 DEBUG 1032530 --- [Executor] feign.Logger : [AuthApi#login] ---> END HTTP (21-byte body)
2022-07-25 14:12:43.901 DEBUG 1032530 --- [Executor] feign.Logger : [AuthApi#login] <--- UNKNOWN 200 (324ms)
2022-07-25 14:12:43.901 DEBUG 1032530 --- [Executor] feign.Logger : [AuthApi#login] cache-control: no-cache
2022-07-25 14:12:43.901 DEBUG 1032530 --- [Executor] feign.Logger : [AuthApi#login] cf-cache-status: DYNAMIC
2022-07-25 14:12:43.901 DEBUG 1032530 --- [Executor] feign.Logger : [AuthApi#login] cf-ray: 730476518ea441ce-AMS
2022-07-25 14:12:43.901 DEBUG 1032530 --- [Executor] feign.Logger : [AuthApi#login] content-type: application/json
2022-07-25 14:12:43.901 DEBUG 1032530 --- [Executor] feign.Logger : [AuthApi#login] date: Mon, 25 Jul 2022 11:12:43 GMT
2022-07-25 14:12:43.901 DEBUG 1032530 --- [Executor] feign.Logger : [AuthApi#login] expect-ct: max-age=604800, report-uri="https://report-uri.cloudflare.com/cdn-cgi/beacon/expect-ct"
2022-07-25 14:12:43.901 DEBUG 1032530 --- [Executor] feign.Logger : [AuthApi#login] feature-policy: accelerometer 'none'; camera 'none'; geolocation 'none'; gyroscope 'none'; magnetometer 'none'; microphone 'none'; payment *; usb 'none'
2022-07-25 14:12:43.901 DEBUG 1032530 --- [Executor] feign.Logger : [AuthApi#login] referrer-policy: strict-origin-when-cross-origin
2022-07-25 14:12:43.901 DEBUG 1032530 --- [Executor] feign.Logger : [AuthApi#login] server: cloudflare
2022-07-25 14:12:43.901 DEBUG 1032530 --- [Executor] feign.Logger : [AuthApi#login] set-cookie: ACCESS_TOKEN=eyJh9uygCUMA659bAZ54SHpSNy_KFXQ; Max-Age=1800; Domain=.example.com; Path=/; Secure; SameSite=None
2022-07-25 14:12:43.901 DEBUG 1032530 --- [Executor] feign.Logger : [AuthApi#login] strict-transport-security: max-age=31536000
2022-07-25 14:12:43.901 DEBUG 1032530 --- [Executor] feign.Logger : [AuthApi#login] x-content-type-options: nosniff
2022-07-25 14:12:43.901 DEBUG 1032530 --- [Executor] feign.Logger : [AuthApi#login] x-frame-options: sameorigin
2022-07-25 14:12:43.901 DEBUG 1032530 --- [Executor] feign.Logger : [AuthApi#login] x-xss-protection: 1; mode=block
2022-07-25 14:12:43.901 DEBUG 1032530 --- [Executor] feign.Logger : [AuthApi#login] 
2022-07-25 14:12:43.902 DEBUG 1032530 --- [Executor] feign.Logger : [AuthApi#login] {"status":{"code":"OK","message":"OK"},"body":{"id":"20826"}}
2022-07-25 14:12:43.902 DEBUG 1032530 --- [Executor] feign.Logger : [AuthApi#login] <--- END HTTP (61-byte body)

Нормализованный логгер

2022-07-25 14:16:06.217 INFO 1057053 --- [Executor] me.bvn13.openfeign.logger.NormalizedFeignLogger : normalized feign request {AuthApi#login(LoginRequestDto)=[AuthApi#login] }: [
---> POST https://example.com/api/v1/login HTTP/1.1
Content-Length: 21
Content-Type: application/json
user-agent: Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/91.0.4464.5 Safari/537.36

{"phone":"123456789"}
---> END HTTP (21-byte body)
] has response [
<--- UNKNOWN 200 (411ms)
cache-control: no-cache
cf-cache-status: DYNAMIC
cf-ray: 73047b41ffd2fa4c-AMS
content-type: application/json
date: Mon, 25 Jul 2022 11:16:06 GMT
expect-ct: max-age=604800, report-uri="https://report-uri.cloudflare.com/cdn-cgi/beacon/expect-ct"
feature-policy: accelerometer 'none'; camera 'none'; geolocation 'none'; gyroscope 'none'; magnetometer 'none'; microphone 'none'; payment *; usb 'none'
referrer-policy: strict-origin-when-cross-origin
server: cloudflare
set-cookie: ACCESS_TOKEN=eyJhboft6rzD6Be16dXY5lgQNCzOZNFe4ra_NDIdmXlXi19hlvaQ; Max-Age=1800; Domain=.example.com; Path=/; Secure; SameSite=None
strict-transport-security: max-age=31536000
x-content-type-options: nosniff
x-frame-options: sameorigin
x-xss-protection: 1; mode=block

{"status":{"code":"OK","message":"OK"},"body":{"id":"20826"}}
<--- END HTTP (61-byte body)
]

Как начать использовать новый логгер

1) подключить зависимость в свой проект

<dependency>
    <groupId>me.bvn13.openfeign.logger</groupId>
    <artifactId>feign-normalized-logger</artifactId>
    <version>0.1.3</version>
</dependency>

2) создать конфигурацию для FeignClient

import feign.Logger;

public class MyFeignConfig {
    
    @Bean
    public Logger logger() {
        return new NormalizedFeignLogger();
    }
    
}

3) применить эту конфигурацию в своём клиенте

@FeignClient(name = "auth", configuration = MyFeignConfig.class)
public interface AuthApi {
/*...methods...*/
}

4) включить DEBUG уровень логирования для NormalizedFeignLogger

Для Slf4J + Logback:

logging:
  level:
    me.bvn13.openfeign.logger.NormalizedFeignLogger: DEBUG

5) не забыть указать FULL уровень логирования самого FeignClient

feign:
  client:
    config:
      auth:
        logger-level: FULL

Это авторский перевод статьи

Основной репозиторий кода

Github клон