Feature request: Add logging context to a logger instance or code scope

[SweVictor]

Firstly: Great work and extremely useful to quickly implement an eventsource!

Secondly: I hope it's ok to post requests here and not only problems...

So: We have started using EventSourceProxy heavily and really enjoy the way everything is laid out. We have one request though: To be able to add context to a logging instance or to a scope of code. In our case we one process handling multiple objects, each with its own id and metadata. We would like to decorate each request with that id and metadata to make correlating logs easier. What we would like to achieve is something like this:

for (var specificObject in hander.specificObjects) {
  //The initialization would of course be done early to reuse the instance
  var log = EventSourceImplementer.GetEventSourceAs<IMyLogger>();
  log.ForAnything()
        .AddContext("specificObject", () => new {id = specificObject.Id, name = specificObject.Name};

  //Do stuff and log data!
}

or, with scoping, something like

var log = EventSourceImplementer.GetEventSourceAs<IMyLogger>();
for (var specificObject in hander.specificObjects) {
  using (log.ForAnything()
        .AddContext("specificObject", () => new {id = specificObject.Id, name = specificObject.Name};
  ) {
    //Do stuff and log data!
  }
}

In our use case, the first version would be the most preferred one, but both would make a nice improvement compared to adding the metadata to each request. Also it would be nice if keywords/tasks/opcodes could be added or log levels could be adjusted on a per call or per instance level.

Would something like this be feasible to implement?

Thanks in advance! /Victor

[jonwagner]

I'm glad that you're finding success with ESP. Feel free to post feature requests here. I try to regularly check in on all of my projects and take care of new features and issues.

I think we can implement this with:

• A new TraceContext class that's stored on thread state and follows a disposal pattern.
• A TraceParameterProvider that looks up the context from the TraceContext class. This would probably be the default context provider.

It would look like this:

[TraceContext(true)]
interface ILog
{
    void Foo();
}

using (var context = new TraceContext())
{
    context.Add("id", id);  // works like a dictionary
    log.Foo();
}

I can see a few varieties of the code:

new TraceContext(log); // only adds the context to specific log instances
new TraceContext(dictionary); // adds the dictionary to the context
new TraceContext(context); // copies the previous context into the current context

I'll spend some time thinking about this design a bit.

Changing keywords, etc, dynamically because ETW compiles all of them into metadata at the startup of the eventsource. It would treat any change as a different event source.

[SweVictor]

Hi again and thanks for the quick feedback! Also thanks for the insight in how ETW works internally and the limitations of underlying framework!

I would also like to add that we are using (and would like to continue using) the global provider to provide extra context to all instances (info related to the machine and global state mostly) and that we hope to be able to add context to single instances/scopes as well.

In our use-case we will probably be looking at reasonably few (10-100) separate contexts (instances/objects) we would like to enrich, meaning that we probably would prefer to be able to cache the extra context data for each instance in some way. Normally we will have ~100 classes using the same EventSource, and enriching most calls with a few properties relating to the active specific object. Hope any of that made sense! :-)

We also use dependency injection containers quite heavily (Unity in our case, but it would probably look similar in other cases), meaning we would do constructor injection or container.Resolve<IMyLogger>. If the DI container call could be used to inject the context (basically setting constructor parameters or properties in the EventSourceImplementer call, that would probably be the most seemless solution in our case.

Thanks again! /Victor

[jonwagner]

So a better implementation for you would be to have multiple loggers bound to the same EventSource, and to add the context when the loggers are created.

That definitely lends itself to something like:

var context = new Dictionary<string, object>(); var log = EventSourceImplementer.GetEventSourceAs(context); // context is available for all calls to this specific log

And possibly let the context change dynamically:

var context = (ILogContext)log;
context.Add("id", id);

Let me think about this version. ETW forces you to have only be EventSource object per event source, but that doesn't mean that there can't be other proxy loggers to the EventSource.

[SweVictor]

For us, that seems like it would be a lot easier to be able to reuse the context for multiple calls (but not easily correlated in a using scope). Also seems to lend itself pretty well to a DI approach.

To be clear: The last approach seems a lot better to us! :-)

[SweVictor]

I just wanted to check again. We have now used the possibilities with a custom TraceContextProvider a bit more and have two issues with it related to the discussion above:

• The context we provide can change runtime (although rarely) - from what we have gathered it doesn't seem possible to update the provider?
• If the context is a class with multiple properties it has to be serialized, which to us somewhat defeats the idea of semantic logging. We love the possibilities to control logged data with for example TraceParameterProvider.Default.ForAnything().With<SiteInformation>().Trace(s => s.Id).As("Site.Id").Trace(s => s.Name).As("Site.Name") and had hoped a custom TraceContextProvider could provide similar capabilities. Our main endpoint for logging is ElasticSearch and logging "Site.Name = 'abc'" shows up as a nested, searchable, property, while logging "context = '{\"Site.Name\”: \”abc\”}'" is interpreted as a context property with a custom string inside.

Anyway - the core of EventSourceProxy is still great to work with and the Trace().As() and [TraceAs()] constructs are just wonderful!

[jonwagner]

I'm back from vacation, so I have some time to actually work on this.

Right now, the provider is fixed for each instance of the logger, and due to the way ETW works, it's a singleton, so there isn't a really good way to change it on a per-call basis at the moment.

But I do have some design changes that will fix that. Just need to find time to sit down and code a bit.

When it's done, I expect to be able to have per-logger-instance context that can be sent in as either their own parameters or as a context blob.

[jonwagner]

I just can't leave a problem unsolved. Adding this feature to v3.0.5!

You can now use AddContextData when configuring the TraceParameterProvider. It will look up data stored in the TraceContext context bag, which you can define with TraceContext.Begin(). Example below!

        TraceParameterProvider.Default.For<IHaveRichContext>()
            .AddContextData("Site.Id")
            .AddContextData("Site.Name")
            .AddContextData("PID");

        var proxy = EventSourceImplementer.GetEventSourceAs<IHaveRichContext>();

        using (var context = TraceContext.Begin())
        {
            context["PID"] = 1234;

            using (var context2 = TraceContext.Begin())
            {
                context2["Site.Id"] = "Ts1";
                context2["Site.Name"] = "TestSite1";

                proxy.Log("message");
            }
        }

[SweVictor]

Really great to see this implemented, we will for sure use this in the future to remove the need of adding context with every call - fantastic!

[jonwagner]

Just pushed v3.0.5 with this code in it.