[rabbitmq-discuss] Understanding a crash report

Simone s.sciarrati at gmail.com
Tue Feb 19 12:02:52 GMT 2013


Hi,

I am relatively new to Rabbitmq and would appreciate help in 
troubleshooting a recurring issue on a cluster, apologies for the long 
email.

I run a 3 instances cluster in ec2, 2 disk nodes (A and B) 1 ram node (C), 
exchanges and queues are static and limited in number (less than 50), the 
volume of messages can reach a few thousands per second and the queues can 
occasionally grow up to a few hundred thousands until the processes manage 
to catch up, but this is well within our memory/disk high watermark. 
Rabbitmq is v. 2.8.4 on ubuntu 12.

The processes that produce and consume messages are java/scala and use the 
akka-amqp library driver (akka-amqp-1.3.1).

In normal operations our nodes run on ~ 500MB memory, the limit is set to 
2.7GB, but in a couple occasions one of the nodes managed to very rapidly 
(< 1 min) eat > 1GB memory and triggered the high memory watermark (node B, 
one of the disk nodes last time).

At the moment of the issue most of the memory was held in 'processes', no 
queue was overgrown (messages or memory), I managed to run a rabbitmqctl 
report, I found a crash report in the logs (more on this later) and tried 
to see which process/es was responsible for the memory usage from the 
erlang shell but I wasn't able to pin a specific one (my erlang is limited 
and I didn't dump the processes to file to look at it later unfortunately). 

For every issue we have had (3 in 2 months), the logs show a crash report 
relative to a specific java process (say process D) sending a message to a 
specific queue (queue D - this is a queue with no consumers atm, if the app 
fails to process a message it will end up here). Note that there are 
multiple workers D running on separate instances in ec2 and that queue D is 
very low traffic so it is unlikely to be a coincidence.

At this point I was pressured to restart rmq on the affected node B, this 
was a stop_app, then stop the erlang VM and then restart. All looked good, 
the node was in a nice place and all looked green in the management 
console. 

Our java processes would connect, they'd do some work, but after a while 
they'd throw a connection error (sorry this is all the details the logs 
would show). Specifically a process E was connected to node A and would 
show this random behaviour (different process and different rmq node from 
the two involved in the issue). 
After a while I was forced to restart the whole cluster, this was done 
stopping app on the ram node C, then on the disk node B, then the other 
node A. Unfortunately A seemed to hang and failed to stop within a 
reasonable time (minutes), and I had to kill it (kill -15). I didn't see 
any indication in the logs on why it was hanging.

When I attempted to start A it would fail as the port was already in use 
and I found that a process still had an open connection to port 5672:

tcp6       0 164945 10.xx.xx.xx:5672        10.xx.xx.xx:53712      FIN_WAIT1

Note: This is a worker D but running on a different box from the one showed 
in the crash log.

Once this connection was cleared everything came up nice and happy.

In Summary:

Process D was producing on queue D on node B, something happened and node B 
managed to consume > 1GB memory in less than a minute. Note that this queue 
is really low traffic but in every issue I have looked into I can see a 
similar crash report as below.

After a restart of node B other processes connected to node A started 
exhibiting connection issues, work a bit then break the connection until 
the whole cluster is restarted.

I would like to better understand the crash report and perhaps have some 
ideas on what went wrong and how to more effectively troubleshoot issues 
(what more info should I collect before restarting the nodes, erlang 
processes list, mnesia tables, ets tables etc).


