Log new/closed connections only if they are not a healthcheck

The "new connection" message log is deferred to the moment we receive
the first byte or an error occurs.

If the connection is closed without receiving any data, we consider it
is a TCP healthcheck. Therefore the new/closed messages are logged only
if the log level is 'debug'.

2 files changed, 42 insertions, 13 deletions

diff --git a/src/rabbit_misc.erl b/src/rabbit_misc.erl
index 3e2c88ee..e318f3f7 100644
--- a/src/rabbit_misc.erl
+++ b/src/rabbit_misc.erl
@@ -69,7 +69,7 @@
 -export([get_parent/0]).
 -export([store_proc_name/1, store_proc_name/2]).
 -export([moving_average/4]).
--export([now_to_ms/1]).
+-export([now_to_ms/1, ms_to_now/1]).
 
 %% Horrible macro to use in guards
 -define(IS_BENIGN_EXIT(R),
@@ -988,6 +988,12 @@ term_to_json(V) when is_binary(V) orelse is_number(V) orelse V =:= null orelse
 now_to_ms({Mega, Sec, Micro}) ->
     (Mega * 1000000 * 1000000 + Sec * 1000000 + Micro) div 1000.
 
+ms_to_now(Ms) ->
+    Mega = Ms div 1000 div 1000000,
+    Sec = Ms div 1000 - Mega * 1000000,
+    Micro = (Ms - Mega * 1000 * 1000000 - Sec * 1000) * 1000,
+    {Mega, Sec, Micro}.
+
 check_expiry(N) when N < 0                 -> {error, {value_negative, N}};
 check_expiry(_N)                           -> ok.
 
diff --git a/src/rabbit_reader.erl b/src/rabbit_reader.erl
index e4b14bdc..bfb775da 100644
--- a/src/rabbit_reader.erl
+++ b/src/rabbit_reader.erl
@@ -214,7 +214,7 @@ start_connection(Parent, HelperSup, Deb, Sock, SockTransform) ->
                                     rabbit_net:fast_close(Sock),
                                     exit(normal)
            end,
-    log(info, "accepting AMQP connection ~p (~s)~n", [self(), Name]),
+    log(debug, "incoming connection ~p (~s)~n", [self(), Name]),
     {ok, HandshakeTimeout} = application:get_env(rabbit, handshake_timeout),
     ClientSock = socket_op(Sock, SockTransform),
     erlang:send_after(HandshakeTimeout, self(), handshake_timeout),
@@ -259,15 +259,12 @@ start_connection(Parent, HelperSup, Deb, Sock, SockTransform) ->
                                           handshake, 8)]}),
         log(info, "closing AMQP connection ~p (~s)~n", [self(), Name])
     catch
-        connection_closed_with_no_data_received ->
-            log(info, "closing AMQP connection ~p (~s) - "
-                      "no data received~n", [self(), Name]);
-        Ex ->
-            log(case Ex of
-                    connection_closed_abruptly -> warning;
-                    _                          -> error
-                end, "closing AMQP connection ~p (~s):~n~p~n",
-                [self(), Name, Ex])
+        Ex -> log(case Ex of
+                      connection_closed_with_no_data_received -> debug;
+                      connection_closed_abruptly              -> warning;
+                      _                                       -> error
+                  end, "closing AMQP connection ~p (~s):~n~p~n",
+                  [self(), Name, Ex])
     after
         %% We don't call gen_tcp:close/1 here since it waits for
         %% pending output to be sent, which results in unnecessary
@@ -317,8 +314,34 @@ binlist_split(Len, L, [Acc0|Acc]) when Len < 0 ->
 binlist_split(Len, [H|T], Acc) ->
     binlist_split(Len - size(H), T, [H|Acc]).
 
-mainloop(Deb, Buf, BufLen, State = #v1{sock = Sock}) ->
-    case rabbit_net:recv(Sock) of
+mainloop(Deb, Buf, BufLen, State = #v1{sock = Sock,
+                                       connection_state = CS,
+                                       connection = #connection{
+                                         name = ConnName,
+                                         connected_at = ConnectionTime}}) ->
+    Recv = rabbit_net:recv(Sock),
+    case CS of
+        pre_init when Buf =:= [] ->
+            %% We only new incoming connections only when either the
+            %% first byte was received or there was an error (eg. a
+            %% timeout).
+            %%
+            %% The goal is to not log TCP healthchecks (a connection
+            %% with no data received) unless specified otherwise.
+            Now = rabbit_misc:ms_to_now(ConnectionTime),
+            {{Year, Month, Day}, {Hour, Min, Sec}} =
+              calendar:now_to_local_time(Now),
+            log(case Recv of
+                  closed -> debug;
+                  _      -> info
+                end, "new AMQP connection ~p (~s) - "
+                "accepted at ~b-~2..0b-~2..0b::~2..0b:~2..0b:~2..0b~n",
+                [self(), ConnName, Year, Month, Day,
+                 Hour, Min, Sec]);
+        _ ->
+            ok
+    end,
+    case Recv of
         {data, Data} ->
             recvloop(Deb, [Data | Buf], BufLen + size(Data),
                      State#v1{pending_recv = false});