NServiceBus.Community.Serilog

Add support for sending NServiceBus logging through Serilog

See Milestones for release notes.

Already a Patron? skip past this section

Community backed

It is expected that all developers become a Patron to use NServiceBus Community Extensions. Go to licensing FAQ

Sponsors

Support this project by becoming a Sponsor. The company avatar will show up here with a website link. The avatar will also be added to all GitHub repositories under the NServiceBusCommunity organization.

Patrons

Thanks to all the backing developers. Support this project by becoming a patron.

NuGet package

https://nuget.org/packages/NServiceBus.Community.Serilog/

Usage

var configuration = new LoggerConfiguration();
configuration.Enrich.WithNsbExceptionDetails();
configuration.WriteTo.File("log.txt");
Log.Logger = configuration.CreateLogger();

LogManager.Use<SerilogFactory>();

^{snippet source | anchor}

Filtering

NServiceBus can write a significant amount of information to the log. To limit this information use the filtering features of the underlying logging framework.

For example to limit log output to a specific namespace.

Here is a code configuration example for adding a Filter.

var configuration = new LoggerConfiguration();
configuration.Enrich.WithNsbExceptionDetails();
configuration
    .WriteTo.File(
        path: "log.txt",
        restrictedToMinimumLevel: LogEventLevel.Debug
    );
configuration
    .Filter.ByIncludingOnly(
        inclusionPredicate: Matching.FromSource("MyNamespace"));
Log.Logger = configuration.CreateLogger();

LogManager.Use<SerilogFactory>();

^{snippet source | anchor}

Tracing

Writing diagnostic log entries to Serilog. Plugs into the low level pipeline to give more detailed diagnostics.

When using Serilog for tracing, it is optional to use Serilog as the main NServiceBus logger. i.e. there is no need to include LogManager.Use<SerilogFactory>();.

Create an instance of a Serilog logger

var configuration = new LoggerConfiguration();
configuration.Enrich.WithNsbExceptionDetails();
configuration.WriteTo.File("log.txt");
configuration.MinimumLevel.Information();
var tracingLog = configuration.CreateLogger();

^{snippet source | anchor}

Configure the tracing feature to use that logger

var serilogTracing = configuration.EnableSerilogTracing(tracingLog);
serilogTracing.EnableMessageTracing();

^{snippet source | anchor}

Contextual logger

Serilog tracing injects a contextual Serilog.Ilogger into the NServiceBus pipeline.

NOTE: Saga and message tracing will use the current contextual logger.

There are several layers of enrichment based on the pipeline phase.

Endpoint enrichment

All loggers for an endpoint will have the property ProcessingEndpoint added that contains the current endpoint name.

Incoming message enrichment

When a message is received, the following enrichment properties are added:

• SourceContext will be the message type FullName extracted from the EnclosedMessageTypes header. UnknownMessageType will be used if no header exists. The same value will be added to a property named MessageType.
• MessageId will be the value of the MessageId header.
• CorrelationId will be the value of the CorrelationId header if it exists.
• ConversationId will be the value of the ConversationId header if it exists.

Handler enrichment

When a handler is invoked, a new logger is forked from the above enriched physical logger with a new enriched property named Handler that contains the FullName of the current handler.

Outgoing message enrichment

When a message is sent, the same properties as described in "Incoming message enrichment" will be added to the outgoing pipeline. Note that if a handler sends a message, the logger injected into the outgoing pipeline will be forked from the logger instance as described in "Handler enrichment". As such it will contain a property Handler for the handler that sent the message.

Ambient LogContext enrichment

While the incoming message is being processed, IncomingMessageId, CorrelationId, and ConversationId are also pushed onto Serilog's ambient LogContext. This lets log events written via the static Log.Logger — including events emitted from code that has no access to context.Logger(), such as third-party library callbacks — carry the same correlation properties as this library's own tracing events.

To opt in, the consumer's logger must be configured with Enrich.FromLogContext(). Without it, the values are still pushed but no enricher consumes them, so the properties will not appear on log events.

var configuration = new LoggerConfiguration();
configuration.Enrich.FromLogContext();
configuration.Enrich.WithNsbExceptionDetails();
configuration.WriteTo.File("log.txt");
Log.Logger = configuration.CreateLogger();

Accessing the logger

