Exception when rabbitmq_auth_backend_http do a vhost authentication

[tsigcn]

Describe the bug

There is a running http auth backend on nginx which installed in the same host of RabbitMQ.
When client connecting to RabbitMQ, it was disconnected.
Rabbit MQ log shows there is a Ranch listener exit issue. It seems user authentication is successful but the vhost authentication is terminated even "allow" is received.
RabbitMQ log:
2024-07-25 16:40:15.126780+08:00 [debug] <0.1217.0> auth_backend_http: request timeout: 15000, connection timeout: 15000
2024-07-25 16:40:15.130770+08:00 [debug] <0.1217.0> auth_backend_http: response code is 200, body: "allow administrator\n"
2024-07-25 16:40:15.130804+08:00 [debug] <0.1217.0> User 'test' authenticated successfully by backend rabbit_auth_backend_http
2024-07-25 16:40:15.130872+08:00 [debug] <0.1217.0> auth_backend_http: GET http://127.0.0.1/vhost?username=test&vhost=%2F&ip=%3A%3Affff%3A10.1.9.226&tags=administrator%0A&client_id=MQTT_FX_Client
2024-07-25 16:40:15.130895+08:00 [debug] <0.1217.0> auth_backend_http: request timeout: 15000, connection timeout: 15000
2024-07-25 16:40:15.131025+08:00 [debug] <0.1217.0> auth_backend_http: response code is 200, body: "allow\n"
2024-07-25 16:40:15.131050+08:00 [error] <0.1217.0> ** Generic server <0.1217.0> terminating
2024-07-25 16:40:15.131050+08:00 [error] <0.1217.0> ** Last message in was {tcp,#Port<0.164>,
2024-07-25 16:40:15.132354+08:00 [error] <0.869.0> Ranch listener {acceptor,{0,0,0,0,0,0,0,0},16102} had connection process started with rabbit_mqtt_reader:start_link/3 at <0.1217.0> exit with reason: {{case_clause,"allow\n"},[{rabbit_access_control,check_access,5,[{file,"rabbit_access_control.erl"},{line,213}]},{lists,foldl,3,[{file,"lists.erl"},{line,1594}]},{rabbit_mqtt_processor,check_vhost_access,4,[{file,"rabbit_mqtt_processor.erl"},{line,1107}]},{rabbit_mqtt_processor,process_connect,5,[{file,"rabbit_mqtt_processor.erl"},{line,197}]},{rabbit_mqtt_reader,process_received_bytes,2,[{file,"rabbit_mqtt_reader.erl"},{line,341}]},{gen_server,try_handle_info,3,[{file,"gen_server.erl"},{line,1095}]},{gen_server,handle_msg,6,[{file,"gen_server.erl"},{line,1183}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,241}]}]}

RabbitMQ configuration:

auth_backends.1 = http
auth_http.http_method = get
auth_http.user_path = http://127.0.0.1/user
auth_http.vhost_path = http://127.0.0.1/vhost
auth_http.resource_path = http://127.0.0.1/resource
auth_http.topic_path = http://127.0.0.1/topic

Any advice will be appreciated
/

Reproduction steps

1. Restart RabbitMQ service
2. Restart Nginx Service
3. Change auth_backend_http authentication position
   ...

Expected behavior

Help to correct the issue.

Additional context

No response

[tsigcn]

rabbitmqctl status:
Status of node rabbit@hqrabbitmq01l ...
Runtime

OS PID: 387655
OS: Linux
Uptime (seconds): 693
Is under maintenance?: false
RabbitMQ version: 3.13.4
RabbitMQ release series support status: see https://www.rabbitmq.com/release-information
Node name: rabbit@hqrabbitmq01l
Erlang configuration: Erlang/OTP 26 [erts-14.2.5.2] [source] [64-bit] [smp:80:80] [ds:80:80:10] [async-threads:1] [jit:ns]
Crypto library: OpenSSL 1.1.1k FIPS 25 Mar 2021
Erlang processes: 616 used, 1048576 limit
Scheduler run queue: 1
Cluster heartbeat timeout (net_ticktime): 60

Plugins

Enabled plugin file: /etc/rabbitmq/enabled_plugins
Enabled plugins:

• rabbitmq_auth_backend_http
• rabbitmq_mqtt
• rabbitmq_management
• rabbitmq_management_agent
• rabbitmq_web_dispatch
• amqp_client
• cowboy
• cowlib
• oauth2_client
• jose

