Skip to content

Commit

Permalink
Fix ILogger.BeginScope usage
Browse files Browse the repository at this point in the history
ILogger.BeginScope isn't safe to use at a class scope. It's only safe to use around local calls to ILogger.Log with no intervening Task.Runs or awaits due to AsyncLocal affinity.

https://stackoverflow.com/questions/63851259/since-iloggert-is-a-singleton-how-different-threads-can-use-beginscope-with#comment128022925_63852241
  • Loading branch information
menees committed Jun 19, 2022
1 parent 046952c commit 09752ec
Show file tree
Hide file tree
Showing 22 changed files with 212 additions and 380 deletions.
6 changes: 3 additions & 3 deletions src/Directory.Build.props
Original file line number Diff line number Diff line change
Expand Up @@ -29,7 +29,7 @@

<!-- Make the assembly, file, and NuGet package versions the same. -->
<!-- https://docs.microsoft.com/en-us/nuget/concepts/package-versioning#pre-release-versions -->
<Version>0.3.0-alpha</Version>
<Version>0.4.0-alpha</Version>
</PropertyGroup>

<PropertyGroup Condition="'$(Configuration)'=='Debug'">
Expand Down Expand Up @@ -76,7 +76,7 @@
<PrivateAssets>all</PrivateAssets>
<IncludeAssets>runtime; build; native; contentfiles; analyzers; buildtransitive</IncludeAssets>
</PackageReference>
<PackageReference Include="Menees.Analyzers" Version="3.0.5">
<PackageReference Include="Menees.Analyzers" Version="3.0.6">
<PrivateAssets>all</PrivateAssets>
<IncludeAssets>runtime; build; native; contentfiles; analyzers; buildtransitive</IncludeAssets>
</PackageReference>
Expand All @@ -88,7 +88,7 @@
<PrivateAssets>all</PrivateAssets>
<IncludeAssets>runtime; build; native; contentfiles; analyzers; buildtransitive</IncludeAssets>
</PackageReference>
<PackageReference Include="Microsoft.VisualStudio.Threading.Analyzers" Version="17.1.46">
<PackageReference Include="Microsoft.VisualStudio.Threading.Analyzers" Version="17.2.32">
<PrivateAssets>all</PrivateAssets>
<IncludeAssets>runtime; build; native; contentfiles; analyzers</IncludeAssets>
</PackageReference> </ItemGroup>
Expand Down
4 changes: 2 additions & 2 deletions src/Menees.Remoting/Menees.Remoting.csproj
Original file line number Diff line number Diff line change
Expand Up @@ -16,8 +16,8 @@
</ItemGroup>

<ItemGroup>
<PackageReference Include="System.Text.Json" Version="6.0.2" />
<PackageReference Include="Microsoft.Extensions.Logging.Abstractions" Version="6.0.0" />
<PackageReference Include="System.Text.Json" Version="6.0.5" />
<PackageReference Include="Microsoft.Extensions.Logging.Abstractions" Version="6.0.1" />
</ItemGroup>

<Choose>
Expand Down
4 changes: 2 additions & 2 deletions src/Menees.Remoting/MessageClient.cs
Original file line number Diff line number Diff line change
Expand Up @@ -39,7 +39,7 @@ public MessageClient(
: this(new ClientSettings(serverPath)
{
ConnectTimeout = connectTimeout ?? ClientSettings.DefaultConnectTimeout,
LoggerFactory = loggerFactory,
CreateLogger = loggerFactory != null ? loggerFactory.CreateLogger : null,
})
{
}
Expand All @@ -57,7 +57,7 @@ public MessageClient(ClientSettings settings)
}

this.ConnectTimeout = settings.ConnectTimeout;
this.pipe = new(settings.ServerPath, settings.ServerHost, this.Loggers, (PipeClientSecurity?)settings.Security);
this.pipe = new(settings.ServerPath, settings.ServerHost, this, (PipeClientSecurity?)settings.Security);
}

#endregion
Expand Down
4 changes: 2 additions & 2 deletions src/Menees.Remoting/MessageServer.cs
Original file line number Diff line number Diff line change
Expand Up @@ -74,7 +74,7 @@ public MessageServer(
{
MaxListeners = maxListeners,
MinListeners = minListeners,
LoggerFactory = loggerFactory,
CreateLogger = loggerFactory != null ? loggerFactory.CreateLogger : null,
})
{
}
Expand Down Expand Up @@ -119,7 +119,7 @@ public MessageServer(Func<TIn, CancellationToken, Task<TOut>> requestHandler, Se
settings.MaxListeners,
this.ProcessRequestAsync,
this,
this.Loggers,
this,
(PipeServerSecurity?)settings.Security);

