ssl: Add logging for TLS Handshake Protocol

- Add logging for TLS Handshake messages.
- Remove version from the input map used in format/2.

Change-Id: I1a8a3dbe5854d3b25cca33e9a6634ac9a53d5867

4 files changed, 130 insertions, 42 deletions

diff --git a/lib/ssl/src/logger_ssl_formatter.erl b/lib/ssl/src/logger_ssl_formatter.erl
index 5e897a33c5..de4c09be79 100644
--- a/lib/ssl/src/logger_ssl_formatter.erl
+++ b/lib/ssl/src/logger_ssl_formatter.erl
@@ -27,34 +27,126 @@
            ((X) >= 10) andalso ((X) =< 15) -> (X) + $a - 10
         end).
 
+-define(rec_info(T,R),lists:zip(record_info(fields,T),tl(tuple_to_list(R)))).
+
+-include("tls_record.hrl").
+-include("ssl_internal.hrl").
+-include("tls_handshake.hrl").
+
 %%-------------------------------------------------------------------------
 %% External API
 %%-------------------------------------------------------------------------
 format(#{level:= _Level, msg:= {report, Msg}, meta:= _Meta}, _Config0) ->
      #{direction := Direction,
        protocol := Protocol,
-       version := Version,
        message := BinMsg0} = Msg,
     case Protocol of
         'tls_record' ->
             BinMsg = lists:flatten(BinMsg0),
-            format_tls_record(Direction, Version, BinMsg);
+            format_tls_record(Direction, BinMsg);
         'handshake' ->
-            [];
+            format_handshake(Direction, BinMsg0);
         _Other ->
             []
     end.
 
 
 %%-------------------------------------------------------------------------