Data directory

Node data directory: /var/lib/rabbitmq/mnesia/rabbit@hqrabbitmq01l
Raft data directory: /var/lib/rabbitmq/mnesia/rabbit@hqrabbitmq01l/quorum/rabbit@hqrabbitmq01l

Config files

• /etc/rabbitmq/rabbitmq.conf

Log file(s)

• /var/log/rabbitmq/rabbit@hqrabbitmq01l.log

Alarms

(none)

Memory

Total memory used: 0.2733 gb
Calculation strategy: rss
Memory high watermark setting: 0.4 of available memory, computed to: 107.6528 gb

reserved_unallocated: 0.0846 gb (30.94 %)
other_system: 0.0635 gb (23.23 %)
allocated_unused: 0.0576 gb (21.08 %)
code: 0.0398 gb (14.54 %)
other_proc: 0.0193 gb (7.06 %)
metrics: 0.0057 gb (2.1 %)
atom: 0.0016 gb (0.57 %)
msg_index: 0.0012 gb (0.42 %)
binary: 0.0011 gb (0.39 %)
plugins: 0.001 gb (0.38 %)
mgmt_db: 0.0002 gb (0.06 %)
metadata_store: 0.0001 gb (0.05 %)
mnesia: 0.0001 gb (0.03 %)
quorum_ets: 0.0 gb (0.01 %)
metadata_store_ets: 0.0 gb (0.01 %)
connection_other: 0.0 gb (0.0 %)
quorum_queue_procs: 0.0 gb (0.0 %)
quorum_queue_dlx_procs: 0.0 gb (0.0 %)
stream_queue_procs: 0.0 gb (0.0 %)
stream_queue_replica_reader_procs: 0.0 gb (0.0 %)
connection_readers: 0.0 gb (0.0 %)
connection_writers: 0.0 gb (0.0 %)
connection_channels: 0.0 gb (0.0 %)
queue_procs: 0.0 gb (0.0 %)
queue_slave_procs: 0.0 gb (0.0 %)
stream_queue_coordinator_procs: 0.0 gb (0.0 %)
other_ets: -0.0025 gb (-0.9 %)

File Descriptors

Total: 0, limit: 32671
Sockets: 0, limit: 29401

Free Disk Space

Low free disk space watermark: 0.05 gb
Free disk space: 105.9324 gb

Totals

Connection count: 0
Queue count: 0
Virtual host count: 1

Listeners

Interface: [::], port: 15672, protocol: http, purpose: HTTP API
Interface: [::], port: 16102, protocol: mqtt, purpose: MQTT
Interface: [::], port: 16903, protocol: mqtt/ssl, purpose: MQTT over TLS
Interface: [::], port: 25672, protocol: clustering, purpose: inter-node and CLI tool communication
Interface: [::], port: 5672, protocol: amqp, purpose: AMQP 0-9-1 and AMQP 1.0
Interface: [::], port: 5671, protocol: amqp/ssl, purpose: AMQP 0-9-1 and AMQP 1.0 over TLS

[tsigcn]

Rabbitmqctl environment as attachement.
env.txt

[michaelklishin]

@tsigcn Ranch does not "crash". A core authN module expects a different response, see https://github.com/rabbitmq/rabbitmq-server/blob/main/deps/rabbit/src/rabbit_access_control.erl#L213-L224.

Please put together an executable way to reproduce against 3.13.6 (in a public repo on GitHub), we do not guess in this community.

[tsigcn]

I have known what happened, sorry for the mistake.
Nginx add a "\n" automatic, auth_user ignore it but auth_vhost and others does not.
We removed "\n", all the things go well.

Thanks in advance.

[michaelklishin]

Just for completeness' sake, since I have already spent some time trying to reproduce.

Using our standard Spring HTTP authN/authZ backend example with a small modification to make it return allow for all topic permission checks, and the following config file:

log.file.level = debug
log.console.level = debug

# auth_backends.1 = cache
# auth_cache.cached_backend = http

auth_backends.1 = http

auth_http.http_method   = post
auth_http.user_path     = http://localhost:8080/auth/user
auth_http.vhost_path    = http://localhost:8080/auth/vhost
auth_http.resource_path = http://localhost:8080/auth/resource
auth_http.topic_path    = http://localhost:8080/auth/topic

