Logging of credentials when opening a new connection

[arfl]

Hello.

For a couple of days, we get much more output when opening new RabbitMQ connections using AMQP.Connection.open/1 (recently, we updated elixir to version 1.11.1).

iex(4)> AMQP.Connection.open("amqp://localhost")
[info]     :supervisor: {#PID<0.1217.0>, :amqp_connection_sup}
    :started: [
  pid: #PID<0.1218.0>,
  name: :connection_type_sup,
  mfargs: {:amqp_connection_type_sup, :start_link, []},
  restart_type: :transient,
  shutdown: :infinity,
  child_type: :supervisor
]
[info]     :supervisor: {#PID<0.1217.0>, :amqp_connection_sup}
    :started: [
  pid: #PID<0.1219.0>,
  name: :connection,
  mfargs: {:amqp_gen_connection, :start_link,
   [
     #PID<0.1218.0>,
     {:amqp_params_network, "guest", {:plaintext, "guest"}, "/", 'localhost',
      5672, 2047, 0, 10, 60000, :none,
      [#Function<11.12217282/3 in :amqp_uri.mechanisms/1>,
       #Function<11.12217282/3 in :amqp_uri.mechanisms/1>], [], []}
   ]},
  restart_type: :intrinsic,
  shutdown: :brutal_kill,
  child_type: :worker
]
[info]     :supervisor: {#PID<0.1218.0>, :amqp_connection_type_sup}
    :started: [
  pid: #PID<0.1220.0>,
  name: :channel_sup_sup,
  mfargs: {:amqp_channel_sup_sup, :start_link,
   [:network, #PID<0.1219.0>, "client 127.0.0.1:61146 -> 127.0.0.1:5672"]},
  restart_type: :intrinsic,
  shutdown: :infinity,
  child_type: :supervisor
]
[info]     :supervisor: {#PID<0.1218.0>, :amqp_connection_type_sup}
    :started: [
  pid: #PID<0.1221.0>,
  name: :channels_manager,
  mfargs: {:amqp_channels_manager, :start_link,
   [#PID<0.1219.0>, "client 127.0.0.1:61146 -> 127.0.0.1:5672", #PID<0.1220.0>]},
  restart_type: :transient,
  shutdown: 30000,
  child_type: :worker
]
[info]     :supervisor: {#PID<0.1218.0>, :amqp_connection_type_sup}
    :started: [
  pid: #PID<0.1222.0>,
  name: :writer,
  mfargs: {:rabbit_writer, :start_link,
   [#Port<0.216>, 0, 4096, :rabbit_framing_amqp_0_9_1, #PID<0.1219.0>,
    "client 127.0.0.1:61146 -> 127.0.0.1:5672", false, 1000000000]},
  restart_type: :transient,
  shutdown: 30000,
  child_type: :worker
]
[info]     :supervisor: {#PID<0.1218.0>, :amqp_connection_type_sup}
    :started: [
  pid: #PID<0.1223.0>,
  name: :main_reader,
  mfargs: {:amqp_main_reader, :start_link,
   [
     #Port<0.216>,
     #PID<0.1219.0>,
     #PID<0.1221.0>,
     {:method, :rabbit_framing_amqp_0_9_1},
     "client 127.0.0.1:61146 -> 127.0.0.1:5672"
   ]},
  restart_type: :transient,
  shutdown: 30000,
  child_type: :worker
]
[info]     :supervisor: {#PID<0.1218.0>, :amqp_connection_type_sup}
    :started: [
  pid: #PID<0.1224.0>,
  name: :heartbeat_sender,
  mfargs: {:rabbit_heartbeat, :start_heartbeat_sender,
   [
     #Port<0.216>,
     10,
     #Function<2.52632387/0 in :amqp_network_connection.start_heartbeat/1>,
     {:heartbeat_sender, "client 127.0.0.1:61146 -> 127.0.0.1:5672"}
   ]},
  restart_type: :transient,
  shutdown: 30000,
  child_type: :worker
]
[info]     :supervisor: {#PID<0.1218.0>, :amqp_connection_type_sup}
    :started: [
  pid: #PID<0.1225.0>,
  name: :heartbeat_receiver,
  mfargs: {:rabbit_heartbeat, :start_heartbeat_receiver,
   [
     #Port<0.216>,
     10,
     #Function<3.52632387/0 in :amqp_network_connection.start_heartbeat/1>,
     {:heartbeat_receiver, "client 127.0.0.1:61146 -> 127.0.0.1:5672"}
   ]},
  restart_type: :transient,
  shutdown: 30000,
  child_type: :worker
]
{:ok, %AMQP.Connection{pid: #PID<0.1219.0>}}

The following output is very problematic:

[info]     :supervisor: {#PID<0.1217.0>, :amqp_connection_sup}
    :started: [
  pid: #PID<0.1219.0>,
  name: :connection,
  mfargs: {:amqp_gen_connection, :start_link,
   [
     #PID<0.1218.0>,
     {:amqp_params_network, "guest", {:plaintext, "guest"}, "/", 'localhost',
      5672, 2047, 0, 10, 60000, :none,
      [#Function<11.12217282/3 in :amqp_uri.mechanisms/1>,
       #Function<11.12217282/3 in :amqp_uri.mechanisms/1>], [], []}
   ]},
  restart_type: :intrinsic,
  shutdown: :brutal_kill,
  child_type: :worker

You can see, that :amqp_params_network logs the credentials and the server name as plaintext.

How is it possible to disable this output? Our config contains already the following configuration for the :lager package.

config :lager,
  error_logger_redirect: false,
  handlers: [level: :critical]

Thank you!

[JackParkes1]

I've got this same issue. Setting the level in the logs doesn't have any effect. Would love a solution, thanks.

[JackParkes1]

@arfl I think I just solved this. Adding

config :logger,
    level: :error

prevented the output. I don't know why AMQP is logging with the standard logger instead of lager, but hey, it's something

[ono]

Have you tried https://github.com/pma/amqp#log-related-to-amqp-supervisors-are-too-verbose ? :logger.add_primary_filter/2 solution works for me. If it doesn't work, do you mind sharing a sample repo that lets me reproduce the issue? Please specify Elixir and OTP versions too.

I understand it's not an ideal solution though. It might be a good idea to suggest the upstream (RabbitMQ team) to obfuscate the password at least.

[arfl]

:logger.add_primary_filter/2 solution used to work for us. It does not anymore.
config :logger, handle_otp_reports: false does not work either...

@ono Do you know the source of this output? Official rabbitmq erlang client?

[ono]

@arfl

yes, it's done by erlang library (amqp_client/rabbit_common).

like i said, i am happy to take a look if you can share a sample repo that reproduces the issue with :logger.add_primary_filter/2 solution. I tried with Elixir 1.11.2 and rabbit_common 3.8.9 but the solution still works.

[JackParkes1]

I've just tested the :logger.add_primary_filter/2 solution for Elixir 1.11.1 and rabbit_common 3.8.9 and it works. Thanks for pointing that out. Much better than filtering all logs as I did before.

[arfl]

Hi. I've just tested the solution with :logger.add_primary_filter/2 again and it works actually. It was my mistake that I put the filter code in the config.exs file instead of the start function of my application.
Thank you for your help!

[ono]

@arfl

Thanks for the update. No problem at all!

This makes me think what this library can do better on this. This workaround is not ideal obviously...