Spring Boot, AspectJ. Введение в аспектно-ориентированное программирование

Привет, меня зовут Николай Пискунов, я руководитель направления Big Data и автор медиа вАЙТИ. Недавно мне в руки попался старый проект, написанный на Spring Boot. В нем я нашел пару десятков эндпоинтов, в которых метод обрамлен logger. Логирование в таком виде — это важный элемент как для ПО, так и для безопасности, но оно делает код объемнее, его становится сложнее читать.

В идеальном случае методы можно сократить буквально до пары строк, но для этого нужно отделить бизнес-логику от остального кода. Сделать это можно с помощью аспектно-ориентированного программирования (AOP) — языка для определения именованного аспекта. О нем и пойдет речь в этой статье.

Spring Boot, AspectJ. Введение в аспектно-ориентированное программирование

Для начала приведу пример кода, о котором говорил выше:

@PostMapping("/employees") Employee newEmployee(@RequestBody Employee newEmployee) { if (logger.isDebugEnabled()) { logger.debug("call /employees - add new employee - {}", newEmployee); } else { logger.info("call /employees - add new employee"); } Employee saved = repository.save(newEmployee); if (logger.isDebugEnabled()) { logger.debug("call /employees - new employee saved - {}", saved; } else { logger.info("call /employees - new employee saved"); } return saved; }

Как видно, код сложно воспринимается и как минимум занимает много места на экране. В нем явно нарушен один из основных принципов программирования — DRY (Don’t Repeat Yourself). Эта аббревиатура так и переводится: «Не повторяйся». Она призывает не повторять одинаковые фрагменты программы в нескольких местах. Вместо этого нужно абстрагировать повторяющиеся блоки и использовать их несколько раз через общую функцию или метод. Это делает код более чистым, легким для поддержки и уменьшает вероятность ошибок. DRY помогает сделать код более модульным и упрощает внесение изменений в приложение.

Но надо отдать должное, в последних добавленных эндпоинтах разработчик попытался работать по принципу DRY. Он создал абстракцию, которая принимала в себя текст сообщения и в зависимости от того, включен дебаг или нет, выводила соответствующее сообщение в лог. Код последних методов стал намного чище:

@PostMapping("/job") Job newJob(@RequestBody Jon newJob) { toLog("call /employees - add new job", newJob); Job saved = repository.save(newJob); toLog("call /employees - new job saved", saved); return saved; }

Хотя принцип DRY даже в этом случае отчасти нарушен. И хотелось бы сократить метод до одной строчки, где это возможно:

@PostMapping("/job") Job newJob(@RequestBody Jon newJob) { return repository.save(newJob); }

Здесь нам поможет AOP, которое сделает код более чистым, модульным и гибким. Аспектно-ориентированное программирование позволяет разделить повторяющийся код на аспекты (например, логирование, аудит или безопасность) и применять их ко множеству классов с помощью простого указания имени. В Java для этого используется библиотека AspectJ. Она добавляет в Java возможность использования концепции обертки и прокси, что упрощает рефакторинг и улучшение существующего кода.

Согласно концепции AOP, мы продумаем архитектуру нашего логирования.

1. Аспект — это модульная часть кода, она определяет повторяющуюся логику, которую можно применить ко множеству классов. Как мы выяснили выше, в нашем случае это вывод записей в лог.

Чтобы создать аспект в Spring Boot, достаточно создать новый класс и пометить его аннотациями — это особый тип интерфейсов, которые определяют, когда и как аспект должен быть применен к коду. Аннотации содержат ключевые слова, которые указывают на то, что они должны быть связаны с определенными методами или классами. В нашем случае нужно указать @Aspect и @Component:

@Aspect @Component public class RestLoggingAspect { }

2. Перехват — это механизм для внедрения аспекта в целевой класс или метод. Он предоставляет возможность изменять вызовы и возвраты от этих методов. Чтобы Java поняла, с реализацией какого метода мы хотим поработать, данный метод следует пометить нужной нам аннотацией, например @PostMapping.

Реализуем собственную аннотацию:

/** * Помечать только рест-запросы и рест-фильтры */ @Retention(RetentionPolicy.RUNTIME) @Target({ElementType.METHOD}) public @interface RestLogging { }

3. Ключевые слова — это специальные строки, которые определяют, когда аспект должен быть применен к коду. Грубо говоря, это те же аннотации, которые применяются к методам внутри аспекта. Благодаря им Java понимает, когда применить функционал обертки.

В классическом AspectJ методы класса-аспекта могут быть помечены следующими аннотациями:

@Before — определяет, что аспект должен быть применен перед вызовом оригинального метода.

@Before("execution(* main(..))") public void logCall() { // do something before the method }

@After — определяет, что аспект должен быть применен после возврата от оригинального метода.

@After("execution(* main(..))") public void logReturn() { // do something after the method }

@Around — аспект должен быть применен вокруг вызова и возврата от оригинального метода.

@Around("execution(* main(..))") public void logCall() throws Throwable { // do something before the method proceed(); // do something after the method }

Для решения нашей задачи подойдет как раз @Around. Создадим метод, который обогатит эндпоинты логированием:

public class RestLoggingAspect { @Around("@annotation(RestLogging)") public Object profileAllMethods(ProceedingJoinPoint proceedingJoinPoint) throws Throwable { } }

В нашем коде Java будет искать все методы, помеченные аннотацией RestLogging (@annotation(RestLogging)), и записывать в лог.

4. Обертка — это способ добавить дополнительную логику, чтобы модифицировать вызовы методов и возвратов от них, не меняя исходный код. Обертки используются для замены вызовов и возвратов на основе определенных критериев, добавления или изменения до или после оригинального метода.

В первом приближении аспект у меня получился следующий:

@Slf4j @Aspect @Component @RequiredArgsConstructor public class RestLoggingAspect { private static final String X_REQUEST_ID_HEADER = "x-request-id"; /* Согласованные тексты логов */ private static final String PROCESS_START_LOGGER_PATTERN = "[{}] {}.{}.{} started. {} request to url {} "; private static final String PROCESS_START_WITH_BODY_LOGGER_PATTERN = "[{}] {}.{}.{} started. {} request to url {}. {}"; private static final String PROCESS_END_LOGGER_PATTERN = "[{}] {}.{}.{} completed. {} request to url {}nExecution time :: {} ms"; private static final String PROCESS_END_WITH_BODY_LOGGER_PATTERN = "[{}] {}.{}.{} completed. {} request to url {}. {}nExecution time :: {} ms"; @Value("${spring.application.name}") private String appName; private final RequestScopeObject requestScopeObject; @Around("@annotation(RestLogging)") public Object toLog(ProceedingJoinPoint proceedingJoinPoint) throws Throwable { /* Выполняется ДО кода метода, помеченного аннотацией RestLogging */ MethodSignature methodSignature = (MethodSignature) proceedingJoinPoint.getSignature(); ObjectMapper mapper = new ObjectMapper(); String className = methodSignature.getDeclaringType().getSimpleName(); String methodName = methodSignature.getName(); HttpServletRequest request = ((ServletRequestAttributes) Objects.requireNonNull(RequestContextHolder .getRequestAttributes())) .getRequest(); if (StringUtils.isBlank(requestScopeObject.getRequestId())) { String requestId = request.getHeader(X_REQUEST_ID_HEADER); if (StringUtils.isBlank(requestId)) { requestId = UUID.randomUUID().toString().toUpperCase().replace("-", ""); } requestScopeObject.setRequestId(requestId); } if (StringUtils.isBlank(requestScopeObject.getOperationId())) { String operationId = UUID.randomUUID().toString().toUpperCase(); requestScopeObject.setOperationId(operationId); } String rqUrl = Optional.ofNullable(request.getQueryString()).isPresent() ? request.getRequestURL().toString() + "?" + request.getQueryString() : request.getRequestURL().toString(); if (!LOGGER.isDebugEnabled()) { LOGGER.info(PROCESS_START_LOGGER_PATTERN, requestScopeObject.getRequestId(), appName, className, methodName, request.getMethod(), rqUrl); } else { if (!"DELETE".equalsIgnoreCase(request.getMethod())) { JsonNode node = mapper.valueToTree(proceedingJoinPoint.getArgs()); LOGGER.debug(PROCESS_START_WITH_BODY_LOGGER_PATTERN, requestScopeObject.getRequestId(), appName, className, methodName, request.getMethod(), rqUrl, node.toPrettyString()); } else { LOGGER.debug(PROCESS_START_LOGGER_PATTERN, requestScopeObject.getRequestId(), appName, className, methodName, request.getMethod(), rqUrl); } } final StopWatch stopWatch = new StopWatch(); stopWatch.start(); /* Выполняем код метода, помеченного аннотацией RestLogging. Результат метода записываем в переменную result */ Object result = proceedingJoinPoint.proceed(); /* Выполняется ПОСЛЕ кода метода, помеченного аннотацией RestLogging */ stopWatch.stop(); if (!LOGGER.isDebugEnabled()) { LOGGER.info(PROCESS_END_LOGGER_PATTERN, requestScopeObject.getRequestId(), appName, className, methodName, request.getMethod(), rqUrl, stopWatch.getTotalTimeMillis()); } else { if (!"DELETE".equalsIgnoreCase(request.getMethod()) && Objects.nonNull(result)) { LOGGER.debug(PROCESS_END_WITH_BODY_LOGGER_PATTERN, requestScopeObject.getRequestId(), appName, className, methodName, request.getMethod(), rqUrl, mapper.valueToTree(result).toPrettyString(), stopWatch.getTotalTimeMillis()); } else { LOGGER.debug(PROCESS_END_LOGGER_PATTERN, requestScopeObject.getRequestId(), appName, className, methodName, request.getMethod(), rqUrl, stopWatch.getTotalTimeMillis()); } } return result; } }

Этот аспект используется для оборачивания логированием методов, помеченных аннотацией @RestLogging. Для сериализации объектов в JSON используется библиотека Jackson.

С помощью аннотации @Around я определил точку присоединения, которая вызывает метод toLog перед и после любого метода, помеченного аннотацией @RestLogging.

Запрос и ответ я добавлял в дебаг-логи в виде JSON с помощью библиотеки Jackson, в частности класса JsonNode. Также я использую класс StopWatch из Spring Framework для отслеживания времени выполнения метода.

И так как ранее были определены request id в отдельном классе, я решил эти данные вынести в контекст спринга в RequestScope, для того чтобы иметь доступ к ним в рамках запроса из любой точки приложения.

@Configuration public class CommonConfig { @Bean @RequestScope public RequestScopeObject requestScopedBean() { return new RequestScopeObject(); } }

@Getter @Setter @RequiredArgsConstructor public class RequestScopeObject extends ScopeObject { } @Getter @Setter @FieldDefaults(level = AccessLevel.PRIVATE) public abstract class ScopeObject { String requestId; String operationId; }

Теперь, чтобы однотипно логировать любой эндпоинт, достаточно добавить одну аннотацию:

@RestLogging @PostMapping("/job") Job newJob(@RequestBody Jon newJob) { return repository.save(newJob); }

В качестве дальнейших шагов можно выводить время выполнения методов в Grafana, а также нужно отрефакторить сам аспект, чтобы было проще читать не только код методов, которые его оборачивают, но и код самого аспекта =)

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

В следующей статье я расскажу, как еще можно решить данную проблему с помощью фильтров.

вАЙТИ — DIY-медиа для ИТ-специалистов.
Делитесь личными историями про решение самых разных ИТ-задач и получайте вознаграждение.

Spring Boot, AspectJ. Введение в аспектно-ориентированное программирование

Что такое аспектно-ориентированное программирование

Как написать собственный аспект по принципам AOP

Пример аспекта для логирования методов