Issues with Logback MDC injections in Dropwizard application

[ashishsanodia-harness]

In our Dropwizard application, traceIds and spanIds do not consistently appear in logback logs. For very few logs I am seeing traceIds .
We are relying on agent's automatic instrumentation. My understanding is that opentelemetry agent will manage the MDC context itself (regardless of whether the application is instrumented manually or automatically).

We are using opentelemetry -javaagent 1.13.1 and logger configuration is in config.yml

logging:
  level: INFO
  loggers:
    org.quartz.plugins: WARN
    org.glassfish.jersey: WARN
    allbegray.slack: WARN
  appenders:
    - type: console
      threshold: TRACE
      target: STDOUT
      logFormat: "%date{ISO8601} %green([%thread]) %highlight(%-5level) %cyan(%logger) traceId: %X{trace_id} spanId: %X{span_id} - %msg %yellow(%replace(%mdc){'(.+)', '[$1]'}) %n"

Logs:

2022-05-14 14:49:35,240 [Iterator-ArtifactCollection] INFO  software.wings.service.impl.artifact.ArtifactCollectionServiceAsyncImpl traceId:  spanId:  - Queued delegate taskId 1W5tANM4Rj2XbXlOIRJkNA for artifactStream type: DOCKER and source: harness/todolist-sample [accountId=67890123456789012, entityClass=software.wings.beans.artifact.DockerArtifactStream, artifactStreamId=GjJWbdVnSoiTFuLlZ8VO9w, artifactStreamType=DOCKER] 
2022-05-14 14:49:35,240 [Iterator-ArtifactCollection] INFO  io.harness.mongo.iterator.MongoPersistenceIterator traceId:  spanId:  - Done with entity [accountId=67890123456789012, entityClass=software.wings.beans.artifact.DockerArtifactStream, artifactStreamId=GjJWbdVnSoiTFuLlZ8VO9w] 
2022-05-14 14:49:35,240 [Iterator-ArtifactCollection] INFO  software.wings.service.impl.artifact.ArtifactCollectionServiceAsyncImpl traceId:  spanId:  - Queued delegate taskId 2z3jBS6fT6uipsWBrQbjYg for artifactStream type: AMI and source: us-east-1 [accountId=67890123456789012, entityClass=software.wings.beans.artifact.AmiArtifactStream, artifactStreamId=GpyN2rQXStKekSKGqA0GYA, artifactStreamType=AMI] 
2022-05-14 14:49:35,240 [Iterator-ArtifactCollection] INFO  io.harness.mongo.iterator.MongoPersistenceIterator traceId:  spanId:  - Done with entity [accountId=67890123456789012, entityClass=software.wings.beans.artifact.AmiArtifactStream, artifactStreamId=GpyN2rQXStKekSKGqA0GYA] 
2022-05-14 14:49:35,834 [NotifyEvent-handler-GQ9QTvomSCevj_VIIlyinQ] INFO  io.harness.queue.QueueListener traceId:  spanId:  - Working on message [accountId=67890123456789012, messageTopic=${build.fullVersion};general, taskType=BUILD_SOURCE_TASK, entityClass=software.wings.beans.artifact.DockerArtifactStream, delay=606, artifactStreamId=tdRI8I2cT8GYAeDCPdOGkA, messageClass=io.harness.waiter.NotifyEvent, messageId=QrkR8jsrS-qONK4NTIoDDQ, artifactStreamType=DOCKER, rank=OPTIONAL, taskId=q-k10c_ERGa-fhI5nulWpw, taskGroup=BUILD_SOURCE] 
2022-05-14 14:49:35,837 [NotifyEvent-handler-gA7a4aIVQzCUZgGG8XG8Fw] INFO  io.harness.queue.QueueListener traceId:  spanId:  - Working on message [accountId=67890123456789012, messageTopic=${build.fullVersion};general, taskType=BUILD_SOURCE_TASK, entityClass=software.wings.beans.artifact.AmiArtifactStream, delay=608, artifactStreamId=GpyN2rQXStKekSKGqA0GYA, messageClass=io.harness.waiter.NotifyEvent, messageId=llTlBgbCR72R6jUtUuI8JQ, artifactStreamType=AMI, rank=OPTIONAL, taskId=2z3jBS6fT6uipsWBrQbjYg, taskGroup=BUILD_SOURCE] 
2022-05-14 14:49:35,838 [NotifyEvent-handler-GQ9QTvomSCevj_VIIlyinQ] INFO  io.harness.waiter.persistence.MorphiaPersistenceWrapper traceId:  spanId:  - Failed notification response lbs0ijhsRy6WjBY-D4FyXw [entityClass=software.wings.beans.artifact.DockerArtifactStream, artifactStreamId=tdRI8I2cT8GYAeDCPdOGkA, messageId=QrkR8jsrS-qONK4NTIoDDQ, taskGroup=BUILD_SOURCE, accountId=67890123456789012, messageTopic=${build.fullVersion};general, taskType=BUILD_SOURCE_TASK, waitInstanceId=ZAVt2XDhS6agRkJNprXvMw, messageClass=io.harness.waiter.NotifyEvent, artifactStreamType=DOCKER, rank=OPTIONAL, taskId=q-k10c_ERGa-fhI5nulWpw] 
2022-05-14 14:49:35,840 [NotifyEvent-handler-gA7a4aIVQzCUZgGG8XG8Fw] INFO  io.harness.waiter.persistence.MorphiaPersistenceWrapper traceId:  spanId:  - Failed notification response 0IwB6kMYRx6-F_m1El7n3Q [entityClass=software.wings.beans.artifact.AmiArtifactStream, artifactStreamId=GpyN2rQXStKekSKGqA0GYA, messageId=llTlBgbCR72R6jUtUuI8JQ, taskGroup=BUILD_SOURCE, accountId=67890123456789012, messageTopic=${build.fullVersion};general, taskType=BUILD_SOURCE_TASK, waitInstanceId=v7OWggNFS7Ow1ABAeKkAIw, messageClass=io.harness.waiter.NotifyEvent, artifactStreamType=AMI, rank=OPTIONAL, taskId=2z3jBS6fT6uipsWBrQbjYg] 
2022-05-14 14:49:35,862 [NotifyEvent-handler-GQ9QTvomSCevj_VIIlyinQ] INFO  software.wings.delegatetasks.buildsource.BuildSourceCallback traceId:  spanId:  - Request failed :[Delegates are not available] [entityClass=software.wings.beans.artifact.DockerArtifactStream, artifactStreamId=tdRI8I2cT8GYAeDCPdOGkA, messageId=QrkR8jsrS-qONK4NTIoDDQ, taskGroup=BUILD_SOURCE, accountId=67890123456789012, messageTopic=${build.fullVersion};general, taskType=BUILD_SOURCE_TASK, waitInstanceId=ZAVt2XDhS6agRkJNprXvMw, messageClass=io.harness.waiter.NotifyEvent, artifactStreamType=DOCKER, rank=OPTIONAL, taskId=q-k10c_ERGa-fhI5nulWpw] 
2022-05-14 14:49:35,862 [NotifyEvent-handler-UXgYdcmPTM-xTbWIPlOpbQ] INFO  software.wings.delegatetasks.buildsource.BuildSourceCallback traceId:  spanId:  - Request failed :[Delegates are not available] [entityClass=software.wings.beans.artifact.AmiArtifactStream, artifactStreamId=9ppnwJx9RZmJiaimom19-A, messageId=J_K0F9TQT9GdETDF5kLs_A, taskGroup=BUILD_SOURCE, accountId=67890123456789012, messageTopic=${build.fullVersion};general, taskType=BUILD_SOURCE_TASK, waitInstanceId=25dQLCMqQu6zGDCBGbr92Q, messageClass=io.harness.waiter.NotifyEvent, artifactStreamType=AMI, rank=OPTIONAL, taskId=UqAP7mONRx29O3O1Lws2xA] 
2022-05-14 14:49:36,830 [main-app-pool-13] INFO  software.wings.scheduler.AlertCheckJob traceId: 2a7aec408bd657b92cb3e2904db6188a spanId: 73d39e9d23b5a5a9 - Checking account 67890123456789012 for alert conditions. [trace_id=2a7aec408bd657b92cb3e2904db6188a, trace_flags=01, span_id=73d39e9d23b5a5a9] 
2022-05-14 14:49:36,849 [main-app-pool-14] INFO  software.wings.service.impl.AlertServiceImpl traceId: 2a7aec408bd657b92cb3e2904db6188a spanId: 73d39e9d23b5a5a9 - Finding existing alerts for accountId 67890123456789012 [accountId=67890123456789012, alertType=INVALID_SMTP_CONFIGURATION, applicationId=sample-application-id, trace_id=2a7aec408bd657b92cb3e2904db6188a, trace_flags=01, span_id=73d39e9d23b5a5a9] 
2022-05-14 14:49:36,851 [main-app-pool-14] ERROR io.harness.mongo.HObjectFactory traceId: 2a7aec408bd657b92cb3e2904db6188a spanId: 73d39e9d23b5a5a9 - Class software.wings.beans.alert.Alert is not prerecorded in the known morphia classes [accountId=67890123456789012, alertType=INVALID_SMTP_CONFIGURATION, applicationId=sample-application-id, collectionName=alerts, trace_id=2a7aec408bd657b92cb3e2904db6188a, trace_flags=01, span_id=73d39e9d23b5a5a9] 

