Merge pull request #4312 from esl/instrument/specific-assertions

More specific assertions for instrumentation events

big_tests/tests/accounts_SUITE.erl

@@ -189,20 +189,22 @@ unregister(Config) ->
     assert_event(auth_unregister_user, escalus_users:get_jid(Config, UserSpec)).
 
 already_registered(Config) ->
-    escalus_fresh:story(Config, [{alice, 1}], fun(Alice) ->
-        escalus:send(Alice, escalus_stanza:get_registration_fields()),
-        Stanza = escalus:wait_for_stanza(Alice),
-        escalus:assert(is_iq_result, Stanza),
-        true = has_registered_element(Stanza)
+    escalus_fresh:story(Config, [{alice, 1}], fun already_registered_story/1).
+
+already_registered_story(Alice) ->
+    AliceJid = escalus_utils:get_short_jid(Alice),
+    assert_event(auth_register_user, AliceJid), % one event expected
+    escalus:send(Alice, escalus_stanza:get_registration_fields()),
+    Stanza = escalus:wait_for_stanza(Alice),
+    escalus:assert(is_iq_result, Stanza),
+    true = has_registered_element(Stanza),
+    assert_event(auth_register_user, AliceJid). % still one event - nothing new
 
-                                              end).
 registration_conflict(Config) ->
     [Alice] = escalus_users:get_users([alice]),
     {ok, result, _Stanza} = escalus_users:create_user(Config, Alice),
     {ok, conflict, _Raw} = escalus_users:create_user(Config, Alice).
 
-
-
 admin_notify(Config) ->
     [{Name1, UserSpec1}, {Name2, UserSpec2}] = escalus_users:get_users([alice, bob]),
     [{_, AdminSpec}] = escalus_users:get_users([admin]),

big_tests/tests/amp_big_SUITE.erl

@@ -133,8 +133,9 @@ amp_test_helper_code() ->
     "  end.\n".
 
 declared_events() ->
