From 10a309d82f97e8917121af34c3bea672303bf47c Mon Sep 17 00:00:00 2001 From: David Ansari Date: Mon, 12 Aug 2024 18:41:25 +0200 Subject: [PATCH] Log AMQP connection name and container-id (#11975) * Log AMQP connection name and container-id Fixes #11958 ## What Log container-id and connection name. Example JSON log: ``` {"time":"2024-08-12 10:49:44.365724+02:00","level":"info","msg":"accepting AMQP connection [::1]:56754 -> [::1]:5672","pid":"<0.1164.0>","domain":"rabbitmq.connection"} {"time":"2024-08-12 10:49:44.381244+02:00","level":"debug","msg":"User 'guest' authenticated successfully by backend rabbit_auth_backend_internal","pid":"<0.1164.0>","domain":"rabbitmq","connection":"[::1]:56754 -> [::1]:5672"} {"time":"2024-08-12 10:49:44.381578+02:00","level":"info","msg":"AMQP 1.0 connection from container 'my container ID': user 'guest' authenticated and granted access to vhost '/'","pid":"<0.1164.0>","domain":"rabbitmq.connection","connection":"[::1]:56754 -> [::1]:5672","container_id":"my container ID"} {"time":"2024-08-12 10:49:44.381654+02:00","level":"debug","msg":"AMQP 1.0 connection.open frame: hostname = localhost, extracted vhost = /, idle-time-out = {uint,\n 30000}","pid":"<0.1164.0>","domain":"rabbitmq","connection":"[::1]:56754 -> [::1]:5672","container_id":"my container ID"} {"time":"2024-08-12 10:49:44.386412+02:00","level":"debug","msg":"AMQP 1.0 created session process <0.1170.0> for channel number 0","pid":"<0.1164.0>","domain":"rabbitmq","connection":"[::1]:56754 -> [::1]:5672","container_id":"my container ID"} {"time":"2024-08-12 10:49:46.387957+02:00","level":"debug","msg":"AMQP 1.0 closed session process <0.1170.0> with channel number 0","pid":"<0.1164.0>","domain":"rabbitmq","connection":"[::1]:56754 -> [::1]:5672","container_id":"my container ID"} {"time":"2024-08-12 10:49:46.388201+02:00","level":"info","msg":"closing AMQP connection ([::1]:56754 -> [::1]:5672)","pid":"<0.1164.0>","domain":"rabbitmq.connection","connection":"[::1]:56754 -> [::1]:5672","container_id":"my container ID"} ``` If JSON logging is not used, this commit still includes the container-ID once at info level: ``` 2024-08-12 10:48:57.451580+02:00 [info] <0.1164.0> accepting AMQP connection [::1]:56715 -> [::1]:5672 2024-08-12 10:48:57.465924+02:00 [debug] <0.1164.0> User 'guest' authenticated successfully by backend rabbit_auth_backend_internal 2024-08-12 10:48:57.466289+02:00 [info] <0.1164.0> AMQP 1.0 connection from container 'my container ID': user 'guest' authenticated and granted access to vhost '/' 2024-08-12 10:48:57.466377+02:00 [debug] <0.1164.0> AMQP 1.0 connection.open frame: hostname = localhost, extracted vhost = /, idle-time-out = {uint, 2024-08-12 10:48:57.466377+02:00 [debug] <0.1164.0> 30000} 2024-08-12 10:48:57.470800+02:00 [debug] <0.1164.0> AMQP 1.0 created session process <0.1170.0> for channel number 0 2024-08-12 10:48:59.472928+02:00 [debug] <0.1164.0> AMQP 1.0 closed session process <0.1170.0> with channel number 0 2024-08-12 10:48:59.473332+02:00 [info] <0.1164.0> closing AMQP connection ([::1]:56715 -> [::1]:5672) ``` ## Why? See #11958 and https://www.rabbitmq.com/docs/connections#client-provided-names To provide a similar feature to AMQP 0.9.1 this commit uses container-id as sent by the client in the open frame. > Examples of containers are brokers and client applications. The advantage is that the `container-id` is mandatory. Hence, in AMQP 1.0, we can enforce the desired behaviour that we document on our website for AMQP 0.9.1: > The name is optional; however, developers are strongly encouraged to provide one as it would significantly simplify certain operational tasks. * Clarify that container refers to AMQP 1.0 Rename container_id to amqp_container and change log message such that it's unambigious that the word "container" refers to AMQP 1.0 containers (to reduce confusion with the meaning of "container" in Docker / Kubernetes). --- deps/rabbit/src/rabbit_amqp_reader.erl | 11 +++++++---- 1 file changed, 7 insertions(+), 4 deletions(-) diff --git a/deps/rabbit/src/rabbit_amqp_reader.erl b/deps/rabbit/src/rabbit_amqp_reader.erl index 8e676225b53a..3ad7dba7ce71 100644 --- a/deps/rabbit/src/rabbit_amqp_reader.erl +++ b/deps/rabbit/src/rabbit_amqp_reader.erl @@ -86,6 +86,7 @@ unpack_from_0_9_1( {Sock,RecvLen, PendingRecv, SupPid, Buf, BufLen, ProxySocket, ConnectionName, Host, PeerHost, Port, PeerPort, ConnectedAt}, Parent, HandshakeTimeout) -> + logger:update_process_metadata(#{connection => ConnectionName}), #v1{parent = Parent, sock = Sock, callback = handshake, @@ -380,7 +381,8 @@ parse_frame_body(Body, _Channel) -> end. handle_connection_frame( - #'v1_0.open'{max_frame_size = ClientMaxFrame, + #'v1_0.open'{container_id = {utf8, ContainerId}, + max_frame_size = ClientMaxFrame, channel_max = ClientChannelMax, idle_time_out = IdleTimeout, hostname = Hostname, @@ -390,7 +392,7 @@ handle_connection_frame( user = User = #user{username = Username}}, helper_sup = HelperSupPid, sock = Sock} = State0) -> - + logger:update_process_metadata(#{amqp_container => ContainerId}), Vhost = vhost(Hostname), ok = check_user_loopback(State0), ok = check_vhost_exists(Vhost, State0), @@ -402,8 +404,9 @@ handle_connection_frame( rabbit_core_metrics:auth_attempt_succeeded(<<>>, Username, amqp10), notify_auth(user_authentication_success, Username, State0), rabbit_log_connection:info( - "AMQP 1.0 connection: user '~ts' authenticated and granted access to vhost '~ts'", - [Username, Vhost]), + "Connection from AMQP 1.0 container '~ts': user '~ts' " + "authenticated and granted access to vhost '~ts'", + [ContainerId, Username, Vhost]), OutgoingMaxFrameSize = case ClientMaxFrame of undefined ->