Added test suite for log rotation.

Initialise log rotation in its own phase.

2 files changed, 141 insertions, 55 deletions

diff --git a/src/rabbit.erl b/src/rabbit.erl
index edcea1f712..1af550a341 100644
--- a/src/rabbit.erl
+++ b/src/rabbit.erl
@@ -31,6 +31,8 @@
 
 -export([start/2, stop/1]).
 
+-export([error_log_location/1, sasl_log_location/0]).
+
 -import(application).
 -import(mnesia).
 -import(lists).
@@ -46,6 +48,8 @@
 
 -ifdef(use_specs).
 
+-type(log_location() :: 'tty' | 'undefined' | string()).
+
 -spec(start/0 :: () -> 'ok').
 -spec(stop/0 :: () -> 'ok').
 -spec(stop_and_halt/0 :: () -> 'ok').
@@ -54,6 +58,8 @@
              [{running_applications, [{atom(), string(), string()}]} |
               {nodes, [node()]} |
               {running_nodes, [node()]}]).
+-spec(error_log_location/1 :: ('default' | 'wrapper') -> log_location()).
+-spec(sasl_log_location/0 :: () -> log_location()).
 
 -endif.
 
@@ -61,7 +67,6 @@
 
 start() ->
     try
-        ok = ensure_working_log_config(),
         ok = rabbit_mnesia:ensure_mnesia_dir(),
         ok = start_applications(?APPS)
     after
@@ -143,7 +148,9 @@ start(normal, []) ->
               apply(M, F, A),
               io:format("done~n")
       end,
