From 44e267980fffd6b0aaee49831fc83441e2000082 Mon Sep 17 00:00:00 2001 From: Klaus Aehlig Date: Fri, 10 Aug 2018 09:53:12 -0700 Subject: Combine prefix event and payload stdout/stderr ...in a single event instead of relying on the synchronisation on the reporter. In this way, it will be possible to focus on output of errors, and also to deduplicate warnings. Change-Id: I9669e8497ca6e22a01f3e285ec9ee42c1ecf3fb5 PiperOrigin-RevId: 208223882 --- .../google/devtools/build/lib/events/Event.java | 73 ++++++++++++++++++---- .../devtools/build/lib/events/EventCollector.java | 6 ++ .../build/lib/events/PrintingEventHandler.java | 14 ++++- .../lib/runtime/BlazeCommandEventHandler.java | 7 +++ .../lib/runtime/ExperimentalEventHandler.java | 24 ++++++- .../lib/runtime/FancyTerminalEventHandler.java | 14 ++++- .../build/lib/skyframe/SkyframeActionExecutor.java | 27 ++++---- src/test/shell/integration/experimental_ui_test.sh | 21 +++++++ 8 files changed, 155 insertions(+), 31 deletions(-) diff --git a/src/main/java/com/google/devtools/build/lib/events/Event.java b/src/main/java/com/google/devtools/build/lib/events/Event.java index 5bf5b1dd05..8835d17e06 100644 --- a/src/main/java/com/google/devtools/build/lib/events/Event.java +++ b/src/main/java/com/google/devtools/build/lib/events/Event.java @@ -31,6 +31,8 @@ public final class Event implements Serializable { private final EventKind kind; private final Location location; private final String message; + @Nullable private final String stdout; + @Nullable private final String stderr; /** * An alternative representation for message. @@ -46,23 +48,40 @@ public final class Event implements Serializable { private final int hashCode; - private Event(EventKind kind, @Nullable Location location, String message, @Nullable String tag) { + private Event( + EventKind kind, + @Nullable Location location, + String message, + @Nullable String tag, + @Nullable String stdout, + @Nullable String stderr) { this.kind = Preconditions.checkNotNull(kind); this.location = location; this.message = Preconditions.checkNotNull(message); this.messageBytes = null; this.tag = tag; - this.hashCode = Objects.hash(kind, location, message, tag, Arrays.hashCode(messageBytes)); + this.stdout = stdout; + this.stderr = stderr; + this.hashCode = + Objects.hash(kind, location, message, tag, Arrays.hashCode(messageBytes), stdout, stderr); } private Event( - EventKind kind, @Nullable Location location, byte[] messageBytes, @Nullable String tag) { + EventKind kind, + @Nullable Location location, + byte[] messageBytes, + @Nullable String tag, + @Nullable String stdout, + @Nullable String stderr) { this.kind = Preconditions.checkNotNull(kind); this.location = location; this.message = null; this.messageBytes = Preconditions.checkNotNull(messageBytes); this.tag = tag; - this.hashCode = Objects.hash(kind, location, message, tag, Arrays.hashCode(messageBytes)); + this.stdout = stdout; + this.stderr = stderr; + this.hashCode = + Objects.hash(kind, location, message, tag, Arrays.hashCode(messageBytes), stdout, stderr); } public Event withTag(String tag) { @@ -70,9 +89,17 @@ public final class Event implements Serializable { return this; } if (this.message != null) { - return new Event(this.kind, this.location, this.message, tag); + return new Event(this.kind, this.location, this.message, tag, this.stdout, this.stderr); + } else { + return new Event(this.kind, this.location, this.messageBytes, tag, this.stdout, this.stderr); + } + } + + public Event withStdoutStderr(String stdout, String stderr) { + if (this.message != null) { + return new Event(this.kind, this.location, this.message, this.tag, stdout, stderr); } else { - return new Event(this.kind, this.location, this.messageBytes, tag); + return new Event(this.kind, this.location, this.messageBytes, this.tag, stdout, stderr); } } @@ -96,6 +123,24 @@ public final class Event implements Serializable { return tag; } + /** + * Get the stdout bytes associated with this event; typically, the event will report where the + * output originated from. + */ + @Nullable + public String getStdOut() { + return stdout; + } + + /** + * Get the stdout bytes associated with this event; typically, the event will report where the + * output originated from. + */ + @Nullable + public String getStdErr() { + return stderr; + } + /** * Returns the location of this event, if any. Returns null iff the event * wasn't associated with any particular location, for example, a progress @@ -133,6 +178,8 @@ public final class Event implements Serializable { && Objects.equals(this.location, that.location) && Objects.equals(this.tag, that.tag) && Objects.equals(this.message, that.message) + && Objects.equals(this.stdout, that.stdout) + && Objects.equals(this.stderr, that.stderr) && Arrays.equals(this.messageBytes, that.messageBytes); } @@ -146,7 +193,7 @@ public final class Event implements Serializable { } public static Event of(EventKind kind, @Nullable Location location, String message) { - return new Event(kind, location, message, null); + return new Event(kind, location, message, null, null, null); } /** @@ -155,42 +202,42 @@ public final class Event implements Serializable { * The bytes must be decodable as UTF-8 text. */ public static Event of(EventKind kind, @Nullable Location location, byte[] messageBytes) { - return new Event(kind, location, messageBytes, null); + return new Event(kind, location, messageBytes, null, null, null); } /** * Reports an error. */ public static Event error(@Nullable Location location, String message){ - return new Event(EventKind.ERROR, location, message, null); + return new Event(EventKind.ERROR, location, message, null, null, null); } /** * Reports a warning. */ public static Event warn(@Nullable Location location, String message) { - return new Event(EventKind.WARNING, location, message, null); + return new Event(EventKind.WARNING, location, message, null, null, null); } /** * Reports atemporal statements about the build, i.e. they're true for the duration of execution. */ public static Event info(@Nullable Location location, String message) { - return new Event(EventKind.INFO, location, message, null); + return new Event(EventKind.INFO, location, message, null, null, null); } /** * Reports a temporal statement about the build. */ public static Event progress(@Nullable Location location, String message) { - return new Event(EventKind.PROGRESS, location, message, null); + return new Event(EventKind.PROGRESS, location, message, null, null, null); } /** * Reports a debug message. */ public static Event debug(@Nullable Location location, String message) { - return new Event(EventKind.DEBUG, location, message, null); + return new Event(EventKind.DEBUG, location, message, null, null, null); } /** diff --git a/src/main/java/com/google/devtools/build/lib/events/EventCollector.java b/src/main/java/com/google/devtools/build/lib/events/EventCollector.java index 46bf3adf3f..63c64a6b52 100644 --- a/src/main/java/com/google/devtools/build/lib/events/EventCollector.java +++ b/src/main/java/com/google/devtools/build/lib/events/EventCollector.java @@ -66,6 +66,12 @@ public final class EventCollector extends AbstractEventHandler implements Iterab if (getEventMask().contains(event.getKind())) { collected.add(event); } + if (event.getStdErr() != null) { + handle(Event.of(EventKind.STDERR, null, event.getStdErr())); + } + if (event.getStdOut() != null) { + handle(Event.of(EventKind.STDOUT, null, event.getStdOut())); + } } /** diff --git a/src/main/java/com/google/devtools/build/lib/events/PrintingEventHandler.java b/src/main/java/com/google/devtools/build/lib/events/PrintingEventHandler.java index fc16475694..fc57456d9c 100644 --- a/src/main/java/com/google/devtools/build/lib/events/PrintingEventHandler.java +++ b/src/main/java/com/google/devtools/build/lib/events/PrintingEventHandler.java @@ -81,7 +81,8 @@ public class PrintingEventHandler extends AbstractEventHandler */ @Override public void handle(Event event) { - if (!getEventMask().contains(event.getKind())) { + if (!getEventMask().contains(event.getKind())) { + handleFollowUpEvents(event); return; } try { @@ -113,5 +114,16 @@ public class PrintingEventHandler extends AbstractEventHandler */ outErr.printErrLn(e.getMessage()); } + handleFollowUpEvents(event); } + + private void handleFollowUpEvents(Event event) { + if (event.getStdErr() != null) { + handle(Event.of(EventKind.STDERR, null, event.getStdErr())); + } + if (event.getStdOut() != null) { + handle(Event.of(EventKind.STDOUT, null, event.getStdOut())); + } + } + } diff --git a/src/main/java/com/google/devtools/build/lib/runtime/BlazeCommandEventHandler.java b/src/main/java/com/google/devtools/build/lib/runtime/BlazeCommandEventHandler.java index bceb04c833..5fe8b5130a 100644 --- a/src/main/java/com/google/devtools/build/lib/runtime/BlazeCommandEventHandler.java +++ b/src/main/java/com/google/devtools/build/lib/runtime/BlazeCommandEventHandler.java @@ -329,6 +329,13 @@ public class BlazeCommandEventHandler implements EventHandler { // Event messages go to stderr; results (e.g. 'blaze query') go to stdout. errPrintStream.println(buf); + + if (event.getStdErr() != null) { + handle(Event.of(EventKind.STDERR, null, event.getStdErr())); + } + if (event.getStdOut() != null) { + handle(Event.of(EventKind.STDOUT, null, event.getStdOut())); + } } private void putOutput(OutputStream out, Event event) { diff --git a/src/main/java/com/google/devtools/build/lib/runtime/ExperimentalEventHandler.java b/src/main/java/com/google/devtools/build/lib/runtime/ExperimentalEventHandler.java index f68b3853d2..49ba57ba1b 100644 --- a/src/main/java/com/google/devtools/build/lib/runtime/ExperimentalEventHandler.java +++ b/src/main/java/com/google/devtools/build/lib/runtime/ExperimentalEventHandler.java @@ -319,6 +319,20 @@ public class ExperimentalEventHandler implements EventHandler { clearProgressBar(); terminal.flush(); outErr.getOutputStream().write((event + "\n").getBytes(StandardCharsets.UTF_8)); + if (event.getStdOut() != null) { + outErr + .getOutputStream() + .write( + ("... with STDOUT: " + event.getStdOut() + "\n") + .getBytes(StandardCharsets.UTF_8)); + } + if (event.getStdErr() != null) { + outErr + .getOutputStream() + .write( + ("... with STDERR: " + event.getStdErr() + "\n") + .getBytes(StandardCharsets.UTF_8)); + } outErr.getOutputStream().flush(); addProgressBar(); terminal.flush(); @@ -336,10 +350,10 @@ public class ExperimentalEventHandler implements EventHandler { stream.flush(); } else { byte[] message = event.getMessageBytes(); - double cap = remainingCapacity(message.length); - if (cap < 0) { + if (remainingCapacity() < 0) { return; } + double cap = remainingCapacity(message.length); if (cap < CAPACITY_LIMIT_OUT_ERR_EVENTS) { // Have to ensure the message is not too large. long allowedLength = @@ -439,6 +453,12 @@ public class ExperimentalEventHandler implements EventHandler { case DEPCHECKER: break; } + if (event.getStdErr() != null) { + handle(Event.of(EventKind.STDERR, null, event.getStdErr())); + } + if (event.getStdOut() != null) { + handle(Event.of(EventKind.STDOUT, null, event.getStdOut())); + } } } catch (IOException e) { logger.warning("IO Error writing to output stream: " + e); diff --git a/src/main/java/com/google/devtools/build/lib/runtime/FancyTerminalEventHandler.java b/src/main/java/com/google/devtools/build/lib/runtime/FancyTerminalEventHandler.java index e482eb6054..90975de9a5 100644 --- a/src/main/java/com/google/devtools/build/lib/runtime/FancyTerminalEventHandler.java +++ b/src/main/java/com/google/devtools/build/lib/runtime/FancyTerminalEventHandler.java @@ -133,12 +133,14 @@ public class FancyTerminalEventHandler extends BlazeCommandEventHandler { return; } if (!eventMask.contains(event.getKind())) { + handleFollowUpEvents(event); return; } if (trySpecial && !EventKind.ERRORS_AND_WARNINGS_AND_OUTPUT.contains(event.getKind()) && skipUntil.isAfter(Instant.now())) { // Short-circuit here to avoid wiping out previous terminal contents. + handleFollowUpEvents(event); return; } @@ -235,8 +237,18 @@ public class FancyTerminalEventHandler extends BlazeCommandEventHandler { logger.warning("Terminal was closed during build: " + e); terminalClosed = true; } + handleFollowUpEvents(event); } - + + private void handleFollowUpEvents(Event event) { + if (event.getStdErr() != null) { + handle(Event.of(EventKind.STDERR, null, event.getStdErr())); + } + if (event.getStdOut() != null) { + handle(Event.of(EventKind.STDOUT, null, event.getStdOut())); + } + } + private String getExtraMessage() { synchronized (messageIterator) { if (messageIterator.hasNext()) { diff --git a/src/main/java/com/google/devtools/build/lib/skyframe/SkyframeActionExecutor.java b/src/main/java/com/google/devtools/build/lib/skyframe/SkyframeActionExecutor.java index 5ddabcce58..5fd47c7460 100644 --- a/src/main/java/com/google/devtools/build/lib/skyframe/SkyframeActionExecutor.java +++ b/src/main/java/com/google/devtools/build/lib/skyframe/SkyframeActionExecutor.java @@ -81,7 +81,6 @@ import com.google.devtools.build.lib.profiler.SilentCloseable; import com.google.devtools.build.lib.rules.cpp.IncludeScannable; import com.google.devtools.build.lib.util.Pair; import com.google.devtools.build.lib.util.io.FileOutErr; -import com.google.devtools.build.lib.util.io.OutErr; import com.google.devtools.build.lib.vfs.FileSystem; import com.google.devtools.build.lib.vfs.OutputService; import com.google.devtools.build.lib.vfs.Path; @@ -1211,20 +1210,20 @@ public final class SkyframeActionExecutor { * @param outErrBuffer The OutErr that recorded the actions output */ private void dumpRecordedOutErr(Event prefixEvent, FileOutErr outErrBuffer) { - // Synchronize this on the reporter, so that the output from multiple - // actions will not be interleaved. - synchronized (reporter) { - // Only print the output if we're not winding down. - if (isBuilderAborting()) { - return; - } + // Only print the output if we're not winding down. + if (isBuilderAborting()) { + return; + } + if (outErrBuffer != null && outErrBuffer.hasRecordedOutput()) { + // Bind the output to the prefix event. + // Note: here we temporarily (until the event is handled by the UI) read all + // output into memory; as the output of regular actions (as opposed to test runs) usually is + // short, so this should not be a problem. If it does turn out to be a problem, we have to + // pass the outErrbuffer instead. + reporter.handle( + prefixEvent.withStdoutStderr(outErrBuffer.outAsLatin1(), outErrBuffer.errAsLatin1())); + } else { reporter.handle(prefixEvent); - - if (outErrBuffer != null && outErrBuffer.hasRecordedOutput()) { - OutErr outErr = this.reporter.getOutErr(); - outErrBuffer.dumpOutAsLatin1(outErr.getOutputStream()); - outErrBuffer.dumpErrAsLatin1(outErr.getErrorStream()); - } } } diff --git a/src/test/shell/integration/experimental_ui_test.sh b/src/test/shell/integration/experimental_ui_test.sh index d73778de6a..2759243d8f 100755 --- a/src/test/shell/integration/experimental_ui_test.sh +++ b/src/test/shell/integration/experimental_ui_test.sh @@ -145,8 +145,18 @@ sh_test( srcs = ["true.sh"], deps = [":outputlib"], ) +EOF + mkdir -p error + cat > error/BUILD <<'EOF' +genrule( + name = "failwitherror", + outs = ["fail.txt"], + cmd = "echo Here is the error message; exit 1", +) EOF chmod -w pkg/* # prevent accidental editing + # keep directories writable though, so that test clean up can work + chmod 755 error } #### TESTS ############################################################# @@ -330,6 +340,17 @@ function test_streamed { expect_log 'foobar' } +function test_stdout_bundled { + # Verify that the error message is part of the error event + bazel build --experimental_ui --experimental_ui_debug_all_events \ + error:failwitherror > "${TEST_log}" 2>&1 \ + && fail "expected failure" || : + grep -A1 '^ERROR' "${TEST_log}" \ + | grep -q "with STDOUT: Here is the error message" \ + || fail "Error message not bundled" +} + + function test_output_limit { # Verify that output limting works bazel clean --expunge -- cgit v1.2.3