[#1160] Report what start-ds printed when the server fails to start, and du...

Valery Kharseko

17 hours ago 6e6cbc7128ebc845f968ae95be36be29a0a05ef8

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

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
`StartReader`s 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 `StartReader`s 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 `join`s 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 b35afb762c (`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.

 .github/workflows/build.yml

@@ -437,12 +437,14 @@

    # A test step that fails leaves its instances behind. The server-side story of a
    # failed start lives in logs/server.out and logs/errors, and nothing else prints it
    # (setup only has the client-side view, see issue #1030).
    # (setup only has the client-side view, see issue #1030). The quicksetup tests run
    # their own instance under build/unit-tests/quicksetup (issue #1160).
    - name: Dump the server logs of a failed test
      if: failure()
      shell: bash
      run: |
        for f in opendj-server-legacy/target/package/opendj*/logs/server.out opendj-server-legacy/target/package/opendj*/logs/errors; do
        for f in opendj-server-legacy/target/package/opendj*/logs/server.out opendj-server-legacy/target/package/opendj*/logs/errors \
                 opendj-server-legacy/build/unit-tests/quicksetup/OpenDS/logs/server.out opendj-server-legacy/build/unit-tests/quicksetup/OpenDS/logs/errors; do
          [ -f "$f" ] || continue
          echo "===== $f"
          cat "$f"

 opendj-server-legacy/src/main/java/org/opends/quicksetup/util/ServerController.java

@@ -21,7 +21,9 @@
import java.io.IOException;
import java.io.InputStream;
import java.io.InputStreamReader;
import java.util.ArrayDeque;
import java.util.ArrayList;
import java.util.Deque;
import java.util.List;
import java.util.Map;

@@ -58,6 +60,12 @@

  private static final LocalizedLogger logger = LocalizedLogger.getLoggerForThisClass();

  /** How many of the last lines printed by the start command a failed start reports. */
  private static final int MAX_REPORTED_START_LINES = 100;

  /** How long a failed start waits for the readers to drain what the start command printed. */
  private static final long START_OUTPUT_DRAIN_TIMEOUT_MS = 5000;

  private Application application;

  private Installation installation;
@@ -331,7 +339,8 @@

      try
      {
        startServerViaAnotherProcess();
        // Without suppression the readers have already shown every line to the listeners.
        startServerViaAnotherProcess(suppressOutput || application == null);

        if (verifyCanConnect)
        {
@@ -358,7 +367,8 @@
    }
  }

  private void startServerViaAnotherProcess() throws IOException, InterruptedException, ApplicationException
  private void startServerViaAnotherProcess(boolean reportOutput)
      throws IOException, InterruptedException, ApplicationException
  {
    logger.info(LocalizableMessage.raw("starting server"));

@@ -381,8 +391,12 @@
    String startedId = getStartedId();
    Process process = pb.start();

    StartReader errReader = new StartReader(process.getErrorStream(), startedId, true);
    StartReader outputReader = new StartReader(process.getInputStream(), startedId, false);
    // When the start fails, what start-ds printed (the server.out of a server that stopped
    // during its initialization, or the reason it was not launched) is the only account of
    // the cause that reaches the caller, so both readers keep its last lines (issue #1160).
    Deque<String> outputTail = new ArrayDeque<>();
    StartReader errReader = new StartReader(process.getErrorStream(), startedId, true, outputTail);
    StartReader outputReader = new StartReader(process.getInputStream(), startedId, false, outputTail);

    int returnValue = process.waitFor();

@@ -390,7 +404,12 @@

    if (returnValue != 0)
    {
      throw new ApplicationException(ReturnCode.START_ERROR, INFO_ERROR_STARTING_SERVER_CODE.get(returnValue), null);
      // The readers may still be draining the lines start-ds printed just before it exited.
      errReader.join(START_OUTPUT_DRAIN_TIMEOUT_MS);
      outputReader.join(START_OUTPUT_DRAIN_TIMEOUT_MS);
      throw new ApplicationException(ReturnCode.START_ERROR, reportOutput
          ? getStartFailedMessage(returnValue, outputTail)
          : INFO_ERROR_STARTING_SERVER_CODE.get(returnValue), null);
    }
    if (outputReader.isFinished())
    {
@@ -596,6 +615,20 @@
    return helper.getStartedId();
  }

  private static LocalizableMessage getStartFailedMessage(int returnValue, Deque<String> outputTail)
  {
    // The header is the message a failed start has always reported, which is translated.
    LocalizableMessageBuilder mb = new LocalizableMessageBuilder(INFO_ERROR_STARTING_SERVER_CODE.get(returnValue));
    synchronized (outputTail)
    {
      if (!outputTail.isEmpty())
      {
        mb.append(INFO_ERROR_STARTING_SERVER_OUTPUT.get(String.join(System.lineSeparator(), outputTail)));
      }
    }
    return mb.toMessage();
  }

  /**
   * This class is used to read the standard error and standard output of the
   * Start process.
@@ -613,6 +646,8 @@

    private boolean isFirstLine;

    private final Thread thread;

    /**
     * The protected constructor.
     * @param stream the stream of the start process to read.
@@ -620,9 +655,11 @@
     * the start is over or not.
     * @param isError a boolean indicating whether the stream
     * corresponds to the standard error or to the standard output.
     * @param outputTail the last lines read from both streams of the start process,
     * which this reader appends to; it is guarded by its own monitor.
     */
    public StartReader(final InputStream stream, final String startedId,
        final boolean isError)
        final boolean isError, final Deque<String> outputTail)
    {
      final LocalizableMessage errorTag =
              isError ?
@@ -631,7 +668,7 @@

      isFirstLine = true;

      Thread t = new Thread(new Runnable()
      thread = new Thread(new Runnable()
      {
        @Override
        public void run()
@@ -662,6 +699,14 @@
                isFirstLine = false;
              }
              logger.info(LocalizableMessage.raw("server: " + line));
              synchronized (outputTail)
              {
                if (outputTail.size() == MAX_REPORTED_START_LINES)
                {
                  outputTail.removeFirst();
                }
                outputTail.addLast(line);
              }
              if (line.toLowerCase().contains("=" + startedId))
              {
                isFinished = true;
@@ -680,7 +725,17 @@
          isFinished = true;
        }
      });
      t.start();
      thread.start();
    }

    /**
     * Waits for this reader to reach the end of its stream.
     * @param timeoutMillis the longest time to wait, in milliseconds.
     * @throws InterruptedException if the current thread is interrupted while waiting.
     */
    public void join(long timeoutMillis) throws InterruptedException
    {
      thread.join(timeoutMillis);
    }

    /**

 opendj-server-legacy/src/messages/org/opends/messages/quickSetup.properties

@@ -341,6 +341,7 @@
INFO_ERROR_STARTING_SERVER=Error Starting Directory Server.
INFO_ERROR_STARTING_SERVER_CODE=Error Starting Directory Server. Error code: \
 %s.
INFO_ERROR_STARTING_SERVER_OUTPUT=%nLast lines of the start command output:%n%s
INFO_ERROR_STARTING_SERVER_IN_UNIX=Could not connect to the server after \
 requesting start. Verify that the server has access rights to port %s.
INFO_ERROR_STARTING_SERVER_IN_WINDOWS=Could not connect to the server after \

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

New file
@@ -0,0 +1,275 @@
/*
 * The contents of this file are subject to the terms of the Common Development and
 * Distribution License (the License). You may not use this file except in compliance with the
 * License.
 *
 * You can obtain a copy of the License at legal/CDDLv1.0.txt. See the License for the
 * specific language governing permission and limitations under the License.
 *
 * When distributing Covered Software, include this CDDL Header Notice in each file and include
 * the License file at legal/CDDLv1.0.txt. If applicable, add the following below the CDDL
 * Header, with the fields enclosed by brackets [] replaced by your own identifying
 * information: "Portions copyright [year] [name of copyright owner]".
 *
 * Copyright 2026 3A Systems, LLC.
 */
package org.opends.quicksetup.util;

import static com.forgerock.opendj.util.OperatingSystem.*;
import static org.opends.messages.QuickSetupMessages.INFO_ERROR_STARTING_SERVER_CODE;
import static org.testng.Assert.*;

import java.io.File;
import java.io.IOException;
import java.nio.charset.StandardCharsets;
import java.nio.file.Files;

import org.forgerock.i18n.LocalizableMessage;
import org.opends.quicksetup.Application;
import org.opends.quicksetup.ApplicationException;
import org.opends.quicksetup.Installation;
import org.opends.quicksetup.ProgressStep;
import org.opends.quicksetup.ReturnCode;
import org.opends.server.DirectoryServerTestCase;
import org.testng.SkipException;
import org.testng.annotations.AfterMethod;
import org.testng.annotations.BeforeMethod;
import org.testng.annotations.Test;

/**
 * A failed start reports what the start command printed (issue #1160), unless the listeners of
 * the application have already shown it. The installation is a bare directory whose start command
 * is a stand-in script that prints and exits with 1.
 */
@SuppressWarnings("javadoc")
@Test(sequential = true)
public class ServerControllerStartFailureTest extends DirectoryServerTestCase
{
  private File root;

  @BeforeMethod
  public void createInstallation() throws IOException
  {
    root = Files.createTempDirectory("server-controller-start-failure").toFile();
  }

  @AfterMethod(alwaysRun = true)
  public void deleteInstallation() throws ApplicationException
  {
    new FileManager().deleteRecursively(root);
  }

  @Test
  public void failedStartReportsBothOutputStreams() throws Exception
  {
    writeStartCommandPrintingToBothStreams();

    String message = startAndExpectFailure(null, false);

    assertTrue(message.startsWith(exitCodeMessage()), message);
    assertTrue(message.contains("cause on stdout"), message);
    assertTrue(message.contains("cause on stderr"), message);
  }

  @Test
  public void failedStartReportsOnlyTheLastLines() throws Exception
  {
    if (isWindows())
    {
      writeStartCommand("@for /L %%i in (1,1,150) do @echo L%%iL", "@exit /b 1");
    }
    else
    {
      writeStartCommand("#!/bin/sh", "i=1", "while [ $i -le 150 ]; do echo \"L${i}L\"; i=$((i+1)); done", "exit 1");
    }

    String message = startAndExpectFailure(null, false);

    assertFalse(message.contains("L50L"), message);
    assertTrue(message.contains("L51L"), message);
    assertTrue(message.contains("L150L"), message);
  }

  @Test
  public void failedStartReportsWhatIsPrintedAfterTheExit() throws Exception
  {
    if (isWindows())
    {
      throw new SkipException("needs a child process that outlives the start command");
    }
    // The child holds the inherited pipes after sh exits, so its line arrives after waitFor().
    // When the process exits, the JDK drains what is already in a pipe and closes it, unless a
    // reader is blocked in read() on that stream, which the drain then waits for. The first
    // line and the pause before the exit leave the stdout reader blocked there, so that the
    // line of the child is read rather than cut off by the drain.
    writeStartCommand("#!/bin/sh", "echo 'printed before the exit'", "sleep 1",
        "(sleep 1; echo 'printed after the exit') &", "exit 1");

    String message = startAndExpectFailure(null, false);

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

  @Test
  public void silentFailedStartKeepsTheExitCodeMessage() throws Exception
  {
    if (isWindows())
    {
      writeStartCommand("@exit /b 1");
    }
    else
    {
      writeStartCommand("#!/bin/sh", "exit 1");
    }

    assertEquals(startAndExpectFailure(null, false), exitCodeMessage());
  }

  @Test
  public void failedStartShownToTheListenersKeepsTheExitCodeMessage() throws Exception
  {
    writeStartCommandPrintingToBothStreams();
    ListeningApplication application = new ListeningApplication();

    assertEquals(startAndExpectFailure(application, false), exitCodeMessage());
    assertTrue(application.getShown().contains("cause on stdout"), application.getShown());
    assertTrue(application.getShown().contains("cause on stderr"), application.getShown());
  }

  @Test
  public void failedStartHiddenFromTheListenersReportsBothOutputStreams() throws Exception
  {
    writeStartCommandPrintingToBothStreams();
    ListeningApplication application = new ListeningApplication();

    String message = startAndExpectFailure(application, true);

    assertTrue(message.startsWith(exitCodeMessage()), message);
    assertTrue(message.contains("cause on stdout"), message);
    assertTrue(message.contains("cause on stderr"), message);
    assertEquals(application.getShown(), "");
  }

  private static String exitCodeMessage()
  {
    return INFO_ERROR_STARTING_SERVER_CODE.get(1).toString();
  }

  private void writeStartCommandPrintingToBothStreams() throws IOException
  {
    if (isWindows())
    {
      writeStartCommand("@echo cause on stdout", "@echo cause on stderr 1>&2", "@exit /b 1");
    }
    else
    {
      writeStartCommand("#!/bin/sh", "echo 'cause on stdout'", "echo 'cause on stderr' >&2", "exit 1");
    }
  }

  private void writeStartCommand(String... lines) throws IOException
  {
    Installation installation = new Installation(root, root);
    File command = installation.getServerStartCommandFile();
    assertTrue(command.getParentFile().mkdirs());
    Files.write(command.toPath(), String.join(isWindows() ? "\r\n" : "\n", lines).concat("\n")
        .getBytes(StandardCharsets.US_ASCII));
    assertTrue(command.setExecutable(true));
  }

  private String startAndExpectFailure(Application application, boolean suppressOutput)
  {
    try
    {
      new ServerController(application, new Installation(root, root)).startServer(suppressOutput);
      fail("The start command exited with 1, but the start did not fail");
      return null;
    }
    catch (ApplicationException e)
    {
      assertEquals(e.getType(), ReturnCode.START_ERROR);
      return e.getMessage();
    }
  }

  /** An application whose listener keeps the log details it is shown. */
  private static final class ListeningApplication extends Application
  {
    private final StringBuilder shown = new StringBuilder();

    ListeningApplication()
    {
      setProgressMessageFormatter(new PlainTextProgressMessageFormatter());
      addProgressUpdateListener(ev ->
      {
        synchronized (shown)
        {
          shown.append(ev.getNewLogs());
        }
      });
    }

    String getShown()
    {
      synchronized (shown)
      {
        return shown.toString();
      }
    }

    @Override
    public String getInstallationPath()
    {
      return null;
    }

    @Override
    public String getInstancePath()
    {
      return null;
    }

    @Override
    public ProgressStep getCurrentProgressStep()
    {
      return null;
    }

    @Override
    public Integer getRatio(ProgressStep step)
    {
      return null;
    }

    @Override
    public LocalizableMessage getSummary(ProgressStep step)
    {
      return null;
    }

    @Override
    public boolean isFinished()
    {
      return false;
    }

    @Override
    public boolean isCancellable()
    {
      return false;
    }

    @Override
    public void cancel()
    {
      // Nothing to cancel.
    }

    @Override
    public void run()
    {
      // Never run: the test drives the ServerController directly.
    }
  }
}