Error: There is no current subscription with tag

[Leifhaa]

Hello!

For the past couple of months I've been experiencing the error: 'There is no current subscription with tag 'T_....' which ocasionally occurs. This week I've tried to get to the bottom of what's causing this and frequently breaking my websocket connections. Going through the logs, I've concluded that the error occurs in RabbitMQ. I'm using Stomp plugin. My current architecture is as following:

• Spring boot
• RabbitMQ
• Client applications, communicating with spring boot through STOMP messages.

These are the following logs whenever the issue occurs:
RabbitMQ:

2022-01-12 17:47:25.358129+00:00 [dbug] <0.12199.5> Deleting auto-delete queue 'stomp-subscription-vNIRfMHF_j9lJqq6vf7Zbw' in vhost 'dtdeefmb' because its last consumer with tag 'T_15' was cancelled
2022-01-12 17:47:25.391485+00:00 [info] <0.11967.5> closing STOMP connection <0.11967.5> (193.91.129.67:64909 -> 10.56.72.86:61613)
2022-01-12 17:47:25.391747+00:00 [dbug] <0.12212.5> Closing all channels from connection '193.91.129.67:64909 -> 10.56.72.86:61613' because it has been closed

Spring boot:

18:47:25.637 [WebSocketClient-AsyncIO-4] INFO com.example.demo.client.ConsumerSessionHandler - Received : There is no current subscription with tag 'T_15'.
18:47:25.639 [WebSocketClient-AsyncIO-4] DEBUG org.springframework.web.socket.handler.LoggingWebSocketHandlerDecorator - StandardWebSocketSession[id=84c01a06-2c56-332c-7fa7-e186ba17cbe2, uri=null] closed with CloseStatus[code=1002, reason=null]
18:47:25.639 [WebSocketClient-AsyncIO-4] DEBUG org.springframework.messaging.simp.stomp.DefaultStompSession - Connection closed in session id=eba3d18c-5184-b3dd-3366-03b5d40d2788
18:47:25.639 [WebSocketClient-AsyncIO-4] DEBUG org.springframework.web.socket.adapter.NativeWebSocketSession - Closing StandardWebSocketSession[id=84c01a06-2c56-332c-7fa7-e186ba17cbe2, uri=null]

In order to reproduce the problem, I made a tiny project which can replicate this exact error. It also contains the step in order to reproduce the error. It can be found here:
https://github.com/Leifhaa/rabbitmq-spring-websocket

I suspect there's some kind of multithreading issue as it occurs 'randomly' in my view. I'm not certain about this however. If there's anything more I can contribute with, such as any more logs, assistance in setting up the replication project etc I'd be glad to do so.

[lukebakken]

Thanks for providing code to reproduce this. I'll give it a try this week.

Going through the logs, I've concluded that the error occurs in RabbitMQ.

I don't see any evidence at this point to bolster that claim just yet 😄

Glancing at your code, I see that you're unsubscribing / subscribing during handleFrame. I am not familiar at all with Spring/Stomp, but is that allowed?

[Leifhaa]

Appreciate the feedback!

The reason why I suspect the error occurs in RabbitMQ (STOMP plugin) is because the error message which I'm seeing is generated by RabbitMQ (Stomp plugin) from here: https://github.com/rabbitmq/rabbitmq-stomp/blob/master/src/rabbit_stomp_processor.erl (line 823). It could surely be other reasons, It was just my immidiate thought :)

It's indeed subscribing and unsubscribing at wild even during handleFrame simply to reproduce the issue. I could simply fix this in my application with a lock, however if I'd scale the infrastructure having two instances of such spring boot applications then a simple lock would no longer be sufficient. There would anyway be subscriptions/unsubscriptions together with messages.

[lukebakken]

@Leifhaa when you have time, would you please modify your project or provide instructions for how I can activate the most verbose debug-level logging available. Thank you.

[Leifhaa]

The logging level has been changed in the repository now. The debug-level is "trace" which is the most verbose one.

[lukebakken]

Update - I have been busy with support for paying customers but have added this to my to-do list. I can't guarantee when I will have time to assist.

[Leifhaa]

Ok, appreciate the feedback :)

[sasavilic]

We were also able to reproduce this behaviour. Our observation was that it happens when UNSUBSCRIBE is followed by SEND in other consumer nearly at same time. Here is part of TCP traffic captured by Wireshark just before server closes connection:

.SUBSCRIBE
ack:auto
id:sub-455
destination:/topic/service-operationsbackend--flight--3559ab9f-3402-4bc6-897b-a9d7286a5d14

.SUBSCRIBE
ack:auto
id:sub-456
destination:/topic/service-operationsbackend--summaries--3559ab9f-3402-4bc6-897b-a9d7286a5d14

.UNSUBSCRIBE
id:sub-432

.UNSUBSCRIBE
id:sub-454

.SUBSCRIBE
ack:auto
id:sub-457
destination:/topic/service-operationsbackend--comparison--3559ab9f-3402-4bc6-897b-a9d7286a5d14

.UNSUBSCRIBE
id:sub-430

.SUBSCRIBE
ack:auto
id:sub-458
destination:/topic/service-operationsbackend--transactions--bd99866b-8f96-4c15-970b-9e18857ded40

.UNSUBSCRIBE
id:sub-431

.SUBSCRIBE
ack:auto
id:sub-459
destination:/topic/service-operationsbackend--gammastatus--bd99866b-8f96-4c15-970b-9e18857ded40

.UNSUBSCRIBE
id:sub-457

.SUBSCRIBE
ack:auto
id:sub-460
destination:/topic/service-operationsbackend--comparison--bd99866b-8f96-4c15-970b-9e18857ded40

.UNSUBSCRIBE
id:sub-455

.UNSUBSCRIBE
id:sub-460

.UNSUBSCRIBE
id:sub-450

.UNSUBSCRIBE
id:sub-451

.UNSUBSCRIBE
id:sub-452

.UNSUBSCRIBE
id:sub-453

.ERROR
message:Subscription not found
content-type:text/plain
version:1.0,1.1,1.2
content-length:54

There is no current subscription with tag 'T_sub-455'..
DISCONNECT

[jordanwwb]

HI,

I am facing the same issue. Did you manage to overcome this problem? Is there any updates on this?

[Leifhaa]

Hi, I did not manage to overcome this problem by using the Stomp plugin no. My conclusion was that it can't be considered 100% thread safe, thus I have implemented similar approach as the STOMP plugin, but without the usage of the plugin itself.

[sasavilic]

No, it is broken. We ended up writing our own high performance STOMP broker.

[lukebakken]

Obviously this discussion completely fell off of my radar. I have opened the following issue - #7531

[mkuratczyk]

I had the reproduction app running for over an hour and the issue didn't occur. I reduced the sleep time, to make it go through more iterations (it was thousands of subscriptions). I tried main and v3.11.x on OTP25 and OTP26.

It feels like there's something more needed to trigger this problem. If someone can try to adjust rabbitmq-spring-websocket or provide another app we can try, we'll look into this. Otherwise I don't see how we can fix that.

[lukebakken]

Thanks @mkuratczyk