A replica which reconnects after a restore can be declared up to date and never sent the change it was restored past (ReSyncTest.testResyncAfterRestore)

[vharseko]

Describe the bug

ReSyncTest.testResyncAfterRestore failed in CI: the entry added between the backup and the
restore never came back, and the 30 s the test waits went by with nothing happening at all — no
error, no replay attempt, no message on the wire.

ReSyncTest.testResyncAfterRestore:167->ReplicationTestCase.getEntry:759
  Expected entry with dn "dc=fooUniqueName1,dc=example,dc=com" would exist expected [true] but found [false]

The whole sequence of the test fell inside one second (logs/errors of the failing run):

10:03:55 Backup task ... finished execution in the state Completed successfully
10:03:55 testResyncAfterRestore: backup done
10:03:55 testResyncAfterRestore: entry added
10:03:55 Restore task ... started execution
10:03:55 The backend userRoot is now taken offline
10:03:55 Restored backup file: 00000000.jdb (size 58002)
10:03:55 The database backend userRoot containing 3 entries has started
10:03:55 Directory server DS(123) has connected to replication server RS(104) for domain
         "dc=example,dc=com" at 127.0.0.1:65531 with generation ID 8969
10:03:55 testResyncAfterRestore: restore done
         <30 seconds of silence>
10:04:25 failed to wait for org.opends.server.util.TestTimer$SteppingTimer$1

The replica did announce a state behind the change. From logs/audit, the ds-sync-state of
dc=example,dc=com after the add and after the restore:

replace: ds-sync-state
ds-sync-state: 000001a0807967c2007b00000004   <- after the add of dc=fooUniqueName1
...
replace: ds-sync-state
ds-sync-state: 000001a080796545007b00000002   <- reloaded from the restored backend

So enable() → loadDataState() did what it is meant to do, and DS(123) reconnected asking for
everything after seqnum 2 while the change it needed is seqnum 4.

The replication server had already decided there was nothing to send. The thread dump taken at
the failure:

"Replication server RS(104) writing to Replica DS(123) for domain "dc=example,dc=com" at localhost/127.0.0.1:56934"
  daemon TIMED_WAITING on org.opends.server.replication.server.MsgQueue@442cca58
	at org.opends.server.replication.server.MessageHandler.getNextMessage(MessageHandler.java:390)
	at org.opends.server.replication.server.ServerHandler.take(ServerHandler.java:991)
	at org.opends.server.replication.server.ServerWriter.run(ServerWriter.java:100)

MessageHandler.java:390 is the msgQueue.wait(500) inside if (following). The handler for the
just-reconnected replica was already following — i.e. it had read the changelog once, found
nothing after the announced state, and concluded the replica was up to date.

Why it matters

following is a one-way door for a change that is already in the changelog:

// MessageHandler.java:302
boolean queueContributesToDomainState = fillLateQueue();
if (lateQueue.isEmpty())
{
  // we could not find any messages in the changelog
  // so the remote server is not late anymore.
  synchronized (msgQueue)
  {
    if (isMsgQueueBelowThreshold())
    {
      following = true;
    }
  }
}

fillLateQueue() is the only reader of the changelog (getCursorFrom(serverState),
MessageHandler.java:429). Once following is set, the handler serves nothing but what add()
puts on its queue, and add() only ever carries changes published after the handler started
following. Nothing re-reads the changelog, so a change missed at that one moment is not sent again
— short of the queue overflowing, which is the single place that clears the flag
(MessageHandler.java:141).

This is not only a test problem. The same window is what a real replica depends on: a server that
restores a backup gets the changes it was restored past only if the changelog cursor, opened once
at the reconnect, yields them. If it comes back empty the replica silently stays short of those
changes, and the replication server considers it in sync.

What to look into

Why fillLateQueue() came back empty while the announced state was demonstrably behind. Two
candidates:

1. The change was not yet visible to a cursor opened right then. The add, the backend going
   offline, the restore and the reconnect all happened inside the same second, so the cursor was
   opened on a changelog record written milliseconds earlier — worth checking what the file
   changelog guarantees between ReplicationServerDomain.put() and a subsequent
   getCursorFrom().
2. The start position for the replica's own serverId in this path — the change to be resent
   here originates from the very server the handler serves, which is the unusual part of
   resync-after-restore compared to ordinary catch-up.

Whatever the cause turns out to be, treating "the changelog gave me nothing" as final is what makes
a transient miss permanent: a handler whose queue stays empty while the state it was given is
behind the domain state could read the changelog again instead of waiting forever.

