Send what a replication session's publisher left queued when it is closed - #1035
Send what a replication session's publisher left queued when it is closed#1035vharseko wants to merge 2 commits into
Conversation
…osed Session.close() set closeInitiated, interrupted the publisher thread and joined it, and everything still in sendQueue went with it. The StopMsg published afterwards still went out, so the peer read an orderly close with no sign that anything was missing. PR OpenIdentityPlatform#919 recorded this as a known limitation and named the fix; this takes the first of the two options it listed. The queue is now sent from close(), after the join - the publisher is gone, so the closing thread owns the socket - and before the StopMsg, so that message stays last on the wire. A session which already failed is left alone, for the reason the StopMsg is. The drain is bounded by DRAIN_BUDGET_MS, 5 s, the value DSRSShutdownSync.REPLICA_OFFLINE_GRACE_PERIOD already spends waiting for one of these messages to be forwarded: close() is on shutdown paths, and an unbounded drain would hold the thread shutting the server down for as long as a stalled consumer stays stalled. What it gives up on is logged rather than dropped in silence. SessionPublisherDrainTest also pins which end of a session could ever lose a queued message: only ServerHandler starts a session's publisher, so a change a directory server publishes is written to the socket before publish() returns. That rules the send queue out as the explanation of OpenIdentityPlatform#963. Refs OpenIdentityPlatform#963
The case failed on three ubuntu legs of CI and on nothing else: the peer had received 2025, 2134 and 1306 of the 3000 messages. The give-up warning appeared in none of those logs, so the drain had written the whole queue and the loss was under the write. The case had no reader on the closing side, so that side reached close() with inbound bytes nobody had read, and a close in that state ends the connection with a reset rather than a FIN - which discards what the peer has not read yet, the drained queue included. Measured with a bare socket pair, 8 MiB to a peer reading behind the writer, the only difference being whether the closing side drained its own inbound: linux 6.12/jdk11 53.4% against 100%, macos 15.7/jdk26 98.3% against 100%. That spread is why every macos and windows leg passed. The server has no such condition where the drain does anything: ServerHandler.shutdown() closes the session at :946 and joins its ServerReader only at :966, and the paths which close without a live reader are the ones the drain skips anyway - Session.run() after a send threw, and ServerReader's finally on an error, both of which leave sessionError set. So the case keeps a reader too, with its soTimeout lifted, receive() handing a read timeout to setSessionError() being enough to skip the drain and test nothing. The read of the peer end now reports what ended it. Run on linux/jdk11 with that reader commented out, the case fails with "the peer received 2873 of the 3000 messages published; the read ended by java.net.SocketException: Connection reset", and passes with it in. Refs OpenIdentityPlatform#963
|
@maximthomas this was in draft while I chased its own CI failure. It is back for review, and the The first run failed on three ubuntu legs and on nothing else - 32560 tests, one failure, this The warning this change adds for a queue it cannot send appeared in none of those logs, which is Measured with a bare socket pair, 8 MiB written to a peer reading behind the writer, the only
That spread is the whole reason the case passed on every macos and windows leg, and on my machine,
The server does not have that condition where the drain does anything, which is why the change to Two things I would rather you heard from me than found:
On the part of this which is yours: the send-queue candidate you raised on #963 is ruled out as the |
Refs #963. Two things which came out of investigating that issue, and which belong together
because the second is what the first ruled out.
The tests: which end of a session can lose a queued message
Session.publish()has two branches, and which one a message takes decides whether a close canlose it:
isRunningis set insiderun(), so it is true only where something calledSession.start()-and in the whole server that is one place,
ServerHandler.java:362.ReplicationBrokerneverstarts its own. So the replication-server end of a session has a publisher thread and the
directory-server end does not.
SessionPublisherDrainTestpins that, because it is what decides where a close can lose anything:theSessionOfADirectoryServerBrokerHasNoPublisherThread- the session a real broker publishesits changes on is still
Thread.State.NEWafter the handshake;aSessionWithNoPublisherThreadHasReachedTheWireWhenPublishReturns- a change published and thesession closed at once still reaches the peer, and the session's own thread never ran, so
publish()is what wrote it. Without that second assertion the case would pass on eitherbranch: a publisher thread usually outruns a close for a single message, which is measured
rather than assumed - starting the publisher in that case is what makes it fail;
aSessionWithAPublisherThreadSendsWhatIsStillQueuedWhenItIsClosed- the case for the changebelow.
drain()stops at theStopMsg, so the size it asserts pins the order too.What this says about #963. The candidate raised there - that the
AddMsgofReSyncTest.testResyncAfterRestorewas dropped bySession.close()without being drained -cannot be what happened. That message is published by a directory server, on a session with no
publisher thread, so it was written to the socket before
publish()returned. The conclusion ofthat candidate, that the change never reached the replication server, stands on other evidence and
this PR does not touch it; only the mechanism is ruled out. Hence
Refs, notFixes: #963 staysopen.
The change: a close sends the queue instead of dropping it
Where a publisher thread does exist,
close()setcloseInitiated, interrupted that thread andjoined it, and everything still in
sendQueuewent with it. TheStopMsgpublished afterwardsstill went out -
isRunningis false by then, so it takes the direct branch - so the peer read anorderly close with no sign that anything was missing.
PR #919 recorded this as a known limitation and named the fix: "Fixing it belongs in
Session-drain before interrupting, or report the forward from the publisher thread."
ReplicationServerShutdownSyncTestcarries a comment pointing at it as the reason one of itsassertions may fail. This takes the first of the two.
close()now sends that queue:which is what already lets the
StopMsgbe published on it;StopMsg, so that message stays last on the wire, which is what it means;StopMsgis skipped there:writing more to it cannot work. That is also the path where
close()runs on the publisherthread itself -
run()calls it when asend()threw - where the queue is unsendable byconstruction.
The budget.
close()is called from shutdown paths, so an unbounded drain would hold thethread shutting the server down for as long as a stalled consumer stays stalled, which is the
hazard #952 and #983 are about.
DRAIN_BUDGET_MSis 5 s, the same value asDSRSShutdownSync.REPLICA_OFFLINE_GRACE_PERIOD: a close has no reason to wait longer for one ofthese messages than the shutdown which is waiting on the close. A peer which is reading pays none
of it; a peer which is gone pays none either, its write failing at once. Only a peer which is alive
and not reading pays, and that is the case the old code answered by dropping the messages.
What is given up on is reported. A
logger.warnnames the session, how many messages it couldnot hand over and why. The silence is what cost the most to diagnose in #963.
LocalizableMessage.rawis the idiom this package already uses for a log line, so this needs nonew ordinal in
replication.properties.What the first CI run found, and why the case needed a reader
The first run of this branch failed on three ubuntu legs - and on nothing else: 32560 tests, one
failure, this suite's own. The peer had received 2025, 2134 and 1306 of the 3000 messages. Every
macos and windows leg passed, and so did ubuntu 21 and 26.
The give-up warning this change adds appeared in none of those logs, which is what made it
diagnosable: the drain had not given up on anything, so the whole queue had been written to the
socket. The loss was under the write, in the teardown.
close()ends withStaticUtils.close(plainSocket, secureSocket)straight after the last write,and the case had no reader on the closing side - so that side reached the close with inbound
bytes nobody had ever read. A close in that state ends the connection with a reset instead of a
FIN, and a reset discards whatever the peer has not read yet. Measured with a bare socket pair,
8 MiB written to a peer reading behind the writer, the only difference between runs being whether
the closing side drained its own inbound:
Connection resetConnection resetThat is the whole of it: the platform spread explains why the suite passed on every macos leg and
on this machine while losing half the queue on ubuntu.
The server does not have that condition where the drain does anything.
ServerHandler.shutdown()closes the session atServerHandler.java:946and joins itsServerReaderonly at:966, so the reader is still consuming inbound across the close. The pathsthat close without a live reader are the ones that skip the drain anyway:
Session.run()callsclose()after asend()threw, andServerReader'sfinally(:228) is reached either on anerror - both leave
sessionErrorset - or on aStopMsg, where the peer has announced it isleaving and there is nothing unread inbound. The directory-server side has no publisher thread at
all, so its queue is empty and the drain is a no-op there.
So the case now keeps a reader on the sending end, as the server does, and its
soTimeoutislifted because
receive()hands a read timeout tosetSessionError()- which would skip thedrain and test nothing. The read of the peer end reports what ended it, so a short read names its
cause instead of leaving the next reader to find this out again.
Limits, stated rather than left to be found
completion. Bounding a single write needs a non-blocking socket, which this session is not.
case would itself hang on that blocked write. The drain is covered; the give-up is not.
isRunningtrue and
closeInitiatedtrue, thewhile (!closeInitiated)loop ofpublish()does not run andthe call returns having done nothing. That is a different silent drop - at the door rather than in
the queue - and it is not touched here.
above shows, a close whose side has unread inbound resets the connection and the peer loses what
it has not read - which would undo a drain. Every server path where the drain does something has
a reader consuming inbound across the close, so this does not bite today, but it is a property of
the callers rather than of
close()itself. Making the close orderly regardless - reading theinbound to its end before closing the socket - is a change to every session teardown and belongs
in its own PR, not bundled here.
Testing
190 tests, 0 failures, 0 errors, 0 skips, on the branch as it stands on master. The set is wider than the change because the drain adds
time to a
close()whose peer is not reading, andclose()is on every shutdown and handshakepath of this package - the shutdown and handshake classes are in there to catch a timing shift
rather than a logic one.
Every assertion was built with its defect put back:
...SendsWhatIsStillQueuedWhenItIsClosedfails withthe close dropped 2820 of the 3000 messages published- 180 reached the peer through the socket buffers...HasReachedTheWireWhenPublishReturnsfails on the thread state, which is what stops that case from passing on both branches