Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

ForContext() Extension Method Generate Context Trees and Layered Adapter #33

Merged
merged 1 commit into from
Oct 18, 2017

Conversation

arturosevilla
Copy link
Contributor

@arturosevilla arturosevilla commented Oct 9, 2017

This changeset models Serilog's ForContext() behavior for the provided extension method. For example,

var logger1 = _logger.ForContext("CorrelationId", "some-id");
logger.Info("Some message");
...
var logger2 = logger1.ForContext("InstanceId", "some-other-id");
logger2.Info("Some other message");

With Serilog, we would expect that logger1 would have a property CorrelationId, but not InstanceId, and logger2 would have both.

The current implementation of ForContext() extension method does not allow for this behavior if the ILoggingAdapter is used as recommended in Akka.net's documentation as a class field/variable: http://getakka.net/articles/utilities/logging.html#how-to-log

For example, the following code would throw an exception depending on how messages are received:

public class SomeActor : ReceiveActor
{
    private readonly ILoggingAdapter _logger = Context.GetLogger<SerilogLoggingAdapter>();
    public SomeActor()
    {
        Receive<MessageA>(msg => Handle(msg));
        Receive<MessageB>(msg => Handle(msg));
    }

    public void Handle(MessageA msg)
    {
        var logger = _logger.ForContext("CorrelationId", Guid.NewGuid().ToString());
        logger.Info("Received MessageA");
        Self.Tell(new MessageB());
    }
    public void Handle(MessageB msg)
    {
        var logger = _logger.ForContext("CorrelationId", Guid.NewGuid().ToString());
        logger.Info("Received MessageB");
    }
}

If MessageB would be received by the actor first, then no issue would arise, however, if MessageA is sent then the correlation ID property would be set, but then a MessageB would be sent to itself, and the ForContext() extension method would fail as the internal storage (dictionary) would have already such property, even though if a programmer used to Serilog behavior would see this code as valid (the ForContext() should generate its own context).

Just like Serilog's ForContext(), the ForContext() extension method
generates a new logging adapter instance which has as context the given
property values. This means that other calls to ForContext() will generate
a new context in which the new value will not be pushed into other
previously generated logging contexts.
@Danthar
Copy link
Member

Danthar commented Oct 10, 2017

The reasons the docs describe that you need to assign it to a private member variable, is because retrieving a logger instance, has more overhead then you might think. Its not alot, but still its more then just creating a new logger instance.

However in your example, this issue at hand could easily be circumvented by creating a new logger instance on each message.

I understand why you'd want this change. But i'd have to think about it some more, meaning, if this is the way we want the api to behave that is.

@arturosevilla
Copy link
Contributor Author

You are right, in fact right now my message handlers look something like this:

public class SomeActor : ReceiveActor
{
    private readonly ILoggingAdapter _logger = Context.GetLogger<SerilogLoggingAdapter>();
    public SomeActor()
    {
        Receive<MessageA>(msg => Handle(msg));
        Receive<MessageB>(msg => Handle(msg));
    }

    public void Handle(MessageA msg)
    {
        var logger = Context.GetLogger<SerilogLoggingAdapter>().ForContext("CorrelationId", Guid.NewGuid().ToString());
        logger.Info("Received MessageA");
        Self.Tell(new MessageB());
    }
    public void Handle(MessageB msg)
    {
        var logger = Context.GetLogger<SerilogLoggingAdapter>().ForContext("CorrelationId", Guid.NewGuid().ToString());
        logger.Info("Received MessageB");
    }
}

But, in my opinion, this feels more like a fix than how it should normally behave.

The reasons I believe the behavior introduced by this PR is correct are the following:

  1. When using Serilog, or Akka.Net logging (without this Serilog adapter), you usually put the logger as private class field, because, as you said it, the creating of the log involves some overhead. You can also see this behavior with other loggers like log4net. So, it is not atypical to create the logger as a class field.
  2. The expected behavior of the ILogger returned by Serilog's ForContext() does not match the current implementation of the ForContext() extension method, even though, it seems that it should: same name, and same purpose.

@Danthar
Copy link
Member

Danthar commented Oct 18, 2017

@arturosevilla Would you mind doing a PR on the main akka.net repo to update the serilog docs. And providing a small explanation of how to use the ForContext() and how it behaves ?

@Danthar Danthar merged commit de33d22 into akkadotnet:dev Oct 18, 2017
@arturosevilla
Copy link
Contributor Author

@Danthar Not at all. I will start working on that.

@arturosevilla
Copy link
Contributor Author

@Danthar Do you know when these changes will be published into a Nuget package?

@arturosevilla arturosevilla deleted the avoid-forcontext-leak branch October 19, 2017 20:55
@Danthar
Copy link
Member

Danthar commented Oct 25, 2017

Soon. We are prepping a 1.3.3 release. I plan release an update for this plugin shortly thereafter

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants