Custom formatter for logs coming from :ssl application. How?

Questions / Help
, , ,
1

I’m failing to use my own custom module to format log entries coming from :ssl application, under OTP 25. Here’s my code:

require Logger

defmodule MyFormatter do
  def format(level, message, _timestamp, _metadata) do
    ['[', level, ']', 'Simon says:', message, ?\n]
  end
end

:inets.start()
:ssl.start()

:ok = :logger.update_handler_config(:ssl_handler, :formatter, {MyFormatter, %{}})

:httpc.request('https://github.com')

The output still prints what looks like a default message:

11:50:31.761 [warning] Description: ~c"Server authenticity is not verified since certificate path validation is not enabled"
     Reason: ~c"The option {verify, verify_peer} and one of the options 'cacertfile' or 'cacerts' are required to enable this."

If I check handler configuration via :logger.get_handler_config(:ssl_handler) it looks as expected:

{:ok,
 %{
   config: %{
     burst_limit_enable: true,
     burst_limit_max_count: 500,
     burst_limit_window_time: 1000,
     drop_mode_qlen: 200,
     filesync_repeat_interval: :no_repeat,
     flush_qlen: 1000,
     overload_kill_enable: false,
     overload_kill_mem_size: 3000000,
     overload_kill_qlen: 20000,
     overload_kill_restart_after: 5000,
     sync_mode_qlen: 10,
     type: :standard_io
   },
   filter_default: :stop,
   filters: [
     filter_non_ssl: {&:logger_filters.domain/2, {:log, :sub, [:otp, :ssl]}}
   ],
   formatter: {MyFormatter, %{}},
   id: :ssl_handler,
   level: :debug,
   module: :logger_std_h
 }}

What I might be doing wrong? :thinking:

1 Like
2

Your format function looks incorrect. It should take only two arguments - the log event and the formatter configuration, as per docs.

3

That doesn’t seem to help :confused:

I just tried a simple thing to rule out possibility that I am misconfiguring the logger: removal of handler. It doesn’t work either:

defmodule MyFormatter do
  def format(value1, value2) do
    ['[', value1, ']', 'Simon says:', value2, ?\n]
  end
end

:inets.start()
:ssl.start()

:ok = :logger.remove_handler(:ssl_handler)

:httpc.request('https://github.com')

So now I there are two possibilities left:

  1. either I am modifying something wrong, that’s not related to logs coming from SSL application,
  2. or some logging facility somewhere needs to notified of the change, and re-read the config

:thinking:

4

Yes, the values that are passed to the formatter aren’t strings. That is your problem. Check out documentation

https://erlang.org/doc/man/logger.html#FModule:format-2

It says that 1st argument is log_event() which is a map, and 2nd argument is a formatter_config() which happens to be map as well. Your function then should return unicode:chardata(). In your case you break that contract and instead you return list that is mix between chartists, maps, and integers.

2 Likes
5

Would Jason.encode! help? :thinking:

  def format(value1, value2) do
    ['[', Jason.encode!(value1), ']', 'Simon says:', Jason.encode!(value2), ?\n]
  end
6

If these values are JSON encodable (hint - usually they are not).

1 Like
7

@hauleth thanks! I’ve modified the code according to your comment about the contract,
but the original issue is still there - this code prints “typical” output, and not the
“This log entry is redacted completely”.

Can you spot an issue with this code?

require Logger

defmodule MyFormatter do
  def format(_value1, _value2) do
    "This log entry is redacted completely"
  end
end

:inets.start()
:ssl.start()

:ok = :logger.update_handler_config(:ssl_handler, :formatter, {MyFormatter, %{}})

:httpc.request('https://github.com')

I wonder if I have the wrong expectations regarding how the formatter for :ssl_handler
must be updated, for the update to take effect :thinking:

8

I spent some time to look into your issue and found out that if I set filter_default of ssl_handler to true via

:logger.update_handler_config(:ssl_handler, :filter_default, :log)

the custom formatter is called.

Edit: On a second thought, it’s natural for your formatter to not be called because the log event is filtered out by ssl’s filter_non_ssl filter. Combined with filter_default: :stop, the log event is not getting to the handler at all.

9

Thanks for looking into this @krasenyp! But unfortunately, even adding that line doesn’t exactly work as expected - e.g. will not replace the “warning”. If I add a line that you mentioned, I see this output:

This log entry is redacted completely
15:10:22.096 [warning] Description: ~c"Server authenticity is not verified since certificate path validation is not enabled"
     Reason: ~c"The option {verify, verify_peer} and one of the options 'cacertfile' or 'cacerts' are required to enable this."

The expectation is that “Description: …” and “Reason: …” lines are gone completely :thinking: