Reduce log noise and improve formatting (#9227)

Adjust log levels and improve formatting

src/Orleans.Core/Lifecycle/LifecycleSubject.cs

@@ -90,9 +90,9 @@ protected virtual void PerfMeasureOnStart(int stage, TimeSpan elapsed)
             {
                 this.Logger.LogTrace(
                     (int)ErrorCode.SiloStartPerfMeasure,
-                    "Starting lifecycle stage {Stage} took {Elapsed} Milliseconds",
-                    stage,
-                    elapsed.TotalMilliseconds);
+                    "Starting lifecycle stage '{Stage}' took '{Elapsed}'.",
+                    GetStageName(stage),
+                    elapsed);
             }
         }
 
@@ -108,7 +108,7 @@ public virtual async Task OnStart(CancellationToken cancellationToken = default)
                 {
                     if (cancellationToken.IsCancellationRequested)
                     {
-                        throw new OrleansLifecycleCanceledException("Lifecycle start canceled by request");
+                        throw new OrleansLifecycleCanceledException($"Lifecycle start canceled at stage '{GetStageName(observerGroup.Key)}' by request.");
                     }
 
                     var stage = observerGroup.Key;
@@ -126,8 +126,8 @@ public virtual async Task OnStart(CancellationToken cancellationToken = default)
                 this.Logger.LogError(
                     (int)ErrorCode.LifecycleStartFailure,
                     ex,
-                    "Lifecycle start canceled due to errors at stage {Stage}",
-                    this._highStage);
+                    "Lifecycle start canceled due to errors at stage '{Stage}'.",
+                    _highStage is { } highStage ? GetStageName(highStage) : "Unknown");
                 throw;
             }
 
@@ -161,9 +161,9 @@ protected virtual void PerfMeasureOnStop(int stage, TimeSpan elapsed)
             {
                 this.Logger.LogTrace(
                     (int)ErrorCode.SiloStartPerfMeasure,
-                    "Stopping lifecycle stage {Stage} took {Elapsed} Milliseconds",
-                    stage,
-                    elapsed.TotalMilliseconds);
+                    "Stopping lifecycle stage '{Stage}' took '{Elapsed}'.",
+                    GetStageName(stage),
+                    elapsed);
             }
         }
 
@@ -181,7 +181,7 @@ public virtual async Task OnStop(CancellationToken cancellationToken = default)
             {
                 if (cancellationToken.IsCancellationRequested && !loggedCancellation)
                 {
-                    this.Logger.LogWarning("Lifecycle stop operations canceled by request.");
+                    this.Logger.LogWarning("Lifecycle stop operations canceled at stage '{Stage}' by request.", GetStageName(observerGroup.Key));
                     loggedCancellation = true;
                 }
 
@@ -190,32 +190,32 @@ public virtual async Task OnStop(CancellationToken cancellationToken = default)
                 try
                 {
                     var stopwatch = ValueStopwatch.StartNew();
-                    await Task.WhenAll(observerGroup.Select(orderedObserver => CallOnStop(orderedObserver, cancellationToken)));
+                    await Task.WhenAll(observerGroup.Select(orderedObserver => orderedObserver?.Observer is not null ? CallObserverStopAsync(orderedObserver.Observer, cancellationToken) : Task.CompletedTask));
                     stopwatch.Stop();
                     this.PerfMeasureOnStop(stage, stopwatch.Elapsed);
                 }
                 catch (Exception ex)
                 {
-                    this.Logger.LogError(
+                    this.Logger.LogWarning(
                         (int)ErrorCode.LifecycleStopFailure,
                         ex,
-                        "Stopping lifecycle encountered an error at stage {Stage}. Continuing to stop.",
-                        this._highStage);
+                        "Stopping lifecycle encountered an error at stage '{Stage}'. Continuing to stop.",
+                        _highStage is { } highStage ? GetStageName(highStage) : "Unknown");
                 }
 
                 this.OnStopStageCompleted(stage);
             }
+        }
 
