diff --git a/sandbox/ConsoleApp/Program.cs b/sandbox/ConsoleApp/Program.cs index 653290103..e3577bda9 100644 --- a/sandbox/ConsoleApp/Program.cs +++ b/sandbox/ConsoleApp/Program.cs @@ -96,3 +96,56 @@ public async Task Run() } public record NatsHealth(string Status); + +public class MinimumConsoleLoggerFactory : ILoggerFactory +{ + private readonly LogLevel _logLevel; + + public MinimumConsoleLoggerFactory(LogLevel logLevel) => _logLevel = logLevel; + + public void AddProvider(ILoggerProvider provider) + { + } + + public ILogger CreateLogger(string categoryName) => new Logger(_logLevel); + + public void Dispose() + { + } + + private class Logger : ILogger + { + private readonly LogLevel _logLevel; + + public Logger(LogLevel logLevel) => _logLevel = logLevel; + + public IDisposable BeginScope(TState state) => NullDisposable.Instance; + + public bool IsEnabled(LogLevel logLevel) => _logLevel <= logLevel; + + public void Log(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func formatter) + { + if (IsEnabled(logLevel)) + { + Console.WriteLine(formatter(state, exception)); + if (exception != null) + { + Console.WriteLine(exception.ToString()); + } + } + } + } + + private class NullDisposable : IDisposable + { + public static readonly IDisposable Instance = new NullDisposable(); + + private NullDisposable() + { + } + + public void Dispose() + { + } + } +} diff --git a/sandbox/Example.Core.PublishHeaders/Example.Core.PublishHeaders.csproj b/sandbox/Example.Core.PublishHeaders/Example.Core.PublishHeaders.csproj index e4a0b5983..753c5334b 100644 --- a/sandbox/Example.Core.PublishHeaders/Example.Core.PublishHeaders.csproj +++ b/sandbox/Example.Core.PublishHeaders/Example.Core.PublishHeaders.csproj @@ -12,4 +12,8 @@ + + + + diff --git a/sandbox/Example.Core.PublishHeaders/Program.cs b/sandbox/Example.Core.PublishHeaders/Program.cs index 696f22e0b..51f0aa49f 100644 --- a/sandbox/Example.Core.PublishHeaders/Program.cs +++ b/sandbox/Example.Core.PublishHeaders/Program.cs @@ -3,7 +3,7 @@ using NATS.Client.Core; var subject = "bar.xyz"; -var options = NatsOpts.Default with { LoggerFactory = new MinimumConsoleLoggerFactory(LogLevel.Error) }; +var options = NatsOpts.Default with { LoggerFactory = LoggerFactory.Create(builder => builder.AddConsole()) }; Print("[CON] Connecting...\n"); diff --git a/sandbox/Example.Core.PublishModel/Example.Core.PublishModel.csproj b/sandbox/Example.Core.PublishModel/Example.Core.PublishModel.csproj index e4a0b5983..f0214d692 100644 --- a/sandbox/Example.Core.PublishModel/Example.Core.PublishModel.csproj +++ b/sandbox/Example.Core.PublishModel/Example.Core.PublishModel.csproj @@ -12,4 +12,8 @@ + + + + diff --git a/sandbox/Example.Core.PublishModel/Program.cs b/sandbox/Example.Core.PublishModel/Program.cs index d458201d4..0b603a2fd 100644 --- a/sandbox/Example.Core.PublishModel/Program.cs +++ b/sandbox/Example.Core.PublishModel/Program.cs @@ -3,7 +3,7 @@ using NATS.Client.Core; var subject = "bar.xyz"; -var options = NatsOpts.Default with { LoggerFactory = new MinimumConsoleLoggerFactory(LogLevel.Error) }; +var options = NatsOpts.Default with { LoggerFactory = LoggerFactory.Create(builder => builder.AddConsole()) }; Print("[CON] Connecting...\n"); diff --git a/sandbox/Example.Core.SubscribeHeaders/Example.Core.SubscribeHeaders.csproj b/sandbox/Example.Core.SubscribeHeaders/Example.Core.SubscribeHeaders.csproj index e4a0b5983..f0214d692 100644 --- a/sandbox/Example.Core.SubscribeHeaders/Example.Core.SubscribeHeaders.csproj +++ b/sandbox/Example.Core.SubscribeHeaders/Example.Core.SubscribeHeaders.csproj @@ -12,4 +12,8 @@ + + + + diff --git a/sandbox/Example.Core.SubscribeHeaders/Program.cs b/sandbox/Example.Core.SubscribeHeaders/Program.cs index a64403200..cc01621c6 100644 --- a/sandbox/Example.Core.SubscribeHeaders/Program.cs +++ b/sandbox/Example.Core.SubscribeHeaders/Program.cs @@ -5,7 +5,7 @@ using NATS.Client.Core; var subject = "bar.*"; -var options = NatsOpts.Default with { LoggerFactory = new MinimumConsoleLoggerFactory(LogLevel.Error) }; +var options = NatsOpts.Default with { LoggerFactory = LoggerFactory.Create(builder => builder.AddConsole()) }; Print("[CON] Connecting...\n"); diff --git a/sandbox/Example.Core.SubscribeModel/Example.Core.SubscribeModel.csproj b/sandbox/Example.Core.SubscribeModel/Example.Core.SubscribeModel.csproj index e4a0b5983..f0214d692 100644 --- a/sandbox/Example.Core.SubscribeModel/Example.Core.SubscribeModel.csproj +++ b/sandbox/Example.Core.SubscribeModel/Example.Core.SubscribeModel.csproj @@ -12,4 +12,8 @@ + + + + diff --git a/sandbox/Example.Core.SubscribeModel/Program.cs b/sandbox/Example.Core.SubscribeModel/Program.cs index 69e799edf..fcf9c276e 100644 --- a/sandbox/Example.Core.SubscribeModel/Program.cs +++ b/sandbox/Example.Core.SubscribeModel/Program.cs @@ -2,7 +2,7 @@ using NATS.Client.Core; var subject = "bar.*"; -var options = NatsOpts.Default with { LoggerFactory = new MinimumConsoleLoggerFactory(LogLevel.Error) }; +var options = NatsOpts.Default with { LoggerFactory = LoggerFactory.Create(builder => builder.AddConsole()) }; Print("[CON] Connecting...\n"); diff --git a/sandbox/Example.Core.SubscribeQueueGroup/Example.Core.SubscribeQueueGroup.csproj b/sandbox/Example.Core.SubscribeQueueGroup/Example.Core.SubscribeQueueGroup.csproj index e4a0b5983..f0214d692 100644 --- a/sandbox/Example.Core.SubscribeQueueGroup/Example.Core.SubscribeQueueGroup.csproj +++ b/sandbox/Example.Core.SubscribeQueueGroup/Example.Core.SubscribeQueueGroup.csproj @@ -12,4 +12,8 @@ + + + + diff --git a/sandbox/Example.Core.SubscribeQueueGroup/Program.cs b/sandbox/Example.Core.SubscribeQueueGroup/Program.cs index 9924864ab..4dbbe7792 100644 --- a/sandbox/Example.Core.SubscribeQueueGroup/Program.cs +++ b/sandbox/Example.Core.SubscribeQueueGroup/Program.cs @@ -3,7 +3,7 @@ using NATS.Client.Core; var subject = "foo.*"; -var options = NatsOpts.Default with { LoggerFactory = new MinimumConsoleLoggerFactory(LogLevel.Error) }; +var options = NatsOpts.Default with { LoggerFactory = LoggerFactory.Create(builder => builder.AddConsole()) }; // --- // Worker 1 diff --git a/sandbox/Example.Core.SubscribeRaw/Example.Core.SubscribeRaw.csproj b/sandbox/Example.Core.SubscribeRaw/Example.Core.SubscribeRaw.csproj index 38908caae..b709bad71 100644 --- a/sandbox/Example.Core.SubscribeRaw/Example.Core.SubscribeRaw.csproj +++ b/sandbox/Example.Core.SubscribeRaw/Example.Core.SubscribeRaw.csproj @@ -13,4 +13,8 @@ + + + + diff --git a/sandbox/Example.Core.SubscribeRaw/Program.cs b/sandbox/Example.Core.SubscribeRaw/Program.cs index c8158de6c..b80832d96 100644 --- a/sandbox/Example.Core.SubscribeRaw/Program.cs +++ b/sandbox/Example.Core.SubscribeRaw/Program.cs @@ -3,7 +3,7 @@ using NATS.Client.Core; var subject = "foo.*"; -var options = NatsOpts.Default with { LoggerFactory = new MinimumConsoleLoggerFactory(LogLevel.Error) }; +var options = NatsOpts.Default with { LoggerFactory = LoggerFactory.Create(builder => builder.AddConsole()) }; Print("[CON] Connecting...\n"); diff --git a/sandbox/Example.JetStream.PullConsumer/Example.JetStream.PullConsumer.csproj b/sandbox/Example.JetStream.PullConsumer/Example.JetStream.PullConsumer.csproj index 17f60cc21..5bba973ed 100644 --- a/sandbox/Example.JetStream.PullConsumer/Example.JetStream.PullConsumer.csproj +++ b/sandbox/Example.JetStream.PullConsumer/Example.JetStream.PullConsumer.csproj @@ -12,4 +12,8 @@ + + + + diff --git a/sandbox/Example.JetStream.PullConsumer/Program.cs b/sandbox/Example.JetStream.PullConsumer/Program.cs index 68ada47a2..a7966f628 100644 --- a/sandbox/Example.JetStream.PullConsumer/Program.cs +++ b/sandbox/Example.JetStream.PullConsumer/Program.cs @@ -13,7 +13,7 @@ cts.Cancel(); }; -var options = NatsOpts.Default with { LoggerFactory = new MinimumConsoleLoggerFactory(LogLevel.Error) }; +var options = NatsOpts.Default with { LoggerFactory = LoggerFactory.Create(builder => builder.AddConsole()) }; await using var nats = new NatsConnection(options); diff --git a/sandbox/Example.ObjectStore/Example.ObjectStore.csproj b/sandbox/Example.ObjectStore/Example.ObjectStore.csproj index e74912569..5212087a8 100644 --- a/sandbox/Example.ObjectStore/Example.ObjectStore.csproj +++ b/sandbox/Example.ObjectStore/Example.ObjectStore.csproj @@ -12,4 +12,8 @@ + + + + diff --git a/sandbox/Example.ObjectStore/Program.cs b/sandbox/Example.ObjectStore/Program.cs index 465f9e54f..4b42ca7ac 100644 --- a/sandbox/Example.ObjectStore/Program.cs +++ b/sandbox/Example.ObjectStore/Program.cs @@ -4,7 +4,7 @@ using NATS.Client.JetStream; using NATS.Client.ObjectStore; -var opts = NatsOpts.Default with { LoggerFactory = new MinimumConsoleLoggerFactory(LogLevel.Error) }; +var opts = NatsOpts.Default with { LoggerFactory = LoggerFactory.Create(builder => builder.AddConsole()) }; var nats = new NatsConnection(opts); var js = new NatsJSContext(nats); diff --git a/sandbox/Example.Services/Example.Services.csproj b/sandbox/Example.Services/Example.Services.csproj index b67798a56..628a2a3d5 100644 --- a/sandbox/Example.Services/Example.Services.csproj +++ b/sandbox/Example.Services/Example.Services.csproj @@ -12,4 +12,8 @@ + + + + diff --git a/sandbox/Example.Services/Program.cs b/sandbox/Example.Services/Program.cs index a06051132..694ca2ff7 100644 --- a/sandbox/Example.Services/Program.cs +++ b/sandbox/Example.Services/Program.cs @@ -3,7 +3,7 @@ using NATS.Client.Core; using NATS.Client.Services; -var opts = NatsOpts.Default with { LoggerFactory = new MinimumConsoleLoggerFactory(LogLevel.Error) }; +var opts = NatsOpts.Default with { LoggerFactory = LoggerFactory.Create(builder => builder.AddConsole()) }; var nats = new NatsConnection(opts); var svc = new NatsSvcContext(nats); diff --git a/src/NATS.Client.Core/Internal/InboxSub.cs b/src/NATS.Client.Core/Internal/InboxSub.cs index bda5fa3e5..25cb73efb 100644 --- a/src/NATS.Client.Core/Internal/InboxSub.cs +++ b/src/NATS.Client.Core/Internal/InboxSub.cs @@ -78,7 +78,7 @@ public async ValueTask ReceivedAsync(string subject, string? replyTo, ReadOnlySe { if (!_bySubject.TryGetValue(subject, out var subTable)) { - _logger.LogWarning($"Unregistered message inbox received for {subject}"); + _logger.LogWarning(NatsLogEvents.InboxSubscription, "Unregistered message inbox received for {Subject}", subject); return; } @@ -92,14 +92,14 @@ public ValueTask RemoveAsync(NatsSubBase sub) { if (!_bySubject.TryGetValue(sub.Subject, out var subTable)) { - _logger.LogWarning($"Unregistered message inbox received for {sub.Subject}"); + _logger.LogWarning(NatsLogEvents.InboxSubscription, "Unregistered message inbox received for {Subject}", sub.Subject); return ValueTask.CompletedTask; } lock (subTable) { if (!subTable.Remove(sub)) - _logger.LogWarning($"Unregistered message inbox received for {sub.Subject}"); + _logger.LogWarning(NatsLogEvents.InboxSubscription, "Unregistered message inbox received for {Subject}", sub.Subject); if (!subTable.Any()) { diff --git a/src/NATS.Client.Core/Internal/NatsReadProtocolProcessor.cs b/src/NATS.Client.Core/Internal/NatsReadProtocolProcessor.cs index f9a717602..6bd7fc852 100644 --- a/src/NATS.Client.Core/Internal/NatsReadProtocolProcessor.cs +++ b/src/NATS.Client.Core/Internal/NatsReadProtocolProcessor.cs @@ -234,14 +234,14 @@ private async Task ReadLoopAsync() if (_trace) { - _logger.LogTrace("HMSG trace dump: {MsgHeader}", msgHeader.Dump()); + _logger.LogTrace(NatsLogEvents.Protocol, "HMSG trace dump: {MsgHeader}", msgHeader.Dump()); } var (subject, sid, replyTo, headersLength, totalLength) = ParseHMessageHeader(msgHeader); if (_trace) { - _logger.LogTrace("HMSG trace parsed: {Subject} {Sid} {ReplyTo} {HeadersLength} {TotalLength}", subject, sid, replyTo, headersLength, totalLength); + _logger.LogTrace(NatsLogEvents.Protocol, "HMSG trace parsed: {Subject} {Sid} {ReplyTo} {HeadersLength} {TotalLength}", subject, sid, replyTo, headersLength, totalLength); } var payloadLength = totalLength - headersLength; @@ -294,7 +294,7 @@ await _connection.PublishToClientHandlersAsync(subject, replyTo, sid, headerSlic } catch (Exception ex) { - _logger.LogError(ex, "Error occured during read loop."); + _logger.LogError(NatsLogEvents.Protocol, ex, "Error occured during read loop"); continue; } } @@ -353,14 +353,14 @@ private async ValueTask> DispatchCommandAsync(int code, R var newBuffer = await _socketReader.ReadUntilReceiveNewLineAsync().ConfigureAwait(false); var newPosition = newBuffer.PositionOf((byte)'\n'); var error = ParseError(newBuffer.Slice(0, buffer.GetOffset(newPosition!.Value) - 1)); - _logger.LogError(error); + _logger.LogError(NatsLogEvents.Protocol, "Server error {Error}", error); _waitForPongOrErrorSignal.TrySetException(new NatsServerException(error)); return newBuffer.Slice(newBuffer.GetPosition(1, newPosition!.Value)); } else { var error = ParseError(buffer.Slice(0, buffer.GetOffset(position.Value) - 1)); - _logger.LogError(error); + _logger.LogError(NatsLogEvents.Protocol, "Server error {Error}", error); _waitForPongOrErrorSignal.TrySetException(new NatsServerException(error)); return buffer.Slice(buffer.GetPosition(1, position.Value)); } @@ -391,7 +391,7 @@ private async ValueTask> DispatchCommandAsync(int code, R var serverInfo = ParseInfo(newBuffer); _connection.WritableServerInfo = serverInfo; - _logger.LogInformation("Received ServerInfo: {0}", serverInfo); + _logger.LogInformation(NatsLogEvents.Protocol, "Received server info: {ServerInfo}", serverInfo); _waitForInfoSignal.TrySetResult(); await _infoParsed.ConfigureAwait(false); return newBuffer.Slice(newBuffer.GetPosition(1, newPosition!.Value)); @@ -400,7 +400,7 @@ private async ValueTask> DispatchCommandAsync(int code, R { var serverInfo = ParseInfo(buffer); _connection.WritableServerInfo = serverInfo; - _logger.LogInformation("Received ServerInfo: {0}", serverInfo); + _logger.LogInformation(NatsLogEvents.Protocol, "Received server info: {ServerInfo}", serverInfo); _waitForInfoSignal.TrySetResult(); await _infoParsed.ConfigureAwait(false); return buffer.Slice(buffer.GetPosition(1, position.Value)); @@ -409,7 +409,7 @@ private async ValueTask> DispatchCommandAsync(int code, R else { // reaches invalid line, log warn and try to get newline and go to nextloop. - _logger.LogWarning("reaches invalid line."); + _logger.LogWarning(NatsLogEvents.Protocol, "Reached invalid line"); Interlocked.Decrement(ref _connection.Counter.ReceivedMessages); var position = buffer.PositionOf((byte)'\n'); diff --git a/src/NATS.Client.Core/Internal/SocketReader.cs b/src/NATS.Client.Core/Internal/SocketReader.cs index 16bd11ba2..ea032a9e9 100644 --- a/src/NATS.Client.Core/Internal/SocketReader.cs +++ b/src/NATS.Client.Core/Internal/SocketReader.cs @@ -53,7 +53,7 @@ public async ValueTask> ReadAtLeastAsync(int minimumSize) _stopwatch.Stop(); if (_isTraceLogging) { - _logger.LogTrace("Socket.ReceiveAsync Size: {0} Elapsed: {1}ms", read, _stopwatch.Elapsed.TotalMilliseconds); + _logger.LogTrace(NatsLogEvents.TcpSocket, "Socket.ReceiveAsync Size: {Size} Elapsed: {ElapsedMs}ms", read, _stopwatch.Elapsed.TotalMilliseconds); } if (read == 0) @@ -98,7 +98,7 @@ public async ValueTask> ReadUntilReceiveNewLineAsync() _stopwatch.Stop(); if (_isTraceLogging) { - _logger.LogTrace("Socket.ReceiveAsync Size: {0} Elapsed: {1}ms", read, _stopwatch.Elapsed.TotalMilliseconds); + _logger.LogTrace(NatsLogEvents.TcpSocket, "Socket.ReceiveAsync Size: {Size} Elapsed: {ElapsedMs}ms", read, _stopwatch.Elapsed.TotalMilliseconds); } if (read == 0) diff --git a/src/NATS.Client.Core/Internal/SslStreamConnection.cs b/src/NATS.Client.Core/Internal/SslStreamConnection.cs index 12837f52c..92019a3f7 100644 --- a/src/NATS.Client.Core/Internal/SslStreamConnection.cs +++ b/src/NATS.Client.Core/Internal/SslStreamConnection.cs @@ -142,7 +142,7 @@ private bool RcsCbCaCertChain( if (!success) { - _logger.LogError("TLS certificate validation failed: {SslPolicyErrors}", sslPolicyErrors); + _logger.LogError(NatsLogEvents.Security, "TLS certificate validation failed: {SslPolicyErrors}", sslPolicyErrors); } return success; diff --git a/src/NATS.Client.Core/Internal/SubscriptionManager.cs b/src/NATS.Client.Core/Internal/SubscriptionManager.cs index f4a528fd3..af14e075e 100644 --- a/src/NATS.Client.Core/Internal/SubscriptionManager.cs +++ b/src/NATS.Client.Core/Internal/SubscriptionManager.cs @@ -77,13 +77,13 @@ public ValueTask PublishToClientHandlersAsync(string subject, string? replyTo, i } else { - _logger.LogWarning($"Subscription GCd but was never disposed {subject}/{sid}"); + _logger.LogWarning(NatsLogEvents.Subscription, "Subscription GCd but was never disposed {Subject}/{Sid}", subject, sid); orphanSid = sid; } } else { - _logger.LogWarning($"Can't find subscription for {subject}/{sid}"); + _logger.LogWarning(NatsLogEvents.Subscription, "Can\'t find subscription for {Subject}/{Sid}", subject, sid); } } @@ -95,7 +95,7 @@ public ValueTask PublishToClientHandlersAsync(string subject, string? replyTo, i } catch (Exception e) { - _logger.LogWarning($"Error unsubscribing orphan SID during publish: {e.GetBaseException().Message}"); + _logger.LogWarning(NatsLogEvents.Subscription, "Error unsubscribing orphan SID during publish: {Message}", e.GetBaseException().Message); } } @@ -252,14 +252,17 @@ private async Task CleanupAsync() continue; // NatsSub object GCed - _logger.LogWarning($"Subscription GCd but was never disposed {sidMetadata.Subject}/{sid}"); + _logger.LogWarning(NatsLogEvents.Subscription, "Subscription GCd but was never disposed {SidMetadataSubject}/{Sid}", sidMetadata.Subject, sid); orphanSids ??= new List(); orphanSids.Add(sid); } } if (orphanSids != null) + { + _logger.LogWarning(NatsLogEvents.Subscription, "Unsubscribing orphan subscriptions"); await UnsubscribeSidsAsync(orphanSids).ConfigureAwait(false); + } } } @@ -269,11 +272,12 @@ private async ValueTask UnsubscribeSidsAsync(List sids) { try { + _logger.LogWarning(NatsLogEvents.Subscription, "Unsubscribing orphan subscription {Sid}", sid); await _connection.UnsubscribeAsync(sid).ConfigureAwait(false); } catch (Exception e) { - _logger.LogWarning($"Error unsubscribing during cleanup: {e.GetBaseException().Message}"); + _logger.LogWarning(NatsLogEvents.Subscription, "Error unsubscribing during cleanup: {Error}", e.GetBaseException().Message); } } } diff --git a/src/NATS.Client.Core/Internal/ThreadPoolWorkItem.cs b/src/NATS.Client.Core/Internal/ThreadPoolWorkItem.cs index 832168c71..e29079160 100644 --- a/src/NATS.Client.Core/Internal/ThreadPoolWorkItem.cs +++ b/src/NATS.Client.Core/Internal/ThreadPoolWorkItem.cs @@ -57,7 +57,7 @@ public void Execute() { if (_loggerFactory != null) { - _loggerFactory.CreateLogger>().LogError(ex, "Error occured during execute callback on ThreadPool."); + _loggerFactory.CreateLogger>().LogError(NatsLogEvents.Internal, ex, "Error occured during execute callback on ThreadPool"); } } } diff --git a/src/NATS.Client.Core/MinimumConsoleLoggerFactory.cs b/src/NATS.Client.Core/MinimumConsoleLoggerFactory.cs deleted file mode 100644 index 158174ebc..000000000 --- a/src/NATS.Client.Core/MinimumConsoleLoggerFactory.cs +++ /dev/null @@ -1,71 +0,0 @@ -using Microsoft.Extensions.Logging; - -namespace NATS.Client.Core; - -public class MinimumConsoleLoggerFactory : ILoggerFactory -{ - private readonly LogLevel _logLevel; - - public MinimumConsoleLoggerFactory(LogLevel logLevel) - { - _logLevel = logLevel; - } - - public void AddProvider(ILoggerProvider provider) - { - } - - public ILogger CreateLogger(string categoryName) - { - return new Logger(_logLevel); - } - - public void Dispose() - { - } - - private class Logger : ILogger - { - private readonly LogLevel _logLevel; - - public Logger(LogLevel logLevel) - { - _logLevel = logLevel; - } - - public IDisposable BeginScope(TState state) - { - return NullDisposable.Instance; - } - - public bool IsEnabled(LogLevel logLevel) - { - return _logLevel <= logLevel; - } - - public void Log(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func formatter) - { - if (IsEnabled(logLevel)) - { - Console.WriteLine(formatter(state, exception)); - if (exception != null) - { - Console.WriteLine(exception.ToString()); - } - } - } - } - - private class NullDisposable : IDisposable - { - public static readonly IDisposable Instance = new NullDisposable(); - - private NullDisposable() - { - } - - public void Dispose() - { - } - } -} diff --git a/src/NATS.Client.Core/NatsConnection.cs b/src/NATS.Client.Core/NatsConnection.cs index b9e67874f..5455eb072 100644 --- a/src/NATS.Client.Core/NatsConnection.cs +++ b/src/NATS.Client.Core/NatsConnection.cs @@ -147,7 +147,7 @@ public async ValueTask DisposeAsync() if (!_isDisposed) { _isDisposed = true; - _logger.Log(LogLevel.Information, $"Disposing connection {_name}."); + _logger.Log(LogLevel.Information, NatsLogEvents.Connection, "Disposing connection {Name}", _name); await DisposeSocketAsync(false).ConfigureAwait(false); if (_pingTimerCancellationTokenSource != null) @@ -232,7 +232,7 @@ internal ValueTask UnsubscribeAsync(int sid) return ValueTask.CompletedTask; } - _logger.LogError(ex, "Failed to send unsubscribe command."); + _logger.LogError(NatsLogEvents.Subscription, ex, "Failed to send unsubscribe command"); } return ValueTask.CompletedTask; @@ -265,11 +265,11 @@ private async ValueTask InitialConnectAsync() var target = (uri.Host, uri.Port); if (OnConnectingAsync != null) { - _logger.LogInformation("Try to invoke OnConnectingAsync before connect to NATS."); + _logger.LogInformation(NatsLogEvents.Connection, "Try to invoke OnConnectingAsync before connect to NATS"); target = await OnConnectingAsync(target).ConfigureAwait(false); } - _logger.LogInformation("Try to connect NATS {0}", uri); + _logger.LogInformation(NatsLogEvents.Connection, "Try to connect NATS {0}", uri); if (uri.IsWebSocket) { var conn = new WebSocketConnection(); @@ -296,7 +296,7 @@ private async ValueTask InitialConnectAsync() } catch (Exception ex) { - _logger.LogError(ex, "Fail to connect NATS {0}", uri); + _logger.LogError(NatsLogEvents.Connection, ex, "Fail to connect NATS {Url}", uri); } } @@ -336,7 +336,7 @@ private async ValueTask InitialConnectAsync() lock (_gate) { var url = _currentConnectUri; - _logger.LogInformation("Connect succeed {0}, NATS {1}", _name, url); + _logger.LogInformation(NatsLogEvents.Connection, "Connect succeed {Name}, NATS {Url}", _name, url); ConnectionState = NatsConnectionState.Open; _pingTimerCancellationTokenSource = new CancellationTokenSource(); StartPingTimer(_pingTimerCancellationTokenSource.Token); @@ -382,7 +382,7 @@ private async ValueTask SetupReaderWriterAsync(bool reconnect) // do TLS upgrade var targetUri = FixTlsHost(_currentConnectUri); - _logger.LogDebug("Perform TLS Upgrade to " + targetUri); + _logger.LogDebug(NatsLogEvents.Security, "Perform TLS Upgrade to {Uri}", targetUri); // cancel INFO parsed signal and dispose current socket reader infoParsedSignal.SetCanceled(); @@ -437,7 +437,7 @@ private async ValueTask SetupReaderWriterAsync(bool reconnect) { if (e is NatsServerException { IsAuthError: true } se) { - _logger.LogWarning("Authentication error: {Error}", se.Error); + _logger.LogWarning(NatsLogEvents.Security, "Authentication error: {Error}", se.Error); var error = se.Error; string last; @@ -454,7 +454,7 @@ private async ValueTask SetupReaderWriterAsync(bool reconnect) _stopRetries = true; } - _logger.LogError("Received same authentication error ({Error}) twice in a row. Stopping retires", se.Error); + _logger.LogError(NatsLogEvents.Security, "Received same authentication error ({Error}) twice in a row. Stopping retires", se.Error); } } @@ -471,7 +471,7 @@ private async void ReconnectLoop() // If dispose this client, WaitForClosed throws OperationCanceledException so stop reconnect-loop correctly. await _socket!.WaitForClosed.ConfigureAwait(false); - _logger.LogTrace($"Detect connection {_name} closed, start to cleanup current connection and start to reconnect."); + _logger.LogTrace(NatsLogEvents.Connection, "Connection {Name} is closed. Will cleanup and reconnect", _name); lock (_gate) { ConnectionState = NatsConnectionState.Reconnecting; @@ -510,7 +510,7 @@ private async void ReconnectLoop() if (OnConnectingAsync != null) { var target = (url.Host, url.Port); - _logger.LogInformation("Try to invoke OnConnectingAsync before connect to NATS."); + _logger.LogInformation(NatsLogEvents.Connection, "Try to invoke OnConnectingAsync before connect to NATS"); var newTarget = await OnConnectingAsync(target).ConfigureAwait(false); if (newTarget.Host != target.Host || newTarget.Port != target.Port) @@ -519,7 +519,7 @@ private async void ReconnectLoop() } } - _logger.LogInformation("Try to connect NATS {0}", url); + _logger.LogInformation(NatsLogEvents.Connection, "Tried to connect NATS {Url}", url); if (url.IsWebSocket) { var conn = new WebSocketConnection(); @@ -556,7 +556,7 @@ private async void ReconnectLoop() { if (url != null) { - _logger.LogError(ex, "Fail to connect NATS {0}", url); + _logger.LogError(NatsLogEvents.Connection, ex, "Failed to connect NATS {Url}", url); } ReconnectFailed?.Invoke(this, url?.ToString() ?? string.Empty); @@ -568,7 +568,7 @@ private async void ReconnectLoop() { _connectRetry = 0; _backoff = TimeSpan.Zero; - _logger.LogInformation("Connect succeed {0}, NATS {1}", _name, url); + _logger.LogInformation(NatsLogEvents.Connection, "Connection succeeded {Name}, NATS {Url}", _name, url); ConnectionState = NatsConnectionState.Open; _pingTimerCancellationTokenSource = new CancellationTokenSource(); StartPingTimer(_pingTimerCancellationTokenSource.Token); @@ -582,7 +582,7 @@ private async void ReconnectLoop() if (ex is OperationCanceledException) return; _waitForOpenConnection.TrySetException(ex); - _logger.LogError(ex, "Retry loop stopped and connection state is invalid"); + _logger.LogError(NatsLogEvents.Connection, ex, "Retry loop stopped and connection state is invalid"); } } @@ -654,7 +654,7 @@ private async Task WaitWithJitterAsync() var waitTime = TimeSpan.FromMilliseconds(jitter) + backoff; if (waitTime != TimeSpan.Zero) { - _logger.LogTrace("Wait {0}ms to reconnect.", waitTime.TotalMilliseconds); + _logger.LogTrace(NatsLogEvents.Connection, "Waiting {WaitMs}ms to reconnect", waitTime.TotalMilliseconds); await Task.Delay(waitTime).ConfigureAwait(false); } } @@ -672,7 +672,7 @@ private async void StartPingTimer(CancellationToken cancellationToken) { if (Interlocked.Increment(ref _pongCount) > Opts.MaxPingOut) { - _logger.LogInformation("Detect MaxPingOut, try to connection abort."); + _logger.LogInformation(NatsLogEvents.Connection, "Server didn't respond to our ping requests. Aborting connection"); if (_socket != null) { await _socket.AbortConnectionAsync(cancellationToken).ConfigureAwait(false); @@ -733,7 +733,7 @@ private async ValueTask DisposeSocketComponentAsync(IAsyncDisposable component, } catch (Exception ex) { - _logger.LogError(ex, $"Error occured when disposing {description}."); + _logger.LogError(NatsLogEvents.Connection, ex, $"Error occured when disposing {description}"); } } diff --git a/src/NATS.Client.Core/NatsLogEvents.cs b/src/NATS.Client.Core/NatsLogEvents.cs new file mode 100644 index 000000000..1cd9af164 --- /dev/null +++ b/src/NATS.Client.Core/NatsLogEvents.cs @@ -0,0 +1,14 @@ +using Microsoft.Extensions.Logging; + +namespace NATS.Client.Core; + +public static class NatsLogEvents +{ + public static readonly EventId Connection = new(1001, nameof(Connection)); + public static readonly EventId Subscription = new(1002, nameof(Subscription)); + public static readonly EventId Security = new(1003, nameof(Security)); + public static readonly EventId InboxSubscription = new(1004, nameof(InboxSubscription)); + public static readonly EventId Protocol = new(1005, nameof(Protocol)); + public static readonly EventId TcpSocket = new(1006, nameof(TcpSocket)); + public static readonly EventId Internal = new(1006, nameof(Internal)); +} diff --git a/src/NATS.Client.Core/NatsSubBase.cs b/src/NATS.Client.Core/NatsSubBase.cs index 9ce43edd5..1b97fefeb 100644 --- a/src/NATS.Client.Core/NatsSubBase.cs +++ b/src/NATS.Client.Core/NatsSubBase.cs @@ -285,7 +285,7 @@ protected void DecrementMaxMsgs() protected void EndSubscription(NatsSubEndReason reason) { if (_debug) - _logger.LogDebug("End subscription {Reason}", reason); + _logger.LogDebug(NatsLogEvents.Subscription, "End subscription {Reason}", reason); lock (this) { diff --git a/src/NATS.Client.JetStream/Internal/NatsJSConsume.cs b/src/NATS.Client.JetStream/Internal/NatsJSConsume.cs index 20c6d87ea..91722057c 100644 --- a/src/NATS.Client.JetStream/Internal/NatsJSConsume.cs +++ b/src/NATS.Client.JetStream/Internal/NatsJSConsume.cs @@ -155,7 +155,7 @@ public ValueTask CallMsgNextAsync(string origin, ConsumerGetnextRequest request, if (_debug) { - _logger.LogDebug("Sending pull request for {Origin} {Msgs}, {Bytes}", origin, request.Batch, request.MaxBytes); + _logger.LogDebug(NatsJSLogEvents.PullRequest, "Sending pull request for {Origin} {Msgs}, {Bytes}", origin, request.Batch, request.MaxBytes); } return Connection.PubModelAsync( @@ -311,10 +311,7 @@ protected override async ValueTask ReceiveInternalAsync( } else { - if (_debug) - { - _logger.LogDebug(NatsJSLogEvents.ProtocolMessage, "Protocol message: {Code} {Description}", headers.Code, headers.MessageText); - } + _logger.LogWarning(NatsJSLogEvents.ProtocolMessage, "Unhandled protocol message: {Code} {Description}", headers.Code, headers.MessageText); } } else diff --git a/src/NATS.Client.JetStream/Internal/NatsJSFetch.cs b/src/NATS.Client.JetStream/Internal/NatsJSFetch.cs index 967860fe6..8997cfdb7 100644 --- a/src/NATS.Client.JetStream/Internal/NatsJSFetch.cs +++ b/src/NATS.Client.JetStream/Internal/NatsJSFetch.cs @@ -209,14 +209,7 @@ protected override async ValueTask ReceiveInternalAsync( } else { - if (_debug) - { - _logger.LogDebug( - NatsJSLogEvents.ProtocolMessage, - "Protocol message: {Code} {Description}", - headers.Code, - headers.MessageText); - } + _logger.LogWarning(NatsJSLogEvents.ProtocolMessage, "Unhandled protocol message: {Code} {Description}", headers.Code, headers.MessageText); } } else diff --git a/src/NATS.Client.JetStream/Internal/NatsJSOrderedConsume.cs b/src/NATS.Client.JetStream/Internal/NatsJSOrderedConsume.cs index 814c8e513..70d351412 100644 --- a/src/NATS.Client.JetStream/Internal/NatsJSOrderedConsume.cs +++ b/src/NATS.Client.JetStream/Internal/NatsJSOrderedConsume.cs @@ -89,7 +89,7 @@ public NatsJSOrderedConsume( static state => { var self = (NatsJSOrderedConsume)state!; - self._logger.LogWarning("Idle heartbeat timeout"); + self._logger.LogWarning(NatsJSLogEvents.IdleTimeout, "Idle heartbeat timeout"); self._userMsgs.Writer.TryComplete(new NatsJSTimeoutException("idle-heartbeat")); }, this, @@ -123,7 +123,7 @@ public ValueTask CallMsgNextAsync(string origin, ConsumerGetnextRequest request, if (_debug) { - _logger.LogDebug("Sending pull request for {Origin} {Msgs}, {Bytes}", origin, request.Batch, request.MaxBytes); + _logger.LogDebug(NatsJSLogEvents.PullRequest, "Sending pull request for {Origin} {Msgs}, {Bytes}", origin, request.Batch, request.MaxBytes); } return Connection.PubModelAsync( @@ -255,10 +255,7 @@ protected override async ValueTask ReceiveInternalAsync( } else { - if (_debug) - { - _logger.LogDebug(NatsJSLogEvents.ProtocolMessage, "Protocol message: {Code} {Description}", headers.Code, headers.MessageText); - } + _logger.LogWarning(NatsJSLogEvents.ProtocolMessage, "Unhandled protocol message: {Code} {Description}", headers.Code, headers.MessageText); } } else @@ -327,7 +324,7 @@ protected override void TryComplete() private void ConnectionOnConnectionDisconnected(object? sender, string e) { - _logger.LogWarning("Disconnected {Reason}", e); + _logger.LogWarning(NatsJSLogEvents.Connection, "Disconnected {Reason}", e); _userMsgs.Writer.TryComplete(new NatsJSConnectionException(e)); } diff --git a/src/NATS.Client.JetStream/Internal/NatsJSOrderedPushConsumer.cs b/src/NATS.Client.JetStream/Internal/NatsJSOrderedPushConsumer.cs index c1099ab61..5753acf24 100644 --- a/src/NATS.Client.JetStream/Internal/NatsJSOrderedPushConsumer.cs +++ b/src/NATS.Client.JetStream/Internal/NatsJSOrderedPushConsumer.cs @@ -224,7 +224,7 @@ private async Task CommandLoop() if (sequence != metadata.Sequence.Consumer) { CreateSub("sequence-mismatch"); - _logger.LogWarning("Missed messages, recreating consumer"); + _logger.LogWarning(NatsJSLogEvents.RecreateConsumer, "Missed messages, recreating consumer"); continue; } @@ -248,7 +248,7 @@ private async Task CommandLoop() } else { - _logger.LogWarning("Protocol error: Message metadata is missing"); + _logger.LogWarning(NatsJSLogEvents.ProtocolMessage, "Protocol error: Message metadata is missing"); } } } @@ -258,12 +258,12 @@ private async Task CommandLoop() } else { - _logger.LogError("Internal error: unexpected command {Command}", subCommand); + _logger.LogError(NatsJSLogEvents.Internal, "Internal error: unexpected command {Command}", subCommand); } } catch (Exception e) { - _logger.LogWarning(e, "Command error"); + _logger.LogWarning(NatsJSLogEvents.Internal, e, "Command error"); } } } @@ -273,7 +273,7 @@ private async Task CommandLoop() } catch (Exception e) { - _logger.LogError(e, "Unexpected command loop error"); + _logger.LogError(NatsJSLogEvents.Internal, e, "Unexpected command loop error"); } } @@ -291,7 +291,7 @@ private async Task ConsumerCreateLoop() } catch (Exception e) { - _logger.LogWarning(e, "Consumer create error"); + _logger.LogWarning(NatsJSLogEvents.RecreateConsumer, e, "Consumer create error"); } } } @@ -301,7 +301,7 @@ private async Task ConsumerCreateLoop() } catch (Exception e) { - _logger.LogError(e, "Unexpected consumer create loop error"); + _logger.LogError(NatsJSLogEvents.Internal, e, "Unexpected consumer create loop error"); } } diff --git a/src/NATS.Client.JetStream/NatsJSLogEvents.cs b/src/NATS.Client.JetStream/NatsJSLogEvents.cs index 3771634a6..a78bd9e2f 100644 --- a/src/NATS.Client.JetStream/NatsJSLogEvents.cs +++ b/src/NATS.Client.JetStream/NatsJSLogEvents.cs @@ -19,4 +19,8 @@ public static class NatsJSLogEvents public static readonly EventId NewConsumerCreated = new(2013, nameof(NewConsumerCreated)); public static readonly EventId Stopping = new(2014, nameof(Stopping)); public static readonly EventId LeadershipChange = new(2015, nameof(LeadershipChange)); + public static readonly EventId Connection = new(2016, nameof(Connection)); + public static readonly EventId RecreateConsumer = new(2017, nameof(RecreateConsumer)); + public static readonly EventId Internal = new(2018, nameof(Internal)); + public static readonly EventId Retry = new(2019, nameof(Retry)); } diff --git a/src/NATS.Client.JetStream/NatsJSOrderedConsumer.cs b/src/NATS.Client.JetStream/NatsJSOrderedConsumer.cs index c2bbae0a6..2d7ab6f24 100644 --- a/src/NATS.Client.JetStream/NatsJSOrderedConsumer.cs +++ b/src/NATS.Client.JetStream/NatsJSOrderedConsumer.cs @@ -71,7 +71,7 @@ public async IAsyncEnumerable> ConsumeAsync( { var consumer = await RecreateConsumer(consumerName, seq, cancellationToken); consumerName = consumer.Info.Name; - _logger.LogInformation("Created {ConsumerName} with sequence {Seq}", consumerName, seq); + _logger.LogInformation(NatsJSLogEvents.NewConsumer, "Created {ConsumerName} with sequence {Seq}", consumerName, seq); NatsJSProtocolException? protocolException = default; @@ -102,13 +102,13 @@ public async IAsyncEnumerable> ConsumeAsync( } catch (NatsJSConnectionException e) { - _logger.LogWarning($"{e.Message}. Retrying..."); + _logger.LogWarning(NatsJSLogEvents.Retry, "{Error}. Retrying...", e.Message); goto CONSUME_LOOP; } catch (NatsJSTimeoutException e) { notificationHandler?.Invoke(new NatsJSTimeoutNotification(), cancellationToken); - _logger.LogWarning($"{e.Message}. Retrying..."); + _logger.LogWarning(NatsJSLogEvents.Retry, "{Error}. Retrying...", e.Message); goto CONSUME_LOOP; } @@ -133,13 +133,13 @@ public async IAsyncEnumerable> ConsumeAsync( } catch (NatsJSConnectionException e) { - _logger.LogWarning($"{e.Message}. Retrying..."); + _logger.LogWarning(NatsJSLogEvents.Retry, "{Error}. Retrying...", e.Message); goto CONSUME_LOOP; } catch (NatsJSTimeoutException e) { notificationHandler?.Invoke(new NatsJSTimeoutNotification(), cancellationToken); - _logger.LogWarning($"{e.Message}. Retrying..."); + _logger.LogWarning(NatsJSLogEvents.Retry, "{Error}. Retrying...", e.Message); goto CONSUME_LOOP; } @@ -155,7 +155,7 @@ public async IAsyncEnumerable> ConsumeAsync( CONSUME_LOOP: - _logger.LogWarning("Consumer loop exited"); + _logger.LogWarning(NatsJSLogEvents.Internal, "Consumer loop exited"); if (protocolException != null) { diff --git a/src/NATS.Client.KeyValueStore/Internal/NatsKVWatcher.cs b/src/NATS.Client.KeyValueStore/Internal/NatsKVWatcher.cs index 52e46aae3..968f9a070 100644 --- a/src/NATS.Client.KeyValueStore/Internal/NatsKVWatcher.cs +++ b/src/NATS.Client.KeyValueStore/Internal/NatsKVWatcher.cs @@ -176,7 +176,7 @@ private async Task CommandLoop() { var exception = new NatsKVException("Message metadata is missing"); _entryChannel.Writer.TryComplete(exception); - _logger.LogError("Protocol error: unexpected number ({Count}) of KV-Operation headers", operationValues.Count); + _logger.LogError(NatsKVLogEvents.Protocol, "Protocol error: unexpected number ({Count}) of KV-Operation headers", operationValues.Count); return; } @@ -202,7 +202,7 @@ private async Task CommandLoop() { if (msg.Subject.Length <= _keyBase.Length) { - _logger.LogWarning("Protocol error: unexpected message subject {Subject}", msg.Subject); + _logger.LogWarning(NatsKVLogEvents.Protocol, "Protocol error: unexpected message subject {Subject}", msg.Subject); continue; } @@ -223,7 +223,7 @@ private async Task CommandLoop() if (sequence != (long)metadata.Sequence.Consumer) { CreateSub("sequence-mismatch"); - _logger.LogWarning("Missed messages, recreating consumer"); + _logger.LogWarning(NatsKVLogEvents.RecreateConsumer, "Missed messages, recreating consumer"); continue; } @@ -252,7 +252,7 @@ private async Task CommandLoop() } else { - _logger.LogWarning("Protocol error: Message metadata is missing"); + _logger.LogWarning(NatsKVLogEvents.Protocol, "Protocol error: Message metadata is missing"); } } } @@ -262,12 +262,12 @@ private async Task CommandLoop() } else { - _logger.LogError("Internal error: unexpected command {Command}", subCommand); + _logger.LogError(NatsKVLogEvents.Internal, "Internal error: unexpected command {Command}", subCommand); } } catch (Exception e) { - _logger.LogWarning(e, "Command error"); + _logger.LogWarning(NatsKVLogEvents.Internal, e, "Command error"); } } } @@ -277,7 +277,7 @@ private async Task CommandLoop() } catch (Exception e) { - _logger.LogError(e, "Unexpected command loop error"); + _logger.LogError(NatsKVLogEvents.Internal, e, "Unexpected command loop error"); } } @@ -295,7 +295,7 @@ private async Task ConsumerCreateLoop() } catch (Exception e) { - _logger.LogWarning(e, "Consumer create error"); + _logger.LogWarning(NatsKVLogEvents.NewConsumer, e, "Consumer create error"); } } } @@ -305,7 +305,7 @@ private async Task ConsumerCreateLoop() } catch (Exception e) { - _logger.LogError(e, "Unexpected consumer create loop error"); + _logger.LogError(NatsKVLogEvents.Internal, e, "Unexpected consumer create loop error"); } } diff --git a/src/NATS.Client.KeyValueStore/NatsKVLogEvents.cs b/src/NATS.Client.KeyValueStore/NatsKVLogEvents.cs index fc6b177fa..a64fb5ae2 100644 --- a/src/NATS.Client.KeyValueStore/NatsKVLogEvents.cs +++ b/src/NATS.Client.KeyValueStore/NatsKVLogEvents.cs @@ -9,4 +9,7 @@ public static class NatsKVLogEvents public static readonly EventId NewConsumerCreated = new(3003, nameof(NewConsumerCreated)); public static readonly EventId DeleteOldDeliverySubject = new(3004, nameof(DeleteOldDeliverySubject)); public static readonly EventId NewDeliverySubject = new(3005, nameof(NewDeliverySubject)); + public static readonly EventId Protocol = new(3006, nameof(Protocol)); + public static readonly EventId RecreateConsumer = new(3007, nameof(RecreateConsumer)); + public static readonly EventId Internal = new(3008, nameof(Internal)); } diff --git a/src/NATS.Client.Services/NatsSvcEndPoint.cs b/src/NATS.Client.Services/NatsSvcEndPoint.cs index 4433f3ab7..d066442e7 100644 --- a/src/NATS.Client.Services/NatsSvcEndPoint.cs +++ b/src/NATS.Client.Services/NatsSvcEndPoint.cs @@ -195,7 +195,7 @@ protected override ValueTask ReceiveInternalAsync( } catch (Exception e) { - _logger.LogError(e, "Endpoint {Name} error building message", Name); + _logger.LogError(NatsSvcLogEvents.Endpoint, e, "Endpoint {Name} error building message", Name); exception = e; // Most likely a serialization error. @@ -240,7 +240,7 @@ private async Task HandlerLoop() body = string.Empty; // Only log unknown exceptions - _logger.LogError(e, "Endpoint {Name} error processing message", Name); + _logger.LogError(NatsSvcLogEvents.Endpoint, e, "Endpoint {Name} error processing message", Name); } try @@ -256,7 +256,7 @@ private async Task HandlerLoop() } catch (Exception e1) { - _logger.LogError(e1, "Endpoint {Name} error responding", Name); + _logger.LogError(NatsSvcLogEvents.Endpoint, e1, "Endpoint {Name} error responding", Name); } } finally diff --git a/src/NATS.Client.Services/NatsSvcLogEvents.cs b/src/NATS.Client.Services/NatsSvcLogEvents.cs new file mode 100644 index 000000000..3bc385802 --- /dev/null +++ b/src/NATS.Client.Services/NatsSvcLogEvents.cs @@ -0,0 +1,8 @@ +using Microsoft.Extensions.Logging; + +namespace NATS.Client.Services; + +public static class NatsSvcLogEvents +{ + public static readonly EventId Endpoint = new(5001, nameof(Endpoint)); +}