NSB 4.7 Saga creating a duplicate saga when it shouldn't

NSB4.7 with NHibernate and SQL2012

I have a saga service whose sole job is to maintain a integer counter per unique formid. It’s singlethreaded.

public class FormCreationServiceSaga : Saga<FormCreationSagaData>, IAmStartedByMessages<GenerateNewFormNumber>
{
    public override void ConfigureHowToFindSaga()
    {
        ConfigureMapping<GenerateNewFormNumber>(m => m.FormTypeID).ToSaga(s => s.FormTypeId);
    }

    public void Handle(GenerateNewFormNumber message)
    {
        if (Data.FormTypeId == Guid.Empty)
            Data.FormTypeId = message.FormTypeID;

        Data.FormTypeDescription = message.FormName;
        Data.CurrentFormIdentifier = Data.CurrentFormIdentifier + 1;
        Data.CurrentFormGloballyUniqueId = Guid.NewGuid();

        Bus.Reply<NewFormNumberGenerated>(m =>
        {
            m.Id = Data.CurrentFormGloballyUniqueId;
            m.ReferenceId = Data.CurrentFormIdentifier;
            m.FormType = Data.FormTypeDescription;
        });
    }
}

public class FormCreationSagaData : ContainSagaData
{       
    public virtual Guid FormTypeId { get; set; }
    public virtual string FormTypeDescription { get; set; }

    public virtual int CurrentFormIdentifier { get; set; }
    public virtual Guid CurrentFormGloballyUniqueId { get; set; }
}

This has been running for years without trouble. I have two separate environments now suffering the same problem.

