Stomp, persistent subscription to amq.topic and error 530

[Daniel Sundström]

Hi,

Daniel here. I'm managing an installation under development with ~80 iPads running inhouse-app, and a few other clients - all communicating via Rabbit. The iPads communicate using STOMP via the plugin with explicit set id-header and persistent set to true on subscription frame, the other clients talk AMQP. We recently switched to persistent subscriptions due to network conditions being untrustworthy and so far, so good.

However, now we see connections being terminated once in a while with a 530-error, and "attempted to reuse consumertag T_XXXXX".

I'm guessing that the client has dropped - at which point it will try to reconnect until connection is established, then try to resubscribe to the previous topics. What I don't understand is why when this happens as I was under the impression that if the client sends a SUBSCRIBE with persistent = 1, and id = "XXX" after loosing connection, then it would automatically resubscribe to the existing topic queue (given that these queues are created by the stomp gateway)? If not, how should resubscription after re-establishing connection be done? Also, this seems to not happen every time, but once in a while.

Thoughts? Have I misconfigured something? Any pointers would be helpful!

Many Regards,
Daniel

[Michael Klishin]

 On 11 March 2015 at 03:05:45, Daniel Sundström (dan...@monkeydancers.com) wrote:
> However, now we see connections being terminated once in a while
> with a 530-error, and "attempted to reuse consumertag T_XXXXX".
>
> I'm guessing that the client has dropped - at which point it will
> try to reconnect until connection is established, then try to
> resubscribe to the previous topics. What I don't understand
> is why when this happens as I was under the impression that if the
> client sends a SUBSCRIBE with persistent = 1, and id = "XXX" after
> loosing connection, then it would automatically resubscribe
> to the existing topic queue (given that these queues are created
> by the stomp gateway)? If not, how should resubscription after
> re-establishing connection be done? Also, this seems to not
> happen every time, but once in a while.
>
> Thoughts? Have I misconfigured something? Any pointers would
> be helpful!

This happens because connection loss is not necessarily noticed by the server immediately.
This is explained in http://rabbitmq.com/heartbeats.html.

STOMP also has heartbeats in the protocol:
https://stomp.github.io/stomp-specification-1.2.html#Heart-beating

and they are supported by the RabbitMQ STOMP plugin.

I'd recommend using a value of 5 seconds or greater. Lower ones can result in false
positives.
--
MK

Staff Software Engineer, Pivotal/RabbitMQ

[Michael Klishin]

  On 11 March 2015 at 07:46:00, Michael Klishin (mkli...@pivotal.io) wrote:
> This happens because connection loss is not necessarily noticed
> by the server immediately.
> This is explained in http://rabbitmq.com/heartbeats.html.
>
> STOMP also has heartbeats in the protocol:
> https://stomp.github.io/stomp-specification-1.2.html#Heart-beating

FTR, I should point out that in AMQP 0-9-1 heartbeats can be disabled but they are opt-out. Default value is 580
seconds.

In STOMP, heartbeats are opt-in.

[Michael Klishin]

On 11 March 2015 at 03:05:45, Daniel Sundström (dan...@monkeydancers.com) wrote:
> This happens because connection loss is not necessarily noticed
> by the server immediately.
> This is explained in http://rabbitmq.com/heartbeats.html.
>
> STOMP also has heartbeats in the protocol:
> https://stomp.github.io/stomp-specification-1.2.html#Heart-beating

Our docs now mention that STOMP heartbeats are supported a well:
 * https://github.com/rabbitmq/rabbitmq-server/issues/64
 * http://www.rabbitmq.com/heartbeats.html 

[Michael Klishin]

On 11 March 2015 at 03:05:45, Daniel Sundström (dan...@monkeydancers.com) wrote:
> This happens because connection loss is not necessarily noticed
> by the server immediately.

or not. Consumer tags on a new connection won't interfere with those on the existing one.

Daniel, what do your code do to recover? Can it be sending SUBSCRIBE more than once in rapid succession?
Can you post the exact error message?

Thanks. 

[Daniel Sundström]

Hi, 

Thanks for the prompt reply! 

