Add Enrich API in NServiceBus OpenTelemetry Integration

[benv-nti]

Describe the suggested improvement

Is your improvement related to a problem? Please describe.

In our handlers, we typically do not catch exceptions. We let NServiceBus handle them (to retry) and log them via OpenTelemetry.
For some types of exceptions (like SqlException and ApiException<ProblemDetails>), we want to log additional details from the exception. Ideally, we would like to add these as tags to the exception that NServiceBus is logging.

Describe the suggested solution

The pattern among other OpenTelemetry instrumentation providers seems to be to provide an Enrich API, which allows applications to access the objects being logged and enrich the associated Activity with additional information. The HTTP Instrumentation library is one example.
For NServiceBus, I envision something similar:

endpointConfiguration.EnableOpenTelemetry(options => {
   options.EnrichWithException = (activity, exception) =>
        {
            if (exception is SqlException sqlex)
               activity.SetTag("exception.number", sqlex.Number);
        };
});

Describe alternatives you've considered

Catch/Log/Rethrow

In our handlers, catch the exceptions we are interested in, log the properties of interest (but not the exception), and rethrow for NServiceBus.

public async Task Handle(MyEvent message, IMessageHandlerContext context)
{
   try
   {
      ...
   }
   catch (SqlException ex)
   {
      Activity.Current?.SetTag("exception.number", ex.Number);
      throw;
   }
}

This gives us the desired outcome, but adds a fair amount of boilerplate code to our handlers.

OpenTelemetry Processor

I looked into creating a custom ActivityProcessor. This gives you a hook to modify an Activity when it starts and when it ends. Unfortunately, at this level we don't have access to the raw exception object - it's already been converted to event tags on the activity.

Additional Context

No response

[andreasohlund]

Thanks for the feedback @benv-nti you can already achieve this with our messaging pipeline by adding a new behavior in the invoke handler part of the pipeline that adds the tag using the code you already provided.

Would that work for you?

[benv-nti]

That's a good idea, it basically allows us to write the try/catch once and apply it to all handlers, right?

Looking into this a little deeper, what I really want is to add tags to the ActivityEvent being logged here - this way the tags are associated with the exception itself rather than the Activity (which is all we have access to in a try/catch). Any thoughts on how to do that?

[benv-nti]

I tried out the behavior, and it's slightly less useful than I expected. Since the behavior is around/outside the handler, it is also outside of the Activity for the handler. So adding tags to Activity.Current from the behavior adds them to parent activity, associated with processing the message. So if there were multiple handlers, you wouldn't know which one the exception message came from.

Tagging from behavior shows up at the highest level (1).
Tagging from a try/catch in the handler itself shows up at level (2).
Ideally I would like to tag on the exception / ActivityEvent itself (3).

[andreasohlund]

You are right, we have no way of intercepting individual handlers since the terminator is creating the activity context https://github.com/Particular/NServiceBus/blob/master/src/NServiceBus.Core/Pipeline/Incoming/InvokeHandlerTerminator.cs#L18

@lailabougria @danielmarbach I wonder if we should create that activity context in the connector instead https://github.com/Particular/NServiceBus/blob/master/src/NServiceBus.Core/Pipeline/Incoming/LoadHandlersConnector.cs#L44 ?

That would allow users to add to it via a invoke handler behaviour like @benv-nti mentions?

[danielmarbach]

@andreasohlund My understanding was that the original design idea was to have the activity surrounding the invocation of the handler and not the entire part of the pipeline that leads to invoke the handler. What you are suggesting would work but would deviate from that original design decision (if I recall correctly, which might not be the case since I was only tangentially involved).

By looking at the message handling pipeline though, you can argue from an exception perspective, a single handler throwing leads to the entire pipeline being aborted and that is quite likely why the information is centered around the fact that an exception occurred. That being said, even with the current design the handler information would be available over the exception data. While you would still have to set the information on the parent activity, it would give you the desired information (for now, as a workaround)

[andreasohlund]

@benv-nti we've been discussing this internally, and per the current design, your improvement suggestion is valid. We're contemplating if we should move the creation of the handler span into the handler pipeline to make it easier to customize like in the use case you mention.

In the meantime, you could consider replacing the span created by NServiceBus with your own like this:

class CustomHandlerSpanBehavior : Behavior<IInvokeHandlerContext>
{
    static ActivitySource source = new ActivitySource("NServiceBus.Core", "0.1.0");

    public override async Task Invoke(IInvokeHandlerContext context, Func<Task> next)
    {
        var captured = Activity.Current;

        using var activity = source.StartActivity("NServiceBus.Diagnostics.InvokeHandler");

        activity!.DisplayName = context.MessageHandler.HandlerType.Name;
        activity.AddTag("nservicebus.handler.handler_type", context.MessageHandler.HandlerType.FullName);

        try
        {
            // clear ambient activity to prevent the default nservicebus span to be created
            Activity.Current = null;

            await next();

            activity.SetStatus(ActivityStatusCode.Ok);
        }
        catch (Exception ex)
        {
            activity.SetStatus(ActivityStatusCode.Error, ex.Message);
            activity.SetTag("mytag", "myvalue");
            throw;
        }
        finally
        {
            // restore ambient activity
            Activity.Current = captured;
        }
    }
}

It's a bit messy but it will give you full control over the span created for each message handler.

Would that be a valid workaround for you for now?

See #7318 for a full example of doing this.

[benv-nti]

Thanks @andreasohlund, I'll try that out. Just from looking at it, I think it will give us what we need.

[andreasohlund]

With #7319 being released shortly (v9.2.7) this API would no longer be needed since Activity.Current for behaviors in the message handler stage will provide needed access to enrich the handler span

[andreasohlund]

@benv-nti 9.2.7 is now released, and I have verified that you can now use an invoke handler behavior to achieve your use case. Thanks for reporting this ❤