Merge bug19200 into bug19193

8 files changed, 299 insertions, 81 deletions

diff --git a/docs/rabbitmqctl.pod b/docs/rabbitmqctl.pod
index 927fd8af40..b34cbca754 100644
--- a/docs/rabbitmqctl.pod
+++ b/docs/rabbitmqctl.pod
@@ -69,10 +69,13 @@ force_reset
 rotate_logs [suffix]
     instruct the RabbitMQ node to rotate the log files. The RabbitMQ
     broker will attempt to append the current contents of the log file
-    to the file with name composed of the original name and the suffix.
-    It will create a new file if such a file does not already exist.
-    When no I<suffix> is specified, the log file is simply reopened;
-    no rotation takes place. 
+    to the file with the name composed of the original name and the
+    suffix. It will create a new file if such a file does not already
+    exist. When no I<suffix> is specified, the empty log file is
+    simply created at the original location; no rotation takes place.
+    When an error occurs while appending the contents of the old log
+    file, the operation behaves in the same way as if no I<suffix> was
+    specified.
     This command might be helpful when you are e.g. writing your own
     logrotate script and you do not want to restart the RabbitMQ node.
     
@@ -129,7 +132,7 @@ default Erlang node:
 
     rabbitmqctl map_user_vhost foo test
     
-Append current logs' content to the files with ".1" suffix and reopen
+Append the current logs' content to the files with ".1" suffix and reopen
 them:
 
     rabbitmqctl rotate_logs .1
diff --git a/include/rabbit.hrl b/include/rabbit.hrl
index cc8fb1b526..180a0dc392 100644
--- a/include/rabbit.hrl
+++ b/include/rabbit.hrl
@@ -71,7 +71,7 @@
 -type(r(Kind) ::
       #resource{virtual_host :: vhost(),
                 kind         :: Kind,
-                name         :: name()}).
+                name         :: resource_name()}).
 -type(queue_name() :: r('queue')).
 -type(exchange_name() :: r('exchange')).
 -type(user() ::
diff --git a/include/rabbit_framing_spec.hrl b/include/rabbit_framing_spec.hrl
index ef9ab58487..e9e650929b 100644
--- a/include/rabbit_framing_spec.hrl
+++ b/include/rabbit_framing_spec.hrl
@@ -46,7 +46,7 @@
 -type(channel_number() :: non_neg_integer()).
 %% TODO: make this more precise
 -type(amqp_error() :: {bool(), non_neg_integer(), binary()}).
--type(name() :: binary()).
+-type(resource_name() :: binary()).
 -type(routing_key() :: binary()).
 -type(username() :: binary()).
 -type(password() :: binary()).
diff --git a/src/rabbit.erl b/src/rabbit.erl
index d4b21c43ac..c6ef1749f2 100644
--- a/src/rabbit.erl
+++ b/src/rabbit.erl
@@ -31,6 +31,8 @@
 
 -export([start/2, stop/1]).
 
+-export([log_location/1]).
+
 -import(application).
 -import(mnesia).
 -import(lists).
@@ -46,14 +48,18 @@
 
 -ifdef(use_specs).
 
+-type(log_location() :: 'tty' | 'undefined' | string()).
+-type(file_suffix() :: binary()).
+
 -spec(start/0 :: () -> 'ok').
 -spec(stop/0 :: () -> 'ok').
 -spec(stop_and_halt/0 :: () -> 'ok').
--spec(rotate_logs/1 :: name() -> 'ok' | {'error', any()}).
+-spec(rotate_logs/1 :: (file_suffix()) -> 'ok' | {'error', any()}).
 -spec(status/0 :: () ->
              [{running_applications, [{atom(), string(), string()}]} |
               {nodes, [node()]} |
               {running_nodes, [node()]}]).
+-spec(log_location/1 :: ('sasl' | 'kernel') -> log_location()).
 
 -endif.
 
@@ -61,7 +67,7 @@
 
 start() ->
     try
-        ok = ensure_working_log_config(),
+        ok = ensure_working_log_handlers(),
         ok = rabbit_mnesia:ensure_mnesia_dir(),
         ok = start_applications(?APPS)
     after
@@ -88,9 +94,12 @@ status() ->
 
 rotate_logs(BinarySuffix) ->
     Suffix = binary_to_list(BinarySuffix),
-    log_rotation_result(
-      rotate_logs(error_log_location(wrapper), Suffix, rabbit_error_logger_file_h),
-      rotate_logs(sasl_log_location(), Suffix, rabbit_sasl_report_file_h)).
+    log_rotation_result(rotate_logs(log_location(kernel),
+                                    Suffix,
+                                    rabbit_error_logger_file_h),
+                        rotate_logs(log_location(sasl),
+                                    Suffix,
+                                    rabbit_sasl_report_file_h)).
 
 %%--------------------------------------------------------------------
 
@@ -169,15 +178,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 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 () ->
@@ -201,6 +202,21 @@ stop(_State) ->
 
 %---------------------------------------------------------------------------
 
+log_location(Type) ->
+    case application:get_env(Type, case Type of 
+                                       kernel -> error_logger;
+                                       sasl   -> sasl_error_logger
+                                   end) of
+        {ok, {file, File}} -> File;
+        {ok, false}        -> undefined;
+        {ok, tty}          -> tty;
+        {ok, silent}       -> undefined;
+        {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),
@@ -209,7 +225,9 @@ print_banner() ->
                ?PROTOCOL_VERSION_MAJOR, ?PROTOCOL_VERSION_MINOR,
                ?COPYRIGHT_MESSAGE, ?INFORMATION_MESSAGE]),
     io:format("Logging to ~p~nSASL logging to ~p~n~n",
-              [error_log_location(default), sasl_log_location()]).
+              [log_location(kernel), log_location(sasl)]).
+
+
 
 start_child(Mod) ->
     {ok,_} = supervisor:start_child(rabbit_sup,
@@ -217,6 +235,43 @@ start_child(Mod) ->
                                      transient, 100, worker, [Mod]}),
     ok.
 
