[#885] Give a connection of the JDBC pool a read bound of its own, and take it off for a statement that carries none - #934
Conversation
…bound of its own, and take it off for a statement that carries none The bound of jdbc.connect.timeout covers the connect and the login and is taken off as soon as the login is through; the socket read timeout behind a cancelled statement is armed for the length of that statement alone. Between the two, a commit, a rollback, a lookup of the catalog and the rows a cursor drains are read from a socket with no deadline of any kind, so an operation that meets a database which stops answering after the login stays parked with nothing able to reach it. jdbc.read.timeout is what a deployment asks for one with. It is set on the connection once the login is through, in the same call that takes the read bound of the login off, and it defaults to 0 - the behaviour of every connection this pool established before it existed. The default is a consequence rather than caution: a bound standing on the connection has to exceed the longest silence the database may legitimately produce, and the class those statements belong to ships unbounded. So the statements that legitimately take longer run with it taken off: the backstop of JDBCStorage lifts it for as long as a statement of an unbounded class runs, and puts it back when the last of them is through. It lifts only what this backend set - a read timeout standing in the connection string is the deployment's own, and it is neither replaced at the login nor lifted here. What the connection carried is read once and remembered across the lift; read again while the lift holds, it would be the zero of that lift, and the bound would go back to the pool gone for the rest of the connection's life.
5edae4d to
7b26223
Compare
vharseko
left a comment
There was a problem hiding this comment.
The mechanism reads well and the lift is covered by the tests, but a few things below need changing before this goes in. Line numbers are of the head of this branch.
Blocking
1. JDBCStorage.java:136 — the standing bound is resolved against config.getDBDirectory() rather than poolKey()
poolKey() exists precisely because a db-directory changed on a running backend must not send one path to another pool, and its javadoc says so: "Every path that names a pool goes through here." This one does not.
open() registers jdbc:mysql://db1/x (no read parameter), so every pooled connection carries the 90 s standing bound. db-directory is then changed to jdbc:mysql://db2/x?socketTimeout=600; applyConfigurationChange resets the memo, line 136 reads the new url, bounds() is true and the answer is 0. getConnection() still borrows from the db1 pool, whose connections still carry 90 s — but the lift gate at line 627 is now false, so a BULK statement dies on the socket at 90 s, which is what bulk.timeout=0 promises it will not. The reverse pairing (registered url declares socketTimeout=600, the new one does not) makes the gate true and lifts a bound that is the deployment's own.
2. JDBCStorage.java:627 — the "two bounds the wrong way round" warning is never evaluated at open
Line 627 is the only production call site of standingReadBoundMillis(), and it sits behind state.unbounded > 0. A read-only backend — searches and reads, no import, no clearTree, no create index — runs no statement of an unbounded class, so the memo is never resolved and reportABoundNoStatementCanOutlive never runs.
With read.timeout=60 every ordinary statement of that backend is cut by the socket at 60 s instead of being cancelled at OPERATION's 120 s: the driver closes the connection, timedOut() finds the statement well inside its own bound and passes the failure through, and nothing in the log names either property. The javadoc of READ_TIMEOUT_PROPERTY promises the opposite — "A backend opening with the two set that way says so once." Resolving the memo once in open() would make good on it.
3. JDBCStorage.java:161 — the post-import statistics refresh is neither lifted nor weighed
reportABoundNoStatementCanOutlive weighs only StatementBound.OPERATION, so read.timeout=300 passes it in silence. updateTableStatistics then runs analyze table ... through bounded(con, STATISTICS_TIMEOUT_PROPERTY, 600, cancelArmed=true, ...) — a bounded statement, so applyBackstop takes the tighten path, finds previous=300000 <= wanted=backstopMillis(600)=630000 and leaves the connection carrying 300 s. A ten-minute analyze — the case the javadoc calls one that "legitimately takes as long as a scan of the table it describes" — is cut at 300 s, the driver closes the importer's connection, and since armedMillis is 0 and the elapsed time is well under the 600 s property, timedOut() returns a bare class-08 error naming no property. The statistics of #859 are then silently never refreshed. Any statement carrying a bound of its own longer than OPERATION is in this hole, not only this one.
4. JDBCStorage.java:627 — a configuration change re-arms the bound under a running lift
A BULK statement is running with lifted=true and previous=90000, the connection carrying 0. db-directory changes to a url that declares its own socketTimeout, so the memo is reset. A second BULK statement starts on the same connection: standingReadBoundMillis() is now 0, the state.unbounded > 0 && ... > 0 gate is false, and control falls to giveBack(), which writes 90000 back while two unbounded statements are still in flight. Both then die at 90 s — the failure the lift exists to prevent — and neither has a property to name.
Worth fixing
5. CachedConnection.java:198 — read.timeout is silently ignored outside the four dialects
ConnectDialect.of() answers null for mariadb, h2, db2 and the rest, so standingReadBoundMillis returns 0, applyStandingReadBound takes its millis == 0 && !readBoundSet early return and no setNetworkTimeout is issued: every connection of that pool stays unbounded, which is the state the property exists to fix. Being conservative there is defensible — such a url may bound the read under a name this class does not know, and ours would sit on top of it — but the silence is not, given that the strict parsing of the value exists so that "a deployment that asked for a bound and misspelled it" is not left with none quietly. reportUnknownDialect speaks only of the connect bound and pool.timeout; a word about this property there would close it.
6. JDBCStorage.java:150 — cutsStatementsShort weighs the wrong value for a statement carrying no cancel
The catalog lookups of openTree() run with cancelArmed=false, so the socket read timeout is their only layer and what the backstop arms for them is backstopMillis(120)=150000, not 120000. With read.timeout=140: cutsStatementsShort(140000, 120) is false, so nothing is reported, and applyBackstop finds previous=140000 <= 150000, takes the tighten-only early return and leaves state.armed at 0. When the catalog blocks behind the same lock as the create table it guards, the lookup dies at 140 s, armedMillis() is 0, endsAfterMillis is 0 and timedOut() returns the driver's raw class-08 exception naming neither property. Before this PR previous was 0, the backstop armed 150000 and the same failure was reported as BACKSTOP_ALONE plus the OPERATION property — so this is a step back in what the operator is told. For statements that carry no cancel the threshold has to be backstopMillis(statementSeconds).
7. JDBCStorage.java:133 — the memo and its reset race
Thread A reads standingReadBound == -1 and computes the answer against the old config. applyConfigurationChange then writes this.config = cfg and standingReadBound = -1. Thread A resumes and publishes the pre-change answer, so the reset is lost and the storage answers for the old url for the rest of its life — the very case the reset was added for. A generation counter compared on publish, or recomputing under the lock, makes it reliable.
Minor
8. CachedConnection.java:1003 — bounds() and declared() can disagree about one url. valueInUrl() stops at the first name present even when its value is 0 and never falls back to the last-segment alias, while declaredInUrl() tests both names independently. ...?oracle.jdbc.ReadTimeout=0&ReadTimeout=600 is declared() but not bounds(), so the login keeps the administrator's 600 s and then applyStandingReadBound puts ours on top of it with setNetworkTimeout. Contrived, but the two want to look at the same set of names for "the bound taken off is the bound that was set" to hold.
9. JDBCStorage.java:520 — lifted patches an overload in armed instead of removing it. armed == 0 now means both "nothing of ours is on this connection" and "our lift is on it", told apart by a boolean beside it, so state.armed == 0 && !state.lifted is repeated verbatim in giveBack(), restorePrevious() and both getNetworkTimeout() reads, plus the state.lifted=false that has to be remembered on the arm path. One Integer applied — null for a connection this backstop has not touched, 0 for a lift, the value for an arm — collapses all of them to applied == null and makes the invariant unstateable by mistake.
10. CachedConnection.java:993 — the block comment of declared() now sits above bounds(). The // paragraph ending "...leaving a connection with no read bound where the administrator had set one" was written for declared(); bounds() and its javadoc are now spliced between them. In a file where these comments are the record of why each predicate answers as it does — and where the two differ precisely in how they read a 0 — it is worth moving down to the method it describes.
…d bound The bound is resolved against poolKey() rather than against the configuration as it stands. Every path that names a pool goes through poolKey() because db-directory may be changed under a running backend, and the connections whose bound this decides are the ones of the pool open() registered with: read off the url config names now, the lift would be gated by the answer of a pool this storage never borrows from - leaving the bound of this backend standing on a bulk statement, which bulk.timeout=0 promises will not happen, or taking a bound of the deployment's own off a connection that came with one. It is resolved once, while the backend opens. applyBackstop() is the only caller in production and it asks only behind a statement of a class carrying no bound of its own, so a deployment that gives bulk.timeout a value of its own has no such statement anywhere and would never be told that its two bounds are set the wrong way round. A configuration change no longer resets the memo - poolKey() does not move under one, and a reset would resolve it again under a lift in flight, handing the bound back to the statements it was taken off for. What does move poolKey() is a close and a re-open, which is where it is reset. What the bound is weighed against is the loosest bound a statement of this backend carries, not the bound of an ordinary one: the statistics refresh after an import has a property of its own, ten minutes by default, and a bulk.timeout a deployment sets takes that class out of the lift and into the same weighing. And it is weighed against the socket layer of that bound rather than against its cancel, because the cancel is not always there to come first: the catalog lookups of openTree() ask DatabaseMetaData, which takes no query timeout at all. A standing bound between the two ends such a statement with the backstop arming nothing on top of it, so the failure names neither property. An unknown dialect now reports that it takes no standing read bound either, where one was asked for. bounds() reads the property name and its last-segment alias independently, the way declared() does, so a url naming the bound under both - one turned off, the other set - is the deployment's own under both predicates. Backstop.armed and Backstop.lifted are one Integer applied: null for a connection this backstop has not touched, 0 for a lift, the value for an arm.
|
Addressed in 1. The standing bound is resolved against
|
vharseko
left a comment
There was a problem hiding this comment.
Approving. 439089723c closes all ten items, and I checked each against the head rather than against the
answer.
Closed
The four blocking ones.
- 1 —
standingReadBoundMillis()askspoolKey(), so the answer is the one of the poolopen()registered
with for as long as the storage is open, and the memo is reset where that key really moves:releasePool()
and the failed-claim path beside it. - 2 — resolved in
open(), right afteropenPool()returns, so the warning is weighed by every backend
that opens rather than by the first statement of an unbounded class. - 3 —
loosestStatementBound(). I checked the other side of it too:holdBackstopcounts a
seconds <= 0statement as unbounded, so astatistics.timeoutof 0 goes under the lift rather than under
the weighing, and leaving it out of the loosest bound is right rather than an omission. - 4 —
applyConfigurationChangeno longer touches the memo, and the comment where the reset used to be
says what re-reading it under a lift in flight would do.
The six smaller ones. reportUnknownDialect says it, and only where a bound was asked for; the threshold
is backstopMillis(statementSeconds); the race is gone with item 4; boundInUrl() asks both names
independently the way declaredInUrl does; the comment is back above declared().
Item 9 in particular. I read the Integer applied refactor state by state against the pair it replaces —
null for armed == 0 && !lifted, 0 for the lift, the value for an arm — and every site maps exactly,
armedMillis() included. state.applied != wanted compares numerically rather than by reference, since one
operand is a primitive, and state.applied == null || short-circuits in front of the unboxing.
And the step back in reporting that item 6 attached to the threshold does close the way you argue it. With
standing > backstopMillis(loosest), previous > wanted holds for every class, so the backstop arms and
timedOut() names the property as it did before this branch; with standing <= backstopMillis(loosest) the
tighten-only return can swallow it, and that is exactly the configuration the open now warns about, by name and
by value.
Item 2, where the correction is yours
My repro was wrong and yours is right: ID2Entry.afterOpen() opens a bulk cursor on every open of every
backend, with the comment saying "Make sure the tree is there and readable, even if the storage is
READ_ONLY", so state.unbounded does reach 1 there and a read-only backend was already being told. What
really left the memo unresolved is a bulk.timeout set to anything non-zero — no statement of an unbounded
class anywhere — which is what testTheStandingReadBoundIsResolvedWhileTheBackendOpens sets.
Two things, neither blocking
1. The javadoc of the property still names the old threshold — CachedConnection.java:138-142
"It has to exceed the bound of an ordinary statement as well (
JDBCStorage.StatementBound.OPERATION, two
minutes by default): under it, such a statement dies on the socket at this value instead of being cancelled
at its own"
The threshold the code applies now is backstopMillis(loosestStatementBound()) — 600 s of
statistics.timeout plus the 30 s margin, so 630 s at the defaults. Items 3 and 6 landed in JDBCStorage, and
this paragraph is where a deployment reads about the property before setting it, five times below the value
that actually warns: someone following it sets read.timeout=180 and is told at the next open that the two
bounds are the wrong way round.
Worth saying in substance as well as in arithmetic: at the defaults the warning fires for every value under
about ten and a half minutes, which is most of the range this property is useful in. The warning itself carries
the other half of the remedy — it names loosest.property and its seconds, so the operator can see that
lowering statistics.timeout is the other way out — but the javadoc, which is read first, does not mention the
interaction at all.
2. The description is a round behind, in the same two places and in the test list
Squash-merge lands it in the history:
- "A standing bound at or under the bound of an ordinary statement (
StatementBound.OPERATION, two minutes by
default)" — the same understated threshold as above. - "
JDBCStoragereads the standing bound once per configuration [...] and reads it again after
applyConfigurationChange, since the URL may be another one now" — now the opposite, and deliberately so:
it is resolved once inopen()againstpoolKey()and is not re-read under a configuration change. The
description states the behaviour items 1 and 4 exist to remove. - The test list names
testTheStandingReadBoundIsReadAgainAfterAConfigurationChange, which is deleted, and
omitstestAReadBoundUnderEitherNameOfTheUrlIsTheDeploymentsOwn,
testTheLoosestBoundOfAStatementIsWhatAStandingBoundHasToOutlive,
testTheStandingReadBoundFollowsTheUrlThePoolWasRegisteredWithand
testTheStandingReadBoundIsResolvedWhileTheBackendOpens.
Three things I checked and am not raising, since they hold: the new cases vary system properties and a static
of the pool, and @AfterMethod puts back every StatementBound property, statistics.timeout,
read.timeout, CachedConnection.readTimeoutMillis and the access mode; poolConnectionString cannot be left
null under !claimedHere, since poolRegistered is this storage's own flag and that branch is a second
open() on a string already set; and openedOn() registers a real pool entry and gives it back through
close().
Reviewed against pull/934/head (439089723c) vs master; line numbers are that head's. CI shows no failure,
with build-maven (ubuntu-latest, 17) still running. No database and no benchmark — the thresholds are read
off BACKSTOP_MARGIN_SECONDS and the property defaults, not measured.
Part of #885 — its section 2, and it closes section 3 with it. The DDL lock bound of section 1 is a PR of its own; nothing here depends on it.
Problem
Two bounds already stand on a connection of this pool, and between them there is a gap.
Outside those two windows a connection whose peer has gone quiet is read with no deadline of any kind:
commit(),rollback(), theDatabaseMetaDatalookups ofisExistsTable()/isExistsIndex(), the rows a cursor drains, and every statement of a class carrying no bound. An operation that meets a database which stops answering after the login stays parked with nothing able to reach it, and there is no setting a deployment can ask for one with. That is section 3 of the issue as well as section 2, which is why section 3 needs no work of its own.Change
org.openidentityplatform.opendj.jdbc.read.timeout, in seconds, default 0 — the behaviour of every connection this pool established before it existed.The default is a consequence, not caution. A bound standing on the connection has to exceed the longest silence the database may legitimately produce; the longest statements belong to
StatementBound.BULK, which ships unbounded for reasons of its own. There is no non-zero value here that does not contradictbulk.timeout=0. So the deployment that knows how long its database may go without answering is the one that sets this — and the statements of that class run with it taken off for as long as they run.It is applied at the login, in the same call that takes the login's bound off.
relaxReadBound()becomesapplyStandingReadBound(), which setsread.timeoutin milliseconds where the login's bound used to be replaced with 0. It is called unconditionally, not only where a login bound was set: withconnect.timeout=0the login takes its bound from what is left of the deadline of the borrow instead, and a deployment running that way would otherwise set the property and get nothing for it.A read bound standing in the connection string is the deployment's own and is touched by no part of this — it is not replaced at the login, and it is not the one taken off for a bulk statement. But a
socketTimeout=0in a URL is not a bound of theirs: it is the default of the driver written out. That distinction is why this asksbounds()rather than the existingdeclared(), which answers a different question — whether a property of ours is to be supplied to the connect at all, where on PostgreSQL a URL parameter outranks a system property whatever it says. A bound put on an established connection withsetNetworkTimeoutis outranked by nothing.A misconfiguration is reported, never read as a zero. A value that is not a number, and a negative one, are said once and ignored in favour of the default: a deployment that asked for a bound and misspelled it getting none quietly is the one thing this property exists to prevent. A value past
MAX_BOUND_SECONDSis taken down to it — that ceiling is what a socket read timeout can hold at all, and a value beyond it reaches the driver as a negative timeout, outside the contract of the call.The value is read once, at class initialization, the way
aliveBypassNanosis, and clamped against the inlinedMAX_BOUND_SECONDSconstant rather than throughJDBCStorage.clampSeconds(): this runs in the initializer ofCachedConnection, and a package-private call into another class across two loaders is anIllegalAccessErrorrather than a call — which would leave the class uninitializable.A bulk statement lifts it, and puts it back. With a standing bound in force a statement of a class that carries none would die at it, which is the opposite of what
bulk.timeout=0promises.applyBackstop()— which since #882 only ever tightens — gains the other direction:CachedConnection.standingReadBoundMillis(url)answers with the same predicateapplyStandingReadBound()used, so the bound taken off is the bound that was set;Backstop.liftedflag keepsarmed == 0meaning what it meant: the connection carries its own value.JDBCStoragereads the standing bound once per configuration rather than per statement — it follows a system property and the URL of the backend, neither of which changes under a running statement — and reads it again afterapplyConfigurationChange, since the URL may be another one now.The two bounds set the wrong way round are said once. A standing bound at or under the bound of an ordinary statement (
StatementBound.OPERATION, two minutes by default) means such a statement dies on the socket instead of being cancelled at its own bound — which costs the connection the driver then closes, and names neither property, becausetimedOut()weighs the statement against its own bound, finds it well inside, and passes the failure through as it found it. The socket read timeout stands behind the cancel of a statement, so it has to be the longer of the two.That silence is also what the value should be sized against rather than the longest statement, because the lift covers statements alone: the commit at the end of an import is a call of its own with no statement in flight behind it —
ImporterImpl.close()commits a whole import in one — and so are the rollback of every borrow and the reads of the catalog. Every one of those runs under this bound whatever the class of the statements before it.Poolability is unchanged in substance. A connection still carrying the bound of its login must not be pooled — it would fail the statements of every borrower after this one — and that is what the return of
applyStandingReadBound()still says. A connection that merely never took the standing bound may be pooled: that is exactly the connection this pool handed out before the property existed.Testing
New cases in
CachedConnectionTestCase:testAnEstablishedConnectionCarriesTheReadBoundAskedFor,testTheReadBoundIsSetWhereTheLoginHadNoneToLift,testAReadBoundOfTheUrlIsNotReplacedByTheConfiguredOne,testOnlyTheReadBoundThisClassSetsIsItsOwnToLift,testTheReadBoundIsConfiguredInSeconds,testAConnectionThatWouldNotTakeTheStandingBoundIsStillPooled,testAConnectionThatWouldTakeNeitherTheStandingBoundNorTheLiftIsNotPooled,testAReadParameterOfTheUrlSetToZeroIsNoBoundOfTheDeployments,testTheDefaultTakesTheBoundOfTheLoginOffAndPutsNothingOnTopOfIt, andtestAReadBoundWorthWarningAboutStillInitializesTheClass— the last one against the<clinit>trap above, where a warning reached from a class initializer turns a misconfigured property intoExceptionInInitializerError.New cases in
JDBCStatementBoundTestCase:testABulkStatementTakesTheStandingReadBoundOffTheConnection,testTheStandingReadBoundOutlivesTheLiftAndComesBackAfterIt,testAReadBoundOfTheConnectionStringIsNotTakenOff,testAStandingReadBoundUnderTheBoundOfAStatementCutsItShort,testTheStandingReadBoundIsReadAgainAfterAConfigurationChange.