Yes, I'm guessing that in theory it could - once connection is dropped, it starts to try and reconnect once every second, and quits upon 

getting a valid connection. So, if the connection establishes, and begins to resubscribe - but doesn't return itself as connected until the 

next retry occurs and this sends a new SUBSCRIBE - this is an error that could be expected? Do I understand the issue correctly? 

If so, I could try to scale down the reconnection attempts and see if it disppears. 

This is the exact error message posted in the log: http://pastie.org/10018281

Regards, 

Daniel

[Michael Klishin]

 On 11 March 2015 at 15:00:23, Daniel Sundström (dan...@monkeydancers.com) wrote:
> Yes, I'm guessing that in theory it could - once connection is
> dropped, it starts to try and reconnect once every second, and
> quits upon
> getting a valid connection. So, if the connection establishes,
> and begins to resubscribe - but doesn't return itself as connected
> until the
> next retry occurs and this sends a new SUBSCRIBE - this is an error
> that could be expected? Do I understand the issue correctly?

Not quite, my guess is that two SUBSCRIBE frames are sent nearly at the same time
and there's a race condition in our plugin.

What destination do you use?

> If so, I could try to scale down the reconnection attempts and
> see if it disppears.

Feel free to try but I'd like to see if we can reproduce it.

Thanks, the error message hints at where this may be happening.

[Daniel Sundström]

Aah, okey - thanks for the clarification. 

All subscriptions are on amq.topic using persistent subscriptions as described by the section "Durable Topic Subscriptions" at

https://www.rabbitmq.com/stomp.html - the actual topics are on the format of "jade.dev.ipad.XXX" and never more than 4 "sections"

deep. 

Okey, I'll hold off some time then and see if I can furnish more details as the error occurs. 

Let me know if you need anything else from me? Just for details - we're running 3.4.4 on Ubuntu 14.04.1 LTS. 

Cheers, 

Daniel

[Daniel Sundström]

Hi Michael, 

Just a quick update - we've been running some extensive tests yesterday and today and 

have no problem reproducing this at will now. Basically, just simulating a connection drop and 

then attempt to reconnect every 0.5 seconds will trigger this in 60-80% of the clients at the specific time, and 100% of

the clients over repeated tests. 

I've attached some more error logs displaying the problem, which - to my eye - looks identical to the previous ones

but which may yield more information. Log: http://pastie.org/10020499

In the meantime, do you have any suggestions to changes in the client to prevent this from happening? 

Best regards, 

Daniel

[Michael Klishin]

On 12 March 2015 at 12:52:18, Daniel Sundström (dan...@monkeydancers.com) wrote:
> Just a quick update - we've been running some extensive tests
> yesterday and today and
> have no problem reproducing this at will now. Basically, just
> simulating a connection drop and
> then attempt to reconnect every 0.5 seconds will trigger this
> in 60-80% of the clients at the specific time, and 100% of
> the clients over repeated tests.
>
> I've attached some more error logs displaying the problem, which
> - to my eye - looks identical to the previous ones
> but which may yield more information. Log: http://pastie.org/10020499

Thanks.

> In the meantime, do you have any suggestions to changes in the
> client to prevent this from happening?

Have you tried reconnecting in, say, 5 seconds? Does that help? 

[Michael Klishin]

On Thursday, 12 March 2015 12:52:20 UTC+3, Daniel Sundström wrote:

Hi Michael, 

Just a quick update - we've been running some extensive tests yesterday and today and 

have no problem reproducing this at will now. Basically, just simulating a connection drop and 

then attempt to reconnect every 0.5 seconds will trigger this in 60-80% of the clients at the specific time, and 100% of

the clients over repeated tests. 

I've attached some more error logs displaying the problem, which - to my eye - looks identical to the previous ones

but which may yield more information. Log: http://pastie.org/10020499

Filed an issue you can watch on GitHub:  https://github.com/rabbitmq/rabbitmq-stomp/issues/5.

MK

[Giuseppe Privitera]

Hi Daniel,

please, could you post the code you are using to replicate the issue? 

Kind regards,

Giuseppe