+ensure_working_log_handlers() ->
+    Handlers = gen_event:which_handlers(error_logger),
+    ok = ensure_working_log_handler(error_logger_file_h,
+                                    rabbit_error_logger_file_h,
+                                    error_logger_tty_h,
+                                    log_location(kernel),
+                                    Handlers),
+
+    ok = ensure_working_log_handler(sasl_report_file_h,
+                                    rabbit_sasl_report_file_h,
+                                    sasl_report_tty_h,
+                                    log_location(sasl),
+                                    Handlers),
+    ok.
+
+ensure_working_log_handler(OldFHandler, NewFHandler, TTYHandler,
+                           LogLocation, Handlers) ->
+    case LogLocation of
+        undefined -> ok;
+        tty       -> case lists:member(TTYHandler, Handlers) of
+                         true  -> ok;
+                         false ->
+                             throw({error, {cannot_log_to_tty,
+                                            TTYHandler, not_installed}})
+                     end;
+        _         -> case lists:member(NewFHandler, Handlers) of 
+                         true  -> ok;
+                         false -> case rotate_logs(LogLocation, "",
+                                                   OldFHandler, NewFHandler) of
+                                      ok -> ok;
+                                      {error, Reason} ->
+                                          throw({error, {cannot_log_to_file,
+                                                         LogLocation, Reason}})
+                                  end
+                     end
+    end.
+
 maybe_insert_default_data() ->
     case rabbit_mnesia:is_db_empty() of
         true -> insert_default_data();
@@ -238,47 +293,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;
-        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_error_logger_file_h.erl b/src/rabbit_error_logger_file_h.erl
index 20c6b77800..d67b02ef42 100644
--- a/src/rabbit_error_logger_file_h.erl
+++ b/src/rabbit_error_logger_file_h.erl
@@ -29,22 +29,30 @@
 
 -export([init/1, handle_event/2, handle_call/2, handle_info/2, terminate/2, code_change/3]).
 
-%% rabbit_error_logger_file_h is a wrapper around error_logger_file_h
+%% rabbit_error_logger_file_h is a wrapper around the error_logger_file_h
 %% module because the original's init/1 does not match properly
 %% with the result of closing the old handler when swapping handlers.
 %% The first init/1 additionally allows for simple log rotation
-%% when suffix is not ""
+%% when the suffix is not the empty string.
 
 %% Used only when swapping handlers in log rotation
 init({{File, Suffix}, []}) ->
     case rabbit_misc:append_file(File, Suffix) of
