inet_tls/logger/report_cb combo losing information

[Loïc Hoguin]

D’oh! As they say. Makes sense now. Thanks!

--
Loïc Hoguin

From: Ingela Andin <ingela.andin@REDACTED>
Date: Thursday 14 October 2021 at 15:08
To: Loïc Hoguin <lhoguin@REDACTED>
Cc: Erlang Questions <erlang-questions@REDACTED>
Subject: Re: inet_tls/logger/report_cb combo losing information

Hi!

It is not a logger problem, the first log is done by the client that knows why it is failing the connection and it will give you as much info as advisable as to why.  While
the server only will receive the TLS alert chosen and does not have the knowledge of why.

Regards Ingela


Den tors 14 okt. 2021 kl 13:58 skrev Loïc Hoguin <lhoguin@REDACTED<mailto:lhoguin@REDACTED>>:
Hello,

I am trying to understand why there is a difference between the logs from a simple erl node compared to a node that has logger configuration with a handler that customizes the output and logs to a file.

The message logged comes from a handshake error due to a bad certificate when another node is trying to connect through the TLS distribution.

On the simple erl node we get the following error:

=NOTICE REPORT==== 14-Oct-2021::11:23:43.108059 ===
TLS client: In state certify at ssl_handshake.erl:1901 generated CLIENT ALERT: Fatal - Handshake Failure
- {bad_cert,hostname_check_failed}

On the node with logger configuration we get this :


2021-10-14 11:23:43.108216+02:00 [noti] <0.575.0> TLS server: In state certify received CLIENT ALERT: Fatal - Handshake Failure

2021-10-14 11:23:43.108216+02:00 [noti] <0.575.0>

We are missing the bad_cert line and that’s bad because that line is fairly important for debugging the issue.

I have tracked down the error up until the call to ssl_logger:format/1. It receives the following argument:


#{alert =>

              {alert,2,40,

                     #{file => "ssl_alert.erl",line => 136,

                       mfa => {ssl_alert,decode,3}},

                     client,undefined},

          alerter => peer,protocol => "TLS",role => server,

          statename => certify}

As far as I can tell, based on this data, the output is expected.

For what it’s worth, the Meta information doesn’t have the extra info either:


#{depth => 20,file => "ssl_alert.erl",

                                   gl => <0.46.0>,line => 136,

                                   mfa => {ssl_alert,decode,3},

                                   pid => <0.690.0>,

                                   report_cb => fun ssl_logger:format/1,

                                   time => 1634210440978557}

My question therefore is: how can we get the {bad_cert,hostname_check_failed} line logged as well with our custom logger handler? Why is it in the notice report above but not in the logger event?

Thanks,

--
Loïc Hoguin
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://erlang.org/pipermail/erlang-questions/attachments/20211014/095f80e4/attachment.htm>