-            static Task CallOnStop(OrderedObserver observer, CancellationToken cancellationToken)
+        protected virtual Task CallObserverStopAsync(ILifecycleObserver observer, CancellationToken cancellationToken)
+        {
+            try
             {
-                try
-                {
-                    return observer.Observer?.OnStop(cancellationToken) ?? Task.CompletedTask;
-                }
-                catch (Exception ex)
-                {
-                    return Task.FromException(ex);
-                }
+                return observer.OnStop(cancellationToken) ?? Task.CompletedTask;
+            }
+            catch (Exception ex)
+            {
+                return Task.FromException(ex);
             }
         }
 

src/Orleans.Runtime/Catalog/ActivationData.cs

@@ -1206,14 +1206,15 @@ private void RehydrateInternal(IRehydrationContext context)
         {
             if (_shared.Logger.IsEnabled(LogLevel.Debug))
             {
-                _shared.Logger.LogDebug("Rehydrating grain from previous activation");
+                _shared.Logger.LogDebug("Rehydrating grain '{GrainContext}' from previous activation.", this);
             }
 
             lock (this)
             {
                 if (State != ActivationState.Creating)
                 {
-                    throw new InvalidOperationException($"Attempted to rehydrate a grain in the {State} state");
+                    _shared.Logger.LogWarning("Ignoring attempt to rehydrate grain '{GrainContext}' in the '{State}' state.", this, State);
+                    return;
                 }
 
                 if (context.TryGetValue(GrainAddressMigrationContextKey, out GrainAddress? previousRegistration) && previousRegistration is not null)

src/Orleans.Runtime/Catalog/Catalog.cs

@@ -166,6 +166,7 @@ public IGrainContext GetOrCreateActivation(
                         ActivationId = ActivationId.NewId(),
                         MembershipVersion = MembershipVersion.MinValue,
                     };
+
                     result = this.grainActivator.CreateInstance(address);
                     activations.RecordNewTarget(result);
                 }

src/Orleans.Runtime/Core/ManagementGrain.cs

@@ -60,8 +60,6 @@ public async Task<Dictionary<SiloAddress, SiloStatus>> GetHosts(bool onlyActive
 
         public async Task<MembershipEntry[]> GetDetailedHosts(bool onlyActive = false)
         {
-            logger.LogInformation("GetDetailedHosts OnlyActive={OnlyActive}", onlyActive);
-
             await this.membershipTableManager.Refresh();
 
             var table = this.membershipTableManager.MembershipTableSnapshot;

src/Orleans.Runtime/Lifecycle/SiloLifecycleSubject.cs

@@ -38,7 +38,7 @@ public SiloLifecycleSubject(ILogger<SiloLifecycleSubject> logger) : base(logger)
         /// <inheritdoc />
         public override Task OnStart(CancellationToken cancellationToken = default)
         {
-            foreach(var stage in this.observers.GroupBy(o => o.Stage).OrderBy(s => s.Key))
+            foreach (var stage in this.observers.GroupBy(o => o.Stage).OrderBy(s => s.Key))
             {
                 if (this.Logger.IsEnabled(LogLevel.Debug))
                 {
@@ -47,7 +47,7 @@ public override Task OnStart(CancellationToken cancellationToken = default)
                         "Stage {Stage}: {Observers}",
                         this.GetStageName(stage.Key),
                         string.Join(", ", stage.Select(o => o.Name)));
-                }                
+                }
             }
 
             return base.OnStart(cancellationToken);
@@ -81,9 +81,9 @@ protected override void PerfMeasureOnStop(int stage, TimeSpan elapsed)
             {
                 this.Logger.LogDebug(
                     (int)ErrorCode.SiloStartPerfMeasure,
-                    "Stopping lifecycle stage {Stage} took {Elapsed} Milliseconds",
+                    "Stopping lifecycle stage '{Stage}' took '{Elapsed}'.",
                     this.GetStageName(stage),
-                    elapsed.TotalMilliseconds);
+                    elapsed);
             }
         }
 
