Re: [rabbitmq-users] TTL / Dead letter error

119 views

Skip to first unread message

Michael Klishin

unread,

Nov 14, 2016, 12:16:05 PM11/14/16

to rabbitm...@googlegroups.com

RabbitMQ does not crash, it logs a crash (unhandled exception) of a queue process.

The x-death value is an array of objects (in JSON terms).

It is certainly possible for apps to confuse RabbitMQ by sending invalid modified headers,

we have seen this several times before.

The x-death value logged does look non-standard: expected keys for `x-death` values

are `queue` and `reason`, for example, and none of them are present.

So either Swarrot (I'm not familiar with it) or the PHP client or even your custom code

modifies the x-deaths header value, possibly unintentionally.

This should be easy to see if you use any other client and re-create this sequence of events,

plus inspect what exactly does each client send from a Wireshark traffic dump [1].

1. https://www.rabbitmq.com/amqp-wireshark.html

On Mon, Nov 14, 2016 at 7:05 PM, Pierrick Doreau <pdo...@gmail.com> wrote:

Hello,

I'm using RabbitMq 3.6.5, PHP Amqplib 2.4 and Swarrot 2.2.0.
I'm trying to setup few queues with retries in case of failure : task => retry1 (TTL/DL) => task => retry2 (TTL/DL) => task => retry3 (TTL/DL) => task => DL
Everything's going well until retry2, rabbitmq server crashes when TTL expires.

See the attached picture which shows the message published into retry2.
Here's the server log when the second TTL expires :

=INFO REPORT==== 14-Nov-2016::15:26:38 === accepting AMQP connection <0.22867.2> (172.19.0.7:52018 -> 172.19.0.9:5672) =WARNING REPORT==== 14-Nov-2016::15:26:38 === closing AMQP connection <0.22867.2> (172.19.0.7:52018 -> 172.19.0.9:5672): client unexpectedly closed TCP connection =ERROR REPORT==== 14-Nov-2016::15:27:48 === ** Generic server <0.872.2> terminating ** Last message in was {drop_expired,1} ** When Server state == {q, {amqqueue, {resource,<<"myvhost">>,queue, <<"mytask_retry_2">>}, true,false,none, [{<<"x-message-ttl">>,long,30000}, {<<"x-dead-letter-exchange">>,longstr,<<"retry">>}, {<<"x-dead-letter-routing-key">>,longstr, <<"mytask">>}], <0.872.2>,[],[],[],undefined,[],[],crashed}, none,false,rabbit_priority_queue, {passthrough,rabbit_variable_queue, {vqstate, {0,{[],[]}}, {0,{[],[]}}, {delta,undefined,0,undefined}, {0,{[],[]}}, {1, {[], [{msg_status,0, <<248,215,220,27,249,254,141,145,20,170,169,251, 113,144,3,205>>, {basic_message, {resource,<<"myvhost">>,exchange,<<"retry">>}, [<<"mytask_retry_2">>], {content,60, {'P_basic',undefined,undefined, [{<<"swarrot_retry_attempts">>,signedint,2}, {<<"x-death">>,array, [{array, [{array, [{longstr,<<"l">>},{longstr,<<"1">>}]}, {array, [{longstr,<<"S">>}, {longstr,<<"expired">>}]}, {array, [{longstr,<<"S">>}, {longstr, <<"mytask_retry_1">>}]}, {array, [{longstr,<<"T">>}, {longstr,<<"1479137231">>}]}, {array, [{longstr,<<"S">>}, {longstr,<<"retry">>}]}, {array, [{longstr,<<"A">>}, {array, [{longstr, <<"mytask_retry_1">>}]}]}]}]}], undefined,undefined,undefined,undefined, undefined,undefined,undefined,undefined, undefined,undefined,undefined}, <<32,0,0,0,0,242,22,115,119,97,114,114,111, 116,95,114,101,116,114,121,95,97,116,116, 101,109,112,116,115,73,0,0,0,2,7,120,45,100, 101,97,116,104,65,0,0,0,201,65,0,0,0,196,65, 0,0,0,12,83,0,0,0,1,108,83,0,0,0,1,49,65,0, 0,0,18,83,0,0,0,1,83,83,0,0,0,7,101,120,112, 105,114,101,100,65,0,0,0,47,83,0,0,0,1,83, 83,0,0,0,36,97,115,107,95,109,97,110,103, 111,112,97,121,95,105,100,95,118,101,114, 105,102,105,99,97,116,105,111,110,95,114, 101,116,114,121,95,49,65,0,0,0,21,83,0,0,0, 1,84,83,0,0,0,10,49,52,55,57,49,51,55,50,51, 49,65,0,0,0,16,83,0,0,0,1,83,83,0,0,0,5,114, 101,116,114,121,65,0,0,0,52,83,0,0,0,1,65, 65,0,0,0,41,83,0,0,0,36,97,115,107,95,109, 97,110,103,111,112,97,121,95,105,100,95,118, 101,114,105,102,105,99,97,116,105,111,110, 95,114,101,116,114,121,95,49>>, rabbit_framing_amqp_0_9_1, [<<"{\"userId\":9422800}">>]}, <<248,215,220,27,249,254,141,145,20,170,169, 251,113,144,3,205>>, false}, false,true,false,false,queue_index, {message_properties,1479137268390618,false, 18}}]}}, 1, {0,nil}, {0,nil}, {0,nil}, {qistate, "/var/lib/rabbitmq/mnesia/rabbit@a4e8142ad392/queues/A1576Z48UM5HZE66EKAXWP315", {{dict,0,16,16,8,80,48, {[],[],[],[],[],[],[],[],[],[],[],[],[],[],[], []}, {{[],[],[],[],[],[],[],[],[],[],[],[],[],[],[], []}}}, []}, undefined,0,32768, #Fun<rabbit_variable_queue.2.95522769>, #Fun<rabbit_variable_queue.3.95522769>, {0,nil}, {0,nil}, [],[]}, {{client_msstate,msg_store_persistent, <<164,28,103,54,224,19,214,175,108,157,221,53,93, 168,142,255>>, {dict,0,16,16,8,80,48, {[],[],[],[],[],[],[],[],[],[],[],[],[],[],[], []}, {{[],[],[],[],[],[],[],[],[],[],[],[],[],[],[], []}}}, {state,352339, "/var/lib/rabbitmq/mnesia/rabbit@a4e8142ad392/msg_store_persistent"}, rabbit_msg_store_ets_index, "/var/lib/rabbitmq/mnesia/rabbit@a4e8142ad392/msg_store_persistent", <0.347.0>,356436,348242,360533,364630, {2000,500}}, {client_msstate,msg_store_transient, <<103,164,117,217,235,42,126,67,218,31,45,137,135, 183,163,118>>, {dict,0,16,16,8,80,48, {[],[],[],[],[],[],[],[],[],[],[],[],[],[],[], []}, {{[],[],[],[],[],[],[],[],[],[],[],[],[],[],[], []}}}, {state,327757, "/var/lib/rabbitmq/mnesia/rabbit@a4e8142ad392/msg_store_transient"}, rabbit_msg_store_ets_index, "/var/lib/rabbitmq/mnesia/rabbit@a4e8142ad392/msg_store_transient", <0.342.0>,331854,323660,335951,340048, {2000,500}}}, true,0,4096,1,18,0,0,0,infinity,1,0,0,18,0,0, {rates,0.0584721460961095,0.05842054472555488, 0.05842054472555488,0.0,-576450848546040990}, {0,nil}, {0,nil}, {0,nil}, {0,nil}, 0,0,0,0,2048,default}}, {state, {queue,[],[],0}, {inactive,-576450865057239,2433836640,1.0}}, undefined,undefined, {erlang,#Ref<0.0.2.38607>}, undefined, {state,fine,5000,#Ref<0.0.2.38608>}, {0,nil}, 30000, {erlang,#Ref<0.0.2.38606>}, 1479137268390618, {state, {dict,1,16,16,8,80,48, {[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],[]}, {{[],[],[],[],[],[],[],[],[],[],[],[], [[<0.22198.2>|#Ref<0.0.1.241810>]], [],[],[]}}}, delegate}, {resource,<<"myvhost">>,exchange,<<"retry">>}, <<"mytask">>,undefined, undefined,1,running} ** Reason for termination == ** {function_clause, [{rabbit_dead_letter,'-queue_and_reason_matcher/2-fun-1-', [{array, [{array,[{longstr,<<"l">>},{longstr,<<"1">>}]}, {array,[{longstr,<<"S">>},{longstr,<<"expired">>}]}, {array, [{longstr,<<"S">>}, {longstr,<<"mytask_retry_1">>}]}, {array,[{longstr,<<"T">>},{longstr,<<"1479137231">>}]}, {array,[{longstr,<<"S">>},{longstr,<<"retry">>}]}, {array, [{longstr,<<"A">>}, {array, [{longstr, <<"mytask_retry_1">>}]}]}]}], [{file,"src/rabbit_dead_letter.erl"},{line,178}]}, {lists,partition,4,[{file,"lists.erl"},{line,1302}]}, {rabbit_dead_letter,update_x_death_header,2, [{file,"src/rabbit_dead_letter.erl"},{line,127}]}, {rabbit_dead_letter,'-make_msg/5-fun-2-',8, [{file,"src/rabbit_dead_letter.erl"},{line,65}]}, {rabbit_basic,map_headers,2, [{file,"src/rabbit_basic.erl"},{line,258}]}, {rabbit_dead_letter,make_msg,5, [{file,"src/rabbit_dead_letter.erl"},{line,68}]}, {rabbit_dead_letter,publish,5, [{file,"src/rabbit_dead_letter.erl"},{line,34}]}, {rabbit_amqqueue_process,'-dead_letter_msgs/4-fun-0-',7, [{file,"src/rabbit_amqqueue_process.erl"},{line,848}]}]} =CRASH REPORT==== 14-Nov-2016::15:27:48 === crasher: initial call: rabbit_prequeue:init/1 pid: <0.872.2> registered_name: [] exception exit: {function_clause, [{rabbit_dead_letter, '-queue_and_reason_matcher/2-fun-1-', [{array, [{array,[{longstr,<<"l">>},{longstr,<<"1">>}]}, {array,[{longstr,<<"S">>},{longstr,<<"expired">>}]}, {array, [{longstr,<<"S">>}, {longstr, <<"mytask_retry_1">>}]}, {array, [{longstr,<<"T">>},{longstr,<<"1479137231">>}]}, {array,[{longstr,<<"S">>},{longstr,<<"retry">>}]}, {array, [{longstr,<<"A">>}, {array, [{longstr, <<"mytask_retry_1">>}]}]}]}], [{file,"src/rabbit_dead_letter.erl"},{line,178}]}, {lists,partition,4,[{file,"lists.erl"},{line,1302}]}, {rabbit_dead_letter,update_x_death_header,2, [{file,"src/rabbit_dead_letter.erl"},{line,127}]}, {rabbit_dead_letter,'-make_msg/5-fun-2-',8, [{file,"src/rabbit_dead_letter.erl"},{line,65}]}, {rabbit_basic,map_headers,2, [{file,"src/rabbit_basic.erl"},{line,258}]}, {rabbit_dead_letter,make_msg,5, [{file,"src/rabbit_dead_letter.erl"},{line,68}]}, {rabbit_dead_letter,publish,5, [{file,"src/rabbit_dead_letter.erl"},{line,34}]}, {rabbit_amqqueue_process,'-dead_letter_msgs/4-fun-0-', 7, [{file,"src/rabbit_amqqueue_process.erl"}, {line,848}]}]} in function gen_server2:terminate/3 (src/gen_server2.erl, line 1143) ancestors: [<0.931.0>,rabbit_amqqueue_sup_sup,rabbit_sup,<0.140.0>] messages: [] links: [<0.931.0>] dictionary: [{process_name, {rabbit_amqqueue_process, {resource,<<"myvhost">>,queue, <<"mytask_retry_2">>}}}, {{credit_to,<0.22198.2>},49}, {rand_seed, {#{max => 288230376151711743, next => #Fun<rand.8.41921595>, type => exsplus, uniform => #Fun<rand.9.41921595>, uniform_n => #Fun<rand.10.41921595>}, [287586524076964252|216827261502116418]}}, {guid,{{1738831321,3945430595,3659476361,2276959094},1}}, {credit_flow_default_credit,{200,50}}] trap_exit: true status: running heap_size: 2586 stack_size: 27 reductions: 10836 neighbours: =SUPERVISOR REPORT==== 14-Nov-2016::15:27:48 === Supervisor: {<0.931.0>,rabbit_amqqueue_sup} Context: child_terminated Reason: {function_clause, [{rabbit_dead_letter,'-queue_and_reason_matcher/2-fun-1-', [{array, [{array,[{longstr,<<"l">>},{longstr,<<"1">>}]}, {array,[{longstr,<<"S">>},{longstr,<<"expired">>}]}, {array, [{longstr,<<"S">>}, {longstr, <<"mytask_retry_1">>}]}, {array,[{longstr,<<"T">>},{longstr,<<"1479137231">>}]}, {array,[{longstr,<<"S">>},{longstr,<<"retry">>}]}, {array, [{longstr,<<"A">>}, {array, [{longstr, <<"mytask_retry_1">>}]}]}]}], [{file,"src/rabbit_dead_letter.erl"},{line,178}]}, {lists,partition,4,[{file,"lists.erl"},{line,1302}]}, {rabbit_dead_letter,update_x_death_header,2, [{file,"src/rabbit_dead_letter.erl"},{line,127}]}, {rabbit_dead_letter,'-make_msg/5-fun-2-',8, [{file,"src/rabbit_dead_letter.erl"},{line,65}]}, {rabbit_basic,map_headers,2, [{file,"src/rabbit_basic.erl"},{line,258}]}, {rabbit_dead_letter,make_msg,5, [{file,"src/rabbit_dead_letter.erl"},{line,68}]}, {rabbit_dead_letter,publish,5, [{file,"src/rabbit_dead_letter.erl"},{line,34}]}, {rabbit_amqqueue_process,'-dead_letter_msgs/4-fun-0-',7, [{file,"src/rabbit_amqqueue_process.erl"},{line,848}]}]} Offender: [{pid,<0.872.2>}, {name,rabbit_amqqueue}, {mfargs, {rabbit_prequeue,start_link, [{amqqueue, {resource,<<"myvhost">>,queue, <<"mytask_retry_2">>}, true,false,none, [{<<"x-message-ttl">>,long,30000}, {<<"x-dead-letter-exchange">>,longstr, <<"retry">>}, {<<"x-dead-letter-routing-key">>,longstr, <<"mytask">>}], none,[],[],[],undefined,[],[],live}, declare,<0.930.0>]}}, {restart_type,intrinsic}, {shutdown,30000}, {child_type,worker}] =ERROR REPORT==== 14-Nov-2016::15:27:48 === Restarting crashed queue 'mytask_retry_2' in vhost 'myvhost'.

Do you know where could be the problem ?

--
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-users+unsubscribe@googlegroups.com.
To post to this group, send email to rabbitmq-users@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.