More specific assertions for instrumentation events #4312

chrzaszcz · 2024-06-26T14:39:41Z

The goal is to make instrumentation assertions more specific and flexible, allowing to test negative cases, wait for specific events, and expect a specific number of events.

In a test case, you can now use:

Convenience functions: assert/3, assert_one/3, assert_not_emitted/1-3, wait_and_assert/3, wait_and_assert_new/3. They cover most of the typical cases.
For more complex checks, e.g. expecting more than one event, you can use assert/4, which takes a map of options as the last argument. All the convenience functions are calling assert/4. This can be especially useful with timestamp/0, allowing to check events after a given point in time.

The take function is replaced with selection based on timestamp. By not removing events, we can now use all assertions in parallel tests without the risk of accidental event removal.

The test suites are changed to use the new assertions.

When possible, assert the exact number of events (usually one).
- For privacy tests, this required the use of timestamps, because assertions happen in helpers, which can be executed many times per test case, making the evens accumulate. Alternatively, we could add more metadata to the events, but I tried to limit such changes in this PR, and sometimes the events would be difficult to distinguish anyway. IMO it is good that we have some tests actually using the timestamps.
When suitable, test negative conditions.
Replace custom waiting code with wait_and_assert(_new).
For mod_global_distrib_SUITE, there were some fixes needed (details in commit messages). it was also difficult to make the test more strict, because the cases seem to test some events that have occurred before they start, while during the test there could be more such events happening. This was the case for multiple events (I checked them one by one). I haven't investigated the reasons behind the asynchronous events.

The helpers were tested manually by making various assertions fail. The new logs for failed assertions are also more detailed, for example (output is truncated):

Assertion failed for event mod_privacy_check_packet with labels #{host_type =>
                                                                      <<"localhost">>}.
Matching measurements:
[#{count => 1,dir => out,
   jid =>
       {jid,<<"bob_unnamed_14_messages_from_blocked_user_dont_arrive_15">>,
            <<"localhost">>,<<"res1">>}},
 #{count => 1,dir => out,
   jid =>
       {jid,<<"bob_unnamed_14_messages_from_blocked_user_dont_arrive_15">>,
            <<"localhost">>,<<"res1">>}},
 #{count => 1,dir => out,
   jid =>
       {jid,<<"bob_unnamed_14_messages_from_blocked_user_dont_arrive_15">>,
            <<"localhost">>,<<"res1">>}}]

Other measurements:
[#{count => 1,dir => out,
   jid =>
       {jid,<<"alice_unnamed_3_invalid_block_request_13">>,<<"localhost">>,
            <<"res1">>}},
 #{count => 1,dir => out,
   jid =>
       {jid,<<"alice_unnamed_3_remove_user_from_blocklist_6">>,
            <<"localhost">>,<<"res1">>}},
 #{count => 1,dir => out,
   jid =>
       {jid,<<"alice_unnamed_3_discovering_support_9">>,<<"localhost">>,
            <<"res1">>}},
 #{count => 1,dir => out,
   jid =>
       {jid,<<"alice_unnamed_3_remove_many_user_from_blocklist_12">>,
            <<"localhost">>,<<"res1">>}},
 #{count => 1,dir => out,
   jid =>
       {jid,<<"alice_unnamed_3_clear_blocklist_4">>,<<"localhost">>,
            <<"res1">>}},
...

*** CT Error Notification 2024-07-04 09:49:52.597 ***
mod_blocking_SUITE:'-messages_from_blocked_user_dont_arrive/1-fun-0-' failed on line 239
Reason: {test_case_failed,Incorrect number of instrumentation events - matched: 3, expected: 1}

codecov · 2024-06-26T14:48:31Z

Codecov Report

All modified and coverable lines are covered by tests ✅

Project coverage is 84.65%. Comparing base (6730fe5) to head (6939f92).

Additional details and impacted files

