[rabbitmq-discuss] RabbitMQ very slow (or never) shuts down
Tim Watson
tim at rabbitmq.com
Wed Sep 19 09:37:43 BST 2012
Hi Matt,
Just to keep you up to date - we're still investigating this. I will reply here once we've got to the bottom of it.
Cheers,
Tim
On 13 Sep 2012, at 21:05, Matt Pietrek wrote:
> Here you to Tim:
>
> The scrubbed rabbit at mq1.log:
> --------
> =INFO REPORT==== 13-Sep-2012::12:00:21 ===
> application: rabbitmq_management
> exited: stopped
> type: permanent
>
> =INFO REPORT==== 13-Sep-2012::12:00:21 ===
> application: rabbitmq_federation
> exited: stopped
> type: permanent
>
> =INFO REPORT==== 13-Sep-2012::12:00:21 ===
> Stopping Rabbit
>
> =INFO REPORT==== 13-Sep-2012::12:00:21 ===
> application: rabbitmq_management_agent
> exited: stopped
> type: permanent
>
> =WARNING REPORT==== 13-Sep-2012::12:00:21 ===
> Connection (<0.1659.0>) closing: internal error in channel (<0.1666.0>): shutdown
>
> =INFO REPORT==== 13-Sep-2012::12:00:21 ===
> stopped TCP Listener on 0.0.0.0:5672
>
> =ERROR REPORT==== 13-Sep-2012::12:17:00 ===
> ** Generic server <0.1676.0> terminating
> ** Last message in was {inet_async,#Port<0.5748>,5106,{error,etimedout}}
> ** When Server state == {state,#Port<0.5748>,<0.1671.0>,<0.1673.0>,
> {method,rabbit_framing_amqp_0_9_1},
> none}
> ** Reason for termination ==
> ** {socket_error,etimedout}
>
> =ERROR REPORT==== 13-Sep-2012::12:17:00 ===
> ** Generic server <0.1671.0> terminating
> ** Last message in was {socket_error,etimedout}
> ** When Server state == {state,amqp_network_connection,
> {state,#Port<0.5748>,0,<0.1675.0>,131072,
> undefined,false},
> <0.1670.0>,<0.1673.0>,
> {amqp_params_network,<<"guest">>,<<"guest">>,
> <<"/">>,"slg1matt1.xyz.com",
> 5672,0,0,0,infinity,none,
> [#Fun<amqp_auth_mechanisms.plain.3>,
> #Fun<amqp_auth_mechanisms.amqplain.3>],
> [],[]},
> 0,
> [{<<"capabilities">>,table,
> [{<<"publisher_confirms">>,bool,true},
> {<<"exchange_exchange_bindings">>,bool,true},
> {<<"basic.nack">>,bool,true},
> {<<"consumer_cancel_notify">>,bool,true}]},
> {<<"copyright">>,longstr,
> <<"Copyright (C) 2007-2012 VMware, Inc.">>},
> {<<"information">>,longstr,
> <<"Licensed under the MPL. See http://www.rabbitmq.com/">>},
> {<<"platform">>,longstr,<<"Erlang/OTP">>},
> {<<"product">>,longstr,<<"RabbitMQ">>},
> {<<"version">>,longstr,<<"2.8.6">>}],
> #Fun<amqp_connection_sup.0.39273983>,
> #Fun<amqp_connection_sup.2.54430129>,false}
> ** Reason for termination ==
> ** {socket_error,etimedout}
>
> =ERROR REPORT==== 13-Sep-2012::12:17:00 ===
> ** Generic server <0.1657.0> terminating
> ** Last message in was {'EXIT',<0.197.0>,shutdown}
> ** When Server state == {state,
> {upstream,
> {amqp_params_network,<<"guest">>,<<"guest">>,
> <<"/">>,"slg1matt1.xyz.com",5672,0,
> 0,0,infinity,none,
> [#Fun<amqp_auth_mechanisms.plain.3>,
> #Fun<amqp_auth_mechanisms.amqplain.3>],
> [],[]},
> <<"skytap">>,1000,1,1,none,none,none,"upstream-slg"},
> <0.1671.0>,<0.1683.0>,
> <<"federation: skytap -> rabbit at mq1.matt.xyz.com">>,
> <<"federation: skytap -> rabbit at mq1.matt.xyz.com A">>,
> {0,nil},
> 115,
> {dict,10,16,16,8,80,48,
> {[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],[]},
> {{[],
> [[{<<"charon.us-east.default">>,[]}|
> {set,1,16,16,8,80,48,
> {[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],
> []},
> {{[],[],[],[],[],[],[],[],[],[],[],[],
> [{resource,<<"/">>,exchange,
> <<"federation: skytap -> rabbit at slg1matt1.xyz.com A">>}],
> [],[],[]}}}]],
> [],
> [[{<<"cmcmd.us-east.default">>,[]}|
> {set,1,16,16,8,80,48,
> {[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],
> []},
> {{[],[],[],[],[],[],[],[],[],[],[],[],
> [{resource,<<"/">>,exchange,
> <<"federation: skytap -> rabbit at slg1matt1.xyz.com A">>}],
> [],[],[]}}}],
> [{<<"charon.us-west.default">>,[]}|
> {set,2,16,16,8,80,48,
> {[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],
> []},
> {{[],[],[],
> [{resource,<<"/">>,queue,<<"charon">>}],
> [],[],[],[],[],[],[],[],
> [{resource,<<"/">>,exchange,
> <<"federation: skytap -> rabbit at slg1matt1.xyz.com A">>}],
> [],[],[]}}}]],
> [],
> [[{<<"cmcmd.us-west.default">>,[]}|
> {set,2,16,16,8,80,48,
> {[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],
> []},
> {{[],[],[],[],[],
> [{resource,<<"/">>,queue,<<"cmcmd">>}],
> [],[],[],[],[],[],
> [{resource,<<"/">>,exchange,
> <<"federation: skytap -> rabbit at slg1matt1.xyz.com A">>}],
> [],[],[]}}}]],
> [],
> [[{<<"system_test.us-east.default">>,[]}|
> {set,1,16,16,8,80,48,
> {[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],
> []},
> {{[],[],[],[],[],[],[],[],[],[],[],[],
> [{resource,<<"/">>,exchange,
> <<"federation: skytap -> rabbit at slg1matt1.xyz.com A">>}],
> [],[],[]}}}]],
> [],
> [[{<<"system_test.us-west.default">>,[]}|
> {set,2,16,16,8,80,48,
> {[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],
> []},
> {{[],
> [{resource,<<"/">>,queue,<<"system_test">>}],
> [],[],[],[],[],[],[],[],[],[],
> [{resource,<<"/">>,exchange,
> <<"federation: skytap -> rabbit at slg1matt1.xyz.com A">>}],
> [],[],[]}}}]],
> [],[],
> [[{<<"unit_test.us-east.default">>,[]}|
> {set,1,16,16,8,80,48,
> {[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],
> []},
> {{[],[],[],[],[],[],[],[],[],[],[],[],
> [{resource,<<"/">>,exchange,
> <<"federation: skytap -> rabbit at slg1matt1.xyz.com A">>}],
> [],[],[]}}}]],
> [[{<<"ConfigurationManager.us-east.default">>,
> []}|
> {set,1,16,16,8,80,48,
> {[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],
> []},
> {{[],[],[],[],[],[],[],[],[],[],[],[],
> [{resource,<<"/">>,exchange,
> <<"federation: skytap -> rabbit at slg1matt1.xyz.com A">>}],
> [],[],[]}}}]],
> [[{<<"unit_test.us-west.default">>,[]}|
> {set,2,16,16,8,80,48,
> {[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],
> []},
> {{[],[],[],[],[],[],[],[],
> [{resource,<<"/">>,queue,<<"unit_test">>}],
> [],[],[],
> [{resource,<<"/">>,exchange,
> <<"federation: skytap -> rabbit at slg1matt1.xyz.com A">>}],
> [],[],[]}}}]],
> [[{<<"ConfigurationManager.us-west.default">>,
> []}|
> {set,2,16,16,8,80,48,
> {[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],
> []},
> {{[],[],[],[],[],[],[],
> [{resource,<<"/">>,queue,
> <<"ConfigurationManager">>}],
> [],[],[],[],
> [{resource,<<"/">>,exchange,
> <<"federation: skytap -> rabbit at slg1matt1.xyz.com A">>}],
> [],[],[]}}}]]}}},
> <0.1659.0>,<0.1666.0>,
> {resource,<<"/">>,exchange,<<"skytap">>},
> {0,nil}}
> ** Reason for termination ==
> ** {undef,
> [{rabbit_federation_old_status,report,
> [{upstream,
> {amqp_params_network,<<"guest">>,<<"guest">>,<<"/">>,
> "slg1matt1.xyz.com",5672,0,0,0,infinity,
> none,
> [#Fun<amqp_auth_mechanisms.plain.3>,
> #Fun<amqp_auth_mechanisms.amqplain.3>],
> [],[]},
> <<"skytap">>,1000,1,1,none,none,none,"upstream-slg"},
> {resource,<<"/">>,exchange,<<"skytap">>},
> shutdown],
> []},
> {rabbit_federation_link,terminate,2,[]},
> {gen_server2,terminate,3,[]},
> {proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,227}]}]}
> ** In 'terminate' callback with reason ==
> ** shutdown
>
> =INFO REPORT==== 13-Sep-2012::12:17:00 ===
> application: rabbit
> exited: stopped
> type: permanent
>
> =INFO REPORT==== 13-Sep-2012::12:17:00 ===
> application: os_mon
> exited: stopped
> type: permanent
>
> =INFO REPORT==== 13-Sep-2012::12:17:00 ===
> application: mnesia
> exited: stopped
> type: permanent
>
> =INFO REPORT==== 13-Sep-2012::12:17:00 ===
> Halting Erlang VM
> --------
>
> And the scrubbed rabbit at mq1-sasl.log:
>
> --------
> =SUPERVISOR REPORT==== 13-Sep-2012::12:00:21 ===
> Supervisor: {<0.1664.0>,amqp_channel_sup}
> Context: child_terminated
> Reason: shutdown
> Offender: [{pid,<0.1666.0>},
> {name,channel},
> {mfa,{amqp_channel,start_link,
> [direct,<0.1659.0>,1,<0.1665.0>,
> #Fun<amqp_channel_sup.0.24953263>]}},
> {restart_type,intrinsic},
> {shutdown,4294967295},
> {child_type,worker}]
>
>
> =SUPERVISOR REPORT==== 13-Sep-2012::12:00:21 ===
> Supervisor: {<0.1664.0>,amqp_channel_sup}
> Context: shutdown
> Reason: reached_max_restart_intensity
> Offender: [{pid,<0.1666.0>},
> {name,channel},
> {mfa,{amqp_channel,start_link,
> [direct,<0.1659.0>,1,<0.1665.0>,
> #Fun<amqp_channel_sup.0.24953263>]}},
> {restart_type,intrinsic},
> {shutdown,4294967295},
> {child_type,worker}]
>
>
> =CRASH REPORT==== 13-Sep-2012::12:17:00 ===
> crasher:
> initial call: amqp_main_reader:init/1
> pid: <0.1676.0>
> registered_name: []
> exception exit: {socket_error,etimedout}
> in function gen_server:terminate/6 (gen_server.erl, line 747)
> ancestors: [<0.1674.0>,<0.1670.0>,amqp_sup,<0.240.0>]
> messages: []
> links: [<0.1674.0>]
> dictionary: []
> trap_exit: false
> status: running
> heap_size: 2584
> stack_size: 24
> reductions: 2529
> neighbours:
>
> =CRASH REPORT==== 13-Sep-2012::12:17:00 ===
> crasher:
> initial call: amqp_gen_connection:init/1
> pid: <0.1671.0>
> registered_name: []
> exception exit: {socket_error,etimedout}
> in function gen_server:terminate/6 (gen_server.erl, line 747)
> ancestors: [<0.1670.0>,amqp_sup,<0.240.0>]
> messages: []
> links: [<0.1670.0>,#Port<0.5748>]
> dictionary: []
> trap_exit: false
> status: running
> heap_size: 1597
> stack_size: 24
> reductions: 805
> neighbours:
>
> =SUPERVISOR REPORT==== 13-Sep-2012::12:17:00 ===
> Supervisor: {<0.1670.0>,amqp_connection_sup}
> Context: child_terminated
> Reason: {socket_error,etimedout}
> Offender: [{pid,<0.1671.0>},
> {name,connection},
> {mfa,
> {amqp_gen_connection,start_link,
> [amqp_network_connection,
> {amqp_params_network,<<"guest">>,<<"guest">>,
> <<"/">>,"slg1matt1.xyz.com",
> 5672,0,0,0,infinity,none,
> [#Fun<amqp_auth_mechanisms.plain.3>,
> #Fun<amqp_auth_mechanisms.amqplain.3>],
> [],[]},
> #Fun<amqp_connection_sup.0.39273983>,
> #Fun<amqp_connection_sup.2.54430129>,[]]}},
> {restart_type,intrinsic},
> {shutdown,brutal_kill},
> {child_type,worker}]
>
>
> =SUPERVISOR REPORT==== 13-Sep-2012::12:17:00 ===
> Supervisor: {<0.1670.0>,amqp_connection_sup}
> Context: shutdown
> Reason: reached_max_restart_intensity
> Offender: [{pid,<0.1671.0>},
> {name,connection},
> {mfa,
> {amqp_gen_connection,start_link,
> [amqp_network_connection,
> {amqp_params_network,<<"guest">>,<<"guest">>,
> <<"/">>,"slg1matt1.xyz.com",
> 5672,0,0,0,infinity,none,
> [#Fun<amqp_auth_mechanisms.plain.3>,
> #Fun<amqp_auth_mechanisms.amqplain.3>],
> [],[]},
> #Fun<amqp_connection_sup.0.39273983>,
> #Fun<amqp_connection_sup.2.54430129>,[]]}},
> {restart_type,intrinsic},
> {shutdown,brutal_kill},
> {child_type,worker}]
>
>
> =SUPERVISOR REPORT==== 13-Sep-2012::12:17:00 ===
> Supervisor: {<0.1674.0>,
> amqp_connection_type_sup}
> Context: child_terminated
> Reason: {socket_error,etimedout}
> Offender: [{pid,<0.1676.0>},
> {name,main_reader},
> {mfa,
> {amqp_main_reader,start_link,
> [#Port<0.5748>,<0.1671.0>,<0.1673.0>,
> {method,rabbit_framing_amqp_0_9_1}]}},
> {restart_type,transient},
> {shutdown,4294967295},
> {child_type,worker}]
>
>
> =SUPERVISOR REPORT==== 13-Sep-2012::12:17:00 ===
> Supervisor: {<0.1674.0>,
> amqp_connection_type_sup}
> Context: shutdown
> Reason: reached_max_restart_intensity
> Offender: [{pid,<0.1676.0>},
> {name,main_reader},
> {mfa,
> {amqp_main_reader,start_link,
> [#Port<0.5748>,<0.1671.0>,<0.1673.0>,
> {method,rabbit_framing_amqp_0_9_1}]}},
> {restart_type,transient},
> {shutdown,4294967295},
> {child_type,worker}]
>
>
> =CRASH REPORT==== 13-Sep-2012::12:17:00 ===
> crasher:
> initial call: gen:init_it/6
> pid: <0.1657.0>
> registered_name: []
> exception exit: {undef,
> [{rabbit_federation_old_status,report,
> [{upstream,
> {amqp_params_network,<<"guest">>,
> <<"guest">>,<<"/">>,
> "slg1matt1.xyz.com",
> 5672,0,0,0,infinity,none,
> [#Fun<amqp_auth_mechanisms.plain.3>,
> #Fun<amqp_auth_mechanisms.amqplain.3>],
> [],[]},
> <<"skytap">>,1000,1,1,none,none,none,
> "upstream-slg"},
> {resource,<<"/">>,exchange,<<"skytap">>},
> shutdown],
> []},
> {rabbit_federation_link,terminate,2,[]},
> {gen_server2,terminate,3,[]},
> {proc_lib,init_p_do_apply,3,
> [{file,"proc_lib.erl"},{line,227}]}]}
> in function gen_server2:terminate/3
> ancestors: [<0.197.0>,<0.194.0>,rabbit_federation_link_sup_sup,
> rabbit_federation_sup,rabbit_sup,<0.143.0>]
> messages: [{'DOWN',#Ref<0.0.0.8909>,process,<0.1683.0>,shutdown}]
> links: []
> dictionary: []
> trap_exit: true
> status: running
> heap_size: 2584
> stack_size: 24
> reductions: 9640
> neighbours:
>
> =SUPERVISOR REPORT==== 13-Sep-2012::12:17:00 ===
> Supervisor: {<0.197.0>,
> rabbit_federation_link_sup}
> Context: shutdown_error
> Reason: {undef,
> [{rabbit_federation_old_status,report,
> [{upstream,
> {amqp_params_network,<<"guest">>,<<"guest">>,
> <<"/">>,
> "slg1matt1.xyz.com",5672,0,
> 0,0,infinity,none,
> [#Fun<amqp_auth_mechanisms.plain.3>,
> #Fun<amqp_auth_mechanisms.amqplain.3>],
> [],[]},
> <<"skytap">>,1000,1,1,none,none,none,
> "upstream-slg"},
> {resource,<<"/">>,exchange,<<"skytap">>},
> shutdown],
> []},
> {rabbit_federation_link,terminate,2,[]},
> {gen_server2,terminate,3,[]},
> {proc_lib,init_p_do_apply,3,
> [{file,"proc_lib.erl"},{line,227}]}]}
> Offender: [{pid,<0.1657.0>},
> {name,
> {upstream,
> {amqp_params_network,<<"guest">>,<<"guest">>,
> <<"/">>,"slg1matt1.xyz.com",
> 5672,0,0,0,infinity,none,
> [#Fun<amqp_auth_mechanisms.plain.3>,
> #Fun<amqp_auth_mechanisms.amqplain.3>],
> [],[]},
> <<"skytap">>,1000,1,1,none,none,none,
> "upstream-slg"}},
> {mfa,
> {rabbit_federation_link,start_link,
> [{{upstream,
> {amqp_params_network,<<"guest">>,<<"guest">>,
> <<"/">>,
> "slg1matt1.xyz.com",5672,
> 0,0,0,infinity,none,
> [#Fun<amqp_auth_mechanisms.plain.3>,
> #Fun<amqp_auth_mechanisms.amqplain.3>],
> [],[]},
> <<"skytap">>,1000,1,1,none,none,none,
> "upstream-slg"},
> {resource,<<"/">>,exchange,<<"skytap">>}}]}},
> {restart_type,{permanent,1}},
> {shutdown,4294967295},
> {child_type,worker}]
>
> --------
>
> On Thu, Sep 13, 2012 at 12:30 PM, Tim Watson <tim at rabbitmq.com> wrote:
>
> On 13 Sep 2012, at 20:26, Matt Pietrek wrote:
>
> > We "own" the network in that it's a direct connection between two datacenters. It's not a particularly high speed connection, but it's generally reliable. I've done some ping tests between the two nodes and while an occasional packet will drop every once in awhile, it's not a really horrible connection. The average ping round trip time is areound 80ms.
> >
> > I'd be surprised if it's a dropped packet, as the shutdown on both brokers seems to consistently take a long time. I just reproed this again, and one broker took 1000 seconds to shut down, while the other took 995. I have the logs from this repro, but a quick glance doesn't show anything radically different. Let me know if there's anything else I can supply.
> >
>
> Ok - do send the second pair of logs (or a scrubbed version if you need to hide private data) please, as we're keen to get to the bottom of this.
> _______________________________________________
> rabbitmq-discuss mailing list
> rabbitmq-discuss at lists.rabbitmq.com
> https://lists.rabbitmq.com/cgi-bin/mailman/listinfo/rabbitmq-discuss
>
> _______________________________________________
> rabbitmq-discuss mailing list
> rabbitmq-discuss at lists.rabbitmq.com
> https://lists.rabbitmq.com/cgi-bin/mailman/listinfo/rabbitmq-discuss
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.rabbitmq.com/pipermail/rabbitmq-discuss/attachments/20120919/f14419ad/attachment.htm>
More information about the rabbitmq-discuss
mailing list