Switch to Lager for logging

[hairyhum]

Tried to make lager work with all default logging locations and settings.
Log rotation have 2 sec sleep now to let lager finish all writes to old file and open a new one.
Support for configuring lager from .config, so it's not overwritten by default rabbit config.
Need review

[hairyhum]

Fixes #94 .

[hairyhum]

Spend most time trying to make tests with old config working too support same behaviour.
It should work like nothing is changed. Same log files, same config. But there is a way to customise it with lager .config
Next steps could be better integration with parse_transform or adding more sinks for logging different things separately. But this could be a separate tasks.

[michaelklishin]

Erlang unit tests fail with

OUT=$(RABBITMQ_PID_FILE='/var/folders/6v/nzn6gr5d6k31r39x57fddtpm0000gp/T//rabbitmq-test-instances/rabbit/rabbit.pid' echo "rabbit_tests:all_tests()." | erl_call -sname rabbit -e) ; \
      echo $OUT ; echo $OUT | grep '^{ok, passed}$' > /dev/null
{ok, "Tests failed
Error: {error, {badmatch,[true,{error,enoent}]}}
Stack trace:
[{rabbit_tests,test_log_management,0,
 [{file,"test/src/rabbit_tests.erl"},{line,742}]},
 {rabbit_tests,all_tests0,0,[{file,"test/src/rabbit_tests.erl"},{line,63}]},
 {rabbit_tests,all_tests,0,[{file,"test/src/rabbit_tests.erl"},{line,34}]},
 {erl_eval,do_apply,6,[{file,"erl_eval.erl"},{line,669}]},
 {lib,eval_str,1,[{file,"lib.erl"},{line,106}]},
 {rpc,'-handle_call_call/6-fun-0-',5,[{file,"rpc.erl"},{line,206}]}]
"}
make[1]: *** [run-tests] Error 1

Other test suites pass.

[hairyhum]

Created pull request for test branch

[videlalvaro]

it should be automatically

[michaelklishin]

make full fails for me (Java test suites fail, looks like node startup issues) while they all pass when executed individually.

[hairyhum]

@michaelklishin I don't have any errors with make full. I have tested at MacOS El Capitan and OTP 18

[michaelklishin]

if we add this in rabbitmq-server, we need to do the same in rabbitmq-server.bat.

[dumbbell]

I tested the branch on Windows and it works fine with the default settings, including log rotation.

However, logging to stdout is broken. You can test with:

make run-broker RABBITMQ_LOGS=-

In rabbitmq-server, this becomes:

-rabbit error_logger tty

Lager complains with the following message:

WARNING: Lager's console backend is incompatible with the 'old' shell, not enabling it

Note that, on Windows, this depends on a patch I didn't commit yet (rabbitmq-server.bat doesn't support RABBITMQ_LOGS=- as opposed to rabbitmq-server).

This could be specific to Windows though. I will test on FreeBSD once the profiling of lazy queues is finished (erlgrind is already running for almost three hours...)

[michaelklishin]

Fixing TTY logging is the only thing that's left, it seems.

[dumbbell]

I'm starting to look at this.

[dumbbell]

The problem with TTY is only present on Windows. It works as expected on Unix.

[dumbbell]

Apparently, this is a known limitation:
https://github.com/basho/lager/blob/master/src/lager_console_backend.erl#L55
https://github.com/basho/lager/blob/master/src/lager_console_backend.erl#L137

It's not a regression as it was impossible to enable console logging on Windows anyway.

I'm testing a few more things but this branchs looks ready to be merged. My concern about the timer:sleep/1 can be addressed later.

[dumbbell]

We can't override the log file locations anymore using the environment variables, if lager is configured in rabbitmq.config. Those variables are only considered as the default values. And indeed, with the current rabbitmq-env and rabbitmq-server, we can't distinguish the default values from user-specified ones. I'm looking for a solution.

[hairyhum]

@dumbbell priority of rabbitmq.config parameters was selected on purpose, because it is much more flexible way to configure file locations, log levels and rotating.

[dumbbell]

I agree it's more flexible and powerful. However, I find it handy if I can just set RABBITMQ_LOGS and have this one time log file. Another usecase : I have my complex logging preferences in rabbitmq.config but from time to time, I want RabbitMQ sends everything to stdout.

