Merge pull request #4416 from esl/fix-truncated-html-log

Fix truncated html log

This PR addresses "MIM-2348 Logs are truncated on CI in the links. Increase max_no_bytes to 10 megabytes"

Proposed changes include:

    Increase size of maximum log file size from 2MB to 10MB.
    Disable detailed logs for global distribution - this would reduce amount of logs.
    And still there is too much noise in logs from GD trying to stop connections - changed the loglevel, if connections are stopped because of shutdown.
    Enable logs for mim2/mim3 - but without printing INIT/DONE for tests (that is configurable). Reason is to debug clustering logic, which is often fails on CI nowadays.

We used to disable html logs for mim2/mim3 because it breaks --one-node flag in test-runner. But now we check if the node is running, and if not - the hook would not do anything.

Example of INIT/DONE:

INIT suite=mod_http_upload_SUITE group=mod_http_upload_s3 testcase=get_url_ends_with_filename
DONE suite=mod_http_upload_SUITE group=mod_http_upload_s3 testcase=get_url_ends_with_filename

big_tests/default.spec

@@ -130,7 +130,11 @@
 %% ct_mongoose_hook will:
 %% * ensure preset & mim_data_dir values are passed to ct Config
 %% * check server's purity after SUITE
-{ct_hooks, [ct_groups_summary_hook, ct_tty_hook, ct_mongoose_hook, ct_progress_hook,
+{ct_hooks, [ct_groups_summary_hook, ct_tty_hook,
+            ct_mongoose_hook,
+            {ct_mongoose_log_hook, [{host, mim2}, {print_init_and_done_for_testcases, false}]},
+            {ct_mongoose_log_hook, [{host, mim3}, {print_init_and_done_for_testcases, false}]},
+            ct_progress_hook,
             ct_markdown_errors_hook, ct_mongoose_log_hook]}.
 
 %% since test-runner.sh can be executed with the --one-node option,

big_tests/dynamic_domains.spec

@@ -174,7 +174,10 @@
 %% * ensure preset & mim_data_dir values are passed to ct Config
 %% * check server's purity after SUITE
 {ct_hooks, [ct_groups_summary_hook, ct_tty_hook, ct_mongoose_hook, ct_progress_hook,
-            ct_markdown_errors_hook, ct_mongoose_log_hook]}.
+            ct_markdown_errors_hook,
+            ct_mongoose_log_hook,
+            {ct_mongoose_log_hook, [{host, mim2}, {print_init_and_done_for_testcases, false}]},
+            {ct_mongoose_log_hook, [{host, mim3}, {print_init_and_done_for_testcases, false}]}]}.
 
 %% since test-runner.sh can be executed with the --one-node option,
 %% log collection is enabled by default for host mim1 only.

big_tests/mam.spec

@@ -23,7 +23,10 @@
 %% ct_mongoose_hook will:
 %% * ensure preset & mim_data_dir values are passed to ct Config
 %% * check server's purity after SUITE
