From 553e47fca299f6101b5d94f3d29cc4f89229fff1 Mon Sep 17 00:00:00 2001 From: Marius Thesing Date: Sat, 28 Sep 2024 14:27:45 +0200 Subject: [PATCH 1/8] Replace DiagnosticAbstrations with Microsoft.Extensions.Logging.Abstractions --- .editorconfig | 3 + Directory.Packages.props | 3 + .../Abstractions/DiagnosticAbstraction.cs | 69 ------------------- src/Renci.SshNet/BaseClient.cs | 9 ++- src/Renci.SshNet/Channels/Channel.cs | 7 +- .../Channels/ChannelDirectTcpip.cs | 7 +- .../Channels/ChannelForwardedTcpip.cs | 7 +- src/Renci.SshNet/Connection/ConnectorBase.cs | 9 ++- src/Renci.SshNet/ForwardedPortDynamic.cs | 7 +- src/Renci.SshNet/ForwardedPortLocal.cs | 8 ++- src/Renci.SshNet/ForwardedPortRemote.cs | 7 +- src/Renci.SshNet/Renci.SshNet.csproj | 1 + src/Renci.SshNet/Security/KeyExchange.cs | 33 +++++---- src/Renci.SshNet/ServiceFactory.cs | 12 +++- src/Renci.SshNet/Session.cs | 39 ++++++----- src/Renci.SshNet/Sftp/SftpFileReader.cs | 6 +- .../SshNetLoggingConfiguration.cs | 26 +++++++ src/Renci.SshNet/SubsystemSession.cs | 7 +- .../Renci.SshNet.IntegrationTests.csproj | 2 + .../TestsFixtures/IntegrationTestBase.cs | 28 ++++---- 20 files changed, 151 insertions(+), 139 deletions(-) delete mode 100644 src/Renci.SshNet/Abstractions/DiagnosticAbstraction.cs create mode 100644 src/Renci.SshNet/SshNetLoggingConfiguration.cs diff --git a/.editorconfig b/.editorconfig index 562309d42..8293ee23e 100644 --- a/.editorconfig +++ b/.editorconfig @@ -701,6 +701,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. diff --git a/Directory.Packages.props b/Directory.Packages.props index db68157a2..fbd496dfe 100644 --- a/Directory.Packages.props +++ b/Directory.Packages.props @@ -13,6 +13,9 @@ + + + diff --git a/src/Renci.SshNet/Abstractions/DiagnosticAbstraction.cs b/src/Renci.SshNet/Abstractions/DiagnosticAbstraction.cs deleted file mode 100644 index bc1248dc0..000000000 --- a/src/Renci.SshNet/Abstractions/DiagnosticAbstraction.cs +++ /dev/null @@ -1,69 +0,0 @@ -using System.ComponentModel; -using System.Diagnostics; - -namespace Renci.SshNet.Abstractions -{ - /// - /// Provides access to the internals of SSH.NET. - /// - [EditorBrowsable(EditorBrowsableState.Never)] - public static class DiagnosticAbstraction - { - /// - /// The instance used by SSH.NET. - /// - /// - /// - /// Currently, the library only traces events when compiled in Debug mode. - /// - /// - /// Configuration on .NET Core must be done programmatically, e.g. - /// - /// DiagnosticAbstraction.Source.Switch = new SourceSwitch("sourceSwitch", "Verbose"); - /// DiagnosticAbstraction.Source.Listeners.Remove("Default"); - /// DiagnosticAbstraction.Source.Listeners.Add(new ConsoleTraceListener()); - /// DiagnosticAbstraction.Source.Listeners.Add(new TextWriterTraceListener("trace.log")); - /// - /// - /// - /// On .NET Framework, it is possible to configure via App.config, e.g. - /// - /// - /// - /// - /// - /// - /// - /// - /// - /// - /// - /// - /// - /// - /// - /// ]]> - /// - /// - /// - public static readonly TraceSource Source = new TraceSource("SshNet.Logging"); - - /// - /// Logs a message to at the - /// level. - /// - /// The message to log. - /// The trace event type. - [Conditional("DEBUG")] - public static void Log(string text, TraceEventType type = TraceEventType.Verbose) - { - Source.TraceEvent(type, - System.Environment.CurrentManagedThreadId, - text); - } - } -} diff --git a/src/Renci.SshNet/BaseClient.cs b/src/Renci.SshNet/BaseClient.cs index 3757878b4..6a2cb7aeb 100644 --- a/src/Renci.SshNet/BaseClient.cs +++ b/src/Renci.SshNet/BaseClient.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 /// 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) /// The method was called after the client was disposed. 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.LogInformation("Disposing client."); Disconnect(); diff --git a/src/Renci.SshNet/Channels/Channel.cs b/src/Renci.SshNet/Channels/Channel.cs index 4c0909f26..34e46a1e0 100644 --- a/src/Renci.SshNet/Channels/Channel.cs +++ b/src/Renci.SshNet/Channels/Channel.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 object _messagingLock = new object(); 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); } } } diff --git a/src/Renci.SshNet/Channels/ChannelDirectTcpip.cs b/src/Renci.SshNet/Channels/ChannelDirectTcpip.cs index 6a07d59b0..a0887d4c7 100644 --- a/src/Renci.SshNet/Channels/ChannelDirectTcpip.cs +++ b/src/Renci.SshNet/Channels/ChannelDirectTcpip.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,6 +17,7 @@ namespace Renci.SshNet.Channels internal sealed class ChannelDirectTcpip : ClientChannel, IChannelDirectTcpip { private readonly object _socketLock = new object(); + private readonly ILogger _logger; private EventWaitHandle _channelOpen = new AutoResetEvent(initialState: false); private EventWaitHandle _channelData = new AutoResetEvent(initialState: false); @@ -31,6 +34,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(); } /// @@ -157,8 +161,7 @@ private void ShutdownSocket(SocketShutdown how) } catch (SocketException ex) { - // TODO: log as warning - DiagnosticAbstraction.Log("Failure shutting down socket: " + ex); + _logger.LogWarning(ex, "Failure shutting down socket"); } } } diff --git a/src/Renci.SshNet/Channels/ChannelForwardedTcpip.cs b/src/Renci.SshNet/Channels/ChannelForwardedTcpip.cs index 07271c834..100fb0e1d 100644 --- a/src/Renci.SshNet/Channels/ChannelForwardedTcpip.cs +++ b/src/Renci.SshNet/Channels/ChannelForwardedTcpip.cs @@ -2,6 +2,8 @@ using System.Net; using System.Net.Sockets; +using Microsoft.Extensions.Logging; + using Renci.SshNet.Abstractions; using Renci.SshNet.Common; using Renci.SshNet.Messages.Connection; @@ -14,6 +16,7 @@ namespace Renci.SshNet.Channels internal sealed class ChannelForwardedTcpip : ServerChannel, IChannelForwardedTcpip { private readonly object _socketShutdownAndCloseLock = new object(); + private readonly ILogger _logger; private Socket _socket; private IForwardedPort _forwardedPort; @@ -42,6 +45,7 @@ internal ChannelForwardedTcpip(ISession session, remoteWindowSize, remotePacketSize) { + _logger = SshNetLoggingConfiguration.LoggerFactory.CreateLogger(); } /// @@ -139,8 +143,7 @@ private void ShutdownSocket(SocketShutdown how) } catch (SocketException ex) { - // TODO: log as warning - DiagnosticAbstraction.Log("Failure shutting down socket: " + ex); + _logger.LogWarning(ex, "Failure shutting down socket"); } } } diff --git a/src/Renci.SshNet/Connection/ConnectorBase.cs b/src/Renci.SshNet/Connection/ConnectorBase.cs index c36fae6df..ebea9aa80 100644 --- a/src/Renci.SshNet/Connection/ConnectorBase.cs +++ b/src/Renci.SshNet/Connection/ConnectorBase.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) /// An error occurred trying to establish the connection. 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 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 diff --git a/src/Renci.SshNet/ForwardedPortDynamic.cs b/src/Renci.SshNet/ForwardedPortDynamic.cs index 7d0e5af96..d33dcc32d 100644 --- a/src/Renci.SshNet/ForwardedPortDynamic.cs +++ b/src/Renci.SshNet/ForwardedPortDynamic.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 /// public class ForwardedPortDynamic : ForwardedPort { + private readonly ILogger _logger; private ForwardedPortStatus _status; /// @@ -72,6 +75,7 @@ public ForwardedPortDynamic(string host, uint port) BoundHost = host; BoundPort = port; _status = ForwardedPortStatus.Stopped; + _logger = SshNetLoggingConfiguration.LoggerFactory.CreateLogger(); } /// @@ -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.LogWarning("Timeout waiting for pending channels in dynamic forwarded port to close."); } } diff --git a/src/Renci.SshNet/ForwardedPortLocal.cs b/src/Renci.SshNet/ForwardedPortLocal.cs index ec030be44..d5eb99e31 100644 --- a/src/Renci.SshNet/ForwardedPortLocal.cs +++ b/src/Renci.SshNet/ForwardedPortLocal.cs @@ -3,7 +3,8 @@ using System.Net.Sockets; using System.Threading; -using Renci.SshNet.Abstractions; +using Microsoft.Extensions.Logging; + using Renci.SshNet.Common; namespace Renci.SshNet @@ -13,6 +14,7 @@ namespace Renci.SshNet /// public partial class ForwardedPortLocal : ForwardedPort { + private readonly ILogger _logger; private ForwardedPortStatus _status; private bool _isDisposed; private Socket _listener; @@ -101,6 +103,7 @@ public ForwardedPortLocal(string boundHost, uint boundPort, string host, uint po Host = host; Port = port; _status = ForwardedPortStatus.Stopped; + _logger = SshNetLoggingConfiguration.LoggerFactory.CreateLogger(); } /// @@ -387,8 +390,7 @@ private void InternalStop(TimeSpan timeout) if (!_pendingChannelCountdown.Wait(timeout)) { - // TODO: log as warning - DiagnosticAbstraction.Log("Timeout waiting for pending channels in local forwarded port to close."); + _logger.LogWarning("Timeout waiting for pending channels in local forwarded port to close."); } } diff --git a/src/Renci.SshNet/ForwardedPortRemote.cs b/src/Renci.SshNet/ForwardedPortRemote.cs index 07b234541..7b2ca34d9 100644 --- a/src/Renci.SshNet/ForwardedPortRemote.cs +++ b/src/Renci.SshNet/ForwardedPortRemote.cs @@ -3,6 +3,8 @@ using System.Net; using System.Threading; +using Microsoft.Extensions.Logging; + using Renci.SshNet.Abstractions; using Renci.SshNet.Common; using Renci.SshNet.Messages.Connection; @@ -14,6 +16,7 @@ namespace Renci.SshNet /// public class ForwardedPortRemote : ForwardedPort { + private readonly ILogger _logger; private ForwardedPortStatus _status; private bool _requestStatus; private EventWaitHandle _globalRequestResponse = new AutoResetEvent(initialState: false); @@ -97,6 +100,7 @@ public ForwardedPortRemote(IPAddress boundHostAddress, uint boundPort, IPAddress HostAddress = hostAddress; Port = port; _status = ForwardedPortStatus.Stopped; + _logger = SshNetLoggingConfiguration.LoggerFactory.CreateLogger(); } /// @@ -208,8 +212,7 @@ protected override void StopPort(TimeSpan timeout) if (!_pendingChannelCountdown.Wait(timeout)) { - // TODO: log as warning - DiagnosticAbstraction.Log("Timeout waiting for pending channels in remote forwarded port to close."); + _logger.LogWarning("Timeout waiting for pending channels in remote forwarded port to close."); } _status = ForwardedPortStatus.Stopped; diff --git a/src/Renci.SshNet/Renci.SshNet.csproj b/src/Renci.SshNet/Renci.SshNet.csproj index bf822da85..a1d715440 100644 --- a/src/Renci.SshNet/Renci.SshNet.csproj +++ b/src/Renci.SshNet/Renci.SshNet.csproj @@ -36,6 +36,7 @@ + runtime; build; native; contentfiles; analyzers; buildtransitive diff --git a/src/Renci.SshNet/Security/KeyExchange.cs b/src/Renci.SshNet/Security/KeyExchange.cs index f5c3d5c7f..e55f386f3 100644 --- a/src/Renci.SshNet/Security/KeyExchange.cs +++ b/src/Renci.SshNet/Security/KeyExchange.cs @@ -3,7 +3,8 @@ using System.Linq; using System.Security.Cryptography; -using Renci.SshNet.Abstractions; +using Microsoft.Extensions.Logging; + using Renci.SshNet.Common; using Renci.SshNet.Compression; using Renci.SshNet.Messages; @@ -17,6 +18,7 @@ namespace Renci.SshNet.Security /// public abstract class KeyExchange : Algorithm, IKeyExchange { + private readonly ILogger _logger; private CipherInfo _clientCipherInfo; private CipherInfo _serverCipherInfo; private HashInfo _clientHashInfo; @@ -61,6 +63,11 @@ public byte[] ExchangeHash /// public event EventHandler HostKeyReceived; + private protected KeyExchange() + { + _logger = SshNetLoggingConfiguration.LoggerFactory.CreateLogger(GetType()); + } + /// public virtual void Start(Session session, KeyExchangeInitMessage message, bool sendClientInitMessage) { @@ -190,9 +197,9 @@ public Cipher CreateServerCipher(out bool isAead) serverKey = GenerateSessionKey(SharedKey, ExchangeHash, serverKey, _serverCipherInfo.KeySize / 8); - DiagnosticAbstraction.Log(string.Format("[{0}] Creating {1} server cipher.", + _logger.LogInformation("[{SessionId}] Creating {ServerEncryption} server cipher.", Session.ToHex(Session.SessionId), - Session.ConnectionInfo.CurrentServerEncryption)); + Session.ConnectionInfo.CurrentServerEncryption); // Create server cipher return _serverCipherInfo.Cipher(serverKey, serverVector); @@ -218,9 +225,9 @@ public Cipher CreateClientCipher(out bool isAead) clientKey = GenerateSessionKey(SharedKey, ExchangeHash, clientKey, _clientCipherInfo.KeySize / 8); - DiagnosticAbstraction.Log(string.Format("[{0}] Creating {1} client cipher.", + _logger.LogInformation("[{SessionId}] Creating {ClientEncryption} client cipher.", Session.ToHex(Session.SessionId), - Session.ConnectionInfo.CurrentClientEncryption)); + Session.ConnectionInfo.CurrentClientEncryption); // Create client cipher return _clientCipherInfo.Cipher(clientKey, clientVector); @@ -251,9 +258,9 @@ public HashAlgorithm CreateServerHash(out bool isEncryptThenMAC) Hash(GenerateSessionKey(SharedKey, ExchangeHash, 'F', sessionId)), _serverHashInfo.KeySize / 8); - DiagnosticAbstraction.Log(string.Format("[{0}] Creating {1} server hmac algorithm.", + _logger.LogInformation("[{SessionId}] Creating {ServerHmacAlgorithm} server hmac algorithm.", Session.ToHex(Session.SessionId), - Session.ConnectionInfo.CurrentServerHmacAlgorithm)); + Session.ConnectionInfo.CurrentServerHmacAlgorithm); return _serverHashInfo.HashAlgorithm(serverKey); } @@ -283,9 +290,9 @@ public HashAlgorithm CreateClientHash(out bool isEncryptThenMAC) Hash(GenerateSessionKey(SharedKey, ExchangeHash, 'E', sessionId)), _clientHashInfo.KeySize / 8); - DiagnosticAbstraction.Log(string.Format("[{0}] Creating {1} client hmac algorithm.", + _logger.LogInformation("[{SessionId}] Creating {ClientHmacAlgorithm} client hmac algorithm.", Session.ToHex(Session.SessionId), - Session.ConnectionInfo.CurrentClientHmacAlgorithm)); + Session.ConnectionInfo.CurrentClientHmacAlgorithm); return _clientHashInfo.HashAlgorithm(clientKey); } @@ -303,9 +310,9 @@ public Compressor CreateCompressor() return null; } - DiagnosticAbstraction.Log(string.Format("[{0}] Creating {1} client compressor.", + _logger.LogInformation("[{SessionId}] Creating {CompressionAlgorithm} client compressor.", Session.ToHex(Session.SessionId), - Session.ConnectionInfo.CurrentClientCompressionAlgorithm)); + Session.ConnectionInfo.CurrentClientCompressionAlgorithm); var compressor = _compressorFactory(); @@ -327,9 +334,9 @@ public Compressor CreateDecompressor() return null; } - DiagnosticAbstraction.Log(string.Format("[{0}] Creating {1} server decompressor.", + _logger.LogInformation("[{SessionId}] Creating {ServerCompressionAlgorithm} server decompressor.", Session.ToHex(Session.SessionId), - Session.ConnectionInfo.CurrentServerCompressionAlgorithm)); + Session.ConnectionInfo.CurrentServerCompressionAlgorithm); var decompressor = _decompressorFactory(); diff --git a/src/Renci.SshNet/ServiceFactory.cs b/src/Renci.SshNet/ServiceFactory.cs index d238b6eac..0b8e27f67 100644 --- a/src/Renci.SshNet/ServiceFactory.cs +++ b/src/Renci.SshNet/ServiceFactory.cs @@ -4,7 +4,8 @@ using System.Net.Sockets; using System.Text; -using Renci.SshNet.Abstractions; +using Microsoft.Extensions.Logging; + using Renci.SshNet.Common; using Renci.SshNet.Connection; using Renci.SshNet.Messages.Transport; @@ -25,6 +26,13 @@ internal sealed partial class ServiceFactory : IServiceFactory /// private const int PartialSuccessLimit = 5; + private readonly ILogger _logger; + + internal ServiceFactory() + { + _logger = SshNetLoggingConfiguration.LoggerFactory.CreateLogger(); + } + /// /// Creates an . /// @@ -152,7 +160,7 @@ public ISftpFileReader CreateSftpFileReader(string fileName, ISftpSession sftpSe fileSize = null; maxPendingReads = defaultMaxPendingReads; - DiagnosticAbstraction.Log(string.Format("Failed to obtain size of file. Allowing maximum {0} pending reads: {1}", maxPendingReads, ex)); + _logger.LogInformation(ex, "Failed to obtain size of file. Allowing maximum {MaxPendingReads} pending reads", maxPendingReads); } return sftpSession.CreateFileReader(handle, sftpSession, chunkSize, maxPendingReads, fileSize); diff --git a/src/Renci.SshNet/Session.cs b/src/Renci.SshNet/Session.cs index d914858bb..1c3889174 100644 --- a/src/Renci.SshNet/Session.cs +++ b/src/Renci.SshNet/Session.cs @@ -9,6 +9,8 @@ using System.Threading; using System.Threading.Tasks; +using Microsoft.Extensions.Logging; + using Renci.SshNet.Abstractions; using Renci.SshNet.Channels; using Renci.SshNet.Common; @@ -75,6 +77,7 @@ public class Session : ISession /// private readonly IServiceFactory _serviceFactory; private readonly ISocketFactory _socketFactory; + private readonly ILogger _logger; /// /// Holds an object that is used to ensure only a single thread can read from @@ -535,6 +538,7 @@ internal Session(ConnectionInfo connectionInfo, IServiceFactory serviceFactory, ConnectionInfo = connectionInfo; _serviceFactory = serviceFactory; _socketFactory = socketFactory; + _logger = SshNetLoggingConfiguration.LoggerFactory.CreateLogger(); _messageListenerCompleted = new ManualResetEvent(initialState: true); } @@ -577,7 +581,7 @@ public void Connect() ServerVersion = ConnectionInfo.ServerVersion = serverIdentification.ToString(); ConnectionInfo.ClientVersion = ClientVersion; - DiagnosticAbstraction.Log(string.Format("Server version '{0}'.", serverIdentification)); + _logger.LogInformation("Server version '{ServerIdentification}'.", serverIdentification); if (!(serverIdentification.ProtocolVersion.Equals("2.0") || serverIdentification.ProtocolVersion.Equals("1.99"))) { @@ -703,7 +707,7 @@ public async Task ConnectAsync(CancellationToken cancellationToken) ServerVersion = ConnectionInfo.ServerVersion = serverIdentification.ToString(); ConnectionInfo.ClientVersion = ClientVersion; - DiagnosticAbstraction.Log(string.Format("Server version '{0}'.", serverIdentification)); + _logger.LogInformation("Server version '{ServerIdentification}'.", serverIdentification); if (!(serverIdentification.ProtocolVersion.Equals("2.0") || serverIdentification.ProtocolVersion.Equals("1.99"))) { @@ -796,7 +800,7 @@ public async Task ConnectAsync(CancellationToken cancellationToken) /// public void Disconnect() { - DiagnosticAbstraction.Log(string.Format("[{0}] Disconnecting session.", ToHex(SessionId))); + _logger.LogInformation("[{SessionId}] Disconnecting session.", ToHex(SessionId)); // send SSH_MSG_DISCONNECT message, clear socket read buffer and dispose it Disconnect(DisconnectReason.ByApplication, "Connection terminated by the client."); @@ -1026,7 +1030,7 @@ internal void SendMessage(Message message) WaitOnHandle(_keyExchangeCompletedWaitHandle.WaitHandle); } - DiagnosticAbstraction.Log(string.Format("[{0}] Sending message '{1}' to server: '{2}'.", ToHex(SessionId), message.GetType().Name, message)); + _logger.LogInformation("[{SessionId}] Sending message '{MessageType}' to server: '{Message}'.", ToHex(SessionId), message.GetType().Name, message); var paddingMultiplier = _clientCipher is null ? (byte)8 : Math.Max((byte)8, _clientCipher.MinimumSize); var packetData = message.GetPacket(paddingMultiplier, _clientCompression, _clientEtm || _clientAead); @@ -1165,12 +1169,12 @@ private bool TrySendMessage(Message message) } catch (SshException ex) { - DiagnosticAbstraction.Log(string.Format("Failure sending message '{0}' to server: '{1}' => {2}", message.GetType().Name, message, ex)); + _logger.LogInformation(ex, "Failure sending message '{MessageType}' to server: '{Message}'", message.GetType().Name, message); return false; } catch (SocketException ex) { - DiagnosticAbstraction.Log(string.Format("Failure sending message '{0}' to server: '{1}' => {2}", message.GetType().Name, message, ex)); + _logger.LogInformation(ex, "Failure sending message '{MessageType}' to server: '{Message}'", message.GetType().Name, message); return false; } } @@ -1380,7 +1384,7 @@ private void TrySendDisconnect(DisconnectReason reasonCode, string message) /// message. internal void OnDisconnectReceived(DisconnectMessage message) { - DiagnosticAbstraction.Log(string.Format("[{0}] Disconnect received: {1} {2}.", ToHex(SessionId), message.ReasonCode, message.Description)); + _logger.LogInformation("[{SessionId}] Disconnect received: {ReasonCode} {MessageDescription}.", ToHex(SessionId), message.ReasonCode, message.Description); // transition to disconnecting state to avoid throwing exceptions while cleaning up, and to // ensure any exceptions that are raised do not overwrite the SshConnectionException that we @@ -1475,7 +1479,7 @@ internal void OnKeyExchangeInitReceived(KeyExchangeInitMessage message) { _isStrictKex = true; - DiagnosticAbstraction.Log(string.Format("[{0}] Enabling strict key exchange extension.", ToHex(SessionId))); + _logger.LogInformation("[{SessionId}] Enabling strict key exchange extension.", ToHex(SessionId)); if (_inboundPacketSequence != 1) { @@ -1491,7 +1495,7 @@ internal void OnKeyExchangeInitReceived(KeyExchangeInitMessage message) ConnectionInfo.CurrentKeyExchangeAlgorithm = _keyExchange.Name; - DiagnosticAbstraction.Log(string.Format("[{0}] Performing {1} key exchange.", ToHex(SessionId), ConnectionInfo.CurrentKeyExchangeAlgorithm)); + _logger.LogInformation("[{SessionId}] Performing {KeyExchangeAlgorithm} key exchange.", ToHex(SessionId), ConnectionInfo.CurrentKeyExchangeAlgorithm); _keyExchange.HostKeyReceived += KeyExchange_HostKeyReceived; @@ -1807,7 +1811,7 @@ private Message LoadMessage(byte[] data, int offset, int count) var message = _sshMessageFactory.Create(messageType); message.Load(data, offset + 1, count - 1); - DiagnosticAbstraction.Log(string.Format("[{0}] Received message '{1}' from server: '{2}'.", ToHex(SessionId), message.GetType().Name, message)); + _logger.LogInformation("[{SessionId}] Received message '{MessageType}' from server: '{Message}'.", ToHex(SessionId), message.GetType().Name, message); return message; } @@ -1951,7 +1955,7 @@ private void SocketDisconnectAndDispose() { try { - DiagnosticAbstraction.Log(string.Format("[{0}] Shutting down socket.", ToHex(SessionId))); + _logger.LogInformation("[{SessionId}] Shutting down socket.", ToHex(SessionId)); // Interrupt any pending reads; should be done outside of socket read lock as we // actually want shutdown the socket to make sure blocking reads are interrupted. @@ -1963,14 +1967,13 @@ private void SocketDisconnectAndDispose() } catch (SocketException ex) { - // TODO: log as warning - DiagnosticAbstraction.Log("Failure shutting down socket: " + ex); + _logger.LogWarning(ex, "Failure shutting down socket"); } } - DiagnosticAbstraction.Log(string.Format("[{0}] Disposing socket.", ToHex(SessionId))); + _logger.LogInformation("[{SessionId}] Disposing socket.", ToHex(SessionId)); _socket.Dispose(); - DiagnosticAbstraction.Log(string.Format("[{0}] Disposed socket.", ToHex(SessionId))); + _logger.LogInformation("[{SessionId}] Disposed socket.", ToHex(SessionId)); _socket = null; } } @@ -2054,7 +2057,7 @@ private void RaiseError(Exception exp) { var connectionException = exp as SshConnectionException; - DiagnosticAbstraction.Log(string.Format("[{0}] Raised exception: {1}", ToHex(SessionId), exp)); + _logger.LogInformation(exp, "[{SessionId}] Raised exception", ToHex(SessionId)); if (_isDisconnecting) { @@ -2081,7 +2084,7 @@ private void RaiseError(Exception exp) if (connectionException != null) { - DiagnosticAbstraction.Log(string.Format("[{0}] Disconnecting after exception: {1}", ToHex(SessionId), exp)); + _logger.LogInformation(exp, "[{SessionId}] Disconnecting after exception", ToHex(SessionId)); Disconnect(connectionException.DisconnectReason, exp.ToString()); } } @@ -2154,7 +2157,7 @@ protected virtual void Dispose(bool disposing) if (disposing) { - DiagnosticAbstraction.Log(string.Format("[{0}] Disposing session.", ToHex(SessionId))); + _logger.LogInformation("[{SessionId}] Disposing session.", ToHex(SessionId)); Disconnect(); diff --git a/src/Renci.SshNet/Sftp/SftpFileReader.cs b/src/Renci.SshNet/Sftp/SftpFileReader.cs index 40e13edd4..3c86fc31b 100644 --- a/src/Renci.SshNet/Sftp/SftpFileReader.cs +++ b/src/Renci.SshNet/Sftp/SftpFileReader.cs @@ -4,6 +4,8 @@ using System.Runtime.ExceptionServices; using System.Threading; +using Microsoft.Extensions.Logging; + using Renci.SshNet.Abstractions; using Renci.SshNet.Common; @@ -22,6 +24,7 @@ internal sealed class SftpFileReader : ISftpFileReader private readonly ManualResetEvent _readAheadCompleted; private readonly Dictionary _queue; private readonly WaitHandle[] _waitHandles; + private readonly ILogger _logger; /// /// Holds the size of the file, when available. @@ -68,6 +71,7 @@ public SftpFileReader(byte[] handle, ISftpSession sftpSession, uint chunkSize, i _readAheadCompleted = new ManualResetEvent(initialState: false); _disposingWaitHandle = new ManualResetEvent(initialState: false); _waitHandles = _sftpSession.CreateWaitHandleArray(_disposingWaitHandle, _semaphore.AvailableWaitHandle); + _logger = SshNetLoggingConfiguration.LoggerFactory.CreateLogger(); StartReadAhead(); } @@ -266,7 +270,7 @@ private void Dispose(bool disposing) } catch (Exception ex) { - DiagnosticAbstraction.Log("Failure closing handle: " + ex); + _logger.LogInformation(ex, "Failure closing handle"); } } } diff --git a/src/Renci.SshNet/SshNetLoggingConfiguration.cs b/src/Renci.SshNet/SshNetLoggingConfiguration.cs new file mode 100644 index 000000000..4add75c9f --- /dev/null +++ b/src/Renci.SshNet/SshNetLoggingConfiguration.cs @@ -0,0 +1,26 @@ +#nullable enable +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Abstractions; + +using Renci.SshNet.Common; + +namespace Renci.SshNet +{ + /// + /// Allows configuring the logging for internal logs of SSH.NET. + /// + public static class SshNetLoggingConfiguration + { + internal static ILoggerFactory LoggerFactory { get; private set; } = NullLoggerFactory.Instance; + + /// + /// Initializes the logging for SSH.NET. + /// + /// The logger factory. + public static void InitializeLogging(ILoggerFactory loggerFactory) + { + ThrowHelper.ThrowIfNull(loggerFactory); + LoggerFactory = loggerFactory; + } + } +} diff --git a/src/Renci.SshNet/SubsystemSession.cs b/src/Renci.SshNet/SubsystemSession.cs index b5912a805..5221550d3 100644 --- a/src/Renci.SshNet/SubsystemSession.cs +++ b/src/Renci.SshNet/SubsystemSession.cs @@ -3,7 +3,8 @@ using System.Runtime.ExceptionServices; using System.Threading; -using Renci.SshNet.Abstractions; +using Microsoft.Extensions.Logging; + using Renci.SshNet.Channels; using Renci.SshNet.Common; @@ -21,6 +22,7 @@ internal abstract class SubsystemSession : ISubsystemSession private const int SystemWaitHandleCount = 3; private readonly string _subsystemName; + private readonly ILogger _logger; private ISession _session; private IChannelSession _channel; private Exception _exception; @@ -88,6 +90,7 @@ protected SubsystemSession(ISession session, string subsystemName, int operation _session = session; _subsystemName = subsystemName; + _logger = SshNetLoggingConfiguration.LoggerFactory.CreateLogger(GetType()); OperationTimeout = operationTimeout; } @@ -184,7 +187,7 @@ protected void RaiseError(Exception error) { _exception = error; - DiagnosticAbstraction.Log("Raised exception: " + error); + _logger.LogInformation(error, "Raised exception"); _ = _errorOccuredWaitHandle?.Set(); diff --git a/test/Renci.SshNet.IntegrationTests/Renci.SshNet.IntegrationTests.csproj b/test/Renci.SshNet.IntegrationTests/Renci.SshNet.IntegrationTests.csproj index cd1bf5314..266d599d0 100644 --- a/test/Renci.SshNet.IntegrationTests/Renci.SshNet.IntegrationTests.csproj +++ b/test/Renci.SshNet.IntegrationTests/Renci.SshNet.IntegrationTests.csproj @@ -13,6 +13,8 @@ + + diff --git a/test/Renci.SshNet.IntegrationTests/TestsFixtures/IntegrationTestBase.cs b/test/Renci.SshNet.IntegrationTests/TestsFixtures/IntegrationTestBase.cs index d08578e4e..3d2ed451b 100644 --- a/test/Renci.SshNet.IntegrationTests/TestsFixtures/IntegrationTestBase.cs +++ b/test/Renci.SshNet.IntegrationTests/TestsFixtures/IntegrationTestBase.cs @@ -1,6 +1,4 @@ -using System.Diagnostics; - -using Renci.SshNet.Abstractions; +using Microsoft.Extensions.Logging; namespace Renci.SshNet.IntegrationTests.TestsFixtures { @@ -61,6 +59,17 @@ protected IntegrationTestBase() ShowInfrastructureInformation(); } + static IntegrationTestBase() + { + ILoggerFactory loggerFactory = LoggerFactory.Create(builder => + { + builder.SetMinimumLevel(LogLevel.Debug); + builder.AddConsole(); + }); + + SshNetLoggingConfiguration.InitializeLogging(loggerFactory); + } + private void ShowInfrastructureInformation() { Console.WriteLine($"SSH Server host name: {_infrastructureFixture.SshServerHostName}"); @@ -85,18 +94,5 @@ protected void CreateTestFile(string fileName, int size) } } } - - protected void EnableTracing() - { - DiagnosticAbstraction.Source.Switch = new SourceSwitch("sourceSwitch", nameof(SourceLevels.Verbose)); - DiagnosticAbstraction.Source.Listeners.Remove("Default"); - DiagnosticAbstraction.Source.Listeners.Add(new ConsoleTraceListener() { Name = "TestConsoleLogger" }); - } - - protected void DisableTracing() - { - DiagnosticAbstraction.Source.Switch = new SourceSwitch("sourceSwitch", nameof(SourceLevels.Off)); - DiagnosticAbstraction.Source.Listeners.Remove("TestConsoleLogger"); - } } } From 673e0b2bdecae86c4a422f37e7ccf86ca576b28c Mon Sep 17 00:00:00 2001 From: Marius Thesing Date: Sun, 29 Sep 2024 17:36:18 +0200 Subject: [PATCH 2/8] add documentation --- CONTRIBUTING.md | 4 ++-- README.md | 1 + docfx/logging.md | 10 ++++++++++ 3 files changed, 13 insertions(+), 2 deletions(-) create mode 100644 docfx/logging.md diff --git a/CONTRIBUTING.md b/CONTRIBUTING.md index 31578af80..bbc309583 100644 --- a/CONTRIBUTING.md +++ b/CONTRIBUTING.md @@ -34,9 +34,9 @@ The repository makes use of continuous integration (CI) on [AppVeyor](https://ci ## 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 diff --git a/README.md b/README.md index 8d2b99d25..735b9d468 100644 --- a/README.md +++ b/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 diff --git a/docfx/logging.md b/docfx/logging.md new file mode 100644 index 000000000..ea81f577f --- /dev/null +++ b/docfx/logging.md @@ -0,0 +1,10 @@ +Logging +================= + +SSH.NET uses the `Microsoft.Extensions.Logging` API to log diagnostic messages. In order to access the log messages of SSH.NET in your own application for diagnosis, simply register your own `ILoggerFactory` before using the SSH.NET APIs with the following code: + +```cs +SshNetLoggingConfiguration.InitializeLogging(loggerFactory); +``` + +All messages by SSH.NET are logged under the `Renci.SshNet` category. From 35ac741bb0035029378cd0cd176cf90eb8718840 Mon Sep 17 00:00:00 2001 From: Marius Thesing Date: Sat, 12 Oct 2024 14:05:09 +0200 Subject: [PATCH 3/8] reduce allocations by SessionId hex conversion generate the hex string once instead of every log call and optimize ToHex(). --- src/Renci.SshNet/Security/KeyExchange.cs | 12 ++--- src/Renci.SshNet/Session.cs | 69 ++++++++++++++---------- 2 files changed, 47 insertions(+), 34 deletions(-) diff --git a/src/Renci.SshNet/Security/KeyExchange.cs b/src/Renci.SshNet/Security/KeyExchange.cs index e55f386f3..68c184bec 100644 --- a/src/Renci.SshNet/Security/KeyExchange.cs +++ b/src/Renci.SshNet/Security/KeyExchange.cs @@ -198,7 +198,7 @@ public Cipher CreateServerCipher(out bool isAead) serverKey = GenerateSessionKey(SharedKey, ExchangeHash, serverKey, _serverCipherInfo.KeySize / 8); _logger.LogInformation("[{SessionId}] Creating {ServerEncryption} server cipher.", - Session.ToHex(Session.SessionId), + Session.SessionIdHex, Session.ConnectionInfo.CurrentServerEncryption); // Create server cipher @@ -226,7 +226,7 @@ public Cipher CreateClientCipher(out bool isAead) clientKey = GenerateSessionKey(SharedKey, ExchangeHash, clientKey, _clientCipherInfo.KeySize / 8); _logger.LogInformation("[{SessionId}] Creating {ClientEncryption} client cipher.", - Session.ToHex(Session.SessionId), + Session.SessionIdHex, Session.ConnectionInfo.CurrentClientEncryption); // Create client cipher @@ -259,7 +259,7 @@ public HashAlgorithm CreateServerHash(out bool isEncryptThenMAC) _serverHashInfo.KeySize / 8); _logger.LogInformation("[{SessionId}] Creating {ServerHmacAlgorithm} server hmac algorithm.", - Session.ToHex(Session.SessionId), + Session.SessionIdHex, Session.ConnectionInfo.CurrentServerHmacAlgorithm); return _serverHashInfo.HashAlgorithm(serverKey); @@ -291,7 +291,7 @@ public HashAlgorithm CreateClientHash(out bool isEncryptThenMAC) _clientHashInfo.KeySize / 8); _logger.LogInformation("[{SessionId}] Creating {ClientHmacAlgorithm} client hmac algorithm.", - Session.ToHex(Session.SessionId), + Session.SessionIdHex, Session.ConnectionInfo.CurrentClientHmacAlgorithm); return _clientHashInfo.HashAlgorithm(clientKey); @@ -311,7 +311,7 @@ public Compressor CreateCompressor() } _logger.LogInformation("[{SessionId}] Creating {CompressionAlgorithm} client compressor.", - Session.ToHex(Session.SessionId), + Session.SessionIdHex, Session.ConnectionInfo.CurrentClientCompressionAlgorithm); var compressor = _compressorFactory(); @@ -335,7 +335,7 @@ public Compressor CreateDecompressor() } _logger.LogInformation("[{SessionId}] Creating {ServerCompressionAlgorithm} server decompressor.", - Session.ToHex(Session.SessionId), + Session.SessionIdHex, Session.ConnectionInfo.CurrentServerCompressionAlgorithm); var decompressor = _decompressorFactory(); diff --git a/src/Renci.SshNet/Session.cs b/src/Renci.SshNet/Session.cs index 1c3889174..cd2ae7bd9 100644 --- a/src/Renci.SshNet/Session.cs +++ b/src/Renci.SshNet/Session.cs @@ -5,7 +5,9 @@ using System.Linq; using System.Net.Sockets; using System.Security.Cryptography; +#if !NET using System.Text; +#endif using System.Threading; using System.Threading.Tasks; @@ -291,13 +293,28 @@ public bool IsConnected } } + private byte[] _sessionId; + /// /// Gets the session id. /// /// /// The session id, or if the client has not been authenticated. /// - public byte[] SessionId { get; private set; } + public byte[] SessionId + { + get + { + return _sessionId; + } + private set + { + _sessionId = value; + SessionIdHex = ToHex(value); + } + } + + internal string SessionIdHex { get; private set; } /// /// Gets the client init message. @@ -800,7 +817,7 @@ public async Task ConnectAsync(CancellationToken cancellationToken) /// public void Disconnect() { - _logger.LogInformation("[{SessionId}] Disconnecting session.", ToHex(SessionId)); + _logger.LogInformation("[{SessionId}] Disconnecting session.", SessionIdHex); // send SSH_MSG_DISCONNECT message, clear socket read buffer and dispose it Disconnect(DisconnectReason.ByApplication, "Connection terminated by the client."); @@ -1030,7 +1047,7 @@ internal void SendMessage(Message message) WaitOnHandle(_keyExchangeCompletedWaitHandle.WaitHandle); } - _logger.LogInformation("[{SessionId}] Sending message '{MessageType}' to server: '{Message}'.", ToHex(SessionId), message.GetType().Name, message); + _logger.LogInformation("[{SessionId}] Sending message '{MessageType}' to server: '{Message}'.", SessionIdHex, message.GetType().Name, message); var paddingMultiplier = _clientCipher is null ? (byte)8 : Math.Max((byte)8, _clientCipher.MinimumSize); var packetData = message.GetPacket(paddingMultiplier, _clientCompression, _clientEtm || _clientAead); @@ -1384,7 +1401,7 @@ private void TrySendDisconnect(DisconnectReason reasonCode, string message) /// message. internal void OnDisconnectReceived(DisconnectMessage message) { - _logger.LogInformation("[{SessionId}] Disconnect received: {ReasonCode} {MessageDescription}.", ToHex(SessionId), message.ReasonCode, message.Description); + _logger.LogInformation("[{SessionId}] Disconnect received: {ReasonCode} {MessageDescription}.", SessionIdHex, message.ReasonCode, message.Description); // transition to disconnecting state to avoid throwing exceptions while cleaning up, and to // ensure any exceptions that are raised do not overwrite the SshConnectionException that we @@ -1479,7 +1496,7 @@ internal void OnKeyExchangeInitReceived(KeyExchangeInitMessage message) { _isStrictKex = true; - _logger.LogInformation("[{SessionId}] Enabling strict key exchange extension.", ToHex(SessionId)); + _logger.LogInformation("[{SessionId}] Enabling strict key exchange extension.", SessionIdHex); if (_inboundPacketSequence != 1) { @@ -1495,7 +1512,7 @@ internal void OnKeyExchangeInitReceived(KeyExchangeInitMessage message) ConnectionInfo.CurrentKeyExchangeAlgorithm = _keyExchange.Name; - _logger.LogInformation("[{SessionId}] Performing {KeyExchangeAlgorithm} key exchange.", ToHex(SessionId), ConnectionInfo.CurrentKeyExchangeAlgorithm); + _logger.LogInformation("[{SessionId}] Performing {KeyExchangeAlgorithm} key exchange.", SessionIdHex, ConnectionInfo.CurrentKeyExchangeAlgorithm); _keyExchange.HostKeyReceived += KeyExchange_HostKeyReceived; @@ -1811,34 +1828,30 @@ private Message LoadMessage(byte[] data, int offset, int count) var message = _sshMessageFactory.Create(messageType); message.Load(data, offset + 1, count - 1); - _logger.LogInformation("[{SessionId}] Received message '{MessageType}' from server: '{Message}'.", ToHex(SessionId), message.GetType().Name, message); + _logger.LogInformation("[{SessionId}] Received message '{MessageType}' from server: '{Message}'.", SessionIdHex, message.GetType().Name, message); return message; } - private static string ToHex(byte[] bytes, int offset) + private static string ToHex(byte[] bytes) { - var byteCount = bytes.Length - offset; - - var builder = new StringBuilder(bytes.Length * 2); - - for (var i = offset; i < byteCount; i++) + if (bytes is null) { - var b = bytes[i]; - _ = builder.Append(b.ToString("X2")); + return null; } - return builder.ToString(); - } +#if NET + return Convert.ToHexString(bytes); +#else + var builder = new StringBuilder(bytes.Length * 2); - internal static string ToHex(byte[] bytes) - { - if (bytes is null) + foreach (var b in bytes) { - return null; + builder.Append(b.ToString("X2")); } - return ToHex(bytes, 0); + return builder.ToString(); +#endif } /// @@ -1955,7 +1968,7 @@ private void SocketDisconnectAndDispose() { try { - _logger.LogInformation("[{SessionId}] Shutting down socket.", ToHex(SessionId)); + _logger.LogInformation("[{SessionId}] Shutting down socket.", SessionIdHex); // Interrupt any pending reads; should be done outside of socket read lock as we // actually want shutdown the socket to make sure blocking reads are interrupted. @@ -1971,9 +1984,9 @@ private void SocketDisconnectAndDispose() } } - _logger.LogInformation("[{SessionId}] Disposing socket.", ToHex(SessionId)); + _logger.LogInformation("[{SessionId}] Disposing socket.", SessionIdHex); _socket.Dispose(); - _logger.LogInformation("[{SessionId}] Disposed socket.", ToHex(SessionId)); + _logger.LogInformation("[{SessionId}] Disposed socket.", SessionIdHex); _socket = null; } } @@ -2057,7 +2070,7 @@ private void RaiseError(Exception exp) { var connectionException = exp as SshConnectionException; - _logger.LogInformation(exp, "[{SessionId}] Raised exception", ToHex(SessionId)); + _logger.LogInformation(exp, "[{SessionId}] Raised exception", SessionIdHex); if (_isDisconnecting) { @@ -2084,7 +2097,7 @@ private void RaiseError(Exception exp) if (connectionException != null) { - _logger.LogInformation(exp, "[{SessionId}] Disconnecting after exception", ToHex(SessionId)); + _logger.LogInformation(exp, "[{SessionId}] Disconnecting after exception", SessionIdHex); Disconnect(connectionException.DisconnectReason, exp.ToString()); } } @@ -2157,7 +2170,7 @@ protected virtual void Dispose(bool disposing) if (disposing) { - _logger.LogInformation("[{SessionId}] Disposing session.", ToHex(SessionId)); + _logger.LogInformation("[{SessionId}] Disposing session.", SessionIdHex); Disconnect(); From 0696cb29d14501ff9d526381ced2940cc2fa7820 Mon Sep 17 00:00:00 2001 From: mus65 Date: Sat, 23 Nov 2024 19:24:21 +0100 Subject: [PATCH 4/8] Update docfx/logging.md Co-authored-by: Rob Hague --- docfx/logging.md | 11 ++++++++--- 1 file changed, 8 insertions(+), 3 deletions(-) diff --git a/docfx/logging.md b/docfx/logging.md index ea81f577f..4f59b96d6 100644 --- a/docfx/logging.md +++ b/docfx/logging.md @@ -1,10 +1,15 @@ Logging ================= -SSH.NET uses the `Microsoft.Extensions.Logging` API to log diagnostic messages. In order to access the log messages of SSH.NET in your own application for diagnosis, simply register your own `ILoggerFactory` before using the SSH.NET APIs with the following code: +SSH.NET uses the `Microsoft.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 -SshNetLoggingConfiguration.InitializeLogging(loggerFactory); -``` +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. From 3e46405015d98e818697c81494f5d979c49519d7 Mon Sep 17 00:00:00 2001 From: Marius Thesing Date: Sun, 1 Dec 2024 11:19:53 +0100 Subject: [PATCH 5/8] reduce log levels --- src/Renci.SshNet/BaseClient.cs | 2 +- .../Channels/ChannelDirectTcpip.cs | 2 +- .../Channels/ChannelForwardedTcpip.cs | 2 +- src/Renci.SshNet/ForwardedPortDynamic.cs | 2 +- src/Renci.SshNet/ForwardedPortLocal.cs | 2 +- src/Renci.SshNet/ForwardedPortRemote.cs | 2 +- src/Renci.SshNet/Security/KeyExchange.cs | 12 +++++----- src/Renci.SshNet/Session.cs | 24 ++++++++++++------- .../TestsFixtures/IntegrationTestBase.cs | 2 +- 9 files changed, 28 insertions(+), 22 deletions(-) diff --git a/src/Renci.SshNet/BaseClient.cs b/src/Renci.SshNet/BaseClient.cs index 6a2cb7aeb..876710db9 100644 --- a/src/Renci.SshNet/BaseClient.cs +++ b/src/Renci.SshNet/BaseClient.cs @@ -445,7 +445,7 @@ protected virtual void Dispose(bool disposing) if (disposing) { - _logger.LogInformation("Disposing client."); + _logger.LogDebug("Disposing client."); Disconnect(); diff --git a/src/Renci.SshNet/Channels/ChannelDirectTcpip.cs b/src/Renci.SshNet/Channels/ChannelDirectTcpip.cs index de41c3276..71108e309 100644 --- a/src/Renci.SshNet/Channels/ChannelDirectTcpip.cs +++ b/src/Renci.SshNet/Channels/ChannelDirectTcpip.cs @@ -160,7 +160,7 @@ private void ShutdownSocket(SocketShutdown how) } catch (SocketException ex) { - _logger.LogWarning(ex, "Failure shutting down socket"); + _logger.LogInformation(ex, "Failure shutting down socket"); } } } diff --git a/src/Renci.SshNet/Channels/ChannelForwardedTcpip.cs b/src/Renci.SshNet/Channels/ChannelForwardedTcpip.cs index 7f459c74b..29808e2b4 100644 --- a/src/Renci.SshNet/Channels/ChannelForwardedTcpip.cs +++ b/src/Renci.SshNet/Channels/ChannelForwardedTcpip.cs @@ -146,7 +146,7 @@ private void ShutdownSocket(SocketShutdown how) } catch (SocketException ex) { - _logger.LogWarning(ex, "Failure shutting down socket"); + _logger.LogInformation(ex, "Failure shutting down socket"); } } } diff --git a/src/Renci.SshNet/ForwardedPortDynamic.cs b/src/Renci.SshNet/ForwardedPortDynamic.cs index d33dcc32d..5b8ff9d29 100644 --- a/src/Renci.SshNet/ForwardedPortDynamic.cs +++ b/src/Renci.SshNet/ForwardedPortDynamic.cs @@ -413,7 +413,7 @@ private void InternalStop(TimeSpan timeout) if (!_pendingChannelCountdown.Wait(timeout)) { - _logger.LogWarning("Timeout waiting for pending channels in dynamic forwarded port to close."); + _logger.LogInformation("Timeout waiting for pending channels in dynamic forwarded port to close."); } } diff --git a/src/Renci.SshNet/ForwardedPortLocal.cs b/src/Renci.SshNet/ForwardedPortLocal.cs index d5eb99e31..50d84dc74 100644 --- a/src/Renci.SshNet/ForwardedPortLocal.cs +++ b/src/Renci.SshNet/ForwardedPortLocal.cs @@ -390,7 +390,7 @@ private void InternalStop(TimeSpan timeout) if (!_pendingChannelCountdown.Wait(timeout)) { - _logger.LogWarning("Timeout waiting for pending channels in local forwarded port to close."); + _logger.LogInformation("Timeout waiting for pending channels in local forwarded port to close."); } } diff --git a/src/Renci.SshNet/ForwardedPortRemote.cs b/src/Renci.SshNet/ForwardedPortRemote.cs index 7b2ca34d9..f51a3d82b 100644 --- a/src/Renci.SshNet/ForwardedPortRemote.cs +++ b/src/Renci.SshNet/ForwardedPortRemote.cs @@ -212,7 +212,7 @@ protected override void StopPort(TimeSpan timeout) if (!_pendingChannelCountdown.Wait(timeout)) { - _logger.LogWarning("Timeout waiting for pending channels in remote forwarded port to close."); + _logger.LogInformation("Timeout waiting for pending channels in remote forwarded port to close."); } _status = ForwardedPortStatus.Stopped; diff --git a/src/Renci.SshNet/Security/KeyExchange.cs b/src/Renci.SshNet/Security/KeyExchange.cs index 877aefd7f..ef957afd5 100644 --- a/src/Renci.SshNet/Security/KeyExchange.cs +++ b/src/Renci.SshNet/Security/KeyExchange.cs @@ -197,7 +197,7 @@ public Cipher CreateServerCipher(out bool isAead) serverKey = GenerateSessionKey(SharedKey, ExchangeHash, serverKey, _serverCipherInfo.KeySize / 8); - _logger.LogInformation("[{SessionId}] Creating {ServerEncryption} server cipher.", + _logger.LogDebug("[{SessionId}] Creating {ServerEncryption} server cipher.", Session.SessionIdHex, Session.ConnectionInfo.CurrentServerEncryption); @@ -225,7 +225,7 @@ public Cipher CreateClientCipher(out bool isAead) clientKey = GenerateSessionKey(SharedKey, ExchangeHash, clientKey, _clientCipherInfo.KeySize / 8); - _logger.LogInformation("[{SessionId}] Creating {ClientEncryption} client cipher.", + _logger.LogDebug("[{SessionId}] Creating {ClientEncryption} client cipher.", Session.SessionIdHex, Session.ConnectionInfo.CurrentClientEncryption); @@ -258,7 +258,7 @@ public HashAlgorithm CreateServerHash(out bool isEncryptThenMAC) Hash(GenerateSessionKey(SharedKey, ExchangeHash, 'F', sessionId)), _serverHashInfo.KeySize / 8); - _logger.LogInformation("[{SessionId}] Creating {ServerHmacAlgorithm} server hmac algorithm.", + _logger.LogDebug("[{SessionId}] Creating {ServerHmacAlgorithm} server hmac algorithm.", Session.SessionIdHex, Session.ConnectionInfo.CurrentServerHmacAlgorithm); @@ -290,7 +290,7 @@ public HashAlgorithm CreateClientHash(out bool isEncryptThenMAC) Hash(GenerateSessionKey(SharedKey, ExchangeHash, 'E', sessionId)), _clientHashInfo.KeySize / 8); - _logger.LogInformation("[{SessionId}] Creating {ClientHmacAlgorithm} client hmac algorithm.", + _logger.LogDebug("[{SessionId}] Creating {ClientHmacAlgorithm} client hmac algorithm.", Session.SessionIdHex, Session.ConnectionInfo.CurrentClientHmacAlgorithm); @@ -310,7 +310,7 @@ public Compressor CreateCompressor() return null; } - _logger.LogInformation("[{SessionId}] Creating {CompressionAlgorithm} client compressor.", + _logger.LogDebug("[{SessionId}] Creating {CompressionAlgorithm} client compressor.", Session.SessionIdHex, Session.ConnectionInfo.CurrentClientCompressionAlgorithm); @@ -334,7 +334,7 @@ public Compressor CreateDecompressor() return null; } - _logger.LogInformation("[{SessionId}] Creating {ServerCompressionAlgorithm} server decompressor.", + _logger.LogDebug("[{SessionId}] Creating {ServerCompressionAlgorithm} server decompressor.", Session.SessionIdHex, Session.ConnectionInfo.CurrentServerCompressionAlgorithm); diff --git a/src/Renci.SshNet/Session.cs b/src/Renci.SshNet/Session.cs index d4145e39d..a1ace540c 100644 --- a/src/Renci.SshNet/Session.cs +++ b/src/Renci.SshNet/Session.cs @@ -1047,7 +1047,10 @@ internal void SendMessage(Message message) WaitOnHandle(_keyExchangeCompletedWaitHandle.WaitHandle); } - _logger.LogInformation("[{SessionId}] Sending message '{MessageType}' to server: '{Message}'.", SessionIdHex, message.GetType().Name, message); + if (_logger.IsEnabled(LogLevel.Debug)) + { + _logger.LogDebug("[{SessionId}] Sending message '{MessageType}' to server: '{Message}'.", SessionIdHex, message.GetType().Name, message); + } var paddingMultiplier = _clientCipher is null ? (byte)8 : Math.Max((byte)8, _clientCipher.MinimumSize); var packetData = message.GetPacket(paddingMultiplier, _clientCompression, _clientEtm || _clientAead); @@ -1496,7 +1499,7 @@ internal void OnKeyExchangeInitReceived(KeyExchangeInitMessage message) { _isStrictKex = true; - _logger.LogInformation("[{SessionId}] Enabling strict key exchange extension.", SessionIdHex); + _logger.LogDebug("[{SessionId}] Enabling strict key exchange extension.", SessionIdHex); if (_inboundPacketSequence != 1) { @@ -1512,7 +1515,7 @@ internal void OnKeyExchangeInitReceived(KeyExchangeInitMessage message) ConnectionInfo.CurrentKeyExchangeAlgorithm = _keyExchange.Name; - _logger.LogInformation("[{SessionId}] Performing {KeyExchangeAlgorithm} key exchange.", SessionIdHex, ConnectionInfo.CurrentKeyExchangeAlgorithm); + _logger.LogDebug("[{SessionId}] Performing {KeyExchangeAlgorithm} key exchange.", SessionIdHex, ConnectionInfo.CurrentKeyExchangeAlgorithm); _keyExchange.HostKeyReceived += KeyExchange_HostKeyReceived; @@ -1828,7 +1831,10 @@ private Message LoadMessage(byte[] data, int offset, int count) var message = _sshMessageFactory.Create(messageType); message.Load(data, offset + 1, count - 1); - _logger.LogInformation("[{SessionId}] Received message '{MessageType}' from server: '{Message}'.", SessionIdHex, message.GetType().Name, message); + if (_logger.IsEnabled(LogLevel.Debug)) + { + _logger.LogDebug("[{SessionId}] Received message '{MessageType}' from server: '{Message}'.", SessionIdHex, message.GetType().Name, message); + } return message; } @@ -1968,7 +1974,7 @@ private void SocketDisconnectAndDispose() { try { - _logger.LogInformation("[{SessionId}] Shutting down socket.", SessionIdHex); + _logger.LogDebug("[{SessionId}] Shutting down socket.", SessionIdHex); // Interrupt any pending reads; should be done outside of socket read lock as we // actually want shutdown the socket to make sure blocking reads are interrupted. @@ -1980,13 +1986,13 @@ private void SocketDisconnectAndDispose() } catch (SocketException ex) { - _logger.LogWarning(ex, "Failure shutting down socket"); + _logger.LogInformation(ex, "Failure shutting down socket"); } } - _logger.LogInformation("[{SessionId}] Disposing socket.", SessionIdHex); + _logger.LogDebug("[{SessionId}] Disposing socket.", SessionIdHex); _socket.Dispose(); - _logger.LogInformation("[{SessionId}] Disposed socket.", SessionIdHex); + _logger.LogDebug("[{SessionId}] Disposed socket.", SessionIdHex); _socket = null; } } @@ -2170,7 +2176,7 @@ protected virtual void Dispose(bool disposing) if (disposing) { - _logger.LogInformation("[{SessionId}] Disposing session.", SessionIdHex); + _logger.LogDebug("[{SessionId}] Disposing session.", SessionIdHex); Disconnect(); diff --git a/test/Renci.SshNet.IntegrationTests/TestsFixtures/IntegrationTestBase.cs b/test/Renci.SshNet.IntegrationTests/TestsFixtures/IntegrationTestBase.cs index 3d2ed451b..579474008 100644 --- a/test/Renci.SshNet.IntegrationTests/TestsFixtures/IntegrationTestBase.cs +++ b/test/Renci.SshNet.IntegrationTests/TestsFixtures/IntegrationTestBase.cs @@ -63,7 +63,7 @@ static IntegrationTestBase() { ILoggerFactory loggerFactory = LoggerFactory.Create(builder => { - builder.SetMinimumLevel(LogLevel.Debug); + builder.SetMinimumLevel(LogLevel.Information); builder.AddConsole(); }); From 6d12f5d85674cce638f5a98fe78763c006dea6bc Mon Sep 17 00:00:00 2001 From: Rob Hague Date: Mon, 2 Dec 2024 21:55:08 +0100 Subject: [PATCH 6/8] hook up testcontainers logging --- docfx/logging.md | 2 +- .../TestsFixtures/InfrastructureFixture.cs | 24 ++++++++++++------- .../TestsFixtures/IntegrationTestBase.cs | 23 ++++-------------- 3 files changed, 22 insertions(+), 27 deletions(-) diff --git a/docfx/logging.md b/docfx/logging.md index 4f59b96d6..9c0693412 100644 --- a/docfx/logging.md +++ b/docfx/logging.md @@ -1,7 +1,7 @@ Logging ================= -SSH.NET uses the `Microsoft.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: +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 => diff --git a/test/Renci.SshNet.IntegrationTests/TestsFixtures/InfrastructureFixture.cs b/test/Renci.SshNet.IntegrationTests/TestsFixtures/InfrastructureFixture.cs index 4be520af6..7c095b867 100644 --- a/test/Renci.SshNet.IntegrationTests/TestsFixtures/InfrastructureFixture.cs +++ b/test/Renci.SshNet.IntegrationTests/TestsFixtures/InfrastructureFixture.cs @@ -2,23 +2,27 @@ using DotNet.Testcontainers.Containers; using DotNet.Testcontainers.Images; +using Microsoft.Extensions.Logging; + namespace Renci.SshNet.IntegrationTests.TestsFixtures { public sealed class InfrastructureFixture : IDisposable { private InfrastructureFixture() { + _loggerFactory = LoggerFactory.Create(builder => + { + builder.SetMinimumLevel(LogLevel.Debug); + builder.AddFilter("testcontainers", LogLevel.Information); + builder.AddConsole(); + }); + + SshNetLoggingConfiguration.InitializeLogging(_loggerFactory); } - private static readonly Lazy InstanceLazy = new Lazy(() => new InfrastructureFixture()); + public static InfrastructureFixture Instance { get; } = new InfrastructureFixture(); - public static InfrastructureFixture Instance - { - get - { - return InstanceLazy.Value; - } - } + private readonly ILoggerFactory _loggerFactory; private IContainer _sshServer; @@ -34,11 +38,14 @@ public static InfrastructureFixture Instance public async Task InitializeAsync() { + var containerLogger = _loggerFactory.CreateLogger("testcontainers"); + _sshServerImage = new ImageFromDockerfileBuilder() .WithName("renci-ssh-tests-server-image") .WithDockerfileDirectory(CommonDirectoryPath.GetSolutionDirectory(), Path.Combine("test", "Renci.SshNet.IntegrationTests")) .WithDockerfile("Dockerfile.TestServer") .WithDeleteIfExists(true) + .WithLogger(containerLogger) .Build(); await _sshServerImage.CreateAsync(); @@ -47,6 +54,7 @@ public async Task InitializeAsync() .WithHostname("renci-ssh-tests-server") .WithImage(_sshServerImage) .WithPortBinding(22, true) + .WithLogger(containerLogger) .Build(); await _sshServer.StartAsync(); diff --git a/test/Renci.SshNet.IntegrationTests/TestsFixtures/IntegrationTestBase.cs b/test/Renci.SshNet.IntegrationTests/TestsFixtures/IntegrationTestBase.cs index 579474008..6838e54d7 100644 --- a/test/Renci.SshNet.IntegrationTests/TestsFixtures/IntegrationTestBase.cs +++ b/test/Renci.SshNet.IntegrationTests/TestsFixtures/IntegrationTestBase.cs @@ -8,6 +8,7 @@ namespace Renci.SshNet.IntegrationTests.TestsFixtures public abstract class IntegrationTestBase { private readonly InfrastructureFixture _infrastructureFixture; + private readonly ILogger _logger; /// /// The SSH Server host name. @@ -56,24 +57,10 @@ public SshUser User protected IntegrationTestBase() { _infrastructureFixture = InfrastructureFixture.Instance; - ShowInfrastructureInformation(); - } - - static IntegrationTestBase() - { - ILoggerFactory loggerFactory = LoggerFactory.Create(builder => - { - builder.SetMinimumLevel(LogLevel.Information); - builder.AddConsole(); - }); - - SshNetLoggingConfiguration.InitializeLogging(loggerFactory); - } - - private void ShowInfrastructureInformation() - { - Console.WriteLine($"SSH Server host name: {_infrastructureFixture.SshServerHostName}"); - Console.WriteLine($"SSH Server port: {_infrastructureFixture.SshServerPort}"); + _logger = SshNetLoggingConfiguration.LoggerFactory.CreateLogger(GetType()); + _logger.LogDebug("SSH Server: {Host}:{Port}", + _infrastructureFixture.SshServerHostName, + _infrastructureFixture.SshServerPort); } /// From 13b5f9f44ea792ba8e3c6a45c4778273d8d34da6 Mon Sep 17 00:00:00 2001 From: Rob Hague Date: Mon, 2 Dec 2024 22:54:25 +0100 Subject: [PATCH 7/8] drop packet logs further down to trace --- src/Renci.SshNet/Session.cs | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/src/Renci.SshNet/Session.cs b/src/Renci.SshNet/Session.cs index a1ace540c..639a7dbba 100644 --- a/src/Renci.SshNet/Session.cs +++ b/src/Renci.SshNet/Session.cs @@ -1047,9 +1047,9 @@ internal void SendMessage(Message message) WaitOnHandle(_keyExchangeCompletedWaitHandle.WaitHandle); } - if (_logger.IsEnabled(LogLevel.Debug)) + if (_logger.IsEnabled(LogLevel.Trace)) { - _logger.LogDebug("[{SessionId}] Sending message '{MessageType}' to server: '{Message}'.", SessionIdHex, message.GetType().Name, message); + _logger.LogTrace("[{SessionId}] Sending message {MessageName}({MessageNumber}) to server: '{Message}'.", SessionIdHex, message.MessageName, message.MessageNumber, message.ToString()); } var paddingMultiplier = _clientCipher is null ? (byte)8 : Math.Max((byte)8, _clientCipher.MinimumSize); @@ -1189,12 +1189,12 @@ private bool TrySendMessage(Message message) } catch (SshException ex) { - _logger.LogInformation(ex, "Failure sending message '{MessageType}' to server: '{Message}'", message.GetType().Name, message); + _logger.LogInformation(ex, "Failure sending message {MessageName}({MessageNumber}) to server: '{Message}'", message.MessageName, message.MessageNumber, message.ToString()); return false; } catch (SocketException ex) { - _logger.LogInformation(ex, "Failure sending message '{MessageType}' to server: '{Message}'", message.GetType().Name, message); + _logger.LogInformation(ex, "Failure sending message {MessageName}({MessageNumber}) to server: '{Message}'", message.MessageName, message.MessageNumber, message.ToString()); return false; } } @@ -1831,9 +1831,9 @@ private Message LoadMessage(byte[] data, int offset, int count) var message = _sshMessageFactory.Create(messageType); message.Load(data, offset + 1, count - 1); - if (_logger.IsEnabled(LogLevel.Debug)) + if (_logger.IsEnabled(LogLevel.Trace)) { - _logger.LogDebug("[{SessionId}] Received message '{MessageType}' from server: '{Message}'.", SessionIdHex, message.GetType().Name, message); + _logger.LogTrace("[{SessionId}] Received message {MessageName}({MessageNumber}) from server: '{Message}'.", SessionIdHex, message.MessageName, message.MessageNumber, message.ToString()); } return message; From 69ec6e4e7fdc4ffa5120eae3f4691df079a8848f Mon Sep 17 00:00:00 2001 From: Rob Hague Date: Mon, 2 Dec 2024 22:55:28 +0100 Subject: [PATCH 8/8] add kex traces --- src/Renci.SshNet/Common/Extensions.cs | 7 +++ src/Renci.SshNet/Security/KeyExchange.cs | 75 +++++++++++++++++++++++- 2 files changed, 80 insertions(+), 2 deletions(-) diff --git a/src/Renci.SshNet/Common/Extensions.cs b/src/Renci.SshNet/Common/Extensions.cs index cf4deb077..2f3ae6ac0 100644 --- a/src/Renci.SshNet/Common/Extensions.cs +++ b/src/Renci.SshNet/Common/Extensions.cs @@ -351,5 +351,12 @@ internal static bool IsConnected(this Socket socket) return socket.Connected; } + + internal static string Join(this IEnumerable 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); + } } } diff --git a/src/Renci.SshNet/Security/KeyExchange.cs b/src/Renci.SshNet/Security/KeyExchange.cs index ef957afd5..1331098b0 100644 --- a/src/Renci.SshNet/Security/KeyExchange.cs +++ b/src/Renci.SshNet/Security/KeyExchange.cs @@ -78,12 +78,23 @@ public virtual void Start(Session session, KeyExchangeInitMessage message, bool SendMessage(session.ClientInitMessage); } - // Determine encryption algorithm + // Determine client encryption algorithm var clientEncryptionAlgorithmName = (from b in session.ConnectionInfo.Encryptions.Keys from a in message.EncryptionAlgorithmsClientToServer where a == b select a).FirstOrDefault(); + if (_logger.IsEnabled(LogLevel.Trace)) + { + _logger.LogTrace("[{SessionId}] Encryption client to server: we offer {WeOffer}", + Session.SessionIdHex, + session.ConnectionInfo.Encryptions.Keys.Join(",")); + + _logger.LogTrace("[{SessionId}] Encryption client to server: they offer {TheyOffer}", + Session.SessionIdHex, + message.EncryptionAlgorithmsClientToServer.Join(",")); + } + if (string.IsNullOrEmpty(clientEncryptionAlgorithmName)) { throw new SshConnectionException("Client encryption algorithm not found", DisconnectReason.KeyExchangeFailed); @@ -92,11 +103,23 @@ from a in message.EncryptionAlgorithmsClientToServer session.ConnectionInfo.CurrentClientEncryption = clientEncryptionAlgorithmName; _clientCipherInfo = session.ConnectionInfo.Encryptions[clientEncryptionAlgorithmName]; - // Determine encryption algorithm + // Determine server encryption algorithm var serverDecryptionAlgorithmName = (from b in session.ConnectionInfo.Encryptions.Keys from a in message.EncryptionAlgorithmsServerToClient where a == b select a).FirstOrDefault(); + + if (_logger.IsEnabled(LogLevel.Trace)) + { + _logger.LogTrace("[{SessionId}] Encryption server to client: we offer {WeOffer}", + Session.SessionIdHex, + session.ConnectionInfo.Encryptions.Keys.Join(",")); + + _logger.LogTrace("[{SessionId}] Encryption server to client: they offer {TheyOffer}", + Session.SessionIdHex, + message.EncryptionAlgorithmsServerToClient.Join(",")); + } + if (string.IsNullOrEmpty(serverDecryptionAlgorithmName)) { throw new SshConnectionException("Server decryption algorithm not found", DisconnectReason.KeyExchangeFailed); @@ -112,6 +135,18 @@ from a in message.EncryptionAlgorithmsServerToClient from a in message.MacAlgorithmsClientToServer where a == b select a).FirstOrDefault(); + + if (_logger.IsEnabled(LogLevel.Trace)) + { + _logger.LogTrace("[{SessionId}] MAC client to server: we offer {WeOffer}", + Session.SessionIdHex, + session.ConnectionInfo.HmacAlgorithms.Keys.Join(",")); + + _logger.LogTrace("[{SessionId}] MAC client to server: they offer {TheyOffer}", + Session.SessionIdHex, + message.MacAlgorithmsClientToServer.Join(",")); + } + if (string.IsNullOrEmpty(clientHmacAlgorithmName)) { throw new SshConnectionException("Client HMAC algorithm not found", DisconnectReason.KeyExchangeFailed); @@ -128,6 +163,18 @@ from a in message.MacAlgorithmsClientToServer from a in message.MacAlgorithmsServerToClient where a == b select a).FirstOrDefault(); + + if (_logger.IsEnabled(LogLevel.Trace)) + { + _logger.LogTrace("[{SessionId}] MAC server to client: we offer {WeOffer}", + Session.SessionIdHex, + session.ConnectionInfo.HmacAlgorithms.Keys.Join(",")); + + _logger.LogTrace("[{SessionId}] MAC server to client: they offer {TheyOffer}", + Session.SessionIdHex, + message.MacAlgorithmsServerToClient.Join(",")); + } + if (string.IsNullOrEmpty(serverHmacAlgorithmName)) { throw new SshConnectionException("Server HMAC algorithm not found", DisconnectReason.KeyExchangeFailed); @@ -142,6 +189,18 @@ from a in message.MacAlgorithmsServerToClient from a in message.CompressionAlgorithmsClientToServer where a == b select a).FirstOrDefault(); + + if (_logger.IsEnabled(LogLevel.Trace)) + { + _logger.LogTrace("[{SessionId}] Compression client to server: we offer {WeOffer}", + Session.SessionIdHex, + session.ConnectionInfo.CompressionAlgorithms.Keys.Join(",")); + + _logger.LogTrace("[{SessionId}] Compression client to server: they offer {TheyOffer}", + Session.SessionIdHex, + message.CompressionAlgorithmsClientToServer.Join(",")); + } + if (string.IsNullOrEmpty(compressionAlgorithmName)) { throw new SshConnectionException("Compression algorithm not found", DisconnectReason.KeyExchangeFailed); @@ -155,6 +214,18 @@ from a in message.CompressionAlgorithmsClientToServer from a in message.CompressionAlgorithmsServerToClient where a == b select a).FirstOrDefault(); + + if (_logger.IsEnabled(LogLevel.Trace)) + { + _logger.LogTrace("[{SessionId}] Compression server to client: we offer {WeOffer}", + Session.SessionIdHex, + session.ConnectionInfo.CompressionAlgorithms.Keys.Join(",")); + + _logger.LogTrace("[{SessionId}] Compression server to client: they offer {TheyOffer}", + Session.SessionIdHex, + message.CompressionAlgorithmsServerToClient.Join(",")); + } + if (string.IsNullOrEmpty(decompressionAlgorithmName)) { throw new SshConnectionException("Decompression algorithm not found", DisconnectReason.KeyExchangeFailed);