diff --git a/src/Orleans.Runtime/Cancellation/CancellationSourcesExtension.cs b/src/Orleans.Runtime/Cancellation/CancellationSourcesExtension.cs index 32c8283964..4bc7e9fd4a 100644 --- a/src/Orleans.Runtime/Cancellation/CancellationSourcesExtension.cs +++ b/src/Orleans.Runtime/Cancellation/CancellationSourcesExtension.cs @@ -12,7 +12,7 @@ namespace Orleans.Runtime /// Contains list of cancellation token source corresponding to the tokens /// passed to the related grain activation. /// - internal class CancellationSourcesExtension : ICancellationSourcesExtension, IDisposable + internal partial class CancellationSourcesExtension : ICancellationSourcesExtension, IDisposable { private readonly ConcurrentDictionary _cancellationTokens = new ConcurrentDictionary(); private readonly ILogger _logger; @@ -39,7 +39,7 @@ public Task CancelRemoteToken(Guid tokenId) { if (!_cancellationTokens.TryGetValue(tokenId, out var entry)) { - _logger.LogWarning((int)ErrorCode.CancellationTokenCancelFailed, "Received a cancel call for token with id {TokenId}, but the token was not found", tokenId); + LogCancellationFailed(tokenId); // Record the cancellation anyway, in case the call which would have registered the cancellation is still pending. this.RecordCancellationToken(tokenId, isCancellationRequested: true); @@ -132,5 +132,12 @@ public bool IsExpired(TimeSpan expiry, long nowTimestamp) return untouchedTime >= expiry; } } + + [LoggerMessage( + EventId = (int)ErrorCode.CancellationTokenCancelFailed, + Level = LogLevel.Warning, + Message = "Received a cancel call for token with id '{TokenId}', but the token was not found." + )] + private partial void LogCancellationFailed(Guid tokenId); } } \ No newline at end of file diff --git a/src/Orleans.Runtime/Catalog/ActivationCollector.cs b/src/Orleans.Runtime/Catalog/ActivationCollector.cs index 20b5eb8d49..e2b6d67922 100644 --- a/src/Orleans.Runtime/Catalog/ActivationCollector.cs +++ b/src/Orleans.Runtime/Catalog/ActivationCollector.cs @@ -14,7 +14,7 @@ namespace Orleans.Runtime /// /// Identifies activations that have been idle long enough to be deactivated. /// - internal class ActivationCollector : IActivationWorkingSetObserver, ILifecycleParticipant, IDisposable + internal partial class ActivationCollector : IActivationWorkingSetObserver, ILifecycleParticipant, IDisposable { private readonly TimeSpan quantum; private readonly TimeSpan shortestAgeLimit; @@ -441,7 +441,7 @@ private async Task RunActivationCollectionLoop() } catch (Exception exception) { - this.logger.LogError(exception, "Error while collecting activations."); + LogErrorWhileCollectingActivations(exception); } } } @@ -452,45 +452,25 @@ private async Task CollectActivationsImpl(bool scanStale, TimeSpan ageLimit, Can var number = Interlocked.Increment(ref collectionNumber); long memBefore = GC.GetTotalMemory(false) / (1024 * 1024); - if (logger.IsEnabled(LogLevel.Debug)) - { - logger.LogDebug( - (int)ErrorCode.Catalog_BeforeCollection, - "Before collection #{CollectionNumber}: memory: {MemoryBefore}MB, #activations: {ActivationCount}, collector: {CollectorStatus}", - number, - memBefore, - _activationCount, - ToString()); - } + LogBeforeCollection(number, memBefore, _activationCount, this); List list = scanStale ? ScanStale() : ScanAll(ageLimit); CatalogInstruments.ActivationCollections.Add(1); if (list is { Count: > 0 }) { - if (logger.IsEnabled(LogLevel.Debug)) logger.LogDebug("CollectActivations {Activations}", list.ToStrings(d => d.GrainId.ToString() + d.ActivationId)); + LogCollectActivations(new(list)); await DeactivateActivationsFromCollector(list, cancellationToken); } long memAfter = GC.GetTotalMemory(false) / (1024 * 1024); watch.Stop(); - if (logger.IsEnabled(LogLevel.Debug)) - { - logger.LogDebug( - (int)ErrorCode.Catalog_AfterCollection, - "After collection #{CollectionNumber} memory: {MemoryAfter}MB, #activations: {ActivationCount}, collected {CollectedCount} activations, collector: {CollectorStatus}, collection time: {CollectionTime}", - number, - memAfter, - _activationCount, - list?.Count ?? 0, - ToString(), - watch.Elapsed); - } + LogAfterCollection(number, memAfter, _activationCount, list?.Count ?? 0, this, watch.Elapsed); } private async Task DeactivateActivationsFromCollector(List list, CancellationToken cancellationToken) { - logger.LogInformation((int)ErrorCode.Catalog_ShutdownActivations_1, "Deactivating '{Count}' idle activations.", list.Count); + LogDeactivateActivationsFromCollector(list.Count); CatalogInstruments.ActivationShutdownViaCollection(); var reason = GetDeactivationReason(); @@ -567,5 +547,42 @@ public List CancelAll() return result ?? nothing; } } + + [LoggerMessage( + Level = LogLevel.Error, + Message = "Error while collecting activations." + )] + private partial void LogErrorWhileCollectingActivations(Exception exception); + + [LoggerMessage( + EventId = (int)ErrorCode.Catalog_BeforeCollection, + Level = LogLevel.Debug, + Message = "Before collection #{CollectionNumber}: memory: {MemoryBefore}MB, #activations: {ActivationCount}, collector: {CollectorStatus}" + )] + private partial void LogBeforeCollection(int collectionNumber, long memoryBefore, int activationCount, ActivationCollector collectorStatus); + + [LoggerMessage( + Level = LogLevel.Trace, + Message = "CollectActivations {Activations}" + )] + private partial void LogCollectActivations(ActivationsLogValue activations); + private struct ActivationsLogValue(List list) + { + public override string ToString() => list.ToStrings(d => d.GrainId.ToString() + d.ActivationId); + } + + [LoggerMessage( + EventId = (int)ErrorCode.Catalog_AfterCollection, + Level = LogLevel.Debug, + Message = "After collection #{CollectionNumber} memory: {MemoryAfter}MB, #activations: {ActivationCount}, collected {CollectedCount} activations, collector: {CollectorStatus}, collection time: {CollectionTime}" + )] + private partial void LogAfterCollection(int collectionNumber, long memoryAfter, int activationCount, int collectedCount, ActivationCollector collectorStatus, TimeSpan collectionTime); + + [LoggerMessage( + EventId = (int)ErrorCode.Catalog_ShutdownActivations_1, + Level = LogLevel.Information, + Message = "Deactivating '{Count}' idle activations." + )] + private partial void LogDeactivateActivationsFromCollector(int count); } } diff --git a/src/Orleans.Runtime/Catalog/ActivationData.cs b/src/Orleans.Runtime/Catalog/ActivationData.cs index d184a8ce63..63295b5abd 100644 --- a/src/Orleans.Runtime/Catalog/ActivationData.cs +++ b/src/Orleans.Runtime/Catalog/ActivationData.cs @@ -26,7 +26,7 @@ namespace Orleans.Runtime; /// MUST lock this object for any concurrent access /// Consider: compartmentalize by usage, e.g., using separate interfaces for data for catalog, etc. /// -internal sealed class ActivationData : IGrainContext, ICollectibleGrainContext, IGrainExtensionBinder, IActivationWorkingSetMember, IGrainTimerRegistry, IGrainManagementExtension, ICallChainReentrantGrainContext, IAsyncDisposable, IDisposable +internal sealed partial class ActivationData : IGrainContext, ICollectibleGrainContext, IGrainExtensionBinder, IActivationWorkingSetMember, IGrainTimerRegistry, IGrainManagementExtension, ICallChainReentrantGrainContext, IAsyncDisposable, IDisposable { private const string GrainAddressMigrationContextKey = "sys.addr"; private readonly GrainTypeSharedContext _shared; @@ -354,24 +354,13 @@ public void SetState(ActivationState state) if (maxRequestsHardLimit > 0 && count > maxRequestsHardLimit) // Hard limit { - _shared.Logger.LogWarning( - (int)ErrorCode.Catalog_Reject_ActivationTooManyRequests, - "Overload - {Count} enqueued requests for activation {Activation}, exceeding hard limit rejection threshold of {HardLimit}", - count, - this, - maxRequestsHardLimit); - + LogRejectActivationTooManyRequests(_shared.Logger, count, this, maxRequestsHardLimit); return new LimitExceededException(limitName, count, maxRequestsHardLimit, ToString()); } if (maxRequestsSoftLimit > 0 && count > maxRequestsSoftLimit) // Soft limit { - _shared.Logger.LogWarning( - (int)ErrorCode.Catalog_Warn_ActivationTooManyRequests, - "Hot - {Count} enqueued requests for activation {Activation}, exceeding soft limit warning threshold of {SoftLimit}", - count, - this, - maxRequestsSoftLimit); + LogWarnActivationTooManyRequests(_shared.Logger, count, this, maxRequestsSoftLimit); return null; } @@ -470,7 +459,7 @@ private void CancelPendingOperations() { if (exception is not ObjectDisposedException) { - _shared.Logger.LogWarning(exception, "Error while cancelling on-going operation '{Operation}'.", cmd); + LogErrorCancellingOperation(_shared.Logger, exception, cmd); } } } @@ -525,14 +514,11 @@ private async Task StartMigratingAsync(Dictionary? requestContex StartMigratingCore(requestContext, newLocation); } - if (_shared.Logger.IsEnabled(LogLevel.Debug)) - { - _shared.Logger.LogDebug("Migrating {GrainId} to {SiloAddress}", GrainId, newLocation); - } + LogDebugMigrating(_shared.Logger, GrainId, newLocation); } catch (Exception exception) { - _shared.Logger.LogError(exception, "Error while selecting a migration destination for {GrainId}", GrainId); + LogErrorSelectingMigrationDestination(_shared.Logger, GrainId, exception); return; } } @@ -562,16 +548,13 @@ private void StartMigratingCore(Dictionary? requestContext, Silo // No more appropriate silo was selected for this grain. The migration attempt will be aborted. // This could be because this is the only (compatible) silo for the grain or because the placement director chose this // silo for some other reason. - if (_shared.Logger.IsEnabled(LogLevel.Debug)) + if (newLocation is null) { - if (newLocation is null) - { - _shared.Logger.LogDebug("Placement strategy {PlacementStrategy} failed to select a destination for migration of {GrainId}", PlacementStrategy, GrainId); - } - else - { - _shared.Logger.LogDebug("Placement strategy {PlacementStrategy} selected the current silo as the destination for migration of {GrainId}", PlacementStrategy, GrainId); - } + LogDebugPlacementStrategyFailedToSelectDestination(_shared.Logger, PlacementStrategy, GrainId); + } + else + { + LogDebugPlacementStrategySelectedCurrentSilo(_shared.Logger, PlacementStrategy, GrainId); } // Will not migrate. @@ -992,11 +975,10 @@ void ProcessPendingRequests() else if (currentRequestActiveTime > _shared.MaxWarningRequestProcessingTime) { // Consider: Handle long request detection for reentrant activations -- this logic only works for non-reentrant activations - _shared.Logger.LogWarning( - (int)ErrorCode.Dispatcher_ExtendedMessageProcessing, - "Current request has been active for {CurrentRequestActiveTime} for grain {Grain}. Currently executing {BlockingRequest}. Trying to enqueue {Message}.", + LogWarningDispatcher_ExtendedMessageProcessing( + _shared.Logger, currentRequestActiveTime, - ToDetailedString(), + new(this), _blockingRequest, message); } @@ -1143,7 +1125,7 @@ bool MayInvokeRequest(Message incoming) } catch (Exception exception) { - _shared.Logger?.LogError(exception, "Error invoking MayInterleave predicate on grain {Grain} for message {Message}", this, incoming); + LogErrorInvokingMayInterleavePredicate(_shared.Logger, exception, this, incoming); throw; } } @@ -1198,7 +1180,7 @@ async Task ProcessOperationsAsync() } catch (Exception exception) { - _shared.Logger.LogError(exception, "Error in ProcessOperationsAsync for grain activation '{Activation}'.", this); + LogErrorInProcessOperationsAsync(_shared.Logger, exception, this); } finally { @@ -1212,27 +1194,20 @@ private void RehydrateInternal(IRehydrationContext context) { try { - if (_shared.Logger.IsEnabled(LogLevel.Debug)) - { - _shared.Logger.LogDebug("Rehydrating grain '{GrainContext}' from previous activation.", this); - } + LogRehydratingGrain(_shared.Logger, this); lock (this) { if (State != ActivationState.Creating) { - _shared.Logger.LogWarning("Ignoring attempt to rehydrate grain '{GrainContext}' in the '{State}' state.", this, State); + LogIgnoringRehydrateAttempt(_shared.Logger, this, State); return; } if (context.TryGetValue(GrainAddressMigrationContextKey, out GrainAddress? previousRegistration) && previousRegistration is not null) { - // Propagate the previous registration, so that the new activation can atomically replace it with its new address. PreviousRegistration = previousRegistration; - if (_shared.Logger.IsEnabled(LogLevel.Debug)) - { - _shared.Logger.LogDebug("Previous activation address was {PreviousRegistration}", previousRegistration); - } + LogPreviousActivationAddress(_shared.Logger, previousRegistration); } if (_lifecycle is { } lifecycle) @@ -1246,14 +1221,11 @@ private void RehydrateInternal(IRehydrationContext context) (GrainInstance as IGrainMigrationParticipant)?.OnRehydrate(context); } - if (_shared.Logger.IsEnabled(LogLevel.Debug)) - { - _shared.Logger.LogDebug("Rehydrated grain from previous activation"); - } + LogRehydratedGrain(_shared.Logger); } catch (Exception exception) { - _shared.Logger.LogError(exception, "Error while rehydrating activation"); + LogErrorRehydratingActivation(_shared.Logger, exception); } finally { @@ -1263,10 +1235,7 @@ private void RehydrateInternal(IRehydrationContext context) private void OnDehydrate(IDehydrationContext context) { - if (_shared.Logger.IsEnabled(LogLevel.Debug)) - { - _shared.Logger.LogDebug("Dehydrating grain activation"); - } + LogDehydratingActivation(_shared.Logger); lock (this) { @@ -1289,10 +1258,7 @@ private void OnDehydrate(IDehydrationContext context) } } - if (_shared.Logger.IsEnabled(LogLevel.Debug)) - { - _shared.Logger.LogDebug("Dehydrated grain activation"); - } + LogDehydratedActivation(_shared.Logger); } /// @@ -1443,12 +1409,7 @@ private void RejectAllQueuedMessages() List msgs = DequeueAllWaitingRequests(); if (msgs == null || msgs.Count <= 0) return; - if (_shared.Logger.IsEnabled(LogLevel.Debug)) - _shared.Logger.LogDebug( - (int)ErrorCode.Catalog_RerouteAllQueuedMessages, - "RejectAllQueuedMessages: {Count} messages from invalid activation {Activation}.", - msgs.Count, - this); + LogRejectAllQueuedMessages(_shared.Logger, msgs.Count, this); _shared.InternalRuntime.GrainLocator.InvalidateCache(Address); _shared.InternalRuntime.MessageCenter.ProcessRequestsToInvalidActivation( msgs, @@ -1483,11 +1444,11 @@ private void RerouteAllQueuedMessages() { if (ForwardingAddress is { } address) { - _shared.Logger.LogDebug((int)ErrorCode.Catalog_RerouteAllQueuedMessages, "Rerouting {NumMessages} messages from invalid grain activation {Grain} to {ForwardingAddress}.", msgs.Count, this, address); + LogReroutingMessages(_shared.Logger, msgs.Count, this, address); } else { - _shared.Logger.LogDebug((int)ErrorCode.Catalog_RerouteAllQueuedMessages, "Rerouting {NumMessages} messages from invalid grain activation {Grain}.", msgs.Count, this); + LogReroutingMessagesNoForwarding(_shared.Logger, msgs.Count, this); } } @@ -1527,10 +1488,7 @@ private async Task ActivateAsync(Dictionary? requestContextData, { while (true) { - if (_shared.Logger.IsEnabled(LogLevel.Debug)) - { - _shared.Logger.LogDebug("Registering grain '{Grain}' in activation directory. Previous known registration is '{PreviousRegistration}'.", this, previousRegistration); - } + LogRegisteringGrain(_shared.Logger, this, previousRegistration); var result = await _shared.InternalRuntime.GrainLocator.Register(Address, previousRegistration).WaitAsync(cancellationToken); if (Address.Matches(result)) @@ -1545,17 +1503,7 @@ private async Task ActivateAsync(Dictionary? requestContextData, // since the catalog only allows one activation of a given grain at a time. // This could occur if the previous activation failed to unregister itself from the grain directory. previousRegistration = result; - - if (_shared.Logger.IsEnabled(LogLevel.Debug)) - { - _shared.Logger.LogDebug( - "The grain directory has an existing entry pointing to a different activation of this grain, '{GrainId}', on this silo: '{PreviousRegistration}'." - + " This may indicate that the previous activation was deactivated but the directory was not successfully updated." - + " The directory will be updated to point to this activation.", - GrainId, - result); - } - + LogAttemptToRegisterWithPreviousActivation(_shared.Logger, GrainId, result); continue; } else @@ -1574,11 +1522,8 @@ private async Task ActivateAsync(Dictionary? requestContextData, { // If this was a duplicate, it's not an error, just a race. // Forward on all of the pending messages, and then forget about this activation. - _shared.Logger.LogDebug( - (int)ErrorCode.Catalog_DuplicateActivation, - "Tried to create a duplicate activation {Address}, but we'll use {ForwardingAddress} instead. " - + "GrainInstance type is {GrainInstanceType}." - + "Full activation address is {Address}. We have {WaitingCount} messages to forward.", + LogDuplicateActivation( + _shared.Logger, Address, ForwardingAddress, GrainInstance?.GetType(), @@ -1597,7 +1542,7 @@ private async Task ActivateAsync(Dictionary? requestContextData, registrationException = exception; if (!cancellationToken.IsCancellationRequested) { - _shared.Logger.LogWarning((int)ErrorCode.Runtime_Error_100064, registrationException, "Failed to register grain {Grain} in grain directory", ToString()); + LogFailedToRegisterGrain(_shared.Logger, registrationException, this); } success = false; @@ -1619,7 +1564,7 @@ private async Task ActivateAsync(Dictionary? requestContextData, if (_shared.Logger.IsEnabled(LogLevel.Debug)) { - _shared.Logger.LogDebug((int)ErrorCode.Catalog_BeforeCallingActivate, "Activating grain {Grain}", this); + LogActivatingGrain(_shared.Logger, this); } // Start grain lifecycle within try-catch wrapper to safely capture any exceptions thrown from called function @@ -1635,7 +1580,7 @@ private async Task ActivateAsync(Dictionary? requestContextData, } catch (Exception exception) { - _shared.Logger.LogError(exception, "Error starting lifecycle for activation '{Activation}'.", this); + LogErrorStartingLifecycle(_shared.Logger, exception, this); throw; } @@ -1647,7 +1592,7 @@ private async Task ActivateAsync(Dictionary? requestContextData, } catch (Exception exception) { - _shared.Logger.LogError(exception, $"Error thrown from {nameof(IGrainBase.OnActivateAsync)} for activation '{{Activation}}'.", this); + LogErrorInGrainMethod(_shared.Logger, exception, nameof(IGrainBase.OnActivateAsync), this); throw; } } @@ -1663,7 +1608,7 @@ private async Task ActivateAsync(Dictionary? requestContextData, if (_shared.Logger.IsEnabled(LogLevel.Debug)) { - _shared.Logger.LogDebug((int)ErrorCode.Catalog_AfterCallingActivate, "Finished activating grain {Grain}", this); + LogFinishedActivatingGrain(_shared.Logger, this); } } catch (Exception exception) @@ -1672,7 +1617,7 @@ private async Task ActivateAsync(Dictionary? requestContextData, // Capture the exception so that it can be propagated to rejection messages var sourceException = (exception as OrleansLifecycleCanceledException)?.InnerException ?? exception; - _shared.Logger.LogError((int)ErrorCode.Catalog_ErrorCallingActivate, sourceException, "Error activating grain {Grain}", this); + LogErrorActivatingGrain(_shared.Logger, sourceException, this); // Unregister this as a message target after some period of time. // This is delayed so that consistently failing activation, perhaps due to an application bug or network @@ -1693,7 +1638,7 @@ private async Task ActivateAsync(Dictionary? requestContextData, } catch (Exception exception) { - _shared.Logger.LogError(exception, "Activation of grain {Grain} failed", this); + LogActivationFailed(_shared.Logger, exception, this); Deactivate(new(DeactivationReasonCode.ApplicationError, exception, "Failed to activate grain.")); } finally @@ -1716,7 +1661,7 @@ private async Task FinishDeactivating(ActivationState previousState, Cancellatio { if (_shared.Logger.IsEnabled(LogLevel.Trace)) { - _shared.Logger.LogTrace("Completing deactivation of '{Activation}'", ToDetailedString()); + LogCompletingDeactivation(_shared.Logger, this); } // Stop timers from firing. @@ -1730,22 +1675,16 @@ private async Task FinishDeactivating(ActivationState previousState, Cancellatio try { if (_shared.Logger.IsEnabled(LogLevel.Debug)) - _shared.Logger.LogDebug( - (int)ErrorCode.Catalog_BeforeCallingDeactivate, - "About to call OnDeactivateAsync for '{Activation}'", - this); + LogBeforeOnDeactivateAsync(_shared.Logger, this); await grainBase.OnDeactivateAsync(DeactivationReason, cancellationToken).WaitAsync(cancellationToken); if (_shared.Logger.IsEnabled(LogLevel.Debug)) - _shared.Logger.LogDebug( - (int)ErrorCode.Catalog_AfterCallingDeactivate, - "Returned from calling '{Activation}' OnDeactivateAsync method", - this); + LogAfterOnDeactivateAsync(_shared.Logger, this); } catch (Exception exception) { - _shared.Logger.LogError(exception, $"Error thrown from {nameof(IGrainBase.OnDeactivateAsync)} for activation '{{Activation}}'.", this); + LogErrorInGrainMethod(_shared.Logger, exception, nameof(IGrainBase.OnDeactivateAsync), this); // Swallow the exception and continue with deactivation. encounteredError = true; @@ -1764,7 +1703,7 @@ private async Task FinishDeactivating(ActivationState previousState, Cancellatio } catch (Exception exception) { - _shared.Logger.LogError(exception, "Error stopping lifecycle for activation '{Activation}'.", this); + LogErrorStartingLifecycle(_shared.Logger, exception, this); // Swallow the exception and continue with deactivation. encounteredError = true; @@ -1797,7 +1736,7 @@ private async Task FinishDeactivating(ActivationState previousState, Cancellatio } catch (Exception exception) { - _shared.Logger.LogWarning(exception, "Failed to migrate activation '{Activation}'.", this); + LogFailedToMigrateActivation(_shared.Logger, exception, this); } finally { @@ -1821,7 +1760,7 @@ private async Task FinishDeactivating(ActivationState previousState, Cancellatio { if (!cancellationToken.IsCancellationRequested) { - _shared.Logger.LogError(exception, "Failed to unregister activation '{Activation}' from directory.", this); + LogFailedToUnregisterActivation(_shared.Logger, exception, this); } } } @@ -1833,7 +1772,7 @@ private async Task FinishDeactivating(ActivationState previousState, Cancellatio } catch (Exception ex) { - _shared.Logger.LogWarning((int)ErrorCode.Catalog_DeactivateActivation_Exception, ex, "Error deactivating '{Activation}'.", this); + LogErrorDeactivating(_shared.Logger, ex, this); } if (IsStuckDeactivating) @@ -1861,7 +1800,7 @@ private async Task FinishDeactivating(ActivationState previousState, Cancellatio } catch (Exception exception) { - _shared.Logger.LogWarning(exception, "Exception disposing activation '{Activation}'.", this); + LogExceptionDisposing(_shared.Logger, exception, this); } // Signal deactivation @@ -2113,4 +2052,239 @@ private class MigrateWorkItem(ActivationData activation, Dictionary activation.StartMigratingAsync(requestContext, cts).Ignore(); } + + [LoggerMessage( + EventId = (int)ErrorCode.Catalog_Reject_ActivationTooManyRequests, + Level = LogLevel.Warning, + Message = "Overload - {Count} enqueued requests for activation {Activation}, exceeding hard limit rejection threshold of {HardLimit}" + )] + private static partial void LogRejectActivationTooManyRequests(ILogger logger, int count, ActivationData activation, int hardLimit); + + [LoggerMessage( + EventId = (int)ErrorCode.Catalog_Warn_ActivationTooManyRequests, + Level = LogLevel.Warning, + Message = "Hot - {Count} enqueued requests for activation {Activation}, exceeding soft limit warning threshold of {SoftLimit}" + )] + private static partial void LogWarnActivationTooManyRequests(ILogger logger, int count, ActivationData activation, int softLimit); + + [LoggerMessage( + Level = LogLevel.Warning, + Message = "Error while cancelling on-going operation '{Operation}'." + )] + private static partial void LogErrorCancellingOperation(ILogger logger, Exception exception, object operation); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Migrating {GrainId} to {SiloAddress}" + )] + private static partial void LogDebugMigrating(ILogger logger, GrainId grainId, SiloAddress siloAddress); + + [LoggerMessage( + Level = LogLevel.Error, + Message = "Error while selecting a migration destination for {GrainId}" + )] + private static partial void LogErrorSelectingMigrationDestination(ILogger logger, GrainId grainId, Exception exception); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Placement strategy {PlacementStrategy} failed to select a destination for migration of {GrainId}" + )] + private static partial void LogDebugPlacementStrategyFailedToSelectDestination(ILogger logger, PlacementStrategy placementStrategy, GrainId grainId); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Placement strategy {PlacementStrategy} selected the current silo as the destination for migration of {GrainId}" + )] + private static partial void LogDebugPlacementStrategySelectedCurrentSilo(ILogger logger, PlacementStrategy placementStrategy, GrainId grainId); + + [LoggerMessage( + Level = LogLevel.Error, + Message = "Error invoking MayInterleave predicate on grain {Grain} for message {Message}" + )] + private static partial void LogErrorInvokingMayInterleavePredicate(ILogger logger, Exception exception, ActivationData grain, Message message); + + [LoggerMessage( + Level = LogLevel.Error, + Message = "Error in ProcessOperationsAsync for grain activation '{Activation}'." + )] + private static partial void LogErrorInProcessOperationsAsync(ILogger logger, Exception exception, ActivationData activation); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Rehydrating grain '{GrainContext}' from previous activation." + )] + private static partial void LogRehydratingGrain(ILogger logger, ActivationData grainContext); + + [LoggerMessage( + Level = LogLevel.Warning, + Message = "Ignoring attempt to rehydrate grain '{GrainContext}' in the '{State}' state." + )] + private static partial void LogIgnoringRehydrateAttempt(ILogger logger, ActivationData grainContext, ActivationState state); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Previous activation address was {PreviousRegistration}" + )] + private static partial void LogPreviousActivationAddress(ILogger logger, GrainAddress previousRegistration); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Rehydrated grain from previous activation" + )] + private static partial void LogRehydratedGrain(ILogger logger); + + [LoggerMessage( + Level = LogLevel.Error, + Message = "Error while rehydrating activation" + )] + private static partial void LogErrorRehydratingActivation(ILogger logger, Exception exception); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Dehydrating grain activation" + )] + private static partial void LogDehydratingActivation(ILogger logger); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Dehydrated grain activation" + )] + private static partial void LogDehydratedActivation(ILogger logger); + + [LoggerMessage( + EventId = (int)ErrorCode.Catalog_RerouteAllQueuedMessages, + Level = LogLevel.Debug, + Message = "Rejecting {Count} messages from invalid activation {Activation}." + )] + private static partial void LogRejectAllQueuedMessages(ILogger logger, int count, ActivationData activation); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Registering grain '{Grain}' in activation directory. Previous known registration is '{PreviousRegistration}'.")] + private static partial void LogRegisteringGrain(ILogger logger, ActivationData grain, GrainAddress? previousRegistration); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "The grain directory has an existing entry pointing to a different activation of this grain, '{GrainId}', on this silo: '{PreviousRegistration}'." + + " This may indicate that the previous activation was deactivated but the directory was not successfully updated." + + " The directory will be updated to point to this activation." + )] + private static partial void LogAttemptToRegisterWithPreviousActivation(ILogger logger, GrainId grainId, GrainAddress previousRegistration); + + [LoggerMessage( + EventId = (int)ErrorCode.Dispatcher_ExtendedMessageProcessing, + Level = LogLevel.Warning, + Message = "Current request has been active for {CurrentRequestActiveTime} for grain {Grain}. Currently executing {BlockingRequest}. Trying to enqueue {Message}.")] + private static partial void LogWarningDispatcher_ExtendedMessageProcessing( + ILogger logger, + TimeSpan currentRequestActiveTime, + ActivationDataLogValue grain, + Message blockingRequest, + Message message); + + private readonly struct ActivationDataLogValue(ActivationData activation, bool includeExtraDetails = false) + { + public override string ToString() => activation.ToDetailedString(includeExtraDetails); + } + + [LoggerMessage( + EventId = (int)ErrorCode.Runtime_Error_100064, + Level = LogLevel.Warning, + Message = "Failed to register grain {Grain} in grain directory")] + private static partial void LogFailedToRegisterGrain(ILogger logger, Exception exception, ActivationData grain); + + [LoggerMessage( + EventId = (int)ErrorCode.Catalog_BeforeCallingActivate, + Level = LogLevel.Debug, + Message = "Activating grain {Grain}")] + private static partial void LogActivatingGrain(ILogger logger, ActivationData grain); + + [LoggerMessage( + Level = LogLevel.Error, + Message = "Error starting lifecycle for activation '{Activation}'")] + private static partial void LogErrorStartingLifecycle(ILogger logger, Exception exception, ActivationData activation); + + [LoggerMessage( + Level = LogLevel.Error, + Message = "Error thrown from {MethodName} for activation '{Activation}'")] + private static partial void LogErrorInGrainMethod(ILogger logger, Exception exception, string methodName, ActivationData activation); + + [LoggerMessage( + EventId = (int)ErrorCode.Catalog_AfterCallingActivate, + Level = LogLevel.Debug, + Message = "Finished activating grain {Grain}")] + private static partial void LogFinishedActivatingGrain(ILogger logger, ActivationData grain); + + [LoggerMessage( + EventId = (int)ErrorCode.Catalog_ErrorCallingActivate, + Level = LogLevel.Error, + Message = "Error activating grain {Grain}")] + private static partial void LogErrorActivatingGrain(ILogger logger, Exception exception, ActivationData grain); + + [LoggerMessage( + Level = LogLevel.Error, + Message = "Activation of grain {Grain} failed")] + private static partial void LogActivationFailed(ILogger logger, Exception exception, ActivationData grain); + + [LoggerMessage( + Level = LogLevel.Trace, + Message = "Completing deactivation of '{Activation}'")] + private static partial void LogCompletingDeactivation(ILogger logger, ActivationData activation); + + [LoggerMessage( + EventId = (int)ErrorCode.Catalog_BeforeCallingDeactivate, + Level = LogLevel.Debug, + Message = "About to call OnDeactivateAsync for '{Activation}'")] + private static partial void LogBeforeOnDeactivateAsync(ILogger logger, ActivationData activation); + + [LoggerMessage( + EventId = (int)ErrorCode.Catalog_AfterCallingDeactivate, + Level = LogLevel.Debug, + Message = "Returned from calling '{Activation}' OnDeactivateAsync method")] + private static partial void LogAfterOnDeactivateAsync(ILogger logger, ActivationData activation); + + [LoggerMessage( + Level = LogLevel.Error, + Message = "Failed to unregister activation '{Activation}' from directory")] + private static partial void LogFailedToUnregisterActivation(ILogger logger, Exception exception, ActivationData activation); + + [LoggerMessage( + EventId = (int)ErrorCode.Catalog_DeactivateActivation_Exception, + Level = LogLevel.Warning, + Message = "Error deactivating '{Activation}'")] + private static partial void LogErrorDeactivating(ILogger logger, Exception exception, ActivationData activation); + + [LoggerMessage( + Level = LogLevel.Warning, + Message = "Exception disposing activation '{Activation}'")] + private static partial void LogExceptionDisposing(ILogger logger, Exception exception, ActivationData activation); + + [LoggerMessage( + Level = LogLevel.Warning, + Message = "Failed to migrate activation '{Activation}'")] + private static partial void LogFailedToMigrateActivation(ILogger logger, Exception exception, ActivationData activation); + + [LoggerMessage( + EventId = (int)ErrorCode.Catalog_DuplicateActivation, + Level = LogLevel.Debug, + Message = "Tried to create a duplicate activation {Address}, but we'll use {ForwardingAddress} instead. GrainInstance type is {GrainInstanceType}. Full activation address is {FullAddress}. We have {WaitingCount} messages to forward")] + private static partial void LogDuplicateActivation( + ILogger logger, + GrainAddress address, + SiloAddress? forwardingAddress, + Type? grainInstanceType, + string fullAddress, + int waitingCount); + + [LoggerMessage( + EventId = (int)ErrorCode.Catalog_RerouteAllQueuedMessages, + Level = LogLevel.Debug, + Message = "Rerouting {NumMessages} messages from invalid grain activation {Grain} to {ForwardingAddress}")] + private static partial void LogReroutingMessages(ILogger logger, int numMessages, ActivationData grain, SiloAddress forwardingAddress); + + [LoggerMessage( + EventId = (int)ErrorCode.Catalog_RerouteAllQueuedMessages, + Level = LogLevel.Debug, + Message = "Rerouting {NumMessages} messages from invalid grain activation {Grain}")] + private static partial void LogReroutingMessagesNoForwarding(ILogger logger, int numMessages, ActivationData grain); } diff --git a/src/Orleans.Runtime/Catalog/ActivationMigrationManager.cs b/src/Orleans.Runtime/Catalog/ActivationMigrationManager.cs index 0d78691503..d0335d9a95 100644 --- a/src/Orleans.Runtime/Catalog/ActivationMigrationManager.cs +++ b/src/Orleans.Runtime/Catalog/ActivationMigrationManager.cs @@ -53,7 +53,7 @@ internal interface IActivationMigrationManager /// /// Migrates grain activations to target hosts and handles migration requests from other hosts. /// -internal class ActivationMigrationManager : SystemTarget, IActivationMigrationManagerSystemTarget, IActivationMigrationManager, ILifecycleParticipant +internal partial class ActivationMigrationManager : SystemTarget, IActivationMigrationManagerSystemTarget, IActivationMigrationManager, ILifecycleParticipant { private const int MaxBatchSize = 1_000; private readonly ConcurrentDictionary WorkItemChannel)> _workers = new(); @@ -153,10 +153,7 @@ private async Task ProcessMembershipUpdates() try { - if (_logger.IsEnabled(LogLevel.Debug)) - { - _logger.LogDebug("Monitoring cluster membership updates"); - } + LogDebugMonitoringUpdates(); 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"); + LogErrorProcessingMembershipUpdates(exception); } } } finally { - if (_logger.IsEnabled(LogLevel.Debug)) - { - _logger.LogDebug("No longer monitoring cluster membership updates"); - } + LogDebugNoLongerMonitoring(); } } @@ -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); - } + LogDebugStartingWorker(targetSilo); var items = new List(); var batch = new List(); @@ -222,16 +213,13 @@ private async Task PumpMigrationQueue(SiloAddress targetSilo, Channel _silo = silo; + public override string ToString() => _silo.ToStringWithHashCode(); + } + + // Logger methods at end of class + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Monitoring cluster membership updates")] + private partial void LogDebugMonitoringUpdates(); + + [LoggerMessage( + Level = LogLevel.Error, + Message = "Error processing cluster membership updates" + )] + private partial void LogErrorProcessingMembershipUpdates(Exception exception); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "No longer monitoring cluster membership updates")] + private partial void LogDebugNoLongerMonitoring(); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Starting migration worker for target silo {SiloAddress}")] + private partial void LogDebugStartingWorker(SiloAddress siloAddress); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Migrated {Count} activations to target silo {SiloAddress}")] + private partial void LogDebugMigratedActivations(int count, SiloAddress siloAddress); + + [LoggerMessage( + Level = LogLevel.Error, + Message = "Error while migrating {Count} grain activations to {SiloAddress}")] + private partial void LogErrorMigratingActivations(Exception exception, int count, SiloAddress siloAddress); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Exiting migration worker for target silo {SiloAddress}")] + private partial void LogDebugExitingWorker(SiloAddress siloAddress); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Target silo {SiloAddress} is no longer active, so this migration activation worker is terminating" + )] + private partial void LogDebugTargetSilo(SiloAddress siloAddress); + + [LoggerMessage( + Level = LogLevel.Warning, + Message = "Error signaling shutdown" + )] + private partial void LogWarningSignalShutdownError(Exception exception); } diff --git a/src/Orleans.Runtime/Catalog/ActivationWorkingSet.cs b/src/Orleans.Runtime/Catalog/ActivationWorkingSet.cs index d6e274bf63..862006ea6d 100644 --- a/src/Orleans.Runtime/Catalog/ActivationWorkingSet.cs +++ b/src/Orleans.Runtime/Catalog/ActivationWorkingSet.cs @@ -14,7 +14,7 @@ namespace Orleans.Runtime /// /// Maintains a list of activations which are recently active. /// - internal sealed class ActivationWorkingSet : IActivationWorkingSet, ILifecycleParticipant + internal sealed partial class ActivationWorkingSet : IActivationWorkingSet, ILifecycleParticipant { private class MemberState { @@ -118,7 +118,7 @@ private async Task MonitorWorkingSet() } catch (Exception exception) { - _logger.LogError(exception, "Exception visiting working set member {Member}", pair.Key); + LogExceptionVisitingWorkingSetMember(exception, pair.Key); } } } @@ -172,6 +172,12 @@ void ILifecycleParticipant.Participate(ISiloLifecycle lifecycle) } }); } + + [LoggerMessage( + Level = LogLevel.Error, + Message = "Exception visiting working set member {Member}" + )] + private partial void LogExceptionVisitingWorkingSetMember(Exception exception, IActivationWorkingSetMember member); } /// diff --git a/src/Orleans.Runtime/Catalog/Catalog.cs b/src/Orleans.Runtime/Catalog/Catalog.cs index 9f6e436fdf..91b433005d 100644 --- a/src/Orleans.Runtime/Catalog/Catalog.cs +++ b/src/Orleans.Runtime/Catalog/Catalog.cs @@ -13,7 +13,7 @@ namespace Orleans.Runtime { - internal sealed class Catalog : SystemTarget, ICatalog + internal sealed partial class Catalog : SystemTarget, ICatalog { public SiloAddress LocalSilo { get; private set; } internal ISiloStatusOracle SiloStatusOracle { get; set; } @@ -69,10 +69,7 @@ public void UnregisterMessageTarget(IGrainContext activation) { if (activations.RemoveTarget(activation)) { - if (logger.IsEnabled(LogLevel.Trace)) - { - logger.LogTrace("Unregistered activation {Activation}", activation); - } + LogTraceUnregisteredActivation(activation); // this should be removed once we've refactored the deactivation code path. For now safe to keep. if (activation is ICollectibleGrainContext collectibleActivation) @@ -195,16 +192,13 @@ static IGrainContext UnableToCreateActivation(Catalog self, GrainId grainId) { // Did not find and did not start placing new var isTerminating = self.SiloStatusOracle.CurrentStatus.IsTerminating(); - if (self.logger.IsEnabled(LogLevel.Debug)) + if (isTerminating) { - if (isTerminating) - { - self.logger.LogDebug((int)ErrorCode.CatalogNonExistingActivation2, "Unable to create activation for grain {GrainId} because this silo is terminating", grainId); - } - else - { - self.logger.LogDebug((int)ErrorCode.CatalogNonExistingActivation2, "Unable to create activation for grain {GrainId}", grainId); - } + self.LogDebugUnableToCreateActivationTerminating(grainId); + } + else + { + self.LogDebugUnableToCreateActivation(grainId); } CatalogInstruments.NonExistentActivations.Add(1); @@ -235,11 +229,7 @@ private async Task UnregisterNonExistentActivation(GrainAddress address) } catch (Exception exc) { - logger.LogWarning( - (int)ErrorCode.Dispatcher_FailedToUnregisterNonExistingAct, - exc, - "Failed to unregister non-existent activation {Address}", - address); + LogFailedToUnregisterNonExistingActivation(address, exc); } } @@ -261,7 +251,7 @@ internal async Task DeactivateActivations(DeactivationReason reason, List public async Task DeactivateAllActivations(CancellationToken cancellationToken) { - if (logger.IsEnabled(LogLevel.Debug)) - { - logger.LogDebug((int)ErrorCode.Catalog_DeactivateAllActivations, "DeactivateAllActivations."); - } - - if (logger.IsEnabled(LogLevel.Debug)) logger.LogDebug("DeactivateActivations: {Count} activations.", activations.Count); + LogDebugDeactivateAllActivations(); + LogDebugDeactivateActivations(activations.Count); var reason = new DeactivationReason(DeactivationReasonCode.ShuttingDown, "This process is terminating."); var options = new ParallelOptions { @@ -366,21 +352,14 @@ internal void OnSiloStatusChange(ILocalGrainDirectory directory, SiloAddress upd } catch (Exception exc) { - logger.LogError( - (int)ErrorCode.Catalog_SiloStatusChangeNotification_Exception, - exc, - "Catalog has thrown an exception while handling removal of silo {Silo}", updatedSilo.ToStringWithHashCode()); + LogErrorCatalogSiloStatusChangeNotification(new(updatedSilo), exc); } } } if (activationsToShutdown.Count > 0) { - logger.LogInformation( - (int)ErrorCode.Catalog_SiloStatusChangeNotification, - "Catalog is deactivating {Count} activations due to a failure of silo {Silo}, since it is a primary directory partition to these grain ids.", - activationsToShutdown.Count, - updatedSilo.ToStringWithHashCode()); + LogInfoCatalogSiloStatusChangeNotification(activationsToShutdown.Count, new(updatedSilo)); } } finally @@ -398,7 +377,7 @@ void StartDeactivatingActivations(DeactivationReason reason, List { if (list == null || list.Count == 0) return; - if (logger.IsEnabled(LogLevel.Debug)) logger.LogDebug("DeactivateActivations: {Count} activations.", list.Count); + LogDebugDeactivateActivations(list.Count); foreach (var activation in list) { @@ -406,5 +385,62 @@ void StartDeactivatingActivations(DeactivationReason reason, List } } } + + private readonly struct SiloAddressLogValue(SiloAddress silo) + { + public override string ToString() => silo.ToStringWithHashCode(); + } + + [LoggerMessage( + Level = LogLevel.Error, + EventId = (int)ErrorCode.Catalog_SiloStatusChangeNotification_Exception, + Message = "Catalog has thrown an exception while handling removal of silo {Silo}" + )] + private partial void LogErrorCatalogSiloStatusChangeNotification(SiloAddressLogValue silo, Exception exception); + + [LoggerMessage( + Level = LogLevel.Information, + EventId = (int)ErrorCode.Catalog_SiloStatusChangeNotification, + Message = "Catalog is deactivating {Count} activations due to a failure of silo {Silo}, since it is a primary directory partition to these grain ids." + )] + private partial void LogInfoCatalogSiloStatusChangeNotification(int count, SiloAddressLogValue silo); + + [LoggerMessage( + Level = LogLevel.Trace, + Message = "Unregistered activation {Activation}")] + private partial void LogTraceUnregisteredActivation(IGrainContext activation); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "DeactivateActivations: {Count} activations.")] + private partial void LogDebugDeactivateActivations(int count); + + [LoggerMessage( + Level = LogLevel.Debug, + EventId = (int)ErrorCode.Catalog_DeactivateAllActivations, + Message = "DeactivateAllActivations." + )] + private partial void LogDebugDeactivateAllActivations(); + + [LoggerMessage( + EventId = (int)ErrorCode.CatalogNonExistingActivation2, + Level = LogLevel.Debug, + Message = "Unable to create activation for grain {GrainId} because this silo is terminating")] + private partial void LogDebugUnableToCreateActivationTerminating(GrainId grainId); + + [LoggerMessage( + EventId = (int)ErrorCode.CatalogNonExistingActivation2, + Level = LogLevel.Debug, + Message = "Unable to create activation for grain {GrainId}" + )] + private partial void LogDebugUnableToCreateActivation(GrainId grainId); + + [LoggerMessage( + EventId = (int)ErrorCode.Dispatcher_FailedToUnregisterNonExistingAct, + Level = LogLevel.Warning, + Message = "Failed to unregister non-existent activation {Address}" + )] + private partial void LogFailedToUnregisterNonExistingActivation(GrainAddress address, Exception exception); + } } diff --git a/src/Orleans.Runtime/Catalog/StatelessWorkerGrainContext.cs b/src/Orleans.Runtime/Catalog/StatelessWorkerGrainContext.cs index bb21c74c08..2ab752d8af 100644 --- a/src/Orleans.Runtime/Catalog/StatelessWorkerGrainContext.cs +++ b/src/Orleans.Runtime/Catalog/StatelessWorkerGrainContext.cs @@ -9,7 +9,7 @@ namespace Orleans.Runtime { - internal class StatelessWorkerGrainContext : IGrainContext, IAsyncDisposable, IActivationLifecycleObserver + internal partial class StatelessWorkerGrainContext : IGrainContext, IAsyncDisposable, IActivationLifecycleObserver { private readonly GrainAddress _address; private readonly GrainTypeSharedContext _shared; @@ -169,7 +169,7 @@ private async Task RunMessageLoop() } catch (Exception exception) { - _shared.Logger.LogError(exception, "Error in stateless worker message loop"); + LogErrorInMessageLoop(_shared.Logger, exception); } } } @@ -342,5 +342,11 @@ private record ActivateWorkItemState(Dictionary? RequestContext, private record DeactivateWorkItemState(DeactivationReason DeactivationReason, CancellationToken CancellationToken); private record DeactivatedTaskWorkItemState(TaskCompletionSource Completion); private record DisposeAsyncWorkItemState(TaskCompletionSource Completion); + + [LoggerMessage( + Level = LogLevel.Error, + Message = "Error in stateless worker message loop" + )] + private static partial void LogErrorInMessageLoop(ILogger logger, Exception exception); } } diff --git a/src/Orleans.Runtime/ConsistentRing/VirtualBucketsRingProvider.cs b/src/Orleans.Runtime/ConsistentRing/VirtualBucketsRingProvider.cs index 614c707c9a..da49c917a8 100644 --- a/src/Orleans.Runtime/ConsistentRing/VirtualBucketsRingProvider.cs +++ b/src/Orleans.Runtime/ConsistentRing/VirtualBucketsRingProvider.cs @@ -12,7 +12,7 @@ namespace Orleans.Runtime.ConsistentRing /// Note: MembershipOracle uses 'forward/counter-clockwise' definition to assign responsibilities. /// E.g. in a ring of nodes {5, 10, 15}, the responsible of key 7 is node 5 (the node is responsible for its succeeding range). /// - internal sealed class VirtualBucketsRingProvider : + internal sealed partial class VirtualBucketsRingProvider : IConsistentRingProvider, ISiloStatusListener, IDisposable { private readonly List statusListeners = new(); @@ -40,10 +40,7 @@ internal VirtualBucketsRingProvider(SiloAddress siloAddress, ILoggerFactory logg myRange = RangeFactory.CreateFullRange(); lastNotification = (myRange, myRange, true); - if (logger.IsEnabled(LogLevel.Debug)) - { - logger.LogDebug("Starting {Name} on silo {SiloAddress}.", nameof(VirtualBucketsRingProvider), siloAddress.ToStringWithHashCode()); - } + LogDebugStarting(logger, nameof(VirtualBucketsRingProvider), new(siloAddress)); ConsistentRingInstruments.RegisterRingSizeObserve(() => GetRingSize()); ConsistentRingInstruments.RegisterMyRangeRingPercentageObserve(() => (float)((IRingRangeInternal)myRange).RangePercentage()); @@ -101,10 +98,7 @@ public bool UnSubscribeFromRangeChangeEvents(IRingRangeListener observer) private void NotifyLocalRangeSubscribers(IRingRange old, IRingRange now, bool increased) { - if (logger.IsEnabled(LogLevel.Trace)) - { - logger.LogTrace((int)ErrorCode.CRP_Notify, "NotifyLocalRangeSubscribers about old {Old} new {New} increased? {IsIncrease}", old.ToString(), now.ToString(), increased); - } + LogTraceNotifyLocalRangeSubscribers(logger, old, now, increased); IRingRangeListener[] copy; lock (statusListeners) @@ -120,14 +114,7 @@ private void NotifyLocalRangeSubscribers(IRingRange old, IRingRange now, bool in } catch (Exception exc) { - logger.LogWarning( - (int)ErrorCode.CRP_Local_Subscriber_Exception, - exc, - "Error notifying listener '{ListenerType}' of ring range {AdjustmentKind} from '{OldRange}' to '{NewRange}'.", - listener.GetType().FullName, - increased ? "expansion" : "contraction", - old, - now); + LogWarningErrorNotifyingListener(logger, exc, listener.GetType().FullName, increased ? "expansion" : "contraction", old, now); } } } @@ -149,10 +136,7 @@ private void AddServer(SiloAddress silo) var myOldRange = myRange; var myNewRange = UpdateRange(); - if (logger.IsEnabled(LogLevel.Trace)) - { - logger.LogTrace((int)ErrorCode.CRP_Added_Silo, "Added Server {SiloAddress}. Current view: {CurrentView}", silo.ToStringWithHashCode(), this.ToString()); - } + LogTraceAddedServer(logger, new(silo), this); NotifyLocalRangeSubscribers(myOldRange, myNewRange, true); } @@ -179,10 +163,7 @@ private void RemoveServer(SiloAddress silo) var myOldRange = this.myRange; var myNewRange = UpdateRange(); - if (logger.IsEnabled(LogLevel.Trace)) - { - logger.LogTrace((int)ErrorCode.CRP_Removed_Silo, "Removed Server {SiloAddress}. Current view: {CurrentView}", silo.ToStringWithHashCode(), this.ToString()); - } + LogTraceRemovedServer(logger, new(silo), this); NotifyLocalRangeSubscribers(myOldRange, myNewRange, true); } @@ -325,10 +306,7 @@ private SiloAddress CalculateTargetSilo(uint hash, bool excludeThisSiloIfStoppin } } - if (logger.IsEnabled(LogLevel.Trace)) - { - logger.LogTrace("Calculated ring partition owner silo {Owner} for key {Key}: {Key} --> {OwnerHash}", s.SiloAddress, hash, hash, s.Hash); - } + LogTraceCalculatedRingPartitionOwner(logger, s.SiloAddress, hash, s.Hash); return s.SiloAddress; } @@ -337,6 +315,58 @@ public void Dispose() { _siloStatusOracle.UnSubscribeFromSiloStatusEvents(this); } + + private readonly struct SiloAddressLogValue + { + private readonly SiloAddress _siloAddress; + + public SiloAddressLogValue(SiloAddress siloAddress) + { + _siloAddress = siloAddress; + } + + public override string ToString() => _siloAddress.ToStringWithHashCode(); + } + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Starting {Name} on silo {SiloAddress}." + )] + private static partial void LogDebugStarting(ILogger logger, string name, SiloAddressLogValue siloAddress); + + [LoggerMessage( + EventId = (int)ErrorCode.CRP_Notify, + Level = LogLevel.Trace, + Message = "NotifyLocalRangeSubscribers about old {Old} new {New} increased? {IsIncrease}" + )] + private static partial void LogTraceNotifyLocalRangeSubscribers(ILogger logger, IRingRange old, IRingRange @new, bool isIncrease); + + [LoggerMessage( + EventId = (int)ErrorCode.CRP_Local_Subscriber_Exception, + Level = LogLevel.Warning, + Message = "Error notifying listener '{ListenerType}' of ring range {AdjustmentKind} from '{OldRange}' to '{NewRange}'." + )] + private static partial void LogWarningErrorNotifyingListener(ILogger logger, Exception exception, string listenerType, string adjustmentKind, IRingRange oldRange, IRingRange newRange); + + [LoggerMessage( + EventId = (int)ErrorCode.CRP_Added_Silo, + Level = LogLevel.Trace, + Message = "Added Server {SiloAddress}. Current view: {CurrentView}" + )] + private static partial void LogTraceAddedServer(ILogger logger, SiloAddressLogValue siloAddress, VirtualBucketsRingProvider currentView); + + [LoggerMessage( + EventId = (int)ErrorCode.CRP_Removed_Silo, + Level = LogLevel.Trace, + Message = "Removed Server {SiloAddress}. Current view: {CurrentView}" + )] + private static partial void LogTraceRemovedServer(ILogger logger, SiloAddressLogValue siloAddress, VirtualBucketsRingProvider currentView); + + [LoggerMessage( + Level = LogLevel.Trace, + Message = "Calculated ring partition owner silo {Owner} for key {Key}: {Key} --> {OwnerHash}" + )] + private static partial void LogTraceCalculatedRingPartitionOwner(ILogger logger, SiloAddress owner, uint key, uint ownerHash); } } diff --git a/src/Orleans.Runtime/Core/HostedClient.cs b/src/Orleans.Runtime/Core/HostedClient.cs index 273610ecce..debd301929 100644 --- a/src/Orleans.Runtime/Core/HostedClient.cs +++ b/src/Orleans.Runtime/Core/HostedClient.cs @@ -19,7 +19,7 @@ namespace Orleans.Runtime /// /// A client which is hosted within a silo. /// - internal sealed class HostedClient : IGrainContext, IGrainExtensionBinder, IDisposable, ILifecycleParticipant + internal sealed partial class HostedClient : IGrainContext, IGrainExtensionBinder, IDisposable, ILifecycleParticipant { private readonly object lockObj = new object(); private readonly Channel incomingMessages; @@ -240,10 +240,7 @@ private async Task RunClientMessagePump() var more = await reader.WaitToReadAsync(); if (!more) { - if (this.logger.IsEnabled(LogLevel.Debug)) - { - this.logger.LogDebug($"{nameof(Runtime.HostedClient)} completed processing all messages. Shutting down."); - } + LogDebugShuttingDown(this.logger); break; } @@ -257,14 +254,14 @@ private async Task RunClientMessagePump() this.invokableObjects.Dispatch(message); break; default: - this.logger.LogError((int)ErrorCode.Runtime_Error_100327, "Message not supported: {Message}", message); + LogErrorUnsupportedMessage(this.logger, message); break; } } } catch (Exception exception) { - this.logger.LogError((int)ErrorCode.Runtime_Error_100326, exception, "RunClientMessagePump has thrown an exception. Continuing."); + LogErrorMessagePumpException(this.logger, exception); } } } @@ -398,5 +395,22 @@ 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. } + + [LoggerMessage( + Level = LogLevel.Debug, + Message = $"{nameof(Runtime.HostedClient)} completed processing all messages. Shutting down.")] + private static partial void LogDebugShuttingDown(ILogger logger); + + [LoggerMessage( + EventId = (int)ErrorCode.Runtime_Error_100327, + Level = LogLevel.Error, + Message = "Message not supported: {Message}")] + private static partial void LogErrorUnsupportedMessage(ILogger logger, Message message); + + [LoggerMessage( + EventId = (int)ErrorCode.Runtime_Error_100326, + Level = LogLevel.Error, + Message = "RunClientMessagePump has thrown an exception. Continuing.")] + private static partial void LogErrorMessagePumpException(ILogger logger, Exception exception); } } \ No newline at end of file diff --git a/src/Orleans.Runtime/Core/InsideRuntimeClient.cs b/src/Orleans.Runtime/Core/InsideRuntimeClient.cs index d3069636fc..e4eb99279a 100644 --- a/src/Orleans.Runtime/Core/InsideRuntimeClient.cs +++ b/src/Orleans.Runtime/Core/InsideRuntimeClient.cs @@ -24,7 +24,7 @@ namespace Orleans.Runtime /// /// Internal class for system grains to get access to runtime object /// - internal sealed class InsideRuntimeClient : IRuntimeClient, ILifecycleParticipant + internal sealed partial class InsideRuntimeClient : IRuntimeClient, ILifecycleParticipant { private readonly ILogger logger; private readonly ILogger invokeExceptionLogger; @@ -232,7 +232,7 @@ public void SniffIncomingMessage(Message message) } catch (Exception exc) { - this.logger.LogWarning((int)ErrorCode.IGC_SniffIncomingMessage_Exc, exc, "SniffIncomingMessage has thrown exception. Ignoring."); + LogWarningSniffIncomingMessage(this.logger, exc); } } @@ -285,16 +285,7 @@ public async Task Invoke(IGrainContext target, Message message) if (response.Exception is { } invocationException) { - if (message.Direction == Message.Directions.OneWay || invokeExceptionLogger.IsEnabled(LogLevel.Debug)) - { - var logLevel = message.Direction != Message.Directions.OneWay ? LogLevel.Debug : LogLevel.Warning; - this.invokeExceptionLogger.Log( - logLevel, - (int)ErrorCode.GrainInvokeException, - invocationException, - "Exception during Grain method call of message {Message}: ", - message); - } + LogGrainInvokeException(this.invokeExceptionLogger, message.Direction != Message.Directions.OneWay ? LogLevel.Debug : LogLevel.Warning, invocationException, message); // If a grain allowed an inconsistent state exception to escape and the exception originated from // this activation, then deactivate it. @@ -303,7 +294,7 @@ public async Task Invoke(IGrainContext target, Message message) // Mark the exception so that it doesn't deactivate any other activations. ise.IsSourceActivation = false; - this.invokeExceptionLogger.LogInformation("Deactivating {Target} due to inconsistent state.", target); + LogDeactivatingInconsistentState(this.invokeExceptionLogger, target, invocationException); target.Deactivate(new DeactivationReason(DeactivationReasonCode.ApplicationError, LogFormatter.PrintException(invocationException))); } } @@ -317,7 +308,7 @@ public async Task Invoke(IGrainContext target, Message message) } catch (Exception exc2) { - this.logger.LogWarning((int)ErrorCode.Runtime_Error_100329, exc2, "Exception during Invoke of message {Message}", message); + LogWarningInvokeException(this.logger, exc2, message); if (message.Direction != Message.Directions.OneWay) { @@ -334,10 +325,7 @@ private void SafeSendResponse(Message message, Response response) } catch (Exception exc) { - this.logger.LogWarning( - (int)ErrorCode.IGC_SendResponseFailed, - exc, - "Exception trying to send a response"); + LogWarningResponseFailed(this.logger, exc); SendResponse(message, Response.FromException(exc)); } } @@ -352,18 +340,12 @@ private void SafeSendExceptionResponse(Message message, Exception ex) { try { - this.logger.LogWarning( - (int)ErrorCode.IGC_SendExceptionResponseFailed, - exc1, - "Exception trying to send an exception response"); + LogWarningSendExceptionResponseFailed(this.logger, exc1); SendResponse(message, Response.FromException(exc1)); } catch (Exception exc2) { - this.logger.LogWarning( - (int)ErrorCode.IGC_UnhandledExceptionInInvoke, - exc2, - "Exception trying to send an exception. Ignoring and not trying to send again."); + LogWarningUnhandledExceptionInInvoke(this.logger, exc2); } } } @@ -376,12 +358,12 @@ public void ReceiveResponse(Message message) if (!message.TargetSilo.Matches(this.MySilo)) { // gatewayed message - gateway back to sender - if (logger.IsEnabled(LogLevel.Trace)) this.logger.LogTrace((int)ErrorCode.Dispatcher_NoCallbackForRejectionResp, "No callback for rejection response message: {Message}", message); + LogTraceNoCallbackForRejection(this.logger, message); this.MessageCenter.AddressAndSendMessage(message); return; } - if (logger.IsEnabled(LogLevel.Debug)) this.logger.LogDebug((int)ErrorCode.Dispatcher_HandleMsg, "HandleMessage {Message}", message); + LogHandleMessage(this.logger, message); var rejection = (RejectionResponse)message.BodyObject; switch (rejection.RejectionType) { @@ -402,10 +384,7 @@ public void ReceiveResponse(Message message) // The message targeted an invalid (eg, defunct) activation and this response serves only to invalidate this silo's activation cache. return; default: - this.logger.LogError( - (int)ErrorCode.Dispatcher_InvalidEnum_RejectionType, - "Unsupported rejection type: {RejectionType}", - rejection.RejectionType); + LogErrorUnsupportedRejectionType(this.logger, rejection.RejectionType); break; } } @@ -417,18 +396,16 @@ public void ReceiveResponse(Message message) if (!(request is null)) { callback.OnStatusUpdate(status); - if (status.Diagnostics != null && status.Diagnostics.Count > 0 && logger.IsEnabled(LogLevel.Information)) + if (status.Diagnostics != null && status.Diagnostics.Count > 0) { - var diagnosticsString = string.Join("\n", status.Diagnostics); - this.logger.LogInformation("Received status update for pending request, Request: {RequestMessage}. Status: {Diagnostics}", request, diagnosticsString); + LogInformationReceivedStatusUpdate(this.logger, request, status.Diagnostics); } } else { - if (status.Diagnostics != null && status.Diagnostics.Count > 0 && logger.IsEnabled(LogLevel.Information)) + if (status.Diagnostics != null && status.Diagnostics.Count > 0) { - var diagnosticsString = string.Join("\n", status.Diagnostics); - this.logger.LogInformation("Received status update for unknown request. Message: {StatusMessage}. Status: {Diagnostics}", message, diagnosticsString); + LogInformationReceivedStatusUpdateUnknownRequest(this.logger, message, status.Diagnostics); } } @@ -445,10 +422,7 @@ public void ReceiveResponse(Message message) } else { - if (logger.IsEnabled(LogLevel.Debug)) - { - this.logger.LogDebug((int)ErrorCode.Dispatcher_NoCallbackForResp, "No callback for response message {Message}", message); - } + LogDebugNoCallbackForResponse(this.logger, message); } } @@ -494,16 +468,18 @@ private Task OnRuntimeInitializeStart(CancellationToken tc) var stopWatch = ValueStopwatch.StartNew(); this.callbackTimerTask = Task.Run(MonitorCallbackExpiry); - if (logger.IsEnabled(LogLevel.Debug)) + LogDebugSiloStartPerfMeasure(this.logger, new(stopWatch)); + + return Task.CompletedTask; + } + + private readonly struct ValueStopwatchLogValue(ValueStopwatch stopWatch) + { + override public string ToString() { stopWatch.Stop(); - this.logger.LogInformation( - (int)ErrorCode.SiloStartPerfMeasure, - "Start InsideRuntimeClient took {ElapsedMs} milliseconds", - stopWatch.Elapsed.TotalMilliseconds); + return stopWatch.Elapsed.ToString(); } - - return Task.CompletedTask; } public void BreakOutstandingMessagesToSilo(SiloAddress deadSilo) @@ -547,9 +523,96 @@ private async Task MonitorCallbackExpiry() } catch (Exception ex) { - logger.LogWarning(ex, "Error while processing callback expiry."); + LogWarningWhileProcessingCallbackExpiry(this.logger, ex); } } } + + [LoggerMessage( + Level = LogLevel.Warning, + EventId = (int)ErrorCode.IGC_SniffIncomingMessage_Exc, + Message = "SniffIncomingMessage has thrown exception. Ignoring.")] + private static partial void LogWarningSniffIncomingMessage(ILogger logger, Exception exception); + + [LoggerMessage( + EventId = (int)ErrorCode.GrainInvokeException, + Message = "Exception during Grain method call of message {Message}: ")] + private static partial void LogGrainInvokeException(ILogger logger, LogLevel level, Exception exception, Message message); + + [LoggerMessage( + Level = LogLevel.Warning, + EventId = (int)ErrorCode.Runtime_Error_100329, + Message = "Exception during Invoke of message {Message}")] + private static partial void LogWarningInvokeException(ILogger logger, Exception exception, Message message); + + [LoggerMessage( + Level = LogLevel.Warning, + EventId = (int)ErrorCode.IGC_SendResponseFailed, + Message = "Exception trying to send a response")] + private static partial void LogWarningResponseFailed(ILogger logger, Exception exception); + + [LoggerMessage( + Level = LogLevel.Warning, + EventId = (int)ErrorCode.IGC_SendExceptionResponseFailed, + Message = "Exception trying to send an exception response")] + private static partial void LogWarningSendExceptionResponseFailed(ILogger logger, Exception exception); + + [LoggerMessage( + Level = LogLevel.Warning, + EventId = (int)ErrorCode.IGC_UnhandledExceptionInInvoke, + Message = "Exception trying to send an exception. Ignoring and not trying to send again.")] + private static partial void LogWarningUnhandledExceptionInInvoke(ILogger logger, Exception exception); + + [LoggerMessage( + Level = LogLevel.Trace, + EventId = (int)ErrorCode.Dispatcher_NoCallbackForRejectionResp, + Message = "No callback for rejection response message: {Message}")] + private static partial void LogTraceNoCallbackForRejection(ILogger logger, Message message); + + [LoggerMessage( + Level = LogLevel.Debug, + EventId = (int)ErrorCode.Dispatcher_HandleMsg, + Message = "HandleMessage {Message}")] + private static partial void LogHandleMessage(ILogger logger, Message message); + + [LoggerMessage( + Level = LogLevel.Information, + Message = "Deactivating {Target} due to inconsistent state.")] + private static partial void LogDeactivatingInconsistentState(ILogger logger, IGrainContext target, Exception exception); + + [LoggerMessage( + Level = LogLevel.Error, + EventId = (int)ErrorCode.Dispatcher_InvalidEnum_RejectionType, + Message = "Unsupported rejection type: {RejectionType}")] + private static partial void LogErrorUnsupportedRejectionType(ILogger logger, Message.RejectionTypes rejectionType); + + [LoggerMessage( + Level = LogLevel.Information, + Message = "Received status update for pending request, Request: {RequestMessage}. Status: {Diagnostics}")] + private static partial void LogInformationReceivedStatusUpdate(ILogger logger, Message requestMessage, IEnumerable diagnostics); + + [LoggerMessage( + Level = LogLevel.Information, + Message = "Received status update for unknown request. Message: {StatusMessage}. Status: {Diagnostics}")] + private static partial void LogInformationReceivedStatusUpdateUnknownRequest(ILogger logger, Message statusMessage, IEnumerable diagnostics); + + [LoggerMessage( + Level = LogLevel.Debug, + EventId = (int)ErrorCode.Dispatcher_NoCallbackForResp, + Message = "No callback for response message {Message}")] + private static partial void LogDebugNoCallbackForResponse(ILogger logger, Message message); + + [LoggerMessage( + Level = LogLevel.Debug, + EventId = (int)ErrorCode.SiloStartPerfMeasure, + Message = "Start InsideRuntimeClient took {ElapsedMs} milliseconds" + )] + private static partial void LogDebugSiloStartPerfMeasure(ILogger logger, ValueStopwatchLogValue elapsedMs); + + [LoggerMessage( + Level = LogLevel.Warning, + Message = "Error while processing callback expiry." + )] + private static partial void LogWarningWhileProcessingCallbackExpiry(ILogger logger, Exception exception); } } diff --git a/src/Orleans.Runtime/Core/ManagementGrain.cs b/src/Orleans.Runtime/Core/ManagementGrain.cs index 2bf11cc627..b49e6475f0 100644 --- a/src/Orleans.Runtime/Core/ManagementGrain.cs +++ b/src/Orleans.Runtime/Core/ManagementGrain.cs @@ -19,7 +19,7 @@ namespace Orleans.Runtime.Management /// Implementation class for the Orleans management grain. /// [StatelessWorker, Reentrant] - internal class ManagementGrain : Grain, IManagementGrain + internal partial class ManagementGrain : Grain, IManagementGrain { private readonly IInternalGrainFactory internalGrainFactory; private readonly ISiloStatusOracle siloStatusOracle; @@ -85,7 +85,7 @@ public async Task GetDetailedHosts(bool onlyActive = false) public Task ForceGarbageCollection(SiloAddress[] siloAddresses) { var silos = GetSiloAddresses(siloAddresses); - logger.LogInformation("Forcing garbage collection on {SiloAddresses}", Utils.EnumerableToString(silos)); + LogInformationForceGarbageCollection(new(silos)); List actionPromises = PerformPerSiloAction(silos, s => GetSiloControlReference(s).ForceGarbageCollection()); return Task.WhenAll(actionPromises); @@ -108,7 +108,7 @@ public async Task ForceActivationCollection(TimeSpan ageLimit) public Task ForceRuntimeStatisticsCollection(SiloAddress[] siloAddresses) { var silos = GetSiloAddresses(siloAddresses); - logger.LogInformation("Forcing runtime statistics collection on {SiloAddresses}", Utils.EnumerableToString(silos)); + LogInformationForceRuntimeStatisticsCollection(new(silos)); List actionPromises = PerformPerSiloAction( silos, s => GetSiloControlReference(s).ForceRuntimeStatisticsCollection()); @@ -118,7 +118,7 @@ public Task ForceRuntimeStatisticsCollection(SiloAddress[] siloAddresses) public Task GetRuntimeStatistics(SiloAddress[] siloAddresses) { var silos = GetSiloAddresses(siloAddresses); - if (logger.IsEnabled(LogLevel.Debug)) logger.LogDebug("GetRuntimeStatistics on {SiloAddresses}", Utils.EnumerableToString(silos)); + LogDebugGetRuntimeStatistics(new(silos)); var promises = new List>(); foreach (SiloAddress siloAddress in silos) promises.Add(GetSiloControlReference(siloAddress).GetRuntimeStatistics()); @@ -307,10 +307,7 @@ private async Task ExecutePerSiloCall(Func> { var silos = await GetHosts(true); - if (logger.IsEnabled(LogLevel.Debug)) - { - logger.LogDebug("Executing {Action} against {SiloAddresses}", actionToLog, Utils.EnumerableToString(silos.Keys)); - } + LogDebugExecutingAction(actionToLog, new(silos)); var actionPromises = new List>(); foreach (SiloAddress siloAddress in silos.Keys.ToArray()) @@ -414,5 +411,40 @@ public async ValueTask ResetGrainCallFrequencies(SiloAddress[] hostsIds = null) await siloBalancer.ResetCounters(); } } + + private readonly struct SiloAddressesLogValue(SiloAddress[] siloAddresses) + { + public override string ToString() => Utils.EnumerableToString(siloAddresses); + } + + [LoggerMessage( + EventId = 0, + Level = LogLevel.Information, + Message = "Forcing garbage collection on {SiloAddresses}")] + private partial void LogInformationForceGarbageCollection(SiloAddressesLogValue siloAddresses); + + [LoggerMessage( + EventId = 0, + Level = LogLevel.Information, + Message = "Forcing runtime statistics collection on {SiloAddresses}")] + private partial void LogInformationForceRuntimeStatisticsCollection(SiloAddressesLogValue siloAddresses); + + [LoggerMessage( + EventId = 0, + Level = LogLevel.Debug, + Message = "GetRuntimeStatistics on {SiloAddresses}")] + private partial void LogDebugGetRuntimeStatistics(SiloAddressesLogValue siloAddresses); + + private readonly struct SiloAddressesKeysLogValue(Dictionary silos) + { + public override string ToString() => Utils.EnumerableToString(silos.Keys); + } + + [LoggerMessage( + EventId = 0, + Level = LogLevel.Debug, + Message = "Executing {Action} against {SiloAddresses}" + )] + private partial void LogDebugExecutingAction(string action, SiloAddressesKeysLogValue siloAddresses); } } diff --git a/src/Orleans.Runtime/Core/SystemTarget.cs b/src/Orleans.Runtime/Core/SystemTarget.cs index c84bd40bcd..4382c8068b 100644 --- a/src/Orleans.Runtime/Core/SystemTarget.cs +++ b/src/Orleans.Runtime/Core/SystemTarget.cs @@ -17,7 +17,7 @@ namespace Orleans.Runtime /// Made public for GrainService to inherit from it. /// Can be turned to internal after a refactoring that would remove the inheritance relation. /// - public abstract class SystemTarget : ISystemTarget, ISystemTargetBase, IGrainContext, IGrainExtensionBinder, ISpanFormattable, IDisposable, IGrainTimerRegistry + public abstract partial class SystemTarget : ISystemTarget, ISystemTargetBase, IGrainContext, IGrainExtensionBinder, ISpanFormattable, IDisposable, IGrainTimerRegistry { private readonly SystemTargetGrainId id; private readonly HashSet _timers = []; @@ -328,7 +328,7 @@ public void ReceiveMessage(object message) } default: - this.logger.LogError((int)ErrorCode.Runtime_Error_100097, "Invalid message: {Message}", msg); + LogInvalidMessage(this.logger, msg); break; } } @@ -398,5 +398,12 @@ internal void CheckRuntimeContext() void ThrowAccessViolation(IGrainContext currentContext) => throw new InvalidOperationException($"Access violation: attempt to access context '{this}' from different context, '{currentContext}'."); } } + + [LoggerMessage( + Level = LogLevel.Error, + EventId = (int)ErrorCode.Runtime_Error_100097, + Message = "Invalid message: {Message}" + )] + private static partial void LogInvalidMessage(ILogger logger, Message Message); } } diff --git a/src/Orleans.Runtime/GrainDirectory/ClientDirectory.cs b/src/Orleans.Runtime/GrainDirectory/ClientDirectory.cs index 64d41f0f52..aea045c03c 100644 --- a/src/Orleans.Runtime/GrainDirectory/ClientDirectory.cs +++ b/src/Orleans.Runtime/GrainDirectory/ClientDirectory.cs @@ -29,7 +29,7 @@ namespace Orleans.Runtime.GrainDirectory; /// has updated. /// The process of removing defunct clients is left to the implementation on each silo. /// -internal sealed class ClientDirectory : SystemTarget, ILocalClientDirectory, IRemoteClientDirectory, ILifecycleParticipant +internal sealed partial class ClientDirectory : SystemTarget, ILocalClientDirectory, IRemoteClientDirectory, ILifecycleParticipant { private readonly SimpleConsistentRingProvider _consistentRing; private readonly IInternalGrainFactory _grainFactory; @@ -114,7 +114,7 @@ async ValueTask> LookupClientAsync(GrainId grainId) } catch (Exception exception) when (attemptsRemaining > 0) { - _logger.LogError(exception, "Exception calling remote client directory"); + LogErrorCallingRemoteClientDirectory(exception); } // Try again to find the requested client's routes. @@ -178,19 +178,12 @@ public Task OnUpdateClientRoutes(ImmutableDictionary(Constants.ClientDirectoryType, successor); await remote.OnUpdateClientRoutes(_table).WaitAsync(_shutdownCts.Token); @@ -514,10 +500,7 @@ private async Task PublishUpdates() _previousSuccessor = successor; } - if (_logger.IsEnabled(LogLevel.Debug)) - { - _logger.LogDebug("Successfully routes to {Silo}", successor); - } + LogDebugSuccessfullyPublishedRoutes(successor); _nextPublishTask = null; if (ShouldPublish()) @@ -527,7 +510,7 @@ private async Task PublishUpdates() } catch (Exception exception) { - _logger.LogError(exception, "Exception publishing client routing table to silo {SiloAddress}", successor); + LogErrorPublishingClientRoutingTableToSilo(exception, successor); } } @@ -564,4 +547,54 @@ internal class TestAccessor(ClientDirectory instance) public long ObservedConnectedClientsVersion { get => instance._observedConnectedClientsVersion; set => instance._observedConnectedClientsVersion = value; } public Task PublishUpdates() => instance.PublishUpdates(); } + + [LoggerMessage( + Level = LogLevel.Error, + Message = "Exception calling remote client directory" + )] + private partial void LogErrorCallingRemoteClientDirectory(Exception exception); + + [LoggerMessage( + EventId = 0, + Level = LogLevel.Error, + Message = "Exception publishing client routing table")] + private partial void LogErrorPublishingClientRoutingTable(Exception exception); + + [LoggerMessage( + EventId = 0, + Level = LogLevel.Debug, + Message = "Skipping publishing of routes because target silo already has them")] + private partial void LogDebugSkippingPublishingRoutes(); + + [LoggerMessage( + EventId = 0, + Level = LogLevel.Debug, + Message = "Publishing routes to {Silo}")] + private partial void LogDebugPublishingRoutes(SiloAddress silo); + + [LoggerMessage( + EventId = 0, + Level = LogLevel.Debug, + Message = "Successfully published routes to {Silo}")] + private partial void LogDebugSuccessfullyPublishedRoutes(SiloAddress silo); + + [LoggerMessage( + EventId = 0, + Level = LogLevel.Error, + Message = "Exception publishing client routing table to silo {SiloAddress}")] + private partial void LogErrorPublishingClientRoutingTableToSilo(Exception exception, SiloAddress siloAddress); + + [LoggerMessage( + EventId = 0, + Level = LogLevel.Debug, + Message = "Client table updated, publishing to successor" + )] + private partial void LogDebugClientTableUpdated(); + + [LoggerMessage( + EventId = 0, + Level = LogLevel.Debug, + Message = "Client table not updated" + )] + private partial void LogDebugClientTableNotUpdated(); } diff --git a/src/Orleans.Runtime/GrainDirectory/DirectoryMembershipService.cs b/src/Orleans.Runtime/GrainDirectory/DirectoryMembershipService.cs index cdf3585dc6..40c951b0b1 100644 --- a/src/Orleans.Runtime/GrainDirectory/DirectoryMembershipService.cs +++ b/src/Orleans.Runtime/GrainDirectory/DirectoryMembershipService.cs @@ -73,7 +73,7 @@ private async Task ProcessMembershipUpdates() { if (!_shutdownCts.IsCancellationRequested) { - _logger.LogError(exception, "Error processing membership updates."); + LogErrorProcessingMembershipUpdates(exception); } } } @@ -89,4 +89,10 @@ public async ValueTask DisposeAsync() _shutdownCts.Cancel(); await _runTask.SuppressThrowing(); } + + [LoggerMessage( + Level = LogLevel.Error, + Message = "Error processing membership updates." + )] + private partial void LogErrorProcessingMembershipUpdates(Exception exception); } diff --git a/src/Orleans.Runtime/GrainDirectory/DistributedGrainDirectory.cs b/src/Orleans.Runtime/GrainDirectory/DistributedGrainDirectory.cs index a78ca9bdf8..e355b35d25 100644 --- a/src/Orleans.Runtime/GrainDirectory/DistributedGrainDirectory.cs +++ b/src/Orleans.Runtime/GrainDirectory/DistributedGrainDirectory.cs @@ -189,10 +189,7 @@ private async Task InvokeAsync( continue; } - if (_logger.IsEnabled(LogLevel.Trace)) - { - _logger.LogTrace("Invoked '{Operation}' on '{Owner}' for grain '{GrainId}' and received result '{Result}'.", operation, owner, grainId, result); - } + LogTraceInvokedOperation(_logger, operation, owner, grainId, result); return result; } @@ -210,9 +207,9 @@ public async ValueTask>> RecoverRegisteredActivatio public async ValueTask>> GetRegisteredActivations(MembershipVersion membershipVersion, RingRange range, bool isValidation) { - if (!isValidation && _logger.IsEnabled(LogLevel.Debug)) + if (!isValidation) { - _logger.LogDebug("Collecting registered activations for range {Range} at version {MembershipVersion}.", range, membershipVersion); + LogDebugCollectingRegisteredActivations(_logger, range, membershipVersion); } var recoveryMembershipVersion = _recoveryMembershipVersion; @@ -257,14 +254,14 @@ public async ValueTask>> GetRegisteredActivations(M } catch (Exception exception) { - _logger.LogWarning(exception, "Failed to deactivate activation {Activation}", activation); + LogWarningFailedToDeactivateActivation(_logger, exception, activation); } } else { if (!isValidation) { - _logger.LogTrace("Sending activation '{Activation}' for recovery because its in the requested range {Range} (version {Version}).", activation.GrainId, range, membershipVersion); + LogTraceSendingActivationForRecovery(_logger, activation.GrainId, range, membershipVersion); } result.Add(activation.Address); @@ -274,15 +271,9 @@ public async ValueTask>> GetRegisteredActivations(M await Task.WhenAll(deactivationTasks); - if (!isValidation && _logger.IsEnabled(LogLevel.Debug)) + if (!isValidation) { - _logger.LogDebug( - "Submitting {Count} registered activations for range {Range} at version {MembershipVersion}. Deactivated {DeactivationCount} in-doubt registrations. Took {ElapsedMilliseconds}ms", - result.Count, - range, - membershipVersion, - deactivationTasks.Count, - stopwatch.ElapsedMilliseconds); + LogDebugSubmittingRegisteredActivations(_logger, result.Count, range, membershipVersion, deactivationTasks.Count, stopwatch.ElapsedMilliseconds); } return result.AsImmutable(); @@ -387,19 +378,10 @@ private async Task ProcessMembershipUpdates() tasks.Add(partition.ProcessMembershipUpdateAsync(current)); } - if (_logger.IsEnabled(LogLevel.Debug)) - { - var deltaSize = currentRanges.SizePercent - previousRanges.SizePercent; - var meanSizePercent = current.Members.Length > 0 ? 100.0 / current.Members.Length : 0f; - var deviationFromMean = Math.Abs(meanSizePercent - currentRanges.SizePercent); - _logger.LogDebug( - "Updated view from '{PreviousVersion}' to '{Version}'. Now responsible for {Range:0.00}% (Δ {DeltaPercent:0.00}%). {DeviationFromMean:0.00}% from ideal share.", - previous.Version, - current.Version, - currentRanges.SizePercent, - deltaSize, - deviationFromMean); - } + var deltaSize = currentRanges.SizePercent - previousRanges.SizePercent; + var meanSizePercent = current.Members.Length > 0 ? 100.0 / current.Members.Length : 0f; + var deviationFromMean = Math.Abs(meanSizePercent - currentRanges.SizePercent); + LogDebugUpdatedView(previous.Version, current.Version, currentRanges.SizePercent, deltaSize, deviationFromMean); previousUpdate = update.ClusterMembershipSnapshot; previous = current; @@ -410,7 +392,7 @@ private async Task ProcessMembershipUpdates() { if (!_stoppedCts.IsCancellationRequested) { - _logger.LogError(exception, "Error processing membership updates."); + LogErrorProcessingMembershipUpdates(exception); } } } @@ -444,4 +426,46 @@ internal interface ITestHooks SiloAddress? GetPrimaryForGrain(GrainId grainId); Task GetLocalRecord(GrainId grainId); } + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Updated view from '{PreviousVersion}' to '{Version}'. Now responsible for {Range:0.00}% (Δ {DeltaPercent:0.00}%). {DeviationFromMean:0.00}% from ideal share." + )] + private partial void LogDebugUpdatedView(MembershipVersion previousVersion, MembershipVersion version, double range, double deltaPercent, double deviationFromMean); + + [LoggerMessage( + Level = LogLevel.Error, + Message = "Error processing membership updates." + )] + private partial void LogErrorProcessingMembershipUpdates(Exception exception); + + [LoggerMessage( + Level = LogLevel.Trace, + Message = "Invoked '{Operation}' on '{Owner}' for grain '{GrainId}' and received result '{Result}'." + )] + private static partial void LogTraceInvokedOperation(ILogger logger, string operation, SiloAddress owner, GrainId grainId, object result); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Collecting registered activations for range {Range} at version {MembershipVersion}." + )] + private static partial void LogDebugCollectingRegisteredActivations(ILogger logger, RingRange range, MembershipVersion membershipVersion); + + [LoggerMessage( + Level = LogLevel.Warning, + Message = "Failed to deactivate activation {Activation}" + )] + private static partial void LogWarningFailedToDeactivateActivation(ILogger logger, Exception exception, IGrainContext activation); + + [LoggerMessage( + Level = LogLevel.Trace, + Message = "Sending activation '{Activation}' for recovery because its in the requested range {Range} (version {Version})." + )] + private static partial void LogTraceSendingActivationForRecovery(ILogger logger, GrainId activation, RingRange range, MembershipVersion version); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Submitting {Count} registered activations for range {Range} at version {MembershipVersion}. Deactivated {DeactivationCount} in-doubt registrations. Took {ElapsedMilliseconds}ms" + )] + private static partial void LogDebugSubmittingRegisteredActivations(ILogger logger, int count, RingRange range, MembershipVersion membershipVersion, int deactivationCount, long elapsedMilliseconds); } diff --git a/src/Orleans.Runtime/GrainDirectory/GrainDirectoryHandoffManager.cs b/src/Orleans.Runtime/GrainDirectory/GrainDirectoryHandoffManager.cs index 4fb70750f7..a6f21afc57 100644 --- a/src/Orleans.Runtime/GrainDirectory/GrainDirectoryHandoffManager.cs +++ b/src/Orleans.Runtime/GrainDirectory/GrainDirectoryHandoffManager.cs @@ -13,7 +13,7 @@ namespace Orleans.Runtime.GrainDirectory /// Most methods of this class are synchronized since they might be called both /// from LocalGrainDirectory on CacheValidator.SchedulingContext and from RemoteGrainDirectory. /// - internal sealed class GrainDirectoryHandoffManager + internal sealed partial class GrainDirectoryHandoffManager { private static readonly TimeSpan RetryDelay = TimeSpan.FromMilliseconds(250); private const int MAX_OPERATION_DEQUEUE = 2; @@ -43,7 +43,7 @@ internal void ProcessSiloAddEvent(SiloAddress addedSilo) { lock (this) { - if (logger.IsEnabled(LogLevel.Debug)) logger.LogDebug("Processing silo add event for {AddedSilo}", addedSilo); + LogDebugProcessingSiloAddEvent(logger, addedSilo); // check if this is our immediate successor (i.e., if I should hold this silo's copy) // (if yes, adjust local and/or copied directory partitions by splitting them between old successors and the new one) @@ -51,12 +51,12 @@ internal void ProcessSiloAddEvent(SiloAddress addedSilo) var successor = localDirectory.FindSuccessor(localDirectory.MyAddress); if (successor is null || !successor.Equals(addedSilo)) { - if (logger.IsEnabled(LogLevel.Debug)) logger.LogDebug("{AddedSilo} is not my immediate successor.", addedSilo); + LogDebugNotImmediateSuccessor(logger, addedSilo); return; } // split my local directory and send to my new immediate successor his share - if (logger.IsEnabled(LogLevel.Debug)) logger.LogDebug("Splitting my partition between me and {AddedSilo}", addedSilo); + LogDebugSplittingPartition(logger, addedSilo); var splitPartListSingle = localDirectory.DirectoryPartition.Split( grain => { @@ -77,20 +77,20 @@ private async Task ProcessAddedSiloAsync(SiloAddress addedSilo, List 0) { - if (logger.IsEnabled(LogLevel.Debug)) logger.LogDebug("Sending {Count} single activation entries to {AddedSilo}", splitPartListSingle.Count, addedSilo); + LogDebugSendingEntries(logger, splitPartListSingle.Count, addedSilo); } await localDirectory.GetDirectoryReference(addedSilo).AcceptSplitPartition(splitPartListSingle); } else { - if (logger.IsEnabled(LogLevel.Warning)) logger.LogWarning("Silo " + addedSilo + " is no longer active and therefore cannot receive this partition split"); + LogWarningSiloNotActive(logger, addedSilo); return; } if (splitPartListSingle.Count > 0) { - if (logger.IsEnabled(LogLevel.Debug)) logger.LogDebug("Removing {Count} single activation after partition split", splitPartListSingle.Count); + LogDebugRemovingEntries(logger, splitPartListSingle.Count); foreach (var activationAddress in splitPartListSingle) { @@ -110,10 +110,7 @@ private async Task AcceptExistingRegistrationsAsync(List singleAct { if (!this.localDirectory.Running) return; - if (this.logger.IsEnabled(LogLevel.Debug)) - { - this.logger.LogDebug($"{nameof(AcceptExistingRegistrations)}: accepting {{Count}} single-activation registrations", singleActivations.Count); - } + LogDebugAcceptingRegistrations(logger, singleActivations.Count); var tasks = singleActivations.Select(addr => this.localDirectory.RegisterAsync(addr, previousAddress: null, 1)).ToArray(); try @@ -122,8 +119,7 @@ private async Task AcceptExistingRegistrationsAsync(List singleAct } catch (Exception exception) { - if (this.logger.IsEnabled(LogLevel.Warning)) - this.logger.LogWarning(exception, $"Exception registering activations in {nameof(AcceptExistingRegistrations)}"); + LogWarningExceptionRegistering(logger, exception); throw; } finally @@ -165,14 +161,7 @@ private async Task DestroyDuplicateActivationsAsync(Dictionary _))); - } + LogDebugDestroyingDuplicates(logger, duplicates.Count, pair.Key, new(pair.Value)); var remoteCatalog = this.grainFactory.GetSystemTarget(Constants.CatalogType, pair.Key); await remoteCatalog.DeleteActivations(pair.Value, DeactivationReasonCode.DuplicateActivation, "This grain has been activated elsewhere"); @@ -222,14 +211,12 @@ private async Task ExecutePendingOperations() { if (dequeueCount < MAX_OPERATION_DEQUEUE) { - if (this.logger.IsEnabled(LogLevel.Warning)) - this.logger.LogWarning(exception, "{Operation} failed, will be retried", op.Name); + LogWarningOperationFailedRetry(logger, exception, op.Name); await Task.Delay(RetryDelay); } else { - if (this.logger.IsEnabled(LogLevel.Warning)) - this.logger.LogWarning(exception, "{Operation} failed, will NOT be retried", op.Name); + LogWarningOperationFailedNoRetry(logger, exception, op.Name); } } if (dequeueCount == 0 || dequeueCount >= MAX_OPERATION_DEQUEUE) @@ -244,5 +231,76 @@ private async Task ExecutePendingOperations() } } } + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Processing silo add event for {AddedSilo}" + )] + private static partial void LogDebugProcessingSiloAddEvent(ILogger logger, SiloAddress addedSilo); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "{AddedSilo} is not my immediate successor." + )] + private static partial void LogDebugNotImmediateSuccessor(ILogger logger, SiloAddress addedSilo); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Splitting my partition between me and {AddedSilo}" + )] + private static partial void LogDebugSplittingPartition(ILogger logger, SiloAddress addedSilo); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Sending {Count} single activation entries to {AddedSilo}" + )] + private static partial void LogDebugSendingEntries(ILogger logger, int count, SiloAddress addedSilo); + + [LoggerMessage( + Level = LogLevel.Warning, + Message = "Silo {AddedSilo} is no longer active and therefore cannot receive this partition split" + )] + private static partial void LogWarningSiloNotActive(ILogger logger, SiloAddress addedSilo); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Removing {Count} single activation after partition split" + )] + private static partial void LogDebugRemovingEntries(ILogger logger, int count); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = $"{nameof(AcceptExistingRegistrations)}: accepting {{Count}} single-activation registrations" + )] + private static partial void LogDebugAcceptingRegistrations(ILogger logger, int count); + + [LoggerMessage( + Level = LogLevel.Warning, + Message = $"Exception registering activations in {nameof(AcceptExistingRegistrations)}" + )] + private static partial void LogWarningExceptionRegistering(ILogger logger, Exception exception); + + private readonly struct GrainAddressesLogValue(List grainAddresses) + { + public override string ToString() => string.Join("\n * ", grainAddresses.Select(_ => _)); + } + + [LoggerMessage( + Level = LogLevel.Debug, + Message = $"{nameof(DestroyDuplicateActivations)} will destroy {{Count}} duplicate activations on silo {{SiloAddress}}: {{Duplicates}}" + )] + private static partial void LogDebugDestroyingDuplicates(ILogger logger, int count, SiloAddress siloAddress, GrainAddressesLogValue duplicates); + + [LoggerMessage( + Level = LogLevel.Warning, + Message = "{Operation} failed, will be retried" + )] + private static partial void LogWarningOperationFailedRetry(ILogger logger, Exception exception, string operation); + + [LoggerMessage( + Level = LogLevel.Warning, + Message = "{Operation} failed, will NOT be retried" + )] + private static partial void LogWarningOperationFailedNoRetry(ILogger logger, Exception exception, string operation); } } diff --git a/src/Orleans.Runtime/GrainDirectory/GrainDirectoryPartition.Interface.cs b/src/Orleans.Runtime/GrainDirectory/GrainDirectoryPartition.Interface.cs index 70053971d5..27a75f4d16 100644 --- a/src/Orleans.Runtime/GrainDirectory/GrainDirectoryPartition.Interface.cs +++ b/src/Orleans.Runtime/GrainDirectory/GrainDirectoryPartition.Interface.cs @@ -13,10 +13,7 @@ internal sealed partial class GrainDirectoryPartition async ValueTask> IGrainDirectoryPartition.RegisterAsync(MembershipVersion version, GrainAddress address, GrainAddress? currentRegistration) { ArgumentNullException.ThrowIfNull(address); - if (_logger.IsEnabled(LogLevel.Trace)) - { - _logger.LogTrace("RegisterAsync('{Version}', '{Address}', '{ExistingAddress}')", version, address, currentRegistration); - } + LogRegisterAsync(version, address, currentRegistration); // Ensure that the current membership version is new enough. await WaitForRange(address.GrainId, version); @@ -31,10 +28,7 @@ async ValueTask> IGrainDirectoryPartition.Register async ValueTask> IGrainDirectoryPartition.LookupAsync(MembershipVersion version, GrainId grainId) { - if (_logger.IsEnabled(LogLevel.Trace)) - { - _logger.LogTrace("LookupAsync('{Version}', '{GrainId}')", version, grainId); - } + LogLookupAsync(version, grainId); // Ensure we can serve the request. await WaitForRange(grainId, version); @@ -49,10 +43,7 @@ async ValueTask> IGrainDirectoryPartition.Register async ValueTask> IGrainDirectoryPartition.DeregisterAsync(MembershipVersion version, GrainAddress address) { ArgumentNullException.ThrowIfNull(address); - if (_logger.IsEnabled(LogLevel.Trace)) - { - _logger.LogTrace("DeregisterAsync('{Version}', '{Address}')", version, address); - } + LogDeregisterAsync(version, address); await WaitForRange(address.GrainId, version); if (!IsOwner(CurrentView, address.GrainId)) @@ -109,4 +100,22 @@ private GrainAddress RegisterCore(GrainAddress newAddress, GrainAddress? existin } private bool IsSiloDead(GrainAddress existing) => _owner.ClusterMembershipSnapshot.GetSiloStatus(existing.SiloAddress) == SiloStatus.Dead; + + [LoggerMessage( + Level = LogLevel.Trace, + Message = "RegisterAsync('{Version}', '{Address}', '{ExistingAddress}')" + )] + private partial void LogRegisterAsync(MembershipVersion version, GrainAddress address, GrainAddress? existingAddress); + + [LoggerMessage( + Level = LogLevel.Trace, + Message = "LookupAsync('{Version}', '{GrainId}')" + )] + private partial void LogLookupAsync(MembershipVersion version, GrainId grainId); + + [LoggerMessage( + Level = LogLevel.Trace, + Message = "DeregisterAsync('{Version}', '{Address}')" + )] + private partial void LogDeregisterAsync(MembershipVersion version, GrainAddress address); } diff --git a/src/Orleans.Runtime/GrainDirectory/GrainDirectoryPartition.cs b/src/Orleans.Runtime/GrainDirectory/GrainDirectoryPartition.cs index cb8b81de52..ebdf34d5e8 100644 --- a/src/Orleans.Runtime/GrainDirectory/GrainDirectoryPartition.cs +++ b/src/Orleans.Runtime/GrainDirectory/GrainDirectoryPartition.cs @@ -48,7 +48,7 @@ internal sealed partial class GrainDirectoryPartition( // Requests in these ranges must wait for the range to become available. private readonly List<(RingRange Range, MembershipVersion Version, TaskCompletionSource Completion)> _rangeLocks = []; - // Ranges which were previously at least partially owned by this partition, but which are pending transfer to a new partition. + // Ranges which were previously at least partially owned by this partition, but which are pending transfer to a new partition. private readonly List _partitionSnapshots = []; // Tracked for diagnostic purposes only. @@ -79,10 +79,7 @@ public async ValueTask RefreshViewAsync(MembershipV async ValueTask IGrainDirectoryPartition.GetSnapshotAsync(MembershipVersion version, MembershipVersion rangeVersion, RingRange range) { - if (_logger.IsEnabled(LogLevel.Trace)) - { - _logger.LogTrace("GetSnapshotAsync('{Version}', '{RangeVersion}', '{Range}')", version, rangeVersion, range); - } + LogTraceGetSnapshotAsync(_logger, version, rangeVersion, range); // Wait for the range to be unlocked. await WaitForRange(range, version); @@ -106,15 +103,12 @@ 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); - } + LogDebugTransferringEntries(_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); + LogWarningRequestForSnapshot(_logger, version, rangeVersion, range); return null; } @@ -144,10 +138,7 @@ private void RemoveSnapshotTransferPartner(TState state, Func s.DirectoryMembershipVersion))); - } + LogDebugRemovingSnapshot(_logger, partitionSnapshot.DirectoryMembershipVersion, string.Join(", ", _partitionSnapshots.Select(s => s.DirectoryMembershipVersion))); // If shutdown has been requested and there are no more pending snapshots, signal completion. if (_drainSnapshotsCts.IsCancellationRequested && _partitionSnapshots.Count == 0) @@ -262,19 +253,10 @@ private void OnSiloRemovedFromCluster(ClusterMember change) if (toRemove.Count > 0) { - if (_logger.IsEnabled(LogLevel.Debug)) - { - _logger.LogDebug("Deleting '{Count}' entries located on now-defunct silo '{SiloAddress}'.", toRemove.Count, change.SiloAddress); - } + LogDebugDeletingEntries(_logger, toRemove.Count, change.SiloAddress); foreach (var grainAddress in toRemove) { -#if false - if (_logger.IsEnabled(LogLevel.Debug)) - { - _logger.LogDebug("Deleting '{GrainAddress}' located on now-defunct silo '{SiloAddress}'.", grainAddress, change.SiloAddress); - } -#endif DeregisterCore(grainAddress); } } @@ -295,7 +277,7 @@ internal Task OnRecoveringPartition(MembershipVersion version, RingRange range, } catch (Exception exception) { - _logger.LogWarning(exception, "Error waiting for range to unlock."); + LogWarningErrorWaitingForRangeToUnlock(_logger, exception); } // Remove all snapshots that are associated with the given partition prior or equal to the specified version. @@ -317,10 +299,7 @@ private void ProcessMembershipUpdate(DirectoryMembershipSnapshot current) _viewChangeTasks.RemoveAll(task => task.IsCompleted); - if (_logger.IsEnabled(LogLevel.Trace)) - { - _logger.LogTrace("Observed membership version '{Version}'.", current.Version); - } + LogTraceObservedMembershipVersion(_logger, current.Version); var previous = CurrentView; CurrentView = current; @@ -362,10 +341,7 @@ private async Task ReleaseRangeAsync(DirectoryMembershipSnapshot previous, Direc { GrainRuntime.CheckRuntimeContext(this); 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); - } + LogDebugRelinquishingOwnership(_logger, removedRange, current.Version); try { @@ -403,7 +379,7 @@ private async Task ReleaseRangeAsync(DirectoryMembershipSnapshot previous, Direc { if (transferPartners.Count > 0) { - _logger.LogTrace("Evicting entry '{Address}' to snapshot.", address); + LogTraceEvictingEntry(_logger, address); } _directory.Remove(address.GrainId); @@ -412,21 +388,13 @@ private async Task ReleaseRangeAsync(DirectoryMembershipSnapshot previous, Direc var isContiguous = current.Version.Value == previous.Version.Value + 1; if (!isContiguous) { - 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); - } - + LogDebugEncounteredNonContiguousUpdate(_logger, previous.Version, current.Version, removedRange); return; } if (transferPartners.Count == 0) { - if (_logger.IsEnabled(LogLevel.Debug)) - { - _logger.LogDebug("No transfer partners for snapshot of range '{Range}' at version '{Version}'. Dropping snapshot.", removedRange, current.Version); - } - + LogDebugNoTransferPartners(_logger, removedRange, current.Version); return; } @@ -448,11 +416,8 @@ private async Task AcquireRangeAsync(DirectoryMembershipSnapshot previous, Direc try { CoarseStopwatch stopwatch = default; - if (_logger.IsEnabled(LogLevel.Debug)) - { - _logger.LogDebug("Acquiring range '{Range}'.", addedRange); - stopwatch = CoarseStopwatch.StartNew(); - } + LogDebugAcquiringRange(_logger, addedRange); + stopwatch = CoarseStopwatch.StartNew(); // The view change is contiguous if the new version is exactly one greater than the previous version. // If not, we have missed some updates, so we must declare a potential data loss event. @@ -487,14 +452,7 @@ private async Task AcquireRangeAsync(DirectoryMembershipSnapshot previous, Direc } else { - if (_logger.IsEnabled(LogLevel.Debug)) - { - _logger.LogDebug( - "Non-contiguous view change detected: '{PreviousVersion}' to '{CurrentVersion}'. Performing recovery.", - previous.Version, - current.Version); - } - + LogDebugNonContiguousViewChange(_logger, previous.Version, current.Version); success = false; } @@ -508,10 +466,7 @@ private async Task AcquireRangeAsync(DirectoryMembershipSnapshot previous, Direc recovered = true; } - 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" : ""); - } + LogDebugCompletedTransferringEntries(_logger, addedRange, current.Version, stopwatch.ElapsedMilliseconds, recovered); } finally { @@ -546,10 +501,7 @@ private async Task TransferSnapshotAsync(DirectoryMembershipSnapshot curre try { var stopwatch = ValueStopwatch.StartNew(); - if (_logger.IsEnabled(LogLevel.Trace)) - { - _logger.LogTrace("Requesting entries for ranges '{Range}' from '{PreviousOwner}' at version '{PreviousVersion}'.", addedRange, previousOwner, previousVersion); - } + LogTraceRequestingEntries(_logger, addedRange, previousOwner, previousVersion); var partition = GetPartitionReference(previousOwner, partitionIndex); @@ -558,7 +510,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); + LogWarningExpectedValidSnapshot(_logger, previousOwner, addedRange); return false; } @@ -577,14 +529,11 @@ private async Task TransferSnapshotAsync(DirectoryMembershipSnapshot curre { DebugAssertOwnership(current, entry.GrainId); - _logger.LogTrace("Received '{Entry}' via snapshot from '{PreviousOwner}' for version '{Version}'.", entry, previousOwner, previousVersion); + LogTraceReceivedEntry(_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); - } + LogDebugTransferredEntries(_logger, snapshot.GrainAddresses.Count, addedRange, previousOwner); DirectoryInstruments.SnapshotTransferCount.Add(1); DirectoryInstruments.SnapshotTransferDuration.Record((long)stopwatch.Elapsed.TotalMilliseconds); @@ -595,11 +544,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); + LogWarningRemoteHostUnavailable(_logger, addedRange); } else { - _logger.LogWarning(exception, "Error transferring ownership of range '{Range}'. Recovery will be performed.", addedRange); + LogWarningErrorTransferringOwnership(_logger, exception, addedRange); } return false; @@ -610,10 +559,7 @@ private async Task RecoverPartitionRange(DirectoryMembershipSnapshot current, Ri { var stopwatch = ValueStopwatch.StartNew(); GrainRuntime.CheckRuntimeContext(this); - if (_logger.IsEnabled(LogLevel.Debug)) - { - _logger.LogDebug("Recovering activations from range '{Range}' at version '{Version}'.", addedRange, current.Version); - } + LogDebugRecoveringActivations(_logger, addedRange, current.Version); await foreach (var activations in GetRegisteredActivations(current, addedRange, isValidation: false)) { @@ -621,17 +567,14 @@ 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); + LogTraceRecoveredEntry(_logger, entry, current.Version); _directory[entry.GrainId] = entry; } } DirectoryInstruments.RangeRecoveryCount.Add(1); 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); - } + LogDebugCompletedRecoveringActivations(_logger, addedRange, current.Version, stopwatch.Elapsed); } private async IAsyncEnumerable> GetRegisteredActivations(DirectoryMembershipSnapshot current, RingRange range, bool isValidation) @@ -686,10 +629,7 @@ async Task> GetRegisteredActivationsFromClusterMember(Members new Immutable>([]), nameof(GetRegisteredActivations)); - 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); - } + LogDebugRecoveredEntries(_logger, result.Value.Count, siloAddress, range, version, stopwatch.Elapsed.TotalMilliseconds); return result.Value; } @@ -714,7 +654,7 @@ private async Task InvokeOnClusterMember(SiloAddress siloAddress, Func GrainAddresses, HashSet<(SiloAddress SiloAddress, int PartitionIndex)> TransferPartners); + + [LoggerMessage( + Level = LogLevel.Trace, + Message = "GetSnapshotAsync('{Version}', '{RangeVersion}', '{Range}')" + )] + private static partial void LogTraceGetSnapshotAsync(ILogger logger, MembershipVersion version, MembershipVersion rangeVersion, RingRange range); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Transferring '{Count}' entries in range '{Range}' from version '{Version}' snapshot." + )] + private static partial void LogDebugTransferringEntries(ILogger logger, int count, RingRange range, MembershipVersion version); + + [LoggerMessage( + Level = LogLevel.Warning, + Message = "Received a request for a snapshot which this partition does not have, version '{Version}', range version '{RangeVersion}', range '{Range}'." + )] + private static partial void LogWarningRequestForSnapshot(ILogger logger, MembershipVersion version, MembershipVersion rangeVersion, RingRange range); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Removing version '{Version}' snapshot. Current snapshots: [{CurrentSnapshots}]." + )] + private static partial void LogDebugRemovingSnapshot(ILogger logger, MembershipVersion version, string currentSnapshots); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Deleting '{Count}' entries located on now-defunct silo '{SiloAddress}'." + )] + private static partial void LogDebugDeletingEntries(ILogger logger, int count, SiloAddress siloAddress); + + [LoggerMessage( + Level = LogLevel.Warning, + Message = "Error waiting for range to unlock." + )] + private static partial void LogWarningErrorWaitingForRangeToUnlock(ILogger logger, Exception exception); + + [LoggerMessage( + Level = LogLevel.Trace, + Message = "Observed membership version '{Version}'." + )] + private static partial void LogTraceObservedMembershipVersion(ILogger logger, MembershipVersion version); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Relinquishing ownership of range '{Range}' at version '{Version}'." + )] + private static partial void LogDebugRelinquishingOwnership(ILogger logger, RingRange range, MembershipVersion version); + + [LoggerMessage( + Level = LogLevel.Trace, + Message = "Evicting entry '{Address}' to snapshot." + )] + private static partial void LogTraceEvictingEntry(ILogger logger, GrainAddress address); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Encountered non-contiguous update from '{Previous}' to '{Current}' while releasing range '{Range}'. Dropping snapshot." + )] + private static partial void LogDebugEncounteredNonContiguousUpdate(ILogger logger, MembershipVersion previous, MembershipVersion current, RingRange range); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "No transfer partners for snapshot of range '{Range}' at version '{Version}'. Dropping snapshot." + )] + private static partial void LogDebugNoTransferPartners(ILogger logger, RingRange range, MembershipVersion version); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Acquiring range '{Range}'." + )] + private static partial void LogDebugAcquiringRange(ILogger logger, RingRange range); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Non-contiguous view change detected: '{PreviousVersion}' to '{CurrentVersion}'. Performing recovery." + )] + private static partial void LogDebugNonContiguousViewChange(ILogger logger, MembershipVersion previousVersion, MembershipVersion currentVersion); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Completed transferring entries for range '{Range}' at version '{Version}' took {Elapsed}ms.{Recovered}" + )] + private static partial void LogDebugCompletedTransferringEntries(ILogger logger, RingRange range, MembershipVersion version, long elapsed, bool recovered); + + [LoggerMessage( + Level = LogLevel.Trace, + Message = "Requesting entries for ranges '{Range}' from '{PreviousOwner}' at version '{PreviousVersion}'." + )] + private static partial void LogTraceRequestingEntries(ILogger logger, RingRange range, SiloAddress previousOwner, MembershipVersion previousVersion); + + [LoggerMessage( + Level = LogLevel.Warning, + Message = "Expected a valid snapshot from previous owner '{PreviousOwner}' for part of ranges '{Range}', but found none." + )] + private static partial void LogWarningExpectedValidSnapshot(ILogger logger, SiloAddress previousOwner, RingRange range); + + [LoggerMessage( + Level = LogLevel.Trace, + Message = "Received '{Entry}' via snapshot from '{PreviousOwner}' for version '{Version}'." + )] + private static partial void LogTraceReceivedEntry(ILogger logger, GrainAddress entry, SiloAddress previousOwner, MembershipVersion version); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Transferred '{Count}' entries for range '{Range}' from '{PreviousOwner}'." + )] + private static partial void LogDebugTransferredEntries(ILogger logger, int count, RingRange range, SiloAddress previousOwner); + + [LoggerMessage( + Level = LogLevel.Warning, + Message = "Remote host became unavailable while transferring ownership of range '{Range}'. Recovery will be performed." + )] + private static partial void LogWarningRemoteHostUnavailable(ILogger logger, RingRange range); + + [LoggerMessage( + Level = LogLevel.Warning, + Message = "Error transferring ownership of range '{Range}'. Recovery will be performed." + )] + private static partial void LogWarningErrorTransferringOwnership(ILogger logger, Exception exception, RingRange range); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Recovering activations from range '{Range}' at version '{Version}'." + )] + private static partial void LogDebugRecoveringActivations(ILogger logger, RingRange range, MembershipVersion version); + + [LoggerMessage( + Level = LogLevel.Trace, + Message = "Recovered '{Entry}' for version '{Version}'." + )] + private static partial void LogTraceRecoveredEntry(ILogger logger, GrainAddress entry, MembershipVersion version); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Completed recovering activations from range '{Range}' at version '{Version}' took '{Elapsed}'." + )] + private static partial void LogDebugCompletedRecoveringActivations(ILogger logger, RingRange range, MembershipVersion version, TimeSpan elapsed); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Recovered '{Count}' entries from silo '{SiloAddress}' for ranges '{Range}' at version '{Version}' in {ElapsedMilliseconds}ms." + )] + private static partial void LogDebugRecoveredEntries(ILogger logger, int count, SiloAddress siloAddress, RingRange range, MembershipVersion version, double elapsedMilliseconds); + + [LoggerMessage( + Level = LogLevel.Error, + Message = "Error invoking operation '{Operation}' on silo '{SiloAddress}'." + )] + private static partial void LogErrorErrorInvokingOperation(ILogger logger, Exception exception, string operation, SiloAddress siloAddress); + + [LoggerMessage( + Level = LogLevel.Error, + Message = "Integrity violation: Recovered entry '{RecoveredRecord}' does not match existing entry '{LocalRecord}'." + )] + private static partial void LogErrorIntegrityViolation(ILogger logger, GrainAddress recoveredRecord, GrainAddress localRecord); + + [LoggerMessage( + Level = LogLevel.Error, + Message = "Integrity violation: Recovered entry '{RecoveredRecord}' not found in directory." + )] + private static partial void LogErrorIntegrityViolation(ILogger logger, GrainAddress recoveredRecord); } diff --git a/src/Orleans.Runtime/GrainDirectory/RemoteGrainDirectory.cs b/src/Orleans.Runtime/GrainDirectory/RemoteGrainDirectory.cs index 05b418c1da..b447c98350 100644 --- a/src/Orleans.Runtime/GrainDirectory/RemoteGrainDirectory.cs +++ b/src/Orleans.Runtime/GrainDirectory/RemoteGrainDirectory.cs @@ -8,7 +8,7 @@ #nullable enable namespace Orleans.Runtime.GrainDirectory { - internal sealed class RemoteGrainDirectory : SystemTarget, IRemoteGrainDirectory + internal sealed partial class RemoteGrainDirectory : SystemTarget, IRemoteGrainDirectory { private readonly LocalGrainDirectory router; private readonly LocalGrainDirectoryPartition partition; @@ -39,8 +39,7 @@ public Task RegisterMany(List addresses) // validate that this request arrived correctly //logger.Assert(ErrorCode.Runtime_Error_100140, silo.Matches(router.MyAddress), "destination address != my address"); - if (logger.IsEnabled(LogLevel.Trace)) logger.LogTrace("RegisterMany Count={Count}", addresses.Count); - + LogRegisterMany(addresses.Count); return Task.WhenAll(addresses.Select(addr => router.RegisterAsync(addr, previousAddress: null, 1))); } @@ -68,7 +67,7 @@ public Task LookupAsync(GrainId grainId, int hopCount) public Task> LookUpMany(List<(GrainId GrainId, int Version)> grainAndETagList) { DirectoryInstruments.ValidationsCacheReceived.Add(1); - if (logger.IsEnabled(LogLevel.Trace)) logger.LogTrace("LookUpMany for {Count} entries", grainAndETagList.Count); + LogLookUpMany(grainAndETagList.Count); var result = new List(); @@ -107,5 +106,17 @@ public Task AcceptSplitPartition(List singleActivations) } public Task RegisterAsync(GrainAddress address, int hopCount = 0) => router.RegisterAsync(address, hopCount); + + [LoggerMessage( + Level = LogLevel.Trace, + Message = "RegisterMany Count={Count}" + )] + private partial void LogRegisterMany(int count); + + [LoggerMessage( + Level = LogLevel.Trace, + Message = "LookUpMany for {Count} entries" + )] + private partial void LogLookUpMany(int count); } } diff --git a/src/Orleans.Runtime/Hosting/EndpointOptionsProvider.cs b/src/Orleans.Runtime/Hosting/EndpointOptionsProvider.cs index 2a66350eaf..943d4721ee 100644 --- a/src/Orleans.Runtime/Hosting/EndpointOptionsProvider.cs +++ b/src/Orleans.Runtime/Hosting/EndpointOptionsProvider.cs @@ -7,7 +7,7 @@ namespace Orleans.Configuration { - internal class EndpointOptionsProvider : IPostConfigureOptions + internal partial class EndpointOptionsProvider : IPostConfigureOptions { private readonly ILogger logger; @@ -28,31 +28,33 @@ 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); - } + LogWarningUnableToFindSuitableCandidate(logger, nameof(EndpointOptions), nameof(options.AdvertisedIPAddress), nameof(IPAddress.Loopback), advertisedIPAddress); } else - { + { advertisedIPAddress = resolvedIP; } } 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); - } - } + LogErrorUnableToFindSuitableCandidate(logger, ex, nameof(EndpointOptions), nameof(options.AdvertisedIPAddress), nameof(IPAddress.Loopback), advertisedIPAddress); + } options.AdvertisedIPAddress = advertisedIPAddress; } } + + + [LoggerMessage( + Level = LogLevel.Warning, + Message = "Unable to find a suitable candidate for {OptionName}.{PropertyName}. Falling back to {Fallback} ({AdvertisedIPAddress})" + )] + private static partial void LogWarningUnableToFindSuitableCandidate(ILogger logger, string optionName, string propertyName, string fallback, IPAddress advertisedIPAddress); + + [LoggerMessage( + Level = LogLevel.Error, + Message = "Unable to find a suitable candidate for {OptionName}.{PropertyName}. Falling back to {Fallback} ({AdvertisedIPAddress})" + )] + private static partial void LogErrorUnableToFindSuitableCandidate(ILogger logger, Exception exception, string optionName, string propertyName, string fallback, IPAddress advertisedIPAddress); } } diff --git a/src/Orleans.Runtime/Hosting/SiloHostedService.cs b/src/Orleans.Runtime/Hosting/SiloHostedService.cs index e2e4b9fe7f..ff340c4e09 100644 --- a/src/Orleans.Runtime/Hosting/SiloHostedService.cs +++ b/src/Orleans.Runtime/Hosting/SiloHostedService.cs @@ -7,7 +7,7 @@ namespace Orleans.Hosting { - internal class SiloHostedService : IHostedService + internal partial class SiloHostedService : IHostedService { private readonly ILogger logger; private readonly Silo silo; @@ -24,16 +24,16 @@ public SiloHostedService( public async Task StartAsync(CancellationToken cancellationToken) { - this.logger.LogInformation("Starting Orleans Silo."); + LogInformationStartingSilo(logger); await this.silo.StartAsync(cancellationToken).ConfigureAwait(false); - this.logger.LogInformation("Orleans Silo started."); + LogInformationSiloStarted(logger); } public async Task StopAsync(CancellationToken cancellationToken) { - this.logger.LogInformation("Stopping Orleans Silo"); + LogInformationStoppingSilo(logger); await this.silo.StopAsync(cancellationToken).ConfigureAwait(false); - this.logger.LogInformation("Orleans Silo stopped."); + LogInformationSiloStopped(logger); } private static void ValidateSystemConfiguration(IEnumerable configurationValidators) @@ -43,5 +43,29 @@ private static void ValidateSystemConfiguration(IEnumerable /// Decorator over lifecycle subject for silo. Adds some logging and monitoring /// - public class SiloLifecycleSubject : LifecycleSubject, ISiloLifecycleSubject + public partial class SiloLifecycleSubject : LifecycleSubject, ISiloLifecycleSubject { private static readonly ImmutableDictionary StageNames = GetStageNames(typeof(ServiceLifecycleStage)); private readonly List observers; @@ -40,14 +40,7 @@ public override Task OnStart(CancellationToken cancellationToken = default) { foreach (var stage in this.observers.GroupBy(o => o.Stage).OrderBy(s => s.Key)) { - if (this.Logger.IsEnabled(LogLevel.Debug)) - { - this.Logger.LogDebug( - (int)ErrorCode.LifecycleStagesReport, - "Stage {Stage}: {Observers}", - this.GetStageName(stage.Key), - string.Join(", ", stage.Select(o => o.Name))); - } + LogDebugLifecycleStagesReport(stage.Key, string.Join(", ", stage.Select(o => o.Name))); } return base.OnStart(cancellationToken); @@ -77,27 +70,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); - } + LogDebugStoppingLifecycleStage(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); - } + LogDebugStartingLifecycleStage(this.GetStageName(stage), elapsed); } /// @@ -108,7 +87,7 @@ public override IDisposable Subscribe(string observerName, int stage, ILifecycle return base.Subscribe(observerName, stage, monitoredObserver); } - private class MonitoredObserver : ILifecycleObserver + private partial class MonitoredObserver : ILifecycleObserver { private readonly ILifecycleObserver observer; private readonly ILogger logger; @@ -133,24 +112,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); - } + LogDebugObserverStarted(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); + LogErrorObserverStartFailure(exception, this.Name, this.StageName); throw; } } @@ -160,48 +126,80 @@ 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); - } + LogDebugObserverStopping(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); + LogObserverStopped(LogLevel.Warning, 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); + LogObserverStopped(LogLevel.Debug, 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); + LogErrorObserverStopFailure(exception, this.Name, this.StageName, stopwatch.Elapsed); throw; } } + + [LoggerMessage( + EventId = (int)ErrorCode.SiloStartPerfMeasure, + Level = LogLevel.Debug, + Message = "'{Name}' started in stage '{Stage}' in '{Elapsed}'." + )] + private partial void LogDebugObserverStarted(string name, string stage, TimeSpan elapsed); + + [LoggerMessage( + EventId = (int)ErrorCode.LifecycleStartFailure, + Level = LogLevel.Error, + Message = "'{Name}' failed to start due to errors at stage '{Stage}'." + )] + private partial void LogErrorObserverStartFailure(Exception exception, string name, string stage); + + [LoggerMessage( + EventId = (int)ErrorCode.SiloStartPerfMeasure, + Level = LogLevel.Debug, + Message = "'{Name}' stopping in stage '{Stage}'." + )] + private partial void LogDebugObserverStopping(string name, string stage); + + [LoggerMessage( + EventId = (int)ErrorCode.SiloStartPerfMeasure, + Message = "'{Name}' stopped in stage '{Stage}' in '{Elapsed}'." + )] + private partial void LogObserverStopped(LogLevel logLevel, string name, string stage, TimeSpan elapsed); + + [LoggerMessage( + EventId = (int)ErrorCode.LifecycleStartFailure, + Level = LogLevel.Error, + Message = "'{Name}' failed to stop due to errors at stage '{Stage}' after '{Elapsed}'." + )] + private partial void LogErrorObserverStopFailure(Exception exception, string name, string stage, TimeSpan elapsed); } + + [LoggerMessage( + EventId = (int)ErrorCode.LifecycleStagesReport, + Level = LogLevel.Debug, + Message = "Stage {Stage}: {Observers}" + )] + private partial void LogDebugLifecycleStagesReport(int stage, string observers); + + [LoggerMessage( + EventId = (int)ErrorCode.SiloStartPerfMeasure, + Level = LogLevel.Debug, + Message = "Stopping lifecycle stage '{Stage}' took '{Elapsed}'." + )] + private partial void LogDebugStoppingLifecycleStage(string stage, TimeSpan elapsed); + + [LoggerMessage( + EventId = (int)ErrorCode.SiloStartPerfMeasure, + Level = LogLevel.Debug, + Message = "Starting lifecycle stage '{Stage}' took '{Elapsed}'" + )] + private partial void LogDebugStartingLifecycleStage(string stage, TimeSpan elapsed); } } diff --git a/src/Orleans.Runtime/Manifest/ClusterManifestProvider.cs b/src/Orleans.Runtime/Manifest/ClusterManifestProvider.cs index 689bcc96e9..ec6cb31151 100644 --- a/src/Orleans.Runtime/Manifest/ClusterManifestProvider.cs +++ b/src/Orleans.Runtime/Manifest/ClusterManifestProvider.cs @@ -14,7 +14,7 @@ namespace Orleans.Runtime.Metadata { - internal class ClusterManifestProvider : IClusterManifestProvider, IAsyncDisposable, IDisposable, ILifecycleParticipant + internal partial class ClusterManifestProvider : IClusterManifestProvider, IAsyncDisposable, IDisposable, ILifecycleParticipant { private readonly SiloAddress _localSiloAddress; private readonly ILogger _logger; @@ -60,10 +60,7 @@ private async Task ProcessMembershipUpdates() { try { - if (_logger.IsEnabled(LogLevel.Debug)) - { - _logger.LogDebug("Starting to process membership updates"); - } + LogDebugStartingToProcessMembershipUpdates(); var cancellation = _shutdownCts.Token; await foreach (var _ in _clusterMembershipService.MembershipUpdates.WithCancellation(cancellation)) @@ -93,10 +90,7 @@ private async Task ProcessMembershipUpdates() } finally { - if (_logger.IsEnabled(LogLevel.Debug)) - { - _logger.LogDebug("Stopped processing membership updates"); - } + LogDebugStoppedProcessingMembershipUpdates(); } } @@ -177,7 +171,7 @@ private async Task UpdateManifest(ClusterMembershipSnapshot clusterMembers fetchSuccess = false; if (exception is not OperationCanceledException) { - _logger.LogWarning(exception, "Error retrieving silo manifest for silo {SiloAddress}", result.Key); + LogWarningErrorRetrievingSiloManifest(exception, new(result.Key)); } } else @@ -252,5 +246,23 @@ public void Dispose() { DisposeAsync().AsTask().GetAwaiter().GetResult(); } + + [LoggerMessage( + Level = LogLevel.Warning, + Message = "Error retrieving silo manifest for silo {SiloAddress}" + )] + private partial void LogWarningErrorRetrievingSiloManifest(Exception exception, SiloAddress siloAddress); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Starting to process membership updates" + )] + private partial void LogDebugStartingToProcessMembershipUpdates(); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Stopped processing membership updates" + )] + private partial void LogDebugStoppedProcessingMembershipUpdates(); } } diff --git a/src/Orleans.Runtime/MembershipService/MembershipGossiper.cs b/src/Orleans.Runtime/MembershipService/MembershipGossiper.cs index 0693672d2c..b7bb43f441 100644 --- a/src/Orleans.Runtime/MembershipService/MembershipGossiper.cs +++ b/src/Orleans.Runtime/MembershipService/MembershipGossiper.cs @@ -7,7 +7,7 @@ namespace Orleans.Runtime.MembershipService; -internal class MembershipGossiper(IServiceProvider serviceProvider, ILogger logger) : IMembershipGossiper +internal partial class MembershipGossiper(IServiceProvider serviceProvider, ILogger logger) : IMembershipGossiper { private MembershipSystemTarget? _membershipSystemTarget; @@ -19,16 +19,15 @@ public Task GossipToRemoteSilos( { if (gossipPartners.Count == 0) return Task.CompletedTask; - if (logger.IsEnabled(LogLevel.Debug)) - { - logger.LogDebug( - "Gossiping {Silo} status {Status} to {NumPartners} partners", - updatedSilo, - updatedStatus, - gossipPartners.Count); - } + LogDebugGossipingStatusToPartners(logger, updatedSilo, updatedStatus, gossipPartners.Count); var systemTarget = _membershipSystemTarget ??= serviceProvider.GetRequiredService(); return systemTarget.GossipToRemoteSilos(gossipPartners, snapshot, updatedSilo, updatedStatus); } + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Gossiping {Silo} status {Status} to {NumPartners} partners" + )] + private static partial void LogDebugGossipingStatusToPartners(ILogger logger, SiloAddress silo, SiloStatus status, int numPartners); } diff --git a/src/Orleans.Runtime/MembershipService/MembershipTableCleanupAgent.cs b/src/Orleans.Runtime/MembershipService/MembershipTableCleanupAgent.cs index 476bcf91a2..0de36e2162 100644 --- a/src/Orleans.Runtime/MembershipService/MembershipTableCleanupAgent.cs +++ b/src/Orleans.Runtime/MembershipService/MembershipTableCleanupAgent.cs @@ -14,7 +14,7 @@ namespace Orleans.Runtime.MembershipService /// /// Responsible for cleaning up dead membership table entries. /// - internal class MembershipTableCleanupAgent : IHealthCheckParticipant, ILifecycleParticipant, IDisposable + internal partial class MembershipTableCleanupAgent : IHealthCheckParticipant, ILifecycleParticipant, IDisposable { private readonly ClusterMembershipOptions _clusterMembershipOptions; private readonly IMembershipTable _membershipTableProvider; @@ -47,16 +47,12 @@ private async Task CleanupDefunctSilos() { if (!_clusterMembershipOptions.DefunctSiloCleanupPeriod.HasValue) { - if (_logger.IsEnabled(LogLevel.Debug)) - { - _logger.LogDebug($"Membership table cleanup is disabled due to {nameof(ClusterMembershipOptions)}.{nameof(ClusterMembershipOptions.DefunctSiloCleanupPeriod)} not being specified"); - } - + LogDebugMembershipTableCleanupDisabled(_logger); return; } Debug.Assert(_cleanupDefunctSilosTimer is not null); - if (_logger.IsEnabled(LogLevel.Debug)) _logger.LogDebug("Starting membership table cleanup agent"); + LogDebugStartingMembershipTableCleanupAgent(_logger); try { var period = _clusterMembershipOptions.DefunctSiloCleanupPeriod.Value; @@ -76,20 +72,18 @@ private async Task CleanupDefunctSilos() catch (Exception exception) when (exception is NotImplementedException or MissingMethodException) { _cleanupDefunctSilosTimer.Dispose(); - _logger.LogWarning( - (int)ErrorCode.MembershipCleanDeadEntriesFailure, - $"{nameof(IMembershipTable.CleanupDefunctSiloEntries)} operation is not supported by the current implementation of {nameof(IMembershipTable)}. Disabling the timer now."); + LogWarningCleanupDefunctSiloEntriesNotSupported(_logger); return; } catch (Exception exception) { - _logger.LogError((int)ErrorCode.MembershipCleanDeadEntriesFailure, exception, "Failed to clean up defunct membership table entries"); + LogErrorFailedToCleanUpDefunctMembershipTableEntries(_logger, exception); } } } finally { - if (_logger.IsEnabled(LogLevel.Debug)) _logger.LogDebug("Stopped membership table cleanup agent"); + LogDebugStoppedMembershipTableCleanupAgent(_logger); } } @@ -124,5 +118,35 @@ bool IHealthCheckable.CheckHealth(DateTime lastCheckTime, [NotNullWhen(false)] o reason = default; return true; } + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Membership table cleanup is disabled due to ClusterMembershipOptions.DefunctSiloCleanupPeriod not being specified" + )] + private static partial void LogDebugMembershipTableCleanupDisabled(ILogger logger); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Starting membership table cleanup agent" + )] + private static partial void LogDebugStartingMembershipTableCleanupAgent(ILogger logger); + + [LoggerMessage( + Level = LogLevel.Warning, + Message = "IMembershipTable.CleanupDefunctSiloEntries operation is not supported by the current implementation of IMembershipTable. Disabling the timer now." + )] + private static partial void LogWarningCleanupDefunctSiloEntriesNotSupported(ILogger logger); + + [LoggerMessage( + Level = LogLevel.Error, + Message = "Failed to clean up defunct membership table entries" + )] + private static partial void LogErrorFailedToCleanUpDefunctMembershipTableEntries(ILogger logger, Exception exception); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Stopped membership table cleanup agent" + )] + private static partial void LogDebugStoppedMembershipTableCleanupAgent(ILogger logger); } } diff --git a/src/Orleans.Runtime/MembershipService/SiloStatusListenerManager.cs b/src/Orleans.Runtime/MembershipService/SiloStatusListenerManager.cs index a10efa49b8..7749f48232 100644 --- a/src/Orleans.Runtime/MembershipService/SiloStatusListenerManager.cs +++ b/src/Orleans.Runtime/MembershipService/SiloStatusListenerManager.cs @@ -12,7 +12,7 @@ namespace Orleans.Runtime.MembershipService; /// /// Manages instances. /// -internal class SiloStatusListenerManager : ILifecycleParticipant +internal partial class SiloStatusListenerManager : ILifecycleParticipant { private readonly object _listenersLock = new(); private readonly CancellationTokenSource _cancellation = new(); @@ -77,7 +77,7 @@ private async Task ProcessMembershipUpdates() ClusterMembershipSnapshot? previous = default; try { - if (_logger.IsEnabled(LogLevel.Debug)) _logger.LogDebug("Starting to process membership updates."); + LogDebugStartingToProcessMembershipUpdates(); await foreach (var tableSnapshot in _membershipTableManager.MembershipTableUpdates.WithCancellation(_cancellation.Token)) { var snapshot = tableSnapshot.CreateClusterMembershipSnapshot(); @@ -89,12 +89,12 @@ private async Task ProcessMembershipUpdates() } catch (Exception exception) when (_fatalErrorHandler.IsUnexpected(exception)) { - _logger.LogError(exception, "Error processing membership updates."); + LogErrorProcessingMembershipUpdates(exception); _fatalErrorHandler.OnFatalException(this, nameof(ProcessMembershipUpdates), exception); } finally { - if (_logger.IsEnabled(LogLevel.Debug)) _logger.LogDebug("Stopping membership update processor."); + LogDebugStoppingMembershipUpdateProcessor(); } } @@ -121,10 +121,7 @@ private void NotifyObservers(ClusterMembershipUpdate update) } catch (Exception exception) { - _logger.LogError( - exception, - "Exception while calling " + nameof(ISiloStatusListener.SiloStatusChangeNotification) + " on listener '{Listener}'.", - listener); + LogErrorCallingSiloStatusChangeNotification(exception, listener); } } } @@ -162,4 +159,28 @@ async Task OnStop(CancellationToken ct) } } } + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Starting to process membership updates." + )] + private partial void LogDebugStartingToProcessMembershipUpdates(); + + [LoggerMessage( + Level = LogLevel.Error, + Message = "Error processing membership updates." + )] + private partial void LogErrorProcessingMembershipUpdates(Exception exception); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Stopping membership update processor." + )] + private partial void LogDebugStoppingMembershipUpdateProcessor(); + + [LoggerMessage( + Level = LogLevel.Error, + Message = "Exception while calling " + nameof(ISiloStatusListener.SiloStatusChangeNotification) + " on listener '{Listener}'." + )] + private partial void LogErrorCallingSiloStatusChangeNotification(Exception exception, ISiloStatusListener listener); } diff --git a/src/Orleans.Runtime/MembershipService/SystemTargetBasedMembershipTable.cs b/src/Orleans.Runtime/MembershipService/SystemTargetBasedMembershipTable.cs index c932dc6bcb..d30ecc5a5e 100644 --- a/src/Orleans.Runtime/MembershipService/SystemTargetBasedMembershipTable.cs +++ b/src/Orleans.Runtime/MembershipService/SystemTargetBasedMembershipTable.cs @@ -6,12 +6,11 @@ using Microsoft.Extensions.Options; using Orleans.Concurrency; using Orleans.Configuration; -using Orleans.Internal; using Orleans.Serialization; namespace Orleans.Runtime.MembershipService { - internal class SystemTargetBasedMembershipTable : IMembershipTable + internal partial class SystemTargetBasedMembershipTable : IMembershipTable { private readonly IServiceProvider serviceProvider; private readonly ILogger logger; @@ -40,7 +39,7 @@ private async Task GetMembershipTable() bool isPrimarySilo = siloDetails.SiloAddress.Endpoint.Equals(options.PrimarySiloEndpoint); if (isPrimarySilo) { - this.logger.LogInformation((int)ErrorCode.MembershipFactory1, "Creating in-memory membership table"); + LogInformationCreatingInMemoryMembershipTable(logger); var catalog = serviceProvider.GetRequiredService(); catalog.RegisterSystemTarget(ActivatorUtilities.CreateInstance(serviceProvider)); } @@ -60,13 +59,13 @@ private async Task WaitForTableGrainToInit(IMembershipTableSystemTarget membersh { var timespan = Debugger.IsAttached ? TimeSpan.FromMinutes(5) : TimeSpan.FromSeconds(5); // This is a quick temporary solution to enable primary node to start fully before secondaries. - // Secondary silos waits untill GrainBasedMembershipTable is created. + // Secondary silos waits untill GrainBasedMembershipTable is created. for (int i = 0; i < 100; i++) { try { await membershipTableSystemTarget.ReadAll().WaitAsync(timespan); - logger.LogInformation((int)ErrorCode.MembershipTableGrainInit2, "Connected to membership table provider."); + LogInformationConnectedToMembershipTableProvider(logger); return; } catch (Exception exc) @@ -74,14 +73,11 @@ private async Task WaitForTableGrainToInit(IMembershipTableSystemTarget membersh var type = exc.GetBaseException().GetType(); if (type == typeof(TimeoutException) || type == typeof(OrleansException)) { - logger.LogInformation( - (int)ErrorCode.MembershipTableGrainInit3, - "Waiting for membership table provider to initialize. Going to sleep for {Duration} and re-try to reconnect.", - timespan); + LogInformationWaitingForMembershipTableProvider(logger, timespan); } else { - logger.LogInformation((int)ErrorCode.MembershipTableGrainInit4, "Membership table provider failed to initialize. Giving up."); + LogInformationMembershipTableProviderFailedToInitialize(logger); throw; } } @@ -103,10 +99,38 @@ private async Task WaitForTableGrainToInit(IMembershipTableSystemTarget membersh public Task UpdateIAmAlive(MembershipEntry entry) => this.grain.UpdateIAmAlive(entry); public Task CleanupDefunctSiloEntries(DateTimeOffset beforeDate) => this.grain.CleanupDefunctSiloEntries(beforeDate); + + [LoggerMessage( + EventId = (int)ErrorCode.MembershipFactory1, + Level = LogLevel.Information, + Message = "Creating in-memory membership table" + )] + private static partial void LogInformationCreatingInMemoryMembershipTable(ILogger logger); + + [LoggerMessage( + EventId = (int)ErrorCode.MembershipTableGrainInit2, + Level = LogLevel.Information, + Message = "Connected to membership table provider." + )] + private static partial void LogInformationConnectedToMembershipTableProvider(ILogger logger); + + [LoggerMessage( + EventId = (int)ErrorCode.MembershipTableGrainInit3, + Level = LogLevel.Information, + Message = "Waiting for membership table provider to initialize. Going to sleep for {Duration} and re-try to reconnect." + )] + private static partial void LogInformationWaitingForMembershipTableProvider(ILogger logger, TimeSpan duration); + + [LoggerMessage( + EventId = (int)ErrorCode.MembershipTableGrainInit4, + Level = LogLevel.Information, + Message = "Membership table provider failed to initialize. Giving up." + )] + private static partial void LogInformationMembershipTableProviderFailedToInitialize(ILogger logger); } [Reentrant] - internal sealed class MembershipTableSystemTarget : SystemTarget, IMembershipTableSystemTarget, ILifecycleParticipant + internal sealed partial class MembershipTableSystemTarget : SystemTarget, IMembershipTableSystemTarget, ILifecycleParticipant { private InMemoryMembershipTable table; private readonly ILogger logger; @@ -120,7 +144,7 @@ public MembershipTableSystemTarget( { logger = loggerFactory.CreateLogger(); table = new InMemoryMembershipTable(deepCopier); - logger.LogInformation((int)ErrorCode.MembershipGrainBasedTable1, "GrainBasedMembershipTable Activated."); + LogInformationGrainBasedMembershipTableActivated(logger); catalog.RegisterSystemTarget(this); } @@ -131,13 +155,13 @@ private static SystemTargetGrainId CreateId(ILocalSiloDetails localSiloDetails) public Task InitializeMembershipTable(bool tryInitTableVersion) { - logger.LogInformation("InitializeMembershipTable {TryInitTableVersion}.", tryInitTableVersion); + LogInformationInitializeMembershipTable(logger, tryInitTableVersion); return Task.CompletedTask; } public Task DeleteMembershipTableEntries(string clusterId) { - logger.LogInformation("DeleteMembershipTableEntries {ClusterId}", clusterId); + LogInformationDeleteMembershipTableEntries(logger, clusterId); table = null; return Task.CompletedTask; } @@ -155,38 +179,27 @@ public Task ReadAll() public Task InsertRow(MembershipEntry entry, TableVersion tableVersion) { - if (logger.IsEnabled(LogLevel.Debug)) logger.LogDebug("InsertRow entry = {Entry}, table version = {Version}", entry.ToString(), tableVersion); + LogDebugInsertRow(logger, entry, tableVersion); bool result = table.Insert(entry, tableVersion); if (result == false) - logger.LogInformation( - (int)ErrorCode.MembershipGrainBasedTable2, - "Insert of {Entry} and table version {Version} failed. Table now is {Table}", - entry.ToString(), - tableVersion, - table.ReadAll()); + LogInformationInsertRowFailed(logger, entry, tableVersion, table.ReadAll()); return Task.FromResult(result); } public Task UpdateRow(MembershipEntry entry, string etag, TableVersion tableVersion) { - if (logger.IsEnabled(LogLevel.Debug)) logger.LogDebug("UpdateRow entry = {Entry}, etag = {ETag}, table version = {Version}", entry.ToString(), etag, tableVersion); + LogDebugUpdateRow(logger, entry, etag, tableVersion); bool result = table.Update(entry, etag, tableVersion); if (result == false) - logger.LogInformation( - (int)ErrorCode.MembershipGrainBasedTable3, - "Update of {Entry}, eTag {ETag}, table version {Version} failed. Table now is {Table}", - entry.ToString(), - etag, - tableVersion, - table.ReadAll()); + LogInformationUpdateRowFailed(logger, entry, etag, tableVersion, table.ReadAll()); return Task.FromResult(result); } public Task UpdateIAmAlive(MembershipEntry entry) { - if (logger.IsEnabled(LogLevel.Debug)) logger.LogDebug("UpdateIAmAlive entry = {Entry}", entry.ToString()); + LogDebugUpdateIAmAlive(logger, entry); table.UpdateIAmAlive(entry); return Task.CompletedTask; } @@ -201,5 +214,56 @@ void ILifecycleParticipant.Participate(ISiloLifecycle lifecycle) { // Do nothing, just ensure that this instance is created so that it can register itself in the catalog. } + + [LoggerMessage( + EventId = (int)ErrorCode.MembershipGrainBasedTable1, + Level = LogLevel.Information, + Message = "GrainBasedMembershipTable Activated." + )] + private static partial void LogInformationGrainBasedMembershipTableActivated(ILogger logger); + + [LoggerMessage( + Level = LogLevel.Information, + Message = "InitializeMembershipTable {TryInitTableVersion}." + )] + private static partial void LogInformationInitializeMembershipTable(ILogger logger, bool tryInitTableVersion); + + [LoggerMessage( + Level = LogLevel.Information, + Message = "DeleteMembershipTableEntries {ClusterId}" + )] + private static partial void LogInformationDeleteMembershipTableEntries(ILogger logger, string clusterId); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "InsertRow entry = {Entry}, table version = {Version}" + )] + private static partial void LogDebugInsertRow(ILogger logger, MembershipEntry entry, TableVersion version); + + [LoggerMessage( + EventId = (int)ErrorCode.MembershipGrainBasedTable2, + Level = LogLevel.Information, + Message = "Insert of {Entry} and table version {Version} failed. Table now is {Table}" + )] + private static partial void LogInformationInsertRowFailed(ILogger logger, MembershipEntry entry, TableVersion version, MembershipTableData table); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "UpdateRow entry = {Entry}, etag = {ETag}, table version = {Version}" + )] + private static partial void LogDebugUpdateRow(ILogger logger, MembershipEntry entry, string etag, TableVersion version); + + [LoggerMessage( + EventId = (int)ErrorCode.MembershipGrainBasedTable3, + Level = LogLevel.Information, + Message = "Update of {Entry}, eTag {ETag}, table version {Version} failed. Table now is {Table}" + )] + private static partial void LogInformationUpdateRowFailed(ILogger logger, MembershipEntry entry, string etag, TableVersion version, MembershipTableData table); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "UpdateIAmAlive entry = {Entry}" + )] + private static partial void LogDebugUpdateIAmAlive(ILogger logger, MembershipEntry entry); } } diff --git a/src/Orleans.Runtime/Messaging/Gateway.cs b/src/Orleans.Runtime/Messaging/Gateway.cs index 62bf8bf04d..2b21ede625 100644 --- a/src/Orleans.Runtime/Messaging/Gateway.cs +++ b/src/Orleans.Runtime/Messaging/Gateway.cs @@ -14,7 +14,7 @@ namespace Orleans.Runtime.Messaging { - internal sealed class Gateway : IConnectedClientCollection + internal sealed partial class Gateway : IConnectedClientCollection { // clients is the main authorative collection of all connected clients. // Any client currently in the system appears in this collection. @@ -79,7 +79,7 @@ private async Task PerformGatewayMaintenance() } catch (Exception exception) { - logger.LogError(exception, "Error performing gateway maintenance"); + LogErrorGatewayMaintenanceError(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); + LogInformationGatewayClientOpenedSocket(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); + LogInformationGatewayClientClosedSocket(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); - } + LogInformationGatewayDroppingClient(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); + LogWarningGatewayClientReceivedNewConnectionBeforePreviousConnectionRemoved(_gateway.logger, Id, connection, existing); } _disconnectedSince.Reset(); @@ -416,7 +401,7 @@ private async Task RunMessageLoop() } catch (Exception exception) { - _gateway.logger.LogWarning(exception, "Exception in message loop for client {ClientId}", Id); + LogWarningGatewayClientMessageLoopException(_gateway.logger, Id); } } } @@ -497,5 +482,43 @@ internal void DropExpiredEntries() } } } + [LoggerMessage( + Level = LogLevel.Error, + Message = "Error performing gateway maintenance" + )] + private static partial void LogErrorGatewayMaintenanceError(ILogger logger, Exception exception); + + [LoggerMessage( + EventId = (int)ErrorCode.GatewayClientOpenedSocket, + Level = LogLevel.Information, + Message = "Recorded opened connection from endpoint {EndPoint}, client ID {ClientId}." + )] + private static partial void LogInformationGatewayClientOpenedSocket(ILogger logger, EndPoint endPoint, ClientGrainId clientId); + + [LoggerMessage( + EventId = (int)ErrorCode.GatewayClientClosedSocket, + Level = LogLevel.Information, + Message = "Recorded closed socket from endpoint {Endpoint}, client ID {clientId}." + )] + private static partial void LogInformationGatewayClientClosedSocket(ILogger logger, string endpoint, ClientGrainId clientId); + + [LoggerMessage( + EventId = (int)ErrorCode.GatewayDroppingClient, + Level = LogLevel.Information, + Message = "Dropping client {ClientId}, {IdleDuration} after disconnect with no reconnect" + )] + private static partial void LogInformationGatewayDroppingClient(ILogger logger, ClientGrainId clientId, TimeSpan idleDuration); + + [LoggerMessage( + Level = LogLevel.Warning, + Message = "Client {ClientId} received new connection ({NewConnection}) before the previous connection ({PreviousConnection}) had been removed" + )] + private static partial void LogWarningGatewayClientReceivedNewConnectionBeforePreviousConnectionRemoved(ILogger logger, ClientGrainId clientId, GatewayInboundConnection newConnection, GatewayInboundConnection previousConnection); + + [LoggerMessage( + Level = LogLevel.Warning, + Message = "Exception in message loop for client {ClientId}" + )] + private static partial void LogWarningGatewayClientMessageLoopException(ILogger logger, ClientGrainId clientId); } } diff --git a/src/Orleans.Runtime/Placement/DeploymentLoadPublisher.cs b/src/Orleans.Runtime/Placement/DeploymentLoadPublisher.cs index a64ee300f0..87c9c1a9ea 100644 --- a/src/Orleans.Runtime/Placement/DeploymentLoadPublisher.cs +++ b/src/Orleans.Runtime/Placement/DeploymentLoadPublisher.cs @@ -15,7 +15,7 @@ namespace Orleans.Runtime /// /// This class collects runtime statistics for all silos in the current deployment for use by placement. /// - internal class DeploymentLoadPublisher : SystemTarget, IDeploymentLoadPublisher, ISiloStatusListener, ILifecycleParticipant + internal partial class DeploymentLoadPublisher : SystemTarget, IDeploymentLoadPublisher, ISiloStatusListener, ILifecycleParticipant { private readonly ILocalSiloDetails _siloDetails; private readonly ISiloStatusOracle _siloStatusOracle; @@ -66,10 +66,7 @@ public DeploymentLoadPublisher( private async Task StartAsync(CancellationToken cancellationToken) { - if (_logger.IsEnabled(LogLevel.Debug)) - { - _logger.LogDebug("Starting DeploymentLoadPublisher"); - } + LogDebugStartingDeploymentLoadPublisher(_logger); if (_statisticsRefreshTime > TimeSpan.Zero) { @@ -85,20 +82,14 @@ private async Task StartAsync(CancellationToken cancellationToken) await RefreshClusterStatistics(); await PublishStatistics(); - if (_logger.IsEnabled(LogLevel.Debug)) - { - _logger.LogDebug("Started DeploymentLoadPublisher"); - } + LogDebugStartedDeploymentLoadPublisher(_logger); } private async Task PublishStatistics() { try { - if (_logger.IsEnabled(LogLevel.Trace)) - { - _logger.LogTrace("PublishStatistics"); - } + LogTracePublishStatistics(_logger); // Ensure that our timestamp is monotonically increasing. var ticks = _lastUpdateDateTimeTicks = Math.Max(_lastUpdateDateTimeTicks + 1, DateTime.UtcNow.Ticks); @@ -132,10 +123,7 @@ private async Task PublishStatistics() } catch (Exception exception) { - _logger.LogWarning( - (int)ErrorCode.Placement_RuntimeStatisticsUpdateFailure_1, - exception, - "An unexpected exception was thrown by PublishStatistics.UpdateRuntimeStatistics(). Ignored"); + LogWarningRuntimeStatisticsUpdateFailure1(_logger, exception); } } @@ -143,10 +131,7 @@ private async Task PublishStatistics() } catch (Exception exc) { - _logger.LogWarning( - (int)ErrorCode.Placement_RuntimeStatisticsUpdateFailure_2, - exc, - "An exception was thrown by PublishStatistics.UpdateRuntimeStatistics(). Ignoring"); + LogWarningRuntimeStatisticsUpdateFailure2(_logger, exc); } } @@ -158,7 +143,7 @@ public Task UpdateRuntimeStatistics(SiloAddress siloAddress, SiloRuntimeStatisti private void UpdateRuntimeStatisticsInternal(SiloAddress siloAddress, SiloRuntimeStatistics siloStats) { - if (_logger.IsEnabled(LogLevel.Trace)) _logger.LogTrace("UpdateRuntimeStatistics from {Server}", siloAddress); + LogTraceUpdateRuntimeStatistics(_logger, siloAddress); if (_siloStatusOracle.GetApproximateSiloStatus(siloAddress) != SiloStatus.Active) { return; @@ -176,7 +161,7 @@ private void UpdateRuntimeStatisticsInternal(SiloAddress siloAddress, SiloRuntim internal async Task RefreshClusterStatistics() { - if (_logger.IsEnabled(LogLevel.Trace)) _logger.LogTrace("RefreshStatistics"); + LogTraceRefreshStatistics(_logger); await this.RunOrQueueTask(() => { var members = _siloStatusOracle.GetApproximateSiloStatuses(true).Keys; @@ -199,11 +184,7 @@ private async Task RefreshSiloStatistics(SiloAddress silo) } catch (Exception exception) { - _logger.LogWarning( - (int)ErrorCode.Placement_RuntimeStatisticsUpdateFailure_3, - exception, - "An unexpected exception was thrown from RefreshStatistics by ISiloControl.GetRuntimeStatistics({SiloAddress}). Will keep using stale statistics.", - silo); + LogWarningRuntimeStatisticsUpdateFailure3(_logger, exception, silo); } } @@ -272,5 +253,56 @@ void ILifecycleParticipant.Participate(ISiloLifecycle observer) return Task.CompletedTask; }); } + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Starting DeploymentLoadPublisher" + )] + private static partial void LogDebugStartingDeploymentLoadPublisher(ILogger logger); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Started DeploymentLoadPublisher" + )] + private static partial void LogDebugStartedDeploymentLoadPublisher(ILogger logger); + + [LoggerMessage( + Level = LogLevel.Trace, + Message = "PublishStatistics" + )] + private static partial void LogTracePublishStatistics(ILogger logger); + + [LoggerMessage( + EventId = (int)ErrorCode.Placement_RuntimeStatisticsUpdateFailure_1, + Level = LogLevel.Warning, + Message = "An unexpected exception was thrown by PublishStatistics.UpdateRuntimeStatistics(). Ignored" + )] + private static partial void LogWarningRuntimeStatisticsUpdateFailure1(ILogger logger, Exception exception); + + [LoggerMessage( + EventId = (int)ErrorCode.Placement_RuntimeStatisticsUpdateFailure_2, + Level = LogLevel.Warning, + Message = "An exception was thrown by PublishStatistics.UpdateRuntimeStatistics(). Ignoring" + )] + private static partial void LogWarningRuntimeStatisticsUpdateFailure2(ILogger logger, Exception exception); + + [LoggerMessage( + Level = LogLevel.Trace, + Message = "UpdateRuntimeStatistics from {Server}" + )] + private static partial void LogTraceUpdateRuntimeStatistics(ILogger logger, SiloAddress server); + + [LoggerMessage( + Level = LogLevel.Trace, + Message = "RefreshStatistics" + )] + private static partial void LogTraceRefreshStatistics(ILogger logger); + + [LoggerMessage( + EventId = (int)ErrorCode.Placement_RuntimeStatisticsUpdateFailure_3, + Level = LogLevel.Warning, + Message = "An unexpected exception was thrown from RefreshStatistics by ISiloControl.GetRuntimeStatistics({SiloAddress}). Will keep using stale statistics." + )] + private static partial void LogWarningRuntimeStatisticsUpdateFailure3(ILogger logger, Exception exception, SiloAddress siloAddress); } } diff --git a/src/Orleans.Runtime/Placement/PlacementService.cs b/src/Orleans.Runtime/Placement/PlacementService.cs index cd17709a05..db0ee83a26 100644 --- a/src/Orleans.Runtime/Placement/PlacementService.cs +++ b/src/Orleans.Runtime/Placement/PlacementService.cs @@ -16,7 +16,7 @@ namespace Orleans.Runtime.Placement /// /// Central point for placement decisions. /// - internal class PlacementService : IPlacementContext + internal partial class PlacementService : IPlacementContext { private const int PlacementWorkerCount = 16; private readonly PlacementStrategyResolver _strategyResolver; @@ -74,20 +74,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); - } - + LogDebugFoundAddress(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); - } - + LogDebugLookingUpAddress(grainId, message); var worker = _workers[grainId.GetUniformHashCode() % PlacementWorkerCount]; return worker.AddressMessage(message); @@ -139,7 +131,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"); + LogWarningAllActiveSilos(); return new SiloAddress[] { LocalSilo }; } } @@ -173,10 +165,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); - } + LogDebugInvalidatingCachedEntries(cacheUpdates.Count, message); foreach (var update in cacheUpdates) { @@ -393,5 +382,30 @@ private class GrainPlacementWorkItem public Task Result { get; set; } } } + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Found address {Address} for grain {GrainId} in cache for message {Message}" + )] + private partial void LogDebugFoundAddress(GrainAddress address, GrainId grainId, Message message); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Looking up address for grain {GrainId} for message {Message}" + )] + private partial void LogDebugLookingUpAddress(GrainId grainId, Message message); + + [LoggerMessage( + EventId = (int)ErrorCode.Catalog_GetApproximateSiloStatuses, + Level = LogLevel.Warning, + Message = "AllActiveSilos SiloStatusOracle.GetApproximateSiloStatuses empty" + )] + private partial void LogWarningAllActiveSilos(); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Invalidating {Count} cached entries for message {Message}" + )] + private partial void LogDebugInvalidatingCachedEntries(int count, Message message); } } diff --git a/src/Orleans.Runtime/Placement/Rebalancing/ActivationRebalancerMonitor.cs b/src/Orleans.Runtime/Placement/Rebalancing/ActivationRebalancerMonitor.cs index a1688c03e8..6b651005f0 100644 --- a/src/Orleans.Runtime/Placement/Rebalancing/ActivationRebalancerMonitor.cs +++ b/src/Orleans.Runtime/Placement/Rebalancing/ActivationRebalancerMonitor.cs @@ -70,7 +70,7 @@ public void Participate(ISiloLifecycle observer) ServiceLifecycleStage.ApplicationServices, _ => Task.CompletedTask, OnStop); - } + } private async Task OnStart(CancellationToken cancellationToken) { @@ -153,13 +153,17 @@ public void SubscribeToReports(IActivationRebalancerReportListener listener) public void UnsubscribeFromReports(IActivationRebalancerReportListener listener) => _statusListeners.Remove(listener); - [LoggerMessage(Level = LogLevel.Trace, Message = - "I have not received a report from the activation rebalancer for the last {Duration} which is more than the " + - "allowed interval {Period}. I will now try to wake it up with the assumption that it has has been stopped ungracefully.")] + [LoggerMessage( + Level = LogLevel.Trace, + Message = "I have not received a report from the activation rebalancer for the last {Duration} which is more than the " + + "allowed interval {Period}. I will now try to wake it up with the assumption that it has has been stopped ungracefully." + )] private partial void LogStartingRebalancer(TimeSpan duration, TimeSpan period); - [LoggerMessage(Level = LogLevel.Trace, Message = - "My silo '{Silo}' is stopping now, and I am the host of the activation rebalancer. " + - "I will attempt to migrate the rebalancer to another silo.")] + [LoggerMessage( + Level = LogLevel.Trace, + Message = "My silo '{Silo}' is stopping now, and I am the host of the activation rebalancer. " + + "I will attempt to migrate the rebalancer to another silo." + )] private partial void LogMigratingRebalancer(SiloAddress silo); -} \ No newline at end of file +} \ No newline at end of file diff --git a/src/Orleans.Runtime/Placement/Repartitioning/ActivationRepartitioner.MessageSink.cs b/src/Orleans.Runtime/Placement/Repartitioning/ActivationRepartitioner.MessageSink.cs index 0eb254bf76..92ee8db9fc 100644 --- a/src/Orleans.Runtime/Placement/Repartitioning/ActivationRepartitioner.MessageSink.cs +++ b/src/Orleans.Runtime/Placement/Repartitioning/ActivationRepartitioner.MessageSink.cs @@ -24,10 +24,7 @@ public void StartProcessingEdges() using var _ = new ExecutionContextSuppressor(); _processPendingEdgesTask = ProcessPendingEdges(_shutdownCts.Token); - if (_logger.IsEnabled(LogLevel.Trace)) - { - _logger.LogTrace("{Service} has started.", nameof(ActivationRepartitioner)); - } + LogTraceServiceStarted(_logger, nameof(ActivationRepartitioner)); } public async Task StopProcessingEdgesAsync(CancellationToken cancellationToken) @@ -41,10 +38,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)); - } + LogTraceServiceStopped(_logger, nameof(ActivationRepartitioner)); } private async Task ProcessPendingEdges(CancellationToken cancellationToken) @@ -144,4 +138,16 @@ async ValueTask IActivationRepartitionerSystemTarget.FlushBuffers() await Task.Delay(TimeSpan.FromMilliseconds(30)); } } + + [LoggerMessage( + Level = LogLevel.Trace, + Message = "{Service} has started." + )] + private static partial void LogTraceServiceStarted(ILogger logger, string service); + + [LoggerMessage( + Level = LogLevel.Trace, + Message = "{Service} has stopped." + )] + private static partial void LogTraceServiceStopped(ILogger logger, string service); } \ No newline at end of file diff --git a/src/Orleans.Runtime/Scheduler/ActivationTaskScheduler.cs b/src/Orleans.Runtime/Scheduler/ActivationTaskScheduler.cs index c9e5af0276..7b8d389ad2 100644 --- a/src/Orleans.Runtime/Scheduler/ActivationTaskScheduler.cs +++ b/src/Orleans.Runtime/Scheduler/ActivationTaskScheduler.cs @@ -13,7 +13,7 @@ namespace Orleans.Runtime.Scheduler /// A single-concurrency, in-order task scheduler for per-activation work scheduling. /// [DebuggerDisplay("ActivationTaskScheduler-{myId} RunQueue={workerGroup.WorkItemCount}")] - internal sealed class ActivationTaskScheduler : TaskScheduler + internal sealed partial class ActivationTaskScheduler : TaskScheduler { private readonly ILogger logger; @@ -32,7 +32,7 @@ internal ActivationTaskScheduler(WorkItemGroup workGroup, ILoggerGets an enumerable of the tasks currently scheduled on this scheduler. @@ -136,5 +136,11 @@ protected override bool TryExecuteTaskInline(Task task, bool taskWasPreviouslyQu } public override string ToString() => $"{GetType().Name}-{myId}:Queued={workerGroup.ExternalWorkItemCount}"; + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Created {TaskScheduler} with GrainContext={GrainContext}" + )] + private partial void LogCreatedTaskScheduler(ActivationTaskScheduler taskScheduler, IGrainContext grainContext); } } diff --git a/src/Orleans.Runtime/Services/GrainService.cs b/src/Orleans.Runtime/Services/GrainService.cs index bb0ca6fe4f..d8096161c5 100644 --- a/src/Orleans.Runtime/Services/GrainService.cs +++ b/src/Orleans.Runtime/Services/GrainService.cs @@ -9,7 +9,7 @@ namespace Orleans.Runtime { /// Base class for implementing a grain-like partitioned service with per silo instances of it automatically instantiated and started by silo runtime - public abstract class GrainService : SystemTarget, IRingRangeListener, IGrainService + public abstract partial class GrainService : SystemTarget, IRingRangeListener, IGrainService { private readonly IConsistentRingProvider ring; private readonly string typeName; @@ -88,13 +88,7 @@ private void OnStatusChange(GrainServiceStatus oldStatus, GrainServiceStatus new public virtual Task Start() { RingRange = ring.GetMyRange(); - Logger.LogInformation( - (int)ErrorCode.RS_ServiceStarting, - "Starting {TypeName} grain service on: {Silo} x{HashCode}, with range {RingRange}", - this.typeName, - Silo, - Silo.GetConsistentHashCode().ToString("X8"), - RingRange); + LogInformationServiceStarting(Logger, this.typeName, Silo, new(Silo), RingRange); StartInBackground().Ignore(); return Task.CompletedTask; @@ -117,10 +111,7 @@ public virtual Task Stop() { StoppedCancellationTokenSource.Cancel(); - Logger.LogInformation( - (int)ErrorCode.RS_ServiceStopping, - "Stopping {TypeName} grain service", - typeName); + LogInformationServiceStopping(Logger, typeName); Status = GrainServiceStatus.Stopped; return Task.CompletedTask; @@ -141,18 +132,39 @@ void IRingRangeListener.RangeChangeNotification(IRingRange oldRange, IRingRange /// A representing the work performed. public virtual Task OnRangeChange(IRingRange oldRange, IRingRange newRange, bool increased) { - Logger.LogInformation( - (int)ErrorCode.RS_RangeChanged, - "My range changed from {OldRange} to {NewRange} increased = {Increased}", - oldRange, - newRange, - increased); + LogInformationRangeChanged(Logger, oldRange, newRange, increased); RingRange = newRange; RangeSerialNumber++; return Task.CompletedTask; } + private readonly struct SiloAddressHashCodeLogValue(SiloAddress silo) + { + public override string ToString() => silo.GetConsistentHashCode().ToString("X8"); + } + + [LoggerMessage( + Level = LogLevel.Information, + EventId = (int)ErrorCode.RS_ServiceStarting, + Message = "Starting {TypeName} grain service on: {Silo} x{HashCode}, with range {RingRange}" + )] + private static partial void LogInformationServiceStarting(ILogger logger, string typeName, SiloAddress silo, SiloAddressHashCodeLogValue hashCode, IRingRange ringRange); + + [LoggerMessage( + Level = LogLevel.Information, + EventId = (int)ErrorCode.RS_ServiceStopping, + Message = "Stopping {TypeName} grain service" + )] + private static partial void LogInformationServiceStopping(ILogger logger, string typeName); + + [LoggerMessage( + Level = LogLevel.Information, + EventId = (int)ErrorCode.RS_RangeChanged, + Message = "My range changed from {OldRange} to {NewRange} increased = {Increased}" + )] + private static partial void LogInformationRangeChanged(ILogger logger, IRingRange oldRange, IRingRange newRange, bool increased); + /// Possible statuses of a grain service protected enum GrainServiceStatus { diff --git a/src/Orleans.Runtime/Silo/Silo.cs b/src/Orleans.Runtime/Silo/Silo.cs index a1ae80fb25..c5267c2f86 100644 --- a/src/Orleans.Runtime/Silo/Silo.cs +++ b/src/Orleans.Runtime/Silo/Silo.cs @@ -15,13 +15,14 @@ using Orleans.Services; using Orleans.Configuration; using Orleans.Internal; +using System.Net; namespace Orleans.Runtime { /// /// Orleans silo. /// - public sealed class Silo : IAsyncDisposable, IDisposable + public sealed partial class Silo : IAsyncDisposable, IDisposable { /// Standard name for Primary silo. public const string PrimarySiloName = "Primary"; @@ -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()); + LogSiloStartingWithGC(logger, GCSettings.IsServerGC, GCSettings.LatencyMode); 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)."); + LogWarningSiloGcNotRunningWithServerGC(logger); + LogWarningSiloGcMultiCoreSystem(logger); } 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); + LogWarningSiloGcVerboseLOggingConfigured(logger, 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); + LogInfoSiloInitializing(logger, siloDetails.DnsHostName, Environment.MachineName, localEndpoint, siloDetails.SiloAddress.Generation); + LogInfoSiloInitConfig(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"); + LogErrorSiloStartGrainFactoryNotRegistered(logger, exc); 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")); + LogInfoSiloInitializingFinished(logger, SiloAddress, new(SiloAddress)); } /// @@ -181,7 +161,7 @@ public async Task StartAsync(CancellationToken cancellationToken) } catch (Exception exc) { - logger.LogError((int)ErrorCode.SiloStartError, exc, "Exception during Silo.Start"); + LogErrorSiloStart(logger, exc); throw; } } @@ -211,7 +191,7 @@ private Task OnRuntimeInitializeStart(CancellationToken ct) this.SystemStatus = SystemStatus.Starting; } - logger.LogInformation((int)ErrorCode.SiloStarting, "Silo Start()"); + LogInfoSiloStarting(logger); return Task.CompletedTask; } @@ -220,11 +200,8 @@ 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); + + LogInfoSiloStartPerfMeasure(logger, taskName, stopWatch.ElapsedMilliseconds); } private async Task StartAsyncTaskWithPerfAnalysis(string taskName, Func task, Stopwatch stopWatch) @@ -232,11 +209,8 @@ 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); + + LogInfoSiloStartPerfMeasure(logger, taskName, stopWatch.ElapsedMilliseconds); } private Task OnRuntimeServicesStart(CancellationToken ct) @@ -266,18 +240,11 @@ 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); + LogErrorStartingSiloGoingToFastKill(logger, exc, SiloAddress); throw; } - if (logger.IsEnabled(LogLevel.Debug)) - { - logger.LogDebug("Silo.Start complete: System status = {SystemStatus}", this.SystemStatus); - } + LogDebugSiloStartComplete(logger, this.SystemStatus); } private Task OnBecomeActiveStart(CancellationToken ct) @@ -315,13 +282,11 @@ private async Task RegisterGrainService(IGrainService service) } catch (TimeoutException exception) { - logger.LogError(exception, "GrainService initialization timed out after '{Timeout}'.", initTimeout); + LogErrorGrainInitializationTimeout(logger, exception, initTimeout); throw; } - logger.LogInformation( - "Grain Service {GrainServiceType} registered successfully.", - service.GetType().FullName); + LogInfoGrainServiceRegistered(logger, service.GetType().FullName); } private async Task StartGrainService(IGrainService service) @@ -334,11 +299,11 @@ private async Task StartGrainService(IGrainService service) } catch (TimeoutException exception) { - logger.LogError(exception, "GrainService startup timed out after '{Timeout}'.", initTimeout); + LogErrorGrainStartupTimeout(logger, exception, initTimeout); throw; } - logger.LogInformation("Grain Service {GrainServiceType} started successfully.", service.GetType().FullName); + LogInfoGrainServiceStarted(logger, service.GetType().FullName); } /// @@ -386,18 +351,12 @@ public async Task StopAsync(CancellationToken cancellationToken) if (stopAlreadyInProgress) { - if (logger.IsEnabled(LogLevel.Debug)) - { - logger.LogDebug((int)ErrorCode.SiloStopInProgress, "Silo shutdown in progress. Waiting for shutdown to be completed."); - } + LogDebugSiloStopInProgress(logger); var pause = TimeSpan.FromSeconds(1); while (!this.SystemStatus.Equals(SystemStatus.Terminated)) { - if (logger.IsEnabled(LogLevel.Debug)) - { - logger.LogDebug((int)ErrorCode.WaitingForSiloStop, "Silo shutdown still in progress..."); - } + LogDebugSiloStopStillInProgress(logger); await Task.Delay(pause).ConfigureAwait(false); } @@ -407,17 +366,11 @@ public async Task StopAsync(CancellationToken cancellationToken) if (gracefully) { - if (logger.IsEnabled(LogLevel.Debug)) - { - logger.LogDebug((int)ErrorCode.SiloShuttingDown, "Silo shutdown initiated (graceful)"); - } + LogSiloShuttingDown(logger, LogLevel.Debug, "graceful"); } else { - if (logger.IsEnabled(LogLevel.Warning)) - { - logger.LogWarning((int)ErrorCode.SiloShuttingDown, "Silo shutdown initiated (non-graceful)"); - } + LogSiloShuttingDown(logger, LogLevel.Debug, "non-graceful"); } try @@ -429,17 +382,11 @@ public async Task StopAsync(CancellationToken cancellationToken) // log final status if (gracefully) { - if (logger.IsEnabled(LogLevel.Debug)) - { - logger.LogDebug((int)ErrorCode.SiloShutDown, "Silo shutdown completed (graceful)!"); - } + LogSiloShutDown(logger, LogLevel.Debug, "graceful"); } else { - if (logger.IsEnabled(LogLevel.Warning)) - { - logger.LogWarning((int)ErrorCode.SiloShutDown, "Silo shutdown completed (non-graceful)!"); - } + LogSiloShutDown(logger, LogLevel.Warning, "non-graceful"); } // signal to all awaiters that the silo has terminated. @@ -463,7 +410,7 @@ private async Task OnRuntimeInitializeStop(CancellationToken ct) } catch (Exception exception) { - this.logger.LogError(exception, "Error stopping message center"); + LogErrorStoppingMessageCenter(logger, exception); } SystemStatus = SystemStatus.Terminated; @@ -481,11 +428,11 @@ private async Task OnBecomeActiveStop(CancellationToken ct) { if (!ct.IsCancellationRequested) { - logger.LogError(exception, "Error deactivating activations."); + LogErrorDeactivatingActivations(logger, exception); } else { - logger.LogWarning("Some grains failed to deactivate promptly."); + LogWarningSomeGrainsFailedToDeactivate(logger); } } @@ -494,10 +441,7 @@ private async Task OnBecomeActiveStop(CancellationToken ct) } catch (Exception exc) { - logger.LogError( - (int)ErrorCode.SiloFailedToStopMembership, - exc, - "Failed to shutdown gracefully. About to terminate ungracefully"); + LogErrorSiloFailedToStopMembership(logger, exc); } // Stop the gateway @@ -518,7 +462,7 @@ await lifecycleSchedulingSystemTarget } catch (Exception exception) { - logger.LogError(exception, "Sending gateway disconnection requests to connected clients failed."); + LogErrorSendingDisconnectRequests(logger, exception); if (!ct.IsCancellationRequested) { throw; @@ -536,20 +480,14 @@ await grainService } catch (Exception exception) { - logger.LogError(exception, "Stopping GrainService '{GrainService}' failed.", grainService); + LogErrorStoppingGrainService(logger, grainService, exception); if (!ct.IsCancellationRequested) { throw; } } - if (this.logger.IsEnabled(LogLevel.Debug)) - { - logger.LogDebug( - "{GrainServiceType} Grain Service with Id {GrainServiceId} stopped successfully.", - grainService.GetType().FullName, - grainService.GetGrainId().ToString()); - } + LogDebugGrainServiceStopped(logger, grainService.GetType().FullName, grainService.GetGrainId()); } } @@ -584,6 +522,192 @@ public void Dispose() { } } + + [LoggerMessage( + Level = LogLevel.Information, + Message = "Silo starting with GC settings: ServerGC={ServerGC} GCLatencyMode={GCLatencyMode}" + )] + private static partial void LogSiloStartingWithGC(ILogger logger, bool serverGC, GCLatencyMode gcLatencyMode); + + [LoggerMessage( + Level = LogLevel.Warning, + EventId = (int)ErrorCode.SiloGcWarning, + Message = "Note: Silo not running with ServerGC turned on - recommend checking app config : --" + )] + private static partial void LogWarningSiloGcNotRunningWithServerGC(ILogger logger); + + [LoggerMessage( + Level = LogLevel.Warning, + EventId = (int)ErrorCode.SiloGcWarning, + Message = "Note: ServerGC only kicks in on multi-core systems (settings enabling ServerGC have no effect on single-core machines)." + )] + private static partial void LogWarningSiloGcMultiCoreSystem(ILogger logger); + + [LoggerMessage( + Level = LogLevel.Warning, + EventId = (int)ErrorCode.SiloGcWarning, + Message = $"A verbose logging level ({{highestLogLevel}}) is configured. This will impact performance. The recommended log level is {nameof(LogLevel.Information)}." + )] + private static partial void LogWarningSiloGcVerboseLOggingConfigured(ILogger logger, string highestLogLevel); + + [LoggerMessage( + Level = LogLevel.Information, + EventId = (int)ErrorCode.SiloInitializing, + Message = "-------------- Initializing silo on host {HostName} MachineName {MachineName} at {LocalEndpoint}, gen {Generation} --------------" + )] + private static partial void LogInfoSiloInitializing(ILogger logger, string hostName, string machineName, IPEndPoint localEndpoint, int generation); + + [LoggerMessage( + Level = LogLevel.Information, + EventId = (int)ErrorCode.SiloInitConfig, + Message = "Starting silo {SiloName}" + )] + private static partial void LogInfoSiloInitConfig(ILogger logger, string siloName); + + [LoggerMessage( + Level = LogLevel.Error, + EventId = (int)ErrorCode.SiloStartError, + Message = "Exception during Silo.Start, GrainFactory was not registered in Dependency Injection container" + )] + private static partial void LogErrorSiloStartGrainFactoryNotRegistered(ILogger logger, Exception exc); + + private readonly struct SiloAddressConsistentHashCodeLogValue(SiloAddress siloAddress) + { + public override string ToString() => siloAddress.GetConsistentHashCode().ToString("X"); + } + + [LoggerMessage( + Level = LogLevel.Information, + EventId = (int)ErrorCode.SiloInitializingFinished, + Message = "-------------- Started silo {SiloAddress}, ConsistentHashCode {HashCode} --------------" + )] + private static partial void LogInfoSiloInitializingFinished(ILogger logger, SiloAddress siloAddress, SiloAddressConsistentHashCodeLogValue hashCode); + + [LoggerMessage( + Level = LogLevel.Error, + EventId = (int)ErrorCode.SiloStartError, + Message = "Exception during Silo.Start" + )] + private static partial void LogErrorSiloStart(ILogger logger, Exception exc); + + [LoggerMessage( + Level = LogLevel.Information, + EventId = (int)ErrorCode.SiloStarting, + Message = "Silo Start()" + )] + private static partial void LogInfoSiloStarting(ILogger logger); + + [LoggerMessage( + Level = LogLevel.Information, + EventId = (int)ErrorCode.SiloStartPerfMeasure, + Message = "{TaskName} took {ElapsedMilliseconds} milliseconds to finish" + )] + private static partial void LogInfoSiloStartPerfMeasure(ILogger logger, string taskName, long elapsedMilliseconds); + + [LoggerMessage( + Level = LogLevel.Error, + EventId = (int)ErrorCode.Runtime_Error_100330, + Message = "Error starting silo {SiloAddress}. Going to FastKill()." + )] + private static partial void LogErrorStartingSiloGoingToFastKill(ILogger logger, Exception exc, SiloAddress siloAddress); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Silo.Start complete: System status = {SystemStatus}" + )] + private static partial void LogDebugSiloStartComplete(ILogger logger, SystemStatus systemStatus); + + [LoggerMessage( + Level = LogLevel.Error, + Message = "GrainService initialization timed out after '{Timeout}'." + )] + private static partial void LogErrorGrainInitializationTimeout(ILogger logger, Exception exception, TimeSpan timeout); + + [LoggerMessage( + Level = LogLevel.Information, + Message = "Grain Service {GrainServiceType} registered successfully." + )] + private static partial void LogInfoGrainServiceRegistered(ILogger logger, string grainServiceType); + + [LoggerMessage( + Level = LogLevel.Error, + Message = "GrainService startup timed out after '{Timeout}'." + )] + private static partial void LogErrorGrainStartupTimeout(ILogger logger, Exception exception, TimeSpan timeout); + + [LoggerMessage( + Level = LogLevel.Information, + Message = "Grain Service {GrainServiceType} started successfully." + )] + private static partial void LogInfoGrainServiceStarted(ILogger logger, string grainServiceType); + + [LoggerMessage( + Level = LogLevel.Debug, + EventId = (int)ErrorCode.SiloStopInProgress, + Message = "Silo shutdown in progress. Waiting for shutdown to be completed." + )] + private static partial void LogDebugSiloStopInProgress(ILogger logger); + + [LoggerMessage( + Level = LogLevel.Debug, + EventId = (int)ErrorCode.SiloStopInProgress, + Message = "Silo shutdown still in progress." + )] + private static partial void LogDebugSiloStopStillInProgress(ILogger logger); + + [LoggerMessage( + EventId = (int)ErrorCode.SiloShuttingDown, + Message = "Silo shutdown initiated ({gracefully})." + )] + private static partial void LogSiloShuttingDown(ILogger logger, LogLevel logLevel, string gracefully); + + [LoggerMessage( + EventId = (int)ErrorCode.SiloShutDown, + Message = "Silo shutdown completed ({gracefully})." + )] + private static partial void LogSiloShutDown(ILogger logger, LogLevel logLevel, string gracefully); + + [LoggerMessage( + Level = LogLevel.Error, + Message = "Error stopping message center." + )] + private static partial void LogErrorStoppingMessageCenter(ILogger logger, Exception exception); + + [LoggerMessage( + Level = LogLevel.Error, + Message = "Error deactivating activations." + )] + private static partial void LogErrorDeactivatingActivations(ILogger logger, Exception exception); + + [LoggerMessage( + Level = LogLevel.Warning, + Message = "Some grains failed to deactivate promptly." + )] + private static partial void LogWarningSomeGrainsFailedToDeactivate(ILogger logger); + + [LoggerMessage( + Level = LogLevel.Error, + Message = "Failed to stop gracefully. About to terminate ungracefully." + )] + private static partial void LogErrorSiloFailedToStopMembership(ILogger logger, Exception exc); + + [LoggerMessage( + Level = LogLevel.Error, + Message = "Error sending disconnect requests to connected clients." + )] + private static partial void LogErrorSendingDisconnectRequests(ILogger logger, Exception exception); + + [LoggerMessage( + Level = LogLevel.Error, + Message = "Stopping GrainService '{GrainService}' failed." + )] + private static partial void LogErrorStoppingGrainService(ILogger logger, GrainService grainService, Exception exception); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "{GrainServiceType} Grain Service with Id {GrainServiceId} stopped successfully." + )] + private static partial void LogDebugGrainServiceStopped(ILogger logger, string grainServiceType, GrainId grainServiceId); } // A dummy system target for fallback scheduler diff --git a/src/Orleans.Runtime/Silo/SiloControl.cs b/src/Orleans.Runtime/Silo/SiloControl.cs index 7bbbaf0cb5..cbb985d48a 100644 --- a/src/Orleans.Runtime/Silo/SiloControl.cs +++ b/src/Orleans.Runtime/Silo/SiloControl.cs @@ -24,7 +24,7 @@ namespace Orleans.Runtime { - internal class SiloControl : SystemTarget, ISiloControl + internal partial class SiloControl : SystemTarget, ISiloControl { private readonly ILogger logger; private readonly ILocalSiloDetails localSiloDetails; @@ -88,33 +88,33 @@ public SiloControl( public Task Ping(string message) { - logger.LogInformation("Ping"); + LogInformationPing(); return Task.CompletedTask; } [System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Reliability", "CA2001:AvoidCallingProblematicMethods", MessageId = "System.GC.Collect")] public Task ForceGarbageCollection() { - logger.LogInformation("ForceGarbageCollection"); + LogInformationForceGarbageCollection(); GC.Collect(); return Task.CompletedTask; } public Task ForceActivationCollection(TimeSpan ageLimit) { - logger.LogInformation("ForceActivationCollection"); + LogInformationForceActivationCollection(); return _activationCollector.CollectActivations(ageLimit, CancellationToken.None); } public Task ForceRuntimeStatisticsCollection() { - if (logger.IsEnabled(LogLevel.Debug)) logger.LogDebug("ForceRuntimeStatisticsCollection"); + LogDebugForceRuntimeStatisticsCollection(); return this.deploymentLoadPublisher.RefreshClusterStatistics(); } public Task GetRuntimeStatistics() { - if (logger.IsEnabled(LogLevel.Debug)) logger.LogDebug("GetRuntimeStatistics"); + LogDebugGetRuntimeStatistics(); var activationCount = this.activationDirectory.Count; var stats = new SiloRuntimeStatistics( activationCount, @@ -127,7 +127,7 @@ public Task GetRuntimeStatistics() public Task>> GetGrainStatistics() { - logger.LogInformation("GetGrainStatistics"); + LogInformationGetGrainStatistics(); 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); + LogErrorProviderNotFound(typeof(IControllable).FullName!, providerName); throw new ArgumentException($"Could not find a controllable service for type {typeof(IControllable).FullName} and name {providerName}."); } @@ -345,5 +341,48 @@ private List GetDetailedGrainStatisticsCore(string[]? ty } return stats; } + + [LoggerMessage( + Level = LogLevel.Information, + Message = "Ping" + )] + private partial void LogInformationPing(); + + [LoggerMessage( + Level = LogLevel.Information, + Message = "ForceGarbageCollection" + )] + private partial void LogInformationForceGarbageCollection(); + + [LoggerMessage( + Level = LogLevel.Information, + Message = "ForceActivationCollection" + )] + private partial void LogInformationForceActivationCollection(); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "ForceRuntimeStatisticsCollection" + )] + private partial void LogDebugForceRuntimeStatisticsCollection(); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "GetRuntimeStatistics" + )] + private partial void LogDebugGetRuntimeStatistics(); + + [LoggerMessage( + Level = LogLevel.Information, + Message = "GetGrainStatistics" + )] + private partial void LogInformationGetGrainStatistics(); + + [LoggerMessage( + EventId = (int)ErrorCode.Provider_ProviderNotFound, + Level = LogLevel.Error, + Message = "Could not find a controllable service for type {ProviderTypeFullName} and name {ProviderName}." + )] + private partial void LogErrorProviderNotFound(string providerTypeFullName, string providerName); } } diff --git a/src/Orleans.Runtime/Silo/Watchdog.cs b/src/Orleans.Runtime/Silo/Watchdog.cs index 0bbdb8293e..bcc3c80bf3 100644 --- a/src/Orleans.Runtime/Silo/Watchdog.cs +++ b/src/Orleans.Runtime/Silo/Watchdog.cs @@ -13,7 +13,7 @@ namespace Orleans.Runtime /// /// Monitors runtime and component health periodically, reporting complaints. /// - internal class Watchdog(IOptions clusterMembershipOptions, IEnumerable participants, ILogger logger) : IDisposable + internal partial class Watchdog(IOptions clusterMembershipOptions, IEnumerable participants, ILogger logger) : IDisposable { private static readonly TimeSpan PlatformWatchdogHeartbeatPeriod = TimeSpan.FromMilliseconds(1000); private readonly CancellationTokenSource _cancellation = new(); @@ -32,10 +32,7 @@ internal class Watchdog(IOptions clusterMembershipOpti public void Start() { - if (_logger.IsEnabled(LogLevel.Debug)) - { - _logger.LogDebug("Starting silo watchdog"); - } + LogDebugStartingSiloWatchdog(_logger); if (_platformWatchdogThread is not null) { @@ -64,10 +61,7 @@ public void Start() _componentWatchdogThread.Start(); - if (_logger.IsEnabled(LogLevel.Debug)) - { - _logger.LogDebug("Silo watchdog started successfully."); - } + LogDebugSiloWatchdogStartedSuccessfully(_logger); } public void Stop() @@ -85,7 +79,7 @@ protected void RunPlatformWatchdog() } catch (Exception exc) { - _logger.LogError((int)ErrorCode.Watchdog_InternalError, exc, "Platform watchdog encountered an internal error"); + LogErrorPlatformWatchdogInternalError(_logger, exc); } _platformWatchdogStopwatch.Restart(); @@ -101,24 +95,13 @@ private void CheckRuntimeHealth() if (timeSinceLastTick > PlatformWatchdogHeartbeatPeriod.Multiply(2)) { var gc = new[] { GC.CollectionCount(0), GC.CollectionCount(1), GC.CollectionCount(2) }; - _logger.LogWarning( - (int)ErrorCode.SiloHeartbeatTimerStalled, - ".NET Runtime Platform stalled for {TimeSinceLastTick}. Total GC Pause duration during that period: {pauseDurationSinceLastTick}. We are now using a total of {TotalMemory}MB memory. Collection counts per generation: 0: {GCGen0Count}, 1: {GCGen1Count}, 2: {GCGen2Count}", - timeSinceLastTick, - pauseDurationSinceLastTick, - GC.GetTotalMemory(false) / (1024 * 1024), - gc[0], - gc[1], - gc[2]); + LogWarningSiloHeartbeatTimerStalled(_logger, timeSinceLastTick, pauseDurationSinceLastTick, GC.GetTotalMemory(false) / (1024 * 1024), gc[0], gc[1], gc[2]); } var timeSinceLastParticipantCheck = _componentWatchdogStopwatch.Elapsed; if (timeSinceLastParticipantCheck > _componentHealthCheckPeriod.Multiply(2)) { - _logger.LogWarning( - (int)ErrorCode.SiloHeartbeatTimerStalled, - "Participant check thread has not completed for {TimeSinceLastTick}, potentially indicating lock contention or deadlock, CPU starvation, or another execution anomaly.", - timeSinceLastParticipantCheck); + LogWarningParticipantCheckThreadStalled(_logger, timeSinceLastParticipantCheck); } } @@ -132,7 +115,7 @@ protected void RunComponentWatchdog() } catch (Exception exc) { - _logger.LogError((int)ErrorCode.Watchdog_InternalError, exc, "Component health check encountered an internal error"); + LogErrorComponentHealthCheckInternalError(_logger, exc); } _componentWatchdogStopwatch.Restart(); @@ -167,18 +150,14 @@ private void CheckComponentHealth() } catch (Exception exc) { - _logger.LogWarning( - (int)ErrorCode.Watchdog_ParticipantThrownException, - exc, - "Health check participant {Participant} has thrown an exception from its CheckHealth method.", - participant.GetType()); + LogWarningHealthCheckParticipantException(_logger, exc, participant.GetType()); } } if (complaints != null) { WatchdogInstruments.FailedHealthChecks.Add(1); - _logger.LogWarning((int)ErrorCode.Watchdog_HealthCheckFailure, "{FailedChecks} of {ParticipantCount} components reported issues. Complaints: {Complaints}", numFailedChecks, _participants.Count, complaints); + LogWarningHealthCheckFailure(_logger, numFailedChecks, _participants.Count, complaints); } _lastComponentHealthCheckTime = DateTime.UtcNow; @@ -213,5 +192,64 @@ public void Dispose() // Ignore. } } + + private readonly struct ParticipantTypeLogValue(Type participantType) + { + public override string ToString() => participantType.ToString(); + } + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Starting silo watchdog" + )] + private static partial void LogDebugStartingSiloWatchdog(ILogger logger); + + [LoggerMessage( + Level = LogLevel.Debug, + Message = "Silo watchdog started successfully." + )] + private static partial void LogDebugSiloWatchdogStartedSuccessfully(ILogger logger); + + [LoggerMessage( + EventId = (int)ErrorCode.Watchdog_InternalError, + Level = LogLevel.Error, + Message = "Platform watchdog encountered an internal error" + )] + private static partial void LogErrorPlatformWatchdogInternalError(ILogger logger, Exception exc); + + [LoggerMessage( + EventId = (int)ErrorCode.SiloHeartbeatTimerStalled, + Level = LogLevel.Warning, + Message = ".NET Runtime Platform stalled for {TimeSinceLastTick}. Total GC Pause duration during that period: {PauseDurationSinceLastTick}. We are now using a total of {TotalMemory}MB memory. Collection counts per generation: 0: {GCGen0Count}, 1: {GCGen1Count}, 2: {GCGen2Count}" + )] + private static partial void LogWarningSiloHeartbeatTimerStalled(ILogger logger, TimeSpan timeSinceLastTick, TimeSpan pauseDurationSinceLastTick, long totalMemory, int gcGen0Count, int gcGen1Count, int gcGen2Count); + + [LoggerMessage( + EventId = (int)ErrorCode.SiloHeartbeatTimerStalled, + Level = LogLevel.Warning, + Message = "Participant check thread has not completed for {TimeSinceLastTick}, potentially indicating lock contention or deadlock, CPU starvation, or another execution anomaly." + )] + private static partial void LogWarningParticipantCheckThreadStalled(ILogger logger, TimeSpan timeSinceLastTick); + + [LoggerMessage( + EventId = (int)ErrorCode.Watchdog_InternalError, + Level = LogLevel.Error, + Message = "Component health check encountered an internal error" + )] + private static partial void LogErrorComponentHealthCheckInternalError(ILogger logger, Exception exc); + + [LoggerMessage( + EventId = (int)ErrorCode.Watchdog_ParticipantThrownException, + Level = LogLevel.Warning, + Message = "Health check participant {Participant} has thrown an exception from its CheckHealth method." + )] + private static partial void LogWarningHealthCheckParticipantException(ILogger logger, Exception exc, Type participant); + + [LoggerMessage( + EventId = (int)ErrorCode.Watchdog_HealthCheckFailure, + Level = LogLevel.Warning, + Message = "{FailedChecks} of {ParticipantCount} components reported issues. Complaints: {Complaints}" + )] + private static partial void LogWarningHealthCheckFailure(ILogger logger, int failedChecks, int participantCount, StringBuilder complaints); } } diff --git a/src/Orleans.Runtime/Storage/StateStorageBridge.cs b/src/Orleans.Runtime/Storage/StateStorageBridge.cs index 1b1b5712b5..cdadf912a5 100644 --- a/src/Orleans.Runtime/Storage/StateStorageBridge.cs +++ b/src/Orleans.Runtime/Storage/StateStorageBridge.cs @@ -19,7 +19,7 @@ namespace Orleans.Core /// /// The underlying state type. /// - public class StateStorageBridge : IStorage, IGrainMigrationParticipant + public partial class StateStorageBridge : IStorage, IGrainMigrationParticipant { private readonly IGrainContext _grainContext; private readonly StateStorageBridgeShared _shared; @@ -145,9 +145,7 @@ public void OnDehydrate(IDehydrationContext dehydrationContext) } catch (Exception exception) { - _shared.Logger.LogError(exception, "Failed to dehydrate state named {StateName} for grain {GrainId}", _shared.Name, _grainContext.GrainId); - - // We must throw here since we do not know that the dehydration context is in a clean state after this. + LogErrorOnDehydrate(_shared.Logger, exception, _shared.Name, _grainContext.GrainId); throw; } } @@ -164,8 +162,7 @@ public void OnRehydrate(IRehydrationContext rehydrationContext) } catch (Exception exception) { - // It is ok to swallow this exception, since state rehydration is best-effort. - _shared.Logger.LogError(exception, "Failed to rehydrate state named {StateName} for grain {GrainId}", _shared.Name, _grainContext.GrainId); + LogErrorOnRehydrate(_shared.Logger, exception, _shared.Name, _grainContext.GrainId); } } @@ -178,7 +175,7 @@ private void OnError(Exception exception, ErrorCode id, string operation) var grainId = _grainContext.GrainId; var providerName = _shared.Store.GetType().Name; - _shared.Logger.LogError((int)id, exception, "Error from storage provider {ProviderName}.{StateName} during {Operation} for grain {GrainId}{ErrorCode}", providerName, _shared.Name, operation, grainId, errorString); + LogErrorOnError(_shared.Logger, (int)id, exception, providerName, _shared.Name, operation, grainId, errorString); // If error is not specialization of OrleansException, wrap it if (exception is not OrleansException) @@ -189,6 +186,30 @@ private void OnError(Exception exception, ErrorCode id, string operation) ExceptionDispatchInfo.Throw(exception); } + + private readonly struct GrainIdLogValue(GrainId grainId) + { + public override string ToString() => grainId.ToString(); + } + + [LoggerMessage( + Level = LogLevel.Error, + Message = "Failed to dehydrate state named {StateName} for grain {GrainId}" + )] + private static partial void LogErrorOnDehydrate(ILogger logger, Exception exception, string stateName, GrainIdLogValue grainId); + + [LoggerMessage( + Level = LogLevel.Error, + Message = "Failed to rehydrate state named {StateName} for grain {GrainId}" + )] + private static partial void LogErrorOnRehydrate(ILogger logger, Exception exception, string stateName, GrainIdLogValue grainId); + + [LoggerMessage( + EventId = 0, // Replace with actual EventId if available + Level = LogLevel.Error, + Message = "Error from storage provider {ProviderName}.{StateName} during {Operation} for grain {GrainId}{ErrorCode}" + )] + private static partial void LogErrorOnError(ILogger logger, int eventId, Exception exception, string providerName, string stateName, string operation, GrainIdLogValue grainId, string? errorCode); } internal sealed class StateStorageBridgeSharedMap(ILoggerFactory loggerFactory, IActivatorProvider activatorProvider) diff --git a/src/Orleans.Runtime/Timers/GrainTimer.cs b/src/Orleans.Runtime/Timers/GrainTimer.cs index 75cc194edf..2602b10ac5 100644 --- a/src/Orleans.Runtime/Timers/GrainTimer.cs +++ b/src/Orleans.Runtime/Timers/GrainTimer.cs @@ -12,7 +12,7 @@ namespace Orleans.Runtime; -internal abstract class GrainTimer : IGrainTimer +internal abstract partial class GrainTimer : IGrainTimer { protected static readonly GrainInterfaceType InvokableInterfaceType = GrainInterfaceType.Create("Orleans.Runtime.IGrainTimerInvoker"); protected static readonly TimerCallback TimerCallback = (state) => ((GrainTimer)state!).ScheduleTickOnActivation(); @@ -92,7 +92,7 @@ protected void ScheduleTickOnActivation() { try { - Logger.LogError(exception, "Error invoking timer tick for timer '{Timer}'.", this); + LogErrorScheduleTickOnActivation(Logger, exception, this); } catch { @@ -108,10 +108,7 @@ private ValueTask InvokeGrainTimerCallbackAsync() { try { - if (Logger.IsEnabled(LogLevel.Trace)) - { - Logger.LogTrace((int)ErrorCode.TimerBeforeCallback, "About to invoke callback for timer {Timer}", this); - } + LogTraceBeforeCallback(Logger, this); _changed = false; var task = InvokeCallbackAsync(_cts.Token); @@ -125,10 +122,7 @@ private ValueTask InvokeGrainTimerCallbackAsync() else { // Complete synchronously. - if (Logger.IsEnabled(LogLevel.Trace)) - { - Logger.LogTrace((int)ErrorCode.TimerAfterCallback, "Completed timer callback for timer {Timer}", this); - } + LogTraceAfterCallback(Logger, this); OnTickCompleted(); return new(Response.Completed); @@ -174,11 +168,7 @@ private void OnTickCompleted() private Response OnCallbackException(Exception exc) { - Logger.LogWarning( - (int)ErrorCode.Timer_GrainTimerCallbackError, - exc, - "Caught and ignored exception thrown from timer callback for timer '{Timer}'.", - this); + LogWarningCallbackException(Logger, exc, this); return Response.FromException(exc); } @@ -188,10 +178,7 @@ private async ValueTask AwaitCallbackTask(Task task) { await task; - if (Logger.IsEnabled(LogLevel.Trace)) - { - Logger.LogTrace((int)ErrorCode.TimerAfterCallback, "Completed timer callback for timer '{Timer}'.", this); - } + LogTraceAfterCallback(Logger, this); return Response.Completed; } @@ -305,6 +292,33 @@ public void Dispose() public override string ToString() => timer.ToString(); } + + [LoggerMessage( + Level = LogLevel.Error, + Message = "Error invoking timer tick for timer '{Timer}'." + )] + private static partial void LogErrorScheduleTickOnActivation(ILogger logger, Exception exception, GrainTimer timer); + + [LoggerMessage( + EventId = (int)ErrorCode.TimerBeforeCallback, + Level = LogLevel.Trace, + Message = "About to invoke callback for timer {Timer}" + )] + private static partial void LogTraceBeforeCallback(ILogger logger, GrainTimer timer); + + [LoggerMessage( + EventId = (int)ErrorCode.TimerAfterCallback, + Level = LogLevel.Trace, + Message = "Completed timer callback for timer '{Timer}'." + )] + private static partial void LogTraceAfterCallback(ILogger logger, GrainTimer timer); + + [LoggerMessage( + EventId = (int)ErrorCode.Timer_GrainTimerCallbackError, + Level = LogLevel.Warning, + Message = "Caught and ignored exception thrown from timer callback for timer '{Timer}'." + )] + private static partial void LogWarningCallbackException(ILogger logger, Exception exception, GrainTimer timer); } internal sealed class GrainTimer : GrainTimer