Стандартный логгер 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
Комментарии (4)
Xobotun
26.07.2022 18:58+1А как реализовано собирание денормализованного вывода в общий кусок, если в двух словах? Я полагаю, что на запрос-ответ в оперативке создаётся объект с каким-нибудь
List<String>
с последующимjoining('\n')
?Кстати, вопрос немного рядом с темой, но оффтопик: а чем какой-нибудь trace-id в MDC положить было не выход? По Ctrl+F замечательно ищется в текстовом файле. Но да, тут статья про сам факт нормализованного логгера, а не про поиск решения, как бы ответ и запрос в многороточности найти. :)
bvn13 Автор
27.07.2022 10:51Код открыт - можете посмотреть на реализацию
в оперативке создаётся объект с каким-нибудь
List<String>
с последующимjoining('\n')
Верно.
Такой вывод связан с тем, что у команды мониторинга есть определённые проблемы - они не могут в случае ошибок обращаться к другим логам (делать какой-либо поиск). Лог запроса и ответа должен быть в одной строке.
aol-nnov
А как с производительностью? Сравнивалось, насколько "Нормализованный логгер" медленнее "Старого плохого логгера"?
Ведь, наверняка, старый так был сделан не просто так...
bvn13 Автор
Ещё не сравнивалось. Положу в ближайшие задачи.