Введение
При разработке корпоративных приложений на Spring Boot одной из важнейших задач является организация качественного логирования. Особенно критичным это становится при работе с микросервисной архитектурой, где необходимо отслеживать как входящие HTTP-запросы, так и исходящие вызовы к внешним сервисам.
Мы реализовали универсальное решение для логирования на базе Spring AOP, которое:
-
Автоматически логирует входящие HTTP-запросы в контроллерах
-
Отслеживает исходящие запросы через WebClient
-
Позволяет гибко управлять видимостью чувствительных данных через аннотации
-
Поддерживает автоматическое отключение маскирования в зависимости от уровня логирования
Почему решили искать решение по логированию
В наших проектах на ранних этапах разработки логирование жило своей жизнью в каждом сервисе — кто-то навешивал фильтры, кто-то вручную log.info() в каждом методе контроллера, кто-то забывал залогировать важную информацию. В итоге формат логов разный, где-то персональные данные светятся в открытую, потому что разработчик забыл про маскирование, а если подключили руками маскирование то чтобы включить детальное логирование на проде надо перевыкатывать половину инфраструктуры при том, что логика логирования размазана по всем модулям
Нужно было решение, которое работает из коробки и которое будет:
-
Автоматически логировать все HTTP взаимодействия
-
Маскировать чувствительные данные
-
Позволять безопасно включать детальное логирование при отладке
Что получилось
Сделали два аспекта и пачку аннотаций. Первый аспект оборачивает методы контроллеров, второй — методы клиентов с WebClient. Для чувствительных данных отдельная аннотация на поля моделей, которая сама понимает, когда маскировать, а когда показывать.
Наше решение состоит из нескольких компонентов:
Логирование контроллеров
Вешаешь аннотацию на метод — он логирует запрос и ответ. Можно скрыть тело запроса (пароли, токены и файлы), можно добавить логирование конкретных заголовки.
@Retention(RetentionPolicy.RUNTIME)@Target({ElementType.METHOD})public @interface ControllerMonitoring { String value(); boolean ignoreRequestBody() default false; String ignoreRequestReplacement() default "ignored"; boolean ignoreResponseBody() default false; String ignoreResponseReplacement() default "ignored"; String[] headers() default {};}
В контроллере это выглядит так:
@RestController@RequestMapping("/api/users")public class UserController { @PostMapping @ControllerMonitoring(value = "Создание пользователя", headers = {"X-Request-ID", "User-Agent"}) public ResponseEntity<UserResponse> createUser(@RequestBody UserRequest request) { return ResponseEntity.ok(response); } @PostMapping("/login") @ControllerMonitoring(value = "Авторизация", ignoreRequestBody = true) public ResponseEntity<TokenResponse> login(@RequestBody LoginRequest request) { return ResponseEntity.ok(token); }}
Для login тело запроса в лог не попадёт, вместо него будет “ignored”. Для createUser дополнительно запишутся заголовки X-Request-ID и User-Agent.
Сам аспект:
@Aspectpublic class ControllerMonitoringAspect { private static final Logger LOGGER = LoggerFactory.getLogger(ControllerMonitoringAspect.class); @Pointcut("@annotation(ControllerMonitoring)") public void controllerMonitoring() { } @Around("controllerMonitoring()") public Object logMonitoring(ProceedingJoinPoint joinPoint) throws Throwable { HttpServletRequest request = ((ServletRequestAttributes) RequestContextHolder.currentRequestAttributes()).getRequest(); String login = getLogin(); // Зависит от реализации авторизации request.setAttribute("startTime", System.currentTimeMillis()); storeEventName(joinPoint); logRequest(request, joinPoint, login); Object result = joinPoint.proceed(); logResponse(request, result, joinPoint); return result; } private void logRequest(HttpServletRequest request, ProceedingJoinPoint joinPoint, String login) { MethodSignature signature = (MethodSignature) joinPoint.getSignature(); ControllerMonitoring annotation = signature.getMethod().getAnnotation(ControllerMonitoring.class); try { Object body = annotation.ignoreRequestBody() ? annotation.ignoreRequestReplacement() : extractRequestBody(joinPoint); Log log = Log.event(annotation.value() + " (Request)") .with("method", request.getMethod()) .with("path", request.getRequestURI()) .with("params", request.getQueryString()) .with("body", JsonUtils.getJsonObject(body)) .with("login", login); logHeaders(request, annotation, log); LOGGER.info(log.toString()); } catch (Exception e) { LOGGER.error("Ошибка при логировании запроса", e); } } private void logHeaders(HttpServletRequest request, ControllerMonitoring annotation, Log log) { String[] headersToLog = annotation.headers(); for (String headerName : headersToLog) { String headerValue = request.getHeader(headerName); if (headerValue != null) { log.with("header." + headerName, headerValue); } else { LOGGER.warn("Заголовок '{}' не найден", headerName); } } } private void logResponse(HttpServletRequest request, Object result, ProceedingJoinPoint joinPoint) { MethodSignature signature = (MethodSignature) joinPoint.getSignature(); ControllerMonitoring annotation = signature.getMethod().getAnnotation(ControllerMonitoring.class); try { HttpStatus status = HttpStatus.OK; Object body = result; if (result instanceof ResponseEntity<?> response) { status = HttpStatus.valueOf(response.getStatusCode().value()); body = annotation.ignoreResponseBody() ? annotation.ignoreResponseReplacement() : response.getBody(); } long duration = System.currentTimeMillis() - (Long) request.getAttribute("startTime"); LOGGER.info(Log.event(annotation.value() + " (Response)") .with("status", status.value()) .with("body", JsonUtils.getJsonObject(body)) .with("duration", duration) .toString()); } catch (Exception e) { LOGGER.error("Ошибка при логировании ответа", e); } } private void storeEventName(ProceedingJoinPoint joinPoint) { MethodSignature signature = (MethodSignature) joinPoint.getSignature(); LoggerUtils.addEventAttribute(signature.getMethod().getAnnotation(ControllerMonitoring.class).value()); } private Object extractRequestBody(ProceedingJoinPoint joinPoint) { MethodSignature signature = (MethodSignature) joinPoint.getSignature(); Parameter[] parameters = signature.getMethod().getParameters(); for (int i = 0; i < parameters.length; i++) { if (parameters[i].isAnnotationPresent(RequestBody.class)) { return joinPoint.getArgs()[i]; } } return null; }}
Примеры лога:
Request на создание пользователя — с заголовками:
{ "event": "Создание пользователя (Request)", "method": "POST", "path": "/api/users", "params": "", "body": { "username": "user1", "email": "example@example.com" }, "login": "user1", "header.X-Request-ID": "a1b2c3d4-e5f6-7890", "header.User-Agent": "Mozilla/5.0 (Windows NT 10.0; Win64; x64)"}
Ответ на создание:
{ "event": "Создание пользователя (Response)", "status": 200, "body": { "id": 12345, "username": "user1", "email": "example@example.com" }, "duration": 345}
Запрос на логин — тело скрыто:
{ "event": "Авторизация (Request)", "method": "POST", "path": "/api/users/login", "params": "", "body": "ignored", "login": "admin"}
Имена заголовков в HTTP case-insensitive, и getHeader() их обрабатывает независимо от регистра
Логирование клиентских запросов
В наших сервисах WebClient дёргает соседние микросервисы, и хочется видеть — кто, куда и с какими параметрами пошёл.
Аннотация:
@Retention(RetentionPolicy.RUNTIME)@Target({ElementType.METHOD})public @interface ClientRequestMonitoring { String value() default "";}
В клиенте:
@Componentpublic class UserServiceClient { private final WebClient webClient; @ClientRequestMonitoring("Получение информации о пользователе") public Mono<UserInfo> getUserInfo(String userId) { return webClient.get() .uri("/users/{id}", userId) .retrieve() .bodyToMono(UserInfo.class); }}
Аспект для криентов:
@Aspectpublic class ClientRequestMonitoringAspect { private static final Logger LOGGER = LoggerFactory.getLogger(ClientRequestMonitoringAspect.class); @Pointcut("@annotation(ClientRequestMonitoring)") public void clientRequestMonitoring() { } @Around("clientRequestMonitoring()") public Object logMonitoring(ProceedingJoinPoint joinPoint) throws Throwable { storeEventInContext(joinPoint); logRequest(joinPoint); return joinPoint.proceed(); } private void logRequest(ProceedingJoinPoint joinPoint) { MethodSignature signature = (MethodSignature) joinPoint.getSignature(); Method method = signature.getMethod(); Object[] args = joinPoint.getArgs(); try { String event = getEventName(joinPoint); Log log = Log.event(event + " (Request)"); if (args.length > 0) { Parameter[] parameters = method.getParameters(); for (int i = 0; i < parameters.length; i++) { log.with(parameters[i].getName(), JsonUtils.getJsonObject(args[i])); } } LOGGER.info(log.toString()); } catch (Exception e) { LOGGER.error("Ошибка при логировании клиентского запроса", e); } } private String getEventName(JoinPoint joinPoint) { MethodSignature signature = (MethodSignature) joinPoint.getSignature(); Method method = signature.getMethod(); String clientName = "[" + method.getDeclaringClass().getSimpleName() + "] "; return clientName + method.getAnnotation(ClientRequestMonitoring.class).value(); } private void storeEventInContext(ProceedingJoinPoint joinPoint) { String clientEvent = getEventName(joinPoint); LoggerUtils.addClientEventAttribute(clientEvent); }}
Пример лога:
{ "event": "[UserServiceClient] Обновление токена (Request)", "userId": "12345"}
Ответ логируется отдельно через ExchangeFilterFunction в конфиге WebClient, аспект тут не поможет.
Прокидывание контекста
Чтобы события из аспектов были доступны за их пределами (например в @RestControllerAdvice, кастомных обработчиках исключений, да и просто в реактивных цепочках), нужно добавить утилитный класс:
public class LoggerUtils { public static final String CLIENT_EVENT = "client_event"; public static final String EVENT = "event"; public static void addClientEventAttribute(Object value) { if (RequestContextHolder.getRequestAttributes() == null) { return; } RequestContextHolder.currentRequestAttributes() .setAttribute(CLIENT_EVENT, value, RequestAttributes.SCOPE_REQUEST); } public static String getClientEventAttribute() { RequestAttributes requestAttributes = RequestContextHolder.getRequestAttributes(); if (requestAttributes != null) { return (String) requestAttributes.getAttribute(CLIENT_EVENT, RequestAttributes.SCOPE_REQUEST); } else { return StringUtils.EMPTY; } } public static void addEventAttribute(Object value) { RequestContextHolder.currentRequestAttributes() .setAttribute(EVENT, value, RequestAttributes.SCOPE_REQUEST); } public static String getEventAttribute() { return (String) RequestContextHolder.currentRequestAttributes() .getAttribute(EVENT, RequestAttributes.SCOPE_REQUEST); }}
Для реактивных потоков дополнительно настраиваем ThreadLocalAccessor, чтобы контекст не терялся при переключении потоков.
Маскирование чувствительных данных
Поля моделей могут содержать персональные данные. Хочется, чтобы на проде они маскировались, а при отладке или на деве — показывались. При этом без передеплоя приложения.
Сделали аннотацию, с помощью которой проверяется уровень логирования:
@Target(ElementType.FIELD)@Retention(RetentionPolicy.RUNTIME)public @interface IgnoreLogging { String replacement() default "ignored"; LogLevel showAtLevel() default LogLevel.DEBUG; enum LogLevel { TRACE, DEBUG, INFO, WARN, ERROR }}
Использование в модели выглядит так:
public class UserRequest { private String username; @IgnoreLogging private String password; @IgnoreLogging(replacement = "****") private String creditCard; @IgnoreLogging(showAtLevel = LogLevel.TRACE) private String secretAnswer;}
На уровне INFO все чувствительные поля скрыты, подняли до DEBUG пароль и номер карты видны, подняли до TRACE теперь вообще всё видно. Меняем application.yaml/‘application.properties’ и никакого редеплоя.
Под капотом это работает через кастомный Jackson BeanSerializerModifier:
public class IgnoreLoggingSerializerModifier extends BeanSerializerModifier { private static final Logger logger = LoggerFactory.getLogger(Logger.ROOT_LOGGER_NAME); @Override public List<BeanPropertyWriter> changeProperties( SerializationConfig config, BeanDescription beanDesc, List<BeanPropertyWriter> beanProperties) { for (int i = 0; i < beanProperties.size(); i++) { BeanPropertyWriter writer = beanProperties.get(i); IgnoreLogging annotation = writer.getAnnotation(IgnoreLogging.class); if (annotation != null) { beanProperties.set(i, new IgnoredValueWriter(writer, annotation)); } } return beanProperties; } private static class IgnoredValueWriter extends BeanPropertyWriter { private final IgnoreLogging annotation; public IgnoredValueWriter(BeanPropertyWriter base, IgnoreLogging annotation) { super(base); this.annotation = annotation; } @Override public void serializeAsField(Object bean, JsonGenerator gen, SerializerProvider prov) throws Exception { if (shouldUnmask()) { super.serializeAsField(bean, gen, prov); } else { gen.writeFieldName(_name); gen.writeString(annotation.replacement()); } } private boolean shouldUnmask() { IgnoreLogging.LogLevel showLevel = annotation.showAtLevel(); return switch (showLevel) { case TRACE -> logger.isTraceEnabled(); case DEBUG -> logger.isDebugEnabled(); case INFO -> logger.isInfoEnabled(); case WARN -> logger.isWarnEnabled(); case ERROR -> logger.isErrorEnabled(); }; } }}
Логика простая: для каждого поля с @IgnoreLogging смотрим, включён ли пороговый уровень. Включён — показываем реальное значение, нет — пишем replacement.
ObjectMapper для логирования свой собственный, основной маппер REST API не трогаем. Маскирование привязано к общему уровню логирования приложения (root logger), можно сделать логгер, привязанный к конкретному конфигу, но тогда в пропертях нужно будет устанавливать уровень именно ему.
public class JsonUtils { private static final ObjectWriter objectWriter; static { ObjectMapper mapper = new ObjectMapper() .registerModule(new JavaTimeModule()) .disable(SerializationFeature.FAIL_ON_EMPTY_BEANS); SimpleModule ignoreLoggingModule = new SimpleModule("IgnoreLoggingModule"); ignoreLoggingModule.setSerializerModifier(new IgnoreLoggingSerializerModifier()); mapper.registerModule(ignoreLoggingModule); objectWriter = mapper.writerWithDefaultPrettyPrinter(); } public static String getJsonObject(Object object) { try { return objectWriter.writeValueAsString(object); } catch (JsonProcessingException e) { return "Ошибка при формировании JSON: " + e.getMessage(); } }}
Подключение модулей
Для контроллеров — конфиг и аннотация импорт:
public class ControllerMonitoringConfig { @Bean public ControllerMonitoringAspect controllerMonitoringAspect() { return new ControllerMonitoringAspect(); }}@Target(ElementType.TYPE)@Retention(RetentionPolicy.RUNTIME)@Import(ControllerMonitoringConfig.class)public @interface EnableControllerMonitoring {}
Вешаем аспекты на класс, помеченный аннотацией @SpringBootApplication (или на любой конфигурационный класс):
@SpringBootApplication@EnableControllerMonitoringpublic class Application {}
Для клиентов — то же самое, плюс настройка реактивного контекста:
public class ClientRequestMonitoringConfig { @Bean public ClientRequestMonitoringAspect clientRequestMonitoring() { return new ClientRequestMonitoringAspect(); } @PostConstruct public void configureReactorContext() { Hooks.enableAutomaticContextPropagation(); ContextRegistry.getInstance().registerThreadLocalAccessor( LoggerUtils.CLIENT_EVENT, LoggerUtils::getClientEventAttribute, object -> {}, () -> {} ); }}@Target(ElementType.TYPE)@Retention(RetentionPolicy.RUNTIME)@Import(ClientRequestMonitoringConfig.class)public @interface EnableClientRequestMonitoring {}
Без настройки реактора контекст будет теряться при переключении потоков и в логах ответа вы не увидите имя события.
Тестирование
Аспекты тестируются с поднятием Spring Context:
@SpringBootTest@EnableAspectJAutoProxyclass ControllerMonitoringAspectTest { @Test void shouldMaskSensitiveData() { UserRequest request = new UserRequest(); request.setPassword("secret123"); String json = JsonUtils.getJsonObject(request); assertThat(json).contains("\"password\":\"ignored\""); assertThat(json).doesNotContain("secret123"); }}
Результаты
Решение работает, но без нюансов не обошлось, также отмечу, что оно не является окончательным, а является лишь описанием примера своей реализации системы логирования. То о чем стоит подумать при использовании и по возможности оптимизировать:
Перформанс
Каждый запрос проходит сериализацию в JSON. На средних нагрузках незаметно, но если у вас высоконагруженный сервис с жёсткими SLA синхронное логирование начнёт занимать заметное время.
Можно вынести логирование в отдельный поток, чтобы не тормозить основной:
@Aspectpublic class AsyncControllerMonitoringAspect { private final Executor logExecutor = Executors.newFixedThreadPool(POOL_SIZE); @Around("controllerMonitoring()") public Object logMonitoring(ProceedingJoinPoint joinPoint) throws Throwable { CompletableFuture.runAsync(() -> logRequest(...), logExecutor); Object result = joinPoint.proceed(); CompletableFuture.runAsync(() -> logResponse(...), logExecutor); return result; }}
Задержка снижается, логирование не блокирует обработку запроса. Но есть и обратная сторона: при аварийном завершении приложения логи из очереди потока просто пропадут. Плюс с отладкой асинхронщины могут быть проблемы. Асинхронное логирование стоит вкручивать если у вас требование ко времени ответа < 100мс или очень высокая нагрузка на инстанс.
Большие payload
Если в ответе приходит список на 10к элементов JsonUtils.getJsonObject() сильно начнет использовать ресурсы. Логично добавить обрезание: либо первые N элементов массива, либо только размер коллекции, при возможности полного отображения лога при изменения уровня логирования.
Реактивные потоки (контекст)
Реактор переключает потоки, контекст теряется, и в логах ответа вместо имени события будет пустота. Лечится Hooks.enableAutomaticContextPropagation() и регистрацией ThreadLocalAccessor. Про это легко забыть при первоначальной настройке.
Человеческий фактор
Каждый новый эндпоинт надо аннотировать руками. Если забыть то метод молча не логируется. Аннотацию @IgnoreLogging надо не забыть повесить на новое чувствительное поле. IDE не подскажет, компилятор не ругнётся. Решается ArchUnit тестом, который проверяет, что все методы @RestController имеют @ControllerMonitoring. На уровне полей сложнее, тут только код ревью.
Логирование под высокой нагрузкой и Circuit Breaker
Ещё одна проблема — когда логирование само становится проблемой. При серьёзных нагрузках ошибки записи в лог (диск упёрся, буфер переполнен) могут положить весь сервис. Чтобы такого не случилось, можно добавить Circuit Breaker, который при серии ошибок просто отрубает логирование до нормализации:
@Componentpublic class LoggingCircuitBreaker { private final AtomicInteger errorCount = new AtomicInteger(0); private volatile boolean enabled = true; public boolean canLog() { return enabled && errorCount.get() < MAX_ERRORS; } public void recordError() { if (errorCount.incrementAndGet() >= MAX_ERRORS) { enabled = false; } }}
Основной функционал не страдает, каскадного сбоя нет. Минус в том, что можно не заметить отвалившиеся логи и пропустить важные события.
Итого
После внедрения в наших сервисах:
-
Логи во всех сервисах в едином формате, цепочка запроса прослеживается от входа до выхода
-
Пароли-токены не светятся — на проде
INFO, если нужно смотреть — ставимDEBUG, всё автоматически показывается -
Добавление логирования на новый метод — одна аннотация, не надо много копипастить
-
Централизованно поменять формат — правим аспект, и все контроллеры подхватывают
Для типового микросервиса на Spring Boot — отличный вариант. Если у вас высокая нагрузка и каждый миллисекунд на счету — смотрите в сторону асинхронного логирования с буферизацией, но там свои проблемы.
Ссылки
ссылка на оригинал статьи https://habr.com/ru/articles/1076956/