feat(msg.routing): add message handler summary logging (#648)

Provides a summary-logging structure during the message routing which
focuses on the functionality rather than the technicality of message
handler registration. An example of these logs:

### Error, that results in dead-lettering
```log
2025-09-08T08:38:42 Debug > [Received] message (message ID="c353d940-fb6e-4990-a8d4-3e15be9e874e") on Azure Service Bus Queue message pump
2025-09-08T08:38:42 Debug > Message "c353d940-fb6e-4990-a8d4-3e15be9e874e" [Skipped by] "PassThruOrderMessageHandler" => "✗ custom context filter failed (returns 'false')"
2025-09-08T08:38:42 Debug > Message "c353d940-fb6e-4990-a8d4-3e15be9e874e" [Skipped by] "ShipmentAzureServiceBusMessageHandler" => "✗ default JSON body parsing failed (exception thrown)": System.Text.Json.JsonException: The JSON property 'Amount' could not be mapped to any .NET member contained in type 'Arcus.Messaging.Tests.Core.Messages.v1.Shipment'.
2025-09-08T08:38:42 Debug > Message "c353d940-fb6e-4990-a8d4-3e15be9e874e" [Skipped by] "OrderBatchMessageHandler" => "
✓ custom context filter passed (against type=AzureServiceBusMessageContext)
✗ default JSON body parsing failed (exception thrown)": System.Text.Json.JsonException: The JSON property 'Id' could not be mapped to any .NET member contained in type 'Arcus.Messaging.Tests.Core.Messages.v1.OrderBatch'.
2025-09-08T08:38:42 Error > Message '"c353d940-fb6e-4990-a8d4-3e15be9e874e"' [Failed in] message pump => ✗ no matched handler handled found for message
2025-09-08T08:38:42 Debug > [Settle:DeadLetter] message (message ID="c353d940-fb6e-4990-a8d4-3e15be9e874e") on Azure Service Bus Queue message pump => "no matched handler handled found for message"
```

### Success, after skipping some handlers
```log
2025-09-08T08:40:10 Debug > [Received] message (message ID="9988e52e-030b-ea6c-9bf5-0629cb0727cf") on Azure Service Bus Queue message pump
2025-09-08T08:40:10 Debug > Message "9988e52e-030b-ea6c-9bf5-0629cb0727cf" [Skipped by] "PassThruOrderMessageHandler" => "✗ custom context filter failed (returns 'false')"
2025-09-08T08:40:10 Debug > Message "9988e52e-030b-ea6c-9bf5-0629cb0727cf" [Skipped by] "PassThruOrderMessageHandler" => "✗ custom context filter failed (returns 'false')"
2025-09-08T08:40:10 Trace > [Test] Write order v1 message to disk: "9988e52e-030b-ea6c-9bf5-0629cb0727cf"
2025-09-08T08:40:10 Debug > "Order" "9988e52e-030b-ea6c-9bf5-0629cb0727cf" [Processed by] "WriteOrderToDiskAzureServiceBusMessageHandler" => "
✓ custom context filter passed (against type=AzureServiceBusMessageContext)
✓ default JSON body parsing passed (additional members=Error)
✓ custom body filter passed (against type=Order)"
2025-09-08T08:40:10 Information > Message '"9988e52e-030b-ea6c-9bf5-0629cb0727cf"' was processed by "WriteOrderToDiskAzureServiceBusMessageHandler" | skipped by "2 other handlers"
```

The `DEBUG` is used to write the matching pre-checks, `INFO`/`ERROR` is
used as the final summary, written as a single sentence.

To accomplish this, this PR places all the logging within the non-Azure
Service Bus-related message routing functionality. This gives us the
opportunity to only focus on Azure Service Bus-related code in the
`ServiceBusMessageRouter` 👉 which it should be.

Furthermore, the integration tests have been enhanced to always add
'unrelated' message handlers, to trigger the message routing more and
not to rely on unit tests (which are not only there to test deprecated
functionality).

Closes #647

Author: stijnmoreels

src/Arcus.Messaging.Abstractions.ServiceBus/Extensions/ServiceBusMessageHandlerOptions.cs

@@ -19,8 +19,8 @@ public class ServiceBusMessageHandlerOptions<TMessage>
         private readonly Collection<Func<AzureServiceBusMessageContext, bool>> _messageContextFilters = [];
 
         internal Func<IServiceProvider, IMessageBodySerializer> MessageBodySerializerImplementationFactory { get; private set; }
-        internal Func<TMessage, bool> MessageBodyFilter => msg => _messageBodyFilters.All(filter => filter(msg));
-        internal Func<AzureServiceBusMessageContext, bool> MessageContextFilter => ctx => _messageContextFilters.All(filter => filter(ctx));
+        internal Func<TMessage, bool> MessageBodyFilter => _messageBodyFilters.Count is 0 ? null : msg => _messageBodyFilters.All(filter => filter(msg));
+        internal Func<AzureServiceBusMessageContext, bool> MessageContextFilter => _messageContextFilters.Count is 0 ? null : ctx => _messageContextFilters.All(filter => filter(ctx));
 
         /// <summary>
         /// Adds a custom serializer instance that deserializes the incoming <see cref="ServiceBusReceivedMessage.Body"/>.

src/Arcus.Messaging.Abstractions/Arcus.Messaging.Abstractions.csproj

@@ -26,6 +26,11 @@
     <None Include="..\..\docs\static\img\icon.png" Pack="true" PackagePath="\" />
   </ItemGroup>
 
+
+    <ItemGroup>
+        <PackageReference Include="Microsoft.Extensions.Hosting.Abstractions" Version="[8.*,10.0.0)" />
+    </ItemGroup>
+
   <ItemGroup>
     <!-- TODO: will be removed in v3.0 -->
     <PackageReference Include="Microsoft.ApplicationInsights.WorkerService" Version="2.21.0" />

src/Arcus.Messaging.Abstractions/MessageHandling/MessageHandler.cs

@@ -166,11 +166,6 @@ protected async Task<MessageProcessingResult> RouteMessageAsync(ServiceBusReceiv
                 return MessageProcessingResult.Failure(message.MessageId, MessageProcessingError.ProcessingInterrupted, "Cannot process received message as the message pump is shutting down");
             }
 
-            if (string.IsNullOrEmpty(message.CorrelationId))
-            {
-                Logger.LogTrace("No operation ID was found on the message '{MessageId}' during processing in the Azure Service Bus {EntityType} message pump '{JobId}'", message.MessageId, EntityType, JobId);
-            }
-
 #pragma warning disable CS0618 // Type or member is obsolete
             using MessageCorrelationResult correlationResult = DetermineMessageCorrelation(message);
 

src/Arcus.Messaging.Abstractions/MessageHandling/MessageRouter.cs

@@ -87,50 +87,37 @@ private async Task<MessageProcessingResult> TryRoutingMessageViaRegisteredMessag
             MessageCorrelationInfo correlationInfo,
             CancellationToken cancellationToken)
         {
-            try
-            {
-                MessageHandler[] messageHandlers = GetRegisteredMessageHandlers(serviceProvider).ToArray();
-                if (messageHandlers.Length <= 0)
-                {
-                    await DeadLetterMessageNoHandlerRegisteredAsync(messageContext);
-                    return MessageProcessingResult.Failure(message.MessageId, CannotFindMatchedHandler, "Failed to process message in the message pump as no message handler is registered in the dependency container");
-                }
+            using var _ = Logger.BeginScope(new Dictionary<string, string> { ["MessageId"] = messageContext.MessageId });
 
-                string messageBody = LoadMessageBody(message, messageContext);
-                bool hasGoneThroughMessageHandler = false;
+            Logger.LogDebug("[Received] message (message ID={MessageId}) on Azure Service Bus {EntityType} message pump", messageContext.MessageId, messageContext.EntityType);
 
-                foreach (MessageHandler messageHandler in messageHandlers)
-                {
-                    MessageResult result = await DeserializeMessageForHandlerAsync(messageBody, messageContext, messageHandler);
-                    if (result.IsSuccess)
-                    {
-                        bool isProcessed = await messageHandler.ProcessMessageAsync(result.DeserializedMessage, messageContext, correlationInfo, cancellationToken);
-
-                        hasGoneThroughMessageHandler = true;
-                        if (isProcessed)
-                        {
-                            await PotentiallyAutoCompleteMessageAsync(messageContext);
-                            return MessageProcessingResult.Success(message.MessageId);
-                        }
-                    }
-                }
+            string messageBody = LoadMessageBody(message, messageContext);
 
-                if (hasGoneThroughMessageHandler)
-                {
-                    await AbandonMessageMatchedHandlerFailedAsync(messageContext);
-                    return MessageProcessingResult.Failure(message.MessageId, MatchedHandlerFailed, "Failed to process Azure Service Bus message in pump as the matched handler did not successfully processed the message");
-                }
+            MessageProcessingResult result =
+                await RouteMessageThroughRegisteredHandlersAsync(serviceProvider, messageBody, messageContext, correlationInfo, cancellationToken);
 
-                await DeadLetterMessageNoHandlerMatchedAsync(messageContext);
-                return MessageProcessingResult.Failure(message.MessageId, CannotFindMatchedHandler, "Failed to process Azure Service Bus message in pump as no message handler was matched against the message");
+            if (result.IsSuccessful)
+            {
+                await PotentiallyAutoCompleteMessageAsync(messageContext);
             }
-            catch (Exception exception)
+            else
             {
-                Logger.LogCritical(exception, "Unable to process message with ID '{MessageId}'", message.MessageId);
-
-                await messageContext.AbandonMessageAsync(new Dictionary<string, object>(), CancellationToken.None);
-                return MessageProcessingResult.Failure(message.MessageId, ProcessingInterrupted, "Failed to process message in pump as there was an unexpected critical problem during processing, please see the logs for more information", exception);
+                switch (result.Error)
+                {
+                    case ProcessingInterrupted:
+                    case MatchedHandlerFailed:
+                        Logger.LogDebug("[Settle:Abandon] message (message ID={MessageId}) on Azure Service Bus {EntityType} message pump => {ErrorMessage}", messageContext.MessageId, messageContext.EntityType, result.ErrorMessage);
+                        await messageContext.AbandonMessageAsync(new Dictionary<string, object>(), CancellationToken.None);
+                        break;
+
+                    case CannotFindMatchedHandler:
+                        Logger.LogDebug("[Settle:DeadLetter] message (message ID={MessageId}) on Azure Service Bus {EntityType} message pump => {ErrorMessage}", messageContext.MessageId, messageContext.EntityType, result.ErrorMessage);
+                        await messageContext.DeadLetterMessageAsync(CannotFindMatchedHandler.ToString(), result.ErrorMessage, CancellationToken.None);
+                        break;
+                }
             }
+
+            return result;
         }
 
         private static string LoadMessageBody(ServiceBusReceivedMessage message, AzureServiceBusMessageContext context)
@@ -165,33 +152,14 @@ private async Task PotentiallyAutoCompleteMessageAsync(AzureServiceBusMessageCon
             {
                 try
                 {
-                    Logger.LogTrace("Auto-complete message '{MessageId}' (if needed) after processing in Azure Service Bus in message pump '{JobId}'", messageContext.MessageId, messageContext.JobId);
                     await messageContext.CompleteMessageAsync(CancellationToken.None);
                 }
                 catch (ServiceBusException exception) when (exception.Reason is ServiceBusFailureReason.MessageLockLost)
                 {
-                    Logger.LogTrace(exception, "Message '{MessageId}' on Azure Service Bus in message pump '{JobId}' does not need to be auto-completed, because it was already settled", messageContext.MessageId, messageContext.JobId);
+                    Logger.LogTrace(exception, "[Skipped] auto-completion of message '{MessageId}' in Azure Service Bus message pump (already settled)", messageContext.MessageId);
                 }
             }
         }
-
-        private async Task DeadLetterMessageNoHandlerRegisteredAsync(AzureServiceBusMessageContext messageContext)
-        {
-            Logger.LogError("Failed to process Azure Service Bus message '{MessageId}' in pump '{JobId}' as no message handlers were registered in the application services, dead-lettering message!", messageContext.MessageId, messageContext.JobId);
-            await messageContext.DeadLetterMessageAsync(CannotFindMatchedHandler.ToString(), "No message handlers were registered in the application services", CancellationToken.None);
-        }
-
-        private async Task DeadLetterMessageNoHandlerMatchedAsync(AzureServiceBusMessageContext messageContext)
-        {
-            Logger.LogError("Failed to process Azure Service Bus message '{MessageId}' in pump '{JobId}' as no registered message handler was matched against the message, dead-lettering message!", messageContext.MessageId, messageContext.JobId);
-            await messageContext.DeadLetterMessageAsync(CannotFindMatchedHandler.ToString(), "No registered message handler was matched against the message", CancellationToken.None);
-        }
-
-        private async Task AbandonMessageMatchedHandlerFailedAsync(AzureServiceBusMessageContext messageContext)
-        {
-            Logger.LogDebug("Failed to process Azure Service Bus message '{MessageId}' in pump '{JobId}' as the matched message handler did not successfully process the message, abandoning message!", messageContext.MessageId, messageContext.JobId);
-            await messageContext.AbandonMessageAsync(new Dictionary<string, object>(), CancellationToken.None);
-        }
     }
 
     internal static class ILoggerExtensions

