From 0360e26f440e2f1ce81eb286e3ba657a56f666d5 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?P=C3=A9ter=20Dimitrov?= Date: Tue, 15 May 2018 12:05:37 +0200 Subject: ssl: Define VSN macro in source Define VSN macro in source to remove syntax errors while editing the code. Change-Id: I508d16641cb65ec954fc3fcae90183fa297770da --- lib/ssl/src/Makefile | 2 +- lib/ssl/src/ssl_internal.hrl | 1 + 2 files changed, 2 insertions(+), 1 deletion(-) (limited to 'lib') diff --git a/lib/ssl/src/Makefile b/lib/ssl/src/Makefile index ebcb511653..0d4eb2212a 100644 --- a/lib/ssl/src/Makefile +++ b/lib/ssl/src/Makefile @@ -118,7 +118,7 @@ EXTRA_ERLC_FLAGS = +warn_unused_vars ERL_COMPILE_FLAGS += -I$(ERL_TOP)/lib/kernel/src \ -pz $(EBIN) \ -pz $(ERL_TOP)/lib/public_key/ebin \ - $(EXTRA_ERLC_FLAGS) -DVSN=\"$(VSN)\" + $(EXTRA_ERLC_FLAGS) # ---------------------------------------------------- diff --git a/lib/ssl/src/ssl_internal.hrl b/lib/ssl/src/ssl_internal.hrl index ae1c3ea47c..6719371f95 100644 --- a/lib/ssl/src/ssl_internal.hrl +++ b/lib/ssl/src/ssl_internal.hrl @@ -25,6 +25,7 @@ -include_lib("public_key/include/public_key.hrl"). +-define(VSN, "8.2.6"). -define(SECRET_PRINTOUT, "***"). -type reason() :: term(). -- cgit v1.2.3 From deaadf9e82cee43a3bbc5185e811153f455b9669 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?P=C3=A9ter=20Dimitrov?= Date: Wed, 16 May 2018 11:01:34 +0200 Subject: ssl: Add initial ssl log formatter Change-Id: I649a686ee72fa8bbe1e1dbc44ed5ec2df9662b10 --- lib/ssl/src/Makefile | 3 ++- lib/ssl/src/logger_ssl_formatter.erl | 26 ++++++++++++++++++++++++++ lib/ssl/src/ssl.app.src | 2 ++ lib/ssl/src/ssl.erl | 1 + lib/ssl/src/ssl_app.erl | 17 +++++++++++++++++ 5 files changed, 48 insertions(+), 1 deletion(-) create mode 100644 lib/ssl/src/logger_ssl_formatter.erl (limited to 'lib') diff --git a/lib/ssl/src/Makefile b/lib/ssl/src/Makefile index 0d4eb2212a..335e1c55c3 100644 --- a/lib/ssl/src/Makefile +++ b/lib/ssl/src/Makefile @@ -86,7 +86,8 @@ MODULES= \ ssl_record \ ssl_v3 \ tls_v1 \ - dtls_v1 + dtls_v1 \ + logger_ssl_formatter INTERNAL_HRL_FILES = \ ssl_alert.hrl ssl_cipher.hrl \ diff --git a/lib/ssl/src/logger_ssl_formatter.erl b/lib/ssl/src/logger_ssl_formatter.erl new file mode 100644 index 0000000000..b17100c1f5 --- /dev/null +++ b/lib/ssl/src/logger_ssl_formatter.erl @@ -0,0 +1,26 @@ +%% +%% %CopyrightBegin% +%% +%% Copyright Ericsson AB 1999-2017. 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. +%% You may obtain a copy of the License at +%% +%% http://www.apache.org/licenses/LICENSE-2.0 +%% +%% Unless required by applicable law or agreed to in writing, software +%% distributed under the License is distributed on an "AS IS" BASIS, +%% WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +%% See the License for the specific language governing permissions and +%% limitations under the License. +%% +%% %CopyrightEnd% +%% + +-module(logger_ssl_formatter). + +-export([format/2]). + +format(Log, Extra) -> + logger_formatter:format(Log, Extra). diff --git a/lib/ssl/src/ssl.app.src b/lib/ssl/src/ssl.app.src index da281829cb..e71d9565a9 100644 --- a/lib/ssl/src/ssl.app.src +++ b/lib/ssl/src/ssl.app.src @@ -51,6 +51,8 @@ ssl_crl_cache, ssl_crl_cache_api, ssl_crl_hash_dir, + %% Logging + logger_ssl_formatter, %% App structure ssl_app, ssl_sup, diff --git a/lib/ssl/src/ssl.erl b/lib/ssl/src/ssl.erl index 0f13b737ab..a93695fb7a 100644 --- a/lib/ssl/src/ssl.erl +++ b/lib/ssl/src/ssl.erl @@ -87,6 +87,7 @@ stop() -> application:stop(ssl). %%-------------------------------------------------------------------- + -spec connect(host() | port(), [connect_option()]) -> {ok, #sslsocket{}} | {error, reason()}. -spec connect(host() | port(), [connect_option()] | inet:port_number(), diff --git a/lib/ssl/src/ssl_app.erl b/lib/ssl/src/ssl_app.erl index 62e8765d4a..d1bd113b0d 100644 --- a/lib/ssl/src/ssl_app.erl +++ b/lib/ssl/src/ssl_app.erl @@ -29,9 +29,26 @@ -export([start/2, stop/1]). start(_Type, _StartArgs) -> + start_logger(), ssl_sup:start_link(). stop(_State) -> + stop_logger(), ok. +%% +%% Description: Start SSL logger +start_logger() -> + Config = #{level => info, + filter_default => stop, + formatter => {logger_ssl_formatter, #{}}}, + Filter = {fun logger_filters:domain/2,{log,starts_with,[beam,erlang,otp,ssl]}}, + logger:add_handler(ssl_handler, logger_std_h, Config), + logger:add_handler_filter(ssl_handler, filter_non_ssl, Filter). + +%% +%% Description: Stop SSL logger +stop_logger() -> + logger:remove_handler(ssl_handler). + -- cgit v1.2.3 From aa09b1326a0e88937a3e5c0162bed4cd7d73b4bd Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?P=C3=A9ter=20Dimitrov?= Date: Wed, 16 May 2018 12:01:22 +0200 Subject: ssl: Use logger API instead of legacy error_logger Change-Id: I04cb8e4c09b05fc9d7ead0dfae0d83286decdb74 --- lib/ssl/src/dtls_connection.erl | 5 +++-- lib/ssl/src/dtls_packet_demux.erl | 5 +++-- lib/ssl/src/inet_tls_dist.erl | 23 ++++++++++++----------- lib/ssl/src/ssl_connection.erl | 9 +++++---- lib/ssl/src/ssl_crl_hash_dir.erl | 5 +++-- lib/ssl/src/ssl_pkix_db.erl | 3 ++- 6 files changed, 28 insertions(+), 22 deletions(-) (limited to 'lib') diff --git a/lib/ssl/src/dtls_connection.erl b/lib/ssl/src/dtls_connection.erl index 53b46542e7..610ab9a51c 100644 --- a/lib/ssl/src/dtls_connection.erl +++ b/lib/ssl/src/dtls_connection.erl @@ -32,6 +32,7 @@ -include("ssl_internal.hrl"). -include("ssl_srp.hrl"). -include_lib("public_key/include/public_key.hrl"). +-include_lib("kernel/include/logger.hrl"). %% Internal application API @@ -1125,7 +1126,7 @@ is_ignore_alert(_) -> log_ignore_alert(true, StateName, Alert, Role) -> Txt = ssl_alert:alert_txt(Alert), - error_logger:format("DTLS over UDP ~p: In state ~p ignored to send ALERT ~s as DoS-attack mitigation \n", - [Role, StateName, Txt]); + ?LOG_ERROR("DTLS over UDP ~p: In state ~p ignored to send ALERT ~s as DoS-attack mitigation \n", + [Role, StateName, Txt]); log_ignore_alert(false, _, _,_) -> ok. diff --git a/lib/ssl/src/dtls_packet_demux.erl b/lib/ssl/src/dtls_packet_demux.erl index 1497c77cf3..e03a4e9cb9 100644 --- a/lib/ssl/src/dtls_packet_demux.erl +++ b/lib/ssl/src/dtls_packet_demux.erl @@ -24,6 +24,7 @@ -behaviour(gen_server). -include("ssl_internal.hrl"). +-include_lib("kernel/include/logger.hrl"). %% API -export([start_link/5, active_once/3, accept/2, sockname/1, close/1, @@ -146,11 +147,11 @@ handle_info({Transport, Socket, IP, InPortNo, _} = Msg, #state{listener = Socket %% appears to make things work as expected! handle_info({Error, Socket, econnreset = Error}, #state{listener = Socket, transport = {_,_,_, udp_error}} = State) -> Report = io_lib:format("Ignore SSL UDP Listener: Socket error: ~p ~n", [Error]), - error_logger:info_report(Report), + ?LOG_NOTICE(Report), {noreply, State}; handle_info({Error, Socket, Error}, #state{listener = Socket, transport = {_,_,_, Error}} = State) -> Report = io_lib:format("SSL Packet muliplxer shutdown: Socket error: ~p ~n", [Error]), - error_logger:info_report(Report), + ?LOG_NOTICE(Report), {noreply, State#state{close=true}}; handle_info({'DOWN', _, process, Pid, _}, #state{clients = Clients, diff --git a/lib/ssl/src/inet_tls_dist.erl b/lib/ssl/src/inet_tls_dist.erl index aa3d7e3f72..1194f4fc72 100644 --- a/lib/ssl/src/inet_tls_dist.erl +++ b/lib/ssl/src/inet_tls_dist.erl @@ -41,6 +41,7 @@ -include_lib("public_key/include/public_key.hrl"). -include("ssl_api.hrl"). +-include_lib("kernel/include/logger.hrl"). %% ------------------------------------------------------------------------- @@ -226,7 +227,7 @@ accept_loop(Driver, Listen, Kernel) -> true -> accept_loop(Driver, Listen, Kernel, Socket); {false,IP} -> - error_logger:error_msg( + ?LOG_ERROR( "** Connection attempt from " "disallowed IP ~w ** ~n", [IP]), ?shutdown2(no_node, trace({disallowed, IP})) @@ -261,7 +262,7 @@ accept_loop(Driver, Listen, Kernel, Socket) -> {error, {options, _}} = Error -> %% Bad options: that's probably our fault. %% Let's log that. - error_logger:error_msg( + ?LOG_ERROR( "Cannot accept TLS distribution connection: ~s~n", [ssl:format_error(Error)]), gen_tcp:close(Socket), @@ -437,7 +438,7 @@ allowed_nodes(SslSocket, Allowed) -> PeerCert, allowed_hosts(Allowed), PeerIP) of [] -> - error_logger:error_msg( + ?LOG_ERROR( "** Connection attempt from " "disallowed node(s) ~p ** ~n", [PeerIP]), ?shutdown2( @@ -691,12 +692,12 @@ split_node(Driver, Node, LongOrShortNames) -> {node, Name, Host} -> check_node(Driver, Node, Name, Host, LongOrShortNames); {host, _} -> - error_logger:error_msg( + ?LOG_ERROR( "** Nodename ~p illegal, no '@' character **~n", [Node]), ?shutdown2(Node, trace({illegal_node_n@me, Node})); _ -> - error_logger:error_msg( + ?LOG_ERROR( "** Nodename ~p illegal **~n", [Node]), ?shutdown2(Node, trace({illegal_node_name, Node})) end. @@ -708,7 +709,7 @@ check_node(Driver, Node, Name, Host, LongOrShortNames) -> {ok, _} -> {Name, Host}; _ -> - error_logger:error_msg( + ?LOG_ERROR( "** System running to use " "fully qualified hostnames **~n" "** Hostname ~s is illegal **~n", @@ -716,7 +717,7 @@ check_node(Driver, Node, Name, Host, LongOrShortNames) -> ?shutdown2(Node, trace({not_longnames, Host})) end; [_,_|_] when LongOrShortNames =:= shortnames -> - error_logger:error_msg( + ?LOG_ERROR( "** System NOT running to use " "fully qualified hostnames **~n" "** Hostname ~s is illegal **~n", @@ -846,13 +847,13 @@ monitor_pid(Pid) -> %% MRef = erlang:monitor(process, Pid), %% receive %% {'DOWN', MRef, _, _, normal} -> - %% error_logger:error_report( - %% [dist_proc_died, + %% ?LOG_ERROR( + %% [{slogan, dist_proc_died}, %% {reason, normal}, %% {pid, Pid}]); %% {'DOWN', MRef, _, _, Reason} -> - %% error_logger:info_report( - %% [dist_proc_died, + %% ?LOG_NOTICE( + %% [{slogan, dist_proc_died}, %% {reason, Reason}, %% {pid, Pid}]) %% end diff --git a/lib/ssl/src/ssl_connection.erl b/lib/ssl/src/ssl_connection.erl index 556c204ab1..b4f60c683c 100644 --- a/lib/ssl/src/ssl_connection.erl +++ b/lib/ssl/src/ssl_connection.erl @@ -35,6 +35,7 @@ -include("ssl_internal.hrl"). -include("ssl_srp.hrl"). -include_lib("public_key/include/public_key.hrl"). +-include_lib("kernel/include/logger.hrl"). %% Setup @@ -1339,7 +1340,7 @@ handle_info({ErrorTag, Socket, econnaborted}, StateName, handle_info({ErrorTag, Socket, Reason}, StateName, #state{socket = Socket, error_tag = ErrorTag} = State) -> Report = io_lib:format("SSL: Socket error: ~p ~n", [Reason]), - error_logger:error_report(Report), + ?LOG_ERROR(Report), handle_normal_shutdown(?ALERT_REC(?FATAL, ?CLOSE_NOTIFY), StateName, State), stop(normal, State); @@ -1388,7 +1389,7 @@ handle_info({cancel_start_or_recv, _RecvFrom}, StateName, State) -> handle_info(Msg, StateName, #state{socket = Socket, error_tag = Tag} = State) -> Report = io_lib:format("SSL: Got unexpected info: ~p ~n", [{Msg, Tag, Socket}]), - error_logger:info_report(Report), + ?LOG_NOTICE(Report), {next_state, StateName, State}. %%==================================================================== @@ -2741,10 +2742,10 @@ alert_user(Transport, Tracker, Socket, Active, Pid, From, Alert, Role, Connectio log_alert(true, Role, ProtocolName, StateName, #alert{role = Role} = Alert) -> Txt = ssl_alert:own_alert_txt(Alert), - error_logger:info_report(io_lib:format("~s ~p: In state ~p ~s\n", [ProtocolName, Role, StateName, Txt])); + ?LOG_NOTICE(io_lib:format("~s ~p: In state ~p ~s\n", [ProtocolName, Role, StateName, Txt])); log_alert(true, Role, ProtocolName, StateName, Alert) -> Txt = ssl_alert:alert_txt(Alert), - error_logger:info_report(io_lib:format("~s ~p: In state ~p ~s\n", [ProtocolName, Role, StateName, Txt])); + ?LOG_NOTICE(io_lib:format("~s ~p: In state ~p ~s\n", [ProtocolName, Role, StateName, Txt])); log_alert(false, _, _, _, _) -> ok. diff --git a/lib/ssl/src/ssl_crl_hash_dir.erl b/lib/ssl/src/ssl_crl_hash_dir.erl index bb62737232..9478ff9b78 100644 --- a/lib/ssl/src/ssl_crl_hash_dir.erl +++ b/lib/ssl/src/ssl_crl_hash_dir.erl @@ -20,6 +20,7 @@ -module(ssl_crl_hash_dir). -include_lib("public_key/include/public_key.hrl"). +-include_lib("kernel/include/logger.hrl"). -behaviour(ssl_crl_cache_api). @@ -55,7 +56,7 @@ select(Issuer, {_DbHandle, [{dir, Dir}]}) -> %% is happy with that, but if it's true, this is an error. []; {error, Error} -> - error_logger:error_report( + ?LOG_ERROR( [{cannot_find_crl, Error}, {dir, Dir}, {module, ?MODULE}, @@ -86,7 +87,7 @@ find_crls(Issuer, Hash, Dir, N, Acc) -> error:Error -> %% Something is wrong with the file. Report %% it, and try the next one. - error_logger:error_report( + ?LOG_ERROR( [{crl_parse_error, Error}, {filename, Filename}, {module, ?MODULE}, diff --git a/lib/ssl/src/ssl_pkix_db.erl b/lib/ssl/src/ssl_pkix_db.erl index 8828c3a0d8..4132733ae0 100644 --- a/lib/ssl/src/ssl_pkix_db.erl +++ b/lib/ssl/src/ssl_pkix_db.erl @@ -27,6 +27,7 @@ -include("ssl_internal.hrl"). -include_lib("public_key/include/public_key.hrl"). -include_lib("kernel/include/file.hrl"). +-include_lib("kernel/include/logger.hrl"). -export([create/1, create_pem_cache/1, add_crls/3, remove_crls/2, remove/1, add_trusted_certs/3, @@ -311,7 +312,7 @@ decode_certs(Ref, Cert) -> error:_ -> Report = io_lib:format("SSL WARNING: Ignoring a CA cert as " "it could not be correctly decoded.~n", []), - error_logger:info_report(Report), + ?LOG_NOTICE(Report), undefined end. -- cgit v1.2.3 From 6e0ee7a598c892b6db3282bd719583b68f2d8a89 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?P=C3=A9ter=20Dimitrov?= Date: Wed, 23 May 2018 16:44:58 +0200 Subject: ssl: Add logging for TLS record protocol Change-Id: I18786a9a8523d0ec3d9ca37ad5b2284721c5c4a1 --- lib/ssl/src/logger_ssl_formatter.erl | 216 ++++++++++++++++++++++++++++++++++- lib/ssl/src/ssl.erl | 8 ++ lib/ssl/src/ssl_connection.erl | 37 +++--- lib/ssl/src/tls_connection.erl | 23 ++++ lib/ssl/src/tls_record.erl | 32 +++++- 5 files changed, 298 insertions(+), 18 deletions(-) (limited to 'lib') 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}, [<>|_]) -> + io_lib:format("TLS 1.2 Record Protocol, ~s", [msg_type(B)]); +tls_record_version({3,2}, [<>|_]) -> + io_lib:format("TLS 1.1 Record Protocol, ~s", [msg_type(B)]); +tls_record_version({3,1}, [<>|_]) -> + io_lib:format("TLS 1.0 Record Protocol, ~s", [msg_type(B)]); +tls_record_version({3,0}, [<>|_]) -> + 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"; +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, [<>|T], Row, Acc, C) when C =:= 0 -> + convert_to_hex(P, [<>|T], + update_row(<>, Row), + prepend_first_row(P, A, B, Acc, C), + C + 1); +%% New line +convert_to_hex(P, [<>|T], Row, Acc, C) when C rem 16 =:= 0 -> + convert_to_hex(P, [<>|T], + update_row(<>, []), + 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, [<>|T], Row, Acc, C) when C rem 8 =:= 7 -> + convert_to_hex(P, [<>|T], + update_row(<>, Row), + prepend_eighths_hex(A, B, Acc), + C + 1); +convert_to_hex(P, [<>|T], Row, Acc, C) -> + convert_to_hex(P, [<>|T], + update_row(<>, 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(<>, Versions) - get_tls_records_aux(<>, Acc) -> + RawTLSRecord = <>, + 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(<>, Acc) -> + ?UINT16(Length), + Data:Length/binary, Rest/binary>>, Acc) -> + RawTLSRecord = <>, + 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(<>, Acc) -> + RawTLSRecord = <>, + 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(<>, Acc) -> + RawTLSRecord = <>, + 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]); -- cgit v1.2.3 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(-) (limited to 'lib') 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 From e94c5fad7304aa7b5cd15646a1fd246aae460a3f Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?P=C3=A9ter=20Dimitrov?= Date: Fri, 15 Jun 2018 16:39:15 +0200 Subject: ssl: Update domain filter, use log macros Change-Id: Id52990a105c81373c7c6034df9a2675f9d0e429a --- lib/ssl/src/ssl_app.erl | 4 ++-- lib/ssl/src/ssl_connection.erl | 4 ++-- lib/ssl/src/tls_connection.erl | 15 ++++++++------- lib/ssl/src/tls_handshake.erl | 6 +++--- lib/ssl/src/tls_record.erl | 9 +++++---- 5 files changed, 20 insertions(+), 18 deletions(-) (limited to 'lib') diff --git a/lib/ssl/src/ssl_app.erl b/lib/ssl/src/ssl_app.erl index d1bd113b0d..1beaa513b4 100644 --- a/lib/ssl/src/ssl_app.erl +++ b/lib/ssl/src/ssl_app.erl @@ -39,10 +39,10 @@ stop(_State) -> %% %% Description: Start SSL logger start_logger() -> - Config = #{level => info, + Config = #{level => debug, filter_default => stop, formatter => {logger_ssl_formatter, #{}}}, - Filter = {fun logger_filters:domain/2,{log,starts_with,[beam,erlang,otp,ssl]}}, + Filter = {fun logger_filters:domain/2,{log,sub,[otp,ssl]}}, logger:add_handler(ssl_handler, logger_std_h, Config), logger:add_handler_filter(ssl_handler, filter_non_ssl, Filter). diff --git a/lib/ssl/src/ssl_connection.erl b/lib/ssl/src/ssl_connection.erl index 271365b709..bfb83343d8 100644 --- a/lib/ssl/src/ssl_connection.erl +++ b/lib/ssl/src/ssl_connection.erl @@ -342,7 +342,7 @@ handle_own_alert(Alert, Version, StateName, protocol => 'tls_record', message => BinMsg, version => Version}, - logger:info(Report, #{domain => [beam,erlang,otp,ssl,tls_record]}) + ?LOG_DEBUG(Report, #{domain => [otp,ssl,tls_record]}) catch _:_ -> %% Can crash if we are in a uninitialized state ignore end, @@ -450,7 +450,7 @@ write_application_data(Data0, {FromPid, _} = From, protocol => 'tls_record', message => Msgs, version => Version}, - logger:info(Report, #{domain => [beam,erlang,otp,ssl,tls_record]}), + ?LOG_DEBUG(Report, #{domain => [otp,ssl,tls_record]}), RetVal end. diff --git a/lib/ssl/src/tls_connection.erl b/lib/ssl/src/tls_connection.erl index f1291ec7b4..071f464851 100644 --- a/lib/ssl/src/tls_connection.erl +++ b/lib/ssl/src/tls_connection.erl @@ -38,7 +38,8 @@ -include("ssl_api.hrl"). -include("ssl_internal.hrl"). -include("ssl_srp.hrl"). --include_lib("public_key/include/public_key.hrl"). +-include_lib("public_key/include/public_key.hrl"). +-include_lib("kernel/include/logger.hrl"). %% Internal application API @@ -274,8 +275,8 @@ queue_handshake(Handshake, #state{negotiated_version = Version, 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]}), + ?LOG_DEBUG(HandshakeMsg, #{domain => [otp,ssl,handshake]}), + ?LOG_DEBUG(Report, #{domain => [otp,ssl,tls_record]}), State0#state{connection_states = ConnectionStates, tls_handshake_history = Hist, flight_buffer = Flight0 ++ [BinHandshake]}. @@ -294,7 +295,7 @@ queue_change_cipher(Msg, #state{negotiated_version = Version, Report = #{direction => outbound, protocol => 'tls_record', message => BinChangeCipher}, - logger:info(Report, #{domain => [beam,erlang,otp,ssl,tls_record]}), + ?LOG_DEBUG(Report, #{domain => [otp,ssl,tls_record]}), State0#state{connection_states = ConnectionStates, flight_buffer = Flight0 ++ [BinChangeCipher]}. @@ -330,7 +331,7 @@ send_alert(Alert, #state{negotiated_version = Version, Report = #{direction => outbound, protocol => 'tls_record', message => BinMsg}, - logger:info(Report, #{domain => [beam,erlang,otp,ssl,tls_record]}), + ?LOG_DEBUG(Report, #{domain => [otp,ssl,tls_record]}), State0#state{connection_states = ConnectionStates}. @@ -440,8 +441,8 @@ init({call, From}, {start, Timeout}, 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]}), + ?LOG_DEBUG(HelloMsg, #{domain => [otp,ssl,handshake]}), + ?LOG_DEBUG(Report, #{domain => [otp,ssl,tls_record]}), State1 = State0#state{connection_states = ConnectionStates, negotiated_version = Version, %% Requested version session = diff --git a/lib/ssl/src/tls_handshake.erl b/lib/ssl/src/tls_handshake.erl index 42b457d24a..4aed414b6d 100644 --- a/lib/ssl/src/tls_handshake.erl +++ b/lib/ssl/src/tls_handshake.erl @@ -31,6 +31,7 @@ -include("ssl_internal.hrl"). -include("ssl_cipher.hrl"). -include_lib("public_key/include/public_key.hrl"). +-include_lib("kernel/include/logger.hrl"). %% Handshake handling -export([client_hello/8, hello/4]). @@ -274,9 +275,8 @@ get_tls_handshake_aux(Version, < Report = #{direction => inbound, protocol => 'handshake', - message => Handshake, - version => Version}, - logger:info(Report, #{domain => [beam,erlang,otp,ssl,handshake]}), + message => Handshake}, + ?LOG_DEBUG(Report, #{domain => [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 05c5d703a9..b744555753 100644 --- a/lib/ssl/src/tls_record.erl +++ b/lib/ssl/src/tls_record.erl @@ -30,6 +30,7 @@ -include("ssl_alert.hrl"). -include("tls_handshake.hrl"). -include("ssl_cipher.hrl"). +-include_lib("kernel/include/logger.hrl"). %% Handling of incoming data -export([get_tls_records/3, init_connection_states/2]). @@ -405,7 +406,7 @@ get_tls_records_aux(< inbound, protocol => 'tls_record', message => [RawTLSRecord]}, - logger:info(Report, #{domain => [beam,erlang,otp,ssl,tls_record]}), + ?LOG_DEBUG(Report, #{domain => [otp,ssl,tls_record]}), get_tls_records_aux(Rest, [#ssl_tls{type = ?APPLICATION_DATA, version = {MajVer, MinVer}, fragment = Data} | Acc]); @@ -417,7 +418,7 @@ get_tls_records_aux(< inbound, protocol => 'tls_record', message => [RawTLSRecord]}, - logger:info(Report, #{domain => [beam,erlang,otp,ssl,tls_record]}), + ?LOG_DEBUG(Report, #{domain => [otp,ssl,tls_record]}), get_tls_records_aux(Rest, [#ssl_tls{type = ?HANDSHAKE, version = {MajVer, MinVer}, fragment = Data} | Acc]); @@ -429,7 +430,7 @@ get_tls_records_aux(< inbound, protocol => 'tls_record', message => [RawTLSRecord]}, - logger:info(Report, #{domain => [beam,erlang,otp,ssl,tls_record]}), + ?LOG_DEBUG(Report, #{domain => [otp,ssl,tls_record]}), get_tls_records_aux(Rest, [#ssl_tls{type = ?ALERT, version = {MajVer, MinVer}, fragment = Data} | Acc]); @@ -441,7 +442,7 @@ get_tls_records_aux(< inbound, protocol => 'tls_record', message => [RawTLSRecord]}, - logger:info(Report, #{domain => [beam,erlang,otp,ssl,tls_record]}), + ?LOG_DEBUG(Report, #{domain => [otp,ssl,tls_record]}), get_tls_records_aux(Rest, [#ssl_tls{type = ?CHANGE_CIPHER_SPEC, version = {MajVer, MinVer}, fragment = Data} | Acc]); -- cgit v1.2.3 From 3c3d2d8b14501b4b279deae643490f92f98a99d5 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?P=C3=A9ter=20Dimitrov?= Date: Mon, 18 Jun 2018 13:17:07 +0200 Subject: ssl: Rename logger_ssl_formatter to ssl_logger Change-Id: I4aff56c95d7ea8c46db40b0fa0f6f9b43f00bf8a --- lib/ssl/src/Makefile | 2 +- lib/ssl/src/logger_ssl_formatter.erl | 319 ---------------------------------- lib/ssl/src/ssl.app.src | 2 +- lib/ssl/src/ssl_app.erl | 2 +- lib/ssl/src/ssl_logger.erl | 320 +++++++++++++++++++++++++++++++++++ 5 files changed, 323 insertions(+), 322 deletions(-) delete mode 100644 lib/ssl/src/logger_ssl_formatter.erl create mode 100644 lib/ssl/src/ssl_logger.erl (limited to 'lib') diff --git a/lib/ssl/src/Makefile b/lib/ssl/src/Makefile index 335e1c55c3..1db18d4e5a 100644 --- a/lib/ssl/src/Makefile +++ b/lib/ssl/src/Makefile @@ -87,7 +87,7 @@ MODULES= \ ssl_v3 \ tls_v1 \ dtls_v1 \ - logger_ssl_formatter + ssl_logger INTERNAL_HRL_FILES = \ ssl_alert.hrl ssl_cipher.hrl \ diff --git a/lib/ssl/src/logger_ssl_formatter.erl b/lib/ssl/src/logger_ssl_formatter.erl deleted file mode 100644 index de4c09be79..0000000000 --- a/lib/ssl/src/logger_ssl_formatter.erl +++ /dev/null @@ -1,319 +0,0 @@ -%% -%% %CopyrightBegin% -%% -%% 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. -%% You may obtain a copy of the License at -%% -%% http://www.apache.org/licenses/LICENSE-2.0 -%% -%% Unless required by applicable law or agreed to in writing, software -%% distributed under the License is distributed on an "AS IS" BASIS, -%% WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. -%% See the License for the specific language governing permissions and -%% limitations under the License. -%% -%% %CopyrightEnd% -%% - --module(logger_ssl_formatter). - --export([format/2]). - --define(DEC2HEX(X), - if ((X) >= 0) andalso ((X) =< 9) -> (X) + $0; - ((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, - message := BinMsg0} = Msg, - case Protocol of - 'tls_record' -> - BinMsg = lists:flatten(BinMsg0), - format_tls_record(Direction, BinMsg); - 'handshake' -> - format_handshake(Direction, BinMsg0); - _Other -> - [] - end. - - -%%------------------------------------------------------------------------- -%% 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, 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(BinMsg)]), - Header ++ Message. - - -header_prefix_tls_record(inbound) -> - "reading"; -header_prefix_tls_record(outbound) -> - "writing". - - - -tls_record_version([<>|_]) -> - io_lib:format("TLS 1.2 Record Protocol, ~s", [msg_type(B)]); -tls_record_version([<>|_]) -> - io_lib:format("TLS 1.1 Record Protocol, ~s", [msg_type(B)]); -tls_record_version([<>|_]) -> - io_lib:format("TLS 1.0 Record Protocol, ~s", [msg_type(B)]); -tls_record_version([<>|_]) -> - io_lib:format("SSL 3.0 Record Protocol, ~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. - - -%%------------------------------------------------------------------------- -%% Hex encoding functions -%%------------------------------------------------------------------------- -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, [<>|T], Row, Acc, C) when C =:= 0 -> - convert_to_hex(P, [<>|T], - update_row(<>, Row), - prepend_first_row(P, A, B, Acc, C), - C + 1); -%% New line -convert_to_hex(P, [<>|T], Row, Acc, C) when C rem 16 =:= 0 -> - convert_to_hex(P, [<>|T], - update_row(<>, []), - 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, [<>|T], Row, Acc, C) when C rem 8 =:= 7 -> - convert_to_hex(P, [<>|T], - update_row(<>, Row), - prepend_eighths_hex(A, B, Acc), - C + 1); -convert_to_hex(P, [<>|T], Row, Acc, C) -> - convert_to_hex(P, [<>|T], - update_row(<>, 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 ++ " - ")). - - -end_row(tls_record, 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.app.src b/lib/ssl/src/ssl.app.src index e71d9565a9..9679ea4687 100644 --- a/lib/ssl/src/ssl.app.src +++ b/lib/ssl/src/ssl.app.src @@ -52,7 +52,7 @@ ssl_crl_cache_api, ssl_crl_hash_dir, %% Logging - logger_ssl_formatter, + ssl_logger, %% App structure ssl_app, ssl_sup, diff --git a/lib/ssl/src/ssl_app.erl b/lib/ssl/src/ssl_app.erl index 1beaa513b4..2a5047c75c 100644 --- a/lib/ssl/src/ssl_app.erl +++ b/lib/ssl/src/ssl_app.erl @@ -41,7 +41,7 @@ stop(_State) -> start_logger() -> Config = #{level => debug, filter_default => stop, - formatter => {logger_ssl_formatter, #{}}}, + formatter => {ssl_logger, #{}}}, Filter = {fun logger_filters:domain/2,{log,sub,[otp,ssl]}}, logger:add_handler(ssl_handler, logger_std_h, Config), logger:add_handler_filter(ssl_handler, filter_non_ssl, Filter). diff --git a/lib/ssl/src/ssl_logger.erl b/lib/ssl/src/ssl_logger.erl new file mode 100644 index 0000000000..20e38c4882 --- /dev/null +++ b/lib/ssl/src/ssl_logger.erl @@ -0,0 +1,320 @@ +%% +%% %CopyrightBegin% +%% +%% 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. +%% You may obtain a copy of the License at +%% +%% http://www.apache.org/licenses/LICENSE-2.0 +%% +%% Unless required by applicable law or agreed to in writing, software +%% distributed under the License is distributed on an "AS IS" BASIS, +%% WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +%% See the License for the specific language governing permissions and +%% limitations under the License. +%% +%% %CopyrightEnd% +%% + +-module(ssl_logger). + +-export([format/2]). + +-define(DEC2HEX(X), + if ((X) >= 0) andalso ((X) =< 9) -> (X) + $0; + ((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 +%%------------------------------------------------------------------------- + +%% SSL log formatter +format(#{level:= _Level, msg:= {report, Msg}, meta:= _Meta}, _Config0) -> + #{direction := Direction, + protocol := Protocol, + message := BinMsg0} = Msg, + case Protocol of + 'tls_record' -> + BinMsg = lists:flatten(BinMsg0), + format_tls_record(Direction, BinMsg); + 'handshake' -> + format_handshake(Direction, BinMsg0); + _Other -> + [] + end. + +%%------------------------------------------------------------------------- +%% 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, 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(BinMsg)]), + Header ++ Message. + + +header_prefix_tls_record(inbound) -> + "reading"; +header_prefix_tls_record(outbound) -> + "writing". + + + +tls_record_version([<>|_]) -> + io_lib:format("TLS 1.2 Record Protocol, ~s", [msg_type(B)]); +tls_record_version([<>|_]) -> + io_lib:format("TLS 1.1 Record Protocol, ~s", [msg_type(B)]); +tls_record_version([<>|_]) -> + io_lib:format("TLS 1.0 Record Protocol, ~s", [msg_type(B)]); +tls_record_version([<>|_]) -> + io_lib:format("SSL 3.0 Record Protocol, ~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. + + +%%------------------------------------------------------------------------- +%% Hex encoding functions +%%------------------------------------------------------------------------- +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, [<>|T], Row, Acc, C) when C =:= 0 -> + convert_to_hex(P, [<>|T], + update_row(<>, Row), + prepend_first_row(P, A, B, Acc, C), + C + 1); +%% New line +convert_to_hex(P, [<>|T], Row, Acc, C) when C rem 16 =:= 0 -> + convert_to_hex(P, [<>|T], + update_row(<>, []), + 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, [<>|T], Row, Acc, C) when C rem 8 =:= 7 -> + convert_to_hex(P, [<>|T], + update_row(<>, Row), + prepend_eighths_hex(A, B, Acc), + C + 1); +convert_to_hex(P, [<>|T], Row, Acc, C) -> + convert_to_hex(P, [<>|T], + update_row(<>, 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 ++ " - ")). + + +end_row(tls_record, 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. -- cgit v1.2.3 From 41a71f54b2da01bc532d0c2d16c691e6622817ca Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?P=C3=A9ter=20Dimitrov?= Date: Mon, 18 Jun 2018 15:19:09 +0200 Subject: ssl: Add set_log_level/1 - Add utility function for setting log level of ssl application modules. Change-Id: Iee278ada17b4d872a9891094b96ce5343bf0ade4 --- lib/ssl/doc/src/ssl.xml | 11 +++++++++++ lib/ssl/src/ssl.erl | 29 ++++++++++++++++++++++++++++- 2 files changed, 39 insertions(+), 1 deletion(-) (limited to 'lib') diff --git a/lib/ssl/doc/src/ssl.xml b/lib/ssl/doc/src/ssl.xml index e3deb1c8a4..ab9f485464 100644 --- a/lib/ssl/doc/src/ssl.xml +++ b/lib/ssl/doc/src/ssl.xml @@ -1396,6 +1396,17 @@ fun(srp, Username :: string(), UserState :: term()) -> + + set_log_level(Level) -> ok | {error, Reason} + Sets log level for the SSL application. + + Level = atom() + + +