[trask]

hi @ashishsanodia-harness!

do not consistently appear in logback logs

do they appear sometimes and not others? is there any pattern you can identify?

probably the best way for us to help you is if you can create a small sample application that exhibits the same issue, that we can use to debug and identify the issue

[ashishsanodia-harness]

hi @trask

We have a thread-pool configured in main application with thread name pattern [main-app-pool-%d]. Looks like it is only adding traceIds to executions which are using threads from this thread-pool.
If you see last 3 logs where AlertCheckJob is a type of "org.quartz.Job". A quartz trigger is configured to run AlertCheckJob at a scheduled interval and we are seeing traceIds getting populated in this.

Let me try to create a sample app with these issue.

[ashishsanodia-harness]

Hi @trask

• You can get source from here https://github.com/ashishsanodia-harness/harness-core
• It uses bazel for building project.
• Follow Readme's Build section and run steps 1,2,3,4 and 8
• download opentelemetry-javaagent.jar in project's root directory
• Go to "Run Harness without IDE" section in Readme and follow instructions to start server using below commands
  • bazel build //360-cg-manager:module_deploy.jar
  • java -Xms1024m -Xmx1024m -XX:+HeapDumpOnOutOfMemoryError -XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:mygclogfilename.gc -XX:+UseParallelGC -XX:MaxGCPauseMillis=500 -Xbootclasspath/p:alpn-boot-8.1.13.v20181017.jar -Dfile.encoding=UTF-8 -Dotel.exporter.otlp.endpoint='http://localhost:4317' -Dotel.service.name='cg-manager-otel' -javaagent:opentelemetry-javaagent.jar -jar ~/.bazel-dirs/bin/360-cg-manager/module_deploy.jar server 360-cg-manager/config.yml > cg-manager.log &
• you should be able to see inconsistent traceIds in logs in cg-manager.log

[trask]

@ashishsanodia-harness since you have a repro, can you create an issue for this? that will help us better prioritize investigation, thx!

[ashishsanodia-harness]

Thanks @trask

New issue created here #6062