[#802] Fail fast when the replication server cannot read its changelog - #805
[#802] Fail fast when the replication server cannot read its changelog#805vharseko wants to merge 3 commits into
Conversation
maximthomas
left a comment
There was a problem hiding this comment.
One code change requested, plus two items to confirm before merge.
Aborted initialization leaks the per-domain timer thread (medium)
FileChangelogDB.initializeToChangelogState() calls getReplicationServerDomain(dn, true) for every restored domain, and each ReplicationServerDomain constructor starts an assuredTimeoutTimer thread. abortInitialization() does not do what shutdown() does — cancel them:
// ReplicationServer.shutdown(), missing from abortInitialization()
for (ReplicationServerDomain domain : getReplicationServerDomains())
{
domain.shutdown();
}Reproduced with a probe (changelog holding one domain, second RS whose listen port is taken):
assuredTimers baseline=[]
assuredTimers after =[Replication server RS(1) assured timer for domain "o=test"]
This is guaranteed, not an edge case: loop 1 of initializeToChangelogState() cannot throw (getReplicationServerDomain and initGenerationID are both non-throwing), so every partial-restore failure happens after all domains were created. It also affects the listen-port abort from #795, where initializeDB() succeeded and all domains exist. Adding the loop at the top of abortInitialization() is safe on a partially constructed instance — baseDNs is initialized at its declaration.
File: opendj-server-legacy/src/main/java/org/opends/server/replication/server/ReplicationServer.java
Startup semantics change needs an explicit sign-off (discussion)
Confirmed that the ConfigException propagates uncaught: MultimasterReplication.initializeSynchronizationProvider() → SynchronizationProviderConfigManager.initializeSynchronizationProviders() → DirectoryServer.startServer(). A corrupted changelog — a rebuildable structure, unlike the user backends — now stops the whole directory server, including its ability to serve reads. That is a strictly larger blast radius than the existing ERR_CHANGELOG_SHUTDOWN_DATABASE_ERROR path, which shuts down only the replication server.
The choice is defensible and consistent with #795, but since #795 and #805 together change directory-server startup behaviour, this warrants a maintainer's explicit decision plus a release-note entry rather than landing as an implementation detail.
Test covers one of the three documented failure shapes (low)
replServerFailsWhenChangelogCannotBeRead corrupts domains.state, which fails the ReplicationEnvironment constructor before any domain is created — the cleanest shape. Shape 2 from the PR description (partial restore) and shape 3 (indexer/purger) are uncovered, and shape 2 is the one that exposes the timer leak above. A fixture with a valid domains.state plus a corrupted per-domain state would cover it; assert on thread names containing assured timer for domain, not on DirectoryServer.getMonitorProviders() (see the last nit).
File: opendj-server-legacy/src/test/java/org/opends/server/replication/server/ReplicationServerDynamicConfTest.java
Nits
- msgID 11 disappears from the logs: not logging at the throw site is right, but
ERR_COULD_NOT_READ_DBhad exactly one logging site and it is now removed. The text reaches the operator only insideERR_CONFIG_SYNCH_ERROR_INITIALIZING_PROVIDER, rendered throughstackTraceToSingleLineString()— CONFIG category, single-line stack trace. Worth a line in the release note for anyone alerting on msgID 11. ChangelogDB.initializeDB()signature: adding a checked exception is source-incompatible for out-of-tree implementers. Nothing in-tree breaks, but it belongs in the changelog.switchListenPort()interrupt window (carried from #795):stopListenThread()closeslistenSocketbeforelistenThread.join(). If the join is interrupted, the catch restoresconfig/serverURLand closes the new socket, but nothing rebinds — the RS is left with no listener at all, which is the state this series set out to eliminate. Narrow, but the comment there describes the thread, not the released port.- Comment volume: the blocks in
initializeDB()andinitialize()(6 and 4 lines) largely restate the PR description; a sentence plus the issue reference would read better. - Pre-existing, not this PR: two monitor providers also leak here, but they leak identically on the normal
shutdown()path (probed with no abort involved:replication server rs(3) null,cn=o_test,...). Cause is separate —getMonitorInstanceName()embedsserverURL, which isnullwhileinitializeDB()registers and non-null whenderegisterMonitorProvider()looks the name up, so the key never matches. Worth its own issue; the loop requested above does not fix it.
|
Thanks — all of it addressed in the last commit, including the two items you left as Aborted initialization leaks the per-domain timer threadConfirmed and fixed: Your reading of Startup semantics change needs an explicit sign-offSigned off: a replication server which cannot read its changelog fails to start, and takes Test covers one of the three documented failure shapesShape 2 is covered now, by Two more tests come with it: Both were checked against the unfixed code: with the loop removed from Shape 3 is still uncovered on purpose: it needs Nits
|
…ot read its changelog FileChangelogDB.initializeDB() caught ChangelogException and only logged ERR_COULD_NOT_READ_DB, whose text already says the replication server failed to start. It did start: ReplicationServer.initialize() went on to bind the listen port and start its threads over a changelog it never opened, so the failure surfaced much later and somewhere else - as a failure on the first update to be persisted when the replication environment does not exist at all, or as a domain adopting the generation id of the first replica to connect over a changelog which holds another generation. initializeDB() now declares ChangelogException, FileChangelogDB wraps the cause in the same localized ERR_COULD_NOT_READ_DB message and rethrows it, and initialize() reports it as a ConfigException, exactly like a listen port which cannot be bound. The constructor already releases a half initialized instance through abortInitialization(), which shuts the changelog DB down. ReplicationServerDynamicConfTest.replServerFailsWhenChangelogCannotBeRead covers it: a corrupted domains.state makes the creation fail with a ConfigException naming the changelog directory, leaves no instance registered and no listen port bound.
…hangelog read Reading the changelog restores one ReplicationServerDomain per domain it holds, and each of them starts its assured timer thread and registers its monitor provider. Every failure of that reading happens after that first loop, and so does a listen port which cannot be bound: abortInitialization() now shuts those domains down, as shutdown() does. The monitor instance name of a domain, and of its changelog, embeds the URL of its replication server, which was assigned only after the changelog had been read: the restored domains registered under a name holding a null URL, which no later lookup could match, so they leaked on the normal shutdown path too. setServerURL() now runs first. The listen thread owns the socket it was started on instead of reaching for the current one through a shared stopListen flag, so a port change starts the new listener before it stops the previous one. An interrupted wait for the previous listen thread can no longer leave the replication server with no listener at all.
83b9e25 to
ec16a29
Compare
maximthomas
left a comment
There was a problem hiding this comment.
All round-4 items are addressed — the abortInitialization() loop, the setServerURL() reordering that root-causes the monitor leak, shape 2 coverage, and the switchListenPort() interrupt window fixed rather than documented. One blocker before merge: 3 of 9 build jobs fail, in this PR's own test helper.
The changelog wait matches the change number index, not the replica (blocker)
ReplicationServerDynamicConfTest.createPopulatedChangelog() waits for the published change to be persisted:
// opendj-server-legacy/src/test/java/org/opends/server/replication/server/ReplicationServerDynamicConfTest.java:509
waitFor(dbDirectory, "head", ".log");findFile recurses from the changelog root, so this matches <changelogDb>/changenumberindex/head.log. That file already exists: ReplServerFakeConfiguration:71-73 rewrites purgeDelay = 0 into 24 h, so FileChangelogDB.initializeDB():293 always reaches startCNPurger(), and ChangelogDBPurger.run():897-898 opens the CN index DB as its first statement.
A probe at :509 printed the same thing on every invocation, on every JVM, including runs where all 9 tests passed:
waitFor-matched=changenumberindex/head.log generationIdFile=<none>
tree=[changenumberindex changenumberindex/head.log]
The wait is a no-op, so stop(broker) and replicationServer.shutdown() at :513-514 race the persistence of the change instead of following it. Both resulting shapes are in CI:
| Job | Failing tests | Assertion |
|---|---|---|
| ubuntu 21 | replServerFailsWhenAReplicaChangelogCannotBeRead, restartedReplServerReleasesTheRestoredDomains |
:517 and :521→:539 |
| ubuntu 25 | abortedStartReleasesTheRestoredDomains, restartedReplServerReleasesTheRestoredDomains |
:517 and :521→:539 |
| ubuntu 26 | restartedReplServerReleasesTheRestoredDomains |
:517 |
:343 uses the same unscoped lookup to pick the file it replaces with a directory, so it can corrupt the change number index instead of the replica changelog — the test then passes while exercising a different failure shape than its javadoc claims.
Scoping the lookup to domain directories fixes both. ReplicationEnvironment.getOrCreateReplicaDB():352-372 writes domains.state → <serverId>.server/ → generation<id>.id → head.log, so the replica changelog is last of the four and waiting for it makes the other three exist:
private static final String DOMAIN_DIRECTORY_SUFFIX = ".dom";
/** Returns the head log file of a replica changelog, i.e. the one under a domain directory. */
private File findReplicaLogFile(File dbDirectory)
{
final File[] entries = dbDirectory.listFiles();
if (entries == null)
{
return null;
}
for (File entry : entries)
{
if (entry.isDirectory() && entry.getName().endsWith(DOMAIN_DIRECTORY_SUFFIX))
{
final File replicaLogFile = findFile(entry, "head", ".log");
if (replicaLogFile != null)
{
return replicaLogFile;
}
}
}
return null;
}with waitFor replaced by a waitForReplicaLogFile polling on it, and the call at :343 switched to findReplicaLogFile. Verified: asserting the invariant at :509 reproduces CI's exact message on the unfixed helper (2 of 9 failing), and the fixed helper is 9/9 green, 3482/0 for org.opends.server.replication.**.*Test.
A replica DB created during shutdown leaks its monitor provider (medium)
The :521 failures report found [1] — exactly one leftover registration. That identifies it: FileChangeNumberIndexDB's monitor is "ChangeNumber Index Database" and ReplicationServer's is "Replication Server <port> <id>", so neither matches the test's replication server rs(<id>) filter; a leaked ReplicationServerDomain would leave two entries, because assuredTimeoutTimer is created unconditionally in its constructor. Only a FileReplicaDB monitor leaves one, and its sole deregistration site is FileReplicaDB.shutdown():221, reachable only from the drain in shutdownDB(). A surviving registration therefore proves the DB was absent from domainToReplicaDBs when the drain ran.
In FileChangelogDB, getOrCreateReplicaDB():193 checks the shutdown flag before getExistingOrNewDomainMap() inserts the domain map at :230, so an insertion can land after shutdownDB():359 has already drained. Corroborated in CI by msgID 274 (Log.releaseLog(), "must be released but it is not referenced") on 1.dom/42.server.
One line closes it, inside the existing synchronized (domainMap) block:
// opendj-server-legacy/src/main/java/org/opends/server/replication/server/changelog/file/FileChangelogDB.java:266
if (domainToReplicaDBs.get(baseDN) != domainMap)
{
return null;
}
if (shutdown.get())
{ // a shutdown was initiated after the domain map was inserted: it would not be drained
return null;
}Reading false under that lock means shutdownDB()'s CAS at :336 has not run, so its iterator at :359 does not exist yet, so it will see the map — inserted before the lock was taken — and must block on the same monitor to drain it. Reading true returns null, and the loop at :193 throws ERR_CANNOT_CREATE_REPLICA_DB_BECAUSE_CHANGELOG_DB_SHUTDOWN, which is the intended behaviour. There is one insertion site and two removal sites, so the case analysis is complete.
This predates the PR and the fix above stops these tests from reaching it, so its own issue is fine.
Nits
- msgID 71 is now dead:
ERR_COULD_NOT_STOP_LISTEN_THREADhas zero call sites after theswitchListenPort()rework, but remains inReplicationMessages.javaand nine locale files. Same release-note treatment as msgID 11, or drop it. - Double-listen window: both ports accept between
startListenThread(newListenSocket)atReplicationServer.java:667andclose(previousListenSocket)at:671, andlocalPortsstill names only the old port. A peer connecting to the old port in that window gets a session that outlives the change. This is the inverse trade of the bug being fixed and it is the right one, but the javadoc's "there is nothing to roll back" should say so. replServerKeepsListeningWhenAPortChangeIsInterrupteddoes not reliably exercise the interrupt path:Thread.join()only throws whileisAlive(). If the previous listen thread has already exited,join()returns without throwing and the pre-set flag is never cleared, soassertTrue(interrupted)passes without the catch block running. Verified on JDK 26:join()on a terminated thread with the interrupt set givesthrew=false, interruptStillSet=true. Assert on something only the catch produces.abortInitialization()robustness: an unchecked throw fromdomain.shutdown()atReplicationServer.java:781-784skipsshutdownExternalChangelog()andchangelogDB.shutdownDB().shutdown()has the same shape, but on the abort path the changelog is known broken, which makes it likelier.
…l-fast changelog read The changelog of the change number index holds a head log file of its own, created when the replication server starts, so the unscoped lookup in the test helper could match it instead of the log of the replica: the wait then waited for nothing and the corruption hit the wrong log. The lookup is now scoped to the domain directories, and the test asserts that the failure names the replica log it corrupted, so it cannot pass while exercising another failure shape. A port change whose wait for the previous listen thread is interrupted is now exercised rather than passed over: Thread.join() only throws while the thread it waits for is alive, so the test keeps that thread in its handshake with a connection which says nothing, and asserts the counter which only the interrupted path increments. abortInitialization() shuts each restored domain down on its own, so that an unchecked failure of one of them does not skip the changelog shutdown which follows.
|
Blocker confirmed and fixed, and it was worse than the review says. Everything else is in too. The changelog wait matched the change number indexReproduced the whole chain: One addition to the diagnosis. Where the review says the test "passes while exercising a Fixed as proposed: On top of that the test now asserts that the failure names the log it corrupted, so it cannot
The replica DB created during shutdownAgreed, and filed as #813 with your analysis and your patch. Two corrections which do not
Nits
Tests |
Fixes #802.
Builds on #795, now merged: the cleanup of a half initialized replication server
(
abortInitialization()) comes from there. Rebased onmaster, so this PR carries only itsown commits.
Problem
FileChangelogDB.initializeDB()caughtChangelogExceptionand only loggedERR_COULD_NOT_READ_DB— a message whose own text says "The replication server failed tostart because the database %s could not be read". It did start:
ReplicationServer.initialize()went on to bind the listen port and start its threads, so areplication server whose changelog could not be read accepted connections and replication
traffic, and the failure surfaced later, somewhere else. Three distinct shapes, depending on
where the read failed:
ReplicationEnvironmentcould not be created at all (unreadable or incoherentdomains.state, corruptedoffline.state):replicationEnvstaysnulland the rest ofFileChangelogDBdereferences it unguarded. The first update to persist ends in aNullPointerExceptioninFileReplicaDB.createLog()— and because that is not aChangelogException, it does not even reach the handler inReplicationServerDomain.publishUpdateMsg(), which exists precisely to shut the replicationserver down when the changelog cannot be written (
ERR_CHANGELOG_SHUTDOWN_DATABASE_ERROR).applyConfigurationChange()hits the samenullthroughsetPurgeDelay().their generation id, the others did not. For those,
setGenerationIdIfUnset()then adoptsthe generation id of the first replica to connect — without clearing the changelog, which
changeGenerationId()does — over on-disk logs which belong to another generation, andgetOrCreateReplicaDB()writes a secondgeneration<id>.idfile next to the existing one.On the next start
retrieveGenerationIdFile()picksgenerationIds[0], i.e. whichever thefile system returns first.
cn=changelogsilently answers from anindex which is not maintained, and the changelog is never purged.
Changes
ChangelogDB.initializeDB()declaresthrows ChangelogException, and documents that theDB may be left half open and must then be released with
shutdownDB().FileChangelogDB.initializeDB()wraps the cause in the same localizedERR_COULD_NOT_READ_DBmessage — which already names the changelog directory — andrethrows it instead of logging it. Logging happens once, where the failure is reported.
ReplicationServer.initialize()reports it as aConfigException, exactly like a listenport which cannot be bound. The constructor already routes that through
abortInitialization(), so no half initialized instance is left behind.abortInitialization()shuts the restored domains down, asshutdown()does. Reading thechangelog restores one
ReplicationServerDomainper domain it holds, and each of themstarts its assured timer and its status analyzer threads, and registers its monitor
provider —
getReplicationServerDomain()callsstart()since Fix CodeQL warning-severity alerts: missed wakeups, resource leaks, escaping threads #790. Every failure of thatreading happens after that first loop —
getReplicationServerDomain()andinitGenerationID()cannot throw — and so does a listen port which cannot be bound, soboth aborts used to leave those domains behind. One domain at a time, so that an unchecked
failure of one of them does not skip the changelog shutdown which follows it.
setServerURL()runs before the changelog is read. The monitor instance name of a domain,and of its changelog, embeds the URL of its replication server, which used to be assigned
only after the changelog had been read: the domains restored from it registered under a
name holding a null URL, and the name looked up to deregister them, built from the assigned
URL, could never match it again. That leaked their monitor providers on the normal
shutdown()path too, i.e. on every restart over an existing changelog.one through a shared
stopListenflag. A port change can then start the new listenerbefore it stops the previous one, so an interrupted wait for the previous listen thread —
which used to close the current listen socket, fail the change and rebind nothing — can no
longer leave the replication server with no listener at all.
FileChangelogDBis the only implementation andReplicationServer.initialize()the onlycaller; the
ChangelogDBused inChangeNumberIndexerTestis a Mockito mock, unaffected bythe new
throws.Upgrade note
Same shape as the one in #795, for the changelog instead of the listen port. Three points for
the release note:
the directory server. The
ConfigExceptionpropagates fromMultimasterReplication.initializeSynchronizationProvider()throughSynchronizationProviderConfigManager.initializeSynchronizationProviders()toDirectoryServer.startServer(). Previously such a server came up degraded, without a usablechangelog, and the failure surfaced later and somewhere else. This is a larger blast radius
than the existing
ERR_CHANGELOG_SHUTDOWN_DATABASE_ERRORpath, which stops the replicationserver only. The operator's remedy is the one the message already points at: repair or
remove the changelog directory named in
ERR_COULD_NOT_READ_DB.ERR_COULD_NOT_READ_DBhad exactly one logging site, inFileChangelogDB.initializeDB(), and it is now thrown instead. Its text still reaches thelog, but inside
ERR_CONFIG_SYNCH_ERROR_INITIALIZING_PROVIDER— CONFIG category, renderedthrough
stackTraceToSingleLineString(). Anyone alerting on msgID 11 has to follow itthere.
ERR_COULD_NOT_STOP_LISTEN_THREADreported a portchange which gave up on its listen thread, and a port change no longer gives up: the new
listener is already serving when the previous one is stopped, so an interrupted wait is not
a failure of the change. The message is kept, with its translations, for the release which
removes it from the logs.
ChangelogDB.initializeDB()declaresthrows ChangelogException. Source incompatiblefor out-of-tree implementations of that interface.
Tests
ReplicationServerDynamicConfTest:replServerFailsWhenChangelogCannotBeRead: the first shape, a corrupteddomains.state.The creation fails with a
ConfigExceptionwhose cause is theChangelogExceptionandwhose message names the changelog directory, leaves no instance registered in
ReplicationServer.getAllInstances(), and leaves the listen port free — it is never boundwhen the changelog cannot be read.
replServerFailsWhenAReplicaChangelogCannotBeRead: the second shape, a partial restore.The changelog of a replication server which ran and served one replica has the head log
file of that replica replaced by a directory, so its state is still readable and the changes
of the domain it names are not. The failure then happens after the domain was restored, and
that domain is left neither running nor registered. The changelog of the change number
index holds a head log file of its own, created when the replication server starts, so the
lookup which picks the file to corrupt is scoped to the domain directories, and the test
asserts that the failure names the log it corrupted: it cannot pass while exercising
another failure shape.
abortedStartReleasesTheRestoredDomains: the same changelog, a listen port which is taken.The changelog is read, its domain restored, the bind fails, and the domain is released.
restartedReplServerReleasesTheRestoredDomains: the same changelog, a free port. Thereplication server starts, its restored domain is registered — asserted, so that the test
cannot pass by testing nothing — and stopping it deregisters the domain again.
replServerKeepsListeningWhenAPortChangeIsInterrupted: the interrupt status is set beforethe port change, so its wait for the previous listen thread fails at once. The change
succeeds, the replication server listens on the new port and serves a broker on it.
Thread.join()only throws while the thread it waits for is alive, so the test first keepsthat thread in its handshake with a connection which says nothing, and asserts
interruptedListenThreadStops, which only the interrupted path increments: the test cannotpass over the interruption it is named after.
The two tests which cover the released domains were checked against the unfixed code: with
the loop removed from
abortInitialization(), each of them reports the registrations therestored domain left behind.
The whole replication package passes as well:
Follow-up
#813, found while these tests were being stabilised: a
FileReplicaDBcreated while thechangelog is shutting down is never released, so its monitor provider stays registered and
its log stays referenced. It predates this PR, and the domain-scoped wait added here stops
these tests from racing into it.