Merge pull request #4362 from esl/domain-service-test-fix

Domain service test fix

big_tests/tests/service_domain_db_SUITE.erl

@@ -206,9 +206,12 @@ init_per_suite(Config) ->
     erase_database(mim()),
     Config2 = ejabberd_node_utils:init(mim(), Config1),
     mongoose_helper:inject_module(?MODULE),
+    %% If there are CI issues, use this to debug SQL queries:
+%   mim_loglevel:enable_logging([mim, mim2, mim3], [{mongoose_domain_sql, debug}]),
     escalus:init_per_suite([{service_setup, per_testcase} | Config2]).
 
 end_per_suite(Config) ->
+%   mim_loglevel:disable_logging([mim, mim2, mim3], [{mongoose_domain_sql, debug}]),
     [restart_domain_core(Node) || Node <- all_nodes()],
     dynamic_services:restore_services(Config),
     domain_helper:insert_configured_domains(),
@@ -1209,7 +1212,7 @@ resume_service(Node) ->
     ok = rpc(Node, sys, resume, [service_domain_db]).
 
 sync_local(Node) ->
-    pong = rpc(Node, service_domain_db, sync_local, []).
+    pong = rpc(Node#{timeout => timer:seconds(30)}, service_domain_db, sync_local, []).
 
 force_check_for_updates(Node) ->
     ok = rpc(Node, service_domain_db, force_check_for_updates, []).

src/domain/mongoose_domain_loader.erl

@@ -106,6 +106,7 @@ check_for_updates({Min, Max},
 check_for_updates(MinMax = {Min, Max},
                   #{min_event_id := OldMin, max_event_id := OldMax})
   when is_integer(Min), is_integer(Max) ->
+    put(debug_last_check_for_updates_minmax, MinMax),
     {MinEventId, MaxEventId} = limit_max_id(OldMax, MinMax, 1000),
     check_if_id_is_still_relevant(OldMax, MinEventId),
     NewGapsFromBelow =
@@ -134,7 +135,9 @@ check_for_updates(MinMax = {Min, Max},
                 Ids = rows_to_ids(Rows),
                 ids_to_gaps(FromId, MaxEventId, Ids)
         end,
-    fix_gaps(NewGapsFromBelow ++ NewGapsFromThePage),
+    Gaps = NewGapsFromBelow ++ NewGapsFromThePage,
+    put(debug_last_gaps, list_to_tuple(Gaps)), %% Convert to a tuple so it could be printed
+    fix_gaps(Gaps),
     State2 = #{min_event_id => MinEventId, max_event_id => MaxEventId},
     mongoose_loader_state:set(State2),
     case MaxEventId < Max of
@@ -263,7 +266,7 @@ fix_gaps(Gaps, Retries) when Retries > 0 ->
     %%
     %% There is no easy way to check for a reason.
     %%
-    %% fix_gaps tries to insert_dummy_event with a gap event id.
+    %% fix_gaps tries to insert_dummy_events with a gap event id.
     %% This makes the state of transaction for gap events obvious:
     %% - if this insert fails, this means the actual record finally
     %%   appears and we can read it.
@@ -274,7 +277,7 @@ fix_gaps(Gaps, Retries) when Retries > 0 ->
     %%
     %% RDBMS servers do not overwrite data when INSERT operation is used.
     %% i.e. only one insert for a key succeeded.
-    [catch mongoose_domain_sql:insert_dummy_event(Id) || Id <- Gaps],
+    catch mongoose_domain_sql:insert_dummy_events(Gaps),
     %% The gaps should be filled at this point
     Rows = lists:append([mongoose_domain_sql:select_updates_between(Id, Id) || Id <- Gaps]),
     ?LOG_WARNING(#{what => domain_fix_gaps, gaps => Gaps, rows => Rows}),

src/domain/mongoose_domain_sql.erl

@@ -19,7 +19,7 @@
          select_updates_between/2,
          get_enabled_dynamic/0,
          delete_events_older_than/1,
-         insert_dummy_event/1]).
+         insert_dummy_events/1]).
 
 %% interfaces only for integration tests
 -export([prepare_test_queries/0,
@@ -30,7 +30,8 @@
 -ignore_xref([erase_database/1, prepare_test_queries/0, get_enabled_dynamic/0,
               insert_full_event/2, insert_domain_settings_without_event/2]).
 
--import(mongoose_rdbms, [prepare/4, execute_successfully/3]).
+-import(mongoose_rdbms, [prepare/4]).
+-include("mongoose_logger.hrl").
 
 -type event_id() :: non_neg_integer().
 -type domain() :: jid:lserver().
@@ -258,19 +259,24 @@ delete_events_older_than(Id) ->
             execute_successfully(Pool, domain_events_delete_older_than, [Id])
         end).
 
-insert_dummy_event(EventId) ->
-    insert_full_event(EventId, <<>>).
+insert_dummy_events(EventIds) ->
+    insert_full_events([{EventId, <<>>} || EventId <- EventIds]).
 
 insert_full_event(EventId, Domain) ->
+    [Res] = insert_full_events([{EventId, Domain}]),
+    Res.
+
+insert_full_events(EventIdDomain) ->
     case mongoose_rdbms:db_type() of
         mssql ->
-            insert_full_event_mssql(EventId, Domain);
+            insert_full_events_mssql(EventIdDomain);
         _ ->
             Pool = get_db_pool(),
-            execute_successfully(Pool, domain_insert_full_event, [EventId, Domain])
+            [catch execute_successfully(Pool, domain_insert_full_event, [EventId, Domain])
+             || {EventId, Domain} <- EventIdDomain]
     end.
 
-insert_full_event_mssql(EventId, Domain) ->
+insert_full_events_mssql(EventIdDomain) ->
     %% MSSQL does not allow to specify ids,
     %% that are supposed to be autoincremented, easily
     %% https://docs.microsoft.com/pl-pl/sql/t-sql/statements/set-identity-insert-transact-sql
@@ -281,7 +287,8 @@ insert_full_event_mssql(EventId, Domain) ->
             %% when trying to execute
             mongoose_rdbms:sql_query(Pool, <<"SET IDENTITY_INSERT domain_events ON">>),
             try
-                execute_successfully(Pool, domain_insert_full_event, [EventId, Domain])
+                [catch execute_successfully(Pool, domain_insert_full_event, [EventId, Domain])
+                 || {EventId, Domain} <- EventIdDomain]
             after
                 mongoose_rdbms:sql_query(Pool, <<"SET IDENTITY_INSERT domain_events OFF">>)
             end
@@ -372,16 +379,26 @@ transaction(F) ->
 %% (there is no logic, that would suffer by a restart of a transaction).
 transaction(_F, 0, Errors) ->
     {error, {db_error, Errors}};
-transaction(F, Retries, Errors) when Retries > 0 ->
+transaction(F, Tries, Errors) when Tries > 0 ->
     Pool = get_db_pool(),
     Result = rdbms_queries:sql_transaction(Pool, fun() -> F(Pool) end),
     case Result of
         {aborted, _} -> %% Restart any rolled back transaction
+            put(debug_last_transaction_error, Result),
             timer:sleep(100), %% Small break before retry
-            transaction(F, Retries - 1, [Result|Errors]);
+            transaction(F, Tries - 1, [Result|Errors]);
         _ ->
+            erase(debug_last_transaction_error),
             simple_result(Result)
     end.
 
 simple_result({atomic, Result}) -> Result;
 simple_result(Other) -> {error, {db_error, Other}}.
+
+execute_successfully(Pool, StatementName, Args) ->
+    {Time, Res} = timer:tc(fun() -> mongoose_rdbms:execute_successfully(Pool, StatementName, Args) end),
+    %% Convert args to tuple, because Erlang formats list as a string for domain_event_ids_between
+    ?LOG_DEBUG(#{what => domain_sql_execute,
+                 statement_name => StatementName, args => list_to_tuple(Args), result => Res,
+                 duration => round(Time / 1000)}),
+    Res.

src/domain/service_domain_db.erl

@@ -95,12 +95,18 @@ sync_local() ->
     true = is_pid(LocalPid),
     Nodes = [node(Pid) || Pid <- all_members()],
     %% Ping from all nodes in the cluster
-    [pong = rpc:call(Node, ?MODULE, ping, [LocalPid]) || Node <- Nodes],
+    {Results, []} = rpc:multicall(Nodes, ?MODULE, ping, [LocalPid]),
+    [pong = Res || Res <- Results],
     pong.
 
 -spec ping(pid()) -> pong.
 ping(Pid) ->
-    gen_server:call(Pid, ping).
+    try
+        gen_server:call(Pid, ping, timer:seconds(15))
+    catch Class:Reason:Stacktrace ->
+        Info = rpc:pinfo(Pid, [current_stacktrace, dictionary]),
+        erlang:raise(Class, {Reason, Info}, Stacktrace)
+    end.
 
 %% ---------------------------------------------------------------------------
 %% Server callbacks