The contextual logger instance can be accessed from anywhere in the pipeline via SerilogTracingExtensions.Logger(this IPipelineContext context).

public class HandlerUsingLogger :
    IHandleMessages<TheMessage>
{
    public Task Handle(TheMessage message, HandlerContext context)
    {
        var logger = context.Logger();
        logger.Information("Hello from {@Handler}.");
        return Task.CompletedTask;
    }
}

^{snippet source | anchor}

Log extension methods

IPipelineContext also has extension methods added to expose direct Log* methods

public class HandlerUsingLog :
    IHandleMessages<TheMessage>
{
    public Task Handle(TheMessage message, HandlerContext context)
    {
        context.LogInformation("Hello from {@Handler}.");
        return Task.CompletedTask;
    }
}

^{snippet source | anchor}

Example result of a contextual log entry

Exception enrichment

When an exception occurs in the message processing pipeline, the current pipeline state is added to the exception. When that exception is logged that state can be add to the log entry.

When a pipeline exception is logged, it will be enriched with the following properties:

• ProcessingEndpoint will be the current endpoint name.
• IncomingMessageId will be the value of the MessageId header.
• IncomingTransportMessageId will be the MessageId from the underlying transport if it exist.
• IncomingHeaders will be the value of the Message headers.
• IncomingMessageType will be the message type FullName extracted from the EnclosedMessageTypes header. UnknownMessageType will be used if no header exists.
• CorrelationId will be the value of the CorrelationId header if it exists.
• ConversationId will be the value of the ConversationId header if it exists.
• HandlerType will be type name for the current handler if it exists.
• IncomingMessage will be the value of current logical message if it exists.
• HandlerStartTime the UTC timestamp for when the handler started.
• HandlerFailureTime the UTC timestamp for when the handler threw the exception.

Excluding headers

HeaderAppender.BuildHeaders (used by message audit, saga audit, and exception enrichment) promotes message headers to log event properties. By default a small set of NServiceBus infrastructure headers (EnclosedMessageTypes, ProcessingEndpoint, CorrelationId, ConversationId, NServiceBusVersion, MessageId) is excluded. Additional header names can be added to that exclude set via HeaderAppender.Exclude:

HeaderAppender.Exclude("MyCustomHeader");
HeaderAppender.Exclude("HeaderA", "HeaderB", "HeaderC");

^{snippet source | anchor}

Exclude must be called during application startup, before LogManager.Use<SerilogFactory>(). Once SerilogFactory has been constructed the exclude set is frozen and any subsequent call to Exclude throws InvalidOperationException. This makes the set effectively immutable for the lifetime of the endpoint and eliminates any race between configuration and the running pipeline.

Saga tracing

var serilogTracing = configuration.EnableSerilogTracing(logger);
serilogTracing.EnableSagaTracing();

^{snippet source | anchor}

Example Logs

