fix: improve driver-side timeout logging with timeout value and pool state (3.x)

[nikagra]

Fixes: DRIVER-541

Problem

When OperationTimedOutException fires, the existing log output gives no information about why it happened. There are two distinct failure modes that look identical in the logs:

1. Pool contention — the request was queued inside the driver waiting to borrow a connection, and the cumulative wait pushed the total elapsed time past readTimeoutMillis. The request may never have reached the server.
2. Server-side slowness — the request reached the server but the server took longer than readTimeoutMillis to respond (e.g. due to a reader_concurrency_semaphore stall). The driver gave up, but the server may still be processing it, orphaning the stream ID.

Without knowing the configured timeout value or the connection state at the moment of timeout, diagnosing which scenario occurred requires guesswork.

Motivated by CUSTOMER-301 (Whoop): repeated bursts of OperationTimedOutException on the client side with no corresponding server-side timeouts. The server-side investigation pointed to a reader_concurrency_semaphore bug in ScyllaDB 2025.4.5, but the driver-side picture was unclear without the pool state at timeout time.

Changes

Connection.java

ResponseHandler.readTimeoutMillis: private → package-private.

This field holds the exact timeout value used to schedule the HashedWheelTimer for this request (either the per-statement override from Statement.setReadTimeoutMillis(), or the driver-wide SocketOptions.readTimeoutMillis() as fallback). Making it package-private allows RequestHandler (same package) to read it directly at timeout time, guaranteeing the logged value matches what the timer was set to.

RequestHandler.java

In SpeculativeExecution.onTimeout(), add a WARN log line immediately before the OperationTimedOutException is constructed:

[<execution-id>] Driver-side timeout waiting for response from <host> —
    configured timeout: <N>ms,
    connection in-flight: <N>,
    pool pending borrows: <N>,
    pool total in-flight: <N>

What each field tells you:

Field	Meaning
configured timeout	The readTimeoutMillis value actually used for the timer — confirms whether a per-statement or driver-wide timeout was in effect
connection in-flight	Number of requests currently awaiting a response on this specific connection (Connection.inFlight)
pool pending borrows	Number of requests waiting to acquire any connection from the pool (HostConnectionPool.pendingBorrowCount) — non-zero means pool contention
pool total in-flight	Total in-flight across all connections to this host (HostConnectionPool.totalInFlight)

Diagnosing failure modes with this output:

• pool pending borrows > 0 → pool contention; requests are queuing inside the driver before reaching the server
• pool pending borrows = 0 + high connection in-flight → server is slow; requests are sent but not answered within the timeout
• configured timeout is unexpectedly small → non-default readTimeoutMillis is set somewhere (e.g. in a framework wrapper)

Notes

• No logic changes; the new log line fires at existing WARN level alongside the existing timeout handling path.
• connectionHandler is null-checked defensively; in practice it will always be set when the timer fires, but the field is volatile and set to null at the start of each retry write.
• pool is null-checked since manager.pools.get(queriedHost) can return null if the host was removed between request dispatch and timeout.
• No test changes: there are no existing unit tests for SpeculativeExecution.onTimeout() in RequestHandlerTest; adding meaningful coverage requires a non-trivial mock of HostConnectionPool and is better tracked as a follow-up.

[Copilot]

Pull request overview

Improves driver-side diagnostics for OperationTimedOutException by logging the effective read timeout and relevant pool/connection state at the moment a driver-side timeout fires, helping distinguish pool contention vs server slowness.

Changes:

• Add a WARN log in RequestHandler.SpeculativeExecution.onTimeout() including configured timeout, connection in-flight, and pool queue/load counters.
• Expose the exact timeout used by the request timer by making Connection.ResponseHandler.readTimeoutMillis package-private.

Reviewed changes

Copilot reviewed 2 out of 2 changed files in this pull request and generated 2 comments.

File	Description
driver-core/src/main/java/com/datastax/driver/core/RequestHandler.java	Adds timeout WARN logging with connection/pool state at the time of driver-side timeout.
driver-core/src/main/java/com/datastax/driver/core/Connection.java	Makes ResponseHandler.readTimeoutMillis accessible within the package so the timeout log can reflect the timer’s configured value.

---

💡 Add Copilot custom instructions for smarter, more guided reviews. Learn how to get started.

[Lorak-mmk]

I don't think we should be using warn in something that can happen in a typical operation, and is produced in the request path. It may result in a lot of spam.

Can you instead add new fields to OperationTimedOutException?

[nikagra]

Done — logger.warn() is gone entirely. I've added four new fields to OperationTimedOutException:

• configuredTimeoutMs — the driver-side read timeout in effect for the request
• connectionInFlight — in-flight count on the specific connection at timeout time
• poolPendingBorrows — requests queued waiting for a connection from the pool
• poolTotalInFlight — total in-flight across all connections to that host

A named sentinel constant UNAVAILABLE = -1 is used when any value cannot be determined. The enriched message is baked into the exception's message string (visible in stack traces automatically) and all fields are also accessible via getters for programmatic use (e.g. in a LatencyTracker). No logging added to the hot path.

[roydahan]

@nikagra please change the JIRA reference to https://scylladb.atlassian.net/browse/DRIVER-541

[roydahan]

Looking at the integration tests, it looks like the fix is working:

Starting com.datastax.driver.core.QueryLoggerErrorsTest.should_log_timed_out_queries [Test #714]...
    1423749 [cluster1017-timeouter-0] DEBUG com.datastax.driver.core.QueryLogger.ERROR - [cluster1017] [/127.0.1.1:46829] Query error after 95 ms: [0 bound values] SELECT foo FROM bar;
com.datastax.driver.core.exceptions.OperationTimedOutException: [/127.0.1.1:46829] Timed out waiting for server response [configured timeout: 1ms, connection in-flight: 1, pool pending borrows: 0, pool total in-flight: 1]
	at com.datastax.driver.core.RequestHandler$SpeculativeExecution.onTimeout(RequestHandler.java:1021)
	at com.datastax.driver.core.Connection$ResponseHandler$1.run(Connection.java:1943)
	at io.netty.util.HashedWheelTimer$HashedWheelTimeout.run(HashedWheelTimer.java:713)
	at io.netty.util.concurrent.ImmediateExecutor.execute(ImmediateExecutor.java:34)
	at io.netty.util.HashedWheelTimer$HashedWheelTimeout.expire(HashedWheelTimer.java:701)
	at io.netty.util.HashedWheelTimer$HashedWheelBucket.expireTimeouts(HashedWheelTimer.java:787)
	at io.netty.util.HashedWheelTimer$Worker.run(HashedWheelTimer.java:501)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.lang.Thread.run(Thread.java:750)
SUCCESS: should_log_timed_out_queries

@nikagra Am i correct?