At some point it’s generating two rows in the saga db table like it’s not found an existing row, then the next attempt it throws this error.

 System.Reflection.TargetInvocationException: Exception has been thrown by the target of an invocation. ---> NHibernate.NonUniqueResultException: query did not return a unique result: 2
    at NHibernate.Impl.AbstractQueryImpl.UniqueElement(IList list)
    at NHibernate.Impl.CriteriaImpl.UniqueResult[T]()
    at NServiceBus.Sagas.Finders.PropertySagaFinder`2.FindBy(TMessage message) in c:\BuildAgent\work\1b05a2fea6e4cd32\src\NServiceBus.Core\Sagas\Finders\PropertySagaFinder.cs:line 34
    --- End of inner exception stack trace ---
    at System.RuntimeMethodHandle.InvokeMethod(Object target, Object[] arguments, Signature sig, Boolean constructor)
    at System.Reflection.RuntimeMethodInfo.UnsafeInvokeInternal(Object obj, Object[] parameters, Object[] arguments)
    at System.Reflection.RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture)
    at NServiceBus.Sagas.SagaPersistenceBehavior.UseFinderToFindSaga(IFinder finder, Object message) in c:\BuildAgent\work\1b05a2fea6e4cd32\src\NServiceBus.Core\Sagas\SagaPersistenceBehavior.cs:line 151
    at NServiceBus.Sagas.SagaPersistenceBehavior.TryLoadSagaEntity(ISaga saga, LogicalMessage message) in c:\BuildAgent\work\1b05a2fea6e4cd32\src\NServiceBus.Core\Sagas\SagaPersistenceBehavior.cs:line 131
    at NServiceBus.Sagas.SagaPersistenceBehavior.Invoke(HandlerInvocationContext context, Action next) in c:\BuildAgent\work\1b05a2fea6e4cd32\src\NServiceBus.Core\Sagas\SagaPersistenceBehavior.cs:line 44
    at NServiceBus.Sagas.AuditInvokedSagaBehavior.Invoke(HandlerInvocationContext context, Action next) in c:\BuildAgent\work\1b05a2fea6e4cd32\src\NServiceBus.Core\Sagas\AuditInvokedSagaBehavior.cs:line 14
    at NServiceBus.Unicast.Behaviors.SetCurrentMessageBeingHandledBehavior.Invoke(HandlerInvocationContext context, Action next) in c:\BuildAgent\work\1b05a2fea6e4cd32\src\NServiceBus.Core\Unicast\Behaviors\SetCurrentMessageBeingHandledBehavior.cs:line 21
    at NServiceBus.Pipeline.PipelineExecutor.Execute[T](BehaviorChain`1 pipelineAction, T context) in c:\BuildAgent\work\1b05a2fea6e4cd32\src\NServiceBus.Core\Pipeline\PipelineExecutor.cs:line 138
    at NServiceBus.Pipeline.PipelineExecutor.InvokeHandlerPipeline(MessageHandler handler) in c:\BuildAgent\work\1b05a2fea6e4cd32\src\NServiceBus.Core\Pipeline\PipelineExecutor.cs:line 67
    at NServiceBus.Unicast.Behaviors.LoadHandlersBehavior.Invoke(ReceiveLogicalMessageContext context, Action next) in c:\BuildAgent\work\1b05a2fea6e4cd32\src\NServiceBus.Core\Unicast\Behaviors\LoadHandlersBehavior.cs:line 39
    at NServiceBus.DataBus.DataBusReceiveBehavior.Invoke(ReceiveLogicalMessageContext context, Action next) in c:\BuildAgent\work\1b05a2fea6e4cd32\src\NServiceBus.Core\DataBus\DataBusReceiveBehavior.cs:line 69
    at NServiceBus.Pipeline.PipelineExecutor.Execute[T](BehaviorChain`1 pipelineAction, T context) in c:\BuildAgent\work\1b05a2fea6e4cd32\src\NServiceBus.Core\Pipeline\PipelineExecutor.cs:line 138
    at NServiceBus.Unicast.Messages.ExecuteLogicalMessagesBehavior.Invoke(ReceivePhysicalMessageContext context, Action next) in c:\BuildAgent\work\1b05a2fea6e4cd32\src\NServiceBus.Core\Unicast\Messages\ExecuteLogicalMessagesBehavior.cs:line 28
    at NServiceBus.UnitOfWork.UnitOfWorkBehavior.Invoke(ReceivePhysicalMessageContext context, Action next) in c:\BuildAgent\work\1b05a2fea6e4cd32\src\NServiceBus.Core\UnitOfWork\UnitOfWorkBehavior.cs:line 44
    at NServiceBus.Unicast.Behaviors.ForwardBehavior.Invoke(ReceivePhysicalMessageContext context, Action next) in c:\BuildAgent\work\1b05a2fea6e4cd32\src\NServiceBus.Core\Unicast\Behaviors\ForwardBehavior.cs:line 24
    at NServiceBus.Audit.AuditBehavior.Invoke(ReceivePhysicalMessageContext context, Action next) in c:\BuildAgent\work\1b05a2fea6e4cd32\src\NServiceBus.Core\Audit\AuditBehavior.cs:line 17
    at NServiceBus.Unicast.Behaviors.ImpersonateSenderBehavior.Invoke(ReceivePhysicalMessageContext context, Action next) in c:\BuildAgent\work\1b05a2fea6e4cd32\src\NServiceBus.Core\Unicast\Behaviors\ImpersonateSenderBehavior.cs:line 37
    at NServiceBus.Unicast.Behaviors.MessageHandlingLoggingBehavior.Invoke(ReceivePhysicalMessageContext context, Action next) in c:\BuildAgent\work\1b05a2fea6e4cd32\src\NServiceBus.Core\Unicast\Behaviors\MessageHandlingLoggingBehavior.cs:line 23
    at NServiceBus.Unicast.Behaviors.ChildContainerBehavior.Invoke(ReceivePhysicalMessageContext context, Action next) in c:\BuildAgent\work\1b05a2fea6e4cd32\src\NServiceBus.Core\Unicast\Behaviors\ChildContainerBehavior.cs:line 17
    at NServiceBus.Unicast.Transport.TransportReceiver.OnTransportMessageReceived(TransportMessage msg) in c:\BuildAgent\work\1b05a2fea6e4cd32\src\NServiceBus.Core\Unicast\Transport\TransportReceiver.cs:line 431
    at NServiceBus.Unicast.Transport.TransportReceiver.ProcessMessage(TransportMessage message) in c:\BuildAgent\work\1b05a2fea6e4cd32\src\NServiceBus.Core\Unicast\Transport\TransportReceiver.cs:line 362
    at NServiceBus.Unicast.Transport.TransportReceiver.TryProcess(TransportMessage message) in c:\BuildAgent\work\1b05a2fea6e4cd32\src\NServiceBus.Core\Unicast\Transport\TransportReceiver.cs:line 259
    at NServiceBus.Transports.Msmq.MsmqDequeueStrategy.Action() in c:\BuildAgent\work\1b05a2fea6e4cd32\src\NServiceBus.Core\Transports\Msmq\MsmqDequeueStrategy.cs:line 236

Is this a known problem in NSB4.7 with NHibernate? Has it been fixed? I’ve attempted to search but can’t find anything.

In two environments this error has occurred in interaction with the same calling service, and there is nothing different in that calling service from 30+ other services that do the same thing. I’m failing to see how this could be caused by another service. The calling service is a webapp and uses a blocking call like this to handle the reply

public T SendAndAwaitReply(object instance)
{
	T response = null;
	AsyncCallback callback = delegate(IAsyncResult ar)
	{
		var reply = ar.AsyncState as CompletionResult;
		if (reply == null)
			return;
		var message = reply.Messages.FirstOrDefault() as T;
		response = message;
	};
	var sync = _bus.Send(instance).Register(callback, null);
	sync.AsyncWaitHandle.WaitOne(TimeSpan.FromSeconds(10));
	return response;
}

This has occurred 10+ times in the last 6 months. Last night it failed and correlated with DB performance issues, noticed because our sagas with timeouts’ circuit breakers triggered.

Any ideas? We are planning our upgrade to NSB6.3 currently, so any advice to the future would be appreciated, but specific advice to NSB4.7 would be great.

Regards,
Matt Ritchie

Hi,

NServiceBus v4 is rather old and no longer supported. I advise you to update to a later version, but you already said you would. We still have documentation for version 4, but a lot of issues have been solved by newer versions.

It’s likely your issue is also ‘solved’. Let me try to explain why. In older versions of NServiceBus, we required a property in the saga state to be marked with the [Unique] attribute. This causes a unique index to be created on the table with the added benefit that it’s impossible to submit a second saga with the same business id.

In your code the business id is FormTypeId which I was able to tell because of the mapping in the ConfigureHowToFindSaga method.

When I say ‘solved’ I mean that since NServiceBus v6 the [Unique] attribute isn’t needed anymore since we figure that mapping on a property inside the saga state already makes it unique.

So it’s likely your issues are solved if you put the [Unique] attribute on top of your FormTypeId property. Unfortunately that doesn’t solve sagas that are already duplicate in the database. I’m afraid you’ll probably have to look at each individual row in the table, delete one of them and update the other one to reflect the correct state.

Thanks Dennis,
I’ll try that out.

Hi @Matt_Ritchie,

Was wondering how it’s going and if the attribute did help and solved your issue?
Let me know if you have additional questions!

Hi Dennis, sorry it’s been a while.
We put the attribute into the codebase and deployed it, but still the duplication was occurring every time the database server has been having performance issues.

I thought it had solved the problem, but as soon as the first performance issue occurred we had the duplication back.
Luckily this isn’t in our production DB.
Cheers,
Matt