Tweak dead-lettering (#64)

* Tweak dead-lettering * Fix tests.
Avanade · Apr 26, 2023 · ae8a3bc · ae8a3bc
1 parent 9f00bde
commit ae8a3bc
Show file tree

Hide file tree

Showing 9 changed files with 27 additions and 18 deletions.
diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -2,6 +2,9 @@
 
 Represents the **NuGet** versions.
 
+## v2.9.1
+- *Fixed:* The dead-lettering within `ServiceBusSubscriberInvoker` will write the exception stack trace, etc. to a new message property named `SubscriberException` to ensure this content is consistently persisted, with related error description being the exception message only.
+
 ## v2.9.0
 - *Enhancement:* Added `PagingAttribute` and `PagingOperationFilter` to enable swagger output of `PagingArgs` parameters for an operation.
 

diff --git a/Common.targets b/Common.targets
@@ -1,6 +1,6 @@
 <Project>
 	<PropertyGroup>
-		<Version>2.9.0</Version>
+		<Version>2.9.1</Version>
 		<LangVersion>preview</LangVersion>
 		<Authors>Avanade</Authors>
 		<Company>Avanade</Company>

diff --git a/src/CoreEx.Azure/ServiceBus/ServiceBusOrchestratedSubscriber.cs b/src/CoreEx.Azure/ServiceBus/ServiceBusOrchestratedSubscriber.cs
@@ -96,7 +96,7 @@ public Task ReceiveAsync(ServiceBusReceivedMessage message, ServiceBusMessageAct
                 // Execute subscriber receive with the event.
                 var success = await Orchestrator.ReceiveAsync(this, subscriber!, @event, cancellationToken).ConfigureAwait(false);
                 if (success)
-                    Logger.LogInformation("{Type} executed {Subscriber} successfully - Service Bus message '{Message}'.", GetType().Name, subscriber!.GetType().Name, message.MessageId);
+                    Logger.LogDebug("{Type} executed {Subscriber} successfully - Service Bus message '{Message}'.", GetType().Name, subscriber!.GetType().Name, message.MessageId);
             }, (message, messageActions), cancellationToken);
         }
     }

diff --git a/src/CoreEx.Azure/ServiceBus/ServiceBusSubscriber.cs b/src/CoreEx.Azure/ServiceBus/ServiceBusSubscriber.cs
@@ -93,7 +93,7 @@ public Task ReceiveAsync(ServiceBusReceivedMessage message, ServiceBusMessageAct
                 // Invoke the actual function logic.
                 await function(@event!).ConfigureAwait(false);
 
-                Logger.LogInformation("{Type} executed successfully - Service Bus message '{Message}'.", GetType().Name, message.MessageId);
+                Logger.LogDebug("{Type} executed successfully - Service Bus message '{Message}'.", GetType().Name, message.MessageId);
             }, (message, messageActions), cancellationToken);
         }
 

