Logger.BeginScope ToString fails when LoggerProvider without ISupportExternalScope
snakefoot opened this issue · 9 comments
Registering a single LoggerProvider that doesn't implement ISupportExternalScope will now fail in the following code:
using (var scopeState = _logger.BeginScope("{World} People", "Earth"))
{
_logger.LogInformation(scopeState.ToString()); // No longer prints Earth People
}
Bug introduced by #723, because the following optimization was removed:
if (loggers.Length == 1)
return loggers[0].Logger.BeginScope(state);
@snakefoot Can you provide your ILoggerProvider implementation so that we have a repro?
Not sure why you want me to write an ILoggerProvider that doesn't implement ISupportExternalScope, but here is one:
public class TestLoggerProvider : Microsoft.Extensions.Logging.ILoggerProvider
{
private readonly System.Threading.AsyncLocal<IScope> _currentScope = new System.Threading.AsyncLocal<IScope>();
public Microsoft.Extensions.Logging.ILogger CreateLogger(string categoryName)
{
return new TestLogger(categoryName, this);
}
public void Dispose()
{
// Nothing to do
}
private interface IScope : IDisposable
{
}
private class Scope<T> : IScope
{
private readonly TestLoggerProvider _provider;
private bool _isDisposed;
internal Scope(TestLoggerProvider provider, T state, IScope parent)
{
_provider = provider;
State = state;
Parent = parent;
}
public IScope Parent { get; }
public T State { get; }
public override string ToString()
{
return State?.ToString();
}
public void Dispose()
{
if (!_isDisposed)
{
_provider._currentScope.Value = Parent;
_isDisposed = true;
}
}
}
private class TestLogger : Microsoft.Extensions.Logging.ILogger
{
private readonly string _name;
private readonly TestLoggerProvider _provider;
public TestLogger(string name, TestLoggerProvider provider)
{
_name = name;
_provider = provider;
}
public IDisposable BeginScope<TState>(TState state)
{
var parent = _provider._currentScope.Value;
var newScope = new Scope<TState>(_provider, state, parent);
_provider._currentScope.Value = newScope;
return newScope;
}
public bool IsEnabled(Microsoft.Extensions.Logging.LogLevel logLevel)
{
return true;
}
public void Log<TState>(Microsoft.Extensions.Logging.LogLevel logLevel, EventId eventId, TState state, Exception exception, Func<TState, Exception, string> formatter)
{
Console.WriteLine(string.Concat(_name, formatter(state, exception)));
}
}
}
Another one is the NLog-LoggerProvider here: https://www.nuget.org/packages/NLog.Extensions.Logging
Another one is the Log4net-LoggerProvider here: https://www.nuget.org/packages/Microsoft.Extensions.Logging.Log4Net.AspNetCore/
@snakefoot What I want is the thing you used to verify the bug so that we can use it in a unit test and so that we don't have to spend time figuring out what you already know. The more information you provide the better.
@davidfowl Like I said create a LoggerFactory with one LoggerProvider (That doesn't implement ISupportExternalScope ), and then execute the code in the first post. scopeState.ToString() will not be as expected.
Microsoft.Extensions.Logging ver. 2.0 works, but ver. 2.1 fails.
I'm surprised you wanted a new issue for this @davidfowl. The "breaking change" is that Logger.BeginScope doesn't return the exact same IDisposable object returned by the single ILoggerProvider's ILogger.BeginScope method. Technically this breaks any code that assumes that Logger.BeginScope is passthrough in the single ILoggerProvider case, but I think it's unlikely any real code makes this assumption. That's why this repro uses the contrived example of calling object.ToString() on the IDisposable.
Literally any implementation of Logger.BeginScope that doesn't return exactly loggers[0].Logger.BeginScope(state) in the single ILoggerProvider case is breaking by this definition.
One could also fix Logger.Scope so it overrides ToString and returns the result of state.ToString()
Just like LoggerExternalScopeProvider.Scope does.
@halter73 Literally any implementation of Logger.BeginScope is breaking by this definition.
Before it returned the actual scope-object when having a single LoggingProvider. This is no longer the case.
Yea I don’t think this “breaking change” has any real impact. It’s by design