diff --git a/src/Orleans.Core/Diagnostics/MessagingTrace.cs b/src/Orleans.Core/Diagnostics/MessagingTrace.cs index 9f44a421a9..f1532c3b78 100644 --- a/src/Orleans.Core/Diagnostics/MessagingTrace.cs +++ b/src/Orleans.Core/Diagnostics/MessagingTrace.cs @@ -25,42 +25,26 @@ internal class MessagingTrace : DiagnosticListener, ILogger public const string InvokeMessageEventName = Category + ".Invoke"; public const string RejectSendMessageToDeadSiloEventName = Category + ".Reject.TargetDead"; - private static readonly Action LogDropExpiredMessage - = LoggerMessage.Define( - LogLevel.Warning, - new EventId((int)ErrorCode.Messaging_DroppingExpiredMessage, DropExpiredMessageEventName), - "Dropping expired message {Message} at phase {Phase}"); - - private static readonly Action LogDropBlockedApplicationMessage - = LoggerMessage.Define( - LogLevel.Warning, - new EventId((int)ErrorCode.Messaging_DroppingBlockedMessage, DropBlockedApplicationMessageEventName), - "Dropping message {Message} since this silo is blocking application messages"); - - private static readonly Action LogEnqueueInboundMessage - = LoggerMessage.Define( - LogLevel.Trace, - new EventId((int)ErrorCode.Messaging_Inbound_Enqueue, EnqueueInboundMessageEventName), - "Enqueueing inbound message {Message}"); - - private static readonly Action LogDequeueInboundMessage - = LoggerMessage.Define( - LogLevel.Trace, - new EventId((int)ErrorCode.Messaging_Inbound_Dequeue, DequeueInboundMessageEventName), - "Dequeueing inbound message {Message}"); - - private static readonly Action LogSiloDropSendingMessage - = LoggerMessage.Define( - LogLevel.Warning, - new EventId((int)ErrorCode.Messaging_OutgoingMS_DroppingMessage, DropSendingMessageEventName), - "Silo {SiloAddress} is dropping message {Message}. Reason: {Reason}"); - - private static readonly Action LogRejectSendMessageToDeadSilo - = LoggerMessage.Define( - LogLevel.Information, - new EventId((int)ErrorCode.MessagingSendingRejection, RejectSendMessageToDeadSiloEventName), - "Silo {SiloAddress} is rejecting message to known-dead silo {DeadSilo}: {Message}"); + private static partial class Log + { + [LoggerMessage(1, LogLevel.Warning, "Dropping expired message {Message} at phase {Phase}")] + public static partial void DropExpiredMessage(ILogger logger, Message message, MessagingInstruments.Phase phase); + + [LoggerMessage(2, LogLevel.Warning, "Dropping message {Message} since this silo is blocking application messages")] + public static partial void DropBlockedApplicationMessage(ILogger logger, Message message); + + [LoggerMessage(3, LogLevel.Trace, "Enqueueing inbound message {Message}")] + public static partial void EnqueueInboundMessage(ILogger logger, Message message); + [LoggerMessage(4, LogLevel.Trace, "Dequeueing inbound message {Message}")] + public static partial void DequeueInboundMessage(ILogger logger, Message message); + + [LoggerMessage(5, LogLevel.Warning, "Silo {SiloAddress} is dropping message {Message}. Reason: {Reason}")] + public static partial void SiloDropSendingMessage(ILogger logger, SiloAddress localSiloAddress, Message message, string reason); + + [LoggerMessage(6, LogLevel.Information, "Silo {SiloAddress} is rejecting message to known-dead silo {DeadSilo}: {Message}")] + public static partial void RejectSendMessageToDeadSilo(ILogger logger, SiloAddress localSilo, SiloAddress deadSilo, Message message); + } private readonly ILogger log; @@ -107,7 +91,7 @@ internal void OnDropExpiredMessage(Message message, MessagingInstruments.Phase p } MessagingInstruments.OnMessageExpired(phase); - LogDropExpiredMessage(this, message, phase, null); + Log.DropExpiredMessage(this.log, message, phase); } internal void OnDropBlockedApplicationMessage(Message message) @@ -117,13 +101,13 @@ internal void OnDropBlockedApplicationMessage(Message message) this.Write(DropBlockedApplicationMessageEventName, message); } - LogDropBlockedApplicationMessage(this, message, null); + Log.DropBlockedApplicationMessage(this.log, message); } internal void OnSiloDropSendingMessage(SiloAddress localSiloAddress, Message message, string reason) { MessagingInstruments.OnDroppedSentMessage(message); - LogSiloDropSendingMessage(this, localSiloAddress, message, reason, null); + Log.SiloDropSendingMessage(this.log, localSiloAddress, message, reason); } public void OnEnqueueInboundMessage(Message message) @@ -133,7 +117,7 @@ public void OnEnqueueInboundMessage(Message message) this.Write(EnqueueInboundMessageEventName, message); } - LogEnqueueInboundMessage(this, message, null); + Log.EnqueueInboundMessage(this.log, message); } public void OnDequeueInboundMessage(Message message) @@ -143,7 +127,7 @@ public void OnDequeueInboundMessage(Message message) this.Write(DequeueInboundMessageEventName, message); } - LogDequeueInboundMessage(this, message, null); + Log.DequeueInboundMessage(this.log, message); } internal void OnCreateMessage(Message message) @@ -189,12 +173,11 @@ public void OnRejectSendMessageToDeadSilo(SiloAddress localSilo, Message message this.Write(RejectSendMessageToDeadSiloEventName, message); } - LogRejectSendMessageToDeadSilo( - this, + Log.RejectSendMessageToDeadSilo( + this.log, localSilo, message.TargetSilo, - message, - null); + message); } internal void OnSendRequest(Message message) diff --git a/src/Orleans.Core/Manifest/ClientClusterManifestProvider.cs b/src/Orleans.Core/Manifest/ClientClusterManifestProvider.cs index 1cf6e9e5cc..5a9abe515a 100644 --- a/src/Orleans.Core/Manifest/ClientClusterManifestProvider.cs +++ b/src/Orleans.Core/Manifest/ClientClusterManifestProvider.cs @@ -21,6 +21,27 @@ namespace Orleans.Runtime /// internal class ClientClusterManifestProvider : IClusterManifestProvider, IAsyncDisposable, IDisposable { + private static partial class Log + { + [LoggerMessage(1, LogLevel.Debug, "Refreshed cluster manifest")] + public static partial void RefreshedClusterManifest(ILogger logger); + + [LoggerMessage(2, LogLevel.Debug, "Stopped refreshing cluster manifest")] + public static partial void StoppedRefreshingClusterManifest(ILogger logger); + + [LoggerMessage(3, LogLevel.Information, "Graceful shutdown of cluster manifest provider was canceled.")] + public static partial void GracefulShutdownCanceled(ILogger logger); + + [LoggerMessage(4, LogLevel.Error, "Error stopping cluster manifest provider.")] + public static partial void ErrorStoppingClusterManifestProvider(ILogger logger, Exception exception); + + [LoggerMessage(5, LogLevel.Warning, "Error trying to get cluster manifest from gateway {Gateway}")] + public static partial void ErrorGettingClusterManifest(ILogger logger, Exception exception, SiloAddress gateway); + + [LoggerMessage(6, LogLevel.Warning, "Failed to fetch cluster manifest update from {Provider}.")] + public static partial void FailedToFetchClusterManifestUpdate(ILogger logger, Exception exception, IClusterManifestSystemTarget provider); + } + private readonly TaskCompletionSource _initialized = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); private readonly ILogger _logger; private readonly TypeManagementOptions _typeManagementOptions; @@ -90,11 +111,11 @@ public async Task StopAsync(CancellationToken cancellationToken) } catch (OperationCanceledException) { - _logger.LogInformation("Graceful shutdown of cluster manifest provider was canceled."); + Log.GracefulShutdownCanceled(_logger); } catch (Exception exception) { - _logger.LogError(exception, "Error stopping cluster manifest provider."); + Log.ErrorStoppingClusterManifestProvider(_logger, exception); } } @@ -182,16 +203,13 @@ private async Task RunAsync() _initialized.TrySetResult(true); - if (_logger.IsEnabled(LogLevel.Debug)) - { - _logger.LogDebug("Refreshed cluster manifest"); - } + Log.RefreshedClusterManifest(_logger); await Task.WhenAny(cancellationTask, Task.Delay(_typeManagementOptions.TypeMapRefreshInterval)); } catch (Exception exception) { - _logger.LogWarning(exception, "Error trying to get cluster manifest from gateway {Gateway}", gateway); + Log.ErrorGettingClusterManifest(_logger, exception, gateway); await Task.Delay(StandardExtensions.Min(_typeManagementOptions.TypeMapRefreshInterval, TimeSpan.FromSeconds(5))); // Reset the gateway so that another will be selected on the next iteration. @@ -203,10 +221,7 @@ private async Task RunAsync() { _initialized.TrySetResult(false); - if (_logger.IsEnabled(LogLevel.Debug)) - { - _logger.LogDebug("Stopped refreshing cluster manifest"); - } + Log.StoppedRefreshingClusterManifest(_logger); } } @@ -220,7 +235,7 @@ private async Task RunAsync() } catch (Exception exception) { - _logger.LogWarning(exception, "Failed to fetch cluster manifest update from {Provider}.", provider); + Log.FailedToFetchClusterManifestUpdate(_logger, exception, provider); // If the provider does not support the new API, fall back to the old one. var manifest = await provider.GetClusterManifest(); diff --git a/src/Orleans.Core/Messaging/ClientMessageCenter.cs b/src/Orleans.Core/Messaging/ClientMessageCenter.cs index 62ee871b2e..08a33674a6 100644 --- a/src/Orleans.Core/Messaging/ClientMessageCenter.cs +++ b/src/Orleans.Core/Messaging/ClientMessageCenter.cs @@ -65,6 +65,33 @@ internal class ClientMessageCenter : IMessageCenter, IDisposable private readonly ConnectionManager connectionManager; private readonly LocalClientDetails _localClientDetails; + private static partial class Log + { + [LoggerMessage(1, LogLevel.Debug, "Proxy grain client constructed")] + public static partial void ProxyGrainClientConstructed(ILogger logger); + + [LoggerMessage(2, LogLevel.Debug, "Proxy grain client started")] + public static partial void ProxyGrainClientStarted(ILogger logger); + + [LoggerMessage(3, LogLevel.Error, "Ignoring {Message} because the Client message center is not running")] + public static partial void IgnoringMessage(ILogger logger, Message message); + + [LoggerMessage(4, LogLevel.Trace, "Sending message {Message} via gateway {Gateway}")] + public static partial void SendingMessageViaGateway(ILogger logger, Message message, EndPoint gateway); + + [LoggerMessage(5, LogLevel.Warning, "Unable to send message {Message}; Gateway manager state is {GatewayManager}")] + public static partial void UnableToSendMessage(ILogger logger, Message message, GatewayManager gatewayManager); + + [LoggerMessage(6, LogLevel.Debug, "Dropping message: {Message}. Reason = {Reason}")] + public static partial void DroppingMessage(ILogger logger, Message message, string reason); + + [LoggerMessage(7, LogLevel.Debug, "Rejecting message: {Message}. Reason = {Reason}")] + public static partial void RejectingMessage(ILogger logger, Message message, string reason); + + [LoggerMessage(8, LogLevel.Warning, "Unable to send message {Message}; Gateway manager state is {GatewayManager}")] + public static partial void UnableToSendMessageNoGateway(ILogger logger, Message message, GatewayManager gatewayManager); + } + public ClientMessageCenter( IOptions clientMessagingOptions, LocalClientDetails localClientDetails, @@ -85,7 +112,7 @@ public ClientMessageCenter( numMessages = 0; this.grainBuckets = new WeakReference[clientMessagingOptions.Value.ClientSenderBuckets]; logger = loggerFactory.CreateLogger(); - if (logger.IsEnabled(LogLevel.Debug)) logger.LogDebug("Proxy grain client constructed"); + Log.ProxyGrainClientConstructed(logger); ClientInstruments.RegisterConnectedGatewayCountObserve(() => connectionManager.ConnectionCount); } @@ -94,7 +121,7 @@ public async Task StartAsync(CancellationToken cancellationToken) await EstablishInitialConnection(cancellationToken); Running = true; - if (logger.IsEnabled(LogLevel.Debug)) logger.LogDebug("Proxy grain client started"); + Log.ProxyGrainClientStarted(logger); } private async Task EstablishInitialConnection(CancellationToken cancellationToken) @@ -170,10 +197,7 @@ public void SendMessage(Message msg) { if (!Running) { - this.logger.LogError( - (int)ErrorCode.ProxyClient_MsgCtrNotRunning, - "Ignoring {Message} because the Client message center is not running", - msg); + Log.IgnoringMessage(logger, msg); return; } @@ -185,14 +209,7 @@ public void SendMessage(Message msg) connection.Send(msg); - if (this.logger.IsEnabled(LogLevel.Trace)) - { - this.logger.LogTrace( - (int)ErrorCode.ProxyClient_QueueRequest, - "Sending message {Message} via gateway {Gateway}", - msg, - connection.RemoteEndPoint); - } + Log.SendingMessageViaGateway(logger, msg, connection.RemoteEndPoint); } else { @@ -209,14 +226,7 @@ async Task SendAsync(ValueTask task, Message message) connection.Send(message); - if (this.logger.IsEnabled(LogLevel.Trace)) - { - this.logger.LogTrace( - (int)ErrorCode.ProxyClient_QueueRequest, - "Sending message {Message} via gateway {Gateway}", - message, - connection.RemoteEndPoint); - } + Log.SendingMessageViaGateway(logger, message, connection.RemoteEndPoint); } catch (Exception exception) { @@ -267,11 +277,7 @@ private ValueTask GetGatewayConnection(Message msg) if (numGateways == 0) { RejectMessage(msg, "No gateways available"); - logger.LogWarning( - (int)ErrorCode.ProxyClient_CannotSend, - "Unable to send message {Message}; Gateway manager state is {GatewayManager}", - msg, - gatewayManager); + Log.UnableToSendMessage(logger, msg, gatewayManager); return new ValueTask(default(Connection)); } @@ -305,11 +311,7 @@ private ValueTask GetGatewayConnection(Message msg) if (addr == null) { RejectMessage(msg, "No gateways available"); - logger.LogWarning( - (int)ErrorCode.ProxyClient_CannotSend_NoGateway, - "Unable to send message {Message}; Gateway manager state is {GatewayManager}", - msg, - gatewayManager); + Log.UnableToSendMessageNoGateway(logger, msg, gatewayManager); return new ValueTask(default(Connection)); } @@ -392,11 +394,11 @@ public void RejectMessage(Message msg, string reason, Exception exc = null) if (msg.Direction != Message.Directions.Request) { - if (logger.IsEnabled(LogLevel.Debug)) logger.LogDebug((int)ErrorCode.ProxyClient_DroppingMsg, "Dropping message: {Message}. Reason = {Reason}", msg, reason); + Log.DroppingMessage(logger, msg, reason); } else { - if (logger.IsEnabled(LogLevel.Debug)) logger.LogDebug((int)ErrorCode.ProxyClient_RejectingMsg, "Rejecting message: {Message}. Reason = {Reason}", msg, reason); + Log.RejectingMessage(logger, msg, reason); MessagingInstruments.OnRejectedMessage(msg); var error = this.messageFactory.CreateRejectionResponse(msg, Message.RejectionTypes.Unrecoverable, reason, exc); DispatchLocalMessage(error); diff --git a/src/Orleans.Core/Messaging/GatewayManager.cs b/src/Orleans.Core/Messaging/GatewayManager.cs index 0e7b433839..0ae47d9f5b 100644 --- a/src/Orleans.Core/Messaging/GatewayManager.cs +++ b/src/Orleans.Core/Messaging/GatewayManager.cs @@ -39,6 +39,30 @@ internal class GatewayManager : IDisposable private bool gatewayListProviderInitialized; private Task? gatewayRefreshTimerTask; + private static partial class Log + { + [LoggerMessage(1, LogLevel.Warning, "Could not find any gateway in '{GatewayListProviderName}'. Orleans client cannot initialize until at least one gateway becomes available.")] + public static partial void NoGateways(ILogger logger, string gatewayListProviderName); + + [LoggerMessage(2, LogLevel.Information, "Found {GatewayCount} gateways: {Gateways}")] + public static partial void FoundKnownGateways(ILogger logger, int gatewayCount, string gateways); + + [LoggerMessage(3, LogLevel.Warning, "All known gateways have been marked dead locally. Expediting gateway refresh and resetting all gateways to live status.")] + public static partial void AllKnownGatewaysMarkedDead(ILogger logger); + + [LoggerMessage(4, LogLevel.Warning, "All gateways have previously been marked as dead. Clearing the list of dead gateways to expedite reconnection.")] + public static partial void AllGatewaysDead(ILogger logger); + + [LoggerMessage(5, LogLevel.Debug, "Refreshed the live gateway list. Found {KnownGatewayCount} gateways from gateway list provider: {KnownGateways}. Picked only known live out of them. Now has {LiveGatewayCount} live gateways: {LiveGateways}. Previous refresh time was = {PreviousRefreshTime}")] + public static partial void RefreshedLiveGatewayList(ILogger logger, int knownGatewayCount, string knownGateways, int liveGatewayCount, string liveGateways, DateTime previousRefreshTime); + + [LoggerMessage(6, LogLevel.Error, "Error refreshing gateways.")] + public static partial void ErrorRefreshingGateways(ILogger logger, Exception exception); + + [LoggerMessage(7, LogLevel.Information, "Closing connection to {Endpoint} because it has been marked as dead")] + public static partial void ClosingConnection(ILogger logger, SiloAddress endpoint); + } + public GatewayManager( IOptions gatewayOptions, IGatewayListProvider gatewayListProvider, @@ -68,16 +92,12 @@ public async Task StartAsync(CancellationToken cancellationToken) { // this situation can occur if the client starts faster than the silos. var providerName = this.gatewayListProvider.GetType().FullName; - this.logger.LogWarning((int)ErrorCode.GatewayManager_NoGateways, "Could not find any gateway in '{GatewayListProviderName}'. Orleans client cannot initialize until at least one gateway becomes available.", providerName); + Log.NoGateways(this.logger, providerName); var message = $"Could not find any gateway in '{providerName}'. Orleans client cannot initialize until at least one gateway becomes available."; throw new SiloUnavailableException(message); } - this.logger.LogInformation( - (int)ErrorCode.GatewayManager_FoundKnownGateways, - "Found {GatewayCount} gateways: {Gateways}", - knownGateways.Count, - Utils.EnumerableToString(knownGateways)); + Log.FoundKnownGateways(this.logger, knownGateways.Count, Utils.EnumerableToString(knownGateways)); this.roundRobinCounter = this.gatewayOptions.PreferredGatewayIndex >= 0 ? this.gatewayOptions.PreferredGatewayIndex : Random.Shared.Next(knownGateways.Count); var newGateways = new List(); @@ -194,7 +214,7 @@ public List GetLiveGateways() { if (cachedLiveGateways.Count == 0 && knownGateways.Count > 0) { - this.logger.LogWarning("All known gateways have been marked dead locally. Expediting gateway refresh and resetting all gateways to live status."); + Log.AllKnownGatewaysMarkedDead(this.logger); cachedLiveGateways = knownGateways; cachedLiveGatewaysSet = new HashSet(knownGateways); @@ -267,7 +287,7 @@ private async Task RefreshGatewaySnapshot() } catch (Exception exc) { - logger.LogError((int)ErrorCode.ProxyClient_GetGateways, exc, "Error refreshing gateways."); + Log.ErrorRefreshingGateways(this.logger, exc); } } @@ -326,9 +346,7 @@ private async Task UpdateLiveGatewaysSnapshot(IEnumerable refreshed if (live.Count == 0) { - logger.LogWarning( - (int)ErrorCode.GatewayManager_AllGatewaysDead, - "All gateways have previously been marked as dead. Clearing the list of dead gateways to expedite reconnection."); + Log.AllGatewaysDead(this.logger); live.AddRange(knownGateways); knownDead.Clear(); } @@ -339,17 +357,7 @@ private async Task UpdateLiveGatewaysSnapshot(IEnumerable refreshed DateTime prevRefresh = lastRefreshTime; lastRefreshTime = now; - if (logger.IsEnabled(LogLevel.Debug)) - { - logger.LogDebug( - (int)ErrorCode.GatewayManager_FoundKnownGateways, - "Refreshed the live gateway list. Found {KnownGatewayCount} gateways from gateway list provider: {KnownGateways}. Picked only known live out of them. Now has {LiveGatewayCount} live gateways: {LiveGateways}. Previous refresh time was = {PreviousRefreshTime}", - knownGateways.Count, - Utils.EnumerableToString(knownGateways), - cachedLiveGateways.Count, - Utils.EnumerableToString(cachedLiveGateways), - prevRefresh); - } + Log.RefreshedLiveGatewayList(this.logger, knownGateways.Count, Utils.EnumerableToString(knownGateways), cachedLiveGateways.Count, Utils.EnumerableToString(cachedLiveGateways), prevRefresh); // Close connections to known dead connections, but keep the "masked" ones. // Client will not send any new request to the "masked" connections, but might still @@ -380,10 +388,7 @@ private async Task CloseEvictedGatewayConnections(List liveGateways if (!isLiveGateway) { - if (logger.IsEnabled(LogLevel.Information)) - { - this.logger.LogInformation("Closing connection to {Endpoint} because it has been marked as dead", address); - } + Log.ClosingConnection(this.logger, address); await this.connectionManager.CloseAsync(address); } @@ -395,4 +400,4 @@ public void Dispose() this.gatewayRefreshTimer.Dispose(); } } -} \ No newline at end of file +} diff --git a/src/Orleans.Core/Runtime/InvokableObjectManager.cs b/src/Orleans.Core/Runtime/InvokableObjectManager.cs index 48f752750f..fdec67aa1a 100644 --- a/src/Orleans.Core/Runtime/InvokableObjectManager.cs +++ b/src/Orleans.Core/Runtime/InvokableObjectManager.cs @@ -28,6 +28,36 @@ internal class InvokableObjectManager : IDisposable private List GrainCallFilters => _grainCallFilters ??= new List(runtimeClient.ServiceProvider.GetServices()); + private static partial class Log + { + [LoggerMessage(1, LogLevel.Error, "Message is not addressed to an observer. {Message}")] + public static partial void MessageNotAddressedToObserver(ILogger logger, Message message); + + [LoggerMessage(2, LogLevel.Error, "Unexpected target grain in request: {TargetGrain}. Message: {Message}")] + public static partial void UnexpectedTargetGrain(ILogger logger, GrainId targetGrain, Message message); + + [LoggerMessage(3, LogLevel.Warning, "Object associated with Observer ID {ObserverId} has been garbage collected. Deleting object reference and unregistering it. Message = {Message}")] + public static partial void ObjectGarbageCollected(ILogger logger, ObserverGrainId observerId, Message message); + + [LoggerMessage(4, LogLevel.Trace, "InvokeLocalObjectAsync {Message} start {Start}")] + public static partial void InvokeLocalObjectAsync(ILogger logger, Message message, bool start); + + [LoggerMessage(5, LogLevel.Warning, "Exception during message body deserialization in LocalObjectMessagePumpAsync for message: {Message}")] + public static partial void MessageBodyDeserializationException(ILogger logger, Exception exception, Message message); + + [LoggerMessage(6, LogLevel.Warning, "Exception in LocalObjectMessagePumpAsync")] + public static partial void LocalObjectMessagePumpException(ILogger logger, Exception exception); + + [LoggerMessage(7, LogLevel.Warning, "Exception trying to send a response.")] + public static partial void SendResponseException(ILogger logger, Exception exception); + + [LoggerMessage(8, LogLevel.Error, "Exception during invocation of notification {Request}, interface {Interface}. Ignoring exception because this is a one way request.")] + public static partial void InvocationExceptionOneWay(ILogger logger, Exception exception, string request, int interfaceType); + + [LoggerMessage(9, LogLevel.Warning, "Exception trying to send an exception response")] + public static partial void SendExceptionResponseException(ILogger logger, Exception exception); + } + public InvokableObjectManager( IGrainContext rootGrainContext, IRuntimeClient runtimeClient, @@ -60,10 +90,7 @@ public void Dispatch(Message message) { if (!ObserverGrainId.TryParse(message.TargetGrain, out var observerId)) { - this.logger.LogError( - (int)ErrorCode.ProxyClient_OGC_TargetNotFound_2, - "Message is not addressed to an observer. {Message}", - message); + Log.MessageNotAddressedToObserver(this.logger, message); return; } @@ -73,11 +100,7 @@ public void Dispatch(Message message) } else { - this.logger.LogError( - (int)ErrorCode.ProxyClient_OGC_TargetNotFound, - "Unexpected target grain in request: {TargetGrain}. Message: {Message}", - message.TargetGrain, - message); + Log.UnexpectedTargetGrain(this.logger, message.TargetGrain, message); } } @@ -155,11 +178,7 @@ public void ReceiveMessage(object msg) if (obj == null) { //// Remove from the dictionary record for the garbage collected object? But now we won't be able to detect invalid dispatch IDs anymore. - _manager.logger.LogWarning( - (int)ErrorCode.Runtime_Error_100162, - "Object associated with Observer ID {ObserverId} has been garbage collected. Deleting object reference and unregistering it. Message = {message}", - this.ObserverId, - message); + Log.ObjectGarbageCollected(_manager.logger, this.ObserverId, message); // Try to remove. If it's not there, we don't care. _manager.TryDeregister(this.ObserverId); @@ -174,8 +193,7 @@ public void ReceiveMessage(object msg) this.Running = true; } - if (_manager.logger.IsEnabled(LogLevel.Trace)) - _manager.logger.LogTrace("InvokeLocalObjectAsync {Message} start {Start}", message, start); + Log.InvokeLocalObjectAsync(_manager.logger, message, start); if (start) { @@ -243,13 +261,7 @@ private async Task LocalObjectMessagePumpAsync() } catch (Exception deserializationException) { - if (_manager.logger.IsEnabled(LogLevel.Warning)) - { - _manager.logger.LogWarning( - deserializationException, - "Exception during message body deserialization in " + nameof(LocalObjectMessagePumpAsync) + " for message: {Message}", - message); - } + Log.MessageBodyDeserializationException(_manager.logger, deserializationException, message); _manager.runtimeClient.SendResponse(message, Response.FromException(deserializationException)); continue; @@ -285,9 +297,7 @@ private async Task LocalObjectMessagePumpAsync() catch (Exception outerException) { // ignore, keep looping. - _manager.logger.LogWarning( - outerException, - "Exception in " + nameof(LocalObjectMessagePumpAsync)); + Log.LocalObjectMessagePumpException(_manager.logger, outerException); } } } @@ -310,7 +320,7 @@ private void SendResponseAsync(Message message, Response resultObject) catch (Exception exc2) { _manager.runtimeClient.SendResponse(message, Response.FromException(exc2)); - _manager.logger.LogWarning((int)ErrorCode.ProxyClient_OGC_SendResponseFailed, exc2, "Exception trying to send a response."); + Log.SendResponseException(_manager.logger, exc2); return; } @@ -327,12 +337,7 @@ private void ReportException(Message message, Exception exception) { case Message.Directions.OneWay: { - _manager.logger.LogError( - (int)ErrorCode.ProxyClient_OGC_UnhandledExceptionInOneWayInvoke, - exception, - "Exception during invocation of notification {Request}, interface {Interface}. Ignoring exception because this is a one way request.", - request.ToString(), - message.InterfaceType); + Log.InvocationExceptionOneWay(_manager.logger, exception, request.ToString(), message.InterfaceType); break; } @@ -347,10 +352,7 @@ private void ReportException(Message message, Exception exception) catch (Exception ex2) { _manager.runtimeClient.SendResponse(message, Response.FromException(ex2)); - _manager.logger.LogWarning( - (int)ErrorCode.ProxyClient_OGC_SendExceptionResponseFailed, - ex2, - "Exception trying to send an exception response"); + Log.SendExceptionResponseException(_manager.logger, ex2); return; } diff --git a/src/Orleans.Core/Runtime/OutsideRuntimeClient.cs b/src/Orleans.Core/Runtime/OutsideRuntimeClient.cs index 29d536db26..94ec94126c 100644 --- a/src/Orleans.Core/Runtime/OutsideRuntimeClient.cs +++ b/src/Orleans.Core/Runtime/OutsideRuntimeClient.cs @@ -490,4 +490,4 @@ private void ThrowIfDisposed() void ThrowObjectDisposedException() => throw new ObjectDisposedException(nameof(OutsideRuntimeClient)); } } -} \ No newline at end of file +} diff --git a/src/Orleans.Runtime/Catalog/ActivationMigrationManager.cs b/src/Orleans.Runtime/Catalog/ActivationMigrationManager.cs index 0d78691503..8a6e5fb635 100644 --- a/src/Orleans.Runtime/Catalog/ActivationMigrationManager.cs +++ b/src/Orleans.Runtime/Catalog/ActivationMigrationManager.cs @@ -153,10 +153,7 @@ private async Task ProcessMembershipUpdates() try { - if (_logger.IsEnabled(LogLevel.Debug)) - { - _logger.LogDebug("Monitoring cluster membership updates"); - } + Log.MonitoringClusterMembershipUpdates(_logger); var previousSnapshot = _clusterMembershipService.CurrentSnapshot; await foreach (var snapshot in _clusterMembershipService.MembershipUpdates) @@ -175,16 +172,13 @@ private async Task ProcessMembershipUpdates() } catch (Exception exception) { - _logger.LogError(exception, "Error processing cluster membership updates"); + Log.ErrorProcessingClusterMembershipUpdates(_logger, exception); } } } finally { - if (_logger.IsEnabled(LogLevel.Debug)) - { - _logger.LogDebug("No longer monitoring cluster membership updates"); - } + Log.NoLongerMonitoringClusterMembershipUpdates(_logger); } } @@ -195,10 +189,7 @@ private async Task PumpMigrationQueue(SiloAddress targetSilo, Channel(Constants.ActivationMigratorType, targetSilo); await Task.Yield(); - if (_logger.IsEnabled(LogLevel.Debug)) - { - _logger.LogDebug("Starting migration worker for target silo {SiloAddress}", targetSilo); - } + Log.StartingMigrationWorker(_logger, targetSilo); var items = new List(); var batch = new List(); @@ -222,16 +213,13 @@ private async Task PumpMigrationQueue(SiloAddress targetSilo, Channel.Participate(ISiloLifecycle lifecycle) { lifecycle.Subscribe("HostedClient", ServiceLifecycleStage.RuntimeGrainServices, OnStart, OnStop); @@ -399,4 +411,4 @@ public void Migrate(Dictionary? requestContext, CancellationToke // Migration is not supported. Do nothing: the contract is that this method attempts migration, but does not guarantee it will occur. } } -} \ No newline at end of file +} diff --git a/src/Orleans.Runtime/GrainDirectory/GrainDirectoryPartition.cs b/src/Orleans.Runtime/GrainDirectory/GrainDirectoryPartition.cs index cb8b81de52..fcaf722655 100644 --- a/src/Orleans.Runtime/GrainDirectory/GrainDirectoryPartition.cs +++ b/src/Orleans.Runtime/GrainDirectory/GrainDirectoryPartition.cs @@ -81,7 +81,7 @@ public async ValueTask RefreshViewAsync(MembershipV { if (_logger.IsEnabled(LogLevel.Trace)) { - _logger.LogTrace("GetSnapshotAsync('{Version}', '{RangeVersion}', '{Range}')", version, rangeVersion, range); + Log.GetSnapshotAsync(_logger, version, rangeVersion, range); } // Wait for the range to be unlocked. @@ -108,13 +108,13 @@ public async ValueTask RefreshViewAsync(MembershipV var rangeSnapshot = new GrainDirectoryPartitionSnapshot(rangeVersion, partitionAddresses); if (_logger.IsEnabled(LogLevel.Debug)) { - _logger.LogDebug("Transferring '{Count}' entries in range '{Range}' from version '{Version}' snapshot.", partitionAddresses.Count, range, rangeVersion); + Log.TransferringEntries(_logger, partitionAddresses.Count, range, rangeVersion); } return rangeSnapshot; } - _logger.LogWarning("Received a request for a snapshot which this partition does not have, version '{Version}', range version '{RangeVersion}', range '{Range}'.", version, rangeVersion, range); + Log.ReceivedRequestForSnapshot(_logger, version, rangeVersion, range); return null; } @@ -146,7 +146,7 @@ private void RemoveSnapshotTransferPartner(TState state, Func s.DirectoryMembershipVersion))); + Log.RemovingSnapshot(_logger, partitionSnapshot.DirectoryMembershipVersion, string.Join(", ", _partitionSnapshots.Select(s => s.DirectoryMembershipVersion))); } // If shutdown has been requested and there are no more pending snapshots, signal completion. @@ -264,7 +264,7 @@ private void OnSiloRemovedFromCluster(ClusterMember change) { if (_logger.IsEnabled(LogLevel.Debug)) { - _logger.LogDebug("Deleting '{Count}' entries located on now-defunct silo '{SiloAddress}'.", toRemove.Count, change.SiloAddress); + Log.DeletingEntries(_logger, toRemove.Count, change.SiloAddress); } foreach (var grainAddress in toRemove) @@ -295,7 +295,7 @@ internal Task OnRecoveringPartition(MembershipVersion version, RingRange range, } catch (Exception exception) { - _logger.LogWarning(exception, "Error waiting for range to unlock."); + Log.ErrorWaitingForRange(_logger, exception); } // Remove all snapshots that are associated with the given partition prior or equal to the specified version. @@ -319,7 +319,7 @@ private void ProcessMembershipUpdate(DirectoryMembershipSnapshot current) if (_logger.IsEnabled(LogLevel.Trace)) { - _logger.LogTrace("Observed membership version '{Version}'.", current.Version); + Log.ObservedMembershipVersion(_logger, current.Version); } var previous = CurrentView; @@ -364,7 +364,7 @@ private async Task ReleaseRangeAsync(DirectoryMembershipSnapshot previous, Direc var (tcs, sw) = LockRange(removedRange, current.Version); if (_logger.IsEnabled(LogLevel.Debug)) { - _logger.LogDebug("Relinquishing ownership of range '{Range}' at version '{Version}'.", removedRange, current.Version); + Log.RelinquishingOwnership(_logger, removedRange, current.Version); } try @@ -414,7 +414,7 @@ private async Task ReleaseRangeAsync(DirectoryMembershipSnapshot previous, Direc { if (_logger.IsEnabled(LogLevel.Debug)) { - _logger.LogDebug("Encountered non-contiguous update from '{Previous}' to '{Current}' while releasing range '{Range}'. Dropping snapshot.", previous.Version, current.Version, removedRange); + Log.EncounteredNonContiguousUpdate(_logger, previous.Version, current.Version, removedRange); } return; @@ -424,7 +424,7 @@ private async Task ReleaseRangeAsync(DirectoryMembershipSnapshot previous, Direc { if (_logger.IsEnabled(LogLevel.Debug)) { - _logger.LogDebug("No transfer partners for snapshot of range '{Range}' at version '{Version}'. Dropping snapshot.", removedRange, current.Version); + Log.NoTransferPartners(_logger, removedRange, current.Version); } return; @@ -450,7 +450,7 @@ private async Task AcquireRangeAsync(DirectoryMembershipSnapshot previous, Direc CoarseStopwatch stopwatch = default; if (_logger.IsEnabled(LogLevel.Debug)) { - _logger.LogDebug("Acquiring range '{Range}'.", addedRange); + Log.AcquiringRange(_logger, addedRange); stopwatch = CoarseStopwatch.StartNew(); } @@ -489,10 +489,7 @@ private async Task AcquireRangeAsync(DirectoryMembershipSnapshot previous, Direc { if (_logger.IsEnabled(LogLevel.Debug)) { - _logger.LogDebug( - "Non-contiguous view change detected: '{PreviousVersion}' to '{CurrentVersion}'. Performing recovery.", - previous.Version, - current.Version); + Log.NonContiguousViewChange(_logger, previous.Version, current.Version, addedRange); } success = false; @@ -510,7 +507,7 @@ private async Task AcquireRangeAsync(DirectoryMembershipSnapshot previous, Direc if (_logger.IsEnabled(LogLevel.Debug)) { - _logger.LogDebug("Completed transferring entries for range '{Range}' at version '{Version}' took {Elapsed}ms.{Recovered}", addedRange, current.Version, stopwatch.ElapsedMilliseconds, recovered ? " Recovered" : ""); + Log.CompletedTransferringEntries(_logger, addedRange, current.Version, stopwatch.ElapsedMilliseconds, recovered); } } finally @@ -548,7 +545,7 @@ private async Task TransferSnapshotAsync(DirectoryMembershipSnapshot curre var stopwatch = ValueStopwatch.StartNew(); if (_logger.IsEnabled(LogLevel.Trace)) { - _logger.LogTrace("Requesting entries for ranges '{Range}' from '{PreviousOwner}' at version '{PreviousVersion}'.", addedRange, previousOwner, previousVersion); + Log.RequestingEntries(_logger, addedRange, previousOwner, previousVersion); } var partition = GetPartitionReference(previousOwner, partitionIndex); @@ -558,7 +555,7 @@ private async Task TransferSnapshotAsync(DirectoryMembershipSnapshot curre if (snapshot is null) { - _logger.LogWarning("Expected a valid snapshot from previous owner '{PreviousOwner}' for part of ranges '{Range}', but found none.", previousOwner, addedRange); + Log.ExpectedValidSnapshot(_logger, previousOwner, addedRange); return false; } @@ -577,13 +574,13 @@ private async Task TransferSnapshotAsync(DirectoryMembershipSnapshot curre { DebugAssertOwnership(current, entry.GrainId); - _logger.LogTrace("Received '{Entry}' via snapshot from '{PreviousOwner}' for version '{Version}'.", entry, previousOwner, previousVersion); + Log.ReceivedEntryViaSnapshot(_logger, entry, previousOwner, previousVersion); _directory[entry.GrainId] = entry; } if (_logger.IsEnabled(LogLevel.Debug)) { - _logger.LogDebug("Transferred '{Count}' entries for range '{Range}' from '{PreviousOwner}'.", snapshot.GrainAddresses.Count, addedRange, previousOwner); + Log.TransferredEntries(_logger, snapshot.GrainAddresses.Count, addedRange, previousOwner); } DirectoryInstruments.SnapshotTransferCount.Add(1); @@ -595,11 +592,11 @@ private async Task TransferSnapshotAsync(DirectoryMembershipSnapshot curre { if (exception is SiloUnavailableException) { - _logger.LogWarning("Remote host became unavailable while transferring ownership of range '{Range}'. Recovery will be performed.", addedRange); + Log.RemoteHostUnavailable(_logger, addedRange); } else { - _logger.LogWarning(exception, "Error transferring ownership of range '{Range}'. Recovery will be performed.", addedRange); + Log.ErrorTransferringOwnership(_logger, exception, addedRange); } return false; @@ -612,7 +609,7 @@ private async Task RecoverPartitionRange(DirectoryMembershipSnapshot current, Ri GrainRuntime.CheckRuntimeContext(this); if (_logger.IsEnabled(LogLevel.Debug)) { - _logger.LogDebug("Recovering activations from range '{Range}' at version '{Version}'.", addedRange, current.Version); + Log.RecoveringActivations(_logger, addedRange, current.Version); } await foreach (var activations in GetRegisteredActivations(current, addedRange, isValidation: false)) @@ -621,7 +618,7 @@ private async Task RecoverPartitionRange(DirectoryMembershipSnapshot current, Ri foreach (var entry in activations) { DebugAssertOwnership(current, entry.GrainId); - _logger.LogTrace("Recovered '{Entry}' for version '{Version}'.", entry, current.Version); + Log.RecoveredEntry(_logger, entry, current.Version); _directory[entry.GrainId] = entry; } } @@ -630,7 +627,7 @@ private async Task RecoverPartitionRange(DirectoryMembershipSnapshot current, Ri DirectoryInstruments.RangeRecoveryDuration.Record((long)stopwatch.Elapsed.TotalMilliseconds); if (_logger.IsEnabled(LogLevel.Debug)) { - _logger.LogDebug("Completed recovering activations from range '{Range}' at version '{Version}' took '{Elapsed}'.", addedRange, current.Version, stopwatch.Elapsed); + Log.CompletedRecoveringActivations(_logger, addedRange, current.Version, stopwatch.Elapsed); } } @@ -688,7 +685,7 @@ async Task> GetRegisteredActivationsFromClusterMember(Members if (_logger.IsEnabled(LogLevel.Debug)) { - _logger.LogDebug("Recovered '{Count}' entries from silo '{SiloAddress}' for ranges '{Range}' at version '{Version}' in {ElapsedMilliseconds}ms.", result.Value.Count, siloAddress, range, version, stopwatch.Elapsed.TotalMilliseconds); + Log.RecoveredEntries(_logger, result.Value.Count, siloAddress, range, version, stopwatch.Elapsed.TotalMilliseconds); } return result.Value; @@ -714,7 +711,7 @@ private async Task InvokeOnClusterMember(SiloAddress siloAddress, Func GrainAddresses, HashSet<(SiloAddress SiloAddress, int PartitionIndex)> TransferPartners); + + private static partial class Log + { + [LoggerMessage(1, LogLevel.Trace, "GetSnapshotAsync('{Version}', '{RangeVersion}', '{Range}')")] + public static partial void GetSnapshotAsync(ILogger logger, MembershipVersion version, MembershipVersion rangeVersion, RingRange range); + + [LoggerMessage(2, LogLevel.Debug, "Transferring '{Count}' entries in range '{Range}' from version '{Version}' snapshot.")] + public static partial void TransferringEntries(ILogger logger, int count, RingRange range, MembershipVersion version); + + [LoggerMessage(3, LogLevel.Warning, "Received a request for a snapshot which this partition does not have, version '{Version}', range version '{RangeVersion}', range '{Range}'.")] + public static partial void ReceivedRequestForSnapshot(ILogger logger, MembershipVersion version, MembershipVersion rangeVersion, RingRange range); + + [LoggerMessage(4, LogLevel.Debug, "Removing version '{Version}' snapshot. Current snapshots: [{CurrentSnapshots}].")] + public static partial void RemovingSnapshot(ILogger logger, MembershipVersion version, string currentSnapshots); + + [LoggerMessage(5, LogLevel.Debug, "Deleting '{Count}' entries located on now-defunct silo '{SiloAddress}'.")] + public static partial void DeletingEntries(ILogger logger, int count, SiloAddress siloAddress); + + [LoggerMessage(6, LogLevel.Warning, "Error waiting for range to unlock.")] + public static partial void ErrorWaitingForRange(ILogger logger, Exception exception); + + [LoggerMessage(7, LogLevel.Trace, "Observed membership version '{Version}'.")] + public static partial void ObservedMembershipVersion(ILogger logger, MembershipVersion version); + + [LoggerMessage(8, LogLevel.Debug, "Relinquishing ownership of range '{Range}' at version '{Version}'.")] + public static partial void RelinquishingOwnership(ILogger logger, RingRange range, MembershipVersion version); + + [LoggerMessage(9, LogLevel.Debug, "Encountered non-contiguous update from '{Previous}' to '{Current}' while releasing range '{Range}'. Dropping snapshot.")] + public static partial void EncounteredNonContiguousUpdate(ILogger logger, MembershipVersion previous, MembershipVersion current, RingRange range); + + [LoggerMessage(10, LogLevel.Debug, "No transfer partners for snapshot of range '{Range}' at version '{Version}'. Dropping snapshot.")] + public static partial void NoTransferPartners(ILogger logger, RingRange range, MembershipVersion version); + + [LoggerMessage(11, LogLevel.Debug, "Acquiring range '{Range}'.")] + public static partial void AcquiringRange(ILogger logger, RingRange range); + + [LoggerMessage(12, LogLevel.Debug, "Non-contiguous view change detected: '{PreviousVersion}' to '{CurrentVersion}'. Performing recovery.")] + public static partial void NonContiguousViewChange(ILogger logger, MembershipVersion previousVersion, MembershipVersion currentVersion, RingRange range); + + [LoggerMessage(13, LogLevel.Debug, "Completed transferring entries for range '{Range}' at version '{Version}' took {Elapsed}ms.{Recovered}")] + public static partial void CompletedTransferringEntries(ILogger logger, RingRange range, MembershipVersion version, long elapsed, bool recovered); + + [LoggerMessage(14, LogLevel.Trace, "Requesting entries for ranges '{Range}' from '{PreviousOwner}' at version '{PreviousVersion}'.")] + public static partial void RequestingEntries(ILogger logger, RingRange range, SiloAddress previousOwner, MembershipVersion previousVersion); + + [LoggerMessage(15, LogLevel.Warning, "Expected a valid snapshot from previous owner '{PreviousOwner}' for part of ranges '{Range}', but found none.")] + public static partial void ExpectedValidSnapshot(ILogger logger, SiloAddress previousOwner, RingRange range); + + [LoggerMessage(16, LogLevel.Trace, "Received '{Entry}' via snapshot from '{PreviousOwner}' for version '{Version}'.")] + public static partial void ReceivedEntryViaSnapshot(ILogger logger, GrainAddress entry, SiloAddress previousOwner, MembershipVersion version); + + [LoggerMessage(17, LogLevel.Debug, "Transferred '{Count}' entries for range '{Range}' from '{PreviousOwner}'.")] + public static partial void TransferredEntries(ILogger logger, int count, RingRange range, SiloAddress previousOwner); + + [LoggerMessage(18, LogLevel.Warning, "Remote host became unavailable while transferring ownership of range '{Range}'. Recovery will be performed.")] + public static partial void RemoteHostUnavailable(ILogger logger, RingRange range); + + [LoggerMessage(19, LogLevel.Warning, "Error transferring ownership of range '{Range}'. Recovery will be performed.")] + public static partial void ErrorTransferringOwnership(ILogger logger, Exception exception, RingRange range); + + [LoggerMessage(20, LogLevel.Debug, "Recovering activations from range '{Range}' at version '{Version}'.")] + public static partial void RecoveringActivations(ILogger logger, RingRange range, MembershipVersion version); + + [LoggerMessage(21, LogLevel.Trace, "Recovered '{Entry}' for version '{Version}'.")] + public static partial void RecoveredEntry(ILogger logger, GrainAddress entry, MembershipVersion version); + + [LoggerMessage(22, LogLevel.Debug, "Completed recovering activations from range '{Range}' at version '{Version}' took '{Elapsed}'.")] + public static partial void CompletedRecoveringActivations(ILogger logger, RingRange range, MembershipVersion version, TimeSpan elapsed); + + [LoggerMessage(23, LogLevel.Debug, "Recovered '{Count}' entries from silo '{SiloAddress}' for ranges '{Range}' at version '{Version}' in {ElapsedMilliseconds}ms.")] + public static partial void RecoveredEntries(ILogger logger, int count, SiloAddress siloAddress, RingRange range, MembershipVersion version, long elapsedMilliseconds); + + [LoggerMessage(24, LogLevel.Error, "Error invoking operation '{Operation}' on silo '{SiloAddress}'.")] + public static partial void ErrorInvokingOperation(ILogger logger, Exception exception, string operation, SiloAddress siloAddress); + + [LoggerMessage(25, LogLevel.Error, "Integrity violation: Recovered entry '{RecoveredRecord}' does not match existing entry '{LocalRecord}'.")] + public static partial void IntegrityViolationRecoveredEntry(ILogger logger, GrainAddress recoveredRecord, GrainAddress localRecord); + + [LoggerMessage(26, LogLevel.Error, "Integrity violation: Recovered entry '{RecoveredRecord}' not found in directory.")] + public static partial void IntegrityViolationRecoveredEntryNotFound(ILogger logger, GrainAddress recoveredRecord); + } } diff --git a/src/Orleans.Runtime/Hosting/EndpointOptionsProvider.cs b/src/Orleans.Runtime/Hosting/EndpointOptionsProvider.cs index 2a66350eaf..2c2c5b49d0 100644 --- a/src/Orleans.Runtime/Hosting/EndpointOptionsProvider.cs +++ b/src/Orleans.Runtime/Hosting/EndpointOptionsProvider.cs @@ -16,6 +16,15 @@ public EndpointOptionsProvider(ILogger logger) this.logger = logger; } + private static partial class Log + { + [LoggerMessage(1, LogLevel.Warning, "Unable to find a suitable candidate for {OptionName}.{AdvertisedIPAddress}. Falling back to {IPAddressLoopback} ({AdvertisedIPAddress})")] + public static partial void UnableToFindSuitableCandidate(ILogger logger, string optionName, string advertisedIPAddress, string ipAddressLoopback); + + [LoggerMessage(2, LogLevel.Error, "Unable to find a suitable candidate for {OptionName}.{AdvertisedIPAddress}. Falling back to {IPAddressLoopback} ({AdvertisedIPAddress})")] + public static partial void UnableToFindSuitableCandidateError(ILogger logger, Exception exception, string optionName, string advertisedIPAddress, string ipAddressLoopback); + } + public void PostConfigure(string name, EndpointOptions options) { if (options.AdvertisedIPAddress is null) @@ -28,12 +37,7 @@ public void PostConfigure(string name, EndpointOptions options) if (resolvedIP is null) { - if (logger.IsEnabled(LogLevel.Warning)) - { - logger.LogWarning( - $"Unable to find a suitable candidate for {nameof(EndpointOptions)}.{nameof(options.AdvertisedIPAddress)}. Falling back to {nameof(IPAddress.Loopback)} ({{AdvertisedIPAddress}})", - advertisedIPAddress); - } + Log.UnableToFindSuitableCandidate(logger, nameof(EndpointOptions), nameof(options.AdvertisedIPAddress), nameof(IPAddress.Loopback), advertisedIPAddress.ToString()); } else { @@ -42,13 +46,7 @@ public void PostConfigure(string name, EndpointOptions options) } catch (Exception ex) { - if (logger.IsEnabled(LogLevel.Error)) - { - logger.LogError( - ex, - $"Unable to find a suitable candidate for {nameof(EndpointOptions)}.{nameof(options.AdvertisedIPAddress)}. Falling back to {nameof(IPAddress.Loopback)} ({{AdvertisedIPAddress}})", - advertisedIPAddress); - } + Log.UnableToFindSuitableCandidateError(logger, ex, nameof(EndpointOptions), nameof(options.AdvertisedIPAddress), nameof(IPAddress.Loopback), advertisedIPAddress.ToString()); } options.AdvertisedIPAddress = advertisedIPAddress; diff --git a/src/Orleans.Runtime/Lifecycle/SiloLifecycleSubject.cs b/src/Orleans.Runtime/Lifecycle/SiloLifecycleSubject.cs index 99319b92c4..fbc373a801 100644 --- a/src/Orleans.Runtime/Lifecycle/SiloLifecycleSubject.cs +++ b/src/Orleans.Runtime/Lifecycle/SiloLifecycleSubject.cs @@ -77,27 +77,13 @@ protected override string GetStageName(int stage) /// protected override void PerfMeasureOnStop(int stage, TimeSpan elapsed) { - if (this.Logger.IsEnabled(LogLevel.Debug)) - { - this.Logger.LogDebug( - (int)ErrorCode.SiloStartPerfMeasure, - "Stopping lifecycle stage '{Stage}' took '{Elapsed}'.", - this.GetStageName(stage), - elapsed); - } + SiloLifecycleSubjectLoggerMessages.PerfMeasureOnStop(this.Logger, this.GetStageName(stage), elapsed); } /// protected override void PerfMeasureOnStart(int stage, TimeSpan elapsed) { - if (this.Logger.IsEnabled(LogLevel.Debug)) - { - this.Logger.LogDebug( - (int)ErrorCode.SiloStartPerfMeasure, - "Starting lifecycle stage '{Stage}' took '{Elapsed}'", - this.GetStageName(stage), - elapsed); - } + SiloLifecycleSubjectLoggerMessages.PerfMeasureOnStart(this.Logger, this.GetStageName(stage), elapsed); } /// @@ -133,24 +119,11 @@ public async Task OnStart(CancellationToken ct) var stopwatch = ValueStopwatch.StartNew(); await this.observer.OnStart(ct); stopwatch.Stop(); - if (this.logger.IsEnabled(LogLevel.Debug)) - { - this.logger.LogDebug( - (int)ErrorCode.SiloStartPerfMeasure, - "'{Name}' started in stage '{Stage}' in '{Elapsed}'.", - this.Name, - this.StageName, - stopwatch.Elapsed); - } + SiloLifecycleSubjectLoggerMessages.MonitoredObserverOnStart(this.logger, this.Name, this.StageName, stopwatch.Elapsed); } catch (Exception exception) { - this.logger.LogError( - (int)ErrorCode.LifecycleStartFailure, - exception, - "'{Name}' failed to start due to errors at stage '{Stage}'.", - this.Name, - this.StageName); + SiloLifecycleSubjectLoggerMessages.MonitoredObserverOnStartError(this.logger, exception, this.Name, this.StageName); throw; } } @@ -160,48 +133,51 @@ public async Task OnStop(CancellationToken cancellationToken = default) var stopwatch = ValueStopwatch.StartNew(); try { - if (this.logger.IsEnabled(LogLevel.Debug)) - { - this.logger.LogDebug( - (int)ErrorCode.SiloStartPerfMeasure, - "'{Name}' stopping in stage '{Stage}'.", - this.Name, - this.StageName); - } - + SiloLifecycleSubjectLoggerMessages.MonitoredObserverOnStop(this.logger, this.Name, this.StageName); await this.observer.OnStop(cancellationToken); stopwatch.Stop(); if (stopwatch.Elapsed > TimeSpan.FromSeconds(1)) { - this.logger.LogWarning( - (int)ErrorCode.SiloStartPerfMeasure, - "'{Name}' stopped in stage '{Stage}' in '{Elapsed}'.", - this.Name, - this.StageName, - stopwatch.Elapsed); + SiloLifecycleSubjectLoggerMessages.MonitoredObserverOnStopWarning(this.logger, this.Name, this.StageName, stopwatch.Elapsed); } - else if (this.logger.IsEnabled(LogLevel.Debug)) + else { - this.logger.LogDebug( - (int)ErrorCode.SiloStartPerfMeasure, - "'{Name}' stopped in stage '{Stage}' in '{Elapsed}'.", - this.Name, - this.StageName, - stopwatch.Elapsed); + SiloLifecycleSubjectLoggerMessages.MonitoredObserverOnStopDebug(this.logger, this.Name, this.StageName, stopwatch.Elapsed); } } catch (Exception exception) { - this.logger.LogError( - (int)ErrorCode.LifecycleStartFailure, - exception, - "'{Name}' failed to stop due to errors at stage '{Stage}' after '{Elapsed}'.", - this.Name, - this.StageName, - stopwatch.Elapsed); + SiloLifecycleSubjectLoggerMessages.MonitoredObserverOnStopError(this.logger, exception, this.Name, this.StageName, stopwatch.Elapsed); throw; } } } } + + internal static partial class SiloLifecycleSubjectLoggerMessages + { + [LoggerMessage(1, LogLevel.Debug, "Stopping lifecycle stage '{Stage}' took '{Elapsed}'.")] + public static partial void PerfMeasureOnStop(ILogger logger, string Stage, TimeSpan Elapsed); + + [LoggerMessage(2, LogLevel.Debug, "Starting lifecycle stage '{Stage}' took '{Elapsed}'")] + public static partial void PerfMeasureOnStart(ILogger logger, string Stage, TimeSpan Elapsed); + + [LoggerMessage(3, LogLevel.Debug, "'{Name}' started in stage '{Stage}' in '{Elapsed}'.")] + public static partial void MonitoredObserverOnStart(ILogger logger, string Name, string Stage, TimeSpan Elapsed); + + [LoggerMessage(4, LogLevel.Error, "'{Name}' failed to start due to errors at stage '{Stage}'.")] + public static partial void MonitoredObserverOnStartError(ILogger logger, Exception exception, string Name, string Stage); + + [LoggerMessage(5, LogLevel.Debug, "'{Name}' stopping in stage '{Stage}'.")] + public static partial void MonitoredObserverOnStop(ILogger logger, string Name, string Stage); + + [LoggerMessage(6, LogLevel.Warning, "'{Name}' stopped in stage '{Stage}' in '{Elapsed}'.")] + public static partial void MonitoredObserverOnStopWarning(ILogger logger, string Name, string Stage, TimeSpan Elapsed); + + [LoggerMessage(7, LogLevel.Debug, "'{Name}' stopped in stage '{Stage}' in '{Elapsed}'.")] + public static partial void MonitoredObserverOnStopDebug(ILogger logger, string Name, string Stage, TimeSpan Elapsed); + + [LoggerMessage(8, LogLevel.Error, "'{Name}' failed to stop due to errors at stage '{Stage}' after '{Elapsed}'.")] + public static partial void MonitoredObserverOnStopError(ILogger logger, Exception exception, string Name, string Stage, TimeSpan Elapsed); + } } diff --git a/src/Orleans.Runtime/Manifest/ClusterManifestProvider.cs b/src/Orleans.Runtime/Manifest/ClusterManifestProvider.cs index 347c46ced4..4df029ed5c 100644 --- a/src/Orleans.Runtime/Manifest/ClusterManifestProvider.cs +++ b/src/Orleans.Runtime/Manifest/ClusterManifestProvider.cs @@ -56,10 +56,7 @@ private async Task ProcessMembershipUpdates() { try { - if (_logger.IsEnabled(LogLevel.Debug)) - { - _logger.LogDebug("Starting to process membership updates"); - } + Log.StartingToProcessMembershipUpdates(_logger); var cancellation = _cancellation.Token; await foreach (var _ in _clusterMembershipService.MembershipUpdates.WithCancellation(cancellation)) @@ -85,10 +82,7 @@ private async Task ProcessMembershipUpdates() } finally { - if (_logger.IsEnabled(LogLevel.Debug)) - { - _logger.LogDebug("Stopped processing membership updates"); - } + Log.StoppedProcessingMembershipUpdates(_logger); } } @@ -168,7 +162,7 @@ private async Task UpdateManifest(ClusterMembershipSnapshot clusterMembers if (result.Exception is Exception exception) { fetchSuccess = false; - _logger.LogWarning(exception, "Error retrieving silo manifest for silo {SiloAddress}", result.Key); + Log.ErrorRetrievingSiloManifest(_logger, exception, result.Key); } else { @@ -233,5 +227,17 @@ public void Dispose() { _cancellation.Cancel(); } + + private static partial class Log + { + [LoggerMessage(1, LogLevel.Debug, "Starting to process membership updates")] + public static partial void StartingToProcessMembershipUpdates(ILogger logger); + + [LoggerMessage(2, LogLevel.Debug, "Stopped processing membership updates")] + public static partial void StoppedProcessingMembershipUpdates(ILogger logger); + + [LoggerMessage(3, LogLevel.Warning, "Error retrieving silo manifest for silo {SiloAddress}")] + public static partial void ErrorRetrievingSiloManifest(ILogger logger, Exception exception, SiloAddress SiloAddress); + } } } diff --git a/src/Orleans.Runtime/Messaging/Gateway.cs b/src/Orleans.Runtime/Messaging/Gateway.cs index 62bf8bf04d..5e003ec9bc 100644 --- a/src/Orleans.Runtime/Messaging/Gateway.cs +++ b/src/Orleans.Runtime/Messaging/Gateway.cs @@ -79,7 +79,7 @@ private async Task PerformGatewayMaintenance() } catch (Exception exception) { - logger.LogError(exception, "Error performing gateway maintenance"); + LogErrorPerformingGatewayMaintenance(logger, exception); } } } @@ -122,7 +122,7 @@ List IConnectedClientCollection.GetConnectedClientIds() internal void RecordOpenedConnection(GatewayInboundConnection connection, ClientGrainId clientId) { - logger.LogInformation((int)ErrorCode.GatewayClientOpenedSocket, "Recorded opened connection from endpoint {EndPoint}, client ID {ClientId}.", connection.RemoteEndPoint, clientId); + LogRecordedOpenedConnection(logger, connection.RemoteEndPoint, clientId); lock (clients) { if (clients.TryGetValue(clientId, out var clientState)) @@ -159,11 +159,7 @@ internal void RecordClosedConnection(GatewayInboundConnection connection) clientsCollectionVersion++; } - logger.LogInformation( - (int)ErrorCode.GatewayClientClosedSocket, - "Recorded closed socket from endpoint {Endpoint}, client ID {clientId}.", - connection.RemoteEndPoint?.ToString() ?? "null", - clientState.Id); + LogRecordedClosedSocket(logger, connection.RemoteEndPoint?.ToString() ?? "null", clientState.Id); } internal SiloAddress TryToReroute(Message msg) @@ -230,14 +226,7 @@ internal void DropDisconnectedClients() { if (clients.TryGetValue(kv.Key, out var client) && client.ReadyToDrop()) { - if (logger.IsEnabled(LogLevel.Information)) - { - logger.LogInformation( - (int)ErrorCode.GatewayDroppingClient, - "Dropping client {ClientId}, {IdleDuration} after disconnect with no reconnect", - kv.Key, - client.DisconnectedSince); - } + LogDroppingClient(logger, kv.Key, client.DisconnectedSince); if (clients.TryRemove(kv.Key, out _)) { @@ -339,11 +328,7 @@ public void RecordConnection(GatewayInboundConnection connection) var existing = Interlocked.Exchange(ref _connection, connection); if (existing is not null) { - _gateway.logger.LogWarning( - "Client {ClientId} received new connection ({NewConnection}) before the previous connection ({PreviousConnection}) had been removed", - Id.GrainId, - connection, - existing); + LogClientReceivedNewConnection(_gateway.logger, Id.GrainId, connection, existing); } _disconnectedSince.Reset(); @@ -373,7 +358,7 @@ public void Send(Message msg) _pendingToSend.Enqueue(msg); _signal.Signal(); #if DEBUG - if (_gateway.logger.IsEnabled(LogLevel.Trace)) _gateway.logger.LogTrace("Queued message {Message} for client {TargetGrain}", msg, msg.TargetGrain); + LogQueuedMessageForClient(_gateway.logger, msg, msg.TargetGrain); #endif } @@ -403,7 +388,7 @@ private async Task RunMessageLoop() if (TrySend(connection, message)) { #if DEBUG - if (_gateway.logger.IsEnabled(LogLevel.Trace)) _gateway.logger.LogTrace("Sent queued message {Message} to client {ClientId}", message, Id); + LogSentQueuedMessageToClient(_gateway.logger, message, Id); #endif } else @@ -416,7 +401,7 @@ private async Task RunMessageLoop() } catch (Exception exception) { - _gateway.logger.LogWarning(exception, "Exception in message loop for client {ClientId}", Id); + LogExceptionInMessageLoop(_gateway.logger, exception, Id); } } } @@ -497,5 +482,29 @@ internal void DropExpiredEntries() } } } + + private static readonly Action LogErrorPerformingGatewayMaintenance = + LoggerMessage.Define(LogLevel.Error, new EventId((int)ErrorCode.GatewayMaintenanceError, nameof(ErrorCode.GatewayMaintenanceError)), "Error performing gateway maintenance"); + + private static readonly Action LogRecordedOpenedConnection = + LoggerMessage.Define(LogLevel.Information, new EventId((int)ErrorCode.GatewayClientOpenedSocket, nameof(ErrorCode.GatewayClientOpenedSocket)), "Recorded opened connection from endpoint {EndPoint}, client ID {ClientId}."); + + private static readonly Action LogRecordedClosedSocket = + LoggerMessage.Define(LogLevel.Information, new EventId((int)ErrorCode.GatewayClientClosedSocket, nameof(ErrorCode.GatewayClientClosedSocket)), "Recorded closed socket from endpoint {Endpoint}, client ID {clientId}."); + + private static readonly Action LogDroppingClient = + LoggerMessage.Define(LogLevel.Information, new EventId((int)ErrorCode.GatewayDroppingClient, nameof(ErrorCode.GatewayDroppingClient)), "Dropping client {ClientId}, {IdleDuration} after disconnect with no reconnect"); + + private static readonly Action LogClientReceivedNewConnection = + LoggerMessage.Define(LogLevel.Warning, new EventId((int)ErrorCode.GatewayClientReceivedNewConnection, nameof(ErrorCode.GatewayClientReceivedNewConnection)), "Client {ClientId} received new connection ({NewConnection}) before the previous connection ({PreviousConnection}) had been removed"); + + private static readonly Action LogQueuedMessageForClient = + LoggerMessage.Define(LogLevel.Trace, new EventId((int)ErrorCode.GatewayQueuedMessageForClient, nameof(ErrorCode.GatewayQueuedMessageForClient)), "Queued message {Message} for client {TargetGrain}"); + + private static readonly Action LogSentQueuedMessageToClient = + LoggerMessage.Define(LogLevel.Trace, new EventId((int)ErrorCode.GatewaySentQueuedMessageToClient, nameof(ErrorCode.GatewaySentQueuedMessageToClient)), "Sent queued message {Message} to client {ClientId}"); + + private static readonly Action LogExceptionInMessageLoop = + LoggerMessage.Define(LogLevel.Warning, new EventId((int)ErrorCode.GatewayExceptionInMessageLoop, nameof(ErrorCode.GatewayExceptionInMessageLoop)), "Exception in message loop for client {ClientId}"); } } diff --git a/src/Orleans.Runtime/Placement/PlacementService.cs b/src/Orleans.Runtime/Placement/PlacementService.cs index cd17709a05..756ab8848c 100644 --- a/src/Orleans.Runtime/Placement/PlacementService.cs +++ b/src/Orleans.Runtime/Placement/PlacementService.cs @@ -29,6 +29,24 @@ internal class PlacementService : IPlacementContext private readonly bool _assumeHomogeneousSilosForTesting; private readonly PlacementWorker[] _workers; + private static partial class Log + { + [LoggerMessage(1, LogLevel.Debug, "Found address {Address} for grain {GrainId} in cache for message {Message}")] + public static partial void FoundAddressInCache(ILogger logger, GrainAddress address, GrainId grainId, Message message); + + [LoggerMessage(2, LogLevel.Debug, "Looking up address for grain {GrainId} for message {Message}")] + public static partial void LookingUpAddress(ILogger logger, GrainId grainId, Message message); + + [LoggerMessage(3, LogLevel.Warning, "AllActiveSilos SiloStatusOracle.GetApproximateSiloStatuses empty")] + public static partial void AllActiveSilosEmpty(ILogger logger); + + [LoggerMessage(4, LogLevel.Debug, "Invalidating {Count} cached entries for message {Message}")] + public static partial void InvalidatingCachedEntries(ILogger logger, int count, Message message); + + [LoggerMessage(5, LogLevel.Warning, "Error in placement worker.")] + public static partial void PlacementWorkerError(ILogger logger, Exception exception); + } + /// /// Create a instance. /// @@ -74,19 +92,12 @@ public Task AddressMessage(Message message) var grainId = message.TargetGrain; if (_grainLocator.TryLookupInCache(grainId, out var result) && CachedAddressIsValid(message, result)) { - if (_logger.IsEnabled(LogLevel.Debug)) - { - _logger.LogDebug("Found address {Address} for grain {GrainId} in cache for message {Message}", result, grainId, message); - } - + Log.FoundAddressInCache(_logger, result, grainId, message); SetMessageTargetPlacement(message, result.SiloAddress); return Task.CompletedTask; } - if (_logger.IsEnabled(LogLevel.Debug)) - { - _logger.LogDebug("Looking up address for grain {GrainId} for message {Message}", grainId, message); - } + Log.LookingUpAddress(_logger, grainId, message); var worker = _workers[grainId.GetUniformHashCode() % PlacementWorkerCount]; return worker.AddressMessage(message); @@ -139,7 +150,7 @@ public SiloAddress[] AllActiveSilos var result = _siloStatusOracle.GetApproximateSiloStatuses(true).Keys.ToArray(); if (result.Length > 0) return result; - _logger.LogWarning((int)ErrorCode.Catalog_GetApproximateSiloStatuses, "AllActiveSilos SiloStatusOracle.GetApproximateSiloStatuses empty"); + Log.AllActiveSilosEmpty(_logger); return new SiloAddress[] { LocalSilo }; } } @@ -173,10 +184,7 @@ private bool CachedAddressIsValid(Message message, GrainAddress cachedAddress) bool CachedAddressIsValidCore(Message message, GrainAddress cachedAddress, List cacheUpdates) { var resultIsValid = true; - if (_logger.IsEnabled(LogLevel.Debug)) - { - _logger.LogDebug("Invalidating {Count} cached entries for message {Message}", cacheUpdates.Count, message); - } + Log.InvalidatingCachedEntries(_logger, cacheUpdates.Count, message); foreach (var update in cacheUpdates) { @@ -305,7 +313,7 @@ private async Task ProcessLoop() } catch (Exception exception) { - _logger.LogWarning(exception, "Error in placement worker."); + Log.PlacementWorkerError(_logger, exception); } await _workSignal.WaitAsync(); diff --git a/src/Orleans.Runtime/Placement/Repartitioning/ActivationRepartitioner.MessageSink.cs b/src/Orleans.Runtime/Placement/Repartitioning/ActivationRepartitioner.MessageSink.cs index 0eb254bf76..c42a7baff3 100644 --- a/src/Orleans.Runtime/Placement/Repartitioning/ActivationRepartitioner.MessageSink.cs +++ b/src/Orleans.Runtime/Placement/Repartitioning/ActivationRepartitioner.MessageSink.cs @@ -19,15 +19,21 @@ internal partial class ActivationRepartitioner : IMessageStatisticsSink private readonly BlockedBloomFilter? _anchoredFilter; private Task? _processPendingEdgesTask; + private static partial class Log + { + [LoggerMessage(1, LogLevel.Trace, "{Service} has started.")] + public static partial void ServiceStarted(ILogger logger, string service); + + [LoggerMessage(2, LogLevel.Trace, "{Service} has stopped.")] + public static partial void ServiceStopped(ILogger logger, string service); + } + public void StartProcessingEdges() { using var _ = new ExecutionContextSuppressor(); _processPendingEdgesTask = ProcessPendingEdges(_shutdownCts.Token); - if (_logger.IsEnabled(LogLevel.Trace)) - { - _logger.LogTrace("{Service} has started.", nameof(ActivationRepartitioner)); - } + Log.ServiceStarted(_logger, nameof(ActivationRepartitioner)); } public async Task StopProcessingEdgesAsync(CancellationToken cancellationToken) @@ -41,10 +47,7 @@ public async Task StopProcessingEdgesAsync(CancellationToken cancellationToken) _pendingMessageEvent.Signal(); await _processPendingEdgesTask.WaitAsync(cancellationToken).ConfigureAwait(ConfigureAwaitOptions.SuppressThrowing); - if (_logger.IsEnabled(LogLevel.Trace)) - { - _logger.LogTrace("{Service} has stopped.", nameof(ActivationRepartitioner)); - } + Log.ServiceStopped(_logger, nameof(ActivationRepartitioner)); } private async Task ProcessPendingEdges(CancellationToken cancellationToken) @@ -144,4 +147,4 @@ async ValueTask IActivationRepartitionerSystemTarget.FlushBuffers() await Task.Delay(TimeSpan.FromMilliseconds(30)); } } -} \ No newline at end of file +} diff --git a/src/Orleans.Runtime/Scheduler/ActivationTaskScheduler.cs b/src/Orleans.Runtime/Scheduler/ActivationTaskScheduler.cs index c9e5af0276..2250877447 100644 --- a/src/Orleans.Runtime/Scheduler/ActivationTaskScheduler.cs +++ b/src/Orleans.Runtime/Scheduler/ActivationTaskScheduler.cs @@ -32,7 +32,31 @@ internal ActivationTaskScheduler(WorkItemGroup workGroup, ILoggerGets an enumerable of the tasks currently scheduled on this scheduler. @@ -46,27 +70,17 @@ internal void RunTaskFromWorkItemGroup(Task task) if (!done) { #if DEBUG - LogTryExecuteTaskNotDone(task); + Log.TryExecuteTaskNotDone(this.logger, task.Id, task.Status); #endif } } - [MethodImpl(MethodImplOptions.NoInlining)] - private void LogTryExecuteTaskNotDone(Task task) - { - logger.LogWarning( - (int)ErrorCode.SchedulerTaskExecuteIncomplete4, - "RunTask: Incomplete base.TryExecuteTask for Task Id={TaskId} with Status={TaskStatus}", - task.Id, - task.Status); - } - /// Queues a task to the scheduler. /// The task to be queued. protected override void QueueTask(Task task) { #if DEBUG - if (logger.IsEnabled(LogLevel.Trace)) logger.LogTrace("{TaskScheduler} QueueTask Task Id={TaskId}", myId, task.Id); + Log.QueueTask(this.logger, myId, task.Id); #endif workerGroup.EnqueueTask(task); } @@ -84,22 +98,12 @@ protected override bool TryExecuteTaskInline(Task task, bool taskWasPreviouslyQu var canExecuteInline = !taskWasPreviouslyQueued && Equals(RuntimeContext.Current, workerGroup.GrainContext); #if DEBUG - if (logger.IsEnabled(LogLevel.Trace)) - { - logger.LogTrace( - "{TaskScheduler} TryExecuteTaskInline Task Id={TaskId} Status={Status} PreviouslyQueued={PreviouslyQueued} CanExecute={CanExecute} Queued={Queued}", - myId, - task.Id, - task.Status, - taskWasPreviouslyQueued, - canExecuteInline, - workerGroup.ExternalWorkItemCount); - } + Log.TryExecuteTaskInline(this.logger, myId, task.Id, task.Status, taskWasPreviouslyQueued, canExecuteInline, workerGroup.ExternalWorkItemCount); #endif if (!canExecuteInline) { #if DEBUG - if (logger.IsEnabled(LogLevel.Trace)) logger.LogTrace("{TaskScheduler} Completed TryExecuteTaskInline Task Id={TaskId} Status={Status} Execute=No", myId, task.Id, task.Status); + Log.CompletedTryExecuteTaskInlineNo(this.logger, myId, task.Id, task.Status); #endif return false; } @@ -108,29 +112,18 @@ protected override bool TryExecuteTaskInline(Task task, bool taskWasPreviouslyQu turnsExecutedStatistic.Increment(); #endif #if DEBUG - if (logger.IsEnabled(LogLevel.Trace)) - logger.LogTrace( - "{TaskScheduler} TryExecuteTaskInline Task Id={TaskId} Thread={Thread} Execute=Yes", - myId, - task.Id, - Thread.CurrentThread.ManagedThreadId); + Log.TryExecuteTaskInlineYes(this.logger, myId, task.Id, Thread.CurrentThread.ManagedThreadId); #endif // Try to run the task. bool done = TryExecuteTask(task); if (!done) { #if DEBUG - LogTryExecuteTaskNotDone(task); + Log.TryExecuteTaskNotDone(this.logger, task.Id, task.Status); #endif } #if DEBUG - if (logger.IsEnabled(LogLevel.Trace)) - logger.LogTrace( - "{TaskScheduler} Completed TryExecuteTaskInline Task Id={TaskId} Thread={Thread} Execute=Done Ok={Ok}", - myId, - task.Id, - Thread.CurrentThread.ManagedThreadId, - done); + Log.CompletedTryExecuteTaskInlineDone(this.logger, myId, task.Id, Thread.CurrentThread.ManagedThreadId, done); #endif return done; } diff --git a/src/Orleans.Runtime/Silo/Silo.cs b/src/Orleans.Runtime/Silo/Silo.cs index 54faa7f891..0ca741e5ca 100644 --- a/src/Orleans.Runtime/Silo/Silo.cs +++ b/src/Orleans.Runtime/Silo/Silo.cs @@ -15,6 +15,7 @@ using Orleans.Services; using Orleans.Configuration; using Orleans.Internal; +using Microsoft.Extensions.Logging; namespace Orleans.Runtime { @@ -91,37 +92,21 @@ public Silo(ILocalSiloDetails siloDetails, IServiceProvider services) this.loggerFactory = this.Services.GetRequiredService(); logger = this.loggerFactory.CreateLogger(); - logger.LogInformation( - (int)ErrorCode.SiloGcSetting, - "Silo starting with GC settings: ServerGC={ServerGC} GCLatencyMode={GCLatencyMode}", - GCSettings.IsServerGC, - GCSettings.LatencyMode.ToString()); + SiloLoggerMessages.SiloGcSetting(logger, GCSettings.IsServerGC, GCSettings.LatencyMode.ToString()); if (!GCSettings.IsServerGC) { - logger.LogWarning((int)ErrorCode.SiloGcWarning, "Note: Silo not running with ServerGC turned on - recommend checking app config : --"); - logger.LogWarning((int)ErrorCode.SiloGcWarning, "Note: ServerGC only kicks in on multi-core systems (settings enabling ServerGC have no effect on single-core machines)."); + SiloLoggerMessages.SiloGcWarning(logger, "Note: Silo not running with ServerGC turned on - recommend checking app config : --"); + SiloLoggerMessages.SiloGcWarning(logger, "Note: ServerGC only kicks in on multi-core systems (settings enabling ServerGC have no effect on single-core machines)."); } if (logger.IsEnabled(LogLevel.Debug)) { var highestLogLevel = logger.IsEnabled(LogLevel.Trace) ? nameof(LogLevel.Trace) : nameof(LogLevel.Debug); - logger.LogWarning( - (int)ErrorCode.SiloGcWarning, - $"A verbose logging level ({{highestLogLevel}}) is configured. This will impact performance. The recommended log level is {nameof(LogLevel.Information)}.", - highestLogLevel); - } - - logger.LogInformation( - (int)ErrorCode.SiloInitializing, - "-------------- Initializing silo on host {HostName} MachineName {MachineName} at {LocalEndpoint}, gen {Generation} --------------", - this.siloDetails.DnsHostName, - Environment.MachineName, - localEndpoint, - this.siloDetails.SiloAddress.Generation); - logger.LogInformation( - (int)ErrorCode.SiloInitConfig, - "Starting silo {SiloName}", - siloDetails.Name); + SiloLoggerMessages.SiloGcWarning(logger, $"A verbose logging level ({{highestLogLevel}}) is configured. This will impact performance. The recommended log level is {nameof(LogLevel.Information)}.", highestLogLevel); + } + + SiloLoggerMessages.SiloInitializing(logger, this.siloDetails.DnsHostName, Environment.MachineName, localEndpoint, this.siloDetails.SiloAddress.Generation); + SiloLoggerMessages.SiloInitConfig(logger, siloDetails.Name); try { @@ -129,8 +114,7 @@ public Silo(ILocalSiloDetails siloDetails, IServiceProvider services) } catch (InvalidOperationException exc) { - logger.LogError( - (int)ErrorCode.SiloStartError, exc, "Exception during Silo.Start, GrainFactory was not registered in Dependency Injection container"); + SiloLoggerMessages.SiloStartError(logger, exc, "Exception during Silo.Start, GrainFactory was not registered in Dependency Injection container"); throw; } @@ -157,11 +141,7 @@ public Silo(ILocalSiloDetails siloDetails, IServiceProvider services) // add self to lifecycle this.Participate(this.siloLifecycle); - logger.LogInformation( - (int)ErrorCode.SiloInitializingFinished, - "-------------- Started silo {SiloAddress}, ConsistentHashCode {HashCode} --------------", - SiloAddress.ToString(), - SiloAddress.GetConsistentHashCode().ToString("X")); + SiloLoggerMessages.SiloInitializingFinished(logger, SiloAddress.ToString(), SiloAddress.GetConsistentHashCode().ToString("X")); } /// @@ -181,7 +161,7 @@ public async Task StartAsync(CancellationToken cancellationToken) } catch (Exception exc) { - logger.LogError((int)ErrorCode.SiloStartError, exc, "Exception during Silo.Start"); + SiloLoggerMessages.SiloStartError(logger, exc, "Exception during Silo.Start"); throw; } } @@ -211,7 +191,7 @@ private Task OnRuntimeInitializeStart(CancellationToken ct) this.SystemStatus = SystemStatus.Starting; } - logger.LogInformation((int)ErrorCode.SiloStarting, "Silo Start()"); + SiloLoggerMessages.SiloStarting(logger); return Task.CompletedTask; } @@ -220,11 +200,7 @@ private void StartTaskWithPerfAnalysis(string taskName, Action task, Stopwatch s stopWatch.Restart(); task.Invoke(); stopWatch.Stop(); - this.logger.LogInformation( - (int)ErrorCode.SiloStartPerfMeasure, - "{TaskName} took {ElapsedMilliseconds} milliseconds to finish", - taskName, - stopWatch.ElapsedMilliseconds); + SiloLoggerMessages.SiloStartPerfMeasure(logger, taskName, stopWatch.ElapsedMilliseconds); } private async Task StartAsyncTaskWithPerfAnalysis(string taskName, Func task, Stopwatch stopWatch) @@ -232,11 +208,7 @@ private async Task StartAsyncTaskWithPerfAnalysis(string taskName, Func ta stopWatch.Restart(); await task.Invoke(); stopWatch.Stop(); - this.logger.LogInformation( - (int)ErrorCode.SiloStartPerfMeasure, - "{TaskName} took {ElapsedMilliseconds} milliseconds to finish", - taskName, - stopWatch.ElapsedMilliseconds); + SiloLoggerMessages.SiloStartPerfMeasure(logger, taskName, stopWatch.ElapsedMilliseconds); } private Task OnRuntimeServicesStart(CancellationToken ct) @@ -266,17 +238,13 @@ await StartAsyncTaskWithPerfAnalysis("Init grain services", } catch (Exception exc) { - this.logger.LogError( - (int)ErrorCode.Runtime_Error_100330, - exc, - "Error starting silo {SiloAddress}. Going to FastKill().", - this.SiloAddress); + SiloLoggerMessages.Runtime_Error_100330(logger, exc, "Error starting silo {SiloAddress}. Going to FastKill().", this.SiloAddress); throw; } if (logger.IsEnabled(LogLevel.Debug)) { - logger.LogDebug("Silo.Start complete: System status = {SystemStatus}", this.SystemStatus); + SiloLoggerMessages.SiloStartComplete(logger, this.SystemStatus); } } @@ -315,13 +283,11 @@ private async Task RegisterGrainService(IGrainService service) } catch (TimeoutException exception) { - logger.LogError(exception, "GrainService initialization timed out after '{Timeout}'.", initTimeout); + SiloLoggerMessages.GrainServiceInitializationTimeout(logger, exception, initTimeout); throw; } - logger.LogInformation( - "Grain Service {GrainServiceType} registered successfully.", - service.GetType().FullName); + SiloLoggerMessages.GrainServiceRegistered(logger, service.GetType().FullName); } private async Task StartGrainService(IGrainService service) @@ -334,11 +300,11 @@ private async Task StartGrainService(IGrainService service) } catch (TimeoutException exception) { - logger.LogError(exception, "GrainService startup timed out after '{Timeout}'.", initTimeout); + SiloLoggerMessages.GrainServiceStartupTimeout(logger, exception, initTimeout); throw; } - logger.LogInformation("Grain Service {GrainServiceType} started successfully.",service.GetType().FullName); + SiloLoggerMessages.GrainServiceStarted(logger, service.GetType().FullName); } /// @@ -388,7 +354,7 @@ public async Task StopAsync(CancellationToken cancellationToken) { if (logger.IsEnabled(LogLevel.Debug)) { - logger.LogDebug((int)ErrorCode.SiloStopInProgress, "Silo shutdown in progress. Waiting for shutdown to be completed."); + SiloLoggerMessages.SiloStopInProgress(logger); } var pause = TimeSpan.FromSeconds(1); @@ -396,7 +362,7 @@ public async Task StopAsync(CancellationToken cancellationToken) { if (logger.IsEnabled(LogLevel.Debug)) { - logger.LogDebug((int)ErrorCode.WaitingForSiloStop, "Silo shutdown still in progress..."); + SiloLoggerMessages.WaitingForSiloStop(logger); } await Task.Delay(pause).ConfigureAwait(false); } @@ -409,14 +375,14 @@ public async Task StopAsync(CancellationToken cancellationToken) { if (logger.IsEnabled(LogLevel.Debug)) { - logger.LogDebug((int)ErrorCode.SiloShuttingDown, "Silo shutdown initiated (graceful)"); + SiloLoggerMessages.SiloShuttingDown(logger, "Silo shutdown initiated (graceful)"); } } else { if (logger.IsEnabled(LogLevel.Warning)) { - logger.LogWarning((int)ErrorCode.SiloShuttingDown, "Silo shutdown initiated (non-graceful)"); + SiloLoggerMessages.SiloShuttingDown(logger, "Silo shutdown initiated (non-graceful)"); } } @@ -431,14 +397,14 @@ public async Task StopAsync(CancellationToken cancellationToken) { if (logger.IsEnabled(LogLevel.Debug)) { - logger.LogDebug((int)ErrorCode.SiloShutDown, "Silo shutdown completed (graceful)!"); + SiloLoggerMessages.SiloShutDown(logger, "Silo shutdown completed (graceful)!"); } } else { if (logger.IsEnabled(LogLevel.Warning)) { - logger.LogWarning((int)ErrorCode.SiloShutDown, "Silo shutdown completed (non-graceful)!"); + SiloLoggerMessages.SiloShutDown(logger, "Silo shutdown completed (non-graceful)!"); } } @@ -463,7 +429,7 @@ private async Task OnRuntimeInitializeStop(CancellationToken ct) } catch (Exception exception) { - this.logger.LogError(exception, "Error stopping message center"); + SiloLoggerMessages.ErrorStoppingMessageCenter(logger, exception); } SystemStatus = SystemStatus.Terminated; @@ -481,11 +447,11 @@ private async Task OnBecomeActiveStop(CancellationToken ct) { if (!ct.IsCancellationRequested) { - logger.LogError(exception, "Error deactivating activations."); + SiloLoggerMessages.ErrorDeactivatingActivations(logger, exception); } else { - logger.LogWarning("Some grains failed to deactivate promptly."); + SiloLoggerMessages.Warning(logger, "Some grains failed to deactivate promptly."); } } @@ -494,10 +460,7 @@ private async Task OnBecomeActiveStop(CancellationToken ct) } catch (Exception exc) { - logger.LogError( - (int)ErrorCode.SiloFailedToStopMembership, - exc, - "Failed to shutdown gracefully. About to terminate ungracefully"); + SiloLoggerMessages.SiloFailedToStopMembership(logger, exc); } // Stop the gateway @@ -518,7 +481,7 @@ await lifecycleSchedulingSystemTarget } catch (Exception exception) { - logger.LogError(exception, "Sending gateway disconnection requests to connected clients failed."); + SiloLoggerMessages.ErrorSendingGatewayDisconnectionRequests(logger, exception); if (!ct.IsCancellationRequested) { throw; @@ -536,7 +499,7 @@ await grainService } catch (Exception exception) { - logger.LogError(exception, "Stopping GrainService '{GrainService}' failed.", grainService); + SiloLoggerMessages.ErrorStoppingGrainService(logger, exception, grainService); if (!ct.IsCancellationRequested) { throw; @@ -545,10 +508,7 @@ await grainService if (this.logger.IsEnabled(LogLevel.Debug)) { - logger.LogDebug( - "{GrainServiceType} Grain Service with Id {GrainServiceId} stopped successfully.", - grainService.GetType().FullName, - grainService.GetGrainId().ToString()); + SiloLoggerMessages.GrainServiceStopped(logger, grainService.GetType().FullName, grainService.GetGrainId().ToString()); } } } @@ -603,5 +563,82 @@ public LifecycleSchedulingSystemTarget(ILocalSiloDetails localSiloDetails, ILogg { } } -} + internal static partial class SiloLoggerMessages + { + [LoggerMessage(1, LogLevel.Information, "Silo starting with GC settings: ServerGC={ServerGC} GCLatencyMode={GCLatencyMode}")] + public static partial void SiloGcSetting(ILogger logger, bool ServerGC, string GCLatencyMode); + + [LoggerMessage(2, LogLevel.Warning, "{Message}")] + public static partial void SiloGcWarning(ILogger logger, string Message); + + [LoggerMessage(3, LogLevel.Information, "-------------- Initializing silo on host {HostName} MachineName {MachineName} at {LocalEndpoint}, gen {Generation} --------------")] + public static partial void SiloInitializing(ILogger logger, string HostName, string MachineName, System.Net.IPEndPoint LocalEndpoint, int Generation); + + [LoggerMessage(4, LogLevel.Information, "Starting silo {SiloName}")] + public static partial void SiloInitConfig(ILogger logger, string SiloName); + + [LoggerMessage(5, LogLevel.Error, "{Message}")] + public static partial void SiloStartError(ILogger logger, Exception exception, string Message); + + [LoggerMessage(6, LogLevel.Information, "-------------- Started silo {SiloAddress}, ConsistentHashCode {HashCode} --------------")] + public static partial void SiloInitializingFinished(ILogger logger, string SiloAddress, string HashCode); + + [LoggerMessage(7, LogLevel.Information, "Silo Start()")] + public static partial void SiloStarting(ILogger logger); + + [LoggerMessage(8, LogLevel.Information, "{TaskName} took {ElapsedMilliseconds} milliseconds to finish")] + public static partial void SiloStartPerfMeasure(ILogger logger, string TaskName, long ElapsedMilliseconds); + + [LoggerMessage(9, LogLevel.Error, "Error starting silo {SiloAddress}. Going to FastKill().")] + public static partial void Runtime_Error_100330(ILogger logger, Exception exception, string Message, SiloAddress SiloAddress); + + [LoggerMessage(10, LogLevel.Debug, "Silo.Start complete: System status = {SystemStatus}")] + public static partial void SiloStartComplete(ILogger logger, SystemStatus SystemStatus); + + [LoggerMessage(11, LogLevel.Error, "GrainService initialization timed out after '{Timeout}'.")] + public static partial void GrainServiceInitializationTimeout(ILogger logger, Exception exception, TimeSpan Timeout); + + [LoggerMessage(12, LogLevel.Information, "Grain Service {GrainServiceType} registered successfully.")] + public static partial void GrainServiceRegistered(ILogger logger, string GrainServiceType); + + [LoggerMessage(13, LogLevel.Error, "GrainService startup timed out after '{Timeout}'.")] + public static partial void GrainServiceStartupTimeout(ILogger logger, Exception exception, TimeSpan Timeout); + + [LoggerMessage(14, LogLevel.Information, "Grain Service {GrainServiceType} started successfully.")] + public static partial void GrainServiceStarted(ILogger logger, string GrainServiceType); + + [LoggerMessage(15, LogLevel.Debug, "Silo shutdown in progress. Waiting for shutdown to be completed.")] + public static partial void SiloStopInProgress(ILogger logger); + + [LoggerMessage(16, LogLevel.Debug, "Silo shutdown still in progress...")] + public static partial void WaitingForSiloStop(ILogger logger); + + [LoggerMessage(17, LogLevel.Debug, "{Message}")] + public static partial void SiloShuttingDown(ILogger logger, string Message); + + [LoggerMessage(18, LogLevel.Debug, "{Message}")] + public static partial void SiloShutDown(ILogger logger, string Message); + + [LoggerMessage(19, LogLevel.Error, "Error stopping message center")] + public static partial void ErrorStoppingMessageCenter(ILogger logger, Exception exception); + + [LoggerMessage(20, LogLevel.Error, "Error deactivating activations.")] + public static partial void ErrorDeactivatingActivations(ILogger logger, Exception exception); + + [LoggerMessage(21, LogLevel.Warning, "{Message}")] + public static partial void Warning(ILogger logger, string Message); + + [LoggerMessage(22, LogLevel.Error, "Failed to shutdown gracefully. About to terminate ungracefully")] + public static partial void SiloFailedToStopMembership(ILogger logger, Exception exception); + + [LoggerMessage(23, LogLevel.Error, "Sending gateway disconnection requests to connected clients failed.")] + public static partial void ErrorSendingGatewayDisconnectionRequests(ILogger logger, Exception exception); + + [LoggerMessage(24, LogLevel.Error, "Stopping GrainService '{GrainService}' failed.")] + public static partial void ErrorStoppingGrainService(ILogger logger, Exception exception, GrainService GrainService); + + [LoggerMessage(25, LogLevel.Debug, "{GrainServiceType} Grain Service with Id {GrainServiceId} stopped successfully.")] + public static partial void GrainServiceStopped(ILogger logger, string GrainServiceType, string GrainServiceId); + } +} diff --git a/src/Orleans.Runtime/Silo/SiloControl.cs b/src/Orleans.Runtime/Silo/SiloControl.cs index 7bbbaf0cb5..761e814421 100644 --- a/src/Orleans.Runtime/Silo/SiloControl.cs +++ b/src/Orleans.Runtime/Silo/SiloControl.cs @@ -88,33 +88,33 @@ public SiloControl( public Task Ping(string message) { - logger.LogInformation("Ping"); + Log.Ping(logger); return Task.CompletedTask; } [System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Reliability", "CA2001:AvoidCallingProblematicMethods", MessageId = "System.GC.Collect")] public Task ForceGarbageCollection() { - logger.LogInformation("ForceGarbageCollection"); + Log.ForceGarbageCollection(logger); GC.Collect(); return Task.CompletedTask; } public Task ForceActivationCollection(TimeSpan ageLimit) { - logger.LogInformation("ForceActivationCollection"); + Log.ForceActivationCollection(logger); return _activationCollector.CollectActivations(ageLimit, CancellationToken.None); } public Task ForceRuntimeStatisticsCollection() { - if (logger.IsEnabled(LogLevel.Debug)) logger.LogDebug("ForceRuntimeStatisticsCollection"); + Log.ForceRuntimeStatisticsCollection(logger); return this.deploymentLoadPublisher.RefreshClusterStatistics(); } public Task GetRuntimeStatistics() { - if (logger.IsEnabled(LogLevel.Debug)) logger.LogDebug("GetRuntimeStatistics"); + Log.GetRuntimeStatistics(logger); var activationCount = this.activationDirectory.Count; var stats = new SiloRuntimeStatistics( activationCount, @@ -127,7 +127,7 @@ public Task GetRuntimeStatistics() public Task>> GetGrainStatistics() { - logger.LogInformation("GetGrainStatistics"); + Log.GetGrainStatistics(logger); var counts = new Dictionary>(); lock (activationDirectory) { @@ -238,11 +238,7 @@ public Task SendControlCommandToProvider(string providerName, int com if (controllable == null) { - logger.LogError( - (int)ErrorCode.Provider_ProviderNotFound, - "Could not find a controllable service for type {ProviderTypeFullName} and name {ProviderName}.", - typeof(IControllable).FullName, - providerName); + Log.SendControlCommandToProvider(logger, typeof(IControllable).FullName, providerName); throw new ArgumentException($"Could not find a controllable service for type {typeof(IControllable).FullName} and name {providerName}."); } @@ -345,5 +341,29 @@ private List GetDetailedGrainStatisticsCore(string[]? ty } return stats; } + + private static partial class Log + { + [LoggerMessage(1, LogLevel.Information, "Ping")] + public static partial void Ping(ILogger logger); + + [LoggerMessage(2, LogLevel.Information, "ForceGarbageCollection")] + public static partial void ForceGarbageCollection(ILogger logger); + + [LoggerMessage(3, LogLevel.Information, "ForceActivationCollection")] + public static partial void ForceActivationCollection(ILogger logger); + + [LoggerMessage(4, LogLevel.Debug, "ForceRuntimeStatisticsCollection")] + public static partial void ForceRuntimeStatisticsCollection(ILogger logger); + + [LoggerMessage(5, LogLevel.Debug, "GetRuntimeStatistics")] + public static partial void GetRuntimeStatistics(ILogger logger); + + [LoggerMessage(6, LogLevel.Information, "GetGrainStatistics")] + public static partial void GetGrainStatistics(ILogger logger); + + [LoggerMessage(7, LogLevel.Error, "Could not find a controllable service for type {ProviderTypeFullName} and name {ProviderName}.")] + public static partial void SendControlCommandToProvider(ILogger logger, string ProviderTypeFullName, string ProviderName); + } } }