I am trying to print spanId and traceID when logging in my springboot application but not able to see in console. I am using springboot 3.0.2 version and using micrometer tracing as cloud-slueth is now deprecated. I am also using ESAPI for secure logging.
I am able to get the span id and trace id through tracer and was able to print tracer.currentSpan().traceIdString(); but ideally it should be attached to logs automatically through dependencies.
Please find code details below :
build.gradle
plugins {
id 'org.springframework.boot' version '3.0.2'
id 'java-library'
id 'eclipse'
}
apply plugin: 'io.spring.dependency-management'
ext {
springCloudVersion = "2022.0.1"
esapiVersion = "2.2.0.0"
springDocOpenApiVersion = "2.0.2"
jakartaMailVersion = "2.0.1"
javaCFEnvBootVersion = "2.4.1"
}
dependencies {
implementation 'org.springframework.boot:spring-boot-starter-mail'
implementation 'org.springframework.boot:spring-boot-starter-thymeleaf'
api ("org.springframework.boot:spring-boot-starter-web")
api ("org.springframework.boot:spring-boot-starter-aop")
api ("org.springframework.boot:spring-boot-starter-log4j2")
api ("org.owasp.esapi:esapi:${esapiVersion}")
api ("org.projectlombok:lombok")
api ("org.springdoc:springdoc-openapi-starter-webmvc-ui:${springDocOpenApiVersion}")
api ("com.sun.mail:jakarta.mail:${jakartaMailVersion}")
api ("io.pivotal.cfenv:java-cfenv-boot:${javaCFEnvBootVersion}")
api ("org.springframework.boot:spring-boot-starter-actuator")
api ("io.micrometer:micrometer-tracing-bridge-brave")
api ("org.springframework.boot:spring-boot-starter-webflux")
}
configurations {
all {
exclude group: 'org.springframework.boot', module: 'spring-boot-starter-logging'
exclude group: "log4j", module: "log4j"
exclude group: "org.eclipse.angus", module: "jakarta.mail"
}
}
dependencyManagement {
imports {
mavenBom "org.springframework.cloud:spring-cloud-dependencies:${springCloudVersion}"
}
}
ESAPILogger class written as a wrapper for ESAPI :
package com.cardinalhealth.framework.logging;
import java.util.regex.Matcher;
import org.owasp.esapi.Logger;
public class ESAPILogger implements Logger {
private final Logger logger;
public ESAPILogger(Logger logger) {
this.logger = logger;
}
public void debug(String message) {
this.logger.debug(Logger.EVENT_UNSPECIFIED, message);
}
public void debug(String message, Object... params) {
String parameterValues = patchParameterValues(message, params);
this.logger.debug(Logger.EVENT_UNSPECIFIED, parameterValues);
}
public void error(String message) {
this.logger.error(Logger.EVENT_UNSPECIFIED, message);
}
public void error(String message, Object... params) {
String parameterValues = patchParameterValues(message, params);
this.logger.error(Logger.EVENT_UNSPECIFIED, parameterValues);
}
public void info(String message) {
this.logger.info(Logger.EVENT_UNSPECIFIED, message);
}
public void info(String message, Object... params) {
String parameterValues = patchParameterValues(message, params);
this.logger.info(Logger.EVENT_UNSPECIFIED, parameterValues);
}
public void trace(String message) {
this.logger.trace(Logger.EVENT_UNSPECIFIED, message);
}
public void trace(String message, Object... params) {
String parameterValues = patchParameterValues(message, params);
this.logger.trace(Logger.EVENT_UNSPECIFIED, parameterValues);
}
public void warning(String message) {
this.logger.warning(Logger.EVENT_UNSPECIFIED, message);
}
public void warning(String message, Object... params) {
String parameterValues = patchParameterValues(message, params);
this.logger.warning(Logger.EVENT_UNSPECIFIED, parameterValues);
}
public void fatal(String message) {
this.logger.fatal(Logger.EVENT_UNSPECIFIED, message);
}
public void fatal(String message, Object... params) {
String parameterValues = patchParameterValues(message, params);
this.logger.fatal(Logger.EVENT_UNSPECIFIED, parameterValues);
}
public void always(String message) {
this.logger.always(Logger.EVENT_UNSPECIFIED, message);
}
public void always(String message, Object... params) {
String parameterValues = patchParameterValues(message, params);
this.logger.always(Logger.EVENT_UNSPECIFIED, parameterValues);
}
@Override
public void setLevel(int level) {
this.logger.setLevel(level);
}
@Override
public int getESAPILevel() {
return this.logger.getESAPILevel();
}
@Override
public void fatal(EventType type, String message) {
this.logger.fatal(type, message);
}
@Override
public void fatal(EventType type, String message, Throwable throwable) {
this.logger.fatal(type, message, throwable);
}
@Override
public boolean isFatalEnabled() {
return this.logger.isFatalEnabled();
}
@Override
public void error(EventType type, String message) {
this.logger.error(type, message);
}
@Override
public void error(EventType type, String message, Throwable throwable) {
this.logger.error(type, message, throwable);
}
@Override
public boolean isErrorEnabled() {
return this.logger.isErrorEnabled();
}
@Override
public void warning(EventType type, String message) {
this.logger.warning(type, message);
}
@Override
public void warning(EventType type, String message, Throwable throwable) {
this.logger.warning(type, message, throwable);
}
@Override
public boolean isWarningEnabled() {
return this.logger.isWarningEnabled();
}
@Override
public void info(EventType type, String message) {
this.logger.info(type, message);
}
@Override
public void info(EventType type, String message, Throwable throwable) {
this.logger.info(type, message, throwable);
}
@Override
public boolean isInfoEnabled() {
return this.logger.isInfoEnabled();
}
@Override
public void debug(EventType type, String message) {
this.logger.debug(type, message);
}
@Override
public void debug(EventType type, String message, Throwable throwable) {
this.logger.debug(type, message, throwable);
}
@Override
public boolean isDebugEnabled() {
return this.logger.isDebugEnabled();
}
@Override
public void trace(EventType type, String message) {
this.logger.trace(type, message);
}
@Override
public void trace(EventType type, String message, Throwable throwable) {
this.logger.trace(type, message, throwable);
}
@Override
public boolean isTraceEnabled() {
return this.logger.isTraceEnabled();
}
@Override
public void always(EventType type, String message) {
this.logger.always(type, message);
}
@Override
public void always(EventType type, String message, Throwable throwable) {
this.logger.always(type, message, throwable);
}
/**
* @param message
* @param params
* @return
*/
private String patchParameterValues(String message, Object... params) {
String parameters = message;
try {
if (params != null) {
for (int i = 0; i < params.length; i++) {
Object param = params[i];
if (param != null) {
parameters = parameters.replaceFirst("\\{\\}", Matcher.quoteReplacement(param.toString()));
} else {
parameters = parameters.replaceFirst("\\{\\}", "null");
}
}
}
} catch (Exception ex) {
// Absorb the exception occurred while logging
ex.printStackTrace();
}
return parameters;
}
}
Sample Controller to test log with span id and trace id :
final ESAPILogger logger = new ESAPILogger(ESAPI.getLogger(SampleController.class));
@GetMapping(path = "/")
public String getHelloWOrld() {
Span span = tracer.currentSpan();
logger.debug(".....Started ESAPI LOGGER SAMPLE..Trace ID - {}..Span ID - {}...Parent ID - {}...",
span.context().traceIdString(), span.context().spanIdString(), span.context().parentIdString());
logger.debug(".....Ended ESAPI LOGGER SAMPLE..Trace ID - {}..Span ID - {}...Parent ID - {}...",
span.context().traceIdString(), span.context().spanIdString(), span.context().parentIdString());
}
Logger pattern :
#Logging configuration
logging.level.root=INFO
logging.level.com.cardinalhealth=DEBUG
logging.pattern.console=[%-5level] %d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %c{1} [%X{X-B3-SpanId}] %X{mdcData}- %msg%n
# Trace every action
management.tracing.sampling.probability=1.0
Result looks like :
[DEBUG] 2023-02-07 14:09:09.876 [http-nio-8080-exec-1] SampleController [] - .....Started ESAPI LOGGER SAMPLE..Trace ID - 63e2a1d557b798e4db0685f2c77e9799..Span ID - db0685f2c77e9799...Parent ID - null...
[DEBUG] 2023-02-07 14:09:09.876 [http-nio-8080-exec-1] SampleController [] - .....Ended ESAPI LOGGER SAMPLE..Trace ID - 63e2a1d557b798e4db0685f2c77e9799..Span ID - db0685f2c77e9799...Parent ID - null...
Question : Ideally if Micrometer Tracing is on the classpath, the logs should be automatically correlated so why spanId and traceId is not included in logs automatically under [?] ?
I can see span id and trace id by explicitly calling the tracer.current span.
I tried everything but could not find any result.
Please help me fix this issue.
I was able to fix it. Its strange but found out that its case sensitive.
I fixed by updating my log pattern to below :
logging.pattern.console=[%-5level] %d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %c{1} [%X{traceId}] [%X{spanId}] - %msg%n