[#872] Bound the connect of the JDBC pool and report a connect it cannot make - #876
[#872] Bound the connect of the JDBC pool and report a connect it cannot make#876vharseko wants to merge 7 commits into
Conversation
…ort a connect it cannot make CachedConnection.getConnection() established connections with no bound of its own and treated every SQLException from the connect as "the server is at max_connections", retrying it recursively with a wait doubling from 1 ms and no end to it. A database that listens but does not answer, a password that is not accepted, a driver that is not in lib/extensions - each hung the caller instead of failing it, silently: every backend operation, the open of a backend and dsconfig create-backend-index on a running server included, borrows through this path. The borrow is now bounded in both phases. One connect attempt is bounded by the properties of its dialect, recognized by the prefix of the connection string, through org.openidentityplatform.opendj.jdbc.connect.timeout (30 s by default, 0 for no bound); a property the connection string sets itself keeps precedence, so the loginTimeout/socketTimeout an administrator put into db-directory by hand still governs. Not one of the four drivers bounds the attempt with a single property - the second covers the reads of the prelogin handshake, of TLS and of authentication - and that includes the SQL Server driver, whose loginTimeout leaves the prelogin read open. Where that second property is a socket read timeout for the life of the connection (mysql, oracle, sql server), it is lifted once the login is through, so a statement slower than the bound is unaffected. Only a database that accepts no further connection is retried now, under the deadline of org.openidentityplatform.opendj.jdbc.pool.timeout (60 s by default), with the backoff capped at 1 s and a throttled warning so the stall is visible in the server log; every other failure is reported to the caller. A connect whose setup fails no longer leaks the connection, a connection that cannot be rolled back is closed instead of being pooled or dropped, and a pooled connection is validated with a bound rather than with isValid(0), which means "no timeout" in the JDBC contract. CachedConnectionTestCase covers all of it without a database - every dialect against a socket that never answers and a driver of the test for the retry - and the container suites assert that the read bound of the login does not outlive it.
maximthomas
left a comment
There was a problem hiding this comment.
Solid change that closes a real hang, and the no-database CachedConnectionTestCase is the right way to cover it. No blocker. Three majors below, all in opendj-server-legacy/src/main/java/org/opends/server/backends/jdbc/CachedConnection.java.
Transient "database is starting up" is now permanently fatal (major)
Only isConnectionLimit is retried; every other SQLException is rethrown:
if (!isConnectionLimit(e, dialect)) {
throw e;
}That includes PostgreSQL 57P03 cannot_connect_now ("the database system is starting up" / "is shutting down") and Oracle ORA-01033 — states that clear themselves in seconds. JDBCStorage.open() has no retry of its own, so the backend stays down until the server is restarted:
// opendj-server-legacy/src/main/java/org/opends/server/backends/jdbc/JDBCStorage.java
public void open(AccessMode accessMode) throws Exception {
try (final Connection con=getConnection()) { // throws -> storageStatus is never set
this.accessMode = accessMode;
storageStatus = StorageStatus.working();
}
}
private StorageStatus storageStatus = StorageStatus.lockedDown(LocalizableMessage.raw("closed"));OpenDJ and PostgreSQL restarting together (compose, systemd) is enough: RootContainer.open() reaches the database a second before recovery finishes and the backend is locked down for good. The old loop rode this out. Please add 57P03 and the per-dialect equivalents to the retried set, under the same pool deadline.
The pool deadline is never applied to the drain (major)
poll() validates every pooled entry with no reference to deadline:
private static CachedConnection poll(String connectionString, long waitMs) throws InterruptedException {
CachedConnection con = cached.get(connectionString).poll(waitMs, TimeUnit.MILLISECONDS);
while (con != null) {
if (isUsable(con)) { // isValid(5) per entry, no deadline check
return con;
}
closeQuietly(con.parent);
con = cached.get(connectionString).poll();
}
return null;
}deadline / POOL_TIMEOUT_PROPERTY is consulted only in the connection-limit catch of getConnection(). The pool is .build(conStr -> new LinkedBlockingQueue<>()) — no size cap (#878). After a failover that leaves pooled sockets half-open, one borrow costs 5 s x pooled connections, minutes, while the advertised 60 s bound never fires. Check deadline in the drain loop and stop validating once it has passed.
isValid(VALIDATION_TIMEOUT_SECONDS) is not a bound on SQL Server (major)
The comment claims the bound covers the half-open case:
// The validation needs a bound of its own: isValid(0) means "no timeout" in the JDBC
// contract, and a connection whose socket is half-open answers it no sooner than it
// answers anything else.
return con.isValid(VALIDATION_TIMEOUT_SECONDS);It does not, for MICROSOFT. In mssql-jdbc-13.4.0.jre11, SQLServerConnection.isValid(int) maps its argument to SQLServerStatement.setQueryTimeout(...) and runs SELECT 1 — an attention-based query timeout that needs a working channel, not a socket read timeout. And relaxReadBound() has just cleared the only socket-level bound this connection had:
con.setNetworkTimeout(DIRECT_EXECUTOR, 0); // MICROSOFT: readBoundOutlivesLogin == trueSo a pooled SQL Server connection has SO_TIMEOUT 0 and validating it against a black-holed socket blocks forever — the exact failure the PR description opens with, surviving on the borrow-from-pool path. MySQL, pgjdbc and Oracle do honour isValid(n) at socket level, so this is one dialect out of four.
#877 already owns "a read timeout for an established connection (today unbounded by design)", which would close this. Either fix it here or correct the comment and the PR description and name it explicitly in #877 — right now both claim a bound that is not there.
Nits
relaxReadBound()can clear a bound the administrator set:readBoundSetcomes only fromdeclaredInUrl(..., "oracle.jdbc.ReadTimeout")/readtimeout. An Oracle TNS descriptor spells the read bound(RECV_TIMEOUT=...)(older propertyoracle.net.READ_TIMEOUT), so we set ours on top of it and thensetNetworkTimeout(con, 0)wipes theirs for the life of the connection — contrary to "nothing of the administrator's is lifted along with it". Same shape for(TRANSPORT_CONNECT_TIMEOUT=...)on the connect side.sqlState.startsWith("53")matches the wholeinsufficient_resourcesclass:53100 disk_full,53200 out_of_memoryand53400 configuration_limit_exceededare not fixed by a pooled connection coming back, yet a PostgreSQL server out of disk now makes every borrow spin the full 60 s, a fresh TCP connect every <= 1 s, before reporting. Also the chain is walked withgetCause()only, notSQLException.getNextException().- The leak
connect()closes is only closed forSQLException:conNew.setAutoCommit(false)/setTransactionIsolation(...)can throw unchecked (drivers wrap internal failures), and the fresh connection is dropped on the floor exactly as before the fix.catch (SQLException | RuntimeException e)covers it. safeUrl()can leak the start of a password: it cuts at the first?/;before looking for@, sojdbc:oracle:thin:scott/pa;ss@//h:1521/svcis cut inside the password andjdbc:oracle:thin:scott/pais what reaches the stall warning and theSQLTimeoutException. Strip the userinfo first, then the parameters.readBoundWarnedis one-shot per JVM: ifsetNetworkTimeoutfails, the first connection warns and every later one silently carries a 30 s read timeout; an import batch then dies with nothing in the log pointing atorg.openidentityplatform.opendj.jdbc.connect.timeout. Warn per occurrence (throttled, likewarnStall) or discard the connection. Same file:lastStallWarningis a single static shared across all connection strings, so with two JDBC backends one starves the other's stall warnings.declaredInUrlis case-insensitive, the drivers are not: pgjdbc and Connector/J parse URL parameters case-sensitively, so?ConnectTimeout=5suppresses our bound while the driver ignores the user's.- Dropped unit in the TTL warning:
getNonNegativePropertylogs"using %d"where the old message was"using %d ms". opendj-server-legacy/src/test/java/org/opends/server/backends/jdbc/TestCase.java:CachedConnection.cached.invalidate(url)discards the queue without closing the connections in it.
Verified as correct, no action needed: the empty-Properties overload is equivalent to the 1-arg DriverManager.getConnection; URL precedence holds in both directions (Connector/J and mssql-jdbc let a supplied property win, pgjdbc lets the URL win, and declaredInUrl never sets a property the URL declares); DIRECT_EXECUTOR is safe with Connector/J's setNetworkTimeout; close() rethrowing a failed rollback() is not a regression; the overflow guards on deadline and timeoutSeconds * unitsPerSecond hold; there are no other callers of the removed getConnection(String,int); and **/*TestCase.java is in the failsafe includes, so CachedConnectionTestCase really does run in the default test job.
…d what the review found open A database that is starting up, recovering or shutting down answers a connect with a state of its own - 57P03 on postgresql, ORA-01033/01034/01089, 1053 on mysql, 921/922/927 and 40613 on sql server - and clears it in seconds. Only pool exhaustion was waited out, so a backend whose database restarted together with the server stayed locked down until the next restart of it: nothing above JDBCStorage.open() attempts the open a second time. Those states are retried alongside pool exhaustion now, under the same pool deadline. ORA-12514 is left out of them: it is what a service name of a typo answers as well. The deadline is applied where it was missing. Draining the pool costs a round trip per connection and the pool has no bound on the number it holds, so the drain stops at the deadline of the borrow; and one connect attempt is bounded by what is left of that deadline, so a borrow can no longer outlive its pool timeout by a whole connect timeout - which is what the property promised. The validation of a pooled connection is bounded at the socket rather than through isValid(n) alone: the sql server driver turns that argument into a query timeout (setQueryTimeout, then "SELECT 1"), which needs an answer from the server to fire at all, and the read bound of the login was lifted the moment the connection was established. A tighter bound of the connection string is left alone, and a connection whose bound cannot be put back is discarded instead of being handed out carrying it. Also from the review: a setup failing with an unchecked exception no longer leaks the connection; pool exhaustion is 53300 rather than the whole insufficient_resources class, and getNextException() is walked along with the causes; an url is stripped of its credentials before its parameters and with the separator of its own dialect, so a password holding a ";" no longer reaches the log; a parameter is recognized the way its driver recognizes it, case-sensitively for pgjdbc alone; the read bound of an oracle descriptor (RECV_TIMEOUT, oracle.net.READ_TIMEOUT) counts as one of the administrator, so ours is neither set on top of it nor lifted with it; loginTimeout stays inside the [0, 65535] the sql server driver validates it against; and the warning for a read bound that cannot be set is throttled rather than given once per JVM, as is the stall warning, now kept per connection string. CachedConnectionTestCase covers each of these without a database: 23 tests.
|
Thanks — a good catch on each of the three, and on most of the nits. All of it is in e83d002, with the description updated to match. Point by point, including the one I did not take. Transient "database is starting up" (major) — fixedYou are right about the consequence, and it is worse than a slow start: Retried now, alongside pool exhaustion and under the same Two decisions inside that worth flagging:
One caveat that stands: 60 s of The pool deadline is never applied to the drain (major) — fixed
While there: the deadline did not cover the connect attempt either, so a 60 s borrow could spend 90 s — the property already says it bounds "every connect attempt and every wait for a pooled connection", and now it does. One attempt gets whatever is left of the deadline, never below 1 s, since
|
maximthomas
left a comment
There was a problem hiding this comment.
All three majors from the previous round are genuinely fixed, and I re-checked the load-bearing claims in driver bytecode rather than on trust: SQLServerDriverIntProperty.LOGIN_TIMEOUT really is validated against [0, 65535] while SOCKET_TIMEOUT has no range, so the maxConnectSeconds clamp is right; SQLServerConnection.isValid(int) is new SQLServerStatement + setQueryTimeout(n) + SELECT 1 and never touches the socket, so the new outer setNetworkTimeout(5000) in boundValidation() is the bound it claims to be; ojdbc8 23.7 implements PhysicalConnection.setNetworkTimeout, so relaxReadBound() works on Oracle; and pgjdbc copies the supplied Properties into a flat map before parseURL, so URL precedence holds. The getNextException() walk, the 53300 narrowing, the RuntimeException leak fix and the per-URL stall throttle all check out.
One major left, on the dialect the PR opens with.
PostgreSQL login is bounded only in the caller, and leaks a thread and a socket per borrow (major)
opendj-server-legacy/src/main/java/org/opends/server/backends/jdbc/CachedConnection.java:130
POSTGRES("jdbc:postgresql:", '?',
"connectTimeout", 1, 0,
new String[]{"loginTimeout"}, 1, false, // <- read bound that does not outlive the login
new int[]{}, new int[]{}),pgjdbc never puts an SO_TIMEOUT on the login socket. PGStream.createSocket(int) passes connectTimeout to Socket.connect(addr, timeout) only, and ConnectionFactoryImpl.openConnectionImpl calls newStream.setNetworkTimeout(socketTimeout * 1000) only under if (socketTimeout > 0) (both before and after enableSSL). socketTimeout defaults to 0 and is not set here, so every read of the login is unbounded.
That leaves loginTimeout as the only bound, and it is enforced out of process: Driver$ConnectThread.getResult(timeout) sets abandoned = true, throws PSQLException("Connection attempt timed out.", 08001), and leaves the daemon thread parked in the unbounded read forever.
Against the failure this PR opens with - a VIP or proxy that completes the TCP handshake and never answers - each borrow returns after 30 s and leaks one daemon thread plus one ESTABLISHED socket. tcpKeepAlive is off by default, so nothing reaps them; at a few operations per second the server reaches unable to create new native thread and fd exhaustion within minutes, where the pre-PR code only parked the operation thread.
Fix: treat PostgreSQL like the other three - socketTimeout (seconds) as readProperties[0] with readBoundOutlivesLogin = true, keeping loginTimeout as the outer bound.
Neither new test can see this: testLoginBoundDoesNotOutliveTheLogin reads getNetworkTimeout() == 0 on postgres either way, and testLoginIsBoundedWhenTheDatabaseNeverAnswers only asserts that the caller returns.
poll() destroys a pooled connection it never validated (minor)
opendj-server-legacy/src/main/java/org/opends/server/backends/jdbc/CachedConnection.java:359
while (con != null) {
if (System.currentTimeMillis() >= deadline) {
closeQuietly(con.parent); // <- unvalidated, possibly perfectly good
return null;
}Under connection-limit pressure - the case the retry loop exists for - a connection returned to the pool right at the deadline is closed, and the borrow then fails with SQLTimeoutException anyway. Each timed-out borrow removes one live connection from the only source of connections there is. The deadline should stop the validation, not discard the entry: return con unvalidated, or put it back.
isUsable() restores the network timeout on a connection that just failed validation (minor)
opendj-server-legacy/src/main/java/org/opends/server/backends/jdbc/CachedConnection.java:386
if (restore >= 0 && !setNetworkTimeout(con.parent, restore)) {
return false;
}
return usable;On a connection the server has already reaped - MySQL wait_timeout, PG idle_session_timeout, any failover - Connector/J's isValid calls abortInternal() and the mssql driver calls terminate(), so the restore throws and emits the throttled WARN "The read bound of a JDBC connection could not be set to 0 ms ... statements taking longer than the org.openidentityplatform.opendj.jdbc.connect.timeout property may fail". That is a routine idle-reap, the message describes something else, and it points the operator at an unrelated property. Skip the restore when !usable.
connect() ignores the false from relaxReadBound() (minor)
opendj-server-legacy/src/main/java/org/opends/server/backends/jdbc/CachedConnection.java:423
if (readBoundSet) {
relaxReadBound(conNew); // return value dropped
}isUsable() discards a pooled connection whose bound cannot be put back, but a freshly established one whose login bound cannot be lifted is still pooled and handed out carrying a 30 s SO_TIMEOUT for its whole life - exactly what the comment above relaxReadBound() says must not happen, so an import batch or the #866 statistics pass dies mid-statement (and on MySQL a socket read timeout aborts the connection outright). Either discard it or do not pool it.
safeUrl() still leaks a password holding the dialect's own separator (minor)
opendj-server-legacy/src/main/java/org/opends/server/backends/jdbc/CachedConnection.java:530
if (at >= 0 && (firstParameter < 0 || at < firstParameter)) { // userinfo firstThe previous round fixed the cross-dialect case (a ; in an Oracle password), and there is a test for it. The same-dialect case is not covered: the guard sends jdbc:oracle:thin:scott/pa?ss@//h:1521/svc back down the parameters-first path, so the stall warning and the SQLTimeoutException carry jdbc:oracle:thin:scott/pa. Same shape for jdbc:mysql://u:sec?ret@h/db -> jdbc:mysql://u:sec.
connect.timeout=0 also disables pool.timeout (minor)
opendj-server-legacy/src/main/java/org/opends/server/backends/jdbc/CachedConnection.java:343
private static long attemptSeconds(long connectTimeoutSeconds, long deadline) {
if (connectTimeoutSeconds == 0 || deadline == Long.MAX_VALUE) {
return connectTimeoutSeconds; // 0 -> connect() sets no properties at all
}pool.timeout documents itself as "Bounds a whole borrow - every connect attempt and every wait for a pooled connection", but with the per-attempt bound turned off the attempt is unbounded, so an administrator who sets connect.timeout=0 and leaves pool.timeout=60 gets the #872 hang back. Clamp the attempt to the remaining deadline even when connectTimeoutSeconds == 0.
Nits
- Timeout message misdiagnoses the newly retried state: at
CachedConnection.java:325theSQLTimeoutExceptionstill reads "the database took no further connection and none was returned to the pool" even when the state being retried was57P03/ ORA-01033 ("starting up"), which is the one case this round added.
# Conflicts: # opendj-server-legacy/src/main/java/org/opends/server/backends/jdbc/CachedConnection.java
…nd the rest of what the review found open
pgjdbc puts an SO_TIMEOUT on the login socket only where socketTimeout is set,
and it defaults to none, so every read of the login - the prelogin handshake,
TLS, authentication - was left to loginTimeout alone. That one is not a bound
of the socket at all: Driver.connect hands the login to a daemon thread of its
own and gives up on the thread rather than on the login, leaving it parked in
the read for as long as the read lasts. Against the database this change exists
for - one that completes the TCP handshake and then says nothing - each borrow
to postgresql returned on time and left a daemon thread and an ESTABLISHED
socket behind it, where the code before this branch parked the operation thread
alone; tcpKeepAlive is off by default, so nothing reaped them. socketTimeout is
set now, as on the other three dialects, and lifted once the login is through;
loginTimeout is kept on top of it for a url naming more than one host, where
each host costs a connect and a login of its own.
Also from the review:
- the deadline of a borrow stops the drain of the pool rather than destroying
the connection in hand: a database at its connection limit has no source of
connections other than the ones coming back, and one returned to the pool a
moment before the deadline is the connection this borrow was waiting for;
- nothing is put back on a connection whose validation failed - Connector/J
aborts such a connection and the sql server driver terminates it, so the
restore failed as well and warned about the statements of a connection that
is being closed, over an idle connection the server had merely reaped;
- a connection whose read bound could not be lifted serves the borrower waiting
for it and is closed rather than pooled: the result of relaxReadBound() used
to be dropped, and the bound of the login went into every borrow the pool
handed that connection to - an import batch among them;
- the deadline of the borrow bounds a connect attempt even where the
...jdbc.connect.timeout property gives it no bound of its own: turning the
per-attempt bound off must not turn the bound of the whole borrow off with it;
- safeUrl() looks for the credentials where the url of the dialect holds them -
between the subprotocol and the first "@" on oracle, inside the authority
elsewhere - so a password holding the parameter separator of its own dialect
("scott/pa?ss@//host") no longer reaches the log;
- the message of the timeout no longer reports a database on its way up as one
at its connection limit, and carries the last error it saw.
CachedConnectionTestCase is at 28 tests, still without a database and ~22 s: the
login thread pgjdbc abandons, the pooled connection the deadline used to close
unvalidated, the bound that is not put back on a reaped connection, the
connection that must not be pooled, and a connect attempt the deadline bounds on
its own. Each of them fails against the code it fixes - the last one by hanging
for the whole 600 s of the run, which is the shape of OpenIdentityPlatform#872 itself.
|
Thanks — all six stand, and the major one was worse than the report says. Fixed in e77c8f7, on a branch merged up to master; the description is updated to match. PostgreSQL login is bounded only in the caller (major) — fixedRight down to the mechanism. I checked it in the bytecode of the 42.7.12 we depend on rather than on the source:
So it was not only "bounded out of process": against a peer that completes the handshake and says nothing, the code before this branch parked the operation thread, and this branch returned the operation and leaked a daemon thread plus an ESTABLISHED socket on every borrow. That is a regression on the dialect the PR opens with, not a gap it left. Taken as you proposed. POSTGRES("jdbc:postgresql:", '?',
new String[]{"connectTimeout", "loginTimeout"}, 1, 0,
new String[]{"socketTimeout"}, 1, true, // the read bound, lifted once the login is through
new int[]{}, new int[]{}),
Worth noting that master already had this right elsewhere: the
|
maximthomas
left a comment
There was a problem hiding this comment.
Round 3 looks good on the main point: the round-2 major is fixed — POSTGRES now carries socketTimeout as readProperties[0], set before enableSSL, in seconds, and lifted after login. I re-checked the connectProperty → String[] connectProperties refactor and the index/unit/range arithmetic holds for all four dialects.
Two things I'd want in before this merges, plus some minors. Everything below was measured against the pinned driver jars, not read off the docs.
The password reaches the log in cleartext (blocker)
safeUrl() drops only the first userinfo and assumes it ends before the first /. Both assumptions break on URL shapes these drivers accept. Measured with a verbatim copy of safeUrl / stripCredentials / endOfCredentials over 19 shapes:
jdbc:mysql://u:p@h1:3306,u2:SECOND_PW@h2:3306/db
-> jdbc:mysql://h1:3306,u2:SECOND_PW@h2:3306/db second host's password kept
jdbc:mysql:replication://master:PW1@h1:3306,slave:PW2@h2:3306/db
-> jdbc:mysql:@h1:3306,slave:PW2@h2:3306/db second host's password kept
jdbc:mysql://address=(host=h)(port=3306)(user=u)(password=SECRET)/db
-> unchanged full password
jdbc:mysql://(host=h,port=3306,user=u,password=SECRET)/db
-> unchanged full password
jdbc:mysql://u:pa/ss@h:3306/db
-> unchanged full userinfo ('/' in the password)
It is reached from logger.warn in warnStall (opendj-server-legacy/src/main/java/org/opends/server/backends/jdbc/CachedConnection.java:561) and from the SQLTimeoutException message at :358, so one slow connect writes the production DB password into the server error log and into an exception the operator sees. JDBCStorage.java:143 passes config.getDBDirectory() as the whole connection string, so the URL is the only place credentials live for this backend.
Worth noting on severity: safeUrl() and the warnStall logging are both new in this PR — neither exists at 0b9c0f63f5 — so this is introduced here, not inherited.
Suggested: after the existing shape strip, also redact by value, and drop every remaining userinfo@ rather than just the first:
url = url.replaceAll("(?i)(password|pwd)\\s*=[^,)&;?]*", "$1=***");MySQL properties are matched case-insensitively, but Connector/J matches them case-sensitively (major)
opendj-server-legacy/src/main/java/org/opends/server/backends/jdbc/CachedConnection.java:288:
final boolean exact = this == POSTGRES;I linked against mysql-connector-j-9.2.0 and called PropertyKey.fromValue() directly:
connectTimeout fromValue(exact)=connectTimeout fromValue(lower)=null fromValue(MiXeD)=null
socketTimeout fromValue(exact)=socketTimeout fromValue(lower)=null fromValue(MiXeD)=null
user fromValue(exact)=user fromValue(lower)=user fromValue(MiXeD)=user
So db-directory = jdbc:mysql://db:3306/opendj?...&SocketTimeout=2000 gets no read bound from either side: our matcher lowercases and decides the administrator declared it, and Connector/J ignores the mis-cased key. A host that completes the handshake and then goes silent parks the borrower — the hang #872 is about.
The comment at :283-286 cites PropertyKey.fromValue as the reason for the opposite behaviour, so it needs correcting too. MICROSOFT (getNormalizedPropertyName → equalsIgnoreCase) and ORACLE (EZConnectResolver lowercases) really are case-insensitive and should stay in the lowercasing branch.
final boolean exact = this == POSTGRES || this == MYSQL;An Oracle read bound set with -D is invisible here, and this PR now wipes it (major)
declaredInUrl() searches only the connection string, but oracle.jdbc.ReadTimeout is also honoured as a JVM system property. Probed against a listener that completes the TCP handshake and then never speaks, oracle.net.CONNECT_TIMEOUT pinned at 60s so it cannot be what ends the wait (ojdbc8 23.7.0.25.01):
no bound anywhere still blocked at 25000 ms
-Doracle.jdbc.ReadTimeout=2000 ORA-17002 at 2502 ms, socketOptions {3=2000}
-D...=20000 + Properties oracle.jdbc.ReadTimeout=2000 ORA-17002 at 2501 ms, socketOptions {3=2000}
Row 2 shows the channel is real and declaredInUrl() cannot see it. Row 3 shows our Properties value silently outranks the operator's. Then relaxReadBound() calls setNetworkTimeout(con, 0) — PhysicalConnection.setNetworkTimeout rejects only negatives, so 0 reaches T4CConnection.doSetNetworkTimeout(0) → Communication.setSocketReadTimeout(0), i.e. SO_TIMEOUT infinite.
At base the class never called setNetworkTimeout itself (only the delegating override at :366), so an operator's -Doracle.jdbc.ReadTimeout=30000 used to survive for the life of the connection. It no longer does — this is a regression, not a pre-existing gap.
The comment at :487-488 ("A read bound the connection string sets itself is never touched here") is true as written but too narrow: the connection string is not the only channel. Cheapest fix is to consult System.getProperty() for the dotted names in readProperties inside declaredInUrl().
socketTimeout=0 is accepted as a bound (minor)
containsParameter() returns true as soon as it sees <delim>name=; it never reads the value. Every one of these drivers defines 0 as "block forever", so ?socketTimeout=0 is treated exactly like ?socketTimeout=5000 and bound() declines to set a read bound. Measured:
jdbc:postgresql://h:5432/db?socketTimeout=0 readBoundSet=false, but loginTimeout=30 IS still set
jdbc:mysql://h:3306/db?socketTimeout=0 no read bound
jdbc:sqlserver://h:1433;socketTimeout=0 no read bound
The postgres row is the bad one: loginTimeout alone makes pgjdbc hand the login to Driver$ConnectThread, and on expiry getResult() sets abandoned = true and throws 08001 while that daemon thread stays parked in a read with no timeout — one leaked thread plus one ESTABLISHED socket per borrow, which is the failure the class javadoc says this exists to prevent.
Suggestion: after matching name=, parse the digits and treat 0 as "not declared".
connect.timeout=0 escapes the int clamp and breaks every SQL Server connect (minor)
getConnection() clamps connect.timeout to Integer.MAX_VALUE / 1000 at :328-330, but when it is 0, attemptSeconds() returns remainingSeconds instead (:382-383), derived from pool.timeout — which getNonNegativeProperty() accepts up to Long.MAX_VALUE with no clamp (:107-121, :331). Measured on the pinned mssql-jdbc-13.4.0.jre11:
pool.timeout=60 socketTimeout=60000 normal "connection refused"
pool.timeout=2147483 socketTimeout=2147483000 normal "connection refused"
pool.timeout=3000000 socketTimeout=3000000000 "The socketTimeout 3000000000 is not valid."
The boundary is exactly the clamp the other path already applies. With those two properties set, a SQL Server backend cannot open a single connection, and the error names a property nobody typed. pgjdbc 42.7.12, mysql 9.2.0 and ojdbc8 23.7 all tolerate the value — mssql is the only one affected.
return Math.max(1, Math.min(connectTimeoutSeconds == 0
? remainingSeconds : Math.min(connectTimeoutSeconds, remainingSeconds),
Integer.MAX_VALUE / 1000));Nits
RECV_TIMEOUTis not a name ojdbc8 reads:unzip -p ojdbc8-23.7.0.25.01.jar | strings | grep -cgivesRECV_TIMEOUT0,oracle.net.READ_TIMEOUT6,oracle.jdbc.ReadTimeout5. It is asqlnet.ora/listener-side parameter. A TNS descriptor containing it makesdeclaredInUrl()true and silently drops our read bound, so an administrator who wrote a timeout ends up with less protection than one who wrote nothing. Suggest dropping it from theORACLEreadPropertiesat:163and fixing the comment at:159-162.isUsable()catches onlySQLException: at:420-424, aroundcon.isValid(...).boundValidation(:453) andsetNetworkTimeout(:499) both catchSQLException | RuntimeException. An unchecked throw unwinds throughpoll()— called at:339, outside everytryingetConnection— and the connection already dequeued at:397/:406never reachescloseQuietlyat:402. No driver I checked actually does this, so it is hygiene, but it is the odd one out in its own file.openConnectionImplis the wrong pointer: the comment at:140sends the reader there, but in 42.7.12 bothPGStream.setNetworkTimeoutcalls that readPGProperty.SOCKET_TIMEOUTare in the privatetryConnect(javap offsets 141 and 410,SOCKET_TIMEOUTloaded at 119). The behaviour described is right; the method is not.connectTimeoutis one shared budget, not one per host::141-145says a multi-host URL costs "a connect and a login of its own" per host.openConnectionImplreadsSystem.nanoTime()once at offset 24 — before it obtains the host iterator at offset 99 — and passes that same instant into everytryConnect. The login half of the claim stands; the connect half does not. The conclusion (keeploginTimeout, do not rely on it alone) still holds on the daemon-thread argument in the same comment.POOL_TIMEOUT_PROPERTYjavadoc overstates the bound::49says it bounds a whole borrow, butpoll()checks the deadline at:403, belowisUsable()at:399, so a connection dequeued 1 ms before the deadline still gets a full 5 s validation past it — andattemptSeconds()then floors the last connect attempt at 1 s. A 60 spool.timeoutcan return at ~66 s. The ordering is deliberate and defended at:391-394; it is the one-line description that needs softening.
…rest of what the review found open
safeUrl() took the credentials off the first host of a url and assumed they end
at the first "/", and the stall report of a database that takes no connection
carried whatever was left into the server log. Both assumptions break on shapes
Connector/J accepts: a failover or replication url gives every host credentials
of its own ("//u:p@h1:3306,u2:p2@h2:3306"), and its key-value host syntax holds
them inside the authority itself ("//address=(host=h)(user=u)(password=p)"),
where neither a userinfo nor a parameter stands - so the password of the second
host, or the whole one of a key-value url, reached logger.warn and the message
of the SQLTimeoutException. Every userinfo of an authority is taken off now, a
"password=" left standing anywhere is blanked out, and a url that none of this
took apart is not logged past its subprotocol: the host of a stall report is
worth less than a password in the server log. Both safeUrl() and the warning
belong to this branch, so nothing of this reached a release.
Also from the review, each one measured against the driver it is about:
- Connector/J looks its properties up by their exact name, exactly as pgjdbc
does - PropertyKey.fromValue("SocketTimeout") answers null, and the driver
then reads no bound out of the url either. Taken for a bound of the
administrator, a mis-cased parameter left a mysql backend with no read bound
at all, which is the hang OpenIdentityPlatform#872 is about;
- a dotted property of the oracle driver is read out of the system properties as
well, the way a whole jvm is bounded with -Doracle.jdbc.ReadTimeout: against a
listener that completes the handshake and never speaks, -D alone gives up at
2.5 s and a Properties value of ours on top of it takes the timing over. That
bound was then lifted after the login as if it were ours, leaving a connection
with no read bound where the administrator had set one - so the system
properties are looked up as well now;
- RECV_TIMEOUT is a parameter of sqlnet.ora and of the listener that ojdbc8
never reads - the name appears in none of its classes - so a descriptor
carrying one took our read bound off a connection that had none of its own,
leaving an administrator who wrote a timeout with less than one who wrote
nothing;
- a property set to 0 is not a bound of the administrator either: every one of
these drivers reads 0 as "wait as long as it takes". On postgresql a
"?socketTimeout=0" was worse than no bound at all - loginTimeout alone hands
the login to the daemon thread pgjdbc abandons at the timeout, and an
unbounded read leaves it parked there with the socket it holds;
- the bound handed to a driver stays inside the range an int of milliseconds
takes: with ...jdbc.connect.timeout at 0 an attempt takes what is left of the
deadline, ...jdbc.pool.timeout has no upper bound of its own, and mssql-jdbc
rejects a socketTimeout past Integer.MAX_VALUE outright ("The socketTimeout
3000000000 is not valid"), failing every connect of that backend with the name
of a property nobody typed;
- the validation of a pooled connection catches an unchecked failure of a driver
as well: it would unwind through poll(), which stands outside every try of the
borrow, and leave the connection dequeued and closed by nobody.
And three comments that described the right behaviour after the wrong code: the
SO_TIMEOUT of a pgjdbc login is put on in tryConnect rather than in
openConnectionImpl; the connect of a multi-host url is one budget for all of its
hosts, taken from the single System.nanoTime() in front of the loop over them,
rather than one per host; and ...jdbc.pool.timeout bounds a borrow, but not to
the millisecond - the connection in hand is validated whatever the deadline says
and an attempt is never given less than a second.
CachedConnectionTestCase is at 32 tests, still without a database and ~20 s.
Each of the fixes above was put back one at a time, and the assertion that
covers it failed.
|
Thanks — all eight stand, and I re-measured every one of them against the pinned jars rather than taking the report on trust. Fixed in 625e2f2; the description is updated to match. The password reaches the log in cleartext (blocker) — fixedReproduced with a verbatim copy of Four of the five leak and are real urls. The fifth is worth a correction:
I took the suggestion one step further, because a denylist over url shapes is what failed here in the first place: a url that none of this took apart is not logged past its subprotocol. An And you are right that both MySQL properties are matched case-insensitively (major) — fixedConfirmed end to end rather than at So a mis-cased parameter bounds nothing on either side. An Oracle read bound set with -D (major) — fixedReproduced against a listener that completes the handshake and never speaks, Row 3 is the one that matters: our value takes the timing over, and One extension beyond the report: I applied it to the connect property as well.
|
maximthomas
left a comment
There was a problem hiding this comment.
Seven of the eight fixes land as described — safeUrl() itself is now correct over every shape from the last round, exact = POSTGRES || MYSQL, the int clamp, RECV_TIMEOUT, the widened catch and the four comment corrections all check out. Four things still stand, one of them the same leak as last round through a path the redaction does not cover. Everything below was measured against the pinned jars at 625e2f23.
The password still reaches the log in cleartext (blocker)
safeUrl() guards exactly two call sites, CachedConnection.java:412 and :621. Every other exit carries the raw string. With the driver jar absent the JDK itself throws:
// java.sql.DriverManager
throw new SQLException("No suitable driver found for " + url, "08001");getErrorCode() is 0, and isWorthRetrying() (:582-604) matches only SQLState 53300/57P03 or a dialect vendor code — none of them 0. So :408 rethrows it as it stands:
if (!isWorthRetrying(e, dialect)) {
throw e; // message still holds jdbc:oracle:thin:scott/S3cret@//h:1521/svc
}and :414 concatenates the cause's message into the one that is redacted:
... + " moment and none was returned to the pool, last error: " + e.getMessage(), e);It does not stop at traceException. JDBCStorage.open():150 → RootContainer.open():134 (StorageRuntimeException, message = cause.toString()) → BackendImpl.newRootContainer():994 (ERR_OPEN_ENV_FAIL.get(e.getMessage())) → BackendConfigManager.java:1051 (stackTraceToSingleLineString into the ConfigChangeResult) → BackendConfigManager.java:263:
for (LocalizableMessage msg : ccr.getMessages()) { logger.error(msg); }ERROR in the server error log, and the same string back over LDAP on a config change. ojdbc is not redistributable, so a missing driver jar is the ordinary Oracle misconfiguration — and testMissingDriverIsReportedAtOnce drives exactly this path. It is new here: at 0b9c0f63f5 every SQLException was swallowed by the doubling recursion, so none escaped.
Redact at the boundary rather than at two chosen call sites: wrap the rethrow at :408 in a SQLException carrying safeUrl(connectionString) and the original SQLState/errorCode (keeping the cause attached for traceException), and put the cause's message through the same redactor before concatenating it at :414.
-Doracle.net.READ_TIMEOUT switches off the read bound (major)
CachedConnection.java:305 treats a dotted name as one the driver reads as a system property. ORACLE's readProperties (:178) is {"oracle.jdbc.ReadTimeout", "oracle.net.READ_TIMEOUT"}; the second one is not such a name. Of the six classes in ojdbc8-23.7.0.25.01 carrying the literal (MQLNTAdapter, ConnStrategy, TcpNTAdapter, SdpNTAdapter, SQLnetDef, T4CConnection), none passes it to System.getProperty — the only arguments there are line.separator, socksProxyHost/Port, oracle.jdbc.disablePipeline, mql.Context. T4CConnection@495 only writes the key into the net properties, from thinReadTimeout, itself resolved from oracle.jdbc.ReadTimeout.
So an operator who exports it gets declared() true, :259 never runs, bound() returns false, and connect():524 goes out with only oracle.net.CONNECT_TIMEOUT set. Against a socket that accepts and never speaks:
Properties{oracle.jdbc.ReadTimeout=3000} -> fails at 3007 ms
empty + -Doracle.net.READ_TIMEOUT=3000 -> still blocked at 25 s (killed)
CONNECT_TIMEOUT covers the TCP connect only; the same socket hung past 40 s with it set. There is no DriverManager.setLoginTimeout anywhere, and :524 is synchronous on the borrowing thread — the deadline is read only before and after it (:395-410), so a thread parked inside getConnection is never abandoned. That is #872 again, through a flag the operator believes is helping.
The rule is right for the other two: oracle.net.CONNECT_TIMEOUT is read as a system property (three tiers in GeneratedPhysicalConnection, offsets 2816-2874, via doPrivileged(System.getProperty) at :723 — measured 21223 ms with no flag, 4230 ms at -D=3000, 10225 ms at -D=9000). Only "contains a dot" is the wrong test; mark per entry which names are system-property channels, and keep oracle.net.READ_TIMEOUT in readProperties, where the driver does honour it.
An explicit PostgreSQL connect budget is silently capped at 30 s (major)
CachedConnection.java:253-257 decides the two connect properties one at a time:
for (final String property : connectProperties) {
if (!declared(connectionString, property)) {
properties.setProperty(property, ...);
}
}while the javadoc at :242-249 promises "an explicit setting of theirs keeps precedence". On pgjdbc these are not independent knobs: connectTimeout bounds the TCP connect, loginTimeout bounds the whole login. Setting either is the administrator declaring their budget.
jdbc:postgresql://h:5432/db?connectTimeout=300, defaults connect.timeout=30, measured through postgresql-42.7.12's own Driver.parseURL:
head 625e2f23 -> connectTimeout=300 socketTimeout=30 loginTimeout=30, timeout(props)=30000
-> ConnectThread created, getResult(30000) abandons the login at 30 s
base 0b9c0f63f5 -> loginTimeout=null, timeout(props)=0 -> no ConnectThread, the 300 s budget ran in full
So the 30 s cap is new, and pool.timeout is not what would have capped it anyway — the deadline is never enforced mid-connect (:399 is a straight synchronous call; it is re-read only in poll():454 and in the catch at :410).
Treat a dialect's connect properties as one group: if the administrator declared any of them, inject none. CachedConnectionTestCase.java:504-507 currently asserts the opposite and would move with the code.
The "a zero is nobody's bound" fix does nothing on PostgreSQL (major)
The reasoning is right and the implementation does what it says — but pgjdbc copies supplied Properties into a flat Properties and then runs parseURL over it, so the URL wins. For jdbc:postgresql://h:5432/db?connectTimeout=0&socketTimeout=0&loginTimeout=0, isBound("0") is false, bound() writes 30/30/30 and returns true, setting readBoundSet = true at :522. Measured through Driver.parseURL with exactly those properties:
effective connectTimeout=0 socketTimeout=0 loginTimeout=0
Driver.timeout(props)=0 -> no ConnectThread
makeConnection then runs on the borrowing thread itself: socket.connect with no timeout, login reads with no SO_TIMEOUT. The borrow hangs and nothing can abandon it, while the class believes it bounded the login and queues relaxReadBound() behind a call that will not return.
Two corrections to keep this in proportion: it is not a regression — at e77c8f7267 containsParameter had no value check, nothing was written, and pgjdbc saw 0/0/0 just the same. And there is no leaked daemon thread or ESTABLISHED socket per borrow here, because timeout()=0 means no ConnectThread exists; the caller simply hangs.
On POSTGRES a zero the administrator wrote has to be removed from the URL, not merely overridden in the properties — or the dialect has to declare that its URL outranks supplied properties and not claim readBoundSet when it does. The new test asserts bound() returned true and that the map holds "7", which is why this survived a round of re-measurement; asserting the driver's effective value via Driver.parseURL would have caught it.
The redaction is pinned by no test (minor)
safeUrl() has two call sites in main, :412 and :621. testLoggedConnectionStringCarriesNoCredentials calls the package-private static directly, 15 times, never through a borrow. The only test reaching :412 uses jdbc:opendj-stub:deadline, which has no credentials; :621 is asserted by nothing — there is no log capture in the file at all. Replacing safeUrl(connectionString) with connectionString at either site leaves the class green.
A driver outside the four gets no bound at all (minor)
ConnectDialect.of() (:231-239) matches only the four shipped prefixes. For anything else connect() takes the false arm of the dialect != null guard:
DriverManager.getConnection(connectionString, new Properties()); // :524, empty mapNo connect, login or socket property, and the deadline is unreachable mid-connect. An admin-added jdbc:mariadb: or jdbc:h2: reproduces #872 verbatim, silently. One WARN per connection string naming the four supported prefixes would be enough.
A borrow that exhausted the whole deadline is retried as a failure of the moment (minor)
:412-414 builds the SQLTimeoutException with the (String, Throwable) constructor, so SQLState is null and vendorCode 0, and JDBCStorage.java:626-633 maps e instanceof SQLTimeoutException to FailureScope.MOMENT. A borrow that already spent the full pool.timeout is then retried, each attempt costing another one. Passing "08001" (or the cause's SQLState) explicitly would also stop monitoring keyed on the top-level SQLState from seeing null where base surfaced the driver's own exception.
boundValidation() cannot tell "left it alone" from "it failed" (minor)
:507-515 returns -1 for both. If a driver applies setNetworkTimeout(DIRECT_EXECUTOR, 5000) and then throws before :513, isUsable():492 reads restore >= 0 as "nothing to put back", isValid(5) succeeds, :494 returns true, and close():787 puts the connection back in the pool — permanently carrying a 5 s network timeout, so every statement over 5 s on it fails. The only closeQuietly (:459) is reached solely when isUsable is false. Latent; it needs an apply-then-throw driver, which none of the four pinned ones is known to be. A distinct sentinel from the catch would close it.
Nits
- The read-bound WARN names the wrong property:
:566-569citesCONNECT_TIMEOUT_PROPERTYand warns that "statements taking longer ... may fail", but on theisUsable()restore path the bound in force isVALIDATION_TIMEOUT_SECONDS(5 s),millisis the restore value (usually 0, so it reads "could not be set to 0 ms"), andpoll()closes the connection one line later. - The invalid-value WARN is unthrottled:
getNonNegativeProperty(:118-132) is called twice per borrow from:382-385and its warn at:128has no guard, whilewarnStall(:618) and the read-bound warning (:565) both useSTALL_WARNING_INTERVAL_MS. A typo'dconnect.timeout=30sputs two WARN lines in the log per backend operation. safeUrl()over-redacts:schemestops at the first sub-protocol token, sojdbc:oracle:thin:user/pw@//h:1521/svclogs asjdbc:oracle:@//h:1521/svc— thin-vs-oci is a first question in an Oracle connect diagnosis. And the whole parameter section is dropped, sojdbc:sqlserver://h:1433;databaseName=db;...logs asjdbc:sqlserver://h:1433: two backends on one host produce byte-identical stall lines, though the throttle map at:616is still keyed on the full string so both do warn.attemptSeconds()'s javadoc promises a clamp it does not apply: thedeadline == Long.MAX_VALUEbranch (:434-442) returnsconnectTimeoutSecondsunclamped —attemptSeconds(Long.MAX_VALUE, Long.MAX_VALUE)isLong.MAX_VALUE. The clamp lives at the single caller (:382-384), and the method was widened to package-private this round.withoutUserinfo()drops a separator:hosts.length() > 0as the "not first" test meansjdbc:mysql://,h2:3306/dblogs asjdbc:mysql://h2:3306/db. Cosmetic, no credential impact.- The new container test has no
timeOut:TestCase.java:149, unlike all 32 tests in the sibling file. What it guards against is an unbounded login, so a regression hangs the job instead of failing the test. TestCase.java:157passes against the pre-fix code:assertEquals(con.getNetworkTimeout(), 0, "the read bound of the login is still in force")— no bound was ever set before this PR, so it was already 0; and on the PostgreSQL subclass the login read bound is thesocketTimeoutconnect property, neversetNetworkTimeout, so it cannot fail there. Asserting the bound before the lift, or thatrelaxReadBound()returned true, would fix both.testDrainOfThePoolStopsAtTheDeadlinehas no lower bound:assertTrue(validated.get() < pooled)(CachedConnectionTestCase.java:382) also passes ifpoll()drained nothing at all.validated.get() > 0 && validated.get() < pooled.testTheBoundHandedToADriverStaysInTheRangeAnIntTakesraces an ephemeral port: it disables every bound (connect.timeout=0,pool.timeout=3000000) against a port bound and then closed; if anything on the host takes it in between, only the 120 stimeOutis left. A blackhole socket would be deterministic.testTheLoginThreadOfPostgresDoesNotOutliveTheBorrowcounts JVM-global threads: three sibling tests also open pgjdbc logins against blackhole sockets, so a leak from any of them is attributed here after a 62 s wait, and TestNG method order is not contractual. Capture a delta at method start.
…nd bound what the review found unbounded The password reached the server log through every exit but the two that called safeUrl(). The jdk builds "No suitable driver found for " + url - the ordinary oracle misconfiguration, a driver jar left out of lib/extensions - JDBCStorage .open() hands it to RootContainer, which makes the message of the cause its own, and BackendConfigManager logs that at ERROR and answers a config change with it. What leaves this class is redacted whole now: the message of every link of the chain, the chain rebuilt rather than wrapped, since everything that prints a failure prints its causes along with it. Three bounds that were not bounds: - -Doracle.net.READ_TIMEOUT was taken for a bound of the administrator, but ojdbc8 reads that name out of the connection properties alone - the classes carrying the literal hand it to Properties.get, none of them to System .getProperty. The names a driver does read out of the system properties are listed now instead of told from the dot in them, so a -D of it no longer leaves the login with no read bound at all. - the connect properties of a dialect are one budget rather than independent knobs: filling in the one the administrator left out capped the one they set, and a postgresql "?connectTimeout=300" answered with a loginTimeout of ours was a login pgjdbc gave up on at 30 s. - a parameter of a postgresql url outranks the property supplied to the driver, so a "socketTimeout=0" there cannot be replaced. It is reported now rather than written over in a map the driver goes on to ignore. Also: 08001 on the timeout of a borrow, a report for a connection string whose driver is not one of the four this class knows the properties of, a validation that could not be bounded discarded rather than run unbounded, and the messages, the throttles and the ranges the review listed. CachedConnectionTestCase is at 41 (from 32), still without a database, ~23 s. Each fix was put back one at a time and the assertion covering it failed. The four container suites pass 54/54, and testLoginBoundDoesNotOutliveTheLogin now asserts the read bound is in force before asserting it is lifted - against a relaxReadBound() that lifts nothing it fails with "expected [0] but found [2000]", where before it passed either way.
|
Thanks — the blocker and the two majors stand, and I re-measured each of them against the pinned jars rather than taking the report on trust. Fixed in 52ca42b; the description is updated to match. One minor I did not take, with the measurement below. The password still reaches the log in cleartext (blocker) — fixedConfirmed end to end, including the part that makes it an ERROR line rather than a trace: Which is also why I did not take the shape you proposed as written. Wrapping while "keeping the cause attached for
The redactor takes the url down to Two tests, and neither calls the redactor from the side:
|
…nks it rebuilds, not by its depth CodeQL flagged the pair of redactedCopy() overloads (java/confusing-method- signature): SQLException and Throwable differ by a type one converts into, so which of the two a call reaches is settled by the static type of its argument, not by what that argument holds. Every call site reaches the right one - the Throwable one looks its argument over and hands an SQLException back to the other - but that is a thing a reader has to re-derive at every call. The Throwable one is redactedLink() now, and nothing dispatches on a static type. The bound of the rebuild was the second thing wrong with it. A link of a chain carries a cause and a next exception both, and a driver is free to make the two the same failure; bounded by depth alone, the copy forks into two copies of the same tail at every step - 2^32 links for a chain reaching MAX_CHAIN_LENGTH. A report of a connect that cannot be made, ending in OutOfMemoryError, is the hang of OpenIdentityPlatform#872 over again in the code written to report it: on a 64-link chain of those the redaction as it stood dies of heap in 19 s. What bounds it now is the number of links it rebuilds, the way holdsCredentials() already counts the ones it visits. CachedConnectionTestCase is at 42 (from 41), still without a database, ~24 s.
Problem
CachedConnection.getConnection()— the pool every JDBC-backend operation borrows from — established connections with no bound of its own, and gave up on none of them:Two shapes of the same symptom — "the operation never returns":
lib/extensions—SQLException: No suitable driver found): every one of those was treated as "the server is at max_connections" and retried recursively, the wait doubling from 1 ms. One cycle of that sums to 2³¹ ms ≈ 24.9 days before theintoverflows and the doubling starts over, with nothing logged on the way — indistinguishable from a hang from the outside.isValid(0)on a pooled connection was unbounded as well:0means "no timeout" in the JDBC contract, so validating a connection whose socket is half-open blocks just as long.Every backend operation borrows through this path —
openTree()during a backend open (RootContainer.open()runs on the thread that starts the server) and duringdsconfig create-backend-indexon a running server, every search and modify, and the import. The only workaround was putting driver timeouts into thedb-directoryURL by hand, as the reporter of #529 had done — undocumented, per-deployment, and not available on the Oracle thin URL at all.Change
One connect attempt is bounded, per dialect. The dialect is recognized by the prefix of the connection string — there is no connection yet to ask the driver class of, which is what
JDBCStoragedoes elsewhere — and its properties are handed toDriverManager.getConnection(url, properties):connectTimeout(s),loginTimeout(s)socketTimeout(s)connectTimeout(ms)socketTimeout(ms)oracle.net.CONNECT_TIMEOUT(ms)oracle.jdbc.ReadTimeout(ms)loginTimeout(s)socketTimeout(ms)Bounded through
org.openidentityplatform.opendj.jdbc.connect.timeout(seconds, 30 by default,0for no bound), in the style of the…jdbc.ttl/…jdbc.fetchsizeproperties this backend already has.DriverManager.setLoginTimeout()is deliberately not used: it is JVM-global. A driver with a range of its own for its connect property is never handed a value beyond it —SQLServerDriverIntProperty.LOGIN_TIMEOUTis validated against[0, 65535], so a larger bound would not widen the connect, it would fail every one of them.A property the administrator set keeps precedence — it is not passed at all, so the
loginTimeout=30&socketTimeout=300of #529 still governs. The connect side of a dialect is one budget rather than a set of independent knobs, so a bound of theirs under any of its names leaves all of them alone: on PostgreSQLconnectTimeoutbounds the socket connect andloginTimeoutthe login behind it, and filling in the one they left open caps the one they set — a?connectTimeout=300answered with aloginTimeoutof ours is a login pgjdbc gives up on at 30 s, sinceDriver.connectbranches into a thread of its own as soon asloginTimeoutis anything but0. The read bound is a budget of its own and is still set where they left it open. Recognizing it means allowing for the parameter syntax of each dialect:?a=1&b=2(PostgreSQL, MySQL),;a=1;b=2(SQL Server — whose driver gives a supplied property precedence over the URL, so this matters), and(CONNECT_TIMEOUT=…)inside an Oracle TNS descriptor, where the property also goes by the last segment of its name alone. It is recognized the way its own driver recognizes it: pgjdbc and Connector/J look their properties up by their exact name —PropertyKey.fromValue("SocketTimeout")answersnull, and Connector/J then reads no bound out of the URL either — so a parameter of another case is a parameter of nobody and must not pass for a bound of the administrator, while the SQL Server driver (getNormalizedPropertyName) and the keywords of an Oracle descriptor match either way. The read bound of an Oracle descriptor goes by the two names ojdbc8 reads,oracle.jdbc.ReadTimeoutandoracle.net.READ_TIMEOUT;RECV_TIMEOUTis a parameter ofsqlnet.oraand of the listener, and the name appears in none of the driver's classes, so a descriptor carrying one is not a read bound of the connection and must not take ours off it.The connection string is not the only channel of the administrator. Some properties of the Oracle driver are read out of the system properties as well —
-Doracle.jdbc.ReadTimeout=30000is how a whole JVM is bounded — and a property supplied to the driver outranks that one without a word, so those names are looked up there too. Which names those are is listed rather than told from the shape of them:GeneratedPhysicalConnectionresolvesoracle.jdbc.ReadTimeoutandoracle.net.CONNECT_TIMEOUTin three tiers — the properties supplied to the driver, thenSystem.getProperty, then the properties of the data source — whileoracle.net.READ_TIMEOUT, a dotted name of the same driver and the one the socket option is finally read under, reaches the socket from the connection properties alone: the classes carrying that literal hand it toProperties.get, none of them toSystem.getProperty. Taken for a bound of the administrator, a-Dof it would leave the login with no read bound whatever — theirs not read by the driver, ours not set because we believed theirs was in force. Measured against a listener that completes the handshake and then never speaks, withoracle.net.CONNECT_TIMEOUTpinned at 60 s so it cannot be what ends the wait: no bound anywhere blocks past 20 s,-Doracle.jdbc.ReadTimeout=2000gives up at 2.5 s, and aPropertiesvalue of 2000 on top of-D20000 takes the timing over — which is the bound that would then be lifted after the login as if it were ours, leaving a connection with no read bound where the administrator had set one. A property set to0is not a bound either: every one of these drivers reads0as "wait as long as it takes", so it counts as unset rather than as a setting to stay out of the way of, and one of ours goes on top of it — wherever a supplied property outranks the URL. On PostgreSQL it does not:Driver.connectcopies what it was handed into a flat map andparseURLthen writes the parameters of the URL on top of it, so a?socketTimeout=0there is the value the driver uses whatever this class supplies. Measured through the driver's own parser,?connectTimeout=0&socketTimeout=0&loginTimeout=0comes out0/0/0with a full set of ours in hand,Driver.timeout(props)at0and the login running unbounded on the borrowing thread. So on that dialect a parameter of the URL counts as the administrator's whatever its value, and a zero is reported — once per connection string, naming the parameter and the value — rather than written over in a map the driver goes on to ignore: a bound this class believes it has set is worse than one it knows it has not.Not one of the four drivers bounds the attempt with a single property. The first covers the socket connect; the reads behind it — the prelogin handshake, TLS, authentication, which is exactly the phase left unanswered by a proxy at its limit — need the second. That includes the SQL Server driver, contrary to what its
loginTimeoutsuggests: the test below caught it parked inSQLServerConnection.prelogin()for the full 600 s of the run despiteloginTimeout=2, which is whysocketTimeoutis set there too. And it includes pgjdbc, whoseloginTimeoutis not a bound of the socket at all:ConnectionFactoryImpl.tryConnectputs an SO_TIMEOUT on the login socket only underif (socketTimeout > 0)— both before and afterenableSSL— andsocketTimeoutdefaults to0. WhatloginTimeoutbounds there is the caller, out of process:Driver.connectruns the login on a daemon thread of its own andDriver$ConnectThread.getResultgives up on the thread rather than on the login, leaving it parked in the read. Without a read bound a borrow against a peer that answers nothing returns on time and leaves that thread — and the ESTABLISHED socket it holds — behind, sosocketTimeoutis set on PostgreSQL as well, withloginTimeoutkept on top of it for a URL naming more than one host, where each host costs a login of its own — the connect is one budget for all of them, taken from the singleSystem.nanoTime()in front of the loop over the hosts. TheJDBCStorage.Dialecttable of #866 declares the same three for its stamp connection.That second property is a socket read timeout for the life of the connection on every one of the four, so it is lifted with
setNetworkTimeout(…, 0)once the login is through — left in place it would fail every statement slower than it, an import batch or thedbms_statspass of #866 among them. The two setup round trips (setAutoCommit,setTransactionIsolation) still run under it. A read bound the connection string sets itself is never lifted, because it is never set here — that is what the three names above are for. A connection whose bound cannot be lifted at all serves the borrower waiting for it and is closed rather than pooled: in the pool it would carry that bound into every borrow it was handed to.A database that takes no connection for the moment is retried, under a deadline. Two states qualify, and only these two:
53300 too_many_connectionsplus the vendor codes of the dialect — MySQL 1040/1203, Oracle ORA-00020 and 12516/12518/12519/12520, SQL Server 17809/10928/10929;57P03 cannot_connect_now, Oracle ORA-01033/01034/01089, MySQL 1053, SQL Server 921/922/927 and Azure 40613.JDBCStorage.open()has no second attempt of its own, so without this a backend whose database restarted together with the server — Compose, systemd — would stay locked down until the next restart of the server. ORA-12514 is deliberately not among them: a listener that does not know the service is also what a service name of a typo answers, forever.Both are recognized through the whole chain of the failure, the causes and
getNextException()alike. The rest of theinsufficient_resourcesclass is not retried —53100 disk_fullis not cured by a connection of ours coming back — and neither is anything else: a password that is not accepted, a database that is down, a driver that is not on the classpath is reported to the caller.The wait is bounded by
org.openidentityplatform.opendj.jdbc.pool.timeout(seconds, 60 by default,0for no bound), with the backoff capped at 1 s and a warning — throttled, per connection string, since every operation borrows through here — so the stall reaches the server log. That deadline governs the whole borrow, as its name says: it bounds the connect attempt inside it (an attempt left to run out its own 30 s would overrun a 60 s borrow by half again) and it bounds the drain of the pool, where each connection costs a validation round trip and the pool has no upper bound on the number it holds (#878) — the connection in hand is always validated first, though, since a database at its connection limit has no source of connections other than the ones coming back to the pool. It bounds the attempt even whereorg.openidentityplatform.opendj.jdbc.connect.timeoutis0: turning the per-attempt bound off must not turn the bound of the whole borrow off with it, and both at0is what leaves a connect unbounded. It is not a bound to the millisecond, though: the connection in hand is validated whatever the deadline says, and an attempt is never given less than a second, so a borrow can return one validation and one attempt past it. What it hands a driver stays inside the range an int of milliseconds takes —mssql-jdbcrejects asocketTimeoutpastInteger.MAX_VALUEoutright ("The socketTimeout 3000000000 is not valid"), which withconnect.timeout=0and apool.timeoutof more than 24.9 days would fail every connect of that backend with the name of a property nobody typed.Nothing that leaves this class carries credentials. The logged connection string is stripped of them first, and neither delimiter is looked for in the whole string: on an Oracle URL the credentials stand between the subprotocol and the first
@, which is the delimiter of the descriptor — a password holding an@has to be quoted for the driver itself — and everywhere else they stand inside the authority, which ends at the path rather than at a?. So a password holding the parameter separator of another dialect or of its own (scott/pa;ss@,scott/pa?ss@) is not cut in half and left in the log, while an@inside a parameter value (?user=u@example.com) still leaves the host in the message. Every host of an authority is stripped of credentials of its own, since a URL of Connector/J gives each of them a set (//u:p@h1:3306,u2:p2@h2:3306, andjdbc:mysql:replication://in front of them); apassword=/pwd=left standing anywhere is blanked out, since the key-value host syntax of Connector/J holds one inside the authority itself (//address=(host=h)(user=u)(password=p),//(host=h,user=u,password=p)), where neither a userinfo nor a parameter stands; and a URL that none of this took apart is not logged past its subprotocol — an@left standing where the credentials of an Oracle URL do not end is one this did not recognize, and the host of a stall report is worth less than a password in the server log. What is no credential stays: the token naming the kind of Oracle driver, sincethinagainstociis a first question of an Oracle connect, and the parameter naming the database, since two backends of one SQL Server host answer to the same URL up to theirdatabaseName.That covers a URL this class logs itself. A driver is free to put the connection string it was handed into the message of its own failure, and the JDK itself does —
"No suitable driver found for " + url, which is what a driver jar left out oflib/extensionsarrives as, the ordinary Oracle misconfiguration. That message travels:JDBCStorage.open()hands the failure toRootContainer, whoseStorageRuntimeException(cause)makes the message of the cause its own,BackendImplwraps that intoERR_OPEN_ENV_FAILandBackendConfigManagerlogs it at ERROR and answers a config change with it. So the failure that leaves this class is redacted whole: the connection string replaced by its safe form, the credentials of it blanked wherever a driver quoted a part of them back, and every link of the chain rebuilt that way rather than wrapped — everything that prints a failure prints its causes along with it, so a cause left as it stands would carry the password past the wrapper. A failure naming nothing of the connection string is passed on as it is, with its own type.A driver outside the four is reported. The properties bounding a connect are the properties of a driver, so a connection string this class knows no names for — an admin-added
jdbc:mariadb:, ajdbc:h2:— leaves every attempt unbounded, and the deadline of the borrow cannot reach into a connect already under way, since the driver is the only thing holding the socket. Silently, that is #872 again for a backend nobody thinks of as unbounded, so it is named in the log once along with the prefixes that are bounded. And the timeout of a borrow carries08001now rather than no SQLState at all: it is the failure of a connect that did not happen, and monitoring reading the state off what it caught would otherwise seenullwhere the driver's own exception carried one.Three leaks along the way. A connect whose setup then failed dropped a live connection on the floor and retried — at full speed at first, so a repeated failure could exhaust the database's own connection limit and turn a transient problem into a permanent one; it is closed now, whether the setup failed with a
SQLExceptionor with an unchecked one out of the driver. Andclose(), whoserollback()failed, neither pooled the connection nor closed it; it closes the parent and reports the failure.The validation of a pooled connection is bounded at the socket.
isValid(n)is not that bound on every driver:SQLServerConnection.isValid(int)maps its argument ontosetQueryTimeoutand runsSELECT 1, an attention-based timeout that needs a working channel to fire — and the read bound of the login was lifted the moment the connection was established. So the socket carries the bound, for the length of the validation only, and a read bound of the connection string, being the tighter one, is left alone. A driver that reports the validation as an error discards the connection rather than failing the operation with it, and so does a connection whose bound cannot be put back afterwards. A driver that takes the call bounding the validation and then fails inside it is told apart from one that never takes a network timeout at all: it is free to have applied the bound before failing, so that connection is discarded rather than validated unbounded and handed out — pooled, it would carry five seconds of ours into every statement for the rest of its life. Nothing is put back on a connection that failed the validation: Connector/J answers that by aborting the connection and the SQL Server driver by terminating it, so the restore would fail too and warn about the statements of a connection that is being closed — over an idle connection the server merely reaped.Tests
CachedConnectionTestCase— 41 tests, no database, ~23 s: all four JDBC drivers are compile-scope dependencies, so every dialect is exercised for real and a regression fails the build wherever it runs.testLoginIsBoundedWhenTheDatabaseNeverAnswers— a bound, never-acceptedServerSocket: the kernel completes the handshake, so the connect succeeds and every read of the login hangs. Each dialect is borrowed on a thread of its own, so a driver that does not honour its bound fails the test in seconds instead of hanging the run — which is how the SQL Server prelogin gap surfaced.testTheAttemptIsBoundedByTheDeadlineOfTheBorrow— the same socket with a 600 s connect bound and a 2 s pool timeout: the borrow is over in seconds, not in ten minutes.testRefusedConnectIsReportedAtOnce,testMissingDriverIsReportedAtOnce,testRejectedLoginIsNotRetried,testDiskFullIsNotRetried— the failures that used to be retried forever are reported, after exactly one attempt.testConnectionLimitIsRetried/testConnectionLimitGivesUpAtTheDeadline,testDatabaseOnItsWayUpIsRetried,testTheWholeChainOfTheFailureIsLookedAt— a driver of the test answering with53300and with57P03proves the two cases that still wait, that a wrapped failure is recognized, and that the wait gives up at its deadline rather than 25 days later.testConnectionIsClosedWhenItsSetupFails,testConnectionIsClosedWhenItsSetupFailsWithAnUncheckedError,testConnectionThatCannotBeRolledBackIsClosed,testBrokenPooledConnectionIsDiscarded— the three leaks and the discarded connection.testValidationOfAPooledConnectionIsBoundedAtTheSocket,testValidationLeavesTheBoundOfTheConnectionStringAlone,testDrainOfThePoolStopsAtTheDeadline— the bound around the validation, that a tighter one of the administrator is not widened by it, and that a pool of connections the database no longer answers is not drained past the deadline.testTheLoginThreadOfPostgresDoesNotOutliveTheBorrow— the daemon thread pgjdbc abandons at itsloginTimeout: the borrow is over, and the thread has to be gone with it. Against a PostgreSQL row withoutsocketTimeoutit fails with the thread still alive after the whole window.testTheDeadlineBoundsAnAttemptTheConnectPropertyDoesNot—connect.timeout=0withpool.timeout=2: the borrow is still bounded. Against the previous code this one hangs out the whole run, which is the shape of JDBC backend: the connection pool connects without any timeout and retries a failed connect forever #872 itself.testAPooledConnectionIsNotDiscardedUnvalidatedAtTheDeadline,testAConnectionOnItsWayOutIsNotGivenItsBoundBack,testAConnectionStillCarryingTheBoundOfItsLoginIsNotPooled— the connection the deadline used to close unvalidated, the bound that is not put back on a connection the server reaped, and the connection that must not go into the pool.testBothPhasesOfTheLoginAreBounded,testConnectBoundStaysInTheRangeTheDriverTakes,testConnectionStringKeepsPrecedence,testTheCaseOfAParameterIsTheOneOfItsDriver,testDialectIsRecognizedByTheConnectionString,testLoggedConnectionStringCarriesNoCredentials— the property table, the range the SQL Server driver takes, the precedence of the URL property by property and by case, and that a stall report carries no password: a password holding its own dialect's separator, one of every host of a failover or replication URL, one inside the key-value host syntax, and a URL this cannot take apart at all.testASystemPropertyOfTheAdministratorKeepsPrecedence,testAZeroIsNotABoundOfTheAdministrator,testTheBoundHandedToADriverStaysInTheRangeAnIntTakes,testAPooledConnectionWhoseValidationThrowsIsDiscarded— the bound of-Doracle.jdbc.ReadTimeoutthat is neither overridden nor lifted, the0that is no bound of anybody's, the value no driver would take, and the unchecked failure of a validation that would leave a connection dequeued and unclosed.testAReportedConnectCarriesNoCredentials,testAMessageOfADriverCarriesNoCredentials— the failure of a borrow driven throughgetConnection()with a password in its URL, asserted over every link of the chain and not only the message on top, and the redactor held to the shapes a driver quotes back: the whole URL, the credentials without it, the password alone, and the stall line built apart from the logging of it so that a test can hold it to the same rule.testASystemPropertyNoDriverReadsIsNoBound— a-Doracle.net.READ_TIMEOUTno driver reads must not take the read bound off a login, while the same name written into a descriptor still keeps precedence.testAConnectBudgetOfTheAdministratorIsNotCappedByThisClass,testAParameterOfAPostgresUrlOutranksTheBoundOfThisClass— both read the effective values back throughDriver.parseURLof pgjdbc rather than off the map handed to it, which is the half of the story the bug lived in.testAUrlThisBackendCannotBoundIsReportedOnce,testAReadBoundTurnedOffInAPostgresUrlIsReportedOnce,testAPooledConnectionThatCannotBeBoundedForItsValidationIsDiscarded,testTheBoundOfAnAttemptStaysInRangeWithoutADeadline— the two things that must not happen silently, the connection whose validation could not be bounded, and the clamp of the range where the borrow has no deadline to take it from.TestCase.testLoginBoundDoesNotOutliveTheLoginasserts on every real database that the read bound of the login is in force in the first place — established with the very properties the borrow uses and read back off the socket of that driver, all four at 2000 ms — and only then that it is gone by the time the connection is handed out. Against arelaxReadBound()that lifts nothing it fails withexpected [0] but found [2000], where the assertion on its own passed either way.Every one of the new tests was run against the code it fixes and fails there — each fix was put back one at a time, and the assertion that covers it failed:
All four container suites pass with no skips, re-run against this head: PgSql 54/54, MySql 54/54, Oracle 54/54, MsSql 54/54, plus the JDBC
EncryptedTestCase34/34,JDBCStorageRetryTest26/26 andStampConnectionTestCase5/5 — on top of the 41 that need no database.Out of scope
Left for their own issues, so this one stays reviewable: #877 (no statement gets a
setQueryTimeout, so a query that hangs after a successful connect still parks its worker — the validation of a pooled connection is bounded here, the statements of an operation are not), #878 (the pool has no upper bound on its size and its TTL sits on the URL key rather than on each connection, so a burst of connections survives as long as the backend sees any traffic at all) and #879 (a pooled connection is validated on every borrow, at the cost of a database round trip per operation).#875 reports the same retry loop, filed separately while reviewing #867, so this closes both.
Merged up to master. #866 touches the same method — it added a
conNew.close()to the old recursivegetConnection— and the conflict is resolved in favour of this branch, which removes that method: the leak that patch closed is closed here bycatch (SQLException | RuntimeException e) { closeQuietly(conNew); throw e; }, for an unchecked failure out of the driver as well.Fixes #872
Fixes #875