From 5cc29e823845fcce3f878eddc1c2f1de84f2f7ba Mon Sep 17 00:00:00 2001 From: Daniil Fedotov Date: Thu, 4 Feb 2016 11:49:03 +0000 Subject: [PATCH 01/13] Log auto deleting queues --- src/rabbit_amqqueue_process.erl | 29 +++++++++++++++++++++++++++-- 1 file changed, 27 insertions(+), 2 deletions(-) diff --git a/src/rabbit_amqqueue_process.erl b/src/rabbit_amqqueue_process.erl index 1a86851d0ac2..05670774ce82 100644 --- a/src/rabbit_amqqueue_process.erl +++ b/src/rabbit_amqqueue_process.erl @@ -142,6 +142,8 @@ init_it(Recover, From, State = #q{q = #amqqueue{exclusive_owner = Owner}}) -> {_, Terms} = recovery_status(Recover), BQS = bq_init(BQ, Q, Terms), %% Rely on terminate to delete the queue. + log_auto_delete("Exclusive query connection closed", + Owner, State), {stop, {shutdown, missing_owner}, State#q{backing_queue = BQ, backing_queue_state = BQS}} end. @@ -701,7 +703,9 @@ handle_ch_down(DownPid, State = #q{consumers = Consumers, exclusive_consumer = Holder1}, notify_decorators(State2), case should_auto_delete(State2) of - true -> {stop, State2}; + true -> + log_auto_delete("Channel down", DownPid, State), + {stop, State2}; false -> {ok, requeue_and_run(ChAckTags, ensure_expiry_timer(State2))} end @@ -939,6 +943,7 @@ prioritise_call(Msg, _From, _Len, State) -> prioritise_cast(Msg, _Len, State) -> case Msg of delete_immediately -> 8; + {delete_exclusive, _Pid} -> 8; {set_ram_duration_target, _Duration} -> 8; {set_maximum_since_use, _Age} -> 8; {run_backing_queue, _Mod, _Fun} -> 6; @@ -1063,7 +1068,9 @@ handle_call({basic_cancel, ChPid, ConsumerTag, OkMsg}, _From, notify_decorators(State1), case should_auto_delete(State1) of false -> reply(ok, ensure_expiry_timer(State1)); - true -> stop(ok, State1) + true -> + log_auto_delete("basic.cancel request from", ChPid, State), + stop(ok, State1) end end; @@ -1165,6 +1172,10 @@ handle_cast({reject, false, AckTags, ChPid}, State) -> end) end, fun () -> ack(AckTags, ChPid, State) end)); +handle_cast({delete_exclusive, ConnPid}, State) -> + log_auto_delete("Exclusive query connection closed", ConnPid, State), + stop(State); + handle_cast(delete_immediately, State) -> stop(State); @@ -1284,6 +1295,7 @@ handle_info({'DOWN', _MonitorRef, process, DownPid, _Reason}, %% match what people expect (see bug 21824). However we need this %% monitor-and-async- delete in case the connection goes away %% unexpectedly. + log_auto_delete("Exclusive query connection closed", DownPid, State), stop(State); handle_info({'DOWN', _MonitorRef, process, DownPid, _Reason}, State) -> @@ -1347,3 +1359,16 @@ handle_pre_hibernate(State = #q{backing_queue = BQ, {hibernate, stop_rate_timer(State1)}. format_message_queue(Opt, MQ) -> rabbit_misc:format_message_queue(Opt, MQ). + +log_auto_delete(Reason, Owner, State = #q{ q = #amqqueue{ name = Name } }) -> + rabbit_queue:log("Queue deleted automatically: Queue name: ~p Reason: " + ++ Reason ++ " ~p", + [Name, Owner]). + + + + + + + + From d273e9f72b15ed0448461b85fb8fea89fb08b6a1 Mon Sep 17 00:00:00 2001 From: Daniil Fedotov Date: Thu, 4 Feb 2016 18:22:56 +0000 Subject: [PATCH 02/13] Resolve category name to sink name --- src/rabbit_log.erl | 11 ++++++++++- 1 file changed, 10 insertions(+), 1 deletion(-) diff --git a/src/rabbit_log.erl b/src/rabbit_log.erl index 5eedd925fe43..c0955f5f1877 100644 --- a/src/rabbit_log.erl +++ b/src/rabbit_log.erl @@ -74,10 +74,19 @@ log(Category, Level, Fmt) -> log(Category, Level, Fmt, []). log(Category, Level, Fmt, Args) when is_list(Args) -> Sink = case Category of default -> ?LAGER_SINK; - _ -> lager_util:make_internal_sink_name(Category) + _ -> make_internal_sink_name(Category) end, lager:log(Sink, Level, self(), Fmt, Args). +make_internal_sink_name(Category) when Category == channel; + Category == connection; + Category == mirroring; + Category == queue -> + lager_util:make_internal_sink_name(list_to_atom("rabbit_" ++ + atom_to_list(Category))); +make_internal_sink_name(Category) -> + lager_util:make_internal_sink_name(Category). + debug(Format) -> debug(Format, []). debug(Format, Args) -> debug(self(), Format, Args). debug(Metadata, Format, Args) -> From 4f06877b3adee8d1f39f96d5376aeb6f59c0d16e Mon Sep 17 00:00:00 2001 From: Daniil Fedotov Date: Thu, 4 Feb 2016 18:25:51 +0000 Subject: [PATCH 03/13] Log auto delete with debug level --- src/rabbit_amqqueue_process.erl | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/src/rabbit_amqqueue_process.erl b/src/rabbit_amqqueue_process.erl index 05670774ce82..93d69af5d96c 100644 --- a/src/rabbit_amqqueue_process.erl +++ b/src/rabbit_amqqueue_process.erl @@ -1361,9 +1361,9 @@ handle_pre_hibernate(State = #q{backing_queue = BQ, format_message_queue(Opt, MQ) -> rabbit_misc:format_message_queue(Opt, MQ). log_auto_delete(Reason, Owner, State = #q{ q = #amqqueue{ name = Name } }) -> - rabbit_queue:log("Queue deleted automatically: Queue name: ~p Reason: " - ++ Reason ++ " ~p", - [Name, Owner]). + rabbit_queue:debug("Queue deleted automatically: Queue name: ~p Reason: " + ++ Reason ++ " ~p", + [Name, Owner]). From c533ae0cfbb962d81ce3f76eb079abcef9e29c1f Mon Sep 17 00:00:00 2001 From: Daniil Fedotov Date: Thu, 4 Feb 2016 18:48:25 +0000 Subject: [PATCH 04/13] Federation log sink --- src/rabbit_log.erl | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/src/rabbit_log.erl b/src/rabbit_log.erl index c0955f5f1877..a22dcbb6f0e1 100644 --- a/src/rabbit_log.erl +++ b/src/rabbit_log.erl @@ -81,7 +81,8 @@ log(Category, Level, Fmt, Args) when is_list(Args) -> make_internal_sink_name(Category) when Category == channel; Category == connection; Category == mirroring; - Category == queue -> + Category == queue; + Category == federation -> lager_util:make_internal_sink_name(list_to_atom("rabbit_" ++ atom_to_list(Category))); make_internal_sink_name(Category) -> From f608e304e0dbeb11154514eb249848e482e1d52f Mon Sep 17 00:00:00 2001 From: Daniil Fedotov Date: Thu, 4 Feb 2016 18:58:10 +0000 Subject: [PATCH 05/13] error_logger_lager_event sink --- src/rabbit_lager.erl | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/src/rabbit_lager.erl b/src/rabbit_lager.erl index 6ae9c10a5e27..8beee1084633 100644 --- a/src/rabbit_lager.erl +++ b/src/rabbit_lager.erl @@ -210,7 +210,8 @@ configure_lager() -> %% messages to the default sink. To know the list of expected extra %% sinks, we look at the 'lager_extra_sinks' compilation option. Sinks0 = application:get_env(lager, extra_sinks, []), - Sinks1 = configure_extra_sinks(Sinks0, list_expected_sinks()), + Sinks1 = configure_extra_sinks(Sinks0, + [error_logger | list_expected_sinks()]), %% TODO Waiting for basho/lager#303 %% Sinks2 = lists:keystore(error_logger_lager_event, 1, Sinks1, %% {error_logger_lager_event, From c7e8d67416a88b627f97c77932d64ed385581404 Mon Sep 17 00:00:00 2001 From: Daniil Fedotov Date: Thu, 4 Feb 2016 19:01:22 +0000 Subject: [PATCH 06/13] Remove rabbitmq fork of lager dependency --- Makefile | 2 -- 1 file changed, 2 deletions(-) diff --git a/Makefile b/Makefile index d42890acc8c3..026c05edb468 100644 --- a/Makefile +++ b/Makefile @@ -6,8 +6,6 @@ PACKAGES_DIR ?= $(abspath PACKAGES) DEPS = ranch lager $(PLUGINS) -dep_lager = git https://github.com/rabbitmq/lager.git master - define usage_xml_to_erl $(subst __,_,$(patsubst $(DOCS_DIR)/rabbitmq%.1.xml, src/rabbit_%_usage.erl, $(subst -,_,$(1)))) endef From 7a062e5f5cb1c8caf59d06680c1a015a30fdbe6c Mon Sep 17 00:00:00 2001 From: Daniil Fedotov Date: Fri, 5 Feb 2016 16:05:42 +0000 Subject: [PATCH 07/13] Fix wording --- src/rabbit_amqqueue_process.erl | 35 +++++++++++++++++++++++---------- 1 file changed, 25 insertions(+), 10 deletions(-) diff --git a/src/rabbit_amqqueue_process.erl b/src/rabbit_amqqueue_process.erl index 93d69af5d96c..e3f2a9fc1b32 100644 --- a/src/rabbit_amqqueue_process.erl +++ b/src/rabbit_amqqueue_process.erl @@ -142,8 +142,7 @@ init_it(Recover, From, State = #q{q = #amqqueue{exclusive_owner = Owner}}) -> {_, Terms} = recovery_status(Recover), BQS = bq_init(BQ, Q, Terms), %% Rely on terminate to delete the queue. - log_auto_delete("Exclusive query connection closed", - Owner, State), + log_delete_exclusive(Owner, State), {stop, {shutdown, missing_owner}, State#q{backing_queue = BQ, backing_queue_state = BQS}} end. @@ -704,7 +703,12 @@ handle_ch_down(DownPid, State = #q{consumers = Consumers, notify_decorators(State2), case should_auto_delete(State2) of true -> - log_auto_delete("Channel down", DownPid, State), + log_auto_delete( + io_lib:format( + "because it's last consumer channel was closed"++ + " with ~p consumers", + [length(ChCTags)]), + State), {stop, State2}; false -> {ok, requeue_and_run(ChAckTags, ensure_expiry_timer(State2))} @@ -1069,7 +1073,11 @@ handle_call({basic_cancel, ChPid, ConsumerTag, OkMsg}, _From, case should_auto_delete(State1) of false -> reply(ok, ensure_expiry_timer(State1)); true -> - log_auto_delete("basic.cancel request from", ChPid, State), + log_auto_delete( + io_lib:format( + "because its last consumer ~s was cancelled", + [ConsumerTag]), + State), stop(ok, State1) end end; @@ -1173,7 +1181,7 @@ handle_cast({reject, false, AckTags, ChPid}, State) -> fun () -> ack(AckTags, ChPid, State) end)); handle_cast({delete_exclusive, ConnPid}, State) -> - log_auto_delete("Exclusive query connection closed", ConnPid, State), + log_delete_exclusive(ConnPid, State), stop(State); handle_cast(delete_immediately, State) -> @@ -1295,7 +1303,7 @@ handle_info({'DOWN', _MonitorRef, process, DownPid, _Reason}, %% match what people expect (see bug 21824). However we need this %% monitor-and-async- delete in case the connection goes away %% unexpectedly. - log_auto_delete("Exclusive query connection closed", DownPid, State), + log_delete_exclusive(DownPid, State), stop(State); handle_info({'DOWN', _MonitorRef, process, DownPid, _Reason}, State) -> @@ -1360,10 +1368,17 @@ handle_pre_hibernate(State = #q{backing_queue = BQ, format_message_queue(Opt, MQ) -> rabbit_misc:format_message_queue(Opt, MQ). -log_auto_delete(Reason, Owner, State = #q{ q = #amqqueue{ name = Name } }) -> - rabbit_queue:debug("Queue deleted automatically: Queue name: ~p Reason: " - ++ Reason ++ " ~p", - [Name, Owner]). +log_delete_exclusive(ConPid, #q{ q = #amqqueue{ name = Resource } }) -> + #resource{ name = QName, virtual_host = VHost } = Resource, + rabbit_queue:error("Deleting exclusive queue '~s' for vhost '~s' " ++ + " because it's declaring connection ~p was closed", + [QName, VHost, ConPid]). + +log_auto_delete(Reason, #q{ q = #amqqueue{ name = Resource } }) -> + #resource{ name = QName, virtual_host = VHost } = Resource, + rabbit_queue:error("Deleting auto-delete queue '~s' on vhost '~s' " ++ + Reason, + [QName, VHost]). From 9d6e514a9ead6d784a939fe52e798dcd21d5c519 Mon Sep 17 00:00:00 2001 From: Michael Klishin Date: Fri, 5 Feb 2016 19:31:18 +0300 Subject: [PATCH 08/13] Copy --- src/rabbit_amqqueue_process.erl | 7 +++---- 1 file changed, 3 insertions(+), 4 deletions(-) diff --git a/src/rabbit_amqqueue_process.erl b/src/rabbit_amqqueue_process.erl index e3f2a9fc1b32..2f82b72d0377 100644 --- a/src/rabbit_amqqueue_process.erl +++ b/src/rabbit_amqqueue_process.erl @@ -705,8 +705,7 @@ handle_ch_down(DownPid, State = #q{consumers = Consumers, true -> log_auto_delete( io_lib:format( - "because it's last consumer channel was closed"++ - " with ~p consumers", + "because all ~p of its consumers were on a channel that was closed", [length(ChCTags)]), State), {stop, State2}; @@ -1370,8 +1369,8 @@ format_message_queue(Opt, MQ) -> rabbit_misc:format_message_queue(Opt, MQ). log_delete_exclusive(ConPid, #q{ q = #amqqueue{ name = Resource } }) -> #resource{ name = QName, virtual_host = VHost } = Resource, - rabbit_queue:error("Deleting exclusive queue '~s' for vhost '~s' " ++ - " because it's declaring connection ~p was closed", + rabbit_queue:error("Deleting exclusive queue '~s' in vhost '~s' " ++ + " because its declaring connection ~p was closed", [QName, VHost, ConPid]). log_auto_delete(Reason, #q{ q = #amqqueue{ name = Resource } }) -> From 8e4715b91cec879335b70fccd0fd4e5c9ceb25d7 Mon Sep 17 00:00:00 2001 From: Michael Klishin Date: Fri, 5 Feb 2016 19:34:35 +0300 Subject: [PATCH 09/13] Grammar --- src/rabbit_amqqueue_process.erl | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/rabbit_amqqueue_process.erl b/src/rabbit_amqqueue_process.erl index 2f82b72d0377..fc1a5399863c 100644 --- a/src/rabbit_amqqueue_process.erl +++ b/src/rabbit_amqqueue_process.erl @@ -1375,7 +1375,7 @@ log_delete_exclusive(ConPid, #q{ q = #amqqueue{ name = Resource } }) -> log_auto_delete(Reason, #q{ q = #amqqueue{ name = Resource } }) -> #resource{ name = QName, virtual_host = VHost } = Resource, - rabbit_queue:error("Deleting auto-delete queue '~s' on vhost '~s' " ++ + rabbit_queue:error("Deleting auto-delete queue '~s' in vhost '~s' " ++ Reason, [QName, VHost]). From 41c6ec56c5829286551906c9ddd23fa0a166f9fd Mon Sep 17 00:00:00 2001 From: Daniil Fedotov Date: Fri, 5 Feb 2016 16:43:24 +0000 Subject: [PATCH 10/13] Logging queue deletion at debug level --- src/rabbit_amqqueue_process.erl | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/rabbit_amqqueue_process.erl b/src/rabbit_amqqueue_process.erl index fc1a5399863c..d824a1e22d3e 100644 --- a/src/rabbit_amqqueue_process.erl +++ b/src/rabbit_amqqueue_process.erl @@ -1369,13 +1369,13 @@ format_message_queue(Opt, MQ) -> rabbit_misc:format_message_queue(Opt, MQ). log_delete_exclusive(ConPid, #q{ q = #amqqueue{ name = Resource } }) -> #resource{ name = QName, virtual_host = VHost } = Resource, - rabbit_queue:error("Deleting exclusive queue '~s' in vhost '~s' " ++ + rabbit_queue:debug("Deleting exclusive queue '~s' in vhost '~s' " ++ " because its declaring connection ~p was closed", [QName, VHost, ConPid]). log_auto_delete(Reason, #q{ q = #amqqueue{ name = Resource } }) -> #resource{ name = QName, virtual_host = VHost } = Resource, - rabbit_queue:error("Deleting auto-delete queue '~s' in vhost '~s' " ++ + rabbit_queue:debug("Deleting auto-delete queue '~s' in vhost '~s' " ++ Reason, [QName, VHost]). From cc80a0ce8dab2b8e96c2d0ede17213f0dfdecb7f Mon Sep 17 00:00:00 2001 From: Michael Klishin Date: Fri, 5 Feb 2016 20:28:10 +0300 Subject: [PATCH 11/13] More copy edits --- src/rabbit_amqqueue_process.erl | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/src/rabbit_amqqueue_process.erl b/src/rabbit_amqqueue_process.erl index d824a1e22d3e..513d4df7861e 100644 --- a/src/rabbit_amqqueue_process.erl +++ b/src/rabbit_amqqueue_process.erl @@ -705,7 +705,7 @@ handle_ch_down(DownPid, State = #q{consumers = Consumers, true -> log_auto_delete( io_lib:format( - "because all ~p of its consumers were on a channel that was closed", + "because all of its consumers (~p) were on a channel that was closed", [length(ChCTags)]), State), {stop, State2}; @@ -1074,7 +1074,7 @@ handle_call({basic_cancel, ChPid, ConsumerTag, OkMsg}, _From, true -> log_auto_delete( io_lib:format( - "because its last consumer ~s was cancelled", + "because its last consumer with tag '~s' was cancelled", [ConsumerTag]), State), stop(ok, State1) @@ -1375,7 +1375,7 @@ log_delete_exclusive(ConPid, #q{ q = #amqqueue{ name = Resource } }) -> log_auto_delete(Reason, #q{ q = #amqqueue{ name = Resource } }) -> #resource{ name = QName, virtual_host = VHost } = Resource, - rabbit_queue:debug("Deleting auto-delete queue '~s' in vhost '~s' " ++ + rabbit_queue:debug("Deleting auto-delete queue '~s' in vhost '~s' " ++ Reason, [QName, VHost]). From e14d56d6e8377ff88356783f4e2ede4a3ce3da4a Mon Sep 17 00:00:00 2001 From: Daniil Fedotov Date: Fri, 5 Feb 2016 18:07:06 +0000 Subject: [PATCH 12/13] Do not log connection ref --- src/rabbit_amqqueue_process.erl | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/src/rabbit_amqqueue_process.erl b/src/rabbit_amqqueue_process.erl index 513d4df7861e..54fcdfec9ff9 100644 --- a/src/rabbit_amqqueue_process.erl +++ b/src/rabbit_amqqueue_process.erl @@ -1367,11 +1367,11 @@ handle_pre_hibernate(State = #q{backing_queue = BQ, format_message_queue(Opt, MQ) -> rabbit_misc:format_message_queue(Opt, MQ). -log_delete_exclusive(ConPid, #q{ q = #amqqueue{ name = Resource } }) -> +log_delete_exclusive(_ConPid, #q{ q = #amqqueue{ name = Resource } }) -> #resource{ name = QName, virtual_host = VHost } = Resource, rabbit_queue:debug("Deleting exclusive queue '~s' in vhost '~s' " ++ - " because its declaring connection ~p was closed", - [QName, VHost, ConPid]). + " because its declaring connection was closed", + [QName, VHost]). log_auto_delete(Reason, #q{ q = #amqqueue{ name = Resource } }) -> #resource{ name = QName, virtual_host = VHost } = Resource, From e9ee125aecee9cdd61a4b8f48cdd3849a8bb439d Mon Sep 17 00:00:00 2001 From: Daniil Fedotov Date: Fri, 5 Feb 2016 19:28:17 +0000 Subject: [PATCH 13/13] Log connection pid only --- src/rabbit_amqqueue_process.erl | 8 +++++--- 1 file changed, 5 insertions(+), 3 deletions(-) diff --git a/src/rabbit_amqqueue_process.erl b/src/rabbit_amqqueue_process.erl index 54fcdfec9ff9..f79304632e64 100644 --- a/src/rabbit_amqqueue_process.erl +++ b/src/rabbit_amqqueue_process.erl @@ -1367,11 +1367,13 @@ handle_pre_hibernate(State = #q{backing_queue = BQ, format_message_queue(Opt, MQ) -> rabbit_misc:format_message_queue(Opt, MQ). -log_delete_exclusive(_ConPid, #q{ q = #amqqueue{ name = Resource } }) -> +log_delete_exclusive({ConPid, ConRef}, State) -> + log_delete_exclusive(ConPid, State); +log_delete_exclusive(ConPid, #q{ q = #amqqueue{ name = Resource } }) -> #resource{ name = QName, virtual_host = VHost } = Resource, rabbit_queue:debug("Deleting exclusive queue '~s' in vhost '~s' " ++ - " because its declaring connection was closed", - [QName, VHost]). + " because its declaring connection ~p was closed", + [QName, VHost, ConPid]). log_auto_delete(Reason, #q{ q = #amqqueue{ name = Resource } }) -> #resource{ name = QName, virtual_host = VHost } = Resource,