nblumhardt / serilog-timings

Extends Serilog with support for timed operations
Apache License 2.0
218 stars 22 forks source link

LogContext doesn't become part of message #22

Closed uknickwilliams closed 6 years ago

uknickwilliams commented 6 years ago

When pushing a property to LogContext it is not passed through onto the operation.

Here is a test that fails.

        [Fact]
        public void LogContextPullsThrough()
        {
            var logger = new CollectingLogger();
            Log.Logger = logger.Logger;

            using (LogContext.PushProperty("A", 5))
            {
                var op = Operation.Time("Test should show {A}");
                op.Dispose();

                Assert.Equal(1, logger.Events.Count);

                var message = logger.Events[0].RenderMessage();
                Assert.Contains(5.ToString(), message);
            }

        }
uknickwilliams commented 6 years ago

Forgot to mention I added .Enrich.FromLogContext() to the CollectingLogger constructor

    public class CollectingLogger
    {
        public ILogger Logger { get; }
        public List<LogEvent> Events { get; }

        public CollectingLogger()
        {
            var sink = new CollectionSink();

            Logger = new LoggerConfiguration()
                .Enrich.FromLogContext()
                .MinimumLevel.Is(LevelAlias.Minimum)
                .WriteTo.Sink(sink)
                .CreateLogger();

            Events = sink.Events;
        }
    }
nblumhardt commented 6 years ago

Thanks for the note!

Operation.Time("Test should show {A}") is undefined in Serilog - message template "holes" always need to match the number of parameters provided (zero, here). It may happen to work in some places, but it's unreliable.

You need to use:

                var op = Operation.Time("Test should show {A}", 5);

Hope this helps, and thanks again for opening the ticket 👍

uknickwilliams commented 6 years ago

Yes, I didn't realize this was the case. Thanks.