diff --git a/src/Directory.Build.props b/src/Directory.Build.props index ce7968e..7e3a042 100644 --- a/src/Directory.Build.props +++ b/src/Directory.Build.props @@ -29,7 +29,7 @@ - 0.3.0-alpha + 0.4.0-alpha @@ -76,7 +76,7 @@ all runtime; build; native; contentfiles; analyzers; buildtransitive - + all runtime; build; native; contentfiles; analyzers; buildtransitive @@ -88,7 +88,7 @@ all runtime; build; native; contentfiles; analyzers; buildtransitive - + all runtime; build; native; contentfiles; analyzers diff --git a/src/Menees.Remoting/Menees.Remoting.csproj b/src/Menees.Remoting/Menees.Remoting.csproj index bd56ff7..49db62b 100644 --- a/src/Menees.Remoting/Menees.Remoting.csproj +++ b/src/Menees.Remoting/Menees.Remoting.csproj @@ -16,8 +16,8 @@ - - + + diff --git a/src/Menees.Remoting/MessageClient.cs b/src/Menees.Remoting/MessageClient.cs index 217810b..4892189 100644 --- a/src/Menees.Remoting/MessageClient.cs +++ b/src/Menees.Remoting/MessageClient.cs @@ -39,7 +39,7 @@ public MessageClient( : this(new ClientSettings(serverPath) { ConnectTimeout = connectTimeout ?? ClientSettings.DefaultConnectTimeout, - LoggerFactory = loggerFactory, + CreateLogger = loggerFactory != null ? loggerFactory.CreateLogger : null, }) { } @@ -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 diff --git a/src/Menees.Remoting/MessageServer.cs b/src/Menees.Remoting/MessageServer.cs index 235f6f5..149cf2a 100644 --- a/src/Menees.Remoting/MessageServer.cs +++ b/src/Menees.Remoting/MessageServer.cs @@ -74,7 +74,7 @@ public MessageServer( { MaxListeners = maxListeners, MinListeners = minListeners, - LoggerFactory = loggerFactory, + CreateLogger = loggerFactory != null ? loggerFactory.CreateLogger : null, }) { } @@ -119,7 +119,7 @@ public MessageServer(Func> requestHandler, Se settings.MaxListeners, this.ProcessRequestAsync, this, - this.Loggers, + this, (PipeServerSecurity?)settings.Security); if (settings.CancellationToken != CancellationToken.None) diff --git a/src/Menees.Remoting/Node.cs b/src/Menees.Remoting/Node.cs index 596915e..224cf8b 100644 --- a/src/Menees.Remoting/Node.cs +++ b/src/Menees.Remoting/Node.cs @@ -16,11 +16,13 @@ public abstract class Node : IDisposable { #region Protected Data Members + private readonly string serverPath; + private bool disposed; private Func tryGetType = RequireGetType; private ISerializer? systemSerializer; private ISerializer? userSerializer; - private ILoggerFactory? loggerFactory; + private Func? createLogger; #endregion @@ -32,8 +34,9 @@ public abstract class Node : IDisposable /// Parameters used to initialize this instance. protected Node(NodeSettings settings) { + this.serverPath = settings.ServerPath; this.userSerializer = settings?.Serializer; - this.loggerFactory = settings?.LoggerFactory; + this.createLogger = settings?.CreateLogger; } #endregion @@ -85,9 +88,6 @@ internal ISerializer SystemSerializer internal ISerializer? UserSerializer => this.userSerializer; - internal ILoggerFactory Loggers - => this.loggerFactory ?? NullLoggerFactory.Instance; - #endregion #region Public Methods @@ -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(logger, this.serverPath); + } + + return result; + } + + #endregion + #region Protected Methods /// @@ -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; } } @@ -130,4 +160,49 @@ protected virtual void Dispose(bool disposing) => Type.GetType(qualifiedTypeName, throwOnError: true); #endregion + + #region Private Types + + private sealed class ScopedLogger : 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 state) => this.logger.BeginScope(state); + + public bool IsEnabled(LogLevel logLevel) => this.logger.IsEnabled(logLevel); + + public void Log(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func formatter) + { + // ILogger.BeginScope is a weird API. LoggerExternalScopeProvider uses AsyncLocal, 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 } diff --git a/src/Menees.Remoting/NodeSettings.cs b/src/Menees.Remoting/NodeSettings.cs index d7c1c81..3dd91fb 100644 --- a/src/Menees.Remoting/NodeSettings.cs +++ b/src/Menees.Remoting/NodeSettings.cs @@ -44,9 +44,16 @@ protected NodeSettings(string serverPath) public ISerializer? Serializer { get; set; } /// - /// 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. /// - public ILoggerFactory? LoggerFactory { get; set; } + /// + /// An method can be assigned to this. + /// We don't require a full interface since we never need to + /// call its method. Technically, + /// an method could also be used, but + /// that would be atypical. + /// + public Func? CreateLogger { get; set; } /// /// Gets security settings. diff --git a/src/Menees.Remoting/Pipes/PipeClient.cs b/src/Menees.Remoting/Pipes/PipeClient.cs index 31b3370..a51a1b2 100644 --- a/src/Menees.Remoting/Pipes/PipeClient.cs +++ b/src/Menees.Remoting/Pipes/PipeClient.cs @@ -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; diff --git a/src/Menees.Remoting/Pipes/PipeNode.cs b/src/Menees.Remoting/Pipes/PipeNode.cs index 5adf99c..f7a7c9a 100644 --- a/src/Menees.Remoting/Pipes/PipeNode.cs +++ b/src/Menees.Remoting/Pipes/PipeNode.cs @@ -11,19 +11,17 @@ internal abstract class PipeNode : IDisposable { #region Private Data Members - private IDisposable? logScope; - private bool disposed; + private readonly Lazy 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 @@ -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 @@ -64,13 +62,6 @@ public void Dispose() #endregion - #region Internal Methods - - internal Dictionary CreateScope() - => new() { { nameof(this.PipeName), this.PipeName } }; - - #endregion - #region Protected Methods protected static int ConvertTimeout(TimeSpan timeout) @@ -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 diff --git a/src/Menees.Remoting/Pipes/PipeServer.cs b/src/Menees.Remoting/Pipes/PipeServer.cs index a9006a4..ab83005 100644 --- a/src/Menees.Remoting/Pipes/PipeServer.cs +++ b/src/Menees.Remoting/Pipes/PipeServer.cs @@ -28,9 +28,9 @@ internal PipeServer( int maxListeners, Func processRequestAsync, IServer server, - ILoggerFactory loggers, + Node owner, PipeServerSecurity? security) - : base(pipeName, loggers) + : base(pipeName, owner) { if (minListeners <= 0) { @@ -147,7 +147,7 @@ internal void EnsureMinListeners() break; } - PipeServerListener listener = new(this, pipe, this.Loggers.CreateLogger()); + 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. diff --git a/src/Menees.Remoting/Pipes/PipeServerListener.cs b/src/Menees.Remoting/Pipes/PipeServerListener.cs index 4426926..0ad4f0c 100644 --- a/src/Menees.Remoting/Pipes/PipeServerListener.cs +++ b/src/Menees.Remoting/Pipes/PipeServerListener.cs @@ -7,27 +7,24 @@ #endregion -internal sealed class PipeServerListener : IDisposable +internal sealed class PipeServerListener : PipeNode { #region Private Data Members private readonly PipeServer server; private readonly NamedPipeServerStream pipe; - private readonly ILogger logger; - private IDisposable? logScope; private bool disposed; #endregion #region Constructors - public PipeServerListener(PipeServer server, NamedPipeServerStream pipe, ILogger logger) + public PipeServerListener(PipeServer server, NamedPipeServerStream pipe, Node owner) + : base(server.PipeName, owner) { this.server = server; this.pipe = pipe; - this.logger = logger; - this.logScope = this.logger.BeginScope(server.CreateScope()); this.State = ListenerState.Created; } @@ -41,43 +38,6 @@ public PipeServerListener(PipeServer server, NamedPipeServerStream pipe, ILogger #region Public Methods - public void Dispose() - { - // Note: This method can be called multiple times if a listener is finishing and self-disposes on one thread, - // and the server finishes and disposes its remaining listeners from another thread. - if (!this.disposed) - { - this.disposed = true; - this.State = ListenerState.Disposed; - - if (this.pipe.IsConnected) - { - this.logger.LogTrace("Disconnecting listener."); - try - { - this.pipe.Disconnect(); - } - catch (Exception ex) - { - this.logger.LogError(ex, "Exception disconnecting listener."); - } - } - - this.logger.LogTrace("Disposing listener."); - try - { - this.pipe.Dispose(); - } - catch (Exception ex) - { - this.logger.LogError(ex, "Exception disposing listener."); - } - - this.logScope?.Dispose(); - this.logScope = null; - } - } - public async Task StartAsync() { this.State = ListenerState.WaitingForConnection; @@ -93,17 +53,17 @@ public async Task StartAsync() { // We can get "The pipe has been ended." if the client closed early. LogLevel level = this.disposed ? LogLevel.Debug : LogLevel.Error; - this.logger.Log(level, ex, "Wait for pipe connection failed."); // Note: this.logScope may be disposed already. + this.Logger.Log(level, ex, "Wait for pipe connection failed."); // Note: this.logScope may be disposed already. } catch (ObjectDisposedException ex) { // We'll get "Cannot access a closed pipe." under normal conditions when the server is disposed. LogLevel level = this.disposed ? LogLevel.Trace : LogLevel.Debug; - this.logger.Log(level, ex, "Listener disposed while waiting for pipe."); // Note: this.logScope may be disposed already. + this.Logger.Log(level, ex, "Listener disposed while waiting for pipe."); // Note: this.logScope may be disposed already. } catch (Exception ex) { - this.logger.Log(LogLevel.Error, ex, "Unhandled exception waiting for pipe connection."); // Note: this.logScope may be disposed already. + this.Logger.Log(LogLevel.Error, ex, "Unhandled exception waiting for pipe connection."); // Note: this.logScope may be disposed already. this.server.ReportUnhandledException?.Invoke(ex); } @@ -115,7 +75,7 @@ public async Task StartAsync() { // Since this listener is now connected (and about to begin processing a request), tell the server so it // can start another listener if necessary. If the server is already at its max, it may not be able to. - this.logger.LogTrace("Listener connected"); + this.Logger.LogTrace("Listener connected"); this.server.EnsureMinListeners(); this.State = ListenerState.ProcessingRequest; @@ -132,12 +92,12 @@ public async Task StartAsync() } catch (Exception ex) { - this.logger.LogError(ex, "Error processing request."); + this.Logger.LogError(ex, "Error processing request."); this.server.ReportUnhandledException?.Invoke(ex); } } - this.logger.LogTrace("Stopping listener."); + this.Logger.LogTrace("Stopping listener."); // Self dispose since each listener should only be used for a single request. this.Dispose(); @@ -146,10 +106,49 @@ public async Task StartAsync() // If it was at its max earlier when we started processing, then maybe now // that we're finished it'll be below the max (unless another thread snuck in // and started a new listener). - this.logger.LogTrace($"After listener dispose"); + this.Logger.LogTrace($"After listener dispose"); this.server.EnsureMinListeners(); } } #endregion + + #region Protected Methods + + protected override void Dispose(bool disposing) + { + // Note: This method can be called multiple times if a listener is finishing and self-disposes on one thread, + // and the server finishes and disposes its remaining listeners from another thread. + base.Dispose(disposing); + if (disposing && !this.disposed) + { + this.disposed = true; + this.State = ListenerState.Disposed; + + if (this.pipe.IsConnected) + { + this.Logger.LogTrace("Disconnecting listener."); + try + { + this.pipe.Disconnect(); + } + catch (Exception ex) + { + this.Logger.LogError(ex, "Exception disconnecting listener."); + } + } + + this.Logger.LogTrace("Disposing listener."); + try + { + this.pipe.Dispose(); + } + catch (Exception ex) + { + this.Logger.LogError(ex, "Exception disposing listener."); + } + } + } + + #endregion } diff --git a/src/Menees.Remoting/RmiClient.cs b/src/Menees.Remoting/RmiClient.cs index 4d89a99..f29d976 100644 --- a/src/Menees.Remoting/RmiClient.cs +++ b/src/Menees.Remoting/RmiClient.cs @@ -39,7 +39,7 @@ public RmiClient( : this(new ClientSettings(serverPath) { ConnectTimeout = connectTimeout ?? ClientSettings.DefaultConnectTimeout, - LoggerFactory = loggerFactory, + CreateLogger = loggerFactory != null ? loggerFactory.CreateLogger : null, }) { } @@ -57,7 +57,7 @@ public RmiClient(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 diff --git a/src/Menees.Remoting/RmiServer.cs b/src/Menees.Remoting/RmiServer.cs index 43c2f62..75e1140 100644 --- a/src/Menees.Remoting/RmiServer.cs +++ b/src/Menees.Remoting/RmiServer.cs @@ -50,7 +50,7 @@ public RmiServer( { MaxListeners = maxListeners, MinListeners = minListeners, - LoggerFactory = loggerFactory, + CreateLogger = loggerFactory != null ? loggerFactory.CreateLogger : null, }) { } @@ -78,7 +78,7 @@ public RmiServer(TServiceInterface serviceInstance, ServerSettings settings) settings.MaxListeners, this.ProcessRequestAsync, this, - this.Loggers, + this, (PipeServerSecurity?)settings.Security); this.cancellationToken = settings.CancellationToken; } diff --git a/src/Menees.Remoting/ServerUtility.cs b/src/Menees.Remoting/ServerUtility.cs index ea80a94..6809004 100644 --- a/src/Menees.Remoting/ServerUtility.cs +++ b/src/Menees.Remoting/ServerUtility.cs @@ -29,7 +29,7 @@ public static async Task ProcessRequestAsync( } catch (Exception ex) { - node.Loggers.CreateLogger(node.GetType()).LogError(ex, "Exception while server was processing a request."); + node.CreateLogger(node.GetType()).LogError(ex, "Exception while server was processing a request."); server.ReportUnhandledException?.Invoke(ex); try @@ -53,11 +53,11 @@ public static async Task ProcessRequestAsync( // We can get an ObjectDisposedException("Cannot access a closed pipe.") // when WriteToAsync calls FlushAsync() on the stream if the client has already // received all the data, processed it quickly, and closed the pipe. That's ok. - node.Loggers.CreateLogger(node.GetType()).LogDebug(ex, "Client closed connection while server was finishing write."); + node.CreateLogger(node.GetType()).LogDebug(ex, "Client closed connection while server was finishing write."); } catch (Exception ex) { - node.Loggers.CreateLogger(node.GetType()).LogError(ex, "Unhandled exception while server was finishing write."); + node.CreateLogger(node.GetType()).LogError(ex, "Unhandled exception while server was finishing write."); server.ReportUnhandledException?.Invoke(ex); } } diff --git a/tests/Directory.Build.props b/tests/Directory.Build.props index 3595a95..aa7e7a1 100644 --- a/tests/Directory.Build.props +++ b/tests/Directory.Build.props @@ -14,9 +14,9 @@ - - - + + + all runtime; build; native; contentfiles; analyzers; buildtransitive diff --git a/tests/Menees.Remoting.TestClient/Program.cs b/tests/Menees.Remoting.TestClient/Program.cs index 09cdf98..6a49c20 100644 --- a/tests/Menees.Remoting.TestClient/Program.cs +++ b/tests/Menees.Remoting.TestClient/Program.cs @@ -52,14 +52,14 @@ public static async Task Main(string[] args) ClientSettings rmiClientSettings = new(serverPathPrefix + nameof(ICalculator)) { ConnectTimeout = connectTimeout, - LoggerFactory = logManager.Loggers, + CreateLogger = logManager.LoggerFactory.CreateLogger, }; using RmiClient rmiClient = new(rmiClientSettings); ClientSettings messageClientSettings = new(serverPathPrefix + "Echo") { ConnectTimeout = connectTimeout, - LoggerFactory = logManager.Loggers, + CreateLogger = logManager.LoggerFactory.CreateLogger, }; using MessageClient echoMessageClient = new(messageClientSettings); diff --git a/tests/Menees.Remoting.TestHost/LogManager.cs b/tests/Menees.Remoting.TestHost/LogManager.cs index 157fa51..beb2b35 100644 --- a/tests/Menees.Remoting.TestHost/LogManager.cs +++ b/tests/Menees.Remoting.TestHost/LogManager.cs @@ -13,15 +13,14 @@ public sealed class LogManager : IDisposable #region Private Data Members private ILoggerFactory? loggerFactory; - private ImmediateConsoleLoggerProvider? consoleLoggerProvider; #endregion #region Constructors - public LogManager(LogLevel minimumLogLevel = LogLevel.Debug, LogLevel consoleLogLevel = LogLevel.Debug) + public LogManager(LogLevel minimumLogLevel = LogLevel.Debug) { - this.loggerFactory = LoggerFactory.Create(builder => + this.loggerFactory = Microsoft.Extensions.Logging.LoggerFactory.Create(builder => { builder.ClearProviders(); @@ -30,19 +29,14 @@ public LogManager(LogLevel minimumLogLevel = LogLevel.Debug, LogLevel consoleLog // Make the messages show up in the debugger's Output window. builder.AddDebug(); - if (Convert.ToBoolean(1)) + // The Microsoft.Extensions.Logging.Console provider behaves weird in multi-threaded unit tests due to buffering. + // So we'll dispose the whole loggerFactory after each test to try to force everything to flush out then. + // https://codeburst.io/unit-testing-with-net-core-ilogger-t-e8c16c503a80 + builder.AddSimpleConsole(options => { - builder.AddConsole(); - } - else - { - // The Microsoft.Extensions.Logging.Console provider behaves weird in multi-threaded unit tests due to buffering. - // https://codeburst.io/unit-testing-with-net-core-ilogger-t-e8c16c503a80 - // So I wrote my own ImmediateConsoleLoggerProvider that's aware of async call contexts. - // But since it doesn't do any buffering, it is VERY slow on large tests! - this.consoleLoggerProvider = new ImmediateConsoleLoggerProvider(consoleLogLevel); - builder.AddProvider(this.consoleLoggerProvider); - } + options.IncludeScopes = true; + options.TimestampFormat = "HH:mm:ss.fff "; + }); }); } @@ -50,7 +44,7 @@ public LogManager(LogLevel minimumLogLevel = LogLevel.Debug, LogLevel consoleLog #region Public Properties - public ILoggerFactory Loggers => this.loggerFactory ?? NullLoggerFactory.Instance; + public ILoggerFactory LoggerFactory => this.loggerFactory ?? NullLoggerFactory.Instance; #endregion @@ -60,231 +54,6 @@ public void Dispose() { this.loggerFactory?.Dispose(); this.loggerFactory = null; - this.consoleLoggerProvider?.Dispose(); - this.consoleLoggerProvider = null; - } - - #endregion - - #region Private Types - - private sealed class ImmediateConsoleLoggerProvider : ILoggerProvider - { - #region Private Data Members - - private readonly LogLevel minLevel; - - #endregion - - #region Constructors - - public ImmediateConsoleLoggerProvider(LogLevel minLevel) - { - this.minLevel = minLevel; - } - - #endregion - - #region Public Methods - - public ILogger CreateLogger(string categoryName) => new ImmediateConsoleLogger(categoryName, this.minLevel); - - public void Dispose() - { - } - - #endregion - - private sealed class ImmediateConsoleLogger : ILogger - { - #region Private Data Members - - private readonly string categoryName; - private readonly LogLevel minLevel; - private readonly AsyncLocal> callContextStack = new(); - - #endregion - - #region Constructors - - public ImmediateConsoleLogger(string categoryName, LogLevel minLevel) - { - this.categoryName = categoryName; - this.minLevel = minLevel; - } - - #endregion - - #region Public Methods - - public IDisposable BeginScope(TState state) - { - this.callContextStack.Value ??= new(); - IDisposable result = new Scope(this.callContextStack.Value, state); - return result; - } - - public bool IsEnabled(LogLevel logLevel) => logLevel >= this.minLevel; - - public void Log(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func formatter) - { - string levelName = logLevel switch - { - LogLevel.Trace => "TRC", - LogLevel.Debug => "DBG", - LogLevel.Information => "INF", - LogLevel.Warning => "WRN", - LogLevel.Error => "ERR", - LogLevel.Critical => "CRT", - LogLevel.None => "NON", - _ => logLevel.ToString(), - }; - - StringBuilder sb = new(); - sb.AppendFormat("[{0:HH:mm:ss.fff} {1}] ", DateTime.Now, levelName); - if (eventId.Id != 0) - { - sb.Append('#').Append(eventId.Id).Append(' '); - } - - sb.Append(this.categoryName).Append(' '); - - string message = formatter(state, null); - sb.Append(message); - if (exception != null) - { - sb.Append(' '); - Append(sb, exception, tag: "Exception: "); - } - - // This will be null if a logger user never calls BeginScope. - Stack? contextStack = this.callContextStack.Value; - if (contextStack != null) - { - // TODO: This is not thread-safe! AsyncLocal values can be accessed by multiple Tasks at once! [Bill, 6/18/2022] - // This got InvalidOperationException "Collection was modified after the enumerator was instantiated." during a - // MultiServerLarge test on .NET Framework. - // https://stackoverflow.com/a/63732530/1882616 - foreach (object? value in contextStack) - { - sb.Append(' '); - Append(sb, value); - } - } - - string line = sb.ToString(); - Console.WriteLine(line); - } - - #endregion - - #region Private Methods - - private static void Append(StringBuilder sb, object? value, bool delimit = true, string? tag = null) - { - if (delimit) - { - sb.Append('{'); - } - - sb.Append(tag); - - switch (value) - { - case string text: - sb.Append(text); - break; - - case IDictionary dictionary: - foreach (DictionaryEntry entry in dictionary) - { - Append(sb, entry.Key, delimit: entry.Key is not string); - sb.Append('='); - Append(sb, entry.Value, delimit: entry.Value is not string); - } - - break; - - case IEnumerable enumerable: - foreach (object? item in enumerable) - { - Append(sb, item); - } - - break; - - case Exception ex: - // Some exception messages end with newlines. - sb.Append(ex.Message.TrimEnd()); - if (ex.HResult != 0) - { - sb.Append(' ').Append("HResult=0x").AppendFormat("{0:X2}", ex.HResult); - } - - if (ex.InnerException != null) - { - sb.Append(' '); - Append(sb, ex.InnerException); - } - - break; - - default: - sb.Append(value); - break; - } - - if (delimit) - { - sb.Append('}'); - } - } - - #endregion - - #region Private Types - - private sealed class Scope : IDisposable - { - #region Private Data Members - - private readonly object monitor = new(); - private Stack? scope; - - #endregion - - #region Constructors - - public Scope(Stack scope, object? state) - { - this.scope = scope; - this.scope.Push(state); - } - - #endregion - - #region Public Methods - - public void Dispose() - { - // Protect against simultaneous multi-threaded disposal (e.g., PipeServerListener.Dispose()). - lock (this.monitor) - { - Stack? stack = this.scope; - this.scope = null; - - if (stack?.Count > 0) - { - stack.Pop(); - } - } - } - - #endregion - } - - #endregion - } } #endregion diff --git a/tests/Menees.Remoting.TestHost/Menees.Remoting.TestHost.csproj b/tests/Menees.Remoting.TestHost/Menees.Remoting.TestHost.csproj index bd13249..3046401 100644 --- a/tests/Menees.Remoting.TestHost/Menees.Remoting.TestHost.csproj +++ b/tests/Menees.Remoting.TestHost/Menees.Remoting.TestHost.csproj @@ -13,5 +13,6 @@ + diff --git a/tests/Menees.Remoting.TestHost/Program.cs b/tests/Menees.Remoting.TestHost/Program.cs index e66878f..3690a2f 100644 --- a/tests/Menees.Remoting.TestHost/Program.cs +++ b/tests/Menees.Remoting.TestHost/Program.cs @@ -72,7 +72,7 @@ public static int Main(string[] args) { MaxListeners = maxListeners, MinListeners = minListeners, - LoggerFactory = logManager.Loggers, + CreateLogger = logManager.LoggerFactory.CreateLogger, }; object serviceInstance = Activator.CreateInstance(serviceType)!; using IServer rmiServer = (IServer)Activator.CreateInstance(serverType, serviceInstance, rmiServerSettings)!; @@ -81,13 +81,13 @@ public static int Main(string[] args) { MaxListeners = maxListeners, MinListeners = minListeners, - LoggerFactory = logManager.Loggers, + CreateLogger = logManager.LoggerFactory.CreateLogger, }; using MessageServer echoMessageServer = new(input => Task.FromResult(input), messageServerSettings); string hostServerPath = serverPathPrefix + nameof(IServerHost); using ServerHost host = new(); - using RmiServer hostServer = new(host, hostServerPath, 1, loggerFactory: logManager.Loggers); + using RmiServer hostServer = new(host, hostServerPath, 1, loggerFactory: logManager.LoggerFactory); host.Add(rmiServer); host.Add(echoMessageServer); diff --git a/tests/Menees.Remoting.Tests/BaseTests.cs b/tests/Menees.Remoting.Tests/BaseTests.cs index 19836f6..86bd0f3 100644 --- a/tests/Menees.Remoting.Tests/BaseTests.cs +++ b/tests/Menees.Remoting.Tests/BaseTests.cs @@ -20,7 +20,7 @@ public class BaseTests #region Public Properties - public ILoggerFactory Loggers => this.logManager?.Loggers ?? NullLoggerFactory.Instance; + public ILoggerFactory LoggerFactory => this.logManager?.LoggerFactory ?? NullLoggerFactory.Instance; #endregion @@ -109,7 +109,7 @@ protected async Task TestCrossProcessServerAsync( TimeSpan connectTimeout = Debugger.IsAttached ? TimeSpan.FromMinutes(5) : TimeSpan.FromSeconds(2); string hostServerPath = $"{serverPathPrefix}{nameof(IServerHost)}"; - using RmiClient hostClient = new(hostServerPath, connectTimeout: connectTimeout, loggerFactory: this.Loggers); + using RmiClient hostClient = new(hostServerPath, connectTimeout: connectTimeout, loggerFactory: this.LoggerFactory); IServerHost serverHost = hostClient.CreateProxy(); serverHost.IsReady.ShouldBeTrue(); diff --git a/tests/Menees.Remoting.Tests/MessageNodeTests.cs b/tests/Menees.Remoting.Tests/MessageNodeTests.cs index e36d6e0..585ec9a 100644 --- a/tests/Menees.Remoting.Tests/MessageNodeTests.cs +++ b/tests/Menees.Remoting.Tests/MessageNodeTests.cs @@ -36,10 +36,10 @@ public async Task CodeNameToStringInProcessAsync() using MessageServer server = new( async codeName => await Task.FromResult($"{codeName.Code}: {codeName.Name}").ConfigureAwait(false), serverPath, - loggerFactory: this.Loggers); + loggerFactory: this.LoggerFactory); server.Start(); - using MessageClient client = new(serverPath, loggerFactory: this.Loggers); + using MessageClient client = new(serverPath, loggerFactory: this.LoggerFactory); string response = await client.SendAsync(new CodeName { Code = 1, Name = "Billy" }).ConfigureAwait(false); response.ShouldBe("1: Billy"); response = await client.SendAsync(new CodeName { Code = 2, Name = "Bob" }).ConfigureAwait(false); @@ -55,10 +55,10 @@ public async Task StringToCodeNameInProcessAsync() async text => await Task.FromResult(new CodeName { Code = text.Length, Name = text }).ConfigureAwait(false), serverPath, maxListeners: 10, - loggerFactory: this.Loggers); + loggerFactory: this.LoggerFactory); server.Start(); - using MessageClient client = new(serverPath, loggerFactory: this.Loggers); + using MessageClient client = new(serverPath, loggerFactory: this.LoggerFactory); IEnumerable tasks = Enumerable.Range(1, 20).Select(async item => { string combined = "Item " + item; @@ -76,7 +76,7 @@ await this.TestCrossProcessServerAsync( this.GenerateServerPathPrefix(), async prefix => { - using MessageClient echoClient = new(prefix + "Echo", loggerFactory: this.Loggers); + using MessageClient echoClient = new(prefix + "Echo", loggerFactory: this.LoggerFactory); for (int i = 1; i <= 5; i++) { string input = $"Test {i}"; @@ -104,7 +104,7 @@ public async Task CancellationAsync() ServerSettings serverSettings = new(serverPath) { CancellationToken = serverCancellationSource.Token, - LoggerFactory = this.Loggers, + CreateLogger = this.LoggerFactory.CreateLogger, }; using MessageServer server = new( async (value, cancel) => @@ -120,7 +120,7 @@ public async Task CancellationAsync() serverSettings); server.Start(); - using MessageClient client = new(serverPath, loggerFactory: this.Loggers); + using MessageClient client = new(serverPath, loggerFactory: this.LoggerFactory); using CancellationTokenSource clientCancellationSource = new(TimeSpan.FromSeconds(0.5)); try { @@ -160,10 +160,10 @@ public async Task ThrowExceptionAsync() return await Task.FromResult(value.ToString()).ConfigureAwait(false); }, serverPath, - loggerFactory: this.Loggers); + loggerFactory: this.LoggerFactory); server.Start(); - using MessageClient client = new(serverPath, loggerFactory: this.Loggers); + using MessageClient client = new(serverPath, loggerFactory: this.LoggerFactory); for (int i = 0; i < 2; i++) { try @@ -208,7 +208,7 @@ async Task TestAsync(int code, PipeClientSecurity? clientSecurity, PipeServerSec ServerSettings serverSettings = new(serverPath) { - LoggerFactory = this.Loggers, + CreateLogger = this.LoggerFactory.CreateLogger, Security = serverSecurity, }; using MessageServer server = new( @@ -218,7 +218,7 @@ async Task TestAsync(int code, PipeClientSecurity? clientSecurity, PipeServerSec ClientSettings clientSettings = new(serverPath) { - LoggerFactory = this.Loggers, + CreateLogger = this.LoggerFactory.CreateLogger, Security = clientSecurity, }; using MessageClient client = new(clientSettings); diff --git a/tests/Menees.Remoting.Tests/RmiClientTests.cs b/tests/Menees.Remoting.Tests/RmiClientTests.cs index 23d9c81..8dcfdbd 100644 --- a/tests/Menees.Remoting.Tests/RmiClientTests.cs +++ b/tests/Menees.Remoting.Tests/RmiClientTests.cs @@ -23,12 +23,12 @@ public void HasherExample() [TestMethod] public void Constructor() { - using (RmiClient client = new(this.GetType().FullName!, loggerFactory: this.Loggers)) + using (RmiClient client = new(this.GetType().FullName!, loggerFactory: this.LoggerFactory)) { client.ConnectTimeout.ShouldBe(ClientSettings.DefaultConnectTimeout); } - using (RmiClient client = new(this.GetType().FullName!, connectTimeout: TimeSpan.FromSeconds(1), loggerFactory: this.Loggers)) + using (RmiClient client = new(this.GetType().FullName!, connectTimeout: TimeSpan.FromSeconds(1), loggerFactory: this.LoggerFactory)) { client.ConnectTimeout.ShouldBe(TimeSpan.FromSeconds(1)); } @@ -39,12 +39,12 @@ public void CreateProxy() { string serverPath = this.GenerateServerPath(); - using RmiClient client = new(serverPath, connectTimeout: TimeSpan.FromSeconds(2), loggerFactory: this.Loggers); + using RmiClient client = new(serverPath, connectTimeout: TimeSpan.FromSeconds(2), loggerFactory: this.LoggerFactory); ITester testerProxy = client.CreateProxy(); testerProxy.ShouldNotBeNull(); Tester tester = new(); - using RmiServer server = new(tester, serverPath, loggerFactory: this.Loggers); + using RmiServer server = new(tester, serverPath, loggerFactory: this.LoggerFactory); server.ReportUnhandledException = RmiServerTests.WriteUnhandledServerException; server.Start(); @@ -57,12 +57,12 @@ public void ThrowException() { string serverPath = this.GenerateServerPath(); - using RmiClient client = new(serverPath, loggerFactory: this.Loggers); + using RmiClient client = new(serverPath, loggerFactory: this.LoggerFactory); ITester testerProxy = client.CreateProxy(); testerProxy.ShouldNotBeNull(); Tester tester = new(); - using RmiServer server = new(tester, serverPath, loggerFactory: this.Loggers); + using RmiServer server = new(tester, serverPath, loggerFactory: this.LoggerFactory); server.ReportUnhandledException = RmiServerTests.WriteUnhandledServerException; server.Start(); @@ -81,7 +81,7 @@ public void CustomSerializer() ClientSettings clientSettings = new(serverPath) { ConnectTimeout = TimeSpan.FromSeconds(2), - LoggerFactory = this.Loggers, + CreateLogger = this.LoggerFactory.CreateLogger, Serializer = new TestSerializer(), }; @@ -91,7 +91,7 @@ public void CustomSerializer() ServerSettings serverSettings = new(serverPath) { - LoggerFactory = this.Loggers, + CreateLogger = this.LoggerFactory.CreateLogger, Serializer = new TestSerializer(), }; Tester tester = new(); diff --git a/tests/Menees.Remoting.Tests/RmiServerTests.cs b/tests/Menees.Remoting.Tests/RmiServerTests.cs index 294895e..9483383 100644 --- a/tests/Menees.Remoting.Tests/RmiServerTests.cs +++ b/tests/Menees.Remoting.Tests/RmiServerTests.cs @@ -21,7 +21,7 @@ public void CloneString() { string serverPath = this.GenerateServerPath(); string expected = Guid.NewGuid().ToString(); - using RmiServer server = new(expected, serverPath, loggerFactory: this.Loggers); + using RmiServer server = new(expected, serverPath, loggerFactory: this.LoggerFactory); // This is a super weak, insecure example since it just checks for the word "System". server.TryGetType = typeName => typeName.Contains(nameof(System)) @@ -31,7 +31,7 @@ public void CloneString() server.ReportUnhandledException = WriteUnhandledServerException; server.Start(); - using RmiClient client = new(serverPath, loggerFactory: this.Loggers); + using RmiClient client = new(serverPath, loggerFactory: this.LoggerFactory); ICloneable proxy = client.CreateProxy(); string actual = (string)proxy.Clone(); actual.ShouldBe(expected); @@ -70,11 +70,11 @@ public void InProcessServer() { string serverPath = this.GenerateServerPath(); using ServerHost host = new(); - using RmiServer server = new(host, serverPath, 2, 2, loggerFactory: this.Loggers); + using RmiServer server = new(host, serverPath, 2, 2, loggerFactory: this.LoggerFactory); server.ReportUnhandledException = WriteUnhandledServerException; host.Add(server); - using RmiClient client = new(serverPath, connectTimeout: TimeSpan.FromSeconds(2), loggerFactory: this.Loggers); + using RmiClient client = new(serverPath, connectTimeout: TimeSpan.FromSeconds(2), loggerFactory: this.LoggerFactory); IServerHost proxy = client.CreateProxy(); IServerHost direct = host; proxy.IsReady.ShouldBeTrue(); @@ -147,7 +147,7 @@ private void TestClient( { MaxListeners = maxServerListeners, MinListeners = minServerListeners, - LoggerFactory = this.Loggers, + CreateLogger = this.LoggerFactory.CreateLogger, Security = serverSecurity, }; @@ -177,7 +177,7 @@ private void TestClient(int clientCount, string serverPath, ClientSecurity? clie ClientSettings clientSettings = new(serverPath) { ConnectTimeout = timeout, - LoggerFactory = this.Loggers, + CreateLogger = this.LoggerFactory.CreateLogger, Security = clientSecurity, };