Sign Up
Log In
Log In
or
Sign Up
Places
All Projects
Status Monitor
Collapse sidebar
home:Ledest:erlang:25
erlang
2851-ssl-add-ssl_trace-module.patch
Overview
Repositories
Revisions
Requests
Users
Attributes
Meta
File 2851-ssl-add-ssl_trace-module.patch of Package erlang
From a18c5de9ef7ec5faaea03d44d9b0ad076b3945db Mon Sep 17 00:00:00 2001 From: Jakub Witczak <kuba@erlang.org> Date: Wed, 16 Nov 2022 08:22:02 +0100 Subject: [PATCH] ssl: add ssl_trace module --- lib/ssl/src/Makefile | 1 + lib/ssl/src/ssl.app.src | 1 + lib/ssl/src/ssl.erl | 14 + lib/ssl/src/ssl_gen_statem.erl | 11 + lib/ssl/src/ssl_trace.erl | 403 ++++++++++++++++++++++++++++ lib/ssl/test/Makefile | 1 + lib/ssl/test/ssl_test_lib.erl | 7 +- lib/ssl/test/ssl_trace_SUITE.erl | 441 +++++++++++++++++++++++++++++++ 8 files changed, 878 insertions(+), 1 deletion(-) create mode 100644 lib/ssl/src/ssl_trace.erl create mode 100644 lib/ssl/test/ssl_trace_SUITE.erl diff --git a/lib/ssl/src/Makefile b/lib/ssl/src/Makefile index 789bed5c3f..2ec093579c 100644 --- a/lib/ssl/src/Makefile +++ b/lib/ssl/src/Makefile @@ -39,6 +39,7 @@ RELSYSDIR = $(RELEASE_PATH)/lib/ssl-$(VSN) # ---------------------------------------------------- BEHAVIOUR_MODULES= \ + ssl_trace \ ssl_crl_cache_api \ ssl_session_cache_api diff --git a/lib/ssl/src/ssl.app.src b/lib/ssl/src/ssl.app.src index 9801d0c319..d1ef18e5d9 100644 --- a/lib/ssl/src/ssl.app.src +++ b/lib/ssl/src/ssl.app.src @@ -75,6 +75,7 @@ ssl_crl_hash_dir, %% Logging ssl_logger, + ssl_trace, %% App structure ssl_app, ssl_sup, diff --git a/lib/ssl/src/ssl.erl b/lib/ssl/src/ssl.erl index f4eb51b5e2..f371307d94 100644 --- a/lib/ssl/src/ssl.erl +++ b/lib/ssl/src/ssl.erl @@ -100,6 +100,8 @@ suite_to_str/1, suite_to_openssl_str/1, str_to_suite/1]). +%% Tracing +-export([handle_trace/3]). -removed({ssl_accept, '_', "use ssl_handshake/1,2,3 instead"}). @@ -2726,3 +2728,15 @@ unambiguous_path(Value) -> _ -> AbsName end. + +%%%################################################################ +%%%# +%%%# Tracing +%%%# +handle_trace(rle, {call, {?MODULE, listen, Args}}, Stack0) -> + Role = server, + {io_lib:format("(*~w) Args = ~W", [Role, Args, 10]), [{role, Role} | Stack0]}; +handle_trace(rle, {call, {?MODULE, connect, Args}}, Stack0) -> + Role = client, + {io_lib:format("(*~w) Args = ~W", [Role, Args, 10]), [{role, Role} | Stack0]}. + diff --git a/lib/ssl/src/ssl_gen_statem.erl b/lib/ssl/src/ssl_gen_statem.erl index e470103074..596c168d43 100644 --- a/lib/ssl/src/ssl_gen_statem.erl +++ b/lib/ssl/src/ssl_gen_statem.erl @@ -99,6 +99,9 @@ %% Log handling -export([format_status/2]). +%% Tracing +-export([handle_trace/3]). + %%-------------------------------------------------------------------- %%% Initial Erlang process setup %%-------------------------------------------------------------------- @@ -2220,3 +2223,11 @@ maybe_generate_client_shares(#{versions := [Version|_], ssl_cipher:generate_client_shares([Group]); maybe_generate_client_shares(_) -> undefined. + +%%%################################################################ +%%%# +%%%# Tracing +%%%# +handle_trace(rle, + {call, {?MODULE, init, Args = [[Role | _]]}}, Stack0) -> + {io_lib:format("(*~w) Args = ~W", [Role, Args, 3]), [{role, Role} | Stack0]}. diff --git a/lib/ssl/src/ssl_trace.erl b/lib/ssl/src/ssl_trace.erl new file mode 100644 index 0000000000..c40381b78d --- /dev/null +++ b/lib/ssl/src/ssl_trace.erl @@ -0,0 +1,403 @@ +%% +%% %CopyrightBegin% +%% +%% Copyright Ericsson AB 2022. 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% +%% + +%% + +%%% Purpose: +%%% 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. +%%% +%%% 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 +%%% ssl_trace:on() -- switch on all ssl trace profiles +%%% +%%% 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() -- switch off all ssl tracing +%%% +%%% 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: +%%% 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]). +-export([init/1, handle_call/3, handle_cast/2, handle_info/2]). +%% Internal apply_after: +-export([ets_delete/2]). + +-behaviour(gen_server). +-define(SERVER, ?MODULE). +-define(CALL_TIMEOUT, 15000). % 3x the default +-define(TRACE_BUDGET, 10000). +-define(TRACE_FILE, "ssl_trace.txt"). + +-record(state, { + file = undefined, + types_on = [], + io_device = undefined + }). + +%%%---------------------------------------------------------------- +start() -> start(fun io:format/2). + +start(file) -> + start(fun io:format/2, [file]); +start(IoFmtFun) when is_function(IoFmtFun,2) ; is_function(IoFmtFun,3) -> + start(IoFmtFun, []). + +start(IoFmtFun, TraceOpts) when is_function(IoFmtFun,2); + is_function(IoFmtFun,3); + is_list(TraceOpts) -> + {ok, Pid} = gen_server:start({local,?SERVER}, ?MODULE, TraceOpts, []), + true = is_process_alive(Pid), + catch dbg:start(), + start_tracer(IoFmtFun, TraceOpts), + dbg:p(all, [timestamp, c]), + get_all_trace_profiles(). + +stop() -> + try + dbg:stop(), + ok = gen_server:call(?SERVER, file_close, ?CALL_TIMEOUT), + gen_server:stop(?SERVER) + catch + _:_ -> ok + end. + +on() -> + on(get_all_trace_profiles()). + +on(Type) -> + switch(on, Type). + +off() -> + off(get_all_trace_profiles()). + +off(Type) -> + switch(off, Type). + +is_on() -> + gen_server:call(?SERVER, get_on, ?CALL_TIMEOUT). + +is_off() -> + get_all_trace_profiles() -- is_on(). + +%%%---------------------------------------------------------------- +init(_) -> + try + ets:new(?MODULE, [public, named_table]) + catch + exit:badarg -> + ok + end, + {ok, #state{}}. + +handle_call({switch,on,Profiles}, _From, State) -> + [enable_profile(P) || P <- Profiles], + NowOn = lists:usort(Profiles ++ State#state.types_on), + {reply, {ok,NowOn}, State#state{types_on = NowOn}}; +handle_call({switch,off,Profiles}, _From, State) -> + StillOn = State#state.types_on -- Profiles, + [disable_profile(P) || P <- Profiles], + {reply, {ok,StillOn}, State#state{types_on = StillOn}}; +handle_call(get_on, _From, State) -> + {reply, State#state.types_on, State}; +handle_call({file_open, File}, _From, State) -> + {ok, IODevice} = file:open(File, [write]), + {reply, {ok, IODevice}, State#state{io_device = IODevice}}; +handle_call(file_close, _From, #state{io_device = IODevice} = State) -> + case is_pid(IODevice) of + true -> + ok = file:close(IODevice); + _ -> + ok + end, + {reply, ok, State#state{io_device = undefined}}; +handle_call(C, _From, State) -> + io:format('*** Unknown call: ~p~n',[C]), + {reply, {error,{unknown_call,C}}, State}. + +handle_cast({new_proc,Pid}, State) -> + monitor(process, Pid), + {noreply, State}; +handle_cast(C, State) -> + io:format('*** Unknown cast: ~p~n',[C]), + {noreply, State}. + +handle_info({'DOWN', _MonitorRef, process, Pid, _Info}, State) -> + %% Universal real-time synchronization (there might be dbg msgs in the queue to the tracer): + timer:apply_after(20000, ?MODULE, ets_delete, [?MODULE, Pid]), + {noreply, State}; +handle_info(C, State) -> + io:format('*** Unknown info: ~p~n',[C]), + {noreply, State}. + +%%%---------------------------------------------------------------- +get_proc_stack(Pid) when is_pid(Pid) -> + try ets:lookup_element(?MODULE, Pid, 2) + catch + error:badarg -> + %% Non-existing item + new_proc(Pid), + ets:insert(?MODULE, {Pid,[]}), + [] + end. + +new_proc(Pid) when is_pid(Pid) -> + gen_server:cast(?SERVER, {new_proc,Pid}). + +put_proc_stack(Pid, Stack) when is_pid(Pid), + is_list(Stack) -> + ets:insert(?MODULE, {Pid, Stack}). + +ets_delete(Tab, Key) -> + catch ets:delete(Tab, Key). + +start_tracer(WriteFun, TraceOpts) when is_function(WriteFun,2) -> + start_tracer(fun(F,A,S) -> WriteFun(F,A), S end, TraceOpts); +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]; + _ -> + Acc0 + end, + start_dbg_tracer(WriteFun, Acc1). + +start_dbg_tracer(WriteFun, InitHandlerAcc0) when is_function(WriteFun, 3) -> + Handler = + fun(Arg, Acc0) -> + try_handle_trace(gen_server:call(?SERVER, get_on, ?CALL_TIMEOUT), + Arg, WriteFun, + Acc0) + end, + InitHandlerAcc1 = + case proplists:get_value(file, InitHandlerAcc0) of + undefined -> + InitHandlerAcc0; + File -> + {ok, IODevice} = gen_server:call(?SERVER, {file_open, File}, ?CALL_TIMEOUT), + [{io_device, IODevice} | InitHandlerAcc0] + end, + dbg:tracer(process, {Handler,InitHandlerAcc1}). + +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, + Budget0 = proplists:get_value(budget, HandlerAcc, 0), + Timestamp = trace_ts(Arg), + Pid = trace_pid(Arg), + TraceInfo = trace_info(Arg), + Module = trace_module(TraceInfo), + ProcessStack = get_proc_stack(Pid), + Role = proplists:get_value(role, ProcessStack, '?'), + Budget1 = + lists:foldl( + fun(Profile, BAcc) -> + case BAcc > 1 of + true -> + try + Module:handle_trace(Profile, TraceInfo, ProcessStack) + of + {skip, NewProcessStack} -> + %% Don't try to process this later + put_proc_stack(Pid, NewProcessStack), + reduce_budget(BAcc); + {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) + catch + _:_ -> + %% not processed by custom handler + BAcc + end; + _ -> + BAcc + end + end, Budget0, ProfilesOn), + %% generate default trace if was not processed by any custom handler + Budget2 = + case (Budget1 == Budget0 andalso Budget0 > 0) of + true -> + WriteFun("~.100s ~W~n", + [io_lib:format("~s ~p ~s ", + [lists:flatten(Timestamp),Pid, + common_prefix(TraceInfo, Role, + " ")]), + TraceInfo, 7], processed), + reduce_budget(Budget0); + _ -> + Budget1 + end, + [{budget, Budget2} | proplists:delete(budget, HandlerAcc)]. + +reduce_budget(B) when B>1 -> + B - 1; +reduce_budget(_B) -> + 0. + +write_txt(WriteFun, Timestamp, Pid, Txt) when is_list(Txt) -> + WriteFun("~s ~p ~ts~n", [Timestamp, Pid, Txt], processed). + +get_all_trace_profiles() -> + Unsorted = [Profile || + {Profile, _TraceOn, _TraceOff, _TracedFuns} + <- trace_profiles()], + lists:usort(Unsorted). + +switch(X, Profile) when is_atom(Profile); is_tuple(Profile) -> + switch(X, [Profile]); +switch(X, Profiles) when is_list(Profiles) -> + case whereis(?SERVER) of + undefined -> + start(); + _ -> + ok + end, + case unknown_types(Profiles, get_all_trace_profiles(), []) of + [] -> + gen_server:call(?SERVER, {switch,X,Profiles}, ?CALL_TIMEOUT); + L -> + {error, {unknown, L}} + end. + +unknown_types([], _AllProfiles, Acc) -> Acc; +unknown_types([Profile | Tail], AllProfiles, Acc) + when is_atom(Profile) -> + case lists:member(Profile, AllProfiles) of + false -> unknown_types(Tail, AllProfiles, [Profile | Acc]); + _ -> unknown_types(Tail, AllProfiles, Acc) + end; +unknown_types([ModProfile = {_Mod, Profile} | Tail], AllProfiles, Acc) + when is_tuple(ModProfile) -> + unknown_types([Profile | Tail], AllProfiles, Acc). + +%%%---------------------------------------------------------------- +%%% Format of trace messages are described in reference manual for erlang:trace/4 +%%% {call,MFA} +%%% {return_from,{M,F,N},Result} +%%% {send,Msg,To} +%%% {'receive',Msg} + +%% Pick 2nd element, the Pid +trace_pid(T) when element(1,T)==trace + ; element(1,T)==trace_ts -> + element(2,T). + +%% Pick last element, the Time Stamp, and format it +trace_ts(T) when element(1,T)==trace_ts -> + ts( element(size(T), T) ). + +ts({_,_,Usec}=Now) when is_integer(Usec) -> + {_Date,{HH,MM,SS}} = calendar:now_to_local_time(Now), + io_lib:format("~.2.0w:~.2.0w:~.2.0w.~.6.0w",[HH,MM,SS,Usec]); +ts(_) -> + "-". + +%% Make a tuple of all elements but the 1st, 2nd and last +trace_info(T) -> + case tuple_to_list(T) of + [trace,_Pid | Info] -> list_to_tuple(Info); + [trace_ts,_Pid | InfoTS] -> list_to_tuple( + lists:droplast(InfoTS)) + end. + +trace_module(Info) -> + {Module, _, _} = element(2, Info), + Module. + +common_prefix({call, {M, F, Args}}, Role, Profile) -> + [io_lib:format("~s (~w) -> ~w:~w/~w ", + [Profile, Role, M, F, length(Args)])]; +common_prefix({return_from, {M, F, Arity}, _Return}, Role, Profile) -> + [io_lib:format("~s (~w) <- ~w:~w/~w returned ", + [Profile, Role, M, F, Arity])]; +common_prefix({exception_from, {M, F, Arity}, Reason}, Role, Profile) -> + [io_lib:format("~s (~w) exception_from ~w:~w/~w ~w", + [Profile, Role, M, F, Arity, Reason])]; +common_prefix(_E, _Role, _Profile) -> + []. + +enable_profile(Profile) when is_atom(Profile) -> + [enable_profile({M, Profile}) || M <- modules(Profile)]; +enable_profile({Module, Profile}) when is_atom(Module); is_atom(Profile) -> + {Profile, TraceOn, _, AllFuns} = profile(Profile), + Funs = proplists:get_value(Module, AllFuns), + process_profile(Module, TraceOn, Funs). + +disable_profile(Profile) when is_atom(Profile) -> + [disable_profile({M, Profile}) || M <- modules(Profile)]; +disable_profile({Module, Profile}) when is_atom(Module); is_atom(Profile) -> + {Profile, _, TraceOff, AllFuns} = profile(Profile), + Funs = proplists:get_value(Module, AllFuns), + process_profile(Module, TraceOff, Funs). + +process_profile(Module, Action, Funs) when is_atom(Module) -> + [Action(Module, F, A) || {F, A} <- Funs]. + +profile(P) -> + lists:keyfind(P, 1, trace_profiles()). + +modules(P) -> + {_, _, _, Funs} = profile(P), + proplists:get_keys(Funs). + +trace_profiles() -> + [{api, + 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}, {handshake,2}, {close, 1}]}, + {ssl_gen_statem, + [{initial_hello,3}, {connect, 8}, {close, 2}, {terminate_alert, 1}]} + ]}, + {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}]}]} + ]. diff --git a/lib/ssl/test/Makefile b/lib/ssl/test/Makefile index ac1318bd14..ddbc3a7c25 100644 --- a/lib/ssl/test/Makefile +++ b/lib/ssl/test/Makefile @@ -79,6 +79,7 @@ MODULES = \ ssl_session_cache_SUITE \ ssl_session_cache_api_SUITE\ \ ssl_session_ticket_SUITE \ + ssl_trace_SUITE \ openssl_session_ticket_SUITE \ openssl_session_SUITE \ ssl_ECC_SUITE \ diff --git a/lib/ssl/test/ssl_test_lib.erl b/lib/ssl/test/ssl_test_lib.erl index 8e7bef1098..b48cf916a4 100644 --- a/lib/ssl/test/ssl_test_lib.erl +++ b/lib/ssl/test/ssl_test_lib.erl @@ -213,7 +213,8 @@ portable_cmd/2, portable_open_port/2, close_port/1, - verify_early_data/1 + verify_early_data/1, + trace/0 ]). -record(sslsocket, { fd = nil, pid = nil}). @@ -4063,3 +4064,7 @@ curve_default(eddsa) -> ed25519; curve_default(_) -> ?DEFAULT_CURVE. + +trace() -> + ssl_trace:start(fun ct:pal/2, []), + ssl_trace:on(). diff --git a/lib/ssl/test/ssl_trace_SUITE.erl b/lib/ssl/test/ssl_trace_SUITE.erl new file mode 100644 index 0000000000..7e64c9cb2e --- /dev/null +++ b/lib/ssl/test/ssl_trace_SUITE.erl @@ -0,0 +1,441 @@ +%% +%% %CopyrightBegin% +%% +%% Copyright Ericsson AB 2022. 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_trace_SUITE). + +-include("ssl_test_lib.hrl"). +-include_lib("common_test/include/ct.hrl"). +-include_lib("ssl/src/ssl_api.hrl"). + +-export([suite/0, + all/0, + init_per_suite/1, + end_per_suite/1, + init_per_testcase/2, + end_per_testcase/2]). + +-export([tc_basic/0, + tc_basic/1, + tc_no_trace/0, + tc_no_trace/1, + tc_api_profile/0, + tc_api_profile/1, + tc_rle_profile/0, + tc_rle_profile/1, + tc_budget_option/0, + tc_budget_option/1, + tc_file_option/0, + tc_file_option/1]). + +%%-------------------------------------------------------------------- +%% Common Test interface functions ----------------------------------- +%%-------------------------------------------------------------------- +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]. + +init_per_suite(Config) -> + catch crypto:stop(), + try crypto:start() of + ok -> + ssl_test_lib:clean_start(), + ssl_test_lib:make_rsa_cert(Config) + catch _:_ -> + {skip, "Crypto did not start"} + end. + +end_per_suite(_Config) -> + ssl:stop(), + application:stop(crypto). + +init_per_testcase(_TC, Config) -> + Config. + +end_per_testcase(_TC, Config) -> + ssl_trace:stop(), + Config. + +%%-------------------------------------------------------------------- +%% Test Cases -------------------------------------------------------- +%%-------------------------------------------------------------------- +tc_basic() -> + [{doc, "Basic test of ssl_trace API"}]. +tc_basic(_Config) -> + L0 = ssl_trace:start(), + true = is_pid(whereis(ssl_trace)), + true = is_list(L0), + {ok,L0} = ssl_trace:on(), + {ok,L0} = ssl_trace:on(), + L0 = ssl_trace:is_on(), + [] = ssl_trace:is_off(), + + L1 = [hd(L0)], + L2 = tl(L0), + {ok,L1} = ssl_trace:off(L2), + + L1 = ssl_trace:is_on(), + L2 = ssl_trace:is_off(), + + {ok,[]} = ssl_trace:off(), + {ok,[]} = ssl_trace:off(), + + [] = ssl_trace:is_on(), + L0 = ssl_trace:is_off(), + ok = ssl_trace:stop(), + undefined = whereis(ssl_trace), + + [api, rle] = ssl_trace:start(), + {ok, [api]} = ssl_trace:on(api), + {ok, []} = ssl_trace:off(api), + ok = ssl_trace:stop(), + ok. + +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), + ssl_test_lib:close(Server), + ssl_test_lib:close(Client), + ExpectedTraces = + #{call => [], processed => [], exception_from => [], return_from => []}, + ExpectedTraces = receive_map(Ref), + ok = ssl_trace:stop(), + ok. + +tc_api_profile() -> + [{doc, "Verify traces for 'api' trace profile"}]. + +tc_api_profile(Config) -> + On = [api, rle], + Off = [], + TracesAfterConnect = + #{ + call => + [{" (server) -> ssl:handshake/2", ssl, handshake}, + {" (client) -> ssl_gen_statem:connect/8", ssl_gen_statem, connect}, + {" (server) -> ssl_gen_statem:initial_hello/3", + ssl_gen_statem, initial_hello}, + {" (client) -> ssl_gen_statem:initial_hello/3", + ssl_gen_statem, initial_hello}], + return_from => + [{" (server) <- ssl:listen/2 returned", ssl, listen}, + {" (server) <- ssl_gen_statem:initial_hello/3 returned", + ssl_gen_statem, initial_hello}, + {" (client) <- ssl_gen_statem:initial_hello/3 returned", + ssl_gen_statem, initial_hello}, + {" (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} + ], + 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"]}, + TracesAfterDisconnect = + #{ + call => + [{" (client) -> ssl:close/1", ssl, close}, + {" (client) -> ssl:close/1", ssl, close}, + {" (client) -> ssl_gen_statem:close/2", ssl_gen_statem, close}, + {" (client) -> ssl_gen_statem:terminate_alert/1", + ssl_gen_statem, terminate_alert}, + {" (server) -> ssl:close/1", ssl, close}, + {" (server) -> ssl_gen_statem:close/2", ssl_gen_statem, close}, + {" (server) -> ssl_gen_statem:terminate_alert/1", + ssl_gen_statem, terminate_alert}], + return_from => + [{" (client) <- ssl:close/1 returned", ssl, close}, + {" (client) <- ssl:close/1 returned", ssl, close}, + {" (client) <- ssl_gen_statem:close/2 returned", + ssl_gen_statem, close}, + {" (client) <- ssl_gen_statem:terminate_alert/1 returned", + ssl_gen_statem, terminate_alert}, + {" (server) <- ssl:close/1 returned", ssl, close}, + {" (server) <- ssl_gen_statem:close/2 returned", + ssl_gen_statem, close}, + {" (server) <- ssl_gen_statem:terminate_alert/1 returned", + ssl_gen_statem, terminate_alert}], + exception_from => + [{" (server) exception_from ssl_gen_statem:init/1 {exit,{shutdown,normal}}", + ssl_gen_statem, init}, + {" (client) exception_from ssl_gen_statem:init/1 {exit,{shutdown,normal}}", + ssl_gen_statem, init}]}, + Ref = ssl_trace_start(), + {ok, On} = ssl_trace:on(On), + Delta = On -- Off, + {ok, Delta} = ssl_trace:off(Off), + [Server, Client] = ssl_connect(Config), + UnhandledTraceCnt1 = + #{call => 0, processed => 0, exception_from => no_trace_received, + return_from => 0}, + check_trace_map(Ref, TracesAfterConnect, UnhandledTraceCnt1), + ssl_test_lib:close(Server), + ssl_test_lib:close(Client), + UnhandledTraceCnt2 = + #{call => 0, processed => no_trace_received, exception_from => 0, + return_from => 0}, + check_trace_map(Ref, TracesAfterDisconnect, UnhandledTraceCnt2), + ssl_trace:stop(), + ok. + +tc_rle_profile() -> + [{doc, "Verify traces for 'rle' trace profile"}]. + +tc_rle_profile(Config) -> + On = [rle], + ExpectedTraces = + #{ + call => + [], + return_from => + [{" (client) <- ssl:connect/3 returned", ssl, connect}, + {" (server) <- ssl:listen/2 returned", ssl, listen}], + 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"]}, + Ref = ssl_trace_start(), + {ok, On} = ssl_trace:on(On), + [Server, Client] = ssl_connect(Config), + ssl_test_lib:close(Server), + ssl_test_lib:close(Client), + UnhandledTraceCnt = + #{call => no_trace_received, processed => 0, exception_from => 2, + return_from => 0}, + check_trace_map(Ref, ExpectedTraces, UnhandledTraceCnt), + ssl_trace:stop(), + ok. + +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]), + [Server, Client] = ssl_connect(Config), + ssl_test_lib:close(Server), + ssl_test_lib:close(Client), + CountReceived = fun(Reference) -> + ReceiveStats = check_trace_map(Reference, #{}), + ReceivedNumbers = + lists:filter(fun is_number/1, + maps:values(ReceiveStats)), + lists:sum(ReceivedNumbers) + end, + ssl_trace:stop(), + ExpectedTraceCnt = 10, + ActualTraceCnt = CountReceived(Ref), + case ExpectedTraceCnt == ActualTraceCnt of + true -> + ok; + _ -> + ?FAIL("Expected ~w traces, but found ~w", + [ExpectedTraceCnt, ActualTraceCnt]) + end. + +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, + ssl_trace:stop(), + case ExpectedTraceCnt == ActualTraceCnt of + true -> + ok; + _ -> + ?FAIL("Expected ~w traces, but found ~w", + [ExpectedTraceCnt, ActualTraceCnt]) + end. + +%%%---------------------------------------------------------------- +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), + Ref. + +receive_map(Ref) -> + Empty = #{call => [], return_from => [], exception_from => [], + processed => []}, + receive_map(Ref, Empty). + +receive_map(Ref, + Map = #{call := Call, return_from := Return, + exception_from := Exception, processed := Processed}) -> + receive + {Ref, Msg = [_, {call, {_, _, _}}, _]} -> + receive_map(Ref, Map#{call => [Msg|Call]}); + {Ref, Msg = [_, {return_from, {_, _, _}, _}, _]} -> + receive_map(Ref, Map#{return_from => [Msg|Return]}); + {Ref, Msg = [_, {exception_from, {_, _, _}, _}, _]} -> + receive_map(Ref, Map#{exception_from => [Msg|Exception]}); + {Ref, Msg = [_Timestamp, _Pid, _ExpectString]} -> + %% processed means a trace was processed by Module:handle_trace + %% function and is not received as a trace tuple + receive_map(Ref, Map#{processed => [Msg|Processed]}) + after 5000 -> + Map + end. + +check_trace_map(Ref, ExpectedTraces) -> + Received = receive_map(Ref), + L = [check_key(Type, ExpectedTraces, maps:get(Type, Received)) || + Type <- maps:keys(Received)], + maps:from_list(L). + +check_trace_map(Ref, ExpectedTraces, ExpectedRemainders) -> + ActualRemainders = check_trace_map(Ref, ExpectedTraces), + case ExpectedRemainders == ActualRemainders of + true -> + ok; + _ -> + ?FAIL("Expected trace remainders = ~w ~n" + "Actual trace remainders = ~w", + [ExpectedRemainders, ActualRemainders]) + end. + +check_key(Type, ExpectedTraces, ReceivedPerType) -> + ReceivedPerTypeCnt = length(ReceivedPerType), + ?LOG("Received Type = ~w Messages# = ~w", [Type, ReceivedPerTypeCnt]), + case ReceivedPerTypeCnt > 0 of + true -> + ExpectedPerType = maps:get(Type, ExpectedTraces, []), + ExpectedPerTypeCnt = length(ExpectedPerType), + check_trace(Type, ExpectedPerType, ReceivedPerType), + {Type, ReceivedPerTypeCnt - ExpectedPerTypeCnt}; + _ -> + {Type, no_trace_received} + end. + +-define(CHECK_TRACE(PATTERN, Expected), + fun({ExpectedString, Module, Function}) -> + P2 = fun(Received) -> + PATTERN = Received, + SearchResult = + string:str(lists:flatten(Txt), ExpectedString), + case {Module == M, Function == F, SearchResult > 0} of + {true, true, true} -> + true; + _ -> false + end + end, + Result = lists:any(P2, ReceivedPerType), + case Result of + false -> + F = "Trace not found: {~s, ~w, ~w}", + ?FAIL(F, [ExpectedString, Module, Function]); + _ -> ok + end, + Result + end). + +-define(CHECK_PROCESSED_TRACE(PATTERN, Expected), + fun(ExpectedString) -> + P2 = fun(Received) -> + PATTERN = Received, + SearchResult = + string:str(lists:flatten(Txt), ExpectedString), + SearchResult > 0 + end, + Result = lists:any(P2, ReceivedPerType), + case Result of + false -> + F = "Processed trace not found: ~s", + ?FAIL(F, [ExpectedString]); + _ -> ok + end, + Result + end). + +check_trace(call, ExpectedPerType, ReceivedPerType) -> + P1 = ?CHECK_TRACE([Txt, {call, {M, F, _Args}}, _], Expected), + true = lists:all(P1, ExpectedPerType); +check_trace(return_from, ExpectedPerType, ReceivedPerType) -> + P1 = ?CHECK_TRACE([Txt, {return_from, {M, F, _Args}, _Return}, _], Expected), + true = lists:all(P1, ExpectedPerType); +check_trace(exception_from, ExpectedPerType, ReceivedPerType) -> + P1 = ?CHECK_TRACE([Txt, {exception_from, {M, F, _Args}, _Return}, _], Expected), + true = lists:all(P1, ExpectedPerType); +check_trace(processed, ExpectedPerType, ReceivedPerType) -> + P1 = ?CHECK_PROCESSED_TRACE([_Timestamp, _Pid, Txt], Expected), + true = lists:all(P1, ExpectedPerType); +check_trace(Type, _ExpectedPerType, _ReceivedPerType) -> + ?FAIL("Type = ~w not checked", [Type]), + ok. + +count_line(Filename) -> + case file:open(Filename, [read]) of + {ok, IoDevice} -> + Count = count_line(IoDevice, 0), + file:close(IoDevice), + Count; + {error, Reason} -> + ?PAL("~s open error reason:~s~n", [Filename, Reason]), + ng + end. + +count_line(IoDevice, Count) -> + case file:read_line(IoDevice) of + {ok, _} -> count_line(IoDevice, Count+1); + eof -> Count + end. + +ssl_connect(Config) when is_list(Config) -> + ?LOG("Establishing connection for producing traces", []), + ClientOpts = ssl_test_lib:ssl_options(client_rsa_verify_opts, Config), + ServerOpts = ssl_test_lib:ssl_options(server_rsa_verify_opts, Config), + {ClientNode, ServerNode, Hostname} = ssl_test_lib:run_where(Config), + Server = + ssl_test_lib:start_server([{node, ServerNode}, {port, 0}, + {from, self()}, + {mfa, {ssl_test_lib, send_recv_result, []}}, + {options, [{keepalive, true},{active, false} + | ServerOpts]}]), + Port = ssl_test_lib:inet_port(Server), + Client = + ssl_test_lib:start_client([{node, ClientNode}, {port, Port}, + {host, Hostname}, + {from, self()}, + {mfa, {ssl_test_lib, send_recv_result, []}}, + {options, [{keepalive, true},{active, false} + | ClientOpts]}]), + ?LOG("Testcase ~p, Client ~p Server ~p ~n", [self(), Client, Server]), + [Server, Client]. -- 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
