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: 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.