Skip to content

[#963] Dump the state of the replication servers when a test fails - #1015

Open
vharseko wants to merge 1 commit into
OpenIdentityPlatform:masterfrom
vharseko:issues/963-dump-replication-state-on-failure
Open

vharseko wants to merge 1 commit into
OpenIdentityPlatform:masterfrom
vharseko:issues/963-dump-replication-state-on-failure

Conversation

@vharseko

@vharseko vharseko commented Sep 10, 2026

Copy link
Copy Markdown
Member

Closes #963. This does not fix that issue - it makes the next occurrence of it decidable; the issue is closed with it and reopened if the failure comes back.

Why

ReSyncTest has now failed five times with the same shape: the replica reconnects after a
restore or an import announcing a state behind the entry added in between, and the 30 s the
test waits go by with nothing on the wire. Every occurrence leaves the same three candidates
open:

  1. the change never reached the replication server - the Session.close() of the disable
    drops what is still queued for the writer thread;
  2. it reached the changelog and the cursor opened at the reconnect missed it;
  3. it was sent and lost on the replica before it was applied.

Nothing in the artifacts tells them apart, and the thread dump cannot: a handler which was
never given the change and one which was given it and sent it both end up following an empty
queue, waiting in the same msgQueue.wait(500).

The occurrence on the head of #964 shows how little the existing evidence settles. That branch
adds WARN_CHANGELOG_READ_AGAIN_FOR_MISSING_CHANGES, which is logged when the domain is ahead
of a following handler whose queue is empty. In the failing run
(attempt 1
of run 34241837159, job 102113708234) the warning never appears, while the writer of RS(104)
sat in the wait loop which calls that check for the whole 30 s and the generation ids matched on
both connects. So the domain was never seen ahead of the handler - which rules candidate 2 out
for that run and leaves 1 and 3 tied, since both of them leave the two states equal.

What is added

TestCaseUtils.appendReplicationServersState(), called from TestListener.appendFailureInfo() -
the one place which already assembles the failure dump, and the one which covers a failed
configuration method as well as a failed test.

For every replication server running in the VM, for each of its domains: the newest CSN the
changelog holds per replica, then, per connected DS and RS handler, the state that handler has
handed its consumer and its monitor attributes.

Replication server RS(104) state for domain "dc=example,dc=com":
  changelog: 000001a08a5e371c007b00000002
  DS(123): state 000001a08a5e371c007b00000002
    handler: Connected directory server DS(123) localhost:53276,...
    queue-size: 0
    following: true
    sent-updates: 2
    generation-id: 8702
    missing-changes: 0
    approximate-delay: 2
    server-state: 000001a08a5e364d007b00000001 Thu Sep 10 11:10:25 MSK 2026

The two lines which matter are the first two, and they read three ways:

  • handler level with the changelog - the change was delivered, and it was lost past the
    handler: candidate 3, and the fix belongs on the replica;
  • handler behind the changelog - the change is in the changelog and was never sent:
    candidate 2, which is what [#963] Read the changelog again for a following replica the domain is ahead of #964 addresses;
  • changelog itself short of the change - it was never published: candidate 1, and the fix
    belongs on the publish side.

Cost

The test tree only; no production code is touched. Everything read is already public, and
following is already a monitor attribute, so nothing had to be widened for this.

It runs on the failure path alone. It reads no file and waits on no peer -
getLatestServerState() walks the in-memory FileReplicaDB.getNewestCSN() of each replica -
and ReplicationServer.getAllInstances() is empty for every test which starts no replication
server, so those append nothing. A throwable it meets is reported into the buffer rather than
thrown: a diagnostic must leave the failure it was called to describe as it found it.

The monitor of a handler carries some thirty attributes, printed one per line. The first version
printed MonitorData as it renders itself, and a single line of some 1500 characters is where
the attribute which matters goes unread.

Testing

Watched on a forced failure: a temporary assertNotNull on a DN which does not exist, added to
ReSyncTest.testResyncAfterImport so that it fails with the topology still up. The dump appears
in the failure output ahead of the thread dump, and reads the way a resync which worked should -
the domain and the handler both at seqnum 2, following true, the queue empty. The temporary
assertion was then removed.

ReSyncTest, ReplicationServerShutdownSyncTest, DSRSShutdownSyncTest: 22 tests, no failures.

…when a test fails

A test which fails waiting for a change that never arrived cannot be diagnosed from the
logs the harness already dumps: they say what the replica applied, not what the replication
server held for it. ReSyncTest has failed that way five times, and every occurrence left
the same three candidates open - the change never reached the changelog, it reached it and
the cursor missed it, or it was sent and lost on the replica - because nothing in the dump
tells them apart. The thread dump cannot: a handler which was never given a change and one
which was given it and sent it both end up following an empty queue.

Two states separate them, and the local replication server holds both in memory.
ReplicationServerDomain.getLatestServerState() is the newest CSN the changelog has per
replica; MessageHandler.getServerState() is what a handler has handed its consumer. The
handler level with the domain means the change was delivered and lost past the handler, the
handler behind it means the change is in the changelog and was never sent, and both short of
the change mean it was never published at all - and those have their fix in opposite places.

TestListener.appendFailureInfo() is where the failure dump is assembled, so
TestCaseUtils.appendReplicationServersState() joins it there and covers a failed
configuration method as well as a failed test. It reads no file and waits on no peer -
getDomainNewestCSNs() walks the in-memory FileReplicaDB of each replica - it runs on the
failure path only, and the registry it walks is empty for every test which starts no
replication server. A throwable it meets is reported into the buffer rather than thrown: a
diagnostic must leave the failure it was called to describe as it found it.

The monitor of a handler carries some thirty attributes and is printed one per line. On one
line it is where the attribute which matters goes unread.

Watched on a forced failure of ReSyncTest.testResyncAfterImport with the topology up: the
domain and the handler both at seqnum 2, following true, queue empty, which is the shape of
a resync that worked. ReSyncTest, ReplicationServerShutdownSyncTest and DSRSShutdownSyncTest:
22 tests, no failures.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

enhancement replication tests Test suites: fixing, enabling, un-disabling

Projects

None yet

Development

Successfully merging this pull request may close these issues.

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

1 participant