From 9e0308e0f7f18f752cf11350520313cf75c228e5 Mon Sep 17 00:00:00 2001 From: buchgr Date: Tue, 25 Apr 2017 16:38:45 +0200 Subject: [PATCH] Automated g4 rollback of commit d9fea57268ff01c001fbcbdc2bd057c86c362e6f. *** Reason for rollback *** Rollforward with fix for test flakiness. BEP transport closed events are delivered via their own threadpool and thus might not have been sent immediately. BuildEventStreamerTest#testSimpleStream now waits for a bit until the event has been delivered. I ran the test with --runs_per_test=1000 several times and had no further failures. *** Original change description *** Automated g4 rollback of commit 3d596d63f883fff56001ed7b2e5cf51dba45f082. *** Reason for rollback *** Made BuildEventStreamerTest#testSimpleStream 3% flaky based on --runs_per_test=1000. RELNOTES: None PiperOrigin-RevId: 154170833 --- .../AnnounceBuildEventTransportsEvent.java | 38 ++++++ .../buildeventstream/BuildEventTransport.java | 9 +- .../BuildEventTransportClosedEvent.java | 35 +++++ .../transports/BinaryFormatFileTransport.java | 5 + .../transports/FileTransport.java | 4 +- .../transports/TextFormatFileTransport.java | 5 + .../build/lib/runtime/BuildEventStreamer.java | 87 ++++++++++-- .../lib/runtime/BuildEventStreamerModule.java | 3 +- .../lib/runtime/ExperimentalEventHandler.java | 41 +++++- .../lib/runtime/ExperimentalStateTracker.java | 76 +++++++++++ .../lib/runtime/BuildEventStreamerTest.java | 67 +++++++-- .../runtime/ExperimentalStateTrackerTest.java | 127 ++++++++++++++++++ .../lib/testutil/FoundationTestCase.java | 5 +- 13 files changed, 470 insertions(+), 32 deletions(-) create mode 100644 src/main/java/com/google/devtools/build/lib/buildeventstream/AnnounceBuildEventTransportsEvent.java create mode 100644 src/main/java/com/google/devtools/build/lib/buildeventstream/BuildEventTransportClosedEvent.java diff --git a/src/main/java/com/google/devtools/build/lib/buildeventstream/AnnounceBuildEventTransportsEvent.java b/src/main/java/com/google/devtools/build/lib/buildeventstream/AnnounceBuildEventTransportsEvent.java new file mode 100644 index 00000000000000..e27f0b13ec1190 --- /dev/null +++ b/src/main/java/com/google/devtools/build/lib/buildeventstream/AnnounceBuildEventTransportsEvent.java @@ -0,0 +1,38 @@ +// 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.buildeventstream; + +import com.google.common.collect.ImmutableSet; +import com.google.devtools.build.lib.events.ExtendedEventHandler.Postable; +import java.util.Collection; +import java.util.Set; + +/** + * An event announcing a list of all active {@link BuildEventTransport}s. + */ +public class AnnounceBuildEventTransportsEvent implements Postable { + + private final Set transports; + + public AnnounceBuildEventTransportsEvent(Collection transports) { + this.transports = ImmutableSet.copyOf(transports); + } + + /** + * Returns a list of all active build event transports. + */ + public Set transports() { + return transports; + } +} diff --git a/src/main/java/com/google/devtools/build/lib/buildeventstream/BuildEventTransport.java b/src/main/java/com/google/devtools/build/lib/buildeventstream/BuildEventTransport.java index dba5a123d2314f..84845ab80c7dfa 100644 --- a/src/main/java/com/google/devtools/build/lib/buildeventstream/BuildEventTransport.java +++ b/src/main/java/com/google/devtools/build/lib/buildeventstream/BuildEventTransport.java @@ -13,7 +13,7 @@ // limitations under the License. package com.google.devtools.build.lib.buildeventstream; -import java.util.concurrent.Future; +import com.google.common.util.concurrent.ListenableFuture; import javax.annotation.concurrent.ThreadSafe; /** @@ -27,6 +27,11 @@ @ThreadSafe public interface BuildEventTransport { + /** + * The name of this transport as can be displayed to a user. + */ + String name(); + /** * Writes a build event to an endpoint. This method will always return quickly and will not * wait for the write to complete. @@ -49,5 +54,5 @@ public interface BuildEventTransport { * *