-{ct_hooks, [ct_groups_summary_hook, ct_tty_hook, ct_mongoose_hook, ct_progress_hook,
+{ct_hooks, [ct_groups_summary_hook, ct_tty_hook, ct_mongoose_hook,
+            ct_progress_hook,
+            {ct_mongoose_log_hook, [{host, mim2}, {print_init_and_done_for_testcases, false}]},
+            {ct_mongoose_log_hook, [{host, mim3}, {print_init_and_done_for_testcases, false}]},
             ct_markdown_errors_hook, ct_mongoose_log_hook]}.
 
 %% since test-runner.sh can be executed with the --one-node option,

big_tests/src/ct_mongoose_log_hook.erl

@@ -33,7 +33,8 @@
 -export([pre_init_per_testcase/3]).
 -export([post_end_per_testcase/4]).
 
--record(state, { node_name, reader, writer,
+-record(state, { print_init_and_done_for_testcases,
+                 node_name, reader, writer,
                  current_line_num, out_file, url_file, group, suite,
                  log_flags = [] }).
 -include_lib("exml/include/exml.hrl").
@@ -48,30 +49,42 @@ id(Opts) ->
 init(_Id, Opts) ->
     Node = connect_mim_node(Opts),
     LogFlags = proplists:get_value(log, Opts, [suite]),
-    {ok, #state{ node_name=Node, log_flags=LogFlags }}.
+    PrintInitDone = proplists:get_value(print_init_and_done_for_testcases, Opts),
+    {ok, #state{ node_name=Node, log_flags=LogFlags,
+                 print_init_and_done_for_testcases = PrintInitDone }}.
 
 %% @doc Called before init_per_suite is called.
-pre_init_per_suite(Suite,Config,State) ->
+pre_init_per_suite(_Suite, Config, State = #state{node_name = undefined}) ->
+    {Config, State};
+pre_init_per_suite(Suite, Config, State) ->
     maybe_print_log_on_mim_node(suite, starting, Suite, State),
     {Config, State#state{group=no_group, suite=Suite}}.
 
 %% @doc Called before end_per_suite.
-post_end_per_suite(Suite,_Config,Return,State) ->
+post_end_per_suite(_Suite, Config, Return, State = #state{node_name = undefined}) ->
+    {Config, State};
+post_end_per_suite(Suite, _Config, Return, State) ->
     maybe_print_log_on_mim_node(suite, finishing, Suite, State),
     {Return, State#state{suite=no_suite}}.
 
 %% @doc Called before each init_per_group.
-pre_init_per_group(Group,Config,State) ->
+pre_init_per_group(_Group, Config, State = #state{node_name = undefined}) ->
+    {Config, State};
+pre_init_per_group(Group, Config, State) ->
     maybe_print_log_on_mim_node(group, starting, Group, State),
     {Config, State#state{group=Group}}.
 
 %% @doc Called after each end_per_group.
-post_end_per_group(Group,_Config,Return,State) ->
+post_end_per_group(_Group, _Config, Return, State = #state{node_name = undefined}) ->
+    {Return, State};
+post_end_per_group(Group, _Config, Return, State) ->
     maybe_print_log_on_mim_node(group, finishing, Group, State),
     {Return, State#state{group=no_group}}.
 
 %% @doc Called before each test case.
-pre_init_per_testcase(TC,Config,State=#state{}) ->
+pre_init_per_testcase(_TC, Config, State = #state{node_name = undefined}) ->
+    {Config, State};
+pre_init_per_testcase(TC, Config, State=#state{}) ->
     maybe_print_log_on_mim_node(testcase, starting, TC, State),
     Dog = test_server:timetrap(test_server:seconds(10)),
     State3 = ensure_initialized(Config, State),
@@ -80,14 +93,18 @@ pre_init_per_testcase(TC,Config,State=#state{}) ->
     {Config, State4}.
 
 %% @doc Called after each test case.
-post_end_per_testcase(TC,_Config,Return,State) ->
+post_end_per_testcase(_TC, _Config, Return, State = #state{node_name = undefined}) ->
+    {Return, State};
+post_end_per_testcase(TC, _Config, Return, State) ->
     Dog = test_server:timetrap(test_server:seconds(10)),
     State2 = post_insert_line_numbers_into_report(State, TC),
     test_server:timetrap_cancel(Dog),
     maybe_print_log_on_mim_node(testcase, finishing, TC, State),
     {Return, State2 }.
 
 %% @doc Called when the scope of the CTH is done
+terminate(State = #state{node_name = undefined}) ->
+    State;
 terminate(State) ->
     insert_line_numbers_into_report(State).
 
@@ -183,7 +200,7 @@ pre_insert_line_numbers_into_report(State=#state{node_name=Node, reader=Reader,
     Message = io_lib:format(
         "<font color=gray>INIT suite=~p group=~p testcase=~p</font>~n",
         [Suite, Group, TC]),
-    file:write(Writer, Message),
+    maybe_file_write(State, Writer, Message),
     State#state{current_line_num=CurrentLineNum2}.
 
 post_insert_line_numbers_into_report(State=#state{writer=undefined}, _TC) ->
@@ -192,12 +209,17 @@ post_insert_line_numbers_into_report(State=#state{node_name=Node, reader=Reader,
                                              current_line_num=CurrentLineNum, url_file=UrlFile,
                                              group=Group, suite=Suite}, TC) ->
     CurrentLineNum2 = read_and_write_lines(Node, Reader, Writer, CurrentLineNum),
-    add_log_link_to_line(UrlFile, CurrentLineNum2, Node, " when finished"),
+    case CurrentLineNum of
+        CurrentLineNum2 ->
+            skip; %% Reduce noise in logs because nothing was logged
+        _ ->
+            add_log_link_to_line(UrlFile, CurrentLineNum2, Node, " when finished")
+    end,
     %% Write a message after the main part
     Message = io_lib:format(
         "<font color=gray>DONE suite=~p group=~p testcase=~p</font>~n",
         [Suite, Group, TC]),
-    file:write(Writer, Message),
+    maybe_file_write(State, Writer, Message),
     State#state{current_line_num=CurrentLineNum2}.
 
 insert_line_numbers_into_report(State=#state{node_name=Node, reader=Reader, writer=Writer,
@@ -288,9 +310,13 @@ connect_mim_node(HookOpts) ->
     erlang:set_cookie(Node, Cookie),
     %% this log message lands at misc_io.log.html file
     ct:pal("connecting to the '~p' node (cookie: '~p')", [Node, Cookie]),
-    %% crash if cannot connect to the node
-    true = net_kernel:connect_node(Node),
-    Node.
+    case net_kernel:connect_node(Node) of
+        true ->
+            Node;
+        _ ->
+            %% Could happen if we test not with all nodes enabled.
+            undefined
+    end.
 
 maybe_print_log_on_mim_node(Type, Event, Name, #state{log_flags = LogFlags, node_name = Node}) ->
     ValidEvents = [starting, finishing],
@@ -307,3 +333,8 @@ maybe_print_log_on_mim_node(Type, Event, Name, #state{log_flags = LogFlags, node
         _ ->
             ok
     end.
+
+maybe_file_write(State = #state{print_init_and_done_for_testcases = true}, Writer, Message) ->
+    file:write(Writer, Message);
+maybe_file_write(_State, _Writer, _Message) ->
+    ok.

big_tests/tests/mod_global_distrib_SUITE.erl

@@ -1441,11 +1441,17 @@ print_sessions_debug_info(NodeName) ->
 %% -----------------------------------------------------------------------
 %% Custom log levels for GD modules during the tests
 
+%% Set it to true, if you need to debug GD on CI
+detailed_logging() ->
+    false.
+
 enable_logging() ->
-    mim_loglevel:enable_logging(test_hosts(), custom_loglevels()).
+    detailed_logging() andalso
+        mim_loglevel:enable_logging(test_hosts(), custom_loglevels()).
 
 disable_logging() ->
-    mim_loglevel:disable_logging(test_hosts(), custom_loglevels()).
+    detailed_logging() andalso
+        mim_loglevel:disable_logging(test_hosts(), custom_loglevels()).
 
 custom_loglevels() ->
     %% for "s2s connection to muc.localhost not found" debugging

rel/files/app.config

@@ -42,7 +42,7 @@
            file => "{{mongooseim_log_dir}}/mongooseim.log",
            type => wrap,
            max_no_files => 5,
-           max_no_bytes => 2097152,
+           max_no_bytes => 10485760, %% 10 Megabytes
            sync_mode_qlen => 2000, % If sync_mode_qlen is set to the same value as drop_mode_qlen,
            drop_mode_qlen => 2000, % synchronous mode is disabled. That is, the handler always runs
            flush_qlen => 5000,     % in asynchronous mode, unless dropping or flushing is invoked.

src/global_distrib/mod_global_distrib_connection.erl

@@ -108,8 +108,14 @@ code_change(_OldVsn, State, _Extra) ->
     {ok, State}.
 
 terminate(Reason, State) ->
-    ?LOG_ERROR(#{what => gd_outgoing_socket_error,
-                 reason => Reason, peer => State#state.peer, conn_id => State#state.conn_id}),
+    case Reason of
+        shutdown ->
+            ?LOG_INFO(#{what => gd_outgoing_socket_error,
+                        reason => Reason, peer => State#state.peer, conn_id => State#state.conn_id});
+        _ ->
+            ?LOG_ERROR(#{what => gd_outgoing_socket_error,
+                         reason => Reason, peer => State#state.peer, conn_id => State#state.conn_id})
+    end,
     mongoose_instrument:execute(?GLOBAL_DISTRIB_OUTGOING_CLOSED, #{}, #{count => 1, host => State#state.host}),
     catch mod_global_distrib_transport:close(State#state.socket),
     ignore.

src/global_distrib/mod_global_distrib_receiver.erl

@@ -135,9 +135,16 @@ code_change(_Version, State, _Extra) ->
     {ok, State}.
 
 terminate(Reason, State) ->
-    ?LOG_WARNING(#{what => gd_incoming_socket_closed,
-                   peer => State#state.peer, server => State#state.host,
-                   reason => Reason, conn_id => State#state.conn_id}),
+    case Reason of
+        normal ->
+            ?LOG_INFO(#{what => gd_incoming_socket_closed,
+                        peer => State#state.peer, server => State#state.host,
+                        reason => Reason, conn_id => State#state.conn_id});
+        _ ->
+            ?LOG_WARNING(#{what => gd_incoming_socket_closed,
+                           peer => State#state.peer, server => State#state.host,
+                           reason => Reason, conn_id => State#state.conn_id})
+    end,
     mongoose_instrument:execute(?GLOBAL_DISTRIB_INCOMING_CLOSED, #{},
                                 #{count => 1, host => State#state.host}),
     catch mod_global_distrib_transport:close(State#state.socket),