Merging default into bug24455

8 files changed, 34 insertions, 18 deletions

diff --git a/src/rabbit.erl b/src/rabbit.erl
index dbd31a59..47bc4433 100644
--- a/src/rabbit.erl
+++ b/src/rabbit.erl
@@ -232,12 +232,14 @@ start() ->
     end.
 
 stop() ->
+    rabbit_log:info("Stopping Rabbit~n"),
     ok = rabbit_misc:stop_applications(application_load_order()).
 
 stop_and_halt() ->
     try
         stop()
     after
+        rabbit_misc:local_info_msg("Halting Erlang VM~n", []),
         init:stop()
     end,
     ok.
@@ -264,6 +266,7 @@ environment() ->
 
 rotate_logs(BinarySuffix) ->
     Suffix = binary_to_list(BinarySuffix),
+    rabbit_misc:local_info_msg("Rotating logs with suffix '~s'~n", [Suffix]),
     log_rotation_result(rotate_logs(log_location(kernel),
                                     Suffix,
                                     rabbit_error_logger_file_h),
diff --git a/src/rabbit_auth_backend_internal.erl b/src/rabbit_auth_backend_internal.erl
index 156d98dc..086a90b4 100644
--- a/src/rabbit_auth_backend_internal.erl
+++ b/src/rabbit_auth_backend_internal.erl
@@ -146,6 +146,7 @@ permission_index(read)      -> #permission.read.
 %% Manipulation of the user database
 
 add_user(Username, Password) ->
+    rabbit_log:info("Creating user '~s'~n", [Username]),
     R = rabbit_misc:execute_mnesia_transaction(
           fun () ->
                   case mnesia:wread({rabbit_user, Username}) of
@@ -161,10 +162,10 @@ add_user(Username, Password) ->
                           mnesia:abort({user_already_exists, Username})
                   end
           end),
-    rabbit_log:info("Created user ~p~n", [Username]),
     R.
 
 delete_user(Username) ->
+    rabbit_log:info("Deleting user '~s'~n", [Username]),
     R = rabbit_misc:execute_mnesia_transaction(
           rabbit_misc:with_user(
             Username,
@@ -181,13 +182,14 @@ delete_user(Username) ->
                                write)],
                     ok
             end)),
-    rabbit_log:info("Deleted user ~p~n", [Username]),
     R.
 
 change_password(Username, Password) ->
+    rabbit_log:info("Changing password for '~s'~n", [Username]),
     change_password_hash(Username, hash_password(Password)).
 
 clear_password(Username) ->
+    rabbit_log:info("Clearing password for '~s'~n", [Username]),
     change_password_hash(Username, <<"">>).
 
 change_password_hash(Username, PasswordHash) ->
@@ -195,7 +197,6 @@ change_password_hash(Username, PasswordHash) ->
                                       User#internal_user{
                                         password_hash = PasswordHash }
                               end),
-    rabbit_log:info("Changed password for user ~p~n", [Username]),
     R.
 
 hash_password(Cleartext) ->
@@ -217,11 +218,10 @@ salted_md5(Salt, Cleartext) ->
     erlang:md5(Salted).
 
 set_tags(Username, Tags) ->
+    rabbit_log:info("Setting user tags for user '~s' to ~p~n", [Username, Tags]),
     R = update_user(Username, fun(User) ->
                                       User#internal_user{tags = Tags}
                               end),
-    rabbit_log:info("Set user tags for user ~p to ~p~n",
-                    [Username, Tags]),
     R.
 
 update_user(Username, Fun) ->
@@ -251,6 +251,8 @@ validate_regexp(RegexpBin) ->
     end.
 
 set_permissions(Username, VHostPath, ConfigurePerm, WritePerm, ReadPerm) ->
