Hook into pipeline for conversation id logging

1

I want to log the ConversationId with every log message that is written within this conversation to be able to group everything together.

We’re using log4net for logging. I assume the solution will be similar for other logging libraries.
I’m setting a property on the logical thread context to capture the conversation id like so

log4net.LogicalThreadContext.Properties["ConversationId"] = conversationId;

Now my goal is to hook into the pipeline as soon as possible, so that messages logged by NServiceBus also get the conversation id assigned and end up having the conversation id as a value in the log message.

I know of the Mutators and Behaviors to hook into the pipeline. I’m just not sure where the best place is to hook into. I also didn’t see a way for me to tell NServiceBus "Hey, I want this behavior to be the first in the pipeline (e.g. for IncomingPhysicalMessage). I know that Mutators don’t have a particular order, so I imagein it would be better to use a Behavior for this.

I came up with this code

public class LogConversationIdBehavior : Behavior<IIncomingPhysicalMessageContext>
{
    public override Task Invoke(IIncomingPhysicalMessageContext context, Func<Task> next)
    {
        string conversationId = context.MessageHeaders[Headers.ConversationId];
        log4net.LogicalThreadContext.Properties["ConversationId"] = conversationId;
        return next();
    }
}

and

endpointConfiguration.Pipeline.Register(new LogConversationIdBehavior(), "Adds the conversation id to the logging context");

to register it.

In the docs I understand that ITransportReceiveContext is coming even earlier in the pipeline, but due to its purpose I’m very hesitant in implementing it as a behavior in this stage.

I also read about how this could be done with Serilog https://docs.particular.net/nservicebus/logging/serilog. But as I understand this approach is specific to Serilog.

My questions:

  1. According to the documentation every message has the Headers.ConversationId header set, so I can safely access the key in the dictionary without checking, right?
  2. Where is the best (intended) way to hook into the incoming pipeline?
  3. I don’t need to hook into the outgoing pipeline because everything is happening inside the same logical thread context? Unless I manually add some parallel processing of course.
2
  1. You should not rely on the ConversationId header being set. It’s possible that some other external integration point could be set up to send messages to this endpoint and you probably do not want the message to fail processing if this header is not present, which is what will happen if your behavior throws an exception. This will trigger immediate and delayed retries until finally the message ends up in the error queue. Depending on your situation, this may be appropriate and desired. I leave that up to you.
  2. I can’t think of a good reason that you shouldn’t set up in the ITransportReceiveContext. It has the IncomingMessage, including the headers, so if you want to look for conversation id here, you can. This will guarantee that your behavior executes before the behaviors in the Incoming Logical/Physical Message contexts. The best way to set up your behavior is with a feature. If you create a feature and enable it by default, then it will get installed as long as the type scanner picks it up.
  3. You are correct. As long as you are awaiting outgoing sends, publishes, and replies properly (which you need to anyway) then the context should flow through from the incoming message. If you do anything from a background thread then you are no longer in the same context, so there is no incoming message to deal with anyway.

Let me know if you have any more questions.

3

You probably would want to log the message identifier too:

I also once wrote a similar extension for NLog:

1 Like
4

@ramonsmits

If added it as a ITransportReceiveContext behavior as outlined by you in your reply.
It works fine for all the logs that are written using ILog.Debug etc. inside a message handler, BUT: the exceptions logged by NServiceBus when handling a message fails do not have this info anymore.

2019-07-11 11:19:22,946 INFO  testing [ConversationId=db920bc0-da76-4ce3-8f95-7b7978e2542a;MessageId=7198c610-0d34-4570-a203-aa8700ba79f1] Logging from within the message handler
2019-07-11 11:19:23,973 INFO  testing [ConversationId=db920bc0-da76-4ce3-8f95-7b7978e2542a;MessageId=7198c610-0d34-4570-a203-aa8700ba79f1] Logging from within the message handler
2019-07-11 11:19:24,987 WARN  NServiceBus.RecoverabilityExecutor [(null)] Delayed Retry will reschedule message '7198c610-0d34-4570-a203-aa8700ba79f1' after a delay of 00:00:10 because of an exception:

System.Exception: Exception inside message handler

I understand why it doesn’t have this info. Of course when an exception inside the using occurs, it will remove the previously pushed context.

I wonder, is there a way I can make sure this info will be on those exception logs as well? e.g. by hooking into the pipeline differently? Having this info in these logs as well, would make log analysis simpler.

5

Hi Philipp

I don’t think you can hook into the pipeline and do this properly because the recoverability part is executed outside the pipeline so the using scope doesn’t apply anymore.

I was thinking you might be able to do a trickery with the recoverability policy but the problem is while you could log something there with the appropriate ids the recoverability policy doesn’t spawn the log statements of the recoverability executor. So those log statements would still be “misplaced” for you and not contain that information.

Regards
Daniel

6

Hi Daniel,

thank you for your reply. Maybe there is a way to customize the log messages that are written by the recoverability executor? Otherwise we can live with the current limitation.

Regards,
Philipp

7

Hi Philipp

Given that those loggers are static we would need to somehow lift all the logging up to DI entirely in NServiceBus and I’m not sure we’d be able to pull this off at this stage.

You could try to write your own LogManager and factory that wraps an existing one but it would still be tricky to put the right context at the right point in time into the wrapping log manager. See for example https://github.com/Particular/NServiceBus/blob/develop/src/NServiceBus.Testing.Fakes/TestingLoggerFactory.cs

TBH it sounds like a lot of effort and complex code to manage and I’d have a hard time to justify this given that Particular provides tooling like ServiceInsight that allows you to immediately filter a while message conversation based on an ID.

Regards
Daniel