src/Arcus.Messaging.Pumps.ServiceBus/ServiceBusMessagePump.cs

@@ -72,7 +72,7 @@ protected override async Task StartProcessingMessagesAsync(CancellationToken can
                    https://github.com/arcus-azure/arcus.messaging/issues/176 */
 #pragma warning restore S1135
 
-            Logger.LogInformation("Azure Service Bus {EntityType} message pump '{JobId}' on entity path '{EntityPath}' in namespace '{Namespace}' started", EntityType, JobId, EntityName, Namespace);
+            Logger.LogTrace("Azure Service Bus {EntityType} message pump '{JobId}' on entity path '{EntityPath}' in namespace '{Namespace}' started", EntityType, JobId, EntityName, Namespace);
 
             _receiveMessagesCancellation = new CancellationTokenSource();
             while (CircuitState.IsClosed
@@ -179,7 +179,7 @@ protected override async Task StopProcessingMessagesAsync()
             IsStarted = false;
             CircuitState = CircuitState.TransitionTo(CircuitBreakerState.Open);
 
-            Logger.LogInformation("Azure Service Bus {EntityType} message pump '{JobId}' on entity path '{EntityPath}' in '{Namespace}' closed : {Time}", EntityType, JobId, EntityName, Namespace, DateTimeOffset.UtcNow);
+            Logger.LogTrace("Azure Service Bus {EntityType} message pump '{JobId}' on entity path '{EntityPath}' in '{Namespace}' closed : {Time}", EntityType, JobId, EntityName, Namespace, DateTimeOffset.UtcNow);
 
             if (_receiveMessagesCancellation != null)
             {
@@ -210,11 +210,6 @@ private async Task<MessageProcessingResult> ProcessMessageAsync(ServiceBusReceiv
                 return MessageProcessingResult.Failure("<unavailable>", MessageProcessingError.ProcessingInterrupted, "Cannot process received message as the message is was 'null'");
             }
 
-            if (string.IsNullOrEmpty(message.CorrelationId))
-            {
-                Logger.LogTrace("No operation ID was found on the message '{MessageId}' during processing in the Azure Service Bus {EntityType} message pump '{JobId}'", message.MessageId, EntityType, JobId);
-            }
-
             var messageContext = AzureServiceBusMessageContext.Create(JobId, EntityType, _messageReceiver, message);
 
             MessageProcessingResult routingResult = await RouteMessageAsync(message, messageContext, cancellationToken);

src/Arcus.Messaging.Pumps.ServiceBus/ServiceBusMessageRouter.cs

@@ -74,11 +74,6 @@ private async Task ProcessMessageAsync(ProcessSessionMessageEventArgs arg)
                 return;
             }
 
-            if (string.IsNullOrEmpty(message.CorrelationId))
-            {
-                Logger.LogTrace("No operation ID was found on the message '{MessageId}' during processing in the Azure Service Bus {EntityType} session-aware message pump '{JobId}'", message.MessageId, EntityType, JobId);
-            }
-
             var messageContext = AzureServiceBusMessageContext.Create(JobId, EntityType, arg);
             await RouteMessageAsync(message, messageContext, arg.CancellationToken);
         }

src/Arcus.Messaging.Pumps.ServiceBus/ServiceBusReceiverMessagePump.cs

@@ -28,17 +28,14 @@ public OrderBatchMessageBodySerializer(ILogger<OrderBatchMessageBodySerializer>
         /// </returns>
         public Task<MessageResult> DeserializeMessageAsync(string messageBody)
         {
-            _logger.LogTrace("Start deserializing to an 'Order'...");
             var order = JsonConvert.DeserializeObject<Order>(messageBody);
-            
+
             if (order is null)
             {
-                _logger.LogError("Cannot deserialize incoming message to an 'Order', so can't use 'Order'");
                 return Task.FromResult(MessageResult.Failure("Cannot deserialize incoming message to an 'Order', so can't use 'Order'"));
             }
 
-            _logger.LogInformation("Deserialized to an 'Order', using 'Order'");
-            return Task.FromResult(MessageResult.Success(new OrderBatch { Orders = new [] { order } }));
+            return Task.FromResult(MessageResult.Success(new OrderBatch { Orders = new[] { order } }));
         }
     }
 }

src/Arcus.Messaging.Pumps.ServiceBus/ServiceBusSessionMessagePump.cs

@@ -30,7 +30,7 @@ public async Task ProcessMessageAsync(
             MessageCorrelationInfo correlationInfo,
             CancellationToken cancellationToken)
         {
-            _logger.LogTrace("Write order v1 message to disk: {MessageId}", message.Id);
+            _logger.LogTrace("[Test] Write order v1 message to disk: {MessageId}", message.Id);
 
             string fileName = message.Id + ".json";
             string dirPath = Directory.GetCurrentDirectory();