Skip to content

Latest commit

 

History

History
762 lines (627 loc) · 27.6 KB

readme.md

File metadata and controls

762 lines (627 loc) · 27.6 KB
Raw

NServiceBus.Serilog

Build status NuGet Status

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 either become a Patron to use NServiceBusExtensions. 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 NServiceBusExtensions organization.

Patrons

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

NuGet package

https://nuget.org/packages/NServiceBus.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:

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.

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.

Saga tracing

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

snippet source | anchor

Example Logs

{
  logsForTarget: [
    {
      MessageTemplate: Hello from {@Saga}. Message: {@Message},
      Level: Information,
      Properties: {
        ConversationId: Guid_1,
        CorrelationId: Guid_2,
        Handler: TheSaga,
        IncomingMessageId: Guid_2,
        IncomingMessageType: StartSaga,
        IncomingMessageTypeLong: StartSaga, Tests, Version=0.0.0.0,
        Message: {
          TypeTag: StartSaga,
          Properties: [
            {
              Property: TheProperty
            }
          ]
        },
        ProcessingEndpoint: SerilogTestsStartSaga,
        Saga: TheSaga,
        SourceContext: StartSaga
      }
    },
    {
      MessageTemplate: Receive message {IncomingMessageType} {IncomingMessageId} ({ElapsedTime:N3}s).,
      Level: Information,
      Properties: {
        ContentType: text/xml,
        ConversationId: Guid_1,
        CorrelationId: Guid_2,
        ElapsedTime: {Scrubbed},
        FinishTime: DateTimeOffset_1,
        IncomingMessage: {
          TypeTag: StartSaga,
          Properties: [
            {
              Property: TheProperty
            }
          ]
        },
        IncomingMessageId: Guid_2,
        IncomingMessageType: StartSaga,
        IncomingMessageTypeLong: StartSaga, Tests, Version=0.0.0.0,
        MessageIntent: Send,
        OriginatingEndpoint: SerilogTestsStartSaga,
        OriginatingHostId: Guid_3,
        OriginatingMachine: TheMachineName,
        ProcessingEndpoint: SerilogTestsStartSaga,
        ReplyToAddress: SerilogTestsStartSaga,
        Serilog.SagaStateChange: {Scrubbed},
        SourceContext: StartSaga,
        StartTime: DateTimeOffset_2,
        TimeSent: DateTimeOffset_3
      }
    },
    {
      MessageTemplate: Saga execution {SagaType} {SagaId} ({ElapsedTime:N3}s).,
      Level: Information,
      Properties: {
        ConversationId: Guid_1,
        CorrelationId: Guid_2,
        ElapsedTime: {Scrubbed},
        Entity: {
          TypeTag: TheSagaData,
          Properties: [
            {
              Property: TheProperty
            },
            {
              Id: Guid_4
            },
            {
              Originator: SerilogTestsStartSaga
            },
            {
              OriginalMessageId: Guid_2
            }
          ]
        },
        FinishTime: DateTimeOffset_4,
        IncomingMessageId: Guid_2,
        IncomingMessageType: StartSaga,
        IncomingMessageTypeLong: StartSaga, Tests, Version=0.0.0.0,
        Initiator: {
          Elements: {
            "IsSagaTimeout": false,
            "MessageId": Guid_2,
            "OriginatingMachine": TheMachineName,
            "OriginatingEndpoint": SerilogTestsStartSaga,
            "MessageType": StartSaga,
            "TimeSent": DateTimeOffset_5,
            "Intent": Send
          }
        },
        IsCompleted: false,
        IsNew: true,
        ProcessingEndpoint: SerilogTestsStartSaga,
        ResultingMessages: {
          Elements: [
            {
              Elements: {
                "Id": Guid_5,
                "Type": BackIntoSaga,
                "Intent": Send,
                "Destination": SerilogTestsStartSaga
              }
            }
          ]
        },
        SagaId: Guid_4,
        SagaType: TheSaga,
        SourceContext: StartSaga,
        StartTime: DateTimeOffset_6
      }
    },
    {
      MessageTemplate: Sent message {OutgoingMessageType} {OutgoingMessageId}.,
      Level: Information,
      Properties: {
        ContentType: text/xml,
        ConversationId: Guid_1,
        CorrelationId: Guid_2,
        MessageIntent: Send,
        OriginatingEndpoint: SerilogTestsStartSaga,
        OriginatingHostId: Guid_3,
        OriginatingMachine: TheMachineName,
        OutgoingMessage: {
          TypeTag: StartSaga,
          Properties: [
            {
              Property: TheProperty
            }
          ]
        },
        OutgoingMessageId: Guid_2,
        OutgoingMessageType: StartSaga,
        ProcessingEndpoint: SerilogTestsStartSaga,
        ReplyToAddress: SerilogTestsStartSaga,
        SourceContext: StartSaga,
        UnicastRoutes: {
          Elements: [
            SerilogTestsStartSaga
          ]
        }
      }
    },
    {
      MessageTemplate: Sent message {OutgoingMessageType} {OutgoingMessageId}.,
      Level: Information,
      Properties: {
        ContentType: text/xml,
        ConversationId: Guid_1,
        CorrelationId: Guid_2,
        IncomingMessageId: Guid_2,
        IncomingMessageType: StartSaga,
        IncomingMessageTypeLong: StartSaga, Tests, Version=0.0.0.0,
        MessageIntent: Send,
        OriginatingEndpoint: SerilogTestsStartSaga,
        OriginatingHostId: Guid_3,
        OriginatingMachine: TheMachineName,
        OriginatingSagaId: Guid_4,
        OriginatingSagaType: TheSaga,
        OutgoingMessage: {
          TypeTag: BackIntoSaga,
          Properties: [
            {
              Property: TheProperty
            }
          ]
        },
        OutgoingMessageId: Guid_5,
        OutgoingMessageType: BackIntoSaga,
        ProcessingEndpoint: SerilogTestsStartSaga,
        RelatedTo: Guid_2,
        ReplyToAddress: SerilogTestsStartSaga,
        SourceContext: StartSaga,
        UnicastRoutes: {
          Elements: [
            SerilogTestsStartSaga
          ]
        }
      }
    }
  ]
}

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

