From 59a442cdb56899cde22cf57ab11615d90d472427 Mon Sep 17 00:00:00 2001 From: Kjell Winblad Date: Wed, 27 Mar 2024 11:11:16 +0100 Subject: [PATCH 01/23] feat(rule trace): add support for ruleid as a trace type --- apps/emqx/include/emqx_trace.hrl | 9 +- apps/emqx/src/emqx_trace/emqx_trace.erl | 6 ++ .../src/emqx_trace/emqx_trace_handler.erl | 14 ++- apps/emqx/test/emqx_trace_handler_SUITE.erl | 85 +++++++++++++++++-- .../src/emqx_mgmt_api_trace.erl | 11 ++- .../test/emqx_mgmt_api_trace_SUITE.erl | 67 ++++++++++++++- .../src/emqx_rule_runtime.erl | 3 + rel/i18n/emqx_mgmt_api_trace.hocon | 5 ++ 8 files changed, 188 insertions(+), 12 deletions(-) diff --git a/apps/emqx/include/emqx_trace.hrl b/apps/emqx/include/emqx_trace.hrl index 5c50fa706..476794223 100644 --- a/apps/emqx/include/emqx_trace.hrl +++ b/apps/emqx/include/emqx_trace.hrl @@ -20,9 +20,14 @@ -record(?TRACE, { name :: binary() | undefined | '_', - type :: clientid | topic | ip_address | undefined | '_', + type :: clientid | topic | ip_address | ruleid | undefined | '_', filter :: - emqx_types:topic() | emqx_types:clientid() | emqx_trace:ip_address() | undefined | '_', + emqx_types:topic() + | emqx_types:clientid() + | emqx_trace:ip_address() + | emqx_trace:ruleid() + | undefined + | '_', enable = true :: boolean() | '_', payload_encode = text :: hex | text | hidden | '_', extra = #{} :: map() | '_', diff --git a/apps/emqx/src/emqx_trace/emqx_trace.erl b/apps/emqx/src/emqx_trace/emqx_trace.erl index f3a5be084..8151c19b5 100644 --- a/apps/emqx/src/emqx_trace/emqx_trace.erl +++ b/apps/emqx/src/emqx_trace/emqx_trace.erl @@ -66,6 +66,9 @@ -export_type([ip_address/0]). -type ip_address() :: string(). +-export_type([ruleid/0]). +-type ruleid() :: binary(). + publish(#message{topic = <<"$SYS/", _/binary>>}) -> ignore; publish(#message{from = From, topic = Topic, payload = Payload}) when @@ -517,6 +520,9 @@ to_trace(#{type := ip_address, ip_address := Filter} = Trace, Rec) -> Error -> Error end; +to_trace(#{type := ruleid, ruleid := Filter} = Trace, Rec) -> + Trace0 = maps:without([type, ruleid], Trace), + to_trace(Trace0, Rec#?TRACE{type = ruleid, filter = Filter}); to_trace(#{type := Type}, _Rec) -> {error, io_lib:format("required ~s field", [Type])}; to_trace(#{payload_encode := PayloadEncode} = Trace, Rec) -> diff --git a/apps/emqx/src/emqx_trace/emqx_trace_handler.erl b/apps/emqx/src/emqx_trace/emqx_trace_handler.erl index 313826cde..3af543013 100644 --- a/apps/emqx/src/emqx_trace/emqx_trace_handler.erl +++ b/apps/emqx/src/emqx_trace/emqx_trace_handler.erl @@ -33,6 +33,7 @@ %% For logger handler filters callbacks -export([ + filter_ruleid/2, filter_clientid/2, filter_topic/2, filter_ip_address/2 @@ -133,6 +134,12 @@ uninstall(HandlerId) -> running() -> lists:foldl(fun filter_traces/2, [], emqx_logger:get_log_handlers(started)). +-spec filter_ruleid(logger:log_event(), {binary(), atom()}) -> logger:log_event() | stop. +filter_ruleid(#{meta := Meta = #{ruleid := RuleId}} = Log, {MatchId, _Name}) -> + filter_ret(RuleId =:= MatchId andalso is_trace(Meta), Log); +filter_ruleid(_Log, _ExpectId) -> + stop. + -spec filter_clientid(logger:log_event(), {binary(), atom()}) -> logger:log_event() | stop. filter_clientid(#{meta := Meta = #{clientid := ClientId}} = Log, {MatchId, _Name}) -> filter_ret(ClientId =:= MatchId andalso is_trace(Meta), Log); @@ -164,7 +171,9 @@ filters(#{type := clientid, filter := Filter, name := Name}) -> filters(#{type := topic, filter := Filter, name := Name}) -> [{topic, {fun ?MODULE:filter_topic/2, {ensure_bin(Filter), Name}}}]; filters(#{type := ip_address, filter := Filter, name := Name}) -> - [{ip_address, {fun ?MODULE:filter_ip_address/2, {ensure_list(Filter), Name}}}]. + [{ip_address, {fun ?MODULE:filter_ip_address/2, {ensure_list(Filter), Name}}}]; +filters(#{type := ruleid, filter := Filter, name := Name}) -> + [{ruleid, {fun ?MODULE:filter_ruleid/2, {ensure_bin(Filter), Name}}}]. formatter(#{type := _Type, payload_encode := PayloadEncode}) -> {emqx_trace_formatter, #{ @@ -184,7 +193,8 @@ filter_traces(#{id := Id, level := Level, dst := Dst, filters := Filters}, Acc) [{Type, {FilterFun, {Filter, Name}}}] when Type =:= topic orelse Type =:= clientid orelse - Type =:= ip_address + Type =:= ip_address orelse + Type =:= ruleid -> [Init#{type => Type, filter => Filter, name => Name, filter_fun => FilterFun} | Acc]; _ -> diff --git a/apps/emqx/test/emqx_trace_handler_SUITE.erl b/apps/emqx/test/emqx_trace_handler_SUITE.erl index 59a472f3e..85a9c056b 100644 --- a/apps/emqx/test/emqx_trace_handler_SUITE.erl +++ b/apps/emqx/test/emqx_trace_handler_SUITE.erl @@ -20,6 +20,7 @@ -compile(nowarn_export_all). -include_lib("eunit/include/eunit.hrl"). +-include_lib("snabbkaffe/include/test_macros.hrl"). -include_lib("common_test/include/ct.hrl"). -define(CLIENT, [ @@ -29,11 +30,12 @@ {password, <<"pass">>} ]). -all() -> [t_trace_clientid, t_trace_topic, t_trace_ip_address, t_trace_clientid_utf8]. +all() -> + [t_trace_clientid, t_trace_topic, t_trace_ip_address, t_trace_clientid_utf8, t_trace_rule_id]. init_per_suite(Config) -> Apps = emqx_cth_suite:start( - [emqx], + [emqx, emqx_rule_engine], #{work_dir => emqx_cth_suite:work_dir(Config)} ), [{apps, Apps} | Config]. @@ -205,6 +207,79 @@ t_trace_topic(_Config) -> ?assertEqual([], emqx_trace_handler:running()), emqtt:disconnect(T). +create_rule(Name, SQL) -> + Rule = emqx_rule_engine_SUITE:make_simple_rule(Name, SQL), + {ok, _} = emqx_rule_engine:create_rule(Rule). + +t_trace_rule_id(_Config) -> + %% Start MQTT Client + {ok, T} = emqtt:start_link(?CLIENT), + emqtt:connect(T), + %% Create rules + create_rule( + <<"test_rule_id_1">>, + <<"select 1 as rule_number from \"rule_1_topic\"">> + ), + create_rule( + <<"test_rule_id_2">>, + <<"select 2 as rule_number from \"rule_2_topic\"">> + ), + %% Start tracing + ok = emqx_trace_handler:install( + "CLI-RULE-1", ruleid, <<"test_rule_id_1">>, all, "tmp/rule_trace_1.log" + ), + ok = emqx_trace_handler:install( + "CLI-RULE-2", ruleid, <<"test_rule_id_2">>, all, "tmp/rule_trace_2.log" + ), + emqx_trace:check(), + ok = filesync("CLI-RULE-1", ruleid), + ok = filesync("CLI-RULE-2", ruleid), + + %% Verify the tracing file exits + ?assert(filelib:is_regular("tmp/rule_trace_1.log")), + ?assert(filelib:is_regular("tmp/rule_trace_2.log")), + + %% Get current traces + ?assertMatch( + [ + #{ + type := ruleid, + filter := <<"test_rule_id_1">>, + level := debug, + dst := "tmp/rule_trace_1.log", + name := <<"CLI-RULE-1">> + }, + #{ + type := ruleid, + filter := <<"test_rule_id_2">>, + name := <<"CLI-RULE-2">>, + level := debug, + dst := "tmp/rule_trace_2.log" + } + ], + emqx_trace_handler:running() + ), + + %% Trigger rule + emqtt:publish(T, <<"rule_1_topic">>, <<"my_traced_message">>), + ?retry( + 100, + 5, + begin + ok = filesync("CLI-RULE-1", ruleid), + {ok, Bin} = file:read_file("tmp/rule_trace_1.log"), + ?assertNotEqual(nomatch, binary:match(Bin, [<<"my_traced_message">>])) + end + ), + ok = filesync("CLI-RULE-2", ruleid), + ?assert(filelib:file_size("tmp/rule_trace_2.log") =:= 0), + + %% Stop tracing + ok = emqx_trace_handler:uninstall(ruleid, <<"CLI-RULE-1">>), + ok = emqx_trace_handler:uninstall(ruleid, <<"CLI-RULE-2">>), + ?assertEqual([], emqx_trace_handler:running()), + emqtt:disconnect(T). + t_trace_ip_address(_Config) -> {ok, T} = emqtt:start_link(?CLIENT), emqtt:connect(T), @@ -272,11 +347,11 @@ t_trace_ip_address(_Config) -> filesync(Name, Type) -> ct:sleep(50), - filesync(Name, Type, 3). + filesync(Name, Type, 5). %% sometime the handler process is not started yet. -filesync(_Name, _Type, 0) -> - ok; +filesync(Name, Type, 0) -> + ct:fail("Handler process not started ~p ~p", [Name, Type]); filesync(Name0, Type, Retry) -> Name = case is_binary(Name0) of diff --git a/apps/emqx_management/src/emqx_mgmt_api_trace.erl b/apps/emqx_management/src/emqx_mgmt_api_trace.erl index 5cdbc65ff..19edc229d 100644 --- a/apps/emqx_management/src/emqx_mgmt_api_trace.erl +++ b/apps/emqx_management/src/emqx_mgmt_api_trace.erl @@ -222,7 +222,7 @@ fields(trace) -> )}, {type, hoconsc:mk( - hoconsc:enum([clientid, topic, ip_address]), + hoconsc:enum([clientid, topic, ip_address, ruleid]), #{ description => ?DESC(filter_type), required => true, @@ -257,6 +257,15 @@ fields(trace) -> example => <<"127.0.0.1">> } )}, + {ruleid, + hoconsc:mk( + binary(), + #{ + description => ?DESC(ruleid_field), + required => false, + example => <<"my_rule">> + } + )}, {status, hoconsc:mk( hoconsc:enum([running, stopped, waiting]), diff --git a/apps/emqx_management/test/emqx_mgmt_api_trace_SUITE.erl b/apps/emqx_management/test/emqx_mgmt_api_trace_SUITE.erl index cb93bc9d6..ef7b5a191 100644 --- a/apps/emqx_management/test/emqx_mgmt_api_trace_SUITE.erl +++ b/apps/emqx_management/test/emqx_mgmt_api_trace_SUITE.erl @@ -122,6 +122,56 @@ t_http_test(_Config) -> unload(), ok. +t_http_test_rule_trace(_Config) -> + emqx_trace:clear(), + load(), + %% create + Name = atom_to_binary(?FUNCTION_NAME), + Trace = [ + {<<"name">>, Name}, + {<<"type">>, <<"ruleid">>}, + {<<"ruleid">>, Name} + ], + + {ok, Create} = request_api(post, api_path("trace"), Trace), + ?assertMatch(#{<<"name">> := Name}, json(Create)), + + {ok, List} = request_api(get, api_path("trace")), + [Data] = json(List), + ?assertEqual(Name, maps:get(<<"name">>, Data)), + + %% update + {ok, Update} = request_api(put, api_path(iolist_to_binary(["trace/", Name, "/stop"])), #{}), + ?assertEqual( + #{ + <<"enable">> => false, + <<"name">> => Name + }, + json(Update) + ), + {ok, List1} = request_api(get, api_path("trace")), + [Data1] = json(List1), + Node = atom_to_binary(node()), + ?assertMatch( + #{ + <<"status">> := <<"stopped">>, + <<"name">> := Name, + <<"log_size">> := #{Node := _}, + <<"start_at">> := _, + <<"end_at">> := _, + <<"type">> := <<"ruleid">>, + <<"ruleid">> := Name + }, + Data1 + ), + + %% delete + {ok, Delete} = request_api(delete, api_path(["trace/", Name])), + ?assertEqual(<<>>, Delete), + + unload(), + ok. + t_create_failed(_Config) -> load(), Trace = [{<<"type">>, <<"topic">>}, {<<"topic">>, <<"/x/y/z">>}], @@ -252,13 +302,16 @@ t_log_file(_Config) -> ok. create_trace(Name, ClientId, Start) -> + create_trace(Name, clientid, ClientId, Start). + +create_trace(Name, Type, TypeValue, Start) -> ?check_trace( #{timetrap => 900}, begin {ok, _} = emqx_trace:create([ {<<"name">>, Name}, - {<<"type">>, clientid}, - {<<"clientid">>, ClientId}, + {<<"type">>, Type}, + {atom_to_binary(Type), TypeValue}, {<<"start_at">>, Start} ]), ?block_until(#{?snk_kind := update_trace_done}) @@ -268,6 +321,16 @@ create_trace(Name, ClientId, Start) -> end ). +create_rule_trace(RuleId) -> + Now = erlang:system_time(second), + emqx_mgmt_api_trace_SUITE:create_trace(atom_to_binary(?FUNCTION_NAME), ruleid, RuleId, Now - 2). + +t_create_rule_trace(_Config) -> + load(), + create_rule_trace(atom_to_binary(?FUNCTION_NAME)), + unload(), + ok. + t_stream_log(_Config) -> emqx_trace:clear(), load(), diff --git a/apps/emqx_rule_engine/src/emqx_rule_runtime.erl b/apps/emqx_rule_engine/src/emqx_rule_runtime.erl index f51908772..9a307e2c3 100644 --- a/apps/emqx_rule_engine/src/emqx_rule_runtime.erl +++ b/apps/emqx_rule_engine/src/emqx_rule_runtime.erl @@ -69,6 +69,9 @@ apply_rule_discard_result(Rule, Columns, Envs) -> ok. apply_rule(Rule = #{id := RuleID}, Columns, Envs) -> + ?TRACE("APPLY_RULE", "rule_activated", #{ + ruleid => RuleID, input => Columns, environment => Envs + }), ok = emqx_metrics_worker:inc(rule_metrics, RuleID, 'matched'), clear_rule_payload(), try diff --git a/rel/i18n/emqx_mgmt_api_trace.hocon b/rel/i18n/emqx_mgmt_api_trace.hocon index 67462ab43..ba07d7d53 100644 --- a/rel/i18n/emqx_mgmt_api_trace.hocon +++ b/rel/i18n/emqx_mgmt_api_trace.hocon @@ -80,6 +80,11 @@ client_ip_addess.desc: client_ip_addess.label: """Client IP Address""" +ruleid.desc: +"""Specify the Rule ID if the trace type is 'ruleid'.""" +ruleid.label: +"""Rule ID""" + trace_status.desc: """trace status""" trace_status.label: From ef705c228503ba570e0276f62e45af283203ec19 Mon Sep 17 00:00:00 2001 From: Kjell Winblad Date: Tue, 2 Apr 2024 18:00:27 +0200 Subject: [PATCH 02/23] feat: add apply rule API, clientid/ruleid tracing for rule and connector This commit adds: * Support for forwarding the rule id and client id to the connector so that events such as template rendered successfully can be traced. * HTTP API for for applying/activating a rule with the given context --- .../src/emqx_trace/emqx_trace_handler.erl | 14 +- .../src/emqx_bridge_http_connector.erl | 13 +- .../test/emqx_bridge_http_SUITE.erl | 248 +++++----- .../test/emqx_bridge_http_test_lib.erl | 161 +++++++ .../src/emqx_resource_buffer_worker.erl | 185 +++++-- .../src/emqx_rule_api_schema.erl | 45 +- .../src/emqx_rule_engine_api.erl | 38 ++ .../src/emqx_rule_runtime.erl | 248 +++++++--- .../src/emqx_rule_sqltester.erl | 70 ++- .../emqx_rule_engine_api_rule_apply_SUITE.erl | 451 ++++++++++++++++++ 10 files changed, 1232 insertions(+), 241 deletions(-) create mode 100644 apps/emqx_bridge_http/test/emqx_bridge_http_test_lib.erl create mode 100644 apps/emqx_rule_engine/test/emqx_rule_engine_api_rule_apply_SUITE.erl diff --git a/apps/emqx/src/emqx_trace/emqx_trace_handler.erl b/apps/emqx/src/emqx_trace/emqx_trace_handler.erl index 3af543013..c69809052 100644 --- a/apps/emqx/src/emqx_trace/emqx_trace_handler.erl +++ b/apps/emqx/src/emqx_trace/emqx_trace_handler.erl @@ -135,14 +135,22 @@ running() -> lists:foldl(fun filter_traces/2, [], emqx_logger:get_log_handlers(started)). -spec filter_ruleid(logger:log_event(), {binary(), atom()}) -> logger:log_event() | stop. -filter_ruleid(#{meta := Meta = #{ruleid := RuleId}} = Log, {MatchId, _Name}) -> - filter_ret(RuleId =:= MatchId andalso is_trace(Meta), Log); +filter_ruleid(#{meta := Meta = #{rule_id := RuleId}} = Log, {MatchId, _Name}) -> + RuleIDs = maps:get(rule_ids, Meta, #{}), + IsMatch = (RuleId =:= MatchId) orelse maps:get(MatchId, RuleIDs, false), + filter_ret(IsMatch andalso is_trace(Meta), Log); +filter_ruleid(#{meta := Meta = #{rule_ids := RuleIDs}} = Log, {MatchId, _Name}) -> + filter_ret(maps:get(MatchId, RuleIDs, false) andalso is_trace(Meta), Log); filter_ruleid(_Log, _ExpectId) -> stop. -spec filter_clientid(logger:log_event(), {binary(), atom()}) -> logger:log_event() | stop. filter_clientid(#{meta := Meta = #{clientid := ClientId}} = Log, {MatchId, _Name}) -> - filter_ret(ClientId =:= MatchId andalso is_trace(Meta), Log); + ClientIDs = maps:get(client_ids, Meta, #{}), + IsMatch = (ClientId =:= MatchId) orelse maps:get(MatchId, ClientIDs, false), + filter_ret(IsMatch andalso is_trace(Meta), Log); +filter_clientid(#{meta := Meta = #{client_ids := ClientIDs}} = Log, {MatchId, _Name}) -> + filter_ret(maps:get(MatchId, ClientIDs, false) andalso is_trace(Meta), Log); filter_clientid(_Log, _ExpectId) -> stop. diff --git a/apps/emqx_bridge_http/src/emqx_bridge_http_connector.erl b/apps/emqx_bridge_http/src/emqx_bridge_http_connector.erl index ae1e727ca..99222aa00 100644 --- a/apps/emqx_bridge_http/src/emqx_bridge_http_connector.erl +++ b/apps/emqx_bridge_http/src/emqx_bridge_http_connector.erl @@ -661,13 +661,22 @@ process_request_and_action(Request, ActionState, Msg) -> ), BodyTemplate = maps:get(body, ActionState), Body = render_request_body(BodyTemplate, RenderTmplFunc, Msg), - #{ + RenderResult = #{ method => Method, path => Path, body => Body, headers => Headers, request_timeout => maps:get(request_timeout, ActionState) - }. + }, + ?TRACE( + "QUERY_RENDER", + "http_connector_successfully_rendered_request", + #{ + request => Request, + render_result => RenderResult + } + ), + RenderResult. merge_proplist(Proplist1, Proplist2) -> lists:foldl( diff --git a/apps/emqx_bridge_http/test/emqx_bridge_http_SUITE.erl b/apps/emqx_bridge_http/test/emqx_bridge_http_SUITE.erl index 3da04012d..ab0d5bb55 100644 --- a/apps/emqx_bridge_http/test/emqx_bridge_http_SUITE.erl +++ b/apps/emqx_bridge_http/test/emqx_bridge_http_SUITE.erl @@ -30,8 +30,8 @@ -include_lib("snabbkaffe/include/snabbkaffe.hrl"). -include_lib("emqx/include/asserts.hrl"). --define(BRIDGE_TYPE, <<"webhook">>). --define(BRIDGE_NAME, atom_to_binary(?MODULE)). +-define(BRIDGE_TYPE, emqx_bridge_http_test_lib:bridge_type()). +-define(BRIDGE_NAME, emqx_bridge_http_test_lib:bridge_name()). all() -> emqx_common_test_helpers:all(?MODULE). @@ -73,21 +73,10 @@ suite() -> init_per_testcase(t_bad_bridge_config, Config) -> Config; -init_per_testcase(t_send_async_connection_timeout, Config) -> - HTTPPath = <<"/path">>, - ServerSSLOpts = false, - {ok, {HTTPPort, _Pid}} = emqx_bridge_http_connector_test_server:start_link( - _Port = random, HTTPPath, ServerSSLOpts - ), - ResponseDelayMS = 500, - ok = emqx_bridge_http_connector_test_server:set_handler( - success_http_handler(#{response_delay => ResponseDelayMS}) - ), - [ - {http_server, #{port => HTTPPort, path => HTTPPath}}, - {response_delay_ms, ResponseDelayMS} - | Config - ]; +init_per_testcase(Case, Config) when + Case =:= t_send_async_connection_timeout orelse Case =:= t_send_get_trace_messages +-> + emqx_bridge_http_test_lib:init_http_success_server(Config); init_per_testcase(t_path_not_found, Config) -> HTTPPath = <<"/nonexisting/path">>, ServerSSLOpts = false, @@ -115,7 +104,9 @@ init_per_testcase(t_bridge_probes_header_atoms, Config) -> {ok, {HTTPPort, _Pid}} = emqx_bridge_http_connector_test_server:start_link( _Port = random, HTTPPath, ServerSSLOpts ), - ok = emqx_bridge_http_connector_test_server:set_handler(success_http_handler()), + ok = emqx_bridge_http_connector_test_server:set_handler( + emqx_bridge_http_test_lib:success_http_handler() + ), [{http_server, #{port => HTTPPort, path => HTTPPath}} | Config]; init_per_testcase(_TestCase, Config) -> Server = start_http_server(#{response_delay_ms => 0}), @@ -126,7 +117,8 @@ end_per_testcase(TestCase, _Config) when TestCase =:= t_too_many_requests; TestCase =:= t_rule_action_expired; TestCase =:= t_bridge_probes_header_atoms; - TestCase =:= t_send_async_connection_timeout + TestCase =:= t_send_async_connection_timeout; + TestCase =:= t_send_get_trace_messages -> ok = emqx_bridge_http_connector_test_server:stop(), persistent_term:erase({?MODULE, times_called}), @@ -250,115 +242,8 @@ get_metrics(Name) -> Type = <<"http">>, emqx_bridge:get_metrics(Type, Name). -bridge_async_config(#{port := Port} = Config) -> - Type = maps:get(type, Config, ?BRIDGE_TYPE), - Name = maps:get(name, Config, ?BRIDGE_NAME), - Host = maps:get(host, Config, "localhost"), - Path = maps:get(path, Config, ""), - PoolSize = maps:get(pool_size, Config, 1), - QueryMode = maps:get(query_mode, Config, "async"), - ConnectTimeout = maps:get(connect_timeout, Config, "1s"), - RequestTimeout = maps:get(request_timeout, Config, "10s"), - ResumeInterval = maps:get(resume_interval, Config, "1s"), - HealthCheckInterval = maps:get(health_check_interval, Config, "200ms"), - ResourceRequestTTL = maps:get(resource_request_ttl, Config, "infinity"), - LocalTopic = - case maps:find(local_topic, Config) of - {ok, LT} -> - lists:flatten(["local_topic = \"", LT, "\""]); - error -> - "" - end, - ConfigString = io_lib:format( - "bridges.~s.~s {\n" - " url = \"http://~s:~p~s\"\n" - " connect_timeout = \"~p\"\n" - " enable = true\n" - %% local_topic - " ~s\n" - " enable_pipelining = 100\n" - " max_retries = 2\n" - " method = \"post\"\n" - " pool_size = ~p\n" - " pool_type = \"random\"\n" - " request_timeout = \"~s\"\n" - " body = \"${id}\"\n" - " resource_opts {\n" - " inflight_window = 100\n" - " health_check_interval = \"~s\"\n" - " max_buffer_bytes = \"1GB\"\n" - " query_mode = \"~s\"\n" - " request_ttl = \"~p\"\n" - " resume_interval = \"~s\"\n" - " start_after_created = \"true\"\n" - " start_timeout = \"5s\"\n" - " worker_pool_size = \"1\"\n" - " }\n" - " ssl {\n" - " enable = false\n" - " }\n" - "}\n", - [ - Type, - Name, - Host, - Port, - Path, - ConnectTimeout, - LocalTopic, - PoolSize, - RequestTimeout, - HealthCheckInterval, - QueryMode, - ResourceRequestTTL, - ResumeInterval - ] - ), - ct:pal(ConfigString), - parse_and_check(ConfigString, Type, Name). - -parse_and_check(ConfigString, BridgeType, Name) -> - {ok, RawConf} = hocon:binary(ConfigString, #{format => map}), - hocon_tconf:check_plain(emqx_bridge_schema, RawConf, #{required => false, atom_key => false}), - #{<<"bridges">> := #{BridgeType := #{Name := RetConfig}}} = RawConf, - RetConfig. - make_bridge(Config) -> - Type = ?BRIDGE_TYPE, - Name = ?BRIDGE_NAME, - BridgeConfig = bridge_async_config(Config#{ - name => Name, - type => Type - }), - {ok, _} = emqx_bridge:create( - Type, - Name, - BridgeConfig - ), - emqx_bridge_resource:bridge_id(Type, Name). - -success_http_handler() -> - success_http_handler(#{response_delay => 0}). - -success_http_handler(Opts) -> - ResponseDelay = maps:get(response_delay, Opts, 0), - TestPid = self(), - fun(Req0, State) -> - {ok, Body, Req} = cowboy_req:read_body(Req0), - Headers = cowboy_req:headers(Req), - ct:pal("http request received: ~p", [ - #{body => Body, headers => Headers, response_delay => ResponseDelay} - ]), - ResponseDelay > 0 andalso timer:sleep(ResponseDelay), - TestPid ! {http, Headers, Body}, - Rep = cowboy_req:reply( - 200, - #{<<"content-type">> => <<"text/plain">>}, - <<"hello">>, - Req - ), - {ok, Rep, State} - end. + emqx_bridge_http_test_lib:make_bridge(Config). not_found_http_handler() -> TestPid = self(), @@ -452,6 +337,103 @@ t_send_async_connection_timeout(Config) -> receive_request_notifications(MessageIDs, ResponseDelayMS, []), ok. +t_send_get_trace_messages(Config) -> + ResponseDelayMS = ?config(response_delay_ms, Config), + #{port := Port, path := Path} = ?config(http_server, Config), + BridgeID = make_bridge(#{ + port => Port, + path => Path, + pool_size => 1, + query_mode => "async", + connect_timeout => integer_to_list(ResponseDelayMS * 2) ++ "ms", + request_timeout => "10s", + resume_interval => "200ms", + health_check_interval => "200ms", + resource_request_ttl => "infinity" + }), + RuleTopic = iolist_to_binary([<<"my_rule_topic/">>, atom_to_binary(?FUNCTION_NAME)]), + SQL = <<"SELECT payload.id as id FROM \"", RuleTopic/binary, "\"">>, + {ok, #{<<"id">> := RuleId}} = + emqx_bridge_testlib:create_rule_and_action_http( + ?BRIDGE_TYPE, + RuleTopic, + Config, + #{sql => SQL} + ), + %% =================================== + %% Create trace for RuleId + %% =================================== + Now = erlang:system_time(second) - 10, + Start = Now, + End = Now + 60, + TraceName = atom_to_binary(?FUNCTION_NAME), + Trace = #{ + name => TraceName, + type => ruleid, + ruleid => RuleId, + start_at => Start, + end_at => End + }, + emqx_trace_SUITE:reload(), + ok = emqx_trace:clear(), + {ok, _} = emqx_trace:create(Trace), + %% =================================== + + ResourceId = emqx_bridge_resource:resource_id(BridgeID), + ?retry( + _Interval0 = 200, + _NAttempts0 = 20, + ?assertMatch({ok, connected}, emqx_resource_manager:health_check(ResourceId)) + ), + ?retry( + _Interval0 = 200, + _NAttempts0 = 20, + ?assertEqual(<<>>, read_rule_trace_file(TraceName, Now)) + ), + Msg = emqx_message:make(RuleTopic, <<"{\"id\": 1}">>), + emqx:publish(Msg), + ?retry( + _Interval = 500, + _NAttempts = 20, + ?assertMatch( + #{ + counters := #{ + 'matched' := 1, + 'actions.failed' := 0, + 'actions.failed.unknown' := 0, + 'actions.success' := 1, + 'actions.total' := 1 + } + }, + emqx_metrics_worker:get_metrics(rule_metrics, RuleId) + ) + ), + + ok = emqx_trace_handler_SUITE:filesync(TraceName, ruleid), + {ok, Bin} = file:read_file(emqx_trace:log_file(TraceName, Now)), + + ?retry( + _Interval0 = 200, + _NAttempts0 = 20, + begin + Bin = read_rule_trace_file(TraceName, Now), + ?assertNotEqual(nomatch, binary:match(Bin, [<<"rule_activated">>])), + ?assertNotEqual(nomatch, binary:match(Bin, [<<"SELECT_yielded_result">>])), + ?assertNotEqual(nomatch, binary:match(Bin, [<<"bridge_action">>])), + ?assertNotEqual(nomatch, binary:match(Bin, [<<"action_activated">>])), + ?assertNotEqual(nomatch, binary:match(Bin, [<<"successfully_rendered_request">>])), + ?assertNotEqual(nomatch, binary:match(Bin, [<<"QUERY_ASYNC">>])) + end + ), + emqx_trace:delete(TraceName), + ok. + +read_rule_trace_file(TraceName, From) -> + emqx_trace:check(), + ok = emqx_trace_handler_SUITE:filesync(TraceName, ruleid), + {ok, Bin} = file:read_file(emqx_trace:log_file(TraceName, From)), + Bin. + t_async_free_retries(Config) -> #{port := Port} = ?config(http_server, Config), _BridgeID = make_bridge(#{ @@ -518,7 +500,7 @@ t_async_common_retries(Config) -> ok. t_bad_bridge_config(_Config) -> - BridgeConfig = bridge_async_config(#{port => 12345}), + BridgeConfig = emqx_bridge_http_test_lib:bridge_async_config(#{port => 12345}), ?assertMatch( {ok, {{_, 201, _}, _Headers, #{ @@ -540,7 +522,7 @@ t_bad_bridge_config(_Config) -> t_start_stop(Config) -> #{port := Port} = ?config(http_server, Config), - BridgeConfig = bridge_async_config(#{ + BridgeConfig = emqx_bridge_http_test_lib:bridge_async_config(#{ type => ?BRIDGE_TYPE, name => ?BRIDGE_NAME, port => Port @@ -554,7 +536,7 @@ t_path_not_found(Config) -> begin #{port := Port, path := Path} = ?config(http_server, Config), MQTTTopic = <<"t/webhook">>, - BridgeConfig = bridge_async_config(#{ + BridgeConfig = emqx_bridge_http_test_lib:bridge_async_config(#{ type => ?BRIDGE_TYPE, name => ?BRIDGE_NAME, local_topic => MQTTTopic, @@ -593,7 +575,7 @@ t_too_many_requests(Config) -> begin #{port := Port, path := Path} = ?config(http_server, Config), MQTTTopic = <<"t/webhook">>, - BridgeConfig = bridge_async_config(#{ + BridgeConfig = emqx_bridge_http_test_lib:bridge_async_config(#{ type => ?BRIDGE_TYPE, name => ?BRIDGE_NAME, local_topic => MQTTTopic, @@ -633,7 +615,7 @@ t_rule_action_expired(Config) -> ?check_trace( begin RuleTopic = <<"t/webhook/rule">>, - BridgeConfig = bridge_async_config(#{ + BridgeConfig = emqx_bridge_http_test_lib:bridge_async_config(#{ type => ?BRIDGE_TYPE, name => ?BRIDGE_NAME, host => "non.existent.host", @@ -689,7 +671,7 @@ t_bridge_probes_header_atoms(Config) -> ?check_trace( begin LocalTopic = <<"t/local/topic">>, - BridgeConfig0 = bridge_async_config(#{ + BridgeConfig0 = emqx_bridge_http_test_lib:bridge_async_config(#{ type => ?BRIDGE_TYPE, name => ?BRIDGE_NAME, port => Port, diff --git a/apps/emqx_bridge_http/test/emqx_bridge_http_test_lib.erl b/apps/emqx_bridge_http/test/emqx_bridge_http_test_lib.erl new file mode 100644 index 000000000..4959a24c3 --- /dev/null +++ b/apps/emqx_bridge_http/test/emqx_bridge_http_test_lib.erl @@ -0,0 +1,161 @@ +%%-------------------------------------------------------------------- +%% Copyright (c) 2020-2024 EMQ Technologies Co., Ltd. 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. +%%-------------------------------------------------------------------- + +-module(emqx_bridge_http_test_lib). + +-export([ + bridge_type/0, + bridge_name/0, + make_bridge/1, + bridge_async_config/1, + init_http_success_server/1, + success_http_handler/0 +]). + +-define(BRIDGE_TYPE, bridge_type()). +-define(BRIDGE_NAME, bridge_name()). + +bridge_type() -> + <<"webhook">>. + +bridge_name() -> + atom_to_binary(?MODULE). + +make_bridge(Config) -> + Type = ?BRIDGE_TYPE, + Name = ?BRIDGE_NAME, + BridgeConfig = bridge_async_config(Config#{ + name => Name, + type => Type + }), + {ok, _} = emqx_bridge:create( + Type, + Name, + BridgeConfig + ), + emqx_bridge_resource:bridge_id(Type, Name). + +bridge_async_config(#{port := Port} = Config) -> + Type = maps:get(type, Config, ?BRIDGE_TYPE), + Name = maps:get(name, Config, ?BRIDGE_NAME), + Host = maps:get(host, Config, "localhost"), + Path = maps:get(path, Config, ""), + PoolSize = maps:get(pool_size, Config, 1), + QueryMode = maps:get(query_mode, Config, "async"), + ConnectTimeout = maps:get(connect_timeout, Config, "1s"), + RequestTimeout = maps:get(request_timeout, Config, "10s"), + ResumeInterval = maps:get(resume_interval, Config, "1s"), + HealthCheckInterval = maps:get(health_check_interval, Config, "200ms"), + ResourceRequestTTL = maps:get(resource_request_ttl, Config, "infinity"), + LocalTopic = + case maps:find(local_topic, Config) of + {ok, LT} -> + lists:flatten(["local_topic = \"", LT, "\""]); + error -> + "" + end, + ConfigString = io_lib:format( + "bridges.~s.~s {\n" + " url = \"http://~s:~p~s\"\n" + " connect_timeout = \"~p\"\n" + " enable = true\n" + %% local_topic + " ~s\n" + " enable_pipelining = 100\n" + " max_retries = 2\n" + " method = \"post\"\n" + " pool_size = ~p\n" + " pool_type = \"random\"\n" + " request_timeout = \"~s\"\n" + " body = \"${id}\"\n" + " resource_opts {\n" + " inflight_window = 100\n" + " health_check_interval = \"~s\"\n" + " max_buffer_bytes = \"1GB\"\n" + " query_mode = \"~s\"\n" + " request_ttl = \"~p\"\n" + " resume_interval = \"~s\"\n" + " start_after_created = \"true\"\n" + " start_timeout = \"5s\"\n" + " worker_pool_size = \"1\"\n" + " }\n" + " ssl {\n" + " enable = false\n" + " }\n" + "}\n", + [ + Type, + Name, + Host, + Port, + Path, + ConnectTimeout, + LocalTopic, + PoolSize, + RequestTimeout, + HealthCheckInterval, + QueryMode, + ResourceRequestTTL, + ResumeInterval + ] + ), + ct:pal(ConfigString), + parse_and_check(ConfigString, Type, Name). + +parse_and_check(ConfigString, BridgeType, Name) -> + {ok, RawConf} = hocon:binary(ConfigString, #{format => map}), + hocon_tconf:check_plain(emqx_bridge_schema, RawConf, #{required => false, atom_key => false}), + #{<<"bridges">> := #{BridgeType := #{Name := RetConfig}}} = RawConf, + RetConfig. + +success_http_handler() -> + success_http_handler(#{response_delay => 0}). + +success_http_handler(Opts) -> + ResponseDelay = maps:get(response_delay, Opts, 0), + TestPid = self(), + fun(Req0, State) -> + {ok, Body, Req} = cowboy_req:read_body(Req0), + Headers = cowboy_req:headers(Req), + ct:pal("http request received: ~p", [ + #{body => Body, headers => Headers, response_delay => ResponseDelay} + ]), + ResponseDelay > 0 andalso timer:sleep(ResponseDelay), + TestPid ! {http, Headers, Body}, + Rep = cowboy_req:reply( + 200, + #{<<"content-type">> => <<"text/plain">>}, + <<"hello">>, + Req + ), + {ok, Rep, State} + end. + +init_http_success_server(Config) -> + HTTPPath = <<"/path">>, + ServerSSLOpts = false, + {ok, {HTTPPort, _Pid}} = emqx_bridge_http_connector_test_server:start_link( + _Port = random, HTTPPath, ServerSSLOpts + ), + ResponseDelayMS = 500, + ok = emqx_bridge_http_connector_test_server:set_handler( + success_http_handler(#{response_delay => ResponseDelayMS}) + ), + [ + {http_server, #{port => HTTPPort, path => HTTPPath}}, + {response_delay_ms, ResponseDelayMS}, + {bridge_name, ?BRIDGE_NAME} + | Config + ]. diff --git a/apps/emqx_resource/src/emqx_resource_buffer_worker.erl b/apps/emqx_resource/src/emqx_resource_buffer_worker.erl index 37f9369ff..6dfcde88c 100644 --- a/apps/emqx_resource/src/emqx_resource_buffer_worker.erl +++ b/apps/emqx_resource/src/emqx_resource_buffer_worker.erl @@ -64,8 +64,10 @@ -define(COLLECT_REQ_LIMIT, 1000). -define(SEND_REQ(FROM, REQUEST), {'$send_req', FROM, REQUEST}). --define(QUERY(FROM, REQUEST, SENT, EXPIRE_AT), {query, FROM, REQUEST, SENT, EXPIRE_AT}). --define(SIMPLE_QUERY(FROM, REQUEST), ?QUERY(FROM, REQUEST, false, infinity)). +-define(QUERY(FROM, REQUEST, SENT, EXPIRE_AT, TRACE_CTX), + {query, FROM, REQUEST, SENT, EXPIRE_AT, TRACE_CTX} +). +-define(SIMPLE_QUERY(FROM, REQUEST, TRACE_CTX), ?QUERY(FROM, REQUEST, false, infinity, TRACE_CTX)). -define(REPLY(FROM, SENT, RESULT), {reply, FROM, SENT, RESULT}). -define(INFLIGHT_ITEM(Ref, BatchOrQuery, IsRetriable, AsyncWorkerMRef), {Ref, BatchOrQuery, IsRetriable, AsyncWorkerMRef} @@ -77,7 +79,10 @@ -type id() :: binary(). -type index() :: pos_integer(). -type expire_at() :: infinity | integer(). --type queue_query() :: ?QUERY(reply_fun(), request(), HasBeenSent :: boolean(), expire_at()). +-type trace_context() :: map() | undefined. +-type queue_query() :: ?QUERY( + reply_fun(), request(), HasBeenSent :: boolean(), expire_at(), TraceCtx :: trace_context() +). -type request() :: term(). -type request_from() :: undefined | gen_statem:from(). -type timeout_ms() :: emqx_schema:timeout_duration_ms(). @@ -154,7 +159,10 @@ simple_sync_query(Id, Request, QueryOpts0) -> emqx_resource_metrics:matched_inc(Id), Ref = make_request_ref(), ReplyTo = maps:get(reply_to, QueryOpts0, undefined), - Result = call_query(force_sync, Id, Index, Ref, ?SIMPLE_QUERY(ReplyTo, Request), QueryOpts), + TraceCtx = maps:get(trace_ctx, QueryOpts0, undefined), + Result = call_query( + force_sync, Id, Index, Ref, ?SIMPLE_QUERY(ReplyTo, Request, TraceCtx), QueryOpts + ), _ = handle_query_result(Id, Result, _HasBeenSent = false), Result. @@ -167,8 +175,9 @@ simple_async_query(Id, Request, QueryOpts0) -> emqx_resource_metrics:matched_inc(Id), Ref = make_request_ref(), ReplyTo = maps:get(reply_to, QueryOpts0, undefined), + TraceCtx = maps:get(trace_ctx, QueryOpts0, undefined), Result = call_query( - async_if_possible, Id, Index, Ref, ?SIMPLE_QUERY(ReplyTo, Request), QueryOpts + async_if_possible, Id, Index, Ref, ?SIMPLE_QUERY(ReplyTo, Request, TraceCtx), QueryOpts ), _ = handle_query_result(Id, Result, _HasBeenSent = false), Result. @@ -439,10 +448,10 @@ retry_inflight_sync(Ref, QueryOrBatch, Data0) -> Result = call_query(force_sync, Id, Index, Ref, QueryOrBatch, QueryOpts), {ShouldAck, PostFn, DeltaCounters} = case QueryOrBatch of - ?QUERY(ReplyTo, _, HasBeenSent, _ExpireAt) -> + ?QUERY(ReplyTo, _, HasBeenSent, _ExpireAt, _TraceCtx) -> Reply = ?REPLY(ReplyTo, HasBeenSent, Result), reply_caller_defer_metrics(Id, Reply, QueryOpts); - [?QUERY(_, _, _, _) | _] = Batch -> + [?QUERY(_, _, _, _, _) | _] = Batch -> batch_reply_caller_defer_metrics(Id, Result, Batch, QueryOpts) end, Data1 = aggregate_counters(Data0, DeltaCounters), @@ -501,11 +510,13 @@ collect_and_enqueue_query_requests(Request0, Data0) -> ReplyFun = maps:get(async_reply_fun, Opts, undefined), HasBeenSent = false, ExpireAt = maps:get(expire_at, Opts), - ?QUERY(ReplyFun, Req, HasBeenSent, ExpireAt); + TraceCtx = maps:get(trace_ctx, Opts, undefined), + ?QUERY(ReplyFun, Req, HasBeenSent, ExpireAt, TraceCtx); (?SEND_REQ(ReplyTo, {query, Req, Opts})) -> HasBeenSent = false, ExpireAt = maps:get(expire_at, Opts), - ?QUERY(ReplyTo, Req, HasBeenSent, ExpireAt) + TraceCtx = maps:get(trace_ctx, Opts, undefined), + ?QUERY(ReplyTo, Req, HasBeenSent, ExpireAt, TraceCtx) end, Requests ), @@ -515,7 +526,7 @@ collect_and_enqueue_query_requests(Request0, Data0) -> reply_overflown([]) -> ok; -reply_overflown([?QUERY(ReplyTo, _Req, _HasBeenSent, _ExpireAt) | More]) -> +reply_overflown([?QUERY(ReplyTo, _Req, _HasBeenSent, _ExpireAt, _TraceCtx) | More]) -> do_reply_caller(ReplyTo, {error, buffer_overflow}), reply_overflown(More). @@ -630,7 +641,7 @@ do_flush( inflight_tid := InflightTID } = Data0, %% unwrap when not batching (i.e., batch size == 1) - [?QUERY(ReplyTo, _, HasBeenSent, _ExpireAt) = Request] = Batch, + [?QUERY(ReplyTo, _, HasBeenSent, _ExpireAt, _TraceCtx) = Request] = Batch, QueryOpts = #{inflight_tid => InflightTID, simple_query => false}, Result = call_query(async_if_possible, Id, Index, Ref, Request, QueryOpts), Reply = ?REPLY(ReplyTo, HasBeenSent, Result), @@ -824,14 +835,14 @@ batch_reply_caller_defer_metrics(Id, BatchResult, Batch, QueryOpts) -> expand_batch_reply(BatchResults, Batch) when is_list(BatchResults) -> lists:map( - fun({?QUERY(FROM, _REQUEST, SENT, _EXPIRE_AT), Result}) -> + fun({?QUERY(FROM, _REQUEST, SENT, _EXPIRE_AT, _TraceCtx), Result}) -> ?REPLY(FROM, SENT, Result) end, lists:zip(Batch, BatchResults) ); expand_batch_reply(BatchResult, Batch) -> lists:map( - fun(?QUERY(FROM, _REQUEST, SENT, _EXPIRE_AT)) -> + fun(?QUERY(FROM, _REQUEST, SENT, _EXPIRE_AT, _TraceCtx)) -> ?REPLY(FROM, SENT, BatchResult) end, Batch @@ -880,7 +891,7 @@ reply_dropped(_ReplyTo, _Result) -> -spec batch_reply_dropped([queue_query()], {error, late_reply | request_expired}) -> ok. batch_reply_dropped(Batch, Result) -> lists:foreach( - fun(?QUERY(ReplyTo, _CoreReq, _HasBeenSent, _ExpireAt)) -> + fun(?QUERY(ReplyTo, _CoreReq, _HasBeenSent, _ExpireAt, _TraceCtx)) -> reply_dropped(ReplyTo, Result) end, Batch @@ -1093,11 +1104,80 @@ call_query(QM, Id, Index, Ref, Query, QueryOpts) -> {ok, _Group, #{status := ?status_connecting, error := unhealthy_target}} -> {error, {unrecoverable_error, unhealthy_target}}; {ok, _Group, Resource} -> - do_call_query(QM, Id, Index, Ref, Query, QueryOpts, Resource); + set_rule_id_trace_meta_data(Query), + QueryResult = do_call_query(QM, Id, Index, Ref, Query, QueryOpts, Resource), + %% do_call_query does not throw an exception as the call to the + %% resource is wrapped in a try catch expression so we will always + %% unset the trace meta data + unset_rule_id_trace_meta_data(), + QueryResult; {error, not_found} -> ?RESOURCE_ERROR(not_found, "resource not found") end. +set_rule_id_trace_meta_data(Requests) when is_list(Requests) -> + %% Get the rule ids from requests + RuleIDs = lists:foldl(fun collect_rule_id/2, #{}, Requests), + ClientIDs = lists:foldl(fun collect_client_id/2, #{}, Requests), + StopAfterRender = lists:foldl(fun collect_stop_after_render/2, no_info, Requests), + StopAfterRenderVal = + case StopAfterRender of + only_true -> + logger:update_process_metadata(#{stop_action_after_render => false}), + true; + only_false -> + false; + mixed -> + ?TRACE( + warning, + "ACTION", + "mixed_stop_action_after_render_batch " + "(A batch will be sent to connector where some but " + "not all requests has stop_action_after_render set. " + "The batch will get assigned " + "stop_action_after_render = false)", + #{rule_ids => RuleIDs, client_ids => ClientIDs} + ), + false + end, + logger:update_process_metadata(#{ + rule_ids => RuleIDs, client_ids => ClientIDs, stop_action_after_render => StopAfterRenderVal + }), + ok; +set_rule_id_trace_meta_data(Request) -> + set_rule_id_trace_meta_data([Request]), + ok. + +collect_rule_id(?QUERY(_, _, _, _, #{rule_id := RuleId}), Acc) -> + Acc#{RuleId => true}; +collect_rule_id(?QUERY(_, _, _, _, _), Acc) -> + Acc. + +collect_client_id(?QUERY(_, _, _, _, #{clientid := ClientId}), Acc) -> + Acc#{ClientId => true}; +collect_client_id(?QUERY(_, _, _, _, _), Acc) -> + Acc. + +collect_stop_after_render(?QUERY(_, _, _, _, #{stop_action_after_render := true}), no_info) -> + only_true; +collect_stop_after_render(?QUERY(_, _, _, _, #{stop_action_after_render := true}), only_true) -> + only_true; +collect_stop_after_render(?QUERY(_, _, _, _, #{stop_action_after_render := true}), only_false) -> + mixed; +collect_stop_after_render(?QUERY(_, _, _, _, _), no_info) -> + only_false; +collect_stop_after_render(?QUERY(_, _, _, _, _), only_true) -> + mixed; +collect_stop_after_render(?QUERY(_, _, _, _, _), only_false) -> + only_false; +collect_stop_after_render(?QUERY(_, _, _, _, _), mixed) -> + mixed. + +unset_rule_id_trace_meta_data() -> + logger:update_process_metadata(#{ + rule_ids => #{}, client_ids => #{}, stop_action_after_render => false + }). + %% action:kafka_producer:myproducer1:connector:kafka_producer:mykakfaclient1 extract_connector_id(Id) when is_binary(Id) -> case binary:split(Id, <<":">>, [global]) of @@ -1208,7 +1288,15 @@ do_call_query(_QM, _Id, _Index, _Ref, _Query, _QueryOpts, _Data) -> ). apply_query_fun( - sync, Mod, Id, _Index, _Ref, ?QUERY(_, Request, _, _) = _Query, ResSt, Channels, QueryOpts + sync, + Mod, + Id, + _Index, + _Ref, + ?QUERY(_, Request, _, _, _TraceCtx) = _Query, + ResSt, + Channels, + QueryOpts ) -> ?tp(call_query, #{id => Id, mod => Mod, query => _Query, res_st => ResSt, call_mode => sync}), maybe_reply_to( @@ -1227,7 +1315,15 @@ apply_query_fun( QueryOpts ); apply_query_fun( - async, Mod, Id, Index, Ref, ?QUERY(_, Request, _, _) = Query, ResSt, Channels, QueryOpts + async, + Mod, + Id, + Index, + Ref, + ?QUERY(_, Request, _, _, _TraceCtx) = Query, + ResSt, + Channels, + QueryOpts ) -> ?tp(call_query_async, #{ id => Id, mod => Mod, query => Query, res_st => ResSt, call_mode => async @@ -1268,7 +1364,7 @@ apply_query_fun( Id, _Index, _Ref, - [?QUERY(_, FirstRequest, _, _) | _] = Batch, + [?QUERY(_, FirstRequest, _, _, _) | _] = Batch, ResSt, Channels, QueryOpts @@ -1276,7 +1372,9 @@ apply_query_fun( ?tp(call_batch_query, #{ id => Id, mod => Mod, batch => Batch, res_st => ResSt, call_mode => sync }), - Requests = lists:map(fun(?QUERY(_ReplyTo, Request, _, _ExpireAt)) -> Request end, Batch), + Requests = lists:map( + fun(?QUERY(_ReplyTo, Request, _, _ExpireAt, _TraceCtx)) -> Request end, Batch + ), maybe_reply_to( ?APPLY_RESOURCE( call_batch_query, @@ -1298,7 +1396,7 @@ apply_query_fun( Id, Index, Ref, - [?QUERY(_, FirstRequest, _, _) | _] = Batch, + [?QUERY(_, FirstRequest, _, _, _) | _] = Batch, ResSt, Channels, QueryOpts @@ -1321,7 +1419,7 @@ apply_query_fun( min_batch => minimize(Batch) }, Requests = lists:map( - fun(?QUERY(_ReplyTo, Request, _, _ExpireAt)) -> Request end, Batch + fun(?QUERY(_ReplyTo, Request, _, _ExpireAt, _TraceCtx)) -> Request end, Batch ), IsRetriable = false, AsyncWorkerMRef = undefined, @@ -1367,7 +1465,7 @@ handle_async_reply1( inflight_tid := InflightTID, resource_id := Id, buffer_worker := BufferWorkerPid, - min_query := ?QUERY(ReplyTo, _, _, ExpireAt) = _Query + min_query := ?QUERY(ReplyTo, _, _, ExpireAt, _TraceCtx) = _Query } = ReplyContext, Result ) -> @@ -1399,7 +1497,7 @@ do_handle_async_reply( request_ref := Ref, buffer_worker := BufferWorkerPid, inflight_tid := InflightTID, - min_query := ?QUERY(ReplyTo, _, Sent, _ExpireAt) = _Query + min_query := ?QUERY(ReplyTo, _, Sent, _ExpireAt, _TraceCtx) = _Query }, Result ) -> @@ -1486,13 +1584,13 @@ handle_async_batch_reply2([Inflight], ReplyContext, Results0, Now) -> %% So we just take the original flag from the ReplyContext batch %% and put it back to the batch found in inflight table %% which must have already been set to `false` - [?QUERY(_ReplyTo, _, HasBeenSent, _ExpireAt) | _] = Batch, + [?QUERY(_ReplyTo, _, HasBeenSent, _ExpireAt, _TraceCtx) | _] = Batch, {RealNotExpired0, RealExpired, Results} = sieve_expired_requests_with_results(RealBatch, Now, Results0), RealNotExpired = lists:map( - fun(?QUERY(ReplyTo, CoreReq, _HasBeenSent, ExpireAt)) -> - ?QUERY(ReplyTo, CoreReq, HasBeenSent, ExpireAt) + fun(?QUERY(ReplyTo, CoreReq, _HasBeenSent, ExpireAt, TraceCtx)) -> + ?QUERY(ReplyTo, CoreReq, HasBeenSent, ExpireAt, TraceCtx) end, RealNotExpired0 ), @@ -1678,7 +1776,10 @@ inflight_get_first_retriable(InflightTID, Now) -> case ets:select(InflightTID, MatchSpec, _Limit = 1) of '$end_of_table' -> none; - {[{Ref, Query = ?QUERY(_ReplyTo, _CoreReq, _HasBeenSent, ExpireAt)}], _Continuation} -> + { + [{Ref, Query = ?QUERY(_ReplyTo, _CoreReq, _HasBeenSent, ExpireAt, _TraceCtx)}], + _Continuation + } -> case is_expired(ExpireAt, Now) of true -> {expired, Ref, [Query]}; @@ -1714,7 +1815,7 @@ inflight_append(undefined, _InflightItem) -> ok; inflight_append( InflightTID, - ?INFLIGHT_ITEM(Ref, [?QUERY(_, _, _, _) | _] = Batch0, IsRetriable, AsyncWorkerMRef) + ?INFLIGHT_ITEM(Ref, [?QUERY(_, _, _, _, _) | _] = Batch0, IsRetriable, AsyncWorkerMRef) ) -> Batch = mark_as_sent(Batch0), InflightItem = ?INFLIGHT_ITEM(Ref, Batch, IsRetriable, AsyncWorkerMRef), @@ -1726,7 +1827,10 @@ inflight_append( inflight_append( InflightTID, ?INFLIGHT_ITEM( - Ref, ?QUERY(_ReplyTo, _Req, _HasBeenSent, _ExpireAt) = Query0, IsRetriable, AsyncWorkerMRef + Ref, + ?QUERY(_ReplyTo, _Req, _HasBeenSent, _ExpireAt, _TraceCtx) = Query0, + IsRetriable, + AsyncWorkerMRef ) ) -> Query = mark_as_sent(Query0), @@ -1790,9 +1894,13 @@ ack_inflight(undefined, _Ref, _BufferWorkerPid) -> ack_inflight(InflightTID, Ref, BufferWorkerPid) -> {Count, Removed} = case ets:take(InflightTID, Ref) of - [?INFLIGHT_ITEM(Ref, ?QUERY(_, _, _, _), _IsRetriable, _AsyncWorkerMRef)] -> + [?INFLIGHT_ITEM(Ref, ?QUERY(_, _, _, _, _), _IsRetriable, _AsyncWorkerMRef)] -> {1, true}; - [?INFLIGHT_ITEM(Ref, [?QUERY(_, _, _, _) | _] = Batch, _IsRetriable, _AsyncWorkerMRef)] -> + [ + ?INFLIGHT_ITEM( + Ref, [?QUERY(_, _, _, _, _) | _] = Batch, _IsRetriable, _AsyncWorkerMRef + ) + ] -> {length(Batch), true}; [] -> {0, false} @@ -1942,9 +2050,9 @@ do_collect_requests(Acc, Count, Limit) -> mark_as_sent(Batch) when is_list(Batch) -> lists:map(fun mark_as_sent/1, Batch); -mark_as_sent(?QUERY(ReplyTo, Req, _HasBeenSent, ExpireAt)) -> +mark_as_sent(?QUERY(ReplyTo, Req, _HasBeenSent, ExpireAt, TraceCtx)) -> HasBeenSent = true, - ?QUERY(ReplyTo, Req, HasBeenSent, ExpireAt). + ?QUERY(ReplyTo, Req, HasBeenSent, ExpireAt, TraceCtx). is_unrecoverable_error({error, {unrecoverable_error, _}}) -> true; @@ -1967,7 +2075,7 @@ is_async_return(_) -> sieve_expired_requests(Batch, Now) -> lists:partition( - fun(?QUERY(_ReplyTo, _CoreReq, _HasBeenSent, ExpireAt)) -> + fun(?QUERY(_ReplyTo, _CoreReq, _HasBeenSent, ExpireAt, _TraceCtx)) -> not is_expired(ExpireAt, Now) end, Batch @@ -1978,7 +2086,7 @@ sieve_expired_requests_with_results(Batch, Now, Results) when is_list(Results) - {RevNotExpiredBatch, RevNotExpiredResults, ExpiredBatch} = lists:foldl( fun( - {?QUERY(_ReplyTo, _CoreReq, _HasBeenSent, ExpireAt) = Query, Result}, + {?QUERY(_ReplyTo, _CoreReq, _HasBeenSent, ExpireAt, _TraceCtx) = Query, Result}, {NotExpAcc, ResAcc, ExpAcc} ) -> case not is_expired(ExpireAt, Now) of @@ -2026,15 +2134,16 @@ ensure_expire_at(#{timeout := TimeoutMS} = Opts) -> Opts#{expire_at => ExpireAt}. %% no need to keep the request for async reply handler -minimize(?QUERY(_, _, _, _) = Q) -> +minimize(?QUERY(_, _, _, _, _) = Q) -> do_minimize(Q); minimize(L) when is_list(L) -> lists:map(fun do_minimize/1, L). -ifdef(TEST). -do_minimize(?QUERY(_ReplyTo, _Req, _Sent, _ExpireAt) = Query) -> Query. +do_minimize(?QUERY(_ReplyTo, _Req, _Sent, _ExpireAt, _TraceCtx) = Query) -> Query. -else. -do_minimize(?QUERY(ReplyTo, _Req, Sent, ExpireAt)) -> ?QUERY(ReplyTo, [], Sent, ExpireAt). +do_minimize(?QUERY(ReplyTo, _Req, Sent, ExpireAt, TraceCtx)) -> + ?QUERY(ReplyTo, [], Sent, ExpireAt, TraceCtx). -endif. %% To avoid message loss due to misconfigurations, we adjust diff --git a/apps/emqx_rule_engine/src/emqx_rule_api_schema.erl b/apps/emqx_rule_engine/src/emqx_rule_api_schema.erl index d82951124..a24ef5bd0 100644 --- a/apps/emqx_rule_engine/src/emqx_rule_api_schema.erl +++ b/apps/emqx_rule_engine/src/emqx_rule_api_schema.erl @@ -54,7 +54,8 @@ roots() -> {"rule_creation", sc(ref("rule_creation"), #{desc => ?DESC("root_rule_creation")})}, {"rule_info", sc(ref("rule_info"), #{desc => ?DESC("root_rule_info")})}, {"rule_events", sc(ref("rule_events"), #{desc => ?DESC("root_rule_events")})}, - {"rule_test", sc(ref("rule_test"), #{desc => ?DESC("root_rule_test")})} + {"rule_test", sc(ref("rule_test"), #{desc => ?DESC("root_rule_test")})}, + {"rule_apply_test", sc(ref("rule_apply_test"), #{desc => ?DESC("root_apply_rule_test")})} ]. fields("rule_engine") -> @@ -124,6 +125,48 @@ fields("rule_test") -> )}, {"sql", sc(binary(), #{desc => ?DESC("test_sql"), required => true})} ]; +fields("rule_apply_test") -> + [ + {"context", + sc( + hoconsc:union([ + ref("ctx_pub"), + ref("ctx_sub"), + ref("ctx_unsub"), + ref("ctx_delivered"), + ref("ctx_acked"), + ref("ctx_dropped"), + ref("ctx_connected"), + ref("ctx_disconnected"), + ref("ctx_connack"), + ref("ctx_check_authz_complete"), + ref("ctx_bridge_mqtt"), + ref("ctx_delivery_dropped") + ]), + #{ + desc => ?DESC("test_context"), + default => #{} + } + )}, + {"environment", + sc( + typerefl:map(), + #{ + desc => + ?DESC("test_rule_environment"), + default => #{} + } + )}, + {"stop_action_after_template_render", + sc( + typerefl:boolean(), + #{ + desc => + ?DESC("stop_action_after_template_render"), + default => false + } + )} + ]; fields("metrics") -> [ {"matched", diff --git a/apps/emqx_rule_engine/src/emqx_rule_engine_api.erl b/apps/emqx_rule_engine/src/emqx_rule_engine_api.erl index 354e40c5f..c0514b82b 100644 --- a/apps/emqx_rule_engine/src/emqx_rule_engine_api.erl +++ b/apps/emqx_rule_engine/src/emqx_rule_engine_api.erl @@ -37,6 +37,7 @@ '/rule_test'/2, '/rules'/2, '/rules/:id'/2, + '/rules/:id/test'/2, '/rules/:id/metrics'/2, '/rules/:id/metrics/reset'/2 ]). @@ -145,6 +146,7 @@ paths() -> "/rule_test", "/rules", "/rules/:id", + "/rules/:id/test", "/rules/:id/metrics", "/rules/:id/metrics/reset" ]. @@ -161,6 +163,9 @@ rule_creation_schema() -> rule_test_schema() -> ref(emqx_rule_api_schema, "rule_test"). +rule_apply_test_schema() -> + ref(emqx_rule_api_schema, "rule_apply_test"). + rule_info_schema() -> ref(emqx_rule_api_schema, "rule_info"). @@ -258,6 +263,21 @@ schema("/rules/:id") -> } } }; +schema("/rules/:id/test") -> + #{ + 'operationId' => '/rules/:id/test', + post => #{ + tags => [<<"rules">>], + description => ?DESC("api8"), + summary => <<"Apply a rule with the given message and environment">>, + 'requestBody' => rule_apply_test_schema(), + responses => #{ + 400 => error_schema('BAD_REQUEST', "Invalid Parameters"), + 412 => error_schema('NOT_MATCH', "SQL Not Match"), + 200 => <<"Rule Applied">> + } + } + }; schema("/rules/:id/metrics") -> #{ 'operationId' => '/rules/:id/metrics', @@ -392,6 +412,24 @@ param_path_id() -> end ). +'/rules/:id/test'(post, #{body := Params, bindings := #{id := RuleId}}) -> + ?CHECK_PARAMS( + Params, + rule_apply_test, + begin + case emqx_rule_sqltester:apply_rule(RuleId, CheckedParams) of + {ok, Result} -> + {200, Result}; + {error, {parse_error, Reason}} -> + {400, #{code => 'BAD_REQUEST', message => err_msg(Reason)}}; + {error, nomatch} -> + {412, #{code => 'NOT_MATCH', message => <<"SQL Not Match">>}}; + {error, Reason} -> + {400, #{code => 'BAD_REQUEST', message => err_msg(Reason)}} + end + end + ). + '/rules/:id'(get, #{bindings := #{id := Id}}) -> case emqx_rule_engine:get_rule(Id) of {ok, Rule} -> diff --git a/apps/emqx_rule_engine/src/emqx_rule_runtime.erl b/apps/emqx_rule_engine/src/emqx_rule_runtime.erl index 9a307e2c3..1204ea5e5 100644 --- a/apps/emqx_rule_engine/src/emqx_rule_runtime.erl +++ b/apps/emqx_rule_engine/src/emqx_rule_runtime.erl @@ -69,9 +69,14 @@ apply_rule_discard_result(Rule, Columns, Envs) -> ok. apply_rule(Rule = #{id := RuleID}, Columns, Envs) -> - ?TRACE("APPLY_RULE", "rule_activated", #{ - ruleid => RuleID, input => Columns, environment => Envs - }), + set_process_trace_metadata(RuleID, Columns), + trace_rule_sql( + "rule_activated", + #{ + input => Columns, environment => Envs + }, + debug + ), ok = emqx_metrics_worker:inc(rule_metrics, RuleID, 'matched'), clear_rule_payload(), try @@ -80,48 +85,80 @@ apply_rule(Rule = #{id := RuleID}, Columns, Envs) -> %% ignore the errors if select or match failed _:Reason = {select_and_transform_error, Error} -> ok = emqx_metrics_worker:inc(rule_metrics, RuleID, 'failed.exception'), - ?SLOG(warning, #{ - msg => "SELECT_clause_exception", - rule_id => RuleID, - reason => Error - }), + trace_rule_sql( + "SELECT_clause_exception", + #{ + reason => Error + }, + warning + ), {error, Reason}; _:Reason = {match_conditions_error, Error} -> ok = emqx_metrics_worker:inc(rule_metrics, RuleID, 'failed.exception'), - ?SLOG(warning, #{ - msg => "WHERE_clause_exception", - rule_id => RuleID, - reason => Error - }), + trace_rule_sql( + "WHERE_clause_exception", + #{ + reason => Error + }, + warning + ), {error, Reason}; _:Reason = {select_and_collect_error, Error} -> ok = emqx_metrics_worker:inc(rule_metrics, RuleID, 'failed.exception'), - ?SLOG(warning, #{ - msg => "FOREACH_clause_exception", - rule_id => RuleID, - reason => Error - }), + trace_rule_sql( + "FOREACH_clause_exception", + #{ + reason => Error + }, + warning + ), {error, Reason}; _:Reason = {match_incase_error, Error} -> ok = emqx_metrics_worker:inc(rule_metrics, RuleID, 'failed.exception'), - ?SLOG(warning, #{ - msg => "INCASE_clause_exception", - rule_id => RuleID, - reason => Error - }), + trace_rule_sql( + "INCASE_clause_exception", + #{ + reason => Error + }, + warning + ), {error, Reason}; Class:Error:StkTrace -> ok = emqx_metrics_worker:inc(rule_metrics, RuleID, 'failed.exception'), - ?SLOG(error, #{ - msg => "apply_rule_failed", - rule_id => RuleID, - exception => Class, - reason => Error, - stacktrace => StkTrace - }), + trace_rule_sql( + "apply_rule_failed", + #{ + exception => Class, + reason => Error, + stacktrace => StkTrace + }, + warning + ), {error, {Error, StkTrace}} + after + reset_process_trace_metadata(Columns) end. +set_process_trace_metadata(RuleID, #{clientid := ClientID}) -> + logger:update_process_metadata(#{ + rule_id => RuleID, + clientid => ClientID + }); +set_process_trace_metadata(RuleID, _) -> + logger:update_process_metadata(#{ + rule_id => RuleID + }). + +reset_process_trace_metadata(#{clientid := _ClientID}) -> + Meta = logger:get_process_metadata(), + Meta1 = maps:remove(clientid, Meta), + Meta2 = maps:remove(rule_id, Meta1), + logger:set_process_metadata(Meta2); +reset_process_trace_metadata(_) -> + Meta = logger:get_process_metadata(), + Meta1 = maps:remove(rule_id, Meta), + logger:set_process_metadata(Meta1). + do_apply_rule( #{ id := RuleId, @@ -139,13 +176,18 @@ do_apply_rule( {ok, ColumnsAndSelected, FinalCollection} -> case FinalCollection of [] -> + trace_rule_sql("FOREACH_yielded_no_result"), ok = emqx_metrics_worker:inc(rule_metrics, RuleId, 'failed.no_result'); _ -> + trace_rule_sql( + "FOREACH_yielded_result", #{result => FinalCollection}, debug + ), ok = emqx_metrics_worker:inc(rule_metrics, RuleId, 'passed') end, NewEnvs = maps:merge(ColumnsAndSelected, Envs), {ok, [handle_action_list(RuleId, Actions, Coll, NewEnvs) || Coll <- FinalCollection]}; false -> + trace_rule_sql("FOREACH_yielded_no_result_no_match"), ok = emqx_metrics_worker:inc(rule_metrics, RuleId, 'failed.no_result'), {error, nomatch} end; @@ -162,9 +204,11 @@ do_apply_rule( ) -> case evaluate_select(Fields, Columns, Conditions) of {ok, Selected} -> + trace_rule_sql("SELECT_yielded_result", #{result => Selected}, debug), ok = emqx_metrics_worker:inc(rule_metrics, RuleId, 'passed'), {ok, handle_action_list(RuleId, Actions, Selected, maps:merge(Columns, Envs))}; false -> + trace_rule_sql("SELECT_yielded_no_result_no_match"), ok = emqx_metrics_worker:inc(rule_metrics, RuleId, 'failed.no_result'), {error, nomatch} end. @@ -348,37 +392,42 @@ handle_action_list(RuleId, Actions, Selected, Envs) -> handle_action(RuleId, ActId, Selected, Envs) -> ok = emqx_metrics_worker:inc(rule_metrics, RuleId, 'actions.total'), + trace_action(ActId, "activating_action"), try - do_handle_action(RuleId, ActId, Selected, Envs) + Result = do_handle_action(RuleId, ActId, Selected, Envs), + trace_action(ActId, "action_activated", #{result => Result}), + Result catch throw:out_of_service -> ok = emqx_metrics_worker:inc(rule_metrics, RuleId, 'actions.failed'), ok = emqx_metrics_worker:inc( rule_metrics, RuleId, 'actions.failed.out_of_service' ), - ?SLOG(warning, #{msg => "out_of_service", action => ActId}); + trace_action(ActId, "out_of_service", #{}, warning); Err:Reason:ST -> ok = emqx_metrics_worker:inc(rule_metrics, RuleId, 'actions.failed'), ok = emqx_metrics_worker:inc(rule_metrics, RuleId, 'actions.failed.unknown'), - ?SLOG(error, #{ - msg => "action_failed", - action => ActId, - exception => Err, - reason => Reason, - stacktrace => ST - }) + trace_action( + ActId, + "action_failed", + #{ + exception => Err, + reason => Reason, + stacktrace => ST + }, + error + ) end. -define(IS_RES_DOWN(R), R == stopped; R == not_connected; R == not_found; R == unhealthy_target). -do_handle_action(RuleId, {bridge, BridgeType, BridgeName, ResId}, Selected, _Envs) -> - ?TRACE( - "BRIDGE", - "bridge_action", - #{bridge_id => emqx_bridge_resource:bridge_id(BridgeType, BridgeName)} - ), - ReplyTo = {fun ?MODULE:inc_action_metrics/2, [RuleId], #{reply_dropped => true}}, +do_handle_action(RuleId, {bridge, BridgeType, BridgeName, ResId} = Action, Selected, _Envs) -> + trace_action_bridge("BRIDGE", Action, "bridge_action", #{}, debug), + TraceCtx = do_handle_action_get_trace_context(Action), + ReplyTo = {fun ?MODULE:inc_action_metrics/2, [TraceCtx], #{reply_dropped => true}}, case - emqx_bridge:send_message(BridgeType, BridgeName, ResId, Selected, #{reply_to => ReplyTo}) + emqx_bridge:send_message(BridgeType, BridgeName, ResId, Selected, #{ + reply_to => ReplyTo, trace_ctx => maps:remove(action_id, TraceCtx) + }) of {error, Reason} when Reason == bridge_not_found; Reason == bridge_stopped -> throw(out_of_service); @@ -388,23 +437,20 @@ do_handle_action(RuleId, {bridge, BridgeType, BridgeName, ResId}, Selected, _Env Result end; do_handle_action( - RuleId, - {bridge_v2, BridgeType, BridgeName}, + _RuleId, + {bridge_v2, BridgeType, BridgeName} = Action, Selected, _Envs ) -> - ?TRACE( - "BRIDGE", - "bridge_action", - #{bridge_id => {bridge_v2, BridgeType, BridgeName}} - ), - ReplyTo = {fun ?MODULE:inc_action_metrics/2, [RuleId], #{reply_dropped => true}}, + trace_action_bridge("BRIDGE", Action, "bridge_action", #{}, debug), + TraceCtx = do_handle_action_get_trace_context(Action), + ReplyTo = {fun ?MODULE:inc_action_metrics/2, [TraceCtx], #{reply_dropped => true}}, case emqx_bridge_v2:send_message( BridgeType, BridgeName, Selected, - #{reply_to => ReplyTo} + #{reply_to => ReplyTo, trace_ctx => maps:remove(action_id, TraceCtx)} ) of {error, Reason} when Reason == bridge_not_found; Reason == bridge_stopped -> @@ -414,13 +460,43 @@ do_handle_action( Result -> Result end; -do_handle_action(RuleId, #{mod := Mod, func := Func} = Action, Selected, Envs) -> +do_handle_action(_RuleId, #{mod := Mod, func := Func} = Action, Selected, Envs) -> + trace_action(Action, "call_action_function"), %% the function can also throw 'out_of_service' Args = maps:get(args, Action, []), Result = Mod:Func(Selected, Envs, Args), - inc_action_metrics(RuleId, Result), + TraceCtx = do_handle_action_get_trace_context(Action), + inc_action_metrics(TraceCtx, Result), + trace_action(Action, "call_action_function_result", #{result => Result}, debug), Result. +do_handle_action_get_trace_context(Action) -> + case logger:get_process_metadata() of + #{ + rule_id := RuleID, + clientid := ClientID + } -> + #{ + rule_id => RuleID, + clientid => ClientID, + action_id => Action + }; + #{ + rule_id := RuleID + } -> + #{ + rule_id => RuleID, + action_id => Action + } + end. + +action_info({bridge, BridgeType, BridgeName, _ResId}) -> + #{type => BridgeType, name => BridgeName}; +action_info({bridge_v2, BridgeType, BridgeName}) -> + #{type => BridgeType, name => BridgeName}; +action_info(FuncInfoMap) -> + FuncInfoMap. + eval({Op, _} = Exp, Context) when is_list(Context) andalso (Op == path orelse Op == var) -> case Context of [Columns] -> @@ -599,21 +675,31 @@ nested_put(Alias, Val, Columns0) -> Columns = ensure_decoded_payload(Alias, Columns0), emqx_rule_maps:nested_put(Alias, Val, Columns). -inc_action_metrics(RuleId, Result) -> - _ = do_inc_action_metrics(RuleId, Result), +inc_action_metrics(TraceCtx, Result) -> + _ = do_inc_action_metrics(TraceCtx, Result), Result. -do_inc_action_metrics(RuleId, {error, {recoverable_error, _}}) -> +do_inc_action_metrics( + #{rule_id := RuleId, action_id := ActId} = TraceContext, + {error, {recoverable_error, _}} +) -> + trace_action(ActId, "out_of_service", TraceContext), emqx_metrics_worker:inc(rule_metrics, RuleId, 'actions.failed.out_of_service'); -do_inc_action_metrics(RuleId, {error, {unrecoverable_error, _}}) -> +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)), emqx_metrics_worker:inc(rule_metrics, RuleId, 'actions.failed'), emqx_metrics_worker:inc(rule_metrics, RuleId, 'actions.failed.unknown'); -do_inc_action_metrics(RuleId, R) -> +do_inc_action_metrics(#{rule_id := RuleId, action_id := ActId} = TraceContext, R) -> case is_ok_result(R) of false -> + trace_action(ActId, "action_failed", maps:merge(#{reason => R}, TraceContext)), 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)), emqx_metrics_worker:inc(rule_metrics, RuleId, 'actions.success') end. @@ -661,3 +747,39 @@ parse_function_name(Module, Name) when is_binary(Name) -> end; parse_function_name(_Module, Name) when is_atom(Name) -> Name. + +trace_action(ActId, Message) -> + trace_action_bridge("ACTION", ActId, Message). + +trace_action(ActId, Message, Extra) -> + trace_action_bridge("ACTION", ActId, Message, Extra, debug). + +trace_action(ActId, Message, Extra, Level) -> + trace_action_bridge("ACTION", ActId, Message, Extra, Level). + +trace_action_bridge(Tag, ActId, Message) -> + trace_action_bridge(Tag, ActId, Message, #{}, debug). + +trace_action_bridge(Tag, ActId, Message, Extra, Level) -> + ?TRACE( + Level, + Tag, + Message, + maps:merge( + #{ + action_info => action_info(ActId) + }, + Extra + ) + ). + +trace_rule_sql(Message) -> + trace_rule_sql(Message, #{}, debug). + +trace_rule_sql(Message, Extra, Level) -> + ?TRACE( + Level, + "RULE_SQL_EXEC", + Message, + Extra + ). diff --git a/apps/emqx_rule_engine/src/emqx_rule_sqltester.erl b/apps/emqx_rule_engine/src/emqx_rule_sqltester.erl index 8212e3385..e72b0fcd0 100644 --- a/apps/emqx_rule_engine/src/emqx_rule_sqltester.erl +++ b/apps/emqx_rule_engine/src/emqx_rule_sqltester.erl @@ -20,9 +20,77 @@ test/1, get_selected_data/3, %% Some SQL functions return different results in the test environment - is_test_runtime_env/0 + is_test_runtime_env/0, + apply_rule/2 ]). +apply_rule( + RuleId, + #{ + context := Context, + environment := Env, + stop_action_after_template_render := StopAfterRender + } +) -> + {ok, Rule} = emqx_rule_engine:get_rule(RuleId), + InTopic = get_in_topic(Context), + EventTopics = maps:get(from, Rule, []), + case lists:all(fun is_publish_topic/1, EventTopics) of + true -> + %% test if the topic matches the topic filters in the rule + case emqx_topic:match_any(InTopic, EventTopics) of + true -> do_apply_matched_rule(Rule, Context, Env, StopAfterRender); + false -> {error, nomatch} + end; + false -> + case lists:member(InTopic, EventTopics) of + true -> + %% the rule is for both publish and events, test it directly + do_apply_matched_rule(Rule, Context, Env, StopAfterRender); + false -> + {error, nomatch} + end + end. + +do_apply_matched_rule(Rule, Context, Env, StopAfterRender) -> + update_process_trace_metadata(StopAfterRender), + Env1 = + case Env of + M when map_size(M) =:= 0 -> + %% Use the default environment if no environment is provided + default_apply_rule_environment(); + _ -> + Env + end, + ApplyRuleRes = emqx_rule_runtime:apply_rule(Rule, Context, Env1), + reset_trace_process_metadata(StopAfterRender), + ApplyRuleRes. + +update_process_trace_metadata(true = _StopAfterRender) -> + logger:update_process_trace_metadata(#{ + stop_action_after_render => true + }); +update_process_trace_metadata(false = _StopAfterRender) -> + ok. + +reset_trace_process_metadata(true = _StopAfterRender) -> + Meta = logger:get_process_metadata(), + NewMeta = maps:remove(stop_action_after_render, Meta), + logger:set_process_metadata(NewMeta); +reset_trace_process_metadata(false = _StopAfterRender) -> + ok. + +default_apply_rule_environment() -> + #{ + headers => #{ + protocol => mqtt, + username => undefined, + peerhost => {127, 0, 0, 1}, + proto_ver => 5, + properties => #{} + } + }. + -spec test(#{sql := binary(), context := map()}) -> {ok, map() | list()} | {error, term()}. test(#{sql := Sql, context := Context}) -> case emqx_rule_sqlparser:parse(Sql) of 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 new file mode 100644 index 000000000..d9d15dba0 --- /dev/null +++ b/apps/emqx_rule_engine/test/emqx_rule_engine_api_rule_apply_SUITE.erl @@ -0,0 +1,451 @@ +%%-------------------------------------------------------------------- +%% Copyright (c) 2022-2024 EMQ Technologies Co., Ltd. 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. +%%-------------------------------------------------------------------- + +-module(emqx_rule_engine_api_rule_apply_SUITE). + +-compile(nowarn_export_all). +-compile(export_all). + +-include_lib("eunit/include/eunit.hrl"). +-include_lib("common_test/include/ct.hrl"). +-include_lib("snabbkaffe/include/snabbkaffe.hrl"). + +-define(CONF_DEFAULT, <<"rule_engine {rules {}}">>). + +all() -> + emqx_common_test_helpers:all(?MODULE). + +init_per_suite(Config) -> + application:load(emqx_conf), + % ok = emqx_common_test_helpers:load_config(emqx_rule_engine_schema, ?CONF_DEFAULT), + % ok = emqx_common_test_helpers:start_apps([emqx_conf, emqx, emqx_rule_engine, emqx_bridge, emqx_bridge_http]), + + Apps = emqx_cth_suite:start( + [ + emqx, + emqx_conf, + emqx_connector, + emqx_bridge_http, + emqx_bridge, + emqx_rule_engine + ], + #{work_dir => emqx_cth_suite:work_dir(Config)} + ), + emqx_mgmt_api_test_util:init_suite(), + [{apps, Apps} | Config]. + +end_per_suite(Config) -> + Apps = ?config(apps, Config), + emqx_mgmt_api_test_util:end_suite(), + ok = emqx_cth_suite:stop(Apps), + ok. + +init_per_testcase(_Case, Config) -> + emqx_bridge_http_test_lib:init_http_success_server(Config). + +end_per_testcase(_TestCase, _Config) -> + ok = emqx_bridge_http_connector_test_server:stop(), + emqx_bridge_v2_testlib:delete_all_bridges(), + emqx_bridge_v2_testlib:delete_all_connectors(), + emqx_common_test_helpers:call_janitor(), + ok. + +t_basic_apply_rule_trace_ruleid(Config) -> + basic_apply_rule_test_helper(Config, ruleid). + +t_basic_apply_rule_trace_clientid(Config) -> + basic_apply_rule_test_helper(Config, clientid). + +basic_apply_rule_test_helper(Config, TraceType) -> + HTTPServerConfig = ?config(http_server, Config), + emqx_bridge_http_test_lib:make_bridge(HTTPServerConfig), + #{status := connected} = emqx_bridge_v2:health_check( + http, emqx_bridge_http_test_lib:bridge_name() + ), + %% Create Rule + RuleTopic = iolist_to_binary([<<"my_rule_topic/">>, atom_to_binary(?FUNCTION_NAME)]), + SQL = <<"SELECT payload.id as id FROM \"", RuleTopic/binary, "\"">>, + {ok, #{<<"id">> := RuleId}} = + emqx_bridge_testlib:create_rule_and_action_http( + http, + RuleTopic, + Config, + #{sql => SQL} + ), + ClientId = <<"c_emqx">>, + %% =================================== + %% Create trace for RuleId + %% =================================== + Now = erlang:system_time(second) - 10, + Start = Now, + End = Now + 60, + TraceName = atom_to_binary(?FUNCTION_NAME), + TraceValue = + case TraceType of + ruleid -> + RuleId; + clientid -> + ClientId + end, + Trace = #{ + name => TraceName, + type => TraceType, + TraceType => TraceValue, + start_at => Start, + end_at => End + }, + emqx_trace_SUITE:reload(), + ok = emqx_trace:clear(), + {ok, _} = emqx_trace:create(Trace), + %% =================================== + Context = #{ + clientid => ClientId, + event_type => message_publish, + payload => <<"{\"msg\": \"hello\"}">>, + qos => 1, + topic => RuleTopic, + username => <<"u_emqx">> + }, + Params = #{ + % body => #{ + <<"context">> => Context + % } + }, + emqx_trace:check(), + ok = emqx_trace_handler_SUITE:filesync(TraceName, TraceType), + {ok, _} = file:read_file(emqx_trace:log_file(TraceName, Now)), + ?assertMatch({ok, _}, call_apply_rule_api(RuleId, Params)), + ?retry( + _Interval0 = 200, + _NAttempts0 = 20, + begin + Bin = read_rule_trace_file(TraceName, TraceType, Now), + ?assertNotEqual(nomatch, binary:match(Bin, [<<"rule_activated">>])), + ?assertNotEqual(nomatch, binary:match(Bin, [<<"SELECT_yielded_result">>])), + ?assertNotEqual(nomatch, binary:match(Bin, [<<"bridge_action">>])), + ?assertNotEqual(nomatch, binary:match(Bin, [<<"action_activated">>])), + ?assertNotEqual(nomatch, binary:match(Bin, [<<"successfully_rendered_request">>])), + ?assertNotEqual(nomatch, binary:match(Bin, [<<"QUERY_ASYNC">>])) + end + ), + emqx_trace:delete(TraceName), + ok. + +%% Helper Functions + +% t_ctx_pub(_) -> +% SQL = <<"SELECT payload.msg as msg, clientid, username, payload, topic, qos FROM \"t/#\"">>, +% Context = #{ +% clientid => <<"c_emqx">>, +% event_type => message_publish, +% payload => <<"{\"msg\": \"hello\"}">>, +% qos => 1, +% topic => <<"t/a">>, +% username => <<"u_emqx">> +% }, +% Expected = Context#{msg => <<"hello">>}, +% do_test(SQL, Context, Expected). + +% t_ctx_sub(_) -> +% SQL = <<"SELECT clientid, username, topic, qos FROM \"$events/session_subscribed\"">>, +% Context = #{ +% clientid => <<"c_emqx">>, +% event_type => session_subscribed, +% qos => 1, +% topic => <<"t/a">>, +% username => <<"u_emqx">> +% }, + +% do_test(SQL, Context, Context). + +% t_ctx_unsub(_) -> +% SQL = <<"SELECT clientid, username, topic, qos FROM \"$events/session_unsubscribed\"">>, +% Context = #{ +% clientid => <<"c_emqx">>, +% event_type => session_unsubscribed, +% qos => 1, +% topic => <<"t/a">>, +% username => <<"u_emqx">> +% }, +% do_test(SQL, Context, Context). + +% t_ctx_delivered(_) -> +% SQL = +% <<"SELECT from_clientid, from_username, topic, qos, node, timestamp FROM \"$events/message_delivered\"">>, +% Context = #{ +% clientid => <<"c_emqx_2">>, +% event_type => message_delivered, +% from_clientid => <<"c_emqx_1">>, +% from_username => <<"u_emqx_1">>, +% payload => <<"{\"msg\": \"hello\"}">>, +% qos => 1, +% topic => <<"t/a">>, +% username => <<"u_emqx_2">> +% }, +% Expected = check_result([from_clientid, from_username, topic, qos], [node, timestamp], Context), +% do_test(SQL, Context, Expected). + +% t_ctx_acked(_) -> +% SQL = +% <<"SELECT from_clientid, from_username, topic, qos, node, timestamp FROM \"$events/message_acked\"">>, + +% Context = #{ +% clientid => <<"c_emqx_2">>, +% event_type => message_acked, +% from_clientid => <<"c_emqx_1">>, +% from_username => <<"u_emqx_1">>, +% payload => <<"{\"msg\": \"hello\"}">>, +% qos => 1, +% topic => <<"t/a">>, +% username => <<"u_emqx_2">> +% }, + +% Expected = with_node_timestampe([from_clientid, from_username, topic, qos], Context), + +% do_test(SQL, Context, Expected). + +% t_ctx_droped(_) -> +% SQL = <<"SELECT reason, topic, qos, node, timestamp FROM \"$events/message_dropped\"">>, +% Topic = <<"t/a">>, +% QoS = 1, +% Reason = <<"no_subscribers">>, +% Context = #{ +% clientid => <<"c_emqx">>, +% event_type => message_dropped, +% payload => <<"{\"msg\": \"hello\"}">>, +% qos => QoS, +% reason => Reason, +% topic => Topic, +% username => <<"u_emqx">> +% }, + +% Expected = with_node_timestampe([reason, topic, qos], Context), +% do_test(SQL, Context, Expected). + +% t_ctx_connected(_) -> +% SQL = +% <<"SELECT clientid, username, keepalive, is_bridge FROM \"$events/client_connected\"">>, + +% Context = +% #{ +% clean_start => true, +% clientid => <<"c_emqx">>, +% event_type => client_connected, +% is_bridge => false, +% peername => <<"127.0.0.1:52918">>, +% username => <<"u_emqx">> +% }, +% Expected = check_result([clientid, username, keepalive, is_bridge], [], Context), +% do_test(SQL, Context, Expected). + +% t_ctx_disconnected(_) -> +% SQL = +% <<"SELECT clientid, username, reason, disconnected_at, node FROM \"$events/client_disconnected\"">>, + +% Context = +% #{ +% clientid => <<"c_emqx">>, +% event_type => client_disconnected, +% reason => <<"normal">>, +% username => <<"u_emqx">> +% }, +% Expected = check_result([clientid, username, reason], [disconnected_at, node], Context), +% do_test(SQL, Context, Expected). + +% t_ctx_connack(_) -> +% SQL = +% <<"SELECT clientid, username, reason_code, node FROM \"$events/client_connack\"">>, + +% Context = +% #{ +% clean_start => true, +% clientid => <<"c_emqx">>, +% event_type => client_connack, +% reason_code => <<"sucess">>, +% username => <<"u_emqx">> +% }, +% Expected = check_result([clientid, username, reason_code], [node], Context), +% do_test(SQL, Context, Expected). + +% t_ctx_check_authz_complete(_) -> +% SQL = +% << +% "SELECT clientid, username, topic, action, result,\n" +% "authz_source, node FROM \"$events/client_check_authz_complete\"" +% >>, + +% Context = +% #{ +% action => <<"publish">>, +% clientid => <<"c_emqx">>, +% event_type => client_check_authz_complete, +% result => <<"allow">>, +% topic => <<"t/1">>, +% username => <<"u_emqx">> +% }, +% Expected = check_result( +% [clientid, username, topic, action], +% [authz_source, node, result], +% Context +% ), + +% do_test(SQL, Context, Expected). + +% t_ctx_delivery_dropped(_) -> +% SQL = +% <<"SELECT from_clientid, from_username, reason, topic, qos FROM \"$events/delivery_dropped\"">>, + +% Context = +% #{ +% clientid => <<"c_emqx_2">>, +% event_type => delivery_dropped, +% from_clientid => <<"c_emqx_1">>, +% from_username => <<"u_emqx_1">>, +% payload => <<"{\"msg\": \"hello\"}">>, +% qos => 1, +% reason => <<"queue_full">>, +% topic => <<"t/a">>, +% username => <<"u_emqx_2">> +% }, +% Expected = check_result([from_clientid, from_username, reason, qos, topic], [], Context), +% do_test(SQL, Context, Expected). + +% t_mongo_date_function_should_return_string_in_test_env(_) -> +% SQL = +% <<"SELECT mongo_date() as mongo_date FROM \"$events/client_check_authz_complete\"">>, +% Context = +% #{ +% action => <<"publish">>, +% clientid => <<"c_emqx">>, +% event_type => client_check_authz_complete, +% result => <<"allow">>, +% topic => <<"t/1">>, +% username => <<"u_emqx">> +% }, +% CheckFunction = fun(Result) -> +% MongoDate = maps:get(mongo_date, Result), +% %% Use regex to match the expected string +% MatchResult = re:run(MongoDate, <<"ISODate\\([0-9]{4}-[0-9]{2}-[0-9]{2}T.*\\)">>), +% ?assertMatch({match, _}, MatchResult), +% ok +% end, +% do_test(SQL, Context, CheckFunction). + +% do_test(SQL, Context, Expected0) -> +% Res = emqx_rule_engine_api:'/rule_test'( +% post, +% test_rule_params(SQL, Context) +% ), +% ?assertMatch({200, _}, Res), +% {200, Result0} = Res, +% Result = emqx_utils_maps:unsafe_atom_key_map(Result0), +% case is_function(Expected0) of +% false -> +% Expected = maps:without([event_type], Expected0), +% ?assertMatch(Expected, Result, Expected); +% _ -> +% Expected0(Result) +% end, +% ok. + +% test_rule_params(Sql, Context) -> +% #{ +% body => #{ +% <<"context">> => Context, +% <<"sql">> => Sql +% } +% }. + +% with_node_timestampe(Keys, Context) -> +% check_result(Keys, [node, timestamp], Context). + +% check_result(Keys, Exists, Context) -> +% Log = fun(Format, Args) -> +% lists:flatten(io_lib:format(Format, Args)) +% end, + +% Base = maps:with(Keys, Context), + +% fun(Result) -> +% maps:foreach( +% fun(Key, Value) -> +% ?assertEqual( +% Value, +% maps:get(Key, Result, undefined), +% Log("Key:~p value error~nResult:~p~n", [Key, Result]) +% ) +% end, +% Base +% ), + +% NotExists = fun(Key) -> Log("Key:~p not exists in result:~p~n", [Key, Result]) end, +% lists:foreach( +% fun(Key) -> +% Find = maps:find(Key, Result), +% Formatter = NotExists(Key), +% ?assertMatch({ok, _}, Find, Formatter), +% ?assertNotMatch({ok, undefined}, Find, Formatter), +% ?assertNotMatch({ok, <<"undefined">>}, Find, Formatter) +% end, +% Exists +% ), + +% ?assertEqual(erlang:length(Keys) + erlang:length(Exists), maps:size(Result), Result) +% end. + +call_apply_rule_api(RuleId, Params) -> + Method = post, + Path = emqx_mgmt_api_test_util:api_path(["rules", RuleId, "test"]), + ct:pal("sql test (http):\n ~p", [Params]), + Res = request(Method, Path, Params), + ct:pal("sql test (http) result:\n ~p", [Res]), + Res. + +request(Method, Path, Params) -> + AuthHeader = emqx_mgmt_api_test_util:auth_header_(), + Opts = #{return_all => true}, + case emqx_mgmt_api_test_util:request_api(Method, Path, "", AuthHeader, Params, Opts) of + {ok, {Status, Headers, Body0}} -> + Body = maybe_json_decode(Body0), + {ok, {Status, Headers, Body}}; + {error, {Status, Headers, Body0}} -> + Body = + case emqx_utils_json:safe_decode(Body0, [return_maps]) of + {ok, Decoded0 = #{<<"message">> := Msg0}} -> + Msg = maybe_json_decode(Msg0), + Decoded0#{<<"message">> := Msg}; + {ok, Decoded0} -> + Decoded0; + {error, _} -> + Body0 + end, + {error, {Status, Headers, Body}}; + Error -> + Error + end. + +maybe_json_decode(X) -> + case emqx_utils_json:safe_decode(X, [return_maps]) of + {ok, Decoded} -> Decoded; + {error, _} -> X + end. + +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. From 5479932190270b704f56d957910fd4e7eefb5db7 Mon Sep 17 00:00:00 2001 From: Kjell Winblad Date: Sat, 6 Apr 2024 17:21:12 +0200 Subject: [PATCH 03/23] feat(apply rule test): make option to stop action after render work This commit makes the apply rule HTTP API option to stop an action work for the HTTP action, and adds infrastructure that makes it easy to add this functionality to other actions. --- apps/emqx/src/emqx_trace/emqx_trace.erl | 22 +- .../src/emqx_bridge_http_connector.erl | 59 +++- .../src/emqx_rule_runtime.erl | 10 +- .../src/emqx_rule_sqltester.erl | 2 +- .../emqx_rule_engine_api_rule_apply_SUITE.erl | 297 ++---------------- 5 files changed, 109 insertions(+), 281 deletions(-) diff --git a/apps/emqx/src/emqx_trace/emqx_trace.erl b/apps/emqx/src/emqx_trace/emqx_trace.erl index 8151c19b5..408644128 100644 --- a/apps/emqx/src/emqx_trace/emqx_trace.erl +++ b/apps/emqx/src/emqx_trace/emqx_trace.erl @@ -28,7 +28,8 @@ subscribe/3, unsubscribe/2, log/3, - log/4 + log/4, + rendered_action_template/2 ]). -export([ @@ -86,6 +87,25 @@ unsubscribe(<<"$SYS/", _/binary>>, _SubOpts) -> unsubscribe(Topic, SubOpts) -> ?TRACE("UNSUBSCRIBE", "unsubscribe", #{topic => Topic, sub_opts => SubOpts}). +rendered_action_template(ActionID, RenderResult) -> + Msg = io_lib:format("action_template_rendered(~s)", [ActionID]), + TraceResult = ?TRACE("QUERY_RENDER", Msg, RenderResult), + case logger:get_process_metadata() of + #{stop_action_after_render := true} -> + %% We throw an unrecoverable error to stop action before the + %% resource is called/modified + StopMsg = io_lib:format( + "action_stopped_after_render(~s): " + "Action stopped after template render due to test setting.", + [ActionID] + ), + MsgBin = iolist_to_binary(StopMsg), + error({unrecoverable_error, MsgBin}); + _ -> + ok + end, + TraceResult. + log(List, Msg, Meta) -> log(debug, List, Msg, Meta). diff --git a/apps/emqx_bridge_http/src/emqx_bridge_http_connector.erl b/apps/emqx_bridge_http/src/emqx_bridge_http_connector.erl index 99222aa00..46b3d5e1f 100644 --- a/apps/emqx_bridge_http/src/emqx_bridge_http_connector.erl +++ b/apps/emqx_bridge_http/src/emqx_bridge_http_connector.erl @@ -371,6 +371,29 @@ on_query( } ), NRequest = formalize_request(Method, BasePath, Request), + case NRequest of + {Path, Headers} -> + emqx_trace:rendered_action_template( + InstId, + #{ + path => Path, + method => Method, + headers => Headers, + timeout => Timeout + } + ); + {Path, Headers, Body} -> + emqx_trace:rendered_action_template( + InstId, + #{ + path => Path, + method => Method, + headers => Headers, + timeout => Timeout, + body => Body + } + ) + end, Worker = resolve_pool_worker(State, KeyOrNum), Result0 = ehttpc:request( Worker, @@ -480,6 +503,29 @@ on_query_async( } ), NRequest = formalize_request(Method, BasePath, Request), + case NRequest of + {Path, Headers} -> + emqx_trace:rendered_action_template( + InstId, + #{ + path => Path, + method => Method, + headers => Headers, + timeout => Timeout + } + ); + {Path, Headers, Body} -> + emqx_trace:rendered_action_template( + InstId, + #{ + path => Path, + method => Method, + headers => Headers, + timeout => Timeout, + body => Body + } + ) + end, MaxAttempts = maps:get(max_attempts, State, 3), Context = #{ attempt => 1, @@ -661,22 +707,13 @@ process_request_and_action(Request, ActionState, Msg) -> ), BodyTemplate = maps:get(body, ActionState), Body = render_request_body(BodyTemplate, RenderTmplFunc, Msg), - RenderResult = #{ + #{ method => Method, path => Path, body => Body, headers => Headers, request_timeout => maps:get(request_timeout, ActionState) - }, - ?TRACE( - "QUERY_RENDER", - "http_connector_successfully_rendered_request", - #{ - request => Request, - render_result => RenderResult - } - ), - RenderResult. + }. merge_proplist(Proplist1, Proplist2) -> lists:foldl( diff --git a/apps/emqx_rule_engine/src/emqx_rule_runtime.erl b/apps/emqx_rule_engine/src/emqx_rule_runtime.erl index 1204ea5e5..f2c89e8ed 100644 --- a/apps/emqx_rule_engine/src/emqx_rule_runtime.erl +++ b/apps/emqx_rule_engine/src/emqx_rule_runtime.erl @@ -471,7 +471,9 @@ do_handle_action(_RuleId, #{mod := Mod, func := Func} = Action, Selected, Envs) Result. do_handle_action_get_trace_context(Action) -> - case logger:get_process_metadata() of + Metadata = logger:get_process_metadata(), + StopAfterRender = maps:get(stop_action_after_render, Metadata, false), + case Metadata of #{ rule_id := RuleID, clientid := ClientID @@ -479,14 +481,16 @@ do_handle_action_get_trace_context(Action) -> #{ rule_id => RuleID, clientid => ClientID, - action_id => Action + action_id => Action, + stop_action_after_render => StopAfterRender }; #{ rule_id := RuleID } -> #{ rule_id => RuleID, - action_id => Action + action_id => Action, + stop_action_after_render => StopAfterRender } end. diff --git a/apps/emqx_rule_engine/src/emqx_rule_sqltester.erl b/apps/emqx_rule_engine/src/emqx_rule_sqltester.erl index e72b0fcd0..fc4d2614f 100644 --- a/apps/emqx_rule_engine/src/emqx_rule_sqltester.erl +++ b/apps/emqx_rule_engine/src/emqx_rule_sqltester.erl @@ -67,7 +67,7 @@ do_apply_matched_rule(Rule, Context, Env, StopAfterRender) -> ApplyRuleRes. update_process_trace_metadata(true = _StopAfterRender) -> - logger:update_process_trace_metadata(#{ + logger:update_process_metadata(#{ stop_action_after_render => true }); update_process_trace_metadata(false = _StopAfterRender) -> 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 d9d15dba0..31a462de3 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 @@ -64,12 +64,15 @@ end_per_testcase(_TestCase, _Config) -> ok. t_basic_apply_rule_trace_ruleid(Config) -> - basic_apply_rule_test_helper(Config, ruleid). + basic_apply_rule_test_helper(Config, ruleid, false). t_basic_apply_rule_trace_clientid(Config) -> - basic_apply_rule_test_helper(Config, clientid). + basic_apply_rule_test_helper(Config, clientid, false). -basic_apply_rule_test_helper(Config, TraceType) -> +t_basic_apply_rule_trace_ruleid_stop_after_render(Config) -> + basic_apply_rule_test_helper(Config, ruleid, true). + +basic_apply_rule_test_helper(Config, TraceType, StopAfterRender) -> HTTPServerConfig = ?config(http_server, Config), emqx_bridge_http_test_lib:make_bridge(HTTPServerConfig), #{status := connected} = emqx_bridge_v2:health_check( @@ -121,7 +124,8 @@ basic_apply_rule_test_helper(Config, TraceType) -> }, Params = #{ % body => #{ - <<"context">> => Context + <<"context">> => Context, + <<"stop_action_after_template_render">> => StopAfterRender % } }, emqx_trace:check(), @@ -133,279 +137,42 @@ basic_apply_rule_test_helper(Config, TraceType) -> _NAttempts0 = 20, begin Bin = read_rule_trace_file(TraceName, TraceType, Now), + io:format("THELOG:~n~s", [Bin]), ?assertNotEqual(nomatch, binary:match(Bin, [<<"rule_activated">>])), ?assertNotEqual(nomatch, binary:match(Bin, [<<"SELECT_yielded_result">>])), ?assertNotEqual(nomatch, binary:match(Bin, [<<"bridge_action">>])), ?assertNotEqual(nomatch, binary:match(Bin, [<<"action_activated">>])), - ?assertNotEqual(nomatch, binary:match(Bin, [<<"successfully_rendered_request">>])), + ?assertNotEqual(nomatch, binary:match(Bin, [<<"action_template_rendered">>])), ?assertNotEqual(nomatch, binary:match(Bin, [<<"QUERY_ASYNC">>])) end ), + case StopAfterRender of + true -> + ?retry( + _Interval0 = 200, + _NAttempts0 = 20, + begin + Bin = read_rule_trace_file(TraceName, TraceType, Now), + io:format("THELOG2:~n~s", [Bin]), + ?assertNotEqual(nomatch, binary:match(Bin, [<<"action_failed">>])) + end + ); + false -> + ?retry( + _Interval0 = 200, + _NAttempts0 = 20, + begin + Bin = read_rule_trace_file(TraceName, TraceType, Now), + io:format("THELOG3:~n~s", [Bin]), + ?assertNotEqual(nomatch, binary:match(Bin, [<<"action_success">>])) + end + ) + end, emqx_trace:delete(TraceName), ok. %% Helper Functions -% t_ctx_pub(_) -> -% SQL = <<"SELECT payload.msg as msg, clientid, username, payload, topic, qos FROM \"t/#\"">>, -% Context = #{ -% clientid => <<"c_emqx">>, -% event_type => message_publish, -% payload => <<"{\"msg\": \"hello\"}">>, -% qos => 1, -% topic => <<"t/a">>, -% username => <<"u_emqx">> -% }, -% Expected = Context#{msg => <<"hello">>}, -% do_test(SQL, Context, Expected). - -% t_ctx_sub(_) -> -% SQL = <<"SELECT clientid, username, topic, qos FROM \"$events/session_subscribed\"">>, -% Context = #{ -% clientid => <<"c_emqx">>, -% event_type => session_subscribed, -% qos => 1, -% topic => <<"t/a">>, -% username => <<"u_emqx">> -% }, - -% do_test(SQL, Context, Context). - -% t_ctx_unsub(_) -> -% SQL = <<"SELECT clientid, username, topic, qos FROM \"$events/session_unsubscribed\"">>, -% Context = #{ -% clientid => <<"c_emqx">>, -% event_type => session_unsubscribed, -% qos => 1, -% topic => <<"t/a">>, -% username => <<"u_emqx">> -% }, -% do_test(SQL, Context, Context). - -% t_ctx_delivered(_) -> -% SQL = -% <<"SELECT from_clientid, from_username, topic, qos, node, timestamp FROM \"$events/message_delivered\"">>, -% Context = #{ -% clientid => <<"c_emqx_2">>, -% event_type => message_delivered, -% from_clientid => <<"c_emqx_1">>, -% from_username => <<"u_emqx_1">>, -% payload => <<"{\"msg\": \"hello\"}">>, -% qos => 1, -% topic => <<"t/a">>, -% username => <<"u_emqx_2">> -% }, -% Expected = check_result([from_clientid, from_username, topic, qos], [node, timestamp], Context), -% do_test(SQL, Context, Expected). - -% t_ctx_acked(_) -> -% SQL = -% <<"SELECT from_clientid, from_username, topic, qos, node, timestamp FROM \"$events/message_acked\"">>, - -% Context = #{ -% clientid => <<"c_emqx_2">>, -% event_type => message_acked, -% from_clientid => <<"c_emqx_1">>, -% from_username => <<"u_emqx_1">>, -% payload => <<"{\"msg\": \"hello\"}">>, -% qos => 1, -% topic => <<"t/a">>, -% username => <<"u_emqx_2">> -% }, - -% Expected = with_node_timestampe([from_clientid, from_username, topic, qos], Context), - -% do_test(SQL, Context, Expected). - -% t_ctx_droped(_) -> -% SQL = <<"SELECT reason, topic, qos, node, timestamp FROM \"$events/message_dropped\"">>, -% Topic = <<"t/a">>, -% QoS = 1, -% Reason = <<"no_subscribers">>, -% Context = #{ -% clientid => <<"c_emqx">>, -% event_type => message_dropped, -% payload => <<"{\"msg\": \"hello\"}">>, -% qos => QoS, -% reason => Reason, -% topic => Topic, -% username => <<"u_emqx">> -% }, - -% Expected = with_node_timestampe([reason, topic, qos], Context), -% do_test(SQL, Context, Expected). - -% t_ctx_connected(_) -> -% SQL = -% <<"SELECT clientid, username, keepalive, is_bridge FROM \"$events/client_connected\"">>, - -% Context = -% #{ -% clean_start => true, -% clientid => <<"c_emqx">>, -% event_type => client_connected, -% is_bridge => false, -% peername => <<"127.0.0.1:52918">>, -% username => <<"u_emqx">> -% }, -% Expected = check_result([clientid, username, keepalive, is_bridge], [], Context), -% do_test(SQL, Context, Expected). - -% t_ctx_disconnected(_) -> -% SQL = -% <<"SELECT clientid, username, reason, disconnected_at, node FROM \"$events/client_disconnected\"">>, - -% Context = -% #{ -% clientid => <<"c_emqx">>, -% event_type => client_disconnected, -% reason => <<"normal">>, -% username => <<"u_emqx">> -% }, -% Expected = check_result([clientid, username, reason], [disconnected_at, node], Context), -% do_test(SQL, Context, Expected). - -% t_ctx_connack(_) -> -% SQL = -% <<"SELECT clientid, username, reason_code, node FROM \"$events/client_connack\"">>, - -% Context = -% #{ -% clean_start => true, -% clientid => <<"c_emqx">>, -% event_type => client_connack, -% reason_code => <<"sucess">>, -% username => <<"u_emqx">> -% }, -% Expected = check_result([clientid, username, reason_code], [node], Context), -% do_test(SQL, Context, Expected). - -% t_ctx_check_authz_complete(_) -> -% SQL = -% << -% "SELECT clientid, username, topic, action, result,\n" -% "authz_source, node FROM \"$events/client_check_authz_complete\"" -% >>, - -% Context = -% #{ -% action => <<"publish">>, -% clientid => <<"c_emqx">>, -% event_type => client_check_authz_complete, -% result => <<"allow">>, -% topic => <<"t/1">>, -% username => <<"u_emqx">> -% }, -% Expected = check_result( -% [clientid, username, topic, action], -% [authz_source, node, result], -% Context -% ), - -% do_test(SQL, Context, Expected). - -% t_ctx_delivery_dropped(_) -> -% SQL = -% <<"SELECT from_clientid, from_username, reason, topic, qos FROM \"$events/delivery_dropped\"">>, - -% Context = -% #{ -% clientid => <<"c_emqx_2">>, -% event_type => delivery_dropped, -% from_clientid => <<"c_emqx_1">>, -% from_username => <<"u_emqx_1">>, -% payload => <<"{\"msg\": \"hello\"}">>, -% qos => 1, -% reason => <<"queue_full">>, -% topic => <<"t/a">>, -% username => <<"u_emqx_2">> -% }, -% Expected = check_result([from_clientid, from_username, reason, qos, topic], [], Context), -% do_test(SQL, Context, Expected). - -% t_mongo_date_function_should_return_string_in_test_env(_) -> -% SQL = -% <<"SELECT mongo_date() as mongo_date FROM \"$events/client_check_authz_complete\"">>, -% Context = -% #{ -% action => <<"publish">>, -% clientid => <<"c_emqx">>, -% event_type => client_check_authz_complete, -% result => <<"allow">>, -% topic => <<"t/1">>, -% username => <<"u_emqx">> -% }, -% CheckFunction = fun(Result) -> -% MongoDate = maps:get(mongo_date, Result), -% %% Use regex to match the expected string -% MatchResult = re:run(MongoDate, <<"ISODate\\([0-9]{4}-[0-9]{2}-[0-9]{2}T.*\\)">>), -% ?assertMatch({match, _}, MatchResult), -% ok -% end, -% do_test(SQL, Context, CheckFunction). - -% do_test(SQL, Context, Expected0) -> -% Res = emqx_rule_engine_api:'/rule_test'( -% post, -% test_rule_params(SQL, Context) -% ), -% ?assertMatch({200, _}, Res), -% {200, Result0} = Res, -% Result = emqx_utils_maps:unsafe_atom_key_map(Result0), -% case is_function(Expected0) of -% false -> -% Expected = maps:without([event_type], Expected0), -% ?assertMatch(Expected, Result, Expected); -% _ -> -% Expected0(Result) -% end, -% ok. - -% test_rule_params(Sql, Context) -> -% #{ -% body => #{ -% <<"context">> => Context, -% <<"sql">> => Sql -% } -% }. - -% with_node_timestampe(Keys, Context) -> -% check_result(Keys, [node, timestamp], Context). - -% check_result(Keys, Exists, Context) -> -% Log = fun(Format, Args) -> -% lists:flatten(io_lib:format(Format, Args)) -% end, - -% Base = maps:with(Keys, Context), - -% fun(Result) -> -% maps:foreach( -% fun(Key, Value) -> -% ?assertEqual( -% Value, -% maps:get(Key, Result, undefined), -% Log("Key:~p value error~nResult:~p~n", [Key, Result]) -% ) -% end, -% Base -% ), - -% NotExists = fun(Key) -> Log("Key:~p not exists in result:~p~n", [Key, Result]) end, -% lists:foreach( -% fun(Key) -> -% Find = maps:find(Key, Result), -% Formatter = NotExists(Key), -% ?assertMatch({ok, _}, Find, Formatter), -% ?assertNotMatch({ok, undefined}, Find, Formatter), -% ?assertNotMatch({ok, <<"undefined">>}, Find, Formatter) -% end, -% Exists -% ), - -% ?assertEqual(erlang:length(Keys) + erlang:length(Exists), maps:size(Result), Result) -% end. - call_apply_rule_api(RuleId, Params) -> Method = post, Path = emqx_mgmt_api_test_util:api_path(["rules", RuleId, "test"]), From 79440064fe9b1d6ab47a3bf0d8c001e268761319 Mon Sep 17 00:00:00 2001 From: Kjell Winblad Date: Mon, 8 Apr 2024 11:03:55 +0200 Subject: [PATCH 04/23] style: fix problems reported by elvis --- .../src/emqx_rule_api_schema.erl | 67 +++++++------------ .../src/emqx_rule_runtime.erl | 2 +- 2 files changed, 26 insertions(+), 43 deletions(-) diff --git a/apps/emqx_rule_engine/src/emqx_rule_api_schema.erl b/apps/emqx_rule_engine/src/emqx_rule_api_schema.erl index a24ef5bd0..4058d2f83 100644 --- a/apps/emqx_rule_engine/src/emqx_rule_api_schema.erl +++ b/apps/emqx_rule_engine/src/emqx_rule_api_schema.erl @@ -102,52 +102,12 @@ fields("rule_events") -> ]; fields("rule_test") -> [ - {"context", - sc( - hoconsc:union([ - ref("ctx_pub"), - ref("ctx_sub"), - ref("ctx_unsub"), - ref("ctx_delivered"), - ref("ctx_acked"), - ref("ctx_dropped"), - ref("ctx_connected"), - ref("ctx_disconnected"), - ref("ctx_connack"), - ref("ctx_check_authz_complete"), - ref("ctx_bridge_mqtt"), - ref("ctx_delivery_dropped") - ]), - #{ - desc => ?DESC("test_context"), - default => #{} - } - )}, + rule_input_message_context(), {"sql", sc(binary(), #{desc => ?DESC("test_sql"), required => true})} ]; fields("rule_apply_test") -> [ - {"context", - sc( - hoconsc:union([ - ref("ctx_pub"), - ref("ctx_sub"), - ref("ctx_unsub"), - ref("ctx_delivered"), - ref("ctx_acked"), - ref("ctx_dropped"), - ref("ctx_connected"), - ref("ctx_disconnected"), - ref("ctx_connack"), - ref("ctx_check_authz_complete"), - ref("ctx_bridge_mqtt"), - ref("ctx_delivery_dropped") - ]), - #{ - desc => ?DESC("test_context"), - default => #{} - } - )}, + rule_input_message_context(), {"environment", sc( typerefl:map(), @@ -358,6 +318,29 @@ fields("ctx_delivery_dropped") -> | msg_event_common_fields() ]. +rule_input_message_context() -> + {"context", + sc( + hoconsc:union([ + ref("ctx_pub"), + ref("ctx_sub"), + ref("ctx_unsub"), + ref("ctx_delivered"), + ref("ctx_acked"), + ref("ctx_dropped"), + ref("ctx_connected"), + ref("ctx_disconnected"), + ref("ctx_connack"), + ref("ctx_check_authz_complete"), + ref("ctx_bridge_mqtt"), + ref("ctx_delivery_dropped") + ]), + #{ + desc => ?DESC("test_context"), + default => #{} + } + )}. + qos() -> {"qos", sc(emqx_schema:qos(), #{desc => ?DESC("event_qos")})}. diff --git a/apps/emqx_rule_engine/src/emqx_rule_runtime.erl b/apps/emqx_rule_engine/src/emqx_rule_runtime.erl index f2c89e8ed..f90b5a974 100644 --- a/apps/emqx_rule_engine/src/emqx_rule_runtime.erl +++ b/apps/emqx_rule_engine/src/emqx_rule_runtime.erl @@ -420,7 +420,7 @@ handle_action(RuleId, ActId, Selected, Envs) -> end. -define(IS_RES_DOWN(R), R == stopped; R == not_connected; R == not_found; R == unhealthy_target). -do_handle_action(RuleId, {bridge, BridgeType, BridgeName, ResId} = Action, Selected, _Envs) -> +do_handle_action(_RuleId, {bridge, BridgeType, BridgeName, ResId} = Action, Selected, _Envs) -> trace_action_bridge("BRIDGE", Action, "bridge_action", #{}, debug), TraceCtx = do_handle_action_get_trace_context(Action), ReplyTo = {fun ?MODULE:inc_action_metrics/2, [TraceCtx], #{reply_dropped => true}}, From b57725f9961f5d1bfa45210222c4627f243e9e1a Mon Sep 17 00:00:00 2001 From: Kjell Winblad Date: Mon, 8 Apr 2024 12:41:35 +0200 Subject: [PATCH 05/23] test(resource_SUITE): do test case fixes needed due to rule tracing work --- .../test/emqx_resource_SUITE.erl | 55 +++++++++---------- 1 file changed, 27 insertions(+), 28 deletions(-) diff --git a/apps/emqx_resource/test/emqx_resource_SUITE.erl b/apps/emqx_resource/test/emqx_resource_SUITE.erl index a6cdaedb2..a97d589b3 100644 --- a/apps/emqx_resource/test/emqx_resource_SUITE.erl +++ b/apps/emqx_resource/test/emqx_resource_SUITE.erl @@ -277,10 +277,9 @@ t_batch_query_counter(_) -> fun(Result, Trace) -> ?assertMatch({ok, 0}, Result), QueryTrace = ?of_kind(call_batch_query, Trace), - ?assertMatch([#{batch := [{query, _, get_counter, _, _}]}], QueryTrace) + ?assertMatch([#{batch := [{query, _, get_counter, _, _, _}]}], QueryTrace) end ), - NMsgs = 1_000, ?check_trace( ?TRACE_OPTS, @@ -340,7 +339,7 @@ t_query_counter_async_query(_) -> fun(Trace) -> %% the callback_mode of 'emqx_connector_demo' is 'always_sync'. QueryTrace = ?of_kind(call_query, Trace), - ?assertMatch([#{query := {query, _, {inc_counter, 1}, _, _}} | _], QueryTrace) + ?assertMatch([#{query := {query, _, {inc_counter, 1}, _, _, _}} | _], QueryTrace) end ), %% simple query ignores the query_mode and batching settings in the resource_worker @@ -351,7 +350,7 @@ t_query_counter_async_query(_) -> ?assertMatch({ok, 1000}, Result), %% the callback_mode if 'emqx_connector_demo' is 'always_sync'. QueryTrace = ?of_kind(call_query, Trace), - ?assertMatch([#{query := {query, _, get_counter, _, _}}], QueryTrace) + ?assertMatch([#{query := {query, _, get_counter, _, _, _}}], QueryTrace) end ), #{counters := C} = emqx_resource:get_metrics(?ID), @@ -397,7 +396,7 @@ t_query_counter_async_callback(_) -> end, fun(Trace) -> QueryTrace = ?of_kind(call_query_async, Trace), - ?assertMatch([#{query := {query, _, {inc_counter, 1}, _, _}} | _], QueryTrace) + ?assertMatch([#{query := {query, _, {inc_counter, 1}, _, _, _}} | _], QueryTrace) end ), @@ -408,7 +407,7 @@ t_query_counter_async_callback(_) -> fun(Result, Trace) -> ?assertMatch({ok, 1000}, Result), QueryTrace = ?of_kind(call_query, Trace), - ?assertMatch([#{query := {query, _, get_counter, _, _}}], QueryTrace) + ?assertMatch([#{query := {query, _, get_counter, _, _, _}}], QueryTrace) end ), #{counters := C} = emqx_resource:get_metrics(?ID), @@ -480,7 +479,7 @@ t_query_counter_async_inflight(_) -> ), fun(Trace) -> QueryTrace = ?of_kind(call_query_async, Trace), - ?assertMatch([#{query := {query, _, {inc_counter, 1}, _, _}} | _], QueryTrace) + ?assertMatch([#{query := {query, _, {inc_counter, 1}, _, _, _}} | _], QueryTrace) end ), tap_metrics(?LINE), @@ -537,7 +536,7 @@ t_query_counter_async_inflight(_) -> end, fun(Trace) -> QueryTrace = ?of_kind(call_query_async, Trace), - ?assertMatch([#{query := {query, _, {inc_counter, _}, _, _}} | _], QueryTrace), + ?assertMatch([#{query := {query, _, {inc_counter, _}, _, _, _}} | _], QueryTrace), ?assertEqual(WindowSize + Num + 1, ets:info(Tab0, size), #{tab => ets:tab2list(Tab0)}), tap_metrics(?LINE), ok @@ -557,7 +556,7 @@ t_query_counter_async_inflight(_) -> ), fun(Trace) -> QueryTrace = ?of_kind(call_query_async, Trace), - ?assertMatch([#{query := {query, _, {inc_counter, 1}, _, _}} | _], QueryTrace) + ?assertMatch([#{query := {query, _, {inc_counter, 1}, _, _, _}} | _], QueryTrace) end ), @@ -669,8 +668,8 @@ t_query_counter_async_inflight_batch(_) -> || Event = #{ ?snk_kind := call_batch_query_async, batch := [ - {query, _, {inc_counter, 1}, _, _}, - {query, _, {inc_counter, 1}, _, _} + {query, _, {inc_counter, 1}, _, _, _}, + {query, _, {inc_counter, 1}, _, _, _} ] } <- Trace @@ -754,7 +753,7 @@ t_query_counter_async_inflight_batch(_) -> fun(Trace) -> QueryTrace = ?of_kind(call_batch_query_async, Trace), ?assertMatch( - [#{batch := [{query, _, {inc_counter, _}, _, _} | _]} | _], + [#{batch := [{query, _, {inc_counter, _}, _, _, _} | _]} | _], QueryTrace ) end @@ -779,7 +778,7 @@ t_query_counter_async_inflight_batch(_) -> fun(Trace) -> QueryTrace = ?of_kind(call_batch_query_async, Trace), ?assertMatch( - [#{batch := [{query, _, {inc_counter, _}, _, _} | _]} | _], + [#{batch := [{query, _, {inc_counter, _}, _, _, _} | _]} | _], QueryTrace ) end @@ -2051,7 +2050,7 @@ do_t_expiration_before_sending(QueryMode) -> end, fun(Trace) -> ?assertMatch( - [#{batch := [{query, _, {inc_counter, 99}, _, _}]}], + [#{batch := [{query, _, {inc_counter, 99}, _, _, _}]}], ?of_kind(buffer_worker_flush_all_expired, Trace) ), Metrics = tap_metrics(?LINE), @@ -2167,7 +2166,7 @@ do_t_expiration_before_sending_partial_batch(QueryMode) -> #{ ?snk_kind := handle_async_reply, action := ack, - batch_or_query := [{query, _, {inc_counter, 99}, _, _}] + batch_or_query := [{query, _, {inc_counter, 99}, _, _, _}] }, 10 * TimeoutMS ); @@ -2189,8 +2188,8 @@ do_t_expiration_before_sending_partial_batch(QueryMode) -> ?assertMatch( [ #{ - expired := [{query, _, {inc_counter, 199}, _, _}], - not_expired := [{query, _, {inc_counter, 99}, _, _}] + expired := [{query, _, {inc_counter, 199}, _, _, _}], + not_expired := [{query, _, {inc_counter, 99}, _, _, _}] } ], ?of_kind(buffer_worker_flush_potentially_partial, Trace) @@ -2303,7 +2302,7 @@ do_t_expiration_async_after_reply(IsBatch) -> #{?snk_kind := delay}, #{ ?snk_kind := handle_async_reply_enter, - batch_or_query := [{query, _, {inc_counter, 199}, _, _} | _] + batch_or_query := [{query, _, {inc_counter, 199}, _, _, _} | _] } ), @@ -2346,8 +2345,8 @@ do_t_expiration_async_after_reply(IsBatch) -> [ #{ expired := [ - {query, _, {inc_counter, 199}, _, _}, - {query, _, {inc_counter, 299}, _, _} + {query, _, {inc_counter, 199}, _, _, _}, + {query, _, {inc_counter, 299}, _, _, _} ] } ], @@ -2365,8 +2364,8 @@ do_t_expiration_async_after_reply(IsBatch) -> single -> ?assertMatch( [ - #{expired := [{query, _, {inc_counter, 199}, _, _}]}, - #{expired := [{query, _, {inc_counter, 299}, _, _}]} + #{expired := [{query, _, {inc_counter, 199}, _, _, _}]}, + #{expired := [{query, _, {inc_counter, 299}, _, _, _}]} ], ?of_kind(handle_async_reply_expired, Trace) ) @@ -2417,7 +2416,7 @@ t_expiration_batch_all_expired_after_reply(_Config) -> #{?snk_kind := delay}, #{ ?snk_kind := handle_async_reply_enter, - batch_or_query := [{query, _, {inc_counter, 199}, _, _} | _] + batch_or_query := [{query, _, {inc_counter, 199}, _, _, _} | _] } ), @@ -2451,8 +2450,8 @@ t_expiration_batch_all_expired_after_reply(_Config) -> [ #{ expired := [ - {query, _, {inc_counter, 199}, _, _}, - {query, _, {inc_counter, 299}, _, _} + {query, _, {inc_counter, 199}, _, _, _}, + {query, _, {inc_counter, 299}, _, _, _} ] } ], @@ -2578,7 +2577,7 @@ do_t_expiration_retry() -> end, fun(Trace) -> ?assertMatch( - [#{expired := [{query, _, {inc_counter, 1}, _, _}]}], + [#{expired := [{query, _, {inc_counter, 1}, _, _, _}]}], ?of_kind(buffer_worker_retry_expired, Trace) ), Metrics = tap_metrics(?LINE), @@ -2655,8 +2654,8 @@ t_expiration_retry_batch_multiple_times(_Config) -> fun(Trace) -> ?assertMatch( [ - #{expired := [{query, _, {inc_counter, 1}, _, _}]}, - #{expired := [{query, _, {inc_counter, 2}, _, _}]} + #{expired := [{query, _, {inc_counter, 1}, _, _, _}]}, + #{expired := [{query, _, {inc_counter, 2}, _, _, _}]} ], ?of_kind(buffer_worker_retry_expired, Trace) ), From 02ee87309471092c7f8794def9ac519b4c1f5a42 Mon Sep 17 00:00:00 2001 From: Kjell Winblad Date: Mon, 8 Apr 2024 13:42:15 +0200 Subject: [PATCH 06/23] docs(emqx_rule_api_schema): fix type spec --- apps/emqx_rule_engine/src/emqx_rule_api_schema.erl | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/apps/emqx_rule_engine/src/emqx_rule_api_schema.erl b/apps/emqx_rule_engine/src/emqx_rule_api_schema.erl index 4058d2f83..862aea3b3 100644 --- a/apps/emqx_rule_engine/src/emqx_rule_api_schema.erl +++ b/apps/emqx_rule_engine/src/emqx_rule_api_schema.erl @@ -26,7 +26,7 @@ -export([namespace/0, roots/0, fields/1]). --type tag() :: rule_creation | rule_test | rule_engine. +-type tag() :: rule_creation | rule_test | rule_engine | rule_apply_test. -spec check_params(map(), tag()) -> {ok, map()} | {error, term()}. check_params(Params, Tag) -> From 600526a0e407e768701e179ba8c4904b35c34984 Mon Sep 17 00:00:00 2001 From: Kjell Winblad Date: Mon, 8 Apr 2024 14:54:33 +0200 Subject: [PATCH 07/23] test(emqx_bridge_http_SUITE): test case after name change --- apps/emqx_bridge_http/test/emqx_bridge_http_SUITE.erl | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/apps/emqx_bridge_http/test/emqx_bridge_http_SUITE.erl b/apps/emqx_bridge_http/test/emqx_bridge_http_SUITE.erl index ab0d5bb55..73f6359ab 100644 --- a/apps/emqx_bridge_http/test/emqx_bridge_http_SUITE.erl +++ b/apps/emqx_bridge_http/test/emqx_bridge_http_SUITE.erl @@ -421,7 +421,7 @@ t_send_get_trace_messages(Config) -> ?assertNotEqual(nomatch, binary:match(Bin, [<<"SELECT_yielded_result">>])), ?assertNotEqual(nomatch, binary:match(Bin, [<<"bridge_action">>])), ?assertNotEqual(nomatch, binary:match(Bin, [<<"action_activated">>])), - ?assertNotEqual(nomatch, binary:match(Bin, [<<"successfully_rendered_request">>])), + ?assertNotEqual(nomatch, binary:match(Bin, [<<"action_template_rendered">>])), ?assertNotEqual(nomatch, binary:match(Bin, [<<"QUERY_ASYNC">>])) end ), From 9628a00a82295da6190dbe4dc4a6fac1e0de9357 Mon Sep 17 00:00:00 2001 From: Kjell Winblad Date: Mon, 8 Apr 2024 15:34:29 +0200 Subject: [PATCH 08/23] docs(emqx_rule_api apply rule): fix doc strings --- apps/emqx_rule_engine/src/emqx_rule_api_schema.erl | 2 +- apps/emqx_rule_engine/src/emqx_rule_engine_api.erl | 4 ++-- apps/emqx_rule_engine/src/emqx_rule_sqltester.erl | 2 +- .../test/emqx_rule_engine_api_rule_apply_SUITE.erl | 5 +---- rel/i18n/emqx_rule_api_schema.hocon | 12 ++++++++++++ rel/i18n/emqx_rule_engine_api.hocon | 6 ++++++ 6 files changed, 23 insertions(+), 8 deletions(-) diff --git a/apps/emqx_rule_engine/src/emqx_rule_api_schema.erl b/apps/emqx_rule_engine/src/emqx_rule_api_schema.erl index 862aea3b3..20363e726 100644 --- a/apps/emqx_rule_engine/src/emqx_rule_api_schema.erl +++ b/apps/emqx_rule_engine/src/emqx_rule_api_schema.erl @@ -117,7 +117,7 @@ fields("rule_apply_test") -> default => #{} } )}, - {"stop_action_after_template_render", + {"stop_action_after_template_rendering", sc( typerefl:boolean(), #{ diff --git a/apps/emqx_rule_engine/src/emqx_rule_engine_api.erl b/apps/emqx_rule_engine/src/emqx_rule_engine_api.erl index c0514b82b..d203dd915 100644 --- a/apps/emqx_rule_engine/src/emqx_rule_engine_api.erl +++ b/apps/emqx_rule_engine/src/emqx_rule_engine_api.erl @@ -268,8 +268,8 @@ schema("/rules/:id/test") -> 'operationId' => '/rules/:id/test', post => #{ tags => [<<"rules">>], - description => ?DESC("api8"), - summary => <<"Apply a rule with the given message and environment">>, + description => ?DESC("api11"), + summary => <<"Apply a rule for testing">>, 'requestBody' => rule_apply_test_schema(), responses => #{ 400 => error_schema('BAD_REQUEST', "Invalid Parameters"), diff --git a/apps/emqx_rule_engine/src/emqx_rule_sqltester.erl b/apps/emqx_rule_engine/src/emqx_rule_sqltester.erl index fc4d2614f..342a8d9f9 100644 --- a/apps/emqx_rule_engine/src/emqx_rule_sqltester.erl +++ b/apps/emqx_rule_engine/src/emqx_rule_sqltester.erl @@ -29,7 +29,7 @@ apply_rule( #{ context := Context, environment := Env, - stop_action_after_template_render := StopAfterRender + stop_action_after_template_rendering := StopAfterRender } ) -> {ok, Rule} = emqx_rule_engine:get_rule(RuleId), 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 31a462de3..2b77f9c3d 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 @@ -30,9 +30,6 @@ all() -> init_per_suite(Config) -> application:load(emqx_conf), - % ok = emqx_common_test_helpers:load_config(emqx_rule_engine_schema, ?CONF_DEFAULT), - % ok = emqx_common_test_helpers:start_apps([emqx_conf, emqx, emqx_rule_engine, emqx_bridge, emqx_bridge_http]), - Apps = emqx_cth_suite:start( [ emqx, @@ -125,7 +122,7 @@ basic_apply_rule_test_helper(Config, TraceType, StopAfterRender) -> Params = #{ % body => #{ <<"context">> => Context, - <<"stop_action_after_template_render">> => StopAfterRender + <<"stop_action_after_template_rendering">> => StopAfterRender % } }, emqx_trace:check(), diff --git a/rel/i18n/emqx_rule_api_schema.hocon b/rel/i18n/emqx_rule_api_schema.hocon index 0289f53ab..7f684e8ef 100644 --- a/rel/i18n/emqx_rule_api_schema.hocon +++ b/rel/i18n/emqx_rule_api_schema.hocon @@ -66,6 +66,18 @@ test_context.desc: test_context.label: """Event Conetxt""" +test_rule_environment.desc: +"""The environment that will be passed to the rule when it is applied. A default environment will be used if no environment is given.""" + +test_rule_environment.label: +"""Event Environment""" + +stop_action_after_template_render.desc: +"""Set this to true if the action should be stopped after its template has been rendered.""" + +stop_action_after_template_render.label: +"""Stop Action After Template Rendering""" + node_node.desc: """The node name""" diff --git a/rel/i18n/emqx_rule_engine_api.hocon b/rel/i18n/emqx_rule_engine_api.hocon index 385b71ddc..0745a108d 100644 --- a/rel/i18n/emqx_rule_engine_api.hocon +++ b/rel/i18n/emqx_rule_engine_api.hocon @@ -90,4 +90,10 @@ api9.desc: api9.label: """Get configuration""" +api11.desc: +"""Apply a rule with the given message and environment""" + +api11.label: +"""Apply Rule""" + } From 958748cf7ff2117cb049aa168d6de4ff47c05d79 Mon Sep 17 00:00:00 2001 From: Kjell Winblad Date: Tue, 9 Apr 2024 11:10:39 +0200 Subject: [PATCH 09/23] test: fix inter test suite problem --- apps/emqx_rule_engine/rebar.config | 8 +++++++ .../emqx_rule_engine_api_rule_apply_SUITE.erl | 21 ++++++++++++------- 2 files changed, 21 insertions(+), 8 deletions(-) diff --git a/apps/emqx_rule_engine/rebar.config b/apps/emqx_rule_engine/rebar.config index 07c53d3e3..d51bffa20 100644 --- a/apps/emqx_rule_engine/rebar.config +++ b/apps/emqx_rule_engine/rebar.config @@ -5,6 +5,14 @@ {emqx_utils, {path, "../emqx_utils"}} ]}. +{profiles, [ + {test, [ + {deps, [ + {emqx_bridge_http, {path, "../emqx_bridge_http"}} + ]} + ]} +]}. + {erl_opts, [ warn_unused_vars, warn_shadow_vars, 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 2b77f9c3d..576806464 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 @@ -30,15 +30,20 @@ all() -> init_per_suite(Config) -> application:load(emqx_conf), + AppsToStart = [ + emqx, + emqx_conf, + emqx_connector, + emqx_bridge, + emqx_bridge_http, + emqx_rule_engine + ], + %% I don't know why we need to stop the apps and then start them but if we + %% don't do this and other suites run before this suite the test cases will + %% fail as it seems like the connector silently refuses to start. + ok = emqx_cth_suite:stop(AppsToStart), Apps = emqx_cth_suite:start( - [ - emqx, - emqx_conf, - emqx_connector, - emqx_bridge_http, - emqx_bridge, - emqx_rule_engine - ], + AppsToStart, #{work_dir => emqx_cth_suite:work_dir(Config)} ), emqx_mgmt_api_test_util:init_suite(), From 3898950017f4dc8eee4dfbd23fa19a6931b84df2 Mon Sep 17 00:00:00 2001 From: Kjell Winblad Date: Tue, 9 Apr 2024 11:38:35 +0200 Subject: [PATCH 10/23] test: fix test by adding dependency --- apps/emqx/rebar.config | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/apps/emqx/rebar.config b/apps/emqx/rebar.config index 4e850b2cc..66600cebc 100644 --- a/apps/emqx/rebar.config +++ b/apps/emqx/rebar.config @@ -46,7 +46,8 @@ {meck, "0.9.2"}, {proper, "1.4.0"}, {bbmustache, "1.10.0"}, - {emqtt, {git, "https://github.com/emqx/emqtt", {tag, "1.10.0"}}} + {emqtt, {git, "https://github.com/emqx/emqtt", {tag, "1.10.0"}}}, + {emqx_rule_engine, {path, "../emqx_rule_engine"}} ]}, {extra_src_dirs, [ {"test", [recursive]}, @@ -58,7 +59,8 @@ {meck, "0.9.2"}, {proper, "1.4.0"}, {bbmustache, "1.10.0"}, - {emqtt, {git, "https://github.com/emqx/emqtt", {tag, "1.9.7"}}} + {emqtt, {git, "https://github.com/emqx/emqtt", {tag, "1.9.7"}}}, + {emqx_rule_engine, {path, "../emqx_rule_engine"}} ]}, {extra_src_dirs, [{"test", [recursive]}]} ]} From 7bcd553786ff4825a37ff2662a86ecc567c0adfe Mon Sep 17 00:00:00 2001 From: Kjell Winblad Date: Tue, 9 Apr 2024 14:08:46 +0200 Subject: [PATCH 11/23] test: move test case with rule_engine dep from emqx to emqx_rule_engine --- apps/emqx/rebar.config | 6 +- apps/emqx/test/emqx_trace_handler_SUITE.erl | 85 +------------ .../test/emqx_rule_engine_SUITE.erl | 115 +++++++++++++++++- 3 files changed, 119 insertions(+), 87 deletions(-) diff --git a/apps/emqx/rebar.config b/apps/emqx/rebar.config index 66600cebc..4e850b2cc 100644 --- a/apps/emqx/rebar.config +++ b/apps/emqx/rebar.config @@ -46,8 +46,7 @@ {meck, "0.9.2"}, {proper, "1.4.0"}, {bbmustache, "1.10.0"}, - {emqtt, {git, "https://github.com/emqx/emqtt", {tag, "1.10.0"}}}, - {emqx_rule_engine, {path, "../emqx_rule_engine"}} + {emqtt, {git, "https://github.com/emqx/emqtt", {tag, "1.10.0"}}} ]}, {extra_src_dirs, [ {"test", [recursive]}, @@ -59,8 +58,7 @@ {meck, "0.9.2"}, {proper, "1.4.0"}, {bbmustache, "1.10.0"}, - {emqtt, {git, "https://github.com/emqx/emqtt", {tag, "1.9.7"}}}, - {emqx_rule_engine, {path, "../emqx_rule_engine"}} + {emqtt, {git, "https://github.com/emqx/emqtt", {tag, "1.9.7"}}} ]}, {extra_src_dirs, [{"test", [recursive]}]} ]} diff --git a/apps/emqx/test/emqx_trace_handler_SUITE.erl b/apps/emqx/test/emqx_trace_handler_SUITE.erl index 85a9c056b..59a472f3e 100644 --- a/apps/emqx/test/emqx_trace_handler_SUITE.erl +++ b/apps/emqx/test/emqx_trace_handler_SUITE.erl @@ -20,7 +20,6 @@ -compile(nowarn_export_all). -include_lib("eunit/include/eunit.hrl"). --include_lib("snabbkaffe/include/test_macros.hrl"). -include_lib("common_test/include/ct.hrl"). -define(CLIENT, [ @@ -30,12 +29,11 @@ {password, <<"pass">>} ]). -all() -> - [t_trace_clientid, t_trace_topic, t_trace_ip_address, t_trace_clientid_utf8, t_trace_rule_id]. +all() -> [t_trace_clientid, t_trace_topic, t_trace_ip_address, t_trace_clientid_utf8]. init_per_suite(Config) -> Apps = emqx_cth_suite:start( - [emqx, emqx_rule_engine], + [emqx], #{work_dir => emqx_cth_suite:work_dir(Config)} ), [{apps, Apps} | Config]. @@ -207,79 +205,6 @@ t_trace_topic(_Config) -> ?assertEqual([], emqx_trace_handler:running()), emqtt:disconnect(T). -create_rule(Name, SQL) -> - Rule = emqx_rule_engine_SUITE:make_simple_rule(Name, SQL), - {ok, _} = emqx_rule_engine:create_rule(Rule). - -t_trace_rule_id(_Config) -> - %% Start MQTT Client - {ok, T} = emqtt:start_link(?CLIENT), - emqtt:connect(T), - %% Create rules - create_rule( - <<"test_rule_id_1">>, - <<"select 1 as rule_number from \"rule_1_topic\"">> - ), - create_rule( - <<"test_rule_id_2">>, - <<"select 2 as rule_number from \"rule_2_topic\"">> - ), - %% Start tracing - ok = emqx_trace_handler:install( - "CLI-RULE-1", ruleid, <<"test_rule_id_1">>, all, "tmp/rule_trace_1.log" - ), - ok = emqx_trace_handler:install( - "CLI-RULE-2", ruleid, <<"test_rule_id_2">>, all, "tmp/rule_trace_2.log" - ), - emqx_trace:check(), - ok = filesync("CLI-RULE-1", ruleid), - ok = filesync("CLI-RULE-2", ruleid), - - %% Verify the tracing file exits - ?assert(filelib:is_regular("tmp/rule_trace_1.log")), - ?assert(filelib:is_regular("tmp/rule_trace_2.log")), - - %% Get current traces - ?assertMatch( - [ - #{ - type := ruleid, - filter := <<"test_rule_id_1">>, - level := debug, - dst := "tmp/rule_trace_1.log", - name := <<"CLI-RULE-1">> - }, - #{ - type := ruleid, - filter := <<"test_rule_id_2">>, - name := <<"CLI-RULE-2">>, - level := debug, - dst := "tmp/rule_trace_2.log" - } - ], - emqx_trace_handler:running() - ), - - %% Trigger rule - emqtt:publish(T, <<"rule_1_topic">>, <<"my_traced_message">>), - ?retry( - 100, - 5, - begin - ok = filesync("CLI-RULE-1", ruleid), - {ok, Bin} = file:read_file("tmp/rule_trace_1.log"), - ?assertNotEqual(nomatch, binary:match(Bin, [<<"my_traced_message">>])) - end - ), - ok = filesync("CLI-RULE-2", ruleid), - ?assert(filelib:file_size("tmp/rule_trace_2.log") =:= 0), - - %% Stop tracing - ok = emqx_trace_handler:uninstall(ruleid, <<"CLI-RULE-1">>), - ok = emqx_trace_handler:uninstall(ruleid, <<"CLI-RULE-2">>), - ?assertEqual([], emqx_trace_handler:running()), - emqtt:disconnect(T). - t_trace_ip_address(_Config) -> {ok, T} = emqtt:start_link(?CLIENT), emqtt:connect(T), @@ -347,11 +272,11 @@ t_trace_ip_address(_Config) -> filesync(Name, Type) -> ct:sleep(50), - filesync(Name, Type, 5). + filesync(Name, Type, 3). %% sometime the handler process is not started yet. -filesync(Name, Type, 0) -> - ct:fail("Handler process not started ~p ~p", [Name, Type]); +filesync(_Name, _Type, 0) -> + ok; filesync(Name0, Type, Retry) -> Name = case is_binary(Name0) of diff --git a/apps/emqx_rule_engine/test/emqx_rule_engine_SUITE.erl b/apps/emqx_rule_engine/test/emqx_rule_engine_SUITE.erl index 76cc23c0d..5040d15b3 100644 --- a/apps/emqx_rule_engine/test/emqx_rule_engine_SUITE.erl +++ b/apps/emqx_rule_engine/test/emqx_rule_engine_SUITE.erl @@ -43,7 +43,8 @@ all() -> {group, metrics}, {group, metrics_simple}, {group, metrics_fail}, - {group, metrics_fail_simple} + {group, metrics_fail_simple}, + {group, tracing} ]. suite() -> @@ -142,6 +143,9 @@ groups() -> {metrics_fail_simple, [], [ t_rule_metrics_sync_fail, t_rule_metrics_async_fail + ]}, + {tracing, [], [ + t_trace_rule_id ]} ]. @@ -154,13 +158,13 @@ init_per_suite(Config) -> emqx_rule_funcs_demo:module_info(), application:load(emqx_conf), ok = emqx_common_test_helpers:start_apps( - [emqx_conf, emqx_rule_engine, emqx_auth, emqx_bridge], + [emqx, emqx_conf, emqx_rule_engine, emqx_auth, emqx_bridge], fun set_special_configs/1 ), Config. end_per_suite(_Config) -> - emqx_common_test_helpers:stop_apps([emqx_conf, emqx_rule_engine]), + emqx_common_test_helpers:stop_apps([emqx, emqx_conf, emqx_rule_engine, emqx_auth, emqx_bridge]), ok. set_special_configs(emqx_auth) -> @@ -3632,6 +3636,111 @@ create_bridge(Type, Name, Config) -> {ok, _Bridge} = emqx_bridge:create(Type, Name, Config), emqx_bridge_resource:bridge_id(Type, Name). +create_rule(Name, SQL) -> + Rule = emqx_rule_engine_SUITE:make_simple_rule(Name, SQL), + {ok, _} = emqx_rule_engine:create_rule(Rule). + +emqtt_client_config() -> + [ + {host, "localhost"}, + {clientid, <<"client">>}, + {username, <<"testuser">>}, + {password, <<"pass">>} + ]. + +filesync(Name, Type) -> + ct:sleep(50), + filesync(Name, Type, 5). + +%% sometime the handler process is not started yet. +filesync(Name, Type, 0) -> + ct:fail("Handler process not started ~p ~p", [Name, Type]); +filesync(Name0, Type, Retry) -> + Name = + case is_binary(Name0) of + true -> Name0; + false -> list_to_binary(Name0) + end, + try + Handler = binary_to_atom(<<"trace_", (atom_to_binary(Type))/binary, "_", Name/binary>>), + ok = logger_disk_log_h:filesync(Handler) + catch + E:R -> + ct:pal("Filesync error:~p ~p~n", [{Name, Type, Retry}, {E, R}]), + ct:sleep(100), + filesync(Name, Type, Retry - 1) + end. + +t_trace_rule_id(_Config) -> + %% Start MQTT Client + emqx_trace_SUITE:reload(), + {ok, T} = emqtt:start_link(emqtt_client_config()), + emqtt:connect(T), + %% Create rules + create_rule( + <<"test_rule_id_1">>, + <<"select 1 as rule_number from \"rule_1_topic\"">> + ), + create_rule( + <<"test_rule_id_2">>, + <<"select 2 as rule_number from \"rule_2_topic\"">> + ), + %% Start tracing + ok = emqx_trace_handler:install( + "CLI-RULE-1", ruleid, <<"test_rule_id_1">>, all, "tmp/rule_trace_1.log" + ), + ok = emqx_trace_handler:install( + "CLI-RULE-2", ruleid, <<"test_rule_id_2">>, all, "tmp/rule_trace_2.log" + ), + emqx_trace:check(), + ok = filesync("CLI-RULE-1", ruleid), + ok = filesync("CLI-RULE-2", ruleid), + + %% Verify the tracing file exits + ?assert(filelib:is_regular("tmp/rule_trace_1.log")), + ?assert(filelib:is_regular("tmp/rule_trace_2.log")), + + %% Get current traces + ?assertMatch( + [ + #{ + type := ruleid, + filter := <<"test_rule_id_1">>, + level := debug, + dst := "tmp/rule_trace_1.log", + name := <<"CLI-RULE-1">> + }, + #{ + type := ruleid, + filter := <<"test_rule_id_2">>, + name := <<"CLI-RULE-2">>, + level := debug, + dst := "tmp/rule_trace_2.log" + } + ], + emqx_trace_handler:running() + ), + + %% Trigger rule + emqtt:publish(T, <<"rule_1_topic">>, <<"my_traced_message">>), + ?retry( + 100, + 5, + begin + ok = filesync("CLI-RULE-1", ruleid), + {ok, Bin} = file:read_file("tmp/rule_trace_1.log"), + ?assertNotEqual(nomatch, binary:match(Bin, [<<"my_traced_message">>])) + end + ), + ok = filesync("CLI-RULE-2", ruleid), + ?assert(filelib:file_size("tmp/rule_trace_2.log") =:= 0), + + %% Stop tracing + ok = emqx_trace_handler:uninstall(ruleid, <<"CLI-RULE-1">>), + ok = emqx_trace_handler:uninstall(ruleid, <<"CLI-RULE-2">>), + ?assertEqual([], emqx_trace_handler:running()), + emqtt:disconnect(T). + %%------------------------------------------------------------------------------ %% Internal helpers %%------------------------------------------------------------------------------ From 43ff2e3a743f6c2f34e5d0c83897c572b3cf0af7 Mon Sep 17 00:00:00 2001 From: Kjell Winblad Date: Tue, 9 Apr 2024 16:17:26 +0200 Subject: [PATCH 12/23] docs: add change log entry --- changes/ce/feat-12827.en.md | 1 + 1 file changed, 1 insertion(+) create mode 100644 changes/ce/feat-12827.en.md diff --git a/changes/ce/feat-12827.en.md b/changes/ce/feat-12827.en.md new file mode 100644 index 000000000..633a33d6b --- /dev/null +++ b/changes/ce/feat-12827.en.md @@ -0,0 +1 @@ +It is now possible to trace rules with a new Rule ID trace filter as well as with the Client ID filter. For testing purposes it is now also possible to use a new HTTP API endpoint (rules/:id/test) to artificially apply a rule and optionally stop its actions after they have been rendered. From 31142df5cfc375a744d41faf485b72873cd54bbd Mon Sep 17 00:00:00 2001 From: Kjell Winblad Date: Tue, 9 Apr 2024 16:20:37 +0200 Subject: [PATCH 13/23] fix: default value of stop_action_after_template_rendering to true This commit changes the default value for the stop_action_after_template_rendering option of the apply rule HTTP API endpoint so that it is true instead of false. --- apps/emqx_rule_engine/src/emqx_rule_api_schema.erl | 2 +- rel/i18n/emqx_rule_api_schema.hocon | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/apps/emqx_rule_engine/src/emqx_rule_api_schema.erl b/apps/emqx_rule_engine/src/emqx_rule_api_schema.erl index 20363e726..5e19b33ee 100644 --- a/apps/emqx_rule_engine/src/emqx_rule_api_schema.erl +++ b/apps/emqx_rule_engine/src/emqx_rule_api_schema.erl @@ -123,7 +123,7 @@ fields("rule_apply_test") -> #{ desc => ?DESC("stop_action_after_template_render"), - default => false + default => true } )} ]; diff --git a/rel/i18n/emqx_rule_api_schema.hocon b/rel/i18n/emqx_rule_api_schema.hocon index 7f684e8ef..25535d0ca 100644 --- a/rel/i18n/emqx_rule_api_schema.hocon +++ b/rel/i18n/emqx_rule_api_schema.hocon @@ -73,7 +73,7 @@ test_rule_environment.label: """Event Environment""" stop_action_after_template_render.desc: -"""Set this to true if the action should be stopped after its template has been rendered.""" +"""Set this to true if the action should be stopped after its template has been rendered (default is true).""" stop_action_after_template_render.label: """Stop Action After Template Rendering""" From 9998940aa22626a263d39a7b2e97b851d4b53b2e Mon Sep 17 00:00:00 2001 From: Kjell Winblad Date: Thu, 11 Apr 2024 16:48:43 +0200 Subject: [PATCH 14/23] fix(trace): several improvements thanks to comments from @zmstone --- apps/emqx/src/emqx_trace/emqx_trace.erl | 12 +-- .../src/emqx_bridge_http_connector.erl | 73 +++++++------------ apps/emqx_rule_engine/rebar.config | 3 +- .../src/emqx_rule_api_schema.erl | 9 --- .../src/emqx_rule_engine.app.src | 4 +- .../src/emqx_rule_runtime.erl | 38 +++++++--- .../src/emqx_rule_sqltester.erl | 44 +++++------ .../test/emqx_rule_engine_SUITE.erl | 4 +- rel/i18n/emqx_rule_api_schema.hocon | 6 -- 9 files changed, 87 insertions(+), 106 deletions(-) diff --git a/apps/emqx/src/emqx_trace/emqx_trace.erl b/apps/emqx/src/emqx_trace/emqx_trace.erl index 408644128..4e182f300 100644 --- a/apps/emqx/src/emqx_trace/emqx_trace.erl +++ b/apps/emqx/src/emqx_trace/emqx_trace.erl @@ -88,16 +88,18 @@ unsubscribe(Topic, SubOpts) -> ?TRACE("UNSUBSCRIBE", "unsubscribe", #{topic => Topic, sub_opts => SubOpts}). rendered_action_template(ActionID, RenderResult) -> - Msg = io_lib:format("action_template_rendered(~s)", [ActionID]), + Msg = lists:flatten(io_lib:format("action_template_rendered(~ts)", [ActionID])), TraceResult = ?TRACE("QUERY_RENDER", Msg, RenderResult), case logger:get_process_metadata() of #{stop_action_after_render := true} -> %% We throw an unrecoverable error to stop action before the %% resource is called/modified - StopMsg = io_lib:format( - "action_stopped_after_render(~s): " - "Action stopped after template render due to test setting.", - [ActionID] + StopMsg = lists:flatten( + io_lib:format( + "action_stopped_after_render(~ts): " + "Action stopped after template render due to test setting.", + [ActionID] + ) ), MsgBin = iolist_to_binary(StopMsg), error({unrecoverable_error, MsgBin}); diff --git a/apps/emqx_bridge_http/src/emqx_bridge_http_connector.erl b/apps/emqx_bridge_http/src/emqx_bridge_http_connector.erl index 46b3d5e1f..19b7ef875 100644 --- a/apps/emqx_bridge_http/src/emqx_bridge_http_connector.erl +++ b/apps/emqx_bridge_http/src/emqx_bridge_http_connector.erl @@ -371,29 +371,7 @@ on_query( } ), NRequest = formalize_request(Method, BasePath, Request), - case NRequest of - {Path, Headers} -> - emqx_trace:rendered_action_template( - InstId, - #{ - path => Path, - method => Method, - headers => Headers, - timeout => Timeout - } - ); - {Path, Headers, Body} -> - emqx_trace:rendered_action_template( - InstId, - #{ - path => Path, - method => Method, - headers => Headers, - timeout => Timeout, - body => Body - } - ) - end, + trace_rendered_action_template(InstId, Method, NRequest, Timeout), Worker = resolve_pool_worker(State, KeyOrNum), Result0 = ehttpc:request( Worker, @@ -503,29 +481,7 @@ on_query_async( } ), NRequest = formalize_request(Method, BasePath, Request), - case NRequest of - {Path, Headers} -> - emqx_trace:rendered_action_template( - InstId, - #{ - path => Path, - method => Method, - headers => Headers, - timeout => Timeout - } - ); - {Path, Headers, Body} -> - emqx_trace:rendered_action_template( - InstId, - #{ - path => Path, - method => Method, - headers => Headers, - timeout => Timeout, - body => Body - } - ) - end, + trace_rendered_action_template(InstId, Method, NRequest, Timeout), MaxAttempts = maps:get(max_attempts, State, 3), Context = #{ attempt => 1, @@ -545,6 +501,31 @@ on_query_async( ), {ok, Worker}. +trace_rendered_action_template(InstId, Method, NRequest, Timeout) -> + case NRequest of + {Path, Headers} -> + emqx_trace:rendered_action_template( + InstId, + #{ + path => Path, + method => Method, + headers => Headers, + timeout => Timeout + } + ); + {Path, Headers, Body} -> + emqx_trace:rendered_action_template( + InstId, + #{ + path => Path, + method => Method, + headers => emqx_utils_redact:redact_headers(Headers), + timeout => Timeout, + body => Body + } + ) + end. + resolve_pool_worker(State, undefined) -> resolve_pool_worker(State, self()); resolve_pool_worker(#{pool_name := PoolName} = State, Key) -> diff --git a/apps/emqx_rule_engine/rebar.config b/apps/emqx_rule_engine/rebar.config index d51bffa20..0f00f15c6 100644 --- a/apps/emqx_rule_engine/rebar.config +++ b/apps/emqx_rule_engine/rebar.config @@ -2,7 +2,8 @@ {deps, [ {emqx, {path, "../emqx"}}, - {emqx_utils, {path, "../emqx_utils"}} + {emqx_utils, {path, "../emqx_utils"}}, + {emqx_modules, {path, "../emqx_modules"}} ]}. {profiles, [ diff --git a/apps/emqx_rule_engine/src/emqx_rule_api_schema.erl b/apps/emqx_rule_engine/src/emqx_rule_api_schema.erl index 5e19b33ee..f4685222c 100644 --- a/apps/emqx_rule_engine/src/emqx_rule_api_schema.erl +++ b/apps/emqx_rule_engine/src/emqx_rule_api_schema.erl @@ -108,15 +108,6 @@ fields("rule_test") -> fields("rule_apply_test") -> [ rule_input_message_context(), - {"environment", - sc( - typerefl:map(), - #{ - desc => - ?DESC("test_rule_environment"), - default => #{} - } - )}, {"stop_action_after_template_rendering", sc( typerefl:boolean(), diff --git a/apps/emqx_rule_engine/src/emqx_rule_engine.app.src b/apps/emqx_rule_engine/src/emqx_rule_engine.app.src index 1768141ae..1fed922dd 100644 --- a/apps/emqx_rule_engine/src/emqx_rule_engine.app.src +++ b/apps/emqx_rule_engine/src/emqx_rule_engine.app.src @@ -17,7 +17,9 @@ %% rule_engine should wait for bridge connector start, %% it's will check action/connector ref's exist. emqx_bridge, - emqx_connector + emqx_connector, + %% Needed to start the tracing functionality + emqx_modules ]}, {mod, {emqx_rule_engine_app, []}}, {env, []}, diff --git a/apps/emqx_rule_engine/src/emqx_rule_runtime.erl b/apps/emqx_rule_engine/src/emqx_rule_runtime.erl index f90b5a974..d4cde213d 100644 --- a/apps/emqx_rule_engine/src/emqx_rule_runtime.erl +++ b/apps/emqx_rule_engine/src/emqx_rule_runtime.erl @@ -420,13 +420,13 @@ handle_action(RuleId, ActId, Selected, Envs) -> end. -define(IS_RES_DOWN(R), R == stopped; R == not_connected; R == not_found; R == unhealthy_target). -do_handle_action(_RuleId, {bridge, BridgeType, BridgeName, ResId} = Action, Selected, _Envs) -> +do_handle_action(RuleId, {bridge, BridgeType, BridgeName, ResId} = Action, Selected, _Envs) -> trace_action_bridge("BRIDGE", Action, "bridge_action", #{}, debug), - TraceCtx = do_handle_action_get_trace_context(Action), - ReplyTo = {fun ?MODULE:inc_action_metrics/2, [TraceCtx], #{reply_dropped => true}}, + {TraceCtx, IncCtx} = do_handle_action_get_trace_inc_metrics_context(RuleId, Action), + ReplyTo = {fun ?MODULE:inc_action_metrics/2, [IncCtx], #{reply_dropped => true}}, case emqx_bridge:send_message(BridgeType, BridgeName, ResId, Selected, #{ - reply_to => ReplyTo, trace_ctx => maps:remove(action_id, TraceCtx) + reply_to => ReplyTo, trace_ctx => TraceCtx }) of {error, Reason} when Reason == bridge_not_found; Reason == bridge_stopped -> @@ -437,20 +437,20 @@ do_handle_action(_RuleId, {bridge, BridgeType, BridgeName, ResId} = Action, Sele Result end; do_handle_action( - _RuleId, + RuleId, {bridge_v2, BridgeType, BridgeName} = Action, Selected, _Envs ) -> trace_action_bridge("BRIDGE", Action, "bridge_action", #{}, debug), - TraceCtx = do_handle_action_get_trace_context(Action), - ReplyTo = {fun ?MODULE:inc_action_metrics/2, [TraceCtx], #{reply_dropped => true}}, + {TraceCtx, IncCtx} = do_handle_action_get_trace_inc_metrics_context(RuleId, Action), + ReplyTo = {fun ?MODULE:inc_action_metrics/2, [IncCtx], #{reply_dropped => true}}, case emqx_bridge_v2:send_message( BridgeType, BridgeName, Selected, - #{reply_to => ReplyTo, trace_ctx => maps:remove(action_id, TraceCtx)} + #{reply_to => ReplyTo, trace_ctx => TraceCtx} ) of {error, Reason} when Reason == bridge_not_found; Reason == bridge_stopped -> @@ -460,17 +460,31 @@ do_handle_action( Result -> Result end; -do_handle_action(_RuleId, #{mod := Mod, func := Func} = Action, Selected, Envs) -> +do_handle_action(RuleId, #{mod := Mod, func := Func} = Action, Selected, Envs) -> trace_action(Action, "call_action_function"), %% the function can also throw 'out_of_service' Args = maps:get(args, Action, []), Result = Mod:Func(Selected, Envs, Args), - TraceCtx = do_handle_action_get_trace_context(Action), - inc_action_metrics(TraceCtx, Result), + {_, IncCtx} = do_handle_action_get_trace_inc_metrics_context(RuleId, Action), + inc_action_metrics(IncCtx, Result), trace_action(Action, "call_action_function_result", #{result => Result}, debug), Result. -do_handle_action_get_trace_context(Action) -> +do_handle_action_get_trace_inc_metrics_context(RuleID, Action) -> + case emqx_trace:list() of + [] -> + %% As a performance/memory optimization, we don't create any trace + %% context if there are no trace patterns. + {undefined, #{ + rule_id => RuleID, + action_id => Action + }}; + _List -> + Ctx = do_handle_action_get_trace_inc_metrics_context_unconditionally(Action), + {maps:remove(action_id, Ctx), Ctx} + end. + +do_handle_action_get_trace_inc_metrics_context_unconditionally(Action) -> Metadata = logger:get_process_metadata(), StopAfterRender = maps:get(stop_action_after_render, Metadata, false), case Metadata of diff --git a/apps/emqx_rule_engine/src/emqx_rule_sqltester.erl b/apps/emqx_rule_engine/src/emqx_rule_sqltester.erl index 342a8d9f9..83f29eef3 100644 --- a/apps/emqx_rule_engine/src/emqx_rule_sqltester.erl +++ b/apps/emqx_rule_engine/src/emqx_rule_sqltester.erl @@ -28,7 +28,6 @@ apply_rule( RuleId, #{ context := Context, - environment := Env, stop_action_after_template_rendering := StopAfterRender } ) -> @@ -39,30 +38,32 @@ apply_rule( true -> %% test if the topic matches the topic filters in the rule case emqx_topic:match_any(InTopic, EventTopics) of - true -> do_apply_matched_rule(Rule, Context, Env, StopAfterRender); - false -> {error, nomatch} + true -> + do_apply_matched_rule( + Rule, + Context, + StopAfterRender + ); + false -> + {error, nomatch} end; false -> case lists:member(InTopic, EventTopics) of true -> %% the rule is for both publish and events, test it directly - do_apply_matched_rule(Rule, Context, Env, StopAfterRender); + do_apply_matched_rule(Rule, Context, StopAfterRender); false -> {error, nomatch} end end. -do_apply_matched_rule(Rule, Context, Env, StopAfterRender) -> +do_apply_matched_rule(Rule, Context, StopAfterRender) -> update_process_trace_metadata(StopAfterRender), - Env1 = - case Env of - M when map_size(M) =:= 0 -> - %% Use the default environment if no environment is provided - default_apply_rule_environment(); - _ -> - Env - end, - ApplyRuleRes = emqx_rule_runtime:apply_rule(Rule, Context, Env1), + ApplyRuleRes = emqx_rule_runtime:apply_rule( + Rule, + Context, + apply_rule_environment() + ), reset_trace_process_metadata(StopAfterRender), ApplyRuleRes. @@ -80,16 +81,11 @@ reset_trace_process_metadata(true = _StopAfterRender) -> reset_trace_process_metadata(false = _StopAfterRender) -> ok. -default_apply_rule_environment() -> - #{ - headers => #{ - protocol => mqtt, - username => undefined, - peerhost => {127, 0, 0, 1}, - proto_ver => 5, - properties => #{} - } - }. +%% At the time of writing the environment passed to the apply rule function is +%% not used at all for normal actions. When it is used for custom functions it +%% is first merged with the context so there does not seem to be any need to +%% set this to anything else then the empty map. +apply_rule_environment() -> #{}. -spec test(#{sql := binary(), context := map()}) -> {ok, map() | list()} | {error, term()}. test(#{sql := Sql, context := Context}) -> diff --git a/apps/emqx_rule_engine/test/emqx_rule_engine_SUITE.erl b/apps/emqx_rule_engine/test/emqx_rule_engine_SUITE.erl index 5040d15b3..b0ca00a0e 100644 --- a/apps/emqx_rule_engine/test/emqx_rule_engine_SUITE.erl +++ b/apps/emqx_rule_engine/test/emqx_rule_engine_SUITE.erl @@ -158,13 +158,13 @@ init_per_suite(Config) -> emqx_rule_funcs_demo:module_info(), application:load(emqx_conf), ok = emqx_common_test_helpers:start_apps( - [emqx, emqx_conf, emqx_rule_engine, emqx_auth, emqx_bridge], + [emqx_conf, emqx_rule_engine, emqx_auth, emqx_bridge], fun set_special_configs/1 ), Config. end_per_suite(_Config) -> - emqx_common_test_helpers:stop_apps([emqx, emqx_conf, emqx_rule_engine, emqx_auth, emqx_bridge]), + emqx_common_test_helpers:stop_apps([emqx_conf, emqx_rule_engine, emqx_auth, emqx_bridge]), ok. set_special_configs(emqx_auth) -> diff --git a/rel/i18n/emqx_rule_api_schema.hocon b/rel/i18n/emqx_rule_api_schema.hocon index 25535d0ca..68c6a560d 100644 --- a/rel/i18n/emqx_rule_api_schema.hocon +++ b/rel/i18n/emqx_rule_api_schema.hocon @@ -66,12 +66,6 @@ test_context.desc: test_context.label: """Event Conetxt""" -test_rule_environment.desc: -"""The environment that will be passed to the rule when it is applied. A default environment will be used if no environment is given.""" - -test_rule_environment.label: -"""Event Environment""" - stop_action_after_template_render.desc: """Set this to true if the action should be stopped after its template has been rendered (default is true).""" From aa950f97fa6ed07be927c3e99239a18b82ada85a Mon Sep 17 00:00:00 2001 From: Kjell Winblad Date: Fri, 12 Apr 2024 11:22:46 +0200 Subject: [PATCH 15/23] test: fix tests with missing application --- .../test/emqx_bridge_rabbitmq_test_utils.erl | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/apps/emqx_bridge_rabbitmq/test/emqx_bridge_rabbitmq_test_utils.erl b/apps/emqx_bridge_rabbitmq/test/emqx_bridge_rabbitmq_test_utils.erl index 47df47976..2110a0520 100644 --- a/apps/emqx_bridge_rabbitmq/test/emqx_bridge_rabbitmq_test_utils.erl +++ b/apps/emqx_bridge_rabbitmq/test/emqx_bridge_rabbitmq_test_utils.erl @@ -52,7 +52,7 @@ init_per_group(_Group, Config) -> common_init_per_group(Opts) -> emqx_common_test_helpers:render_and_load_app_config(emqx_conf), ok = emqx_common_test_helpers:start_apps([ - emqx_conf, emqx_bridge, emqx_bridge_rabbitmq, emqx_rule_engine + emqx_conf, emqx_bridge, emqx_bridge_rabbitmq, emqx_rule_engine, emqx_modules ]), ok = emqx_connector_test_helpers:start_apps([emqx_resource]), {ok, _} = application:ensure_all_started(emqx_connector), @@ -116,7 +116,9 @@ end_per_group(_Group, Config) -> } = get_channel_connection(Config), amqp_channel:call(Channel, #'queue.purge'{queue = rabbit_mq_queue()}), emqx_mgmt_api_test_util:end_suite(), - ok = emqx_common_test_helpers:stop_apps([emqx_conf, emqx_bridge_rabbitmq, emqx_rule_engine]), + ok = emqx_common_test_helpers:stop_apps([ + emqx_conf, emqx_bridge_rabbitmq, emqx_rule_engine, emqx_modules + ]), ok = emqx_connector_test_helpers:stop_apps([emqx_resource]), _ = application:stop(emqx_connector), _ = application:stop(emqx_bridge), From f444c6fc328765bf5e5739d5e6ea636aa2654cbe Mon Sep 17 00:00:00 2001 From: Kjell Winblad Date: Fri, 12 Apr 2024 11:38:01 +0200 Subject: [PATCH 16/23] fix: pass stop_action_after_render=true in trace meta data Even if there is no trace we still need to pass stop_action_after_render=true in the trace meta data so that the action will be stopped. --- .../src/emqx_rule_runtime.erl | 28 +++++++++++++------ 1 file changed, 20 insertions(+), 8 deletions(-) diff --git a/apps/emqx_rule_engine/src/emqx_rule_runtime.erl b/apps/emqx_rule_engine/src/emqx_rule_runtime.erl index d4cde213d..7181fb59b 100644 --- a/apps/emqx_rule_engine/src/emqx_rule_runtime.erl +++ b/apps/emqx_rule_engine/src/emqx_rule_runtime.erl @@ -471,23 +471,35 @@ do_handle_action(RuleId, #{mod := Mod, func := Func} = Action, Selected, Envs) - Result. do_handle_action_get_trace_inc_metrics_context(RuleID, Action) -> - case emqx_trace:list() of - [] -> + case {emqx_trace:list(), logger:get_process_metadata()} of + {[], #{stop_action_after_render := true}} -> + %% Even if there is no trace we still need to pass + %% stop_action_after_render in the trace meta data so that the + %% action will be stopped. + { + #{ + stop_action_after_render => true + }, + #{ + rule_id => RuleID, + action_id => Action + } + }; + {[], _} -> %% As a performance/memory optimization, we don't create any trace %% context if there are no trace patterns. {undefined, #{ rule_id => RuleID, action_id => Action }}; - _List -> - Ctx = do_handle_action_get_trace_inc_metrics_context_unconditionally(Action), + {_List, TraceMeta} -> + Ctx = do_handle_action_get_trace_inc_metrics_context_unconditionally(Action, TraceMeta), {maps:remove(action_id, Ctx), Ctx} end. -do_handle_action_get_trace_inc_metrics_context_unconditionally(Action) -> - Metadata = logger:get_process_metadata(), - StopAfterRender = maps:get(stop_action_after_render, Metadata, false), - case Metadata of +do_handle_action_get_trace_inc_metrics_context_unconditionally(Action, TraceMeta) -> + StopAfterRender = maps:get(stop_action_after_render, TraceMeta, false), + case TraceMeta of #{ rule_id := RuleID, clientid := ClientID From ed5409fb6a6fa7449a2b983094fb9e8ccc554c06 Mon Sep 17 00:00:00 2001 From: Kjell Winblad Date: Fri, 12 Apr 2024 11:54:14 +0200 Subject: [PATCH 17/23] docs(trace): add emqx_ctl documentation for the new ruleid trace --- apps/emqx_management/src/emqx_mgmt_cli.erl | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/apps/emqx_management/src/emqx_mgmt_cli.erl b/apps/emqx_management/src/emqx_mgmt_cli.erl index ddbc60d5c..36013791c 100644 --- a/apps/emqx_management/src/emqx_mgmt_cli.erl +++ b/apps/emqx_management/src/emqx_mgmt_cli.erl @@ -512,7 +512,9 @@ trace(_) -> {"trace stop topic ", "Stop tracing for a topic on local node"}, {"trace start ip_address [] ", "Traces for a client ip on local node"}, - {"trace stop ip_address ", "Stop tracing for a client ip on local node"} + {"trace stop ip_address ", "Stop tracing for a client ip on local node"}, + {"trace start ruleid [] ", "Traces for a rule ID on local node"}, + {"trace stop ruleid ", "Stop tracing for a rule ID on local node"} ]). trace_on(Name, Type, Filter, Level, LogFile) -> @@ -583,6 +585,7 @@ traces(_) -> "and will end after seconds. The default value for is " ?DEFAULT_TRACE_DURATION " seconds."}, + {"traces start ruleid []", "Traces for a rule ID in cluster"}, {"traces stop ", "Stop trace in cluster"}, {"traces delete ", "Delete trace in cluster"} ]). From 6777f04780cae222403bd371bd9357a1eaa8c08f Mon Sep 17 00:00:00 2001 From: Kjell Winblad Date: Fri, 12 Apr 2024 15:21:25 +0200 Subject: [PATCH 18/23] fix: iolist_to_binrary -> unicode:characters_to_binary It is not always safe to use iolist_to_binrary on the output of an io_lib:format call with the ~ts placeholder. --- apps/emqx/src/emqx_trace/emqx_trace.erl | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/apps/emqx/src/emqx_trace/emqx_trace.erl b/apps/emqx/src/emqx_trace/emqx_trace.erl index 4e182f300..17580745a 100644 --- a/apps/emqx/src/emqx_trace/emqx_trace.erl +++ b/apps/emqx/src/emqx_trace/emqx_trace.erl @@ -101,7 +101,7 @@ rendered_action_template(ActionID, RenderResult) -> [ActionID] ) ), - MsgBin = iolist_to_binary(StopMsg), + MsgBin = unicode:characters_to_binary(StopMsg), error({unrecoverable_error, MsgBin}); _ -> ok From b4198185bc4b12f61e19beed00887e0aab7d0065 Mon Sep 17 00:00:00 2001 From: Kjell Winblad Date: Fri, 12 Apr 2024 15:27:03 +0200 Subject: [PATCH 19/23] fix(http connector): redact sensitive information from headers --- apps/emqx_bridge_http/src/emqx_bridge_http_connector.erl | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/apps/emqx_bridge_http/src/emqx_bridge_http_connector.erl b/apps/emqx_bridge_http/src/emqx_bridge_http_connector.erl index 19b7ef875..ec75922a7 100644 --- a/apps/emqx_bridge_http/src/emqx_bridge_http_connector.erl +++ b/apps/emqx_bridge_http/src/emqx_bridge_http_connector.erl @@ -509,7 +509,7 @@ trace_rendered_action_template(InstId, Method, NRequest, Timeout) -> #{ path => Path, method => Method, - headers => Headers, + headers => emqx_utils_redact:redact_headers(Headers), timeout => Timeout } ); From cf56050759d96806b1e1cb39a564cdf7f3acbb44 Mon Sep 17 00:00:00 2001 From: Kjell Winblad Date: Wed, 17 Apr 2024 16:12:12 +0200 Subject: [PATCH 20/23] feat: avoid mixing request with and without the stop_after_render flag Previously a batch of requests that was sent to a connector could contain both requests with the stop_after_rendering flag and requests without this flag. When this happened a warning message was generated and the stop_after_render flags for the batch would be ignored. This commit fixes so that a mixed batch is never created so there is no longer any need for a warning message or ignoring flags. --- apps/emqx_bridge/src/emqx_action_info.erl | 10 +- .../src/emqx_connector_info.erl | 10 +- .../src/emqx_resource_buffer_worker.erl | 110 +++++++---- .../emqx_rule_engine_api_rule_apply_SUITE.erl | 182 ++++++++++++++++-- .../emqx_rule_engine_test_action_info.erl | 101 ++++++++++ .../test/emqx_rule_engine_test_connector.erl | 99 ++++++++++ .../emqx_rule_engine_test_connector_info.erl | 43 +++++ mix.exs | 2 +- rebar.config | 2 +- 9 files changed, 505 insertions(+), 54 deletions(-) create mode 100644 apps/emqx_rule_engine/test/emqx_rule_engine_test_action_info.erl create mode 100644 apps/emqx_rule_engine/test/emqx_rule_engine_test_connector.erl create mode 100644 apps/emqx_rule_engine/test/emqx_rule_engine_test_connector_info.erl diff --git a/apps/emqx_bridge/src/emqx_action_info.erl b/apps/emqx_bridge/src/emqx_action_info.erl index 464b2e429..a8aaf9fdd 100644 --- a/apps/emqx_bridge/src/emqx_action_info.erl +++ b/apps/emqx_bridge/src/emqx_action_info.erl @@ -41,6 +41,9 @@ ]). -export([clean_cache/0]). +%% For tests +-export([hard_coded_test_action_info_modules/0]). + -callback bridge_v1_type_name() -> atom() | { @@ -128,8 +131,13 @@ hard_coded_action_info_modules_common() -> emqx_bridge_mqtt_pubsub_action_info ]. +%% This exists so that it can be mocked for test cases +hard_coded_test_action_info_modules() -> []. + hard_coded_action_info_modules() -> - hard_coded_action_info_modules_common() ++ hard_coded_action_info_modules_ee(). + hard_coded_action_info_modules_common() ++ + hard_coded_action_info_modules_ee() ++ + ?MODULE:hard_coded_test_action_info_modules(). %% ==================================================================== %% API diff --git a/apps/emqx_connector/src/emqx_connector_info.erl b/apps/emqx_connector/src/emqx_connector_info.erl index 766f34168..e87c2ad7e 100644 --- a/apps/emqx_connector/src/emqx_connector_info.erl +++ b/apps/emqx_connector/src/emqx_connector_info.erl @@ -31,6 +31,9 @@ -export([clean_cache/0]). +%% For tests +-export([hard_coded_test_connector_info_modules/0]). + %% The type name for the conncector -callback type_name() -> atom(). @@ -117,8 +120,13 @@ hard_coded_connector_info_modules_common() -> emqx_bridge_mqtt_pubsub_connector_info ]. +%% This exists so that it can be mocked for test cases +hard_coded_test_connector_info_modules() -> []. + hard_coded_connector_info_modules() -> - hard_coded_connector_info_modules_common() ++ hard_coded_connector_info_modules_ee(). + hard_coded_connector_info_modules_common() ++ + hard_coded_connector_info_modules_ee() ++ + ?MODULE:hard_coded_test_connector_info_modules(). %% -------------------------------------------------------------------- %% Atom macros to avoid typos diff --git a/apps/emqx_resource/src/emqx_resource_buffer_worker.erl b/apps/emqx_resource/src/emqx_resource_buffer_worker.erl index 6dfcde88c..24eb86d37 100644 --- a/apps/emqx_resource/src/emqx_resource_buffer_worker.erl +++ b/apps/emqx_resource/src/emqx_resource_buffer_worker.erl @@ -583,7 +583,11 @@ flush(Data0) -> {keep_state, Data1}; {_, false} -> ?tp(buffer_worker_flush_before_pop, #{}), - {Q1, QAckRef, Batch} = replayq:pop(Q0, #{count_limit => BatchSize}), + PopOpts = #{ + count_limit => BatchSize, + stop_before => {fun stop_before_mixed_stop_after_render/2, initial_state} + }, + {Q1, QAckRef, Batch} = replayq:pop(Q0, PopOpts), Data2 = Data1#{queue := Q1}, ?tp(buffer_worker_flush_before_sieve_expired, #{}), Now = now_(), @@ -619,6 +623,73 @@ flush(Data0) -> end end. +stop_before_mixed_stop_after_render( + ?QUERY( + _, + _, + _, + _, + #{stop_action_after_render := true} = _TraceCtx + ), + initial_state +) -> + stop_action_after_render; +stop_before_mixed_stop_after_render( + ?QUERY( + _, + _, + _, + _, + _TraceCtx + ), + initial_state +) -> + no_stop_action_after_render; +stop_before_mixed_stop_after_render( + ?QUERY( + _, + _, + _, + _, + #{stop_action_after_render := true} = _TraceCtx + ), + no_stop_action_after_render +) -> + true; +stop_before_mixed_stop_after_render( + ?QUERY( + _, + _, + _, + _, + #{stop_action_after_render := true} = _TraceCtx + ), + stop_action_after_render +) -> + stop_action_after_render; +stop_before_mixed_stop_after_render( + ?QUERY( + _, + _, + _, + _, + _TraceCtx + ), + stop_action_after_render +) -> + true; +stop_before_mixed_stop_after_render( + ?QUERY( + _, + _, + _, + _, + _TraceCtx + ), + State +) -> + State. + -spec do_flush(data(), #{ is_batch := boolean(), batch := [queue_query()], @@ -1119,25 +1190,13 @@ set_rule_id_trace_meta_data(Requests) when is_list(Requests) -> %% Get the rule ids from requests RuleIDs = lists:foldl(fun collect_rule_id/2, #{}, Requests), ClientIDs = lists:foldl(fun collect_client_id/2, #{}, Requests), - StopAfterRender = lists:foldl(fun collect_stop_after_render/2, no_info, Requests), StopAfterRenderVal = - case StopAfterRender of - only_true -> - logger:update_process_metadata(#{stop_action_after_render => false}), + case Requests of + %% We know that the batch is not mixed since we prevent this by + %% using a stop_after function in the replayq:pop call + [?QUERY(_, _, _, _, #{stop_action_after_render := true}) | _] -> true; - only_false -> - false; - mixed -> - ?TRACE( - warning, - "ACTION", - "mixed_stop_action_after_render_batch " - "(A batch will be sent to connector where some but " - "not all requests has stop_action_after_render set. " - "The batch will get assigned " - "stop_action_after_render = false)", - #{rule_ids => RuleIDs, client_ids => ClientIDs} - ), + [?QUERY(_, _, _, _, _TraceCTX) | _] -> false end, logger:update_process_metadata(#{ @@ -1158,21 +1217,6 @@ collect_client_id(?QUERY(_, _, _, _, #{clientid := ClientId}), Acc) -> collect_client_id(?QUERY(_, _, _, _, _), Acc) -> Acc. -collect_stop_after_render(?QUERY(_, _, _, _, #{stop_action_after_render := true}), no_info) -> - only_true; -collect_stop_after_render(?QUERY(_, _, _, _, #{stop_action_after_render := true}), only_true) -> - only_true; -collect_stop_after_render(?QUERY(_, _, _, _, #{stop_action_after_render := true}), only_false) -> - mixed; -collect_stop_after_render(?QUERY(_, _, _, _, _), no_info) -> - only_false; -collect_stop_after_render(?QUERY(_, _, _, _, _), only_true) -> - mixed; -collect_stop_after_render(?QUERY(_, _, _, _, _), only_false) -> - only_false; -collect_stop_after_render(?QUERY(_, _, _, _, _), mixed) -> - mixed. - unset_rule_id_trace_meta_data() -> logger:update_process_metadata(#{ rule_ids => #{}, client_ids => #{}, stop_action_after_render => false 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 576806464..e73c2c44d 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 @@ -94,9 +94,6 @@ basic_apply_rule_test_helper(Config, TraceType, StopAfterRender) -> %% =================================== %% Create trace for RuleId %% =================================== - Now = erlang:system_time(second) - 10, - Start = Now, - End = Now + 60, TraceName = atom_to_binary(?FUNCTION_NAME), TraceValue = case TraceType of @@ -105,16 +102,7 @@ basic_apply_rule_test_helper(Config, TraceType, StopAfterRender) -> clientid -> ClientId end, - Trace = #{ - name => TraceName, - type => TraceType, - TraceType => TraceValue, - start_at => Start, - end_at => End - }, - emqx_trace_SUITE:reload(), - ok = emqx_trace:clear(), - {ok, _} = emqx_trace:create(Trace), + create_trace(TraceName, TraceType, TraceValue), %% =================================== Context = #{ clientid => ClientId, @@ -125,13 +113,12 @@ basic_apply_rule_test_helper(Config, TraceType, StopAfterRender) -> username => <<"u_emqx">> }, Params = #{ - % body => #{ <<"context">> => Context, <<"stop_action_after_template_rendering">> => StopAfterRender - % } }, emqx_trace:check(), ok = emqx_trace_handler_SUITE:filesync(TraceName, TraceType), + Now = erlang:system_time(second) - 10, {ok, _} = file:read_file(emqx_trace:log_file(TraceName, Now)), ?assertMatch({ok, _}, call_apply_rule_api(RuleId, Params)), ?retry( @@ -173,14 +160,175 @@ basic_apply_rule_test_helper(Config, TraceType, StopAfterRender) -> emqx_trace:delete(TraceName), ok. +create_trace(TraceName, TraceType, TraceValue) -> + Now = erlang:system_time(second) - 10, + Start = Now, + End = Now + 60, + Trace = #{ + name => TraceName, + type => TraceType, + TraceType => TraceValue, + start_at => Start, + end_at => End + }, + emqx_trace_SUITE:reload(), + ok = emqx_trace:clear(), + {ok, _} = emqx_trace:create(Trace). + +t_apply_rule_test_batch_separation_stop_after_render(_Config) -> + MeckOpts = [passthrough, no_link, no_history, non_strict], + catch meck:new(emqx_connector_info, MeckOpts), + meck:expect( + emqx_connector_info, + hard_coded_test_connector_info_modules, + 0, + [emqx_rule_engine_test_connector_info] + ), + emqx_connector_info:clean_cache(), + catch meck:new(emqx_action_info, MeckOpts), + meck:expect( + emqx_action_info, + hard_coded_test_action_info_modules, + 0, + [emqx_rule_engine_test_action_info] + ), + emqx_action_info:clean_cache(), + {ok, _} = emqx_connector:create(rule_engine_test, ?FUNCTION_NAME, #{}), + Name = atom_to_binary(?FUNCTION_NAME), + ActionConf = + #{ + <<"connector">> => Name, + <<"parameters">> => + #{ + <<"values">> => + #{ + <<"send_to_pid">> => emqx_utils:bin_to_hexstr( + term_to_binary(self()), upper + ) + } + }, + <<"resource_opts">> => #{ + <<"batch_size">> => 1000, + <<"batch_time">> => 500 + } + }, + {ok, _} = emqx_bridge_v2:create( + rule_engine_test, + ?FUNCTION_NAME, + ActionConf + ), + SQL = <<"SELECT payload.is_stop_after_render as stop_after_render FROM \"", Name/binary, "\"">>, + {ok, RuleID} = create_rule_with_action( + rule_engine_test, + ?FUNCTION_NAME, + SQL + ), + create_trace(Name, ruleid, RuleID), + emqx_trace:check(), + ok = emqx_trace_handler_SUITE:filesync(Name, ruleid), + Now = erlang:system_time(second) - 10, + %% Stop + ParmsStopAfterRender = apply_rule_parms(true, Name), + ParmsNoStopAfterRender = apply_rule_parms(false, Name), + %% Check that batching is working + Count = 400, + CountMsgFun = + fun + CountMsgFunRec(0 = _CurCount, GotBatchWithAtLeastTwo) -> + GotBatchWithAtLeastTwo; + CountMsgFunRec(CurCount, GotBatchWithAtLeastTwo) -> + receive + List -> + Len = length(List), + CountMsgFunRec(CurCount - Len, GotBatchWithAtLeastTwo orelse (Len > 1)) + end + end, + lists:foreach( + fun(_) -> + {ok, _} = call_apply_rule_api(RuleID, ParmsStopAfterRender) + end, + lists:seq(1, Count) + ), + %% We should get the messages and at least one batch with more than 1 + true = CountMsgFun(Count, false), + %% We should check that we don't get any mixed batch + CheckBatchesFun = + fun + CheckBatchesFunRec(0 = _CurCount) -> + ok; + CheckBatchesFunRec(CurCount) -> + receive + [{_, #{<<"stop_after_render">> := StopValue}} | _] = List -> + [ + ?assertMatch(#{<<"stop_after_render">> := StopValue}, Msg) + || {_, Msg} <- List + ], + Len = length(List), + CheckBatchesFunRec(CurCount - Len) + end + end, + lists:foreach( + fun(_) -> + case rand:normal() < 0 of + true -> + {ok, _} = call_apply_rule_api(RuleID, ParmsStopAfterRender); + false -> + {ok, _} = call_apply_rule_api(RuleID, ParmsNoStopAfterRender) + end + end, + lists:seq(1, Count) + ), + CheckBatchesFun(Count), + %% Just check that the log file is created as expected + ?retry( + _Interval0 = 200, + _NAttempts0 = 20, + begin + Bin = read_rule_trace_file(Name, ruleid, Now), + ?assertNotEqual(nomatch, binary:match(Bin, [<<"action_success">>])) + end + ), + ok. + +apply_rule_parms(StopAfterRender, Name) -> + Payload = #{<<"is_stop_after_render">> => StopAfterRender}, + Context = #{ + clientid => Name, + event_type => message_publish, + payload => emqx_utils_json:encode(Payload), + qos => 1, + topic => Name, + username => <<"u_emqx">> + }, + #{ + <<"context">> => Context, + <<"stop_action_after_template_rendering">> => StopAfterRender + }. + +create_rule_with_action(ActionType, ActionName, SQL) -> + BridgeId = emqx_bridge_resource:bridge_id(ActionType, ActionName), + Params = #{ + enable => true, + sql => SQL, + actions => [BridgeId] + }, + Path = emqx_mgmt_api_test_util:api_path(["rules"]), + AuthHeader = emqx_mgmt_api_test_util:auth_header_(), + ct:pal("rule action params: ~p", [Params]), + case emqx_mgmt_api_test_util:request_api(post, Path, "", AuthHeader, Params) of + {ok, Res0} -> + #{<<"id">> := RuleId} = emqx_utils_json:decode(Res0, [return_maps]), + {ok, RuleId}; + Error -> + Error + end. + %% Helper Functions call_apply_rule_api(RuleId, Params) -> Method = post, Path = emqx_mgmt_api_test_util:api_path(["rules", RuleId, "test"]), - ct:pal("sql test (http):\n ~p", [Params]), Res = request(Method, Path, Params), - ct:pal("sql test (http) result:\n ~p", [Res]), Res. request(Method, Path, Params) -> diff --git a/apps/emqx_rule_engine/test/emqx_rule_engine_test_action_info.erl b/apps/emqx_rule_engine/test/emqx_rule_engine_test_action_info.erl new file mode 100644 index 000000000..91bbcb442 --- /dev/null +++ b/apps/emqx_rule_engine/test/emqx_rule_engine_test_action_info.erl @@ -0,0 +1,101 @@ +%%-------------------------------------------------------------------- +%% Copyright (c) 2022-2024 EMQ Technologies Co., Ltd. All Rights Reserved. +%%-------------------------------------------------------------------- + +-module(emqx_rule_engine_test_action_info). + +-behaviour(emqx_action_info). + +-export([ + bridge_v1_type_name/0, + action_type_name/0, + connector_type_name/0, + schema_module/0 +]). + +-export([ + namespace/0, + roots/0, + fields/1, + desc/1 +]). + +-define(CONNECTOR_TYPE, rule_engine_test). +-define(ACTION_TYPE, ?CONNECTOR_TYPE). + +bridge_v1_type_name() -> ?ACTION_TYPE. + +action_type_name() -> ?ACTION_TYPE. + +connector_type_name() -> ?ACTION_TYPE. + +schema_module() -> emqx_rule_engine_test_action_info. + +%% ------------------------------------------------------------------------------------------------- +%% Hocon Schema Definitions + +namespace() -> "bridge_test_action_info". + +roots() -> []. + +fields(Field) when + Field == "get_connector"; + Field == "put_connector"; + Field == "post_connector" +-> + Fields = + fields(connector_fields) ++ + emqx_connector_schema:resource_opts_ref(?MODULE, connector_resource_opts), + emqx_connector_schema:api_fields(Field, ?CONNECTOR_TYPE, Fields); +fields(Field) when + Field == "get_bridge_v2"; + Field == "post_bridge_v2"; + Field == "put_bridge_v2" +-> + emqx_bridge_v2_schema:api_fields(Field, ?ACTION_TYPE, fields(rule_engine_test_action)); +fields(action) -> + {?ACTION_TYPE, + hoconsc:mk( + hoconsc:map(name, hoconsc:ref(?MODULE, rule_engine_test_action)), + #{ + desc => <<"Test Action Config">>, + required => false + } + )}; +fields(rule_engine_test_action) -> + emqx_bridge_v2_schema:make_producer_action_schema( + hoconsc:mk( + hoconsc:ref(?MODULE, action_parameters), + #{ + required => true, + desc => undefined + } + ) + ); +fields(action_parameters) -> + [ + {values, + hoconsc:mk( + typerefl:map(), + #{desc => undefined, default => #{}} + )} + ]; +fields("config_connector") -> + emqx_connector_schema:common_fields() ++ + fields(connector_fields) ++ + emqx_connector_schema:resource_opts_ref(?MODULE, connector_resource_opts); +fields(connector_resource_opts) -> + emqx_connector_schema:resource_opts_fields(); +fields("config") -> + emqx_resource_schema:fields("resource_opts") ++ + fields(connector_fields); +fields(connector_fields) -> + [ + {values, + hoconsc:mk( + typerefl:map(), + #{desc => undefined, default => #{}} + )} + ]. +desc(_) -> + undefined. 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 new file mode 100644 index 000000000..5633ed27e --- /dev/null +++ b/apps/emqx_rule_engine/test/emqx_rule_engine_test_connector.erl @@ -0,0 +1,99 @@ +%%-------------------------------------------------------------------- +%% Copyright (c) 2020-2024 EMQ Technologies Co., Ltd. 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. +%%-------------------------------------------------------------------- +-module(emqx_rule_engine_test_connector). + +-include_lib("emqx_connector/include/emqx_connector.hrl"). +-include_lib("typerefl/include/types.hrl"). +-include_lib("emqx/include/logger.hrl"). +-include_lib("hocon/include/hoconsc.hrl"). +-include_lib("snabbkaffe/include/snabbkaffe.hrl"). + +-behaviour(emqx_resource). + +%% callbacks of behaviour emqx_resource +-export([ + callback_mode/0, + on_start/2, + on_stop/2, + on_query/3, + on_batch_query/3, + on_get_status/2, + on_add_channel/4, + on_remove_channel/3, + on_get_channels/1, + on_get_channel_status/3 +]). + +%% =================================================================== +callback_mode() -> always_sync. + +on_start( + _InstId, + _Config +) -> + {ok, #{installed_channels => #{}}}. + +on_stop(_InstId, _State) -> + ok. + +on_add_channel( + _InstId, + #{ + installed_channels := InstalledChannels + } = OldState, + ChannelId, + ChannelConfig +) -> + NewInstalledChannels = maps:put(ChannelId, ChannelConfig, InstalledChannels), + NewState = OldState#{installed_channels => NewInstalledChannels}, + {ok, NewState}. + +on_remove_channel( + _InstId, + OldState, + _ChannelId +) -> + {ok, OldState}. + +on_get_channel_status( + _ResId, + _ChannelId, + _State +) -> + connected. + +on_get_channels(ResId) -> + emqx_bridge_v2:get_channels_for_connector(ResId). + +on_query( + _InstId, + _Query, + _State +) -> + ok. + +on_batch_query( + _InstId, + [{ChannelId, _Req} | _] = Msg, + #{installed_channels := Channels} = _State +) -> + #{parameters := #{values := #{send_to_pid := PidBin}}} = maps:get(ChannelId, Channels), + Pid = binary_to_term(emqx_utils:hexstr_to_bin(PidBin)), + Pid ! Msg, + ok. + +on_get_status(_InstId, _State) -> + connected. diff --git a/apps/emqx_rule_engine/test/emqx_rule_engine_test_connector_info.erl b/apps/emqx_rule_engine/test/emqx_rule_engine_test_connector_info.erl new file mode 100644 index 000000000..1c300bff8 --- /dev/null +++ b/apps/emqx_rule_engine/test/emqx_rule_engine_test_connector_info.erl @@ -0,0 +1,43 @@ +%%-------------------------------------------------------------------- +%% Copyright (c) 2022-2024 EMQ Technologies Co., Ltd. All Rights Reserved. +%%-------------------------------------------------------------------- + +-module(emqx_rule_engine_test_connector_info). + +-behaviour(emqx_connector_info). + +-export([ + type_name/0, + bridge_types/0, + resource_callback_module/0, + config_schema/0, + schema_module/0, + api_schema/1 +]). + +type_name() -> + rule_engine_test. + +bridge_types() -> + [rule_engine_test]. + +resource_callback_module() -> + emqx_rule_engine_test_connector. + +config_schema() -> + {rule_engine_test, + hoconsc:mk( + hoconsc:map(name, hoconsc:ref(emqx_rule_engine_test_action_info, "config_connector")), + #{ + desc => <<"Test Connector Config">>, + required => false + } + )}. + +schema_module() -> + emqx_rule_engine_test_action_info. + +api_schema(Method) -> + emqx_connector_schema:api_ref( + ?MODULE, <<"rule_engine_test">>, Method ++ "_connector" + ). diff --git a/mix.exs b/mix.exs index 486484f72..6ce5c4885 100644 --- a/mix.exs +++ b/mix.exs @@ -60,7 +60,7 @@ defmodule EMQXUmbrella.MixProject do {:grpc, github: "emqx/grpc-erl", tag: "0.6.12", override: true}, {:minirest, github: "emqx/minirest", tag: "1.4.0", override: true}, {:ecpool, github: "emqx/ecpool", tag: "0.5.7", override: true}, - {:replayq, github: "emqx/replayq", tag: "0.3.7", override: true}, + {:replayq, github: "emqx/replayq", tag: "0.3.8", override: true}, {:pbkdf2, github: "emqx/erlang-pbkdf2", tag: "2.0.4", override: true}, # maybe forbid to fetch quicer {:emqtt, diff --git a/rebar.config b/rebar.config index 8bbe178aa..a0a726fcf 100644 --- a/rebar.config +++ b/rebar.config @@ -88,7 +88,7 @@ {grpc, {git, "https://github.com/emqx/grpc-erl", {tag, "0.6.12"}}}, {minirest, {git, "https://github.com/emqx/minirest", {tag, "1.4.0"}}}, {ecpool, {git, "https://github.com/emqx/ecpool", {tag, "0.5.7"}}}, - {replayq, {git, "https://github.com/emqx/replayq.git", {tag, "0.3.7"}}}, + {replayq, {git, "https://github.com/emqx/replayq.git", {tag, "0.3.8"}}}, {pbkdf2, {git, "https://github.com/emqx/erlang-pbkdf2.git", {tag, "2.0.4"}}}, {emqtt, {git, "https://github.com/emqx/emqtt", {tag, "1.10.1"}}}, {rulesql, {git, "https://github.com/emqx/rulesql", {tag, "0.2.0"}}}, From 6cf29ba68883f425b8101b12b22fd213231bbd98 Mon Sep 17 00:00:00 2001 From: Kjell Winblad Date: Wed, 17 Apr 2024 18:20:17 +0200 Subject: [PATCH 21/23] 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) -> From 95891db29ab75529fd33b721587a8cab98395963 Mon Sep 17 00:00:00 2001 From: Kjell Winblad Date: Wed, 17 Apr 2024 18:43:19 +0200 Subject: [PATCH 22/23] test: clean up created resources in the end of test case --- .../test/emqx_rule_engine_api_rule_apply_SUITE.erl | 6 ++++++ 1 file changed, 6 insertions(+) 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 063982367..c875617ce 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 @@ -293,6 +293,12 @@ t_apply_rule_test_batch_separation_stop_after_render(_Config) -> ) end ), + %% Cleanup + ok = emqx_trace:delete(Name), + ok = emqx_rule_engine:delete_rule(RuleID), + ok = emqx_bridge_v2:remove(rule_engine_test, ?FUNCTION_NAME), + ok = emqx_connector:remove(rule_engine_test, ?FUNCTION_NAME), + [_, _] = meck:unload(), ok. apply_rule_parms(StopAfterRender, Name) -> From b16b9d8fcc3a4a3ca36f0c30f341c88995d8470c Mon Sep 17 00:00:00 2001 From: Kjell Winblad Date: Thu, 18 Apr 2024 06:51:30 +0200 Subject: [PATCH 23/23] refactor: made code more readable thanks to suggestion from @zmstone --- .../src/emqx_resource_buffer_worker.erl | 82 ++++--------------- 1 file changed, 16 insertions(+), 66 deletions(-) diff --git a/apps/emqx_resource/src/emqx_resource_buffer_worker.erl b/apps/emqx_resource/src/emqx_resource_buffer_worker.erl index 24eb86d37..bc1aea734 100644 --- a/apps/emqx_resource/src/emqx_resource_buffer_worker.erl +++ b/apps/emqx_resource/src/emqx_resource_buffer_worker.erl @@ -585,7 +585,7 @@ flush(Data0) -> ?tp(buffer_worker_flush_before_pop, #{}), PopOpts = #{ count_limit => BatchSize, - stop_before => {fun stop_before_mixed_stop_after_render/2, initial_state} + stop_before => {fun stop_batching/2, initial_state} }, {Q1, QAckRef, Batch} = replayq:pop(Q0, PopOpts), Data2 = Data1#{queue := Q1}, @@ -623,72 +623,22 @@ flush(Data0) -> end end. -stop_before_mixed_stop_after_render( - ?QUERY( - _, - _, - _, - _, - #{stop_action_after_render := true} = _TraceCtx - ), - initial_state -) -> +stop_batching(Query, initial_state) -> + get_stop_flag(Query); +stop_batching(Query, PrevStopFlag) -> + case get_stop_flag(Query) =:= PrevStopFlag of + true -> + PrevStopFlag; + false -> + %% We stop beceause we don't want a batch with mixed values for the + %% stop_action_after_render option + true + end. + +get_stop_flag(?QUERY(_, _, _, _, #{stop_action_after_render := true})) -> stop_action_after_render; -stop_before_mixed_stop_after_render( - ?QUERY( - _, - _, - _, - _, - _TraceCtx - ), - initial_state -) -> - no_stop_action_after_render; -stop_before_mixed_stop_after_render( - ?QUERY( - _, - _, - _, - _, - #{stop_action_after_render := true} = _TraceCtx - ), - no_stop_action_after_render -) -> - true; -stop_before_mixed_stop_after_render( - ?QUERY( - _, - _, - _, - _, - #{stop_action_after_render := true} = _TraceCtx - ), - stop_action_after_render -) -> - stop_action_after_render; -stop_before_mixed_stop_after_render( - ?QUERY( - _, - _, - _, - _, - _TraceCtx - ), - stop_action_after_render -) -> - true; -stop_before_mixed_stop_after_render( - ?QUERY( - _, - _, - _, - _, - _TraceCtx - ), - State -) -> - State. +get_stop_flag(_) -> + no_stop_action_after_render. -spec do_flush(data(), #{ is_batch := boolean(),