@@ -94,10 +94,10 @@ protected override void PerfMeasureOnStart(int stage, TimeSpan elapsed)
             {
                 this.Logger.LogDebug(
                     (int)ErrorCode.SiloStartPerfMeasure,
-                    "Starting lifecycle stage {Stage} took {Elapsed} Milliseconds",
+                    "Starting lifecycle stage '{Stage}' took '{Elapsed}'",
                     this.GetStageName(stage),
-                    elapsed.TotalMilliseconds);
-            }                
+                    elapsed);
+            }
         }
 
         /// <inheritdoc />
@@ -137,18 +137,18 @@ public async Task OnStart(CancellationToken ct)
                     {
                         this.logger.LogDebug(
                             (int)ErrorCode.SiloStartPerfMeasure,
-                            "{Name} started in stage {Stage} in {Elapsed} Milliseconds",
+                            "'{Name}' started in stage '{Stage}' in '{Elapsed}'.",
                             this.Name,
                             this.StageName,
-                            stopwatch.Elapsed.TotalMilliseconds);
-                    }                    
+                            stopwatch.Elapsed);
+                    }
                 }
                 catch (Exception exception)
                 {
                     this.logger.LogError(
                         (int)ErrorCode.LifecycleStartFailure,
                         exception,
-                        "{Name} failed to start due to errors at stage {Stage}",
+                        "'{Name}' failed to start due to errors at stage '{Stage}'.",
                         this.Name,
                         this.StageName);
                     throw;
@@ -157,29 +157,48 @@ public async Task OnStart(CancellationToken ct)
 
             public async Task OnStop(CancellationToken cancellationToken = default)
             {
+                var stopwatch = ValueStopwatch.StartNew();
                 try
                 {
-                    var stopwatch = ValueStopwatch.StartNew();
+                    if (this.logger.IsEnabled(LogLevel.Debug))
+                    {
+                        this.logger.LogDebug(
+                            (int)ErrorCode.SiloStartPerfMeasure,
+                            "'{Name}' stopping in stage '{Stage}'.",
+                            this.Name,
+                            this.StageName);
+                    }
+
                     await this.observer.OnStop(cancellationToken);
                     stopwatch.Stop();
-                    if (this.logger.IsEnabled(LogLevel.Debug))
+                    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);
+                    }
+                    else if (this.logger.IsEnabled(LogLevel.Debug))
                     {
                         this.logger.LogDebug(
                             (int)ErrorCode.SiloStartPerfMeasure,
-                            "{Name} stopped in stage {Stage} in {Elapsed} Milliseconds.",
+                            "'{Name}' stopped in stage '{Stage}' in '{Elapsed}'.",
                             this.Name,
                             this.StageName,
-                            stopwatch.Elapsed.TotalMilliseconds);
-                    }                    
+                            stopwatch.Elapsed);
+                    }
                 }
                 catch (Exception exception)
                 {
                     this.logger.LogError(
                         (int)ErrorCode.LifecycleStartFailure,
                         exception,
-                        "{Name} failed to stop due to errors at stage {Stage}",
+                        "'{Name}' failed to stop due to errors at stage '{Stage}' after '{Elapsed}'.",
                         this.Name,
-                        this.StageName);
+                        this.StageName,
+                        stopwatch.Elapsed);
                     throw;
                 }
             }

src/Orleans.Runtime/MembershipService/ClusterMembershipSnapshot.cs

@@ -109,13 +109,12 @@ public ClusterMembershipUpdate CreateUpdate(ClusterMembershipSnapshot previous)
         public override string ToString()
         {
             var sb = new StringBuilder();
-            sb.Append($"Version: {this.Version}. {this.Members.Count} members");
+            sb.Append($"ClusterMembershipSnapshot {{ Version = {this.Version}, Members.Count = {this.Members.Count}, Members = [");
             var first = true;
             foreach (var member in this.Members)
             {
                 if (first)
                 {
-                    sb.Append(": ");
                     first = false;
                 }
                 else
@@ -126,6 +125,7 @@ public override string ToString()
                 sb.Append(member.Value);
             }
 
+            sb.Append("] }}");
             return sb.ToString();
         }
     }

src/Orleans.Runtime/MembershipService/MembershipAgent.cs