+    rabbit_log:info("Setting permissions for '~s' in '~s' to '~s', '~s', '~s'~n",
+                    [Username, VHostPath, ConfigurePerm, WritePerm, ReadPerm]),
     lists:map(fun validate_regexp/1, [ConfigurePerm, WritePerm, ReadPerm]),
     rabbit_misc:execute_mnesia_transaction(
       rabbit_misc:with_user_and_vhost(
diff --git a/src/rabbit_misc.erl b/src/rabbit_misc.erl
index d47041d6..f2dc97fd 100644
--- a/src/rabbit_misc.erl
+++ b/src/rabbit_misc.erl
@@ -38,7 +38,7 @@
 -export([upmap/2, map_in_order/2]).
 -export([table_filter/3]).
 -export([dirty_read_all/1, dirty_foreach_key/2, dirty_dump_log/1]).
--export([format_stderr/2, with_local_io/1]).
+-export([format_stderr/2, with_local_io/1, local_info_msg/2]).
 -export([start_applications/1, stop_applications/1]).
 -export([unfold/2, ceil/1, queue_fold/3]).
 -export([sort_field_table/1]).
@@ -155,6 +155,7 @@
 -spec(dirty_dump_log/1 :: (file:filename()) -> ok_or_error()).
 -spec(format_stderr/2 :: (string(), [any()]) -> 'ok').
 -spec(with_local_io/1 :: (fun (() -> A)) -> A).
+-spec(local_info_msg/2 :: (string(), [any()]) -> 'ok').
 -spec(start_applications/1 :: ([atom()]) -> 'ok').
 -spec(stop_applications/1 :: ([atom()]) -> 'ok').
 -spec(unfold/2  :: (fun ((A) -> ({'true', B, A} | 'false')), A) -> {[B], A}).
@@ -532,6 +533,12 @@ with_local_io(Fun) ->
         group_leader(GL, self())
     end.
 
+%% Log an info message on the local node using the standard logger.
+%% Use this if rabbit isn't running and the call didn't originate on
+%% the local node (e.g. rabbitmqctl calls).
+local_info_msg(Format, Args) ->
+    with_local_io(fun () -> error_logger:info_msg(Format, Args) end).
+
 manage_applications(Iterate, Do, Undo, SkipError, ErrorTag, Apps) ->
     Iterate(fun (App, Acc) ->
                     case Do(App) of
diff --git a/src/rabbit_mnesia.erl b/src/rabbit_mnesia.erl
index 9348896a..c8c18843 100644
--- a/src/rabbit_mnesia.erl
+++ b/src/rabbit_mnesia.erl
@@ -121,6 +121,10 @@ force_cluster(ClusterNodes) ->
 %% node.  If Force is false, only connections to online nodes are
 %% allowed.
 cluster(ClusterNodes, Force) ->
+    rabbit_misc:local_info_msg("Clustering with ~p~s~n",
+                               [ClusterNodes, if Force -> " forcefully";
+                                                 true  -> ""
+                                              end]),
     ensure_mnesia_not_running(),
     ensure_mnesia_dir(),
 
@@ -718,6 +722,9 @@ wait_for_tables(TableNames) ->
     end.
 
 reset(Force) ->
+    rabbit_misc:local_info_msg("Resetting Rabbit~s~n", [if Force -> " forcefully";
+                                                           true  -> ""
+                                                        end]),
     ensure_mnesia_not_running(),
     case not Force andalso is_clustered() andalso
          is_only_disc_node(node(), false)
@@ -778,19 +785,13 @@ wait_for(Condition) ->
 
 on_node_up(Node) ->
     case is_only_disc_node(Node, true) of
-        true  -> rabbit_misc:with_local_io(
-                   fun () -> rabbit_log:info("cluster contains disc "
-                                             "nodes again~n")
-                   end);
+        true  -> rabbit_log:info("cluster contains disc nodes again~n");
         false -> ok
     end.
 
 on_node_down(Node) ->
     case is_only_disc_node(Node, true) of
-        true  -> rabbit_misc:with_local_io(
-                   fun () -> rabbit_log:info("only running disc node "
-                                             "went down~n")
-                   end);
+        true  -> rabbit_log:info("only running disc node went down~n");
         false -> ok
     end.
 
diff --git a/src/rabbit_networking.erl b/src/rabbit_networking.erl
index 31f476fc..2c0912df 100644
--- a/src/rabbit_networking.erl
+++ b/src/rabbit_networking.erl
@@ -320,6 +320,7 @@ connection_info_all() -> cmap(fun (Q) -> connection_info(Q) end).
 connection_info_all(Items) -> cmap(fun (Q) -> connection_info(Q, Items) end).
 
 close_connection(Pid, Explanation) ->
+    rabbit_log:info("Closing connection ~p because ~p~n", [Pid, Explanation]),
     case lists:member(Pid, connections()) of
         true  -> rabbit_reader:shutdown(Pid, Explanation);
         false -> throw({error, {not_a_connection_pid, Pid}})
diff --git a/src/rabbit_tests.erl b/src/rabbit_tests.erl
index ba67730e..44c13376 100644
--- a/src/rabbit_tests.erl
+++ b/src/rabbit_tests.erl
@@ -805,11 +805,11 @@ test_log_management() ->
     ok = control_action(rotate_logs, []),
     ok = test_logs_working(MainLog, SaslLog),
 
-    %% log rotation on empty file
+    %% log rotation on empty files (the main log will have a ctl action logged)
     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]]),