diff --git a/src/CoreEx.Azure/ServiceBus/ServiceBusSubscriberInvoker.cs b/src/CoreEx.Azure/ServiceBus/ServiceBusSubscriberInvoker.cs
@@ -18,6 +18,8 @@ namespace CoreEx.Azure.ServiceBus
     /// </summary>
     public class ServiceBusSubscriberInvoker : InvokerBase<EventSubscriberBase, (ServiceBusReceivedMessage Message, ServiceBusMessageActions MessageActions)>
     {
+        private const string SubscriberExceptionPropertyName = "SubscriberException";
+
         /// <inheritdoc/>
         protected async override Task<TResult> OnInvokeAsync<TResult>(EventSubscriberBase invoker, Func<CancellationToken, Task<TResult>> func, (ServiceBusReceivedMessage Message, ServiceBusMessageActions MessageActions) args, CancellationToken cancellationToken)
         {
@@ -94,14 +96,14 @@ protected async override Task<TResult> OnInvokeAsync<TResult>(EventSubscriberBas
         public static async Task DeadLetterExceptionAsync(EventSubscriberBase invoker, ServiceBusReceivedMessage message, ServiceBusMessageActions messageActions, string errorReason, Exception exception, CancellationToken cancellationToken)
         {
             invoker.Logger.LogDebug("Dead Lettering - Service Bus message '{Message}'. [{Reason}] {Error}", message.MessageId, errorReason, exception.Message);
-            await messageActions.DeadLetterMessageAsync(message, errorReason, ToDeadLetterReason(exception.ToString()), cancellationToken).ConfigureAwait(false);
+            await messageActions.DeadLetterMessageAsync(message, new Dictionary<string, object?> { { SubscriberExceptionPropertyName, FormatText(exception.ToString()) } }, errorReason, FormatText(exception.Message), cancellationToken).ConfigureAwait(false);
             invoker.Logger.LogError(exception, "Dead Lettered - Service Bus message '{Message}'. [{Reason}] {Error}", message.MessageId, errorReason, exception.Message);
         }
 
         /// <summary>
-        /// Shortens the reason text to 4096 characters, which is the maximum allowed length for a dead letter reason.
+        /// Shortens the text to 2048 characters; should be enough to given context - otherwise, full context should have be written to the log.
         /// </summary>
-        private static string? ToDeadLetterReason(string? reason) => reason?[..Math.Min(reason.Length, 4096)];
+        private static string? FormatText(string? text) => text?[..Math.Min(text.Length, 2048)];
 
         /// <summary>
         /// Update the <see cref="ILogger.BeginScope{TState}(TState)"/> <paramref name="state"/> from the <paramref name="message"/>.

diff --git a/tests/CoreEx.Test/Framework/FluentValidation/ServiceBusTriggerExecutorTest.cs b/tests/CoreEx.Test/Framework/FluentValidation/ServiceBusTriggerExecutorTest.cs
@@ -5,6 +5,7 @@
 using Microsoft.Azure.WebJobs.ServiceBus;
 using Moq;
 using NUnit.Framework;
+using System.Collections.Generic;
 using UnitTestEx.NUnit;
 
 namespace CoreEx.Test.Framework.FluentValidation
@@ -23,7 +24,7 @@ public void ReceiveAsync_ValidationException_Validation()
                 .Run(s => s.RunAsync(message, actionsMock.Object))
                 .AssertSuccess();
 
-            actionsMock.Verify(m => m.DeadLetterMessageAsync(message, ErrorType.ValidationError.ToString(), It.IsAny<string>(), default), Times.Once);
+            actionsMock.Verify(m => m.DeadLetterMessageAsync(message, It.IsAny<Dictionary<string, object?>>(), ErrorType.ValidationError.ToString(), It.IsAny<string>(), default), Times.Once);
             actionsMock.VerifyNoOtherCalls();
         }
     }

diff --git a/tests/CoreEx.Test/Framework/Messaging/Azure/ServiceBus/ServiceBusSubscriberTest.cs b/tests/CoreEx.Test/Framework/Messaging/Azure/ServiceBus/ServiceBusSubscriberTest.cs
@@ -7,6 +7,7 @@
 using Moq;
 using NUnit.Framework;
 using System;
+using System.Collections.Generic;
 using System.Threading.Tasks;
 using UnitTestEx.NUnit;
 
@@ -26,7 +27,7 @@ public void ReceiveAsync_ValidationException()
                 .Run(s => s.ReceiveAsync<Product>(message, actionsMock.Object, ed => throw new InvalidOperationException("Should not get here.")))
                 .AssertSuccess();
 
-            actionsMock.Verify(m => m.DeadLetterMessageAsync(message, ErrorType.ValidationError.ToString(), It.IsAny<string>(), default), Times.Once);
+            actionsMock.Verify(m => m.DeadLetterMessageAsync(message, It.IsAny<Dictionary<string, object?>>(), ErrorType.ValidationError.ToString(), It.IsAny<string>(), default), Times.Once);
             actionsMock.VerifyNoOtherCalls();
         }
 
