fix: clean up traces to make them easier to parse and understand

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 ~ts stopped after template rendering due to test setting.",
-                    "Action stopped after template render 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,

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.
 

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.

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) ->