-      [{"database",
+      [{"log configuration",
+        fun () -> ok = maybe_swap_log_handlers() end},
+       {"database",
         fun () -> ok = rabbit_mnesia:init() end},
        {"core processes",
         fun () ->
@@ -172,15 +179,7 @@ start(normal, []) ->
                 {ok, DefaultVHost} = application:get_env(default_vhost),
                 ok = error_logger:add_report_handler(
                        rabbit_error_logger, [DefaultVHost]),
-                ok = start_builtin_amq_applications(),
-                %% Swap default handlers with rabbit wrappers
-                %% to simplify the swapping of log handlers later
-                ok = rotate_logs(error_log_location(default), "",
-                                 error_logger_file_h,
-                                 rabbit_error_logger_file_h),
-                ok = rotate_logs(sasl_log_location(), "",
-                                 sasl_report_file_h,
-                                 rabbit_sasl_report_file_h)
+                ok = start_builtin_amq_applications()
         end},
        {"TCP listeners",
         fun () ->
@@ -204,6 +203,29 @@ stop(_State) ->
 
 %---------------------------------------------------------------------------
 
+error_log_location(Type) ->
+    case case Type of
+             default -> error_logger:logfile(filename);
+             wrapper -> gen_event:call(error_logger,
+                                       rabbit_error_logger_file_h,
+                                       filename)
+         end of 
+        {error, no_log_file} -> tty;
+        {error, _}           -> undefined;
+        File                 -> File
+    end.
+
+sasl_log_location() ->
+    case application:get_env(sasl, sasl_error_logger) of
+        {ok, {file, File}} -> File;
+        {ok, false}        -> undefined;
+        {ok, tty}          -> tty;
+        {ok, Bad}          -> throw({error, {cannot_log_to_file, Bad}});
+        _                  -> undefined
+    end.
+
+%---------------------------------------------------------------------------
+
 print_banner() ->
     {ok, Product} = application:get_key(id),
     {ok, Version} = application:get_key(vsn),
@@ -220,6 +242,25 @@ start_child(Mod) ->
                                      transient, 100, worker, [Mod]}),
     ok.
 
+maybe_swap_log_handlers() ->
+    Handlers = gen_event:which_handlers(error_logger),
+    ok = maybe_swap_log_handlers(error_logger_file_h,
+                                 rabbit_error_logger_file_h,
+                                 error_log_location(default),
+                                 Handlers),
+    ok = maybe_swap_log_handlers(sasl_report_file_h,
+                                 rabbit_sasl_report_file_h,
+                                 sasl_log_location(),
+                                 Handlers),
+    ok.
+
+maybe_swap_log_handlers(Old, New, LogLocation, Handlers) ->
+    case lists:member(Old, Handlers)
+	   and not(lists:member(New, Handlers)) of
+        true -> rotate_logs(LogLocation, "", Old, New);
+        false -> ok
+    end.
+   
 maybe_insert_default_data() ->
     case rabbit_mnesia:is_db_empty() of
         true -> insert_default_data();
@@ -241,50 +282,6 @@ start_builtin_amq_applications() ->
     %%restart
     ok.
 
-ensure_working_log_config() ->
-    case error_logger:logfile(filename) of
-        {error, no_log_file} ->
-            %% either no log file was configured or opening it failed.
-            case application:get_env(kernel, error_logger) of
-                {ok, {file, Filename}} ->
-                    case filelib:ensure_dir(Filename) of
-                        ok -> ok;
-                        {error, Reason1} ->
-                            throw({error, {cannot_log_to_file,
-                                           Filename, Reason1}})
-                    end,
-                    case error_logger:logfile({open, Filename}) of
-                        ok -> ok;
-                        {error, Reason2} ->
-                            throw({error, {cannot_log_to_file,
-                                           Filename, Reason2}})
-                    end;
-                _ -> ok
-            end;
-        _Filename -> ok
-    end.
-
-error_log_location(Type) ->
-    case case Type of
-             default -> error_logger:logfile(filename);
-             wrapper -> gen_event:call(error_logger,
-                                       rabbit_error_logger_file_h,
-                                       filename)
-         end of 
-        {error, no_log_file} -> tty;
-        {error, _}           -> undefined;
-        File                 -> File
-    end.
-
-sasl_log_location() ->
-    case application:get_env(sasl, sasl_error_logger) of
-        {ok, {file, File}} -> File;
-        {ok, false}        -> undefined;
-        {ok, tty}          -> tty;
-        {ok, Bad}          -> throw({error, {cannot_log_to_file, Bad}});
-        _                  -> undefined
-    end.
-
 rotate_logs(File, Suffix, Handler) ->
     rotate_logs(File, Suffix, Handler, Handler).
 
diff --git a/src/rabbit_tests.erl b/src/rabbit_tests.erl
index 6f43b08a38..f8d68f17c8 100644
--- a/src/rabbit_tests.erl
+++ b/src/rabbit_tests.erl
@@ -1,3 +1,4 @@
+
 %%   The contents of this file are subject to the Mozilla Public License
 %%   Version 1.1 (the "License"); you may not use this file except in
 %%   compliance with the License. You may obtain a copy of the License at
@@ -29,6 +30,9 @@
 
 -import(lists).
 
+-include("rabbit.hrl").
+-include_lib("kernel/include/file.hrl").
+
 test_content_prop_roundtrip(Datum, Binary) ->
     Types =  [element(1, E) || E <- Datum],
     Values = [element(2, E) || E <- Datum],
@@ -38,6 +42,7 @@ test_content_prop_roundtrip(Datum, Binary) ->
 all_tests() ->
     passed = test_parsing(),
     passed = test_topic_matching(),
+    passed = test_log_management(),
     passed = test_app_management(),
     passed = test_cluster_management(),
     passed = test_user_management(),
@@ -136,6 +141,57 @@ test_app_management() ->
     ok = control_action(status, []),
     passed.
 
+test_log_management() ->
+    MainLog = rabbit:error_log_location(wrapper),
+    SaslLog = rabbit:sasl_log_location(),
+    Suffix = ".1",
+
+    %% prepare basic logs
+    file:delete([MainLog, Suffix]),
+    file:delete([SaslLog, Suffix]),
+    ok = test_logs_working(MainLog, SaslLog),
+
+    %% simple logs reopening
+    ok = control_action(rotate_logs, []),
+    true = empty_file(MainLog),
+    true = empty_file(SaslLog),
+    ok = test_logs_working(MainLog, SaslLog),
+
+    %% simple log rotation
+    ok = control_action(rotate_logs, [Suffix]),
+    true = non_empty_file([MainLog, Suffix]),
+    true = non_empty_file([SaslLog, Suffix]),
+    true = empty_file(MainLog),
+    true = empty_file(MainLog),
+    ok = test_logs_working(MainLog, SaslLog),
+
+    %% reopening logs with log rotation performed first
+    clean_logs([MainLog, SaslLog], Suffix),
+    ok = control_action(rotate_logs, []),
+    ok = file:rename(MainLog, [MainLog, Suffix]),
+    ok = file:rename(SaslLog, [SaslLog, Suffix]),
+    ok = test_logs_working([MainLog, Suffix], [SaslLog, Suffix]),
+    ok = control_action(rotate_logs, []),
+    ok = test_logs_working(MainLog, SaslLog),
+
+    %% logs with suffix are not writable
+    non_writable_file([MainLog, Suffix]),
+    non_writable_file([SaslLog, Suffix]),
+    ok = control_action(rotate_logs, [Suffix]),
+    ok = test_logs_working(MainLog, SaslLog),
+
+    %% original log files are not writable
+    non_writable_file(MainLog),
+    non_writable_file(SaslLog),
+    {error, _} = control_action(rotate_logs, []),
+    %% cleanup, add handlers removed by last command
+    clean_logs([MainLog, SaslLog], Suffix),
+    ok = error_logger:add_report_handler(rabbit_error_logger_file_h,
+					 MainLog),
+    ok = error_logger:add_report_handler(rabbit_sasl_report_file_h,
+					 SaslLog),
+    passed.
+
 test_cluster_management() ->
 
     %% 'cluster' and 'reset' should only work if the app is stopped
@@ -329,6 +385,8 @@ test_user_management() ->
 
     passed.
 
+%---------------------------------------------------------------------
+
 control_action(Command, Args) -> control_action(Command, node(), Args).
 
 control_action(Command, Node, Args) ->
@@ -340,3 +398,34 @@ control_action(Command, Node, Args) ->
             io:format("failed.~n"),
             Other
     end.
+
+empty_file(File) ->
+    case file:read_file_info(File) of
+        {ok, FInfo} -> FInfo#file_info.size == 0;
+        Error       -> Error
+    end.
+
+non_empty_file(File) ->
+    case empty_file(File) of
+        {error, Reason} -> {error, Reason};
+        Result          -> not(Result)
+    end.
+
+test_logs_working(MainLogFile, SaslLogFile) ->
+    ok = rabbit_log:error("foo bar"),
+    ok = error_logger:error_report(crash_report, [foo, bar]),
+    %% give the error loggers some time to catch up
+    timer:sleep(50),
+    true = non_empty_file(MainLogFile),
+    true = non_empty_file(SaslLogFile),
+    ok.
+
+clean_logs(Files, Suffix) ->
+    lists:map(fun(File) ->
+                      file:delete(File),
+                      file:delete([File, Suffix])
+              end, Files),
+    ok.
+
+non_writable_file(File) ->
+    ok = file:write_file_info(File, #file_info{mode=0}).