+    [false, true] = empty_files([[MainLog, Suffix], [SaslLog, Suffix]]),
 
     %% logs with suffix are not writable
     ok = control_action(rotate_logs, [Suffix]),
diff --git a/src/rabbit_trace.erl b/src/rabbit_trace.erl
index f9632324..58079ccf 100644
--- a/src/rabbit_trace.erl
+++ b/src/rabbit_trace.erl
@@ -67,9 +67,11 @@ tap_trace_out({#resource{name = QName}, _QPid, _QMsgId, Redelivered, Msg},
 %%----------------------------------------------------------------------------
 
 start(VHost) ->
+    rabbit_log:info("Enabling tracing for vhost '~s'~n", [VHost]),
     update_config(fun (VHosts) -> [VHost | VHosts -- [VHost]] end).
 
 stop(VHost) ->
+    rabbit_log:info("Disabling tracing for vhost '~s'~n", [VHost]),
     update_config(fun (VHosts) -> VHosts -- [VHost] end).
 
 update_config(Fun) ->
diff --git a/src/rabbit_vhost.erl b/src/rabbit_vhost.erl
index 08d6c99a..38bb76b0 100644
--- a/src/rabbit_vhost.erl
+++ b/src/rabbit_vhost.erl
@@ -44,6 +44,7 @@
 -define(INFO_KEYS, [name, tracing]).
 
 add(VHostPath) ->
+    rabbit_log:info("Adding vhost '~s'~n", [VHostPath]),
     R = rabbit_misc:execute_mnesia_transaction(
           fun () ->
                   case mnesia:wread({rabbit_vhost, VHostPath}) of
@@ -69,7 +70,6 @@ add(VHostPath) ->
                            {<<"amq.rabbitmq.trace">>, topic}]],
                   ok
           end),
-    rabbit_log:info("Added vhost ~p~n", [VHostPath]),
     R.
 
 delete(VHostPath) ->
@@ -78,6 +78,7 @@ delete(VHostPath) ->
     %% process, which in turn results in further mnesia actions and
     %% eventually the termination of that process. Exchange deletion causes
     %% notifications which must be sent outside the TX
+    rabbit_log:info("Deleting vhost '~s'~n", [VHostPath]),
     [{ok,_} = rabbit_amqqueue:delete(Q, false, false) ||
         Q <- rabbit_amqqueue:list(VHostPath)],
     [ok = rabbit_exchange:delete(Name, false) ||
@@ -86,7 +87,6 @@ delete(VHostPath) ->
           with(VHostPath, fun () ->
                                   ok = internal_delete(VHostPath)
                           end)),
-    rabbit_log:info("Deleted vhost ~p~n", [VHostPath]),
     R.
 
 internal_delete(VHostPath) ->