@@                  Coverage Diff                   @@
##           feature/instrument    #4312      +/-   ##
======================================================
+ Coverage               81.99%   84.65%   +2.65%     
======================================================
  Files                     553      553              
  Lines                   33867    33868       +1     
======================================================
+ Hits                    27769    28670     +901     
+ Misses                   6098     5198     -900

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

mongoose-im · 2024-07-04T08:14:17Z

elasticsearch_and_cassandra_26 / elasticsearch_and_cassandra_mnesia / fdea5fa
Reports root/ big
OK: 455 / Failed: 0 / User-skipped: 41 / Auto-skipped: 0

small_tests_25 / small_tests / fdea5fa
Reports root / small

small_tests_26 / small_tests / fdea5fa
Reports root / small

small_tests_26_arm64 / small_tests / fdea5fa
Reports root / small

ldap_mnesia_25 / ldap_mnesia / fdea5fa
Reports root/ big
OK: 2286 / Failed: 0 / User-skipped: 910 / Auto-skipped: 0

dynamic_domains_pgsql_mnesia_25 / pgsql_mnesia / fdea5fa
Reports root/ big
OK: 4612 / Failed: 0 / User-skipped: 106 / Auto-skipped: 0

ldap_mnesia_26 / ldap_mnesia / fdea5fa
Reports root/ big
OK: 2285 / Failed: 1 / User-skipped: 910 / Auto-skipped: 0

privacy_SUITE:management:remove_list

{error,{test_case_failed,"Incorrect number of instrumentation events - matched: 0, expected: 1"}}

Report log

dynamic_domains_mysql_redis_26 / mysql_redis / fdea5fa
Reports root/ big
OK: 4578 / Failed: 0 / User-skipped: 139 / Auto-skipped: 1

mam_SUITE:rdbms_async_cache_muc_all:muc_prefs_cases:muc_query_get_request

