[#1160] Report what start-ds printed when the server fails to start, and dump the quicksetup test instance's logs on a failed build

[vharseko]

Fixes #1160

Problem

ServerControllerTest#testStartServer failed once on CI with Error Starting Directory Server. Error code: 1. and nothing else. The cause could not be recovered:

• ServerController.startServerViaAnotherProcess() threw INFO_ERROR_STARTING_SERVER_CODE with the exit code only. The two StartReaders did read every line start-ds printed, but passed them only to logger.info and to the application listeners (none in the test).
• The "Dump the server logs of a failed test" step read only target/package/opendj*/logs, not the quicksetup tests' own instance under build/unit-tests/quicksetup/OpenDS.

start-ds exits with 1 in one branch only: WaitForFileDelete returned 0, yet the second --checkStartability did not report a running server (98). Before that, WaitForFileDelete --logFile prints logs/server.out of the server it waits for to stdout. So the server's own account of why it stopped already reaches StartReader; it just never reached the exception.

Change

• ServerController: both StartReaders append to one shared tail of the last 100 lines of stdout and stderr (guarded by its own monitor). On a non-zero exit, the controller waits up to 5 s for each reader to drain what start-ds printed. waitFor() returns as soon as the process has exited, while the readers may still be behind on what is left in the pipes. A line that a child of start-ds prints after the exit arrives only if the reader is blocked in read() at that moment: otherwise the JDK drains what the pipe holds and closes it (ProcessPipeInputStream.processExited()). Then, if nobody has seen those lines, it appends them to the old message:

  Error Starting Directory Server. Error code: 1.
  Last lines of the start command output:
  <lines>
  

  The first line is the translated INFO_ERROR_STARTING_SERVER_CODE; only the new INFO_ERROR_STARTING_SERVER_OUTPUT part is untranslated.

  • "Nobody has seen them" means the start was called with suppressOutput or without an application. Otherwise the readers have already shown every line to the listeners (setup --verbose, the uninstall CLI and GUI), and the error keeps the old message instead of repeating up to 100 lines.
  • A start command that printed nothing keeps the old message. A successful start is unchanged.

• .github/workflows/build.yml: the dump step also prints opendj-server-legacy/build/unit-tests/quicksetup/OpenDS/logs/{server.out,errors}.

• New ServerControllerStartFailureTest: the installation is a bare temporary directory whose start command (bin/start-ds, or bat/start-ds.bat on Windows) is a stand-in script that prints and exits with 1. Six cases:

  • both streams reach the message;
  • out of 150 lines, only the last 100 do;
  • a line printed by a background child after the start command has exited reaches the message (skipped on Windows). The script prints a line and sleeps for 1 s before it exits, so the stdout reader is already blocked in read() and the JDK waits for that read instead of closing the pipe;
  • a silent failure keeps the old message;
  • with an application whose listener is not suppressed, the listener gets both lines and the message stays the old one;
  • with the same application and suppressOutput, the listener gets nothing and the message carries both lines.

  Every expected message is built from INFO_ERROR_STARTING_SERVER_CODE, not from its English text, so the cases also pass under a translated default locale.

This PR does not fix the flake itself. It makes the next occurrence name its cause, which item 3 of the issue waits for.

Testing

• mvn -Pprecommit verify -pl opendj-server-legacy -am -Dit.test=ServerControllerStartFailureTest,ServerControllerTest: BUILD SUCCESS. ServerControllerStartFailureTest 6/6, ServerControllerTest 2/2. attach-javadocs (doclint) passed.
• RED, by running the new test with TestNG directly against mutants of ServerController (each one goes red in the case named for it):
  • both drain joins deleted: failedStartReportsWhatIsPrintedAfterTheExit, in every run. On Linux it also fails other cases from time to time, since without the joins the message can also miss lines printed before the exit (in eclipse-temurin:21-jdk, over 20 runs: failedStartReportsBothOutputStreams 19, failedStartReportsOnlyTheLastLines 11, failedStartShownToTheListenersKeepsTheExitCodeMessage 9);
  • removeFirst dropped (no tail bound): failedStartReportsOnlyTheLastLines;
  • output always reported: failedStartShownToTheListenersKeepsTheExitCodeMessage;
  • output reported only without an application: failedStartHiddenFromTheListenersReportsBothOutputStreams.
• Locale: the failsafe classpath holds only opendj.jar, whose bundle is the English base; the translations ship in lib/opendj_<lang>.jar. With opendj_fr.jar and opendj_ja.jar added to the classpath (as an IDE run with target/classes has them), the new test passes under -Duser.language=en, fr and ja. The previous version of the test fails 2 cases under fr and ja against this code.
• Linux: this case failed on CI at b35afb7 (build-maven (ubuntu-latest, 21) and (ubuntu-latest, 25), run 37187761859). Its stand-in exited at once, so the line of the child was lost whenever the reader was not yet blocked in read() at the exit. In eclipse-temurin:21-jdk that version failed in 5 of 20 runs, then in 0 of the next 30. The current version passes 20 of 20 in eclipse-temurin:21-jdk (and 30 of 30 in a second series) and in eclipse-temurin:25-jdk, and 20 of 20 on macOS with JDK 21. With both joins deleted, it fails in every run: 10 of 10 on each, and 20 of 20 in the second series on 21.
• Windows: not run. CI runs failsafe only on the Linux legs (-P precommit is set only when runner.os == 'Linux'), and I have no Windows host, so the .bat stand-ins (@for /L, 1>&2, @exit /b 1, CRLF) have not run anywhere.

[maximthomas]

praise: The failure message now carries the cause, and the change sits exactly on the one throw that lost it.

• getStartFailedMessage falls back to INFO_ERROR_STARTING_SERVER_CODE when start-ds printed nothing, and silentFailedStartKeepsTheExitCodeMessage pins that fallback.
• The tail is bounded by MAX_REPORTED_START_LINES, and failedStartReportsOnlyTheLastLines pins the bound from both sides (L50L absent, L51L present); the description shows the removeFirst mutant going red.
• The drain joins run only on the returnValue != 0 branch, so a successful start keeps its timing.

---

issue (non-blocking): silentFailedStartKeepsTheExitCodeMessage compares the message with the English text of a translated key.

opendj-server-legacy/src/test/java/org/opends/quicksetup/util/ServerControllerStartFailureTest.java:106

INFO_ERROR_STARTING_SERVER_CODE is translated in quickSetup_de/es/fr/ja/ko/zh_CN/zh_TW.properties, and nothing in the pom argLine, the failsafe properties or the test harness pins user.language. Running the silent stand-in through startServer() with -Duser.language=fr, de or ja returns the translated text ("Erreur lors du démarrage de Directory Server. Code d'erreur : 1."), so the assertion fails on a developer JVM with any of those default locales. CI's English runners stay green.

import static org.opends.messages.QuickSetupMessages.INFO_ERROR_STARTING_SERVER_CODE;

    assertEquals(startAndExpectFailure(), INFO_ERROR_STARTING_SERVER_CODE.get(1).toString());

---

suggestion (non-blocking): No test pins the drain joins, but one stand-in script can.

opendj-server-legacy/src/main/java/org/opends/quicksetup/util/ServerController.java:406-407, opendj-server-legacy/src/test/java/org/opends/quicksetup/util/ServerControllerStartFailureTest.java:56

All three stand-ins print and exit at once, so the readers have emptied the pipes before waitFor() returns. With both joins deleted, each case stayed green 120 of 120 times (the test's own scripts and assertions, run through the real startServer(), macOS, JDK 26). The description says a test cannot force the readers to lag behind the exit. A background child can: it holds the inherited pipes after sh exits, so its line arrives after waitFor(). At the head the message contains that line in 3 of 3 runs. Without the joins the tail is empty and the bare "Error code: 1." is thrown, also 3 of 3.

  @Test
  public void failedStartReportsWhatIsPrintedAfterTheExit() throws Exception
  {
    if (isWindows())
    {
      throw new SkipException("needs a child process that outlives the start command");
    }
    writeStartCommand("#!/bin/sh", "(sleep 1; echo 'printed after the exit') &", "exit 1");

    String message = startAndExpectFailure();

    assertTrue(message.contains("printed after the exit"), message);
  }

Pin: the case above (plus import org.testng.SkipException;, as LauncherTest has) goes red when either join is deleted.

---

suggestion (non-blocking): On a localized install, a failed start that printed anything now reports in English.

opendj-server-legacy/src/messages/org/opends/messages/quickSetup.properties:345, opendj-server-legacy/src/main/java/org/opends/quicksetup/util/ServerController.java:622

INFO_ERROR_STARTING_SERVER_CODE_OUTPUT exists only in the base bundle. Before this PR the same failure was reported through the translated INFO_ERROR_STARTING_SERVER_CODE. With -Duser.language=fr the head reports "Error Starting Directory Server. Error code: 1. Last lines of the start command output:", where the base reported the French header. Leaving the new text untranslated is normal here. The suggestion is only to keep the header that is already translated:

      LocalizableMessageBuilder mb = new LocalizableMessageBuilder();
      mb.append(INFO_ERROR_STARTING_SERVER_CODE.get(returnValue));
      mb.append(INFO_ERROR_STARTING_SERVER_OUTPUT.get(String.join(System.lineSeparator(), outputTail)));
      return mb.toMessage();

INFO_ERROR_STARTING_SERVER_OUTPUT=%nLast lines of the start command output:%n%s

If you take this, the contains("Error code: 1.") checks in the other two cases become locale-dependent too. Compare them with INFO_ERROR_STARTING_SERVER_CODE.get(1).toString() as well.

---

question (non-blocking): On a verbose or unsuppressed start, is it deliberate that the error repeats up to 100 lines the user has just seen?

opendj-server-legacy/src/main/java/org/opends/quicksetup/util/ServerController.java:622, :692

StartReader.run sends each start-ds line to application.notifyListeners unless output is suppressed, and the same lines then go into the exception. Three paths print them live and then again inside the error. The first is setup --verbose or a large LDIF import (Installer.java:371, startServer(!verbose)), where handleInstallationError prints them. The second is the non-quiet uninstall CLI (UninstallCliHelper.java:997, startServer(false)), through printErrorMessage. The third is the GUI uninstaller (Uninstaller.java:1413, startServer() = startServer(true, false)). This is cosmetic. If it is deliberate, so that the error stays self-contained, nothing needs to change. If not:

        startServerViaAnotherProcess(suppressOutput || application == null);

  private void startServerViaAnotherProcess(boolean reportOutput) throws IOException, InterruptedException, ApplicationException

      throw new ApplicationException(ReturnCode.START_ERROR, reportOutput
          ? getStartFailedMessage(returnValue, outputTail)
          : INFO_ERROR_STARTING_SERVER_CODE.get(returnValue), null);

---

suggestion (non-blocking): No CI cell runs the .bat branches of the three cases.

opendj-server-legacy/src/test/java/org/opends/quicksetup/util/ServerControllerStartFailureTest.java:59-62, :80, :99

build.yml:106-110 adds -P precommit only when runner.os == 'Linux'. opendj-server-legacy/pom.xml:646-655 binds surefire to phase none, and failsafe is declared only in the precommit profile. So the Windows build-maven cells compile the class and run none of it. As a result, the @for /L %%i loop, @echo … 1>&2, the @exit /b 1 exit code reaching waitFor(), and the CRLF write have not run anywhere.

Pin: one run on a Windows host, mvn -Pprecommit verify -pl opendj-server-legacy -am -Dit.test=ServerControllerStartFailureTest. If that is not possible, change the Testing section to say the Windows branch is unrun.

---

note (non-blocking): Deviation from the description.

• PR description, Testing: "the Windows legs of this PR run it". No CI cell runs failsafe outside Linux (see the suggestion above).

[vharseko]

Thanks for the review. All six points are taken in b35afb7.

issue: the silent case compares with English text. Fixed: every expected message is built from INFO_ERROR_STARTING_SERVER_CODE.get(1).toString(). One nuance for the record: under mvn verify the failsafe classpath has only opendj.jar, whose bundle is the English base. The translations ship in lib/opendj_<lang>.jar, so the Maven run stays English under any locale. The failure shows up when target/classes is on the classpath, as in an IDE run. With opendj_fr.jar and opendj_ja.jar added to the classpath, the previous test fails 2 cases under fr and ja against the new code, and the new test passes under en, fr and ja.

suggestion: pin the drain joins. Added failedStartReportsWhatIsPrintedAfterTheExit, with your background-child stand-in, skipped on Windows. With both joins deleted it goes red, and it is the only case that does. I removed "Not pinned: the drain wait" from the description, which was wrong.

suggestion: keep the translated header. Done as you proposed. The message is the translated INFO_ERROR_STARTING_SERVER_CODE plus the new INFO_ERROR_STARTING_SERVER_OUTPUT=%nLast lines of the start command output:%n%s, and INFO_ERROR_STARTING_SERVER_CODE_OUTPUT is gone.

question: the repeated lines. They were not deliberate. The tail is now reported only for suppressOutput || application == null. In the other cases the old message is kept. The joins still run on every failed start, so the listeners have received every line before the error is thrown. Two cases pin the new condition. Both use a small Application subclass whose listener records what it is shown:

• failedStartShownToTheListenersKeepsTheExitCodeMessage (startServer(false)): the listener got both lines, and the message is the bare exit code. It goes red when the output is always reported.
• failedStartHiddenFromTheListenersReportsBothOutputStreams (startServer(true)): the listener got nothing, and the message carries both lines. It goes red when only application == null reports.

suggestion / note: the .bat branches. You are right: failsafe runs only on the Linux legs. I have no Windows host, so the Testing section now says the .bat stand-ins have not run anywhere, and it no longer claims the Windows legs run them.

Mutants, each red in exactly one case: no joins, no removeFirst, always report, report only without an application. mvn -Pprecommit verify -pl opendj-server-legacy -am -Dit.test=ServerControllerStartFailureTest,ServerControllerTest: 6/6 and 2/2, doclint passed. The branch is rebased onto the current master (#1170).

[vharseko]

Fixed in 280676f. The branch is rebased onto master 92ea60a; the two earlier commits are unchanged.

CI at b35afb7 failed failedStartReportsWhatIsPrintedAfterTheExit on build-maven (ubuntu-latest, 21) and (ubuntu-latest, 25) (run 37187761859): the message had no tail at all. The stand-in from round 1 relies on a race the JDK does not guarantee. When the process exits, the reaper calls ProcessPipeInputStream.processExited(), which drains only what available() reports and then closes the pipe. A line that the background child prints a second later arrives only if the reader is blocked in read() at that moment. processExited() and BufferedInputStream.read are synchronized on the same stream, so the drain then waits for that read. If the reader is not blocked there yet, the line is lost. On macOS the reader is nearly always already there, which is why it was green 3 of 3 there and in my runs. In eclipse-temurin:21-jdk the same version failed in 5 of 20 runs.

The stand-in now prints a line and sleeps for 1 s before it starts the child and exits, so the stdout reader is blocked in read() by then:

echo 'printed before the exit'
sleep 1
(sleep 1; echo 'printed after the exit') &
exit 1

It passes 20 of 20 in eclipse-temurin:21-jdk and eclipse-temurin:25-jdk and on macOS (JDK 21). With both joins deleted, it fails in every run (10 of 10 on each, and 20 of 20 in a second series on 21). That mutant also fails other cases now and then on Linux, since without the joins lines printed before the exit go missing too. The description now says which lines the joins can catch after the exit.

[maximthomas]

praise: The round-1 points are all fixed, and the Linux flake was diagnosed instead of retried.

• ServerController.java:343 reports the tail only when no listener saw it (suppressOutput || application == null), and getStartFailedMessage (:618-630) keeps the translated INFO_ERROR_STARTING_SERVER_CODE header.
• The failedStartReportsWhatIsPrintedAfterTheExit stand-in (ServerControllerStartFailureTest.java:100-106) is built around the JDK's ProcessPipeInputStream.processExited() drain, and its comment says why the pause is there.
• Every expected message comes from INFO_ERROR_STARTING_SERVER_CODE.get(1).toString() (:154-157), so the cases do not depend on the locale.