Implement logging in LocalSpawnRunner This is a prerequisite for Google to use it; there's no consistent logging strategy yet, but Google internally requires logging, and it needs to be somewhat backwards compatible. PiperOrigin-RevId: 153454160
diff --git a/src/main/java/com/google/devtools/build/lib/exec/local/LocalSpawnRunner.java b/src/main/java/com/google/devtools/build/lib/exec/local/LocalSpawnRunner.java index 3ae6e39..b96a226 100644 --- a/src/main/java/com/google/devtools/build/lib/exec/local/LocalSpawnRunner.java +++ b/src/main/java/com/google/devtools/build/lib/exec/local/LocalSpawnRunner.java
@@ -17,6 +17,7 @@ import static java.util.logging.Level.INFO; import static java.util.logging.Level.SEVERE; +import com.google.common.base.Joiner; import com.google.common.io.ByteStreams; import com.google.devtools.build.lib.actions.ActionExecutionMetadata; import com.google.devtools.build.lib.actions.ResourceManager; @@ -42,7 +43,9 @@ import java.util.EnumMap; import java.util.List; import java.util.Map; +import java.util.concurrent.atomic.AtomicInteger; import java.util.logging.Level; +import java.util.logging.Logger; import javax.annotation.Nullable; /** @@ -51,14 +54,18 @@ */ @ThreadSafe public final class LocalSpawnRunner implements SpawnRunner { + private static final Joiner SPACE_JOINER = Joiner.on(' '); private static final String UNHANDLED_EXCEPTION_MSG = "Unhandled exception running a local spawn"; private static final int LOCAL_EXEC_ERROR = -1; private static final int POSIX_TIMEOUT_EXIT_CODE = /*SIGNAL_BASE=*/128 + /*SIGWINCH=*/28; + private final Logger logger; + private final Path execRoot; private final ResourceManager resourceManager; private final String hostName; + private final AtomicInteger execCount; private final ActionInputPrefetcher actionInputPrefetcher; @@ -68,16 +75,20 @@ private final String processWrapper; public LocalSpawnRunner( + Logger logger, + AtomicInteger execCount, Path execRoot, ActionInputPrefetcher actionInputPrefetcher, LocalExecutionOptions localExecutionOptions, ResourceManager resourceManager, boolean useProcessWrapper) { + this.logger = logger; this.execRoot = execRoot; this.actionInputPrefetcher = Preconditions.checkNotNull(actionInputPrefetcher); this.processWrapper = execRoot.getRelative("_bin/process-wrapper").getPathString(); this.localExecutionOptions = localExecutionOptions; this.hostName = NetUtil.findShortHostName(); + this.execCount = execCount; this.resourceManager = resourceManager; this.useProcessWrapper = useProcessWrapper; } @@ -88,6 +99,8 @@ LocalExecutionOptions localExecutionOptions, ResourceManager resourceManager) { this( + null, + new AtomicInteger(), execRoot, actionInputPrefetcher, localExecutionOptions, @@ -122,6 +135,8 @@ private State currentState = State.INITIALIZING; private final Map<State, Long> stateTimes = new EnumMap<>(State.class); + private final int id = execCount.getAndIncrement(); + public SubprocessHandler( Spawn spawn, SpawnExecutionPolicy policy) { @@ -137,6 +152,9 @@ } catch (Error e) { stepLog(SEVERE, UNHANDLED_EXCEPTION_MSG, e); throw e; + } catch (IOException e) { + stepLog(SEVERE, "Local I/O error", e); + throw e; } catch (RuntimeException e) { stepLog(SEVERE, UNHANDLED_EXCEPTION_MSG, e); throw new RuntimeException(UNHANDLED_EXCEPTION_MSG, e); @@ -149,11 +167,21 @@ @SuppressWarnings("unused") private void stepLog(Level level, String fmt, @Nullable Throwable cause, Object... args) { - // Do nothing for now. + String msg = String.format(fmt, args); + String toLog = String.format("%s (#%d %s)", msg, id, desc()); + logger.log(level, toLog, cause); + } + + private String desc() { + String progressMessage = spawn.getResourceOwner().getProgressMessage(); + return progressMessage != null + ? progressMessage + : "ActionType=" + spawn.getResourceOwner().getMnemonic(); } private void setState(State newState) { long now = System.currentTimeMillis(); + long totalDelta = now - creationTime; long stepDelta = now - stateStartTime; stateStartTime = now; @@ -161,11 +189,25 @@ long stateTime = (stateTimeBoxed == null) ? 0 : stateTimeBoxed; stateTimes.put(currentState, stateTime + stepDelta); + logger.info(String.format( + "Step #%d time: %.3f delta: %.3f state: %s --> %s", + id, totalDelta / 1000f, stepDelta / 1000f, currentState, newState)); currentState = newState; } + private String debugCmdString() { + String cmd = SPACE_JOINER.join(spawn.getArguments()); + if (cmd.length() > 500) { + // Shrink argstr by replacing middle of string with "...". + return cmd.substring(0, 250) + "..." + cmd.substring(cmd.length() - 250); + } + return cmd; + } + /** Parse the request and run it locally. */ private SpawnResult start() throws InterruptedException, IOException { + logger.info(String.format("starting local subprocess #%d, argv: %s", id, debugCmdString())); + FileOutErr outErr = policy.getFileOutErr(); String actionType = spawn.getResourceOwner().getMnemonic(); if (localExecutionOptions.allowedLocalAction != null
diff --git a/src/test/java/com/google/devtools/build/lib/exec/local/LocalSpawnRunnerTest.java b/src/test/java/com/google/devtools/build/lib/exec/local/LocalSpawnRunnerTest.java index 97265c4..23d6515 100644 --- a/src/test/java/com/google/devtools/build/lib/exec/local/LocalSpawnRunnerTest.java +++ b/src/test/java/com/google/devtools/build/lib/exec/local/LocalSpawnRunnerTest.java
@@ -47,6 +47,10 @@ import java.io.InputStream; import java.io.OutputStream; import java.util.SortedMap; +import java.util.concurrent.atomic.AtomicInteger; +import java.util.logging.Filter; +import java.util.logging.LogRecord; +import java.util.logging.Logger; import java.util.regex.Pattern; import org.junit.After; import org.junit.Before; @@ -130,6 +134,8 @@ private final ActionInputFileCache mockFileCache = mock(ActionInputFileCache.class); private final ResourceManager resourceManager = ResourceManager.instanceForTestingOnly(); + private Logger logger; + private AtomicInteger execCount = new AtomicInteger(); private FileOutErr outErr; private long timeoutMillis = 0; private boolean calledLockOutputFiles; @@ -174,6 +180,13 @@ @Before public final void setup() throws Exception { + logger = Logger.getAnonymousLogger(); + logger.setFilter(new Filter() { + @Override + public boolean isLoggable(LogRecord record) { + return false; + } + }); fs = new InMemoryFileSystem(); // Prevent any subprocess execution at all. SubprocessBuilder.setSubprocessFactory(new SubprocessInterceptor()); @@ -196,7 +209,8 @@ LocalExecutionOptions options = Options.getDefaults(LocalExecutionOptions.class); options.localSigkillGraceSeconds = 456; LocalSpawnRunner runner = new LocalSpawnRunner( - fs.getPath("/execroot"), ActionInputPrefetcher.NONE, options, resourceManager, USE_WRAPPER); + logger, execCount, fs.getPath("/execroot"), ActionInputPrefetcher.NONE, options, + resourceManager, USE_WRAPPER); timeoutMillis = 123 * 1000L; outErr = new FileOutErr(fs.getPath("/out/stdout"), fs.getPath("/out/stderr")); @@ -228,7 +242,8 @@ LocalExecutionOptions options = Options.getDefaults(LocalExecutionOptions.class); options.localSigkillGraceSeconds = 456; LocalSpawnRunner runner = new LocalSpawnRunner( - fs.getPath("/execroot"), ActionInputPrefetcher.NONE, options, resourceManager, NO_WRAPPER); + logger, execCount, fs.getPath("/execroot"), ActionInputPrefetcher.NONE, options, + resourceManager, NO_WRAPPER); timeoutMillis = 123 * 1000L; outErr = new FileOutErr(fs.getPath("/out/stdout"), fs.getPath("/out/stderr")); @@ -257,7 +272,8 @@ LocalExecutionOptions options = Options.getDefaults(LocalExecutionOptions.class); LocalSpawnRunner runner = new LocalSpawnRunner( - fs.getPath("/execroot"), ActionInputPrefetcher.NONE, options, resourceManager, USE_WRAPPER); + logger, execCount, fs.getPath("/execroot"), ActionInputPrefetcher.NONE, options, + resourceManager, USE_WRAPPER); outErr = new FileOutErr(fs.getPath("/out/stdout"), fs.getPath("/out/stderr")); SpawnResult result = runner.exec(SIMPLE_SPAWN, policy); @@ -286,7 +302,8 @@ LocalExecutionOptions options = Options.getDefaults(LocalExecutionOptions.class); LocalSpawnRunner runner = new LocalSpawnRunner( - fs.getPath("/execroot"), ActionInputPrefetcher.NONE, options, resourceManager, USE_WRAPPER); + logger, execCount, fs.getPath("/execroot"), ActionInputPrefetcher.NONE, options, + resourceManager, USE_WRAPPER); outErr = new FileOutErr(fs.getPath("/out/stdout"), fs.getPath("/out/stderr")); SpawnResult result = runner.exec(SIMPLE_SPAWN, policy); @@ -305,7 +322,8 @@ LocalExecutionOptions options = Options.getDefaults(LocalExecutionOptions.class); options.allowedLocalAction = Pattern.compile("none"); LocalSpawnRunner runner = new LocalSpawnRunner( - fs.getPath("/execroot"), ActionInputPrefetcher.NONE, options, resourceManager, USE_WRAPPER); + logger, execCount, fs.getPath("/execroot"), ActionInputPrefetcher.NONE, options, + resourceManager, USE_WRAPPER); outErr = new FileOutErr(); SpawnResult reply = runner.exec(SIMPLE_SPAWN, policy); @@ -343,7 +361,8 @@ LocalExecutionOptions options = Options.getDefaults(LocalExecutionOptions.class); LocalSpawnRunner runner = new LocalSpawnRunner( - fs.getPath("/execroot"), ActionInputPrefetcher.NONE, options, resourceManager, USE_WRAPPER); + logger, execCount, fs.getPath("/execroot"), ActionInputPrefetcher.NONE, options, + resourceManager, USE_WRAPPER); outErr = new FileOutErr(fs.getPath("/out/stdout"), fs.getPath("/out/stderr")); try {