[Bug] Intermittent connection timeouts after upgrade from 3.7.2 -> 4.2.0 #618

Search before asking

• I searched in the issues and found nothing similar.

Version

Pulsar 4.2.0 on Rocky 9 Linux, connecting to Pulsar cluster running 4.0.11 in AWS

Minimal reproduce step

Unfortunately this is not easily reproducible in a test environment. We have a fairly widespread deployment of Pulsar, with many thousands of processes connecting from a variety of platforms 24/7. After upgrading the Pulsar client to v4.2.0 from v3.7.2, our telemetry indicated the sudden appearance of relatively rare intermittent connection timeouts: about 100 per day out of several hundred thousand. We've isolated the appearance of these timeouts to this code upgrade - we never saw this behavior on 3.7.2 or before (it's been used in production for >5 years).

I believe these timeouts have something to do with the code changes to ClientConnection.cc, which underwent some significant refactoring to adopt the new non-deprecated ASIO APIs: https://github.com/apache/pulsar-client-cpp/compare/v3.7.2..v4.2.0#diff-66de9f613070810cabd10f6103de05aaa9ca232d6de47ba388ec7178fdbe90ab

Our Pulsar cluster host names (we have three clusters, all are affected) resolve to AWS NLBs split across 3 availability zones, so the DNS resolution always results in 3 IP endpoints to connect to. We have both TLS and regular connections in the mix, and both are affected. The majority (but not all) of the timeout failures we see come from short-lived command line applications that fail on their very first connection attempt, so I don't think it's related to the connection state management code (like a socket being left in a weird state), but the initial connect path. It feels like an off-by-one that causes the connection state to get stuck after the first two attempts fail, but I haven't been able to find any direct evidence of this.

The previous code would individually attempt to connect to each endpoint directly with socket->connect_async, while the new code defers this logic to the ASIO::connect_async free function. We're using boost's ASIO from v1.85, the code for which ends up here. I find the code for this implementation to be rather absurd, but I've stepped through it in the debugger and on paper, and it seems like it should work... but somehow it's getting stuck.

One of our affected processes has Pulsar debug logging turned on, so we were able to get some more insight. From those logs we observe that when it times out on 4.2.0, the handleTcpConnected callback is never called until the timeout expires (currently set at 7 seconds) and forcefully closes the socket. Scrolling back in time to v3.7.2, I found a few cases where 1 or 2 of the IPs would fail with "connection refused", and then the next call would succeed, all within a matter of a few milliseconds.

I'm going to attempt a manual patch of the code to return it to explicitly iterating over the endpoint IPs (logging any intermediate failures) and see if that helps or provides additional clues, but I wanted to file an issue here to see if the project maintainers had any ideas on why this might suddenly start happening, and to see if anyone else was experiencing it. I'd appreciate any insight you might have. Thanks!

What did you expect to see?

No connection timeouts

What did you see instead?

~90-120 connection timeouts per day out of ~500k connection attempts, spread across three clusters

Anything else?

No response

Are you willing to submit a PR?

• I'm willing to submit a PR!