-        ok -> error_logger_file_h:init(File);
-        Error -> Error
-    end;
+        ok  -> ok;
+        {error, Error} ->
+            rabbit_log:error("Failed to append contents of " ++
+                             "log file '~s' to '~s':~n~p~n",
+                             [File, [File, Suffix], Error])
+    end,
+    init(File);
+%% Used only when swapping handlers and the original handler
+%% failed to terminate or was never installed
+init({{File, _}, error}) ->
+    init(File);
 %% Used only when swapping handlers without performing
 %% log rotation 
 init({File, []}) ->
-    error_logger_file_h:init(File);
+    init(File);
 init({_File, _Type} = FileInfo) ->
     error_logger_file_h:init(FileInfo);
 init(File) ->
diff --git a/src/rabbit_misc.erl b/src/rabbit_misc.erl
index d7d1ff1483..3e4ed8f36f 100644
--- a/src/rabbit_misc.erl
+++ b/src/rabbit_misc.erl
@@ -68,7 +68,7 @@
 -spec(get_config/2 :: (atom(), A) -> A).
 -spec(set_config/2 :: (atom(), any()) -> 'ok').
 -spec(dirty_read/1 :: ({atom(), any()}) -> {'ok', any()} | not_found()).
--spec(r/3 :: (vhost(), K, name()) -> r(K) when is_subtype(K, atom())).
+-spec(r/3 :: (vhost(), K, resource_name()) -> r(K) when is_subtype(K, atom())).
 -spec(r/2 :: (vhost(), K) -> #resource{virtual_host :: vhost(),
                                        kind         :: K,
                                        name         :: '_'}
@@ -339,16 +339,19 @@ dirty_dump_log1(LH, {K, Terms, BadBytes}) ->
 
 
 append_file(File, Suffix) ->