=CRASH REPORT==== 14-Feb-2013::10:36:54 ===
  crasher:
    initial call: rabbit_reader:init/4
    pid: <*0.29283.387*>
    registered_name: []
    exception error: bad argument
      in function  port_close/1
         called as port_close(#Port<0.746540>)
      in call from rabbit_net:maybe_fast_close/1
      in call from rabbit_reader:start_connection/7
    ancestors: [<0.29280.387>,rabbit_tcp_client_sup,rabbit_sup,<0.161.0>]
    messages: []
    links: [<0.29280.387>]
    dictionary: [{{channel,10},
                   {<0.29364.387>,{method,rabbit_framing_amqp_0_9_1}}},
                  {{ch_pid,<0.29338.387>},{7,#Ref<0.0.2158.60093>}},
                  {{ch_pid,<0.29333.387>},{6,#Ref<0.0.2158.60085>}},
                  {{ch_pid,<0.29325.387>},{5,#Ref<0.0.2158.60053>}},
                  {{channel,3},
                   {<0.29313.387>,{method,rabbit_framing_amqp_0_9_1}}},
                  {{ch_pid,<0.29305.387>},{2,#Ref<0.0.2158.60002>}},
                  {{channel,4},
                   {<0.29321.387>,{method,rabbit_framing_amqp_0_9_1}}},
                  {{channel,11},
                   {<0.29370.387>,{method,rabbit_framing_amqp_0_9_1}}},
                  {{ch_pid,<0.29313.387>},{3,#Ref<0.0.2158.60017>}},
                  {{ch_pid,<0.29299.387>},{1,#Ref<0.0.2158.59976>}},
                  {{ch_pid,<0.29346.387>},{8,#Ref<0.0.2158.60112>}},
                  {{ch_pid,<0.29370.387>},{11,#Ref<0.0.2158.60189>}},
                  {{channel,7},
                   {<0.29338.387>,{method,rabbit_framing_amqp_0_9_1}}},
                  {{channel,9},
                   {<0.29356.387>,{method,rabbit_framing_amqp_0_9_1}}},
                  {{ch_pid,<0.29321.387>},{4,#Ref<0.0.2158.60034>}},
                  {{ch_pid,<0.29364.387>},{10,#Ref<0.0.2158.60166>}},
                  {{ch_pid,<0.29356.387>},{9,#Ref<0.0.2158.60140>}},
                  {{channel,8},
                   {<0.29346.387>,{method,rabbit_framing_amqp_0_9_1}}},
                  {{channel,5},
                   {<0.29325.387>,{method,rabbit_framing_amqp_0_9_1}}},
                  {{channel,1},
                   {<0.29299.387>,
                    {content_body,
                        {'basic.publish',0,<<"some_exchange">>,<<>>,false,
                            false},
                        1048189,
                        {content,60,none,
                            <<BYTES IN HERE>>,   --> this showed which 
process was sending the message
                            rabbit_framing_amqp_0_9_1,
                            [<<MORE BYTES IN HERE>>]  --> This I haven't 
been able to decode, it is fairly big, is it truncated?


And in the logs we can find the pid *0.29283.387 *right before the crash:

=INFO REPORT==== 14-Feb-2013::10:31:46 ===
accepting AMQP connection <*0.29283.387*> (10.xx.xx.xx:58622 -> 10.xx.xx.xx
:5672)

=INFO REPORT==== 14-Feb-2013::10:31:46 ===
accepting AMQP connection <0.29287.387> (10.xx.xx.xx:58623 -> 10.xx.xx.xx
:5672)

=WARNING REPORT==== 14-Feb-2013::10:32:27 ===
closing AMQP connection <0.27107.387> (10.xx.xx.xx:50882 -> 10.xx.xx.xx
:5672):
connection_closed_abruptly

=WARNING REPORT==== 14-Feb-2013::10:32:27 ===
closing AMQP connection <0.27111.387> (10.xx.xx.xx:50883 -> 10.xx.xx.xx
:5672):
connection_closed_abruptly

=INFO REPORT==== 14-Feb-2013::10:33:35 ===
accepting AMQP connection <0.30447.387> (10.xx.xx.xx:50187 -> 10.xx.xx.xx
:5672)

=INFO REPORT==== 14-Feb-2013::10:33:35 ===
accepting AMQP connection <0.30451.387> (10.xx.xx.xx:50188 -> 10.xx.xx.xx
:5672)

=WARNING REPORT==== 14-Feb-2013::10:37:34 ===
closing AMQP connection <*0.29283.387*> (10.xx.xx.xx:58622 -> 10.xx.xx.xx
:5672):
connection_closed_abruptly

=WARNING REPORT==== 14-Feb-2013::10:37:34 ===
closing AMQP connection <0.29287.387> (10.xx.xx.xx:58623 -> 10.xx.xx.xx
:5672):
connection_closed_abruptly

=WARNING REPORT==== 14-Feb-2013::10:37:34 ===
closing AMQP connection <0.30451.387> (10.xx.xx.xx:50188 -> 10.xx.xx.xx
:5672):
connection_closed_abruptly

=WARNING REPORT==== 14-Feb-2013::10:37:34 ===
closing AMQP connection <0.30447.387> (10.xx.xx.xx:50187 -> 10.xx.xx.xx
:5672):
connection_closed_abruptly

=INFO REPORT==== 14-Feb-2013::10:37:34 ===
vm_memory_high_watermark set. Memory used:3384669192 allowed:2914218803

Looking at the rabbitmqctl report I have not been able to map the memory 
consumption to something specific yet.

Any help appreciated,

S

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.rabbitmq.com/pipermail/rabbitmq-discuss/attachments/20130219/fea3fdeb/attachment.htm>


More information about the rabbitmq-discuss mailing list