Not seeing Telemetry for ServiceBusReceiver operations for ServiceBus ApplicationInsights using latest stable Azure.Messaging.ServiceBus SDK

[jalexander-bb]

nuget: PackageReference Include="Microsoft.ApplicationInsights" Version="2.21.0" / PackageReference Include="Azure.Messaging.ServiceBus" Version="7.9.0" / Runtime version dotnet 6 Hosting environment: Mac & Windows2019Server

Description:

Im following documentation: https://docs.microsoft.com/en-us/azure/service-bus-messaging/service-bus-end-to-end-tracing trying to get servicebus telemetry to work with Azure.Messaging.ServiceBus SDK. We recently migrated from Microsoft.Azure.ServiceBus SDK and this used to work for all the MessageReceiver operations automatically. Now we are using ServiceBusReceiver and calling operations like:

ServiceBusReceiver.ReceiveMessagesAsync(); await ServiceBusReceiver.CompleteMessageAsync(brokeredMessage) await ServiceBusReceiver.DeadLetterMessageAsync(brokeredMessage)

Im sometimes not able to see Request telemetry being sent to Application Insights for operations like Process nor am I able to see Dependencies telemetry like: Complete, DeadLetter, AcceptMessageSession etc. Because of this we sometimes see multiple dependencies from the same thread with different operation_Ids or sometimes we wont even see operation_Ids at all. Whats weird is that dependencies will log to AI though processed from that message thread, just none of the request telemetry is coming up to tie it all together like before.

Our messaging library is complex and using ServiceBusProcessor is not an option for us. We need the complex granularity of controlling how the messages get processed. It also says in your MS docs that it is recommended to not use ServiceBusProcessor for complex use cases, so this seems fine to use ServiceBusReceiver.

I even tried creating a telemetryClient and getting it to log to applicationInsights and then processing all the messagings, I still did not see any request telemetry get setup, eg: https://docs.microsoft.com/en-us/azure/service-bus-messaging/service-bus-end-to-end-tracing?tabs=net-standard-sdk-2#trace-message-processing

Here are some pictures showing it before and after the SDK changes Before:

After:

[jalexander-bb]

Does this issue need to moved to the dotnet sdk repo instead?

[lmolkova]

@jalexander-bb, thanks for reporting this.

I believe the problem is that ServiceBus Receiver client does not correlate receive/settle calls to producer calls. This is a gap in ServiceBus SDK and I created this issue there.

To confirm my assumption, can you please check if you see ServiceBusReceiver.Receive, ServiceBusReceiver.Complete or any other ServiceBusReceiver.* calls (not correlated to producer telemetry)?

[jalexander-bb]

@lmolkova I do see ServiceBusReceiver.Receive and ServiceBusReceiver.Complete dependencies being logged and they are just not being correlated properly to the operation ids. Thanks for filing that ticket, i believe ur assumption is prolly the problem.

[lmolkova]

@jalexander-bb thank you for the clarification! I believe we've fixed it and you should get it with the next ServiceBus SDK release happening in the next 2-3 weeks. You could also try out the latest nightly build with the fix from this nuget source

By default, you should see links between message and receive or complete call like this:

If you want to trace message processing as a child of the message, here's how you could do it:

1. Obtain TelemetryClient instance from dependency injection (or create one)
2. Per each message received create ApplicationInsights operation as shown below:
3. do all you message processing within a scope of this operation

var messages = await receiver.ReceiveMessagesAsync(3, TimeSpan.FromMinutes(1));

foreach(var m in messages) {
    // create the activity with any name
    var processMessageActivity = new Activity("process message");
    if (m.ApplicationProperties.TryGetValue("Diagnostic-Id", out var parentId) && parentId is string parentIdStr) {

        // if there is a parent, get it from the message and set on the activity
        processMessageActivity.SetParentId(parentIdStr);
    }

    // track activity with ApplicationInsights SDK
    using var operation = telemetryClient.StartOperation<RequestTelemetry>(processMessageActivity);

    // process messsage...

    await receiver.CompleteMessageAsync(m);
}

Here's what you should see

Please let us know how it works for you!

[jalexander-bb]

@lmolkova Can you clarify abit? We use the automatic telemetry logging the SDK provides, so it is already creating the telemetry under the hood for the received message right now. So I shouldnt need to explicity create another telemetry request to connect everything up. Shouldnt the SDK fix also include what your example is doing which is associating the diagnostic id/parent id? Seems like this should be a default behavior within the SDK to automatically do this like the old ServiceBus lib was doing before.

[lmolkova]

@jalexander-bb the default path would connect receive and complete calls (or other settlement operation) to the message. this is what you see in the first screenshot. You don't need to do anything except updating the SDK.

However, if you make an HTTP request or DB call between receive and complete, there is no way to correlate it back to any of these operations. Since you process a message outside of SDK, we don't know anything about this code - which message it's related to? Is it related to any message at all? When does it complete? Does it fail? We have no way to tell. So if you want to correlate telemetry generated for your custom message processing to the message, you'd need to write something similar to what I showed above.

Let me know if it helps.

[jalexander-bb]

@lmolkova Hello, sorry for the late reply but i was able to test the recent SDK and i see the operationId is now being carried over across the entire servicebus request when initiated via a HTTP request. However I am still noticing a bug when it comes to session messages not carrying the same operationId as the previous SDK did. Looks related to the AcceptMessageSession no longer existing/ or the dependency no longer carrying over the operationId to the received session message.

Here are some pictures showing the cross communication between 2 services sending a servicebus session message between 2 microservices: Before (Previous Microsoft.Azure.ServiceBus SDK):

After (Latest Azure.Messaging.ServiceBus SDK):

When i look to see how the message was received on the other microservice, you can see that no operationIds are present on the received session message. So the bug still exists for session messages based on this.

[jalexander-bb]

Also unrelated to last post: This issue is still not resolved for messages received by servicebus that are not initiated via a HTTP request. The last message shows that a HTTP POST Android/EnrollDevice request was what initiated the entire operation Request telemetry. The main issue for this scenario looks to be that the Process operation is what was starting the Request itemType telemetry which tied everything together with an operationId. With the new SDK that is no longer happening with the "ServiceBusReceiver. Receive", so now no operationIds are present on anything when processing that message. Im not even seeing the Receive being logged in this case.

Before (Previous Microsoft.Azure.ServiceBus SDK):

After (Latest Azure.Messaging.ServiceBus SDK):

As you can see these both this issue and the last issue i described relating to session messages, worked out of the box with the previous SDK. We did not do any additional code to add telemetry data to produce operationIds when consuming servicebus messages of any kind.

[jalexander-bb]

@lmolkova see last two comments about 2 issues still going on. Let me know if more info needed. Tested using version 7.11.1

[jalexander-bb]

Was able to resolve my issues switching to ServiceBusProcessor and adding back event hooks that got lost in the migration to the new SDK. This started to automatically correlate operationIds across all the different services and processes we had.