[dumbbell]

I still have a few things I would like to fix before merging this branch:

• Lager's documentation recommends to use a parse_transform, {parse_transform, lager_transform}, during the build.

• When a crash is logged, the message is even more unreadable than with standard error_logger format, except on stdout:

  # In rabbit-sasl.log
  2016-01-06 12:01:41.341 [error] <0.227.0> CRASH REPORT Process <0.227.0> with 0 neighbours exited with reason: no function clause matching rabbit_memory_monitor:init([]) line 113 in gen_server2:init_it/6 line 601
  2016-01-06 12:01:41.342 [error] <0.226.0> Supervisor rabbit_memory_monitor_sup had child rabbit_memory_monitor started with rabbit_memory_monitor:start_link() at undefined exit with reason no function clause matching rabbit_memory_monitor:init([]) line 113 in context start_error
  2016-01-06 12:01:41.343 [error] <0.161.0> CRASH REPORT Process <0.161.0> with 0 neighbours exited with reason: {error,{{shutdown,{failed_to_start_child,rabbit_memory_monitor,{function_clause,[{rabbit_memory_monitor,init,[[]],[{file,"src/rabbit_memory_monitor.erl"},{line,113}]},{gen_server2,init_it,6,[{file,"src/gen_server2.erl"},{line,559}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,240}]}]}}},{child,undefined,rabbit_memory_monitor_sup,{rabbit_restartable_sup,start_link,[rabbit_memory_monitor_sup,{rabbit_memory_monitor,start_link,[]},false]},transient,infinity,supervisor,[rabbit_restartable_sup]}}} in application_master:init/4 line 134
  2016-01-06 12:01:41.343 [info] <0.7.0> Application rabbit exited with reason: {error,{{shutdown,{failed_to_start_child,rabbit_memory_monitor,{function_clause,[{rabbit_memory_monitor,init,[[]],[{file,"src/rabbit_memory_monitor.erl"},{line,113}]},{gen_server2,init_it,6,[{file,"src/gen_server2.erl"},{line,559}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,240}]}]}}},{child,undefined,rabbit_memory_monitor_sup,{rabbit_restartable_sup,start_link,[rabbit_memory_monitor_sup,{rabbit_memory_monitor,start_link,[]},false]},transient,infinity,supervisor,[rabbit_restartable_sup]}}}
  

  # In rabbit.log
  2016-01-06 12:01:41.351 [info] <0.2.0> Error description:
  {could_not_start,rabbit,{error,{{shutdown,{failed_to_start_child,rabbit_memory_monitor,{function_clause,[{rabbit_memory_monitor,init,[[]],[{file,"src/rabbit_memory_monitor.erl"},{line,113}]},{gen_server2,init_it,6,[{file,"src/gen_server2.erl"},{line,559}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,240}]}]}}},{child,undefined,rabbit_memory_monitor_sup,{rabbit_restartable_sup,start_link,[rabbit_memory_monitor_sup,{rabbit_memory_monitor,start_link,[]},false]},transient,infinity,supervisor,[rabbit_restartable_sup]}}}}
  
  Log files (may contain more information):
     rabbit.log
     /tmp/rabbitmq-test-instances/rabbit/log/rabbit-sasl.log
  

  # On stdout
  BOOT FAILED
  ===========
  
  Error description:
     {could_not_start,rabbit,
         {error,
             {{shutdown,
                  {failed_to_start_child,rabbit_memory_monitor,
                      {function_clause,
                          [{rabbit_memory_monitor,init,
                               [[]],
                               [{file,"src/rabbit_memory_monitor.erl"},
                                {line,113}]},
                           {gen_server2,init_it,6,
                               [{file,"src/gen_server2.erl"},{line,559}]},
                           {proc_lib,init_p_do_apply,3,
                               [{file,"proc_lib.erl"},{line,240}]}]}}},
              {child,undefined,rabbit_memory_monitor_sup,
                  {rabbit_restartable_sup,start_link,
                      [rabbit_memory_monitor_sup,
                       {rabbit_memory_monitor,start_link,[]},
                       false]},
                  transient,infinity,supervisor,
                  [rabbit_restartable_sup]}}}}
  
  Log files (may contain more information):
     rabbit.log
     /tmp/rabbitmq-test-instances/rabbit/log/rabbit-sasl.log
  
  12:01:41.351 [info] Error description:
     {could_not_start,rabbit,{error,{{shutdown,{failed_to_start_child,rabbit_memory_monitor,{function_clause,[{rabbit_memory_monitor,init,[[]],[{file,"src/rabbit_memory_monitor.erl"},{line,113}]},{gen_server2,init_it,6,[{file,"src/gen_server2.erl"},{line,559}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,240}]}]}}},{child,undefined,rabbit_memory_monitor_sup,{rabbit_restartable_sup,start_link,[rabbit_memory_monitor_sup,{rabbit_memory_monitor,start_link,[]},false]},transient,infinity,supervisor,[rabbit_restartable_sup]}}}}
  
  Log files (may contain more information):
     rabbit.log
     /tmp/rabbitmq-test-instances/rabbit/log/rabbit-sasl.log
  

