From bf326fa3f4c40412c3e945d0b0eb7e81325e7d4d Mon Sep 17 00:00:00 2001 From: olaola Date: Wed, 21 Mar 2018 11:22:12 -0700 Subject: Propagating and printing server logs on demand. WANT_LGTM=all TESTED=RBE, unit tests RELNOTES: None PiperOrigin-RevId: 189938345 --- .../lib/remote/AbstractRemoteActionCache.java | 2 +- .../lib/remote/RemoteActionContextProvider.java | 9 +- .../devtools/build/lib/remote/RemoteModule.java | 16 +- .../build/lib/remote/RemoteSpawnRunner.java | 38 +++- .../lib/remote/GrpcRemoteExecutionClientTest.java | 5 +- .../build/lib/remote/RemoteSpawnRunnerTest.java | 208 +++++++++++++++++++-- 6 files changed, 256 insertions(+), 22 deletions(-) diff --git a/src/main/java/com/google/devtools/build/lib/remote/AbstractRemoteActionCache.java b/src/main/java/com/google/devtools/build/lib/remote/AbstractRemoteActionCache.java index 2828424d83..be81ad6cfe 100644 --- a/src/main/java/com/google/devtools/build/lib/remote/AbstractRemoteActionCache.java +++ b/src/main/java/com/google/devtools/build/lib/remote/AbstractRemoteActionCache.java @@ -210,7 +210,7 @@ public abstract class AbstractRemoteActionCache implements AutoCloseable { * Download a file (that is not a directory). If the {@code content} is not given, the content is * fetched from the digest. */ - protected void downloadFile( + public void downloadFile( Path path, Digest digest, boolean isExecutable, @Nullable ByteString content) throws IOException, InterruptedException { FileSystemUtils.createDirectoryAndParents(path.getParentDirectory()); diff --git a/src/main/java/com/google/devtools/build/lib/remote/RemoteActionContextProvider.java b/src/main/java/com/google/devtools/build/lib/remote/RemoteActionContextProvider.java index f3a2baec31..a4f074a9b9 100644 --- a/src/main/java/com/google/devtools/build/lib/remote/RemoteActionContextProvider.java +++ b/src/main/java/com/google/devtools/build/lib/remote/RemoteActionContextProvider.java @@ -30,6 +30,7 @@ import com.google.devtools.build.lib.exec.local.WindowsLocalEnvProvider; import com.google.devtools.build.lib.remote.util.DigestUtil; import com.google.devtools.build.lib.runtime.CommandEnvironment; import com.google.devtools.build.lib.util.OS; +import com.google.devtools.build.lib.vfs.Path; import javax.annotation.Nullable; /** @@ -40,16 +41,19 @@ final class RemoteActionContextProvider extends ActionContextProvider { private final AbstractRemoteActionCache cache; private final GrpcRemoteExecutor executor; private final DigestUtil digestUtil; + private final Path logDir; RemoteActionContextProvider( CommandEnvironment env, @Nullable AbstractRemoteActionCache cache, @Nullable GrpcRemoteExecutor executor, - DigestUtil digestUtil) { + DigestUtil digestUtil, + Path logDir) { this.env = env; this.executor = executor; this.cache = cache; this.digestUtil = digestUtil; + this.logDir = logDir; } @Override @@ -84,7 +88,8 @@ final class RemoteActionContextProvider extends ActionContextProvider { commandId, cache, executor, - digestUtil); + digestUtil, + logDir); return ImmutableList.of(new RemoteSpawnStrategy(env.getExecRoot(), spawnRunner)); } } diff --git a/src/main/java/com/google/devtools/build/lib/remote/RemoteModule.java b/src/main/java/com/google/devtools/build/lib/remote/RemoteModule.java index 72c58d312b..dbb0e063b4 100644 --- a/src/main/java/com/google/devtools/build/lib/remote/RemoteModule.java +++ b/src/main/java/com/google/devtools/build/lib/remote/RemoteModule.java @@ -30,6 +30,7 @@ import com.google.devtools.build.lib.runtime.ServerBuilder; import com.google.devtools.build.lib.util.AbruptExitException; import com.google.devtools.build.lib.util.ExitCode; import com.google.devtools.build.lib.vfs.FileSystem.HashFunction; +import com.google.devtools.build.lib.vfs.FileSystemUtils; import com.google.devtools.build.lib.vfs.Path; import com.google.devtools.common.options.OptionsBase; import com.google.devtools.common.options.OptionsProvider; @@ -97,6 +98,18 @@ public final class RemoteModule extends BlazeModule { String buildRequestId = env.getBuildRequestId().toString(); String commandId = env.getCommandId().toString(); logger.info("Command: buildRequestId = " + buildRequestId + ", commandId = " + commandId); + Path logDir = + env.getOutputBase().getRelative(env.getRuntime().getProductName() + "-remote-logs"); + try { + // Clean out old logs files. + if (logDir.exists()) { + FileSystemUtils.deleteTree(logDir); + } + logDir.createDirectory(); + } catch (IOException e) { + env.getReporter() + .handle(Event.error("Could not create base directory for remote logs: " + logDir)); + } RemoteOptions remoteOptions = env.getOptions().getOptions(RemoteOptions.class); AuthAndTLSOptions authAndTlsOptions = env.getOptions().getOptions(AuthAndTLSOptions.class); HashFunction hashFn = env.getRuntime().getFileSystem().getDigestFunction(); @@ -154,7 +167,8 @@ public final class RemoteModule extends BlazeModule { executor = null; } - actionContextProvider = new RemoteActionContextProvider(env, cache, executor, digestUtil); + actionContextProvider = + new RemoteActionContextProvider(env, cache, executor, digestUtil, logDir); } catch (IOException e) { env.getReporter().handle(Event.error(e.getMessage())); env.getBlazeModuleEnvironment().exit(new AbruptExitException(ExitCode.COMMAND_LINE_ERROR)); diff --git a/src/main/java/com/google/devtools/build/lib/remote/RemoteSpawnRunner.java b/src/main/java/com/google/devtools/build/lib/remote/RemoteSpawnRunner.java index 289fe8b4a9..fb9724bac9 100644 --- a/src/main/java/com/google/devtools/build/lib/remote/RemoteSpawnRunner.java +++ b/src/main/java/com/google/devtools/build/lib/remote/RemoteSpawnRunner.java @@ -49,6 +49,7 @@ import com.google.devtools.remoteexecution.v1test.Command; import com.google.devtools.remoteexecution.v1test.Digest; import com.google.devtools.remoteexecution.v1test.ExecuteRequest; import com.google.devtools.remoteexecution.v1test.ExecuteResponse; +import com.google.devtools.remoteexecution.v1test.LogFile; import com.google.devtools.remoteexecution.v1test.Platform; import com.google.protobuf.TextFormat; import com.google.protobuf.TextFormat.ParseException; @@ -83,6 +84,7 @@ class RemoteSpawnRunner implements SpawnRunner { private final String buildRequestId; private final String commandId; private final DigestUtil digestUtil; + private final Path logDir; // Used to ensure that a warning is reported only once. private final AtomicBoolean warningReported = new AtomicBoolean(); @@ -97,7 +99,8 @@ class RemoteSpawnRunner implements SpawnRunner { String commandId, @Nullable AbstractRemoteActionCache remoteCache, @Nullable GrpcRemoteExecutor remoteExecutor, - DigestUtil digestUtil) { + DigestUtil digestUtil, + Path logDir) { this.execRoot = execRoot; this.options = options; this.fallbackRunner = fallbackRunner; @@ -108,6 +111,7 @@ class RemoteSpawnRunner implements SpawnRunner { this.buildRequestId = buildRequestId; this.commandId = commandId; this.digestUtil = digestUtil; + this.logDir = logDir; } @Override @@ -196,6 +200,7 @@ class RemoteSpawnRunner implements SpawnRunner { .setAction(action) .setSkipCacheLookup(!acceptCachedResult); ExecuteResponse reply = remoteExecutor.executeRemotely(request.build()); + maybeDownloadServerLogs(reply, actionKey); result = reply.getResult(); remoteCacheHit = reply.getCachedResult(); } catch (IOException e) { @@ -215,6 +220,32 @@ class RemoteSpawnRunner implements SpawnRunner { } } + private void maybeDownloadServerLogs(ExecuteResponse resp, ActionKey actionKey) + throws InterruptedException { + ActionResult result = resp.getResult(); + if (resp.getServerLogsCount() > 0 + && (result.getExitCode() != 0 || resp.getStatus().getCode() != Code.OK.value())) { + Path parent = logDir.getRelative(actionKey.getDigest().getHash()); + Path logPath = null; + int logCount = 0; + for (Map.Entry e : resp.getServerLogsMap().entrySet()) { + if (e.getValue().getHumanReadable()) { + logPath = parent.getRelative(e.getKey()); + logCount++; + try { + remoteCache.downloadFile(logPath, e.getValue().getDigest(), false, null); + } catch (IOException ex) { + reportOnce(Event.warn("Failed downloading server logs from the remote cache.")); + } + } + } + if (logCount > 0 && verboseFailures) { + report( + Event.info("Server logs of failing action:\n " + (logCount > 1 ? parent : logPath))); + } + } + } + private SpawnResult.Builder downloadRemoteResults(ActionResult result, FileOutErr outErr) throws ExecException, IOException, InterruptedException { remoteCache.download(result, execRoot, outErr); @@ -242,16 +273,17 @@ class RemoteSpawnRunner implements SpawnRunner { && RemoteRetrierUtils.causedByExecTimeout((RetryException) cause))) { return execLocally(spawn, policy, inputMap, uploadLocalResults, remoteCache, actionKey); } - return handleError(cause, policy.getFileOutErr()); + return handleError(cause, policy.getFileOutErr(), actionKey); } - private SpawnResult handleError(IOException exception, FileOutErr outErr) + private SpawnResult handleError(IOException exception, FileOutErr outErr, ActionKey actionKey) throws ExecException, InterruptedException, IOException { final Throwable cause = exception.getCause(); if (cause instanceof ExecutionStatusException) { ExecutionStatusException e = (ExecutionStatusException) cause; if (e.getResponse() != null) { ExecuteResponse resp = e.getResponse(); + maybeDownloadServerLogs(resp, actionKey); if (resp.hasResult()) { // We try to download all (partial) results even on server error, for debuggability. remoteCache.download(resp.getResult(), execRoot, outErr); diff --git a/src/test/java/com/google/devtools/build/lib/remote/GrpcRemoteExecutionClientTest.java b/src/test/java/com/google/devtools/build/lib/remote/GrpcRemoteExecutionClientTest.java index 4f3252b71b..3bc5b37b1e 100644 --- a/src/test/java/com/google/devtools/build/lib/remote/GrpcRemoteExecutionClientTest.java +++ b/src/test/java/com/google/devtools/build/lib/remote/GrpcRemoteExecutionClientTest.java @@ -120,6 +120,7 @@ public class GrpcRemoteExecutionClientTest { private final MutableHandlerRegistry serviceRegistry = new MutableHandlerRegistry(); private FileSystem fs; private Path execRoot; + private Path logDir; private SimpleSpawn simpleSpawn; private FakeActionInputFileCache fakeFileCache; private Digest inputDigest; @@ -195,6 +196,7 @@ public class GrpcRemoteExecutionClientTest { Chunker.setDefaultChunkSizeForTesting(1000); // Enough for everything to be one chunk. fs = new InMemoryFileSystem(new JavaClock(), HashFunction.SHA256); execRoot = fs.getPath("/exec/root"); + logDir = fs.getPath("/server-logs"); FileSystemUtils.createDirectoryAndParents(execRoot); fakeFileCache = new FakeActionInputFileCache(execRoot); simpleSpawn = @@ -255,7 +257,8 @@ public class GrpcRemoteExecutionClientTest { "command-id", remoteCache, executor, - DIGEST_UTIL); + DIGEST_UTIL, + logDir); inputDigest = fakeFileCache.createScratchInput(simpleSpawn.getInputFiles().get(0), "xyz"); } diff --git a/src/test/java/com/google/devtools/build/lib/remote/RemoteSpawnRunnerTest.java b/src/test/java/com/google/devtools/build/lib/remote/RemoteSpawnRunnerTest.java index 98b56706d7..29470f4438 100644 --- a/src/test/java/com/google/devtools/build/lib/remote/RemoteSpawnRunnerTest.java +++ b/src/test/java/com/google/devtools/build/lib/remote/RemoteSpawnRunnerTest.java @@ -61,8 +61,11 @@ import com.google.devtools.build.lib.vfs.PathFragment; import com.google.devtools.build.lib.vfs.inmemoryfs.InMemoryFileSystem; import com.google.devtools.common.options.Options; import com.google.devtools.remoteexecution.v1test.ActionResult; +import com.google.devtools.remoteexecution.v1test.Digest; import com.google.devtools.remoteexecution.v1test.ExecuteRequest; import com.google.devtools.remoteexecution.v1test.ExecuteResponse; +import com.google.devtools.remoteexecution.v1test.LogFile; +import com.google.protobuf.ByteString; import com.google.rpc.Code; import java.io.IOException; import java.time.Duration; @@ -85,6 +88,7 @@ public class RemoteSpawnRunnerTest { ImmutableMap.of(ExecutionRequirements.NO_CACHE, ""); private Path execRoot; + private Path logDir; private DigestUtil digestUtil; private FakeActionInputFileCache fakeFileCache; private FileOutErr outErr; @@ -97,12 +101,17 @@ public class RemoteSpawnRunnerTest { @Mock private SpawnRunner localRunner; + // The action key of the Spawn returned by newSimpleSpawn(). + private final String simpleActionId = + "eb45b20cc979d504f96b9efc9a08c48103c6f017afa09c0df5c70a5f92a98ea8"; + @Before public final void setUp() throws Exception { MockitoAnnotations.initMocks(this); digestUtil = new DigestUtil(HashFunction.SHA256); FileSystem fs = new InMemoryFileSystem(new JavaClock(), HashFunction.SHA256); execRoot = fs.getPath("/exec/root"); + logDir = fs.getPath("/server-logs"); FileSystemUtils.createDirectoryAndParents(execRoot); fakeFileCache = new FakeActionInputFileCache(execRoot); @@ -136,7 +145,8 @@ public class RemoteSpawnRunnerTest { "command-id", cache, executor, - digestUtil); + digestUtil, + logDir); ExecuteResponse succeeded = ExecuteResponse.newBuilder().setResult( ActionResult.newBuilder().setExitCode(0).build()).build(); @@ -194,7 +204,8 @@ public class RemoteSpawnRunnerTest { "command-id", cache, null, - digestUtil); + digestUtil, + logDir); // Throw an IOException to trigger the local fallback. when(executor.executeRemotely(any(ExecuteRequest.class))).thenThrow(IOException.class); @@ -246,7 +257,8 @@ public class RemoteSpawnRunnerTest { "command-id", cache, null, - digestUtil)); + digestUtil, + logDir)); Spawn spawn = newSimpleSpawn(); SpawnExecutionPolicy policy = new FakeSpawnExecutionPolicy(spawn); @@ -294,7 +306,8 @@ public class RemoteSpawnRunnerTest { "command-id", cache, null, - digestUtil)); + digestUtil, + logDir)); try { runner.exec(spawn, policy); @@ -328,7 +341,8 @@ public class RemoteSpawnRunnerTest { "command-id", cache, null, - digestUtil); + digestUtil, + logDir); Spawn spawn = newSimpleSpawn(); SpawnExecutionPolicy policy = new FakeSpawnExecutionPolicy(spawn); @@ -379,7 +393,8 @@ public class RemoteSpawnRunnerTest { "command-id", cache, null, - digestUtil); + digestUtil, + logDir); Spawn spawn = newSimpleSpawn(); SpawnExecutionPolicy policy = new FakeSpawnExecutionPolicy(spawn); @@ -418,7 +433,8 @@ public class RemoteSpawnRunnerTest { "command-id", cache, null, - digestUtil); + digestUtil, + logDir); Spawn spawn = newSimpleSpawn(); SpawnExecutionPolicy policy = new FakeSpawnExecutionPolicy(spawn); @@ -454,7 +470,8 @@ public class RemoteSpawnRunnerTest { "command-id", cache, executor, - digestUtil); + digestUtil, + logDir); when(cache.getCachedActionResult(any(ActionKey.class))).thenReturn(null); when(executor.executeRemotely(any(ExecuteRequest.class))).thenThrow(new IOException()); @@ -475,6 +492,163 @@ public class RemoteSpawnRunnerTest { verify(localRunner).exec(eq(spawn), eq(policy)); } + @Test + public void testHumanReadableServerLogsSavedForFailingAction() throws Exception { + RemoteSpawnRunner runner = + new RemoteSpawnRunner( + execRoot, + Options.getDefaults(RemoteOptions.class), + localRunner, + true, + /*cmdlineReporter=*/ null, + "build-req-id", + "command-id", + cache, + executor, + digestUtil, + logDir); + + Digest logDigest = digestUtil.computeAsUtf8("bla"); + when(executor.executeRemotely(any(ExecuteRequest.class))) + .thenReturn( + ExecuteResponse.newBuilder() + .putServerLogs( + "logname", + LogFile.newBuilder().setHumanReadable(true).setDigest(logDigest).build()) + .setResult(ActionResult.newBuilder().setExitCode(31).build()) + .build()); + + Spawn spawn = newSimpleSpawn(); + SpawnExecutionPolicy policy = new FakeSpawnExecutionPolicy(spawn); + + SpawnResult res = runner.exec(spawn, policy); + assertThat(res.status()).isEqualTo(Status.NON_ZERO_EXIT); + + verify(executor).executeRemotely(any(ExecuteRequest.class)); + Path logPath = logDir.getRelative(simpleActionId).getRelative("logname"); + verify(cache).downloadFile(eq(logPath), eq(logDigest), eq(false), eq(null)); + } + + @Test + public void testHumanReadableServerLogsSavedForFailingActionWithStatus() throws Exception { + RemoteSpawnRunner runner = + new RemoteSpawnRunner( + execRoot, + Options.getDefaults(RemoteOptions.class), + localRunner, + true, + /*cmdlineReporter=*/ null, + "build-req-id", + "command-id", + cache, + executor, + digestUtil, + logDir); + + Digest logDigest = digestUtil.computeAsUtf8("bla"); + com.google.rpc.Status timeoutStatus = + com.google.rpc.Status.newBuilder().setCode(Code.DEADLINE_EXCEEDED.getNumber()).build(); + ExecuteResponse resp = + ExecuteResponse.newBuilder() + .putServerLogs( + "logname", LogFile.newBuilder().setHumanReadable(true).setDigest(logDigest).build()) + .setStatus(timeoutStatus) + .build(); + when(executor.executeRemotely(any(ExecuteRequest.class))) + .thenThrow(new Retrier.RetryException( + "", 1, new ExecutionStatusException(resp.getStatus(), resp))); + + Spawn spawn = newSimpleSpawn(); + SpawnExecutionPolicy policy = new FakeSpawnExecutionPolicy(spawn); + + SpawnResult res = runner.exec(spawn, policy); + assertThat(res.status()).isEqualTo(Status.TIMEOUT); + + verify(executor).executeRemotely(any(ExecuteRequest.class)); + Path logPath = logDir.getRelative(simpleActionId).getRelative("logname"); + verify(cache).downloadFile(eq(logPath), eq(logDigest), eq(false), eq(null)); + } + + @Test + public void testNonHumanReadableServerLogsNotSaved() throws Exception { + RemoteSpawnRunner runner = + new RemoteSpawnRunner( + execRoot, + Options.getDefaults(RemoteOptions.class), + localRunner, + true, + /*cmdlineReporter=*/ null, + "build-req-id", + "command-id", + cache, + executor, + digestUtil, + logDir); + + Digest logDigest = digestUtil.computeAsUtf8("bla"); + ActionResult result = ActionResult.newBuilder().setExitCode(31).build(); + when(executor.executeRemotely(any(ExecuteRequest.class))) + .thenReturn( + ExecuteResponse.newBuilder() + .putServerLogs( + "logname", + LogFile.newBuilder().setDigest(logDigest).build()) + .setResult(result) + .build()); + + Spawn spawn = newSimpleSpawn(); + SpawnExecutionPolicy policy = new FakeSpawnExecutionPolicy(spawn); + + SpawnResult res = runner.exec(spawn, policy); + assertThat(res.status()).isEqualTo(Status.NON_ZERO_EXIT); + + verify(executor).executeRemotely(any(ExecuteRequest.class)); + verify(cache).download(eq(result), eq(execRoot), any(FileOutErr.class)); + verify(cache, never()) + .downloadFile( + any(Path.class), any(Digest.class), any(Boolean.class), any(ByteString.class)); + } + + @Test + public void testServerLogsNotSavedForSuccessfulAction() throws Exception { + RemoteSpawnRunner runner = + new RemoteSpawnRunner( + execRoot, + Options.getDefaults(RemoteOptions.class), + localRunner, + true, + /*cmdlineReporter=*/ null, + "build-req-id", + "command-id", + cache, + executor, + digestUtil, + logDir); + + Digest logDigest = digestUtil.computeAsUtf8("bla"); + ActionResult result = ActionResult.newBuilder().setExitCode(0).build(); + when(executor.executeRemotely(any(ExecuteRequest.class))) + .thenReturn( + ExecuteResponse.newBuilder() + .putServerLogs( + "logname", + LogFile.newBuilder().setHumanReadable(true).setDigest(logDigest).build()) + .setResult(result) + .build()); + + Spawn spawn = newSimpleSpawn(); + SpawnExecutionPolicy policy = new FakeSpawnExecutionPolicy(spawn); + + SpawnResult res = runner.exec(spawn, policy); + assertThat(res.status()).isEqualTo(Status.SUCCESS); + + verify(executor).executeRemotely(any(ExecuteRequest.class)); + verify(cache).download(eq(result), eq(execRoot), any(FileOutErr.class)); + verify(cache, never()) + .downloadFile( + any(Path.class), any(Digest.class), any(Boolean.class), any(ByteString.class)); + } + @Test public void cacheDownloadFailureTriggersRemoteExecution() throws Exception { // If downloading a cached action fails, remote execution should be tried. @@ -492,7 +666,8 @@ public class RemoteSpawnRunnerTest { "command-id", cache, executor, - digestUtil); + digestUtil, + logDir); ActionResult cachedResult = ActionResult.newBuilder().setExitCode(0).build(); when(cache.getCachedActionResult(any(ActionKey.class))).thenReturn(cachedResult); @@ -533,7 +708,8 @@ public class RemoteSpawnRunnerTest { "command-id", cache, executor, - digestUtil); + digestUtil, + logDir); ActionResult cachedResult = ActionResult.newBuilder().setExitCode(0).build(); when(cache.getCachedActionResult(any(ActionKey.class))).thenReturn(null); @@ -580,7 +756,8 @@ public class RemoteSpawnRunnerTest { "command-id", cache, executor, - digestUtil); + digestUtil, + logDir); ActionResult cachedResult = ActionResult.newBuilder().setExitCode(0).build(); when(cache.getCachedActionResult(any(ActionKey.class))).thenReturn(null); @@ -625,7 +802,8 @@ public class RemoteSpawnRunnerTest { "command-id", cache, executor, - digestUtil); + digestUtil, + logDir); ActionResult cachedResult = ActionResult.newBuilder().setExitCode(0).build(); when(cache.getCachedActionResult(any(ActionKey.class))).thenReturn(null); @@ -665,7 +843,8 @@ public class RemoteSpawnRunnerTest { "command-id", cache, executor, - digestUtil); + digestUtil, + logDir); when(cache.getCachedActionResult(any(ActionKey.class))).thenReturn(null); when(executor.executeRemotely(any(ExecuteRequest.class))).thenThrow(new IOException()); @@ -701,7 +880,8 @@ public class RemoteSpawnRunnerTest { "command-id", cache, executor, - digestUtil); + digestUtil, + logDir); when(cache.getCachedActionResult(any(ActionKey.class))).thenThrow(new IOException()); -- cgit v1.2.3