File 3861-ssl-ssl_trace-updates.patch of Package erlang
From 8f205c2b160c6f4f1833464cfc09630d6fa80e19 Mon Sep 17 00:00:00 2001
From: Jakub Witczak <kuba@erlang.org>
Date: Sat, 7 Jan 2023 15:39:45 +0100
Subject: [PATCH] ssl: ssl_trace updates
- add tc_check_profiles test to ssl_trace_SUITE
- return ok tuple from ssl_trace:start
- OCSP, cert trace profiles
- key update trace profile
- ssl_trace:write/2
- no more budget message
- add tls_sender:init to rle trace profile
- hibernate trace profile
- ssn trace profile
---
lib/ssl/src/dtls_connection.erl | 12 ++
lib/ssl/src/ssl.erl | 5 +
lib/ssl/src/ssl_certificate.erl | 30 ++++
lib/ssl/src/ssl_gen_statem.erl | 17 ++-
lib/ssl/src/ssl_handshake.erl | 14 ++
lib/ssl/src/ssl_trace.erl | 163 +++++++++++++++++-----
lib/ssl/src/tls_connection.erl | 13 +-
lib/ssl/src/tls_connection_1_3.erl | 17 +++
lib/ssl/src/tls_dtls_connection.erl | 11 ++
lib/ssl/src/tls_sender.erl | 50 +++++++
lib/ssl/src/tls_server_session_ticket.erl | 98 ++++++++++++-
lib/ssl/src/tls_v1.erl | 23 +++
lib/ssl/test/ssl_test_lib.erl | 9 ++
lib/ssl/test/ssl_trace_SUITE.erl | 96 ++++++++++---
14 files changed, 494 insertions(+), 64 deletions(-)
diff --git a/lib/ssl/src/dtls_connection.erl b/lib/ssl/src/dtls_connection.erl
index 94576a577f..eab76d2ef2 100644
--- a/lib/ssl/src/dtls_connection.erl
+++ b/lib/ssl/src/dtls_connection.erl
@@ -155,6 +155,9 @@
code_change/4,
format_status/2]).
+%% Tracing
+-export([handle_trace/3]).
+
%%====================================================================
%% Internal application API
%%====================================================================
@@ -862,3 +865,12 @@ is_time_to_renegotiate(N, M) when N < M->
is_time_to_renegotiate(_,_) ->
true.
+%%%################################################################
+%%%#
+%%%# Tracing
+%%%#
+handle_trace(hbn,
+ {call, {?MODULE, connection,
+ [_Type = info, Event, _State]}},
+ Stack) ->
+ {io_lib:format("Type = info Event = ~W ", [Event, 10]), Stack}.
diff --git a/lib/ssl/src/ssl.erl b/lib/ssl/src/ssl.erl
index 37bcc36c12..e77c14bdaa 100644
--- a/lib/ssl/src/ssl.erl
+++ b/lib/ssl/src/ssl.erl
@@ -2764,6 +2764,11 @@ unambiguous_path(Value) ->
%%%#
%%%# Tracing
%%%#
+handle_trace(csp, {return_from, {?MODULE, opt_ocsp, 3}, Return}, Stack) ->
+ #{ocsp_stapling := Stapling, ocsp_nonce := Nonce,
+ ocsp_responder_certs := Certs} = Return,
+ {io_lib:format("Stapling = ~w Nonce = ~W Certs = ~W",
+ [Stapling, Nonce, 5, Certs, 5]), Stack};
handle_trace(rle, {call, {?MODULE, listen, Args}}, Stack0) ->
Role = server,
{io_lib:format("(*~w) Args = ~W", [Role, Args, 10]), [{role, Role} | Stack0]};
diff --git a/lib/ssl/src/ssl_certificate.erl b/lib/ssl/src/ssl_certificate.erl
index 2e2b43f564..d0a9ca875e 100644
--- a/lib/ssl/src/ssl_certificate.erl
+++ b/lib/ssl/src/ssl_certificate.erl
@@ -85,6 +85,9 @@
available_cert_key_pairs/2
]).
+%% Tracing
+-export([handle_trace/3]).
+
%%====================================================================
%% Internal application API
%%====================================================================
@@ -825,3 +828,30 @@ cert_issuers(OTPCerts) ->
cert_auth_member(ChainSubjects, CertAuths) ->
CommonAuthorities = sets:intersection(sets:from_list(ChainSubjects), sets:from_list(CertAuths)),
not sets:is_empty(CommonAuthorities).
+
+%%%################################################################
+%%%#
+%%%# Tracing
+%%%#
+handle_trace(crt,
+ {call, {?MODULE, validate, [Cert, StatusOrExt| _]}}, Stack) ->
+ {io_lib:format("[~W] StatusOrExt = ~W", [Cert, 3, StatusOrExt, 10]), Stack};
+handle_trace(crt, {call, {?MODULE, verify_cert_extensions,
+ [Cert,
+ _UserState,
+ [], _Context]}}, Stack) ->
+ {io_lib:format(" no more extensions [~W]", [Cert, 3]), Stack};
+handle_trace(crt, {call, {?MODULE, verify_cert_extensions,
+ [Cert,
+ #{ocsp_responder_certs := _ResponderCerts,
+ ocsp_state := OcspState,
+ issuer := Issuer} = _UserState,
+ [#certificate_status{response = OcspResponsDer} |
+ _Exts], _Context]}}, Stack) ->
+ {io_lib:format("#2 OcspState = ~W Issuer = [~W] OcspResponsDer = ~W [~W]",
+ [OcspState, 10, Issuer, 3, OcspResponsDer, 2, Cert, 3]),
+ Stack};
+handle_trace(crt, {return_from,
+ {ssl_certificate, verify_cert_extensions, 4},
+ {valid, #{issuer := Issuer}}}, Stack) ->
+ {io_lib:format(" extensions valid Issuer = ~W", [Issuer, 3]), Stack}.
diff --git a/lib/ssl/src/ssl_gen_statem.erl b/lib/ssl/src/ssl_gen_statem.erl
index a9e16a309d..9d21ac154c 100644
--- a/lib/ssl/src/ssl_gen_statem.erl
+++ b/lib/ssl/src/ssl_gen_statem.erl
@@ -2225,4 +2225,19 @@ maybe_generate_client_shares(_) ->
%%%#
handle_trace(rle,
{call, {?MODULE, init, Args = [[Role | _]]}}, Stack0) ->
- {io_lib:format("(*~w) Args = ~W", [Role, Args, 3]), [{role, Role} | Stack0]}.
+ {io_lib:format("(*~w) Args = ~W", [Role, Args, 3]), [{role, Role} | Stack0]};
+handle_trace(hbn,
+ {call, {?MODULE, hibernate_after,
+ [_StateName = connection, State, Actions]}},
+ Stack) ->
+ #state{ssl_options= #{hibernate_after := HibernateAfter}} = State,
+ {io_lib:format("* * * maybe hibernating in ~w ms * * * Actions = ~W ",
+ [HibernateAfter, Actions, 10]), Stack};
+handle_trace(hbn,
+ {return_from, {?MODULE, hibernate_after, 3},
+ {Cmd, Arg,_State, Actions}},
+ Stack) ->
+ {io_lib:format("Cmd = ~w Arg = ~w Actions = ~W", [Cmd, Arg, Actions, 10]), Stack};
+handle_trace(hbn,
+ {call, {?MODULE, handle_common_event, [timeout, hibernate, connection | _]}}, Stack) ->
+ {io_lib:format("* * * hibernating * * *", []), Stack}.
diff --git a/lib/ssl/src/ssl_handshake.erl b/lib/ssl/src/ssl_handshake.erl
index 56a1ca81b9..9293a9f742 100644
--- a/lib/ssl/src/ssl_handshake.erl
+++ b/lib/ssl/src/ssl_handshake.erl
@@ -89,6 +89,8 @@
validation_fun_and_state/4,
path_validation_alert/1]).
+%% Tracing
+-export([handle_trace/3]).
%%====================================================================
%% Create handshake messages
%%====================================================================
@@ -3894,3 +3896,15 @@ extkey_oids_to_names([?'anyExtendedKeyUsage'| Rest], Acc) ->
extkey_oids_to_names(Rest, ["anyExtendedKeyUsage"| Acc]);
extkey_oids_to_names([Other| Rest], Acc) ->
extkey_oids_to_names(Rest, [Other | Acc]).
+
+%%%################################################################
+%%%#
+%%%# Tracing
+%%%#
+handle_trace(csp,
+ {call, {?MODULE, maybe_add_certificate_status_request,
+ [_Version, #{ocsp_stapling := true},
+ _OcspNonce, _HelloExtensions]}},
+ Stack) ->
+ {io_lib:format("#1 ADDING certificate status request",
+ []), Stack}.
diff --git a/lib/ssl/src/ssl_trace.erl b/lib/ssl/src/ssl_trace.erl
index c40381b78d..325e31d1fd 100644
--- a/lib/ssl/src/ssl_trace.erl
+++ b/lib/ssl/src/ssl_trace.erl
@@ -21,15 +21,16 @@
%%
%%% Purpose:
-%%% This module implements support for using the Erlang trace in a simple way for ssl
-%%% tracing.
+%%% This module implements support for using the Erlang trace in a simple way
+%%% for ssl tracing.
%%%
-%%% Begin the session with ssl_trace:start(). This will do a dbg:start() if needed and
-%%% then dbg:p/2 to set some flags.
+%%% Begin the session with ssl_trace:start(). This will do a dbg:start()
+%%% if needed and then dbg:p/2 to set some flags.
%%%
-%%% Next select trace profiles to activate: for example plain text printouts of messages
-%%% sent or received. This is switched on and off with ssl_trace:on(TraceProfile(s)) and
-%%% ssl_trace:off(TraceProfile(s)). For example:
+%%% Next select trace profiles to activate: for example plain text
+%%% printouts of messages sent or received. This is switched on and off with
+%%% ssl_trace:on(TraceProfile(s)) and ssl_trace:off(TraceProfile(s)).
+%%% For example:
%%%
%%% ssl_trace:on(rle) -- switch on printing role traces
%%% ssl_trace:on([api, rle]) -- switch on printing role and api traces
@@ -37,23 +38,26 @@
%%%
%%% To switch, use the off/0 or off/1 function in the same way, for example:
%%%
-%%% ssl_trace:off(api) -- switch off api tracing, but keep all other
+%%% ssl_trace:off(api) -- switch off api tracing, keep all other
%%% ssl_trace:off() -- switch off all ssl tracing
%%%
-%%% Present the trace result with some other method than the default io:format/2:
+%%% Present the trace result with some other method than the default
+%%% io:format/2:
%%% ssl_trace:start(fun(Format,Args) ->
%%% my_special( io_lib:format(Format,Args) )
%%% end)
-%%% Write to ssl_trace.txt file with budget of 1000 trace entries:
+%%% Write traces to text file with budget of 1000 trace entries:
%%% ssl_trace:start(IoFmt, [file, {budget, 1000}])
%%%
-module(ssl_trace).
-export([start/0, start/1, start/2, stop/0, on/0, on/1, off/0, off/1, is_on/0,
- is_off/0]).
+ is_off/0, write/2]).
-export([init/1, handle_call/3, handle_cast/2, handle_info/2]).
%% Internal apply_after:
-export([ets_delete/2]).
+%% Test purpose
+-export([trace_profiles/0]).
-behaviour(gen_server).
-define(SERVER, ?MODULE).
@@ -64,7 +68,8 @@
-record(state, {
file = undefined,
types_on = [],
- io_device = undefined
+ io_device = undefined,
+ write_fun
}).
%%%----------------------------------------------------------------
@@ -78,12 +83,14 @@ start(IoFmtFun) when is_function(IoFmtFun,2) ; is_function(IoFmtFun,3) ->
start(IoFmtFun, TraceOpts) when is_function(IoFmtFun,2);
is_function(IoFmtFun,3);
is_list(TraceOpts) ->
- {ok, Pid} = gen_server:start({local,?SERVER}, ?MODULE, TraceOpts, []),
+ WriteFun = fun(F,A,S) -> IoFmtFun(F,A), S end,
+ {ok, Pid} = gen_server:start({local,?SERVER}, ?MODULE,
+ [{write_fun, WriteFun}, TraceOpts], []),
true = is_process_alive(Pid),
catch dbg:start(),
start_tracer(IoFmtFun, TraceOpts),
dbg:p(all, [timestamp, c]),
- get_all_trace_profiles().
+ {ok, get_all_trace_profiles()}.
stop() ->
try
@@ -112,15 +119,18 @@ is_on() ->
is_off() ->
get_all_trace_profiles() -- is_on().
+write(Fmt, Args) ->
+ gen_server:call(?SERVER, {write, Fmt, Args}, ?CALL_TIMEOUT).
+
%%%----------------------------------------------------------------
-init(_) ->
+init(Args) ->
try
ets:new(?MODULE, [public, named_table])
catch
exit:badarg ->
ok
end,
- {ok, #state{}}.
+ {ok, #state{write_fun = proplists:get_value(write_fun, Args)}}.
handle_call({switch,on,Profiles}, _From, State) ->
[enable_profile(P) || P <- Profiles],
@@ -143,6 +153,11 @@ handle_call(file_close, _From, #state{io_device = IODevice} = State) ->
ok
end,
{reply, ok, State#state{io_device = undefined}};
+handle_call({write, Fmt, Args}, _From, State) ->
+ #state{io_device = IODevice, write_fun = WriteFun0} = State,
+ WriteFun = get_write_fun(IODevice, WriteFun0),
+ WriteFun(Fmt, Args, processed),
+ {reply, ok, State};
handle_call(C, _From, State) ->
io:format('*** Unknown call: ~p~n',[C]),
{reply, {error,{unknown_call,C}}, State}.
@@ -189,7 +204,12 @@ start_tracer(WriteFun, TraceOpts) when is_function(WriteFun,3) ->
Acc0 = [{budget, proplists:get_value(budget, TraceOpts, ?TRACE_BUDGET)}],
Acc1 = case lists:member(file, TraceOpts) of
true ->
- [{file, ?TRACE_FILE} | Acc0];
+ TraceFile =
+ case init:get_argument(ssl_trace_file) of
+ {ok, [[Path]]} -> Path;
+ _ -> ?TRACE_FILE
+ end,
+ [{file, TraceFile} | Acc0];
_ ->
Acc0
end,
@@ -214,16 +234,7 @@ start_dbg_tracer(WriteFun, InitHandlerAcc0) when is_function(WriteFun, 3) ->
try_handle_trace(ProfilesOn, Arg, WriteFun0, HandlerAcc) ->
IODevice = proplists:get_value(io_device, HandlerAcc),
- WriteFun =
- case is_pid(IODevice) of
- true ->
- fun(Format, Args, Return) ->
- ok = io:format(IODevice, Format, Args),
- Return
- end;
- false ->
- WriteFun0
- end,
+ WriteFun = get_write_fun(IODevice, WriteFun0),
Budget0 = proplists:get_value(budget, HandlerAcc, 0),
Timestamp = trace_ts(Arg),
Pid = trace_pid(Arg),
@@ -242,13 +253,13 @@ try_handle_trace(ProfilesOn, Arg, WriteFun0, HandlerAcc) ->
{skip, NewProcessStack} ->
%% Don't try to process this later
put_proc_stack(Pid, NewProcessStack),
- reduce_budget(BAcc);
+ reduce_budget(BAcc, WriteFun);
{Txt, NewProcessStack} when is_list(Txt) ->
put_proc_stack(Pid, NewProcessStack),
write_txt(WriteFun, Timestamp, Pid,
common_prefix(TraceInfo, Role,
Profile) ++ Txt),
- reduce_budget(BAcc)
+ reduce_budget(BAcc, WriteFun)
catch
_:_ ->
%% not processed by custom handler
@@ -268,15 +279,33 @@ try_handle_trace(ProfilesOn, Arg, WriteFun0, HandlerAcc) ->
common_prefix(TraceInfo, Role,
" ")]),
TraceInfo, 7], processed),
- reduce_budget(Budget0);
+ reduce_budget(Budget0, WriteFun);
_ ->
Budget1
end,
[{budget, Budget2} | proplists:delete(budget, HandlerAcc)].
-reduce_budget(B) when B>1 ->
+get_write_fun(IODevice, WriteFun0) ->
+ case is_pid(IODevice) of
+ true ->
+ fun(Format, Args, Return) ->
+ ok = io:format(IODevice, Format, Args),
+ Return
+ end;
+ false ->
+ WriteFun0
+ end.
+
+reduce_budget(B, _) when B > 1 ->
B - 1;
-reduce_budget(_B) ->
+reduce_budget(_, WriteFun) ->
+ case get(no_budget_msg_written) of
+ undefined ->
+ WriteFun("No more trace budget!~n", [], processed),
+ put(no_budget_msg_written, true);
+ _ ->
+ ok
+ end,
0.
write_txt(WriteFun, Timestamp, Pid, Txt) when is_list(Txt) ->
@@ -394,10 +423,74 @@ trace_profiles() ->
{ssl_gen_statem,
[{initial_hello,3}, {connect, 8}, {close, 2}, {terminate_alert, 1}]}
]},
- {rle, %%role
+ {csp, %% OCSP
+ fun(M, F, A) -> dbg:tpl(M, F, A, x) end,
+ fun(M, F, A) -> dbg:ctpl(M, F, A) end,
+ [{ssl_handshake, [{maybe_add_certificate_status_request, 4},
+ {client_hello_extensions, 10}, {cert_status_check, 5},
+ {get_ocsp_responder_list, 1}, {handle_ocsp_extension, 2},
+ {handle_server_hello_extensions, 10},
+ {handle_client_hello_extensions, 10},
+ {cert_status_check, 5}]},
+ {public_key, [{ocsp_extensions, 1}, %%{pkix_decode_cert, 2},
+ {pkix_ocsp_validate, 5}]},
+ {ssl, [{opt_ocsp, 3}]},
+ {ssl_certificate, [{verify_cert_extensions, 4}]},
+ {ssl_test_lib, [{init_openssl_server, 3}, {openssl_server_loop, 3}]},
+ {tls_connection, [{wait_ocsp_stapling, 3}]},
+ {dtls_connection, [{initial_hello, 3}, {hello, 3}, {connection, 3}]},
+ {tls_dtls_connection, [{wait_ocsp_stapling, 3}, {certify, 3}]},
+ {tls_handshake, [{ocsp_expect, 1}, {client_hello, 11}]},
+ {dtls_handshake, [{client_hello, 8}]}]},
+ {crt, %% certificates
+ fun(M, F, A) -> dbg:tpl(M, F, A, x) end,
+ fun(M, F, A) -> dbg:ctpl(M, F, A) end,
+ [{public_key, [{pkix_path_validation, 3}]},
+ {ssl_certificate, [{validate, 3}]},
+ {ssl_gen_statem, [{initial_hello, 3}]},
+ {ssl_handshake, [{path_validate, 11}, {path_validation, 10},
+ {maybe_check_hostname, 3}, {maybe_check_hostname, 3}]},
+ {tls_handshake_1_3, [{path_validation, 10}]},
+ {tls_connection_1_3, [{init,1}]},
+ {tls_connection, [{init,1}]},
+ {dtls_connection, [{init,1}]}]},
+ {kdt, %% key update
+ fun(M, F, A) -> dbg:tpl(M, F, A, x) end,
+ fun(M, F, A) -> dbg:ctpl(M, F, A) end,
+ [{tls_connection_1_3, [{handle_key_update, 2}]},
+ {tls_sender, [{init, 3}, {time_to_rekey, 6},
+ {send_post_handshake_data, 4}]},
+ {tls_v1, [{update_traffic_secret, 2}]}]},
+ {rle, %% role
fun(M, F, A) -> dbg:tpl(M, F, A, x) end,
fun(M, F, A) -> dbg:ctpl(M, F, A) end,
[{ssl, [{listen,2}, {connect,3}]},
{ssl_gen_statem, [{init, 1}]},
- {tls_server_session_ticket, [{init,1}]}]}
- ].
+ {tls_server_session_ticket, [{init,1}]},
+ {tls_sender, [{init, 3}]}]},
+ {ssn, %% session
+ fun(M, F, A) -> dbg:tpl(M, F, A, x) end,
+ fun(M, F, A) -> dbg:ctpl(M, F, A) end,
+ [{tls_server_session_ticket,
+ [{handle_call,3}, {handle_cast,2}, {handle_info,2},
+ {terminate,2}, {start_link,7},
+ {init,1}, {initial_state,1}, {validate_binder,5}, {stateful_store,0},
+ {stateful_ticket_store,6}, {stateful_use,4}, {stateful_use,6},
+ {stateful_usable_ticket,5}, {stateful_living_ticket,2},
+ {stateful_psk_ticket_id,1}, {generate_stateless_ticket,5}, {stateless_use,6},
+ {stateless_usable_ticket,5}, {stateless_living_ticket,5}, {in_window,2},
+ {stateless_anti_replay,5}]},
+ {tls_handshake_1_3,
+ [{get_ticket_data,3}]}]},
+ {hbn, %% hibernate
+ fun(M, F, A) -> dbg:tpl(M, F, A, x) end,
+ fun(M, F, A) -> dbg:ctpl(M, F, A) end,
+ [{tls_sender,
+ [{connection, 3}, {hibernate_after, 3}]},
+ {dtls_connection,
+ [{connection,3},
+ {gen_info, 3}]},
+ {dtls_gen_connection,
+ [{handle_info,3}]},
+ {ssl_gen_statem,
+ [{hibernate_after, 3}, {handle_common_event, 4}]}]}].
diff --git a/lib/ssl/src/tls_connection.erl b/lib/ssl/src/tls_connection.erl
index 1687721e54..07c922ce76 100644
--- a/lib/ssl/src/tls_connection.erl
+++ b/lib/ssl/src/tls_connection.erl
@@ -135,7 +135,9 @@
terminate/3,
code_change/4,
format_status/2]).
-
+
+%% Tracing
+-export([handle_trace/3]).
%%====================================================================
%% Internal application API
%%====================================================================
@@ -596,3 +598,12 @@ choose_tls_fsm(#{versions := Versions},
end;
choose_tls_fsm(_, _) ->
tls_1_0_to_1_2_fsm.
+
+%%%################################################################
+%%%#
+%%%# Tracing
+%%%#
+handle_trace(csp,
+ {call, {?MODULE, wait_ocsp_stapling,
+ [Type, Event|_]}}, Stack) ->
+ {io_lib:format("Type = ~w Event = ~W", [Type, Event, 10]), Stack}.
diff --git a/lib/ssl/src/tls_connection_1_3.erl b/lib/ssl/src/tls_connection_1_3.erl
index c99a64c42e..6824430a5d 100644
--- a/lib/ssl/src/tls_connection_1_3.erl
+++ b/lib/ssl/src/tls_connection_1_3.erl
@@ -145,6 +145,8 @@
send_key_update/2,
update_cipher_key/2]).
+%% Tracing
+-export([handle_trace/3]).
%%====================================================================
%% Internal API
%%====================================================================
@@ -745,3 +747,18 @@ handle_change_cipher_spec(Type, Msg, StateName, #state{protocol_specific = PS0}
fail ->
ssl_gen_statem:handle_common_event(Type, Msg, StateName, State)
end.
+
+%%%################################################################
+%%%#
+%%%# Tracing
+%%%#
+handle_trace(kdt,
+ {call, {?MODULE, handle_key_update,
+ [#key_update{request_update = update_requested}, _State]}},
+ Stack) ->
+ {io_lib:format("KeyUpdate procedure 2/4 - ~w received", [update_requested]), Stack};
+handle_trace(kdt,
+ {call, {?MODULE, handle_key_update,
+ [#key_update{request_update = update_not_requested}, _State]}},
+ Stack) ->
+ {io_lib:format("KeyUpdate procedure 4/4 - ~w received", [update_not_requested]), Stack}.
diff --git a/lib/ssl/src/tls_dtls_connection.erl b/lib/ssl/src/tls_dtls_connection.erl
index 14d812252b..ebf6f1b085 100644
--- a/lib/ssl/src/tls_dtls_connection.erl
+++ b/lib/ssl/src/tls_dtls_connection.erl
@@ -63,6 +63,9 @@
downgrade/3,
gen_handshake/4]).
+%% Tracing
+-export([handle_trace/3]).
+
%%--------------------------------------------------------------------
-spec internal_renegotiation(pid(), ssl_record:connection_states()) ->
ok.
@@ -1724,3 +1727,11 @@ assert_curve(ECCCurve) ->
_ ->
ok
end.
+
+%%%################################################################
+%%%#
+%%%# Tracing
+%%%#
+handle_trace(csp,
+ {call, {?MODULE, wait_ocsp_stapling, [Type, Msg | _]}}, Stack) ->
+ {io_lib:format("Type = ~w Msg = ~W", [Type, Msg, 10]), Stack}.
diff --git a/lib/ssl/src/tls_sender.erl b/lib/ssl/src/tls_sender.erl
index b53a801b90..4f7920ed35 100644
--- a/lib/ssl/src/tls_sender.erl
+++ b/lib/ssl/src/tls_sender.erl
@@ -54,6 +54,8 @@
connection/3,
handshake/3,
death_row/3]).
+%% Tracing
+-export([handle_trace/3]).
-record(static,
{connection_pid,
@@ -712,3 +714,51 @@ hibernate_after(connection = StateName,
{next_state, StateName, State, [{timeout, HibernateAfter, hibernate} | Actions]};
hibernate_after(StateName, State, Actions) ->
{next_state, StateName, State, Actions}.
+
+%%%################################################################
+%%%#
+%%%# Tracing
+%%%#
+handle_trace(kdt,
+ {call, {?MODULE, time_to_rekey,
+ [_Version, Data, Map, _RenegotiateAt,
+ KeyUpdateAt, BytesSent]}}, Stack) ->
+ #{current_write := #{sequence_number := Sn}} = Map,
+ DataSize = iolist_size(Data),
+ {io_lib:format("~w) (BytesSent:~w + DataSize:~w) > KeyUpdateAt:~w",
+ [Sn, BytesSent, DataSize, KeyUpdateAt]), Stack};
+handle_trace(kdt,
+ {call, {?MODULE, send_post_handshake_data,
+ [{key_update, update_requested}|_]}}, Stack) ->
+ {io_lib:format("KeyUpdate procedure 1/4 - update_requested sent", []), Stack};
+handle_trace(kdt,
+ {call, {?MODULE, send_post_handshake_data,
+ [{key_update, update_not_requested}|_]}}, Stack) ->
+ {io_lib:format("KeyUpdate procedure 3/4 - update_not_requested sent", []), Stack};
+handle_trace(hbn,
+ {call, {?MODULE, connection,
+ [timeout, hibernate | _]}}, Stack) ->
+ {io_lib:format("* * * hibernating * * *", []), Stack};
+handle_trace(hbn,
+ {call, {?MODULE, hibernate_after,
+ [_StateName = connection, State, Actions]}},
+ Stack) ->
+ #data{static=#static{hibernate_after = HibernateAfter}} = State,
+ {io_lib:format("* * * maybe hibernating in ~w ms * * * Actions = ~W ",
+ [HibernateAfter, Actions, 10]), Stack};
+handle_trace(hbn,
+ {return_from, {?MODULE, hibernate_after, 3},
+ {Cmd, Arg,_State, Actions}},
+ Stack) ->
+ {io_lib:format("Cmd = ~w Arg = ~w Actions = ~W", [Cmd, Arg, Actions, 10]), Stack};
+handle_trace(rle,
+ {call, {?MODULE, init, [Type, Opts, _StateData]}}, Stack0) ->
+ {Pid, #{role := Role,
+ socket := _Socket,
+ key_update_at := KeyUpdateAt,
+ erl_dist := IsErlDist,
+ trackers := Trackers,
+ negotiated_version := _Version}} = Opts,
+ {io_lib:format("(*~w) Type = ~w Pid = ~w Trackers = ~w Dist = ~w KeyUpdateAt = ~w",
+ [Role, Type, Pid, Trackers, IsErlDist, KeyUpdateAt]),
+ [{role, Role} | Stack0]}.
diff --git a/lib/ssl/src/tls_server_session_ticket.erl b/lib/ssl/src/tls_server_session_ticket.erl
index 2e2d708c6f..e0fea089bc 100644
--- a/lib/ssl/src/tls_server_session_ticket.erl
+++ b/lib/ssl/src/tls_server_session_ticket.erl
@@ -40,6 +40,9 @@
-export([init/1, handle_call/3, handle_cast/2, handle_info/2,
terminate/2, code_change/3, format_status/2]).
+%% Tracing
+-export([handle_trace/3]).
+
-define(SERVER, ?MODULE).
-record(state, {
@@ -85,7 +88,7 @@ use(Pid, Identifiers, Prf, HandshakeHist) ->
init([Listener | Args]) ->
process_flag(trap_exit, true),
Monitor = inet:monitor(Listener),
- State = inital_state(Args),
+ State = initial_state(Args),
{ok, State#state{listen_monitor = Monitor}}.
-spec handle_call(Request :: term(), From :: {pid(), term()}, State :: term()) ->
@@ -156,18 +159,18 @@ code_change(_OldVsn, State, _Extra) ->
Status :: list()) -> Status :: term().
format_status(_Opt, Status) ->
Status.
+
%%%===================================================================
%%% Internal functions
%%%===================================================================
-
-inital_state([stateless, Lifetime, _, MaxEarlyDataSize, undefined, Seed]) ->
+initial_state([stateless, Lifetime, _, MaxEarlyDataSize, undefined, Seed]) ->
#state{nonce = 0,
stateless = #{seed => stateless_seed(Seed),
window => undefined},
lifetime = Lifetime,
max_early_data_size = MaxEarlyDataSize
};
-inital_state([stateless, Lifetime, _, MaxEarlyDataSize, {Window, K, M}, Seed]) ->
+initial_state([stateless, Lifetime, _, MaxEarlyDataSize, {Window, K, M}, Seed]) ->
erlang:send_after(Window * 1000, self(), rotate_bloom_filters),
#state{nonce = 0,
stateless = #{bloom_filter => tls_bloom_filter:new(K, M),
@@ -177,7 +180,7 @@ inital_state([stateless, Lifetime, _, MaxEarlyDataSize, {Window, K, M}, Seed]) -
lifetime = Lifetime,
max_early_data_size = MaxEarlyDataSize
};
-inital_state([stateful, Lifetime, TicketStoreSize, MaxEarlyDataSize|_]) ->
+initial_state([stateful, Lifetime, TicketStoreSize, MaxEarlyDataSize|_]) ->
%% statfeful servers replay
%% protection is that it saves
%% all valid tickets
@@ -481,3 +484,88 @@ warm_up_windows(_) ->
%% 2*WindowSize to ensure tickets from a previous instance of the server
%% (before a restart) cannot be reused, if the ticket encryption seed is reused.
2.
+
+%%%################################################################
+%%%#
+%%%# Tracing
+%%%#
+handle_trace(rle, {call, {?MODULE, init, [[ListenSocket, Mode, Lifetime,
+ StoreSize | _T]]}}, Stack) ->
+ {io_lib:format("(*server) ([ListenSocket = ~w Mode = ~w Lifetime = ~w "
+ "StoreSize = ~w, ...])",
+ [ListenSocket, Mode, Lifetime, StoreSize]),
+ [{role, server} | Stack]};
+handle_trace(ssn,
+ {call, {?MODULE, terminate, [Reason, _State]}}, Stack) ->
+ {io_lib:format("(Reason ~w)", [Reason]), Stack};
+handle_trace(ssn,
+ {call, {?MODULE, handle_call,
+ [CallTuple, _From, _State]}}, Stack) ->
+ {io_lib:format("(Call = ~w)", [element(1, CallTuple)]), Stack};
+handle_trace(ssn,
+ {call, {?MODULE,handle_call,
+ [{Call = use_ticket,
+ {offered_psks,
+ [{psk_identity, PskIdentity, _ObfAge}],
+ [Binder]},
+ _Prf,
+ _HandshakeHist}, _From, _State]}}, Stack) ->
+ {io_lib:format("(Call = ~w PskIdentity = ~W Binder = ~W)",
+ [Call, PskIdentity, 5, Binder, 5]), Stack};
+handle_trace(ssn,
+ {call, {?MODULE, validate_binder,
+ [Binder, _HandshakeHist, PSK, _Prf, _AlertDetail]}}, Stack) ->
+ {io_lib:format("(Binder = ~W PSK = ~W)", [Binder, 5, PSK, 5]), Stack};
+handle_trace(ssn,
+ {call, {?MODULE, initial_state,
+ [[Mode, _Lifetime, _StoreSize,_MaxEarlyDataSize,
+ Window, Seed]]}}, Stack) ->
+ {io_lib:format("(Mode = ~w Window = ~w Seed = ~W)", [Mode, Window, Seed, 5]), Stack};
+handle_trace(ssn,
+ {call, {?MODULE, generate_stateless_ticket,
+ [_BaseTicket, _Prf, MasterSecret, _State]}}, Stack) ->
+ {io_lib:format("(MasterSecret = ~W)", [MasterSecret, 5]), Stack};
+handle_trace(ssn,
+ {call, {?MODULE, stateless_use,
+ [[{psk_identity, Encrypted, _ObfAge} | _],
+ [Binder | _],
+ _Prf, _HandshakeHist, _Index, _State]}}, Stack) ->
+ {io_lib:format("(Encrypted = ~W Binder = ~W)", [Encrypted, 5, Binder, 5]), Stack};
+handle_trace(ssn,
+ {call, {?MODULE, in_window, [RealAge, Window]}}, Stack) ->
+ {io_lib:format("(RealAge = ~w Window = ~w)",
+ [RealAge, Window]), Stack};
+handle_trace(ssn,
+ {call, {?MODULE, stateless_usable_ticket,
+ [{stateless_ticket, _Prf, _PreSharedKey, _TicketAgeAdd,
+ _Lifetime, _Timestamp}, _ObfAge, Binder,
+ _HandshakeHist, Window]}}, Stack) ->
+ {io_lib:format("(Binder = ~W Window = ~w)", [Binder, 5, Window]), Stack};
+handle_trace(ssn,
+ {call, {?MODULE, stateless_anti_replay,
+ [_Index, PSK, _Binder, _State]}}, Stack) ->
+ {io_lib:format("(PSK = ~W)", [PSK, 5]), Stack};
+handle_trace(ssn,
+ {return_from, {?MODULE, stateless_use, 6},
+ {{ok, {_Index, PSK}}, _State}}, Stack) ->
+ {io_lib:format("PSK = ~W", [PSK, 5]), Stack};
+handle_trace(ssn,
+ {return_from, {?MODULE, generate_stateless_ticket, 4},
+ {new_session_ticket, _LifeTime, _AgeAdd, _Nonce, Ticket,
+ _Extensions}}, Stack) ->
+ {io_lib:format("Ticket = ~W", [Ticket, 5]), Stack};
+handle_trace(ssn,
+ {return_from, {?MODULE, initial_state, 1},
+ {state, _Stateless = #{seed := {IV, Shard}, window := Window},
+ _Stateful = undefined, _Nonce, _Lifetime ,
+ _MaxEarlyDataSize, ListenMonitor}}, Stack) ->
+ {io_lib:format("IV = ~W Shard = ~W Window = ~w ListenMonitor = ~w",
+ [IV, 5, Shard, 5, Window, ListenMonitor]), Stack};
+handle_trace(ssn,
+ {return_from, {?MODULE, stateless_anti_replay, 4},
+ {{ok, {_Index, PSK}}, _State}}, Stack) ->
+ {io_lib:format("ticket OK ~W", [PSK, 5]), Stack};
+handle_trace(ssn,
+ {return_from, {?MODULE, stateless_anti_replay, 4},
+ Return}, Stack) ->
+ {io_lib:format("ticket REJECTED ~W", [Return, 5]), Stack}.
diff --git a/lib/ssl/src/tls_v1.erl b/lib/ssl/src/tls_v1.erl
index dd891967bc..fdbeac298f 100644
--- a/lib/ssl/src/tls_v1.erl
+++ b/lib/ssl/src/tls_v1.erl
@@ -90,6 +90,9 @@
finished_verify_data/3,
pre_shared_key/3]).
+%% Tracing
+-export([handle_trace/3]).
+
-type named_curve() :: sect571r1 | sect571k1 | secp521r1 | brainpoolP512r1 |
sect409k1 | sect409r1 | brainpoolP384r1 | secp384r1 |
sect283k1 | sect283r1 | brainpoolP256r1 | secp256k1 | secp256r1 |
@@ -1273,3 +1276,23 @@ enum_to_oid(29) -> ?'id-X25519';
enum_to_oid(30) -> ?'id-X448';
enum_to_oid(_) ->
undefined.
+
+%%%################################################################
+%%%#
+%%%# Tracing
+%%%#
+handle_trace(kdt,
+ {call, {?MODULE, update_traffic_secret,
+ [_HKDF, ApplicationTrafficSecret0]}},
+ Stack) ->
+ ATS0 = string:sub_string(
+ binary:bin_to_list(
+ binary:encode_hex(ApplicationTrafficSecret0)), 1, 5) ++ "...",
+ {io_lib:format("ApplicationTrafficSecret0 = \"~s\"", [ATS0]), Stack};
+handle_trace(kdt,
+ {return_from, {?MODULE, update_traffic_secret, 2},
+ Return}, Stack) ->
+ ATS = string:sub_string(
+ binary:bin_to_list(
+ binary:encode_hex(Return)), 1, 5) ++ "...",
+ {io_lib:format("ApplicationTrafficSecret = \"~s\"", [ATS]), Stack}.
diff --git a/lib/ssl/test/ssl_test_lib.erl b/lib/ssl/test/ssl_test_lib.erl
index cea2897b4c..cf47f6ac07 100644
--- a/lib/ssl/test/ssl_test_lib.erl
+++ b/lib/ssl/test/ssl_test_lib.erl
@@ -217,6 +217,8 @@
verify_early_data/1,
trace/0
]).
+%% Tracing
+-export([handle_trace/3]).
-record(sslsocket, { fd = nil, pid = nil}).
-define(SLEEP, 1000).
@@ -4135,3 +4137,10 @@ curve_default(_) ->
trace() ->
ssl_trace:start(fun ct:pal/2, []),
ssl_trace:on().
+
+handle_trace(rle,
+ {call, {?MODULE, init_openssl_server, [Mode, ResponderPort | _]}}, Stack0) ->
+ Role = server,
+ {io_lib:format("(*~w) Mode = ~w ResponderPort = ~w",
+ [Role, Mode, ResponderPort]),
+ [{role, Role} | Stack0]}.
diff --git a/lib/ssl/test/ssl_trace_SUITE.erl b/lib/ssl/test/ssl_trace_SUITE.erl
index 7e64c9cb2e..376b9a01ab 100644
--- a/lib/ssl/test/ssl_trace_SUITE.erl
+++ b/lib/ssl/test/ssl_trace_SUITE.erl
@@ -44,7 +44,12 @@
tc_budget_option/0,
tc_budget_option/1,
tc_file_option/0,
- tc_file_option/1]).
+ tc_file_option/1,
+ tc_write/0,
+ tc_write/1,
+ tc_check_profiles/0,
+ tc_check_profiles/1]).
+-define(TRACE_FILE, "ssl_trace.txt").
%%--------------------------------------------------------------------
%% Common Test interface functions -----------------------------------
@@ -53,7 +58,7 @@ suite() -> [{ct_hooks,[ts_install_cth]},
{timetrap,{seconds,60}}].
all() -> [tc_basic, tc_no_trace, tc_api_profile, tc_rle_profile,
- tc_budget_option, tc_file_option].
+ tc_budget_option, tc_write, tc_file_option, tc_check_profiles].
init_per_suite(Config) ->
catch crypto:stop(),
@@ -82,7 +87,7 @@ end_per_testcase(_TC, Config) ->
tc_basic() ->
[{doc, "Basic test of ssl_trace API"}].
tc_basic(_Config) ->
- L0 = ssl_trace:start(),
+ {ok, L0} = ssl_trace:start(),
true = is_pid(whereis(ssl_trace)),
true = is_list(L0),
{ok,L0} = ssl_trace:on(),
@@ -105,7 +110,7 @@ tc_basic(_Config) ->
ok = ssl_trace:stop(),
undefined = whereis(ssl_trace),
- [api, rle] = ssl_trace:start(),
+ {ok, [api, crt, csp, hbn, kdt, rle, ssn]} = ssl_trace:start(),
{ok, [api]} = ssl_trace:on(api),
{ok, []} = ssl_trace:off(api),
ok = ssl_trace:stop(),
@@ -113,7 +118,6 @@ tc_basic(_Config) ->
tc_no_trace() ->
[{doc, "Verify there are no traces if not enabled"}].
-
tc_no_trace(Config) ->
Ref = ssl_trace_start(),
[Server, Client] = ssl_connect(Config),
@@ -127,7 +131,6 @@ tc_no_trace(Config) ->
tc_api_profile() ->
[{doc, "Verify traces for 'api' trace profile"}].
-
tc_api_profile(Config) ->
On = [api, rle],
Off = [],
@@ -149,13 +152,16 @@ tc_api_profile(Config) ->
{" (client) <- ssl_gen_statem:connect/8 returned",
ssl_gen_statem, connect},
{" (client) <- ssl:connect/3 returned", ssl, connect},
- {" (server) <- ssl:handshake/2 returned", ssl, handshake}
- ],
+ {" (server) <- ssl:handshake/2 returned", ssl, handshake},
+ {" (client) <- tls_sender:init/3 returned", tls_sender, init},
+ {" (server) <- tls_sender:init/3 returned", tls_sender, init}],
processed =>
["rle ('?') -> ssl_gen_statem:init/1 (*client)",
"rle ('?') -> ssl_gen_statem:init/1 (*server)",
"rle ('?') -> ssl:listen/2 (*server) Args",
- "rle ('?') -> ssl:connect/3 (*client) Args"]},
+ "rle ('?') -> ssl:connect/3 (*client) Args",
+ "rle ('?') -> tls_sender:init/3 (*server)",
+ "rle ('?') -> tls_sender:init/3 (*client)"]},
TracesAfterDisconnect =
#{
call =>
@@ -205,7 +211,6 @@ tc_api_profile(Config) ->
tc_rle_profile() ->
[{doc, "Verify traces for 'rle' trace profile"}].
-
tc_rle_profile(Config) ->
On = [rle],
ExpectedTraces =
@@ -214,12 +219,16 @@ tc_rle_profile(Config) ->
[],
return_from =>
[{" (client) <- ssl:connect/3 returned", ssl, connect},
- {" (server) <- ssl:listen/2 returned", ssl, listen}],
+ {" (server) <- ssl:listen/2 returned", ssl, listen},
+ {" (client) <- tls_sender:init/3 returned", tls_sender, init},
+ {" (server) <- tls_sender:init/3 returned", tls_sender, init}],
processed =>
["rle ('?') -> ssl:listen/2 (*server) Args =",
"rle ('?') -> ssl:connect/3 (*client) Args",
"rle ('?') -> ssl_gen_statem:init/1 (*server) Args = [[server",
- "rle ('?') -> ssl_gen_statem:init/1 (*client) Args = [[client"]},
+ "rle ('?') -> ssl_gen_statem:init/1 (*client) Args = [[client",
+ "rle ('?') -> tls_sender:init/3 (*server)",
+ "rle ('?') -> tls_sender:init/3 (*client)"]},
Ref = ssl_trace_start(),
{ok, On} = ssl_trace:on(On),
[Server, Client] = ssl_connect(Config),
@@ -234,10 +243,10 @@ tc_rle_profile(Config) ->
tc_budget_option() ->
[{doc, "Verify that budget option limits amount of traces"}].
-
tc_budget_option(Config) ->
Ref = ssl_trace_start(make_ref(), [{budget, 10}]),
{ok, [api,rle]} = ssl_trace:on([api,rle]),
+ ssl_trace:write("Not a trace from dbg - not included in budget", []),
[Server, Client] = ssl_connect(Config),
ssl_test_lib:close(Server),
ssl_test_lib:close(Client),
@@ -261,15 +270,31 @@ tc_budget_option(Config) ->
tc_file_option() ->
[{doc, "Verify that file option redirects traces to file"}].
-
tc_file_option(Config) ->
_Ref = ssl_trace_start(make_ref(), [{budget, 10}, file]),
{ok, [api,rle]} = ssl_trace:on([api,rle]),
[Server, Client] = ssl_connect(Config),
ssl_test_lib:close(Server),
ssl_test_lib:close(Client),
- ActualTraceCnt = count_line("ssl_trace.txt"),
- ExpectedTraceCnt = 10,
+ ActualTraceCnt = count_line(?TRACE_FILE),
+ ExpectedTraceCnt = 11, %% budget + 1 message about end of budget
+ ssl_trace:stop(),
+ case ExpectedTraceCnt == ActualTraceCnt of
+ true ->
+ ok;
+ _ ->
+ ?FAIL("Expected ~w traces, but found ~w",
+ [ExpectedTraceCnt, ActualTraceCnt])
+ end.
+
+tc_write() ->
+ [{doc, "Verify that custom messages can be written"}].
+tc_write(_Config) ->
+ _Ref = ssl_trace_start(make_ref(), [{budget, 10}, file]),
+ {ok, [api,rle]} = ssl_trace:on([api,rle]),
+ ssl_trace:write("Custom trace message ~w", [msg]),
+ ActualTraceCnt = count_line(?TRACE_FILE),
+ ExpectedTraceCnt = 1,
ssl_trace:stop(),
case ExpectedTraceCnt == ActualTraceCnt of
true ->
@@ -279,17 +304,44 @@ tc_file_option(Config) ->
[ExpectedTraceCnt, ActualTraceCnt])
end.
+tc_check_profiles() ->
+ [{doc, "Verify that trace profile contain valid functions"}].
+tc_check_profiles(_Config) ->
+ CheckFun =
+ fun(Profile, Module, Fun, DefinedFunctions) ->
+ case lists:member(Fun, DefinedFunctions) of
+ true -> ok;
+ _ ->
+ {F, A} = Fun,
+ ct:fail("~w:~w/~w from '~w' trace profile not found",
+ [Module, F, A, Profile])
+ end
+ end,
+ CheckModule =
+ fun(Profile, {Module, Funs}) ->
+ DefinedFunctions = Module:module_info(functions),
+ [CheckFun(Profile, Module, F, DefinedFunctions) ||
+ F <- Funs]
+ end,
+ CheckTProfile =
+ fun({Profile, _, _, ModFunsTuples}) ->
+ [CheckModule(Profile, MFTuple) ||
+ MFTuple <- ModFunsTuples]
+ end,
+ [CheckTProfile(P) || P <- ssl_trace:trace_profiles()],
+ ok.
+
%%%----------------------------------------------------------------
ssl_trace_start() ->
ssl_trace_start(make_ref(), []).
ssl_trace_start(Ref, TraceOpts) ->
TestProcess = self(),
- [_|_] = ssl_trace:start(fun(Format,Args) ->
- ct:log(Format, Args),
- TestProcess ! {Ref, Args}
- end,
- TraceOpts),
+ {ok, [_|_]} = ssl_trace:start(fun(Format,Args) ->
+ ct:log(Format, Args),
+ TestProcess ! {Ref, Args}
+ end,
+ TraceOpts),
Ref.
receive_map(Ref) ->
@@ -409,7 +461,7 @@ count_line(Filename) ->
Count;
{error, Reason} ->
?PAL("~s open error reason:~s~n", [Filename, Reason]),
- ng
+ ct:fail(Reason)
end.
count_line(IoDevice, Count) ->
--
2.35.3
