Switch from Lager to the new Erlang Logger API for logging #2861

dumbbell · 2021-03-03T11:04:24Z

Switch from Lager to the new Erlang Logger API for logging

The configuration remains the same for the end-user. The only exception is the log root directory: it is now set through the log_root application env. variable in rabbit. People using the Cuttlefish-based configuration file are not affected by this exception.

The main change is how the logging facility is configured. It now happens in rabbit_prelaunch_logging. The rabbit_lager module is removed.

The supported outputs remain the same: the console, text files, the amq.rabbitmq.log exchange and syslog.

The message text format slightly changed: the timestamp is more precise (now to the microsecond) and the level can be abbreviated to always be 4-character long to align all messages and improve readability. Here is an example:

2021-03-03 10:22:30.377392+01:00 [dbug] <0.229.0> == Prelaunch DONE ==
2021-03-03 10:22:30.377860+01:00 [info] <0.229.0>
2021-03-03 10:22:30.377860+01:00 [info] <0.229.0>  Starting RabbitMQ 3.8.10+115.g071f3fb on Erlang 23.2.5
2021-03-03 10:22:30.377860+01:00 [info] <0.229.0>  Licensed under the MPL 2.0. Website: https://rabbitmq.com

The example above also shows that multiline messages are supported and each line is prepended with the same prefix (the timestamp, the level and the Erlang process PID).

JSON is also supported as a message format and now for any outputs. Indeed, it is possible to use it with e.g. syslog or the exchange. Here is an example of a JSON-formatted message sent to syslog:

Mar  3 11:23:06 localhost rabbitmq-server[27908] <0.229.0> - {"time":"2021-03-03T11:23:06.998466+01:00","level":"notice","msg":"Logging: configured log handlers are now ACTIVE","meta":{"domain":"rabbitmq.prelaunch","file":"src/rabbit_prelaunch_logging.erl","gl":"<0.228.0>","line":311,"mfa":["rabbit_prelaunch_logging","configure_logger",1],"pid":"<0.229.0>"}}

For quick testing, the values accepted by the $RABBITMQ_LOGS environment variables were extended:

- still means stdout
-stderr means stderr
syslog: means syslog on localhost
exchange: means logging to amq.rabbitmq.log

$RABBITMQ_LOG was also extended. It now accepts a +json modifier (in addition to the existing +color one). With that modifier, messages are formatted as JSON intead of plain text.

The rabbitmqctl rotate_logs command is deprecated. The reason is Logger does not expose a function to force log rotation. However, it will detect when a file was rotated by an external tool.

From a developer point of view, the old rabbit_log* API remains supported, though it is now deprecated. It is implemented as regular modules: there is no parse_transform involved anymore.

In the code, it is recommended to use the new Logger macros. For instance, ?LOG_INFO(Format, Args). If possible, messages should be augmented with some metadata. For instance (note the map after the message):

