Replace DiagnosticAbstration with Microsoft.Extensions.Logging.Abstractions (#1509)

* Replace DiagnosticAbstrations with Microsoft.Extensions.Logging.Abstractions

* add documentation

* reduce allocations by SessionId hex conversion

generate the hex string once instead of every log
call and optimize ToHex().

* Update docfx/logging.md

Co-authored-by: Rob Hague <[email protected]>

* reduce log levels

* hook up testcontainers logging

* drop packet logs further down to trace

* add kex traces

---------

Co-authored-by: Rob Hague <[email protected]>

Author: mus65

.editorconfig

@@ -704,6 +704,9 @@ dotnet_code_quality.CA1828.api_surface = all
 # Similar to MA0053, but does not support public types and types that define (new) virtual members.
 dotnet_diagnostic.CA1852.severity = none
 
+# CA1848: don't enforce LoggerMessage pattern
+dotnet_diagnostic.CA1848.severity = suggestion
+
 # CA1859: Change return type for improved performance
 #
 # By default, this diagnostic is only reported for private members.

CONTRIBUTING.md

@@ -34,9 +34,9 @@ The repository makes use of continuous integration (CI) with GitHub Actions to v
 
 ## Good to know
 
-### TraceSource logging
+### Logging
 
-The Debug build of SSH.NET contains rudimentary logging functionality via `System.Diagnostics.TraceSource`. See `Renci.SshNet.Abstractions.DiagnosticAbstraction` for usage examples.
+The tests always log to the console. See the [Logging documentation](https://sshnet.github.io/SSH.NET/logging.html) on how to set a custom `ILoggerFactory`.
 
 ### Wireshark
 

Directory.Packages.props

@@ -15,6 +15,9 @@
     <PackageVersion Include="Meziantou.Analyzer" Version="2.0.163" />
     <!-- Must be kept at version 1.0.0 or higher, see https://github.com/sshnet/SSH.NET/pull/1288 for details. -->
     <PackageVersion Include="Microsoft.Bcl.AsyncInterfaces" Version="1.0.0" />
+    <PackageVersion Include="Microsoft.Extensions.Logging" Version="8.0.0" />
+    <PackageVersion Include="Microsoft.Extensions.Logging.Abstractions" Version="6.0.0" />
+    <PackageVersion Include="Microsoft.Extensions.Logging.Console" Version="8.0.0" />
     <PackageVersion Include="Microsoft.NET.Test.Sdk" Version="17.11.1" />
     <PackageVersion Include="MSTest.TestAdapter" Version="3.6.2" />
     <PackageVersion Include="MSTest.TestFramework" Version="3.6.2" />

README.md

@@ -62,6 +62,7 @@ The main types provided by this library are:
 ## Additional Documentation
 
 * [Further examples](https://sshnet.github.io/SSH.NET/examples.html)
+* [Logging](https://sshnet.github.io/SSH.NET/logging.html)
 * [API browser](https://sshnet.github.io/SSH.NET/api/Renci.SshNet.html)
 
 ## Encryption Methods

docfx/logging.md

@@ -0,0 +1,15 @@
+Logging
+=================
+
+SSH.NET uses the [Microsoft.Extensions.Logging](https://learn.microsoft.com/dotnet/core/extensions/logging) API to log diagnostic messages. In order to access the log messages of SSH.NET in your own application for diagnosis, register your own `ILoggerFactory` before using the SSH.NET APIs, for example:
+
+```cs
+ILoggerFactory loggerFactory = LoggerFactory.Create(builder =>
+{
+    builder.SetMinimumLevel(LogLevel.Debug);
+    builder.AddConsole();
+});
+
+Renci.SshNet.SshNetLoggingConfiguration.InitializeLogging(loggerFactory);
+
+All messages by SSH.NET are logged under the `Renci.SshNet` category.

src/Renci.SshNet/Abstractions/DiagnosticAbstraction.cs

@@ -4,7 +4,8 @@
 using System.Threading;
 using System.Threading.Tasks;
 
-using Renci.SshNet.Abstractions;
+using Microsoft.Extensions.Logging;
+
 using Renci.SshNet.Common;
 using Renci.SshNet.Messages.Transport;
 
@@ -20,6 +21,7 @@ public abstract class BaseClient : IBaseClient
         /// </summary>
         private readonly bool _ownsConnectionInfo;
 
+        private readonly ILogger _logger;
         private readonly IServiceFactory _serviceFactory;
         private readonly object _keepAliveLock = new object();
         private TimeSpan _keepAliveInterval;
@@ -190,6 +192,7 @@ private protected BaseClient(ConnectionInfo connectionInfo, bool ownsConnectionI
             _connectionInfo = connectionInfo;
             _ownsConnectionInfo = ownsConnectionInfo;
             _serviceFactory = serviceFactory;
+            _logger = SshNetLoggingConfiguration.LoggerFactory.CreateLogger(GetType());
             _keepAliveInterval = Timeout.InfiniteTimeSpan;
         }
 
@@ -343,7 +346,7 @@ public async Task ConnectAsync(CancellationToken cancellationToken)
         /// <exception cref="ObjectDisposedException">The method was called after the client was disposed.</exception>
         public void Disconnect()
         {
-            DiagnosticAbstraction.Log("Disconnecting client.");
+            _logger.LogInformation("Disconnecting client.");
 
             CheckDisposed();
 
@@ -442,7 +445,7 @@ protected virtual void Dispose(bool disposing)
 
             if (disposing)
             {
-                DiagnosticAbstraction.Log("Disposing client.");
+                _logger.LogDebug("Disposing client.");
 
                 Disconnect();
 

src/Renci.SshNet/BaseClient.cs

@@ -2,7 +2,8 @@
 using System.Net.Sockets;
 using System.Threading;
 
-using Renci.SshNet.Abstractions;
+using Microsoft.Extensions.Logging;
+
 using Renci.SshNet.Common;
 using Renci.SshNet.Messages;
 using Renci.SshNet.Messages.Connection;
@@ -18,6 +19,7 @@ internal abstract class Channel : IChannel
         private readonly Lock _messagingLock = new Lock();
         private readonly uint _initialWindowSize;
         private readonly ISession _session;
+        private readonly ILogger _logger;
         private EventWaitHandle _channelClosedWaitHandle = new ManualResetEvent(initialState: false);
         private EventWaitHandle _channelServerWindowAdjustWaitHandle = new ManualResetEvent(initialState: false);
         private uint? _remoteWindowSize;
@@ -81,6 +83,7 @@ protected Channel(ISession session, uint localChannelNumber, uint localWindowSiz
             LocalChannelNumber = localChannelNumber;
             LocalPacketSize = localPacketSize;
             LocalWindowSize = localWindowSize;
+            _logger = SshNetLoggingConfiguration.LoggerFactory.CreateLogger(GetType());
 
             session.ChannelWindowAdjustReceived += OnChannelWindowAdjust;
             session.ChannelDataReceived += OnChannelData;
@@ -555,7 +558,7 @@ protected virtual void Close()
                         var closeWaitResult = _session.TryWait(_channelClosedWaitHandle, ConnectionInfo.ChannelCloseTimeout);
                         if (closeWaitResult != WaitResult.Success)
                         {
-                            DiagnosticAbstraction.Log(string.Format("Wait for channel close not successful: {0:G}.", closeWaitResult));
+                            _logger.LogInformation("Wait for channel close not successful: {CloseWaitResult}", closeWaitResult);
                         }
                     }
                 }

src/Renci.SshNet/Channels/Channel.cs

@@ -3,6 +3,8 @@
 using System.Net.Sockets;
 using System.Threading;
 
+using Microsoft.Extensions.Logging;
+
 using Renci.SshNet.Abstractions;
 using Renci.SshNet.Common;
 using Renci.SshNet.Messages.Connection;
@@ -15,7 +17,7 @@ namespace Renci.SshNet.Channels
     internal sealed class ChannelDirectTcpip : ClientChannel, IChannelDirectTcpip
     {
         private readonly Lock _socketLock = new Lock();
-
+        private readonly ILogger _logger;
         private EventWaitHandle _channelOpen = new AutoResetEvent(initialState: false);
         private EventWaitHandle _channelData = new AutoResetEvent(initialState: false);
         private IForwardedPort _forwardedPort;
@@ -31,6 +33,7 @@ internal sealed class ChannelDirectTcpip : ClientChannel, IChannelDirectTcpip
         public ChannelDirectTcpip(ISession session, uint localChannelNumber, uint localWindowSize, uint localPacketSize)
             : base(session, localChannelNumber, localWindowSize, localPacketSize)
         {
+            _logger = SshNetLoggingConfiguration.LoggerFactory.CreateLogger<ChannelDirectTcpip>();
         }
 
         /// <summary>
@@ -157,8 +160,7 @@ private void ShutdownSocket(SocketShutdown how)
                 }
                 catch (SocketException ex)
                 {
-                    // TODO: log as warning
-                    DiagnosticAbstraction.Log("Failure shutting down socket: " + ex);
+                    _logger.LogInformation(ex, "Failure shutting down socket");
                 }
             }
         }

src/Renci.SshNet/Channels/ChannelDirectTcpip.cs

@@ -5,6 +5,8 @@
 using System.Threading;
 #endif
 
+using Microsoft.Extensions.Logging;
+
 using Renci.SshNet.Abstractions;
 using Renci.SshNet.Common;
 using Renci.SshNet.Messages.Connection;
@@ -17,6 +19,7 @@ namespace Renci.SshNet.Channels
     internal sealed class ChannelForwardedTcpip : ServerChannel, IChannelForwardedTcpip
     {
         private readonly Lock _socketShutdownAndCloseLock = new Lock();
+        private readonly ILogger _logger;
         private Socket _socket;
         private IForwardedPort _forwardedPort;
 
@@ -45,6 +48,7 @@ internal ChannelForwardedTcpip(ISession session,
                    remoteWindowSize,
                    remotePacketSize)
         {
+            _logger = SshNetLoggingConfiguration.LoggerFactory.CreateLogger<ChannelForwardedTcpip>();
         }
 
         /// <summary>
@@ -142,8 +146,7 @@ private void ShutdownSocket(SocketShutdown how)
                 }
                 catch (SocketException ex)
                 {
-                    // TODO: log as warning
-                    DiagnosticAbstraction.Log("Failure shutting down socket: " + ex);
+                    _logger.LogInformation(ex, "Failure shutting down socket");
                 }
             }
         }

src/Renci.SshNet/Channels/ChannelForwardedTcpip.cs

@@ -351,5 +351,12 @@ internal static bool IsConnected(this Socket socket)
 
             return socket.Connected;
         }
+
+        internal static string Join(this IEnumerable<string> values, string separator)
+        {
+            // Used to avoid analyzers asking to "use an overload with a char parameter"
+            // which is not available on all targets.
+            return string.Join(separator, values);
+        }
     }
 }

src/Renci.SshNet/Common/Extensions.cs

@@ -4,6 +4,8 @@
 using System.Threading;
 using System.Threading.Tasks;
 
+using Microsoft.Extensions.Logging;
+
 using Renci.SshNet.Abstractions;
 using Renci.SshNet.Common;
 using Renci.SshNet.Messages.Transport;
@@ -12,11 +14,14 @@ namespace Renci.SshNet.Connection
 {
     internal abstract class ConnectorBase : IConnector
     {
+        private readonly ILogger _logger;
+
         protected ConnectorBase(ISocketFactory socketFactory)
         {
             ThrowHelper.ThrowIfNull(socketFactory);
 
             SocketFactory = socketFactory;
+            _logger = SshNetLoggingConfiguration.LoggerFactory.CreateLogger(GetType());
         }
 
         internal ISocketFactory SocketFactory { get; private set; }
@@ -34,7 +39,7 @@ protected ConnectorBase(ISocketFactory socketFactory)
         /// <exception cref="SocketException">An error occurred trying to establish the connection.</exception>
         protected Socket SocketConnect(EndPoint endPoint, TimeSpan timeout)
         {
-            DiagnosticAbstraction.Log(string.Format("Initiating connection to '{0}'.", endPoint));
+            _logger.LogInformation("Initiating connection to '{EndPoint}'.", endPoint);
 
             var socket = SocketFactory.Create(SocketType.Stream, ProtocolType.Tcp);
 
@@ -65,7 +70,7 @@ protected async Task<Socket> SocketConnectAsync(EndPoint endPoint, CancellationT
         {
             cancellationToken.ThrowIfCancellationRequested();
 
-            DiagnosticAbstraction.Log(string.Format("Initiating connection to '{0}'.", endPoint));
+            _logger.LogInformation("Initiating connection to '{EndPoint}'.", endPoint);
 
             var socket = SocketFactory.Create(SocketType.Stream, ProtocolType.Tcp);
             try

src/Renci.SshNet/Connection/ConnectorBase.cs

@@ -7,6 +7,8 @@
 using System.Text;
 using System.Threading;
 
+using Microsoft.Extensions.Logging;
+
 using Renci.SshNet.Abstractions;
 using Renci.SshNet.Channels;
 using Renci.SshNet.Common;
@@ -19,6 +21,7 @@ namespace Renci.SshNet
     /// </summary>
     public class ForwardedPortDynamic : ForwardedPort
     {
+        private readonly ILogger _logger;
         private ForwardedPortStatus _status;
 
         /// <summary>
@@ -72,6 +75,7 @@ public ForwardedPortDynamic(string host, uint port)
             BoundHost = host;
             BoundPort = port;
             _status = ForwardedPortStatus.Stopped;
+            _logger = SshNetLoggingConfiguration.LoggerFactory.CreateLogger<ForwardedPortDynamic>();
         }
 
         /// <summary>
@@ -409,8 +413,7 @@ private void InternalStop(TimeSpan timeout)
 
             if (!_pendingChannelCountdown.Wait(timeout))
             {
-                // TODO: log as warning
-                DiagnosticAbstraction.Log("Timeout waiting for pending channels in dynamic forwarded port to close.");
+                _logger.LogInformation("Timeout waiting for pending channels in dynamic forwarded port to close.");
             }
         }