-    [
-     {mod_privacy_set, #{host_type => host_type()}} % tested by privacy helpers
+    [ % tested by privacy helpers
+     {mod_privacy_set, #{host_type => host_type()}},
+     {mod_privacy_get, #{host_type => host_type()}}
     ].
 
 end_per_suite(C) ->

big_tests/tests/anonymous_SUITE.erl

@@ -89,7 +89,7 @@ connection_is_registered_with_login(Config) ->
         true = F(),
         escalus_connection:kill(Anna),
         mongoose_helper:wait_until(F, false),
-        assert_event(auth_anonymous_register_user, JID)
+        assert_event(auth_anonymous_unregister_user, JID)
     end).
 
 messages_story(Config) ->
@@ -110,5 +110,6 @@ host_type() ->
     domain_helper:anonymous_host_type().
 
 assert_event(EventName, #jid{luser = LUser, lserver = LServer}) ->
-    instrument_helper:assert(EventName, #{host_type => host_type()},
-                             fun(M) -> M =:= #{count => 1, user => LUser, server => LServer} end).
+    instrument_helper:assert_one(
+      EventName, #{host_type => host_type()},
+      fun(M) -> M =:= #{count => 1, user => LUser, server => LServer} end).

big_tests/tests/auth_helper.erl

@@ -10,17 +10,18 @@ assert_event(EventName, BinJid)
     F = fun(M) ->
             M =:= #{count => 1, user => LUser, server => LServer}
         end,
-    instrument_helper:assert(EventName, #{host_type => host_type()}, F);
+    instrument_helper:assert_one(EventName, #{host_type => host_type()}, F);
 assert_event(EventName, BinJid)
     when EventName =:= auth_authorize ->
     #jid{lserver = LServer} = jid:from_binary(BinJid),
     F = fun(#{time := Time, count := 1, server := Server}) ->
            (Time > 0) and (Server =:= LServer)
         end,
+    %% Note: this could match events from other tests because there is no user name
     instrument_helper:assert(EventName, #{host_type => host_type()}, F);
 assert_event(EventName, BinJid) ->
     #jid{luser = LUser, lserver = LServer} = jid:from_binary(BinJid),
     F = fun(#{time := Time, count := 1, user := User, server := Server}) ->
            (Time > 0) and (User =:= LUser) and (Server =:= LServer)
         end,
-    instrument_helper:assert(EventName, #{host_type => host_type()}, F).
+    instrument_helper:assert_one(EventName, #{host_type => host_type()}, F).

big_tests/tests/disco_and_caps_SUITE.erl

@@ -235,5 +235,5 @@ urls(sales) -> [<<"[email protected]">>].
 
 assert_roster_get_event(Client) ->
     ClientJid = jid:from_binary(escalus_client:full_jid(Client)),
-    instrument_helper:assert(mod_disco_roster_get, #{host_type => host_type()},
-                             fun(#{count := 1, jid := Jid}) -> ClientJid =:= Jid end).
+    instrument_helper:assert_one(mod_disco_roster_get, #{host_type => host_type()},
+                                 fun(#{count := 1, jid := Jid}) -> ClientJid =:= Jid end).

big_tests/tests/domain_isolation_SUITE.erl

@@ -157,7 +157,7 @@ verify_alice_has_no_pending_messages(Alice, Bob) ->
 assert_stanza_dropped(Sender, Recipient, Stanza) ->
     SenderJid = jid:from_binary(escalus_utils:get_jid(Sender)),
     RecipientJid = jid:from_binary(escalus_utils:get_jid(Recipient)),
-    instrument_helper:assert(
+    instrument_helper:assert_one(
       router_stanza_dropped, #{host_type => host_type()},
       fun(#{count := 1, from_jid := From, to_jid := To, stanza := DroppedStanza}) ->
               From =:= SenderJid andalso To =:= RecipientJid andalso DroppedStanza =:= Stanza

big_tests/tests/graphql_roster_SUITE.erl

@@ -398,7 +398,7 @@ admin_list_contacts_story(Config, Alice, Bob) ->
     [#{<<"subscription">> := <<"NONE">>, <<"ask">> := <<"NONE">>, <<"jid">> := BobBin,
        <<"name">> := BobName, <<"groups">> := ?DEFAULT_GROUPS}] =
         get_ok_value([data, roster, listContacts], Res),
-    roster_helper:assert_roster_event(Alice, mod_roster_get).
+    roster_helper:assert_roster_event(escalus_client:short_jid(Alice), mod_roster_get).
 
 admin_list_contacts_wrong_user(Config) ->
     % User with a non-existent domain
@@ -548,7 +548,7 @@ user_list_contacts_story(Config, Alice, Bob) ->
     [#{<<"subscription">> := <<"NONE">>, <<"ask">> := <<"NONE">>, <<"jid">> := BobBin,
        <<"name">> := Name, <<"groups">> := ?DEFAULT_GROUPS}] =
         get_ok_value(?LIST_CONTACTS_PATH, Res),
-    roster_helper:assert_roster_event(Alice, mod_roster_get).
+    roster_helper:assert_roster_event(escalus_client:short_jid(Alice), mod_roster_get).
 
 user_get_contact(Config) ->
     escalus:fresh_story_with_config(Config, [{alice, 1}, {bob, 1}],

big_tests/tests/instrument_cets_SUITE.erl

@@ -42,15 +42,13 @@ end_per_group(_, _Config) ->
 init_per_testcase(_, Config) ->
     Config.
 
-check_instrumentation(Config) ->
-    instrument_helper:wait_for_new(cets_info, #{}),
-    instrument_helper:assert(cets_info, #{}, fun(Res) ->
-            %% Values are integers
-            lists:all(fun(Name) -> is_integer(maps:get(Name, Res)) end, instrumentation_metrics_names())
-            andalso
-            %% Check that there are no unknown fields
-            [] =:= maps:keys(maps:without(instrumentation_metrics_names(), Res))
-        end).
+check_instrumentation(_Config) ->
+    instrument_helper:wait_and_assert_new(cets_info, #{}, fun check_info/1).
+
+%% Check that values are integers and there are no unknown fields
+check_info(Res) ->
+    lists:all(fun(Name) -> is_integer(maps:get(Name, Res)) end, instrumentation_metrics_names())
+        andalso #{} =:= maps:without(instrumentation_metrics_names(), Res).
 
 instrumentation_metrics_names() ->
     [available_nodes,

big_tests/tests/instrument_helper.erl

@@ -3,12 +3,12 @@
 
 -module(instrument_helper).
 
--export([declared_events/1, declared_events/2,
-         start/1, start/2, stop/0,
-         assert/3, assert/4, filter/2,
-         assert_not_emitted/1, assert_not_emitted/2,
-         wait_for/2, wait_for_new/2,
-         lookup/2, take/2]).
+%% API for setup and teardown in test suites
+-export([declared_events/1, declared_events/2, start/1, start/2, stop/0]).
+
+%% API for assertions in test cases
+-export([assert/3, assert_one/3, assert_not_emitted/3, assert_not_emitted/2, assert_not_emitted/1,
+         wait_and_assert/3, wait_and_assert_new/3, assert/4, timestamp/0]).
 
 -import(distributed_helper, [rpc/4, mim/0]).
 
@@ -20,8 +20,14 @@
 -type event_name() :: atom().
 -type labels() :: #{atom() => term()}.
 -type measurements() :: #{atom() => term()}.
+-type check_fun() :: fun((measurements()) -> boolean()).
+-type event_count() :: non_neg_integer() | positive.
+-type opts() :: #{min_timestamp => integer(),
+                  retries := non_neg_integer(),
+                  delay := non_neg_integer(),
+                  expected_count := event_count()}.
 
-%% API
+%% API for setup and teardown in test suites
 
 %% @doc Helper to get `DeclaredEvents' needed by `start/1'
 declared_events(Modules) ->
@@ -59,65 +65,116 @@ stop() ->
     verify_unlogged((Untested -- Logged) -- Negative),
     verify_logged_but_untested((Logged -- Tested) -- Negative).
 
--spec assert(event_name(), labels(), fun((measurements()) -> boolean())) -> ok.
+%% API for assertions in test cases
+
+%% @doc Checks that there is at least one event with `EventName', `Labels'
+%%      and matching measurements.
+ -spec assert(event_name(), labels(), check_fun()) -> ok.
 assert(EventName, Labels, CheckF) ->
-    assert(EventName, Labels, lookup(EventName, Labels), CheckF).
+    assert(EventName, Labels, CheckF, #{}).
 
-%% @doc `CheckF' can return a boolean or fail with `function_clause', which means `false'.
-%% This is for convenience - you only have to code one clause.
--spec assert(event_name(), labels(), [measurements()], fun((measurements()) -> boolean())) -> ok.
-assert(EventName, Labels, MeasurementsList, CheckF) ->
-    case filter(CheckF, MeasurementsList) of
-        [] ->
-            ct:log("All measurements for event ~p with labels ~p:~n~p",
-                   [EventName, Labels, MeasurementsList]),
-            ct:fail("No instrumentation events matched");
-        Filtered ->
-            ct:log("Matching measurements for event ~p with labels ~p:~n~p",
-                   [EventName, Labels, Filtered]),
-            event_tested(EventName, Labels)
-    end.
+%% @doc Checks that there is exactly one event with `EventName', `Labels'
+%%      and matching measurements.
+-spec assert_one(event_name(), labels(), check_fun()) -> ok.
+assert_one(EventName, Labels, CheckF) ->
+    assert(EventName, Labels, CheckF, #{expected_count => 1}).
+
+%% @doc Checks that there is no event with `EventName', `Labels' and matching measurements.
+-spec assert_not_emitted(event_name(), labels(), check_fun()) -> ok.
+assert_not_emitted(EventName, Labels, CheckF) ->
+    assert(EventName, Labels, CheckF, #{expected_count => 0}).
 
+%% @doc Checks that there is no event with `EventName' and `Labels'.
+-spec assert_not_emitted(event_name(), labels()) -> ok.
 assert_not_emitted(EventName, Labels) ->
-    case lookup(EventName, Labels) of
-        [] ->
-            ok;
-        Events ->
-            ct:fail("Measurements emitted but should not ~p", [Events])
-    end.
+    assert_not_emitted(EventName, Labels, fun(_) -> true end).
 
+%% @doc Checks that there is no event for any of the `{EventName, Labels}' tuples.
+-spec assert_not_emitted([{event_name(), labels()}]) -> ok.
 assert_not_emitted(Events) ->
-    [assert_not_emitted(Event, Label) || {Event, Label} <- Events].
+    [assert_not_emitted(Event, Label) || {Event, Label} <- Events],
+    ok.
+
+%% @doc Waits for a matching event.
+-spec wait_and_assert(event_name(), labels(), check_fun()) -> ok.
+wait_and_assert(EventName, Labels, CheckF) ->
+    assert(EventName, Labels, CheckF, #{retries => 50, delay => 100}).
+
+%% @doc Waits for a matching event, ignoring past events.
+-spec wait_and_assert_new(event_name(), labels(), check_fun()) -> ok.
+wait_and_assert_new(EventName, Labels, CheckF) ->
+    assert(EventName, Labels, CheckF, #{min_timestamp => timestamp(), retries => 50, delay => 100}).
+
+%% @doc Assert that an expected number of events with `EventName' and `Labels' are present.
+%% Events are filtered by applying `CheckF' to the map of measurements.
+%% `CheckF' can return a boolean or fail with `function_clause', which means `false'.
+%% This is for convenience - you only have to code one clause.
+-spec assert(event_name(), labels(), check_fun(), opts()) -> ok.
+assert(EventName, Labels, CheckF, Opts) ->
+    FullOpts = maps:merge(default_opts(), Opts),
+    assert_loop(EventName, Labels, CheckF, FullOpts).
+
+-spec timestamp() -> integer().
+timestamp() ->
+    rpc(mim(), ?HANDLER_MODULE, timestamp, []).
+
+%% Internal functions
+
+-spec default_opts() -> opts().
+default_opts() ->
+    #{retries => 0, delay => timer:seconds(1), expected_count => positive}.
+
+-spec assert_loop(event_name(), labels(), check_fun(), opts()) -> ok.
+assert_loop(EventName, Labels, CheckF, Opts) ->
+    #{retries := Retries, expected_count := ExpectedCount, delay := Delay} = Opts,
+    All = case Opts of
+              #{min_timestamp := Timestamp} ->
+                  select_new(EventName, Labels, Timestamp);
+              #{} ->
+                  select(EventName, Labels)
+          end,
+    Filtered = filter(CheckF, All),
+    case check(Filtered, ExpectedCount) of
+        false when Retries > 0 ->
+            timer:sleep(Delay),
+            assert_loop(EventName, Labels, CheckF, Opts#{retries := Retries - 1});
+        CheckResult ->
+            assert_check_result(EventName, Labels, All, Filtered, CheckResult, ExpectedCount)
+    end.
 
 -spec filter(fun((measurements()) -> boolean()), [measurements()]) -> [measurements()].
 filter(CheckF, MeasurementsList) ->
     lists:filter(fun(Measurements) ->
                          try CheckF(Measurements) catch error:function_clause -> false end
                  end, MeasurementsList).
 
-%% @doc Remove previous events, and wait for a new one. Use for probes only.
--spec wait_for_new(event_name(), labels()) -> [measurements()].
-wait_for_new(EventName, Labels) ->
-    take(EventName, Labels),
-    wait_for(EventName, Labels).
-
-%% @doc Lookup an element, or wait for it, if it didn't happen yet.
--spec wait_for(event_name(), labels()) -> [measurements()].
-wait_for(EventName, Labels) ->
-    {ok, MeasurementsList} = mongoose_helper:wait_until(fun() -> lookup(EventName, Labels) end,
-                                                        fun(L) -> L =/= [] end,
-                                                        #{name => EventName}),
-    MeasurementsList.
-
--spec lookup(event_name(), labels()) -> [measurements()].
-lookup(EventName, Labels) ->
-    [Measurements || {_, Measurements} <- rpc(mim(), ?HANDLER_MODULE, lookup, [EventName, Labels])].
-
--spec take(event_name(), labels()) -> [measurements()].
-take(EventName, Labels) ->
-    [Measurements || {_, Measurements} <- rpc(mim(), ?HANDLER_MODULE, take, [EventName, Labels])].
-
-%% Internal functions
+-spec select(event_name(), labels()) -> [measurements()].
+select(EventName, Labels) ->
+    rpc(mim(), ?HANDLER_MODULE, select, [EventName, Labels]).
+
+-spec select_new(event_name(), labels(), integer()) -> [measurements()].
+select_new(EventName, Labels, Timestamp) ->
+    rpc(mim(), ?HANDLER_MODULE, select_new, [EventName, Labels, Timestamp]).
+
+-spec check([measurements()], event_count()) -> boolean().
+check(Filtered, positive) ->
+    length(Filtered) > 0;
+check(Filtered, ExpectedCount) ->
+    length(Filtered) =:= ExpectedCount.
+
+-spec assert_check_result(event_name(), labels(), All :: [measurements()],
+                          Filtered :: [measurements()], CheckResult :: boolean(),
+                          event_count()) -> ok.
+assert_check_result(_EventName, _Labels, _All, [], true, _ExpectedCount) ->
+    ok; % don't mark non-emitted events as tested
+assert_check_result(EventName, Labels, _All, Filtered, true, _ExpectedCount) ->
+    ct:log("Matching measurements for event ~p with labels ~p:~n~p", [EventName, Labels, Filtered]),
+    event_tested(EventName, Labels);
+assert_check_result(EventName, Labels, All, Filtered, false, ExpectedCount) ->
+    ct:log("Assertion failed for event ~p with labels ~p.~nMatching measurements:~n~p~n~n"
+           "Other measurements:~n~p", [EventName, Labels, Filtered, All -- Filtered]),
+    ct:fail("Incorrect number of instrumentation events - matched: ~p, expected: ~p",
+            [length(Filtered), ExpectedCount]).
 
 %% Don't fail if some events are unlogged, because we don't have full test coverage (yet)
 verify_unlogged([]) -> ok;

big_tests/tests/mam_SUITE.erl

@@ -113,7 +113,8 @@
          assert_lookup_event/2,
          assert_flushed_event_if_async/2,
          assert_dropped_iq_event/2,
-         assert_event_with_jid/2
+         assert_event_with_jid/2,
+         assert_no_event_with_jid/2
         ]).
 
 -import(muc_light_helper,
@@ -3287,7 +3288,7 @@ prefs_set_request(Config) ->
         ?assert_equal(ResultIQ1, ResultIQ2),
         ok
         end,
-    escalus:story(Config, [{alice, 1}], F).
+    escalus:fresh_story(Config, [{alice, 1}], F).
 
 query_get_request(Config) ->
     F = fun(Alice) ->
@@ -3377,11 +3378,13 @@ muc_prefs_set_request(ConfigIn) ->
 muc_prefs_set_request_not_an_owner(ConfigIn) ->
     F = fun(Config, _Alice, Bob) ->
         Room = ?config(room, Config),
+        RoomAddr = room_address(Room),
         escalus:send(Bob, stanza_to_room(stanza_prefs_set_request(<<"roster">>,
                                                                     [<<"[email protected]">>],
                                                                     [<<"[email protected]">>],
                                                                     mam_ns_binary()), Room)),
-        escalus:assert(is_error, [<<"cancel">>, <<"not-allowed">>], escalus:wait_for_stanza(Bob))
+        escalus:assert(is_error, [<<"cancel">>, <<"not-allowed">>], escalus:wait_for_stanza(Bob)),
+        assert_no_event_with_jid(mod_mam_muc_get_prefs, RoomAddr)
     end,
     RoomOpts = [{persistent, true}],
     UserSpecs = [{alice, 1}, {bob, 1}],