Padronizando Logs de uma aplicação Java usando Spring AOP

Victor Matheus da Silva — Thu, 05 May 2022 19:08:07 +0000

Em aplicações corporativas, é muito comum colocarmos logs nos métodos que criamos para indicar, por exemplo:

Os parâmetros de entrada
O tempo de execução
O retorno do método

Acontece que isso, se feito de forma manual, se torna muito repetitivo e propenso a erros. O dev pode facilmente esquecer de incluir algum desses logs, além de aumentar as linhas de código e assim diminuir a legibilidade.

Como exemplo, para fins didáticos, iremos demonstrar uma API simples que retorna uma mensagem juntamente com o nome que foi passado como parâmetro.

Observe o código abaixo:

@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;
    }
}

Abaixo segue o log de saída da execução da 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

Perceba como a leitura do código fica difícil

Primeiro capturamos o início do fluxo;
Depois logamos o nome do método, nome da classe e os parâmetros;
Chamamos o Service para armazenar a mensagem que será retornada;
Capturamos o final do fluxo;
Logamos o retorno, juntamente com o tempo de execução em milisegundos;

O mesmo se repete para a Classe de serviço.

Todas essas informações são importantes, mas repetir esse processo para todos os métodos é inviável.

Como solução desse problema, podemos usar o Spring AOP. Com ele, podemos automatizar procedimentos repetitivos que geralmente codificamos manualmente;

Vantagens do seu uso nessa abordagem:

Evita redundância de código: esse processo de log descrito anteriormente não fica mais sendo manualmente repetido em todos os metodos e sim em um classe específica do Spring para tal uso.
Reaproveitamento de códgo: a classe a qual concentra a estrutura padrão dos logs pode ser reutilizada em outros projetos;
Facilidade de manutenção: ao invés de alterar um padrão de log em todos os métodos, a manutenção ou melhoria será feita apenas uma vez e será refletida em todo o sistema;

Podemos ter uma classe como a exemplificada abaixo para centralizar esse tipo de log:

@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;
    }
}

Nessa estrutura, estamos usando o Logback e o Logstash. Então é necessário criar o arquivo logback.xml e colocá-lo dentro da pasta resources da sua aplicação.

OBS: os logs passarão a ficar no formato JSON. Irei explicar com detalhes no próximo artigo. Por hora, basta copiar esse arquivo xml e incluir as dependências. Você pode consultar tudo que precisa no código fonte que irei disponibilizar no final do artigo.

Observe como ficaram os logs:

{"@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}

Com isso, temos uma classe centralizada focada em logar nossa aplicação, refletindo para todos os métodos dentro do package especificado. Perceba também que temos muito mais riqueza de detalhes.

Agora veja como as classes de Controller e Service ficaram muito mais simples sem aquela repetição de código manual:

@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!";
    }
}

Em um próximo artigo, irei explicar sobre como deixar os logs da aplicação em formato de JSON, o qual ajuda bastante no throubleshooting e até na criação de dashboards e monitoramentos.

Espero que tenha contribuído em algo e até mais!

Código fonte do projeto disponível no meu Github:

DEV Community: Victor Matheus da Silva

Padronizando Logs de uma aplicação Java usando Spring AOP