if (settings.CancellationToken != CancellationToken.None)
Expand Down
87 changes: 81 additions & 6 deletions src/Menees.Remoting/Node.cs
Original file line number Diff line number Diff line change
Expand Up @@ -16,11 +16,13 @@ public abstract class Node : IDisposable
{
#region Protected Data Members

private readonly string serverPath;

private bool disposed;
private Func<string, Type?> tryGetType = RequireGetType;
private ISerializer? systemSerializer;
private ISerializer? userSerializer;
private ILoggerFactory? loggerFactory;
private Func<string, ILogger>? createLogger;

#endregion

Expand All @@ -32,8 +34,9 @@ public abstract class Node : IDisposable
/// <param name="settings">Parameters used to initialize this instance.</param>
protected Node(NodeSettings settings)
{
this.serverPath = settings.ServerPath;
this.userSerializer = settings?.Serializer;
this.loggerFactory = settings?.LoggerFactory;
this.createLogger = settings?.CreateLogger;
}

#endregion
Expand Down Expand Up @@ -85,9 +88,6 @@ internal ISerializer SystemSerializer

internal ISerializer? UserSerializer => this.userSerializer;

internal ILoggerFactory Loggers
=> this.loggerFactory ?? NullLoggerFactory.Instance;

#endregion

#region Public Methods
Expand All @@ -104,6 +104,36 @@ public void Dispose()

#endregion

#region Internal Methods

internal ILogger CreateLogger(Type type)
{
ILogger result = NullLogger.Instance;

if (this.createLogger != null)
{
ILogger logger = this.createLogger(type.FullName ?? string.Empty);

// ILogger.BeginScope is weird. I'd prefer to pass a dictionary with a named entry like "ServerPath",
// so I can provide more info on what type of scope information is available. However, Microsoft's
// Console provider only does ToString() when it shows the scope values, so that would only show
// a scope dictionary as its .NET type name, which is useless. Microsoft's other standard providers
// don't even support scopes.
//
// At https://nblumhardt.com/2016/11/ilogger-beginscope/, Nicholas Blumhardt discuss how he
// implemented ILogger.BeginScope in Serilog. It handles dictionaries as named value pairs, and
// it attaches loose values like strings to a named "Scope" property with a list of values. I hope
// other logging libraries handle dictionaries similarly. However, since I can't know what the ILogger
// implementation does with scopes, I'll just go with a simple string scope. Every ILogger library
// should support that.
result = new ScopedLogger<string>(logger, this.serverPath);
}

return result;
}

#endregion

#region Protected Methods

/// <summary>
Expand All @@ -117,7 +147,7 @@ protected virtual void Dispose(bool disposing)
// Allow any custom serializer to be GCed.
this.userSerializer = null;
this.systemSerializer = null;
this.loggerFactory = null;
this.createLogger = null;
this.disposed = true;
}
}
Expand All @@ -130,4 +160,49 @@ protected virtual void Dispose(bool disposing)
=> Type.GetType(qualifiedTypeName, throwOnError: true);

#endregion

#region Private Types

private sealed class ScopedLogger<TScope> : ILogger
{
#region Private Data Members

private readonly ILogger logger;
private readonly TScope scope;

#endregion

#region Constructors

public ScopedLogger(ILogger logger, TScope scope)
{
this.logger = logger;
this.scope = scope;
}

#endregion

#region Public Methods

public IDisposable BeginScope<TState>(TState state) => this.logger.BeginScope(state);

public bool IsEnabled(LogLevel logLevel) => this.logger.IsEnabled(logLevel);

public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func<TState, Exception?, string> formatter)
{
// ILogger.BeginScope is a weird API. LoggerExternalScopeProvider uses AsyncLocal<T>, so it's not safe to
// start the scope from a class constructor and dispose of it from the class's Dispose method. Doing that
// causes the scope to "stay open" and pick up any pushed scopes from spawned Tasks/awaits, which leads
// to bizarre nested/stacked scopes. Due to AsyncLocal, ILogger.BeginScope can only be safely used in a local
// call context wrapped around one or more local ILogger.Log calls with no intervening Task.Runs or awaits.
// To avoid having to do BeginScope around all our Log calls, it's easier to make this wrapper class that does it.
// https://stackoverflow.com/questions/63851259/since-iloggert-is-a-singleton-how-different-threads-can-use-beginscope-with#comment128022925_63852241
using IDisposable logScope = this.BeginScope(this.scope);
this.logger.Log(logLevel, eventId, state, exception, formatter);
}

