rabbitmq crashed due because of `badarg`

[flyer]

Hi,

Recently I encountered a problem that rabbitmq-server crashed. After I read the log of rabbitmq-server, I find those information below. Is message in `bad` format will crash the rabbitmq-server?

Thanks in advance.

=ERROR REPORT==== 26-Jan-2016::23:40:45 ===
** Generic server <0.24742.12> terminating
** Last message in was {'$gen_cast',
                           {command,
                               {'basic.consume_ok',
                                   <<"ctag1.7201627bf21e42a3a0fd1c273a2d5b0d">>}}}
** When Server state == {ch,running,rabbit_framing_amqp_0_9_1,1,<0.24735.12>,
                         <0.24740.12>,<0.24735.12>,
                         <<"172.17.42.1:60612 -> 172.17.0.21:5672">>,
                         {lstate,<0.24741.12>,false},
                         none,1,
                         {[],[]},
                         {user,<<"guest">>,
                          [administrator],
                          [{rabbit_auth_backend_internal,none}]},
                         <<"/">>,<<>>,
                         {dict,1,16,16,8,80,48,
                          {[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],[]},
                          {{[],[],[],[],
                            [[<0.267.0>|
                              {resource,<<"/">>,queue,
                               <<"weini:waiter:account:20">>}]],
                            [],[],[],[],[],[],[],[],[],[],[]}}},
                         {state,
                          {dict,1,16,16,8,80,48,
                           {[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],[]},
                           {{[],[],[],[],
                             [[<0.267.0>|#Ref<0.0.1572866.86673>]],
                             [],[],[],[],[],[],[],[],[],[],[]}}},
                          erlang},
                         {dict,0,16,16,8,80,48,
                          {[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],[]},
                          {{[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],[]}}},
                         {dict,0,16,16,8,80,48,
                          {[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],[]},
                          {{[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],[]}}},
                         {set,1,16,16,8,80,48,
                          {[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],[]},
                          {{[],[],[],[],
                            [<0.267.0>],
                            [],[],[],[],[],[],[],[],[],[],[]}}},
                         <0.24737.12>,
                         {state,fine,5000,#Ref<0.0.1572866.86657>},
                         false,1,
                         {{0,nil},{0,nil}},
                         [],
                         {{0,nil},{0,nil}},
                         [{<<"connection.blocked">>,bool,true},
                          {<<"authentication_failure_close">>,bool,true},
                          {<<"publisher_confirms">>,bool,true},
                          {<<"consumer_cancel_notify">>,bool,true},
                          {<<"basic.nack">>,bool,true}],
                         none,0,none,flow,[]}
** Reason for termination ==
** {badarg,[{dict,fetch,
                  [<<"ctag1.7201627bf21e42a3a0fd1c273a2d5b0d">>,
                   {dict,0,16,16,8,80,48,
                         {[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],[]},
                         {{[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],[]}}}],
                  [{file,"dict.erl"},{line,131}]},
            {rabbit_channel,consumer_monitor,2,
                            [{file,"src/rabbit_channel.erl"},{line,1533}]},
            {rabbit_channel,handle_cast,2,
                            [{file,"src/rabbit_channel.erl"},{line,483}]},
            {gen_server2,handle_msg,2,
                         [{file,"src/gen_server2.erl"},{line,1049}]},
            {proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,240}]}]}

=CRASH REPORT==== 26-Jan-2016::23:40:45 ===
  crasher:
    initial call: gen:init_it/6
    pid: <0.24742.12>
    registered_name: []
    exception exit: {badarg,
                        [{dict,fetch,
                             [<<"ctag1.7201627bf21e42a3a0fd1c273a2d5b0d">>,
                              {dict,0,16,16,8,80,48,
                                  {[],[],[],[],[],[],[],[],[],[],[],[],[],[],
                                   [],[]},
                                  {{[],[],[],[],[],[],[],[],[],[],[],[],[],[],
                                    [],[]}}}],
                             [{file,"dict.erl"},{line,131}]},
                         {rabbit_channel,consumer_monitor,2,
                             [{file,"src/rabbit_channel.erl"},{line,1533}]},
                         {rabbit_channel,handle_cast,2,
                             [{file,"src/rabbit_channel.erl"},{line,483}]},
                         {gen_server2,handle_msg,2,
                             [{file,"src/gen_server2.erl"},{line,1049}]},
                         {proc_lib,init_p_do_apply,3,
                             [{file,"proc_lib.erl"},{line,240}]}]}
      in function  gen_server2:terminate/3 (src/gen_server2.erl, line 1160)
    ancestors: [<0.24739.12>,<0.24738.12>,<0.24734.12>,<0.24733.12>,
                  <0.388.0>,<0.387.0>,<0.386.0>,rabbit_sup,<0.141.0>]
    messages: []
    links: [<0.24739.12>]
    dictionary: [{process_name,
                      {rabbit_channel,
                          {<<"172.17.42.1:60612 -> 172.17.0.21:5672">>,1}}},
                  {permission_cache,
                      [{{resource,<<"/">>,queue,<<"weini:waiter:account:20">>},
                        read}]}]
    trap_exit: true
    status: running
    heap_size: 1598
    stack_size: 27
    reductions: 1565
  neighbours:

=SUPERVISOR REPORT==== 26-Jan-2016::23:40:45 ===
     Supervisor: {<0.24739.12>,rabbit_channel_sup}
     Context:    child_terminated
     Reason:     {badarg,
                     [{dict,fetch,
                          [<<"ctag1.7201627bf21e42a3a0fd1c273a2d5b0d">>,
                           {dict,0,16,16,8,80,48,
                               {[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],
                                []},
                               {{[],[],[],[],[],[],[],[],[],[],[],[],[],[],[],
                                 []}}}],
                          [{file,"dict.erl"},{line,131}]},
                      {rabbit_channel,consumer_monitor,2,
                          [{file,"src/rabbit_channel.erl"},{line,1533}]},
                      {rabbit_channel,handle_cast,2,
                          [{file,"src/rabbit_channel.erl"},{line,483}]},
                      {gen_server2,handle_msg,2,
                          [{file,"src/gen_server2.erl"},{line,1049}]},
                      {proc_lib,init_p_do_apply,3,
                          [{file,"proc_lib.erl"},{line,240}]}]}
     Offender:   [{pid,<0.24742.12>},
                  {name,channel},
                  {mfargs,
                      {rabbit_channel,start_link,
                          [1,<0.24735.12>,<0.24740.12>,<0.24735.12>,
                           <<"172.17.42.1:60612 -> 172.17.0.21:5672">>,
                           rabbit_framing_amqp_0_9_1,
                           {user,<<"guest">>,
                               [administrator],
                               [{rabbit_auth_backend_internal,none}]},
                           <<"/">>,
                           [{<<"connection.blocked">>,bool,true},
                            {<<"authentication_failure_close">>,bool,true},
                            {<<"publisher_confirms">>,bool,true},
                            {<<"consumer_cancel_notify">>,bool,true},
                            {<<"basic.nack">>,bool,true}],
                           <0.24737.12>,<0.24741.12>]}},
                  {restart_type,intrinsic},
                  {shutdown,4294967295},
                  {child_type,worker}]


=SUPERVISOR REPORT==== 26-Jan-2016::23:40:45 ===
     Supervisor: {<0.24739.12>,rabbit_channel_sup}
     Context:    shutdown
     Reason:     reached_max_restart_intensity
     Offender:   [{pid,<0.24742.12>},
                  {name,channel},
                  {mfargs,
                      {rabbit_channel,start_link,
                          [1,<0.24735.12>,<0.24740.12>,<0.24735.12>,
                           <<"172.17.42.1:60612 -> 172.17.0.21:5672">>,
                           rabbit_framing_amqp_0_9_1,
                           {user,<<"guest">>,
                               [administrator],
                               [{rabbit_auth_backend_internal,none}]},
                           <<"/">>,
                           [{<<"connection.blocked">>,bool,true},
                            {<<"authentication_failure_close">>,bool,true},
                            {<<"publisher_confirms">>,bool,true},
                            {<<"consumer_cancel_notify">>,bool,true},
                            {<<"basic.nack">>,bool,true}],
                           <0.24737.12>,<0.24741.12>]}},
                  {restart_type,intrinsic},
                  {shutdown,4294967295},
                  {child_type,worker}]

Error in log handler
====================
Event: {error,<0.140.0>,
           {<0.24735.12>,
            "Error on AMQP connection ~p (~s, vhost: '~s', user: '~s', state: ~p), channel ~p:~n~s~n",
            [<0.24735.12>,<<"172.17.42.1:60612 -> 172.17.0.21:5672">>,<<"/">>,
             <<"guest">>,running,1,
             {badarg,
                 [{dict,fetch,
                      [<<"ctag1.7201627bf21e42a3a0fd1c273a2d5b"...>>,
                       {dict,0,16,16,8,80,48,{...},...}],
                      [{file,"dict.erl"},{line,131}]},
                  {rabbit_channel,consumer_monitor,2,
                      [{file,"src/rabbit_channel.erl"},{line,1533}]},
                  {rabbit_channel,handle_cast,2,
                      [{file,"src/rabbit_channel.erl"},{line,483}]},
                  {gen_server2,handle_msg,2,
                      [{file,"src/gen_server2.erl"},{line,1049}]},
                  {proc_lib,init_p_do_apply,3,
                      [{file,"proc_lib.erl"},{line,240}]}]}]}}
Error: badarg
Stack trace: [{io_lib,format,
                  ["Error on AMQP connection ~p (~s, vhost: '~s', user: '~s', state: ~p), channel ~p:~n~s~n",
                   [<0.24735.12>,<<"172.17.42.1:60612 -> 172.17.0.21:5672">>,
                    <<"/">>,<<"guest">>,running,1,
                    {badarg,
                        [{dict,fetch,
                             [<<"ctag1.7201627bf21e42a3a0fd1c273a2d5b0d">>,
                              {dict,0,16,16,8,80,48,
                                  {[],[],[],[],[],[],[],[],[],[],[],[],[],[],
                                   [],[]},
                                  {{[],[],[],[],[],[],[],[],[],[],[],[],[],[],
                                    [],[]}}}],
                             [{file,"dict.erl"},{line,131}]},
                         {rabbit_channel,consumer_monitor,2,
                             [{file,"src/rabbit_channel.erl"},{line,1533}]},
                         {rabbit_channel,handle_cast,2,
                             [{file,"src/rabbit_channel.erl"},{line,483}]},
                         {gen_server2,handle_msg,2,
                             [{file,"src/gen_server2.erl"},{line,1049}]},
                         {proc_lib,init_p_do_apply,3,
                             [{file,"proc_lib.erl"},{line,240}]}]}]],
                  [{file,"io_lib.erl"},{line,168}]},
              {rabbit_error_logger,publish1,4,
                  [{file,"src/rabbit_error_logger.erl"},{line,111}]},
              {rabbit_error_logger,handle_event0,2,
                  [{file,"src/rabbit_error_logger.erl"},{line,84}]},
              {rabbit_error_logger_file_h,safe_handle_event,3,
                  [{file,"src/rabbit_error_logger_file_h.erl"},{line,118}]},
              {gen_event,server_update,4,[{file,"gen_event.erl"},{line,538}]},
              {gen_event,server_notify,4,[{file,"gen_event.erl"},{line,520}]},
              {gen_event,handle_msg,5,[{file,"gen_event.erl"},{line,261}]},
              {proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,240}]}]

