ssl: Add logging for TLS record protocol

Change-Id: I18786a9a8523d0ec3d9ca37ad5b2284721c5c4a1

5 files changed, 298 insertions, 18 deletions

diff --git a/lib/ssl/src/logger_ssl_formatter.erl b/lib/ssl/src/logger_ssl_formatter.erl
index b17100c1f5..5e897a33c5 100644
--- a/lib/ssl/src/logger_ssl_formatter.erl
+++ b/lib/ssl/src/logger_ssl_formatter.erl
@@ -1,7 +1,7 @@
 %%
 %% %CopyrightBegin%
 %%
-%% Copyright Ericsson AB 1999-2017. All Rights Reserved.
+%% Copyright Ericsson AB 1999-2018. All Rights Reserved.
 %%
 %% Licensed under the Apache License, Version 2.0 (the "License");
 %% you may not use this file except in compliance with the License.
@@ -22,5 +22,215 @@
 
 -export([format/2]).
 
-format(Log, Extra) ->
-     logger_formatter:format(Log, Extra).
+-define(DEC2HEX(X),
+        if ((X) >= 0) andalso ((X) =< 9) -> (X) + $0;
+           ((X) >= 10) andalso ((X) =< 15) -> (X) + $a - 10
+        end).
+
+%%-------------------------------------------------------------------------
+%% 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);
+        'handshake' ->
+            [];
+        _Other ->
+            []
+    end.
+
+
+%%-------------------------------------------------------------------------
+%% Internal functions
+%%-------------------------------------------------------------------------
+format_tls_record(Direction, Version, 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 ++ Message.
+
+
+header_prefix_tls_record(inbound) ->
+    "reading";
+header_prefix_tls_record(outbound) ->
+    "writing".
+
+
+
+tls_record_version({3,3}, [<<B,_/binary>>|_]) ->
+    io_lib:format("TLS 1.2 Record Protocol, ~s", [msg_type(B)]);
+tls_record_version({3,2}, [<<B,_/binary>>|_]) ->
+    io_lib:format("TLS 1.1 Record Protocol, ~s", [msg_type(B)]);
+tls_record_version({3,1}, [<<B,_/binary>>|_]) ->
+    io_lib:format("TLS 1.0 Record Protocol, ~s", [msg_type(B)]);
+tls_record_version({3,0}, [<<B,_/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";
+msg_type(22) -> "handshake";
+msg_type(23) -> "application_data";
+msg_type(_) -> unknown.
+
+
+convert_to_hex(Protocol, BinMsg) ->
+    convert_to_hex(Protocol, BinMsg, [], [], 0).
+%%
+convert_to_hex(P, [], Row0, Acc, C) when C rem 16 =:= 0 ->
+    Row = lists:reverse(end_row(P, Row0)),
+    {lists:reverse(Acc) ++ Row ++ io_lib:nl(), C};
+convert_to_hex(P, [], Row0, Acc, C) ->
+    Row = lists:reverse(end_row(P, Row0)),
+    Padding = calculate_padding(Row0, Acc),
+    PaddedRow = string:pad(Row, Padding, leading, $ ),
+    {lists:reverse(Acc) ++ PaddedRow ++ io_lib:nl(), C};
+convert_to_hex(P, [H|T], Row, Acc, C) when is_list(H) ->
+    convert_to_hex(P, H ++ T, Row, Acc, C);
+convert_to_hex(P, [<<>>|T], Row, Acc, C) ->
+    convert_to_hex(P, T, Row, Acc, C);
+
+%% First line
+convert_to_hex(P, [<<A:4,B:4,R/binary>>|T], Row, Acc, C) when C =:= 0 ->
+    convert_to_hex(P, [<<R/binary>>|T],
+                   update_row(<<A:4,B:4>>, Row),
+                   prepend_first_row(P, A, B, Acc, C),
+                   C + 1);
+%% New line
+convert_to_hex(P, [<<A:4,B:4,R/binary>>|T], Row, Acc, C) when C rem 16 =:= 0 ->
+    convert_to_hex(P, [<<R/binary>>|T],
+                   update_row(<<A:4,B:4>>, []),
+                   prepend_row(P, A, B, Row, Acc, C),
+                   C + 1);
+%% Add 8th hex with extra whitespace
+%% 0000 - 16 03 02 00 bd 01 00 00  b9 ...
+%%                             ^^^^
+convert_to_hex(P, [<<A:4,B:4,R/binary>>|T], Row, Acc, C) when C rem 8 =:= 7 ->
+    convert_to_hex(P, [<<R/binary>>|T],
+                   update_row(<<A:4,B:4>>, Row),
+                   prepend_eighths_hex(A, B, Acc),
+                   C + 1);
+convert_to_hex(P, [<<A:4,B:4,R/binary>>|T], Row, Acc, C) ->
+    convert_to_hex(P, [<<R/binary>>|T],
+                   update_row(<<A:4,B:4>>, Row),
+                   prepend_hex(A, B, Acc),
+                   C + 1);
+%% First line
+convert_to_hex(P, [H|T], Row, Acc, C) when is_integer(H), C =:= 0 ->
+    convert_to_hex(P, T,
+                   update_row(H, Row),
+                   prepend_first_row(P, H, Acc, C),
+                   C + 1);
+%% New line
+convert_to_hex(P, [H|T], Row, Acc, C) when is_integer(H), C rem 16 =:= 0 ->
+    convert_to_hex(P, T,
+                   update_row(H, []),
+                   prepend_row(P, H, Row, Acc, C),
+                   C + 1);
+%% Add 8th hex with extra whitespace
+%% 0000 - 16 03 02 00 bd 01 00 00  b9 ...
+%%                             ^^^^
+convert_to_hex(P, [H|T], Row, Acc, C) when is_integer(H), C rem 8 =:= 7 ->
+    convert_to_hex(P, T,
+                   update_row(H, Row),
+                   prepend_eighths_hex(H, Acc),
+                   C + 1);
+convert_to_hex(P, [H|T], Row, Acc, C) when is_integer(H) ->
+    convert_to_hex(P, T,
+                   update_row(H, Row),
+                   prepend_hex(H, Acc),
+                   C + 1).
+
+
+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, _) ->
+    "   ".
+
+
+end_row(tls_record, Row) ->
+    Row ++ "  ";
+end_row(_, Row) ->
+    Row.
+
+
+%% Calculate padding of the "printable character" lines in order to be
+%% visually aligned.
+calculate_padding(Row, Acc) ->
+    %% Number of new line characters
+    NNL = (length(Acc) div 75) * length(io_lib:nl()),
+    %% Length of the last printed line
+    Length = (length(Acc) - NNL) rem 75,
+    %% Adjusted length of the last printed line
+    PaddedLength = 75 - (16 - length(Row)), %% Length
+    %% Padding
+    PaddedLength - Length.
+
+
+%%-------------------------------------------------------------------------
+%% Functions operating on reversed lists
+%%-------------------------------------------------------------------------
+update_row(B, Row) when is_binary(B) ->
+    case binary_to_list(B) of
+        [C] when 32 =< C, C =< 126 ->
+            [C|Row];
+        _Else ->
+            [$.|Row]
+    end;
+update_row(C, Row) when 32 =< C, C =< 126 ->
+    [C|Row];
+update_row(_, Row) ->
+    [$.|Row].
+
+
+prepend_first_row(P, A, B, Acc, C) ->
+    prepend_hex(A, B,row_prefix(P, C) ++ Acc).
+%%
+prepend_first_row(P, N, Acc, C) ->
+    prepend_hex(N,row_prefix(P, C) ++ Acc).
+
+prepend_row(P, A, B, Row, Acc, C) ->
+    prepend_hex(A, B,row_prefix(P, C) ++ io_lib:nl() ++ end_row(P, Row) ++ Acc).
+%%
+prepend_row(P, N, Row, Acc, C) ->
+    prepend_hex(N,row_prefix(P, C) ++ io_lib:nl() ++ end_row(P, Row) ++ Acc).
+
+
+
+prepend_hex(A, B, Acc) ->
+    [$ ,?DEC2HEX(B),?DEC2HEX(A)|Acc].
+%%
+prepend_hex(N, Acc) ->
+    " " ++ number_to_hex(N) ++ Acc.
+
+
+prepend_eighths_hex(A, B, Acc) ->
+    [$ ,$ ,?DEC2HEX(B),?DEC2HEX(A)|Acc].
+%%
+prepend_eighths_hex(N, Acc) ->
+    "  " ++ number_to_hex(N) ++ Acc.
+
+number_to_hex(N) ->
+    case string:to_lower(erlang:integer_to_list(N, 16)) of
+        H when length(H) < 2 ->
+            lists:append(H, "0");
+        H ->
+            lists:reverse(H)
+    end.
diff --git a/lib/ssl/src/ssl.erl b/lib/ssl/src/ssl.erl
index a93695fb7a..592c02a28c 100644
--- a/lib/ssl/src/ssl.erl
+++ b/lib/ssl/src/ssl.erl
@@ -210,6 +210,8 @@ ssl_accept(Socket, SslOptions, Timeout) ->
 %% Description: Performs accept on an ssl listen socket. e.i. performs
 %%              ssl handshake.
 %%--------------------------------------------------------------------
+
+%% Performs the SSL/TLS/DTLS server-side handshake.
 handshake(ListenSocket) ->
     handshake(ListenSocket, infinity).
 
@@ -217,6 +219,12 @@ handshake(#sslsocket{} = Socket, Timeout) when  (is_integer(Timeout) andalso Tim
                                                 (Timeout == infinity) ->
     ssl_connection:handshake(Socket, Timeout);
 
+%% If Socket is a ordinary socket(): upgrades a gen_tcp, or equivalent, socket to
+%% an SSL socket, that is, performs the SSL/TLS server-side handshake and returns
+%% the SSL socket.
+%%
+%% If Socket is an sslsocket(): provides extra SSL/TLS/DTLS options to those
+%% specified in ssl:listen/2 and then performs the SSL/TLS/DTLS handshake.
 handshake(ListenSocket, SslOptions)  when is_port(ListenSocket) ->
     handshake(ListenSocket, SslOptions, infinity).
 
diff --git a/lib/ssl/src/ssl_connection.erl b/lib/ssl/src/ssl_connection.erl
index b4f60c683c..271365b709 100644
--- a/lib/ssl/src/ssl_connection.erl
+++ b/lib/ssl/src/ssl_connection.erl
@@ -335,9 +335,14 @@ handle_own_alert(Alert, Version, StateName,
                         connection_states = ConnectionStates,
                         ssl_options = SslOpts} = State) ->
     try %% Try to tell the other side
-	{BinMsg, _} =
-	Connection:encode_alert(Alert, Version, ConnectionStates),
-	Connection:send(Transport, Socket, BinMsg)
+        {BinMsg, _} =
+            Connection:encode_alert(Alert, Version, ConnectionStates),
+        Connection:send(Transport, Socket, BinMsg),
+        Report = #{direction => outbound,
+                   protocol => 'tls_record',
+                   message => BinMsg,
+                   version => Version},
+        logger:info(Report, #{domain => [beam,erlang,otp,ssl,tls_record]})
     catch _:_ ->  %% Can crash if we are in a uninitialized state
 	    ignore
     end,
@@ -431,16 +436,22 @@ write_application_data(Data0, {FromPid, _} = From,
 	    {Msgs, ConnectionStates} =
                 Connection:encode_data(Data, Version, ConnectionStates0),
             NewState = State#state{connection_states = ConnectionStates},
-	    case Connection:send(Transport, Socket, Msgs) of
-                ok when FromPid =:= self() ->
-                    hibernate_after(connection, NewState, []);
-                Error when FromPid =:= self() ->
-                    stop({shutdown, Error}, NewState);
-                ok ->
-                    hibernate_after(connection, NewState, [{reply, From, ok}]);
-                Result ->
-                    hibernate_after(connection, NewState, [{reply, From, Result}])
-            end
+	    RetVal = case Connection:send(Transport, Socket, Msgs) of
+                         ok when FromPid =:= self() ->
+                             hibernate_after(connection, NewState, []);
+                         Error when FromPid =:= self() ->
+                             stop({shutdown, Error}, NewState);
+                         ok ->
+                             hibernate_after(connection, NewState, [{reply, From, ok}]);
+                         Result ->
+                             hibernate_after(connection, NewState, [{reply, From, Result}])
+                     end,
+            Report = #{direction => outbound,
+                       protocol => 'tls_record',
+                       message => Msgs,
+                       version => Version},
+            logger:info(Report, #{domain => [beam,erlang,otp,ssl,tls_record]}),
+            RetVal
     end.
 
 read_application_data(Data, #state{user_application = {_Mon, Pid},
diff --git a/lib/ssl/src/tls_connection.erl b/lib/ssl/src/tls_connection.erl
index a3002830d1..6b9e4540f4 100644
--- a/lib/ssl/src/tls_connection.erl
+++ b/lib/ssl/src/tls_connection.erl
@@ -129,6 +129,7 @@ next_record(#state{protocol_buffers =
 		   = Buffers,
 		   connection_states = ConnStates0,
 		   ssl_options = #ssl_options{padding_check = Check}} = State) ->
+
     case tls_record:decode_cipher_text(CT, ConnStates0, Check) of
 	{Plain, ConnStates} ->		      
 	    {Plain, State#state{protocol_buffers =
@@ -267,6 +268,11 @@ queue_handshake(Handshake, #state{negotiated_version = Version,
 				  connection_states = ConnectionStates0} = State0) ->
     {BinHandshake, ConnectionStates, Hist} =
 	encode_handshake(Handshake, Version, ConnectionStates0, Hist0),
+    Report = #{direction => outbound,
+               protocol => 'tls_record',
+               message => BinHandshake,
+               version => Version},
+    logger:info(Report, #{domain => [beam,erlang,otp,ssl,tls_record]}),
     State0#state{connection_states = ConnectionStates,
 		 tls_handshake_history = Hist,
 		 flight_buffer = Flight0 ++ [BinHandshake]}.
@@ -282,6 +288,11 @@ queue_change_cipher(Msg, #state{negotiated_version = Version,
 				  connection_states = ConnectionStates0} = State0) ->
     {BinChangeCipher, ConnectionStates} =
 	encode_change_cipher(Msg, Version, ConnectionStates0),
+    Report = #{direction => outbound,
+               protocol => 'tls_record',
+               message => BinChangeCipher,
+               version => Version},
+    logger:info(Report, #{domain => [beam,erlang,otp,ssl,tls_record]}),
     State0#state{connection_states = ConnectionStates,
 		 flight_buffer = Flight0 ++ [BinChangeCipher]}.
 
@@ -312,7 +323,14 @@ send_alert(Alert, #state{negotiated_version = Version,
 			 connection_states = ConnectionStates0} = State0) ->
     {BinMsg, ConnectionStates} =
 	encode_alert(Alert, Version, ConnectionStates0),
+
     send(Transport, Socket, BinMsg),
+    Report = #{direction => outbound,
+               protocol => 'tls_record',
+               message => BinMsg,
+               version => Version},
+    logger:info(Report, #{domain => [beam,erlang,otp,ssl,tls_record]}),
+
     State0#state{connection_states = ConnectionStates}.
 
 %%--------------------------------------------------------------------
@@ -415,6 +433,11 @@ init({call, From}, {start, Timeout},
     {BinMsg, ConnectionStates, Handshake} =
         encode_handshake(Hello,  HelloVersion, ConnectionStates0, Handshake0),
     send(Transport, Socket, BinMsg),
+    Report = #{direction => outbound,
+               protocol => 'tls_record',
+               message => BinMsg,
+               version => HelloVersion},
+    logger:info(Report, #{domain => [beam,erlang,otp,ssl,tls_record]}),
     State1 = State0#state{connection_states = ConnectionStates,
 			  negotiated_version = Version, %% Requested version
 			  session =
diff --git a/lib/ssl/src/tls_record.erl b/lib/ssl/src/tls_record.erl
index f1aca8c801..78e2cce81e 100644
--- a/lib/ssl/src/tls_record.erl
+++ b/lib/ssl/src/tls_record.erl
@@ -400,24 +400,52 @@ assert_version(<<?BYTE(_), ?BYTE(MajVer), ?BYTE(MinVer), _/binary>>, Versions) -
 get_tls_records_aux(<<?BYTE(?APPLICATION_DATA),?BYTE(MajVer),?BYTE(MinVer),
 		     ?UINT16(Length), Data:Length/binary, Rest/binary>>, 
 		    Acc) ->
+    RawTLSRecord = <<?BYTE(?APPLICATION_DATA),?BYTE(MajVer),?BYTE(MinVer),
+                     ?UINT16(Length), Data:Length/binary>>,
+    Report = #{direction => inbound,
+               protocol => 'tls_record',
+               message => [RawTLSRecord],
+               version => {MajVer, MinVer}},
+    logger:info(Report, #{domain => [beam,erlang,otp,ssl,tls_record]}),
     get_tls_records_aux(Rest, [#ssl_tls{type = ?APPLICATION_DATA,
 					version = {MajVer, MinVer},
 					fragment = Data} | Acc]);
 get_tls_records_aux(<<?BYTE(?HANDSHAKE),?BYTE(MajVer),?BYTE(MinVer),
-		     ?UINT16(Length), 
-		     Data:Length/binary, Rest/binary>>, Acc) ->
+                      ?UINT16(Length),
+                      Data:Length/binary, Rest/binary>>, Acc) ->
+    RawTLSRecord = <<?BYTE(?HANDSHAKE),?BYTE(MajVer),?BYTE(MinVer),
+                     ?UINT16(Length), Data:Length/binary>>,
+    Report = #{direction => inbound,
+               protocol => 'tls_record',
+               message => [RawTLSRecord],
+               version => {MajVer, MinVer}},
+    logger:info(Report, #{domain => [beam,erlang,otp,ssl,tls_record]}),
     get_tls_records_aux(Rest, [#ssl_tls{type = ?HANDSHAKE,
 					version = {MajVer, MinVer},
 					fragment = Data} | Acc]);
 get_tls_records_aux(<<?BYTE(?ALERT),?BYTE(MajVer),?BYTE(MinVer),
 		     ?UINT16(Length), Data:Length/binary, 
 		     Rest/binary>>, Acc) ->