Sets log level for the SSL application.

+ + + shutdown(SslSocket, How) -> ok | {error, Reason} Immediately closes a socket. diff --git a/lib/ssl/src/ssl.erl b/lib/ssl/src/ssl.erl index 592c02a28c..9cf2b8acb0 100644 --- a/lib/ssl/src/ssl.erl +++ b/lib/ssl/src/ssl.erl @@ -55,7 +55,8 @@ format_error/1, renegotiate/1, prf/5, negotiated_protocol/1, connection_information/1, connection_information/2]). %% Misc --export([handle_options/2, tls_version/1, new_ssl_options/3, suite_to_str/1]). +-export([handle_options/2, tls_version/1, new_ssl_options/3, suite_to_str/1, + set_log_level/1]). -deprecated({ssl_accept, 1, eventually}). -deprecated({ssl_accept, 2, eventually}). @@ -801,6 +802,32 @@ suite_to_str(Cipher) -> ssl_cipher:suite_to_str(Cipher). +%%-------------------------------------------------------------------- +-spec set_log_level(atom()) -> ok | {error, term()}. +%% +%% Description: Set log level for the SSL application +%%-------------------------------------------------------------------- +set_log_level(Level) -> + case application:get_all_key(ssl) of + {ok, PropList} -> + Modules = proplists:get_value(modules, PropList), + set_module_level(Modules, Level); + undefined -> + {error, ssl_not_started} + end. + +set_module_level(Modules, Level) -> + Fun = fun (Module) -> + ok = logger:set_module_level(Module, Level) + end, + try lists:map(Fun, Modules) of + _ -> + ok + catch + error:{badmatch, Error} -> + Error + end. + %%%-------------------------------------------------------------- %%% Internal functions %%%-------------------------------------------------------------------- -- cgit v1.2.3 From 13ae4276e81853a1d66aeaeaa392230037cf3a04 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?P=C3=A9ter=20Dimitrov?= Date: Mon, 18 Jun 2018 17:17:22 +0200 Subject: ssl: Add support for stateful logging - Introduce stateful logging levels to the ssl application: The SSL option 'log_alert' sets log level to notice/warning if it is set to true/false. Default log level is notice. - Add new SSL option 'log_level' that overrides the value of 'log_alert'. Default value is notice. - 'log_level' debug triggers verbose logging of TLS protocol messages and logging of ignored alerts in DTLS. Change-Id: I28d3f4029a5d504ec612abe4b9ae0b7d9b115197 --- lib/ssl/src/dtls_connection.erl | 6 +++--- lib/ssl/src/ssl.erl | 30 ++++++++++++++++++++------ lib/ssl/src/ssl_connection.erl | 48 ++++++++++++++++++++++------------------- lib/ssl/src/ssl_internal.hrl | 4 +++- lib/ssl/src/ssl_logger.erl | 28 +++++++++++++++++++++++- lib/ssl/src/tls_connection.erl | 31 ++++++++++++++------------ lib/ssl/src/tls_handshake.erl | 2 +- lib/ssl/src/tls_record.erl | 42 ++++++++++++++++++++---------------- 8 files changed, 124 insertions(+), 67 deletions(-) (limited to 'lib') diff --git a/lib/ssl/src/dtls_connection.erl b/lib/ssl/src/dtls_connection.erl index 610ab9a51c..9596fe25c8 100644 --- a/lib/ssl/src/dtls_connection.erl +++ b/lib/ssl/src/dtls_connection.erl @@ -927,7 +927,7 @@ handle_own_alert(Alert, Version, StateName, #state{data_tag = udp, ssl_options = Options} = State0) -> case ignore_alert(Alert, State0) of {true, State} -> - log_ignore_alert(Options#ssl_options.log_alert, StateName, Alert, Role), + log_ignore_alert(Options#ssl_options.log_level, StateName, Alert, Role), {next_state, StateName, State}; {false, State} -> ssl_connection:handle_own_alert(Alert, Version, StateName, State) @@ -1124,9 +1124,9 @@ is_ignore_alert(#alert{description = ?ILLEGAL_PARAMETER}) -> is_ignore_alert(_) -> false. -log_ignore_alert(true, StateName, Alert, Role) -> +log_ignore_alert(debug, StateName, Alert, Role) -> Txt = ssl_alert:alert_txt(Alert), ?LOG_ERROR("DTLS over UDP ~p: In state ~p ignored to send ALERT ~s as DoS-attack mitigation \n", [Role, StateName, Txt]); -log_ignore_alert(false, _, _,_) -> +log_ignore_alert(_, _, _, _) -> ok. diff --git a/lib/ssl/src/ssl.erl b/lib/ssl/src/ssl.erl index 9cf2b8acb0..c7f1f36d5d 100644 --- a/lib/ssl/src/ssl.erl +++ b/lib/ssl/src/ssl.erl @@ -924,7 +924,7 @@ handle_options(Opts0, Role, Host) -> ok end, - SSLOptions = #ssl_options{ + SSLOptions0 = #ssl_options{ versions = Versions, verify = validate_option(verify, Verify), verify_fun = VerifyFun, @@ -971,7 +971,6 @@ handle_options(Opts0, Role, Host) -> next_protocol_selector = make_next_protocol_selector( handle_option(client_preferred_next_protocols, Opts, undefined)), - log_alert = handle_option(log_alert, Opts, true), server_name_indication = handle_option(server_name_indication, Opts, default_option_role(client, server_name_indication_default(Host), Role)), @@ -997,6 +996,10 @@ handle_options(Opts0, Role, Host) -> handshake = handle_option(handshake, Opts, full), customize_hostname_check = handle_option(customize_hostname_check, Opts, []) }, + LogLevel = handle_option(log_alert, Opts, true), + SSLOptions = SSLOptions0#ssl_options{ + log_level = handle_option(log_level, Opts, LogLevel) + }, CbInfo = proplists:get_value(cb_info, Opts, default_cb_info(Protocol)), SslOptions = [protocol, versions, verify, verify_fun, partial_chain, @@ -1008,7 +1011,7 @@ handle_options(Opts0, Role, Host) -> cb_info, renegotiate_at, secure_renegotiate, hibernate_after, erl_dist, alpn_advertised_protocols, sni_hosts, sni_fun, alpn_preferred_protocols, next_protocols_advertised, - client_preferred_next_protocols, log_alert, + client_preferred_next_protocols, log_alert, log_level, server_name_indication, honor_cipher_order, padding_check, crl_check, crl_cache, fallback, signature_algs, eccs, honor_ecc_order, beast_mitigation, max_handshake_size, handshake, customize_hostname_check], @@ -1187,7 +1190,20 @@ validate_option(client_preferred_next_protocols, {Precedence, PreferredProtocols Value; validate_option(client_preferred_next_protocols, undefined) -> undefined; -validate_option(log_alert, Value) when is_boolean(Value) -> +validate_option(log_alert, true) -> + notice; +validate_option(log_alert, false) -> + warning; +validate_option(log_level, Value) when + is_atom(Value) andalso + (Value =:= emergency orelse + Value =:= alert orelse + Value =:= critical orelse + Value =:= error orelse + Value =:= warning orelse + Value =:= notice orelse + Value =:= info orelse + Value =:= debug) -> Value; validate_option(next_protocols_advertised, Value) when is_list(Value) -> validate_binary_list(next_protocols_advertised, Value), @@ -1562,8 +1578,10 @@ new_ssl_options([{next_protocols_advertised, Value} | Rest], #ssl_options{} = Op new_ssl_options([{client_preferred_next_protocols, Value} | Rest], #ssl_options{} = Opts, RecordCB) -> new_ssl_options(Rest, Opts#ssl_options{next_protocol_selector = make_next_protocol_selector(validate_option(client_preferred_next_protocols, Value))}, RecordCB); -new_ssl_options([{log_alert, Value} | Rest], #ssl_options{} = Opts, RecordCB) -> - new_ssl_options(Rest, Opts#ssl_options{log_alert = validate_option(log_alert, Value)}, RecordCB); +new_ssl_options([{log_alert, Value} | Rest], #ssl_options{} = Opts, RecordCB) -> + new_ssl_options(Rest, Opts#ssl_options{log_level = validate_option(log_alert, Value)}, RecordCB); +new_ssl_options([{log_level, Value} | Rest], #ssl_options{} = Opts, RecordCB) -> + new_ssl_options(Rest, Opts#ssl_options{log_level = validate_option(log_level, Value)}, RecordCB); new_ssl_options([{server_name_indication, Value} | Rest], #ssl_options{} = Opts, RecordCB) -> new_ssl_options(Rest, Opts#ssl_options{server_name_indication = validate_option(server_name_indication, Value)}, RecordCB); new_ssl_options([{honor_cipher_order, Value} | Rest], #ssl_options{} = Opts, RecordCB) -> diff --git a/lib/ssl/src/ssl_connection.erl b/lib/ssl/src/ssl_connection.erl index bfb83343d8..bd0057243d 100644 --- a/lib/ssl/src/ssl_connection.erl +++ b/lib/ssl/src/ssl_connection.erl @@ -340,14 +340,15 @@ handle_own_alert(Alert, Version, StateName, Connection:send(Transport, Socket, BinMsg), Report = #{direction => outbound, protocol => 'tls_record', - message => BinMsg, - version => Version}, - ?LOG_DEBUG(Report, #{domain => [otp,ssl,tls_record]}) + message => BinMsg}, + ssl_logger:debug(SslOpts#ssl_options.log_level, Report, #{domain => [otp,ssl,tls_record]}) catch _:_ -> %% Can crash if we are in a uninitialized state ignore end, try %% Try to tell the local user - log_alert(SslOpts#ssl_options.log_alert, Role, Connection:protocol_name(), StateName, Alert#alert{role = Role}), + log_alert(SslOpts#ssl_options.log_level, Role, + Connection:protocol_name(), StateName, + Alert#alert{role = Role}), handle_normal_shutdown(Alert,StateName, State) catch _:_ -> ok @@ -378,8 +379,9 @@ handle_alert(#alert{level = ?FATAL} = Alert, StateName, port = Port, session = Session, user_application = {_Mon, Pid}, role = Role, socket_options = Opts, tracker = Tracker} = State) -> invalidate_session(Role, Host, Port, Session), - log_alert(SslOpts#ssl_options.log_alert, Role, Connection:protocol_name(), - StateName, Alert#alert{role = opposite_role(Role)}), + log_alert(SslOpts#ssl_options.log_level, Role, + Connection:protocol_name(), StateName, + Alert#alert{role = opposite_role(Role)}), alert_user(Transport, Tracker, Socket, StateName, Opts, Pid, From, Alert, Role, Connection), stop(normal, State); @@ -390,8 +392,9 @@ handle_alert(#alert{level = ?WARNING, description = ?CLOSE_NOTIFY} = Alert, handle_alert(#alert{level = ?WARNING, description = ?NO_RENEGOTIATION} = Alert, StateName, #state{role = Role, ssl_options = SslOpts, protocol_cb = Connection, renegotiation = {true, internal}} = State) -> - log_alert(SslOpts#ssl_options.log_alert, Role, - Connection:protocol_name(), StateName, Alert#alert{role = opposite_role(Role)}), + log_alert(SslOpts#ssl_options.log_level, Role, + Connection:protocol_name(), StateName, + Alert#alert{role = opposite_role(Role)}), handle_normal_shutdown(Alert, StateName, State), stop({shutdown, peer_close}, State); @@ -399,8 +402,9 @@ handle_alert(#alert{level = ?WARNING, description = ?NO_RENEGOTIATION} = Alert, #state{role = Role, ssl_options = SslOpts, renegotiation = {true, From}, protocol_cb = Connection} = State0) -> - log_alert(SslOpts#ssl_options.log_alert, Role, - Connection:protocol_name(), StateName, Alert#alert{role = opposite_role(Role)}), + log_alert(SslOpts#ssl_options.log_level, Role, + Connection:protocol_name(), StateName, + Alert#alert{role = opposite_role(Role)}), gen_statem:reply(From, {error, renegotiation_rejected}), {Record, State1} = Connection:next_record(State0), %% Go back to connection! @@ -410,8 +414,9 @@ handle_alert(#alert{level = ?WARNING, description = ?NO_RENEGOTIATION} = Alert, %% Gracefully log and ignore all other warning alerts handle_alert(#alert{level = ?WARNING} = Alert, StateName, #state{ssl_options = SslOpts, protocol_cb = Connection, role = Role} = State0) -> - log_alert(SslOpts#ssl_options.log_alert, Role, - Connection:protocol_name(), StateName, Alert#alert{role = opposite_role(Role)}), + log_alert(SslOpts#ssl_options.log_level, Role, + Connection:protocol_name(), StateName, + Alert#alert{role = opposite_role(Role)}), {Record, State} = Connection:next_record(State0), Connection:next_event(StateName, Record, State). @@ -425,7 +430,7 @@ write_application_data(Data0, {FromPid, _} = From, transport_cb = Transport, connection_states = ConnectionStates0, socket_options = SockOpts, - ssl_options = #ssl_options{renegotiate_at = RenegotiateAt}} = State) -> + ssl_options = #ssl_options{renegotiate_at = RenegotiateAt} = SslOpts} = State) -> Data = encode_packet(Data0, SockOpts), case time_to_renegotiate(Data, ConnectionStates0, RenegotiateAt) of @@ -448,9 +453,8 @@ write_application_data(Data0, {FromPid, _} = From, end, Report = #{direction => outbound, protocol => 'tls_record', - message => Msgs, - version => Version}, - ?LOG_DEBUG(Report, #{domain => [otp,ssl,tls_record]}), + message => Msgs}, + ssl_logger:debug(SslOpts#ssl_options.log_level, Report, #{domain => [otp,ssl,tls_record]}), RetVal end. @@ -2751,14 +2755,14 @@ alert_user(Transport, Tracker, Socket, Active, Pid, From, Alert, Role, Connectio Transport, Socket, Connection, Tracker), ReasonCode}) end. -log_alert(true, Role, ProtocolName, StateName, #alert{role = Role} = Alert) -> +log_alert(Level, Role, ProtocolName, StateName, #alert{role = Role} = Alert) -> Txt = ssl_alert:own_alert_txt(Alert), - ?LOG_NOTICE(io_lib:format("~s ~p: In state ~p ~s\n", [ProtocolName, Role, StateName, Txt])); -log_alert(true, Role, ProtocolName, StateName, Alert) -> + Report = io_lib:format("~s ~p: In state ~p ~s\n", [ProtocolName, Role, StateName, Txt]), + ssl_logger:notice(Level, Report); +log_alert(Level, Role, ProtocolName, StateName, Alert) -> Txt = ssl_alert:alert_txt(Alert), - ?LOG_NOTICE(io_lib:format("~s ~p: In state ~p ~s\n", [ProtocolName, Role, StateName, Txt])); -log_alert(false, _, _, _, _) -> - ok. + Report = io_lib:format("~s ~p: In state ~p ~s\n", [ProtocolName, Role, StateName, Txt]), + ssl_logger:notice(Level, Report). invalidate_session(client, Host, Port, Session) -> ssl_manager:invalidate_session(Host, Port, Session); diff --git a/lib/ssl/src/ssl_internal.hrl b/lib/ssl/src/ssl_internal.hrl index 6719371f95..a98cbf8542 100644 --- a/lib/ssl/src/ssl_internal.hrl +++ b/lib/ssl/src/ssl_internal.hrl @@ -128,7 +128,7 @@ alpn_preferred_protocols = undefined :: [binary()] | undefined, next_protocols_advertised = undefined :: [binary()] | undefined, next_protocol_selector = undefined, %% fun([binary()]) -> binary()) - log_alert :: boolean(), + log_level = notice :: atom(), server_name_indication = undefined, sni_hosts :: [{inet:hostname(), [tuple()]}], sni_fun :: function() | undefined, @@ -181,6 +181,8 @@ -type gen_fsm_state_return() :: {next_state, state_name(), term()} | {next_state, state_name(), term(), timeout()} | {stop, term(), term()}. +-type ssl_options() :: #ssl_options{}. + -endif. % -ifdef(ssl_internal). diff --git a/lib/ssl/src/ssl_logger.erl b/lib/ssl/src/ssl_logger.erl index 20e38c4882..23e9e096cc 100644 --- a/lib/ssl/src/ssl_logger.erl +++ b/lib/ssl/src/ssl_logger.erl @@ -20,7 +20,9 @@ -module(ssl_logger). --export([format/2]). +-export([debug/3, + format/2, + notice/2]). -define(DEC2HEX(X), if ((X) >= 0) andalso ((X) =< 9) -> (X) + $0; @@ -32,6 +34,7 @@ -include("tls_record.hrl"). -include("ssl_internal.hrl"). -include("tls_handshake.hrl"). +-include_lib("kernel/include/logger.hrl"). %%------------------------------------------------------------------------- %% External API @@ -52,6 +55,29 @@ format(#{level:= _Level, msg:= {report, Msg}, meta:= _Meta}, _Config0) -> [] end. +%% Stateful logging +debug(Level, Report, Meta) -> + case logger:compare_levels(Level, debug) of + lt -> + ?LOG_DEBUG(Report, Meta); + eq -> + ?LOG_DEBUG(Report, Meta); + _ -> + ok + end. + +%% Stateful logging +notice(Level, Report) -> + case logger:compare_levels(Level, notice) of + lt -> + ?LOG_NOTICE(Report); + eq -> + ?LOG_NOTICE(Report); + _ -> + ok + end. + + %%------------------------------------------------------------------------- %% Handshake Protocol %%------------------------------------------------------------------------- diff --git a/lib/ssl/src/tls_connection.erl b/lib/ssl/src/tls_connection.erl index 071f464851..47779c3450 100644 --- a/lib/ssl/src/tls_connection.erl +++ b/lib/ssl/src/tls_connection.erl @@ -266,7 +266,8 @@ send_handshake(Handshake, State) -> queue_handshake(Handshake, #state{negotiated_version = Version, tls_handshake_history = Hist0, flight_buffer = Flight0, - connection_states = ConnectionStates0} = State0) -> + connection_states = ConnectionStates0, + ssl_options = SslOpts} = State0) -> {BinHandshake, ConnectionStates, Hist} = encode_handshake(Handshake, Version, ConnectionStates0, Hist0), Report = #{direction => outbound, @@ -275,8 +276,9 @@ queue_handshake(Handshake, #state{negotiated_version = Version, HandshakeMsg = #{direction => outbound, protocol => 'handshake', message => Handshake}, - ?LOG_DEBUG(HandshakeMsg, #{domain => [otp,ssl,handshake]}), - ?LOG_DEBUG(Report, #{domain => [otp,ssl,tls_record]}), + ssl_logger:debug(SslOpts#ssl_options.log_level, HandshakeMsg, #{domain => [otp,ssl,handshake]}), + ssl_logger:debug(SslOpts#ssl_options.log_level, Report, #{domain => [otp,ssl,tls_record]}), + State0#state{connection_states = ConnectionStates, tls_handshake_history = Hist, flight_buffer = Flight0 ++ [BinHandshake]}. @@ -288,14 +290,15 @@ send_handshake_flight(#state{socket = Socket, {State0#state{flight_buffer = []}, []}. queue_change_cipher(Msg, #state{negotiated_version = Version, - flight_buffer = Flight0, - connection_states = ConnectionStates0} = State0) -> + flight_buffer = Flight0, + connection_states = ConnectionStates0, + ssl_options = SslOpts} = State0) -> {BinChangeCipher, ConnectionStates} = encode_change_cipher(Msg, Version, ConnectionStates0), Report = #{direction => outbound, protocol => 'tls_record', message => BinChangeCipher}, - ?LOG_DEBUG(Report, #{domain => [otp,ssl,tls_record]}), + ssl_logger:debug(SslOpts#ssl_options.log_level, Report, #{domain => [otp,ssl,tls_record]}), State0#state{connection_states = ConnectionStates, flight_buffer = Flight0 ++ [BinChangeCipher]}. @@ -323,7 +326,8 @@ empty_connection_state(ConnectionEnd, BeastMitigation) -> send_alert(Alert, #state{negotiated_version = Version, socket = Socket, transport_cb = Transport, - connection_states = ConnectionStates0} = State0) -> + connection_states = ConnectionStates0, + ssl_options = SslOpts} = State0) -> {BinMsg, ConnectionStates} = encode_alert(Alert, Version, ConnectionStates0), @@ -331,8 +335,7 @@ send_alert(Alert, #state{negotiated_version = Version, Report = #{direction => outbound, protocol => 'tls_record', message => BinMsg}, - ?LOG_DEBUG(Report, #{domain => [otp,ssl,tls_record]}), - + ssl_logger:debug(SslOpts#ssl_options.log_level, Report, #{domain => [otp,ssl,tls_record]}), State0#state{connection_states = ConnectionStates}. %%-------------------------------------------------------------------- @@ -441,8 +444,8 @@ init({call, From}, {start, Timeout}, HelloMsg = #{direction => outbound, protocol => 'handshake', message => Hello}, - ?LOG_DEBUG(HelloMsg, #{domain => [otp,ssl,handshake]}), - ?LOG_DEBUG(Report, #{domain => [otp,ssl,tls_record]}), + ssl_logger:debug(SslOpts#ssl_options.log_level, HelloMsg, #{domain => [otp,ssl,handshake]}), + ssl_logger:debug(SslOpts#ssl_options.log_level, Report, #{domain => [otp,ssl,tls_record]}), State1 = State0#state{connection_states = ConnectionStates, negotiated_version = Version, %% Requested version session = @@ -679,11 +682,11 @@ initial_state(Role, Host, Port, Socket, {SSLOptions, SocketOptions, Tracker}, Us next_tls_record(Data, StateName, #state{protocol_buffers = #protocol_buffers{tls_record_buffer = Buf0, - tls_cipher_texts = CT0} = Buffers} - = State0) -> + tls_cipher_texts = CT0} = Buffers, + ssl_options = SslOpts} = State0) -> case tls_record:get_tls_records(Data, acceptable_record_versions(StateName, State0), - Buf0) of + Buf0, SslOpts) of {Records, Buf1} -> CT1 = CT0 ++ Records, next_record(State0#state{protocol_buffers = diff --git a/lib/ssl/src/tls_handshake.erl b/lib/ssl/src/tls_handshake.erl index 4aed414b6d..4e6bbb5061 100644 --- a/lib/ssl/src/tls_handshake.erl +++ b/lib/ssl/src/tls_handshake.erl @@ -276,7 +276,7 @@ get_tls_handshake_aux(Version, < inbound, protocol => 'handshake', message => Handshake}, - ?LOG_DEBUG(Report, #{domain => [otp,ssl,handshake]}), + ssl_logger:debug(Opts#ssl_options.log_level, Report, #{domain => [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 b744555753..278d471fdb 100644 --- a/lib/ssl/src/tls_record.erl +++ b/lib/ssl/src/tls_record.erl @@ -33,7 +33,7 @@ -include_lib("kernel/include/logger.hrl"). %% Handling of incoming data --export([get_tls_records/3, init_connection_states/2]). +-export([get_tls_records/4, init_connection_states/2]). %% Encoding TLS records -export([encode_handshake/3, encode_alert_record/3, @@ -76,24 +76,24 @@ init_connection_states(Role, BeastMitigation) -> pending_write => Pending}. %%-------------------------------------------------------------------- --spec get_tls_records(binary(), [tls_version()], binary()) -> {[binary()], binary()} | #alert{}. +-spec get_tls_records(binary(), [tls_version()], binary(), ssl_options()) -> {[binary()], binary()} | #alert{}. %% %% and returns it as a list of tls_compressed binaries also returns leftover %% Description: Given old buffer and new data from TCP, packs up a records %% data %%-------------------------------------------------------------------- -get_tls_records(Data, Versions, Buffer) -> +get_tls_records(Data, Versions, Buffer, SslOpts) -> BinData = list_to_binary([Buffer, Data]), case erlang:byte_size(BinData) of N when N >= 3 -> case assert_version(BinData, Versions) of true -> - get_tls_records_aux(BinData, []); + get_tls_records_aux(BinData, [], SslOpts); false -> ?ALERT_REC(?FATAL, ?BAD_RECORD_MAC) end; _ -> - get_tls_records_aux(BinData, []) + get_tls_records_aux(BinData, [], SslOpts) end. %%==================================================================== @@ -400,57 +400,61 @@ assert_version(<>, Versions) - get_tls_records_aux(<>, - Acc) -> + Acc, SslOpts) -> RawTLSRecord = <>, Report = #{direction => inbound, protocol => 'tls_record', message => [RawTLSRecord]}, - ?LOG_DEBUG(Report, #{domain => [otp,ssl,tls_record]}), + ssl_logger:debug(SslOpts#ssl_options.log_level, Report, #{domain => [otp,ssl,tls_record]}), get_tls_records_aux(Rest, [#ssl_tls{type = ?APPLICATION_DATA, version = {MajVer, MinVer}, - fragment = Data} | Acc]); + fragment = Data} | Acc], + SslOpts); get_tls_records_aux(<>, Acc) -> + Data:Length/binary, Rest/binary>>, Acc, SslOpts) -> RawTLSRecord = <>, Report = #{direction => inbound, protocol => 'tls_record', message => [RawTLSRecord]}, - ?LOG_DEBUG(Report, #{domain => [otp,ssl,tls_record]}), + ssl_logger:debug(SslOpts#ssl_options.log_level, Report, #{domain => [otp,ssl,tls_record]}), get_tls_records_aux(Rest, [#ssl_tls{type = ?HANDSHAKE, version = {MajVer, MinVer}, - fragment = Data} | Acc]); + fragment = Data} | Acc], + SslOpts); get_tls_records_aux(<>, Acc) -> + Rest/binary>>, Acc, SslOpts) -> RawTLSRecord = <>, Report = #{direction => inbound, protocol => 'tls_record', message => [RawTLSRecord]}, - ?LOG_DEBUG(Report, #{domain => [otp,ssl,tls_record]}), + ssl_logger:debug(SslOpts#ssl_options.log_level, Report, #{domain => [otp,ssl,tls_record]}), get_tls_records_aux(Rest, [#ssl_tls{type = ?ALERT, version = {MajVer, MinVer}, - fragment = Data} | Acc]); + fragment = Data} | Acc], + SslOpts); get_tls_records_aux(<>, - Acc) -> + Acc, SslOpts) -> RawTLSRecord = <>, Report = #{direction => inbound, protocol => 'tls_record', message => [RawTLSRecord]}, - ?LOG_DEBUG(Report, #{domain => [otp,ssl,tls_record]}), + ssl_logger:debug(SslOpts#ssl_options.log_level, Report, #{domain => [otp,ssl,tls_record]}), get_tls_records_aux(Rest, [#ssl_tls{type = ?CHANGE_CIPHER_SPEC, version = {MajVer, MinVer}, - fragment = Data} | Acc]); + fragment = Data} | Acc], + SslOpts); get_tls_records_aux(<<0:1, _CT:7, ?BYTE(_MajVer), ?BYTE(_MinVer), ?UINT16(Length), _/binary>>, - _Acc) when Length > ?MAX_CIPHER_TEXT_LENGTH -> + _Acc, _SslOpts) when Length > ?MAX_CIPHER_TEXT_LENGTH -> ?ALERT_REC(?FATAL, ?RECORD_OVERFLOW); -get_tls_records_aux(Data, Acc) -> +get_tls_records_aux(Data, Acc, _SslOpts) -> case size(Data) =< ?MAX_CIPHER_TEXT_LENGTH + ?INITIAL_BYTES of true -> {lists:reverse(Acc), Data}; -- cgit v1.2.3 From 4fd537f3984c7c5169e06438bdfb76e784e077f0 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?P=C3=A9ter=20Dimitrov?= Date: Wed, 20 Jun 2018 10:42:09 +0200 Subject: ssl: Add documentation to the log_level option Change-Id: Ibbb66f62c122cac2b1b6bd7f09cdaede4a86bd97 --- lib/ssl/doc/src/ssl.xml | 13 ++++++++++++- 1 file changed, 12 insertions(+), 1 deletion(-) (limited to 'lib') diff --git a/lib/ssl/doc/src/ssl.xml b/lib/ssl/doc/src/ssl.xml index ab9f485464..2f4cc7d8d7 100644 --- a/lib/ssl/doc/src/ssl.xml +++ b/lib/ssl/doc/src/ssl.xml @@ -88,6 +88,7 @@

| {client_preferred_next_protocols, {client | server, [binary()]} | {client | server, [binary()], binary()}}

| {log_alert, boolean()}

+

| {log_level, atom()}

| {server_name_indication, hostname() | disable}

| {customize_hostname_check, list()}

| {sni_hosts, [{hostname(), [ssl_option()]}]}

@@ -796,7 +797,17 @@ fun(srp, Username :: string(), UserState :: term()) -> the client.

{log_alert, boolean()} -

If set to false, error reports are not displayed.

 +

If set to false, error reports are not displayed.

+

Deprecated in OTP 22, use log_level instead.

+ + + {log_level, atom()} +

Specifies the log level for TLS/DTLS. It can take the following + values (ordered by increasing verbosity level): emergency, alert, critical, error, + warning, notice, info, debug.

+

At verbosity level notice and above error reports are + displayed in TLS. The level debug triggers verbose logging of TLS protocol + messages and logging of ignored alerts in DTLS.

 {honor_cipher_order, boolean()}

If set to true, use the server preference for cipher -- cgit v1.2.3 From bde179fd47062cda33dc801d5117bf74dde14acb Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?P=C3=A9ter=20Dimitrov?= Date: Wed, 20 Jun 2018 16:04:10 +0200 Subject: ssl: Prepare for release Change-Id: I40b13b3dce5c70b65cb0963c6ce4175268174e02 --- lib/ssl/vsn.mk | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) (limited to 'lib') diff --git a/lib/ssl/vsn.mk b/lib/ssl/vsn.mk index 10be907b4f..75d959accf 100644 --- a/lib/ssl/vsn.mk +++ b/lib/ssl/vsn.mk @@ -1 +1 @@ -SSL_VSN = 9.0 +SSL_VSN = 9.1 -- cgit v1.2.3