Skip to content
Merged
Show file tree
Hide file tree
Changes from 3 commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 1 addition & 1 deletion docfx/logging.md
Original file line number Diff line number Diff line change
@@ -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 =>
Expand Down
7 changes: 7 additions & 0 deletions src/Renci.SshNet/Common/Extensions.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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);
}
}
}
75 changes: 73 additions & 2 deletions src/Renci.SshNet/Security/KeyExchange.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand All @@ -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);
Expand All @@ -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);
Expand All @@ -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);
Expand All @@ -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);
Expand All @@ -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);
Expand Down
12 changes: 6 additions & 6 deletions src/Renci.SshNet/Session.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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());
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I changed it to output e.g. "Sending message SSH_MSG_NEWKEYS(21)" as it is helpful to see the number as well. It is a bit duplicative atm because most messages include the message name in the ToString

also I added explicit ToString on the message in case e.g. a json logger would dump all the properties of the message. trying to strike a balance between useful information and private session information

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

also, wondering if logger.BeginScope would have a valid use for tagging the SessionId to logs

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Using a scope for SessionId would make sense. A logging scope is based on an AsyncLocal though, so the BeginScope would have to be called in quite a few places.

}

var paddingMultiplier = _clientCipher is null ? (byte)8 : Math.Max((byte)8, _clientCipher.MinimumSize);
Expand Down Expand Up @@ -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;
}
}
Expand Down Expand Up @@ -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;
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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<InfrastructureFixture> InstanceLazy = new Lazy<InfrastructureFixture>(() => new InfrastructureFixture());
public static InfrastructureFixture Instance { get; } = new InfrastructureFixture();

public static InfrastructureFixture Instance
{
get
{
return InstanceLazy.Value;
}
}
private readonly ILoggerFactory _loggerFactory;

private IContainer _sshServer;

Expand All @@ -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();
Expand All @@ -47,6 +54,7 @@ public async Task InitializeAsync()
.WithHostname("renci-ssh-tests-server")
.WithImage(_sshServerImage)
.WithPortBinding(22, true)
.WithLogger(containerLogger)
.Build();

await _sshServer.StartAsync();
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -8,6 +8,7 @@ namespace Renci.SshNet.IntegrationTests.TestsFixtures
public abstract class IntegrationTestBase
{
private readonly InfrastructureFixture _infrastructureFixture;
private readonly ILogger _logger;

/// <summary>
/// The SSH Server host name.
Expand Down Expand Up @@ -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);
}

/// <summary>
Expand Down