NSB7 Multiple sagas handle the same message

sql-persistence
nservicebus
sagas

(Tommy) #1

Hi,

I have two SqlSagas that sends a message to the same handler and then waits for a reply from that handler. But using the same message from both sagas seems to confuse NSB when it gets the reply from the handler becuase it throws an exception

2018-06-19 10:35:09 [Information] [NServiceBus.Serilog.MessageReceived] Receive message Modules.Messages.ActiveModulesForAccount "b113fbf4-580a-4e10-bdfe-a904008d7e46". 2018-06-19 10:35:09 [Information] [NServiceBus.RecoverabilityExecutor] Immediate Retry is going to retry message 'b113fbf4-580a-4e10-bdfe-a904008d7e46' because of an exception: System.Collections.Generic.KeyNotFoundException: No item found in behavior context with key: NServiceBus.Sagas.ActiveSagaInstance at NServiceBus.Extensibility.ContextBag.Get[T](String key) in C:\BuildAgent\work\b549d46003942065\src\NServiceBus.Core\Extensibility\ContextBag.cs:line 71 at CaptureSagaStateBehavior.Invoke(IInvokeHandlerContext context, Func1 next)
at NServiceBus.LoadHandlersConnector.Invoke(IIncomingLogicalMessageContext context, Func2 stage) in C:\BuildAgent\work\b549d46003942065\src\NServiceBus.Core\Pipeline\Incoming\LoadHandlersConnector.cs:line 42 at NServiceBus.InvokeSagaNotFoundBehavior.Invoke(IIncomingLogicalMessageContext context, Func2 next) in C:\BuildAgent\work\b549d46003942065\src\NServiceBus.Core\Sagas\InvokeSagaNotFoundBehavior.cs:line 18
at NServiceBus.DeserializeLogicalMessagesConnector.Invoke(IIncomingPhysicalMessageContext context, Func2 stage) in C:\BuildAgent\work\b549d46003942065\src\NServiceBus.Core\Pipeline\Incoming\DeserializeLogicalMessagesConnector.cs:line 33 at NServiceBus.SubscriptionReceiverBehavior.Invoke(IIncomingPhysicalMessageContext context, Func2 next) in C:\BuildAgent\work\b549d46003942065\src\NServiceBus.Core\Routing\MessageDrivenSubscriptions\SubscriptionReceiverBehavior.cs:line 29
at NServiceBus.ProcessingStatisticsBehavior.Invoke(IIncomingPhysicalMessageContext context, Func2 next) in C:\BuildAgent\work\b549d46003942065\src\NServiceBus.Core\Performance\Statistics\ProcessingStatisticsBehavior.cs:line 25 at Infrastructure.NServiceBus.ExtractSqlConnectionBehavior.Invoke(IIncomingPhysicalMessageContext context, Func1 next) in C:\dev\astral\src\Astral\Infrastructure\NServiceBus\ExtractSqlConnectionBehavior.cs:line 37
at NServiceBus.TransportReceiveToPhysicalMessageProcessingConnector.Invoke(ITransportReceiveContext context, Func2 next) in C:\BuildAgent\work\b549d46003942065\src\NServiceBus.Core\Pipeline\Incoming\TransportReceiveToPhysicalMessageProcessingConnector.cs:line 39 at NServiceBus.MainPipelineExecutor.Invoke(MessageContext messageContext) in C:\BuildAgent\work\b549d46003942065\src\NServiceBus.Core\Pipeline\MainPipelineExecutor.cs:line 34 at NServiceBus.Transport.SQLServer.DelayedDeliveryMessagePump.<>c__DisplayClass1_0.<<Init>b__0>d.MoveNext() in C:\BuildAgent\work\1c57be3e94b4bd73\src\NServiceBus.SqlServer\DelayedDelivery\DelayedDeliveryMessagePump.cs:line 23 --- End of stack trace from previous location where exception was thrown --- at NServiceBus.Transport.SQLServer.ReceiveStrategy.TryProcessingMessage(Message message, TransportTransaction transportTransaction) in C:\BuildAgent\work\1c57be3e94b4bd73\src\NServiceBus.SqlServer\Receiving\ReceiveStrategy.cs:line 63 at NServiceBus.Transport.SQLServer.ProcessWithNativeTransaction.TryProcess(Message message, TransportTransaction transportTransaction) in C:\BuildAgent\work\1c57be3e94b4bd73\src\NServiceBus.SqlServer\Receiving\ProcessWithNativeTransaction.cs:line 92

If I create two different messages/handlers then everything works. Is this by design or is it a bug? I thought that NSB should be able to resolve the correct saga from the headers.

Regars,
Tommy


(Tim Bussmann) #2

Hi @Tommy

Just to verify: Have you made sure that all messages used (especially the response type) have been marked with the IMessage or ICommand marker interfaces (or declared via conventions)?


(Tommy) #3

Hi @Tim

Yes, both messages are marked with IMessage.


(Tim Bussmann) #4

Thanks for checking @Tommy. What transport and persistence are you using (and what versions)? Do you have a project you can share with us to reproduce your issue?


(Tommy) #5

I’m using SqlServerTransport and SqlPersistence. I’ll try to make small project to reproduce the issue.


(Tommy) #6

I created a gist https://gist.github.com/Rensvind/c33b4a9314c6a4bb90f49a19993e3ee0

While creating the project I noticed that the problem only appears when using Serilog. If you remove everything serilog-related the code works as expected.


(Tim Bussmann) #7

Thanks for the repro @Tommy. Your observation is correct as this exception seems to originate from the NServiceBus.Serilog package as also hinted by the stacktrace:

Immediate Retry is going to retry message ‘b113fbf4-580a-4e10-bdfe-a904008d7e46’ because of an exception: System.Collections.Generic.KeyNotFoundException: No item found in behavior context with key: NServiceBus.Sagas.ActiveSagaInstance at NServiceBus.Extensibility.ContextBag.Get[T](String key) in C:\BuildAgent\work\b549d46003942065\src\NServiceBus.Core\Extensibility\ContextBag.cs:line 71 at CaptureSagaStateBehavior.Invoke

The CaptureSagaStateBehavior is part of the Serilog package and at first glance it looks like the behavior didn’t take into account the possibility of a message having handlers in mutliple sagas where only one saga will actually handle the message as it’s a response message.

I’ll look a bit closer into the Serilog behavior to verify this assumption. Please note that the Serilog package is a community package and not supported by Particular Software.


(Tim Bussmann) #8

Hey @Tommy
I have verified that this issue is indeed due to a bug in the NServiceBus Serilog package. I’ve raised an issue in the github repo: https://github.com/NServiceBusExtensions/NServiceBus.Serilog/issues/16. I’d recommend to watch that issue to receive updates on this matter.


(Tommy) #9

Hi @Tim
Thank you so much for the help! I’ll be watching the issue.


(Simon Cropp) #10

@Tommy tims fix is now deployed. it may take nuget up to an hour to re-index