I can successfully publish and consume using Mosquitto CLI tools:

mosquitto_sub -h localhost -t "/mosquitto/t1" -V mqttv5

mosquitto_pub -h localhost -t "/mosquitto/t1" -m "123" -V mqttv5

mosquitto_pub -h localhost -t "/mosquitto/t1" -m "123" -V mqttv5

mosquitto_pub -h localhost -t "/mosquitto/t1" -m "123" -V mqttv5

Here are the logs:

2024-07-25 09:15:59.038873-04:00 [debug] <0.922.0> MQTT accepting TCP connection <0.922.0> ([::1]:50681 -> [::1]:1883)
2024-07-25 09:15:59.039040-04:00 [debug] <0.922.0> Received a CONNECT, client ID: , username: undefined, clean start: true, protocol version: 5, keepalive: 60, property names: ['Receive-Maximum']
2024-07-25 09:15:59.039184-04:00 [debug] <0.922.0> MQTT connection [::1]:50681 -> [::1]:1883 picked vhost using plugin_configuration_or_default_vhost
2024-07-25 09:15:59.039311-04:00 [debug] <0.922.0> auth_backend_http: POST http://localhost:8080/auth/user
2024-07-25 09:15:59.039339-04:00 [debug] <0.922.0> auth_backend_http: request timeout: infinity, connection timeout: infinity
2024-07-25 09:15:59.041319-04:00 [debug] <0.922.0> auth_backend_http: response code is 200, body: "allow administrator management"
2024-07-25 09:15:59.041392-04:00 [debug] <0.922.0> User 'guest' authenticated successfully by backend rabbit_auth_backend_http
2024-07-25 09:15:59.041522-04:00 [debug] <0.922.0> auth_backend_http: POST http://localhost:8080/auth/vhost
2024-07-25 09:15:59.041588-04:00 [debug] <0.922.0> auth_backend_http: request timeout: infinity, connection timeout: infinity
2024-07-25 09:15:59.042952-04:00 [debug] <0.922.0> auth_backend_http: response code is 200, body: "allow"
2024-07-25 09:15:59.043100-04:00 [info] <0.922.0> Accepted MQTT connection [::1]:50681 -> [::1]:1883 for client ID JhdTJCj1sNSbt_gm6uWNOA
2024-07-25 09:15:59.043316-04:00 [debug] <0.922.0> auth_backend_http: POST http://localhost:8080/auth/resource
2024-07-25 09:15:59.043366-04:00 [debug] <0.922.0> auth_backend_http: request timeout: infinity, connection timeout: infinity
2024-07-25 09:15:59.044546-04:00 [debug] <0.922.0> auth_backend_http: response code is 200, body: "allow"
2024-07-25 09:15:59.044692-04:00 [debug] <0.922.0> auth_backend_http: POST http://localhost:8080/auth/topic
2024-07-25 09:15:59.044729-04:00 [debug] <0.922.0> auth_backend_http: request timeout: infinity, connection timeout: infinity
2024-07-25 09:15:59.046089-04:00 [debug] <0.922.0> auth_backend_http: response code is 200, body: "allow"
2024-07-25 09:15:59.046181-04:00 [debug] <0.922.0> Received a DISCONNECT with reason code 0 and properties #{}
2024-07-25 09:15:59.046274-04:00 [info] <0.922.0> closing MQTT connection <0.922.0> ([::1]:50681 -> [::1]:1883)
2024-07-25 09:15:59.680790-04:00 [debug] <0.927.0> MQTT accepting TCP connection <0.927.0> ([::1]:50682 -> [::1]:1883)
2024-07-25 09:15:59.680940-04:00 [debug] <0.927.0> Received a CONNECT, client ID: , username: undefined, clean start: true, protocol version: 5, keepalive: 60, property names: ['Receive-Maximum']
2024-07-25 09:15:59.681088-04:00 [debug] <0.927.0> MQTT connection [::1]:50682 -> [::1]:1883 picked vhost using plugin_configuration_or_default_vhost
2024-07-25 09:15:59.681276-04:00 [debug] <0.927.0> auth_backend_http: POST http://localhost:8080/auth/user
2024-07-25 09:15:59.681316-04:00 [debug] <0.927.0> auth_backend_http: request timeout: infinity, connection timeout: infinity
2024-07-25 09:15:59.683203-04:00 [debug] <0.927.0> auth_backend_http: response code is 200, body: "allow administrator management"
2024-07-25 09:15:59.683260-04:00 [debug] <0.927.0> User 'guest' authenticated successfully by backend rabbit_auth_backend_http
2024-07-25 09:15:59.683405-04:00 [debug] <0.927.0> auth_backend_http: POST http://localhost:8080/auth/vhost
2024-07-25 09:15:59.683479-04:00 [debug] <0.927.0> auth_backend_http: request timeout: infinity, connection timeout: infinity
2024-07-25 09:15:59.685012-04:00 [debug] <0.927.0> auth_backend_http: response code is 200, body: "allow"
2024-07-25 09:15:59.685185-04:00 [info] <0.927.0> Accepted MQTT connection [::1]:50682 -> [::1]:1883 for client ID OoqxFVpVeYRxTc-zVuRi1A
2024-07-25 09:15:59.685416-04:00 [debug] <0.927.0> auth_backend_http: POST http://localhost:8080/auth/resource
2024-07-25 09:15:59.685471-04:00 [debug] <0.927.0> auth_backend_http: request timeout: infinity, connection timeout: infinity
2024-07-25 09:15:59.686937-04:00 [debug] <0.927.0> auth_backend_http: response code is 200, body: "allow"
2024-07-25 09:15:59.687031-04:00 [debug] <0.927.0> auth_backend_http: POST http://localhost:8080/auth/topic
2024-07-25 09:15:59.687060-04:00 [debug] <0.927.0> auth_backend_http: request timeout: infinity, connection timeout: infinity
2024-07-25 09:15:59.688599-04:00 [debug] <0.927.0> auth_backend_http: response code is 200, body: "allow"