• As shown above, the path to rabbit.log is missing.

[hairyhum]

Or as an option we can configure rabbit_log_lager_event sink and enable lager_transform so lager will send rabbit_log:error|debug|info etc to this sink. At least that's what lager docs say.

[michaelklishin]

Using Lager directly will break a lot of plugins. Lets hold off on that and do it for 3.8.

[michaelklishin]

As for deprecating rabbit_log, plugin authors may find it convenient to have this known way of logging to the broker log file.

[dumbbell]

@hairyhum: That's interesting! I will look at that.
@michaelklishin: By deprecating, I mean stop using it internally (and in our plugins). The module can stay (and should probably be moved to rabbit_common). It would become a wrapper above Lager API / standard sink.

[michaelklishin]

@dumbbell no objections to that.

[hairyhum]

@dumbbell it's mentioned in sinks doc section https://github.com/rabbitmq/lager#sinks
It won't support logging with categories, so could be unsafe if categories are used in some plugin code.

[dumbbell]

Here is what I propose to fully use Lager and its features, while still maintaining compatibility for those using rabbit_log.

• Let's use the default sink to log everything by default. For the end-user, it's easy to configure, because they only have to mess with the main list of handlers:

  % In rabbitmq.config
  {lager, [
      {handlers, [
          {lager_console_backend, [info]}
        ]}
    ]}

• By default (ie. if nothing is configured in rabbitmq.config), we honor $RABBITMQ_LOGS: a handler based on $RABBITMQ_LOGS is added to the default sink. If there is something configured, but $RABBITMQ_LOGS is forced on the command line (or rabbitmq-env.conf), the configured handlers are replaced with a handler based on $RABBITMQ_LOGS. This is mainly useful to developers when they want to temporarily redirect messages to stdout by starting make run-broker RABBITMQ_LOGS=- for instance.