@@ -55,7 +56,7 @@ public void ReceiveAsync_UnhandledException()
                 .Run(s => s.ReceiveAsync<Product>(message, actionsMock.Object, ed => throw new DivideByZeroException()))
                 .AssertSuccess();
 
-            actionsMock.Verify(m => m.DeadLetterMessageAsync(message, ErrorType.UnhandledError.ToString(), It.IsAny<string>(), default), Times.Once);
+            actionsMock.Verify(m => m.DeadLetterMessageAsync(message, It.IsAny<Dictionary<string, object?>>(), ErrorType.UnhandledError.ToString(), It.IsAny<string>(), default), Times.Once);
             actionsMock.VerifyNoOtherCalls();
         }
 

diff --git a/tests/CoreEx.Test/TestFunction/ServiceBusOrchestratedTriggerFunctionTest.cs b/tests/CoreEx.Test/TestFunction/ServiceBusOrchestratedTriggerFunctionTest.cs
@@ -12,6 +12,7 @@
 using Moq;
 using NUnit.Framework;
 using System;
+using System.Collections.Generic;
 using UnitTestEx.Abstractions;
 using UnitTestEx.NUnit;
 using Az = Azure.Messaging.ServiceBus;
@@ -33,7 +34,7 @@ public void NotSubscribed()
                 .Run(f => f.RunAsync(message, actionsMock.Object))
                 .AssertSuccess();
 
-            actionsMock.Verify(m => m.DeadLetterMessageAsync(message, EventSubscriberExceptionSource.OrchestratorNotSubscribed.ToString(), It.IsNotNull<string>(), default), Times.Once);
+            actionsMock.Verify(m => m.DeadLetterMessageAsync(message, It.IsAny<Dictionary<string, object?>>(), EventSubscriberExceptionSource.OrchestratorNotSubscribed.ToString(), It.IsNotNull<string>(), default), Times.Once);
             actionsMock.VerifyNoOtherCalls();
         }
 
@@ -64,7 +65,7 @@ public void Product_ValueIsRequired()
                 .Run(f => f.RunAsync(message, actionsMock.Object))
                 .AssertSuccess();
 
-            actionsMock.Verify(m => m.DeadLetterMessageAsync(message, ErrorType.ValidationError.ToString(), It.IsNotNull<string>(), default), Times.Once);
+            actionsMock.Verify(m => m.DeadLetterMessageAsync(message, It.IsAny<Dictionary<string, object?>>(), ErrorType.ValidationError.ToString(), It.IsNotNull<string>(), default), Times.Once);
             actionsMock.VerifyNoOtherCalls();
         }
 
@@ -79,7 +80,7 @@ public void Product_ValueIsInvalid()
                 .Run(f => f.RunAsync(message, actionsMock.Object))
                 .AssertSuccess();
 
-            actionsMock.Verify(m => m.DeadLetterMessageAsync(message, ErrorType.ValidationError.ToString(), It.IsNotNull<string>(), default), Times.Once);
+            actionsMock.Verify(m => m.DeadLetterMessageAsync(message, It.IsAny<Dictionary<string, object?>>(), ErrorType.ValidationError.ToString(), It.IsNotNull<string>(), default), Times.Once);
             actionsMock.VerifyNoOtherCalls();
         }
 

diff --git a/tests/CoreEx.Test/TestFunction/ServiceBusTriggerTest.cs b/tests/CoreEx.Test/TestFunction/ServiceBusTriggerTest.cs
@@ -8,6 +8,7 @@
 using Microsoft.Azure.WebJobs.ServiceBus;
 using Moq;
 using NUnit.Framework;
+using System.Collections.Generic;
 using System.Net;
 using System.Net.Http;
 using UnitTestEx.NUnit;
