sasl logging leaks sensitive data

[brainlid]

Environment

• Elixir: 1.4.5
• Erlang: Erlang/OTP 20 [erts-9.0]
• Operating system: Arch Linux w/ LTS kernel

Current behavior

We found a report like this in our production system logs. It includes full production DB credentials. I realize that this is just dumping the state of a process, but I have no means to handle or process the data prior to going into the logs.

=PROGRESS REPORT==== 31-Aug-2017::16:39:44 ===
          supervisor: {local,'Elixir.SomeApp.Repo'}
             started: [{pid,<0.473.0>},
                       {id,'Elixir.DBConnection.Poolboy'},
                       {mfargs,
                        {poolboy,start_link,
                         [[{name,{local,'Elixir.SomeApp.Repo.Pool'}},
                           {strategy,fifo},
                           {size,10},
                           {max_overflow,0},
                           {worker_module,
                            'Elixir.DBConnection.Poolboy.Worker'}],
                          {'Elixir.Postgrex.Protocol',
                           [{types,'Elixir.Ecto.Adapters.Postgres.TypeModule'},
                            {name,'Elixir.SomeApp.Repo.Pool'},
                            {otp_app,shared_db},
                            {repo,'Elixir.SomeApp.Repo'},
                            {pool_size,10},
                            {timeout,30000},
                            {adapter,'Elixir.Ecto.Adapters.Postgres'},
                            {database,<<"my_app_dev">>},
                            {username,<<"postgres">>},
                            {password,<<>>},
                            {hostname,<<"localhost">>},
                            {port,5432},
                            {pool_timeout,5000},
                            {pool_size,10},
                            {timeout,30000},
                            {adapter,'Elixir.Ecto.Adapters.Postgres'},
                            {database,<<"my_app_dev">>},
                            {username,<<"postgres">>},
                            {password,<<pass123123123>>},
                            {hostname,<<"localhost">>},
                            {pool,'Elixir.DBConnection.Poolboy'}]}]}},
                       {restart_type,permanent},
                       {shutdown,5000},
                       {child_type,worker}]

It includes the database name, username, password. Our production system is set to use a database url which also includes all of the sensitive information.

Expected behavior

That SASL logs might be piped through the Elixir logging so I can handle this myself, or there is some method for redacting the logs from sensitive production data being leaked to logs.

Additional Information

I have written a custom Elixir log formatter. It does not receive SASL log messages so I can't redact the information there.

Umbrella project with top-level config.exs overriding logging settings...

  config :logger, :console,
    handle_otp_reports: true,
    handle_sasl_reports: true,
    format: {Util.ConsoleFormatLogger, :format},
    compile_time_purge_level: :info,
    metadata: [:request_id, :application, :module, :ip, :endpoint, :uid, :oid, :type, :custom]

[josevalim]

I am not sure there is something we can do here. The SASL reports come directly from OTP and the truth is that any sensitive information in your callstack can also be reported from those.

@fishcakez, any ideas?

[brainlid]

I did find one workaround is to not start sasl until after my project is up-and-running. However, when the Ecto pool manager gets killed/dies, it will log that information then. But it doesn't show up when an individual connection is killed.

[fishcakez]

I don't think starting sasl later is a good option here because processes can crash or get restarted causing similar logs. Certainly its possible to disable logging in sasl (this is sasl printing these logs to stdout and not logger if @josevalim wasn't clear enough):

config :sasl, sasl_error_logger: false

WIth the logger configuration above in place one could set a Logger translator with:

config :logger, translators: [CustomTranslator, Logger.Translator]

It seems we don't have good documentation for this, see Logger.add_translator for information. You could add it that way also.

[brainlid]

@fishcakez Thanks for the translator information. I'll investigate that further. The OTP sasl reports are helpful as we enabled it recently and it helped me find a serious config problem I was diagnosing.

Thanks for the details and for confirming Elixir's role (or lack of) in this situation.

[fishcakez]

@brainlid the output in your first post is from the sasl error logger handler. However it is fine to disable sasls error handler and use Logger instead to log these reports. It seems you should be getting duplicate logs with your setup: one in Erlang format from sasl and one in elixir format from logger. These log messages are sent to the error logger regardless of whether sasl is started or not.

[OvermindDL1]

Well sasl logs a lot more than Logger overall though.

[fishcakez]

Logger will be logging the same as sasl with this option:

config : logger, handle_sasl_reports: true

[brainlid]

@fishcakez We only get the Erlang-style output (Elixir 1.4.5). This is my setup...

Umbrella's root level config.exs file contains:

  use Mix.Config

  config :my_app,
    ecto_repos: []

  import_config "../apps/*/config/config.exs"

  :ok = Application.ensure_started(:sasl)

  config :logger, :console,
    handle_otp_reports: true,
    handle_sasl_reports: true,
    format: {Util.ConsoleFormatLogger, :format},
    compile_time_purge_level: :info,
    metadata: [:request_id, :application, :module, :ip, :endpoint, :uid, :oid, :type, :custom]

Logger does not catch or display the OTP sasl messages. Without the .ensure_started(:sasl), we don't get any sasl messages.

I'm currently researching your previous suggestions.

[josevalim]

you need to make sure sasl is started before logger (or otherwise, i can't quite remember) by adding sasl to applications/extra_applications.

[fishcakez]

Logger does not catch or display the OTP sasl messages.

@brainlid Ah, I misread your configuration!

The following does not go in :console, it's a top level configuration in :logger

config :logger, :console,
    handle_otp_reports: true,
    handle_sasl_reports: true,
    ...
    compile_time_purge_level: :info,

Instead, it should be:

config :logger,
    handle_otp_reports: true,
    handle_sasl_reports: true,
    compile_time_purge_level: :info

[brainlid]

Well that makes a BIG difference!

The log messages now pass through my log formatter where I can redact known sensitive information. Thanks!