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

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

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

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

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

@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

Согласно концепции 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-медиа для ИТ-специалистов. Делитесь личными историями про решение самых разных ИТ-задач и получайте вознаграждение.

---

Другие статьи по теме

#Разработка

Автоматизация типовых задач в таск-трекере: инструкция по применению
Как найти процессы для автоматизации в любой отрасли, какие выгоды это принесет компании и как не ошибиться

Перевели крупный холдинг с монолита на микросервисы и сразу увидели улучшения
Микросервисы — это дороже, дольше и сложнее, чем монолит, но позволяет бизнесу достичь нужных показателей

Провели автоматизацию бизнес-процессов сети химчисток: от склада и пунктов приема до колл-центра и службы доставки
Расскажу, как федеральная сеть химчисток вышла на новый уровень работы после автоматизации бизнес-процессов

Как пересобрать сложную разработку в облачное решение и начать работу с малым и средним бизнесом
Мы переделали кастомный логистический продукт в облачное SaaS-решение «Курьерика» и привлекли сотни клиентов.