Many "Pool connection error" with small Session.Timeout

[moguchev]

Version of driver: v2.0.0 (latest)
Go version: 1.24
Cassandra version: 5.0.4

If set global Session Timeout equal 1*time.Second or less in logs we can see a lot of messages:

"message":"Pool connection error.","addr":"10.239.171.143:9042","err":"read tcp 10.221.55.21:53299->10.229.171.143:9042: i/o timeout"

The same thing happens with long timeouts, but less often.

I tracked the full error flow:
Conn.serve -> Conn.recv -> Conn.processFrame -> readHeader -> connReader.Read -> Conn.serve -> Conn.closeWithError ->hostConnPool.HandleError

So the driver keeps getting read/timeout errors and closes the connection with error and establishes a new one (and so on all the time).

The most surprising thing is that Cassandra's response time doesn't exceed 40ms at 99.9p. The go client isn't under any load.

Also I've found, the Heartbeat connection is established with a general timeout, not a Connect timeout (which isn't entirely accurate). However, debugging has shown that this isn't the reason the connection is closed.

Constant client-side reconnects put a strain on Cassandra.

[joao-r-reis]

The most surprising thing is that Cassandra's response time doesn't exceed 40ms at 99.9p.

Where are you measuring this? Are you sure that is the latency that gocql itself is seeing?

[joao-r-reis]

Did you start observing this behavior only after you upgraded to gocql 2.0.0?

[moguchev]

Did you start observing this behavior only after you upgraded to gocql 2.0.0?

No, this can also be observed on v2.0.0-rc1. I was sure that this PR #1903 would fix this error but unfortantly it didn't

Where are you measuring this? Are you sure that is the latency that gocql itself is seeing?

Response time is determined by Cassandra cluster monitoring data. The latency seen by gocql itself is unknown. I'll have to check.

[moguchev]

What worries me most is that the driver has a hertbeat mechanism that removes connections from the pool due to errors (including timeouts). This mechanism should be the only one to close the connection in such cases. But it turns out that somewhere at the Conn level, an I/O timeout occurs, causing it to be closed...

[moguchev]

May be problem somewhere here:

func (c *Conn) processFrame(ctx context.Context, r io.Reader) error {
	// not safe for concurrent reads

	// read a full header, ignore timeouts, as this is being ran in a loop
	// TODO: TCP level deadlines? or just query level deadlines?
	if c.r.GetTimeout() > 0 {
		c.r.SetReadDeadline(time.Time{}) //nolint:errcheck
	}

	headStartTime := time.Now()
	// were just reading headers over and over and copy bodies
	head, err := readHeader(r, c.headerBuf[:])
	headEndTime := time.Now()
	if err != nil {
		return err // here we get error i/o timeout
	}

We set no timeout c.r.SetReadDeadline(time.Time{}) to read a full header, ignore timeouts. But readHeader call io.ReadFull(c.r) which calls (c *connReader) Read:

func (c *connReader) Read(p []byte) (n int, err error) {
	const maxAttempts = 5

	for i := 0; i < maxAttempts; i++ {
		var nn int
		if c.timeout > 0 {
			c.conn.SetReadDeadline(time.Now().Add(c.timeout)) //nolint:errcheck
		}

		nn, err = io.ReadFull(c.r, p[n:])
		n += nn
		if err == nil {
			break
		}

		if verr, ok := err.(net.Error); !ok || !verr.Temporary() { //nolint:staticcheck
			break
		}
	}

	return
}

connReader.timeout is not zero so we SetReadDeadline again...

May be it's ok logic now, I don't know...

[joao-r-reis]

I think the main issue is that we are using the Timeout setting for both request level timeouts and connection read timeout. The connection read timeout should in general be quite high and it should be fine to close the connection when those timeouts happen. Users should only care about the request level timeout but there doesn't seem to be a session wide timeout config field just for those if I'm understanding correctly...

[joao-r-reis]

But you're right that if we already have a heartbeat mechanism we probably should not close the connection when the connection read times out...