Re: [rabbitmq-users] Connection crash report regularly logged

[Michael Klishin]

It's an unhandled notification of a clean Objective-C client connection shutdown. Almost certainly just noise but we'd be interested in a way to reproduce.

On Thu, May 10, 2018 at 3:36 PM, Sean Nolan <sno...@nextradioapp.com> wrote:

I am seeing this crash report logged regularly, can anyone explain what would be causing this? The server is running normally, I do not see any obvious issues.

Running RabbitMQ 3.7.5, Erlang 20.3 on Ubuntu 16.04

2018-05-10 20:19:01.963 [error] <0.12406.8> ** Generic server <0.12406.8> terminating
** Last message in was {'$gen_cast',{method,{'queue.bind',0,<<"rmq-objc-client.gen-8A3E9C3C-F7CB-4E24-9F38-85997BF46DFB-564-0000006757AA094C">>,<<"anexchange">>,<<"#.item_13434">>,false,[]},none,noflow}}
** When Server state == {ch,running,rabbit_framing_amqp_0_9_1,1,<0.9447.8>,<0.12404.8>,<0.9447.8>,<<"10.0.12.31:15878 -> 10.0.3.96:5672">>,{lstate,<0.12405.8>,false},none,1,{[],[]},{user,<<"rmquser">>,[],[{rabbit_auth_backend_internal,none}]},<<"/">>,<<"rmq-objc-client.gen-8A3E9C3C-F7CB-4E24-9F38-85997BF46DFB-564-0000006757AA094C">>,#{},{state,{dict,0,16,16,8,80,48,{[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],[]},{{[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],[]}}},erlang},#{},#{},{set,0,16,16,8,80,48,{[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],[]},{{[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],[]}}},<0.11824.8>,{state,fine,5000,undefined},false,1,{{0,nil},{0,nil}},[],[],{{0,nil},{0,nil}},[{<<"authentication_failure_close">>,bool,true},{<<"basic.nack">>,bool,true},{<<"connection.blocked">>,bool,true},{<<"consumer_cancel_notify">>,bool,true},{<<"exchange_exchange_bindings">>,bool,true},{<<"publisher_confirms">>,bool,true}],none,0,none,flow,[]}
** Reason for termination ==
** {{normal,{gen_server,call,[<0.9447.8>,{info,[amqp_params]},15000]}},[{gen_server,call,3,[{file,"gen_server.erl"},{line,214}]},{rabbit_amqp_connection,amqp_params,2,[{file,"src/rabbit_amqp_connection.erl"},{line,24}]},{rabbit_channel,check_topic_authorisation,5,[{file,"src/rabbit_channel.erl"},{line,850}]},{rabbit_channel,binding_action,9,[{file,"src/rabbit_channel.erl"},{line,1648}]},{rabbit_channel,handle_method,3,[{file,"src/rabbit_channel.erl"},{line,1419}]},{rabbit_channel,handle_cast,2,[{file,"src/rabbit_channel.erl"},{line,523}]},{gen_server2,handle_msg,2,[{file,"src/gen_server2.erl"},{line,1050}]},{proc_lib,wake_up,3,[{file,"proc_lib.erl"},{line,257}]}]}
2018-05-10 20:19:01.963 [error] <0.12406.8> CRASH REPORT Process <0.12406.8> with 0 neighbours exited with reason: {normal,{gen_server,call,[<0.9447.8>,{info,[amqp_params]},15000]}} in gen_server:call/3 line 214 in gen_server2:terminate/3 line 1166
2018-05-10 20:19:01.963 [error] <0.12403.8> Supervisor {<0.12403.8>,rabbit_channel_sup} had child channel started with rabbit_channel:start_link(1, <0.9447.8>, <0.12404.8>, <0.9447.8>, <<"10.0.12.31:15878 -> 10.0.3.96:5672">>, rabbit_framing_amqp_0_9_1, {user,<<"rmquser">>,[],[{rabbit_auth_backend_internal,none}]}, <<"/">>, [{<<"authentication_failure_close">>,bool,true},{<<"basic.nack">>,bool,true},{<<"connection.block...">>,...},...], <0.11824.8>, <0.12405.8>) at <0.12406.8> exit with reason {normal,{gen_server,call,[<0.9447.8>,{info,[amqp_params]},15000]}} in gen_server:call/3 line 214 in context shutdown_error

--
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.

--

MK

Staff Software Engineer, Pivotal/RabbitMQ

[Sean Nolan]

I don't have good visibility into the iOS app that is doing this but I can try to collect some info - when you say an unhandled notification, should the client be doing something to handle the notification or are you saying that it is simply unhandled on the server side and you need to know what the client was doing when it happened? Would you expect to see an error or exception in the client when this occurs - I'm guessing not?

Sean

To unsubscribe from this group and stop receiving emails from it, send an email to rabbitmq-user...@googlegroups.com.
To post to this group, send email to rabbitm...@googlegroups.com.

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

[Michael Klishin]

Can you take a look at the regular log around the same timestamp and see if the connection was closed cleanly?

A couple of things in the trace suggest that it was, in which case reproducing should be much easier.

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.

[Sean Nolan]

Here's everything I could find for a connection that crashed

2018-05-11 15:25:17.178 [info] <0.7940.3> accepting AMQP connection <0.7940.3> (10.0.11.58:44020 -> 10.0.7.96:5672)
2018-05-11 15:25:18.123 [info] <0.7940.3> connection <0.7940.3> (10.0.11.58:44020 -> 10.0.7.96:5672): user 'rmquser' authenticated and granted access to vhost '/'
2018-05-11 15:25:22.186 [warning] <0.7940.3> closing AMQP connection <0.7940.3> (10.0.11.58:44020 -> 10.0.7.96:5672, vhost: '/', user: 'rmquser'):
client unexpectedly closed TCP connection
2018-05-11 15:25:22.186 [error] <0.8801.3> ** Generic server <0.8801.3> terminating
** Last message in was {'$gen_cast',{method,{'queue.bind',0,<<"rmq-objc-client.gen-39D66FC8-1992-45D9-85C1-42837DAD9DC8-3619-0000034A11A28811">>,<<"anexchange">>,<<"#.item_9796">>,false,[]},none,noflow}}
** When Server state == {ch,running,rabbit_framing_amqp_0_9_1,1,<0.7940.3>,<0.8799.3>,<0.7940.3>,<<"10.0.11.58:44020 -> 10.0.7.96:5672">>,{lstate,<0.8800.3>,false},none,1,{[],[]},{user,<<"rmquser">>,[],[{rabbit_auth_backend_internal,none}]},<<"/">>,<<"rmq-objc-client.gen-39D66FC8-1992-45D9-85C1-42837DAD9DC8-3619-0000034A11A28811">>,#{},{state,{dict,0,16,16,8,80,48,{[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],[]},{{[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],[]}}},erlang},#{},#{},{set,0,16,16,8,80,48,{[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],[]},{{[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],[]}}},<0.8725.3>,{state,fine,5000,#Ref<0.2255695146.891027460.138796>},false,1,{{0,nil},{0,nil}},[],[],{{0,nil},{0,nil}},[{<<"authentication_failure_close">>,bool,true},{<<"basic.nack">>,bool,true},{<<"connection.blocked">>,bool,true},{<<"consumer_cancel_notify">>,bool,true},{<<"exchange_exchange_bindings">>,bool,true},{<<"publisher_confirms">>,bool,true}],none,0,none,flow,[]}

** Reason for termination ==

** {{normal,{gen_server,call,[<0.7940.3>,{info,[amqp_params]},15000]}},[{gen_server,call,3,[{file,"gen_server.erl"},{line,214}]},{rabbit_amqp_connection,amqp_params,2,[{file,"src/rabbit_amqp_connection.erl"},{line,24}]},{rabbit_channel,check_topic_authorisation,5,[{file,"src/rabbit_channel.erl"},{line,850}]},{rabbit_channel,binding_action,9,[{file,"src/rabbit_channel.erl"},{line,1648}]},{rabbit_channel,handle_method,3,[{file,"src/rabbit_channel.erl"},{line,1419}]},{rabbit_channel,handle_cast,2,[{file,"src/rabbit_channel.erl"},{line,523}]},{gen_server2,handle_msg,2,[{file,"src/gen_server2.erl"},{line,1050}]},{proc_lib,wake_up,3,[{file,"proc_lib.erl"},{line,257}]}]}
2018-05-11 15:25:22.186 [error] <0.8801.3> CRASH REPORT Process <0.8801.3> with 0 neighbours exited with reason: {normal,{gen_server,call,[<0.7940.3>,{info,[amqp_params]},15000]}} in gen_server:call/3 line 214 in gen_server2:terminate/3 line 1166
2018-05-11 15:25:22.187 [error] <0.8798.3> Supervisor {<0.8798.3>,rabbit_channel_sup} had child channel started with rabbit_channel:start_link(1, <0.7940.3>, <0.8799.3>, <0.7940.3>, <<"10.0.11.58:44020 -> 10.0.7.96:5672">>, rabbit_framing_amqp_0_9_1, {user,<<"rmquser">>,[],[{rabbit_auth_backend_internal,none}]}, <<"/">>, [{<<"authentication_failure_close">>,bool,true},{<<"basic.nack">>,bool,true},{<<"connection.block...">>,...},...], <0.8725.3>, <0.8800.3>) at <0.8801.3> exit with reason {normal,{gen_server,call,[<0.7940.3>,{info,[amqp_params]},15000]}} in gen_server:call/3 line 214 in context shutdown_error

[Sean Nolan]

Actually, sorry, there's also this separate crash log

2018-05-11 15:25:22 =ERROR REPORT====

** Generic server <0.8801.3> terminating
** Last message in was {'$gen_cast',{method,{'queue.bind',0,<<"rmq-objc-client.gen-39D66FC8-1992-45D9-85C1-42837DAD9DC8-3619-0000034A11A28811">>,<<"anexchange">>,<<"#.item_9796">>,false,[]},none,noflow}}
** When Server state == {ch,running,rabbit_framing_amqp_0_9_1,1,<0.7940.3>,<0.8799.3>,<0.7940.3>,<<"10.0.11.58:44020 -> 10.0.7.96:5672">>,{lstate,<0.8800.3>,false},none,1,{[],[]},{user,<<"rmquser">>,[],[{rabbit_auth_backend_internal,none}]},<<"/">>,<<"rmq-objc-client.gen-39D66FC8-1992-45D9-85C1-42837DAD9DC8-3619-0000034A11A28811">>,#{},{state,{dict,0,16,16,8,80,48,{[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],[]},{{[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],[]}}},erlang},#{},#{},{set,0,16,16,8,80,48,{[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],[]},{{[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],[]}}},<0.8725.3>,{state,fine,5000,#Ref<0.2255695146.891027460.138796>},false,1,{{0,nil},{0,nil}},[],[],{{0,nil},{0,nil}},[{<<"authentication_failure_close">>,bool,true},{<<"basic.nack">>,bool,true},{<<"connection.blocked">>,bool,true},{<<"consumer_cancel_notify">>,bool,true},{<<"exchange_exchange_bindings">>,bool,true},{<<"publisher_confirms">>,bool,true}],none,0,none,flow,[]}
** Reason for termination ==
** {{normal,{gen_server,call,[<0.7940.3>,{info,[amqp_params]},15000]}},[{gen_server,call,3,[{file,"gen_server.erl"},{line,214}]},{rabbit_amqp_connection,amqp_params,2,[{file,"src/rabbit_amqp_connection.erl"},{line,24}]},{rabbit_channel,check_topic_authorisation,5,[{file,"src/rabbit_channel.erl"},{line,850}]},{rabbit_channel,binding_action,9,[{file,"src/rabbit_channel.erl"},{line,1648}]},{rabbit_channel,handle_method,3,[{file,"src/rabbit_channel.erl"},{line,1419}]},{rabbit_channel,handle_cast,2,[{file,"src/rabbit_channel.erl"},{line,523}]},{gen_server2,handle_msg,2,[{file,"src/gen_server2.erl"},{line,1050}]},{proc_lib,wake_up,3,[{file,"proc_lib.erl"},{line,257}]}]}

2018-05-11 15:25:22 =CRASH REPORT====
  crasher:
    initial call: rabbit_channel:init/1
    pid: <0.8801.3>
    registered_name: []
    exception exit: {{{normal,{gen_server,call,[<0.7940.3>,{info,[amqp_params]},15000]}},[{gen_server,call,3,[{file,"gen_server.erl"},{line,214}]},{rabbit_amqp_connection,amqp_params,2,[{file,"src/rabbit_amqp_connection.erl"},{line,24}]},{rabbit_channel,check_topic_authorisation,5,[{file,"src/rabbit_channel.erl"},{line,850}]},{rabbit_channel,binding_action,9,[{file,"src/rabbit_channel.erl"},{line,1648}]},{rabbit_channel,handle_method,3,[{file,"src/rabbit_channel.erl"},{line,1419}]},{rabbit_channel,handle_cast,2,[{file,"src/rabbit_channel.erl"},{line,523}]},{gen_server2,handle_msg,2,[{file,"src/gen_server2.erl"},{line,1050}]},{proc_lib,wake_up,3,[{file,"proc_lib.erl"},{line,257}]}]},[{gen_server2,terminate,3,[{file,"src/gen_server2.erl"},{line,1166}]},{proc_lib,wake_up,3,[{file,"proc_lib.erl"},{line,257}]}]}
    ancestors: [<0.8798.3>,<0.8765.3>,<0.7939.3>,<0.7938.3>,<0.341.0>,<0.340.0>,<0.339.0>,rabbit_sup,<0.218.0>]
    message_queue_len: 1
    messages: [{'EXIT',<0.8798.3>,shutdown}]
    links: []
    dictionary: [{topic_permission_cache,[{{resource,<<"/">>,topic,<<"anexchange">>},#{routing_key => <<"#.item_18239">>,variable_map => #{<<"username">> => <<"rmquser">>,<<"vhost">> => <<"/">>}},read},{{resource,<<"/">>,topic,<<"anexchange">>},#{routing_key => <<"#.item_12558">>,variable_map => #{<<"username">> => <<"rmquser">>,<<"vhost">> => <<"/">>}},read},{{resource,<<"/">>,topic,<<"anexchange">>},#{routing_key => <<"#.item_7643">>,variable_map => #{<<"username">> => <<"rmquser">>,<<"vhost">> => <<"/">>}},read}]},{process_name,{rabbit_channel,{<<"10.0.11.58:44020 -> 10.0.7.96:5672">>,1}}},{channel_operation_timeout,15000},{permission_cache,[{{resource,<<"/">>,exchange,<<"anexchange">>},read},{{resource,<<"/">>,queue,<<"rmq-objc-client.gen-39D66FC8-1992-45D9-85C1-42837DAD9DC8-3619-0000034A11A28811">>},write},{{resource,<<"/">>,queue,<<"rmq-objc-client.gen-39D66FC8-1992-45D9-85C1-42837DAD9DC8-3619-0000034A11A28811">>},configure}]},{{xtype_to_module,topic},rabbit_exchange_type_topic},{rand_seed,{#{jump => #Fun<rand.16.15449617>,max => 288230376151711743,next => #Fun<rand.15.15449617>,type => exsplus},[32595977238789278|255688937109202618]}}]
    trap_exit: true
    status: running
    heap_size: 4185
    stack_size: 27
    reductions: 5737
  neighbours:
2018-05-11 15:25:22 =SUPERVISOR REPORT====
     Supervisor: {<0.8798.3>,rabbit_channel_sup}
     Context:    shutdown_error
     Reason:     {{normal,{gen_server,call,[<0.7940.3>,{info,[amqp_params]},15000]}},[{gen_server,call,3,[{file,"gen_server.erl"},{line,214}]},{rabbit_amqp_connection,amqp_params,2,[{file,"src/rabbit_amqp_connection.erl"},{line,24}]},{rabbit_channel,check_topic_authorisation,5,[{file,"src/rabbit_channel.erl"},{line,850}]},{rabbit_channel,binding_action,9,[{file,"src/rabbit_channel.erl"},{line,1648}]},{rabbit_channel,handle_method,3,[{file,"src/rabbit_channel.erl"},{line,1419}]},{rabbit_channel,handle_cast,2,[{file,"src/rabbit_channel.erl"},{line,523}]},{gen_server2,handle_msg,2,[{file,"src/gen_server2.erl"},{line,1050}]},{proc_lib,wake_up,3,[{file,"proc_lib.erl"},{line,257}]}]}
     Offender:   [{pid,<0.8801.3>},{name,channel},{mfargs,{rabbit_channel,start_link,[1,<0.7940.3>,<0.8799.3>,<0.7940.3>,<<"10.0.11.58:44020 -> 10.0.7.96:5672">>,rabbit_framing_amqp_0_9_1,{user,<<"rmquser">>,[],[{rabbit_auth_backend_internal,none}]},<<"/">>,[{<<"authentication_failure_close">>,bool,true},{<<"basic.nack">>,bool,true},{<<"connection.blocked">>,bool,true},{<<"consumer_cancel_notify">>,bool,true},{<<"exchange_exchange_bindings">>,bool,true},{<<"publisher_confirms">>,bool,true}],<0.8725.3>,<0.8800.3>]}},{restart_type,intrinsic},{shutdown,70000},{child_type,worker}]

On Friday, May 11, 2018 at 10:58:09 AM UTC-5, Sean Nolan wrote:

Here's everything I could find for a connection that crashed

2018-05-11 15:25:17.178 [info] <0.7940.3> accepting AMQP connection <0.7940.3> (10.0.11.58:44020 -> 10.0.7.96:5672)
2018-05-11 15:25:18.123 [info] <0.7940.3> connection <0.7940.3> (10.0.11.58:44020 -> 10.0.7.96:5672): user 'rmquser' authenticated and granted access to vhost '/'
2018-05-11 15:25:22.186 [warning] <0.7940.3> closing AMQP connection <0.7940.3> (10.0.11.58:44020 -> 10.0.7.96:5672, vhost: '/', user: 'rmquser'):
client unexpectedly closed TCP connection
2018-05-11 15:25:22.186 [error] <0.8801.3> ** Generic server <0.8801.3> terminating
** Last message in was {'$gen_cast',{method,{'queue.bind',0,<<"rmq-objc-client.gen-39D66FC8-1992-45D9-85C1-42837DAD9DC8-3619-0000034A11A28811">>,<<"anexchange">>,<<"#.item_9796">>,false,[]},none,noflow}}
** When Server state == {ch,running,rabbit_framing_amqp_0_9_1,1,<0.7940.3>,<0.8799.3>,<0.7940.3>,<<"10.0.11.58:44020 -> 10.0.7.96:5672">>,{lstate,<0.8800.3>,false},none,1,{[],[]},{user,<<"rmquser">>,[],[{rabbit_auth_backend_internal,none}]},<<"/">>,<<"rmq-objc-client.gen-39D66FC8-1992-45D9-85C1-42837DAD9DC8-3619-0000034A11A28811">>,#{},{state,{dict,0,16,16,8,80,48,{[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],[]},{{[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],[]}}},erlang},#{},#{},{set,0,16,16,8,80,48,{[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],[]},{{[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],[]}}},<0.8725.3>,{state,fine,5000,#Ref<0.2255695146.891027460.138796>},false,1,{{0,nil},{0,nil}},[],[],{{0,nil},{0,nil}},[{<<"authentication_failure_close">>,bool,true},{<<"basic.nack">>,bool,true},{<<"connection.blocked">>,bool,true},{<<"consumer_cancel_notify">>,bool,true},{<<"exchange_exchange_bindings">>,bool,true},{<<"publisher_confirms">>,bool,true}],none,0,none,flow,[]}
** Reason for termination ==
** {{normal,{gen_server,call,[<0.7940.3>,{info,[amqp_params]},15000]}},[{gen_server,call,3,[{file,"gen_server.erl"},{line,214}]},{rabbit_amqp_connection,amqp_params,2,[{file,"src/rabbit_amqp_connection.erl"},{line,24}]},{rabbit_channel,check_topic_authorisation,5,[{file,"src/rabbit_channel.erl"},{line,850}]},{rabbit_channel,binding_action,9,[{file,"src/rabbit_channel.erl"},{line,1648}]},{rabbit_channel,handle_method,3,[{file,"src/rabbit_channel.erl"},{line,1419}]},{rabbit_channel,handle_cast,2,[{file,"src/rabbit_channel.erl"},{line,523}]},{gen_server2,handle_msg,2,[{file,"src/gen_server2.erl"},{line,1050}]},{proc_lib,wake_up,3,[{file,"proc_lib.erl"},{line,257}]}]}
2018-05-11 15:25:22.186 [error] <0.8801.3> CRASH REPORT Process <0.8801.3> with 0 neighbours exited with reason: {normal,{gen_server,call,[<0.7940.3>,{info,[amqp_params]},15000]}} in gen_server:call/3 line 214 in gen_server2:terminate/3 line 1166

2018-05-11 15:25:22.187 [error] <0.8798.3> Supervisor {<0.8798.3>,rabbit_channel_sup} had child channel started with rabbit_channel:start_link(1, <0.7940.3>, <0.8799.3>, <0.7940.3>, <<"10.0.11.58:44020 -> 10.0.7.96:5672">>, rabbit_framing_amqp_0_9_1, {user,<<"rmquser">>,[],[{rabbit_auth_backend_internal,none}]}, <<"/">>, [{<<"authentication_failure_close">>,bool,true},{<<"basic.nack">>,bool,true},{<<"connection.block...">>,...},...], <0.8725.3>, <0.8800.3>) at <<span style="color: #066;" class=

[Michael Klishin]

Thank you, so the connection wasn't closed cleanly. I don't know why I haven't been able to reproduce this but it should be something

fairly trivial. Thanks for the details.

--

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.

[Luke Bakken]

Hello,

Please test the upcoming RabbitMQ 3.7.13 release candidates which contain a fix for the issue you report:

https://github.com/rabbitmq/rabbitmq-server/pull/1886

If you are using topic exchanges you are probably experiencing this issue.

Thanks,

Luke

[Luke Bakken]

FTR, a beta build is available from [1] and [2]. Note that the apt repo also includes up to 3 most recent alpha builds, so version pinning is probably a good idea.

1. https://bintray.com/beta/#/rabbitmq/all-prereleases/rabbitmq-server/3.7.13-beta.1?tab=overview

2. https://bintray.com/beta/#/rabbitmq/debian-prereleases/rabbitmq-server/3.7.13~beta.1-1?tab=overview