Merge pull request #14445 from rabbitmq/v4.1.x-consistent-logging

v4.1.x consistent logging (with ?LOG_MACROs)

Author: michaelklishin

deps/amqp10_client/src/amqp10_client.hrl

@@ -13,7 +13,7 @@
 
 % -define(debug, true).
 -ifdef(debug).
--define(DBG(F, A), error_logger:info_msg(F, A)).
+-define(DBG(F, A), ?LOG_INFO(F, A)).
 -else.
 -define(DBG(F, A), ok).
 -endif.

deps/amqp10_client/src/amqp10_client_connection.erl

@@ -12,6 +12,7 @@
 -include("amqp10_client.hrl").
 -include_lib("amqp10_common/include/amqp10_framing.hrl").
 -include_lib("amqp10_common/include/amqp10_types.hrl").
+-include_lib("kernel/include/logger.hrl").
 
 %% public API
 -export([open/1,
@@ -247,8 +248,8 @@ hdr_sent(_EvtType, {protocol_header_received, 0, 1, 0, 0}, State) ->
     end;
 hdr_sent(_EvtType, {protocol_header_received, Protocol, Maj, Min,
                                 Rev}, State) ->
-    logger:warning("Unsupported protocol version: ~b ~b.~b.~b",
-                             [Protocol, Maj, Min, Rev]),
+    ?LOG_WARNING("Unsupported protocol version: ~b ~b.~b.~b",
+                 [Protocol, Maj, Min, Rev]),
     {stop, normal, State};
 hdr_sent({call, From}, begin_session,
          #state{pending_session_reqs = PendingSessionReqs} = State) ->
@@ -342,8 +343,8 @@ opened(info, {'DOWN', MRef, process, _, _Info},
     ok = notify_closed(Config, shutdown),
     {stop, normal};
 opened(_EvtType, Frame, State) ->
-    logger:warning("Unexpected connection frame ~tp when in state ~tp ",
-                   [Frame, State]),
+    ?LOG_WARNING("Unexpected connection frame ~tp when in state ~tp ",
+                 [Frame, State]),
     keep_state_and_data.
 
 close_sent(_EvtType, heartbeat, _Data) ->

deps/amqp10_client/src/amqp10_client_frame_reader.erl

@@ -10,6 +10,7 @@
 
 -include("amqp10_client.hrl").
 -include_lib("amqp10_common/include/amqp10_framing.hrl").
+-include_lib("kernel/include/logger.hrl").
 
 -ifdef(TEST).
 -include_lib("eunit/include/eunit.hrl").
@@ -141,33 +142,33 @@ handle_event(info, {gun_ws, WsPid, StreamRef, WsFrame}, StateName,
         {binary, Bin} ->
             handle_socket_input(Bin, StateName, State);
         close ->
-            logger:info("peer closed AMQP over WebSocket connection in state '~s'",
-                        [StateName]),
+            ?LOG_INFO("peer closed AMQP over WebSocket connection in state '~s'",
+                      [StateName]),
             {stop, normal, socket_closed(State)};
         {close, ReasonStatusCode, ReasonUtf8} ->
-            logger:info("peer closed AMQP over WebSocket connection in state '~s', reason: ~b ~ts",
-                        [StateName, ReasonStatusCode, ReasonUtf8]),
+            ?LOG_INFO("peer closed AMQP over WebSocket connection in state '~s', reason: ~b ~ts",
+                      [StateName, ReasonStatusCode, ReasonUtf8]),
             {stop, {shutdown, {ReasonStatusCode, ReasonUtf8}}, socket_closed(State)}
     end;
 handle_event(info, {TcpError, _Sock, Reason}, StateName, State)
   when TcpError == tcp_error orelse TcpError == ssl_error ->
-    logger:warning("AMQP 1.0 connection socket errored, connection state: '~ts', reason: '~tp'",
-                   [StateName, Reason]),
+    ?LOG_WARNING("AMQP 1.0 connection socket errored, connection state: '~ts', reason: '~tp'",
+                 [StateName, Reason]),
     {stop, {error, Reason}, socket_closed(State)};
 handle_event(info, {TcpClosed, _}, StateName, State)
   when TcpClosed == tcp_closed orelse TcpClosed == ssl_closed ->
-    logger:info("AMQP 1.0 connection socket was closed, connection state: '~ts'",
+    ?LOG_INFO("AMQP 1.0 connection socket was closed, connection state: '~ts'",
                 [StateName]),
     {stop, normal, socket_closed(State)};
 handle_event(info, {gun_down, WsPid, _Proto, Reason, _Streams}, StateName,
              #state{socket = {ws, WsPid, _StreamRef}} = State) ->
-    logger:warning("AMQP over WebSocket process ~p lost connection in state: '~s': ~p",
-                   [WsPid, StateName, Reason]),
+    ?LOG_WARNING("AMQP over WebSocket process ~p lost connection in state: '~s': ~p",
+                 [WsPid, StateName, Reason]),
     {stop, Reason, socket_closed(State)};
 handle_event(info, {'DOWN', _Mref, process, WsPid, Reason}, StateName,
              #state{socket = {ws, WsPid, _StreamRef}} = State) ->
-    logger:warning("AMQP over WebSocket process ~p terminated in state: '~s': ~p",
-                   [WsPid, StateName, Reason]),
+    ?LOG_WARNING("AMQP over WebSocket process ~p terminated in state: '~s': ~p",
+                 [WsPid, StateName, Reason]),
     {stop, Reason, socket_closed(State)};
 
 handle_event(info, heartbeat, _StateName, #state{connection = Connection}) ->

deps/amqp10_client/src/amqp10_client_session.erl

@@ -11,6 +11,7 @@
 -include("amqp10_client.hrl").
 -include_lib("amqp10_common/include/amqp10_framing.hrl").
 -include_lib("amqp10_common/include/amqp10_types.hrl").
+-include_lib("kernel/include/logger.hrl").
 
 %% Public API.
 -export(['begin'/1,
@@ -433,7 +434,7 @@ mapped(cast, {Transfer0 = #'v1_0.transfer'{handle = {uint, InHandle}},
                     notify_credit_exhausted(Link3),
                     {keep_state, State};
                 {transfer_limit_exceeded, Link3, State} ->
-                    logger:warning("transfer_limit_exceeded for link ~tp", [Link3]),
+                    ?LOG_WARNING("transfer_limit_exceeded for link ~tp", [Link3]),
                     Link = detach_with_error_cond(Link3,
                                                   State,
                                                   ?V_1_0_LINK_ERROR_TRANSFER_LIMIT_EXCEEDED,
@@ -445,7 +446,7 @@ mapped(cast, {Transfer0 = #'v1_0.transfer'{handle = {uint, InHandle}},
                             io_lib:format(
                               "~s checksum error: expected ~b, actual ~b",
                               [FooterOpt, Expected, Actual])),
-            logger:warning("deteaching link ~tp due to ~s", [Link2, Description]),
+            ?LOG_WARNING("deteaching link ~tp due to ~s", [Link2, Description]),
             Link = detach_with_error_cond(Link2,
                                           State0,
                                           ?V_1_0_AMQP_ERROR_DECODE_ERROR,
@@ -484,8 +485,8 @@ mapped(cast, #'v1_0.disposition'{role = true,
 
     {keep_state, State#state{outgoing_unsettled = Unsettled}};
 mapped(cast, Frame, State) ->
-    logger:warning("Unhandled session frame ~tp in state ~tp",
-                             [Frame, State]),
+    ?LOG_WARNING("Unhandled session frame ~tp in state ~tp",
+                 [Frame, State]),
     {keep_state, State};
 mapped({call, From},
        {transfer, _Transfer, _Sections},
@@ -565,8 +566,8 @@ mapped({call, From}, Msg, State) ->
     {keep_state, State1, {reply, From, Reply}};
 
 mapped(_EvtType, Msg, _State) ->
-    logger:warning("amqp10_session: unhandled msg in mapped state ~W",
-                   [Msg, 10]),
+    ?LOG_WARNING("amqp10_session: unhandled msg in mapped state ~W",
+                 [Msg, 10]),
     keep_state_and_data.
 
 end_sent(_EvtType, #'v1_0.end'{} = End, State) ->
@@ -1364,6 +1365,7 @@ format_status(Status = #{data := Data0}) ->
 
 -ifdef(TEST).
 -include_lib("eunit/include/eunit.hrl").
+-include_lib("kernel/include/logger.hrl").
 
 handle_session_flow_test() ->
     % see spec section: 2.5.6 for logic

deps/amqp_client/include/amqp_client_internal.hrl

@@ -14,11 +14,6 @@
 
 -define(MAX_CHANNEL_NUMBER, 65535).
 
--define(LOG_DEBUG(Format),      error_logger:info_msg(Format)).
--define(LOG_INFO(Format, Args), error_logger:info_msg(Format, Args)).
--define(LOG_WARN(Format, Args), error_logger:warning_msg(Format, Args)).
--define(LOG_ERR(Format, Args),  error_logger:error_msg(Format, Args)).
-
 -define(CLIENT_CAPABILITIES,
     [{<<"publisher_confirms">>,           bool, true},
      {<<"exchange_exchange_bindings">>,   bool, true},

deps/amqp_client/src/amqp_channel.erl

@@ -54,6 +54,7 @@
 -module(amqp_channel).
 
 -include("amqp_client_internal.hrl").
+-include_lib("kernel/include/logger.hrl").
 
 -behaviour(gen_server).
 
@@ -514,35 +515,35 @@ handle_info({bump_credit, Msg}, State) ->
     {noreply, State};
 %% @private
 handle_info(timed_out_flushing_channel, State) ->
-    ?LOG_WARN("Channel (~tp) closing: timed out flushing while "
-              "connection closing", [self()]),
+    ?LOG_WARNING("Channel (~tp) closing: timed out flushing while "
+                 "connection closing", [self()]),
     {stop, timed_out_flushing_channel, State};
 %% @private
 handle_info({'DOWN', _, process, ReturnHandler, shutdown},
             State = #state{return_handler = {ReturnHandler, _Ref}}) ->
     {noreply, State#state{return_handler = none}};
 handle_info({'DOWN', _, process, ReturnHandler, Reason},
             State = #state{return_handler = {ReturnHandler, _Ref}}) ->
-    ?LOG_WARN("Channel (~tp): Unregistering return handler ~tp because it died. "
-              "Reason: ~tp", [self(), ReturnHandler, Reason]),
+    ?LOG_WARNING("Channel (~tp): Unregistering return handler ~tp because it died. "
+                 "Reason: ~tp", [self(), ReturnHandler, Reason]),
     {noreply, State#state{return_handler = none}};
 %% @private
 handle_info({'DOWN', _, process, ConfirmHandler, shutdown},
             State = #state{confirm_handler = {ConfirmHandler, _Ref}}) ->
     {noreply, State#state{confirm_handler = none}};
 handle_info({'DOWN', _, process, ConfirmHandler, Reason},
             State = #state{confirm_handler = {ConfirmHandler, _Ref}}) ->
-    ?LOG_WARN("Channel (~tp): Unregistering confirm handler ~tp because it died. "
-              "Reason: ~tp", [self(), ConfirmHandler, Reason]),
+    ?LOG_WARNING("Channel (~tp): Unregistering confirm handler ~tp because it died. "
+                 "Reason: ~tp", [self(), ConfirmHandler, Reason]),
     {noreply, State#state{confirm_handler = none}};
 %% @private
 handle_info({'DOWN', _, process, FlowHandler, shutdown},
             State = #state{flow_handler = {FlowHandler, _Ref}}) ->
     {noreply, State#state{flow_handler = none}};
 handle_info({'DOWN', _, process, FlowHandler, Reason},
             State = #state{flow_handler = {FlowHandler, _Ref}}) ->
-    ?LOG_WARN("Channel (~tp): Unregistering flow handler ~tp because it died. "
-              "Reason: ~tp", [self(), FlowHandler, Reason]),
+    ?LOG_WARNING("Channel (~tp): Unregistering flow handler ~tp because it died. "
+                 "Reason: ~tp", [self(), FlowHandler, Reason]),
     {noreply, State#state{flow_handler = none}};
 handle_info({'DOWN', _, process, QPid, _Reason}, State) ->
     rabbit_amqqueue_common:notify_sent_queue_down(QPid),
@@ -591,13 +592,13 @@ handle_method_to_server(Method, AmqpMsg, From, Sender, Flow,
             {noreply, rpc_top_half(Method, build_content(AmqpMsg),
                                    From, Sender, Flow, State1)};
         {ok, none, BlockReply} ->
-            ?LOG_WARN("Channel (~tp): discarding method ~tp in cast.~n"
+            ?LOG_WARNING("Channel (~tp): discarding method ~tp in cast.~n"
                       "Reason: ~tp", [self(), Method, BlockReply]),
             {noreply, State};
         {ok, _, BlockReply} ->
             {reply, BlockReply, State};
         {{_, InvalidMethodMessage}, none, _} ->
-            ?LOG_WARN("Channel (~tp): ignoring cast of ~tp method. " ++
+            ?LOG_WARNING("Channel (~tp): ignoring cast of ~tp method. " ++
                       InvalidMethodMessage ++ "", [self(), Method]),
             {noreply, State};
         {{InvalidMethodReply, _}, _, _} ->
@@ -779,9 +780,9 @@ handle_method_from_server1(
         #'basic.return'{} = BasicReturn, AmqpMsg,
         State = #state{return_handler = ReturnHandler}) ->
     _ = case ReturnHandler of
-        none        -> ?LOG_WARN("Channel (~tp): received {~tp, ~tp} but there is "
-                                 "no return handler registered",
-                                 [self(), BasicReturn, AmqpMsg]);
+        none        -> ?LOG_WARNING("Channel (~tp): received {~tp, ~tp} but there is "
+                                    "no return handler registered",
+                                    [self(), BasicReturn, AmqpMsg]);
         {Pid, _Ref} -> Pid ! {BasicReturn, AmqpMsg}
     end,
     {noreply, State};
@@ -794,7 +795,7 @@ handle_method_from_server1(#'basic.ack'{} = BasicAck, none,
     {noreply, update_confirm_set(BasicAck, State)};
 handle_method_from_server1(#'basic.nack'{} = BasicNack, none,
                            #state{confirm_handler = none} = State) ->
-    ?LOG_WARN("Channel (~tp): received ~tp but there is no "
+    ?LOG_WARNING("Channel (~tp): received ~tp but there is no "
               "confirm handler registered", [self(), BasicNack]),
     {noreply, update_confirm_set(BasicNack, State)};
 handle_method_from_server1(#'basic.nack'{} = BasicNack, none,
@@ -834,7 +835,7 @@ handle_connection_closing(CloseType, Reason,
 handle_channel_exit(Reason = #amqp_error{name = ErrorName, explanation = Expl},
                     State = #state{connection = Connection, number = Number}) ->
     %% Sent by rabbit_channel for hard errors in the direct case
-    ?LOG_ERR("connection ~tp, channel ~tp - error:~n~tp",
+    ?LOG_ERROR("connection ~tp, channel ~tp - error:~n~tp",
              [Connection, Number, Reason]),
     {true, Code, _} = ?PROTOCOL:lookup_amqp_exception(ErrorName),
     ReportedReason = {server_initiated_close, Code, Expl},
@@ -930,7 +931,7 @@ server_misbehaved(#amqp_error{} = AmqpError, State = #state{number = Number}) ->
         {0, _} ->
             handle_shutdown({server_misbehaved, AmqpError}, State);
         {_, Close} ->
-            ?LOG_WARN("Channel (~tp) flushing and closing due to soft "
+            ?LOG_WARNING("Channel (~tp) flushing and closing due to soft "
                       "error caused by the server ~tp", [self(), AmqpError]),
             Self = self(),
             spawn(fun () -> call(Self, Close) end),

deps/amqp_client/src/amqp_channels_manager.erl

@@ -9,6 +9,7 @@
 -module(amqp_channels_manager).
 
 -include("amqp_client_internal.hrl").
+-include_lib("kernel/include/logger.hrl").
 
 -behaviour(gen_server).
 

deps/amqp_client/src/amqp_connection.erl

@@ -59,6 +59,7 @@
 -module(amqp_connection).
 
 -include("amqp_client_internal.hrl").
+-include_lib("kernel/include/logger.hrl").
 
 -export([open_channel/1, open_channel/2, open_channel/3, register_blocked_handler/2]).
 -export([start/1, start/2, close/1, close/2, close/3, close/4]).
@@ -427,7 +428,7 @@ maybe_update_call_timeout(BaseTimeout, CallTimeout)
     ok;
 maybe_update_call_timeout(BaseTimeout, CallTimeout) ->
     EffectiveSafeCallTimeout = amqp_util:safe_call_timeout(BaseTimeout),
-    ?LOG_WARN("AMQP 0-9-1 client call timeout was ~tp ms, is updated to a safe effective "
+    ?LOG_WARNING("AMQP 0-9-1 client call timeout was ~tp ms, is updated to a safe effective "
               "value of ~tp ms", [CallTimeout, EffectiveSafeCallTimeout]),
     amqp_util:update_call_timeout(EffectiveSafeCallTimeout),
     ok.

deps/amqp_client/src/amqp_direct_connection.erl

@@ -9,6 +9,7 @@
 -module(amqp_direct_connection).
 
 -include("amqp_client_internal.hrl").
+-include_lib("kernel/include/logger.hrl").
 
 -behaviour(amqp_gen_connection).
 

deps/amqp_client/src/amqp_gen_connection.erl

@@ -9,6 +9,7 @@
 -module(amqp_gen_connection).
 
 -include("amqp_client_internal.hrl").
+-include_lib("kernel/include/logger.hrl").
 
 -behaviour(gen_server).
 
@@ -191,8 +192,8 @@ handle_cast(channels_terminated, State) ->
 handle_cast({hard_error_in_channel, _Pid, Reason}, State) ->
     server_initiated_close(Reason, State);
 handle_cast({channel_internal_error, Pid, Reason}, State) ->
-    ?LOG_WARN("Connection (~tp) closing: internal error in channel (~tp): ~tp",
-              [self(), Pid, Reason]),
+    ?LOG_WARNING("Connection (~tp) closing: internal error in channel (~tp): ~tp",
+                 [self(), Pid, Reason]),
     internal_error(Pid, Reason, State);
 handle_cast({server_misbehaved, AmqpError}, State) ->
     server_misbehaved_close(AmqpError, State);
@@ -205,13 +206,13 @@ handle_cast({register_blocked_handler, HandlerPid}, State) ->
 %% @private
 handle_info({'DOWN', _, process, BlockHandler, Reason},
             State = #state{block_handler = {BlockHandler, _Ref}}) ->
-    ?LOG_WARN("Connection (~tp): Unregistering connection.{blocked,unblocked} handler ~tp because it died. "
-              "Reason: ~tp", [self(), BlockHandler, Reason]),
+    ?LOG_WARNING("Connection (~tp): Unregistering connection.{blocked,unblocked} handler ~tp because it died. "
+                 "Reason: ~tp", [self(), BlockHandler, Reason]),
     {noreply, State#state{block_handler = none}};
 handle_info({'EXIT', BlockHandler, Reason},
             State = #state{block_handler = {BlockHandler, Ref}}) ->
-    ?LOG_WARN("Connection (~tp): Unregistering connection.{blocked,unblocked} handler ~tp because it died. "
-              "Reason: ~tp", [self(), BlockHandler, Reason]),
+    ?LOG_WARNING("Connection (~tp): Unregistering connection.{blocked,unblocked} handler ~tp because it died. "
+                 "Reason: ~tp", [self(), BlockHandler, Reason]),
     erlang:demonitor(Ref, [flush]),
     {noreply, State#state{block_handler = none}};
 %% propagate the exit to the module that will stop with a sensible reason logged
@@ -316,14 +317,14 @@ internal_error(Pid, Reason, State) ->
                       State).
 
 server_initiated_close(Close, State) ->
-    ?LOG_WARN("Connection (~tp) closing: received hard error ~tp "
+    ?LOG_WARNING("Connection (~tp) closing: received hard error ~tp "
               "from server", [self(), Close]),
     set_closing_state(abrupt, #closing{reason = server_initiated_close,
                                        close = Close}, State).
 
 server_misbehaved_close(AmqpError, State) ->
-    ?LOG_WARN("Connection (~tp) closing: server misbehaved: ~tp",
-              [self(), AmqpError]),
+    ?LOG_WARNING("Connection (~tp) closing: server misbehaved: ~tp",
+                 [self(), AmqpError]),
     {0, Close} = rabbit_binary_generator:map_exception(0, AmqpError, ?PROTOCOL),
     set_closing_state(abrupt, #closing{reason = server_misbehaved,
                                        close = Close}, State).