2024-07-25T09:15:43.339-04:00  INFO 99276 --- [nio-8080-exec-5] c.r.examples.AuthBackendHttpController   : Checking resource access with ResourceCheck{resource='queue', name='mqtt-subscription-pYx3R3i4rkrBLSqpM7Orogqos0', permission='read'} ResourceCheck{username='guest', vhost='/'}
2024-07-25T09:15:47.187-04:00  INFO 99276 --- [nio-8080-exec-6] c.r.examples.AuthBackendHttpController   : Successfully authenticated user guest
2024-07-25T09:15:47.193-04:00  INFO 99276 --- [nio-8080-exec-7] c.r.examples.AuthBackendHttpController   : Successfully authenticated user guest
2024-07-25T09:15:49.843-04:00  INFO 99276 --- [nio-8080-exec-8] c.r.examples.AuthBackendHttpController   : Successfully authenticated user guest
2024-07-25T09:15:49.845-04:00  INFO 99276 --- [nio-8080-exec-9] c.r.examples.AuthBackendHttpController   : Checking vhost access with VirtualHostCheck{username='guest', vhost='/'}
2024-07-25T09:15:49.848-04:00  INFO 99276 --- [io-8080-exec-10] c.r.examples.AuthBackendHttpController   : Checking resource access with ResourceCheck{resource='exchange', name='amq.topic', permission='write'} ResourceCheck{username='guest', vhost='/'}
2024-07-25T09:15:49.851-04:00  INFO 99276 --- [nio-8080-exec-1] c.r.examples.AuthBackendHttpController   : Checking topic access with TopicCheck{routing_key='.mosquitto.1'} ResourceCheck{resource='topic', name='amq.topic', permission='write'} TopicCheck{username='guest', vhost='/'}, result: false
2024-07-25T09:15:52.191-04:00  INFO 99276 --- [nio-8080-exec-2] c.r.examples.AuthBackendHttpController   : Successfully authenticated user guest
2024-07-25T09:15:52.202-04:00  INFO 99276 --- [nio-8080-exec-3] c.r.examples.AuthBackendHttpController   : Successfully authenticated user guest
2024-07-25T09:15:57.192-04:00  INFO 99276 --- [nio-8080-exec-4] c.r.examples.AuthBackendHttpController   : Successfully authenticated user guest
2024-07-25T09:15:57.200-04:00  INFO 99276 --- [nio-8080-exec-5] c.r.examples.AuthBackendHttpController   : Successfully authenticated user guest
2024-07-25T09:15:57.853-04:00  INFO 99276 --- [nio-8080-exec-6] c.r.examples.AuthBackendHttpController   : Successfully authenticated user guest
2024-07-25T09:15:57.855-04:00  INFO 99276 --- [nio-8080-exec-7] c.r.examples.AuthBackendHttpController   : Checking vhost access with VirtualHostCheck{username='guest', vhost='/'}
2024-07-25T09:15:57.857-04:00  INFO 99276 --- [nio-8080-exec-8] c.r.examples.AuthBackendHttpController   : Checking resource access with ResourceCheck{resource='exchange', name='amq.topic', permission='write'} ResourceCheck{username='guest', vhost='/'}
2024-07-25T09:15:57.859-04:00  INFO 99276 --- [nio-8080-exec-9] c.r.examples.AuthBackendHttpController   : Checking topic access with TopicCheck{routing_key='.mosquitto.t1'} ResourceCheck{resource='topic', name='amq.topic', permission='write'} TopicCheck{username='guest', vhost='/'}, result: false
2024-07-25T09:15:59.040-04:00  INFO 99276 --- [io-8080-exec-10] c.r.examples.AuthBackendHttpController   : Successfully authenticated user guest
2024-07-25T09:15:59.042-04:00  INFO 99276 --- [nio-8080-exec-1] c.r.examples.AuthBackendHttpController   : Checking vhost access with VirtualHostCheck{username='guest', vhost='/'}
2024-07-25T09:15:59.044-04:00  INFO 99276 --- [nio-8080-exec-2] c.r.examples.AuthBackendHttpController   : Checking resource access with ResourceCheck{resource='exchange', name='amq.topic', permission='write'} ResourceCheck{username='guest', vhost='/'}
2024-07-25T09:15:59.045-04:00  INFO 99276 --- [nio-8080-exec-3] c.r.examples.AuthBackendHttpController   : Checking topic access with TopicCheck{routing_key='.mosquitto.t1'} ResourceCheck{resource='topic', name='amq.topic', permission='write'} TopicCheck{username='guest', vhost='/'}, result: false
2024-07-25T09:15:59.682-04:00  INFO 99276 --- [nio-8080-exec-4] c.r.examples.AuthBackendHttpController   : Successfully authenticated user guest
2024-07-25T09:15:59.684-04:00  INFO 99276 --- [nio-8080-exec-5] c.r.examples.AuthBackendHttpController   : Checking vhost access with VirtualHostCheck{username='guest', vhost='/'}
2024-07-25T09:15:59.686-04:00  INFO 99276 --- [nio-8080-exec-6] c.r.examples.AuthBackendHttpController   : Checking resource access with ResourceCheck{resource='exchange', name='amq.topic', permission='write'} ResourceCheck{username='guest', vhost='/'}
2024-07-25T09:15:59.687-04:00  INFO 99276 --- [nio-8080-exec-7] c.r.examples.AuthBackendHttpController   : Checking topic access with TopicCheck{routing_key='.mosquitto.t1'} ResourceCheck{resource='topic', name='amq.topic', permission='write'} TopicCheck{username='guest', vhost='/'}, result: false
2024-07-25T09:16:00.334-04:00  INFO 99276 --- [nio-8080-exec-8] c.r.examples.AuthBackendHttpController   : Successfully authenticated user guest
2024-07-25T09:16:00.335-04:00  INFO 99276 --- [nio-8080-exec-9] c.r.examples.AuthBackendHttpController   : Checking vhost access with VirtualHostCheck{username='guest', vhost='/'}
2024-07-25T09:16:00.337-04:00  INFO 99276 --- [io-8080-exec-10] c.r.examples.AuthBackendHttpController   : Checking resource access with ResourceCheck{resource='exchange', name='amq.topic', permission='write'} ResourceCheck{username='guest', vhost='/'}
2024-07-25T09:16:00.339-04:00  INFO 99276 --- [nio-8080-exec-1] c.r.examples.AuthBackendHttpController   : Checking topic access with TopicCheck{routing_key='.mosquitto.t1'} ResourceCheck{resource='topic', name='amq.topic', permission='write'} TopicCheck{username='guest', vhost='/'}, result: false
2024-07-25T09:16:02.190-04:00  INFO 99276 --- [nio-8080-exec-2] c.r.examples.AuthBackendHttpController   : Successfully authenticated user guest
2024-07-25T09:16:02.201-04:00  INFO 99276 --- [nio-8080-exec-3] c.r.examples.AuthBackendHttpController   : Successfully authenticated user guest