This method should not throw any exceptions. */ - Future close(); + ListenableFuture close(); } diff --git a/src/main/java/com/google/devtools/build/lib/buildeventstream/BuildEventTransportClosedEvent.java b/src/main/java/com/google/devtools/build/lib/buildeventstream/BuildEventTransportClosedEvent.java new file mode 100644 index 00000000000000..813e4f4a1c8222 --- /dev/null +++ b/src/main/java/com/google/devtools/build/lib/buildeventstream/BuildEventTransportClosedEvent.java @@ -0,0 +1,35 @@ +// 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.buildeventstream; + +import com.google.devtools.build.lib.events.ExtendedEventHandler.Postable; + +/** + * An event signaling that a {@link BuildEventTransport} has been closed. + */ +public class BuildEventTransportClosedEvent implements Postable { + + private final BuildEventTransport transport; + + public BuildEventTransportClosedEvent(BuildEventTransport transport) { + this.transport = transport; + } + + /** + * Returns the {@link BuildEventTransport} that has been closed. + */ + public BuildEventTransport transport() { + return transport; + } +} diff --git a/src/main/java/com/google/devtools/build/lib/buildeventstream/transports/BinaryFormatFileTransport.java b/src/main/java/com/google/devtools/build/lib/buildeventstream/transports/BinaryFormatFileTransport.java index 9de20b7175dddf..6173e9febc7927 100644 --- a/src/main/java/com/google/devtools/build/lib/buildeventstream/transports/BinaryFormatFileTransport.java +++ b/src/main/java/com/google/devtools/build/lib/buildeventstream/transports/BinaryFormatFileTransport.java @@ -43,6 +43,11 @@ public final class BinaryFormatFileTransport extends FileTransport { this.pathConverter = pathConverter; } + @Override + public String name() { + return this.getClass().getSimpleName(); + } + @Override public synchronized void sendBuildEvent(BuildEvent event, final ArtifactGroupNamer namer) { BuildEventConverters converters = diff --git a/src/main/java/com/google/devtools/build/lib/buildeventstream/transports/FileTransport.java b/src/main/java/com/google/devtools/build/lib/buildeventstream/transports/FileTransport.java index 6744df3ef6bbec..3482cadd4bb268 100644 --- a/src/main/java/com/google/devtools/build/lib/buildeventstream/transports/FileTransport.java +++ b/src/main/java/com/google/devtools/build/lib/buildeventstream/transports/FileTransport.java @@ -18,6 +18,7 @@ import static com.google.common.base.Preconditions.checkState; import com.google.common.annotations.VisibleForTesting; +import com.google.common.util.concurrent.ListenableFuture; import com.google.common.util.concurrent.SettableFuture; import com.google.devtools.build.lib.buildeventstream.BuildEvent; import com.google.devtools.build.lib.buildeventstream.BuildEventTransport; @@ -27,7 +28,6 @@ import java.nio.channels.CompletionHandler; import java.nio.file.Paths; import java.nio.file.StandardOpenOption; -import java.util.concurrent.Future; import java.util.logging.Level; import java.util.logging.Logger; @@ -87,7 +87,7 @@ synchronized void writeData(byte[] data) { } @Override - public synchronized Future close() { + public synchronized ListenableFuture close() { if (closing()) { return closeFuture; } diff --git a/src/main/java/com/google/devtools/build/lib/buildeventstream/transports/TextFormatFileTransport.java b/src/main/java/com/google/devtools/build/lib/buildeventstream/transports/TextFormatFileTransport.java index cf892955a7a191..dc7c2ade65c25a 100644 --- a/src/main/java/com/google/devtools/build/lib/buildeventstream/transports/TextFormatFileTransport.java +++ b/src/main/java/com/google/devtools/build/lib/buildeventstream/transports/TextFormatFileTransport.java @@ -37,6 +37,11 @@ public final class TextFormatFileTransport extends FileTransport { this.pathConverter = pathConverter; } + @Override + public String name() { + return this.getClass().getSimpleName(); + } + @Override public synchronized void sendBuildEvent(BuildEvent event, final ArtifactGroupNamer namer) { BuildEventConverters converters = diff --git a/src/main/java/com/google/devtools/build/lib/runtime/BuildEventStreamer.java b/src/main/java/com/google/devtools/build/lib/runtime/BuildEventStreamer.java index 63583149fcc91f..90242a8e7e73a8 100644 --- a/src/main/java/com/google/devtools/build/lib/runtime/BuildEventStreamer.java +++ b/src/main/java/com/google/devtools/build/lib/runtime/BuildEventStreamer.java @@ -14,23 +14,31 @@ package com.google.devtools.build.lib.runtime; +import static com.google.devtools.build.lib.events.Event.of; +import static com.google.devtools.build.lib.events.EventKind.PROGRESS; +import static com.google.devtools.build.lib.util.Preconditions.checkArgument; + import com.google.common.annotations.VisibleForTesting; import com.google.common.collect.HashMultimap; import com.google.common.collect.ImmutableSet; import com.google.common.collect.Multimap; import com.google.common.collect.Sets; import com.google.common.eventbus.Subscribe; +import com.google.common.util.concurrent.Futures; +import com.google.common.util.concurrent.ListenableFuture; import com.google.devtools.build.lib.actions.ActionExecutedEvent; import com.google.devtools.build.lib.actions.Artifact; import com.google.devtools.build.lib.actions.EventReportingArtifacts; import com.google.devtools.build.lib.analysis.NoBuildEvent; import com.google.devtools.build.lib.buildeventstream.AbortedEvent; +import com.google.devtools.build.lib.buildeventstream.AnnounceBuildEventTransportsEvent; import com.google.devtools.build.lib.buildeventstream.ArtifactGroupNamer; import com.google.devtools.build.lib.buildeventstream.BuildEvent; import com.google.devtools.build.lib.buildeventstream.BuildEventId; import com.google.devtools.build.lib.buildeventstream.BuildEventStreamProtos.Aborted.AbortReason; import com.google.devtools.build.lib.buildeventstream.BuildEventStreamProtos.BuildEventId.NamedSetOfFilesId; import com.google.devtools.build.lib.buildeventstream.BuildEventTransport; +import com.google.devtools.build.lib.buildeventstream.BuildEventTransportClosedEvent; import com.google.devtools.build.lib.buildeventstream.BuildEventWithOrderConstraint; import com.google.devtools.build.lib.buildeventstream.ProgressEvent; import com.google.devtools.build.lib.buildtool.buildevent.BuildCompleteEvent; @@ -39,6 +47,7 @@ import com.google.devtools.build.lib.collect.nestedset.NestedSetView; import com.google.devtools.build.lib.events.Event; import com.google.devtools.build.lib.events.EventHandler; +import com.google.devtools.build.lib.events.Reporter; import com.google.devtools.build.lib.rules.extra.ExtraAction; import java.util.ArrayList; import java.util.Collection; @@ -47,13 +56,26 @@ import java.util.List; import java.util.Map; import java.util.Set; -import java.util.concurrent.Future; +import java.util.concurrent.Executors; +import java.util.concurrent.ScheduledExecutorService; +import java.util.concurrent.ScheduledFuture; +import java.util.concurrent.TimeUnit; import java.util.logging.Logger; -/** Listen for {@link BuildEvent} and stream them to the provided {@link BuildEventTransport}. */ +/** + * Listens for {@link BuildEvent}s and streams them to the provided {@link BuildEventTransport}s. + * + *

