Dump the stderr log of a worker when it crashes during a build.

This should help users and developers a lot figuring out *why* the worker crashed as the log file was very undiscoverable for them.

Part of the "make error messages great" effort (#2855).

PiperOrigin-RevId: 154165665

8 files changed, 289 insertions, 8 deletions

diff --git a/src/main/java/com/google/devtools/build/lib/worker/BUILD b/src/main/java/com/google/devtools/build/lib/worker/BUILD
index 50d3928a6a..ef7427542e 100644
--- a/src/main/java/com/google/devtools/build/lib/worker/BUILD
+++ b/src/main/java/com/google/devtools/build/lib/worker/BUILD
@@ -21,6 +21,7 @@ java_library(
         "//src/main/protobuf:test_status_java_proto",
         "//src/main/protobuf:worker_protocol_java_proto",
         "//third_party:apache_commons_pool2",
+        "//third_party:auto_value",
         "//third_party:guava",
         "//third_party:jsr305",
         "//third_party/protobuf:protobuf_java",
diff --git a/src/main/java/com/google/devtools/build/lib/worker/ErrorMessage.java b/src/main/java/com/google/devtools/build/lib/worker/ErrorMessage.java
new file mode 100644
index 0000000000..343ad1d239
--- /dev/null
+++ b/src/main/java/com/google/devtools/build/lib/worker/ErrorMessage.java
@@ -0,0 +1,118 @@
+// Copyright 2017 The Bazel Authors. All rights reserved.
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+// http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+package com.google.devtools.build.lib.worker;
+
+import static java.nio.charset.StandardCharsets.UTF_8;
+
+import com.google.auto.value.AutoValue;
+import com.google.common.base.Preconditions;
+import com.google.common.base.Throwables;
+import com.google.devtools.build.lib.vfs.FileSystemUtils;
+import com.google.devtools.build.lib.vfs.Path;
+import java.io.IOException;
+
+/** A well-formatted error message that is easy to read and easy to create. */
+@AutoValue
+abstract class ErrorMessage {
+  abstract String message();
+
+  @Override
+  public String toString() {
+    return message();
+  }
+
+  public static Builder builder() {
+    return new Builder();
+  }
+
+  public static final class Builder {
+    private String message = "Unknown error";
+    private Path logFile;
+    private String logText = "";
+    private int logSizeLimit = Integer.MAX_VALUE;
+
+    private Builder() {}
+
+    /** Sets the main text of this error message. */
+    public Builder message(String message) {
+      Preconditions.checkNotNull(message);
+      this.message = message.isEmpty() ? "Unknown error" : message;
+      return this;
+    }
+
+    /** Sets the log file that should be printed as part of the error message. */
+    public Builder logFile(Path logFile) {
+      Preconditions.checkNotNull(logFile);
+      try {
+        this.logFile = logFile;
+        return logText(FileSystemUtils.readContent(logFile, UTF_8));
+      } catch (IOException e) {
+        logSizeLimit(Integer.MAX_VALUE);
+        return logText(
+            "ERROR: IOException while trying to read log file:\n"
+                + Throwables.getStackTraceAsString(e));
+      }
+    }
+
+    /**
+     * Sets additional text, which is to be presented as a log file in the error message.
+     *
+     * <p>If the log originally comes from a file, it is recommended to use {@link #logFile}
+     * instead, because then the path to the log file can be printed together with the message.
+     */
+    public Builder logText(String logText) {
+      Preconditions.checkNotNull(logText);
+      // Set the log text to "(empty)" when the passed in string is empty, otherwise error messages
+      // like "Something failed. Check below log for details:" would be pretty confusing for users.
+      this.logText = logText.isEmpty() ? "(empty)" : logText.trim();
+      return this;
+    }
+
+    /**
+     * If the log file or text of this error message is longer than the character limit set via this
+     * method, it will be truncated so that only the last X characters of the log are printed.
+     */
+    public Builder logSizeLimit(int logSizeLimit) {
+      Preconditions.checkArgument(logSizeLimit > 0, "logSizeLimit must be positive");
+      this.logSizeLimit = logSizeLimit;
+      return this;
+    }
+
+    /** Builds and returns the formatted error message. */
+    public ErrorMessage build() {
+      StringBuilder sb = new StringBuilder(message);
+      if (!logText.isEmpty()) {
+        sb.append("\n---8<---8<--- (start of log");
+        if (logFile != null) {
+          sb.append(", file at ");
+          sb.append(logFile.getPathString());
+        }
+        sb.append(") ---8<---8<---\n");
+        // If the length of the log is longer than the limit, print only the last part.
+        if (logText.length() > logSizeLimit) {
+          sb.append("[... truncated ...]\n");
+          sb.append(logText, logText.length() - logSizeLimit, logText.length());
+          sb.append("\n---8<---8<--- (end of log snippet, ");
+          sb.append(logText.length() - logSizeLimit);
+          sb.append(" chars omitted) ---8<---8<---");
+        } else {
+          sb.append(logText);
+          sb.append("\n---8<---8<--- (end of log) ---8<---8<---");
+        }
+      }
+      return new AutoValue_ErrorMessage(sb.toString());
+    }
+  }
+}
diff --git a/src/main/java/com/google/devtools/build/lib/worker/Worker.java b/src/main/java/com/google/devtools/build/lib/worker/Worker.java
index 470e49f84b..a86cd1115e 100644
--- a/src/main/java/com/google/devtools/build/lib/worker/Worker.java
+++ b/src/main/java/com/google/devtools/build/lib/worker/Worker.java
@@ -150,4 +150,8 @@ class Worker {
   public void prepareExecution(WorkerKey key) throws IOException {}
 
   public void finishExecution(WorkerKey key) throws IOException {}
+
+  public Path getLogFile() {
+    return logFile;
+  }
 }
diff --git a/src/main/java/com/google/devtools/build/lib/worker/WorkerSpawnStrategy.java b/src/main/java/com/google/devtools/build/lib/worker/WorkerSpawnStrategy.java
index 96021406be..f6f3dc9391 100644
--- a/src/main/java/com/google/devtools/build/lib/worker/WorkerSpawnStrategy.java
+++ b/src/main/java/com/google/devtools/build/lib/worker/WorkerSpawnStrategy.java
@@ -296,15 +296,18 @@ public final class WorkerSpawnStrategy implements SandboxedSpawnActionContext {
       recordingStream.startRecording(4096);
       try {
         response = WorkResponse.parseDelimitedFrom(recordingStream);
-      } catch (InvalidProtocolBufferException e2) {
+      } catch (InvalidProtocolBufferException e) {
         // If protobuf couldn't parse the response, try to print whatever the failing worker wrote
         // to stdout - it's probably a stack trace or some kind of error message that will help the
         // user figure out why the compiler is failing.
         recordingStream.readRemaining();
-        String data = recordingStream.getRecordedDataAsString(Charsets.UTF_8);
-        eventHandler.handle(
-            Event.warn("Worker process returned an unparseable WorkResponse:\n" + data));
-        throw e2;
+        ErrorMessage errorMessage =
+            ErrorMessage.builder()
+                .message("Worker process returned an unparseable WorkResponse:")
+                .logText(recordingStream.getRecordedDataAsString(Charsets.UTF_8))
+                .build();
+        eventHandler.handle(Event.warn(errorMessage.toString()));
+        throw e;
       }
 
       if (writeOutputFiles != null
@@ -315,9 +318,15 @@ public final class WorkerSpawnStrategy implements SandboxedSpawnActionContext {
       worker.finishExecution(key);
 
       if (response == null) {
-        throw new UserExecException(
-            "Worker process did not return a WorkResponse. This is probably caused by a "
-                + "bug in the worker, writing unexpected other data to stdout.");
+        ErrorMessage errorMessage =
+            ErrorMessage.builder()
+                .message(
+                    "Worker process did not return a WorkResponse. This is usually caused by a bug"
+                        + " in the worker, thus dumping its log file for debugging purposes:")
+                .logFile(worker.getLogFile())
+                .logSizeLimit(4096)
+                .build();
+        throw new UserExecException(errorMessage.toString());
       }
     } catch (IOException e) {
       if (worker != null) {
diff --git a/src/test/java/com/google/devtools/build/lib/worker/ErrorMessageTest.java b/src/test/java/com/google/devtools/build/lib/worker/ErrorMessageTest.java
new file mode 100644
index 0000000000..37038b4172
--- /dev/null
+++ b/src/test/java/com/google/devtools/build/lib/worker/ErrorMessageTest.java
@@ -0,0 +1,115 @@
+// Copyright 2017 The Bazel Authors. All rights reserved.
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+// http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+package com.google.devtools.build.lib.worker;
+
+import static com.google.common.truth.Truth.assertThat;
+import static java.nio.charset.StandardCharsets.UTF_8;
+
+import com.google.devtools.build.lib.vfs.FileSystemUtils;
+import com.google.devtools.build.lib.vfs.Path;
+import com.google.devtools.build.lib.vfs.inmemoryfs.InMemoryFileSystem;
+import org.junit.Test;
+import org.junit.runner.RunWith;
+import org.junit.runners.JUnit4;
+
+/** Tests for {@link ErrorMessage}. */
+@RunWith(JUnit4.class)
+public class ErrorMessageTest {
+  String logText = "\n\nabcdefghijklmnopqrstuvwxyz\n\n";
+
+  @Test
+  public void testEmptyErrorMessage() {
+    ErrorMessage errorMessage = ErrorMessage.builder().build();
+    assertThat(errorMessage.toString()).isEqualTo("Unknown error");
+  }
+
+  @Test
+  public void testSimpleErrorMessage() {
+    ErrorMessage errorMessage = ErrorMessage.builder().message("Error").build();
+    assertThat(errorMessage.toString()).isEqualTo("Error");
+  }
+
+  @Test
+  public void testErrorMessageWithLogText() {
+    ErrorMessage errorMessage =
+        ErrorMessage.builder().message("Error with log text").logText(logText).build();
+    assertThat(errorMessage.toString())
+        .isEqualTo(
+            "Error with log text\n"
+                + "---8<---8<--- (start of log) ---8<---8<---\n"
+                + "abcdefghijklmnopqrstuvwxyz\n"
+                + "---8<---8<--- (end of log) ---8<---8<---");
+  }
+
+  @Test
+  public void testErrorMessageWithEmptyLogText() {
+    ErrorMessage errorMessage =
+        ErrorMessage.builder().message("Error with log text").logText("").build();
+    assertThat(errorMessage.toString())
+        .isEqualTo(
+            "Error with log text\n"
+                + "---8<---8<--- (start of log) ---8<---8<---\n"
+                + "(empty)\n"
+                + "---8<---8<--- (end of log) ---8<---8<---");
+  }
+
+  @Test
+  public void testErrorMessageWithTruncatedLogText() {
+    ErrorMessage errorMessage =
+        ErrorMessage.builder()
+            .message("Error with log text")
+            .logText(logText)
+            .logSizeLimit(13)
+            .build();
+    assertThat(errorMessage.toString())
+        .isEqualTo(
+            "Error with log text\n"
+                + "---8<---8<--- (start of log) ---8<---8<---\n"
+                + "[... truncated ...]\n"
+                + "nopqrstuvwxyz\n"
+                + "---8<---8<--- (end of log snippet, 13 chars omitted) ---8<---8<---");
+  }
+
+  @Test
+  public void testErrorMessageWithLogFile() throws Exception {
+    InMemoryFileSystem fs = new InMemoryFileSystem();
+    Path logFile = fs.getPath("/log.txt");
+    FileSystemUtils.writeContent(logFile, UTF_8, logText);
+    ErrorMessage errorMessage =
+        ErrorMessage.builder().message("Error with log file").logFile(logFile).build();
+    assertThat(errorMessage.toString())
+        .isEqualTo(
+            "Error with log file\n"
+                + "---8<---8<--- (start of log, file at /log.txt) ---8<---8<---\n"
+                + "abcdefghijklmnopqrstuvwxyz\n"
+                + "---8<---8<--- (end of log) ---8<---8<---");
+  }
+
+  @Test
+  public void testErrorMessageWithUnreadableLogFile() {
+    InMemoryFileSystem fs = new InMemoryFileSystem();
+    // This file does not exist.
+    Path logFile = fs.getPath("/nope.txt");
+    ErrorMessage errorMessage =
+        ErrorMessage.builder().message("Error with log file").logFile(logFile).build();
+    assertThat(errorMessage.toString())
+        .startsWith(
+            "Error with log file\n"
+                + "---8<---8<--- (start of log, file at /nope.txt) ---8<---8<---\n"
+                + "ERROR: IOException while trying to read log file:\n"
+                + "java.io.FileNotFoundException: /nope.txt (No such file or directory)\n");
+    assertThat(errorMessage.toString()).endsWith("---8<---8<--- (end of log) ---8<---8<---");
+  }
+}
diff --git a/src/test/java/com/google/devtools/build/lib/worker/ExampleWorker.java b/src/test/java/com/google/devtools/build/lib/worker/ExampleWorker.java
index a940ed0bd3..2ae261e309 100644
--- a/src/test/java/com/google/devtools/build/lib/worker/ExampleWorker.java
+++ b/src/test/java/com/google/devtools/build/lib/worker/ExampleWorker.java
@@ -96,6 +96,9 @@ public class ExampleWorker {
           System.setErr(ps);
 
           if (poisoned) {
+            if (workerOptions.hardPoison) {
+              throw new IllegalStateException("I'm a very poisoned worker and will just crash.");
+            }
             System.out.println("I'm a poisoned worker and this is not a protobuf.");
             System.out.println("Here's a fake stack trace for you:");
             System.out.println("    at com.example.Something(Something.java:83)");
diff --git a/src/test/java/com/google/devtools/build/lib/worker/ExampleWorkerOptions.java b/src/test/java/com/google/devtools/build/lib/worker/ExampleWorkerOptions.java
index 4de906a2ea..de454c9bc1 100644
--- a/src/test/java/com/google/devtools/build/lib/worker/ExampleWorkerOptions.java
+++ b/src/test/java/com/google/devtools/build/lib/worker/ExampleWorkerOptions.java
@@ -78,4 +78,11 @@ public class ExampleWorkerOptions extends OptionsBase {
             + "corrupt response instead of a response protobuf from then on (default: disabled)."
   )
   public int poisonAfter;
+
+  @Option(
+    name = "hard_poison",
+    defaultValue = "false",
+    help = "Instead of writing an error message to stdout, write it to stderr and terminate."
+  )
+  public boolean hardPoison;
 }
diff --git a/src/test/shell/integration/bazel_worker_test.sh b/src/test/shell/integration/bazel_worker_test.sh
index 84705beb9b..5c41d49861 100755
--- a/src/test/shell/integration/bazel_worker_test.sh
+++ b/src/test/shell/integration/bazel_worker_test.sh
@@ -523,4 +523,28 @@ EOF
   expect_log "Destroying Work worker (id [0-9]\+)"
 }
 
+function test_crashed_worker_causes_log_dump() {
+  prepare_example_worker
+  cat >>BUILD <<'EOF'
+[work(
+  name = "hello_world_%s" % idx,
+  worker = ":worker",
+  worker_args = ["--poison_after=1", "--hard_poison"],
+  args = ["--write_uuid", "--write_counter"],
+) for idx in range(10)]
+EOF
+
+  bazel build :hello_world_1 &> $TEST_log \
+    || fail "build failed"
+  worker_uuid_1=$(cat $BINS/hello_world_1.out | grep UUID | cut -d' ' -f2)
+
+  bazel build :hello_world_2 &> $TEST_log \
+    && fail "expected build to fail" || /bin/true
+  worker_uuid_2=$(cat $BINS/hello_world_2.out | grep UUID | cut -d' ' -f2)
+
+  expect_log "^---8<---8<--- (start of log, file at /"
+  expect_log "thus dumping its log file for debugging purposes:"
+  expect_log "I'm a very poisoned worker and will just crash."
+  expect_log "^---8<---8<--- (end of log) ---8<---8<---"
+}
 run_suite "Worker integration tests"