add RABBITMQ_LOG_LEVELS as a valid env var in docker-entrypoint.sh

[ilude]

Allows setting of log levels via environment variable

[ilude]

See #158

[kernel-sanders]

Please merge this PR. There is currently no way to set the logging level (even with a custom rabbitmq.config) since the config is overwritten by the entrypoint script.

[tianon]

See docker-library/docs#1011 (the example of which is changing the value of log_levels).

[ilude]

The issue is that docker-library/docs#1011 does not actually work.
In addition it does not provide a declarative way of setting the log variable. i.e. there is no way to confirm what those settings are for a running instance.

[michaelklishin]

@ilude can you please be more specific than "it doesn't work"? Your claim is a bit light on details.
AFAIK there are no known issues with using RABBITMQ_SERVER_ADDITIONAL_ERL_ARGS with this image's case as of #161.

It is possible to inspect effective node configuration, see Verify Configuration in RabbitMQ docs.

[michaelklishin]

@tianon I think the downside of using RABBITMQ_SERVER_ADDITIONAL_ERL_ARGS for log level configuration comes down to

• It requires some familiarity with how Erlang VM accepts configuration settings for the apps on the command line. It's fairly easy to get wrong (and most users from my experience only read the docs on how to inspect effective node configuration only after they try to wing it and run into a problem).
• It is not possible to tell what the configuration is from looking at the config file alone

So this PR may be worth considering until 3.7.0 ships with the new config format which should be much easier for this image to manage, plus a separate "advanced configuration" file which can be used for really fine grained logger tuning.

WDYT?

[ilude]

here is a docker-compose.yml showing the RABBITMQ_SERVER_ADDITIONAL_ERL_ARGS not working:

https://gist.github.com/ilude/ba7a5a6df7decb369bfbdc4b562d5ad9

follow that with a

docker-compose exec rabbitmq rabbitmqctl environment

and you'll see that logging is still set to info.

In addition (constructive criticism incoming, please don't read this as I'm mad or demanding anything) none of this is in anyway intuitive. Most images provide a way to configure logging without digging into closed comment threads for incomplete examples. And this is all coupled with the fact that your startup script does not allow a user of the image to easily override or add to the configuration file.

Now having said all that my pull request was an attempt to make an easy way for image users to customize the log levels which is something I think many users would like to do. I would also be happy to submit a pull request on the docker hub docs for the image explaining the logging env setting and its use.

Finally I would add that Pull request #174 and Pull request #53 should both be given serious consideration as they would make this image alot easier to customize to peoples needs.

[tianon]

@ilude you've got an error in your docker-compose.yml syntax -- for environment:, you need to either use - or :, not both; I had success with the following change:

diff --git a/docker-compose.yml b/docker-compose.yml
index 1c065fb..2c8596d 100644
--- a/docker-compose.yml
+++ b/docker-compose.yml
@@ -5,4 +5,4 @@ rabbitmq:
       - "5672:5672"
       - "15672:15672"
     environment:
-      - RABBITMQ_SERVER_ADDITIONAL_ERL_ARGS:"-rabbit log_levels [{connection, warning}, {channel, warning}]"
+      RABBITMQ_SERVER_ADDITIONAL_ERL_ARGS: "-rabbit log_levels [{connection,warning},{channel,warning}]"

$ docker-compose exec -T rabbitmq rabbitmqctl environment | grep log_levels
          {log_levels,[{connection,warning},{channel,warning}]},

Your point about usability is certainly not lost, but we're already a bit overboard on divergence from the upstream experience with the number of additional environment variables we support, so punting further configuration (and perhaps all configuration in 3.7+) to the upstream-supported methods is something we'd really like to do without really strong justification or explicit blessing from upstream to continue down the rabbit hole of extra environment variables that they don't officially support and know nothing about (and will inevitably get references to in bug reports to their project).

[ilude]

Now that's strange, I get the following with the dash removed:

  ERROR: The Compose file '.\docker-compose.yml' is invalid because:
  rabbitmq.environment contains an invalid type, it should be an object, or an array

And the docs show that the dash is correct: https://docs.docker.com/compose/environment-variables/#setting-environment-variables-in-containers so perhaps this is a docker issue... more investigation needed...