#endregion
}

#endregion
}
11 changes: 9 additions & 2 deletions src/Menees.Remoting/NodeSettings.cs
Original file line number Diff line number Diff line change
Expand Up @@ -44,9 +44,16 @@ protected NodeSettings(string serverPath)
public ISerializer? Serializer { get; set; }

/// <summary>
/// Gets or sets an optional factory for creating type-specific server loggers for status information.
/// Gets or sets an optional function for creating categorized loggers for status information.
/// </summary>
public ILoggerFactory? LoggerFactory { get; set; }
/// <remarks>
/// An <see cref="ILoggerFactory.CreateLogger(string)"/> method can be assigned to this.
/// We don't require a full <see cref="ILoggerFactory"/> interface since we never need to
/// call its <see cref="ILoggerFactory.AddProvider(ILoggerProvider)"/> method. Technically,
/// an <see cref="ILoggerProvider.CreateLogger(string)"/> method could also be used, but
/// that would be atypical.
/// </remarks>
public Func<string, ILogger>? CreateLogger { get; set; }

/// <summary>
/// Gets security settings.
Expand Down
4 changes: 2 additions & 2 deletions src/Menees.Remoting/Pipes/PipeClient.cs
Original file line number Diff line number Diff line change
Expand Up @@ -22,8 +22,8 @@ internal sealed class PipeClient : PipeNode

#region Constructors

internal PipeClient(string pipeName, string serverName, ILoggerFactory loggers, PipeClientSecurity? security)
: base(pipeName, loggers)
internal PipeClient(string pipeName, string serverName, Node owner, PipeClientSecurity? security)
: base(pipeName, owner)
{
this.ServerName = serverName;
this.security = security;
Expand Down
31 changes: 6 additions & 25 deletions src/Menees.Remoting/Pipes/PipeNode.cs
Original file line number Diff line number Diff line change
Expand Up @@ -11,19 +11,17 @@ internal abstract class PipeNode : IDisposable
{
#region Private Data Members

private IDisposable? logScope;
private bool disposed;
private readonly Lazy<ILogger> lazyLogger;

#endregion

#region Constructors

protected PipeNode(string pipeName, ILoggerFactory loggers)
protected PipeNode(string pipeName, Node owner)
{
this.PipeName = pipeName;
this.Loggers = loggers;
this.Logger = loggers.CreateLogger(this.GetType());
this.logScope = this.Logger.BeginScope(this.CreateScope());
this.Owner = owner;
this.lazyLogger = new(() => owner.CreateLogger(this.GetType()));
}

#endregion
Expand All @@ -47,9 +45,9 @@ protected PipeNode(string pipeName, ILoggerFactory loggers)

#region Private Protected Properties

private protected ILogger Logger { get; }
private protected ILogger Logger => this.lazyLogger.Value;

private protected ILoggerFactory Loggers { get; }
private protected Node Owner { get; }

#endregion

Expand All @@ -64,13 +62,6 @@ public void Dispose()

#endregion

#region Internal Methods

internal Dictionary<string, object> CreateScope()
=> new() { { nameof(this.PipeName), this.PipeName } };

#endregion

#region Protected Methods

protected static int ConvertTimeout(TimeSpan timeout)
Expand All @@ -92,16 +83,6 @@ protected static int ConvertTimeout(TimeSpan timeout)

protected virtual void Dispose(bool disposing)
{
if (!this.disposed)
{
if (disposing)
{
this.logScope?.Dispose();
this.logScope = null;
}

this.disposed = true;
}
}

#endregion
Expand Down
6 changes: 3 additions & 3 deletions src/Menees.Remoting/Pipes/PipeServer.cs
Original file line number Diff line number Diff line change
Expand Up @@ -28,9 +28,9 @@ internal PipeServer(
int maxListeners,
Func<Stream, Task> processRequestAsync,
IServer server,
ILoggerFactory loggers,
Node owner,
PipeServerSecurity? security)
: base(pipeName, loggers)
: base(pipeName, owner)
{
if (minListeners <= 0)
{
Expand Down Expand Up @@ -147,7 +147,7 @@ internal void EnsureMinListeners()
break;
}

PipeServerListener listener = new(this, pipe, this.Loggers.CreateLogger<PipeServerListener>());
PipeServerListener listener = new(this, pipe, this.Owner);
this.listeners.Add(listener);

// Note: We're intentionally not waiting on this to return. This is a true fire-and-forget case.
Expand Down
Loading

0 comments on commit 09752ec

Please sign in to comment.