-    case catch file:read_file_info(File) of
+    case file:read_file_info(File) of
         {ok, FInfo}     -> append_file(File, FInfo#file_info.size, Suffix);
-        {error, enoent} -> ok;
+        {error, enoent} -> append_file(File, 0, Suffix);
         Error           -> Error
     end.
 
-append_file(_, 0, _) ->
-    ok;
 append_file(_, _, "") ->
     ok;
+append_file(File, 0, Suffix) ->
+    case file:open([File, Suffix], [append]) of
+        {ok, Fd} -> file:close(Fd);
+        Error    -> Error
+    end;
 append_file(File, _, Suffix) ->
     case file:read_file(File) of
         {ok, Data} -> file:write_file([File, Suffix], Data, [append]);
diff --git a/src/rabbit_sasl_report_file_h.erl b/src/rabbit_sasl_report_file_h.erl
index eb5bf09178..3374d63d0b 100644
--- a/src/rabbit_sasl_report_file_h.erl
+++ b/src/rabbit_sasl_report_file_h.erl
@@ -29,23 +29,31 @@
 
 -export([init/1, handle_event/2, handle_call/2, handle_info/2, terminate/2, code_change/3]).
 
-%% rabbit_sasl_report_file_h is a wrapper around sasl_report_file_h
+%% rabbit_sasl_report_file_h is a wrapper around the sasl_report_file_h
 %% module because the original's init/1 does not match properly
 %% with the result of closing the old handler when swapping handlers.
 %% The first init/1 additionally allows for simple log rotation
-%% when suffix is not ""
+%% when the suffix is not the empty string.
 
 %% Used only when swapping handlers and performing
 %% log rotation
 init({{File, Suffix}, []}) ->
     case rabbit_misc:append_file(File, Suffix) of
-        ok -> sasl_report_file_h:init({File, sasl_error_logger_type()});
-        Error -> Error
-    end;
+        ok -> ok;
+        {error, Error} ->
+            rabbit_log:error("Failed to append contents of " ++
+                             "sasl log file '~s' to '~s':~n~p~n",
+                             [File, [File, Suffix], Error])
+    end,
+    init(File);
+%% Used only when swapping handlers and the original handler
+%% failed to terminate or was never installed
+init({{File, _}, error}) ->
+    init(File);
 %% Used only when swapping handlers without
 %% doing any log rotation
 init({File, []}) ->
-    sasl_report_file_h:init({File, sasl_error_logger_type()});
+    init(File);
 init({_File, _Type} = FileInfo) ->
     sasl_report_file_h:init(FileInfo);
 init(File) ->
diff --git a/src/rabbit_tests.erl b/src/rabbit_tests.erl
index 6f43b08a38..fff02d7363 100644
--- a/src/rabbit_tests.erl
+++ b/src/rabbit_tests.erl
@@ -29,6 +29,8 @@
 
 -import(lists).
 
+-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,7 +40,9 @@ 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_log_management_during_startup(),
     passed = test_cluster_management(),
     passed = test_user_management(),
     passed.
@@ -136,6 +140,134 @@ test_app_management() ->
     ok = control_action(status, []),
     passed.
 
+test_log_management() ->
+    MainLog = rabbit:log_location(kernel),
+    SaslLog = rabbit:log_location(sasl),
+    Suffix = ".1",
+
+    %% prepare basic logs
+    file:delete([MainLog, Suffix]),
+    file:delete([SaslLog, Suffix]),
+
+    %% simple logs reopening
+    ok = control_action(rotate_logs, []),
+    [true, true] = empty_files([MainLog, SaslLog]),
+    ok = test_logs_working(MainLog, SaslLog),
+
+    %% simple log rotation
+    ok = control_action(rotate_logs, [Suffix]),
+    [true, true] = non_empty_files([[MainLog, Suffix], [SaslLog, Suffix]]),
+    [true, true] = empty_files([MainLog, SaslLog]),
+    ok = test_logs_working(MainLog, SaslLog),
+
+    %% reopening logs with log rotation performed first
+    ok = 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),
+
+    %% log rotation on empty file
+    ok = clean_logs([MainLog, SaslLog], Suffix),
+    ok = control_action(rotate_logs, []),
+    ok = control_action(rotate_logs, [Suffix]),
+    [true, true] = empty_files([[MainLog, Suffix], [SaslLog, Suffix]]),
+
+    %% original main log file is not writable
+    ok = make_files_non_writable([MainLog]),
+    {error, {cannot_rotate_main_logs, _}} = control_action(rotate_logs, []),
+    ok = clean_logs([MainLog], Suffix),
+    ok = add_log_handlers([{rabbit_error_logger_file_h, MainLog}]),
+
+    %% original sasl log file is not writable
+    ok = make_files_non_writable([SaslLog]),
+    {error, {cannot_rotate_sasl_logs, _}} = control_action(rotate_logs, []),
+    ok = clean_logs([SaslLog], Suffix),
+    ok = add_log_handlers([{rabbit_sasl_report_file_h, SaslLog}]),
+
+    %% logs with suffix are not writable
+    ok = control_action(rotate_logs, [Suffix]),
+    ok = make_files_non_writable([[MainLog, Suffix], [SaslLog, Suffix]]),
+    ok = control_action(rotate_logs, [Suffix]),
+    ok = test_logs_working(MainLog, SaslLog),
+
+    %% original log files are not writable
+    ok = make_files_non_writable([MainLog, SaslLog]),
+    {error, {{cannot_rotate_main_logs, _},
+	     {cannot_rotate_sasl_logs, _}}} = control_action(rotate_logs, []),
+
+    %% logging directed to tty (handlers were removed in last test)
+    ok = clean_logs([MainLog, SaslLog], Suffix),
+    ok = application:set_env(sasl, sasl_error_logger, tty),
+    ok = application:set_env(kernel, error_logger, tty),
+    ok = control_action(rotate_logs, []),
+    [{error, enoent}, {error, enoent}] = empty_files([MainLog, SaslLog]),
+
+    %% rotate logs when logging is turned off
+    ok = application:set_env(sasl, sasl_error_logger, false),
+    ok = application:set_env(kernel, error_logger, silent),
+    ok = control_action(rotate_logs, []),
+    [{error, enoent}, {error, enoent}] = empty_files([MainLog, SaslLog]),
+
+    %% cleanup
+    ok = application:set_env(sasl, sasl_error_logger, {file, SaslLog}),
+    ok = application:set_env(kernel, error_logger, {file, MainLog}),
+    ok = add_log_handlers([{rabbit_error_logger_file_h, MainLog},
+			   {rabbit_sasl_report_file_h, SaslLog}]),
+    passed.
+
+test_log_management_during_startup() ->
+    MainLog = rabbit:log_location(kernel),
+    SaslLog = rabbit:log_location(sasl),
+
+    %% start application with simple tty logging
+    ok = control_action(stop_app, []),
+    ok = application:set_env(kernel, error_logger, tty),
+    ok = application:set_env(sasl, sasl_error_logger, tty),
+    ok = add_log_handlers([{error_logger_tty_h, []},
+                           {sasl_report_tty_h, []}]),
+    ok = control_action(start_app, []),
+
+    %% start application with tty logging and 
+    %% proper handlers not installed
+    ok = control_action(stop_app, []),
+    ok = error_logger:tty(false),
+    ok = delete_log_handlers([sasl_report_tty_h]),
+    ok = case catch control_action(start_app, []) of
+        ok -> exit(got_success_but_expected_failure);
+        {error, {cannot_log_to_tty, _, _}} -> ok
+    end,
+
+    %% fix sasl logging
+    ok = application:set_env(sasl, sasl_error_logger,
+                             {file, SaslLog}),
+
+    %% start application with logging to invalid directory
+    TmpLog = "/tmp/rabbit-tests/test.log",
+    file:delete(TmpLog),
+    ok = application:set_env(kernel, error_logger, {file, TmpLog}),
+
+    ok = delete_log_handlers([rabbit_error_logger_file_h]),
+    ok = add_log_handlers([{error_logger_file_h, MainLog}]),
+    ok = case catch control_action(start_app, []) of
+        ok -> exit(got_success_but_expected_failure);
+        {error, {cannot_log_to_file, _, _}} -> ok
+    end,
+
+    %% start application with standard error_logger_file_h
+    %% handler not installed 
+    ok = application:set_env(kernel, error_logger, {file, MainLog}),
+    ok = control_action(start_app, []),
+    ok = control_action(stop_app, []),
+
+    %% start application with standard sasl handler not installed
+    %% and rabbit main log handler installed correctly
+    ok = delete_log_handlers([rabbit_sasl_report_file_h]),
+    ok = control_action(start_app, []),
+    passed.
+
 test_cluster_management() ->
 
     %% 'cluster' and 'reset' should only work if the app is stopped
