SubscriptionService removing subscription instead of adding it

[John Weber]

I've been experiencing an issue with the MSMQ subscription service where *sometimes* a subscription will be removed when it's expected to be added. The scenario is this:

1. Start up the subscription service, producer and consumer applications (three seperate console apps receiving from their own queues)
   
1. The producer has a subscription added to the consumer
2. Dispose of the IServiceBus on the consumer app without executing the UnsubscribeAction for the consumer
3. Bring the consumer back up

After step 3, sometimes the subscription will be present on the producer and sometimes it will not be.

For the case where the subscription is not present, the log files of the subscription service indicate it first sent an AddSubscription message to the producer immediately followed by a RemoveSubscription message. For the case where the subscription is present, this order is reversed.

Here are the full log files representing both of these cases where the subscription is present and the case where the subscription is not present.

Subscription not present: https://gist.github.com/f1ecb04bcf3772e52e1e

Subscription present: https://gist.github.com/1c7bd8624d14e5b72795

[John Weber]

I'm getting the feeling that the correlation for the SubscriptionAdded event in the SubscriptionSaga might have an issue. 

In the case where things work as expected, the subscription service reuses the existing SubscriptionSaga immediately when the consumer sends the AddSubscription message. This causes the saga to act on the DuplicateSubscriptionAdded event and removed the subscription from the producer. A new SubscriptionSaga is then created which adds the subscription back to the producer.

In the alternate case, the AddSubscription message first creates a new SubscriptionSaga which adds the route to the producer. When it handles the AddSubscription message again it hits the DuplicateSubscriptionAdded event and unsubscribes the route from the producer.

Any thoughts on how to fix this?

[John Weber]

I believe I've figured out what's happening but am not sure how to address it.

The SubscriptionSaga has two events for the AddSubscription message - SubscriptionAdded and DuplicateSubscriptionAdded. When the Consumer is brought back online and it sends the AddSubscription message to the SubscriptionService, the saga operates on this message twice (once for each event).

According to the SubscriptionSaga both events should be handled. The problem is it appears that the order the events are handled is nondeterministic.

When the DuplicateSubscriptionAdded event precedes the AddSubscription event, then the Producer receives the RemoveSubscription message followed by the AddSubscription message. When it happens the other way around, the RemoveSubscription is the final operation which causes the route to be lost.

This is definitely an issue for our implementation and is an easily recreatable and repeatable scenario. Does my analysis of this issue make any sense?

[Chris Patterson]

Those messages are correlated by the subscriptionId, so there should be an instance of the saga for each one of those messages, the duplicate should remove the old one, the Add creates a new one by CorrelationId.

--
You received this message because you are subscribed to the Google Groups "masstransit-discuss" group.
To post to this group, send email to masstrans...@googlegroups.com.
To unsubscribe from this group, send email to masstransit-dis...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msg/masstransit-discuss/-/ZQ9QpaKKabsJ.

For more options, visit https://groups.google.com/groups/opt_out.
 
 

[John Weber]

Yeah, there are definitely two instances of the saga. The problem is sometimes the Duplicate is handled after the Add which causes the Producer to unsubscribe.

Here are the applicable log lines from when this happens:

DEBUG 2013-01-12 13:18:35,867 SAGA: MassTransit.Services.Subscriptions.Server.SubscriptionSaga Creating New 08cfbf21-83a4-a5a3-902b-345c73880000 for MassTransit.Services.Subscriptions.Messages.AddSubscription

DEBUG 2013-01-12 13:18:35,867 RECV:msmq://orville/mt_subscription?tx=true:8b454455-9535-45cf-97b5-e50fae26f753\5703:MassTransit.Services.Subscriptions.Messages.AddSubscription, MassTransit

DEBUG 2013-01-12 13:18:35,867 RaiseEvent: SubscriptionSaga SubscriptionAdded 08cfbf21-83a4-a5a3-902b-345c73880000

DEBUG 2013-01-12 13:18:35,868 SEND:msmq://orville/mt_subscription?tx=true:8b454455-9535-45cf-97b5-e50fae26f753\5707:MassTransit.Services.Subscriptions.Server.Messages.SubscriptionAdded, MassTransit

DEBUG 2013-01-12 13:18:35,868 SAGA: MassTransit.Services.Subscriptions.Server.SubscriptionSaga Using Existing 08cfbf21-7a94-2e0a-902b-345c73880000 for MassTransit.Services.Subscriptions.Messages.AddSubscription

DEBUG 2013-01-12 13:18:35,868 RECV:msmq://orville/mt_subscription?tx=true:8b454455-9535-45cf-97b5-e50fae26f753\5703:MassTransit.Services.Subscriptions.Messages.AddSubscription, MassTransit

DEBUG 2013-01-12 13:18:35,869 RaiseEvent: SubscriptionSaga DuplicateSubscriptionAdded 08cfbf21-7a94-2e0a-902b-345c73880000

DEBUG 2013-01-12 13:18:35,869 SEND:msmq://orville/mt_subscription?tx=true:8b454455-9535-45cf-97b5-e50fae26f753\5708:MassTransit.Services.Subscriptions.Server.Messages.SubscriptionRemoved, MassTransit

