Привет, меня зовут Николай Пискунов, я руководитель направления 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-решение «Курьерика» и привлекли сотни клиентов.