| // Copyright 2015 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.runtime; | |
| import com.google.common.base.Splitter; | |
| import com.google.common.collect.ImmutableSet; | |
| import com.google.common.eventbus.AllowConcurrentEvents; | |
| import com.google.common.eventbus.Subscribe; | |
| import com.google.common.primitives.Bytes; | |
| import com.google.common.util.concurrent.Uninterruptibles; | |
| import com.google.devtools.build.lib.actions.ActionCompletionEvent; | |
| import com.google.devtools.build.lib.actions.ActionStartedEvent; | |
| import com.google.devtools.build.lib.actions.AnalyzingActionEvent; | |
| import com.google.devtools.build.lib.actions.RunningActionEvent; | |
| import com.google.devtools.build.lib.actions.SchedulingActionEvent; | |
| import com.google.devtools.build.lib.analysis.AnalysisPhaseCompleteEvent; | |
| import com.google.devtools.build.lib.analysis.NoBuildEvent; | |
| import com.google.devtools.build.lib.analysis.NoBuildRequestFinishedEvent; | |
| 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.buildevent.BuildCompleteEvent; | |
| import com.google.devtools.build.lib.buildtool.buildevent.BuildStartingEvent; | |
| import com.google.devtools.build.lib.buildtool.buildevent.ExecutionProgressReceiverAvailableEvent; | |
| import com.google.devtools.build.lib.buildtool.buildevent.TestFilteringCompleteEvent; | |
| import com.google.devtools.build.lib.clock.Clock; | |
| import com.google.devtools.build.lib.events.Event; | |
| import com.google.devtools.build.lib.events.EventHandler; | |
| import com.google.devtools.build.lib.events.EventKind; | |
| import com.google.devtools.build.lib.events.ExtendedEventHandler.FetchProgress; | |
| import com.google.devtools.build.lib.events.Location; | |
| import com.google.devtools.build.lib.pkgcache.LoadingPhaseCompleteEvent; | |
| import com.google.devtools.build.lib.pkgcache.PathPackageLocator; | |
| import com.google.devtools.build.lib.skyframe.ConfigurationPhaseStartedEvent; | |
| import com.google.devtools.build.lib.skyframe.LoadingPhaseStartedEvent; | |
| import com.google.devtools.build.lib.util.io.AnsiTerminal; | |
| import com.google.devtools.build.lib.util.io.AnsiTerminal.Color; | |
| import com.google.devtools.build.lib.util.io.AnsiTerminalWriter; | |
| import com.google.devtools.build.lib.util.io.LineCountingAnsiTerminalWriter; | |
| import com.google.devtools.build.lib.util.io.LineWrappingAnsiTerminalWriter; | |
| import com.google.devtools.build.lib.util.io.LoggingTerminalWriter; | |
| import com.google.devtools.build.lib.util.io.OutErr; | |
| import com.google.devtools.build.lib.vfs.Path; | |
| import com.google.devtools.build.lib.vfs.PathFragment; | |
| import com.google.devtools.build.lib.view.test.TestStatus.BlazeTestStatus; | |
| import java.io.ByteArrayOutputStream; | |
| import java.io.IOException; | |
| import java.io.OutputStream; | |
| import java.nio.charset.StandardCharsets; | |
| import java.time.Instant; | |
| import java.time.ZoneId; | |
| import java.time.format.DateTimeFormatter; | |
| import java.util.Arrays; | |
| import java.util.HashSet; | |
| import java.util.Set; | |
| import java.util.concurrent.atomic.AtomicLong; | |
| import java.util.concurrent.atomic.AtomicReference; | |
| import java.util.logging.Logger; | |
| import javax.annotation.Nullable; | |
| /** An experimental new output stream. */ | |
| public class ExperimentalEventHandler implements EventHandler { | |
| private static final Logger logger = Logger.getLogger(ExperimentalEventHandler.class.getName()); | |
| /** Latest refresh of the progress bar, if contents other than time changed */ | |
| static final long MAXIMAL_UPDATE_DELAY_MILLIS = 200L; | |
| /** Minimal rate limiting (in ms), if the progress bar cannot be updated in place */ | |
| static final long NO_CURSES_MINIMAL_PROGRESS_RATE_LIMIT = 1000L; | |
| /** | |
| * Minimal rate limiting, as fraction of the request time so far, if the progress bar cannot be | |
| * updated in place | |
| */ | |
| static final double NO_CURSES_MINIMAL_RELATIVE_PROGRESS_RATE_LMIT = 0.15; | |
| /** Periodic update interval of a time-dependent progress bar if it can be updated in place */ | |
| static final long SHORT_REFRESH_MILLIS = 1000L; | |
| /** Periodic update interval of a time-dependent progress bar if it cannot be updated in place */ | |
| static final long LONG_REFRESH_MILLIS = 20000L; | |
| private static final DateTimeFormatter TIMESTAMP_FORMAT = | |
| DateTimeFormatter.ofPattern("(HH:mm:ss) "); | |
| private static final DateTimeFormatter DATE_FORMAT = DateTimeFormatter.ofPattern("yyyy-MM-dd"); | |
| private final boolean cursorControl; | |
| private final Clock clock; | |
| private final long uiStartTimeMillis; | |
| private final AnsiTerminal terminal; | |
| private final boolean debugAllEvents; | |
| private final ExperimentalStateTracker stateTracker; | |
| private final LocationPrinter locationPrinter; | |
| private final boolean showProgress; | |
| private final boolean progressInTermTitle; | |
| private final boolean showTimestamp; | |
| private final boolean deduplicate; | |
| private final OutErr outErr; | |
| private long minimalDelayMillis; | |
| private long minimalUpdateInterval; | |
| private long lastRefreshMillis; | |
| private long mustRefreshAfterMillis; | |
| private boolean dateShown; | |
| private int numLinesProgressBar; | |
| private boolean buildRunning; | |
| // Number of open build even protocol transports. | |
| private boolean progressBarNeedsRefresh; | |
| private final AtomicReference<Thread> updateThread; | |
| private byte[] stdoutBuffer; | |
| private byte[] stderrBuffer; | |
| private final Set<String> messagesSeen; | |
| private long deduplicateCount; | |
| private final long outputLimit; | |
| private long reservedOutputCapacity; | |
| private final AtomicLong counter; | |
| private long droppedEvents; | |
| /** | |
| * The following constants determine how the output limiting is done gracefully. They are all | |
| * values for the remaining relative capacity left at which we start taking given measure. | |
| * | |
| * <p>The degrading of progress updates to stay within output limit is done in the following | |
| * steps. | |
| * | |
| * <ul> | |
| * <li>We limit progress updates to at most one per second; this is the granularity at which | |
| * times in the progress bar are shown. So the appearance won't look too bad. Hence we start | |
| * that measure relatively early. | |
| * <li>We only show the short version of the progress bar, even if curses are enabled. | |
| * <li>We reduce the update frequency of the progress bar to at most one update per 5s. This | |
| * still looks moving and is in line with the escalation strategy that so far: every step | |
| * reduces output by about a factor of 5. | |
| * <li>We start decreasing the update frequency to what we would do, if curses were not allowed. | |
| * Note that now the time between updates is at least a fixed fraction of the time that | |
| * passed so far; so the time between progress updates will continue to increase. | |
| * <li>We do not show any event, except for errors. | |
| * <li>The last small fraction of the output, we reserve for a post-build status messages (in | |
| * particular test summaries). | |
| * </ul> | |
| */ | |
| private static final double CAPACITY_INCREASE_UPDATE_DELAY = 0.9; | |
| private static final double CAPACITY_SHORT_PROGRESS_BAR = 0.6; | |
| private static final double CAPACITY_UPDATE_DELAY_5_SECONDS = 0.4; | |
| private static final double CAPACITY_UPDATE_DELAY_AS_NO_CURSES = 0.3; | |
| private static final double CAPACITY_ERRORS_ONLY = 0.2; | |
| /** | |
| * The degrading of printing stdout/stderr is achieved by limiting the output for an individual | |
| * event if printing it fully would get us above the threshold. If limited, at most a given | |
| * fraction of the remaining capacity my be used by any such event; larger events are truncated to | |
| * their end (this is what the user would anyway only see on the terminal if the output is very | |
| * large). In any case, we always allow at least twice the terminal width, to make the output at | |
| * least somewhat useful. From a given threshold onwards, we always restrict to at most twice the | |
| * terminal width. | |
| */ | |
| private static final double CAPACITY_LIMIT_OUT_ERR_EVENTS = 0.8; | |
| private static final double CAPACITY_STRONG_LIMIT_OUT_ERR_EVENTS = 0.5; | |
| private static final double RELATIVE_OUT_ERR_LIMIT = 0.1; | |
| /** | |
| * The reservation of output capacity for the final status is computed as follows: we always | |
| * reserve at least a certain numer of lines, and at least a certain fraction of the overall | |
| * capacity, to show more status in scenarios where we have a bigger limit. | |
| */ | |
| private static final long MINIMAL_POST_BUILD_OUTPUT_LINES = 14; | |
| private static final double MINIMAL_POST_BUILD_OUTPUT_CAPACITY = 0.05; | |
| public final int terminalWidth; | |
| /** | |
| * An output stream that wraps another output stream and that fully buffers writes until flushed. | |
| * Additionally, it optionally takes into account a budget for the number of bytes it may still | |
| * write to the wrapped stream. | |
| */ | |
| private static class FullyBufferedOutputStreamMaybeWithCounting extends ByteArrayOutputStream { | |
| /** The (possibly unbuffered) stream wrapped by this one. */ | |
| private final OutputStream wrapped; | |
| /** The counter for the amount of bytes we're still allowed to write */ | |
| @Nullable private final AtomicLong counter; | |
| /** | |
| * Constructs a new fully-buffered output stream that wraps an unbuffered one. | |
| * | |
| * @param wrapped the (possibly unbuffered) stream wrapped by this one | |
| * @param counter a counter specifying the number of bytes the stream may still write | |
| */ | |
| FullyBufferedOutputStreamMaybeWithCounting(OutputStream wrapped, @Nullable AtomicLong counter) { | |
| this.wrapped = wrapped; | |
| this.counter = counter; | |
| } | |
| @Override | |
| public void flush() throws IOException { | |
| super.flush(); | |
| try { | |
| if (counter == null || counter.addAndGet(-count) >= 0) { | |
| writeTo(wrapped); | |
| wrapped.flush(); | |
| } | |
| } finally { | |
| // If we failed to write our current buffered contents to the output, there is not much | |
| // we can do because reporting an error would require another write, and that write would | |
| // probably fail. So, instead, we silently discard whatever was previously buffered in the | |
| // hopes that the data itself was what caused the problem. | |
| reset(); | |
| } | |
| } | |
| } | |
| public ExperimentalEventHandler( | |
| OutErr outErr, | |
| BlazeCommandEventHandler.Options options, | |
| Clock clock, | |
| @Nullable PathFragment workspacePathFragment) { | |
| this.terminalWidth = (options.terminalColumns > 0 ? options.terminalColumns : 80); | |
| this.outputLimit = options.experimentalUiLimitConsoleOutput; | |
| this.counter = new AtomicLong(outputLimit); | |
| this.droppedEvents = 0; | |
| if (outputLimit > 0) { | |
| this.outErr = | |
| OutErr.create( | |
| new FullyBufferedOutputStreamMaybeWithCounting( | |
| outErr.getOutputStream(), this.counter), | |
| new FullyBufferedOutputStreamMaybeWithCounting( | |
| outErr.getErrorStream(), this.counter)); | |
| reservedOutputCapacity = | |
| Math.max( | |
| MINIMAL_POST_BUILD_OUTPUT_LINES * this.terminalWidth, | |
| Math.round(MINIMAL_POST_BUILD_OUTPUT_CAPACITY * outputLimit)); | |
| } else { | |
| // unlimited output; no need to count, but still fully buffer | |
| this.outErr = | |
| OutErr.create( | |
| new FullyBufferedOutputStreamMaybeWithCounting(outErr.getOutputStream(), null), | |
| new FullyBufferedOutputStreamMaybeWithCounting(outErr.getErrorStream(), null)); | |
| } | |
| this.cursorControl = options.useCursorControl(); | |
| this.terminal = new AnsiTerminal(this.outErr.getErrorStream()); | |
| this.showProgress = options.showProgress; | |
| this.progressInTermTitle = options.progressInTermTitle && options.useCursorControl(); | |
| this.showTimestamp = options.showTimestamp; | |
| this.clock = clock; | |
| this.uiStartTimeMillis = clock.currentTimeMillis(); | |
| this.debugAllEvents = options.experimentalUiDebugAllEvents; | |
| this.deduplicate = options.experimentalUiDeduplicate; | |
| this.messagesSeen = new HashSet<>(); | |
| this.locationPrinter = | |
| new LocationPrinter(options.attemptToPrintRelativePaths, workspacePathFragment); | |
| // If we have cursor control, we try to fit in the terminal width to avoid having | |
| // to wrap the progress bar. We will wrap the progress bar to terminalWidth - 1 | |
| // characters to avoid depending on knowing whether the underlying terminal does the | |
| // line feed already when reaching the last character of the line, or only once an | |
| // additional character is written. Another column is lost for the continuation character | |
| // in the wrapping process. | |
| this.stateTracker = | |
| this.cursorControl | |
| ? new ExperimentalStateTracker(clock, this.terminalWidth - 2) | |
| : new ExperimentalStateTracker(clock); | |
| this.stateTracker.setSampleSize(options.experimentalUiActionsShown); | |
| this.numLinesProgressBar = 0; | |
| if (this.cursorControl) { | |
| this.minimalDelayMillis = Math.round(options.showProgressRateLimit * 1000); | |
| } else { | |
| this.minimalDelayMillis = | |
| Math.max( | |
| Math.round(options.showProgressRateLimit * 1000), | |
| NO_CURSES_MINIMAL_PROGRESS_RATE_LIMIT); | |
| } | |
| this.minimalUpdateInterval = Math.max(this.minimalDelayMillis, MAXIMAL_UPDATE_DELAY_MILLIS); | |
| this.stdoutBuffer = new byte[] {}; | |
| this.stderrBuffer = new byte[] {}; | |
| this.dateShown = false; | |
| this.updateThread = new AtomicReference<>(); | |
| // The progress bar has not been updated yet. | |
| ignoreRefreshLimitOnce(); | |
| } | |
| /** | |
| * Return the remaining output capacity, relative to the total capacity, afer a write of the given | |
| * number of bytes. | |
| */ | |
| private double remainingCapacity(long wantWrite) { | |
| if (outputLimit <= 0) { | |
| // we have unlimited capacity, so we're still at full capacity, regardless of | |
| // how much we write. | |
| return 1.0; | |
| } | |
| return (counter.get() - wantWrite - reservedOutputCapacity) / (double) outputLimit; | |
| } | |
| private double remainingCapacity() { | |
| return remainingCapacity(0); | |
| } | |
| /** | |
| * Flush buffers for stdout and stderr. Return if either of them flushed a non-zero number of | |
| * symbols. | |
| */ | |
| private synchronized boolean flushStdOutStdErrBuffers() { | |
| boolean didFlush = false; | |
| try { | |
| if (stdoutBuffer.length > 0) { | |
| outErr.getOutputStream().write(stdoutBuffer); | |
| outErr.getOutputStream().flush(); | |
| stdoutBuffer = new byte[] {}; | |
| didFlush = true; | |
| } | |
| if (stderrBuffer.length > 0) { | |
| outErr.getErrorStream().write(stderrBuffer); | |
| outErr.getErrorStream().flush(); | |
| stderrBuffer = new byte[] {}; | |
| didFlush = true; | |
| } | |
| } catch (IOException e) { | |
| logger.warning("IO Error writing to output stream: " + e); | |
| } | |
| return didFlush; | |
| } | |
| private synchronized void maybeAddDate() { | |
| if (!showTimestamp || dateShown || !buildRunning) { | |
| return; | |
| } | |
| dateShown = true; | |
| handle( | |
| Event.info( | |
| null, | |
| "Current date is " | |
| + DATE_FORMAT.format( | |
| Instant.ofEpochMilli(clock.currentTimeMillis()) | |
| .atZone(ZoneId.systemDefault())))); | |
| } | |
| @Override | |
| public void handle(Event event) { | |
| if (!debugAllEvents | |
| && !showTimestamp | |
| && (event.getKind() == EventKind.START || event.getKind() == EventKind.FINISH)) { | |
| return; | |
| } | |
| handleLocked(event, /* isFollowUp= */ false); | |
| } | |
| private synchronized void handleLocked(Event event, boolean isFollowUp) { | |
| try { | |
| if (debugAllEvents) { | |
| // Debugging only: show all events visible to the new UI. | |
| 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(); | |
| } else { | |
| if (!isFollowUp | |
| && (remainingCapacity() < CAPACITY_ERRORS_ONLY) | |
| && (event.getKind() != EventKind.ERROR)) { | |
| droppedEvents++; | |
| return; | |
| } | |
| if (shouldDeduplicate(event)) { | |
| return; | |
| } | |
| maybeAddDate(); | |
| switch (event.getKind()) { | |
| case STDOUT: | |
| case STDERR: | |
| OutputStream stream = | |
| event.getKind() == EventKind.STDOUT | |
| ? outErr.getOutputStream() | |
| : outErr.getErrorStream(); | |
| if (!buildRunning) { | |
| stream.write(event.getMessageBytes()); | |
| stream.flush(); | |
| } else { | |
| byte[] message = event.getMessageBytes(); | |
| 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 = | |
| Math.max(2 * terminalWidth, Math.round(RELATIVE_OUT_ERR_LIMIT * counter.get())); | |
| if (cap < CAPACITY_STRONG_LIMIT_OUT_ERR_EVENTS) { | |
| allowedLength = Math.min(allowedLength, 2 * terminalWidth); | |
| } | |
| if (message.length > allowedLength) { | |
| // Have to truncate the message | |
| message = | |
| Arrays.copyOfRange( | |
| message, message.length - (int) allowedLength, message.length); | |
| // Mark message as truncated | |
| message[0] = '.'; | |
| message[1] = '.'; | |
| message[2] = '.'; | |
| } | |
| } | |
| int eolIndex = Bytes.lastIndexOf(message, (byte) '\n'); | |
| if (eolIndex >= 0) { | |
| clearProgressBar(); | |
| terminal.flush(); | |
| stream.write(event.getKind() == EventKind.STDOUT ? stdoutBuffer : stderrBuffer); | |
| stream.write(Arrays.copyOf(message, eolIndex + 1)); | |
| byte[] restMessage = Arrays.copyOfRange(message, eolIndex + 1, message.length); | |
| if (event.getKind() == EventKind.STDOUT) { | |
| stdoutBuffer = restMessage; | |
| } else { | |
| stderrBuffer = restMessage; | |
| } | |
| stream.flush(); | |
| if (showProgress && cursorControl) { | |
| addProgressBar(); | |
| } | |
| terminal.flush(); | |
| } else { | |
| if (event.getKind() == EventKind.STDOUT) { | |
| stdoutBuffer = Bytes.concat(stdoutBuffer, message); | |
| } else { | |
| stderrBuffer = Bytes.concat(stderrBuffer, message); | |
| } | |
| } | |
| } | |
| break; | |
| case ERROR: | |
| case FAIL: | |
| case WARNING: | |
| case INFO: | |
| case DEBUG: | |
| case SUBCOMMAND: | |
| boolean incompleteLine; | |
| if (showProgress && buildRunning) { | |
| clearProgressBar(); | |
| } | |
| incompleteLine = flushStdOutStdErrBuffers(); | |
| if (incompleteLine) { | |
| crlf(); | |
| } | |
| if (remainingCapacity() < 0) { | |
| terminal.flush(); | |
| return; | |
| } | |
| if (showTimestamp) { | |
| terminal.writeString( | |
| TIMESTAMP_FORMAT.format( | |
| Instant.ofEpochMilli(clock.currentTimeMillis()) | |
| .atZone(ZoneId.systemDefault()))); | |
| } | |
| setEventKindColor(event.getKind()); | |
| terminal.writeString(event.getKind() + ": "); | |
| terminal.resetTerminal(); | |
| incompleteLine = true; | |
| Location location = event.getLocation(); | |
| if (location != null) { | |
| terminal.writeString(locationPrinter.getLocationString(location) + ": "); | |
| } | |
| if (event.getMessage() != null) { | |
| terminal.writeString(event.getMessage()); | |
| incompleteLine = !event.getMessage().endsWith("\n"); | |
| } | |
| if (incompleteLine) { | |
| crlf(); | |
| } | |
| if (showProgress && buildRunning && cursorControl) { | |
| addProgressBar(); | |
| } | |
| terminal.flush(); | |
| break; | |
| case PROGRESS: | |
| if (stateTracker.progressBarTimeDependent()) { | |
| refresh(); | |
| } | |
| break; | |
| case START: | |
| case FINISH: | |
| case PASS: | |
| case TIMEOUT: | |
| case DEPCHECKER: | |
| break; | |
| } | |
| if (event.getStdErr() != null) { | |
| handleLocked( | |
| Event.of( | |
| EventKind.STDERR, null, event.getStdErr().getBytes(StandardCharsets.ISO_8859_1)), | |
| /* isFollowUp= */ true); | |
| } | |
| if (event.getStdOut() != null) { | |
| handleLocked( | |
| Event.of( | |
| EventKind.STDOUT, null, event.getStdOut().getBytes(StandardCharsets.ISO_8859_1)), | |
| /* isFollowUp= */ true); | |
| } | |
| } | |
| } catch (IOException e) { | |
| logger.warning("IO Error writing to output stream: " + e); | |
| } | |
| } | |
| private void setEventKindColor(EventKind kind) throws IOException { | |
| switch (kind) { | |
| case ERROR: | |
| case FAIL: | |
| terminal.setTextColor(Color.RED); | |
| terminal.textBold(); | |
| break; | |
| case WARNING: | |
| terminal.setTextColor(Color.MAGENTA); | |
| break; | |
| case INFO: | |
| terminal.setTextColor(Color.GREEN); | |
| break; | |
| case DEBUG: | |
| terminal.setTextColor(Color.YELLOW); | |
| break; | |
| case SUBCOMMAND: | |
| terminal.setTextColor(Color.BLUE); | |
| break; | |
| default: | |
| terminal.resetTerminal(); | |
| } | |
| } | |
| private boolean shouldDeduplicate(Event event) { | |
| if (!deduplicate) { | |
| // deduplication disabled | |
| return false; | |
| } | |
| if (event.getKind() == EventKind.DEBUG) { | |
| String message = event.getMessage(); | |
| synchronized (this) { | |
| if (messagesSeen.contains(message)) { | |
| deduplicateCount++; | |
| return true; | |
| } else { | |
| messagesSeen.add(message); | |
| } | |
| } | |
| } | |
| if (event.getKind() != EventKind.INFO) { | |
| // only deduplicate INFO messages | |
| return false; | |
| } | |
| if (event.getStdOut() == null && event.getStdErr() == null) { | |
| // We deduplicate on the attached output (assuming the event itself only describes | |
| // the source of the output). If no output is attached it is a different kind of event | |
| // and should not be deduplicated. | |
| return false; | |
| } | |
| boolean allMessagesSeen = true; | |
| if (event.getStdOut() != null) { | |
| for (String line : Splitter.on("\n").split(event.getStdOut())) { | |
| if (!messagesSeen.contains(line)) { | |
| allMessagesSeen = false; | |
| messagesSeen.add(line); | |
| } | |
| } | |
| } | |
| if (event.getStdErr() != null) { | |
| for (String line : Splitter.on("\n").split(event.getStdErr())) { | |
| if (!messagesSeen.contains(line)) { | |
| allMessagesSeen = false; | |
| messagesSeen.add(line); | |
| } | |
| } | |
| } | |
| if (allMessagesSeen) { | |
| synchronized (this) { | |
| deduplicateCount++; | |
| } | |
| } | |
| return allMessagesSeen; | |
| } | |
| @Subscribe | |
| public void buildStarted(BuildStartingEvent event) { | |
| synchronized (this) { | |
| buildRunning = true; | |
| } | |
| maybeAddDate(); | |
| stateTracker.buildStarted(event); | |
| // As a new phase started, inform immediately. | |
| ignoreRefreshLimitOnce(); | |
| refresh(); | |
| } | |
| @Subscribe | |
| public void loadingStarted(LoadingPhaseStartedEvent event) { | |
| maybeAddDate(); | |
| stateTracker.loadingStarted(event); | |
| // As a new phase started, inform immediately. | |
| ignoreRefreshLimitOnce(); | |
| refresh(); | |
| startUpdateThread(); | |
| } | |
| @Subscribe | |
| public void configurationStarted(ConfigurationPhaseStartedEvent event) { | |
| maybeAddDate(); | |
| stateTracker.configurationStarted(event); | |
| // As a new phase started, inform immediately. | |
| ignoreRefreshLimitOnce(); | |
| refresh(); | |
| startUpdateThread(); | |
| } | |
| @Subscribe | |
| public void loadingComplete(LoadingPhaseCompleteEvent event) { | |
| stateTracker.loadingComplete(event); | |
| refresh(); | |
| } | |
| @Subscribe | |
| public synchronized void analysisComplete(AnalysisPhaseCompleteEvent event) { | |
| String analysisSummary = stateTracker.analysisComplete(event); | |
| handle(Event.info(null, analysisSummary)); | |
| } | |
| @Subscribe | |
| public void progressReceiverAvailable(ExecutionProgressReceiverAvailableEvent event) { | |
| stateTracker.progressReceiverAvailable(event); | |
| // As this is the first time we have a progress message, update immediately. | |
| ignoreRefreshLimitOnce(); | |
| startUpdateThread(); | |
| } | |
| @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 timestamp, if events are supposed to have a timestamp. | |
| boolean done = false; | |
| synchronized (this) { | |
| stateTracker.buildComplete(event); | |
| reservedOutputCapacity = 0; | |
| ignoreRefreshLimitOnce(); | |
| refresh(); | |
| // After a build has completed, only stop updating the UI if there is no more BEP | |
| // upload happening. | |
| if (stateTracker.pendingTransports() == 0) { | |
| buildRunning = false; | |
| done = true; | |
| } | |
| } | |
| if (done) { | |
| stopUpdateThread(); | |
| flushStdOutStdErrBuffers(); | |
| } | |
| } | |
| private void completeBuild() { | |
| synchronized (this) { | |
| if (!buildRunning) { | |
| return; | |
| } | |
| buildRunning = false; | |
| } | |
| stopUpdateThread(); | |
| synchronized (this) { | |
| try { | |
| // If a progress bar is currently present, clean it and redraw it. | |
| boolean progressBarPresent = numLinesProgressBar > 0; | |
| if (progressBarPresent) { | |
| clearProgressBar(); | |
| } | |
| terminal.flush(); | |
| boolean incompleteLine = flushStdOutStdErrBuffers(); | |
| if (incompleteLine) { | |
| crlf(); | |
| } | |
| if (deduplicateCount > 0) { | |
| handle(Event.info(null, "deduplicated " + deduplicateCount + " events")); | |
| } | |
| if (droppedEvents > 0) { | |
| handleLocked( | |
| Event.info( | |
| null, | |
| "dropped " | |
| + droppedEvents | |
| + " events on the console," | |
| + " to stay within output limit."), | |
| /* isFollowUp= */ true); | |
| } | |
| if (progressBarPresent) { | |
| addProgressBar(); | |
| } | |
| terminal.flush(); | |
| } catch (IOException e) { | |
| logger.warning("IO Error writing to output stream: " + e); | |
| } | |
| } | |
| } | |
| @Subscribe | |
| public void packageLocatorCreated(PathPackageLocator packageLocator) { | |
| locationPrinter.packageLocatorCreated(packageLocator); | |
| } | |
| @Subscribe | |
| public void noBuild(NoBuildEvent event) { | |
| if (event.showProgress()) { | |
| synchronized (this) { | |
| buildRunning = true; | |
| } | |
| return; | |
| } | |
| completeBuild(); | |
| } | |
| @Subscribe | |
| public void noBuildFinished(NoBuildRequestFinishedEvent event) { | |
| completeBuild(); | |
| } | |
| @Subscribe | |
| public void afterCommand(AfterCommandEvent event) { | |
| synchronized (this) { | |
| buildRunning = true; | |
| } | |
| completeBuild(); | |
| try { | |
| terminal.resetTerminal(); | |
| terminal.flush(); | |
| } catch (IOException e) { | |
| logger.warning("IO Error writing to user terminal: " + e); | |
| } | |
| } | |
| @Subscribe | |
| public void downloadProgress(FetchProgress event) { | |
| maybeAddDate(); | |
| stateTracker.downloadProgress(event); | |
| refresh(); | |
| } | |
| @Subscribe | |
| @AllowConcurrentEvents | |
| public void actionStarted(ActionStartedEvent event) { | |
| stateTracker.actionStarted(event); | |
| refresh(); | |
| } | |
| @Subscribe | |
| @AllowConcurrentEvents | |
| public void analyzingAction(AnalyzingActionEvent event) { | |
| stateTracker.analyzingAction(event); | |
| refresh(); | |
| } | |
| @Subscribe | |
| @AllowConcurrentEvents | |
| public void schedulingAction(SchedulingActionEvent event) { | |
| stateTracker.schedulingAction(event); | |
| refresh(); | |
| } | |
| @Subscribe | |
| @AllowConcurrentEvents | |
| public void runningAction(RunningActionEvent event) { | |
| stateTracker.runningAction(event); | |
| refresh(); | |
| } | |
| @Subscribe | |
| @AllowConcurrentEvents | |
| public void actionCompletion(ActionCompletionEvent event) { | |
| stateTracker.actionCompletion(event); | |
| refreshSoon(); | |
| } | |
| @Subscribe | |
| public void testFilteringComplete(TestFilteringCompleteEvent event) { | |
| stateTracker.testFilteringComplete(event); | |
| refresh(); | |
| } | |
| /** | |
| * Return true, if the test summary provides information that is both | |
| * worth being shown in the scroll-back buffer and new with respect to | |
| * the alreay shown failure messages. | |
| */ | |
| private boolean testSummaryProvidesNewInformation(TestSummary summary) { | |
| ImmutableSet<BlazeTestStatus> statusToIgnore = | |
| ImmutableSet.of( | |
| BlazeTestStatus.PASSED, | |
| BlazeTestStatus.FAILED_TO_BUILD, | |
| BlazeTestStatus.BLAZE_HALTED_BEFORE_TESTING, | |
| BlazeTestStatus.NO_STATUS); | |
| if (statusToIgnore.contains(summary.getStatus())) { | |
| return false; | |
| } | |
| if (summary.getStatus() == BlazeTestStatus.FAILED && summary.getFailedLogs().size() == 1) { | |
| return false; | |
| } | |
| return true; | |
| } | |
| @Subscribe | |
| public synchronized void testSummary(TestSummary summary) { | |
| stateTracker.testSummary(summary); | |
| if (testSummaryProvidesNewInformation(summary)) { | |
| // For failed test, write the failure to the scroll-back buffer immediately | |
| try { | |
| clearProgressBar(); | |
| crlf(); | |
| setEventKindColor(EventKind.ERROR); | |
| terminal.writeString("" + summary.getStatus() + ": "); | |
| terminal.resetTerminal(); | |
| terminal.writeString(summary.getLabel().toString()); | |
| terminal.writeString(" (Summary)"); | |
| crlf(); | |
| for (Path logPath : summary.getFailedLogs()) { | |
| terminal.writeString(" " + logPath.getPathString()); | |
| crlf(); | |
| } | |
| if (showProgress && cursorControl) { | |
| addProgressBar(); | |
| } | |
| terminal.flush(); | |
| } catch (IOException e) { | |
| logger.warning("IO Error writing to output stream: " + e); | |
| } | |
| } else { | |
| refresh(); | |
| } | |
| } | |
| @Subscribe | |
| public synchronized void buildEventTransportsAnnounced(AnnounceBuildEventTransportsEvent event) { | |
| stateTracker.buildEventTransportsAnnounced(event); | |
| if (debugAllEvents) { | |
| String message = "Transports announced:"; | |
| for (BuildEventTransport transport : event.transports()) { | |
| message += " " + transport.name(); | |
| } | |
| this.handle(Event.info(null, message)); | |
| } | |
| } | |
| @Subscribe | |
| public void buildEventTransportClosed(BuildEventTransportClosedEvent event) { | |
| stateTracker.buildEventTransportClosed(event); | |
| if (debugAllEvents) { | |
| this.handle(Event.info(null, "Transport " + event.transport().name() + " closed")); | |
| } | |
| if (stateTracker.pendingTransports() == 0) { | |
| stopUpdateThread(); | |
| flushStdOutStdErrBuffers(); | |
| ignoreRefreshLimitOnce(); | |
| refresh(); | |
| } else { | |
| refresh(); | |
| } | |
| } | |
| private void refresh() { | |
| if (showProgress) { | |
| progressBarNeedsRefresh = true; | |
| doRefresh(); | |
| } | |
| } | |
| private void doRefresh(boolean fromUpdateThread) { | |
| if (!buildRunning) { | |
| return; | |
| } | |
| long nowMillis = clock.currentTimeMillis(); | |
| if (lastRefreshMillis + minimalDelayMillis < nowMillis) { | |
| synchronized (this) { | |
| try { | |
| if (showProgress && (progressBarNeedsRefresh || timeBasedRefresh())) { | |
| progressBarNeedsRefresh = false; | |
| clearProgressBar(); | |
| addProgressBar(); | |
| terminal.flush(); | |
| double remaining = remainingCapacity(); | |
| if (remaining < CAPACITY_INCREASE_UPDATE_DELAY) { | |
| // Increase the update interval if the start producing too much output | |
| minimalDelayMillis = Math.max(minimalDelayMillis, 1000); | |
| if (remaining < CAPACITY_UPDATE_DELAY_5_SECONDS) { | |
| minimalDelayMillis = Math.max(minimalDelayMillis, 5000); | |
| } | |
| } | |
| if (!cursorControl || remaining < CAPACITY_UPDATE_DELAY_AS_NO_CURSES) { | |
| // If we can't update the progress bar in place, make sure we increase the update | |
| // interval as time progresses, to avoid too many progress messages in place. | |
| minimalDelayMillis = | |
| Math.max( | |
| minimalDelayMillis, | |
| Math.round( | |
| NO_CURSES_MINIMAL_RELATIVE_PROGRESS_RATE_LMIT | |
| * (clock.currentTimeMillis() - uiStartTimeMillis))); | |
| minimalUpdateInterval = Math.max(minimalDelayMillis, MAXIMAL_UPDATE_DELAY_MILLIS); | |
| } | |
| } | |
| } catch (IOException e) { | |
| logger.warning("IO Error writing to output stream: " + e); | |
| } | |
| } | |
| } else { | |
| // We skipped an update due to rate limiting. If this however, turned | |
| // out to be the last update for a long while, we need to show it in a | |
| // timely manner, as it best describes the current state. | |
| if (!fromUpdateThread) { | |
| startUpdateThread(); | |
| } | |
| } | |
| } | |
| private void doRefresh() { | |
| doRefresh(false); | |
| } | |
| private void refreshSoon() { | |
| // Schedule an update of the progress bar in the near future, unless there is already | |
| // a future update scheduled. | |
| long nowMillis = clock.currentTimeMillis(); | |
| if (mustRefreshAfterMillis <= lastRefreshMillis) { | |
| mustRefreshAfterMillis = Math.max(nowMillis + minimalUpdateInterval, lastRefreshMillis + 1); | |
| } | |
| startUpdateThread(); | |
| } | |
| /** Decide whether the progress bar should be redrawn only for the reason that time has passed. */ | |
| private synchronized boolean timeBasedRefresh() { | |
| if (!stateTracker.progressBarTimeDependent()) { | |
| return false; | |
| } | |
| long nowMillis = clock.currentTimeMillis(); | |
| long intervalMillis = cursorControl ? SHORT_REFRESH_MILLIS : LONG_REFRESH_MILLIS; | |
| if (lastRefreshMillis < mustRefreshAfterMillis | |
| && mustRefreshAfterMillis < nowMillis + minimalDelayMillis) { | |
| // Within the a smal interval from now, an update is scheduled anyway, | |
| // so don't do a time-based update of the progress bar now, to avoid | |
| // updates too close to each other. | |
| return false; | |
| } | |
| return lastRefreshMillis + intervalMillis < nowMillis; | |
| } | |
| private void ignoreRefreshLimitOnce() { | |
| // Set refresh time variables in a state such that the next progress bar | |
| // update will definitely be written out. | |
| lastRefreshMillis = clock.currentTimeMillis() - minimalDelayMillis - 1; | |
| } | |
| private void startUpdateThread() { | |
| // Refuse to start an update thread once the build is complete; such a situation might | |
| // arise if the completion of the build is reported (shortly) before the completion of | |
| // the last action is reported. | |
| if (buildRunning && updateThread.get() == null) { | |
| final ExperimentalEventHandler eventHandler = this; | |
| Thread threadToStart = | |
| new Thread( | |
| () -> { | |
| try { | |
| while (true) { | |
| Thread.sleep(minimalUpdateInterval); | |
| if (lastRefreshMillis < mustRefreshAfterMillis | |
| && mustRefreshAfterMillis < clock.currentTimeMillis()) { | |
| progressBarNeedsRefresh = true; | |
| } | |
| eventHandler.doRefresh(/* fromUpdateThread= */ true); | |
| } | |
| } catch (InterruptedException e) { | |
| // Ignore | |
| } | |
| }, | |
| "cli-update-thread"); | |
| if (updateThread.compareAndSet(null, threadToStart)) { | |
| threadToStart.start(); | |
| } | |
| } | |
| } | |
| /** | |
| * Stop the update thread and wait for it to terminate. As the update thread, which is a separate | |
| * thread, might have to call a synchronized method between being interrupted and terminating, DO | |
| * NOT CALL from a SYNCHRONIZED block, as this will give the opportunity for dead locks. | |
| */ | |
| private void stopUpdateThread() { | |
| Thread threadToWaitFor = updateThread.getAndSet(null); | |
| if (threadToWaitFor != null) { | |
| threadToWaitFor.interrupt(); | |
| Uninterruptibles.joinUninterruptibly(threadToWaitFor); | |
| } | |
| } | |
| private void clearProgressBar() throws IOException { | |
| if (!cursorControl) { | |
| return; | |
| } | |
| for (int i = 0; i < numLinesProgressBar; i++) { | |
| terminal.cr(); | |
| terminal.cursorUp(1); | |
| terminal.clearLine(); | |
| } | |
| numLinesProgressBar = 0; | |
| } | |
| /** Terminate the line in the way appropriate for the operating system. */ | |
| private void crlf() throws IOException { | |
| terminal.writeString(System.lineSeparator()); | |
| } | |
| private synchronized void addProgressBar() throws IOException { | |
| if (remainingCapacity() < 0) { | |
| return; | |
| } | |
| LineCountingAnsiTerminalWriter countingTerminalWriter = | |
| new LineCountingAnsiTerminalWriter(terminal); | |
| AnsiTerminalWriter terminalWriter = countingTerminalWriter; | |
| lastRefreshMillis = clock.currentTimeMillis(); | |
| if (cursorControl) { | |
| terminalWriter = new LineWrappingAnsiTerminalWriter(terminalWriter, terminalWidth - 1); | |
| } | |
| String timestamp = null; | |
| if (showTimestamp) { | |
| timestamp = | |
| TIMESTAMP_FORMAT.format( | |
| Instant.ofEpochMilli(clock.currentTimeMillis()).atZone(ZoneId.systemDefault())); | |
| } | |
| stateTracker.writeProgressBar( | |
| terminalWriter, | |
| /* shortVersion=*/ !cursorControl || remainingCapacity() < CAPACITY_SHORT_PROGRESS_BAR, | |
| timestamp); | |
| terminalWriter.newline(); | |
| numLinesProgressBar = countingTerminalWriter.getWrittenLines(); | |
| if (progressInTermTitle) { | |
| LoggingTerminalWriter stringWriter = new LoggingTerminalWriter(true); | |
| stateTracker.writeProgressBar(stringWriter, true); | |
| terminal.setTitle(stringWriter.getTranscript()); | |
| } | |
| } | |
| } |