The "Parent Id" & "Operation Id" fields of trace logs are displayed as "00000000000000000000000000000000"

[bvahdat]

Expected behavior

The displayed Parent Id & Operation Id fields should display the effective real values.

Actual behavior

The Parent Id & Operation Id fields are displayed as 00000000000000000000000000000000 which is invalid.

To Reproduce

The release 3.2.11 doesn't have this issue, however using 3.3.0 or 3.3.1 we came across this problem. We are making use of Spring-Boot and write a log through SLF4J which gets collected through App-Insights as a trace log:

org.slf4j.Logger.info("this is my log message");

Looking into the corresponding trace logs in portal for it the Parent Id & Operation Id fields are displayed as zeros on the right hand side of the screen.

Sample Application

If applicable, provide a sample application which reproduces the issue.

System information

Please provide the following information:

• SDK Version: Both 3.3.0 and 3.3.1 have got this issue, 3.2.11 however works fine.
• OS type and version: Running in AKS using the azul/zulu-openjdk-alpine:11-jre-headless base image.
• Application Server type and version (if applicable):
• Using spring-boot? Yes, version 2.7.1
• Additional relevant libraries (with version, if applicable): Apache Camel 3.18.0

Logs

Turn on SDK logs and attach/paste them to the issue. If using an application server, also attach any relevant server logs.

The Turn on SDK logs link above doesn't work for me.

Screenshots

See the comparison below between 3.2.11 versus 3.3.1:

[trask]

hi @bvahdat, thanks for reporting this!

This looks like an issue with "standalone" logs (logs that aren't part of a request).

Previously "standalone" logs would each generate their own "operation id" ("trace id").

As we are aligning more and more with OpenTelemetry, and standalone logs don't have any "span context" (distributed trace), there is not really an operation id / parent id anymore for standalone logs.

I have sent #2440 to not report any operation id / parent id now in this case (we definitely should not have been reporting 0000...). This is still slightly different from pre-3.3.0, but does align more closely with OpenTelemetry.

[bvahdat]

Hi @trask

Thanks for your feedback.

This looks like an issue with "standalone" logs (logs that aren't part of a request).

The logs belong to an application listening on a Azure ServiceBus topic which was triggered using:

https://docs.microsoft.com/en-us/azure/service-bus-messaging/explorer

Do you think we should not expect to see the Parent Id & Operation Id fields in this case?

[trask]

hi @bvahdat,

Is Application Insights auto-capturing a request telemetry record for the Azure ServiceBus listener?

If it is, then I would expect the log to be tied to that "request".

If it isn't, then it makes sense that the log is standalone, and probably the underlying issue is https://github.com/Azure/azure-sdk-for-java/issues/26269.

[bvahdat]

Is Application Insights auto-capturing a request telemetry record for the Azure ServiceBus listener?

Yes, it does both in case of 3.2.11 & 3.3.1.

If it is, then I would expect the log to be tied to that "request".

Which unfortunately is not the case using 3.3.1, but it's the case using 3.2.11. So your current fix with https://github.com/microsoft/ApplicationInsights-Java/pull/2440 is not the solution for this issue here, right?

[trask]

@bvahdat can you help me reproduce this behavior?

I tested with https://github.com/trask/azure-sdk-examples/blob/main/servicebus/src/main/java/com/example/servicebus/Receiver.java, and I got the request telemetry and the correlated log telemetry

and I test with https://github.com/trask/azure-sdk-examples/blob/main/servicebus/src/main/java/com/example/servicebus/ReceiverAsyncClient.java and https://github.com/trask/azure-sdk-examples/blob/main/servicebus/src/main/java/com/example/servicebus/ReceiverAsyncClientAlt.java, and I didn't get the request telemetry, and I did get the "standalone" log telemetry (both 3.2.11 and 3.3.1), which is due to the ServiceBus tracing issue linked above

[bvahdat]

@bvahdat can you help me reproduce this behavior?

Please give this reproducer a try: https://github.com/bvahdat/test-app

[trask]

@bvahdat thx! from the screenshot it looks like in 3.2.11 the "Operation Id" and "Parent Id" are the same, which means it's a standalone log record and not correlated with the Service Bus transaction, which would explain zeros in 3.3.0 (and once 3.3.2 is released it the "Operation Id" and "Parent Id" for those will be empty, since they are not correlated with any operation).

[bvahdat]

which means it's a standalone log record and not correlated with the Service Bus transaction

Thanks, how can I force the Service Bus Explorer to correlate it's pushed message with the Service Bus transaction?

[trask]

check out the workaround described in https://github.com/Azure/azure-sdk-for-java/issues/26269

[trask]

@bvahdat since you are using apache camel, you may want to try the apache camel preview instrumentation, it would be great to hear if/how that works out for you

{
  "preview": {
    "instrumentation": {
      "apacheCamel": {
        "enabled": true
      }
    }
  }
}

[bvahdat]

you may want to try the apache camel preview instrumentation

Tried it out and pushed that upstream by the reproducer codebase mentioned above with no change by the observed behaviour.

But honestly I don't see why the apache camel preview instrumentation support should change anything in the behaviour we are observing here, as the problem is about diagnostic trace logs any application could write.

[trask]

hi @bvahdat, I believe you received a build of Service Bus SDK that has fix for https://github.com/Azure/azure-sdk-for-java/issues/26269, does that resolve this issue? thx!

[ghost]

This issue has been automatically marked as stale because it has been marked as requiring author feedback but has not had any activity for 7 days. It will be closed if no further activity occurs within 7 days of this comment.

[Premcnathan]

We are testing the dev build of the jar. testing will be completed by 07-Sep-2022.

[ghost]

This issue has been automatically marked as stale because it has been marked as requiring author feedback but has not had any activity for 7 days. It will be closed if no further activity occurs within 7 days of this comment.

[bvahdat]

msftbot please don't close.

[trask]

@bvahdat were you able to confirm that this issue is resolved?

[bvahdat]

Thanks, closing.