Merge pull request #4304 from esl/instrument_c2s

Add C2S TCP/TLS listener instrumentation metrics

big_tests/tests/bosh_SUITE.erl

@@ -107,7 +107,7 @@ acks_test_cases() ->
 %%--------------------------------------------------------------------
 
 init_per_suite(Config) ->
-    instrument_helper:start(instrumentation_events()),
+    instrument_helper:start(instrumentation_events(), negative_instrumentation_events()),
     Config1 = dynamic_modules:save_modules(host_type(), Config),
     escalus:init_per_suite([{escalus_user_db, {module, escalus_ejabberd}} | Config1]).
 
@@ -172,11 +172,6 @@ required_bosh_opts(_Group) ->
 %%--------------------------------------------------------------------
 
 create_and_terminate_session(Config) ->
-    MongooseMetrics = [{[global, data, xmpp, received, xml_stanza_size], changed},
-                       {[global, data, xmpp, sent, xml_stanza_size], changed},
-                       {[global, data, xmpp, received, c2s, tcp], 0},
-                       {[global, data, xmpp, sent, c2s, tcp], 0}],
-    PreStoryData = escalus_mongooseim:pre_story([{mongoose_metrics, MongooseMetrics}]),
     NamedSpecs = escalus_config:get_config(escalus_users, Config),
     CarolSpec = proplists:get_value(?config(user, Config), NamedSpecs),
     Conn = escalus_connection:connect(CarolSpec),
