From 5f8114974f8df671ce9774e68b267be03312eb95 Mon Sep 17 00:00:00 2001 From: Pouriya Date: Tue, 15 Jun 2021 15:13:03 +0430 Subject: [PATCH 1/3] ref: fix WS typos --- src/ejabberd_http_ws.erl | 16 +++++----- src/ejabberd_websocket.erl | 64 +++++++++++++++++++------------------- 2 files changed, 40 insertions(+), 40 deletions(-) diff --git a/src/ejabberd_http_ws.erl b/src/ejabberd_http_ws.erl index 911a69a58..eb2100a42 100644 --- a/src/ejabberd_http_ws.erl +++ b/src/ejabberd_http_ws.erl @@ -51,7 +51,7 @@ active = false :: boolean(), c2s_pid :: pid(), ws :: {#ws{}, pid()}, - rfc_compilant = undefined :: boolean() | undefined}). + rfc_compliant = undefined :: boolean() | undefined}). %-define(DBGFSM, true). @@ -166,7 +166,7 @@ handle_event({new_shaper, Shaper}, StateName, #state{ws = {_, WsPid}} = StateDat {next_state, StateName, StateData}. handle_sync_event({send_xml, Packet}, _From, StateName, - #state{ws = {_, WsPid}, rfc_compilant = R} = StateData) -> + #state{ws = {_, WsPid}, rfc_compliant = R} = StateData) -> Packet2 = case {case R of undefined -> true; V -> V end, Packet} of {true, {xmlstreamstart, _, Attrs}} -> Attrs2 = [{<<"xmlns">>, <<"urn:ietf:params:xml:ns:xmpp-framing">>} | @@ -215,7 +215,7 @@ handle_sync_event({send_xml, Packet}, _From, StateName, StateName end, {reply, ok, SN2, StateData}; -handle_sync_event(close, _From, StateName, #state{ws = {_, WsPid}, rfc_compilant = true} = StateData) +handle_sync_event(close, _From, StateName, #state{ws = {_, WsPid}, rfc_compliant = true} = StateData) when StateName /= stream_end_sent -> Close = #xmlel{name = <<"close">>, attrs = [{<<"xmlns">>, <<"urn:ietf:params:xml:ns:xmpp-framing">>}]}, @@ -313,7 +313,7 @@ get_human_html_xmlel() -> "client that supports it.">>}]}]}]}. -parse(#state{rfc_compilant = C} = State, Data) -> +parse(#state{rfc_compliant = C} = State, Data) -> case C of undefined -> P = fxml_stream:new(self()), @@ -321,13 +321,13 @@ parse(#state{rfc_compilant = C} = State, Data) -> fxml_stream:close(P2), case parsed_items([]) of error -> - {State#state{rfc_compilant = true}, <<"parse error">>}; + {State#state{rfc_compliant = true}, <<"parse error">>}; [] -> - {State#state{rfc_compilant = true}, <<"parse error">>}; + {State#state{rfc_compliant = true}, <<"parse error">>}; [{xmlstreamstart, <<"open">>, _} | _] -> - parse(State#state{rfc_compilant = true}, Data); + parse(State#state{rfc_compliant = true}, Data); _ -> - parse(State#state{rfc_compilant = false}, Data) + parse(State#state{rfc_compliant = false}, Data) end; true -> El = fxml_stream:parse_element(Data), diff --git a/src/ejabberd_websocket.erl b/src/ejabberd_websocket.erl index 5eb5ab1a2..5f9d284a6 100644 --- a/src/ejabberd_websocket.erl +++ b/src/ejabberd_websocket.erl @@ -187,32 +187,32 @@ find_subprotocol(Headers) -> end. -ws_loop(FrameInfo, Socket, WsHandleLoopPid, SocketMode, Shaper) -> +ws_loop(FrameInfo, Socket, WsHandleLoopPid, SockMod, Shaper) -> receive {DataType, _Socket, Data} when DataType =:= tcp orelse DataType =:= raw -> - case handle_data(DataType, FrameInfo, Data, Socket, WsHandleLoopPid, SocketMode, Shaper) of + case handle_data(DataType, FrameInfo, Data, Socket, WsHandleLoopPid, SockMod, Shaper) of {error, Error} -> ?DEBUG("TLS decode error ~p", [Error]), - websocket_close(Socket, WsHandleLoopPid, SocketMode, 1002); % protocol error + websocket_close(Socket, WsHandleLoopPid, SockMod, 1002); % protocol error {NewFrameInfo, ToSend, NewShaper} -> - lists:foreach(fun(Pkt) -> SocketMode:send(Socket, Pkt) + lists:foreach(fun(Pkt) -> SockMod:send(Socket, Pkt) end, ToSend), - ws_loop(NewFrameInfo, Socket, WsHandleLoopPid, SocketMode, NewShaper) + ws_loop(NewFrameInfo, Socket, WsHandleLoopPid, SockMod, NewShaper) end; {new_shaper, NewShaper} -> NewShaper = case NewShaper of none when Shaper /= none -> - activate(Socket, SocketMode, true), none; + activate(Socket, SockMod, true), none; _ -> NewShaper end, - ws_loop(FrameInfo, Socket, WsHandleLoopPid, SocketMode, NewShaper); + ws_loop(FrameInfo, Socket, WsHandleLoopPid, SockMod, NewShaper); {tcp_closed, _Socket} -> ?DEBUG("TCP connection was closed, exit", []), - websocket_close(Socket, WsHandleLoopPid, SocketMode, 0); + websocket_close(Socket, WsHandleLoopPid, SockMod, 0); {tcp_error, Socket, Reason} -> ?DEBUG("TCP connection error: ~ts", [inet:format_error(Reason)]), - websocket_close(Socket, WsHandleLoopPid, SocketMode, 0); + websocket_close(Socket, WsHandleLoopPid, SockMod, 0); {'DOWN', Ref, process, WsHandleLoopPid, Reason} -> Code = case Reason of normal -> @@ -224,39 +224,39 @@ ws_loop(FrameInfo, Socket, WsHandleLoopPid, SocketMode, Shaper) -> 1011 % internal error end, erlang:demonitor(Ref), - websocket_close(Socket, WsHandleLoopPid, SocketMode, Code); + websocket_close(Socket, WsHandleLoopPid, SockMod, Code); {text_with_reply, Data, Sender} -> - SocketMode:send(Socket, encode_frame(Data, 1)), + SockMod:send(Socket, encode_frame(Data, 1)), Sender ! {text_reply, self()}, ws_loop(FrameInfo, Socket, WsHandleLoopPid, - SocketMode, Shaper); + SockMod, Shaper); {data_with_reply, Data, Sender} -> - SocketMode:send(Socket, encode_frame(Data, 2)), + SockMod:send(Socket, encode_frame(Data, 2)), Sender ! {data_reply, self()}, ws_loop(FrameInfo, Socket, WsHandleLoopPid, - SocketMode, Shaper); + SockMod, Shaper); {text, Data} -> - SocketMode:send(Socket, encode_frame(Data, 1)), + SockMod:send(Socket, encode_frame(Data, 1)), ws_loop(FrameInfo, Socket, WsHandleLoopPid, - SocketMode, Shaper); + SockMod, Shaper); {data, Data} -> - SocketMode:send(Socket, encode_frame(Data, 2)), + SockMod:send(Socket, encode_frame(Data, 2)), ws_loop(FrameInfo, Socket, WsHandleLoopPid, - SocketMode, Shaper); + SockMod, Shaper); {ping, Data} -> - SocketMode:send(Socket, encode_frame(Data, 9)), + SockMod:send(Socket, encode_frame(Data, 9)), ws_loop(FrameInfo, Socket, WsHandleLoopPid, - SocketMode, Shaper); + SockMod, Shaper); shutdown -> ?DEBUG("Shutdown request received, closing websocket " "with pid ~p", [self()]), - websocket_close(Socket, WsHandleLoopPid, SocketMode, 1001); % going away + websocket_close(Socket, WsHandleLoopPid, SockMod, 1001); % going away _Ignored -> ?WARNING_MSG("Received unexpected message, ignoring: ~p", [_Ignored]), ws_loop(FrameInfo, Socket, WsHandleLoopPid, - SocketMode, Shaper) + SockMod, Shaper) end. encode_frame(Data, Opcode) -> @@ -421,7 +421,7 @@ handle_data(tcp, FrameInfo, Data, Socket, WsHandleLoopPid, fast_tls, Shaper) -> handle_data(_, FrameInfo, Data, Socket, WsHandleLoopPid, SockMod, Shaper) -> handle_data_int(FrameInfo, Data, Socket, WsHandleLoopPid, SockMod, Shaper). -handle_data_int(FrameInfo, Data, Socket, WsHandleLoopPid, SocketMode, Shaper) -> +handle_data_int(FrameInfo, Data, Socket, WsHandleLoopPid, SockMod, Shaper) -> {NewFrameInfo, Recv, Send} = process_frame(FrameInfo, Data), lists:foreach(fun (El) -> case El of @@ -434,27 +434,27 @@ handle_data_int(FrameInfo, Data, Socket, WsHandleLoopPid, SocketMode, Shaper) -> end end, Recv), - {NewFrameInfo, Send, handle_shaping(Data, Socket, SocketMode, Shaper)}. + {NewFrameInfo, Send, handle_shaping(Data, Socket, SockMod, Shaper)}. websocket_close(Socket, WsHandleLoopPid, - SocketMode, CloseCode) when CloseCode > 0 -> + SockMod, CloseCode) when CloseCode > 0 -> Frame = encode_frame(<>, 8), - SocketMode:send(Socket, Frame), - websocket_close(Socket, WsHandleLoopPid, SocketMode, 0); -websocket_close(Socket, WsHandleLoopPid, SocketMode, _CloseCode) -> + SockMod:send(Socket, Frame), + websocket_close(Socket, WsHandleLoopPid, SockMod, 0); +websocket_close(Socket, WsHandleLoopPid, SockMod, _CloseCode) -> WsHandleLoopPid ! closed, - SocketMode:close(Socket). + SockMod:close(Socket). get_origin() -> ejabberd_option:websocket_origin(). -handle_shaping(_Data, _Socket, _SocketMode, none) -> +handle_shaping(_Data, _Socket, _SockMod, none) -> none; -handle_shaping(Data, Socket, SocketMode, Shaper) -> +handle_shaping(Data, Socket, SockMod, Shaper) -> {NewShaper, Pause} = ejabberd_shaper:update(Shaper, byte_size(Data)), if Pause > 0 -> activate_after(Socket, self(), Pause); - true -> activate(Socket, SocketMode, once) + true -> activate(Socket, SockMod, once) end, NewShaper. From 20326e8908b935f25428a3eb1efff628b9c3a09c Mon Sep 17 00:00:00 2001 From: Pouriya Jahanbakhsh Date: Fri, 21 Jan 2022 03:18:55 +0330 Subject: [PATCH 2/3] feat: process hook tracing --- src/ejabberd_hooks.erl | 408 ++++++++++++++++++++++++++++++++++++++++- 1 file changed, 406 insertions(+), 2 deletions(-) diff --git a/src/ejabberd_hooks.erl b/src/ejabberd_hooks.erl index 605b7e226..36edf29c8 100644 --- a/src/ejabberd_hooks.erl +++ b/src/ejabberd_hooks.erl @@ -46,12 +46,23 @@ handle_info/2, terminate/2]). + +-export( + [ + get_tracing_options/3, + trace_off/3, + trace_on/5 + ] +). + -include("logger.hrl"). -include("ejabberd_stacktrace.hrl"). -record(state, {}). -type hook() :: {Seq :: integer(), Module :: atom(), Function :: atom() | fun()}. +-define(TRACE_HOOK_KEY, '$trace_hook'). +-define(TIMING_KEY, '$trace_hook_timer'). %%%---------------------------------------------------------------------- %%% API %%%---------------------------------------------------------------------- @@ -104,7 +115,18 @@ run(Hook, Args) -> run(Hook, Host, Args) -> try ets:lookup(hooks, {Hook, Host}) of [{_, Ls}] -> - run1(Ls, Hook, Args); + case erlang:get(?TRACE_HOOK_KEY) of + undefined -> + run1(Ls, Hook, Args); + TracingHooksOpts -> + case do_get_tracing_options(Hook, Host, TracingHooksOpts) of + undefined -> + run1(Ls, Hook, Args); + TracingOpts -> + foreach_start_hook_tracing(TracingOpts, Hook, Host, Args), + run2(Ls, Hook, Args, Host, TracingOpts) + end + end; [] -> ok catch _:badarg -> @@ -124,13 +146,75 @@ run_fold(Hook, Val, Args) -> run_fold(Hook, Host, Val, Args) -> try ets:lookup(hooks, {Hook, Host}) of [{_, Ls}] -> - run_fold1(Ls, Hook, Val, Args); + case erlang:get(?TRACE_HOOK_KEY) of + undefined -> + run_fold1(Ls, Hook, Val, Args); + TracingHooksOpts -> + case do_get_tracing_options(Hook, Host, TracingHooksOpts) of + undefined -> + run_fold1(Ls, Hook, Val, Args); + TracingOpts -> + fold_start_hook_tracing(TracingOpts, Hook, Host, [Val | Args]), + run_fold2(Ls, Hook, Val, Args, Host, TracingOpts) + end + end; [] -> Val catch _:badarg -> Val end. +get_tracing_options(Hook, Host, Pid) when Pid == erlang:self() -> + do_get_tracing_options(Hook, Host, erlang:get(?TRACE_HOOK_KEY)); +get_tracing_options(Hook, Host, Pid) when erlang:is_pid(Pid) -> + case erlang:process_info(Pid, dictionary) of + {_, DictPropList} -> + case lists:keyfind(?TRACE_HOOK_KEY, 1, DictPropList) of + {_, TracingHooksOpts} -> + do_get_tracing_options(Hook, Host, TracingHooksOpts); + _ -> + undefined + end; + _ -> + undefined + end. + +trace_on(Hook, Host, Pid, #{}=Opts, Timeout) when Pid == erlang:self() -> + do_trace_on(Hook, Host, Opts, Timeout); +trace_on(Hook, Host, Proc, #{}=Opts, Timeout) -> + try sys:replace_state( + Proc, + fun(State) -> + do_trace_on(Hook, Host, Opts, Timeout), + State + end, + 15000 + ) of + _ -> % process state + ok + catch + _:Reason -> + {error, Reason} + end. + +trace_off(Hook, Host, Pid) when Pid == erlang:self() -> + do_trace_off(Hook, Host); +trace_off(Hook, Host, Proc) -> + try sys:replace_state( + Proc, + fun(State) -> + do_trace_off(Hook, Host), + State + end, + 15000 + ) of + _ -> % process state + ok + catch + _:Reason -> + {error, Reason} + end. + %%%---------------------------------------------------------------------- %%% Callback functions from gen_server %%%---------------------------------------------------------------------- @@ -247,3 +331,323 @@ safe_apply(Hook, Module, Function, Args) -> misc:format_exception(2, E, R, Stack)|Args]), 'EXIT' end. + +%%%---------------------------------------------------------------------- +%%% Internal tracing functions +%%%---------------------------------------------------------------------- + +do_trace_on(Hook, Host, Opts, undefined) -> + case erlang:get(?TRACE_HOOK_KEY) of + _ when Hook == '_' andalso Host == <<"*">> -> + % Trace everything: + erlang:put(?TRACE_HOOK_KEY, #{'_' => #{<<"*">> => Opts}}); + #{'_' := #{<<"*">> := _}} -> % Already tracing everything + % Update Opts: + erlang:put(?TRACE_HOOK_KEY, #{'_' => #{<<"*">> => Opts}}); + #{'_' := HostOpts} when Hook == '_' -> % Already Tracing everything for some hosts + % Add/Update Host and Opts: + erlang:put(?TRACE_HOOK_KEY, #{'_' => HostOpts#{Host => Opts}}); + #{'_' := _} -> % Already tracing everything and Hook is not '_' + ok; + #{} when Hook == '_' -> + % Remove other hooks by just adding '_': + erlang:put(?TRACE_HOOK_KEY, #{'_' => #{Host => Opts}}); + #{}=TraceHooksOpts when Host == <<"*">> -> % Want to trace a hook for all hosts + erlang:put(?TRACE_HOOK_KEY, TraceHooksOpts#{Hook => #{Host => Opts}}); + #{}=TraceHooksOpts -> + case maps:get(Hook, TraceHooksOpts, #{}) of + #{<<"*">> := _} -> % Already tracing this hook for all hosts + ok; + HostOpts -> + erlang:put(?TRACE_HOOK_KEY, TraceHooksOpts#{Hook => HostOpts#{Host => Opts}}) + end; + undefined -> + erlang:put(?TRACE_HOOK_KEY, #{Hook => #{Host => Opts}}) + end, + ok; +do_trace_on(Hook, Host, Opts, Timeout) -> % Trace myself `Timeout` time + ParentPid = erlang:self(), + try erlang:spawn( + fun() -> + MonitorRef = erlang:monitor(process, ParentPid), + receive + {_, MonitorRef, _, _, _} -> + ok + after Timeout -> + trace_off(Hook, Host, ParentPid) + end, + erlang:exit(normal) + end + ) of + _ -> + do_trace_on(Hook, Host, Opts, undefined) % ok + catch + _:Reason -> % system_limit + {error, Reason} + end. + +do_trace_off(Hook, Host) -> + case erlang:get(?TRACE_HOOK_KEY) of + _ when Hook == '_' andalso Host == <<"*">> -> + % Remove all tracing: + erlang:erase(?TRACE_HOOK_KEY); + #{'_' := HostOpts} when Hook == '_' -> % Already tracing all hooks + % Remove Host: + HostOpts2 = maps:remove(Host, HostOpts), + if + HostOpts2 == #{} -> + % Remove all tracing: + erlang:erase(?TRACE_HOOK_KEY); + true -> + erlang:put(?TRACE_HOOK_KEY, #{'_' => HostOpts2}) + end; + #{}=TraceHooksOpts when Host == <<"*">> -> + % Remove tracing of this hook for all hosts: + TraceHooksOpts2 = maps:remove(Hook, TraceHooksOpts), + if + TraceHooksOpts2 == #{} -> + % Remove all tracing: + erlang:erase(?TRACE_HOOK_KEY); + true -> + erlang:put(?TRACE_HOOK_KEY, TraceHooksOpts2) + end; + #{}=TraceHooksOpts -> + case maps:get(Hook, TraceHooksOpts, undefined) of + #{}=HostOpts -> + NewHostOpts = maps:remove(Host, HostOpts), + if + NewHostOpts == #{} -> + % Remove hook: + erlang:put(?TRACE_HOOK_KEY, maps:remove(Hook, TraceHooksOpts)); + true -> + erlang:put(?TRACE_HOOK_KEY, TraceHooksOpts#{Hook => NewHostOpts}) + end; + _ -> + ok + end; + undefined -> + ok + end, + ok. + +do_get_tracing_options(Hook, Host, MaybeMap) -> + case MaybeMap of + undefined -> + undefined; + #{'_' := #{<<"*">> := Opts}} -> % Tracing everything + Opts; + #{'_' := HostOpts} -> % Tracing all hooks for some hosts + maps:get(Host, HostOpts, undefined); + #{}=TraceHooksOpts -> + HostOpts = maps:get(Hook, TraceHooksOpts, #{}), + case maps:get(Host, HostOpts, undefined) of + undefined -> + maps:get(<<"*">>, HostOpts, undefined); + Opts -> + Opts + end + end. + +run2([], Hook, Args, Host, Opts) -> + foreach_stop_hook_tracing(Opts, Hook, Host, Args, undefined), + ok; +run2([{Seq, Module, Function} | Ls], Hook, Args, Host, TracingOpts) -> + foreach_start_callback_tracing(TracingOpts, Hook, Host, Module, Function, Args, Seq), + Res = safe_apply(Hook, Module, Function, Args), + foreach_stop_callback_tracing(TracingOpts, Hook, Host, Module, Function, Args, Seq, Res), + case Res of + 'EXIT' -> + run2(Ls, Hook, Args, Host, TracingOpts); + stop -> + foreach_stop_hook_tracing(TracingOpts, Hook, Host, Args, {Module, Function, Seq, Ls}), + ok; + _ -> + run2(Ls, Hook, Args, Host, TracingOpts) + end. + +run_fold2([], Hook, Val, Args, Host, Opts) -> + fold_stop_hook_tracing(Opts, Hook, Host, [Val | Args], undefined), + Val; +run_fold2([{Seq, Module, Function} | Ls], Hook, Val, Args, Host, TracingOpts) -> + fold_start_callback_tracing(TracingOpts, Hook, Host, Module, Function, [Val | Args], Seq), + Res = safe_apply(Hook, Module, Function, [Val | Args]), + fold_stop_callback_tracing(TracingOpts, Hook, Host, Module, Function, [Val | Args], Seq, Res), + case Res of + 'EXIT' -> + run_fold2(Ls, Hook, Val, Args, Host, TracingOpts); + stop -> + fold_stop_hook_tracing(TracingOpts, Hook, Host, [Val | Args], {Module, Function, Seq, {old, Val}, Ls}), + Val; + {stop, NewVal} -> + fold_stop_hook_tracing(TracingOpts, Hook, Host, [Val | Args], {Module, Function, Seq, {new, NewVal}, Ls}), + NewVal; + NewVal -> + run_fold2(Ls, Hook, NewVal, Args, Host, TracingOpts) + end. + +foreach_start_hook_tracing(TracingOpts, Hook, Host, Args) -> + run_event_handler(TracingOpts, Hook, Host, start_hook, [Args], foreach). + +foreach_stop_hook_tracing(TracingOpts, Hook, Host, Args, BreakCallback) -> + run_event_handler(TracingOpts, Hook, Host, stop_hook, [Args, BreakCallback], foreach). + +foreach_start_callback_tracing(TracingOpts, Hook, Host, Mod, Func, Args, Seq) -> + run_event_handler(TracingOpts, Hook, Host, start_callback, [Mod, Func, Args, Seq], foreach). + +foreach_stop_callback_tracing(TracingOpts, Hook, Host, Mod, Func, Args, Seq, Res) -> + run_event_handler(TracingOpts, Hook, Host, stop_callback, [Mod, Func, Args, Seq, Res], foreach). + +fold_start_hook_tracing(TracingOpts, Hook, Host, Args) -> + run_event_handler(TracingOpts, Hook, Host, start_hook, [Args], fold). + +fold_stop_hook_tracing(TracingOpts, Hook, Host, Args, BreakCallback) -> + run_event_handler(TracingOpts, Hook, Host, stop_hook, [Args, BreakCallback], fold). + +fold_start_callback_tracing(TracingOpts, Hook, Host, Mod, Func, Args, Seq) -> + run_event_handler(TracingOpts, Hook, Host, start_callback, [Mod, Func, Args, Seq], fold). + +fold_stop_callback_tracing(TracingOpts, Hook, Host, Mod, Func, Args, Seq, Res) -> + run_event_handler(TracingOpts, Hook, Host, stop_callback, [Mod, Func, Args, Seq, Res], fold). + +run_event_handler(TracingOpts, Hook, Host, Event, EventArgs, RunType) -> + EventHandler = maps:get(event_handler, TracingOpts, fun default_tracing_event_handler/6), + EventHandlerOpts = maps:get(event_handler_options, TracingOpts, #{}), + try + if + erlang:is_function(EventHandler) -> + erlang:apply(EventHandler, [Event, EventArgs, RunType, Hook, Host, EventHandlerOpts]); + true -> + EventHandler:handle_hook_tracing_event(Event, EventArgs, RunType, Hook, Host, EventHandlerOpts) + end + of + _ -> + ok + catch + ?EX_RULE(E, R, St) -> + ?ERROR_MSG("Tracing event handler exception(~0p): ~0p: ~0p", [E, R, St]), + ok + end. + +default_tracing_event_handler(Event, EventArgs, RunType, Hook, Host, EventHandlerOpts) -> + % For now: + case maps:get(timing, EventHandlerOpts, true) of + true -> + tracing_timing_event_handler(Event, EventArgs, RunType, Hook, Host, EventHandlerOpts); + _ -> + ok + end. + +tracing_timing_event_handler(start_hook, _, _, Hook, Host, EventHandlerOpts) -> + HookStart = erlang:system_time(nanosecond), + tracing_output(EventHandlerOpts, "(~0p|~ts) Timing started\n", [Hook, Host]), + case erlang:get(?TIMING_KEY) of + #{}=TimingMap -> + erlang:put(?TIMING_KEY, TimingMap#{{Hook, Host} => {HookStart, []}}); + _ -> + erlang:put(?TIMING_KEY, #{{Hook, Host} => {HookStart, []}}) + end, + ok; +tracing_timing_event_handler(stop_hook, _, _, Hook, Host, EventHandlerOpts) -> + HookStop = erlang:system_time(nanosecond), + TimingMap = #{} = erlang:get(?TIMING_KEY), + {HookStart, CallbackList} = maps:get({Hook, Host}, TimingMap), + if + erlang:length(CallbackList) < 2 -> % We don't need sorted timing result + ok; + true -> + {CallbackListText, CallbackListTotal} = + lists:foldl( + fun({Mod, Func, Arity, Diff}, {CallbackText, Total}) -> + { + CallbackText + ++ "\n\t" + ++ mfa_string({Mod, Func, Arity}) + ++ " -> " + ++ erlang:integer_to_list(Diff) + ++ "ns", + Total + Diff + } + end, + {"", 0}, + lists:keysort(4, CallbackList) + ), + tracing_output( + EventHandlerOpts, + "(~0p|~ts) All callbacks got ~0pns to run. Sorted running time:" + ++ CallbackListText + ++ "\n", + [Hook, Host, CallbackListTotal] + ), + tracing_output( + EventHandlerOpts, + "(~0p|~ts) Time calculations for all callbacks got ~0pns\n", + [Hook, Host, (HookStop - HookStart) - CallbackListTotal] + ) + end, + tracing_output(EventHandlerOpts, "(~0p|~ts) Timing stopped\n", [Hook, Host]), + NewTimingMap = maps:remove({Hook, Host}, TimingMap), + if + NewTimingMap == #{} -> + erlang:erase(?TIMING_KEY); + true -> + erlang:put(?TIMING_KEY, NewTimingMap) + end, + ok; +tracing_timing_event_handler(start_callback, [Mod, Func, Args | _], _, Hook, Host, _) -> + CallbackStart = erlang:system_time(nanosecond), + TimingMap = #{} = erlang:get(?TIMING_KEY), + {HookStart, Callbacks} = maps:get({Hook, Host}, TimingMap), + erlang:put( + ?TIMING_KEY, + TimingMap#{ + {Hook, Host} => {HookStart, [{Mod, Func, erlang:length(Args), CallbackStart} | Callbacks]} + } + ), + ok; +tracing_timing_event_handler(stop_callback, _, _, Hook, Host, EventHandlerOpts) -> + CallbackStop = erlang:system_time(nanosecond), + TimingMap = #{} = erlang:get(?TIMING_KEY), + {HookStart, [{Mod, Func, Arity, CallbackStart} | Callbacks]} = maps:get({Hook, Host}, TimingMap), + tracing_output( + EventHandlerOpts, + "(~0p|~ts) " ++ + mfa_string({Mod, Func, Arity}) ++ + " got " ++ + erlang:integer_to_list(CallbackStop - CallbackStart) ++ + "ns\n", + [Hook, Host] + ), + erlang:put( + ?TIMING_KEY, + TimingMap#{ + {Hook, Host} => {HookStart, [{Mod, Func, Arity, CallbackStop - CallbackStart} | Callbacks]} + } + ), + ok. + +tracing_output(#{output_function := OutputF}, Text, Args) -> + try + OutputF(Text, Args) + of + _ -> + ok + catch + ?EX_RULE(E, R, St) -> + ?ERROR_MSG("Tracing output function exception(~0p): ~0p: ~0p", [E, R, St]), + ok + end; +tracing_output(#{output_log_level := Output}, Text, Args) -> + if + Output == debug -> + ?DEBUG(Text, Args); + true -> % info + ?INFO_MSG(Text, Args) + end, + ok; +tracing_output(Opts, Text, Args) -> + tracing_output(Opts#{output_log_level => info}, Text, Args). + +mfa_string({_, Fun, _}) when erlang:is_function(Fun) -> + io_lib:format("~0p", [Fun]); +mfa_string({Mod, Func, Arity}) -> + erlang:atom_to_list(Mod) ++ ":" ++ erlang:atom_to_list(Func) ++ "/" ++ erlang:integer_to_list(Arity). From 259876cb7453948270ccc12cecbfd6503285f035 Mon Sep 17 00:00:00 2001 From: Pouriya Jahanbakhsh Date: Sat, 22 Jan 2022 18:17:11 +0330 Subject: [PATCH 3/3] feat: event handling run multiple event handlers generate new events in timing event handlers print human-readable times output each callback time info is optional and by default is disabled --- src/ejabberd_hooks.erl | 272 ++++++++++++++++++++++++++++------------- 1 file changed, 186 insertions(+), 86 deletions(-) diff --git a/src/ejabberd_hooks.erl b/src/ejabberd_hooks.erl index 36edf29c8..11cd20f9a 100644 --- a/src/ejabberd_hooks.erl +++ b/src/ejabberd_hooks.erl @@ -51,7 +51,7 @@ [ get_tracing_options/3, trace_off/3, - trace_on/5 + trace_on/5,human_readable_time_string/1 ] ). @@ -336,22 +336,24 @@ safe_apply(Hook, Module, Function, Args) -> %%% Internal tracing functions %%%---------------------------------------------------------------------- +do_trace_on(Hook, Host, Opts, Timeout) when erlang:is_list(Host) -> + do_trace_on(Hook, erlang:list_to_binary(Host), Opts, Timeout); do_trace_on(Hook, Host, Opts, undefined) -> case erlang:get(?TRACE_HOOK_KEY) of - _ when Hook == '_' andalso Host == <<"*">> -> + _ when Hook == all andalso Host == <<"*">> -> % Trace everything: - erlang:put(?TRACE_HOOK_KEY, #{'_' => #{<<"*">> => Opts}}); - #{'_' := #{<<"*">> := _}} -> % Already tracing everything + erlang:put(?TRACE_HOOK_KEY, #{all => #{<<"*">> => Opts}}); + #{all := #{<<"*">> := _}} -> % Already tracing everything % Update Opts: - erlang:put(?TRACE_HOOK_KEY, #{'_' => #{<<"*">> => Opts}}); - #{'_' := HostOpts} when Hook == '_' -> % Already Tracing everything for some hosts + erlang:put(?TRACE_HOOK_KEY, #{all => #{<<"*">> => Opts}}); + #{all := HostOpts} when Hook == all -> % Already Tracing everything for some hosts % Add/Update Host and Opts: - erlang:put(?TRACE_HOOK_KEY, #{'_' => HostOpts#{Host => Opts}}); - #{'_' := _} -> % Already tracing everything and Hook is not '_' + erlang:put(?TRACE_HOOK_KEY, #{all => HostOpts#{Host => Opts}}); + #{all := _} -> % Already tracing everything and Hook is not all ok; - #{} when Hook == '_' -> - % Remove other hooks by just adding '_': - erlang:put(?TRACE_HOOK_KEY, #{'_' => #{Host => Opts}}); + #{} when Hook == all -> + % Remove other hooks by just adding all: + erlang:put(?TRACE_HOOK_KEY, #{all => #{Host => Opts}}); #{}=TraceHooksOpts when Host == <<"*">> -> % Want to trace a hook for all hosts erlang:put(?TRACE_HOOK_KEY, TraceHooksOpts#{Hook => #{Host => Opts}}); #{}=TraceHooksOpts -> @@ -365,7 +367,8 @@ do_trace_on(Hook, Host, Opts, undefined) -> erlang:put(?TRACE_HOOK_KEY, #{Hook => #{Host => Opts}}) end, ok; -do_trace_on(Hook, Host, Opts, Timeout) -> % Trace myself `Timeout` time +do_trace_on(Hook, Host, Opts, TimeoutSeconds) -> % Trace myself `Timeout` time + Timeout = timer:seconds(TimeoutSeconds), ParentPid = erlang:self(), try erlang:spawn( fun() -> @@ -386,12 +389,14 @@ do_trace_on(Hook, Host, Opts, Timeout) -> % Trace myself `Timeout` time {error, Reason} end. +do_trace_off(Hook, Host) when erlang:is_list(Host) -> + do_trace_off(Hook, erlang:list_to_binary(Host)); do_trace_off(Hook, Host) -> case erlang:get(?TRACE_HOOK_KEY) of - _ when Hook == '_' andalso Host == <<"*">> -> + _ when Hook == all andalso Host == <<"*">> -> % Remove all tracing: erlang:erase(?TRACE_HOOK_KEY); - #{'_' := HostOpts} when Hook == '_' -> % Already tracing all hooks + #{all := HostOpts} when Hook == all -> % Already tracing all hooks % Remove Host: HostOpts2 = maps:remove(Host, HostOpts), if @@ -399,7 +404,7 @@ do_trace_off(Hook, Host) -> % Remove all tracing: erlang:erase(?TRACE_HOOK_KEY); true -> - erlang:put(?TRACE_HOOK_KEY, #{'_' => HostOpts2}) + erlang:put(?TRACE_HOOK_KEY, #{all => HostOpts2}) end; #{}=TraceHooksOpts when Host == <<"*">> -> % Remove tracing of this hook for all hosts: @@ -434,9 +439,9 @@ do_get_tracing_options(Hook, Host, MaybeMap) -> case MaybeMap of undefined -> undefined; - #{'_' := #{<<"*">> := Opts}} -> % Tracing everything + #{all := #{<<"*">> := Opts}} -> % Tracing everything Opts; - #{'_' := HostOpts} -> % Tracing all hooks for some hosts + #{all := HostOpts} -> % Tracing all hooks for some hosts maps:get(Host, HostOpts, undefined); #{}=TraceHooksOpts -> HostOpts = maps:get(Hook, TraceHooksOpts, #{}), @@ -486,60 +491,119 @@ run_fold2([{Seq, Module, Function} | Ls], Hook, Val, Args, Host, TracingOpts) -> end. foreach_start_hook_tracing(TracingOpts, Hook, Host, Args) -> - run_event_handler(TracingOpts, Hook, Host, start_hook, [Args], foreach). + run_event_handlers(TracingOpts, Hook, Host, start_hook, [Args], foreach). foreach_stop_hook_tracing(TracingOpts, Hook, Host, Args, BreakCallback) -> - run_event_handler(TracingOpts, Hook, Host, stop_hook, [Args, BreakCallback], foreach). + run_event_handlers(TracingOpts, Hook, Host, stop_hook, [Args, BreakCallback], foreach). foreach_start_callback_tracing(TracingOpts, Hook, Host, Mod, Func, Args, Seq) -> - run_event_handler(TracingOpts, Hook, Host, start_callback, [Mod, Func, Args, Seq], foreach). + run_event_handlers(TracingOpts, Hook, Host, start_callback, [Mod, Func, Args, Seq], foreach). foreach_stop_callback_tracing(TracingOpts, Hook, Host, Mod, Func, Args, Seq, Res) -> - run_event_handler(TracingOpts, Hook, Host, stop_callback, [Mod, Func, Args, Seq, Res], foreach). + run_event_handlers(TracingOpts, Hook, Host, stop_callback, [Mod, Func, Args, Seq, Res], foreach). fold_start_hook_tracing(TracingOpts, Hook, Host, Args) -> - run_event_handler(TracingOpts, Hook, Host, start_hook, [Args], fold). + run_event_handlers(TracingOpts, Hook, Host, start_hook, [Args], fold). fold_stop_hook_tracing(TracingOpts, Hook, Host, Args, BreakCallback) -> - run_event_handler(TracingOpts, Hook, Host, stop_hook, [Args, BreakCallback], fold). + run_event_handlers(TracingOpts, Hook, Host, stop_hook, [Args, BreakCallback], fold). fold_start_callback_tracing(TracingOpts, Hook, Host, Mod, Func, Args, Seq) -> - run_event_handler(TracingOpts, Hook, Host, start_callback, [Mod, Func, Args, Seq], fold). + run_event_handlers(TracingOpts, Hook, Host, start_callback, [Mod, Func, Args, Seq], fold). fold_stop_callback_tracing(TracingOpts, Hook, Host, Mod, Func, Args, Seq, Res) -> - run_event_handler(TracingOpts, Hook, Host, stop_callback, [Mod, Func, Args, Seq, Res], fold). + run_event_handlers(TracingOpts, Hook, Host, stop_callback, [Mod, Func, Args, Seq, Res], fold). -run_event_handler(TracingOpts, Hook, Host, Event, EventArgs, RunType) -> - EventHandler = maps:get(event_handler, TracingOpts, fun default_tracing_event_handler/6), +run_event_handlers(TracingOpts, Hook, Host, Event, EventArgs, RunType) -> + EventHandlerList = maps:get(event_handler_list, TracingOpts, default_tracing_event_handler_list()), EventHandlerOpts = maps:get(event_handler_options, TracingOpts, #{}), - try - if - erlang:is_function(EventHandler) -> - erlang:apply(EventHandler, [Event, EventArgs, RunType, Hook, Host, EventHandlerOpts]); - true -> - EventHandler:handle_hook_tracing_event(Event, EventArgs, RunType, Hook, Host, EventHandlerOpts) - end - of - _ -> - ok - catch - ?EX_RULE(E, R, St) -> - ?ERROR_MSG("Tracing event handler exception(~0p): ~0p: ~0p", [E, R, St]), - ok - end. - -default_tracing_event_handler(Event, EventArgs, RunType, Hook, Host, EventHandlerOpts) -> - % For now: - case maps:get(timing, EventHandlerOpts, true) of + if + erlang:is_list(EventHandlerList) -> + lists:foreach( + fun(EventHandler) -> + try + if + erlang:is_function(EventHandler) -> + erlang:apply( + EventHandler, + [Event, EventArgs, RunType, Hook, Host, EventHandlerOpts, TracingOpts] + ); + true -> + EventHandler:handle_hook_tracing_event( + Event, + EventArgs, + RunType, + Hook, + Host, + EventHandlerOpts, + TracingOpts + ) + end + of + _ -> + ok + catch + ?EX_RULE(E, R, St) -> + ?ERROR_MSG( + "(~0p|~ts|~0p) Tracing event '~0p' handler exception(~0p): ~0p: ~0p", + [Hook, Host, erlang:self(), EventHandler, E, R, St] + ), + ok + end + end, + EventHandlerList + ); % ok true -> - tracing_timing_event_handler(Event, EventArgs, RunType, Hook, Host, EventHandlerOpts); - _ -> + ?ERROR_MSG("(~0p|~ts|~0p) Bad event handler list: ~0p", [Hook, Host, erlang:self(), EventHandlerList]), ok end. -tracing_timing_event_handler(start_hook, _, _, Hook, Host, EventHandlerOpts) -> +default_tracing_event_handler_list() -> + [fun tracing_timing_event_handler/7]. + +tracing_timing_event_handler(start_hook, EventArgs, RunType, Hook, Host, _, TracingOpts) -> HookStart = erlang:system_time(nanosecond), - tracing_output(EventHandlerOpts, "(~0p|~ts) Timing started\n", [Hook, Host]), + % Generate new event: + run_event_handlers(TracingOpts, Hook, Host, start_hook_timing, EventArgs ++ [HookStart], RunType); +tracing_timing_event_handler(stop_hook, EventArgs, RunType, Hook, Host, _, TracingOpts) -> + HookStop = erlang:system_time(nanosecond), + TimingMap = #{} = erlang:get(?TIMING_KEY), + {HookStart, CallbackList} = maps:get({Hook, Host}, TimingMap), + {CallbackListTiming, CallbackListTotal} = lists:foldl( + fun({_, _, _, CallbackStart, CallbackStop}=CallbackTimingInfo, {CallbackListTimingX, Total}) -> + {CallbackListTimingX ++ [CallbackTimingInfo], Total + (CallbackStop - CallbackStart)} + end, + {[], 0}, + CallbackList + ), + % Generate new event: + run_event_handlers( + TracingOpts, + Hook, + Host, + stop_hook_timing, + EventArgs ++ [HookStart, HookStop, CallbackListTiming, CallbackListTotal], + RunType + ); +tracing_timing_event_handler(start_callback, EventArgs, RunType, Hook, Host, _, TracingOpts) -> + CallbackStart = erlang:system_time(nanosecond), + % Generate new event: + run_event_handlers(TracingOpts, Hook, Host, start_callback_timing, EventArgs ++ [CallbackStart], RunType); +tracing_timing_event_handler(stop_callback, EventArgs, RunType, Hook, Host, _, TracingOpts) -> + CallbackStop = erlang:system_time(nanosecond), + TimingMap = #{} = erlang:get(?TIMING_KEY), + {_, [{_, _, _, CallbackStart} | _]} = maps:get({Hook, Host}, TimingMap), + run_event_handlers( + TracingOpts, + Hook, + Host, + stop_callback_timing, + EventArgs ++ [CallbackStart, CallbackStop], + RunType + ), + ok; +tracing_timing_event_handler(start_hook_timing, [_, HookStart], RunType, Hook, Host, EventHandlerOpts, _) -> + tracing_output(EventHandlerOpts, "(~0p|~ts|~0p|~0p) Timing started\n", [Hook, Host, erlang:self(), RunType]), case erlang:get(?TIMING_KEY) of #{}=TimingMap -> erlang:put(?TIMING_KEY, TimingMap#{{Hook, Host} => {HookStart, []}}); @@ -547,44 +611,58 @@ tracing_timing_event_handler(start_hook, _, _, Hook, Host, EventHandlerOpts) -> erlang:put(?TIMING_KEY, #{{Hook, Host} => {HookStart, []}}) end, ok; -tracing_timing_event_handler(stop_hook, _, _, Hook, Host, EventHandlerOpts) -> - HookStop = erlang:system_time(nanosecond), - TimingMap = #{} = erlang:get(?TIMING_KEY), - {HookStart, CallbackList} = maps:get({Hook, Host}, TimingMap), +tracing_timing_event_handler( + stop_hook_timing, + [_, _, HookStart, HookStop, CallbackListTiming, CallbackListTotal], + RunType, + Hook, + Host, + EventHandlerOpts, + _ +) -> if - erlang:length(CallbackList) < 2 -> % We don't need sorted timing result + erlang:length(CallbackListTiming) < 2 -> % We don't need sorted timing result ok; true -> - {CallbackListText, CallbackListTotal} = + CallbackListTimingText = lists:foldl( - fun({Mod, Func, Arity, Diff}, {CallbackText, Total}) -> - { - CallbackText - ++ "\n\t" - ++ mfa_string({Mod, Func, Arity}) - ++ " -> " - ++ erlang:integer_to_list(Diff) - ++ "ns", - Total + Diff - } + fun({Mod, Func, Arity, Diff}, CallbackListTimingText) -> + CallbackListTimingText + ++ "\n\t" + ++ mfa_string({Mod, Func, Arity}) + ++ " -> " + ++ human_readable_time_string(Diff) end, - {"", 0}, - lists:keysort(4, CallbackList) + "", + lists:keysort( + 4, + [ + {Mod, Func, Arity, CallbackStop - CallbackStart} || + {Mod, Func, Arity, CallbackStart, CallbackStop} <- CallbackListTiming + ] + ) ), tracing_output( EventHandlerOpts, - "(~0p|~ts) All callbacks got ~0pns to run. Sorted running time:" - ++ CallbackListText + "(~0p|~ts|~0p|~0p) All callbacks took ~ts to run. Sorted running time:" + ++ CallbackListTimingText ++ "\n", - [Hook, Host, CallbackListTotal] + [Hook, Host, erlang:self(), RunType, human_readable_time_string(CallbackListTotal)] ), tracing_output( EventHandlerOpts, - "(~0p|~ts) Time calculations for all callbacks got ~0pns\n", - [Hook, Host, (HookStop - HookStart) - CallbackListTotal] + "(~0p|~ts|~0p|~0p) Time calculations for all callbacks took ~ts\n", + [ + Hook, + Host, + erlang:self(), + RunType, + human_readable_time_string((HookStop - HookStart) - CallbackListTotal) + ] ) end, - tracing_output(EventHandlerOpts, "(~0p|~ts) Timing stopped\n", [Hook, Host]), + tracing_output(EventHandlerOpts, "(~0p|~ts|~0p|~0p) Timing stopped\n", [Hook, Host, erlang:self(), RunType]), + TimingMap = #{} = erlang:get(?TIMING_KEY), NewTimingMap = maps:remove({Hook, Host}, TimingMap), if NewTimingMap == #{} -> @@ -593,8 +671,7 @@ tracing_timing_event_handler(stop_hook, _, _, Hook, Host, EventHandlerOpts) -> erlang:put(?TIMING_KEY, NewTimingMap) end, ok; -tracing_timing_event_handler(start_callback, [Mod, Func, Args | _], _, Hook, Host, _) -> - CallbackStart = erlang:system_time(nanosecond), +tracing_timing_event_handler(start_callback_timing, [Mod, Func, Args, _, CallbackStart], _, Hook, Host, _, _) -> TimingMap = #{} = erlang:get(?TIMING_KEY), {HookStart, Callbacks} = maps:get({Hook, Host}, TimingMap), erlang:put( @@ -604,25 +681,34 @@ tracing_timing_event_handler(start_callback, [Mod, Func, Args | _], _, Hook, Hos } ), ok; -tracing_timing_event_handler(stop_callback, _, _, Hook, Host, EventHandlerOpts) -> - CallbackStop = erlang:system_time(nanosecond), +tracing_timing_event_handler( + stop_callback_timing, + [Mod, Func, _, _, _, CallbackStart, CallbackStop], + RunType, + Hook, + Host, + EventHandlerOpts, + _ +) -> TimingMap = #{} = erlang:get(?TIMING_KEY), {HookStart, [{Mod, Func, Arity, CallbackStart} | Callbacks]} = maps:get({Hook, Host}, TimingMap), - tracing_output( + maps:get(output_for_each_callback, maps:get(timing, EventHandlerOpts, #{}), false) andalso tracing_output( EventHandlerOpts, - "(~0p|~ts) " ++ - mfa_string({Mod, Func, Arity}) ++ - " got " ++ - erlang:integer_to_list(CallbackStop - CallbackStart) ++ - "ns\n", - [Hook, Host] + "(~0p|~ts|~0p|~0p) " + ++ mfa_string({Mod, Func, Arity}) + ++ " took " + ++ human_readable_time_string(CallbackStop - CallbackStart) + ++ "\n", + [Hook, Host, erlang:self(), RunType] ), erlang:put( ?TIMING_KEY, TimingMap#{ - {Hook, Host} => {HookStart, [{Mod, Func, Arity, CallbackStop - CallbackStart} | Callbacks]} + {Hook, Host} => {HookStart, [{Mod, Func, Arity, CallbackStart, CallbackStop} | Callbacks]} } ), + ok; +tracing_timing_event_handler(_, _, _, _, _, _, _) -> ok. tracing_output(#{output_function := OutputF}, Text, Args) -> @@ -651,3 +737,17 @@ mfa_string({_, Fun, _}) when erlang:is_function(Fun) -> io_lib:format("~0p", [Fun]); mfa_string({Mod, Func, Arity}) -> erlang:atom_to_list(Mod) ++ ":" ++ erlang:atom_to_list(Func) ++ "/" ++ erlang:integer_to_list(Arity). + +human_readable_time_string(TimeNS) -> + {Time, Unit, Decimals} = + if + TimeNS >= 1000000000 -> + {TimeNS / 1000000000, "", 10}; + TimeNS >= 1000000 -> + {TimeNS / 1000000, "m", 7}; + TimeNS >= 1000 -> + {TimeNS / 1000, "μ", 4}; + true -> + {TimeNS / 1, "n", 0} + end, + erlang:float_to_list(Time, [{decimals, Decimals}, compact]) ++ Unit ++ "s".