Merge pull request #4427 from esl/mnesia-wait-for-tables-noisy

Print mnesia:wait_for_tables progress

src/mongoose_internal_databases.erl

@@ -7,8 +7,10 @@
 -export([probe/2]).
 
 %% For tests
--export([instrumentation/0]).
--ignore_xref([instrumentation/0]).
+-export([instrumentation/0, wait_for_mnesia/0]).
+-ignore_xref([instrumentation/0, wait_for_mnesia/0]).
+
+-include("mongoose_logger.hrl").
 
 -type db() :: mnesia | cets.
 
@@ -28,11 +30,35 @@ init(mnesia, #{}) ->
             ok
     end,
     application:start(mnesia, permanent),
-    mnesia:wait_for_tables(mnesia:system_info(local_tables), infinity),
+    wait_for_mnesia(),
     mongoose_node_num_mnesia:init();
 init(cets, #{}) ->
     ok.
 
+wait_for_mnesia() ->
+    wait_for_tables_loop(mnesia:system_info(local_tables), 10000, 0).
+
+%% Sometimes mnesia:wait_for_tables/2 could hang on startup.
+%% This function logs which tables are not ready and their status.
+wait_for_tables_loop(Tables, Interval, Total) ->
+    case mnesia:wait_for_tables(Tables, Interval) of
+        ok ->
+            ok;
+        {timeout, WaitingTables} ->
+            ?LOG_WARNING(#{what => mnesia_wait_for_tables_progress,
+                           waiting_for_tables => WaitingTables,
+                           waiting_time => Total + Interval}),
+            [log_detailed_table_info(Tab) || Tab <- WaitingTables],
+            wait_for_tables_loop(WaitingTables, Interval, Total + Interval);
+        {error, Reason} ->
+            error({mnesia_wait_for_tables_failed, Reason})
+    end.
+
+log_detailed_table_info(Tab) ->
+    ?LOG_WARNING(#{what => log_detailed_table_info,
+                   table => Tab,
+                   details => mnesia:table_info(Tab, all)}).
+
 -spec instrumentation() -> [mongoose_instrument:spec()].
 instrumentation() ->
     lists:flatmap(fun instrumentation/1, maps:keys(mongoose_config:get_opt(internal_databases))).

test/common/mongoose_helper.erl

@@ -351,18 +351,20 @@ inject_module(Module) ->
 inject_module(Module, ReloadIfAlreadyLoaded) ->
     inject_module(mim(), Module, ReloadIfAlreadyLoaded).
 
--spec inject_module(Node :: atom(),
+-spec inject_module(Node :: distributed_helper:rpc_spec(),
                     Module :: module(),
                     ReloadIfAlreadyLoaded :: no_reload | reload) ->
     ok | already_loaded.
-inject_module(Node, Module, no_reload) ->
+inject_module(#{node := NodeAtom} = _Node, _, _) when NodeAtom =:= node() ->
+    already_loaded;
+inject_module(#{} = Node, Module, no_reload) ->
     case successful_rpc(Node, code, is_loaded, [Module]) of
         false ->
             inject_module(Node, Module, reload);
         _ ->
             already_loaded
     end;
-inject_module(Node, Module, reload) ->
+inject_module(#{} = Node, Module, reload) ->
     {Mod, Bin, File} = code:get_object_code(Module),
     successful_rpc(Node, code, load_binary, [Mod, File, Bin]).
 

test/mnesia_db_SUITE.erl

@@ -0,0 +1,44 @@
+-module(mnesia_db_SUITE).
+-compile([export_all, nowarn_export_all]).
+
+-include_lib("eunit/include/eunit.hrl").
+
+local() ->
+    #{node => node()}.
+
+all() ->
+      [mnesia_wait_for_tables].
+
+init_per_suite(Config) ->
+    Config.
+
+end_per_suite(_Config) ->
+    ok.
+
+init_per_testcase(_, C) ->
+    mock_mnesia(),
+    logger_ct_backend:start(local()),
+    C.
+
+end_per_testcase(_, _) ->
+    meck:unload(),
+    logger_ct_backend:stop(local()).
+
+mock_mnesia() ->
+    meck:new(mnesia, []),
+    meck:expect(mnesia, system_info, fun(local_tables) -> [test_table_fast, test_table_slow] end),
+    meck:expect(mnesia, table_info, fun(_, _) -> [] end),
+    meck:expect(mnesia, wait_for_tables, fun(Tables, _Interval) ->
+            case meck:num_calls(mnesia, wait_for_tables, '_') > 5 of
+                true -> ok;
+                false -> {timeout, Tables -- [test_table_fast]}
+            end
+        end),
+    ok.
+
+mnesia_wait_for_tables(_Config) ->
+    logger_ct_backend:capture(warning, local()),
+    mongoose_internal_databases:wait_for_mnesia(),
+    logger_ct_backend:stop_capture(local()),
+    FilterFun = fun(_, Msg) -> re:run(Msg, "what: mnesia_wait_for_tables_progress") /= nomatch end,
+    6 = length(logger_ct_backend:recv(FilterFun)).