Propagating and printing server logs on demand.
WANT_LGTM=all
TESTED=RBE, unit tests
RELNOTES: None
PiperOrigin-RevId: 189938345
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 2828424..be81ad6 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 @@
* 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 f3a2bae..a4f074a 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.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 @@
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 @@
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 72c58d3..dbb0e06 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.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 @@
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 @@
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 289fe8b..fb9724b 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.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 @@
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 @@
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 @@
this.buildRequestId = buildRequestId;
this.commandId = commandId;
this.digestUtil = digestUtil;
+ this.logDir = logDir;
}
@Override
@@ -196,6 +200,7 @@
.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 @@
}
}
+ 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<String, LogFile> 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 @@
&& 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 4f3252b..3bc5b37 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 @@
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 @@
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 @@
"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 98b5670..29470f4 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.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 @@
ImmutableMap.of(ExecutionRequirements.NO_CACHE, "");
private Path execRoot;
+ private Path logDir;
private DigestUtil digestUtil;
private FakeActionInputFileCache fakeFileCache;
private FileOutErr outErr;
@@ -97,12 +101,17 @@
@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 @@
"command-id",
cache,
executor,
- digestUtil);
+ digestUtil,
+ logDir);
ExecuteResponse succeeded = ExecuteResponse.newBuilder().setResult(
ActionResult.newBuilder().setExitCode(0).build()).build();
@@ -194,7 +204,8 @@
"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 @@
"command-id",
cache,
null,
- digestUtil));
+ digestUtil,
+ logDir));
Spawn spawn = newSimpleSpawn();
SpawnExecutionPolicy policy = new FakeSpawnExecutionPolicy(spawn);
@@ -294,7 +306,8 @@
"command-id",
cache,
null,
- digestUtil));
+ digestUtil,
+ logDir));
try {
runner.exec(spawn, policy);
@@ -328,7 +341,8 @@
"command-id",
cache,
null,
- digestUtil);
+ digestUtil,
+ logDir);
Spawn spawn = newSimpleSpawn();
SpawnExecutionPolicy policy = new FakeSpawnExecutionPolicy(spawn);
@@ -379,7 +393,8 @@
"command-id",
cache,
null,
- digestUtil);
+ digestUtil,
+ logDir);
Spawn spawn = newSimpleSpawn();
SpawnExecutionPolicy policy = new FakeSpawnExecutionPolicy(spawn);
@@ -418,7 +433,8 @@
"command-id",
cache,
null,
- digestUtil);
+ digestUtil,
+ logDir);
Spawn spawn = newSimpleSpawn();
SpawnExecutionPolicy policy = new FakeSpawnExecutionPolicy(spawn);
@@ -454,7 +470,8 @@
"command-id",
cache,
executor,
- digestUtil);
+ digestUtil,
+ logDir);
when(cache.getCachedActionResult(any(ActionKey.class))).thenReturn(null);
when(executor.executeRemotely(any(ExecuteRequest.class))).thenThrow(new IOException());
@@ -476,6 +493,163 @@
}
@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 @@
"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 @@
"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 @@
"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 @@
"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 @@
"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 @@
"command-id",
cache,
executor,
- digestUtil);
+ digestUtil,
+ logDir);
when(cache.getCachedActionResult(any(ActionKey.class))).thenThrow(new IOException());
