Sign Up
Log In
Log In
or
Sign Up
Places
All Projects
Status Monitor
Collapse sidebar
home:Ledest:erlang:25
erlang
2861-ssl-ssl_trace-updates.patch
Overview
Repositories
Revisions
Requests
Users
Attributes
Meta
File 2861-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 @@ path_validation_cb({3,4}) -> tls_handshake_1_3; path_validation_cb(_) -> ?MODULE. + +%%%################################################################ +%%%# +%%%# 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
Locations
Projects
Search
Status Monitor
Help
OpenBuildService.org
Documentation
API Documentation
Code of Conduct
Contact
Support
@OBShq
Terms
openSUSE Build Service is sponsored by
The Open Build Service is an
openSUSE project
.
Sign Up
Log In
Places
Places
All Projects
Status Monitor
