Move ErrorHandlerMiddleware down next to HandlerInvocationMiddleware,…

… and ensure exceptions are logged (#1023)

* - Add HandleMessageContext.HandledException to log context so handler failures can be explained

* - Move ErrorHandler middleware next to handler invocation middleware in default setup so that it handles errors as a first priority.

LoggingMiddleware assumes a handled exception is available in the context, as should others, instead of handling and rethrowing themselves.

* - Update doc comments that list middleware order

* - Check exception not null before checking the message

Co-authored-by: George Kinsman <george.kinsman@justeattakeaway.com>

src/JustSaying/Fluent/ISubscriptionBuilder`1.cs

@@ -37,16 +37,16 @@ public interface ISubscriptionBuilder<out T>
     /// <li>Before_SomeCustomMiddleware</li>
     /// <li>Before_SomeOtherCustomMiddleware</li>
     /// <li>Before_MessageContextAccessorMiddleware</li>
-    /// <li>Before_ErrorHandlerMiddleware</li>
     /// <li>Before_LoggingMiddleware</li>
     /// <li>Before_StopwatchMiddleware</li>
     /// <li>Before_SqsPostProcessorMiddleware</li>
+    /// <li>Before_ErrorHandlerMiddleware</li>
     /// <li>Before_HandlerInvocationMiddleware</li>
     /// <li>After_HandlerInvocationMiddleware</li>
+    /// <li>After_ErrorHandlerMiddleware</li>
     /// <li>After_SqsPostProcessorMiddleware</li>
     /// <li>After_StopwatchMiddleware</li>
     /// <li>After_LoggingMiddleware</li>
-    /// <li>After_ErrorHandlerMiddleware</li>
     /// <li>After_MessageContextAccessorMiddleware</li>
     /// <li>After_SomeOtherCustomMiddleware</li>
     /// <li>After_SomeCustomMiddleware</li>
@@ -72,4 +72,4 @@ public interface ISubscriptionBuilder<out T>
         IVerifyAmazonQueues creator,
         IAwsClientFactoryProxy awsClientFactoryProxy,
         ILoggerFactory loggerFactory);
-}
+}

src/JustSaying/Messaging/Middleware/Handle/HandlerMiddlewareBuilderExtensions.cs

@@ -36,18 +36,18 @@ public static class HandlerMiddlewareBuilderExtensions
     /// <summary>
     /// <para>
     /// Applies a set of default middlewares in order. Adding other middlewares before this will add them
-    /// to the top of the stack, and are run first and last.
+    /// to the top of the stack, and are run first to last.
     /// Adding other middleware after this will add them to the bottom of the stack, just before the
     /// handler itself is invoked.
     /// </para>
     /// The middlewares this adds are, in order:
     /// <list type="bullet">
     /// <item>MessageContextAccessorMiddleware</item>
     /// <item>BackoffMiddleware (only if an <see cref="IMessageBackoffStrategy"/> is available)</item>
-    /// <item>ErrorHandlerMiddleware</item>
     /// <item>LoggingMiddleware</item>
     /// <item>StopwatchMiddleware</item>
     /// <item>SqsPostProcessorMiddleware</item>
+    /// <item>ErrorHandlerMiddleware</item>
     /// <item>HandlerInvocationMiddleware`1</item>
     /// </list>
     /// </summary>
@@ -65,12 +65,12 @@ public static class HandlerMiddlewareBuilderExtensions
         if (handlerType == null) throw new ArgumentNullException(nameof(handlerType), "HandlerType is used here to");
 
         builder.UseMessageContextAccessor();
-        builder.UseErrorHandler();
         builder.Use<LoggingMiddleware>();
         builder.UseStopwatch(handlerType);
         builder.Use<SqsPostProcessorMiddleware>();
+        builder.UseErrorHandler();
         builder.UseHandler<TMessage>();
 
         return builder;
     }
-}
+}

src/JustSaying/Messaging/Middleware/Logging/LoggingMiddleware.cs

@@ -44,20 +44,20 @@ protected override async Task<bool> RunInnerAsync(HandleMessageContext context,
         {
             if (dispatchSuccessful)
             {
-                _logger.LogInformation(MessageTemplate,
+                _logger.LogInformation(context.HandledException, MessageTemplate,
                     Succeeded,
                     context.Message.Id,
                     context.MessageType.FullName,
                     watch.ElapsedMilliseconds);
             }
             else
             {
-                _logger.LogWarning(MessageTemplate,
+                _logger.LogWarning(context.HandledException, MessageTemplate,
                     Failed,
                     context.Message.Id,
                     context.MessageType.FullName,
                     watch.ElapsedMilliseconds);
             }
         }
     }
-}
+}

tests/JustSaying.IntegrationTests/Fluent/Configuration/Approvals/WhenUsingNamingConventions.ThenTheNamingConventionIsApplied.approved.txt