?LOG_NOTICE("Logging: switching to configured handler(s); following "
            "messages may not be visible in this log output",
            #{domain => ?RMQLOG_DOMAIN_PRELAUNCH}),

Domains in Erlang Logger parlance are the way to categorize messages. Some predefined domains, matching previous categories, are currently defined in rabbit_common/include/logging.hrl or headers in the relevant plugins for plugin-specific categories.

At this point, very few messages have been converted from the old rabbit_log* API to the new macros. It can be done gradually when working on a particular module or logging.

The Erlang builtin console/file handler, logger_std_h, has been forked because it lacks date-based file rotation. The configuration of date-based rotation is identical to Lager. Once the dust has settled for this feature, the goal is to submit it upstream for inclusion in Erlang. The forked module is calld rabbit_logger_std_h and is based logger_std_h in Erlang 23.0.

michaelklishin · 2021-03-05T00:30:43Z

Why was rabbitmqctl rotate_logs removed? If we don't have it, it would be much harder to get this into 3.8.x one day, which means supporting Erlang 24 there potentially would be impossible.

michaelklishin · 2021-03-05T00:40:32Z

There is a subtle change to severity formatting in the logs. Note how it uses [dbug] instead of [debug] which most tools use:

2021-03-05 01:39:36.577765+03:00 [dbug] <0.6137.0> User 'guest' authenticated successfully by backend rabbit_auth_backend_internal

dumbbell · 2021-03-05T10:54:20Z

Why was rabbitmqctl rotate_logs removed? If we don't have it, it would be much harder to get this into 3.8.x one day, which means supporting Erlang 24 there potentially would be impossible.

Erlang Logger does not offer a way to force log rotation. However it will detect correctly when a file was rotated by an external tool. We can restore rotate_logs if we backport but it will be a no-op and should return an error.

dumbbell · 2021-03-05T10:57:19Z

There is a subtle change to severity formatting in the logs. Note how it uses [dbug] instead of [debug] which most tools use:
2021-03-05 01:39:36.577765+03:00 [dbug] <0.6137.0> User 'guest' authenticated successfully by backend rabbit_auth_backend_internal

That's me who wanted aligned messages. It made the logs much more readable during development. I plan to make this configurable (it is already in the code), but I don't know yet how to expose the new settings. I would like to have more feedback from the Platform team because they will need the JSON structure to be configurable as well probably. Once I have more input, I can figure out a good way to expose the configuration.

dumbbell · 2021-03-05T10:59:17Z

Thank you for the patch for Erlang 24. I squashed it in the first commit.

michaelklishin · 2021-03-05T12:29:51Z

@dumbbell I suspect there is a lot of systems that depend on rabbitmqctl rotate_logs. So I'd reintroduce it and make it print a warning and do nothing, or find a way to perform rotation. Windows users specifically do not have a lot of options when it comes to log rotation, in fact, we see that some Windows users learn about log rotation from RabbitMQ :(

michaelklishin · 2021-03-05T12:31:07Z

Speaking of Windows, a bit of research yields this comment which suggests that external log rotation is indeed something that Windows users cannot use and/or frown upon.

deps/rabbit/apps/rabbitmq_prelaunch/src/rabbit_logger_std_h.erl

michaelklishin · 2021-03-05T17:29:21Z

We have lost support for log.default.level in the process:

log.console = false
log.default.level = warning
log.connection.level = error

doesn't have the desired effect (the node logs at debug level)

dumbbell · 2021-03-08T17:01:29Z

We have lost support for log.default.level in the process:
log.console = false
log.default.level = warning
log.connection.level = error
doesn't have the desired effect (the node logs at debug level)

We discussed this outside of GitHub: the reason is that when the node is started using gmake run-broker, we override automatically the log level to debug. That's why the configuration file is ignored.

dumbbell · 2021-03-09T14:19:22Z

The latest changes (squashed into the main commit and force-pushed) include:

the update to syslog 4.0.0
the renaming of unit_log_config_SUITE to logging_SUITE
a new test case for JSON formatting
fixes after testing the patch on Microsoft Windows 2019

The configuration remains the same for the end-user. The only exception is the log root directory: it is now set through the `log_root` application env. variable in `rabbit`. People using the Cuttlefish-based configuration file are not affected by this exception. The main change is how the logging facility is configured. It now happens in `rabbit_prelaunch_logging`. The `rabbit_lager` module is removed. The supported outputs remain the same: the console, text files, the `amq.rabbitmq.log` exchange and syslog. The message text format slightly changed: the timestamp is more precise (now to the microsecond) and the level can be abbreviated to always be 4-character long to align all messages and improve readability. Here is an example: 2021-03-03 10:22:30.377392+01:00 [dbug] <0.229.0> == Prelaunch DONE == 2021-03-03 10:22:30.377860+01:00 [info] <0.229.0> 2021-03-03 10:22:30.377860+01:00 [info] <0.229.0> Starting RabbitMQ 3.8.10+115.g071f3fb on Erlang 23.2.5 2021-03-03 10:22:30.377860+01:00 [info] <0.229.0> Licensed under the MPL 2.0. Website: https://rabbitmq.com The example above also shows that multiline messages are supported and each line is prepended with the same prefix (the timestamp, the level and the Erlang process PID). JSON is also supported as a message format and now for any outputs. Indeed, it is possible to use it with e.g. syslog or the exchange. Here is an example of a JSON-formatted message sent to syslog: Mar 3 11:23:06 localhost rabbitmq-server[27908] <0.229.0> - {"time":"2021-03-03T11:23:06.998466+01:00","level":"notice","msg":"Logging: configured log handlers are now ACTIVE","meta":{"domain":"rabbitmq.prelaunch","file":"src/rabbit_prelaunch_logging.erl","gl":"<0.228.0>","line":311,"mfa":["rabbit_prelaunch_logging","configure_logger",1],"pid":"<0.229.0>"}} For quick testing, the values accepted by the `$RABBITMQ_LOGS` environment variables were extended: * `-` still means stdout * `-stderr` means stderr * `syslog:` means syslog on localhost * `exchange:` means logging to `amq.rabbitmq.log` `$RABBITMQ_LOG` was also extended. It now accepts a `+json` modifier (in addition to the existing `+color` one). With that modifier, messages are formatted as JSON intead of plain text. The `rabbitmqctl rotate_logs` command is deprecated. The reason is Logger does not expose a function to force log rotation. However, it will detect when a file was rotated by an external tool. From a developer point of view, the old `rabbit_log*` API remains supported, though it is now deprecated. It is implemented as regular modules: there is no `parse_transform` involved anymore. In the code, it is recommended to use the new Logger macros. For instance, `?LOG_INFO(Format, Args)`. If possible, messages should be augmented with some metadata. For instance (note the map after the message): ?LOG_NOTICE("Logging: switching to configured handler(s); following " "messages may not be visible in this log output", #{domain => ?RMQLOG_DOMAIN_PRELAUNCH}), Domains in Erlang Logger parlance are the way to categorize messages. Some predefined domains, matching previous categories, are currently defined in `rabbit_common/include/logging.hrl` or headers in the relevant plugins for plugin-specific categories. At this point, very few messages have been converted from the old `rabbit_log*` API to the new macros. It can be done gradually when working on a particular module or logging. The Erlang builtin console/file handler, `logger_std_h`, has been forked because it lacks date-based file rotation. The configuration of date-based rotation is identical to Lager. Once the dust has settled for this feature, the goal is to submit it upstream for inclusion in Erlang. The forked module is calld `rabbit_logger_std_h` and is based `logger_std_h` in Erlang 23.0.

... from `rabbit_log:*` calls. Many rabbitmq_peer_discovery_consul testcases are executed outside of a RabbitMQ server node. When we had Lager `parse_transform` enabled, calls to `rabbit_log` were converted to something which happened to not break when executed outside of RabbitMQ. Now that `rabbit_log` calls are kept (there is no `parse_transform`), the missing dependency to rabbit_common in the common_test node surfaces nad hilights the breakage which has always been there. Calls to `rabbit_log` are now replaced with Logger macros and this works again, even in the context of the common_test node.

it no longer depends on Lager

Lager strips trailing newline characters but OTP logger with the default formatter adds a newline at the end. To avoid unintentional multi-line log messages we have to revisit most messages logged. Some log entries are intentionally multiline, others are printed to stdout directly: newlines are required there for sensible formatting.

Introduced in #2861

... if it is set in the configuration file. Here is an example of that use case: * The official Docker image sets $RABBITMQ_LOGS=- * A user of that image adds a configuration file with: log.console.level = debug The initial implementation, introduced in #2861, considered that if the output is overriden in the environment (through $RABBITMQ_LOGS), any output configuration in the configuration file is ignored. The problem is that the output-specific configuration could also set the log level which is not changed by $RABBITMQ_LOGS. This patch fixes that by keeping the log level from the configuration (if it is set obviously) even if the output is overridden in the environment.

... if it is set in the configuration file. Here is an example of that use case: * The official Docker image sets RABBITMQ_LOGS=- in the environment * A user of that image adds a configuration file with: log.console.level = debug The initial implementation, introduced in #2861, considered that if the output is overriden in the environment (through $RABBITMQ_LOGS), any output configuration in the configuration file is ignored. The problem is that the output-specific configuration could also set the log level which is not changed by $RABBITMQ_LOGS. This patch fixes that by keeping the log level from the configuration (if it is set obviously) even if the output is overridden in the environment.

dumbbell requested a review from gerhard March 3, 2021 11:04

dumbbell force-pushed the use-builtin-logger branch from 3500345 to ad0891c Compare March 3, 2021 15:52

michaelklishin mentioned this pull request Mar 4, 2021

Upgrade Lager to 3.9 for OTP 24 compatibility #2864

Merged

dumbbell force-pushed the use-builtin-logger branch 4 times, most recently from 3417d2a to b0457df Compare March 4, 2021 18:04

dumbbell force-pushed the use-builtin-logger branch 2 times, most recently from 24920d4 to 13b8421 Compare March 5, 2021 10:51

dumbbell commented Mar 5, 2021

View reviewed changes

deps/rabbit/apps/rabbitmq_prelaunch/src/rabbit_logger_std_h.erl Outdated Show resolved Hide resolved

dumbbell force-pushed the use-builtin-logger branch 4 times, most recently from 8f11399 to ff5a42a Compare March 5, 2021 15:37

dumbbell force-pushed the use-builtin-logger branch 3 times, most recently from a188968 to e22ed70 Compare March 8, 2021 16:37

dumbbell force-pushed the use-builtin-logger branch 3 times, most recently from 816ba9c to e6f6c18 Compare March 9, 2021 14:14

dumbbell force-pushed the use-builtin-logger branch 2 times, most recently from 1ca1125 to 752f1a6 Compare March 10, 2021 11:17

michaelklishin force-pushed the use-builtin-logger branch from 9ecd493 to 59103bf Compare March 11, 2021 10:16

dumbbell and others added 4 commits March 11, 2021 15:17

Use Cuttlefish master for now

b67c030

it no longer depends on Lager

dumbbell force-pushed the use-builtin-logger branch from 777ad85 to 97ff62d Compare March 11, 2021 14:19

dumbbell marked this pull request as ready for review March 11, 2021 14:24

dumbbell merged commit 132dee6 into master Mar 11, 2021

dumbbell deleted the use-builtin-logger branch March 11, 2021 14:46

michaelklishin added a commit that referenced this pull request Mar 12, 2021

MQTT: correct a typo in mqtt_machine

91964db

Introduced in #2861

michaelklishin mentioned this pull request Mar 12, 2021

MQTT: correct a typo in mqtt_machine #2886

Merged

dumbbell mentioned this pull request Mar 19, 2021

rabbit_prelaunch_logging: $RABBITMQ_LOGS doesn't override log level if it is set in the configuration file #2911

Merged

timothyvanderaerden mentioned this pull request Aug 17, 2021

Bump amqp_client to 3.9.1 pma/amqp#201

Merged

jeremy-evidos mentioned this pull request Mar 31, 2022

RABBITMQ_LOGS=- prevents logging to other sources altogether #4303

Closed

This was referenced May 3, 2025

No logs published to Cloudwatch noxdafox/rabbitmq-cloudwatch-exporter#40

Closed

Logs are not being sent to Cloudwatch noxdafox/rabbitmq-cloudwatch-exporter#42

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Switch from Lager to the new Erlang Logger API for logging #2861

Switch from Lager to the new Erlang Logger API for logging #2861

Uh oh!

dumbbell commented Mar 3, 2021 •

edited

Loading

Uh oh!

michaelklishin commented Mar 5, 2021

Uh oh!

michaelklishin commented Mar 5, 2021

Uh oh!

dumbbell commented Mar 5, 2021

Uh oh!

dumbbell commented Mar 5, 2021

Uh oh!

dumbbell commented Mar 5, 2021

Uh oh!

michaelklishin commented Mar 5, 2021

Uh oh!

michaelklishin commented Mar 5, 2021

Uh oh!

Uh oh!

michaelklishin commented Mar 5, 2021

Uh oh!

dumbbell commented Mar 8, 2021

Uh oh!

dumbbell commented Mar 9, 2021

Uh oh!

Uh oh!

Switch from Lager to the new Erlang Logger API for logging #2861

Switch from Lager to the new Erlang Logger API for logging #2861

Uh oh!

Conversation

dumbbell commented Mar 3, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

michaelklishin commented Mar 5, 2021

Uh oh!

michaelklishin commented Mar 5, 2021

Uh oh!

dumbbell commented Mar 5, 2021

Uh oh!

dumbbell commented Mar 5, 2021

Uh oh!

dumbbell commented Mar 5, 2021

Uh oh!

michaelklishin commented Mar 5, 2021

Uh oh!

michaelklishin commented Mar 5, 2021

Uh oh!

Uh oh!

michaelklishin commented Mar 5, 2021

Uh oh!

dumbbell commented Mar 8, 2021

Uh oh!

dumbbell commented Mar 9, 2021

Uh oh!

Uh oh!

dumbbell commented Mar 3, 2021 •

edited

Loading