Skip to content

Commit 0dccf40

Browse files
gerhardlukebakken
authored andcommitted
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,'[email protected]'},...],...} ** When handler state == [] ** Reason == {error,{no_exists,['tracked_connection_on_node_rabbit@rabbitmq-2.rabbitmq-headless.rabbitmq.svc.cluster.local',{'[email protected]',<<"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 parent d256c78 commit 0dccf40

File tree

1 file changed

+19
-7
lines changed

1 file changed

+19
-7
lines changed

src/rabbit_connection_tracking_handler.erl

Lines changed: 19 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -52,13 +52,25 @@ init([]) ->
5252
handle_event(#event{type = connection_created, props = Details}, State) ->
5353
ThisNode = node(),
5454
case pget(node, Details) of
55-
ThisNode ->
56-
rabbit_connection_tracking:register_connection(
57-
rabbit_connection_tracking:tracked_connection_from_connection_created(Details)
58-
);
59-
_OtherNode ->
60-
%% ignore
61-
ok
55+
ThisNode ->
56+
TConn = rabbit_connection_tracking:tracked_connection_from_connection_created(Details),
57+
ConnId = TConn#tracked_connection.id,
58+
try
59+
rabbit_connection_tracking:register_connection(TConn)
60+
catch
61+
error:{no_exists, _} ->
62+
Msg = "Could not register connection ~p for tracking, "
63+
"its table is not ready yet or the connection terminated prematurely",
64+
rabbit_log_connection:warning(Msg, [ConnId]),
65+
ok;
66+
error:Err ->
67+
Msg = "Could not register connection ~p for tracking: ~p",
68+
rabbit_log_connection:warning(Msg, [ConnId, Err]),
69+
ok
70+
end;
71+
_OtherNode ->
72+
%% ignore
73+
ok
6274
end,
6375
{ok, State};
6476
handle_event(#event{type = connection_closed, props = Details}, State) ->

0 commit comments

Comments
 (0)