-%% Internal functions
+%% Handshake Protocol
+%%-------------------------------------------------------------------------
+format_handshake(Direction, BinMsg) ->
+    {Header, Message} = parse_handshake(Direction, BinMsg),
+    io_lib:format("~s~n~s~n", [Header, Message]).
+
+
+parse_handshake(Direction, #client_hello{
+                              client_version = Version
+                             } = ClientHello) ->
+    Header = io_lib:format("~s ~s Handshake, ClientHello",
+                           [header_prefix(Direction),
+                            version(Version)]),
+    Message = io_lib:format("~p", [?rec_info(client_hello, ClientHello)]),
+    {Header, Message};
+parse_handshake(Direction, #server_hello{
+                              server_version = Version
+                             } = ServerHello) ->
+    Header = io_lib:format("~s ~s Handshake, ServerHello",
+                           [header_prefix(Direction),
+                            version(Version)]),
+    Message = io_lib:format("~p", [?rec_info(server_hello, ServerHello)]),
+    {Header, Message};
+parse_handshake(Direction, #certificate{} = Certificate) ->
+    Header = io_lib:format("~s Handshake, Certificate",
+                           [header_prefix(Direction)]),
+    Message = io_lib:format("~p", [?rec_info(certificate, Certificate)]),
+    {Header, Message};
+parse_handshake(Direction, #server_key_exchange{} = ServerKeyExchange) ->
+    Header = io_lib:format("~s Handshake, ServerKeyExchange",
+                           [header_prefix(Direction)]),
+    Message = io_lib:format("~p", [?rec_info(server_key_exchange, ServerKeyExchange)]),
+    {Header, Message};
+parse_handshake(Direction, #server_key_params{} = ServerKeyExchange) ->
+    Header = io_lib:format("~s Handshake, ServerKeyExchange",
+                           [header_prefix(Direction)]),
+    Message = io_lib:format("~p", [?rec_info(server_key_params, ServerKeyExchange)]),
+    {Header, Message};
+parse_handshake(Direction, #certificate_request{} = CertificateRequest) ->
+    Header = io_lib:format("~s Handshake, CertificateRequest",
+                           [header_prefix(Direction)]),
+    Message = io_lib:format("~p", [?rec_info(certificate_request, CertificateRequest)]),
+    {Header, Message};
+parse_handshake(Direction, #server_hello_done{} = ServerHelloDone) ->
+    Header = io_lib:format("~s Handshake, ServerHelloDone",
+                           [header_prefix(Direction)]),
+    Message = io_lib:format("~p", [?rec_info(server_hello_done, ServerHelloDone)]),
+    {Header, Message};
+parse_handshake(Direction, #client_key_exchange{} = ClientKeyExchange) ->
+    Header = io_lib:format("~s Handshake, ClientKeyExchange",
+                           [header_prefix(Direction)]),
+    Message = io_lib:format("~p", [?rec_info(client_key_exchange, ClientKeyExchange)]),
+    {Header, Message};
+parse_handshake(Direction, #certificate_verify{} = CertificateVerify) ->
+    Header = io_lib:format("~s Handshake, CertificateVerify",
+                           [header_prefix(Direction)]),
+    Message = io_lib:format("~p", [?rec_info(certificate_verify, CertificateVerify)]),
+    {Header, Message};
+parse_handshake(Direction, #finished{} = Finished) ->
+    Header = io_lib:format("~s Handshake, Finished",
+                           [header_prefix(Direction)]),
+    Message = io_lib:format("~p", [?rec_info(finished, Finished)]),
+    {Header, Message};
+parse_handshake(Direction, #hello_request{} = HelloRequest) ->
+    Header = io_lib:format("~s Handshake, HelloRequest",
+                           [header_prefix(Direction)]),
+    Message = io_lib:format("~p", [?rec_info(hello_request, HelloRequest)]),
+    {Header, Message}.
+
+
+version({3,3}) ->
+    "TLS 1.2";
+version({3,2}) ->
+    "TLS 1.1";
+version({3,1}) ->
+    "TLS 1.0";
+version({3,0}) ->
+    "SSL 3.0".
+
+
+header_prefix(inbound) ->
+    "<<<";
+header_prefix(outbound) ->
+    ">>>".
+
+
+%%-------------------------------------------------------------------------
+%% TLS Record Protocol
 %%-------------------------------------------------------------------------
-format_tls_record(Direction, Version, BinMsg) ->
+format_tls_record(Direction, BinMsg) ->
     {Message, Size} = convert_to_hex('tls_record', BinMsg),
     Header = io_lib:format("~s (~B bytes) ~s~n",
-                            [header_prefix_tls_record(Direction),
-                             Size,
-                            tls_record_version(Version, BinMsg)]),
+                           [header_prefix_tls_record(Direction),
+                            Size,
+                            tls_record_version(BinMsg)]),
     Header ++ Message.
 
 
@@ -65,23 +157,15 @@ header_prefix_tls_record(outbound) ->
 
 
 
-tls_record_version({3,3}, [<<B,_/binary>>|_]) ->
+tls_record_version([<<?BYTE(B),?BYTE(3),?BYTE(3),_/binary>>|_]) ->
     io_lib:format("TLS 1.2 Record Protocol, ~s", [msg_type(B)]);
-tls_record_version({3,2}, [<<B,_/binary>>|_]) ->
+tls_record_version([<<?BYTE(B),?BYTE(3),?BYTE(2),_/binary>>|_]) ->
     io_lib:format("TLS 1.1 Record Protocol, ~s", [msg_type(B)]);
-tls_record_version({3,1}, [<<B,_/binary>>|_]) ->
+tls_record_version([<<?BYTE(B),?BYTE(3),?BYTE(1),_/binary>>|_]) ->
     io_lib:format("TLS 1.0 Record Protocol, ~s", [msg_type(B)]);
-tls_record_version({3,0}, [<<B,_/binary>>|_]) ->
+tls_record_version([<<?BYTE(B),?BYTE(3),?BYTE(0),_/binary>>|_]) ->
     io_lib:format("SSL 3.0 Record Protocol, ~s", [msg_type(B)]).
 
-tls_version({3,3}, [<<B,_/binary>>|_]) ->
-    io_lib:format("TLS 1.2 Handshake, ~s", [msg_type(B)]);
-tls_version({3,2}, [<<B,_/binary>>|_]) ->
-    io_lib:format("TLS 1.1 Handshake, ~s", [msg_type(B)]);
-tls_version({3,1}, [<<B,_/binary>>|_]) ->
-    io_lib:format("TLS 1.0 Handshake, ~s", [msg_type(B)]);
-tls_version({3,0}, [<<B,_/binary>>|_]) ->
-    io_lib:format("SSL 3.0 Handshake, ~s", [msg_type(B)]).
 
 msg_type(20) -> "change_cipher_spec";
 msg_type(21) -> "alert";
@@ -90,6 +174,9 @@ msg_type(23) -> "application_data";
 msg_type(_) -> unknown.
 
 
+%%-------------------------------------------------------------------------
+%% Hex encoding functions
+%%-------------------------------------------------------------------------
 convert_to_hex(Protocol, BinMsg) ->
     convert_to_hex(Protocol, BinMsg, [], [], 0).
 %%
@@ -160,15 +247,11 @@ convert_to_hex(P, [H|T], Row, Acc, C) when is_integer(H) ->
 
 row_prefix(tls_record, N) ->
     S = string:pad(string:to_lower(erlang:integer_to_list(N, 16)),4,leading,$0),
-    lists:reverse(lists:flatten(S ++ " - "));
-row_prefix(handshake, _) ->
-    "   ".
+    lists:reverse(lists:flatten(S ++ " - ")).
 
 
 end_row(tls_record, Row) ->
-    Row ++ "  ";
-end_row(_, Row) ->
-    Row.
+    Row ++ "  ".
 
 
 %% Calculate padding of the "printable character" lines in order to be
diff --git a/lib/ssl/src/tls_connection.erl b/lib/ssl/src/tls_connection.erl
index 6b9e4540f4..f1291ec7b4 100644
--- a/lib/ssl/src/tls_connection.erl
+++ b/lib/ssl/src/tls_connection.erl
@@ -270,8 +270,11 @@ queue_handshake(Handshake, #state{negotiated_version = Version,
 	encode_handshake(Handshake, Version, ConnectionStates0, Hist0),
     Report = #{direction => outbound,
                protocol => 'tls_record',
-               message => BinHandshake,
-               version => Version},
+               message => BinHandshake},
+    HandshakeMsg = #{direction => outbound,
+                     protocol => 'handshake',
+                     message => Handshake},
+    logger:info(HandshakeMsg, #{domain => [beam,erlang,otp,ssl,handshake]}),
     logger:info(Report, #{domain => [beam,erlang,otp,ssl,tls_record]}),
     State0#state{connection_states = ConnectionStates,
 		 tls_handshake_history = Hist,
@@ -290,8 +293,7 @@ queue_change_cipher(Msg, #state{negotiated_version = Version,
 	encode_change_cipher(Msg, Version, ConnectionStates0),
     Report = #{direction => outbound,
                protocol => 'tls_record',
-               message => BinChangeCipher,
-               version => Version},
+               message => BinChangeCipher},
     logger:info(Report, #{domain => [beam,erlang,otp,ssl,tls_record]}),
     State0#state{connection_states = ConnectionStates,
 		 flight_buffer = Flight0 ++ [BinChangeCipher]}.
@@ -327,8 +329,7 @@ send_alert(Alert, #state{negotiated_version = Version,
     send(Transport, Socket, BinMsg),
     Report = #{direction => outbound,
                protocol => 'tls_record',
-               message => BinMsg,
-               version => Version},
+               message => BinMsg},
     logger:info(Report, #{domain => [beam,erlang,otp,ssl,tls_record]}),
 
     State0#state{connection_states = ConnectionStates}.
@@ -435,8 +436,11 @@ init({call, From}, {start, Timeout},
     send(Transport, Socket, BinMsg),
     Report = #{direction => outbound,
                protocol => 'tls_record',
-               message => BinMsg,
-               version => HelloVersion},
+               message => BinMsg},
+    HelloMsg = #{direction => outbound,
+               protocol => 'handshake',
+               message => Hello},
+    logger:info(HelloMsg, #{domain => [beam,erlang,otp,ssl,handshake]}),
     logger:info(Report, #{domain => [beam,erlang,otp,ssl,tls_record]}),
     State1 = State0#state{connection_states = ConnectionStates,
 			  negotiated_version = Version, %% Requested version
diff --git a/lib/ssl/src/tls_handshake.erl b/lib/ssl/src/tls_handshake.erl
index f1eecb2875..42b457d24a 100644
--- a/lib/ssl/src/tls_handshake.erl
+++ b/lib/ssl/src/tls_handshake.erl
@@ -272,6 +272,11 @@ get_tls_handshake_aux(Version, <<?BYTE(Type), ?UINT24(Length),
     Raw = <<?BYTE(Type), ?UINT24(Length), Body/binary>>,
     try decode_handshake(Version, Type, Body) of
 	Handshake ->
+            Report = #{direction => inbound,
+                       protocol => 'handshake',
+                       message => Handshake,
+                       version => Version},
+            logger:info(Report, #{domain => [beam,erlang,otp,ssl,handshake]}),
 	    get_tls_handshake_aux(Version, Rest, Opts, [{Handshake,Raw} | Acc])
     catch
 	_:_ ->
diff --git a/lib/ssl/src/tls_record.erl b/lib/ssl/src/tls_record.erl
index 78e2cce81e..05c5d703a9 100644
--- a/lib/ssl/src/tls_record.erl
+++ b/lib/ssl/src/tls_record.erl
@@ -404,8 +404,7 @@ get_tls_records_aux(<<?BYTE(?APPLICATION_DATA),?BYTE(MajVer),?BYTE(MinVer),
                      ?UINT16(Length), Data:Length/binary>>,
     Report = #{direction => inbound,
                protocol => 'tls_record',
-               message => [RawTLSRecord],
-               version => {MajVer, MinVer}},
+               message => [RawTLSRecord]},
     logger:info(Report, #{domain => [beam,erlang,otp,ssl,tls_record]}),
     get_tls_records_aux(Rest, [#ssl_tls{type = ?APPLICATION_DATA,
 					version = {MajVer, MinVer},
@@ -417,8 +416,7 @@ get_tls_records_aux(<<?BYTE(?HANDSHAKE),?BYTE(MajVer),?BYTE(MinVer),
                      ?UINT16(Length), Data:Length/binary>>,
     Report = #{direction => inbound,
                protocol => 'tls_record',
-               message => [RawTLSRecord],
-               version => {MajVer, MinVer}},
+               message => [RawTLSRecord]},
     logger:info(Report, #{domain => [beam,erlang,otp,ssl,tls_record]}),
     get_tls_records_aux(Rest, [#ssl_tls{type = ?HANDSHAKE,
 					version = {MajVer, MinVer},
@@ -430,8 +428,7 @@ get_tls_records_aux(<<?BYTE(?ALERT),?BYTE(MajVer),?BYTE(MinVer),
                      ?UINT16(Length), Data:Length/binary>>,
     Report = #{direction => inbound,
                protocol => 'tls_record',
-               message => [RawTLSRecord],
-               version => {MajVer, MinVer}},
+               message => [RawTLSRecord]},
     logger:info(Report, #{domain => [beam,erlang,otp,ssl,tls_record]}),
     get_tls_records_aux(Rest, [#ssl_tls{type = ?ALERT,
 					version = {MajVer, MinVer},
@@ -443,8 +440,7 @@ get_tls_records_aux(<<?BYTE(?CHANGE_CIPHER_SPEC),?BYTE(MajVer),?BYTE(MinVer),
                      ?UINT16(Length), Data:Length/binary>>,
     Report = #{direction => inbound,
                protocol => 'tls_record',
-               message => [RawTLSRecord],
-               version => {MajVer, MinVer}},
+               message => [RawTLSRecord]},
     logger:info(Report, #{domain => [beam,erlang,otp,ssl,tls_record]}),
     get_tls_records_aux(Rest, [#ssl_tls{type = ?CHANGE_CIPHER_SPEC,
 					version = {MajVer, MinVer},