Tidy-up logging (#228)

* Tidy-up logging Added logging event ids and a few typo fixes. * Update src/NATS.Client.Core/Internal/NatsReadProtocolProcessor.cs Co-authored-by: Tomasz Pietrek <melgaer@gmail.com> * Update src/NATS.Client.Core/NatsConnection.cs Co-authored-by: Tomasz Pietrek <melgaer@gmail.com> * Update src/NATS.Client.Core/NatsConnection.cs Co-authored-by: Tomasz Pietrek <melgaer@gmail.com> * Update src/NATS.Client.Core/NatsConnection.cs Co-authored-by: Tomasz Pietrek <melgaer@gmail.com> * Log message grammar fixes --------- Co-authored-by: Tomasz Pietrek <melgaer@gmail.com>
nats-io · Nov 23, 2023 · 38d2f5f · 38d2f5f
1 parent 1698442
commit 38d2f5f
Show file tree

Hide file tree

Showing 39 changed files with 202 additions and 164 deletions.
diff --git 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>(TState state) => NullDisposable.Instance;
+
+        public bool IsEnabled(LogLevel logLevel) => _logLevel <= logLevel;
+
+        public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func<TState, Exception?, string> 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
@@ -12,4 +12,8 @@
       <ProjectReference Include="..\..\src\NATS.Client.Core\NATS.Client.Core.csproj" />
     </ItemGroup>
 
+    <ItemGroup>
+      <PackageReference Include="Microsoft.Extensions.Logging.Console" Version="6.0.0" />
+    </ItemGroup>
+
 </Project>
diff --git 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
@@ -12,4 +12,8 @@
       <ProjectReference Include="..\..\src\NATS.Client.Core\NATS.Client.Core.csproj" />
     </ItemGroup>
 
+  <ItemGroup>
+    <PackageReference Include="Microsoft.Extensions.Logging.Console" Version="6.0.0" />
+  </ItemGroup>
+
 </Project>
diff --git 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
@@ -12,4 +12,8 @@
       <ProjectReference Include="..\..\src\NATS.Client.Core\NATS.Client.Core.csproj" />
     </ItemGroup>
 
+  <ItemGroup>
+    <PackageReference Include="Microsoft.Extensions.Logging.Console" Version="6.0.0" />
+  </ItemGroup>
+
 </Project>
diff --git 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
@@ -12,4 +12,8 @@
       <ProjectReference Include="..\..\src\NATS.Client.Core\NATS.Client.Core.csproj" />
     </ItemGroup>
 
+  <ItemGroup>
+    <PackageReference Include="Microsoft.Extensions.Logging.Console" Version="6.0.0" />
+  </ItemGroup>
+
 </Project>
diff --git 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
@@ -12,4 +12,8 @@
       <ProjectReference Include="..\..\src\NATS.Client.Core\NATS.Client.Core.csproj" />
     </ItemGroup>
 
+  <ItemGroup>
+    <PackageReference Include="Microsoft.Extensions.Logging.Console" Version="6.0.0" />
+  </ItemGroup>
+
 </Project>
diff --git 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
@@ -13,4 +13,8 @@
       <ProjectReference Include="..\..\src\NATS.Client.Core\NATS.Client.Core.csproj" />
     </ItemGroup>
 
+  <ItemGroup>
+    <PackageReference Include="Microsoft.Extensions.Logging.Console" Version="6.0.0" />
+  </ItemGroup>
+
 </Project>
diff --git 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
@@ -12,4 +12,8 @@
       <ProjectReference Include="..\..\src\NATS.Client.JetStream\NATS.Client.JetStream.csproj" />
     </ItemGroup>
 
+  <ItemGroup>
+    <PackageReference Include="Microsoft.Extensions.Logging.Console" Version="6.0.0" />
+  </ItemGroup>
+
 </Project>
diff --git 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
@@ -12,4 +12,8 @@
       <ProjectReference Include="..\..\src\NATS.Client.ObjectStore\NATS.Client.ObjectStore.csproj" />
     </ItemGroup>
 
+  <ItemGroup>
+    <PackageReference Include="Microsoft.Extensions.Logging.Console" Version="6.0.0" />
+  </ItemGroup>
+
 </Project>
diff --git 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
@@ -12,4 +12,8 @@
       <ProjectReference Include="..\..\src\NATS.Client.Services\NATS.Client.Services.csproj" />
     </ItemGroup>
 
+  <ItemGroup>
+    <PackageReference Include="Microsoft.Extensions.Logging.Console" Version="6.0.0" />
+  </ItemGroup>
+
 </Project>
diff --git 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
@@ -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
@@ -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<ReadOnlySequence<byte>> 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<ReadOnlySequence<byte>> 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<ReadOnlySequence<byte>> 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<ReadOnlySequence<byte>> 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
@@ -53,7 +53,7 @@ public async ValueTask<ReadOnlySequence<byte>> 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<ReadOnlySequence<byte>> 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
@@ -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
@@ -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<int>();
                     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<int> 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);
             }
         }
     }