Improved exception logging to the console by making sure internal cancellations and timeout exceptions are logged

Author: daveaglick

RELEASE.md

@@ -1,6 +1,7 @@
 # 1.0.0-beta.68
 
 - Improved the `HttpClient.SendWithRetryAsync()` extension to log retries at the information level since they may indicate other problems, and to retry during internal `HttpClient` timeouts.
+- Improved exception logging to the console by making sure internal cancellations and timeout exceptions are logged (previously they were silent, which could create the impression nothing went wrong).
 
 # 1.0.0-beta.67
 

src/core/Statiq.App/Commands/EngineManager.cs

@@ -92,10 +92,16 @@ public async Task<ExitCode> ExecuteAsync(CancellationTokenSource cancellationTok
             }
             catch (Exception ex)
             {
+                // If this was a cancellation, check if it was due to a timeout or an actual cancellation
                 if (ex is OperationCanceledException)
                 {
-                    // No log message for cancellation
-                    return ExitCode.OperationCanceled;
+                    // Was this a "true" cancellation of the engine?
+                    if (Engine.CancellationToken.IsCancellationRequested)
+                    {
+                        _logger.LogInformation("Exited due to engine cancellation request");
+                        return ExitCode.OperationCanceled;
+                    }
+                    _logger.LogCritical("Operation/task timeout occurred or internal cancellation was triggered, inner exception(s) follow (if available)");
                 }
 
                 // Log exceptions not already logged (including those thrown by the engine directly)

src/core/Statiq.Common/Util/ExceptionExtensions.cs

@@ -2,6 +2,7 @@
 using System.Collections.Generic;
 using System.Linq;
 using System.Reflection;
+using System.Threading.Tasks;
 using Microsoft.Extensions.Logging;
 
 namespace Statiq.Common
@@ -20,6 +21,11 @@ public static IEnumerable<Exception> Unwrap(this Exception exception, bool unwra
                         return invocationException.InnerException.Unwrap(unwrapLoggedExceptions);
                     case LoggedException loggedException when unwrapLoggedExceptions:
                         return loggedException.InnerException.Unwrap(true);
+                    case TaskCanceledException taskCanceledException:
+                        // Timeouts will throw this and may have an inner exception (I.e. https://stackoverflow.com/a/66694886)
+                        return taskCanceledException.InnerException is object
+                            ? taskCanceledException.InnerException.Unwrap(unwrapLoggedExceptions)
+                            : new Exception[] { taskCanceledException };
                     default:
                         return new Exception[] { exception };
                 }
@@ -28,4 +34,4 @@ public static IEnumerable<Exception> Unwrap(this Exception exception, bool unwra
             return Array.Empty<Exception>();
         }
     }
-}
+}

src/core/Statiq.Core/Execution/PipelinePhase.cs

@@ -108,19 +108,35 @@ public async Task ExecuteAsync(
                 catch (Exception ex)
                 {
                     Outputs = ImmutableArray<IDocument>.Empty;
-                    if (!(ex is OperationCanceledException))
+
+                    // Report on the exception if it's not a "true" cancellation of the engine (I.e. a timeout or internal cancellation)
+                    if (!engine.CancellationToken.IsCancellationRequested)
                     {
+                        string exceptionType = "Exception";
+                        Exception exceptionToLog = ex;
                         LoggedException executeModulesException = ex as LoggedException;
-                        if (executeModulesException is object)
+
+                        // Was this a timeout (already tested that IsCancellationRequested is false)
+                        if (ex is OperationCanceledException)
+                        {
+                            exceptionType = "Timeout/Cancellation";
+                            exceptionToLog = ex.InnerException ?? ex;
+                        }
+                        else if (executeModulesException is object)
                         {
-                            ex = executeModulesException.InnerException;
+                            // ...or was it a logged exception
+                            exceptionToLog = executeModulesException.InnerException;
                         }
-                        _logger.LogDebug($"Exception while executing pipeline {PipelineName}/{Phase}: {ex}");
-                        if (executeModulesException is object)
+
+                        // Log the exception (or inner exception)
+                        _logger.LogDebug($"{exceptionType} while executing pipeline {PipelineName}/{Phase}: {exceptionToLog}");
+                        if (executeModulesException is object && exceptionToLog is object)
                         {
-                            throw executeModulesException.InnerException;
+                            throw exceptionToLog;
                         }
                     }
+
+                    // Always rethrow the exception
                     throw;
                 }
                 finally
@@ -233,4 +249,4 @@ private static void DisposeModules(IEnumerable<IModule> modules)
             }
         }
     }
-}
+}