[#841] Fix flaky InitOnLineTest: notify the requester when a remotely requested export cannot start

[vharseko]

Fixes #841

Production fix

When a total update is requested by a remote replica (InitializeRequestMsg, no local task), a failure before the export starts was thrown without notifying anyone, and the requester kept waiting for an InitializeTargetMsg that never came. This covers:

• the requester missing from the exporter's replicas view - exactly what happens when the request races the topology propagation,
• an import/export already in progress on the exporter (acquireIEContext), and
• a backend that cannot be exported: countEntries() is now probed before acquiring the import/export context, so ERR_INIT_EXPORT_NOT_SUPPORTED is reported like the other rejections instead of escaping past them; the probed value is threaded into the export itself, dropping the repeated counts.

ReplicationDomain.initializeRemote now sends the failure back to the requester as an ErrorMsg, the same way the routing failure paths already do - best effort: only while the broker is connected (a disconnected requester detects the disconnection instead), and gated on the exact ExportTask contract (no local task, a concrete target, a remote requester), so a hypothetical local initializeRemote(ALL_SERVERS, null) caller cannot fan an ErrorMsg(ALL_SERVERS) out to the whole topology. The rejection is also logged on the exporter (new NOTE_FULL_UPDATE_REMOTE_REQUEST_REJECTED message). The task-initiated path is unchanged: there the local task reports the error and no remote is waiting.

Known limitations, both pre-existing gates the notification leans on:

• ErrorMsg.creationTime is stamped with the exporter's wall clock (transmitted verbatim for protocol V4+), while the requester's processErrorMsg compares it against its own clock (creationTime > ieCtx.startTime). Across hosts, an exporter whose clock lags by more than the request round-trip gets its rejection discarded as stale and the requester falls back to waiting. A bounded wait in InitializeTask is the durable fix - follow-up material.
• when the requester is not routable, the replication server bounces the rejection back to the exporter as ErrorMsg(ERR_NO_REACHABLE_PEER), which is applied to whatever import/export context is live there - ErrorMsg carries no correlation id to guard on. Narrow in practice (the RS learns of a new replica before its DSs do), documented in the comment block.

Why the test hung for the full 600 s

initializeExportMultiSS published the InitializeRequestMsg right after connecting the brokers, so it could race the TopologyMsg propagation (RS3 -> RS1 -> DS1). When it lost the race, waitForInitializeTargetMsg waited forever:

• the loop ignored ErrorMsg and null;
• the 10 s broker soTimeout never fired, because the replication server publishes a MonitorMsg every 3 s and ReplicationBroker.receive() consumes it internally, resetting the socket timer each time.

TestNG then abandoned the timed-out thread (a blocking socket read does not respond to interrupt), the finally cleanup never ran, the replication servers kept their ports bound and the cached port poisoned the next test - the BindException in initializeImport from the issue.

Test changes

• initializeExport / initializeExportMultiSS wait for the local domain to see the requester in its topology view (waitForRemoteReplicas) before publishing the InitializeRequestMsg;
• waitForInitializeTargetMsg fails fast on ErrorMsg and on a closed connection - the common paths now that the exporter answers. The extra 60 s deadline is only a backstop: it cannot fire while ReplicationBroker.receive() keeps consuming the periodic monitoring traffic internally;
• new InitOnLineTest.releaseLeakedReplicationServers (@AfterMethod, runs on the main thread - TestNG still runs configuration methods after a thread timeout) releases everything a timed out test method left behind: the domain config entry, the brokers, the replication servers and the cached ports. It neutralises the shared fields before closing the leaked sessions - the close unblocks the abandoned test thread, whose own finally{afterTest()} would otherwise clean up the next test method; afterTest early-returns on the releasedByAfterMethod flag (reset in @BeforeMethod, so later methods keep cleaning up after themselves). The net never throws: with configfailurepolicy=skip one cleanup failure would silently skip the rest of the class;
• new ReplicationDomainTest.remotelyRequestedExportFailureNotifiesRequester deterministically covers the new notification: a second remotely requested export is rejected while the first one holds the import/export context, and the requester receives the ErrorMsg;
• new ReplicationDomainTest.remotelyRequestedExportForUnknownReplicaIsRejected covers the ERR_FULL_UPDATE_MISSING_REMOTE rejection itself (no leaked import/export context); the ErrorMsg delivery cannot be asserted deterministically on this branch - the replication server does not route to a replica it does not know, and a requester connected yet still unknown to the exporter is exactly the race.

Testing

mvn -pl opendj-server-legacy -Pprecommit verify "-Dit.test=InitOnLineTest,ReplicationDomainTest": 20/20 green - InitOnLineTest 10/10 in 63 s, ReplicationDomainTest 10/10 in 68 s.

The @AfterMethod net was exercised for real, not just by the green run: with org.opends.test.timeout temporarily lowered to 60 s and a scratch @Test(priority = -1) blocking in receive() (mirroring the shape of a real timed out method, including the finally{afterTest()}), the scratch method is abandoned on ThreadTimeoutException, the net logs Releasing the replication servers leaked by a timed out test, and the remaining 10 methods of the class all pass - the #841 cascade, closed end to end.

Related: #800 / #803 (replication test listen port allocation), #730 (import/export context leak on failed validation).

[maximthomas]

The fix is correct and worth more than the title suggests: without the ErrorMsg the requester's InitializeTask.runTask parks in while (initState == RUNNING) initStateLock.wait(1000) with no deadline, so a real dsreplication initialize hangs forever, not just the test. I verified ErrorMsg.creationTime is serialized for protocol V4+, so the creationTime > ieCtx.startTime gate in processErrorMsg passes and the notification is actually honoured. Two things to change before merge.

countEntries() is still outside the notified region (medium)

opendj-server-legacy/src/main/java/org/opends/server/replication/service/ReplicationDomain.java:1532,1546 call countEntries() after acquireIEContext succeeds but before the attempt-loop try at :1560. That window is covered neither by the new catch nor by the existing publish at :1663 — the same hang, one line further down. LDAPReplicationDomain.countEntries() throws ERR_INIT_EXPORT_NOT_SUPPORTED deterministically for a backend without LDIF-export support, so a remotely requested total update against such a backend still leaves the requester waiting forever.

Probing it inside the guarded block reports the failure and cannot leak the context, since it runs before the acquire:

      // countEntries() is called by initializeRemote(ieCtx, ...) outside the
      // region that reports the failure to the requester: probe it here so a
      // backend that cannot be exported is notified like any other rejection.
      countEntries();

      ieCtx = acquireIEContext(false);

(Threading the counted value into the private initializeRemote(ieCtx, ...) overload and dropping the two calls would be tidier, but touches a signature.)

initTask == null is not equivalent to "requested by a remote server" (medium)

ReplicationDomain.java:1484. The public initializeRemote(int target, Task initTask) accepts a null task, and ALL_SERVERS reaches the same catch via ERR_FULL_UPDATE_NO_REMOTES and via acquireIEContext. The message then carries destination = ALL_SERVERS (-2), which ReplicationServerDomain.getDestinationServers:1322-1346 fans out to every connected DS and every peer RS; each recipient's processErrorMsg applies it to whatever ImportExportContext is live, aborting an unrelated total update. Nobody is waiting for a reply on that path.

No in-tree caller reaches it today (InitializeTargetTask always passes a non-null task, ExportThread always a concrete serverId), so this is a latent API hazard — but the gate is two lines and matches the ExportThread contract exactly, where serverRunningTheTask == serverToInitialize == requester:

      if (initTask == null
          && serverToInitialize != RoutableMsg.ALL_SERVERS
          && serverRunningTheTask != getServerId())

The 60 s / 30 s deadlines cannot fire (low)

Both new loops check the deadline only after receive() returns, but the hang you diagnosed is receive() never returning: it consumes MonitorMsg/TopologyMsg/WindowMsg internally and loops, and the RS sends a MonitorMsg to every connected DS every 3 s (ReplServerFakeConfiguration monitoringPeriod), inside the 10 s soTimeout. The guards do catch the ErrorMsg and closed-connection cases, which is the common path now — but "fails fast after 60 s, so the cleanup in finally runs" does not hold, and #841's second half (a timed-out method leaving its ports bound) stays open.

A net that survives a method timeout has to live outside the test thread — TestNG still runs configuration methods after ThreadTimeout, and there is no @AfterMethod in ReplicationTestCase today. Narrow enough not to disturb passing tests, in opendj-server-legacy/src/test/java/org/opends/server/replication/InitOnLineTest.java:

  @AfterMethod(alwaysRun = true)
  public void releaseLeakedReplicationServers() throws Exception
  {
    if (replServer1 == null && replServer2 == null && replServer3 == null)
    {
      // the test method cleaned up after itself
      return;
    }
    log("Releasing the replication servers leaked by a timed out test");
    stop(server2, server3);
    server2 = server3 = null;
    remove(replServer1, replServer2, replServer3);
    replServer1 = replServer2 = replServer3 = null;
    replDomain = null;
    Arrays.fill(replServerPort, 0);
  }

Fine as a follow-up to #800 / #803 if you prefer — but please soften the claim in the PR description either way.

Nits

• Assert before cleanup: in opendj-server-legacy/src/test/java/org/opends/server/replication/service/ReplicationDomainTest.java:554, assertFalse(firstExport.isAlive(), ...) precedes disable(domain1) / remove(replServer), so a slow export thread would abort the rest of the finally and leak the domain and the listen port into the next tests — the cascade #841 is about. In practice the thread ends ~1 s after stop(broker2), so it is the ordering that is wrong, not the timing. InitOnLineTest.afterTest:1401-1404 documents the safe shape: capture into a boolean, clean up, assert last.
• No isConnected() guard: ReplicationBroker.publish:2246-2393 loops with no sleep for a non-UpdateMsg while the session is null and connectionError is not yet set. The sibling path at ReplicationDomain.java:1663 waits up to 10 s for reconnection first; the new one publishes unconditionally. Skipping the notification while disconnected is safe — the requester then fails on ERR_INIT_EXPORTER_DISCONNECTION via the TopologyMsg branch of receiveEntryBytes.
• Fractional override bypass: LDAPReplicationDomain.initializeRemote:1513-1523 throws before delegating to super, so it skips the notification. Unreachable from a remote request today (ALL_SERVERS-only), but worth keeping in sync if the gate above lands.
• Untested branch: the new test covers only the acquireIEContext rejection. ERR_FULL_UPDATE_MISSING_REMOTE — the actual #841 trigger — is only avoided via waitForRemoteReplicas. Direct cover is cheap: initializeRemote(<unknown id>, <unknown id>, NO_INIT_TASK, 100) on a domain with a connected broker, assert the broker receives it.
• waitForRemoteReplicas is weaker than the guard: it checks containsKey, while getDsInfoOrNull:1708-1719 also requires protocolVersion >= V4. Fine for these brokers.
• Silent on the exporter: the ExportThread catch logs at trace only, so an admin sees the failure on the requester but no cause on the exporter. A logger.info in the new catch would close the loop.

[vharseko]

Thanks - all points addressed in cff81f9:

• countEntries() is now probed inside the guarded block before acquireIEContext (your first variant; threading the counted value through the private overload felt heavier than the remaining theoretical window where a later countEntries() call fails after the probe succeeded).
• The gate now matches the ExportThread contract exactly: initTask == null && serverToInitialize != ALL_SERVERS && serverRunningTheTask != getServerId(). Note this also closes the fractional-override nit by itself - LDAPReplicationDomain.initializeRemote throws before super only for ALL_SERVERS, which the gate excludes from the notification anyway, so there is nothing left to keep in sync there.
• Added the isConnected() guard and an exporter-side logger.info (new NOTE_FULL_UPDATE_REMOTE_REQUEST_REJECTED message), so the admin sees the cause on both ends.
• Test finally reordered (capture into a boolean, clean up, assert last, as in afterTest).
• Took your @AfterMethod net into this PR rather than a follow-up - it is the piece that actually stops a timed out method from poisoning the class. The PR description no longer claims the 60 s deadline releases the ports: you are right that receive() never returns while it consumes the monitoring traffic internally, so the deadline stays as a cheap backstop only.
• On the ERR_FULL_UPDATE_MISSING_REMOTE direct cover: asserting the delivery deterministically turned out not to be possible - ReplicationServerDomain.getDestinationServers does not route to a destination absent from connectedDSs (the sender gets ERR_NO_REACHABLE_PEER back instead), and a requester that is connected yet still unknown to the exporter is exactly the race window. Added remotelyRequestedExportForUnknownReplicaIsRejected covering what is deterministic: the rejection itself and that it does not leak the import/export context; the publish path is shared with the acquireIEContext branch the other test covers end to end.

mvn -pl opendj-server-legacy -Pprecommit verify "-Dit.test=InitOnLineTest,ReplicationDomainTest": 20/20 green.

[maximthomas]

All six points from the last round are addressed, and the production fix is right: the gate matches the ExportTask call site exactly, no rejection path can leak the import/export context, and the hang it fixes is real and unbounded (InitializeTask.runTask waits on initStateLock with no deadline). I'd merge that half as is.

Everything blocking is in the new @AfterMethod net — and it is load-bearing, so it has to be right. I checked whether the 60 s deadline could make it unnecessary: it cannot fire. HeartbeatThread:98 only publishes when nothing else was sent on the session within the interval, and the RS pushes a MonitorMsg every 3 s (ReplServerFakeConfiguration:61), which ReplicationBroker.receive() consumes internally. receive() never returns, so the loop body — and the deadline check — never runs. Only the config method can recover a timed-out test.

The net resurrects the abandoned test thread, which then cleans up the next test (blocker)

opendj-server-legacy/src/test/java/org/opends/server/replication/InitOnLineTest.java:1447. stop(server2, server3) closes the session the timed-out thread is blocked on (ReplicationBroker.stop() → setConnectedRS(stopped()) → session.close()), receive() returns null, the new fail(...) at :1096 throws, and the thread runs its own finally { afterTest(testCase); } — concurrently with the following @Test. afterTest touches only shared state: cleanConfigEntries(), stop(server2, server3), remove(replServer1..3), Arrays.fill(replServerPort, 0), entriesToCleanup. It has a 5 s ieRunning() wait up front (:1394), so it is routinely late enough to hit the next test.

Verified with a standalone TestNG run: the abandoned thread survives the timeout (a blocking socket read ignores interrupt()), @AfterMethod runs on main, and closing the socket there makes the zombie's finally overlap the next method.

Not stopping the brokers is not an escape — ReplicationServer.remove() closes the sessions too, and with the broker's own shutdown still false receive() enters reStart's infinite reconnect loop. Any working net wakes that thread, so it needs a guard it cannot race:

  private volatile boolean releasedByAfterMethod;

  @AfterMethod(alwaysRun = true)
  public void releaseLeakedReplicationServers()
  {
    if (replServer1 == null && replServer2 == null && replServer3 == null
        && server2 == null && server3 == null && replDomain == null)
    {
      return; // the test method cleaned up after itself
    }
    log("Releasing the replication servers leaked by a timed out test");
    // Neutralise the shared state *before* anything can wake the abandoned
    // test thread: stopping its broker unblocks receive(), and its own
    // finally{afterTest()} would otherwise clean up the *next* test.
    releasedByAfterMethod = true;
    final ReplicationBroker b2 = server2, b3 = server3;
    final ReplicationServer rs1 = replServer1, rs2 = replServer2, rs3 = replServer3;
    server2 = server3 = null;
    replServer1 = replServer2 = replServer3 = null;
    replDomain = null;
    Arrays.fill(replServerPort, 0);
    try
    {
      super.cleanConfigEntries();
      stop(b2, b3);
      remove(rs1, rs2, rs3);
    }
    catch (Throwable t)
    {
      // best effort: throwing here skips the rest of the class
      log("Failed to release the leaked replication servers: " + t);
    }
  }

  private void afterTest(String testCase) throws Exception
  {
    if (releasedByAfterMethod)
    {
      // a timed out method's thread, unblocked by releaseLeakedReplicationServers
      return;
    }
    ...

The flag is read on afterTest's first line and set before anything can wake the thread, so the ordering is one-directional. Reset it in a @BeforeMethod if you want later methods to keep using afterTest.

The net frees the ports but not the leaked domain config entry (blocker)

Without super.cleanConfigEntries(), the synchro-server entry added by connectServer1ToReplServer (InitOnLineTest.java:517) survives the timeout. The next method calls it again and ConfigurationHandler.addEntry:451-453 throws ENTRY_ALREADY_EXISTS. The cascade #841 is about is only half closed — initializeImport stops failing with BindException and starts failing on the config add. afterTest:1408 is the shape to mirror (included in the snippet above).

A throwing @AfterMethod skips the rest of the class (blocker)

opendj-server-legacy/pom.xml:1263 sets configfailurepolicy=skip. The net declares throws Exception and calls rs.remove() + getChangelogDB().removeDB() on servers an abandoned thread may still be using. Confirmed by direct run: 3 tests, 1 ran, 2 skipped — one failure silently becomes a whole-class skip. Hence the catch (Throwable) above.

The net is never exercised by the reported run (medium)

In 20/20 green every method cleans up after itself, so releaseLeakedReplicationServers takes the early return every time. Worth one manual validation: lower -Dorg.opends.test.timeout, or add a scratch method that blocks in receive(), and confirm the following methods still pass.

The notification depends on cross-host clock ordering (low)

ErrorMsg.creationTime is stamped with the exporter's wall clock and, for protocol V4+, transmitted verbatim (opendj-server-legacy/src/main/java/org/opends/server/replication/protocol/ErrorMsg.java:108-111), while the requester gates on errorMsg.getCreationTime() > ieCtx.startTime — its own clock, taken at acquireIEContext (ReplicationDomain.java:824, :1188). The gap between the two stamps is one hop plus validation, so an exporter whose clock is a few ms behind gets its ErrorMsg discarded as stale (logged as ERR_ERROR_MSG_RECEIVED) and the requester hangs exactly as before. Pre-existing gate, but the fix leans on it, and the new test cannot see it — both ends share one JVM clock. Worth a sentence in the PR; a bounded wait in InitializeTask is the durable fix, as a follow-up.

Nits

• Rebase: master 7af51501d5 renamed ExportThread → ExportTask; the new comment at ReplicationDomain.java:1495 still says "the ExportThread contract". Merges cleanly otherwise.
• The rejection can bounce: when the requester is not routable, ReplicationServerDomain.process:1461 → replyWithUnreachablePeerMsg:1517 sends ERR_NO_REACHABLE_PEER back to the exporter, whose listener applies any ErrorMsg to whatever context is live — so a rejection aimed at DS(2) can abort an in-flight total update to DS(3). Narrow (the RS learns of a new replica before its DSs do, so the notification is usually routable), and no cheap guard exists since ErrorMsg carries no correlation id — but worth a line in the comment block.
• Residual countEntries() window: ReplicationDomain.java:1546 / :1560 still call it outside any notified region. Passing the probed value into the private overload would close it and drop two redundant transactions.
• Early-return condition: the net returns when the three replServer* are null, so a method that times out after opening brokers or adding the domain config but before creating an RS leaks those (covered by the extended condition above).
• Message wording: neighbours read Cannot start total update in domain "%s" from this directory server DS(%d): … (opendj-server-legacy/src/messages/org/opends/messages/replication.properties, _298/_299); _306 inverts the order, and its %s detail re-renders the domain and both server ids.

[vharseko]

Thanks - all points addressed in 516c039 (rebased on master):

• The net now neutralises every shared field before closing the leaked sessions, and afterTest early-returns on the volatile releasedByAfterMethod flag - your snippet, plus the @BeforeMethod reset so later methods keep cleaning up after themselves. The residual window of the reset variant (the woken thread would have to sleep through the rest of the @AfterMethod, TestNG's bookkeeping and the next @BeforeMethod before reading the flag) is accepted as theoretical: closing it entirely needs a per-method generation token captured in each of the 15 test methods.
• super.cleanConfigEntries() included - in its own try, so a failure to remove the leaked domain config still releases the ports.
• The net never throws: each step wrapped in catch (Throwable) + log, given configfailurepolicy=skip.
• Exercised for real, not just by the green run: with org.opends.test.timeout temporarily lowered to 60 s and a scratch @Test(priority = -1) blocking in receive() (same shape as a real method, finally{afterTest()} included), the scratch method is abandoned on ThreadTimeoutException, the net logs Releasing the replication servers leaked by a timed out test, and the remaining 10 methods of the class all pass - the Flaky InitOnLineTest: initializeExportMultiSS times out, leaked replication server port fails initializeImport #841 cascade closed end to end.
• Clock ordering documented in the PR description under "Known limitations", with the bounded wait in InitializeTask as the follow-up.
• Nits: rebased on master (ExportTask in the comment), the bounce path documented in the rejection comment block, the probed entry count threaded into the private overload (drops the re-counts, including the one per retry attempt), the early-return condition extended to server2/server3/replDomain, _306 reworded to match _298/_299 with the argument order aligned.

mvn -pl opendj-server-legacy -Pprecommit verify "-Dit.test=InitOnLineTest,ReplicationDomainTest" after a full rebuild on the new base: 20/20 green.