Verbose logging to stdout when application starts

[AndrewDryga]

Hi, we are seeing very verbose logging when :amqp application starts:

12:29:58.631 [info] [supervisor: {#PID<0.271.0>, :amqp_channel_sup}, started: [pid: #PID<0.274.0>, name: :writer, mfargs: {
:rabbit_writer, :start_link, [#Port<0.609>, 1, 131072, :rabbit_framing_amqp_0_9_1, #PID<0.273.0>, {"client 127.0.0.1:60871
-> 127.0.0.1:5672", 1}]}, restart_type: :transient, shutdown: 30000, child_type: :worker]]
12:29:58.646 [info] [supervisor: {#PID<0.278.0>, :amqp_channel_sup}, started: [pid: #PID<0.279.0>, name: :gen_consumer, mfa
rgs: {:amqp_gen_consumer, :start_link, [:amqp_selective_consumer, [], {"client 127.0.0.1:60871 -> 127.0.0.1:5672", 2}]}, re
start_type: :intrinsic, shutdown: 30000, child_type: :worker]]
12:29:58.646 [info] [supervisor: {#PID<0.278.0>, :amqp_channel_sup}, started: [pid: #PID<0.280.0>, name: :channel, mfargs:
{:amqp_channel, :start_link, [:network, #PID<0.261.0>, 2, #PID<0.279.0>, {"client 127.0.0.1:60871 -> 127.0.0.1:5672", 2}]},
 restart_type: :intrinsic, shutdown: 30000, child_type: :worker]]
12:29:58.647 [info] [supervisor: {#PID<0.278.0>, :amqp_channel_sup}, started: [pid: #PID<0.281.0>, name: :writer, mfargs: {
:rabbit_writer, :start_link, [#Port<0.609>, 2, 131072, :rabbit_framing_amqp_0_9_1, #PID<0.280.0>, {"client 127.0.0.1:60871
-> 127.0.0.1:5672", 2}]}, restart_type: :transient, shutdown: 30000, child_type: :worker]]
..

Version we are using: 1.0.0-pre.2 (last one before lager was introduced).
Elixir version:

Erlang/OTP 21 [erts-10.0.4] [source] [64-bit] [smp:8:8] [ds:8:8:10] [async-threads:1] [hipe] [dtrace]

Elixir 1.7.2 (compiled with Erlang/OTP 21)

SASL is disabled.

[Custodia]

👍 for this. Compile time purging doesn't seem to help either. I tried adding this to my config.exs:

config :logger,
  compile_time_purge_matching: [
    [application: :amqp]
  ]

[ono]

Sorry about the late reply. Can you give this a try?

config :logger, handle_otp_reports: false

[ono]

Feel free to reopen if the above doesn't solve the issue. I have added the information to README too. Thanks for reporting 👍

[AndrewDryga]

It definitely does not, we did a short dig and looks that those messages are logged before Elixir Logger is initialized (initialized 2nd time with configuration to be precise).

After Logger is initialized configuration works, but it takes time and a lot of noise is generated during that that one - you get large blob of text every time you run tests.

[ono]

Pushed a test branch: https://github.com/pma/amqp/tree/test/verbose-logging

When you check out this commit and run mix test, yes, you see tons of logging.

However I don't see the logging with this commit.

Is it an application specific issue? Do you mind writing up the steps to reproduce the issue with handle_otp_reports: false?

[AndrewDryga]

@ono so the main difference is that we use 1.0.0-pre.2 version of amqp, I believe logging works totally differently in 1.0.

[ono]

I tried with 1.0.0-pre.2 and handle_otp_reports option just works for me with the version too. I tried it with Elixir 1.7.4 (OTP 21) but I don't think it makes any difference.

v1.0.0-pre.2...master

I think that these logging were introduced by OTP 21.

[AndrewDryga]

@ono here is the true way to filter out those messages:

    :logger.add_primary_filter(
      :ignore_rabbitmq_progress_reports,
      {&:logger_filters.domain/2, {:stop, :equal, [:progress]}}
    )

The logs are coming from here: https://github.com/rabbitmq/rabbitmq-common/blob/da07128609739e1d840c00632bf0a72f11e81d04/src/supervisor2.erl#L1505-L1508.

[ono]

@AndrewDryga hey, sorry I've just noticed your comment. It's great. I am sharing the information on README.