Queue crashing after upgrade to 3.8.17 on Erlang 24.0.2 from 3.7.x on Erlang 21

[Ross Cousens]

Hi,

I just provisioned new servers for RabbitMQ 3.8.17. I exported the old definitions from our 3.7.x server, and imported them into the new one. Everything looked fine!

When we started moving traffic across, we immediately got some crashes for a particular queue:

2021-06-16 01:45:04.447 [error] <0.1101.0> ** Generic server <0.1101.0> terminating

** Last message in was {drop_expired,1}

** When Server state == {q,{amqqueue,{resource,<<"/">>,queue,<<"an-tagFileProcessor-2-medium-files">>},true,false,none,[{<<"x-message-ttl">>,long,120000}],<0.1101.0>,[],[],[],[{vhost,<<"/">>},{name,<<"Lazy All">>},{pattern,<<"^.*$">>},{'apply-to',<<"queues">>},{definition,[{<<"queue-mode">>,<<"lazy">>}]},{priority,0}],undefined,[],undefined,stopped,1,[],<<"/">

>,#{user => <<"rmq-internal">>},rabbit_classic_queue,#{}},none,true,rabbit_priority_queue,{passthrough,rabbit_variable_queue,{vqstate,{0,{[],[]}},{0,{[],[]}},{delta,31,15,0,46},{2,{[{msg_status,30,<<80,150,213,24,97,251,38,79,170,87,57,182,199,217,192,238>>,{basic_message,{resource,<<"/">>,exchange,<<"ol-tagFileProcessor-2">>},[<<"files.medium">>],{content,60,

none,<<176,4,16,97,112,112,108,105,99,97,116,105,111,110,47,106,115,111,110,0,0,0,0,2,0>>,rabbit_framing_amqp_0_9_1,[<<"{\"s3\":{\"Bucket\":\"xxx\",\"Key\":\"xxx/xxx.csv\",\"Size\":102935754,\"FileSizeCategory\":\"medium\"},\"appKey\":\"xxx\",\"contentType\":\"text/csv\",\"cre

atedAt\":\"2021-06-16 01:43:04\"}">>]},<<80,150,213,24,97,251,38,79,170,87,57,182,199,217,192,238>>,true},true,false,false,true,queue_index,{message_properties,1623807904441846,false,247}}],[{msg_status,29,<<49,137,111,114,151,79,21,246,166,34,230,161,109,142,249,88>>,{basic_message,{resource,<<"/">>,exchange,<<"ol-tagFileProcessor-2">>},[<<"files.medium">>],{

content,60,none,<<176,4,16,97,112,112,108,105,99,97,116,105,111,110,47,106,115,111,110,0,0,0,0,2,0>>,rabbit_framing_amqp_0_9_1,[<<"{\"s3\":{\"Bucket\":\"xxx\",\"Key\":\"xxx/xxx.csv\",\"Size\":102935754,\"FileSizeCategory\":\"medium\"},\"appKey\":\"xxx\",\"contentType\":\"text/

csv\",\"createdAt\":\"2021-06-16 01:43:04\"}">>]},<<49,137,111,114,151,79,21,246,166,34,230,161,109,142,249,88>>,true},true,false,false,...}]}},...}},...}

** Reason for termination == 