@@ -203,7 +335,6 @@ test_cluster_management() ->
     end,
 
     ok = control_action(start_app, []),
-
     passed.
 
 test_cluster_management2(SecondaryNode) ->
@@ -329,6 +460,8 @@ test_user_management() ->
 
     passed.
 
+%---------------------------------------------------------------------
+
 control_action(Command, Args) -> control_action(Command, node(), Args).
 
 control_action(Command, Node, Args) ->
@@ -340,3 +473,52 @@ control_action(Command, Node, Args) ->
             io:format("failed.~n"),
             Other
     end.
+
+empty_files(Files) ->
+    [case file:read_file_info(File) of
+         {ok, FInfo} -> FInfo#file_info.size == 0;
+         Error       -> Error
+     end || File <- Files].
+
+non_empty_files(Files) ->
+    [case EmptyFile of
+         {error, Reason} -> {error, Reason};
+         _               -> not(EmptyFile)
+     end || EmptyFile <- empty_files(Files)].
+
+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, true] = non_empty_files([MainLogFile, SaslLogFile]),
+    ok.
+
+clean_logs(Files, Suffix) ->
+    [begin
+         ok = delete_file(File),
+         ok = delete_file([File, Suffix])
+     end || File <- Files],
+    ok.
+
+delete_file(File) ->
+    case file:delete(File) of
+        ok              -> ok;
+        {error, enoent} -> ok;
+        Error           -> Error
+    end.
+
+make_files_non_writable(Files) ->
+    [ok = file:write_file_info(File, #file_info{mode=0}) ||
+        File <- Files],
+    ok.
+
+add_log_handlers(Handlers) ->
+    [ok = error_logger:add_report_handler(Handler, Args) ||
+        {Handler, Args} <- Handlers],
+    ok.
+
+delete_log_handlers(Handlers) ->
+    [[] = error_logger:delete_report_handler(Handler) ||
+        Handler <- Handlers],
+    ok.