@@ -28,7 +29,7 @@ public void NullMessage()
                 .Run(f => f.RunAsync(message, actionsMock.Object))
                 .AssertSuccess();
 
-            actionsMock.Verify(m => m.DeadLetterMessageAsync(message, ErrorType.ValidationError.ToString(), It.IsNotNull<string>(), default), Times.Once);
+            actionsMock.Verify(m => m.DeadLetterMessageAsync(message, It.IsAny<Dictionary<string, object?>>(), ErrorType.ValidationError.ToString(), It.IsNotNull<string>(), default), Times.Once);
             actionsMock.VerifyNoOtherCalls();
         }
 
@@ -43,7 +44,7 @@ public void InvalidMessage()
                 .Run(f => f.RunAsync(message, actionsMock.Object))
                 .AssertSuccess();
 
-            actionsMock.Verify(m => m.DeadLetterMessageAsync(message, EventSubscriberExceptionSource.EventDataDeserialization.ToString(), It.IsNotNull<string>(), default), Times.Once);
+            actionsMock.Verify(m => m.DeadLetterMessageAsync(message, It.IsAny<Dictionary<string, object?>>(), EventSubscriberExceptionSource.EventDataDeserialization.ToString(), It.IsNotNull<string>(), default), Times.Once);
             actionsMock.VerifyNoOtherCalls();
         }
 
@@ -61,7 +62,7 @@ public void InvalidMessage_Newtonsoft()
                 .Run(f => f.RunAsync(message, actionsMock.Object))
                 .AssertSuccess();
 
-            actionsMock.Verify(m => m.DeadLetterMessageAsync(message, EventSubscriberExceptionSource.EventDataDeserialization.ToString(), It.IsNotNull<string>(), default), Times.Once);
+            actionsMock.Verify(m => m.DeadLetterMessageAsync(message, It.IsAny<Dictionary<string, object?>>(), EventSubscriberExceptionSource.EventDataDeserialization.ToString(), It.IsNotNull<string>(), default), Times.Once);
             actionsMock.VerifyNoOtherCalls();
         }
 
@@ -76,7 +77,7 @@ public void InvalidValue()
                 .Run(f => f.RunAsync(message, actionsMock.Object))
                 .AssertSuccess();
 
-            actionsMock.Verify(m => m.DeadLetterMessageAsync(message, ErrorType.ValidationError.ToString(), It.IsNotNull<string>(), default), Times.Once);
+            actionsMock.Verify(m => m.DeadLetterMessageAsync(message, It.IsAny<Dictionary<string, object?>>(), ErrorType.ValidationError.ToString(), It.IsNotNull<string>(), default), Times.Once);
             actionsMock.VerifyNoOtherCalls();
         }
 
@@ -94,7 +95,7 @@ public void InvalidValue_Newtonsoft()
                 .Run(f => f.RunAsync(message, actionsMock.Object))
                 .AssertSuccess();
 
-            actionsMock.Verify(m => m.DeadLetterMessageAsync(message, ErrorType.ValidationError.ToString(), It.IsNotNull<string>(), default), Times.Once);
+            actionsMock.Verify(m => m.DeadLetterMessageAsync(message, It.IsAny<Dictionary<string, object?>>(), ErrorType.ValidationError.ToString(), It.IsNotNull<string>(), default), Times.Once);
             actionsMock.VerifyNoOtherCalls();
         }
 
@@ -135,7 +136,7 @@ public void UnhandledError()
                 .AssertSuccess();
 
             mc.Verify();
-            actionsMock.Verify(m => m.DeadLetterMessageAsync(message, ErrorType.UnhandledError.ToString(), It.IsNotNull<string>(), default), Times.Once);
+            actionsMock.Verify(m => m.DeadLetterMessageAsync(message, It.IsAny<Dictionary<string, object?>>(), ErrorType.UnhandledError.ToString(), It.IsNotNull<string>(), default), Times.Once);
             actionsMock.VerifyNoOtherCalls();
         }