Erlang 18.1 breaks RabbitMQ logging

[gmr]

When upgrading to 3.5.5 I also upgraded erlang to 0:18.1 installed from esl. Downgrading from 0:18.1 to 0:17.5.3 resolved the issue.

All attempts to log end up in startup_log getting flooded with exceptions trying to log:

Error in log handler
====================
Event: {error,<0.119.0>,
              {<0.3140.0>,
               "Channel error on connection ~p (~s, vhost: '~s', user: '~s'), channel ~p:~n~p~n",
               [<0.3132.0>,<<"10.20.16.209:42447 -> 10.20.16.161:5672">>,
                <<"/">>,<<"guest">>,1,
                {amqp_error,not_found,
                            "home node 'rabbit@rabbit1' of durable queue 'foo.bar' in vhost '/' is down or inaccessible",
                            'queue.declare'}]}}
Error: function_clause
Stack trace: [{error_logger_file_h,write_event,
                  [{<0.45.0>,"/var/log/rabbitmq/rabbit@rabbit3.log",[]},
                   {error,<0.119.0>,
                       {<0.3140.0>,
                        "Channel error on connection ~p (~s, vhost: '~s', user: '~s'), channel ~p:~n~p~n",
                        [<0.3132.0>,
                         <<"10.20.16.209:42447 -> 10.20.16.161:5672">>,
                         <<"/">>,<<"guest">>,1,
                         {amqp_error,not_found,
                             "home node 'rabbit@rabbit1' of durable queue 'foo.bar in vhost '/' is down or inaccessible",
                             'queue.declare'}]}}],
                  [{file,"error_logger_file_h.erl"},{line,114}]},
              {error_logger_file_h,handle_event,2,
                  [{file,"error_logger_file_h.erl"},{line,79}]},
              {rabbit_error_logger_file_h,safe_handle_event,3,[]},
              {gen_event,server_update,4,[{file,"gen_event.erl"},{line,538}]},
              {gen_event,server_notify,4,[{file,"gen_event.erl"},{line,520}]},
              {gen_event,server_notify,4,[{file,"gen_event.erl"},{line,522}]},
              {gen_event,handle_msg,5,[{file,"gen_event.erl"},{line,261}]},
              {proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,240}]}]

Error in log handler
====================
Event: {info_msg,<0.119.0>,
                 {<0.3132.0>,"closing AMQP connection ~p (~s)~n",
                  [<0.3132.0>,"10.20.16.209:42447 -> 10.20.16.161:5672"]}}
Error: function_clause
Stack trace: [{error_logger_file_h,write_event,
                  [{<0.45.0>,"/var/log/rabbitmq/rabbit@rabbit3.log",[]},
                   {info_msg,<0.119.0>,
                       {<0.3132.0>,"closing AMQP connection ~p (~s)~n",
                        [<0.3132.0>,
                         "10.20.16.209:42447 -> 10.20.16.161:5672"]}}],
                  [{file,"error_logger_file_h.erl"},{line,114}]},
              {error_logger_file_h,handle_event,2,
                  [{file,"error_logger_file_h.erl"},{line,79}]},
              {rabbit_error_logger_file_h,safe_handle_event,3,[]},
              {gen_event,server_update,4,[{file,"gen_event.erl"},{line,538}]},
              {gen_event,server_notify,4,[{file,"gen_event.erl"},{line,520}]},
              {gen_event,server_notify,4,[{file,"gen_event.erl"},{line,522}]},
              {gen_event,handle_msg,5,[{file,"gen_event.erl"},{line,261}]},
              {proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,240}]}]

[essen]

18.1 has changed the format of some error messages sent by the emulator, this is most likely what happens here.

[videlalvaro]

This user had the same problem way before we released 3.5.5 so I'd guess 18.1 is the culprit here: http://stackoverflow.com/questions/32751556/startup-error-writing-to-to-var-log-rabbitmq-rabbitrab04-log

[gmr]

Yeah should point out that it was not RabbitMQ per se.. 18.1 was the clear change in my testing.

[videlalvaro]

These changes to the error logger in erlang introduced a a new st record: erlang/otp@003091a

So instead of the tuple {Fd, File, PrevHandler} now the state is:

-record(st,
    {fd,
     filename,
     prev_handler}).

Which breaks when RabbitMQ tries to call event handlers: erlang/otp@003091a#diff-d9a19ba08f5d2b60fadfc3aa1566b324R108 and functions that use the server state.

[videlalvaro]

@michaelklishin @gmr I've just pushed branch rabbitmq-server-324 would you mind giving it a try? If it works we need to do some small performance improvements to handle the new depth introduced in 18.1.

[videlalvaro]

This file https://github.com/erlang/otp/blob/maint/lib/sasl/src/sasl_report_file_h.erl was not changed on 18.1 but we have to monitor it just in case, since if they decide to perform similar changes, we will have the same problem.

[videlalvaro]

This change here also breaks log rotation: erlang/otp@ad7bb40#diff-d9a19ba08f5d2b60fadfc3aa1566b324L97

Before terminate was returning an empty list [], now it returns ok assuming file:close(Fd) succeeded.

[moshezvi]

When trying to downgrade erlang-nox, it keeps bringing all the erlang 1:18.1 dependencies. Any idea how to downgrade the deps as well?

[videlalvaro]

@moshezvi perhaps as on the Erlang mailing list/irc channel

[michaelklishin]

I'd extract a function that returns OTP version as major.minor accepting a string from rabbit_misc:opt_version/0, using 16.3 for releases earlier than 17.0 (since R16B03` is the requirement for 3.6.0 and good enough for this case), then add unit tests for it.

[michaelklishin]

Fixed in #334.

[apachesun]

I tried to install rabbitmq on CentOS 7 and I'm still seeing many errors in the startup_log:

Error in log handler

Event: {info_report,<0.29.0>,
{<0.7.0>,progress,
[{application,xmerl},{started_at,'rabbit@vm-centos-7'}]}}
Error: function_clause
Stack trace: [{error_logger_file_h,write_event,
[{<0.48.0>,"/var/log/rabbitmq/rabbit@vm-centos-7.log",[]},
{info_report,<0.29.0>,
{<0.7.0>,progress,
[{application,xmerl},
{started_at,'rabbit@vm-centos-7'}]}}],
[{file,"error_logger_file_h.erl"},{line,113}]},
{error_logger_file_h,handle_event,2,
[{file,"error_logger_file_h.erl"},{line,78}]},
{rabbit_error_logger_file_h,safe_handle_event,3,[]},
{gen_event,server_update,4,[{file,"gen_event.erl"},{line,522}]},
{gen_event,server_notify,4,[{file,"gen_event.erl"},{line,504}]},
{gen_event,server_notify,4,[{file,"gen_event.erl"},{line,506}]},
{gen_event,handle_msg,5,[{file,"gen_event.erl"},{line,266}]},
{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,239}]}]

I tried various combination of erlang package and rabbitmq packages, such as

• Erlang R16B_03 from epel,
• Erlang 18.3.1 and 18.3.3
• rabbitmq server 3.5.4, 3.5.7-1, 3.6.1

The error occurred in each combination.

Exactly in which combination this error is gone? Thanks.

[michaelklishin]

Please post questions to rabbitmq-users or Stack Overflow. RabbitMQ uses GitHub issues for specific actionable items engineers can work on, not questions. Thank you.

[michaelklishin]

Only RabbitMQ 3.5.6+ can run on Erlang 18.x. Otherwise Erlang version requirements are documented.