#518: Fix stream reading timeout (#520)

README.md

@@ -7,8 +7,9 @@ This maven plugin checks and unifies the project's structure according to the Ex
 
 ## Usage in a Nutshell for Maven
 
-1. Create config file
+1. Create config file `~/.m2/toolchains.xml` for the Maven toolchains plugin, see [user guide](doc/user_guide/user_guide.md#configure-mavens-toolchainsxml) for details.
 
+2. Create config file
    ```yml
    sources:
      - type: maven
@@ -17,8 +18,7 @@ This maven plugin checks and unifies the project's structure according to the Ex
          - maven_central
    ```
 
-2. Add PK plugin to your `pom.xml`:
-
+3. Add PK plugin to your `pom.xml`:
    ```xml
    <plugins>
        <plugin>
@@ -36,13 +36,12 @@ This maven plugin checks and unifies the project's structure according to the Ex
    </plugins>
    ```
 
-3. Run PK fix:
-
+4. Run PK fix:
    ```sh
    mvn project-keeper:fix --projects .
    ```
 
-4. Run PK verify:
+5. Run PK verify:
    ```sh
    mvn project-keeper:verify --projects .
    ```

doc/changes/changes_3.0.1.md

@@ -0,0 +1,55 @@
+# Project Keeper 3.0.1, released 2024-01-25
+
+Code name: Fixed timeout exception handling
+
+## Summary
+
+This release fixes the exception handling for process timeouts. When a started process timed out, PK threw exception `E-PK-CORE-99: Stream reading did not finish after timeout of PT5S` instead of the correct `E-PK-CORE-128: Timeout while waiting 10ms for command '...'.`, hiding the root cause of the problem.
+
+## Bugfixes
+
+* #518: Fixed exception handling for process timeouts
+
+## Dependency Updates
+
+### Project Keeper Core
+
+#### Compile Dependency Updates
+
+* Updated `com.exasol:project-keeper-shared-model-classes:3.0.0` to `3.0.1`
+
+#### Runtime Dependency Updates
+
+* Updated `com.exasol:project-keeper-java-project-crawler:3.0.0` to `3.0.1`
+
+#### Test Dependency Updates
+
+* Updated `com.exasol:project-keeper-shared-test-setup:3.0.0` to `3.0.1`
+
+### Project Keeper Command Line Interface
+
+#### Compile Dependency Updates
+
+* Updated `com.exasol:project-keeper-core:3.0.0` to `3.0.1`
+
+#### Test Dependency Updates
+
+* Updated `com.exasol:project-keeper-shared-test-setup:3.0.0` to `3.0.1`
+
+### Project Keeper Maven Plugin
+
+#### Compile Dependency Updates
+
+* Updated `com.exasol:project-keeper-core:3.0.0` to `3.0.1`
+
+### Project Keeper Java Project Crawler
+
+#### Compile Dependency Updates
+
+* Updated `com.exasol:project-keeper-shared-model-classes:3.0.0` to `3.0.1`
+
+### Project Keeper Shared Test Setup
+
+#### Compile Dependency Updates
+
+* Updated `com.exasol:project-keeper-shared-model-classes:3.0.0` to `3.0.1`

doc/user_guide/user_guide.md

@@ -362,3 +362,7 @@ See section [Install Required JDK Versions](#install-required-jdk-versions) for
 ```
 
 Ensure that `~/.m2/toolchains.xml` exists and contains a JDK version 11. See section [Configure Maven's `toolchains.xml`](#configure-mavens-toolchainsxml) for details.
+
+**Problem:**: Running PK using Maven fails but the error message is not helpful.
+
+Run Maven with the `--errors` option to get a stack trace.

parent-pom/pom.xml

@@ -28,7 +28,7 @@
         </repository>
     </distributionManagement>
     <properties>
-        <revision>3.0.0</revision>
+        <revision>3.0.1</revision>
         <maven.version>3.9.6</maven.version>
         <minimum.maven.version>3.6.3</minimum.maven.version>
         <junit.version>5.10.1</junit.version>

project-keeper-cli/src/test/java/com/exasol/projectkeeper/cli/ProjectKeeperLauncherExecutableJarIT.java

@@ -21,7 +21,7 @@
 import org.junit.jupiter.api.io.TempDir;
 
 import com.exasol.mavenprojectversiongetter.MavenProjectVersionGetter;
-import com.exasol.projectkeeper.sources.analyze.golang.SimpleProcess;
+import com.exasol.projectkeeper.sources.analyze.generic.SimpleProcess;
 import com.exasol.projectkeeper.test.GolangProjectFixture;
 import com.exasol.projectkeeper.test.MavenProjectFixture;
 

project-keeper/src/main/java/com/exasol/projectkeeper/JavaProjectCrawlerRunner.java

@@ -71,18 +71,20 @@ private String runCrawlerPlugin(final Path... pomFiles) {
             LOGGER.fine(() -> "Executing command " + commandParts);
             final Process proc = new ProcessBuilder(commandParts).redirectErrorStream(true).start();
 
-            final CollectingConsumer streamConsumer = new AsyncStreamReader()
+            final CollectingConsumer outputStreamConsumer = new AsyncStreamReader()
                     .startCollectingConsumer(proc.getInputStream());
+            final CollectingConsumer errorStreamConsumer = new AsyncStreamReader()
+                    .startCollectingConsumer(proc.getErrorStream());
 
             if (!proc.waitFor(90, TimeUnit.SECONDS)) {
-                final String output = streamConsumer.getContent(STREAM_READING_TIMEOUT);
-                throw new IllegalStateException(ExaError.messageBuilder("E-PK-CORE-81")
-                        .message("Timeout while executing command {{executed command|u}}. Output was {{output}}",
-                                commandParts, output)
-                        .toString());
+                final String stdOutput = outputStreamConsumer.getCurrentContent();
+                final String stdError = errorStreamConsumer.getCurrentContent();
+                throw new IllegalStateException(ExaError.messageBuilder("E-PK-CORE-81").message(
+                        "Timeout while executing command {{executed command|u}}. Output: {{std output}}, error: {{std error}}",
+                        commandParts, stdOutput, stdError).toString());
             }
             final int exitCode = proc.exitValue();
-            final String output = streamConsumer.getContent(STREAM_READING_TIMEOUT);
+            final String output = outputStreamConsumer.getContent(STREAM_READING_TIMEOUT);
             if (exitCode != 0) {
                 LOGGER.log(Level.SEVERE, output);
                 throw new IllegalStateException(ExaError.messageBuilder("E-PK-CORE-78").message(

project-keeper/src/main/java/com/exasol/projectkeeper/sources/analyze/generic/CommandExecutor.java

@@ -2,8 +2,6 @@
 
 import java.nio.file.Path;
 
-import com.exasol.projectkeeper.sources.analyze.golang.SimpleProcess;
-
 /**
  * Enable to execute a {@link ShellCommand} and hence to mock this in tests.
  */

project-keeper/src/main/java/com/exasol/projectkeeper/sources/analyze/golang/SimpleProcess.java → project-keeper/src/main/java/com/exasol/projectkeeper/sources/analyze/generic/SimpleProcess.java

@@ -1,4 +1,4 @@
-package com.exasol.projectkeeper.sources.analyze.golang;
+package com.exasol.projectkeeper.sources.analyze.generic;
 
 import java.io.IOException;
 import java.nio.file.Path;
@@ -26,7 +26,7 @@ public class SimpleProcess {
     private final List<String> command;
     private final Instant startTime;
 
-    private SimpleProcess(final Process process, final CollectingConsumer outputStreamConsumer,
+    SimpleProcess(final Process process, final CollectingConsumer outputStreamConsumer,
             final CollectingConsumer errorStreamConsumer, final Path workingDirectory, final List<String> command,
             final Instant startTime) {
         this.process = process;
@@ -97,7 +97,7 @@ public void waitUntilFinished(final Duration executionTimeout) {
                             + " Output:\n{{std out}}\n" //
                             + "Error output:\n{{std error}}", //
                             formatCommand(), this.workingDirectory, exitCode, duration, //
-                            getOutputStreamContent(), getErrorStreamContent())
+                            getOutputStreamContent().trim(), getErrorStreamContent().trim())
                     .toString());
         }
         LOGGER.finest(() -> "Command '" + formatCommand() + "' finished successfully after " + duration);
@@ -123,7 +123,7 @@ public String getOutputStreamContent() {
      */
     public String getErrorStreamContent() {
         try {
-            return this.errorStreamConsumer.getContent(Duration.ofMillis(500));
+            return this.errorStreamConsumer.getContent(Duration.ofSeconds(5));
         } catch (final InterruptedException exception) {
             throw handleInterruptedException(exception);
         }
@@ -132,11 +132,13 @@ public String getErrorStreamContent() {
     private void waitForExecutionFinished(final Duration executionTimeout) {
         try {
             if (!this.process.waitFor(executionTimeout.toMillis(), TimeUnit.MILLISECONDS)) {
+                final String outputStreamContentUntilNow = this.outputStreamConsumer.getCurrentContent().trim();
+                final String errorStreamContentUntilNow = this.errorStreamConsumer.getCurrentContent().trim();
                 throw new IllegalStateException(ExaError.messageBuilder("E-PK-CORE-128")
                         .message("Timeout while waiting {{timeout|u}}ms for command {{executed command}}." //
-                                + " Output was {{output}}\nError output: {{std error}}", //
+                                + " Output was {{std output}}\nError output: {{std error}}", //
                                 executionTimeout.toMillis(), formatCommand(), //
-                                getOutputStreamContent(), getErrorStreamContent())
+                                outputStreamContentUntilNow, errorStreamContentUntilNow)
                         .toString());
             }
         } catch (final InterruptedException exception) {

project-keeper/src/main/java/com/exasol/projectkeeper/sources/analyze/golang/GoBinary.java

@@ -8,8 +8,7 @@
 
 import com.exasol.errorreporting.ExaError;
 import com.exasol.projectkeeper.OsCheck;
-import com.exasol.projectkeeper.sources.analyze.generic.CommandExecutor;
-import com.exasol.projectkeeper.sources.analyze.generic.ShellCommand;
+import com.exasol.projectkeeper.sources.analyze.generic.*;
 
 /**
  * Represents an executable go binary.

project-keeper/src/main/java/com/exasol/projectkeeper/sources/analyze/golang/GolangServices.java

@@ -229,4 +229,4 @@ void installDependencies(final Path projectPath) {
                 .build();
         this.executor.execute(sc, projectPath);
     }
-}
+}

project-keeper/src/main/java/com/exasol/projectkeeper/sources/analyze/npm/NpmServices.java

@@ -25,14 +25,14 @@ class NpmServices {
     // [impl -> dsn~npm-dependency-licenses~1]
     static final ShellCommand LIST_DEPENDENCIES = ShellCommand.builder() //
             .command(NPM, "list") //
-            .timeout(Duration.ofMinutes(2)) //
+            .timeout(Duration.ofMinutes(4)) //
             .args("--location=project", "--depth=0", "--json") //
             .build();
 
     // [impl -> dsn~npm-dependency-additional-information~1]
     static final ShellCommand LICENSE_CHECKER = ShellCommand.builder() //
             .command(NPX, "license-checker") //
-            .timeout(Duration.ofMinutes(2)) //
+            .timeout(Duration.ofMinutes(4)) //
             .args("--location=project", "--direct", "--json") //
             .build();
 

project-keeper/src/main/java/com/exasol/projectkeeper/stream/CollectingConsumer.java

@@ -44,6 +44,16 @@ public String getContent(final Duration timeout) throws InterruptedException {
                     "Stream reading did not finish after timeout of {{timeout}}. Content collected until now: {{content}}.",
                     timeout, this.stringBuilder.toString()).ticketMitigation().toString());
         }
+        return getCurrentContent();
+    }
+
+    /**
+     * Returns the current content read from the stream, without waiting for the stream to complete. This is useful in
+     * case of a error or timeout where you don't want to wait for the process to complete.
+     * 
+     * @return current stream content
+     */
+    public String getCurrentContent() {
         return this.stringBuilder.toString();
     }
 }

project-keeper/src/test/java/com/exasol/projectkeeper/sources/analyze/generic/SimpleProcessIT.java

@@ -0,0 +1,75 @@
+package com.exasol.projectkeeper.sources.analyze.generic;
+
+import static org.hamcrest.MatcherAssert.assertThat;
+import static org.hamcrest.Matchers.*;
+import static org.junit.jupiter.api.Assertions.assertThrows;
+
+import java.time.Duration;
+import java.util.List;
+
+import org.junit.jupiter.api.Test;
+import org.junit.jupiter.api.condition.DisabledOnOs;
+import org.junit.jupiter.api.condition.OS;
+
+// Windows has problems with the timeout of 10ms. Running these tests under Unix is enough.
+@DisabledOnOs(OS.WINDOWS)
+class SimpleProcessIT {
+
+    private static final Duration TIMEOUT = Duration.ofMillis(10);
+
+    @Test
+    void outputStream() {
+        final SimpleProcess process = SimpleProcess.start(List.of("bash", "-c", "echo output"));
+        process.waitUntilFinished(TIMEOUT);
+        assertThat(process.getOutputStreamContent(), equalTo("output\n"));
+        assertThat(process.getErrorStreamContent(), emptyString());
+    }
+
+    @Test
+    void errorStream() {
+        final SimpleProcess process = SimpleProcess.start(List.of("bash", "-c", ">&2 echo error"));
+        process.waitUntilFinished(TIMEOUT);
+        assertThat(process.getOutputStreamContent(), emptyString());
+        assertThat(process.getErrorStreamContent(), equalTo("error\n"));
+    }
+
+    @Test
+    void outputAndErrorStream() {
+        final SimpleProcess process = SimpleProcess.start(List.of("bash", "-c", "echo output && >&2 echo error"));
+        process.waitUntilFinished(TIMEOUT);
+        assertThat(process.getOutputStreamContent(), equalTo("output\n"));
+        assertThat(process.getErrorStreamContent(), equalTo("error\n"));
+    }
+
+    @Test
+    void processFails() {
+        final SimpleProcess process = SimpleProcess
+                .start(List.of("bash", "-c", "echo output && >&2 echo error && exit 1"));
+        final IllegalStateException exception = assertThrows(IllegalStateException.class,
+                () -> process.waitUntilFinished(TIMEOUT));
+        assertThat(exception.getMessage(), allOf(startsWith(
+                "E-PK-CORE-126: Failed to run command 'bash -c echo output && >&2 echo error && exit 1' in <null>, exit code was 1 after PT"),
+                endsWith("Output:\n'output'\n" + //
+                        "Error output:\n'error'")));
+    }
+
+    @Test
+    void processTimeout() {
+        final SimpleProcess process = SimpleProcess
+                .start(List.of("bash", "-c", "echo output && >&2 echo error && sleep 1"));
+        final IllegalStateException exception = assertThrows(IllegalStateException.class,
+                () -> process.waitUntilFinished(TIMEOUT));
+        assertThat(exception.getMessage(), equalTo(
+                "E-PK-CORE-128: Timeout while waiting 10ms for command 'bash -c echo output && >&2 echo error && sleep 1'. Output was 'output'\n"
+                        + "Error output: 'error'"));
+    }
+
+    @Test
+    void executeFails() {
+        final List<String> command = List.of("no-such-binary");
+        final IllegalStateException exception = assertThrows(IllegalStateException.class,
+                () -> SimpleProcess.start(command));
+        assertThat(exception.getMessage(), equalTo(
+                "E-PK-CORE-125: Error executing command 'no-such-binary'. Verify that the 'no-such-binary' executable is on the PATH."));
+    }
+}

project-keeper/src/test/java/com/exasol/projectkeeper/stream/CollectingConsumerTest.java

@@ -22,14 +22,14 @@ void setup() {
     @Test
     void getEmptyContentReturnsEmptyString() throws InterruptedException {
         this.collectingConsumer.readFinished();
-        assertThat(getcontent(), equalTo(""));
+        assertThat(getContent(), equalTo(""));
     }
 
     @Test
     void getSingleLineContent() throws InterruptedException {
         this.collectingConsumer.accept("line1");
         this.collectingConsumer.readFinished();
-        assertThat(getcontent(), equalTo("line1\n"));
+        assertThat(getContent(), equalTo("line1\n"));
     }
 
     @Test
@@ -38,19 +38,19 @@ void getMultiLineContent() throws InterruptedException {
         this.collectingConsumer.accept("line2");
         this.collectingConsumer.accept("line3");
         this.collectingConsumer.readFinished();
-        assertThat(getcontent(), equalTo("line1\nline2\nline3\n"));
+        assertThat(getContent(), equalTo("line1\nline2\nline3\n"));
     }
 
     @Test
     void getContentAfterFailure() throws InterruptedException {
         this.collectingConsumer.accept("line1");
         this.collectingConsumer.readFailed(null);
-        assertThat(getcontent(), equalTo("line1\n"));
+        assertThat(getContent(), equalTo("line1\n"));
     }
 
     @Test
     void getContentWithoutFinishFails() throws InterruptedException {
-        final IllegalStateException exception = assertThrows(IllegalStateException.class, () -> getcontent());
+        final IllegalStateException exception = assertThrows(IllegalStateException.class, () -> getContent());
         assertThat(exception.getMessage(), equalTo("E-PK-CORE-99: Stream reading did not finish after timeout of "
                 + TIMEOUT
                 + ". Content collected until now: ''. This is an internal error that should not happen. Please report it by opening a GitHub issue."));
@@ -59,13 +59,13 @@ void getContentWithoutFinishFails() throws InterruptedException {
     @Test
     void getContentWithoutFinishAddsCollectedContentToExceptionMessage() throws InterruptedException {
         this.collectingConsumer.accept("line1");
-        final IllegalStateException exception = assertThrows(IllegalStateException.class, () -> getcontent());
+        final IllegalStateException exception = assertThrows(IllegalStateException.class, () -> getContent());
         assertThat(exception.getMessage(), equalTo("E-PK-CORE-99: Stream reading did not finish after timeout of "
                 + TIMEOUT
                 + ". Content collected until now: 'line1\n'. This is an internal error that should not happen. Please report it by opening a GitHub issue."));
     }
 
-    private String getcontent() throws InterruptedException {
+    private String getContent() throws InterruptedException {
         return this.collectingConsumer.getContent(TIMEOUT);
     }
 }