** {function_clause,[{rabbit_queue_index,segment_plus_journal1,[{{true,<<138,97,164,6,99,197,42,135,69,205,58,74,80,200,19,217,0,5,196,216,59,88,243,55,0,0,1,20>>,<<131,104,6,100,0,13,98,97,115,105,99,95,109,101,115,115,97,103,101,104,4,100,0,8,114,101,115,111,117,114,99,101,109,0,0,0,1,47,100,0,8,101,120,99,104,97,110,103,101,109,0,0,0,21,111,108,45,116,97,10

3,70,105,108,101,80,114,111,99,101,115,115,111,114,45,50,108,0,0,0,1,109,0,0,0,12,102,105,108,101,115,46,109,101,100,105,117,109,106,104,6,100,0,7,99,111,110,116,101,110,116,97,60,100,0,4,110,111,110,101,109,0,0,0,25,176,4,16,97,112,112,108,105,99,97,116,105,111,110,47,106,115,111,110,0,0,0,0,2,0,100,0,25,114,97,98,98,105,116,95,102,114,97,109,105,110,103,95,9

7,109,113,112,95,48,95,57,95,49,108,0,0,0,1,109,0,0,1,20,123,34,115,51,34,58,123,34,66,117,99,107,101,116,34,58,34,111,108,45,109,105,99,104,105,103,97,110,115,116,97,116,101,108,111,116,116,101,114,121,34,44,34,75,101,121,34,58,34,101,99,102,99,54,102,57,53,53,56,50,54,50,56,98,53,52,100,49,48,97,99,49,57,55,55,98,52,99,97,55,100,47,79,116,104,101,114,76,101,

118,101,108,115,95,80,117,115,104,78,111,116,105,102,105,99,97,116,105,111,110,115,95,50,48,50,49,45,48,54,45,49,53,46,99,115,118,34,44,34,83,105,122,101,34,58,52,48,52,54,50,53,48,57,44,34,70,105,108,101,83,105,122,101,67,97,116,101,103,111,114,121,34,58,34,109,101,100,105,117,109,34,125,44,34,97,112,112,75,101,121,34,58,34,101,99,102,99,54,102,57,53,53,56,50

,54,50,56,98,53,52,100,49,48,97,99,49,57,55,55,98,52,99,97,55,100,34,44,34,99,111,110,116,101,110,116,84,121,112,101,34,58,34,116,101,120,116,47,99,115,118,34,44,34,99,114,101,97,116,101,100,65,116,34,58,34,50,48,50,49,45,48,54,45,49,54,32,48,49,58,52,50,58,51,49,34,125,106,109,0,0,0,16,138,97,164,6,99,197,42,135,69,205,58,74,80,200,19,217,100,0,4,116,114,117,

101>>},no_del,no_ack},{no_pub,no_del,ack}],[{file,"src/rabbit_queue_index.erl"},{line,1209}]},...]}

2021-06-16 01:45:04.447 [info] <0.1101.0> [{initial_call,{rabbit_prequeue,init,['Argument__1']}},{pid,<0.1101.0>},{registered_name,[]},{error_info,{exit,{function_clause,[{rabbit_queue_index,segment_plus_journal1,[{{true,<<138,97,164,6,99,197,42,135,69,205,58,74,80,200,19,217,0,5,196,216,59,88,243,55,0,0,1,20>>,<<131,104,6,100,0,13,98,97,115,105,99,95,109,101,

115,115,97,103,101,104,4,100,0,8,114,101,115,111,117,114,99,101,109,0,0,0,1,47,100,0,8,101,120,99,104,97,110,103,101,109,0,0,0,21,111,108,45,116,97,103,70,105,108,101,80,114,111,99,101,115,115,111,114,45,50,108,0,0,0,1,109,0,0,0,12,102,105,108,101,115,46,109,101,100,105,117,109,106,104,6,100,0,7,99,111,110,116,101,110,116,97,60,100,0,4,110,111,110,101,109,0,0,

0,25,176,4,16,97,112,112,108,105,99,97,116,105,111,110,47,106,115,111,110,0,0,0,0,2,0,100,0,25,114,97,98,98,105,116,95,102,114,97,109,105,110,103,95,97,109,113,112,95,48,95,57,95,49,108,0,0,0,1,109,0,0,1,20,123,34,115,51,34,58,123,34,66,117,99,107,101,116,34,58,34,111,108,45,109,105,99,104,105,103,97,110,115,116,97,116,101,108,111,116,116,101,114,121,34,44,34,

75,101,121,34,58,34,101,99,102,99,54,102,57,53,53,56,50,54,50,56,98,53,52,100,49,48,97,99,49,57,55,55,98,52,99,97,55,100,47,79,116,104,101,114,76,101,118,101,108,115,95,80,117,115,104,78,111,116,105,102,105,99,97,116,105,111,110,115,95,50,48,50,49,45,48,54,45,49,53,46,99,115,118,34,44,34,83,105,122,101,34,58,52,48,52,54,50,53,48,57,44,34,70,105,108,101,83,105,

122,101,67,97,116,101,103,111,114,121,34,58,34,109,101,100,105,117,109,34,125,44,34,97,112,112,75,101,121,34,58,34,101,99,102,99,54,102,57,53,53,56,50,54,50,56,98,53,52,100,49,48,97,99,49,57,55,55,98,52,99,97,55,100,34,44,34,99,111,110,116,101,110,116,84,121,112,101,34,58,34,116,101,120,116,47,99,115,118,34,44,34,99,114,101,97,116,101,100,65,116,34,58,34,50,48

,50,49,45,48,54,45,49,54,32,48,49,58,52,50,58,51,49,34,125,106,109,0,0,0,16,138,97,164,6,99,197,42,135,69,205,58,74,80,200,19,217,100,0,4,116,114,117,101>>},no_del,no_ack},{no_pub,no_del,ack}],[{file,"src/rabbit_queue_index.erl"},{line,1209}]},{rabbit_queue_index,'-segment_plus_journal/2-fun-0-',...},...]},...}},...], []