{
  logsForTarget: [
    {
      MessageTemplate: Hello from {@Handler}.,
      Level: Information,
      Properties: {
        ConversationId: Guid_1,
        CorrelationId: Guid_2,
        Handler: TheHandler,
        IncomingMessageId: Guid_2,
        IncomingMessageType: StartHandler,
        IncomingMessageTypeLong: StartHandler, Tests, Version=0.0.0.0,
        ProcessingEndpoint: SerilogTestsStartHandler,
        SourceContext: StartHandler
      }
    },
    {
      MessageTemplate: Receive message {IncomingMessageType} {IncomingMessageId} ({ElapsedTime:N3}s).,
      Level: Information,
      Properties: {
        ContentType: application/json,
        ConversationId: Guid_1,
        CorrelationId: Guid_2,
        ElapsedTime: {Scrubbed},
        FinishTime: DateTimeOffset_1,
        IncomingMessage: {
          TypeTag: StartHandler,
          Properties: [
            {
              Property: TheProperty
            }
          ]
        },
        IncomingMessageId: Guid_2,
        IncomingMessageType: StartHandler,
        IncomingMessageTypeLong: StartHandler, Tests, Version=0.0.0.0,
        MessageIntent: Send,
        OriginatingEndpoint: SerilogTestsStartHandler,
        OriginatingHostId: Guid_3,
        OriginatingMachine: TheMachineName,
        ProcessingEndpoint: SerilogTestsStartHandler,
        ReplyToAddress: SerilogTestsStartHandler,
        SourceContext: StartHandler,
        StartTime: DateTimeOffset_2,
        TimeSent: DateTimeOffset_3
      }
    },
    {
      MessageTemplate: Sent message {OutgoingMessageType} {OutgoingMessageId}.,
      Level: Information,
      Properties: {
        ContentType: application/json,
        ConversationId: Guid_1,
        CorrelationId: Guid_2,
        MessageIntent: Send,
        OriginatingEndpoint: SerilogTestsStartHandler,
        OriginatingHostId: Guid_3,
        OriginatingMachine: TheMachineName,
        OutgoingMessage: {
          TypeTag: StartHandler,
          Properties: [
            {
              Property: TheProperty
            }
          ]
        },
        OutgoingMessageId: Guid_2,
        OutgoingMessageType: StartHandler,
        ProcessingEndpoint: SerilogTestsStartHandler,
        ReplyToAddress: SerilogTestsStartHandler,
        SourceContext: StartHandler,
        UnicastRoutes: {
          Elements: [
            SerilogTestsStartHandler
          ]
        }
      }
    }
  ]
}

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
{
    protected override Task OnStart(IMessageSession session, Cancel cancel = default)
    {
        var properties = BuildProperties(settings, logger);

        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);
        logger.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;

    ILogger logger = logger.ForContext<StartupDiagnostics>();
}

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.