@@ -7,10 +7,10 @@
         "QueueName": "beforequeue-simplemessage-afterqueue",
         "MiddlewareChain": [
           "MessageContextAccessorMiddleware",
-          "ErrorHandlerMiddleware",
           "LoggingMiddleware",
           "StopwatchMiddleware",
           "SqsPostProcessorMiddleware",
+          "ErrorHandlerMiddleware",
           "HandlerInvocationMiddleware`1[JustSaying.TestingFramework.SimpleMessage]"
         ]
       }

tests/JustSaying.IntegrationTests/Fluent/Publishing/Approvals/WhenAMessageIsPublishedToATopicWithACustomName.Then_The_Message_Is_Handled.approved.txt

@@ -7,10 +7,10 @@
         "QueueName": "integrationTestQueueName",
         "MiddlewareChain": [
           "MessageContextAccessorMiddleware",
-          "ErrorHandlerMiddleware",
           "LoggingMiddleware",
           "StopwatchMiddleware",
           "SqsPostProcessorMiddleware",
+          "ErrorHandlerMiddleware",
           "HandlerInvocationMiddleware`1[JustSaying.TestingFramework.SimpleMessage]"
         ]
       }

tests/JustSaying.IntegrationTests/Fluent/Publishing/Approvals/WhenInterrogatingTheBus.Then_The_Interrogation_Result_Should_Be_Returned.approved.txt

@@ -7,10 +7,10 @@
         "QueueName": "integrationTestQueueName",
         "MiddlewareChain": [
           "MessageContextAccessorMiddleware",
-          "ErrorHandlerMiddleware",
           "LoggingMiddleware",
           "StopwatchMiddleware",
           "SqsPostProcessorMiddleware",
+          "ErrorHandlerMiddleware",
           "HandlerInvocationMiddleware`1[JustSaying.TestingFramework.SimpleMessage]"
         ]
       }

tests/JustSaying.IntegrationTests/Fluent/Subscribing/Approvals/WhenApplyingDefaultMiddlewares.Then_The_Builder_Should_Put_User_Middlewares_In_The_Correct_Order.approved.txt

@@ -7,10 +7,10 @@
         "WhenApplyingDefaultMiddlewares+OuterTestMiddleware",
         "WhenApplyingDefaultMiddlewares+InnerTestMiddleware",
         "MessageContextAccessorMiddleware",
-        "ErrorHandlerMiddleware",
         "LoggingMiddleware",
         "StopwatchMiddleware",
         "SqsPostProcessorMiddleware",
+        "ErrorHandlerMiddleware",
         "WhenApplyingDefaultMiddlewares+AfterTestMiddleware",
         "HandlerInvocationMiddleware`1[JustSaying.TestingFramework.SimpleMessage]"
       ]

tests/JustSaying.IntegrationTests/Fluent/Subscribing/Approvals/WhenApplyingDefaultMiddlewares.Then_The_Defaults_Are_The_Defaults_For_Sure.approved.txt

@@ -5,10 +5,10 @@
       "QueueName": "TestQueueName",
       "MiddlewareChain": [
         "MessageContextAccessorMiddleware",
-        "ErrorHandlerMiddleware",
         "LoggingMiddleware",
         "StopwatchMiddleware",
         "SqsPostProcessorMiddleware",
+        "ErrorHandlerMiddleware",
         "HandlerInvocationMiddleware`1[JustSaying.TestingFramework.SimpleMessage]"
       ]
     }

tests/JustSaying.IntegrationTests/Fluent/Subscribing/Approvals/WhenHandlerIsDeclaredAsExactlyOnce.Then_The_Handler_Only_Receives_The_Message_Once.approved.txt

@@ -6,10 +6,10 @@
       "MiddlewareChain": [
         "ExactlyOnceMiddleware`1[JustSaying.TestingFramework.SimpleMessage]",
         "MessageContextAccessorMiddleware",
-        "ErrorHandlerMiddleware",
         "LoggingMiddleware",
         "StopwatchMiddleware",
         "SqsPostProcessorMiddleware",
+        "ErrorHandlerMiddleware",
         "HandlerInvocationMiddleware`1[JustSaying.TestingFramework.SimpleMessage]"
       ]
     }

tests/JustSaying.IntegrationTests/Logging/LogContextTests.cs

@@ -122,7 +122,12 @@ public async Task HandleMessageFromQueueLogs_ShouldHaveContext(bool handlerShoul
             handleMessage.ShouldNotBeNull();
 
             handleMessage.LogLevel.ShouldBe(level);
-            handleMessage.Exception?.Message.ShouldBe(exceptionMessage);
+
+            if (exceptionMessage != null)
+            {
+                handleMessage.Exception.ShouldNotBeNull();
+                handleMessage.Exception.Message.ShouldBe(exceptionMessage);
+            }
 
             var propertyMap = new Dictionary<string, object>(handleMessage.Properties);
             propertyMap.ShouldContainKeyAndValue("Status", status);