The streamer takes care of closing all {@link BuildEventTransport}s. It does so after having + * received a {@link BuildCompleteEvent}. Furthermore, it emits two event types to the + * {@code eventBus}. After having received the first {@link BuildEvent} it emits a + * {@link AnnounceBuildEventTransportsEvent} that contains a list of all its transports. + * Furthermore, after a transport has been closed, it emits + * a {@link BuildEventTransportClosedEvent}. + */ public class BuildEventStreamer implements EventHandler { private final Collection transports; + private final Reporter reporter; private Set announcedEvents; private final Set postedEvents = new HashSet<>(); private final Multimap pendingEvents = HashMultimap.create(); @@ -93,8 +115,10 @@ synchronized String maybeName(NestedSetView view) { } } - public BuildEventStreamer(Collection transports) { + public BuildEventStreamer(Collection transports, Reporter reporter) { + checkArgument(transports.size() > 0); this.transports = transports; + this.reporter = reporter; this.announcedEvents = null; this.progressCount = 0; } @@ -119,6 +143,10 @@ private void post(BuildEvent event) { announcedEvents.addAll(linkEvent.getChildrenEvents()); postedEvents.add(linkEvent.getEventId()); } + + if (reporter != null) { + reporter.post(new AnnounceBuildEventTransportsEvent(transports)); + } } else { if (!announcedEvents.contains(id)) { linkEvent = ProgressEvent.progressChainIn(progressCount, id); @@ -165,20 +193,57 @@ private void clearAnnouncedEvents() { } } - private void close() { - List> shutdownFutures = new ArrayList<>(transports.size()); + private ScheduledFuture bepUploadWaitEvent(ScheduledExecutorService executor) { + final long startNanos = System.nanoTime(); + return executor.scheduleAtFixedRate(new Runnable() { + @Override + public void run() { + long deltaNanos = System.nanoTime() - startNanos; + long deltaSeconds = TimeUnit.NANOSECONDS.toSeconds(deltaNanos); + Event waitEvt = + of(PROGRESS, null, "Waiting for build event protocol upload: " + deltaSeconds + "s"); + if (reporter != null) { + reporter.handle(waitEvt); + } + } + }, 0, 1, TimeUnit.SECONDS); + } - for (BuildEventTransport transport : transports) { - shutdownFutures.add(transport.close()); - } + private void close() { + ScheduledExecutorService executor = null; + try { + executor = Executors.newSingleThreadScheduledExecutor(); + List> closeFutures = new ArrayList<>(transports.size()); + for (final BuildEventTransport transport : transports) { + ListenableFuture closeFuture = transport.close(); + closeFuture.addListener(new Runnable() { + @Override + public void run() { + if (reporter != null) { + reporter.post(new BuildEventTransportClosedEvent(transport)); + } + } + }, executor); + closeFutures.add(closeFuture); + } - // Wait for all transports to close. - for (Future f : shutdownFutures) { try { - f.get(); + if (closeFutures.isEmpty()) { + // Don't spam events if there is nothing to close. + return; + } + + ScheduledFuture f = bepUploadWaitEvent(executor); + // Wait for all transports to close. + Futures.allAsList(closeFutures).get(); + f.cancel(true); } catch (Exception e) { log.severe("Failed to close a build event transport: " + e); } + } finally { + if (executor != null) { + executor.shutdown(); + } } } diff --git a/src/main/java/com/google/devtools/build/lib/runtime/BuildEventStreamerModule.java b/src/main/java/com/google/devtools/build/lib/runtime/BuildEventStreamerModule.java index 983aeb38e5c931..846c8aa30212e3 100644 --- a/src/main/java/com/google/devtools/build/lib/runtime/BuildEventStreamerModule.java +++ b/src/main/java/com/google/devtools/build/lib/runtime/BuildEventStreamerModule.java @@ -108,7 +108,8 @@ public String apply(Path path) { ImmutableSet buildEventTransports = createFromOptions(besOptions, pathConverter); if (!buildEventTransports.isEmpty()) { - BuildEventStreamer streamer = new BuildEventStreamer(buildEventTransports); + BuildEventStreamer streamer = new BuildEventStreamer(buildEventTransports, + commandEnvironment != null ? commandEnvironment.getReporter() : null); return Optional.of(streamer); } } catch (IOException e) { 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 ce182be0350ed1..fc5eca4344d1e2 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 @@ -13,6 +13,8 @@ // limitations under the License. package com.google.devtools.build.lib.runtime; +import static com.google.devtools.build.lib.util.Preconditions.checkState; + import com.google.common.collect.ImmutableSet; import com.google.common.eventbus.Subscribe; import com.google.common.primitives.Bytes; @@ -22,6 +24,8 @@ import com.google.devtools.build.lib.actions.ActionStatusMessage; import com.google.devtools.build.lib.analysis.AnalysisPhaseCompleteEvent; import com.google.devtools.build.lib.analysis.NoBuildEvent; +import com.google.devtools.build.lib.buildeventstream.AnnounceBuildEventTransportsEvent; +import com.google.devtools.build.lib.buildeventstream.BuildEventTransportClosedEvent; import com.google.devtools.build.lib.buildtool.buildevent.BuildCompleteEvent; import com.google.devtools.build.lib.buildtool.buildevent.BuildStartingEvent; import com.google.devtools.build.lib.buildtool.buildevent.ExecutionProgressReceiverAvailableEvent; @@ -85,6 +89,8 @@ public class ExperimentalEventHandler implements EventHandler { private long mustRefreshAfterMillis; private int numLinesProgressBar; private boolean buildComplete; + // Number of open build even protocol transports. + private int openBepTransports; private boolean progressBarNeedsRefresh; private Thread updateThread; private byte[] stdoutBuffer; @@ -320,7 +326,7 @@ public void progressReceiverAvailable(ExecutionProgressReceiverAvailableEvent ev @Subscribe public void buildComplete(BuildCompleteEvent event) { // The final progress bar will flow into the scroll-back buffer, to if treat - // it as an event and add a time stamp, if events are supposed to have a time stmap. + // it as an event and add a timestamp, if events are supposed to have a timestmap. synchronized (this) { if (showTimestamp) { stateTracker.buildComplete(event, TIMESTAMP_FORMAT.print(clock.currentTimeMillis())); @@ -329,10 +335,15 @@ public void buildComplete(BuildCompleteEvent event) { } ignoreRefreshLimitOnce(); refresh(); - buildComplete = true; + + // After a build has completed, only stop updating the UI if there is no more BEP + // upload happening. + if (openBepTransports == 0) { + buildComplete = true; + stopUpdateThread(); + flushStdOutStdErrBuffers(); + } } - stopUpdateThread(); - flushStdOutStdErrBuffers(); } @Subscribe @@ -434,6 +445,28 @@ public synchronized void testSummary(TestSummary summary) { } } + @Subscribe + public synchronized void buildEventTransportsAnnounced(AnnounceBuildEventTransportsEvent event) { + openBepTransports = event.transports().size(); + stateTracker.buildEventTransportsAnnounced(event); + } + + @Subscribe + public synchronized void buildEventTransportClosed(BuildEventTransportClosedEvent event) { + checkState(openBepTransports > 0); + openBepTransports--; + stateTracker.buildEventTransportClosed(event); + + if (openBepTransports == 0) { + stopUpdateThread(); + flushStdOutStdErrBuffers(); + ignoreRefreshLimitOnce(); + refresh(); + } else { + refresh(); + } + } + private void refresh() { if (showProgress) { progressBarNeedsRefresh = true; diff --git a/src/main/java/com/google/devtools/build/lib/runtime/ExperimentalStateTracker.java b/src/main/java/com/google/devtools/build/lib/runtime/ExperimentalStateTracker.java index 73f32e493c43e2..e81ce32e616523 100644 --- a/src/main/java/com/google/devtools/build/lib/runtime/ExperimentalStateTracker.java +++ b/src/main/java/com/google/devtools/build/lib/runtime/ExperimentalStateTracker.java @@ -13,12 +13,17 @@ // limitations under the License. package com.google.devtools.build.lib.runtime; +import static java.util.concurrent.TimeUnit.MILLISECONDS; + import com.google.devtools.build.lib.actions.Action; import com.google.devtools.build.lib.actions.ActionCompletionEvent; import com.google.devtools.build.lib.actions.ActionStartedEvent; import com.google.devtools.build.lib.actions.ActionStatusMessage; import com.google.devtools.build.lib.analysis.AnalysisPhaseCompleteEvent; import com.google.devtools.build.lib.analysis.ConfiguredTarget; +import com.google.devtools.build.lib.buildeventstream.AnnounceBuildEventTransportsEvent; +import com.google.devtools.build.lib.buildeventstream.BuildEventTransport; +import com.google.devtools.build.lib.buildeventstream.BuildEventTransportClosedEvent; import com.google.devtools.build.lib.buildtool.ExecutionProgressReceiver; import com.google.devtools.build.lib.buildtool.buildevent.BuildCompleteEvent; import com.google.devtools.build.lib.buildtool.buildevent.BuildStartingEvent; @@ -36,7 +41,9 @@ import com.google.devtools.build.lib.view.test.TestStatus.BlazeTestStatus; import java.io.IOException; import java.util.ArrayDeque; +import java.util.Collections; import java.util.Deque; +import java.util.HashSet; import java.util.LinkedHashSet; import java.util.Map; import java.util.Set; @@ -93,10 +100,16 @@ class ExperimentalStateTracker { private TestSummary mostRecentTest; private int failedTests; private boolean ok; + private boolean buildComplete; private ExecutionProgressReceiver executionProgressReceiver; private PackageProgressReceiver packageProgressReceiver; + // Set of build event protocol transports that need yet to be closed. + private Set bepOpenTransports = Collections.emptySet(); + // The point in time when closing of BEP transports was started. + private long bepTransportClosingStartTimeMillis; + ExperimentalStateTracker(Clock clock, int targetWidth) { this.runningActions = new ArrayDeque<>(); this.actions = new TreeMap<>(); @@ -167,6 +180,10 @@ void progressReceiverAvailable(ExecutionProgressReceiverAvailableEvent event) { } void buildComplete(BuildCompleteEvent event, String additionalInfo) { + buildComplete = true; + // Build event protocol transports are closed right after the build complete event. + bepTransportClosingStartTimeMillis = clock.currentTimeMillis(); + if (event.getResult().getSuccess()) { status = "INFO"; if (failedTests == 0) { @@ -307,6 +324,13 @@ private String shortenedLabelString(Label label, int width) { return label.toString(); } + private String shortenedString(String s, int maxWidth) { + if (maxWidth <= 3 * ELLIPSIS.length() || s.length() <= maxWidth) { + return s; + } + return s.substring(0, maxWidth - ELLIPSIS.length()) + ELLIPSIS; + } + // Describe a group of actions running for the same test. private String describeTestGroup( Label owner, long nanoTime, int desiredWidth, Set allActions) { @@ -471,6 +495,14 @@ public synchronized void testSummary(TestSummary summary) { } } + synchronized void buildEventTransportsAnnounced(AnnounceBuildEventTransportsEvent event) { + this.bepOpenTransports = new HashSet(event.transports()); + } + + synchronized void buildEventTransportClosed(BuildEventTransportClosedEvent event) { + bepOpenTransports.remove(event.transport()); + } + /*** * Predicate indicating whether the contents of the progress bar can change, if the * only thing that happens is that time passes; this is the case, e.g., if the progress @@ -483,6 +515,9 @@ boolean progressBarTimeDependent() { if (runningDownloads.size() >= 1) { return true; } + if (buildComplete && !bepOpenTransports.isEmpty()) { + return true; + } if (status != null) { return false; } @@ -606,6 +641,46 @@ private void reportOnDownloads(AnsiTerminalWriter terminalWriter) throws IOExcep } } + /** + * Display any BEP transports that are still open after the build. Most likely, because + * uploading build events takes longer than the build itself. + */ + private void maybeReportBepTransports(PositionAwareAnsiTerminalWriter terminalWriter) + throws IOException { + if (!buildComplete || bepOpenTransports.isEmpty()) { + return; + } + long sinceSeconds = + MILLISECONDS.toSeconds(clock.currentTimeMillis() - bepTransportClosingStartTimeMillis); + if (sinceSeconds == 0) { + // Special case for when bazel was interrupted, in which case we don't want to have + // a BEP upload message. + return; + } + int count = bepOpenTransports.size(); + // Can just use targetWidth, because we always write to a new line + int maxWidth = targetWidth; + + String waitMessage = "Waiting for build events upload: "; + String name = bepOpenTransports.iterator().next().name(); + String line = waitMessage + name + " " + sinceSeconds + "s"; + + if (count == 1 && line.length() <= maxWidth) { + terminalWriter.newline().append(line); + } else if (count == 1) { + waitMessage = "Waiting for: "; + String waitSecs = " " + sinceSeconds + "s"; + int maxNameWidth = maxWidth - waitMessage.length() - waitSecs.length(); + terminalWriter.newline().append(waitMessage + shortenedString(name, maxNameWidth) + waitSecs); + } else { + terminalWriter.newline().append(waitMessage + sinceSeconds + "s"); + for (BuildEventTransport transport : bepOpenTransports) { + name = " " + transport.name(); + terminalWriter.newline().append(shortenedString(name, maxWidth)); + } + } + } + synchronized void writeProgressBar(AnsiTerminalWriter rawTerminalWriter, boolean shortVersion) throws IOException { PositionAwareAnsiTerminalWriter terminalWriter = @@ -626,6 +701,7 @@ synchronized void writeProgressBar(AnsiTerminalWriter rawTerminalWriter, boolean } if (!shortVersion) { reportOnDownloads(terminalWriter); + maybeReportBepTransports(terminalWriter); } return; } diff --git a/src/test/java/com/google/devtools/build/lib/runtime/BuildEventStreamerTest.java b/src/test/java/com/google/devtools/build/lib/runtime/BuildEventStreamerTest.java index 3e7fe5d2dd5d3a..a360598077d6ce 100644 --- a/src/test/java/com/google/devtools/build/lib/runtime/BuildEventStreamerTest.java +++ b/src/test/java/com/google/devtools/build/lib/runtime/BuildEventStreamerTest.java @@ -15,13 +15,17 @@ import static com.google.common.truth.Truth.assertThat; import static org.junit.Assert.assertEquals; +import static org.junit.Assert.assertNull; import static org.junit.Assert.assertTrue; import com.google.common.collect.ImmutableSet; +import com.google.common.eventbus.Subscribe; import com.google.common.util.concurrent.Futures; +import com.google.common.util.concurrent.ListenableFuture; import com.google.devtools.build.lib.actions.Artifact; import com.google.devtools.build.lib.actions.EventReportingArtifacts; import com.google.devtools.build.lib.actions.Root; +import com.google.devtools.build.lib.buildeventstream.AnnounceBuildEventTransportsEvent; import com.google.devtools.build.lib.buildeventstream.ArtifactGroupNamer; import com.google.devtools.build.lib.buildeventstream.BuildEvent; import com.google.devtools.build.lib.buildeventstream.BuildEventConverters; @@ -29,6 +33,7 @@ import com.google.devtools.build.lib.buildeventstream.BuildEventStreamProtos; import com.google.devtools.build.lib.buildeventstream.BuildEventStreamProtos.BuildEventId.NamedSetOfFilesId; import com.google.devtools.build.lib.buildeventstream.BuildEventTransport; +import com.google.devtools.build.lib.buildeventstream.BuildEventTransportClosedEvent; import com.google.devtools.build.lib.buildeventstream.BuildEventWithOrderConstraint; import com.google.devtools.build.lib.buildeventstream.GenericBuildEvent; import com.google.devtools.build.lib.buildeventstream.PathConverter; @@ -43,11 +48,17 @@ import com.google.devtools.build.lib.vfs.PathFragment; import java.util.ArrayList; import java.util.Collection; +import java.util.Collections; +import java.util.HashSet; import java.util.List; -import java.util.concurrent.Future; +import java.util.Set; +import java.util.concurrent.TimeUnit; +import java.util.concurrent.locks.LockSupport; +import org.junit.Before; import org.junit.Test; import org.junit.runner.RunWith; import org.junit.runners.JUnit4; +import org.mockito.MockitoAnnotations; /** Tests {@link BuildEventStreamer}. */ @RunWith(JUnit4.class) @@ -57,6 +68,11 @@ private static class RecordingBuildEventTransport implements BuildEventTransport private final List events = new ArrayList<>(); private final List eventsAsProtos = new ArrayList<>(); + @Override + public String name() { + return this.getClass().getSimpleName(); + } + @Override public void sendBuildEvent(BuildEvent event, final ArtifactGroupNamer namer) { events.add(event); @@ -81,7 +97,7 @@ public String apply(Path path) { } @Override - public Future close() { + public ListenableFuture close() { return Futures.immediateFuture(null); } @@ -182,14 +198,38 @@ private static BuildEventId testId(String opaque) { return BuildEventId.unknownBuildEventId(opaque); } - @Test + private static class EventBusHandler { + + Set transportSet; + + @Subscribe + void transportsAnnounced(AnnounceBuildEventTransportsEvent evt) { + transportSet = Collections.synchronizedSet(new HashSet<>(evt.transports())); + } + + @Subscribe + void transportClosed(BuildEventTransportClosedEvent evt) { + transportSet.remove(evt.transport()); + } + } + + @Before + public void setup() { + MockitoAnnotations.initMocks(this); + } + + @Test(timeout = 5000) public void testSimpleStream() { // Verify that a well-formed event is passed through and that completion of the // build clears the pending progress-update event. + EventBusHandler handler = new EventBusHandler(); + eventBus.register(handler); + assertNull(handler.transportSet); + RecordingBuildEventTransport transport = new RecordingBuildEventTransport(); BuildEventStreamer streamer = - new BuildEventStreamer(ImmutableSet.of(transport)); + new BuildEventStreamer(ImmutableSet.of(transport), reporter); BuildEvent startEvent = new GenericBuildEvent( @@ -201,6 +241,7 @@ public void testSimpleStream() { List afterFirstEvent = transport.getEvents(); assertThat(afterFirstEvent).hasSize(1); assertEquals(startEvent.getEventId(), afterFirstEvent.get(0).getEventId()); + assertEquals(1, handler.transportSet.size()); streamer.buildEvent(new BuildCompleteEvent(new BuildResult(0))); @@ -208,6 +249,10 @@ public void testSimpleStream() { assertThat(finalStream).hasSize(3); assertEquals(BuildEventId.buildFinished(), finalStream.get(1).getEventId()); assertEquals(ProgressEvent.INITIAL_PROGRESS_UPDATE, finalStream.get(2).getEventId()); + + while (!handler.transportSet.isEmpty()) { + LockSupport.parkNanos(TimeUnit.MILLISECONDS.toNanos(100)); + } } @Test @@ -217,7 +262,7 @@ public void testChaining() { RecordingBuildEventTransport transport = new RecordingBuildEventTransport(); BuildEventStreamer streamer = - new BuildEventStreamer(ImmutableSet.of(transport)); + new BuildEventStreamer(ImmutableSet.of(transport), reporter); BuildEvent startEvent = new GenericBuildEvent( @@ -247,7 +292,7 @@ public void testBadInitialEvent() { RecordingBuildEventTransport transport = new RecordingBuildEventTransport(); BuildEventStreamer streamer = - new BuildEventStreamer(ImmutableSet.of(transport)); + new BuildEventStreamer(ImmutableSet.of(transport), reporter); BuildEvent unexpectedStartEvent = new GenericBuildEvent(testId("unexpected start"), ImmutableSet.of()); @@ -288,7 +333,7 @@ public void testReferPastEvent() { // late-referenced event is not expected again. RecordingBuildEventTransport transport = new RecordingBuildEventTransport(); BuildEventStreamer streamer = - new BuildEventStreamer(ImmutableSet.of(transport)); + new BuildEventStreamer(ImmutableSet.of(transport), reporter); BuildEvent startEvent = new GenericBuildEvent( @@ -322,7 +367,7 @@ public void testReodering() { RecordingBuildEventTransport transport = new RecordingBuildEventTransport(); BuildEventStreamer streamer = - new BuildEventStreamer(ImmutableSet.of(transport)); + new BuildEventStreamer(ImmutableSet.of(transport), reporter); BuildEventId expectedId = testId("the target"); BuildEvent startEvent = @@ -354,7 +399,7 @@ public void testMissingPrerequisits() { RecordingBuildEventTransport transport = new RecordingBuildEventTransport(); BuildEventStreamer streamer = - new BuildEventStreamer(ImmutableSet.of(transport)); + new BuildEventStreamer(ImmutableSet.of(transport), reporter); BuildEventId expectedId = testId("the target"); BuildEvent startEvent = @@ -385,7 +430,7 @@ public void testVeryFirstEventNeedsToWait() { // Verify that we can handle an first event waiting for another event. RecordingBuildEventTransport transport = new RecordingBuildEventTransport(); BuildEventStreamer streamer = - new BuildEventStreamer(ImmutableSet.of(transport)); + new BuildEventStreamer(ImmutableSet.of(transport), reporter); BuildEventId initialId = testId("Initial"); BuildEventId waitId = testId("Waiting for initial event"); @@ -415,7 +460,7 @@ public void testReportedArtifacts() { // Verify that reported artifacts are correctly unfolded into the stream RecordingBuildEventTransport transport = new RecordingBuildEventTransport(); BuildEventStreamer streamer = - new BuildEventStreamer(ImmutableSet.of(transport)); + new BuildEventStreamer(ImmutableSet.of(transport), reporter); BuildEvent startEvent = new GenericBuildEvent( diff --git a/src/test/java/com/google/devtools/build/lib/runtime/ExperimentalStateTrackerTest.java b/src/test/java/com/google/devtools/build/lib/runtime/ExperimentalStateTrackerTest.java index a8ecc550b45a88..54709b0eff81bf 100644 --- a/src/test/java/com/google/devtools/build/lib/runtime/ExperimentalStateTrackerTest.java +++ b/src/test/java/com/google/devtools/build/lib/runtime/ExperimentalStateTrackerTest.java @@ -13,11 +13,15 @@ // limitations under the License. package com.google.devtools.build.lib.runtime; +import static org.hamcrest.CoreMatchers.containsString; +import static org.hamcrest.CoreMatchers.not; +import static org.hamcrest.MatcherAssert.assertThat; import static org.junit.Assert.assertEquals; import static org.junit.Assert.assertFalse; import static org.junit.Assert.assertTrue; import static org.mockito.Mockito.when; +import com.google.common.base.Strings; import com.google.common.collect.ImmutableList; import com.google.common.collect.ImmutableSet; import com.google.devtools.build.lib.actions.Action; @@ -31,6 +35,11 @@ import com.google.devtools.build.lib.actions.Root; import com.google.devtools.build.lib.analysis.ConfiguredTarget; import com.google.devtools.build.lib.bazel.repository.downloader.DownloadProgressEvent; +import com.google.devtools.build.lib.buildeventstream.AnnounceBuildEventTransportsEvent; +import com.google.devtools.build.lib.buildeventstream.BuildEventTransport; +import com.google.devtools.build.lib.buildeventstream.BuildEventTransportClosedEvent; +import com.google.devtools.build.lib.buildtool.BuildResult; +import com.google.devtools.build.lib.buildtool.buildevent.BuildCompleteEvent; import com.google.devtools.build.lib.buildtool.buildevent.TestFilteringCompleteEvent; import com.google.devtools.build.lib.cmdline.Label; import com.google.devtools.build.lib.packages.AspectDescriptor; @@ -38,6 +47,7 @@ import com.google.devtools.build.lib.skyframe.PackageProgressReceiver; import com.google.devtools.build.lib.testutil.FoundationTestCase; import com.google.devtools.build.lib.testutil.ManualClock; +import com.google.devtools.build.lib.util.ExitCode; import com.google.devtools.build.lib.util.Pair; import com.google.devtools.build.lib.util.io.LoggingTerminalWriter; import com.google.devtools.build.lib.vfs.Path; @@ -668,4 +678,121 @@ public void testDownloadOutputLength() throws Exception { output.contains("example.org")); } + @Test + public void testMultipleBuildEventProtocolTransports() throws Exception { + // Verify that all announced transports are present in the progress bar + // and that as transports are closed they disappear from the progress bar. + // Verify that the wait duration is displayed. + // Verify that after all transports have been closed, the build status is displayed. + ManualClock clock = new ManualClock(); + BuildEventTransport transport1 = newBepTransport("BuildEventTransport1"); + BuildEventTransport transport2 = newBepTransport("BuildEventTransport2"); + BuildEventTransport transport3 = newBepTransport("BuildEventTransport3"); + BuildResult buildResult = new BuildResult(clock.currentTimeMillis()); + buildResult.setExitCondition(ExitCode.SUCCESS); + clock.advanceMillis(TimeUnit.SECONDS.toMillis(1)); + buildResult.setStopTime(clock.currentTimeMillis()); + + ExperimentalStateTracker stateTracker = new ExperimentalStateTracker(clock, 80); + stateTracker.buildStarted(null); + stateTracker.buildEventTransportsAnnounced( + new AnnounceBuildEventTransportsEvent( + ImmutableList.of(transport1, transport2, transport3))); + stateTracker.buildComplete(new BuildCompleteEvent(buildResult)); + + LoggingTerminalWriter terminalWriter = new LoggingTerminalWriter(true); + + clock.advanceMillis(TimeUnit.SECONDS.toMillis(1)); + stateTracker.writeProgressBar(terminalWriter); + String output = terminalWriter.getTranscript(); + assertThat(output, containsString("1s")); + assertThat(output, containsString("BuildEventTransport1")); + assertThat(output, containsString("BuildEventTransport2")); + assertThat(output, containsString("BuildEventTransport3")); + assertThat(output, containsString("success")); + assertThat(output, containsString("complete")); + + clock.advanceMillis(TimeUnit.SECONDS.toMillis(1)); + stateTracker.buildEventTransportClosed(new BuildEventTransportClosedEvent(transport1)); + terminalWriter = new LoggingTerminalWriter(true); + stateTracker.writeProgressBar(terminalWriter); + output = terminalWriter.getTranscript(); + assertThat(output, containsString("2s")); + assertThat(output, not(containsString("BuildEventTransport1"))); + assertThat(output, containsString("BuildEventTransport2")); + assertThat(output, containsString("BuildEventTransport3")); + assertThat(output, containsString("success")); + assertThat(output, containsString("complete")); + + clock.advanceMillis(TimeUnit.SECONDS.toMillis(1)); + stateTracker.buildEventTransportClosed(new BuildEventTransportClosedEvent(transport3)); + terminalWriter = new LoggingTerminalWriter(true); + stateTracker.writeProgressBar(terminalWriter); + output = terminalWriter.getTranscript(); + assertThat(output, containsString("3s")); + assertThat(output, not(containsString("BuildEventTransport1"))); + assertThat(output, containsString("BuildEventTransport2")); + assertThat(output, not(containsString("BuildEventTransport3"))); + assertThat(output, containsString("success")); + assertThat(output, containsString("complete")); + + clock.advanceMillis(TimeUnit.SECONDS.toMillis(1)); + stateTracker.buildEventTransportClosed(new BuildEventTransportClosedEvent(transport2)); + terminalWriter = new LoggingTerminalWriter(true); + stateTracker.writeProgressBar(terminalWriter); + output = terminalWriter.getTranscript(); + assertThat(output, not(containsString("3s"))); + assertThat(output, not(containsString("BuildEventTransport1"))); + assertThat(output, not(containsString("BuildEventTransport2"))); + assertThat(output, not(containsString("BuildEventTransport3"))); + assertThat(output, containsString("success")); + assertThat(output, containsString("complete")); + assertEquals(1, output.split("\\n").length); + } + + @Test + public void testBuildEventTransportsOnNarrowTerminal() throws IOException{ + // Verify that the progress bar contains useful information on a 60-character terminal. + // - Too long names should be shortened to reasonably long prefixes of the name. + ManualClock clock = new ManualClock(); + BuildEventTransport transport1 = + newBepTransport(Strings.repeat("A", 61)); + BuildEventTransport transport2 = newBepTransport("BuildEventTransport"); + BuildResult buildResult = new BuildResult(clock.currentTimeMillis()); + buildResult.setExitCondition(ExitCode.SUCCESS); + LoggingTerminalWriter terminalWriter = new LoggingTerminalWriter(true); + ExperimentalStateTracker stateTracker = new ExperimentalStateTracker(clock, 60); + stateTracker.buildStarted(null); + stateTracker.buildEventTransportsAnnounced( + new AnnounceBuildEventTransportsEvent(ImmutableList.of(transport1, transport2))); + stateTracker.buildComplete(new BuildCompleteEvent(buildResult)); + clock.advanceMillis(TimeUnit.SECONDS.toMillis(1)); + stateTracker.writeProgressBar(terminalWriter); + String output = terminalWriter.getTranscript(); + assertTrue(longestLine(output) <= 60); + assertThat(output, containsString("1s")); + assertThat(output, containsString(Strings.repeat("A", 30) + "...")); + assertThat(output, containsString("BuildEventTransport")); + assertThat(output, containsString("success")); + assertThat(output, containsString("complete")); + + clock.advanceMillis(TimeUnit.SECONDS.toMillis(1)); + stateTracker.buildEventTransportClosed(new BuildEventTransportClosedEvent(transport2)); + terminalWriter = new LoggingTerminalWriter(true); + stateTracker.writeProgressBar(terminalWriter); + output = terminalWriter.getTranscript(); + assertTrue(longestLine(output) <= 60); + assertThat(output, containsString("2s")); + assertThat(output, containsString(Strings.repeat("A", 30) + "...")); + assertThat(output, not(containsString("BuildEventTransport"))); + assertThat(output, containsString("success")); + assertThat(output, containsString("complete")); + assertEquals(2, output.split("\\n").length); + } + + private BuildEventTransport newBepTransport(String name) { + BuildEventTransport transport = Mockito.mock(BuildEventTransport.class); + when(transport.name()).thenReturn(name); + return transport; + } } diff --git a/src/test/java/com/google/devtools/build/lib/testutil/FoundationTestCase.java b/src/test/java/com/google/devtools/build/lib/testutil/FoundationTestCase.java index e333784f7987c7..fd140600b06c12 100644 --- a/src/test/java/com/google/devtools/build/lib/testutil/FoundationTestCase.java +++ b/src/test/java/com/google/devtools/build/lib/testutil/FoundationTestCase.java @@ -38,6 +38,8 @@ public abstract class FoundationTestCase { // May be overridden by subclasses: protected Reporter reporter; + // The event bus of the reporter + protected EventBus eventBus; protected EventCollector eventCollector; protected Scratch scratch; @@ -76,7 +78,8 @@ public final void initializeFileSystemAndDirectories() throws Exception { @Before public final void initializeLogging() throws Exception { eventCollector = new EventCollector(EventKind.ERRORS_AND_WARNINGS); - reporter = new Reporter(new EventBus(), eventCollector); + eventBus = new EventBus(); + reporter = new Reporter(eventBus, eventCollector); reporter.addHandler(failFastHandler); }