From 6cf29ba68883f425b8101b12b22fd213231bbd98 Mon Sep 17 00:00:00 2001 From: Kjell Winblad Date: Wed, 17 Apr 2024 18:20:17 +0200 Subject: [PATCH] fix: clean up traces to make them easier to parse and understand --- apps/emqx/src/emqx_trace/emqx_trace.erl | 5 ++-- .../src/emqx_rule_runtime.erl | 23 +++++++++++++++---- .../emqx_rule_engine_api_rule_apply_SUITE.erl | 12 ++++++---- .../test/emqx_rule_engine_test_connector.erl | 1 + 4 files changed, 30 insertions(+), 11 deletions(-) diff --git a/apps/emqx/src/emqx_trace/emqx_trace.erl b/apps/emqx/src/emqx_trace/emqx_trace.erl index 17580745a..4ae973722 100644 --- a/apps/emqx/src/emqx_trace/emqx_trace.erl +++ b/apps/emqx/src/emqx_trace/emqx_trace.erl @@ -96,13 +96,12 @@ rendered_action_template(ActionID, RenderResult) -> %% resource is called/modified StopMsg = lists:flatten( io_lib:format( - "action_stopped_after_render(~ts): " - "Action stopped after template render due to test setting.", + "Action ~ts stopped after template rendering due to test setting.", [ActionID] ) ), MsgBin = unicode:characters_to_binary(StopMsg), - error({unrecoverable_error, MsgBin}); + error({unrecoverable_error, {action_stopped_after_template_rendering, MsgBin}}); _ -> ok end, diff --git a/apps/emqx_rule_engine/src/emqx_rule_runtime.erl b/apps/emqx_rule_engine/src/emqx_rule_runtime.erl index 7181fb59b..3dfc5f6c8 100644 --- a/apps/emqx_rule_engine/src/emqx_rule_runtime.erl +++ b/apps/emqx_rule_engine/src/emqx_rule_runtime.erl @@ -709,27 +709,42 @@ inc_action_metrics(TraceCtx, Result) -> _ = do_inc_action_metrics(TraceCtx, Result), Result. +do_inc_action_metrics( + #{rule_id := RuleId, action_id := ActId} = TraceContext, + {error, {unrecoverable_error, {action_stopped_after_template_rendering, Explanation}} = _Reason} +) -> + TraceContext1 = maps:remove(action_id, TraceContext), + trace_action( + ActId, + "action_stopped_after_template_rendering", + maps:merge(#{reason => Explanation}, TraceContext1) + ), + emqx_metrics_worker:inc(rule_metrics, RuleId, 'actions.failed'), + emqx_metrics_worker:inc(rule_metrics, RuleId, 'actions.failed.unknown'); do_inc_action_metrics( #{rule_id := RuleId, action_id := ActId} = TraceContext, {error, {recoverable_error, _}} ) -> - trace_action(ActId, "out_of_service", TraceContext), + TraceContext1 = maps:remove(action_id, TraceContext), + trace_action(ActId, "out_of_service", TraceContext1), emqx_metrics_worker:inc(rule_metrics, RuleId, 'actions.failed.out_of_service'); do_inc_action_metrics( #{rule_id := RuleId, action_id := ActId} = TraceContext, {error, {unrecoverable_error, _} = Reason} ) -> - trace_action(ActId, "action_failed", maps:merge(#{reason => Reason}, TraceContext)), + TraceContext1 = maps:remove(action_id, TraceContext), + trace_action(ActId, "action_failed", maps:merge(#{reason => Reason}, TraceContext1)), emqx_metrics_worker:inc(rule_metrics, RuleId, 'actions.failed'), emqx_metrics_worker:inc(rule_metrics, RuleId, 'actions.failed.unknown'); do_inc_action_metrics(#{rule_id := RuleId, action_id := ActId} = TraceContext, R) -> + TraceContext1 = maps:remove(action_id, TraceContext), case is_ok_result(R) of false -> - trace_action(ActId, "action_failed", maps:merge(#{reason => R}, TraceContext)), + trace_action(ActId, "action_failed", maps:merge(#{reason => R}, TraceContext1)), emqx_metrics_worker:inc(rule_metrics, RuleId, 'actions.failed'), emqx_metrics_worker:inc(rule_metrics, RuleId, 'actions.failed.unknown'); true -> - trace_action(ActId, "action_success", maps:merge(#{result => R}, TraceContext)), + trace_action(ActId, "action_success", maps:merge(#{result => R}, TraceContext1)), emqx_metrics_worker:inc(rule_metrics, RuleId, 'actions.success') end. diff --git a/apps/emqx_rule_engine/test/emqx_rule_engine_api_rule_apply_SUITE.erl b/apps/emqx_rule_engine/test/emqx_rule_engine_api_rule_apply_SUITE.erl index e73c2c44d..063982367 100644 --- a/apps/emqx_rule_engine/test/emqx_rule_engine_api_rule_apply_SUITE.erl +++ b/apps/emqx_rule_engine/test/emqx_rule_engine_api_rule_apply_SUITE.erl @@ -143,7 +143,9 @@ basic_apply_rule_test_helper(Config, TraceType, StopAfterRender) -> begin Bin = read_rule_trace_file(TraceName, TraceType, Now), io:format("THELOG2:~n~s", [Bin]), - ?assertNotEqual(nomatch, binary:match(Bin, [<<"action_failed">>])) + ?assertNotEqual( + nomatch, binary:match(Bin, [<<"action_stopped_after_template_rendering">>]) + ) end ); false -> @@ -231,7 +233,7 @@ t_apply_rule_test_batch_separation_stop_after_render(_Config) -> ParmsStopAfterRender = apply_rule_parms(true, Name), ParmsNoStopAfterRender = apply_rule_parms(false, Name), %% Check that batching is working - Count = 400, + Count = 200, CountMsgFun = fun CountMsgFunRec(0 = _CurCount, GotBatchWithAtLeastTwo) -> @@ -285,7 +287,10 @@ t_apply_rule_test_batch_separation_stop_after_render(_Config) -> _NAttempts0 = 20, begin Bin = read_rule_trace_file(Name, ruleid, Now), - ?assertNotEqual(nomatch, binary:match(Bin, [<<"action_success">>])) + ?assertNotEqual(nomatch, binary:match(Bin, [<<"action_success">>])), + ?assertNotEqual( + nomatch, binary:match(Bin, [<<"action_stopped_after_template_rendering">>]) + ) end ), ok. @@ -364,5 +369,4 @@ read_rule_trace_file(TraceName, TraceType, From) -> emqx_trace:check(), ok = emqx_trace_handler_SUITE:filesync(TraceName, TraceType), {ok, Bin} = file:read_file(emqx_trace:log_file(TraceName, From)), - io_lib:format("MYTRACE:~n~s", [Bin]), Bin. diff --git a/apps/emqx_rule_engine/test/emqx_rule_engine_test_connector.erl b/apps/emqx_rule_engine/test/emqx_rule_engine_test_connector.erl index 5633ed27e..c22c5fbd5 100644 --- a/apps/emqx_rule_engine/test/emqx_rule_engine_test_connector.erl +++ b/apps/emqx_rule_engine/test/emqx_rule_engine_test_connector.erl @@ -93,6 +93,7 @@ on_batch_query( #{parameters := #{values := #{send_to_pid := PidBin}}} = maps:get(ChannelId, Channels), Pid = binary_to_term(emqx_utils:hexstr_to_bin(PidBin)), Pid ! Msg, + emqx_trace:rendered_action_template(ChannelId, #{nothing_to_render => ok}), ok. on_get_status(_InstId, _State) ->