• We configure an extra sinks (except if it's already configured) called rabbit_log_lager_event. In combination with lager_transform and the +'{lager_extra_sinks,[rabbit_log]} compile option, this makes all calls to rabbit_log:<level>() to be transformed into direct calls to Lager. The advantage is that the logged message can contain metadata such as file name and line number.

• To maintain compatibility, the rabbit_log module still exports those <level>() functions: they call Lager, specifying rabbit_log_lager_event as the sink. The result is the same, minus the automatically added metadata.

• I added a lager_forwarder_backend module: it acts as a Lager backend which forwards all messages to a specified sink. The goal is to use it for rabbit_log_lager_event: if this sink is not configured, a lager_forwarder_backend handler is added to this sink and this handler is configured to forward everything to the default Lager sink. The end result is that messages logged with rabbit_log:<level>() are written to the same log file than messages logged with error_logger. This was necessary because Lager doesn't allow to have multiple lager_file_backend backends to point to the same file.

Let's try to sum up this with a simple drawing of the default configuration:

rabbit_log:info() --> rabbit_log_lager_event sink --+
                                                    |
                                          +---------+
                                          |
                                          V
error_logger:info_msg() --> lager_event default sink --> handler based on $RABBITMQ_LOGS

Now, about categories. rabbit_log:log/{3,4} offers the possibility to specify a category. An admin could then configure per-category minimum log levels. I propose we leverage on extra sinks even further for this purpose:

• +'{lager_extra_sinks,[rabbit_log]} becomes +'{lager_extra_sinks,[rabbit_log,rabbit_connection,rabbit_channel]} if we take two categories we currentl support, "connection" and "channel".

• This means we can use rabbit_channel:info() to log a message to the rabbit_channel_lager_event sink.

• Category-specific sinks are configured exactly like rabbit_log_lager_event. To be exact, I take the list of extra sinks from the module's compilation options stored in the beam:

  (rabbit@magellan)1> rabbit_lager:module_info(compile).
  [{options,[
         ...
         {lager_extra_sinks,[rabbit_log,rabbit_connection,
                             rabbit_channel]},

  They are all treated the same.

• This still allows the user to specify per-category minimum log level:

      {extra_sinks, [
          {rabbit_channel_lager_event, [
              {handlers, [
                  % Do not send messages to $RABBITMQ_LOGS.
                  {lager_forwarder_backend, [lager_event, none]},
                  % Send messages to stdout.
                  {lager_console_backend, info}
                ]}
            ]}
        ]},

Let's expand the previous drawing:

rabbit_connection:info() --> rabbit_connection_lager_event sink --+
rabbit_channel:info() --> rabbit_channel_lager_event sink --+     |
rabbit_log:info() --> rabbit_log_lager_event sink --+       |     |
                                                    |       |     |
                                          +---------+-------+-----+
                                          |
                                          V
error_logger:info_msg() --> lager_event default sink --> handler based on $RABBITMQ_LOGS

Admittedly, this is more complicated to configure than what we have currently, but it's also way more powerful. Lager allows finer-grain control of the log levels: instead of a bare minimum, it supports masks and ranges.

[michaelklishin]

So the extra sinks would be used to allow for finer-grained configuration of things we currently allow to configure. That sounds reasonable to me. As does respecting RABBITMQ_*.

Should lager_forwarder_backend be rabbit_lager_forwarder_backend, though, because it is RabbitMQ-specific?

[dumbbell]

Should lager_forwarder_backend be rabbit_lager_forwarder_backend, though, because it is RabbitMQ-specific?

There is nothing RabbitMQ-specific in it and currently, it lives in rabbitmq-common (where rabbit_log and rabbit_lager should probably go). We could even ship it separately.

[michaelklishin]

Fair enough.

[dumbbell]

I just pushed the proposed patch so you can read the code and test if you want.

[michaelklishin]

I have one test failure:

{ok, "Tests failed
Error: {error, undef}
Stack trace:
[{rabbit,log_location,[kernel],[]},
 {rabbit_tests,test_log_management,0,
 [{file,"test/src/rabbit_tests.erl"},{line,732}]},
 {rabbit_tests,all_tests0,0,[{file,"test/src/rabbit_tests.erl"},{line,63}]},
 {rabbit_tests,all_tests,0,[{file,"test/src/rabbit_tests.erl"},{line,34}]},
 {erl_eval,do_apply,6,[{file,"erl_eval.erl"},{line,669}]},
 {lib,eval_str,1,[{file,"lib.erl"},{line,106}]},
 {rpc,'-handle_call_call/6-fun-0-',5,[{file,"rpc.erl"},{line,206}]}]
"}
make[1]: *** [run-tests] Error 1

(with rabbitmq-test switched to rabbitmq-server-94, of course).

[dumbbell]

I didn't update the testsuite yet. I want to make sure the behavior is what we want first.

[dumbbell]

That said, I should commit lager_forwarder_backend if you actually want to test :-)

[michaelklishin]

@dumbbell I still have the test failure but otherwise no objections to your plan.

[dumbbell]

Thanks, I will update the testsuite, then.

[dumbbell]

The testsuite is up-to-date so this issue is ready for a final test :-)

[michaelklishin]

With a few more tweaks in the rabbitmq-test counterpart to this, Lager now looks good to me. I'd be OK with merging this now and updating plugins (primarily management and plugins that extend it) later as needed.

We should also cut a milestone release after the dust from this change settles.