[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