Handle premature termination in conn tracking handler

If a connection disappears before the handler can get the relevant info
from a connection_created event, the handler crashes:

    2019-02-21 16:47:03.086 [info] <0.1283.0> accepting AMQP connection <0.1283.0> (10.44.1.56:34784 -> 10.44.0.54:5672)
    2019-02-21 16:47:03.239 [info] <0.1283.0> Connection <0.1283.0> (10.44.1.56:34784 -> 10.44.0.54:5672) has a client-provided name: perf-test-configuration
    2019-02-21 16:47:03.254 [info] <0.1283.0> connection <0.1283.0> (10.44.1.56:34784 -> 10.44.0.54:5672 - perf-test-configuration): user 'test' authenticated and granted access to vhost '/'
    2019-02-21 16:47:03.256 [error] <0.392.0> ** gen_event handler rabbit_connection_tracking_handler crashed.
    ** Was installed in rabbit_event
    ** Last event was: {event,connection_created,[{user_provided_name,<<"perf-test-configuration">>},{type,network},{pid,<0.1283.0>},{name,<<"10.44.1.56:34784 -> 10.44.0.54:5672">>},{port,5672},{peer_port,34784},{host,{0,0,0,0,0,65535,2604,54}},{peer_host,{0,0,0,0,0,65535,2604,312}},{ssl,false},{peer_cert_subject,''},{peer_cert_issuer,''},{peer_cert_validity,''},{auth_mechanism,<<"PLAIN">>},{ssl_protocol,''},{ssl_key_exchange,''},{ssl_cipher,''},{ssl_hash,''},{protocol,{0,9,1}},{user,<<"test">>},{vhost,<<"/">>},{timeout,60},{frame_max,131072},{channel_max,2047},{client_properties,[{<<"connection_name">>,longstr,<<"perf-test-configuration">>},{<<"product">>,longstr,<<"RabbitMQ">>},{<<"copyright">>,longstr,<<"Copyright (c) 2007-2019 Pivotal Software, Inc.">>},{<<"capabilities">>,table,[{<<"exchange_exchange_bindings">>,bool,true},{<<"connection.blocked">>,bool,true},{<<"authentication_failure_close">>,bool,true},{<<"basic.nack">>,bool,true},{<<"publisher_confirms">>,bool,true},{<<"consumer_cancel_notify">>,bool,true}]},{<<"information">>,longstr,<<"Licensed under the MPL. See http://www.rabbitmq.com/">>},{<<"version">>,longstr,<<"5.6.0">>},{<<"platform">>,longstr,<<"Java">>}]},{connected_at,1550767623053},{node,'rabbit@rabbitmq-2.rabbitmq-headless.rabbitmq.svc.cluster.local'},...],...}
    ** When handler state == []
    ** Reason == {error,{no_exists,['tracked_connection_on_node_rabbit@rabbitmq-2.rabbitmq-headless.rabbitmq.svc.cluster.local',{'rabbit@rabbitmq-2.rabbitmq-headless.rabbitmq.svc.cluster.local',<<"10.44.1.56:34784 -> 10.44.0.54:5672">>}]}}
    2019-02-21 16:47:03.302 [info] <0.1292.0> accepting AMQP connection <0.1292.0> (10.44.1.56:34788 -> 10.44.0.54:5672)
    2019-02-21 16:47:03.333 [info] <0.1292.0> Connection <0.1292.0> (10.44.1.56:34788 -> 10.44.0.54:5672) has a client-provided name: perf-test-consumer-0
    2019-02-21 16:47:03.336 [info] <0.1292.0> connection <0.1292.0> (10.44.1.56:34788 -> 10.44.0.54:5672 - perf-test-consumer-0): user 'test' authenticated and granted access to vhost '/'
    2019-02-21 16:47:03.942 [info] <0.1315.0> accepting AMQP connection <0.1315.0> (10.44.0.56:49878 -> 10.44.0.54:5672)
    2019-02-21 16:47:03.963 [info] <0.1315.0> Connection <0.1315.0> (10.44.0.56:49878 -> 10.44.0.54:5672) has a client-provided name: perf-test-consumer-0
    2019-02-21 16:47:03.972 [info] <0.1315.0> connection <0.1315.0> (10.44.0.56:49878 -> 10.44.0.54:5672 - perf-test-consumer-0): user 'test' authenticated and granted access to vhost '/'
    2019-02-21 16:47:04.038 [info] <0.1337.0> accepting AMQP connection <0.1337.0> (10.44.0.56:49880 -> 10.44.0.54:5672)
    2019-02-21 16:47:04.044 [info] <0.1337.0> Connection <0.1337.0> (10.44.0.56:49880 -> 10.44.0.54:5672) has a client-provided name: perf-test-producer-0
    2019-02-21 16:47:04.048 [info] <0.1337.0> connection <0.1337.0> (10.44.0.56:49880 -> 10.44.0.54:5672 - perf-test-producer-0): user 'test' authenticated and granted access to vhost '/'

cc @mkuratczyk

rabbit_connection_tracking_handler: handle more errors when registering a connection

Due to #1869, a connection can be accepted before connection tracking
tables were initialized/synced from a peer. The handler should log
a warning and not terminate, even if it would be restarted, to reduce
log noise and scare fewer operators for no real reason:
the condition is transient and should not normally last for more than
a few tenths of a second.

Use tracked connection ID in error message

1 files changed, 19 insertions, 7 deletions

diff --git a/src/rabbit_connection_tracking_handler.erl b/src/rabbit_connection_tracking_handler.erl
index 19b6f8ab40..39e7748a75 100644
--- a/src/rabbit_connection_tracking_handler.erl
+++ b/src/rabbit_connection_tracking_handler.erl
@@ -52,13 +52,25 @@ init([]) ->
 handle_event(#event{type = connection_created, props = Details}, State) ->
     ThisNode = node(),
     case pget(node, Details) of
-      ThisNode ->
-          rabbit_connection_tracking:register_connection(
-            rabbit_connection_tracking:tracked_connection_from_connection_created(Details)
-          );
-      _OtherNode ->
-        %% ignore
-        ok
+        ThisNode ->
+            TConn = rabbit_connection_tracking:tracked_connection_from_connection_created(Details),
+            ConnId = TConn#tracked_connection.id,
+            try
+                rabbit_connection_tracking:register_connection(TConn)
+            catch
+                error:{no_exists, _} ->
+                    Msg = "Could not register connection ~p for tracking, "
+                          "its table is not ready yet or the connection terminated prematurely",
+                    rabbit_log_connection:warning(Msg, [ConnId]),
+                    ok;
+                error:Err ->
+                    Msg = "Could not register connection ~p for tracking: ~p",
+                    rabbit_log_connection:warning(Msg, [ConnId, Err]),
+                    ok
+            end;
+        _OtherNode ->
+            %% ignore
+            ok
     end,
     {ok, State};
 handle_event(#event{type = connection_closed, props = Details}, State) ->