Improve compatibility with Serilog

[nblumhardt]

This PR improves support for Serilog as a logging target. The changes are in the Microsoft.Framework.Logging.Serilog adapter only.

There are a few changes rolled up here; I'm happy to split/squash/etc. as needed but thought I'd get the ball rolling and some feedback first.

The PR:

1. Fixes support for the ASP.NET Debug level and avoids a NotSupportedException
2. Uses the Serilog pipeline for message template formatting
3. Uses the Serilog pipeline for exception processing
4. Updates the Serilog package dependency to 1.5 (latest)

Of these, 1 & 4 are fairly self-explanatory - details of 2 & 3 below.

Message template formatting

ASP.NET Logging supports "Serilog-style {Message} templates" but uses its own formatting infrastructure to process these. In console/file output the difference is pretty much indistinguishable, but elsewhere this makes for a second-class Serilog experience.

Here's a "before" shot of the sample app, using the Literate Console sink which colors output via type information:

All of the messages show in blue because they're just strings; the "after" shot shows the difference, especially in the second message:

The example shows a cosmetic difference - it's nice to have a guide to what parts of a log event are going to be easily queryable later on - but other impacts are more fundamental to Serilog's usability.

For example, it's intended a Serilog user can silence an unwanted event with code like:

    .Filter.ByExcluding(le => {
        return le.MessageTemplate.Text == "Very {Noisy} Event";
    })

In effect:

the message template is Serilog's internal representation of the event type

The unmodified integration does not support this because all events use the same "{Message:l}" template.

The change made here to fix this does so by ignoring ASP.NET's built-in formatting; good compatibility with Serilog seems like a reasonable trade-off here.

(Sinks that are bandwidth-constrained will also benefit from removing the duplicated copy of each element of the message.)

Exception processing

Serilog has its own processing pipeline that allows users to serialize/interrogate exceptions for their own purposes, and many sinks have special handling for exceptions attached to log events. (You can see a trivial case again in the screenshots above.)

The unmodified integration formats the exception into the message text, and adds some helper properties to get back some of the structured exception data. This bloats the log event payload, and will also create headaches for log searches when some of an application's exceptions are logged via the standard property, and some use the ones introduced by ASP.NET.

The PR removes this and passes the exception through as-is, an approach enabled by the move away from built-in formatting discussed above.

Caveats

The change to property enrichment filters out the"{OriginalFormat}" property while stacking ForContext() calls; I don't think this will perform measurably worse than the eariler enricher-based version, but if optimization has been done here I can take it back in the custom-enricher direction

Anyone already dependent on the "Exception", "ExceptionMessage" and "ExceptionType" properties can get them back by adding the enricher below:

class AspNetStyleExceptionEnricher : ILogEventEnricher
{
    public void Enrich(ILogEvent logEvent, ILogEventPropertyFactory propertyFactory)
    {
        if (logEvent.Exception == null)
        {
            return;
        }

        logEvent.AddPropertyIfAbsent(propertyFactory.CreateProperty(
                    "Exception",
                    exception.ToString()));

        logEvent.AddPropertyIfAbsent(propertyFactory.CreateProperty(
                    "ExceptionType",
                    exception.GetType().FullName));

        logEvent.AddPropertyIfAbsent(propertyFactory.CreateProperty(
                    "ExceptionMessage",
                    exception.Message));
    }
}

[dnfclas]

Hi @nblumhardt, I'm your friendly neighborhood .NET Foundation Pull Request Bot (You can call me DNFBOT). Thanks for your contribution!

In order for us to evaluate and accept your PR, we ask that you sign a contribution license agreement. It's all electronic and will take just minutes. I promise there's no faxing. https://cla2.dotnetfoundation.org.

TTYL, DNFBOT;

[nblumhardt]

• Travis build seems to have failed in dnu pack but the error isn't related to anything I can see in the PR?
• CLA signed an hour or so ago :)

[dnfclas]

@nblumhardt, Thanks for signing the contribution license agreement so quickly! Actual humans will now validate the agreement and then evaluate the PR.

Thanks, DNFBOT;

[davidfowl]

@nblumhardt Ideally, this package wouldn't live in this repository. We did it to bootstrap the effort and validate our design. We want 3rd parties to own their logging components and extensions for the ILogger system. Do you think we could move this code over to the serilog org/repo?

[nblumhardt]

Hey @davidfowl - that would be great; let me chat with the other Serilog project folks about the best place to bring it over.

I'd be happy to PR lifting it out, since I have this shiny new CLA burning a hole in my pocket..? :-)

[davidfowl]

Yep!

[Eilon]

@nblumhardt if you can make a new home for the Serilog adapter we'd be happy to link to it from the Logging readme (or, of course, send a PR for that 😄 ).

[nblumhardt]

Nearly there! An initial version of the package is on NuGet. Instructions and so forth are in the README at https://github.com/serilog/serilog-framework-logging

Couple of notes:

The most significant change is to the signature of UseSerilog() - it now accepts a Serilog.ILogger rather than a LoggerConfiguration. This is to allow framework and non-framework code to use the same logging pipeline.

If the ILogger is not passed, Serilog's default static Log will be used, so the simplest configuration now looks like:

// Set up Serilog
Log.Logger = new LoggerConfiguration().CreateLogger();

// Configure `m.f.Logging`
loggerFactory.UseSerilog();

Other than that, usage is the same, and output is pretty similar to what's in the PR branch.

One rough edge I'd love to avoid is the need to re-specify levels on both the Serilog and framework loggers. I am considering having:

loggerFactory.UseSerilog();

"Inherit" the Serilog level and apply it to the framework logger. I'm sure there are other options.

One last thing - is this pattern considered reasonable in ASP.NET code today?

Using string.Format() directly:

if (_logger.IsEnabled(LogLevel.Verbose))
{
    _logger.LogVerbose(string.Format("Copying file {0} to the response body", fileContext.SubPath));
}

instead of delegating to the logger:

if (_logger.IsEnabled(LogLevel.Verbose))
{
    _logger.LogVerbose("Copying file {0} to the response body", fileContext.SubPath);
}

means that event type and property information (e.g. SubPath) isn't available through the logging pipeline.

[nblumhardt]

Ah, sorry - the mistake is in my comment. AddSerilog() is the method name 👍

[davidfowl]

We've been moving more code to delegate to not call string.Format explicitly. That's leftover from before we had those methods.

[nblumhardt]

Closing this PR, will open another for the sample removal and the wiki entry. Thanks @davidfowl and @Eilon for the input!

[davidfowl]

@nblumhardt open up the repo for bugs.

[nblumhardt]

Done - # 1 is all yours: https://github.com/serilog/serilog-framework-logging/issues

[yaroslav-rudchenko]

Hey guys
Is it possible to set up serilog for azure function project?

[Eilon]

Hi, it looks like you are posting on a closed issue/PR/commit!

We're very likely to lose track of your bug/feedback/question unless you:

1. Open a new issue
2. Explain very clearly what you need help with
3. If you think you have found a bug, include detailed repro steps so that we can investigate the problem.