Стандартизация журналов из Java-приложения с помощью Spring AOP

В корпоративных приложениях очень часто мы помещаем журналы в методы, которые мы создаем, чтобы, например, указать:

Входные параметры
Время выполнения
Возврат метода

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

В качестве примера, в дидактических целях, мы продемонстрируем простой API, который возвращает сообщение вместе с именем, переданным в качестве параметра.

Посмотрите на приведенный ниже код:

@RestController
@RequestMapping("/api/v1")
@Slf4j
public class SpringAopExampleController {

    private final SpringAopExampleService service;

    @Autowired
    public SpringAopExampleController(SpringAopExampleService service) {
        this.service = service;
    }

    @GetMapping("/messages/users/{username}")
    public ResponseEntity<String> getMessage(@PathVariable String username){
        long startTime = System.currentTimeMillis();
        log.info("m=getMessage; c=SpringAopExampleController; username={}", username);

        String messageToReturn = service.getMessage(username);

        long endTime = System.currentTimeMillis();
        log.info("received message: {}; response time in milliseconds: {}", messageToReturn, (endTime - startTime));
        return ResponseEntity.ok(messageToReturn);
    }
}

Войдите в полноэкранный режим Выход из полноэкранного режима

@Service
@Slf4j
public class SpringAopExampleService {

    public String getMessage(String username){
        long startTime = System.currentTimeMillis();
        log.info("m=getMessage; c=SpringAopExampleService; username={}", username);

        String generatedMessage = "Hello World " + username + " from Spring AOP!";

        long endTime = System.currentTimeMillis();
        log.info("received message: {}; response time in milliseconds: {}", generatedMessage, (endTime - startTime));
        return generatedMessage;
    }
}

Войдите в полноэкранный режим Выход из полноэкранного режима

Ниже приведен выходной журнал выполнения API:

2022-05-05 14:49:02.583  INFO 21319 --- [nio-8080-exec-2] c.e.s.a.c.SpringAopExampleController     : m=getMessage; c=SpringAopExampleController; username=Victor
2022-05-05 14:49:02.583  INFO 21319 --- [nio-8080-exec-2] c.e.s.a.service.SpringAopExampleService  : m=getMessage; c=SpringAopExampleService; username=Victor
2022-05-05 14:49:02.584  INFO 21319 --- [nio-8080-exec-2] c.e.s.a.service.SpringAopExampleService  : received message: Hello World Victor from Spring AOP!; response time in milliseconds: 1
2022-05-05 14:49:02.584  INFO 21319 --- [nio-8080-exec-2] c.e.s.a.c.SpringAopExampleController     : received message: Hello World Victor from Spring AOP!; response time in milliseconds: 1

Войдите в полноэкранный режим Выход из полноэкранного режима

Обратите внимание, как трудно читать код

Сначала мы фиксируем начало потока;
Затем мы регистрируем имя метода, имя класса и параметры;
Мы вызываем службу для хранения сообщения, которое будет возвращено;
Мы фиксируем конец потока;
Мы регистрируем возврат, а также время выполнения в миллисекундах;

То же самое повторяется для класса Service.

Вся эта информация важна, но повторять этот процесс для всех методов непрактично.

Чтобы решить эту проблему, мы можем использовать Spring AOP. С его помощью мы можем автоматизировать повторяющиеся процедуры, которые мы обычно кодируем вручную;

Преимущества использования данного подхода

Избегает избыточности кода: описанный выше процесс ведения журнала больше не повторяется вручную во всех методах, а выполняется в специальном классе Spring для такого использования.
Повторное использование кода: класс, содержащий стандартную структуру журнала, может быть повторно использован в других проектах;
Простота обслуживания: вместо того, чтобы менять шаблон журнала во всех методах, обслуживание или улучшение будет сделано только один раз и будет отражено во всей системе;

Мы можем иметь класс, подобный приведенному ниже, для централизации такого рода журналов:

@Aspect
@Component
@Slf4j
public class SpringAopInterceptor   {

    @Around("execution(* com.example.spring.aop..*.*(..))")
    public Object executionTime(ProceedingJoinPoint point) throws Throwable {
        if(hasParams(point)) {
            log.info("opening method", kv("method", point.getSignature().getName()),
                    kv("class",point.getSignature().getDeclaringTypeName()), "params",
                    kv("method-params", getParamsAndValuesFromMethod(point)));
        }
        else{
            log.info("opening method", kv("method", point.getSignature().getName()),
                    kv("class",point.getSignature().getDeclaringTypeName()));
        }

        long startTime = System.currentTimeMillis();

        Object object = point.proceed();

        long endTime = System.currentTimeMillis();
        log.info("closing method", kv("method", point.getSignature().getName()),
                kv("class",point.getSignature().getDeclaringTypeName()),
                kv("execution-time in milliseconds", endTime-startTime));
        return object;
    }