@@ -73,7 +73,7 @@ private async Task UpdateIAmAlive()
                     }
                     catch (Exception exception)
                     {
-                        this.log.LogError(
+                        this.log.LogWarning(
                             (int)ErrorCode.MembershipUpdateIAmAliveFailure,
                             exception,
                             "Failed to update table entry for this silo, will retry shortly");

src/Orleans.Runtime/MembershipService/MembershipSystemTarget.cs

@@ -158,10 +158,10 @@ private async Task GossipToRemoteSilo(
             }
             catch (Exception exception)
             {
-                this.log.LogError(
+                this.log.LogWarning(
                     (int)ErrorCode.MembershipGossipSendFailure,
                     exception,
-                    "Exception while sending gossip notification to remote silo {Silo}",
+                    "Error sending gossip notification to remote silo '{Silo}'.",
                     silo);
             }
         }
@@ -177,7 +177,7 @@ private async Task ReadTable()
                 this.log.LogError(
                     (int)ErrorCode.MembershipGossipProcessingFailure,
                     exception,
-                    "Error refreshing membership table");
+                    "Error refreshing membership table.");
             }
         }
 

src/Orleans.Runtime/MembershipService/MembershipTableManager.cs

@@ -258,7 +258,7 @@ private async Task PeriodicallyRefreshMembershipTable()
                     }
                     catch (Exception exception)
                     {
-                        this.log.LogError(
+                        this.log.LogWarning(
                             (int)ErrorCode.MembershipUpdateIAmAliveFailure,
                             exception,
                             "Failed to refresh membership table, will retry shortly");
@@ -270,7 +270,7 @@ private async Task PeriodicallyRefreshMembershipTable()
             }
             catch (Exception exception) when (this.fatalErrorHandler.IsUnexpected(exception))
             {
-                this.log.LogError(exception, "Error refreshing membership table");
+                this.log.LogWarning(exception, "Error refreshing membership table");
                 this.fatalErrorHandler.OnFatalException(this, nameof(PeriodicallyRefreshMembershipTable), exception);
             }
             finally
@@ -363,7 +363,7 @@ async Task<bool> UpdateMyStatusTask(int counter)
                 else
                 {
                     wasThrownLocally = true;
-                    log.LogError(
+                    log.LogInformation(
                         (int)ErrorCode.MembershipFailedToWriteConditional,
                         "Silo {MyAddress} failed to update its status to {Status} in the membership table due to write contention on the table after {NumCalls} attempts.",
                         myAddress,
@@ -374,7 +374,7 @@ async Task<bool> UpdateMyStatusTask(int counter)
             }
             catch (Exception exc)  when (!wasThrownLocally)
             {
-                log.LogError(
+                log.LogWarning(
                     (int)ErrorCode.MembershipFailedToWrite,
                     exc,
                     "Silo {MyAddress} failed to update its status to {Status} in the table due to failures (socket failures or table read/write failures) after {NumCalls} attempts",

src/Orleans.Runtime/Silo/SiloControl.cs

@@ -159,21 +159,18 @@ public Task<List<Tuple<GrainId, string, int>>> GetGrainStatistics()
 
         public Task<List<DetailedGrainStatistic>> GetDetailedGrainStatistics(string[]? types = null)
         {
-            if (logger.IsEnabled(LogLevel.Debug)) logger.LogDebug("GetDetailedGrainStatistics");
             var stats = GetDetailedGrainStatisticsCore();
             return Task.FromResult(stats);
         }
 
         public Task<SimpleGrainStatistic[]> GetSimpleGrainStatistics()
         {
-            logger.LogInformation("GetSimpleGrainStatistics");
             return Task.FromResult(_grainCountStatistics.GetSimpleGrainStatistics().Select(p =>
                 new SimpleGrainStatistic { SiloAddress = this.localSiloDetails.SiloAddress, GrainType = p.Key, ActivationCount = (int)p.Value }).ToArray());
         }
 
         public async Task<DetailedGrainReport> GetDetailedGrainReport(GrainId grainId)
         {
-            logger.LogInformation("DetailedGrainReport for grain id {GrainId}", grainId);
             string? grainClassName;
             try
             {