From eae3952b4af6c3afff39dd0dd5e6b72291566b4a Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?P=C3=A9ter=20Dimitrov?= Date: Mon, 4 Jun 2018 17:14:53 +0200 Subject: 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 --- lib/ssl/src/logger_ssl_formatter.erl | 135 ++++++++++++++++++++++++++++------- lib/ssl/src/tls_connection.erl | 20 +++--- lib/ssl/src/tls_handshake.erl | 5 ++ lib/ssl/src/tls_record.erl | 12 ++-- 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}, [<>|_]) -> +tls_record_version([<>|_]) -> io_lib:format("TLS 1.2 Record Protocol, ~s", [msg_type(B)]); -tls_record_version({3,2}, [<>|_]) -> +tls_record_version([<>|_]) -> io_lib:format("TLS 1.1 Record Protocol, ~s", [msg_type(B)]); -tls_record_version({3,1}, [<>|_]) -> +tls_record_version([<>|_]) -> io_lib:format("TLS 1.0 Record Protocol, ~s", [msg_type(B)]); -tls_record_version({3,0}, [<>|_]) -> +tls_record_version([<>|_]) -> io_lib:format("SSL 3.0 Record Protocol, ~s", [msg_type(B)]). -tls_version({3,3}, [<>|_]) -> - io_lib:format("TLS 1.2 Handshake, ~s", [msg_type(B)]); -tls_version({3,2}, [<>|_]) -> - io_lib:format("TLS 1.1 Handshake, ~s", [msg_type(B)]); -tls_version({3,1}, [<>|_]) -> - io_lib:format("TLS 1.0 Handshake, ~s", [msg_type(B)]); -tls_version({3,0}, [<>|_]) -> - 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, <>, 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(<>, 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(<>, 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(<>, 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(<>, 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}, -- cgit v1.2.3