Evidence

• run https://github.com/OpenIdentityPlatform/OpenDJ/actions/runs/34206334572, job
  build-maven (ubuntu-latest, 17)
  https://github.com/OpenIdentityPlatform/OpenDJ/actions/runs/34206334572/job/101996575306
• one failure out of 32260 tests; the same commit passed ReSyncTest in the ubuntu-latest 11, 21
  and 25 jobs of that same run, in ~2.5 s each — the failing job is not a slow resync, it is a
  resync that never started
• unrelated to the PR that happened to be under test ([#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 touches only
  org.opends.server.backends.jdbc; ReSyncTest runs on the JE userRoot backend)

[maximthomas]

A third candidate for why fillLateQueue() came back empty, which does not require the changelog to
have missed anything: the AddMsg may never have reached RS(104) at all, so the cursor opened at
the reconnect was right — there genuinely was nothing after seqnum 2.

Session.publish() is an enqueue, not a send, and the close does not drain the queue:

// Session.java:99
private final LinkedBlockingQueue<byte[]> sendQueue = new LinkedBlockingQueue<>(4000);

// Session.java:318 (publish)
while (!closeInitiated)
{
  if (sendQueue.offer(buffer, 100, TimeUnit.MILLISECONDS))
  {
    return;                       // handed to the writer thread, not to the socket
  }
}

// Session.java:536 (run — the writer thread)
while (!closeInitiated)
{
  buffer = sendQueue.take();
  send(buffer);
}

Session.close() sets closeInitiated and then interrupts and joins that writer thread
(Session.java:157-162). The loop leaves on the interrupt or on the flag, and everything still in
sendQueue goes with it — there is no drain and no flush of pending buffers anywhere on the close
path. The StopMsg that close() publishes right after is not affected: isRunning is false by
then, so publish() takes the direct send(buffer) branch and the message really does go out. The
peer therefore sees an orderly close and has no reason to suspect that anything was dropped.

The restore path closes the session in exactly the window the test spends adding the entry:

MultimasterReplication.processRestoreBegin           (MultimasterReplication.java:638)
  -> LDAPReplicationDomain.disable()                 (LDAPReplicationDomain.java:3130)
    -> disableService()                              (LDAPReplicationDomain.java:3135)
      -> ReplicationBroker.stop()                    (ReplicationBroker.java:2672)
        -> setConnectedRS(ConnectedRS.stopped())     (ReplicationBroker.java:2689)
          -> oldRS.session.close()                   (ReplicationBroker.java:3288)

This is consistent with every piece of evidence in the report. The ds-sync-state reaching seqnum 4
shows only that the DS generated the CSN and committed the change through
pendingChanges.commitAndPushCommittedChanges() — that call ends at sendQueue.offer(), so it says
nothing about delivery. And the end state is identical to candidates 1 and 2: an empty cursor at the
reconnect, following latched, silence. The thread dump cannot tell the three apart.

One corollary inside the same window: the ReplicaOfflineMsg that stop() publishes at
ReplicationBroker.java:2684 goes onto the same queue right behind the AddMsg and is discarded with
it, while LDAPReplicationDomain.publishReplicaOfflineMsg() (LDAPReplicationDomain.java:1976)
reports it to dsrsShutdownSync as sent regardless — #918 seen from the restore path.

How to separate the candidates on the next occurrence. Compare the RS-side state with what the
replica announced. ReplicationServerDomain.getLatestServerState() (ReplicationServerDomain.java:1683)
for dc=example,dc=com:

• still at seqnum 2 for serverId 123 -> the change never arrived, this candidate, and the change is
  gone from the topology altogether rather than merely unsent to one replica;
• at seqnum 4 -> the change is in the changelog and the cursor missed it, candidates 1 and 2.

Dumping that state (and the RS domain's oldest state) alongside the existing logs when a replication
test fails is cheap and would settle it the next time this fires.

This does not weaken the conclusion about following being a one-way door — if the change was
dropped on the DS side, re-reading the changelog would not recover it either. It does mean the
dropped-on-close path is worth ruling out first, because in that case the fix belongs on the publish
side and the resync would still be quietly incomplete after following is made re-readable.

[vharseko]

The artifacts of the failing job are still retrievable
(gh api repos/OpenIdentityPlatform/OpenDJ/actions/jobs/101996575306/logs): the dump the harness
writes on failure carries the full thread dump plus the complete logs/access, logs/audit and
logs/replication, not only the excerpts quoted above. They settle all three candidates and move
the failure to one place.

The tested tree is 4390897, which predates #889 — that turns out not to matter, see point 4.

1. Nothing can be dropped in sendQueue on the DS side

Session.start() has exactly one caller in the whole source tree, ServerHandler.java:362 — the
RS side. A ReplicationBroker never starts the session thread of its own session, so
isRunning is false there and Session.publish() takes the other branch:

// Session.java:316
if (isRunning.get()) { ... sendQueue.offer(buffer, 100, MILLISECONDS) ... }
else { send(buffer); }        // Session.java:337

and send() writes and flushes to the socket before returning (output.flush(),
Session.java:361). broker.publish() runs in the post-operation plugin, so the AddMsg bytes were
on the wire before the add returned to the test, ~700 ms before stop().

The thread dump agrees: the only session thread in the JVM is
"Replication server RS(104) session thread to Replica DS(123) ... " Id=216, which is the name
ServerHandler.java:359 gives it after starting it. There is no Replication Session from ... to ...
thread — the default name a DS-side started session would carry.

The same applies to the ReplicaOfflineMsg corollary. The sendQueue drop on close is a real
defect, but only in the RS→DS direction, where the session thread does run; that deserves its own
issue and is not this one.

2. The change did reach the changelog

• The old session was closed cleanly. ServerReader logs getBadlyDisconnectedErrorMessage()
  at ERROR on SocketException (ServerReader.java:196-208) and NOTE_READER_EXCEPTION at INFO
  for anything else; logs/errors has neither, for any of the three sessions of the run. The reader
  left its loop through the StopMsg return (ServerReader.java:154-166), so it consumed the
  stream up to the StopMsg — and the AddMsg precedes the StopMsg on that stream. This also rules out
  the one remaining transport story (a hard close() with unread data emitting an RST and wiping
  the peer's receive queue).
• The reader is single-threaded and synchronous: receive() → handler.put() →
  ReplicationServerDomain.put() → publishUpdateMsg() → FileReplicaDB.add() → Log.append().
  Both filters that could swallow the message log a warning (ServerReader.java:262, :271), and a
  changelog failure logs ERR_CHANGELOG_SHUTDOWN_DATABASE_ERROR. None of them is in logs/errors.
• The append is not buffered (this is candidate 1's premise, and it does not hold):
  BlockLogWriter.write() flushes after every record (BlockLogWriter.java:124) onto a plain
  FileOutputStream — LogWriter/MeteredStream add no buffering — and every cursor opens a fresh
  RandomAccessFile (LogReaderPool.getReader()) whose length() is read live
  (BlockLogReader.java:431). A record appended 600 ms earlier is visible to a cursor opened now.

Candidate 2 does not hold either: FileChangelogDB.getCursorFrom(DN, ServerState, CursorOptions)
(FileChangelogDB.java:823-834) iterates every replicaDB of the domain, the handler's own
serverId included, and FileReplicaDB.generateCursorFrom() explicitly special-cases
startCSN.getServerId() == serverId — resync-after-restore is the intended use of that path.

3. The replica really did announce seqnum 2

logs/access has the whole loadDataState() sequence, in order, and it is before the connect:

op=127 SEARCH dc=example,dc=com attrs="ds-sync-state"                  <- PersistentServerState.loadState()
op=128 SEARCH (&(ds-sync-hist>=dummy:...007b00000002)(...))            <- checkAndUpdateServerState()
op=129 SEARCH attrs="ds-sync-generation-id"                            <- loadGenerationId()
op=133 SEARCH attrs="ds-sync-generation-id,ds-sync-fractional-*"       <- isBackendFractionalConfigConsistent()
                                                                          i.e. sessionInitiated() -> connected
op=139 MODIFY ds-sync-state: 000001a080796545007b00000002              <- the flush of what was loaded

enable() is loadDataState() then enableService(), and the state it loaded is the one written
back at op=139. So the ServerStartMsg carried {123 -> seqnum 2}, and
DataServerHandler.processStartFromRemote() passes it to setInitialServerState() verbatim
(DataServerHandler.java:339).

Incidentally the CSN accounting is complete: seqnum 3 belongs to no entry because it went to the
ReplicaOfflineMsg of the import's disable() (ReplicationBroker.stop() →
publishReplicaOfflineMsg() → PendingChanges.putReplicaOfflineMsg() → newCSN()). Nothing was
lost before publication.

4. Nothing was ever delivered to the replica, so it is not a DS-side drop

logs/access is complete to the end of the test — it stops at op=139 because
ReplicationTestCase.getEntry() polls with DirectoryServer.entryExists(), a direct backend read
that logs nothing. There is no ADD REQ ... dn="dc=fooUniqueName1,dc=example,dc=com" type=synchronization
anywhere: no replay was ever attempted, successful or failed. Neither ReplicationBroker.receive()
nor ReplicationDomain.receive() filters an UpdateMsg, and processUpdate() only drops a delivery
whose CSN a replay thread already owns — which cannot be a CSN that was never delivered before. So
the RS did not send it, and none of the pre-#889 replay bookkeeping is involved.

That also pins down which following this is. Of the three assignments, the two on the catch-up path
(MessageHandler.java:339 and :369) both return the message they have just read, so the entry
would have been on the wire. Only MessageHandler.java:313 — the "the cursor gave me nothing" branch
— sets it having sent nothing.

Where that leaves the cause

The record was in the changelog, the announced state was behind it, and fillLateQueue() still came
back empty. So candidate 1 survives, but not for the reason it was raised: not visibility of the
write, but positioning of the read, somewhere in
FileChangelogDB.getCursorFrom(baseDN, serverState, options) →
FileReplicaDB.generateCursorFrom(seqnum2, GREATER_THAN_OR_EQUAL_TO_KEY, AFTER_MATCHING_KEY) →
Log.getCursor() → BlockLogReader.seekToRecord().

Worth noting how unforgiving that stack is about a single bad seek:
BlockLogReader.positionToKey() returns Pair.of(false, null) when the forward scan from the block
the binary search picked reaches EOF without a key >= the target (BlockLogReader.java:482-486);
Log.getCursor() still returns and registers the cursor, because the strategy is not EQUAL_TO_KEY;
LogFileCursor.next() then reads from wherever the reader was left — EOF — and
FileReplicaDBCursor.nextWhenCursorIsExhaustedOrNotCorrectlyPositionned() repeats the same failed
seek every time. One mis-positioned seek is indistinguishable from "this replica is up to date" for
the rest of the session, and following then makes it permanent.

What I would do

1. Instrument the empty cursor, the cheap version of the comparison suggested above: when
   fillLateQueue() comes back empty, log the handler's serverState,
   ReplicationServerDomain.getLatestServerState() and the replicaDB's newest CSN. One line would
   have settled this run, and it settles the next one.
2. The durable fix is the one in the report: a handler whose queue stays empty while the domain
   state is ahead of the state it was given must re-read the changelog instead of treating a single
   empty cursor as final. That is what turns a transient miss into a permanent one, whatever causes
   the miss.
3. A separate defect of the same "silently short" family, worth its own issue:
   ReplicationDomain.publish() (ReplicationDomain.java:3659-3667) discards the boolean
   broker.publish() returns and updates the ServerState regardless. ReplicationBroker.publish()
   returns false without sending on connectionError, on connectRequiresRecovery, and whenever
   shutdown is already set. A change dropped there is recorded as replicated and nothing ever
   resends it. It is not what happened here — the message did go out — but it does mean ds-sync-state
   is never evidence of delivery, including for the seqnum 4 line quoted in the report.

[vharseko]

Three more occurrences since this was filed, and one of them is the discriminating case the recipe
above asks for.

PR under test	job	method	entry
#970	build-maven (ubuntu-latest, 17)	testResyncAfterRestore:167	dc=fooUniqueName1
#968	build-maven (ubuntu-latest, 21)	testResyncAfterRestore:167	dc=fooUniqueName1
#964	build-maven (ubuntu-latest, 17)	testResyncAfterImport:216	dc=fooUniqueName2

Same shape as the report in all three: exactly one of the nine matrix cells fails while the other
eight pass — the same test on the other JDKs included — and master was green at f85d2d2. Of the
branches under test, #970 is the domain ServerState on disable() and #968 the entryUUID search;
neither is on the delivery path.

The third is on the head of #964 itself — c6ca5c8, the branch that fixes this issue — and it is
the import sibling rather than restore.

That one is worth separating from the other two. stopFollowingWhenChangesAreMissing() re-reads the
changelog only while the state of the domain is ahead of the state of the handler, so a failure on
this branch says one of three things:

• the domain state was not ahead — the change never reached RS(104), which is the candidate
  raised above, and the latch cannot recover it by construction;
• it was ahead and the re-read still gave nothing — the seek one layer down, which this branch
  deliberately leaves untouched;
• the throttle — two consecutive waits, then once per advance of the domain state — never let the
  re-read happen inside the 30 s the test waits.

I have not opened the artifacts, so I am not claiming which of the three it is. One thing I did
check, so it is not chased twice: isFedByTheDomain() tests BAD_GEN_ID_STATUS and
FULL_UPDATE_STATUS only, and a local ImportTask brings the replica back through the ordinary
enable() path rather than a total update — so the guard is not an obvious reason for the latch to
skip the import path. Whether the handler can nevertheless be in FULL_UPDATE_STATUS at the moment
of the check is unverified.

By the recipe above, the dump of job 102113708234 should settle it:
ReplicationServerDomain.getLatestServerState() for dc=example,dc=com still at the seqnum the
replica announced means the change never arrived; ahead of it means the cursor missed it again — and
this time WARN_CHANGELOG_READ_AGAIN_FOR_MISSING_CHANGES in logs/errors also says whether the
re-read fired at all, which is what that message was added for.

One caveat on the evidence: I have re-run the failed job in all three runs, so each of these is
attempt 1. The logs stay reachable by job id, but the run artifacts may not survive the newer
attempt.

[vharseko]

A fifth occurrence, the import sibling again:

PR under test	job	method	entry
#982	build-maven (ubuntu-latest, 25)	testResyncAfterImport:216	dc=fooUniqueName2

Same shape as the four before it: one of the nine matrix cells fails, 32383 tests with a single failure,
and the branch under test is not on the delivery path - #982 is the throttle of the replay-retry
warning, which ReSyncTest never reaches, since nothing there fails a replay.

The dump reads the way the report does. logs/audit for dc=example,dc=com:

replace: ds-sync-state
ds-sync-state: 000001a086f0f6b5007b00000002   <- after the add of dc=fooUniqueName2
...
replace: ds-sync-state
ds-sync-state: 000001a086f0f5ed007b00000001   <- reloaded from the imported backend

DS(123) reconnected at 16:12:14 with generation ID 8816, the same it had before the import, and
nothing followed for the 30 s the test waits. The writer of RS(104) sat where it sat in the report:

"Replication server RS(104) writing to Replica DS(123) for domain "dc=example,dc=com" at localhost/127.0.0.1:46282"
  daemon TIMED_WAITING on org.opends.server.replication.server.MsgQueue@3d83ad2e
	at org.opends.server.replication.server.MessageHandler.getNextMessage(MessageHandler.java:390)

One thing worth recording next to the table, because it is checkable rather than a claim about the
cause: none of the five branches carries 36d4af9, the fix for #924, which reached master on
2026-09-09 13:44 UTC - #982 was cut from 2a7bb9d, one commit short of it. Whatever the cause
turns out to be, a run of these branches rebased onto master is worth more than another run of them
as they stand.

[vharseko]

@maximthomas the recipe you proposed - dump the RS-side state alongside the existing logs when a
replication test fails - is #1015. It appends, for every replication server in the VM and each of
its domains, the newest CSN the changelog holds per replica and then, per connected handler, the
state that handler has handed its consumer plus its monitor attributes. Test tree only; nothing had
to be widened for it, since following is already a monitor attribute.

One thing I did open in the meantime, and it narrows the three candidates by one - for that run.
The occurrence on the head of #964 was worth reading precisely because that branch carries a
diagnostic of its own: WARN_CHANGELOG_READ_AGAIN_FOR_MISSING_CHANGES, logged when the domain is
ahead of a following handler whose queue is empty.

In that failing run it never appears. The artifacts of
attempt 1 of
run 34241837159 are still reachable - by attempt, since the job id now serves the passing re-run -
and they say:

• no such warning in logs/errors, while WARNING-severity lines from that test are there, so the
  publisher was not the reason;
• the writer of RS(104) sat in the wait loop which calls that check - MessageHandler.java:401 on
  that branch - for the whole 30 s;
• generation id 9158 on both connects, so isFedByTheDomain() was true;
• the throttle cannot account for it either: lastMissingChangesDomainState starts null, the check
  fires on the second consecutive wait, and there were some sixty waits to spare.

So diffChanges(domainState, serverState) <= 0 held throughout: the domain was never seen ahead of
the handler. That rules out the candidate where the changelog holds a change the queue never got -
and it leaves your candidate tied with a loss on the replica side, because both of those leave the
two states equal. Which is exactly what the dump in #1015 separates, and what nothing in today's
artifacts can.

Worth doing in that order, then: #1015 first, so that the next occurrence says which of the two it
is rather than adding a sixth row to the table above.