2021-06-16 01:45:04.448 [error] <0.1101.0> CRASH REPORT Process <0.1101.0> with 0 neighbours exited with reason: no function clause matching rabbit_queue_index:segment_plus_journal1({{true,<<138,97,164,6,99,197,42,135,69,205,58,74,80,200,19,217,0,5,196,216,59,88,243,55,0,0,1,...>>,...},...}, {no_pub,no_del,ack}) line 1209 in gen_server2:terminate/3 line 1183

2021-06-16 01:45:04.448 [info] <0.1100.0> supervisor: {<0.1100.0>,rabbit_amqqueue_sup}, errorContext: child_terminated, reason: {function_clause,[{rabbit_queue_index,segment_plus_journal1,[{{true,<<138,97,164,6,99,197,42,135,69,205,58,74,80,200,19,217,0,5,196,216,59,88,243,55,0,0,1,20>>,<<131,104,6,100,0,13,98,97,115,105,99,95,109,101,115,115,97,103,101,104,4,

100,0,8,114,101,115,111,117,114,99,101,109,0,0,0,1,47,100,0,8,101,120,99,104,97,110,103,101,109,0,0,0,21,111,108,45,116,97,103,70,105,108,101,80,114,111,99,101,115,115,111,114,45,50,108,0,0,0,1,109,0,0,0,12,102,105,108,101,115,46,109,101,100,105,117,109,106,104,6,100,0,7,99,111,110,116,101,110,116,97,60,100,0,4,110,111,110,101,109,0,0,0,25,176,4,16,97,112,112,

108,105,99,97,116,105,111,110,47,106,115,111,110,0,0,0,0,2,0,100,0,25,114,97,98,98,105,116,95,102,114,97,109,105,110,103,95,97,109,113,112,95,48,95,57,95,49,108,0,0,0,1,109,0,0,1,20,123,34,115,51,34,58,123,34,66,117,99,107,101,116,34,58,34,111,108,45,109,105,99,104,105,103,97,110,115,116,97,116,101,108,111,116,116,101,114,121,34,44,34,75,101,121,34,58,34,101,9

9,102,99,54,102,57,53,53,56,50,54,50,56,98,53,52,100,49,48,97,99,49,57,55,55,98,52,99,97,55,100,47,79,116,104,101,114,76,101,118,101,108,115,95,80,117,115,104,78,111,116,105,102,105,99,97,116,105,111,110,115,95,50,48,50,49,45,48,54,45,49,53,46,99,115,118,34,44,34,83,105,122,101,34,58,52,48,52,54,50,53,48,57,44,34,70,105,108,101,83,105,122,101,67,97,116,101,103

,111,...>>},...},...],...},...]}, offender: [{pid,<0.1101.0>},{id,rabbit_amqqueue},{mfargs,{rabbit_prequeue,start_link,[{amqqueue,{resource,<<"/">>,queue,<<"an-tagFileProcessor-2-medium-files">>},true,false,none,[{<<"x-message-ttl">>,long,120000}],<0.1365.2>,[],[],[],[{vhost,<<"/">>},{name,<<"Lazy All">>},{pattern,<<"^.*$">>},{'apply-to',<<"queues">>},{definit

ion,[{<<"queue-mode">>,<<"lazy">>}]},{priority,0}],undefined,[],undefined,stopped,1,[],<<"/">>,#{user => <<"rmq-internal">>},rabbit_classic_queue,#{}},recovery,<0.1099.0>]}},{restart_type,intrinsic},{shutdown,30000},{child_type,worker}]

2021-06-16 01:45:04.448 [error] <0.1100.0> Supervisor {<0.1100.0>,rabbit_amqqueue_sup} had child rabbit_amqqueue started with rabbit_prequeue:start_link({amqqueue,{resource,<<"/">>,queue,<<"an-tagFileProcessor-2-medium-files">>},true,false,none,[{<<"...">>,...}],...}, recovery, <0.1099.0>) at <0.1101.0> exit with reason no function clause matching rabbit_queue

_index:segment_plus_journal1({{true,<<138,97,164,6,99,197,42,135,69,205,58,74,80,200,19,217,0,5,196,216,59,88,243,55,0,0,1,...>>,...},...}, {no_pub,no_del,ack}) line 1209 in context child_terminated

2021-06-16 01:45:04.452 [error] <0.10102.0> Restarting crashed queue 'an-tagFileProcessor-2-medium-files' in vhost '/'.

2021-06-16 01:45:04.452 [error] <0.10099.0> ** Generic server <0.10099.0> terminating

This happens a few times before the queue state shows 'down' in the management API. 

At this point, if I restart the server, the vhost has failed to come up with an error on boot in the past.

Any ideas how I can debug this issue? 

[Ross Cousens]

Attached is the crash output from when the vhost failed to restart after rabbitmq-server restart after having the queue crashing repeatedly.

[Ross Cousens]

Thought I'd add: I deleted the mnesia db, restarted rabbit, and reimported the 3.7.x queue definitions (I deleted the cluster_name and version key from the file), and then it exhibited the same behaviour with a queue crashing on first message received.

[Ross Cousens]

Ok, it seems we can pretty much crash any rabbitmq queue on 3.8.x if we use the below library:

https://github.com/postwait/node-amqp

Our service is tagged on the 0.1.6 version. 

It had previously been running on rabbitmq 3.7.3 ontop of Erlang 20.3 without incident.

Even worse, when we crash the queue, something gets corrupted that prevents the vhost from booting on restart of rabbit-server service.

Here's a crash log from another queue we crashed using the same NodeJS AMQP library:

** When Server state == {q,{amqqueue,{resource,<<"/">>,queue,<<"an-tagFileProcessor-2">>},true,false,none,[{<<"x-message-ttl">>,long,120000}],<0.1128.0>,[],[],[],[{vhost,<<"/">>},{name,<<"Lazy All">>},{pattern,<<"^.*$">>},{'apply-to',<<"queues">>},{definition,[{<<"queue-mode">>,<<"lazy">>}]},{priority,0}],undefined,[],undefined,stopped,1,[],<<"/">>,#{user => <<"rmq-internal">>},rabbit_classic_queue,#{}},none,true,rabbit_priority_queue,{passthrough,rabbit_variable_queue,{vqstate,{0,{[],[]}},{0,{[],[]}},{delta,18,14,0,32},{0,{[],[]}},{0,{[],[]}},32,{0,nil},{0,nil},{3,{2,{msg_status,2,<<249,228,89,167,171,174,214,8,41,113,13,194,136,159,104,238>>,{basic_message,{resource,<<"/">>,exchange,<<"ol-tagFileProcessor-2">>},[<<"files.medium">>],{content,60,{'P_basic',<<"application/json">>,undefined,[],2,undefined,undefined,undefined,undefined,undefined,undefined,undefined,undefined,undefined,<<>>},<<176,4,16,97,112,112,108,105,99,97,116,105,111,110,47,106,115,111,110,0,0,0,0,2,0>>,rabbit_framing_amqp_0_9_1,[<<"{\"s3\":{\"Bucket\":\"xxxx\",\"Key\":\"7e82ea3fafde6be5ca7c01ab9555296d/xxxx.csv\",\"Size\":92043598,\"FileSizeCategory\":\"medium\"},\"appKey\":\"7e82ea3fafde6be5ca7c01ab9555296d\",\"contentType\":\"text/csv\",\"createdAt\":\"2021-06-16 03:45:43\"}">>]},<<249,228,89,167,171,174,214,8,41,113,13,194,136,159,104,238>>,true},true,true,false,true,queue_index,{message_properties,1623815263404440,false,255}},nil,{3,{msg_status,3,<<90,182,137,246,216,105,82,60,121,135,55,16,241,24,95,254>>,{basic_message,{resource,<<"/">>,exchange,<<"ol-tagFileProcessor-2">>},[<<"files.medium">>],{content,60,{'P_basic',<<"application/json">>,undefined,[],2,undefined,undefined,undefined,undefined,undefined,undefined,undefined,undefined,undefined,<<>>},<<176,4,16,97,112,112,108,105,99,97,116,105,111,110,47,106,115,111,110,0,0,0,0,2,0>>,rabbit_framing_amqp_0_9_1,[<<"{\"s3\":{\"Bucket\":\"xxxx\",\"Key\":\"843c78fa...">>]},...},...},...}}},...}},...}

2021-06-16 03:49:36.623 [error] <0.27196.1> Restarting crashed queue 'an-tagFileProcessor-2' in vhost '/'.

2021-06-16 03:49:36.624 [info] <0.1127.0> supervisor: {<0.1127.0>,rabbit_amqqueue_sup}, errorContext: child_terminated, reason: {function_clause,[{rabbit_queue_index,segment_plus_journal1,[{{true,<<88,19,80,4,8,209,230,92,44,7,135,151,24,107,33,110,0,5,196,217,250,167,237,99,0,0,0,255>>,<<131,104,6,100,0,13,98,97,115,105,99,95,109,101,115,115,97,103,101,104,4,100,0,8,114,101,115,111,117,114,99,101,109,0,0,0,1,47,100,0,8,101,120,99,104,97,110,103,101,109,0,0,0,21,111,108,45,116,97,103,70,105,108,101,80,114,111,99,101,115,115,111,114,45,50,108,0,0,0,1,109,0,0,0,12,102,105,108,101,115,46,109,101,100,105,117,109,106,104,6,100,0,7,99,111,110,116,101,110,116,97,60,100,0,4,110,111,110,101,109,0,0,0,25,176,4,16,97,112,112,108,105,99,97,116,105,111,110,47,106,115,111,110,0,0,0,0,2,0,100,0,25,114,97,98,98,105,116,95,102,114,97,109,105,110,103,95,97,109,113,112,95,48,95,57,95,49,108,0,0,0,1,109,0,0,0,255,123,34,115,51,34,58,123,34,66,117,99,107,101,116,34,58,34,111,108,45,111,112,97,112,34,44,34,75,101,121,34,58,34,56,101,99,100,53,51,54,101,97,51,57,97,48,56,102,52,51,48,56,99,101,99,56,56,102,98,54,50,102,50,57,50,47,79,78,76,73,78,69,95,87,69,66,95,65,80,80,95,84,65,71,83,95,50,48,50,49,48,54,49,54,95,48,49,49,48,48,50,46,99,115,118,34,44,34,83,105,122,101,34,58,57,50,48,52,51,53,57,56,44,34,70,105,108,101,83,105,122,101,67,97,116,101,103,111,114,121,34,58,34,109,101,100,105,117,109,34,125,44,34,97,112,112,75,101,121,34,58,34,56,101,99,...>>},...},...],...},...]}, offender: [{pid,<0.1128.0>},{id,rabbit_amqqueue},{mfargs,{rabbit_prequeue,start_link,[{amqqueue,{resource,<<"/">>,queue,<<"an-tagFileProcessor-2">>},true,false,none,[{<<"x-message-ttl">>,long,120000}],<0.1424.2>,[],[],[],[{vhost,<<"/">>},{name,<<"Lazy All">>},{pattern,<<"^.*$">>},{'apply-to',<<"queues">>},{definition,[{<<"queue-mode">>,<<"lazy">>}]},{priority,0}],undefined,[],undefined,stopped,1,[],<<"/">>,#{user => <<"rmq-internal">>},rabbit_classic_queue,#{}},recovery,<0.1126.0>]}},{restart_type,intrinsic},{shutdown,30000},{child_type,worker}]

2021-06-16 03:49:36.624 [error] <0.1127.0> Supervisor {<0.1127.0>,rabbit_amqqueue_sup} had child rabbit_amqqueue started with rabbit_prequeue:start_link({amqqueue,{resource,<<"/">>,queue,<<"an-tagFileProcessor-2">>},true,false,none,[{<<"x-message-tt...">>,...}],...}, recovery, <0.1126.0>) at <0.1128.0> exit with reason no function clause matching rabbit_queue_index:segment_plus_journal1({{true,<<88,19,80,4,8,209,230,92,44,7,135,151,24,107,33,110,0,5,196,217,250,167,237,99,0,0,0,255>>,...},...}, {no_pub,no_del,ack}) line 1209 in context child_terminated

2021-06-16 03:49:36.628 [error] <0.27199.1> Restarting crashed queue 'an-tagFileProcessor-2' in vhost '/'.

[Michal Kuratczyk]

Hi,

Obviously a client should not be able to render a queue/vhost unusable so we need to look into this but switching to a maintained client library will probably solve the problem for you: https://www.rabbitmq.com/devtools.html#node-dev

--
You received this message because you are subscribed to the Google Groups "rabbitmq-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to rabbitmq-user...@googlegroups.com.
To view this discussion on the web, visit https://groups.google.com/d/msgid/rabbitmq-users/afc1ff3f-2c2d-48e3-8eb5-83e45bec0a44n%40googlegroups.com.

--

Michał

RabbitMQ team

[Ross Cousens]

Hi Michal,

I really wish that was an option right now, there's so much logic to work through on a pretty critical service that is 7-8 years old. Longer term, we will start the migration work to a newer AMQP library! 

Up until today, it had been flying under our radar, operating without incident. 

I'm glad we could help identify an issue that hopefully gets fixed though. Thanks for your response.

Cheers,

Ross

[Michal Kuratczyk]

Could you provide a complete, executable, NodeJS app that uses that client and breaks RabbitMQ? That would make it much easier to debug the problem.

Thanks,

To view this discussion on the web, visit https://groups.google.com/d/msgid/rabbitmq-users/d4dc9435-3184-48d0-a02b-7ca5b75482f4n%40googlegroups.com.

--

Michał

RabbitMQ team

[Ross Cousens]

Hi Michal,

I'll work on a reproducible test case. But I was hoping you could give me some indication from the crash log what was triggering it so I can better isolate it. 

I see it originally said last message in was drop_expired 1, before crashing on the published message. Those queues are imported with a TTL of 120,000 - is that message related to TTLs?

[Michal Kuratczyk]

Yes, I think this is somehow related to TTLs given the "drop_expired" message. Howver, obviously lots of clusters happily used TTLs and/or were upgraded from 3.7 to 3.8 so I'd expect this to be caused by a specific combination of features used and/or settings.

To view this discussion on the web, visit https://groups.google.com/d/msgid/rabbitmq-users/99b2a67d-6cc2-43a5-82d2-f7f22061307fn%40googlegroups.com.

--

Michał

RabbitMQ team

[jo...@cloudamqp.com]

You are most likely looking at this issue: https://github.com/rabbitmq/rabbitmq-server/discussions/3272, upgrade to 3.8.21.

/Johan

[Ross Cousens]

I know I'm a little late here but I wanted to say thank you so much for replying, Johan! It cleared up the mystery we've been experiencing and has given us the confidence to move ahead to later versions on other instances we operate. I'd forgotten about this until now.

Thank you!

 

You received this message because you are subscribed to a topic in the Google Groups "rabbitmq-users" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/rabbitmq-users/8FEZ-9e4hDE/unsubscribe.
To unsubscribe from this group and all its topics, send an email to rabbitmq-user...@googlegroups.com.
To view this discussion on the web, visit https://groups.google.com/d/msgid/rabbitmq-users/c5f50f46-d506-473e-8f1c-30b4f738f2ean%40googlegroups.com.