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
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 50d3928..ef74275 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 @@ "//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 0000000..343ad1d --- /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 470e49f..a86cd11 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 @@ 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 9602140..f6f3dc9 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 @@ 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 @@ 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 0000000..37038b4 --- /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 a940ed0..2ae261e 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 @@ 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 4de906a..de454c9 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 @@ + "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 84705be..5c41d49 100755 --- a/src/test/shell/integration/bazel_worker_test.sh +++ b/src/test/shell/integration/bazel_worker_test.sh
@@ -523,4 +523,28 @@ 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"