If you have a sec could you try this one and see (it sets things to version 3, which I forgot when I pasted the first one)
https://gist.github.com/ilude/ba7a5a6df7decb369bfbdc4b562d5ad9

Back to the issue at large: if 3.7 will address this then I can wait, and I sort of understand your desire to push this off. I'm using my own dockerfile now that incorporates my fix and the healtcheck, so its not a show stopper for me, but I would prefer not to manage my own rabbitmq images long term and instead rely on the official image.

[yosifkit]

If you are using a - (ie an array of items for environment), then each item needs to be in the format of "key=value". Also, erlang parses for a single string after log_levels, so any spaces from that need to be removed as well.

version: '3'
services:
  rabbitmq:
        image: rabbitmq:3.6.12
        hostname: rabbitmq
        ports:
          - "5672:5672"
          - "15672:15672"
        environment:
          - "RABBITMQ_SERVER_ADDITIONAL_ERL_ARGS=-rabbit log_levels [{connection,warning},{channel,warning}]"

# or like this:
        environment:
          RABBITMQ_SERVER_ADDITIONAL_ERL_ARGS: "-rabbit log_levels [{connection,warning},{channel,warning}]"

[ilude]

Thanks @yosifkit it's now working with the following docker-compose.yml.

version: '3'
services:
  rabbitmq:
    image: rabbitmq:3.6.12
    hostname: rabbitmq
    ports:
      - "5672:5672"
      - "15672:15672"
    environment:
      RABBITMQ_SERVER_ADDITIONAL_ERL_ARGS: "-rabbit log_levels [{connection,warning},{channel,warning}]"

