Search code examples
javaloggingaopspring-aopspring-cloud-sleuth

Spring AOP logger trace ID with Spring Cloud Sleuth?


I have a few microservices running with Spring Cloud Sleuth as a distributed logging manager. For some microservices Spring AOP is also included, mostly with @Around advice for methods execution time logging (code below).

Now, I'm probably missing AOP point here and don't really understand when @Around advice actually kicks in, but is it possible to have Sleuth trace ID included in log generated from @Aspect defined class ?

Code:

@Target(ElementType.METHOD)
@Retention(RetentionPolicy.RUNTIME)
public @interface LogExecutionTime {
}

@Aspect class (imports from org.aspectj and org.slf4j):

@Aspect
@Component
public class PerformanceAspect {

private static final Logger logger = LoggerFactory.getLogger(PerformanceAspect.class);

@Around("@annotation(LogExecutionTime)")
public Object logExecutionTime(ProceedingJoinPoint joinPoint) throws Throwable {
    final long start = System.currentTimeMillis();

    final Object proceed = joinPoint.proceed();

    final long executionTime = System.currentTimeMillis() - start;

    logger.debug("\n---- Performance aspect ----\n" +
                "method: {}\n" +
                "execution time: {} [ms]\n" +
                "------------------------\n",
            joinPoint.getSignature().getName(), executionTime);

    return proceed;
    }
} 

Spring Boot version is 2.0.7.RELEASE (Spring Cloud Finchley.SR2) and the related (Maven) dependencies are:

<dependency>
    <groupId>org.springframework.cloud</groupId>
    <artifactId>spring-cloud-starter-sleuth</artifactId>
</dependency>

<dependency>
    <groupId>org.springframework.boot</groupId>
    <artifactId>spring-boot-starter-aop</artifactId>
</dependency>

@LogExecutionTime is set on some of time-critical methods (file upload to storage, external API calls, etc.), and it is much desirable if user actions trace ID could also be set for methods performance logging.

Any help is appreciated, thank you.

UPDATE:

There are trace IDs for other logs, here is example:

January 31st 2019, 09:44:31.024 dev-backend customer-service    31.01.2019 08:44:50 DEBUG [customer-service,f9c173ae7a161cd6,f9c173ae7a161cd6,false] Request for file upload.

Right after that, here are performance logs (without trace ID):

January 31st 2019, 09:44:50.532 dev-backend customer-service    method: fileUploadAzure

January 31st 2019, 09:44:50.532 dev-backend customer-service    ---- Performance aspect ----

January 31st 2019, 09:44:50.532 dev-backend customer-service    execution time: 19507 [ms]

Imports in both cases are:

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

Logging pattern from config:

logging:
  // other config
  pattern:
    console: "%d{dd.MM.yyyy HH:mm:ss} ${LOG_LEVEL_PATTERN:-%5p} %m%n"

Solution

  • Solution: don't use line separators in logs (\n) if you want to analyse all lines with Kibana and see the trace id on every line.