--

时光飞逝，但时光正好。

[Michael Klishin]

On 28 January 2016 at 06:35:46, flyer (flye...@gmail.com) wrote:
> Recently I encountered a problem that rabbitmq-server crashed.

Nothing in the error report suggests that RabbitMQ crashed. A particular process terminated
abnormally (crashed in Erlang terms) but I find it difficult to believe that it somehow affected the entire node.

Nothing suggests that it was due to a "bad message format". One of the messages mentions a log
entry that failed to format but it is not related to user input in any way. 

You're not providing any version information but the error means that a consumer with
tag "ctag1.7201627bf21e42a3a0fd1c273a2d5b0d" wasn't found on a channel.
--
MK

Staff Software Engineer, Pivotal/RabbitMQ

[flyer]

I’m sorry that I missed the base info…

I’m now using python-pika-0.10.0, rabbitmq-server-3.6 and erlang-18.
I’m new to rabbitmq and erlang, so the log info is a little hard to understand for me. Does the log mentioned mean that the consumer with tag “ctag1.7201627bf21e42a3a0fd1c273a2d5b0d” disappears? Moreover, there does have “CRASH REPORT” in the log. Does it not mean that the rabbitmq-server crashed?

In this situation, I couldn’t connect to rabbitmq-server and it showed that clients were refused to connect to the rabbitmq-server unless I restart the server.

[Michael Klishin]

On 28 January 2016 at 17:05:00, flyer (flye...@gmail.com) wrote:
> Does the log mentioned mean that the consumer with tag “ctag1.7201627bf21e42a3a0fd1c273a2d5b0d”
> disappears?

For some reason, it wasn't there, yes.

> Moreover, there does have “CRASH REPORT” in the
> log. Does it not mean that the rabbitmq-server crashed?

It means an Erlang process (like a thread in Java or .NET) failed with an unhandled exception.
This rarely leads to RabbitMQ nodes terminating. In the provided log part there was
no indication of that, possibly there was in the rest of the log file.

Do you have a script that reliably reproduces the issue or was it a single event? 

[flyer]

It happened once and I’m not sure which script caused this problem because there’re a few scripts that interact with rabbitmq-server…

When I saw this log, I firstly thought that there may be some bad format messages because in the message there’re some Chinese characters that were serialized using `json.dumps(msg)` rather than `json.dumps(msg, ensure_ascii=False)` in Python.
I encountered the same serialization of data when using redis one year ago, so I guessed it may be the same problem and after I did serialization using `json.dumps(msg, ensure_ascii=False)`, I haven’t seen the crash log.

[flyer]

I have pasted the complete log info in this gist .