{skip,
  {failed,
    {mam_SUITE,init_per_testcase,
      {{badrpc,
         {'EXIT',
           {#{module => mod_mam_rdbms_prefs,
            text => <<"Module missing from mongoose_config">>,
            host_type => <<"test type">>,
            what => module_not_loaded},
            [{gen_mod,assert_loaded,2,
               [{file,"/home/circleci/project/src/gen_mod.erl"},
              {line,346}]},
             {gen_mod,start_module,3,
               [{file,"/home/circleci/project/src/gen_mod.erl"},
              {line,96}]},
             {mongoose_modules,start_module,4,
               [{file,
                "/home/circleci/project/src/mongoose_modules.erl"},
              {line,90}]},
             {mongoose_modules,ensure_started,3,
               [{file,
                "/home/circleci/project/src/mongoose_modules.erl"},
              {line,80}]},
             {mongoose_modules,'-replace_modules/3-lc$^1/1-1-',2,
               [{file,
                "/home/circleci/project/src/mongoose_modules.erl"},
              {line,50}]},
             {mongoose_modules,replace_modules,3,
               [{file,
                "/home/circleci/project/src/mongoose_modules.erl"},
              {line,51}]}]}}},
       [{distributed_helper,rpc,
          [#{node => mongooseim@localhost},
           mongoose_modules,replace_modules,
           [<<"test type">>,[],
          #{mod_mam =>
              #{cache =>
                #{module => internal,strategy => fifo,
                 ...

Report log

dynamic_domains_mssql_mnesia_26 / odbc_mssql_mnesia / fdea5fa
Reports root/ big
OK: 4609 / Failed: 0 / User-skipped: 109 / Auto-skipped: 0

dynamic_domains_pgsql_mnesia_26 / pgsql_mnesia / fdea5fa
Reports root/ big
OK: 4612 / Failed: 0 / User-skipped: 106 / Auto-skipped: 0

pgsql_cets_26 / pgsql_cets / fdea5fa
Reports root/ big
OK: 4513 / Failed: 0 / User-skipped: 176 / Auto-skipped: 0

internal_mnesia_26 / internal_mnesia / fdea5fa
Reports root/ big
OK: 2428 / Failed: 0 / User-skipped: 768 / Auto-skipped: 0

pgsql_mnesia_25 / pgsql_mnesia / fdea5fa
Reports root/ big
OK: 5003 / Failed: 0 / User-skipped: 115 / Auto-skipped: 1

mam_SUITE:rdbms_cache_muc_all:muc_prefs_cases:muc_prefs_set_request

{skip,
  {failed,
    {mam_SUITE,init_per_testcase,
      {{badrpc,
         {'EXIT',
           {#{host_type => <<"localhost">>,
            module => mod_mam_rdbms_prefs,
            text => <<"Module missing from mongoose_config">>,
            what => module_not_loaded},
            [{gen_mod,assert_loaded,2,
               [{file,"/home/circleci/project/src/gen_mod.erl"},
              {line,346}]},
             {gen_mod,start_module,3,
               [{file,"/home/circleci/project/src/gen_mod.erl"},
              {line,96}]},
             {mongoose_modules,start_module,4,
               [{file,
                "/home/circleci/project/src/mongoose_modules.erl"},
              {line,90}]},
             {mongoose_modules,ensure_started,3,
               [{file,
                "/home/circleci/project/src/mongoose_modules.erl"},
              {line,80}]},
             {mongoose_modules,'-replace_modules/3-lc$^1/1-1-',2,
               [{file,
                "/home/circleci/project/src/mongoose_modules.erl"},
              {line,50}]},
             {mongoose_modules,replace_modules,3,
               [{file,
                "/home/circleci/project/src/mongoose_modules.erl"},
              {line,51}]}]}}},
       [{distributed_helper,rpc,
          [#{node => mongooseim@localhost},
           mongoose_modules,replace_modules,
           [<<"localhost">>,[],
          #{mod_mam =>
              #{archive_chat_markers => false,
              async_writer =>
                #{ba...

Report log

mysql_redis_26 / mysql_redis / fdea5fa
Reports root/ big
OK: 4985 / Failed: 0 / User-skipped: 134 / Auto-skipped: 0

pgsql_mnesia_26 / pgsql_mnesia / fdea5fa
Reports root/ big
OK: 5004 / Failed: 0 / User-skipped: 115 / Auto-skipped: 0

mssql_mnesia_26 / odbc_mssql_mnesia / fdea5fa
Reports root/ big
OK: 5001 / Failed: 0 / User-skipped: 118 / Auto-skipped: 0

In a test case, you can now use: 1. Convenience functions: assert/3, assert_one/3, assert_not_emitted/1-3, wait_and_assert/3, wait_and_assert_new/3. They cover most of the typical cases. 2. For more complex checks, e.g. expecting more than one event, you can use assert/4, which takes a map of options as the last argument. All the convenience functions are calling assert/4. This can be especially useful with timestamp/0, allowing to check events after a given point in time. The 'take' function is replaced with selection based on timestamp. By not removing events, we can now use all assertions in parallel tests without the risk of accidental event removal.

The goal is to have reliable assertions for multiple events. With the 'bag' type, an event occuring twice would be stored once if all metric values were the same. The problem is that some metrics, e.g. time, are unpredictable, and the resulting number of events would be non-deterministic. This change makes it necessary to fix multiple tests, but they are being changed anyway - see the subsequent commits.

mongoose-im · 2024-07-04T09:44:46Z

elasticsearch_and_cassandra_26 / elasticsearch_and_cassandra_mnesia / 16aa0cd
Reports root/ big
OK: 454 / Failed: 0 / User-skipped: 41 / Auto-skipped: 1

mam_SUITE:elasticsearch_muc_all:muc_prefs_cases:muc_messages_filtered_when_prefs_default_policy_is_never

{skip,
  {failed,
    {mam_SUITE,init_per_testcase,
      {{badrpc,
         {'EXIT',
           {#{module => mod_mam_mnesia_prefs,
            text => <<"Module missing from mongoose_config">>,
            host_type => <<"localhost">>,
            what => module_not_loaded},
            [{gen_mod,assert_loaded,2,
               [{file,"/home/circleci/project/src/gen_mod.erl"},
              {line,346}]},
             {gen_mod,start_module,3,
               [{file,"/home/circleci/project/src/gen_mod.erl"},
              {line,96}]},
             {mongoose_modules,start_module,4,
               [{file,
                "/home/circleci/project/src/mongoose_modules.erl"},
              {line,90}]},
             {mongoose_modules,ensure_started,3,
               [{file,
                "/home/circleci/project/src/mongoose_modules.erl"},
              {line,80}]},
             {mongoose_modules,'-replace_modules/3-lc$^1/1-1-',2,
               [{file,
                "/home/circleci/project/src/mongoose_modules.erl"},
              {line,50}]},
             {mongoose_modules,replace_modules,3,
               [{file,
                "/home/circleci/project/src/mongoose_modules.erl"},
              {line,51}]}]}}},
       [{distributed_helper,rpc,
          [#{node => mongooseim@localhost},
           mongoose_modules,replace_modules,
           [<<"localhost">>,[],
          #{mod_mam =>
              #{cache =>
                #{module => internal,strategy => fifo,
                ...

Report log

small_tests_25 / small_tests / 16aa0cd
Reports root / small

small_tests_26 / small_tests / 16aa0cd
Reports root / small

small_tests_26_arm64 / small_tests / 16aa0cd
Reports root / small

ldap_mnesia_26 / ldap_mnesia / 16aa0cd
Reports root/ big
OK: 2286 / Failed: 0 / User-skipped: 910 / Auto-skipped: 0

dynamic_domains_mysql_redis_26 / mysql_redis / 16aa0cd
Reports root/ big
OK: 4579 / Failed: 0 / User-skipped: 139 / Auto-skipped: 0

ldap_mnesia_25 / ldap_mnesia / 16aa0cd
Reports root/ big
OK: 2286 / Failed: 0 / User-skipped: 910 / Auto-skipped: 0

dynamic_domains_pgsql_mnesia_25 / pgsql_mnesia / 16aa0cd
Reports root/ big
OK: 4612 / Failed: 0 / User-skipped: 106 / Auto-skipped: 0

dynamic_domains_pgsql_mnesia_26 / pgsql_mnesia / 16aa0cd
Reports root/ big
OK: 4612 / Failed: 0 / User-skipped: 106 / Auto-skipped: 0

internal_mnesia_26 / internal_mnesia / 16aa0cd
Reports root/ big
OK: 2428 / Failed: 0 / User-skipped: 768 / Auto-skipped: 0

dynamic_domains_mssql_mnesia_26 / odbc_mssql_mnesia / 16aa0cd
Reports root/ big
OK: 4609 / Failed: 0 / User-skipped: 109 / Auto-skipped: 0

pgsql_mnesia_25 / pgsql_mnesia / 16aa0cd
Reports root/ big
OK: 5004 / Failed: 0 / User-skipped: 115 / Auto-skipped: 0

mysql_redis_26 / mysql_redis / 16aa0cd
Reports root/ big
OK: 4985 / Failed: 0 / User-skipped: 134 / Auto-skipped: 0

pgsql_mnesia_26 / pgsql_mnesia / 16aa0cd
Reports root/ big
OK: 5003 / Failed: 1 / User-skipped: 115 / Auto-skipped: 0

mod_global_distrib_SUITE:mod_global_distrib:test_instrumentation_events_on_one_host

{error,{test_case_failed,"Incorrect number of instrumentation events - matched: 2, expected: 1"}}

Report log

mod_global_distrib_SUITE:end_per_suite

{error,{test_case_failed,"Instrumentation events that were logged, but not tested:\n[{mod_global_distrib_incoming_closed,#{}},\n {mod_global_distrib_incoming_established,#{}},\n {mod_global_distrib_incoming_first_packet,#{}},\n {mod_global_distrib_incoming_messages,#{}},\n {mod_global_distrib_incoming_queue,#{}},\n {mod_global_distrib_incoming_transfer,#{}}]\nYou need to test them with instrument_helper:assert/3"}}

Report log

mssql_mnesia_26 / odbc_mssql_mnesia / 16aa0cd
Reports root/ big
OK: 5001 / Failed: 0 / User-skipped: 118 / Auto-skipped: 0

- Expect exact number of events when possible - Correct issues with variable shadowing in funs, which had the effect of disabling some checks - Fix the wrong expected host name - Simplify waiting for events with wait_and_assert(_new)

- Remove a leftover assertion - Fix minor issues with variables - Disable test repeat (we are doing this for all suites)

To assert the exact number of events (usually one), assertions need to check the timestamps, because event in a single test there are usually multiple events for the same user.

- When possible, assert the exact number of events (usually one) - When suitable, test negative conditions - Replace custom waiting code with wait_and_assert(_new)

mongoose-im · 2024-07-04T10:53:30Z

elasticsearch_and_cassandra_26 / elasticsearch_and_cassandra_mnesia / 6939f92
Reports root/ big
OK: 455 / Failed: 0 / User-skipped: 41 / Auto-skipped: 0

small_tests_25 / small_tests / 6939f92
Reports root / small

small_tests_26 / small_tests / 6939f92
Reports root / small

small_tests_26_arm64 / small_tests / 6939f92
Reports root / small

ldap_mnesia_25 / ldap_mnesia / 6939f92
Reports root/ big
OK: 2286 / Failed: 0 / User-skipped: 910 / Auto-skipped: 0

dynamic_domains_pgsql_mnesia_25 / pgsql_mnesia / 6939f92
Reports root/ big
OK: 4612 / Failed: 0 / User-skipped: 106 / Auto-skipped: 0

dynamic_domains_mysql_redis_26 / mysql_redis / 6939f92
Reports root/ big
OK: 4579 / Failed: 0 / User-skipped: 139 / Auto-skipped: 0

ldap_mnesia_26 / ldap_mnesia / 6939f92
Reports root/ big
OK: 2286 / Failed: 0 / User-skipped: 910 / Auto-skipped: 0

internal_mnesia_26 / internal_mnesia / 6939f92
Reports root/ big
OK: 2428 / Failed: 0 / User-skipped: 768 / Auto-skipped: 0

pgsql_cets_26 / pgsql_cets / 6939f92
Reports root/ big
OK: 4513 / Failed: 0 / User-skipped: 176 / Auto-skipped: 0

dynamic_domains_pgsql_mnesia_26 / pgsql_mnesia / 6939f92
Reports root/ big
OK: 4612 / Failed: 0 / User-skipped: 106 / Auto-skipped: 0

dynamic_domains_mssql_mnesia_26 / odbc_mssql_mnesia / 6939f92
Reports root/ big
OK: 4609 / Failed: 0 / User-skipped: 109 / Auto-skipped: 0

pgsql_mnesia_25 / pgsql_mnesia / 6939f92
Reports root/ big
OK: 5004 / Failed: 0 / User-skipped: 115 / Auto-skipped: 0

mysql_redis_26 / mysql_redis / 6939f92
Reports root/ big
OK: 4985 / Failed: 0 / User-skipped: 134 / Auto-skipped: 0

pgsql_mnesia_26 / pgsql_mnesia / 6939f92
Reports root/ big
OK: 5004 / Failed: 0 / User-skipped: 115 / Auto-skipped: 0

mssql_mnesia_26 / odbc_mssql_mnesia / 6939f92
Reports root/ big
OK: 5001 / Failed: 0 / User-skipped: 118 / Auto-skipped: 0

gustawlippa

Thanks for the changes! The new helpers are great, and it's nice to see the code simpler in tests thanks to them. I also really like the new logs for failed assertions! 👍

Nice to see bugs in tests fixed, as well as the tests being more strict in general with the new assertions.

Looks good to me, I have no comments 👍