Что такое аспектно-ориентированное программирование
Для начала приведу пример кода, о котором говорил выше:
@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, будут покрыты логами, а также можно будет увидеть время выполнения определенного метода, что упростит профилирование приложения на проде.
В следующей статье я расскажу, как еще можно решить данную проблему с помощью фильтров.