{
  log: [
    {
      Debug: Serializing message '{0}' with id '{1}', ToString() of the message yields: {2},
      Properties: {
        0: StartSaga, Tests, Version=0.0.0.0, Culture=neutral, PublicKeyToken=ce8ec7717ba6fbb6,
        1: Guid_1,
        2: StartSaga,
        SourceContext: NServiceBus.SerializeMessageConnector
      }
    },
    {
      Information: Sent message {OutgoingMessageType} {OutgoingMessageId}.,
      Properties: {
        ContentType: application/json,
        ConversationId: Guid_2,
        CorrelationId: Guid_1,
        MessageIntent: Send,
        OpenTelemetry.StartNewTrace: False,
        OriginatingEndpoint: SerilogTestsStartSaga,
        OriginatingHostId: Guid_3,
        OriginatingMachine: TheMachineName,
        OutgoingMessage: {
          TypeTag: StartSaga,
          Property: TheProperty
        },
        OutgoingMessageId: Guid_1,
        OutgoingMessageType: StartSaga,
        ProcessingEndpoint: SerilogTestsStartSaga,
        ReplyToAddress: SerilogTestsStartSaga,
        Route: SerilogTestsStartSaga,
        SourceContext: StartSaga
      }
    },
    {
      Information: Hello from {@Saga}. Message: {@Message},
      Properties: {
        ConversationId: Guid_2,
        CorrelationId: Guid_1,
        Handler: TheSaga,
        IncomingMessageId: Guid_1,
        IncomingMessageType: StartSaga,
        IncomingMessageTypeLong: StartSaga, Tests, Version=0.0.0.0,
        Message: {
          TypeTag: StartSaga,
          Property: TheProperty
        },
        ProcessingEndpoint: SerilogTestsStartSaga,
        Saga: TheSaga,
        SourceContext: StartSaga
      }
    },
    {
      Debug: Serializing message '{0}' with id '{1}', ToString() of the message yields: {2},
      Properties: {
        0: BackIntoSaga, Tests, Version=0.0.0.0, Culture=neutral, PublicKeyToken=ce8ec7717ba6fbb6,
        1: Guid_4,
        2: BackIntoSaga,
        ConversationId: Guid_2,
        CorrelationId: Guid_1,
        IncomingMessageId: Guid_1,
        SourceContext: NServiceBus.SerializeMessageConnector
      }
    },
    {
      Information: Sent message {OutgoingMessageType} {OutgoingMessageId}.,
      Properties: {
        ContentType: application/json,
        ConversationId: Guid_2,
        CorrelationId: Guid_1,
        IncomingMessageId: Guid_1,
        IncomingMessageType: StartSaga,
        IncomingMessageTypeLong: StartSaga, Tests, Version=0.0.0.0,
        MessageIntent: Send,
        OpenTelemetry.StartNewTrace: False,
        OriginatingEndpoint: SerilogTestsStartSaga,
        OriginatingHostId: Guid_3,
        OriginatingMachine: TheMachineName,
        OriginatingSagaId: Guid_5,
        OriginatingSagaType: TheSaga,
        OutgoingMessage: {
          TypeTag: BackIntoSaga,
          Property: TheProperty
        },
        OutgoingMessageId: Guid_4,
        OutgoingMessageType: BackIntoSaga,
        ProcessingEndpoint: SerilogTestsStartSaga,
        RelatedTo: Guid_1,
        ReplyToAddress: SerilogTestsStartSaga,
        Route: SerilogTestsStartSaga,
        SourceContext: StartSaga
      }
    },
    {
      Information: Saga execution {SagaType} {SagaId} ({ElapsedTime:N3}s).,
      Properties: {
        ConversationId: Guid_2,
        CorrelationId: Guid_1,
        ElapsedTime: {Scrubbed},
        Entity: {
          TypeTag: TheSagaData,
          Property: TheProperty,
          Id: Guid_5,
          Originator: SerilogTestsStartSaga,
          OriginalMessageId: Guid_1
        },
        FinishTime: {Scrubbed},
        IncomingMessageId: Guid_1,
        IncomingMessageType: StartSaga,
        IncomingMessageTypeLong: StartSaga, Tests, Version=0.0.0.0,
        Initiator: {
          IsSagaTimeout: false,
          MessageId: Guid_1,
          OriginatingMachine: TheMachineName,
          OriginatingEndpoint: SerilogTestsStartSaga,
          MessageType: StartSaga,
          TimeSent: DateTimeOffset_1,
          Intent: Send
        },
        IsCompleted: false,
        IsNew: true,
        ProcessingEndpoint: SerilogTestsStartSaga,
        ResultingMessages: {
          Elements: [
            {
              Id: Guid_4,
              Type: BackIntoSaga,
              Intent: Send,
              Destination: SerilogTestsStartSaga
            }
          ]
        },
        SagaId: Guid_5,
        SagaType: TheSaga,
        SourceContext: StartSaga,
        StartTime: {Scrubbed}
      }
    },
    {
      Information: Receive message {IncomingMessageType} {IncomingMessageId} ({ElapsedTime:N3}s).,
      Properties: {
        ContentType: application/json,
        ConversationId: Guid_2,
        CorrelationId: Guid_1,
        ElapsedTime: {Scrubbed},
        FinishTime: {Scrubbed},
        IncomingMessage: {
          TypeTag: StartSaga,
          Property: TheProperty
        },
        IncomingMessageId: Guid_1,
        IncomingMessageType: StartSaga,
        IncomingMessageTypeLong: StartSaga, Tests, Version=0.0.0.0,
        MessageIntent: Send,
        OpenTelemetry.StartNewTrace: False,
        OriginatingEndpoint: SerilogTestsStartSaga,
        OriginatingHostId: Guid_3,
        OriginatingMachine: TheMachineName,
        OtherHeaders: {
          baggage: {Scrubbed}
        },
        ProcessingEndpoint: SerilogTestsStartSaga,
        ReplyToAddress: SerilogTestsStartSaga,
        Serilog.SagaStateChange: {Scrubbed},
        SourceContext: StartSaga,
        StartTime: {Scrubbed},
        TimeSent: DateTimeOffset_1,
        TraceParent: {Scrubbed}
      }
    },
    {
      Debug:
(IBatchDispatchContext context0) => BatchToDispatchConnector.Invoke(context0, 
    (IDispatchContext context1) => ImmediateDispatchTerminator.Invoke(context1))
,
      Properties: {
        SourceContext: NServiceBus.Pipeline`1[[NServiceBus.Pipeline.IBatchDispatchContext, NServiceBus.Core, Version=10.0.0.0, Culture=neutral, PublicKeyToken=9fc386479f8a226c]]
      }
    },
    {
      Information: Hello from {@Saga}. Message: {@Message},
      Properties: {
        ConversationId: Guid_2,
        CorrelationId: Guid_1,
        Handler: TheSaga,
        IncomingMessageId: Guid_4,
        IncomingMessageType: BackIntoSaga,
        IncomingMessageTypeLong: BackIntoSaga, Tests, Version=0.0.0.0,
        Message: {
          TypeTag: BackIntoSaga,
          Property: TheProperty
        },
        ProcessingEndpoint: SerilogTestsStartSaga,
        Saga: TheSaga,
        SourceContext: BackIntoSaga
      }
    }
  ]
}

^{snippet source | anchor}

Message tracing

Both incoming and outgoing messages will be logged at the Information level. The current message will be included in a property named Message. For outgoing messages any unicast routes will be included in a property named UnicastRoutes.

var serilogTracing = configuration.EnableSerilogTracing(logger);
serilogTracing.EnableMessageTracing();

^{snippet source | anchor}

Example Logs

{
  log: [
    {
      Debug: Serializing message '{0}' with id '{1}', ToString() of the message yields: {2},
      Properties: {
        0: StartHandler, Tests, Version=0.0.0.0, Culture=neutral, PublicKeyToken=ce8ec7717ba6fbb6,
        1: Guid_1,
        2: StartHandler,
        SourceContext: NServiceBus.SerializeMessageConnector
      }
    },
    {
      Information: Sent message {OutgoingMessageType} {OutgoingMessageId}.,
      Properties: {
        ContentType: application/json,
        ConversationId: Guid_2,
        CorrelationId: Guid_1,
        MessageIntent: Send,
        OpenTelemetry.StartNewTrace: False,
        OriginatingEndpoint: SerilogTestsStartHandler,
        OriginatingHostId: Guid_3,
        OriginatingMachine: TheMachineName,
        OutgoingMessage: {
          TypeTag: StartHandler,
          Property: TheProperty
        },
        OutgoingMessageId: Guid_1,
        OutgoingMessageType: StartHandler,
        ProcessingEndpoint: SerilogTestsStartHandler,
        ReplyToAddress: SerilogTestsStartHandler,
        Route: SerilogTestsStartHandler,
        SourceContext: StartHandler
      }
    },
    {
      Information: Hello from {@Handler}.,
      Properties: {
        ConversationId: Guid_2,
        CorrelationId: Guid_1,
        Handler: TheHandler,
        IncomingMessageId: Guid_1,
        IncomingMessageType: StartHandler,
        IncomingMessageTypeLong: StartHandler, Tests, Version=0.0.0.0,
        ProcessingEndpoint: SerilogTestsStartHandler,
        SourceContext: StartHandler
      }
    }
  ]
}

^{snippet source | anchor}

Startup diagnostics

Startup diagnostics is, in addition to its default file location, also written to Serilog with the level of Warning.

class StartupDiagnostics(IReadOnlySettings settings, ILogger logger) :
    FeatureStartupTask
{
    readonly ILogger startupLogger = logger.ForContext<StartupDiagnostics>();

    protected override Task OnStart(IMessageSession session, Cancel cancel = default)
    {
        var properties = BuildProperties(settings, startupLogger);

        var templateParser = new MessageTemplateParser();
        var messageTemplate = templateParser.Parse("DiagnosticEntries");
        var logEvent = new LogEvent(
            timestamp: DateTimeOffset.Now,
            level: LogEventLevel.Warning,
            exception: null,
            messageTemplate: messageTemplate,
            properties: properties);
        startupLogger.Write(logEvent);
        return Task.CompletedTask;
    }

    static IEnumerable<LogEventProperty> BuildProperties(
        IReadOnlySettings settings,
        ILogger logger)
    {
        var entries = settings.ReadStartupDiagnosticEntries();
        foreach (var entry in entries)
        {
            if (entry.Name == "Features")
            {
                continue;
            }

            var name = CleanEntry(entry.Name);
            if (logger.BindProperty(name, entry.Data, out var property))
            {
                yield return property;
            }
        }
    }

    internal static string CleanEntry(string entry)
    {
        if (entry.StartsWith("NServiceBus."))
        {
            return entry[12..];
        }

        return entry;
    }

    protected override Task OnStop(IMessageSession session, Cancel cancel = default) =>
        Task.CompletedTask;
}

^{snippet source | anchor}

Logging to Seq

To log to Seq:

var configuration = new LoggerConfiguration();
configuration.Enrich.WithNsbExceptionDetails();
configuration.WriteTo.Seq("http://localhost:5341");
configuration.MinimumLevel.Information();
var tracingLog = configuration.CreateLogger();

^{snippet source | anchor}

Sample

The sample illustrates how to customize logging by configuring Serilog targets and rules.

Configure Serilog

var configuration = new LoggerConfiguration();
configuration.Enrich.WithNsbExceptionDetails();
configuration.WriteTo.Console();
Log.Logger = configuration.CreateLogger();

^{snippet source | anchor}

var configuration = new LoggerConfiguration();
configuration.Enrich.WithNsbExceptionDetails();
configuration.WriteTo.Seq("http://localhost:5341");
configuration.MinimumLevel.Information();
var logger = configuration.CreateLogger();
var serilogFactory = LogManager.Use<SerilogFactory>();
serilogFactory.WithLogger(logger);

^{snippet source | anchor}

Pass the configuration to NServiceBus

LogManager.Use<SerilogFactory>();

var configuration = new EndpointConfiguration("SerilogSample");

^{snippet source | anchor}

var configuration = new EndpointConfiguration("SeqSample");
var serilogTracing = configuration.EnableSerilogTracing(tracingLog);
serilogTracing.EnableSagaTracing();
serilogTracing.EnableMessageTracing();

^{snippet source | anchor}

Ensure logging is flushed on shutdown

await endpoint.Stop();
Log.CloseAndFlush();

^{snippet source | anchor}

await endpoint.Stop();
Log.CloseAndFlush();

^{snippet source | anchor}

Seq Sample

Illustrates customizing Serilog usage to log to Seq.

Prerequisites

An instance of Seq running one http://localhost:5341.

Configure Serilog

var configuration = new LoggerConfiguration();
configuration.Enrich.WithNsbExceptionDetails();
configuration.WriteTo.Console();
Log.Logger = configuration.CreateLogger();

^{snippet source | anchor}

var configuration = new LoggerConfiguration();
configuration.Enrich.WithNsbExceptionDetails();
configuration.WriteTo.Seq("http://localhost:5341");
configuration.MinimumLevel.Information();
var logger = configuration.CreateLogger();
var serilogFactory = LogManager.Use<SerilogFactory>();
serilogFactory.WithLogger(logger);

^{snippet source | anchor}

Pass that configuration to NServiceBus

LogManager.Use<SerilogFactory>();

var configuration = new EndpointConfiguration("SerilogSample");

^{snippet source | anchor}

var configuration = new EndpointConfiguration("SeqSample");
var serilogTracing = configuration.EnableSerilogTracing(tracingLog);
serilogTracing.EnableSagaTracing();
serilogTracing.EnableMessageTracing();

^{snippet source | anchor}

Ensure logging is flushed on shutdown

await endpoint.Stop();
Log.CloseAndFlush();

^{snippet source | anchor}

await endpoint.Stop();
Log.CloseAndFlush();

^{snippet source | anchor}

Icon

Brain designed by Rémy Médard from The Noun Project.