EventSource implementation

[cwe1ss]

Hi, I created a logger implementation which forwards messages to a System.Diagnostics.Tracing.EventSource and was wondering if this would be interesting for you since EventSource is one of the recommended ways to log in the .NET framework.

https://github.com/cwe1ss/Logging/tree/EventSource/src/Microsoft.Extensions.Logging.EventSource

it has the following features:

• it's a general purpose EventSource called "LoggingEventSource" with the name "Microsoft-Extensions-Logging"
• it has events for every log level (Trace, Debug, ...)
• ILogger.BeginScopeImpl is implemented by calling an ActivityStart and ActivityStop event on the EventSource (which automatically creates an ActivityId)
• ILogValues from the state parameter are stored as a JSON serialized dictionary called "Properties". Right now this uses Newtonsoft.Json - In .NET 4.6 this could be changed to the "rich payload" feature, however most tools seem to not yet support this (Semantic Logging Application Block; Visual Studio "Diagnostic Events" window [from the Azure Service Fabric SDK])
• Exception details are also added as separate properties to this dictionary

If this is interesting for you, I'd be happy to do necessary changes and create a pull request.

@vancem - feedback would be appreciated!

best regards, christian

[muratg]

@lodejard @Eilon @davidfowl

[muratg]

@vancem any updates?

[vancem]

Sorry for the delay. This last week I have been filling in for a lead who is on leave, and there simply are not enough hours in the day. I will take a look at this later today.

[vancem]

This is a straightforward hookup of ILogger to an EventSource. There are many details of exactly how the transformation gets done that are interesting to vet (which is part of the reason it has been taking me a while to give any feedback). Currently all events end up in one EventSource and there is no filtering control at the component level (only the level (volume) control). It also dumps things as JSON which are probably better done as dynamic events. In short, there are issues to resolve. It is fine as something that unblocks someone in the short term, however as a larger standard, I am more concerned.

My main issue is that I would like ILogger data to flow into EventSource automatically, without the need for application developers to explicitly wire up the ILogger to a particular EventSource. There is work on such a thing, and ideally we would use that.

I realize that there is this tradeoff between having something vs waiting for something that is potentially better. We can use this as a fallback, but I would like to see if we can build a more automatic alternative first.

[cwe1ss]

Hi Vance, thank you very much for your review. As always it is greatly appreciated! I share your concerns and would like to add some more input:

Should the library target .NET 4.5 or 4.6?

Damian Edwards said yesterday (ASP.NET Community Standup) that the ASP.NET Core libraries will most likely target .NET 4.5.1 to support Mono. (However, Visual Studio project templates might target .NET 4.6) As far as I understand, having dynamically defined events and rich payload data requires targeting .NET 4.6.

Would you target .NET 4.6 with a library like this or would you want to target 4.5.1 to stay consistent with other ASP.NET Core libraries? Since there isn't any real counterpart to ETW on Linux (afaik), targeting 4.6 might not be an issue anyway, right?!

Using multiple EventSources

I think it's definitely necessary to have some sort of categorization for loggers. However, I think there is a very big difference between the current ILogger implementation and multiple EventSources. If I understand it correctly, the current ILogger system acts like an opt-out system. Everyone (every middleware, every 3rd party, ...) can create its own ILogger with a separate logger name. As an application developer you automatically get all events from all created ILoggers. By default you can filter on the minimum level. Some outputs (Console) also allow you to filter ILogger names like namespaces. This basically means, if you don't want to see something, you have to disable it. (Or in other words, you can't miss something (like errors) unless you disable it)

With multiple EventSources however, it is the opposite. If you configure it in your application you explicitly have to define each EventSource you want to subscribe to. Depending on the amount of libraries you use, it might be a very long list and it also might be very hard to even find out which names exist. This means, if you want to log all errors in an application you easily might miss some.
This is very similar to the current situation where there are many different logger abstractions: if you don't know that library X uses the logger Y (Serilog, LibLog, Castle ILogger, ...) you just miss all events.

In our previous email discussion you said that in-process EventListeners get a callback whenever an EventSource is created. This means it would be possible for something like the Semantic Logging project to do similar namespace-like filtering ("e.g. I want to log all "Microsoft.*" logs). However, it's harder with out-of-process solutions. I'm afraid that this means we have to specify each EventSource name in solutions like Azure Diagnostics. This seems like an inconvenient way because whenever you need to change the configuration, you have to do a redeployment. There might just be too many interesting EventSources.

Lack of tooling support for .NET 4.6 ETW features

Semantic Logging seems to be one of the best libraries for EventSource. However it doesn't support some of the new features that were introduced in .NET 4.6. I know that this is a temporary issue and can (and hopefully will) be fixed, I just want to point it out again.
The same is valid for the new "Diagnostic Events" window in Visual Studio that comes with the Azure Service Fabric SDK. This is a great tool for debugging ASP.NET applications locally and it would be great if it would support the new EventSource features. I also think that this windows should be moved to the core of Visual Studio. This would be a great improvement!

Disclaimer: my main scenario
To put my points into perspective, I'd like to explain our scenario a bit. We only do server-side development with ASP.NET applications, windows services, console applications, ... We don't want to do any debugging/tracing directly on the servers (so perfmon, ... isn't usable for us). Instead, we want to import all interesting log entries into a central logging system (e.g. the ELK stack). The EventSource->ELK configuration on the servers/in the applications should change very rarely. Therefore it's ok for us to send a lot of data to ELK and do the filtering there (do debug issues that happened in the past). This should allow us to resolve most of the issues with the log entries we send to ELK all the time. We are mainly interested in application logs and less in lower-level ETW events from windows.
We use Azure Service Fabric so there is some out-of-proc ETW processing. In-Proc processing for our own applications would be fine.

Next steps
I'd really like to see this topic improved in the future. Is there anything I can help with?

[lodejard]

The result is that I can build a new method 'on the fly' at the call site. Note that this is not 'complete dynamic' because anonymous types cannot be generated at runtime (the C# compile still needs to generate a type definition at compile time), but it does get you most of the way. EventSource goes one step further and allows you to define the EventSource itself on the fly. Thus you could do

EventSource Logger = new EventSource("MinimalEventSource");

Logger.Write("Load", new { ImageBase=10L, Name="AFile.dll" } );

@vancem Do you know if there is a way to use the EventSource to log dynamic events which are not rooted by a compile-time type? I guess it would be possible to ref-emit a Type at runtime to reach the new Write feature.

[cwe1ss]

I'm closing this since there is a newer PR for EventSource in #424

[Eilon]

The PR is out, but we use issues to create release notes 😄

[Eilon]

But thanks for pinging on this bug, otherwise we'd have forgotten!

[muratg]

@karolz-ms are you tracking this bug (and #424) for RTM still? Please note that we have little time left before the ask mode. :)

[karolz-ms]

@muratg I am trying to get 424 ready for RTM and I am aware of the scheduling. But as they say it ain't ready till it is ready and there are still some issues...

[muratg]

@karolz-ms Agreed! :)

Putting in 1.0.1 for now. If it's ready in a reasonable time, we'll bring it back to 1.0.0.

[muratg]

@karolz-ms, @BrennanConroy was talking about some issues with .NET 4.5.*. Could you guys sync-up?

[BrennanConroy]

We did :) working on next steps

[Eilon]

Should this bug be assigned to someone?

[BrennanConroy]

Yeah, me or somone of your choosing

[Eilon]

I choose you? :pokemon:

[BrennanConroy]

Looks like @muratg chose me :P

[Eilon]

I never said I was good at :pokemon: 😄

[BrennanConroy]

62265c0