[rabbitmq-discuss] RabbitMQ very slow (or never) shuts down
Matt Pietrek
mpietrek at skytap.com
Thu Sep 13 21:05:45 BST 2012
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.comA">>,
{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
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.rabbitmq.com/pipermail/rabbitmq-discuss/attachments/20120913/480453f5/attachment.htm>
More information about the rabbitmq-discuss
mailing list