Java tutorial
// 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.collect.ImmutableSet; 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.ActionStatusMessage; import com.google.devtools.build.lib.analysis.AnalysisPhaseCompleteEvent; import com.google.devtools.build.lib.analysis.NoBuildEvent; 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.events.Event; import com.google.devtools.build.lib.events.EventHandler; import com.google.devtools.build.lib.events.EventKind; import com.google.devtools.build.lib.pkgcache.LoadingPhaseCompleteEvent; import com.google.devtools.build.lib.skyframe.LoadingPhaseStartedEvent; import com.google.devtools.build.lib.util.Clock; import com.google.devtools.build.lib.util.io.AnsiTerminal; 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.view.test.TestStatus.BlazeTestStatus; import java.io.IOException; import java.io.OutputStream; import java.nio.charset.StandardCharsets; import java.util.Arrays; import java.util.logging.Logger; import org.joda.time.format.DateTimeFormat; import org.joda.time.format.DateTimeFormatter; /** An experimental new output stream. */ public class ExperimentalEventHandler implements EventHandler { private static Logger LOG = 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, if the progress bar cannot be updated in place */ static final long NO_CURSES_MINIMAL_PROGRESS_RATE_LIMIT = 2000L; /** 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 = DateTimeFormat.forPattern("(HH:mm:ss.SSS) "); private final long minimalDelayMillis; private final boolean cursorControl; private final Clock clock; private final AnsiTerminal terminal; private final boolean debugAllEvents; private final ExperimentalStateTracker stateTracker; private final long minimalUpdateInterval; private final boolean showProgress; private final boolean progressInTermTitle; private final boolean showTimestamp; private final OutErr outErr; private long lastRefreshMillis; private long mustRefreshAfterMillis; private int numLinesProgressBar; private boolean buildComplete; private boolean progressBarNeedsRefresh; private Thread updateThread; private byte[] stdoutBuffer; private byte[] stderrBuffer; public final int terminalWidth; public ExperimentalEventHandler(OutErr outErr, BlazeCommandEventHandler.Options options, Clock clock) { this.outErr = outErr; this.cursorControl = options.useCursorControl(); this.terminal = new AnsiTerminal(outErr.getErrorStream()); this.terminalWidth = (options.terminalColumns > 0 ? options.terminalColumns : 80); this.showProgress = options.showProgress; this.progressInTermTitle = options.progressInTermTitle; this.showTimestamp = options.showTimestamp; this.clock = clock; this.debugAllEvents = options.experimentalUiDebugAllEvents; // 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[] {}; // The progress bar has not been updated yet. ignoreRefreshLimitOnce(); } /** * 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) { LOG.warning("IO Error writing to output stream: " + e); } return didFlush; } @Override public synchronized void handle(Event event) { 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)); outErr.getOutputStream().flush(); addProgressBar(); terminal.flush(); } else { switch (event.getKind()) { case STDOUT: case STDERR: OutputStream stream = event.getKind() == EventKind.STDOUT ? outErr.getOutputStream() : outErr.getErrorStream(); if (buildComplete) { stream.write(event.getMessageBytes()); stream.flush(); } else { byte[] message = event.getMessageBytes(); 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 SUBCOMMAND: boolean incompleteLine; if (showProgress && !buildComplete) { clearProgressBar(); } incompleteLine = flushStdOutStdErrBuffers(); if (incompleteLine) { crlf(); } setEventKindColor(event.getKind()); terminal.writeString(event.getKind() + ": "); terminal.resetTerminal(); incompleteLine = true; if (showTimestamp) { terminal.writeString(TIMESTAMP_FORMAT.print(clock.currentTimeMillis())); } if (event.getLocation() != null) { terminal.writeString(event.getLocation() + ": "); } if (event.getMessage() != null) { terminal.writeString(event.getMessage()); incompleteLine = !event.getMessage().endsWith("\n"); } if (incompleteLine) { crlf(); } if (showProgress && !buildComplete && cursorControl) { addProgressBar(); } terminal.flush(); break; case PROGRESS: if (stateTracker.progressBarTimeDependent()) { refresh(); } break; case START: case FINISH: case PASS: case TIMEOUT: case DEPCHECKER: break; } } } catch (IOException e) { LOG.warning("IO Error writing to output stream: " + e); } } private void setEventKindColor(EventKind kind) throws IOException { switch (kind) { case ERROR: case FAIL: terminal.textRed(); terminal.textBold(); break; case WARNING: terminal.textMagenta(); break; case INFO: terminal.textGreen(); break; case SUBCOMMAND: terminal.textBlue(); break; default: terminal.resetTerminal(); } } @Subscribe public void buildStarted(BuildStartingEvent event) { stateTracker.buildStarted(event); // As a new phase started, inform immediately. ignoreRefreshLimitOnce(); refresh(); } @Subscribe public void loadingStarted(LoadingPhaseStartedEvent event) { stateTracker.loadingStarted(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 time stamp, if events are supposed to have a time stmap. synchronized (this) { if (showTimestamp) { stateTracker.buildComplete(event, TIMESTAMP_FORMAT.print(clock.currentTimeMillis())); } else { stateTracker.buildComplete(event); } ignoreRefreshLimitOnce(); refresh(); buildComplete = true; } stopUpdateThread(); flushStdOutStdErrBuffers(); } @Subscribe public void noBuild(NoBuildEvent event) { synchronized (this) { buildComplete = true; } stopUpdateThread(); flushStdOutStdErrBuffers(); } @Subscribe public void afterCommand(AfterCommandEvent event) { synchronized (this) { buildComplete = true; } stopUpdateThread(); } @Subscribe public void actionStarted(ActionStartedEvent event) { stateTracker.actionStarted(event); refresh(); } @Subscribe public void actionStatusMessage(ActionStatusMessage event) { stateTracker.actionStatusMessage(event); refresh(); } @Subscribe 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.getTarget().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) { LOG.warning("IO Error writing to output stream: " + e); } } else { refresh(); } } private void refresh() { if (showProgress) { progressBarNeedsRefresh = true; doRefresh(); } } private void doRefresh(boolean fromUpdateThread) { if (buildComplete) { return; } long nowMillis = clock.currentTimeMillis(); if (lastRefreshMillis + minimalDelayMillis < nowMillis) { synchronized (this) { try { if (showProgress && (progressBarNeedsRefresh || timeBasedRefresh())) { progressBarNeedsRefresh = false; clearProgressBar(); addProgressBar(); terminal.flush(); } } catch (IOException e) { LOG.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(); synchronized (this) { if (mustRefreshAfterMillis <= lastRefreshMillis) { mustRefreshAfterMillis = Math.max(nowMillis + minimalUpdateInterval, lastRefreshMillis + 1); } } startUpdateThread(); } /** * Decide wheter 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() { Thread threadToStart = null; synchronized (this) { // 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 (!buildComplete && updateThread == null) { final ExperimentalEventHandler eventHandler = this; updateThread = new Thread(new Runnable() { @Override public void run() { try { while (true) { Thread.sleep(minimalUpdateInterval); if (lastRefreshMillis < mustRefreshAfterMillis && mustRefreshAfterMillis < clock.currentTimeMillis()) { progressBarNeedsRefresh = true; } eventHandler.doRefresh(/* fromUpdateThread= */ true); } } catch (InterruptedException e) { // Ignore } } }); threadToStart = updateThread; } } if (threadToStart != null) { threadToStart.start(); } } private void stopUpdateThread() { Thread threadToWaitFor = null; synchronized (this) { if (updateThread != null) { threadToWaitFor = updateThread; updateThread = null; } } if (threadToWaitFor != null) { threadToWaitFor.interrupt(); Uninterruptibles.joinUninterruptibly(threadToWaitFor); } } public void resetTerminal() { try { terminal.resetTerminal(); } catch (IOException e) { LOG.warning("IO Error writing to user terminal: " + e); } } private void clearProgressBar() throws IOException { if (!cursorControl) { return; } for (int i = 0; i < numLinesProgressBar; i++) { terminal.cr(); terminal.cursorUp(1); terminal.clearLine(); } numLinesProgressBar = 0; } private void crlf() throws IOException { terminal.cr(); terminal.writeString("\n"); } private synchronized void addProgressBar() throws IOException { LineCountingAnsiTerminalWriter countingTerminalWriter = new LineCountingAnsiTerminalWriter(terminal); AnsiTerminalWriter terminalWriter = countingTerminalWriter; lastRefreshMillis = clock.currentTimeMillis(); if (cursorControl) { terminalWriter = new LineWrappingAnsiTerminalWriter(terminalWriter, terminalWidth - 1); } stateTracker.writeProgressBar(terminalWriter, /* shortVersion=*/ !cursorControl); terminalWriter.newline(); numLinesProgressBar = countingTerminalWriter.getWrittenLines(); if (progressInTermTitle) { LoggingTerminalWriter stringWriter = new LoggingTerminalWriter(true); stateTracker.writeProgressBar(stringWriter, true); terminal.setTitle(stringWriter.getTranscript()); } } }