@@ -198,9 +193,10 @@ create_and_terminate_session(Config) ->
 
     % Assert that correct events have been executed
     [instrument_helper:assert(Event, Label, fun(#{byte_size := BS}) -> BS > 0 end)
-     || {Event, Label} <- instrumentation_events()],
+     || {Event, Label} <- instrumentation_events(), Event =/= c2s_message_processing_time],
 
-    escalus_mongooseim:post_story(PreStoryData),
+    %% Verify C2S listener is not used
+    instrument_helper:assert_not_emitted(negative_instrumentation_events()),
 
     %% Assert the session was terminated.
     wait_for_zero_bosh_sessions().
@@ -375,6 +371,10 @@ interleave_requests(Config) ->
         escalus:assert(is_chat_message, [Msg4],
                        escalus_client:wait_for_stanza(Geralt)),
 
+        [instrument_helper:assert(Event, Label, fun(#{byte_size := BS}) -> BS > 0;
+                                                   (#{time := Time}) -> Time > 0 end)
+         || {Event, Label} <- instrumentation_events()],
+
         true = is_bosh_connected(Carol)
     end).
 
@@ -952,4 +952,15 @@ wait_for_zero_bosh_sessions() ->
                                #{name => get_bosh_sessions}).
 
 instrumentation_events() ->
-    instrument_helper:declared_events(mod_bosh, []).
+    instrument_helper:declared_events(mod_bosh, [])
+    ++ instrument_helper:declared_events(mongoose_c2s, [global])
+    ++ instrument_helper:declared_events(mongoose_c2s). %% For host_type()
+
+negative_instrumentation_events() ->
+    [{Name, #{}} || Name <- negative_instrumentation_events_names()].
+
+negative_instrumentation_events_names() ->
+    [c2s_tcp_data_sent,
+     c2s_tcp_data_received,
+     c2s_tls_data_sent,
+     c2s_tls_data_received].

big_tests/tests/component_SUITE.erl

@@ -166,13 +166,11 @@ intercomponent_communication(Config) ->
     {Comp1, CompAddr1, _} = connect_component(CompOpts1),
     {Comp2, CompAddr2, _} = connect_component(CompOpts2),
     MongooseMetrics = [{[global, data, xmpp, received, component], changed},
-                       {[global, data, xmpp, sent, component], changed},
-                       {[global, data, xmpp, received, xml_stanza_size], changed},
-                       {[global, data, xmpp, sent, xml_stanza_size], changed}],
+                       {[global, data, xmpp, sent, component], changed}],
 
     PreStoryData = escalus_mongooseim:pre_story([{mongoose_metrics, MongooseMetrics}]),
     %% note that there is no c2s communication happens and 
-    %% data.xmpp.*.xml_stanza_size metrics are bounced
+    %% xmpp_stanza_size_sent/xmpp_stanza_size_received metrics are bounced
     %% for the components communication
 
     %% When the first component sends a message the second component
@@ -195,9 +193,7 @@ register_two_components(Config) ->
     {Comp1, CompAddr1, _} = connect_component(CompOpts1),
     {Comp2, CompAddr2, _} = connect_component(CompOpts2),
     MongooseMetrics = [{[global, data, xmpp, received, component], changed},
-                       {[global, data, xmpp, sent, component], changed},
-                       {[global, data, xmpp, received, xml_stanza_size], changed},
-                       {[global, data, xmpp, sent, xml_stanza_size], changed}],
+                       {[global, data, xmpp, sent, component], changed}],
 
     escalus:story([{mongoose_metrics, MongooseMetrics} | Config],
                   [{alice, 1}, {bob, 1}], fun(Alice, Bob) ->

big_tests/tests/connect_SUITE.erl

@@ -132,6 +132,7 @@ suite() ->
 %%--------------------------------------------------------------------
 
 init_per_suite(Config) ->
+    instrument_helper:start(instrumentation_events()),
     Config0 = escalus:init_per_suite([{escalus_user_db, {module, escalus_ejabberd, []}} | Config]),
     C2SPort = ct:get_config({hosts, mim, c2s_port}),
     [C2SListener] = mongoose_helper:get_listeners(mim(), #{port => C2SPort, module => mongoose_c2s_listener}),
@@ -140,6 +141,7 @@ init_per_suite(Config) ->
     escalus:create_users(Config1, escalus:get_users([?SECURE_USER, alice])).
 
 end_per_suite(Config) ->
+    instrument_helper:stop(),
     escalus_fresh:clean(),
     escalus:delete_users(Config, escalus:get_users([?SECURE_USER, alice])),
     restore_c2s_listener(Config),
@@ -399,16 +401,13 @@ starttls_should_fail_when_disabled(Config) ->
     escalus_connection:wait_for_close(Conn, timer:seconds(5)).
 
 metrics_test(Config) ->
-    MongooseMetrics = [{[global, data, xmpp, received, xml_stanza_size], changed},
-                       {[global, data, xmpp, sent, xml_stanza_size], changed},
-                       {[global, data, xmpp, received, c2s, tls], changed},
-                       {[global, data, xmpp, sent, c2s, tls], changed},
-                       %% TCP traffic before starttls
-                       {[global, data, xmpp, received, c2s, tcp], changed},
-                       {[global, data, xmpp, sent, c2s, tcp], changed}],
-    PreStoryData = escalus_mongooseim:pre_story([{mongoose_metrics, MongooseMetrics}]),
     tls_authenticate(Config),
-    escalus_mongooseim:post_story(PreStoryData).
+
+    % Assert that correct events have been executed
+    [instrument_helper:assert(Event, Label, fun(#{byte_size := BS}) -> BS > 0;
+                                               (#{time := Time}) -> Time > 0 end)
+     || {Event, Label} <- instrumentation_events(),
+        Event =/= c2s_message_processing_time].
 
 tls_authenticate(Config) ->
     %% Given
@@ -815,3 +814,8 @@ proxy_info() ->
       dest_address => {192, 168, 0, 1},
       dest_port => 443
      }.
+
+instrumentation_events() ->
+    instrument_helper:declared_events(mongoose_c2s_listener, [#{}])
+    ++ instrument_helper:declared_events(mongoose_c2s, [global])
+    ++ instrument_helper:declared_events(mongoose_c2s). %% For host_type()

big_tests/tests/graphql_metric_SUITE.erl

@@ -252,16 +252,16 @@ get_metrics_as_dicts_with_nonexistent_key(Config) ->
     Result = get_metrics_as_dicts_with_keys([<<"not_existing">>], Config),
     ParsedResult = get_ok_value([data, metric, getMetricsAsDicts], Result),
     Map = dict_objects_to_map(ParsedResult),
-    SentName = [<<"global">>, <<"data">>, <<"xmpp">>, <<"received">>, <<"xml_stanza_size">>],
-    [] = maps:get(SentName, Map).
+    RecvName = [<<"global">>, <<"xmpp_stanza_size_received">>, <<"byte_size">>],
+    [] = maps:get(RecvName, Map).
 
 get_metrics_as_dicts_empty_args(Config) ->
     %% Empty name
     Result = get_metrics_as_dicts([], [<<"median">>], Config),
     ParsedResult = get_ok_value([data, metric, getMetricsAsDicts], Result),
     Map = dict_objects_to_map(ParsedResult),
-    SentName = [<<"global">>, <<"data">>, <<"xmpp">>, <<"received">>, <<"xml_stanza_size">>],
-    [#{<<"key">> := <<"median">>, <<"value">> := Median}] = maps:get(SentName, Map),
+    RecvName = [<<"global">>, <<"xmpp_stanza_size_received">>, <<"byte_size">>],
+    [#{<<"key">> := <<"median">>, <<"value">> := Median}] = maps:get(RecvName, Map),
     ?assert(is_integer(Median)),
     %% Empty keys
     Result2 = get_metrics_as_dicts([<<"global">>, <<"erlang">>], [], Config),
@@ -376,8 +376,7 @@ check_node_result_is_valid(ResList, MetricsAreGlobal) ->
     [#{<<"key">> := <<"value">>,<<"value">> := V}] =
         maps:get([<<"global">>,<<"uniqueSessionCount">>], Map),
     ?assert(is_integer(V)),
-    HistObjects = maps:get([<<"global">>, <<"data">>, <<"xmpp">>,
-                            <<"sent">>, <<"xml_stanza_size">>], Map),
+    HistObjects = maps:get([<<"global">>, <<"xmpp_stanza_size_received">>, <<"byte_size">>], Map),
     check_histogram(kv_objects_to_map(HistObjects)).
 
 check_histogram(Map) ->

big_tests/tests/instrument_helper.erl

@@ -4,8 +4,9 @@
 -module(instrument_helper).
 
 -export([declared_events/1, declared_events/2,
-         start/1, stop/0,
+         start/1, start/2, stop/0,
          assert/3, assert/4,
+         assert_not_emitted/1, assert_not_emitted/2,
          wait_for/2, wait_for_new/2,
          lookup/2, take/2]).
 
@@ -33,25 +34,30 @@ declared_events(Module, Args) ->
     Specs = rpc(mim(), Module, instrumentation, Args),
     [{Event, Labels} || {Event, Labels, _Config} <- Specs].
 
-%% @doc Only `DeclaredEvents' will be logged, and can be tested with `assert/3'
--spec start([{event_name(), labels()} | module()]) -> ok.
+-spec start([{event_name(), labels()}]) -> ok.
 start(DeclaredEvents) ->
+    start(DeclaredEvents, []).
+
+%% @doc Only `DeclaredEvents' will be logged, and can be tested with `assert/3'
+-spec start([{event_name(), labels()}], [{event_name(), labels()}]) -> ok.
+start(DeclaredEvents, NegativeEvents) ->
     mongoose_helper:inject_module(ets_helper),
     mongoose_helper:inject_module(?HANDLER_MODULE),
     ets_helper:new(?STATUS_TABLE),
+    [ets:insert(?STATUS_TABLE, {Event, negative}) || Event <- NegativeEvents],
     [ets:insert(?STATUS_TABLE, {Event, untested}) || Event <- DeclaredEvents],
     rpc(mim(), mongoose_instrument, add_handler,
-        [event_table, #{declared_events => DeclaredEvents}]).
+        [event_table, #{declared_events => DeclaredEvents ++ NegativeEvents}]).
 
 -spec stop() -> ok.
 stop() ->
-    #{tested := Tested, untested := Untested} = classify_events(),
+    #{tested := Tested, untested := Untested, negative := Negative} = classify_events(),
     ets_helper:delete(?STATUS_TABLE),
     Logged = rpc(mim(), ?HANDLER_MODULE, all_keys, []),
     rpc(mim(), mongoose_instrument, remove_handler, [event_table]),
     ct:log("Tested instrumentation events:~n~p", [lists:sort(Tested)]),
-    verify_unlogged(Untested -- Logged),
-    verify_logged_but_untested(Logged -- Tested).
+    verify_unlogged((Untested -- Logged) -- Negative),
+    verify_logged_but_untested((Logged -- Tested) -- Negative).
 
 -spec assert(event_name(), labels(), fun((measurements()) -> boolean())) -> ok.
 assert(EventName, Labels, CheckF) ->
@@ -74,6 +80,17 @@ assert(EventName, Labels, MeasurementsList, CheckF) ->
             event_tested(EventName, Labels)
     end.
 
+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(Events) ->
+    [assert_not_emitted(Event, Label) || {Event, Label} <- Events].
+
 %% @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) ->
@@ -116,7 +133,7 @@ event_tested(EventName, Labels) ->
     ok.
 
 classify_events() ->
-    ets:foldl(fun classify_event/2, #{tested => [], untested => []}, ?STATUS_TABLE).
+    ets:foldl(fun classify_event/2, #{tested => [], untested => [], negative => []}, ?STATUS_TABLE).
 
 classify_event({Event, Status}, M) ->
     M#{Status => [Event | maps:get(Status, M)]}.

big_tests/tests/metrics_roster_SUITE.erl

@@ -51,9 +51,7 @@ subscription_tests() -> [subscribe,
 
 init_per_suite(Config) ->
     instrument_helper:start(declared_events()),
-    MongooseMetrics = [{[global, data, xmpp, received, xml_stanza_size], changed},
-                       {[global, data, xmpp, sent, xml_stanza_size], changed},
-                       {fun roster_rdbms_precondition/0, [global, data, rdbms, default],
+    MongooseMetrics = [{fun roster_rdbms_precondition/0, [global, data, rdbms, default],
                         [{recv_oct, '>'}, {send_oct, '>'}]}
                        ],
     [{mongoose_metrics, MongooseMetrics} | escalus:init_per_suite(Config)].

big_tests/tests/mim_c2s_SUITE.erl

@@ -45,6 +45,7 @@ groups() ->
 %% Init & teardown
 %%--------------------------------------------------------------------
 init_per_suite(Config) ->
+    instrument_helper:start(instrumentation_events()),
     HostType = domain_helper:host_type(),
     Config1 = dynamic_modules:save_modules(HostType, Config),
     dynamic_modules:ensure_stopped(HostType, [mod_presence]),
@@ -53,6 +54,7 @@ init_per_suite(Config) ->
     escalus:init_per_suite([{escalus_overrides, EscalusOverrides} | Config1 ]).
 
 end_per_suite(Config) ->
+    instrument_helper:stop(),
     dynamic_modules:restore_modules(Config),
     mongoose_helper:restore_config(Config),
     escalus:end_per_suite(Config).
@@ -116,19 +118,18 @@ two_users_can_log_and_chat(Config) ->
     AliceHost = escalus_users:get_server(Config, alice),
     HostType = domain_helper:domain_to_host_type(mim(), AliceHost),
     HostTypePrefix = domain_helper:make_metrics_prefix(HostType),
-    MongooseMetrics = [{[global, data, xmpp, received, xml_stanza_size], changed},
-                       {[global, data, xmpp, sent, xml_stanza_size], changed},
-                       {[global, data, xmpp, received, c2s, tcp], changed},
-                       {[global, data, xmpp, sent, c2s, tcp], changed},
-                       {[HostTypePrefix, data, xmpp, c2s, message, processing_time], changed},
-                       {[global, data, xmpp, received, c2s, tls], 0},
-                       {[global, data, xmpp, sent, c2s, tls], 0}],
-    escalus:fresh_story([{mongoose_metrics, MongooseMetrics} | Config],
+    escalus:fresh_story(Config,
                         [{alice, 1}, {bob, 1}], fun(Alice, Bob) ->
         escalus_client:send(Alice, escalus_stanza:chat_to(Bob, <<"Hi!">>)),
         escalus:assert(is_chat_message, [<<"Hi!">>], escalus_client:wait_for_stanza(Bob)),
         escalus_client:send(Bob, escalus_stanza:chat_to(Alice, <<"Hi!">>)),
-        escalus:assert(is_chat_message, [<<"Hi!">>], escalus_client:wait_for_stanza(Alice))
+        escalus:assert(is_chat_message, [<<"Hi!">>], escalus_client:wait_for_stanza(Alice)),
+
+        % Assert that correct events have been executed
+        [instrument_helper:assert(Event, Label, fun(#{byte_size := BS}) -> BS > 0;
+                                                   (#{time := Time}) -> Time > 0 end)
+         || {Event, Label} <- tcp_instrumentation_events() ++ common_instrumentation_events()],
+        instrument_helper:assert_not_emitted(tls_instrumentation_events())
     end).
 
 too_big_stanza_is_rejected(Config) ->
@@ -236,3 +237,22 @@ escalus_start(Cfg, FlatCDs) ->
     Clients = lists:reverse(RClients),
     [ escalus_assert:has_no_stanzas(Client) || Client <- Clients ],
     Clients.
+
+instrumentation_events() ->
+    instrument_helper:declared_events(mongoose_c2s_listener, [#{}])
+    ++ instrument_helper:declared_events(mongoose_c2s, [global])
+    ++ instrument_helper:declared_events(mongoose_c2s). %% For host_type()
+
+tcp_instrumentation_events() ->
+    [{c2s_tcp_data_sent, #{}},
+     {c2s_tcp_data_received, #{}}].
+
+tls_instrumentation_events() ->
+    [{c2s_tls_data_sent, #{}},
+     {c2s_tls_data_received, #{}}].
+
+common_instrumentation_events() ->
+    HostType = domain_helper:host_type(),
+    [{c2s_message_processing_time, #{host_type => HostType}},
+     {xmpp_stanza_size_received, #{}},
+     {xmpp_stanza_size_sent, #{}}].

big_tests/tests/websockets_SUITE.erl

@@ -54,7 +54,7 @@ suite() ->
 %%--------------------------------------------------------------------
 
 init_per_suite(Config) ->
-    instrument_helper:start(instrumentation_events()),
+    instrument_helper:start(instrumentation_events(), negative_instrumentation_events()),
     Config1 = escalus:init_per_suite(Config),
     Config2 = setup_listeners(Config1),
     escalus:create_users(Config2, escalus:get_users([alice, geralt, geralt_s, carol])).
@@ -101,11 +101,7 @@ update_handler(Handler) ->
 %%--------------------------------------------------------------------
 
 metrics_test(Config) ->
-    MongooseMetrics = [{[global, data, xmpp, received, xml_stanza_size], changed},
-                       {[global, data, xmpp, sent, xml_stanza_size], changed},
-                       {[global, data, xmpp, received, c2s, tcp], 0},
-                       {[global, data, xmpp, sent, c2s, tcp], 0}],
-    escalus:story([{mongoose_metrics, MongooseMetrics} | Config],
+    escalus:story(Config,
                   [{geralt, 1}, {geralt_s, 1}],
                   fun(Geralt, GeraltS) ->
 
@@ -116,8 +112,12 @@ metrics_test(Config) ->
         escalus:assert(is_chat_message, [<<"Hello!">>], escalus_client:wait_for_stanza(GeraltS)),
 
         % Assert that correct events have been executed
-        [instrument_helper:assert(Event, Label, fun(#{byte_size := BS}) -> BS > 0 end)
+        [instrument_helper:assert(Event, Label, fun(#{byte_size := BS}) -> BS > 0;
+                                                   (#{time := Time}) -> Time > 0 end)
          || {Event, Label} <- instrumentation_events()],
+
+        %% Verify C2S listener is not used
+        instrument_helper:assert_not_emitted(negative_instrumentation_events()),
         ok
         end).
 
@@ -169,4 +169,15 @@ escape_attrs(Config) ->
     end).
 
 instrumentation_events() ->
-    instrument_helper:declared_events(mod_websockets, []).
+    instrument_helper:declared_events(mod_websockets, [])
+    ++ instrument_helper:declared_events(mongoose_c2s, [global])
+    ++ instrument_helper:declared_events(mongoose_c2s). %% For host_type()
+
+negative_instrumentation_events() ->
+    [{Name, #{}} || Name <- negative_instrumentation_events_names()].
+
+negative_instrumentation_events_names() ->
+    [c2s_tcp_data_sent,
+     c2s_tcp_data_received,
+     c2s_tls_data_sent,
+     c2s_tls_data_received].