Questions about traceIds in Log4j statements

[pwfarwell]

Sorry for the long post... The only way to explain the issue is with an example.

We are trying to write traceIds in our logs using OpenTelemetery's log4j support. We're using otel java libraries from the maven 1.1 BOM import. We've added the traceId and spanId to the pattern in our log4j xml appender.

We're able to see traceIds and spanIds in our logs, but the results seem inconsistent - or we don't understand how OTEL's interaction with log4j works.

A traceId appears in log statements. But when I print out the traceId in the Span.current(), I see the "null" traceId "0000000000000000". So for the same log statement I see this:

{ ... "message":"traceId: 00000000000000000000000000000000", ... "traceId":"316241696e248bec34acc095076baad5" ...}

Here's the code example:

    Span currentSpan = Span.current();
    LOGGER.info("---------------- current span");
    printSpanInfo(currentSpan);

    private static void printSpanInfo(Span span) {  
      LOGGER.info("span context: " + span.getSpanContext());
      LOGGER.info("traceId: {}", span.getSpanContext().getTraceId(););
      // ... 
    }

And here are the full log statements (all for the same threadId "50"):

{"timestamp":"2021-05-14T22:42:35.585Z","message":"---------------- current span","level":"INFO","loggerName":"com.qlik.common.events.EventFactory","threadId":"50","traceId":"316241696e248bec34acc095076baad5","spanId":"3629229c6eae91d9","instanceId":"12be3bfa16"}
{"timestamp":"2021-05-14T22:42:35.586Z","message":"span context: ImmutableSpanContext{traceId=00000000000000000000000000000000, spanId=0000000000000000, traceFlags=00, traceState=ArrayBasedTraceState{entries=[]}, remote=false, valid=false}","level":"INFO","loggerName":"com.qlik.common.events.EventFactory","threadId":"50","traceId":"316241696e248bec34acc095076baad5","spanId":"3629229c6eae91d9","instanceId":"12be3bfa16"}
{"timestamp":"2021-05-14T22:42:35.586Z","message":"spanId: 0000000000000000","level":"INFO","loggerName":"com.qlik.common.events.EventFactory","threadId":"50","traceId":"316241696e248bec34acc095076baad5","spanId":"3629229c6eae91d9","instanceId":"12be3bfa16"}
{"timestamp":"2021-05-14T22:42:35.586Z","message":"traceId: 00000000000000000000000000000000","level":"INFO","loggerName":"com.qlik.common.events.EventFactory","threadId":"50","traceId":"316241696e248bec34acc095076baad5","spanId":"3629229c6eae91d9","instanceId":"12be3bfa16"}

When I create a new span and make it current, I now get a valid traceId from the span, but the logger continues to use the old traceId:

    LOGGER.info("---------------- testSpan new span");
    Span newSpan = tracer.spanBuilder("my span").startSpan();
    try (Scope scope = newSpan.makeCurrent()) {
      newSpan.setAttribute(Constants.TRACE_ID_KEY, newSpan.getSpanContext().getTraceId());
      printSpanInfo(newSpan);   
    } finally {
        newSpan.end();
    }

Log:

{... "message":"traceId: 7507140d35d466042a3b3d6f4715ddca", ... "traceId":"316241696e248bec34acc095076baad5" ...}

We want to control when the traceId in the logs changes.

In most cases, we want to set a traceId at the beginning of a thread and see that same traceId in the logs for the duration of the thread.

Any suggestions?

[anuraaga]

Hi @pwfarwell - it sounds like you are using the Java agent. What version of the agent and what version of opentelemetry-api are you using? Those versions have to be aligned for Span.current() type of invocations to work within your code.

[pwfarwell]

@anuraaga We are not using the java agent. Are you saying that we need to use the Java agent in order for traceIds to appear correctly in the Log4j log statements?

[anuraaga]

If not using the javaagent, manually registering the library instrumentation can work. Is that what you're doing?

https://github.com/open-telemetry/opentelemetry-java-instrumentation/tree/main/instrumentation/log4j/log4j-2.13.2/library

We commonly see version mismatch issues causing Span.current() to not return a correct ID but that can't be the case if you're not using the agent. When not using the agent, it's actually extremely unlikely to have such a discrepency.

How is your app setup? Do you have a snippet for configuring OpenTelemetrySdk? Are you using spring sleuth? If you're not using the agent, the only reason I can think of for that behavior is you are using sleuth configured for Brave, not OTel, so the logs get injected with Brave's trace IDs but OTel is not active and Span.current() returns nothing.

[pwfarwell]

Hi @anuraaga I have been able to reproduce the issue in an example SpringBoot app. I've posted the issue here:
#3074

[anuraaga]

Transferred this issue to opentelemetry-java-instrumentation since the log4j support is part of this repo.