From f8fac6f4d44a5ae011a8f9c6666f28f9e9047b8b Mon Sep 17 00:00:00 2001 From: Meir Blachman Date: Fri, 6 Jun 2025 16:35:21 +0300 Subject: [PATCH 1/4] chore(Orleans.Runtime): Use [LoggerMessage] p4 Cleanup `src\Orleans.Core\Networking\Connection.cs` --- src/Orleans.Core/Networking/Connection.cs | 152 ++++++++++++++-------- 1 file changed, 101 insertions(+), 51 deletions(-) diff --git a/src/Orleans.Core/Networking/Connection.cs b/src/Orleans.Core/Networking/Connection.cs index 0068ce24bba..7a09c8d90ce 100644 --- a/src/Orleans.Core/Networking/Connection.cs +++ b/src/Orleans.Core/Networking/Connection.cs @@ -16,7 +16,7 @@ namespace Orleans.Runtime.Messaging { - internal abstract class Connection + internal abstract partial class Connection { private static readonly Func OnConnectedDelegate = context => OnConnectedAsync(context); private static readonly Action OnConnectionClosedDelegate = state => ((Connection)state).OnTransportConnectionClosed(); @@ -152,13 +152,7 @@ private void StartClosing(Exception exception) _initializationTcs.TrySetException(exception ?? new ConnectionAbortedException("Connection initialization failed")); _initializationTcs.Task.Ignore(); - if (this.Log.IsEnabled(LogLevel.Information)) - { - this.Log.LogInformation( - exception, - "Closing connection {Connection}", - this); - } + LogInformationClosingConnection(this.Log, exception, this); task.Start(TaskScheduler.Default); } @@ -188,7 +182,7 @@ private async Task CloseAsync() catch (Exception processIncomingException) { // Swallow any exceptions here. - this.Log.LogWarning(processIncomingException, "Exception processing incoming messages on connection {Connection}", this); + LogWarningExceptionProcessingIncomingMessages(this.Log, processIncomingException, this); } } @@ -201,7 +195,7 @@ private async Task CloseAsync() catch (Exception processOutgoingException) { // Swallow any exceptions here. - this.Log.LogWarning(processOutgoingException, "Exception processing outgoing messages on connection {Connection}", this); + LogWarningExceptionProcessingOutgoingMessages(this.Log, processOutgoingException, this); } } @@ -215,7 +209,7 @@ private async Task CloseAsync() } catch (Exception exception) { - this.Log.LogWarning(exception, "Exception aborting connection {Connection}", this); + LogWarningExceptionAbortingConnection(this.Log, exception, this); } await _transportConnectionClosed.Task; @@ -228,7 +222,7 @@ private async Task CloseAsync() catch (Exception abortException) { // Swallow any exceptions here. - this.Log.LogWarning(abortException, "Exception terminating connection {Connection}", this); + LogWarningExceptionTerminatingConnection(this.Log, abortException, this); } // Reject in-flight messages. @@ -243,23 +237,18 @@ private async Task CloseAsync() var i = 0; while (this.outgoingMessages.Reader.TryRead(out var message)) { - if (i == 0 && Log.IsEnabled(LogLevel.Information)) + if (i == 0) { - this.Log.LogInformation( - "Rerouting messages for remote endpoint {EndPoint}", - this.RemoteEndPoint?.ToString() ?? "(never connected)"); + LogInformationReroutingMessages(this.Log, new EndPointLogValue(this.RemoteEndPoint)); } ++i; this.RetryMessage(message); } - if (i > 0 && this.Log.IsEnabled(LogLevel.Information)) + if (i > 0) { - this.Log.LogInformation( - "Rerouted {Count} messages for remote endpoint {EndPoint}", - i, - this.RemoteEndPoint?.ToString() ?? "(never connected)"); + LogInformationReroutedMessages(this.Log, i, new EndPointLogValue(this.RemoteEndPoint)); } } @@ -334,10 +323,7 @@ private async Task ProcessIncoming() { if (IsValid) { - this.Log.LogWarning( - exception, - "Exception while processing messages from remote endpoint {EndPoint}", - this.RemoteEndPoint); + LogWarningExceptionProcessingMessagesFromRemote(this.Log, exception, this.RemoteEndPoint); } error = exception; @@ -402,10 +388,7 @@ private async Task ProcessOutgoing() { if (IsValid) { - this.Log.LogWarning( - exception, - "Exception while processing messages to remote endpoint {EndPoint}", - this.RemoteEndPoint); + LogWarningExceptionProcessingMessagesToRemote(this.Log, exception, this.RemoteEndPoint); } error = exception; @@ -419,13 +402,7 @@ private async Task ProcessOutgoing() private void RerouteMessage(Message message) { - if (this.Log.IsEnabled(LogLevel.Information)) - { - this.Log.LogInformation( - "Rerouting message {Message} from remote endpoint {EndPoint}", - message, - this.RemoteEndPoint?.ToString() ?? "(never connected)"); - } + LogInformationReroutingMessage(this.Log, message, new EndPointLogValue(this.RemoteEndPoint)); ThreadPool.UnsafeQueueUserWorkItem(state => { @@ -453,12 +430,7 @@ private static EndPoint NormalizeEndpoint(EndPoint endpoint) /// if the exception should not be caught and if it should be caught. private bool HandleReceiveMessageFailure(Message message, Exception exception) { - this.Log.LogError( - exception, - "Exception reading message {Message} from remote endpoint {Remote} to local endpoint {Local}", - message, - this.RemoteEndPoint, - this.LocalEndPoint); + LogErrorExceptionReadingMessage(this.Log, exception, message, this.RemoteEndPoint, this.LocalEndPoint); // If deserialization completely failed, rethrow the exception so that it can be handled at another level. if (message is null || exception is InvalidMessageFrameException) @@ -500,12 +472,7 @@ private bool HandleSendMessageFailure(Message message, Exception exception) // We get here if we failed to serialize the msg (or any other catastrophic failure). // Request msg fails to serialize on the sender, so we just enqueue a rejection msg. // Response msg fails to serialize on the responding silo, so we try to send an error response back. - this.Log.LogError( - exception, - "Exception sending message {Message} to remote endpoint {Remote} from local endpoint {Local}", - message, - this.RemoteEndPoint, - this.LocalEndPoint); + LogErrorExceptionSendingMessage(this.Log, exception, message, this.RemoteEndPoint, this.LocalEndPoint); if (message is null || exception is InvalidMessageFrameException) { @@ -535,10 +502,9 @@ private bool HandleSendMessageFailure(Message message, Exception exception) } else { - this.Log.LogWarning( - (int)ErrorCode.Messaging_OutgoingMS_DroppingMessage, + LogWarningDroppingMessage( + this.Log, exception, - "Dropping message which failed during serialization: {Message}", message); MessagingInstruments.OnDroppedSentMessage(message); @@ -581,5 +547,89 @@ public void Reset() this.connection = null; } } + + private readonly struct EndPointLogValue(EndPoint endPoint) + { + public override string ToString() => endPoint?.ToString() ?? "(never connected)"; + } + + [LoggerMessage( + Level = LogLevel.Information, + Message = "Closing connection {Connection}" + )] + private static partial void LogInformationClosingConnection(ILogger logger, Exception exception, Connection connection); + + [LoggerMessage( + Level = LogLevel.Warning, + Message = "Exception processing incoming messages on connection {Connection}" + )] + private static partial void LogWarningExceptionProcessingIncomingMessages(ILogger logger, Exception exception, Connection connection); + + [LoggerMessage( + Level = LogLevel.Warning, + Message = "Exception processing outgoing messages on connection {Connection}" + )] + private static partial void LogWarningExceptionProcessingOutgoingMessages(ILogger logger, Exception exception, Connection connection); + + [LoggerMessage( + Level = LogLevel.Warning, + Message = "Exception aborting connection {Connection}" + )] + private static partial void LogWarningExceptionAbortingConnection(ILogger logger, Exception exception, Connection connection); + + [LoggerMessage( + Level = LogLevel.Warning, + Message = "Exception terminating connection {Connection}" + )] + private static partial void LogWarningExceptionTerminatingConnection(ILogger logger, Exception exception, Connection connection); + + [LoggerMessage( + Level = LogLevel.Information, + Message = "Rerouting messages for remote endpoint {EndPoint}" + )] + private static partial void LogInformationReroutingMessages(ILogger logger, EndPointLogValue endPoint); + + [LoggerMessage( + Level = LogLevel.Information, + Message = "Rerouted {Count} messages for remote endpoint {EndPoint}" + )] + private static partial void LogInformationReroutedMessages(ILogger logger, int count, EndPointLogValue endPoint); + + [LoggerMessage( + Level = LogLevel.Warning, + Message = "Exception while processing messages from remote endpoint {EndPoint}" + )] + private static partial void LogWarningExceptionProcessingMessagesFromRemote(ILogger logger, Exception exception, EndPoint endPoint); + + [LoggerMessage( + Level = LogLevel.Warning, + Message = "Exception while processing messages to remote endpoint {EndPoint}" + )] + private static partial void LogWarningExceptionProcessingMessagesToRemote(ILogger logger, Exception exception, EndPoint endPoint); + + [LoggerMessage( + Level = LogLevel.Information, + Message = "Rerouting message {Message} from remote endpoint {EndPoint}" + )] + private static partial void LogInformationReroutingMessage(ILogger logger, Message message, EndPointLogValue endPoint); + + [LoggerMessage( + Level = LogLevel.Error, + Message = "Exception reading message {Message} from remote endpoint {Remote} to local endpoint {Local}" + )] + private static partial void LogErrorExceptionReadingMessage(ILogger logger, Exception exception, Message message, EndPoint remote, EndPoint local); + + [LoggerMessage( + Level = LogLevel.Error, + Message = "Exception sending message {Message} to remote endpoint {Remote} from local endpoint {Local}" + )] + private static partial void LogErrorExceptionSendingMessage(ILogger logger, Exception exception, Message message, EndPoint remote, EndPoint local); + + [LoggerMessage( + EventId = (int)ErrorCode.Messaging_OutgoingMS_DroppingMessage, + Level = LogLevel.Warning, + Message = "Dropping message which failed during serialization: {Message}" + )] + private static partial void LogWarningDroppingMessage(ILogger logger, Exception exception, Message message); } } From e0e5a0cb00b81b24439c753ae3d7f6062fd46ae2 Mon Sep 17 00:00:00 2001 From: Meir Blachman Date: Fri, 6 Jun 2025 16:47:24 +0300 Subject: [PATCH 2/4] chore(Orleans.Runtime): Use [LoggerMessage] p4 Cleanup `src\Orleans.Core\Utils\ObserverManager.cs` --- src/Orleans.Core/Utils/ObserverManager.cs | 64 ++++++++++++++--------- 1 file changed, 39 insertions(+), 25 deletions(-) diff --git a/src/Orleans.Core/Utils/ObserverManager.cs b/src/Orleans.Core/Utils/ObserverManager.cs index 238c38e393b..878abed137a 100644 --- a/src/Orleans.Core/Utils/ObserverManager.cs +++ b/src/Orleans.Core/Utils/ObserverManager.cs @@ -37,7 +37,7 @@ public ObserverManager(TimeSpan expiration, ILogger log) : base(expiration, log) /// /// The observer type. /// - public class ObserverManager : IEnumerable where TIdentity : notnull + public partial class ObserverManager : IEnumerable where TIdentity : notnull { /// /// The observers. @@ -107,18 +107,12 @@ public void Subscribe(TIdentity id, TObserver observer) { entry.LastSeen = now; entry.Observer = observer; - if (_log.IsEnabled(LogLevel.Debug)) - { - _log.LogDebug("Updating entry for {Id}/{Observer}. {Count} total observers.", id, observer, _observers.Count); - } + LogDebugUpdatingEntry(id, observer, _observers.Count); } else { _observers[id] = new ObserverEntry { LastSeen = now, Observer = observer }; - if (_log.IsEnabled(LogLevel.Debug)) - { - _log.LogDebug("Adding entry for {Id}/{Observer}. {Count} total observers after add.", id, observer, _observers.Count); - } + LogDebugAddingEntry(id, observer, _observers.Count); } } @@ -131,10 +125,7 @@ public void Subscribe(TIdentity id, TObserver observer) public void Unsubscribe(TIdentity id) { _observers.Remove(id, out _); - if (_log.IsEnabled(LogLevel.Debug)) - { - _log.LogDebug("Removed entry for {Id}. {Count} total observers after remove.", id, _observers.Count); - } + LogDebugRemovedEntry(id, _observers.Count); } /// @@ -164,7 +155,7 @@ public async Task Notify(Func notification, Func notification, Func notification, Func predica } // Skip observers which don't match the provided predicate. - if (predicate != null && !predicate(observer.Value.Observer)) + if (predicate is not null && !predicate(observer.Value.Observer)) { continue; } @@ -242,10 +230,7 @@ public void Notify(Action notification, Func predica foreach (var observer in defunct) { _observers.Remove(observer, out _); - if (_log.IsEnabled(LogLevel.Debug)) - { - _log.LogDebug("Removing defunct entry for {Id}. {Count} total observers after remove.", observer, _observers.Count); - } + LogDebugRemovingDefunctEntry(observer, _observers.Count); } } } @@ -270,7 +255,7 @@ public void ClearExpired() // Remove defunct observers. if (defunct is { Count: > 0 }) { - _log.LogInformation("Removing {Count} defunct observers entries.", defunct.Count); + LogInformationRemovingDefunctObservers(defunct.Count); foreach (var observer in defunct) { _observers.Remove(observer, out _); @@ -309,6 +294,35 @@ private class ObserverEntry /// public DateTime LastSeen { get; set; } } - } + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Updating entry for {Id}/{Observer}. {Count} total observers." + )] + private partial void LogDebugUpdatingEntry(TIdentity id, TObserver observer, int count); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Adding entry for {Id}/{Observer}. {Count} total observers after add." + )] + private partial void LogDebugAddingEntry(TIdentity id, TObserver observer, int count); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Removed entry for {Id}. {Count} total observers after remove." + )] + private partial void LogDebugRemovedEntry(TIdentity id, int count); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Removing defunct entry for {Id}. {Count} total observers after remove." + )] + private partial void LogDebugRemovingDefunctEntry(TIdentity id, int count); + + [LoggerMessage( + Level = LogLevel.Information, + Message = "Removing {Count} defunct observers entries." + )] + private partial void LogInformationRemovingDefunctObservers(int count); + } } From 993664ca12c8a28eec0275264fb4cad3d2c451c7 Mon Sep 17 00:00:00 2001 From: Meir Blachman Date: Fri, 6 Jun 2025 16:50:38 +0300 Subject: [PATCH 3/4] chore(Orleans.Runtime): Use [LoggerMessage] p4 Cleanup `src\Orleans.Core\Networking\Shared\SocketConnection.cs` --- .../Networking/Shared/SocketConnection.cs | 18 +++++++++++++++--- 1 file changed, 15 insertions(+), 3 deletions(-) diff --git a/src/Orleans.Core/Networking/Shared/SocketConnection.cs b/src/Orleans.Core/Networking/Shared/SocketConnection.cs index 69577a19ecd..6984fb29a01 100644 --- a/src/Orleans.Core/Networking/Shared/SocketConnection.cs +++ b/src/Orleans.Core/Networking/Shared/SocketConnection.cs @@ -11,7 +11,7 @@ namespace Orleans.Networking.Shared { - internal sealed class SocketConnection : TransportConnection + internal sealed partial class SocketConnection : TransportConnection { private static readonly int MinAllocBufferSize = SlabMemoryPool.BlockSize / 2; private static readonly bool IsWindows = RuntimeInformation.IsOSPlatform(OSPlatform.Windows); @@ -99,7 +99,7 @@ private async Task StartAsync() } catch (Exception ex) { - _trace.LogError(0, ex, $"Unexpected exception in {nameof(SocketConnection)}.{nameof(StartAsync)}."); + LogErrorUnexpectedExceptionInStartAsync(_trace, ex); } } @@ -355,7 +355,7 @@ private void CancelConnectionClosedToken() } catch (Exception ex) { - _trace.LogError(0, ex, $"Unexpected exception in {nameof(SocketConnection)}.{nameof(CancelConnectionClosedToken)}."); + LogErrorUnexpectedExceptionInCancelConnectionClosedToken(_trace, ex); } } @@ -376,5 +376,17 @@ private static bool IsConnectionAbortError(SocketError errorCode) errorCode == SocketError.Interrupted || (errorCode == SocketError.InvalidArgument && !IsWindows); } + + [LoggerMessage( + Level = LogLevel.Error, + Message = "Unexpected exception in SocketConnection.StartAsync." + )] + private static partial void LogErrorUnexpectedExceptionInStartAsync(ILogger logger, Exception exception); + + [LoggerMessage( + Level = LogLevel.Error, + Message = "Unexpected exception in SocketConnection.CancelConnectionClosedToken." + )] + private static partial void LogErrorUnexpectedExceptionInCancelConnectionClosedToken(ILogger logger, Exception exception); } } From bfdd4753e53f9b1f2736ad89271802f5b86e97ff Mon Sep 17 00:00:00 2001 From: Meir Blachman Date: Fri, 6 Jun 2025 16:55:23 +0300 Subject: [PATCH 4/4] Migrates logging methods to source generators Replaces manual LoggerMessage.Define declarations with LoggerMessage attributes to leverage compile-time source generation. Improves performance by eliminating runtime delegate creation and reduces boilerplate code maintenance overhead. --- .../Networking/Shared/SocketsTrace.cs | 91 ++++++++----------- 1 file changed, 40 insertions(+), 51 deletions(-) diff --git a/src/Orleans.Core/Networking/Shared/SocketsTrace.cs b/src/Orleans.Core/Networking/Shared/SocketsTrace.cs index 56bc1566275..0296cd345e5 100644 --- a/src/Orleans.Core/Networking/Shared/SocketsTrace.cs +++ b/src/Orleans.Core/Networking/Shared/SocketsTrace.cs @@ -3,32 +3,9 @@ namespace Orleans.Networking.Shared { - internal class SocketsTrace : ISocketsTrace + internal partial class SocketsTrace : ISocketsTrace { // ConnectionRead: Reserved: 3 - - private static readonly Action _connectionPause = - LoggerMessage.Define(LogLevel.Debug, new EventId(4, nameof(ConnectionPause)), @"Connection id ""{ConnectionId}"" paused."); - - private static readonly Action _connectionResume = - LoggerMessage.Define(LogLevel.Debug, new EventId(5, nameof(ConnectionResume)), @"Connection id ""{ConnectionId}"" resumed."); - - private static readonly Action _connectionReadFin = - LoggerMessage.Define(LogLevel.Debug, new EventId(6, nameof(ConnectionReadFin)), @"Connection id ""{ConnectionId}"" received FIN."); - - private static readonly Action _connectionWriteFin = - LoggerMessage.Define(LogLevel.Debug, new EventId(7, nameof(ConnectionWriteFin)), @"Connection id ""{ConnectionId}"" sending FIN because: ""{Reason}"""); - - // ConnectionWrite: Reserved: 11 - - // ConnectionWriteCallback: Reserved: 12 - - private static readonly Action _connectionError = - LoggerMessage.Define(LogLevel.Information, new EventId(14, nameof(ConnectionError)), @"Connection id ""{ConnectionId}"" communication error."); - - private static readonly Action _connectionReset = - LoggerMessage.Define(LogLevel.Debug, new EventId(19, nameof(ConnectionReset)), @"Connection id ""{ConnectionId}"" reset."); - private readonly ILogger _logger; public SocketsTrace(ILogger logger) @@ -42,15 +19,19 @@ public void ConnectionRead(string connectionId, int count) // Reserved: Event ID 3 } - public void ConnectionReadFin(string connectionId) - { - _connectionReadFin(_logger, connectionId, null); - } + [LoggerMessage( + EventId = 6, + Level = LogLevel.Debug, + Message = @"Connection id ""{ConnectionId}"" received FIN." + )] + public partial void ConnectionReadFin(string connectionId); - public void ConnectionWriteFin(string connectionId, string reason) - { - _connectionWriteFin(_logger, connectionId, reason, null); - } + [LoggerMessage( + EventId = 7, + Level = LogLevel.Debug, + Message = @"Connection id ""{ConnectionId}"" sending FIN because: ""{Reason}""" + )] + public partial void ConnectionWriteFin(string connectionId, string reason); public void ConnectionWrite(string connectionId, int count) { @@ -64,25 +45,33 @@ public void ConnectionWriteCallback(string connectionId, int status) // Reserved: Event ID 12 } - public void ConnectionError(string connectionId, Exception ex) - { - _connectionError(_logger, connectionId, ex); - } - - public void ConnectionReset(string connectionId) - { - _connectionReset(_logger, connectionId, null); - } - - public void ConnectionPause(string connectionId) - { - _connectionPause(_logger, connectionId, null); - } - - public void ConnectionResume(string connectionId) - { - _connectionResume(_logger, connectionId, null); - } + [LoggerMessage( + EventId = 13, + Level = LogLevel.Debug, + Message = @"Connection id ""{ConnectionId}"" sending FIN." + )] + public partial void ConnectionError(string connectionId, Exception ex); + + [LoggerMessage( + EventId = 19, + Level = LogLevel.Debug, + Message = @"Connection id ""{ConnectionId}"" reset." + )] + public partial void ConnectionReset(string connectionId); + + [LoggerMessage( + EventId = 4, + Level = LogLevel.Debug, + Message = @"Connection id ""{ConnectionId}"" paused." + )] + public partial void ConnectionPause(string connectionId); + + [LoggerMessage( + EventId = 5, + Level = LogLevel.Debug, + Message = @"Connection id ""{ConnectionId}"" resumed." + )] + public partial void ConnectionResume(string connectionId); public IDisposable BeginScope(TState state) => _logger.BeginScope(state);