Strange traceid behavior in log

[magicliang]

Hi, guys,

I introduced logback dependency in my project:

  libraryDependencies += "io.opentelemetry" % "opentelemetry-exporter-logging-otlp" % "1.14.0",

logback xml config is like:

  <appender name="FILE"
            class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>${user.dir}/log/application.log</file>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
      <!-- Daily rollover with compression -->
      <fileNamePattern>${user.dir}/log/application-%d{yyyy-MM-dd}.gz</fileNamePattern>
      <!-- keep 30 days worth of history -->
      <maxHistory>30</maxHistory>
    </rollingPolicy>
    <encoder>
      <pattern>traceId: %X{trace_id} spanId: %X{span_id} %date{yyyy-MM-dd HH:mm:ss SSS} [%level] %logger %thread
        %message%n%xException
      </pattern>
      <charset>UTF-8</charset>
    </encoder>
  </appender>

  <appender name="DB"
            class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>${user.dir}/log/db.log</file>
    <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
      <!-- Daily rollover with compression -->
      <fileNamePattern>${user.dir}/log/db-%d{yyyy-MM-dd}.gz</fileNamePattern>
      <!-- keep 30 days worth of history -->
      <maxHistory>30</maxHistory>
    </rollingPolicy>
    <encoder>
      <pattern>traceId: %X{trace_id} spanId: %X{span_id} %date{yyyy-MM-dd HH:mm:ss SSS} [%level] %logger %thread
        %message%n%xException
      </pattern>
      <charset>UTF-8</charset>
    </encoder>
  </appender>

The problem is: sometimes I have a dangling thread traceid, sometimes I have empty traceid:

traceId: 22f9f91cd7ae17ea46258a9d6d160957 spanId: 026310d8c8920106 2022-05-30 15:11:27 854 [INFO] com.company.polaris.client.plugin.server.grpc.SpecDiscovery grpc-default-executor-10
        load discovery, key:ServiceKey{namespace='Polaris', service='polaris.monitor'}, instance size is:103
traceId: 22f9f91cd7ae17ea46258a9d6d160957 spanId: 026310d8c8920106 2022-05-30 15:11:27 854 [INFO] com.company.polaris.client.plugin.server.grpc.ConnectionManagerFactory grpc-default-executor-10
        registerConnectionManager start, cluster type:MONITOR_CLUSTER, instances size:100
traceId: 22f9f91cd7ae17ea46258a9d6d160957 spanId: 026310d8c8920106 2022-05-30 15:11:27 854 [INFO] com.company.polaris.client.plugin.server.grpc.ConnectionManagerFactory grpc-default-executor-10
        filterInstancesByProtocol, from 100 instances to 100
traceId:  spanId:  2022-05-30 15:11:27 855 [INFO] com.company.polaris.client.plugin.server.grpc.SpecDiscovery update-polaris-thread

traceId:  spanId:  2022-05-30 15:13:52 596 [DEBUG] com.zaxxer.hikari.pool.PoolBase HikariPool-2 connection closer
        HikariPool-2 - Closing connection gdt.di.jdbc.DiConnectionImpl@67bcaf75: (connection has passed maxLifetime)

1. I thought opentelemetry agent can inject traceid in every thread(even it is spawned in a thread pool executor), but obviously some traceid is missing.
2. sometimes, 22f9f91cd7ae17ea46258a9d6d160957 in log is a trace id from last request, looks like traceid is inherited by some io thread, and when that io thread doing its heart-beat communication, the traceid is printed again.
3. And apparently hikari connection pool's log doesn't have traceid.

This looks like similar issue to this

[laurit]

1. It is possible that there is no active trace, in which case there is no trace id or trace id is all zeros.
2. We attempt to propagate trace to other threads, for example, when a thread with active trace submits a task to an executor then that task should execute with the same trace as the thread that submitted it. This unfortunately can also result in leaking the trace when the submitted task is actually a long running task. If such undesired propagation happens in application server or framework code then we usually consider it to be a bug and try to fix it.
3. This is expected, background threads aren't supposed to have a trace id unless they perform a traceable activity.

[magicliang]

I believe there is always active trace in every execution. for example:

1. in some case, my service works like server, so the active trace comes from upstream call. But in other cases, my service may work like client, even a client which pings middleware server to do some ping/pong communication. Should this be a trace to record?
2. If I have a internal task which writes some info every 5 seconds, without calling any external distributed service, should the task log print traceid?

"This unfortunately can also result in leaking the trace when the submitted task is actually a long running task."

My problem is, a long running task ended some minutes ago, looping thread is still printing task's trace id.

[laurit]

1. When context is propagated from upstream then there will be no trace before request processing has reached the point where upstream context is extracted from request.
   Inside a client application trace is created with root span, see https://github.com/open-telemetry/opentelemetry-java/blob/92bd65970eb22a860151f66a96b66e02dc416fcf/sdk/trace/src/main/java/io/opentelemetry/sdk/trace/SdkSpanBuilder.java#L168-L180 So if your application creates a span only for the http call to server then this is the only point where you have a trace. Everything that happens before and after the call won't have a trace. Trace is a collection of spans, for the trace to exist you need to have a span.
2. Probably no. If you don't have an active span then there is no trace.

My problem is, a long running task ended some minutes ago, looping thread is still printing task's trace id.

would it be possible to create a minimal sample application that reproduces this issue?

[magicliang]

1. When context is propagated from upstream then there will be no trace before request processing has reached the point where upstream context is extracted from request.
   Inside a client application trace is created with root span, see https://github.com/open-telemetry/opentelemetry-java/blob/92bd65970eb22a860151f66a96b66e02dc416fcf/sdk/trace/src/main/java/io/opentelemetry/sdk/trace/SdkSpanBuilder.java#L168-L180 So if your application creates a span only for the http call to server then this is the only point where you have a trace. Everything that happens before and after the call won't have a trace. Trace is a collection of spans, for the trace to exist you need to have a span.
2. Probably no. If you don't have an active span then there is no trace.

My problem is, a long running task ended some minutes ago, looping thread is still printing task's trace id.

would it be possible to create a minimal sample application that reproduces this issue?

So if the business logic does not spawn a span here, we get no span. Actually I know Opentelemetry agent will automatically create span for execution in invocation like Spring MVC controller calling/Play controller calling, I don't know the standard: For what invocation, the agent will create span for users? If I know this, I will know how to create span as supplement.

Thanks for the tips about sample application, I was planning to create one, but my company is using its inner technical stack(which use its special ThreadPoolExecutor), which I can't introduce in a sample application. I created this discussion thread and wished to ask if someone knows when a thread's trace will run like that.