The spaces were the root of my troubles and sub-optimal user experience. They are not an issue within the configuration file for rabbitmq, so I would have never guessed that they would be an issue when passed via the command line (That's my lack of Erlang knowledge, I know).

[kernel-sanders]

Still can't get this working with docker-compose. Using @ilude's environment setting I am still seeing the =INFO REPORT=== spam on startup but when I run docker-compose exec -T rabbitmq rabbitmqctl environment | grep log_levels it claims to be {log_levels,[{connection,warning},{channel,warning}]}. Any idea where I am going wrong?

[michaelklishin]

Note that the RABBITMQ_SERVER_ADDITIONAL_ERL_ARGS value has to be quoted since it contains spaces.

[michaelklishin]

@kernel-sanders I know this is not the answer your are looking for but I'm in a mood to be particularly annoying: do not disable those "spam" log entries. They will be very handy next time — and it's a matter of when, not if — you have to investigate a problem with one of your applications. Unless you collect a really large number of metrics, including connection attempts/successes/failures per app e.g. using rabbitmq-event-exchange, connection lifecycle events in the log are really useful.

[michaelklishin]

@kernel-sanders your config (assuming you didn't get the nesting wrong which with RABBITMQ_SERVER_ADDITIONAL_ERL_ARGS is difficult to do) instructs RabbitMQ to log connection and channel events as warnings. Boot events are neither of those.

A generic UNIX package node started as

RABBITMQ_SERVER_ADDITIONAL_ERL_ARGS="-rabbit log_levels [{connection,warning},{channel,warning}]" rabbitmq-server

logs

=INFO REPORT==== 27-Sep-2017::08:38:50 ===
Starting RabbitMQ 3.6.12 on Erlang 19.3.6
Copyright (C) 2007-2017 Pivotal Software, Inc.
Licensed under the MPL.  See http://www.rabbitmq.com/

=INFO REPORT==== 27-Sep-2017::08:38:50 ===
node           : rabbit@mercurio
home dir       : …
config file(s) : …/Tools/rabbitmq/generic/etc/rabbitmq/rabbitmq.config
cookie hash    : 3Ep2IzZ27XUnuIsAg7vzJg==
log            : …/Tools/rabbitmq/generic/var/log/rabbitmq/[email protected]
sasl log       : …/Tools/rabbitmq/generic/var/log/rabbitmq/[email protected]
database dir   : …/Tools/rabbitmq/generic/var/lib/rabbitmq/mnesia/rabbit@mercurio

=INFO REPORT==== 27-Sep-2017::08:38:54 ===
Memory high watermark set to 3276 MiB (3435973836 bytes) of 8192 MiB (8589934592 bytes) total

=INFO REPORT==== 27-Sep-2017::08:38:54 ===
Enabling free disk space monitoring

=INFO REPORT==== 27-Sep-2017::08:38:54 ===
Disk free limit set to 50MB

=INFO REPORT==== 27-Sep-2017::08:38:54 ===
Limiting to approx 499900 file handles (449908 sockets)

=INFO REPORT==== 27-Sep-2017::08:38:54 ===
FHC read buffering:  OFF
FHC write buffering: ON

=INFO REPORT==== 27-Sep-2017::08:38:54 ===
Waiting for Mnesia tables for 30000 ms, 9 retries left

=INFO REPORT==== 27-Sep-2017::08:38:54 ===
Waiting for Mnesia tables for 30000 ms, 9 retries left

=INFO REPORT==== 27-Sep-2017::08:38:54 ===
Priority queues enabled, real BQ is rabbit_variable_queue

=INFO REPORT==== 27-Sep-2017::08:38:54 ===
Starting rabbit_node_monitor

=INFO REPORT==== 27-Sep-2017::08:38:54 ===
Management plugin: using rates mode 'basic'

=INFO REPORT==== 27-Sep-2017::08:38:54 ===
msg_store_transient: using rabbit_msg_store_ets_index to provide index

=INFO REPORT==== 27-Sep-2017::08:38:54 ===
msg_store_persistent: using rabbit_msg_store_ets_index to provide index

=INFO REPORT==== 27-Sep-2017::08:38:54 ===
started TCP Listener on [::]:5672

=INFO REPORT==== 27-Sep-2017::08:38:54 ===
started SSL Listener on [::]:5671

=INFO REPORT==== 27-Sep-2017::08:38:55 ===
rabbit_stomp: default user 'guest' enabled

=INFO REPORT==== 27-Sep-2017::08:38:55 ===
started STOMP TCP Listener on [::]:61613

=INFO REPORT==== 27-Sep-2017::08:38:55 ===
MQTT retained message store: rabbit_mqtt_retained_msg_store_dets

=INFO REPORT==== 27-Sep-2017::08:38:55 ===
started MQTT TCP Listener on [::]:1883

=INFO REPORT==== 27-Sep-2017::08:38:55 ===
rabbit_web_mqtt: listening for HTTP connections on 0.0.0.0:15675

=INFO REPORT==== 27-Sep-2017::08:38:55 ===
Management plugin started. Port: 15672

=INFO REPORT==== 27-Sep-2017::08:38:55 ===
Statistics database started.

=INFO REPORT==== 27-Sep-2017::08:38:55 ===
opening log file: "/tmp/rabbit-mgmt/access.log.2017_09_27_05"

=INFO REPORT==== 27-Sep-2017::08:38:55 ===
Server startup complete; 15 plugins started.
 * rabbitmq_consistent_hash_exchange
 * rabbitmq_shovel_management
 * rabbitmq_management
 * rabbitmq_web_dispatch
 * rabbitmq_shovel
 * rabbitmq_web_mqtt
 * rabbitmq_mqtt
 * rabbitmq_auth_mechanism_ssl
 * rabbitmq_jms_topic_exchange
 * rabbitmq_random_exchange
 * rabbitmq_stomp
 * rabbitmq_management_agent
 * cowboy
 * cowlib
 * amqp_client

but when I open a connection from a REPL, it is not logged even though it does send data.

Is there a way to disable those entries in 3.6.x? There is no. In 3.7.0 there might be since logging
configuration is a lot more flexible.

And I don't consider it to be a problem: we see a lot of questions from RabbitMQ users that can be fairly quickly answered after a glance at the log. If all plugin activation, protocol listener and log/data/config file information were gone from the log, there would be little to work with when troubleshooting.

[kernel-sanders]

@michaelklishin I appreciate you taking the time to explain this.

[ilude]

@michaelklishin your points on logging are valid for a production system, and there I would have the logging set to info or even debug. But, at least for me, production logging is pushed into a logging pipeline that allows filtering of that messaging. In a dev environment build on docker-compose everything gets dumped to STDOUT. So its very nice to be able to turn logging down on parts of the system you are not actually developing against.