SerilogLoggerFactory and AddProvider() infrastructure

[nblumhardt]

For #130

The Sample project uses the new LoggerProviderCollection/WriteTo.Providers() mechanism to send events back through dynamically-added providers, and providers registered in IoC.

If you run it you'll see interleaved madness, because the two console sinks aren't synchronized (not really a realistic use case):

Commenting out the Serilog console sink, you'll see what we end up with from the MEL console provider:

And commenting out AddConsole() will get you just Serilog's sink:

A lot is sketchy/TODO (too much to list here!), but - every log event raised through any interface, both Serilog loggers and MEL loggers, goes through the exact same (Serilog) pipeline, uses the same level controls and filters, and ends up at the same sinks/providers.

Ergonomics should be able to be improved at a higher level, in packages like Serilog.AspNetCore/the hosting equivalent.

[merbla]

Be interesting to push this thru the pipe to flush any performance implications. Should be minimal as it is representative of another sink.

[nblumhardt]

Thanks for the 👀, @merbla.

I don't think it's ready for wider consumption just yet, there are a few things to hash out (such as how to make sure the state object we pass through to the provider is maximally useful for it), but the amount of code shouldn't be huge.

I'll have to look into whether named loggers are worth caching - not sure what the default factory does, here, but if they're cached it could turn out that providers rely on this don't optimize for frequent logger creation. A pretty good chance this will be a perf bottleneck.

[nblumhardt]

I've got this to a point now where it works with the default AddConsole() provider (shots above), with the AddSeq() provider:

And with the NReco.Logging.File AddFile() provider:

2019-03-15T10:54:58.4836271+10:00   INFO    [Sample.Program]    [0] Started at 03/15/2019 00:54:58 +00:00 and 0x2A is hex of 42
2019-03-15T10:54:58.5203575+10:00   CRIT    [Sample.Program]    [0] Unexpected critical error starting application
2019-03-15T10:54:58.5243554+10:00   CRIT    [Sample.Program]    [0] Unexpected critical errorSystem.Exception: Boom!
   at Sample.Program.Main(String[] args)

2019-03-15T10:54:58.5253536+10:00   FAIL    [Sample.Program]    [0] Unexpected error
2019-03-15T10:54:58.5253536+10:00   WARN    [Sample.Program]    [0] Unexpected warning
2019-03-15T10:54:58.5303543+10:00   INFO    [Sample.Program]    [0] Waiting for user input
2019-03-15T10:55:00.8609016+10:00   INFO    [Sample.Program]    [0] User pressed { Key: 13, KeyChar: 
 }
2019-03-15T10:55:00.8609016+10:00   INFO    [Sample.Program]    [0] Stopping at 03/15/2019 00:55:00 +00:00
2019-03-15T10:55:00.8609016+10:00   INFO    [Sample.Program]    [0] Stopping
2019-03-15T10:55:00.8609016+10:00   INFO    [Sample.Program]    [0] 

2019-03-15T10:55:00.8619020+10:00   INFO    [Sample.Program]    [0] RESULT         START TIME       END TIME   DURATION(ms)
2019-03-15T10:55:00.8619020+10:00   INFO    [Sample.Program]    [0] ------         ----- ----       --- ----   ------------
2019-03-15T10:55:00.8619020+10:00   INFO    [Sample.Program]    [0] SUCCESS          54:58 AM        55:0 AM      2446.2364

(The sample program produces a very ugly set of logs, it goes waaay back, now - we should probably update it to something more instructive :-D )

Next up, I will:

• [x] Make the implementation a bit less egregiously allocatey
• [ ] Figure out what the user experience, e.g. through helpers like UseSerilog(), should look like
• [x] Write some tests
• [ ] Hook into the configuration story?

[nblumhardt]

See e.g.: https://github.com/opentracing-contrib/csharp-netcore/issues/42

[nblumhardt]

Here's how the OpenTracing contrib provider uses the values passed in via Log(): https://github.com/opentracing-contrib/csharp-netcore/blob/master/src/OpenTracing.Contrib.NetCore/Logging/OpenTracingLogger.cs#L33

We should preserve the OriginalFormatPropertyName for full compatibility with this.

[nblumhardt]

Turns out we were already using FormattedLogValues and thus exposing the original format string. Cleaned things up with a new SerilogLogValues type nonetheless.

There are a lot of perf gains to make, but I think this is ready to go through the wringer now to see where/how it breaks or falls short.

Marked as 3.0.0-* because I think the extended functionality here is pushing into new-major-version territory. This might be re-targeted to a MEL 3.0 release when it's done.

[nblumhardt]

@serilog/reviewers-core anyone keen to dig in? :-)

[nblumhardt]

If no one has time to get up to speed with this, I think we'd be best off sending it to dev and iterating there. This is one part of what should be (I think) a substantial "modernization" of this lib, now that some of the dust seems to be settling around the whole logging story.

Any concerns, let me know, otherwise I'll YOLO it through in a day or two :-)