+    RawTLSRecord = <<?BYTE(?ALERT),?BYTE(MajVer),?BYTE(MinVer),
+                     ?UINT16(Length), Data:Length/binary>>,
+    Report = #{direction => inbound,
+               protocol => 'tls_record',
+               message => [RawTLSRecord],
+               version => {MajVer, MinVer}},
+    logger:info(Report, #{domain => [beam,erlang,otp,ssl,tls_record]}),
     get_tls_records_aux(Rest, [#ssl_tls{type = ?ALERT,
 					version = {MajVer, MinVer},
 					fragment = Data} | Acc]);
 get_tls_records_aux(<<?BYTE(?CHANGE_CIPHER_SPEC),?BYTE(MajVer),?BYTE(MinVer),
 		     ?UINT16(Length), Data:Length/binary, Rest/binary>>, 
 		    Acc) ->
+    RawTLSRecord = <<?BYTE(?CHANGE_CIPHER_SPEC),?BYTE(MajVer),?BYTE(MinVer),
+                     ?UINT16(Length), Data:Length/binary>>,
+    Report = #{direction => inbound,
+               protocol => 'tls_record',
+               message => [RawTLSRecord],
+               version => {MajVer, MinVer}},
+    logger:info(Report, #{domain => [beam,erlang,otp,ssl,tls_record]}),
     get_tls_records_aux(Rest, [#ssl_tls{type = ?CHANGE_CIPHER_SPEC,
 					version = {MajVer, MinVer},
 					fragment = Data} | Acc]);