MinimumLevel.Override not working inside child logger (WriteTo.Logger())

[AR1ES]

Serilog version 2.4.0. Simple demo:

namespace SerilogOverrideErrorDemo {
	class Program {
		static void Main(string[] args) {
			var logBuilder = new LoggerConfiguration()
				.MinimumLevel.Information()
				.WriteTo.Logger(l => l.MinimumLevel.Information().MinimumLevel.Override("SerilogOverrideErrorDemo.Class2", LogEventLevel.Error).WriteTo.LiterateConsole()
				);
			Log.Logger = logBuilder.CreateLogger();
			var l1 = Log.ForContext<Class1>();
			var l2 = Log.ForContext<Class2>();
			l1.Information("Info 1");
			l2.Information("Info 2");
			l1.Error("Error 1");
			l2.Error("Error 2");
			Console.ReadLine();
		}
	}
	class Class1 {
	}
	class Class2 {
	}
}

Output:

[14:06:12 INF] Info 1 - expected
[14:06:13 INF] Info 2 - unexpected
[14:06:13 ERR] Error 1 - expected
[14:06:13 ERR] Error 2 - expected

It works fine if "Override" is placed in rootLoggerConfiguration:

			var logBuilder = new LoggerConfiguration()
				.MinimumLevel.Information()
				.MinimumLevel.Override("SerilogOverrideErrorDemo.Class2", LogEventLevel.Error)
				.WriteTo.LiterateConsole();

[nblumhardt]

Thanks for the report 👍

[johnduhart]

I did some looking on this, and it's a bit tricky. Here's a failing test case I assembled using the original report:

        [Fact]
        public void Issue967()
        {
            var sink = new CollectingSink();
            var logger = new LoggerConfiguration()
                .MinimumLevel.Information()
                .WriteTo.Logger(lc => lc
                    .MinimumLevel.Information()
                    .MinimumLevel.Override("Serilog.Tests", LogEventLevel.Error)
                    .WriteTo.Sink(sink))
                .CreateLogger();

            logger.Write(Some.InformationEvent());
            logger.Write(Some.LogEvent(level: LogEventLevel.Error));

            var contextLogger = logger.ForContext<LoggerConfigurationTests>();
            contextLogger.Write(Some.InformationEvent());
            contextLogger.Write(Some.LogEvent(level: LogEventLevel.Error));

            Assert.Equal(3, sink.Events.Count);
        }

The reason an information log event is propagating to the sink through the contextLogger, is because _overrideMap is only checked at the root logger level when creating a contextual logger, meaning that the log event is emitting directly to the sub-logger.

Should we add additional override checks when emitting to sub-loggers?

[nblumhardt]

Nice job on the test @johnduhart 👍

If we can squirrel this away in sub-logger creation that would be ideal; I'm keen to fix this one, but wouldn't want to incur a performance penalty on the root logger if we can avoid it.

[nblumhardt]

Looking at this now; I think we could do this without an overhead by tweaking the "add override" callback of the LoggerConfiguration created here: https://github.com/serilog/serilog/blob/dev/src/Serilog/Configuration/LoggerSinkConfiguration.cs#L128

But, the other override WriteTo.Logger(ILogger) would need different treatment - we'd need to detect when the logger is actually a Logger, retrieve its _overrideMap, and emit the additional filtering when the map is non-empty.

All possible, I think, but will need some careful work supported by tests. Happy to help guide someone through a PR if anyone can get there before I do :-)

[tsimbalar]

It's up-for-grabs , so maybe I'll take a look and try a PR :)

@nblumhardt I'll tell you if I need assistance ;)

[nblumhardt]

@tsimbalar awesome, good luck with it! Feel free to ping me, though it's probably more efficient to just post questions to this thread - there are more people than just me watching and keen to help out :-)