diff options
author | Péter Dimitrov <[email protected]> | 2018-05-23 16:44:58 +0200 |
---|---|---|
committer | Péter Dimitrov <[email protected]> | 2018-06-20 15:18:37 +0200 |
commit | 6e0ee7a598c892b6db3282bd719583b68f2d8a89 (patch) | |
tree | e1f2b6d3dfa9592e16a621240cf0c2c10719aa94 /lib | |
parent | aa09b1326a0e88937a3e5c0162bed4cd7d73b4bd (diff) | |
download | otp-6e0ee7a598c892b6db3282bd719583b68f2d8a89.tar.gz otp-6e0ee7a598c892b6db3282bd719583b68f2d8a89.tar.bz2 otp-6e0ee7a598c892b6db3282bd719583b68f2d8a89.zip |
ssl: Add logging for TLS record protocol
Change-Id: I18786a9a8523d0ec3d9ca37ad5b2284721c5c4a1
Diffstat (limited to 'lib')
-rw-r--r-- | lib/ssl/src/logger_ssl_formatter.erl | 216 | ||||
-rw-r--r-- | lib/ssl/src/ssl.erl | 8 | ||||
-rw-r--r-- | lib/ssl/src/ssl_connection.erl | 37 | ||||
-rw-r--r-- | lib/ssl/src/tls_connection.erl | 23 | ||||
-rw-r--r-- | lib/ssl/src/tls_record.erl | 32 |
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]); |