To unsubscribe from this group, send email to masstransit-discuss+unsub...@googlegroups.com.

[John Weber]

It looks like the nondetermistic aspect of this problem is due to the SagaStateMachineEventInspector. I was monitoring the results of the inspector as used in the StateMachingSagaConnector class and noticed that the order of events found by the inspector changes at runtime when the saga is inspected. The problem I'm seeing always happens when the DuplicateSubscriptionAdded event gets ordered after the SubscriptionAdded event.

[John Weber]

We ended up switching to RabbitMQ in part due to this issue. I thought I'd summarize my earlier stream of message to consolidate it all.

My setup was:

• One application that produces messages
• One application that consumes the messages
• One application running the SubscriptionService

The steps to recreate were:

• Start up all three services
• Publish message and verify consumer picks it up
• Cleanly shut down the consumer by disposing the IServiceBus instance (but not unsubscribing the consumer subscription)
• Bring up the consumer again
• Observe that some percentage of the time the route from the producer to the consumer will be lost

The problem appears to be in the SubscriptionSaga. It handles the AddSubscription message in two different ways - one to initialize a new saga and another when a duplicate subscription has been added.

When the Subscription Service starts up and the SubscriptionSaga is analyzed to determine events it handles, the order that the events are stored internally dictates if the route will be lost. If the SubscriptionAdded event is ordered before the DuplicateSubscriptionAdded event, then the route will be lost.

I'm not sure of what cases the DuplicateSubscriptionAdded event is meant to handle, but the fix may be to change the way that it's correlated so that it doesn't act on the same AddSubscription message that initializes a new saga.

[Chris Patterson]

I created an issue on GitHub to track the issue, thanks!

To unsubscribe from this group, send email to masstransit-dis...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msg/masstransit-discuss/-/fTkEU3pRVl0J.

[Jeramy Rutley]

We've experienced what looks like the same issue on my co-worker's machine.  So far it only happens on his machine, but is reproducible every time.

If he disposes the bus and restarts the consuming service, he ends up with a SubscriptionAdded, followed by a DuplicateSubscriptionAdded every time on the subscription service, but if he just kill the consumer service and restart, we get DuplicateClientRemoved followed by SubscriptionAdded

Here's a (stripped down) output when we dispose the bus

Info      09/05/2013 14:54:23      SubscriptionSaga SubscriptionAdded <prairieFyre.Storage.Common.Models.INewMailMessage, prairieFyre.Storage.Common> ADDED to <msmq://lcremonesi-pc/router_queue?tx=false>.  Subscription ID <28700000-1891-0026-3b77-08d01afdbf45>

Info      09/05/2013 14:54:23      SubscriptionSaga DuplicateSubscriptionAdded <prairieFyre.Storage.Common.Models.INewMailMessage, prairieFyre.Storage.Common> REMOVED from <msmq://lcremonesi-pc/router_queue?tx=false>.  Subscription ID <28700000-1891-0026-c473-08d01af87334>

And on restart:

Info      09/05/2013 15:00:04      SubscriptionSaga SubscriptionAdded <prairieFyre.Storage.Common.Models.INewMailMessage, prairieFyre.Storage.Common> ADDED to <msmq://lcremonesi-pc/router_queue?tx=false>.  Subscription ID <28700000-1891-0026-1324-08d01afe8991>

Info      09/05/2013 15:00:04      SubscriptionSaga DuplicateSubscriptionAdded <prairieFyre.Storage.Common.Models.INewMailMessage, prairieFyre.Storage.Common> REMOVED from <msmq://lcremonesi-pc/router_queue?tx=false>.  Subscription ID <28700000-1891-0026-3b77-08d01afdbf45>

Note the Subscription ID in the second case truly is a duplicate.

Here's the result when we kill the process and restart:

Info      09/05/2013 15:01:58      SubscriptionSaga DuplicateClientRemoved <prairieFyre.Storage.Common.Models.INewMailMessage, prairieFyre.Storage.Common> REMOVED from <msmq://lcremonesi-pc/router_queue?tx=false>.  Subscription ID <28700000-1891-0026-1324-08d01afe8991>

Info      09/05/2013 15:02:05      SubscriptionSaga SubscriptionAdded <prairieFyre.Storage.Common.Models.INewMailMessage, prairieFyre.Storage.Common> ADDED to <msmq://lcremonesi-pc/router_queue?tx=false>.  Subscription ID <28700000-1891-0026-15be-08d01afed129>

In this case, I see a ClientAdded, followed by all 28 removals, followed by the adds.

The only SubscriptionRemoved that I see is for GetMessageTraceList, which makes sense because we don't want to tear down the subscriptions.  Would using Permanent subscriptions fix this?  We're using Ninject right now, so it makes it a bit awkward, but I can try it.

I can take a stab at fixing this, but may need some guidance.  OTOH, if Permanent subscriptions works out, or we jump on the RabbitMQ train, I may not.  :-)  

