TLS replication still logs error if it cannot connect to first address

[tschuettig]

Describe the bug

Related to the following issue:
#96

RabbitMQ still logs an error if it fails to connect to the first address but succeeds with another address:

2025-04-22 11:10:44.516003+00:00 [notice] <0.33078.0> TLS client: In state wait_cert at ssl_handshake.erl:2186 generated CLIENT ALERT: Fatal - Handshake Failure
2025-04-22 11:10:44.516003+00:00 [notice] <0.33078.0>  - {bad_cert,
2025-04-22 11:10:44.516003+00:00 [notice] <0.33078.0>        {hostname_check_failed,
2025-04-22 11:10:44.516003+00:00 [notice] <0.33078.0>            {requested,{10,244,34,106}},
2025-04-22 11:10:44.516003+00:00 [notice] <0.33078.0>            {received,
2025-04-22 11:10:44.516003+00:00 [notice] <0.33078.0>                [{dNSName,"*.rabbit-mq"},
2025-04-22 11:10:44.516003+00:00 [notice] <0.33078.0>                 {dNSName,"*.rabbit-mq.default"},
2025-04-22 11:10:44.516003+00:00 [notice] <0.33078.0>                 {dNSName,"*.rabbit-mq.default.svc"},
2025-04-22 11:10:44.516003+00:00 [notice] <0.33078.0>                 {dNSName,
2025-04-22 11:10:44.516003+00:00 [notice] <0.33078.0>                     "*.rabbit-mq.default.svc.cluster.local"}]}}}
2025-04-22 11:10:44.516270+00:00 [debug] <0.33074.0> __random_fanout_queue_1744899226694571303 [osiris_replica_reader:maybe_connect/5] TLS connection refused (handshake failure), host:{10,244,34,106} - port: 6198
2025-04-22 11:10:44.516382+00:00 [warning] <0.33074.0> __random_fanout_queue_1744899226694571303 [osiris_replica_reader:init/1] could not connect replica reader to replica at ["rabbit-mq-0","rabbit-mq-0.rabbit-mq.default.svc.cluster.local",{10,244,34,106}] port 6198, Reason: connection_refused
2025-04-22 11:10:44.516545+00:00 [error] <0.33074.0>   crasher:
2025-04-22 11:10:44.516545+00:00 [error] <0.33074.0>     initial call: osiris_replica_reader:init/1
2025-04-22 11:10:44.516545+00:00 [error] <0.33074.0>     pid: <0.33074.0>
2025-04-22 11:10:44.516545+00:00 [error[] <0.33074.0>     registered_name: ]
2025-04-22 11:10:44.516545+00:00 [error] <0.33074.0>     exception exit: connection_refused
2025-04-22 11:10:44.516545+00:00 [error] <0.33074.0>       in function  gen_server:init_it/6 (gen_server.erl, line 2210)
2025-04-22 11:10:44.516545+00:00 [error] <0.33074.0>     ancestors: [osiris_replica_reader_sup,osiris_sup,<0.140.0>]
2025-04-22 11:10:44.516545+00:00 [error] <0.33074.0>     message_queue_len: 0
2025-04-22 11:10:44.516545+00:00 [error[] <0.33074.0>     messages: ]
2025-04-22 11:10:44.516545+00:00 [error] <0.33074.0>     links: [<0.145.0>]
2025-04-22 11:10:44.516545+00:00 [error[] <0.33074.0>     dictionary: ]
2025-04-22 11:10:44.516545+00:00 [error] <0.33074.0>     trap_exit: true
2025-04-22 11:10:44.516545+00:00 [error] <0.33074.0>     status: running
2025-04-22 11:10:44.516545+00:00 [error] <0.33074.0>     heap_size: 2586
2025-04-22 11:10:44.516545+00:00 [error] <0.33074.0>     stack_size: 29
2025-04-22 11:10:44.516545+00:00 [error] <0.33074.0>     reductions: 59554
2025-04-22 11:10:44.516545+00:00 [error] <0.33074.0>   neighbours:
2025-04-22 11:10:44.516545+00:00 [error] <0.33074.0> 
2025-04-22 11:10:44.518282+00:00 [warning] <0.33072.0> rabbit_stream_coordinator: Error while starting replica for __random_fanout_queue_1744899226694571303 on node [email protected] in 8 : {{shutdown,{connection_refused,{child,undefined,#Ref<24710.3053328318.2205155329.224186>,{...},...}}},{gen_server,call,[<24710.12141.0>,await,infinity]}}
2025-04-22 11:10:44.522693+00:00 [debug] <0.5366.0> rabbit_stream_coordinator: running action: 'start_replica' for __random_fanout_queue_1744899226694571303 on node '[email protected]' in epoch 8
2025-04-22 11:10:44.526483+00:00 [debug] <0.33080.0>  [osiris_log:last_epoch_chunk_ids/2]  completed in 0ms
2025-04-22 11:10:44.531674+00:00 [debug] <0.33081.0> __random_fanout_queue_1744899226694571303: trying to connect to replica at ["rabbit-mq-0","rabbit-mq-0.rabbit-mq.default.svc.cluster.local",{10,244,34,106}]
2025-04-22 11:10:44.531868+00:00 [debug] <0.33081.0> __random_fanout_queue_1744899226694571303 [osiris_replica_reader:maybe_connect/5] trying to establish TLS connection to "rabbit-mq-0" using port 6364
2025-04-22 11:10:44.535365+00:00 [debug] <0.33081.0> __random_fanout_queue_1744899226694571303 [osiris_replica_reader:maybe_connect/5] TLS connection refused, host:"rabbit-mq-0" - port: 6364
2025-04-22 11:10:44.535488+00:00 [debug] <0.33081.0> __random_fanout_queue_1744899226694571303 [osiris_replica_reader:maybe_connect/5] error while trying to establish TLS connection nxdomain
2025-04-22 11:10:44.535570+00:00 [debug] <0.33081.0> __random_fanout_queue_1744899226694571303 [osiris_replica_reader:maybe_connect/5] trying to establish TLS connection to "rabbit-mq-0.rabbit-mq.default.svc.cluster.local" using port 6364
2025-04-22 11:10:44.549394+00:00 [debug] <0.33081.0> __random_fanout_queue_1744899226694571303 [osiris_replica_reader:init/1] successfully connected to host "rabbit-mq-0.rabbit-mq.default.svc.cluster.local" port 6364
2025-04-22 11:10:44.550061+00:00 [debug] <0.33081.0> __random_fanout_queue_1744899226694571303 [osiris_log:init_data_reader/2]  at 0 prev empty local range: empty
2025-04-22 11:10:44.550437+00:00 [info] <0.33081.0> __random_fanout_queue_1744899226694571303 [osiris_replica_reader:init/1] starting osiris replica reader at offset 0
2025-04-22 11:10:44.551525+00:00 [info] <0.33079.0> rabbit_stream_coordinator: __random_fanout_queue_1744899226694571303: replica started on [email protected] in 8 pid <24710.12149.0>

This can be misleading, especially because the log message "successfully connected to host" has the log level debug and therefore is not shown in an usual setup.

Reproduction steps

1. Setup replicated RabbitMQ and enable TLS, block access to IP address, e.g. by using a certificate
2. Create stream queue
3. Restart single node

Expected behavior

There should be no error logged unless the connection failed for all addresses.

Additional context

No response

[michaelklishin]

@tschuettig certificates do not "block access to IP addresses".

Some would argue that such errors should be visible in the logs and not hidden.

What #103 (#96) addressed was not logging at all but rather what errors result in a retry with the rest of the hostnames.

[tschuettig]

I noticed this was caused because I was missing the rabbitmq_stream plugin inside the enabled_plugins file, though I don't know what this plugin exactly does to cause this difference and why streams were working in the first place without it. Unfortunately this does not help when working with an older RabbitMQ version, but that is not of your concern.

[acogoluegnes]

Streams are a core feature, they don't require any plugins. The rabbitmq_stream plugin exposes the stream protocol.

Do you mean there is a difference of behavior when the rabbitmq_stream plugin is enabled and when it is not?

[tschuettig]

At first it seemed like it makes a difference but I just saw the error again with the enabled plugin.

[acogoluegnes]

Thanks for the clarification about the readiness probe. I don't think there is much we can do there, I'll do some digging to see if we can rationalize the log messages and make them less verbose.

[acogoluegnes]

@tschuettig I pushed #191 to improve the logging.

[acogoluegnes]

It appears the replica reader cannot connect to the replica when a node restarts because DNS resolution is not possible until the readiness probe is successful. The replica reader does try the IP as a last resort but fails because TLS replication is enabled and the certificate is not issued for the IP.

We don't plan on changing the stream coordinator in RabbitMQ to wait until the node is fully ready (in "K8S readiness probe" terms) to start streams replicas. Instead we'll try to improve the logging (more informative and less verbose).

Follow-up PR: #191

[tschuettig]

This information may arrive a little bit late, but I learned that you can contact pods by their hostname before they are ready by setting spec.publishNotReadyAddresses to true inside the headless service. This might be useful information for the "Deploying to Kubernetes (Do It Yourself)" guide (even if DIY is not the recommended way).

[acogoluegnes]

Thanks for the heads-up. Did you try to use this version and can confirm it is working as expected?