[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