        @AfterReturning(pointcut = "execution(* com.example.spring.aop..*.*(..))", returning = "result")
    public void logAfter(JoinPoint point, Object result) {
        if(result!=null){
            log.info("method-response", kv("method", point.getSignature().getName()),
                    kv("class", point.getSignature().getDeclaringTypeName()),
                    kv("response", result));
        }
    }

    private Boolean hasParams(ProceedingJoinPoint point){
        if(point.getArgs()!= null && point.getArgs().length != 0){
            MethodSignature methodSignature = (MethodSignature) point.getSignature();
            Map<String, Object> paramsAndValues = new HashMap<>();
            String[] parameterNames = methodSignature.getParameterNames();
            return parameterNames != null;
        }
        else return false;

    }

    private Map<String, Object> getParamsAndValuesFromMethod(ProceedingJoinPoint point){
        MethodSignature methodSignature = (MethodSignature) point.getSignature();
        Map<String, Object> paramsAndValues = new HashMap<>();
        String[] parameterNames = methodSignature.getParameterNames();
        Object[] args = point.getArgs();

        for(int i=0; i<args.length; i++){
            paramsAndValues.put(parameterNames[i], args[i]);
        }

        return paramsAndValues;
    }
}

Войдите в полноэкранный режим Выход из полноэкранного режима

В этой структуре мы используем Logback и Logstash. Поэтому вам нужно создать файл logback.xml и поместить его в папку resources вашего приложения.

ПРИМЕЧАНИЕ: теперь журналы будут в формате JSON. Подробно я расскажу об этом в следующей статье. Пока что просто скопируйте этот xml-файл и включите в него зависимости. Вы можете увидеть все необходимое в исходном коде, который я предоставлю в конце статьи.

Посмотрите, как выглядят журналы:

{"@timestamp":"2022-05-05T15:09:52.346-03:00","@version":"1","message":"opening method","logger_name":"com.example.spring.aop.config.SpringAopInterceptor","thread_name":"http-nio-8080-exec-1","level":"INFO","level_value":20000,"method":"getMessage","class":"com.example.spring.aop.controller.SpringAopExampleController","method-params":{"username":"Victor"}}
{"@timestamp":"2022-05-05T15:09:52.389-03:00","@version":"1","message":"opening method","logger_name":"com.example.spring.aop.config.SpringAopInterceptor","thread_name":"http-nio-8080-exec-1","level":"INFO","level_value":20000,"method":"getMessage","class":"com.example.spring.aop.service.SpringAopExampleService","method-params":{"username":"Victor"}}
{"@timestamp":"2022-05-05T15:09:52.404-03:00","@version":"1","message":"method-response","logger_name":"com.example.spring.aop.config.SpringAopInterceptor","thread_name":"http-nio-8080-exec-1","level":"INFO","level_value":20000,"method":"getMessage","class":"com.example.spring.aop.service.SpringAopExampleService","response":"Hello World Victor from Spring AOP!"}
{"@timestamp":"2022-05-05T15:09:52.404-03:00","@version":"1","message":"closing method","logger_name":"com.example.spring.aop.config.SpringAopInterceptor","thread_name":"http-nio-8080-exec-1","level":"INFO","level_value":20000,"method":"getMessage","class":"com.example.spring.aop.service.SpringAopExampleService","execution-time in milliseconds":15}
{"@timestamp":"2022-05-05T15:09:52.413-03:00","@version":"1","message":"method-response","logger_name":"com.example.spring.aop.config.SpringAopInterceptor","thread_name":"http-nio-8080-exec-1","level":"INFO","level_value":20000,"method":"getMessage","class":"com.example.spring.aop.controller.SpringAopExampleController","response":{"headers":{},"body":"Hello World Victor from Spring AOP!","statusCode":"OK","statusCodeValue":200}}
{"@timestamp":"2022-05-05T15:09:52.473-03:00","@version":"1","message":"closing method","logger_name":"com.example.spring.aop.config.SpringAopInterceptor","thread_name":"http-nio-8080-exec-1","level":"INFO","level_value":20000,"method":"getMessage","class":"com.example.spring.aop.controller.SpringAopExampleController","execution-time in milliseconds":101}

Войдите в полноэкранный режим Выход из полноэкранного режима

Таким образом, у нас есть централизованный класс, ориентированный на ведение журнала нашего приложения, отражающий все методы внутри указанного пакета. Заметьте также, что у нас гораздо больше деталей.

Теперь посмотрите, насколько проще классы Controller и Service без этого ручного повторения кода:

@GetMapping("/messages/users/{username}")
    public ResponseEntity<String> getMessage(@PathVariable String username){
        return ResponseEntity.ok(service.getMessage(username));
    }

Войдите в полноэкранный режим Выход из полноэкранного режима

public class SpringAopExampleService {

    public String getMessage(String username){
        return "Hello World " + username + " from Spring AOP!";
    }
}

Войдите в полноэкранный режим Выход из полноэкранного режима

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

Надеюсь, вы внесли свой вклад и до скорой встречи!

Исходный код проекта доступен на моем Github:

Стандартизация журналов из Java-приложения с помощью Spring AOP

Рекомендуем почитать: