Request timeout returns a poisoned connection to the pool: next request gets the previous query's result (LDEV-5966 regression?)

dev
1

We’re seeing queries in production occasionally return a different query’s result set. The exception shows our SQL, but the result has another statement’s columns. When the two statements happen to have the same columns, nothing errors and the wrong rows are used silently. That’s a data-integrity and data-exposure problem for us.

We’ve reproduced it locally and think we know the cause.

Environment

  • 6.2.8.20 (local, where we reproduced it)
  • Java 17, PostgreSQL JDBC driver, no external connection pooler
  • Server-level datasources, default pool settings, validate=false

What we think is happening

  1. A request hits its request timeout while a query is waiting on the database.

  2. Lucee interrupts the thread and then, on the forced pass, calls Thread.stop() (SystemUtil.stop, ~line 1412). If the database response has already arrived, the full result is left unread on the JDBC connection.

  3. Since LDEV-5966 (commit 3417970d4, first in 6.2.5.6), DatasourceManagerImpl.releaseConnection always calls release(), which returns the connection to the pool. It used to call IOUtil.closeEL(dc) when getTimeoutStackTrace() != null:

    -			if (pc != null && ((PageContextImpl) pc).getTimeoutStackTrace() != null) {
-				IOUtil.closeEL(dc);
-			}
-			else {
-				((DatasourceConnectionPro) dc).release();
-			}
+			((DatasourceConnectionPro) dc).release();

  4. With validate=false, validateObject on borrow only checks isClosed(), which is still false. The next request to borrow that connection reads the stale result as the answer to its own query.

Repro

Two pages, same datasource, run one after the other (not concurrently):

a.cfm: times out after the database has sent its result:

<cfsetting requesttimeout="3">
<cfscript>
	q = queryExecute(
		"select 'AAAA' as a_marker, g as a_id from (select pg_sleep(8)) s, generate_series(1, 3) g",
		[], { datasource: "mydsn" }
	);
	writeOutput("A finished without a timeout");
</cfscript>

b.cfm: runs small queries and checks each result is its own:

<cfscript>
	bad = 0;
	for (i = 1; i <= 50; i++) {
		q = queryExecute("select 'B' as b_marker, #i# as b_i", [], { datasource: "mydsn" });
		if (q.columnList != "B_MARKER,B_I" || q.b_i[1] != i) {
			bad++;
			writeOutput("query #i# got columns [#q.columnList#]<br>");
		}
	}
	writeOutput("mismatches: #bad#");
</cfscript>

Request a.cfm (it times out), then request b.cfm.

Results

Scenario Swapped results in b.cfm
Same datasource, validate=false 13 of 18 runs: b.cfm’s first query returned A_MARKER,A_ID
A and B on different datasources 0 of 24
Same datasource, validate=true 0 of 18

Other things we saw:

  • If the timeout lands while rows are still streaming (a slow query that sends rows gradually), the next borrower gets a socket/I-O error instead of a swapped result.
  • With validate=true the stale connection is still reused (same Postgres backend pid). The isValid() round trip on borrow seems to consume the leftover result, so validate=true works around it but doesn’t really fix it. It also adds one round trip per borrow.

Questions

  1. Does this match your understanding? Should a connection whose thread was stopped or interrupted mid-query be closed (or at least invalidated in the pool) rather than released? The LDEV-5966 change fixed pool accounting, but it seems to have removed the only guard against reusing a connection in an unknown protocol state. An invalidateObject on the pool would keep the accounting correct and still discard the connection.
  2. Is validate=true the recommended mitigation in the meantime, or is there a better one?
  3. On Java 19+ Thread.stop() throws UnsupportedOperationException and only the interrupt happens. Is the same risk expected there, for example a driver that abandons a read on interrupt?
2

@dman1 thanks a lot for this report and the clean repro, it made this easy to verify.

We could reproduce it. Your analysis is right: since LDEV-5966 (6.2.5.6 / 7.0.2.10) releaseConnection() always returns the connection to the pool, and with validate=false nothing checks it on the next borrow. With your two pages against PostgreSQL 17 (validate=false, 6 runs each):

Version Java Result
6.2.8.20 17 6 of 6 swapped (A_MARKER,A_ID)
6.2.9.4-RC, 7.0.6.9-RC 17 5 of 6 swapped
6.2.9.4-RC 11 I/O error or a hang in a socket read on the next borrower
7.1.1.15-RC 17 no swap, but the same connection is reused
6.2.9.4-RC, 7.0.6.9-RC, 7.1.1.15-RC, 8.0 snapshot 21 no swap, but the same connection is reused

On 6.2 and 7.0 the timed-out thread is stopped with Thread.stop(), which can leave a half-read result on the connection. 7.1 no longer does that, and on Java 20+ Thread.stop() is gone anyway, so with pgjdbc the query just runs to the end and the result is read completely. The connection still goes back to the pool unchecked, though.

Ticket: LDEV-6503

The fix does what you suggested. When the request timed out or the thread was interrupted, the connection is invalidated in the pool instead of being returned. It is destroyed and the pool counters stay right, so the LDEV-5966 fix is kept. The PR is against 7.1 (it merges up to 8.0) and includes a regression test: LDEV-6503 discard timed-out connections instead of returning them to the pool by GianTschingt · Pull Request #2853 · lucee/Lucee · GitHub

With the patch, every timed-out request got a new connection afterwards. There is no backport to 6.2 or 7.0 planned for now, so on those versions please use the workaround below, or move to 7.1, where we couldn’t reproduce the swap.

Workaround: set validate=true on the datasource. It avoided the swap in all my runs. It hides the problem rather than fixing it, and it costs one round trip per borrow. It also helps to give long-running queries a timeout below the request timeout, so the driver cancels the statement cleanly before the request timeout has to stop the thread.

3

@dman1 the fix is merged and available in 7.1.2.1-SNAPSHOT:

Ticket: LDEV-6503 (now in QA), pull request: LDEV-6503 discard timed-out connections instead of returning them to the pool by GianTschingt · Pull Request #2853 · lucee/Lucee · GitHub

If you get a chance, could you run your two test pages against it (ideally with validate=false) and let us know whether timed-out requests now always get a fresh connection? Thanks!

4

@GianTschingt thanks, that was quick, and the version/Java matrix is really useful.

It’s good to know the swap also needs Thread.stop(). That explains why we only saw it on 6.2 with Java 17, and invalidating the connection in the pool looks like the right fix.

We’re on 6.2, so for now we’re rolling out validate=true on all our datasources, as you suggested. We’ll also look at giving our long-running queries a timeout below the request timeout.

A 7.x upgrade isn’t on our roadmap yet, but your regression test covers the case our pages exercise, so hopefully that’s enough to get it through QA. We’ll keep an eye on the ticket and look forward to picking up the fix when we move to 7.1.

Thanks again to you and the team.