To unsubscribe from this group, send email to masstransit-discuss+unsubscribe...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msg/masstransit-discuss/-/ZQ9QpaKKabsJ.

For more options, visit https://groups.google.com/groups/opt_out.
 
 

--
You received this message because you are subscribed to the Google Groups "masstransit-discuss" group.
To post to this group, send email to masstrans...@googlegroups.com.
To unsubscribe from this group, send email to masstransit-discuss+unsub...@googlegroups.com.

[Chris Patterson]

I'm curious, in both of these cases, are you using the MassTransit.RuntimeServices or hosting the SubscriptionService yourself?

If you're hosting it yourself, can you post your bus setup code? For comparison, look at how the service is setup in the RuntimeServices project:

https://github.com/phatboyg/MassTransit/blob/master/src/MassTransit.RuntimeServices/SubscriptionServiceRegistry.cs#L55

Without that concurrent consumer limit of 1, it's likely you can get messages out of order causing this problem.

To unsubscribe from this group and stop receiving emails from it, send an email to masstransit-dis...@googlegroups.com.

To post to this group, send email to masstrans...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msg/masstransit-discuss/-/FWy4u8LcxAIJ.

[Jeramy Rutley]

Here's the bus subscription code in our rehosted runtime services:

            container.Register(Component.For<IServiceBus>().UsingFactoryMethod(sb =>

                ServiceBusFactory.New(sbConfigurator =>

                {

                    sbConfigurator.Subscribe(x => x.LoadFrom(container));

                    sbConfigurator.UseMsmq(msmq => msmq.VerifyMsmqConfiguration());

                    sbConfigurator.UseBinarySerializer();

                    sbConfigurator.UseControlBus();

                    sbConfigurator.SetNetwork(serverName);

                    sbConfigurator.ReceiveFrom("msmq://localhost/masstransitruntimeservices");

                    sbConfigurator.SetConcurrentConsumerLimit(1);

                    sbConfigurator.UsePfLogging();

                })));

The problem "went away" after we stopped disposing the bus in the client apps.  Now we're seeing duplicate messages, but I don't know if that's related or not yet.

To view this discussion on the web visit https://groups.google.com/d/msg/masstransit-discuss/-/fTkEU3pRVl0J.

For more options, visit https://groups.google.com/groups/opt_out.
 
 

--
You received this message because you are subscribed to the Google Groups "masstransit-discuss" group.

To unsubscribe from this group and stop receiving emails from it, send an email to masstransit-discuss+unsub...@googlegroups.com.

[Dan Dorey]

Hi Chris,

We are also experiencing this issue.

Can you tell me the issue number you logged against this? I can't seem to find it on GitHub... and if you know if it's fixed yet that would also be useful. If not, do you have any suggestions on how to work around this issue? Moving to RabbitMQ is not an option for us in the short-term.

Thanks,

Dan

On Thursday, January 24, 2013 5:11:36 PM UTC-5, Chris Patterson wrote:

To unsubscribe from this group, send email to masstransit-discuss+unsubscribe...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msg/masstransit-discuss/-/ZQ9QpaKKabsJ.

For more options, visit https://groups.google.com/groups/opt_out.
 
 

--
You received this message because you are subscribed to the Google Groups "masstransit-discuss" group.
To post to this group, send email to masstrans...@googlegroups.com.
To unsubscribe from this group, send email to masstransit-discuss+unsub...@googlegroups.com.

[Hamdi Akoğuz]

Hi,

We are also experiencing this problem. Is there any workaround for this problem other than moving to RabbitMQ ? 

Please let me know if there is anything I can do to help fixing this issue.

Thanks

To unsubscribe from this group, send email to masstransit-discuss+unsubscribe...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msg/masstransit-discuss/-/ZQ9QpaKKabsJ.

For more options, visit https://groups.google.com/groups/opt_out.
 
 

--
You received this message because you are subscribed to the Google Groups "masstransit-discuss" group.
To post to this group, send email to masstrans...@googlegroups.com.
To unsubscribe from this group, send email to masstransit-discuss+unsub...@googlegroups.com.

[Dan Dorey]

I ended up doing a hack but it seems to be working for us so far.

In the SubscriptionService class I'm doing the following:

Consume(SubscriptionAdded) : Store when we add a subscription for each message type.

Consume(SubscriptionRemoved) : If we've added a s subscription to this message in the last 5 seconds (or whatever) then don't remove it.

Consume(SubscriptionClientAdded) : Be sure to remove this from your tracking list.

[Chris Patterson]

I think I figured this out with a simple seven-character change in the SubscriptionSaga. I'm building and releasing 2.9.3 (well, now 2.9.4 since NuGet barfed on the package upload) with the potential fix.

I also fixed all the dependency issues with the service.

To unsubscribe from this group and stop receiving emails from it, send an email to masstransit-dis...@googlegroups.com.

To post to this group, send email to masstrans...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/masstransit-discuss/309669bd-ec1b-4f43-a1f4-2f0c68f43c25%40googlegroups.com.

[Chris Patterson]

Okay, so it's 2.9.5 and it's now available. :)