Logging the spawn graph on demand. First step on #4891.

This is a very heavy and slow option by design. It will be enabled only when a user wants to debug their build, most frequently to compare the step-by-step results of two builds.

TESTED: manually on various rules, including directories.
RELNOTES: None
PiperOrigin-RevId: 193539034

8 files changed, 404 insertions, 1 deletions

diff --git a/src/main/java/com/google/devtools/build/lib/BUILD b/src/main/java/com/google/devtools/build/lib/BUILD
index 43c47187fb..070f31984b 100644
--- a/src/main/java/com/google/devtools/build/lib/BUILD
+++ b/src/main/java/com/google/devtools/build/lib/BUILD
@@ -560,6 +560,7 @@ java_library(
         "//src/main/protobuf:analysis_java_proto",
         "//src/main/protobuf:extra_actions_base_java_proto",
         "//src/main/protobuf:invocation_policy_java_proto",
+        "//src/main/protobuf:spawn_java_proto",
         "//src/main/protobuf:test_status_java_proto",
         "//third_party:auto_value",
         "//third_party:guava",
@@ -672,6 +673,7 @@ java_library(
     ],
     deps = [
         ":bazel/BazelRepositoryModule",
+        ":exitcode-external",
         "//src/main/java/com/google/devtools/build/lib:bazel",
         "//src/main/java/com/google/devtools/build/lib:bazel-commands",
         "//src/main/java/com/google/devtools/build/lib:bazel-repository",
diff --git a/src/main/java/com/google/devtools/build/lib/bazel/Bazel.java b/src/main/java/com/google/devtools/build/lib/bazel/Bazel.java
index 47c0e8553e..fde7dc75a6 100644
--- a/src/main/java/com/google/devtools/build/lib/bazel/Bazel.java
+++ b/src/main/java/com/google/devtools/build/lib/bazel/Bazel.java
@@ -42,6 +42,7 @@ public final class Bazel {
           com.google.devtools.build.lib.bazel.BazelWorkspaceStatusModule.class,
           com.google.devtools.build.lib.bazel.BazelDiffAwarenessModule.class,
           com.google.devtools.build.lib.bazel.BazelRepositoryModule.class,
+          com.google.devtools.build.lib.bazel.SpawnLogModule.class,
           com.google.devtools.build.lib.ssd.SsdModule.class,
           com.google.devtools.build.lib.worker.WorkerModule.class,
           com.google.devtools.build.lib.remote.RemoteModule.class,
diff --git a/src/main/java/com/google/devtools/build/lib/bazel/SpawnLogModule.java b/src/main/java/com/google/devtools/build/lib/bazel/SpawnLogModule.java
new file mode 100644
index 0000000000..86ab87eea8
--- /dev/null
+++ b/src/main/java/com/google/devtools/build/lib/bazel/SpawnLogModule.java
@@ -0,0 +1,78 @@
+// Copyright 2018 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.bazel;
+
+import com.google.devtools.build.lib.buildtool.BuildRequest;
+import com.google.devtools.build.lib.events.Event;
+import com.google.devtools.build.lib.exec.ActionContextConsumer;
+import com.google.devtools.build.lib.exec.ExecutionOptions;
+import com.google.devtools.build.lib.exec.ExecutorBuilder;
+import com.google.devtools.build.lib.exec.SpawnActionContextMaps;
+import com.google.devtools.build.lib.exec.SpawnLogContext;
+import com.google.devtools.build.lib.runtime.BlazeModule;
+import com.google.devtools.build.lib.runtime.CommandEnvironment;
+import com.google.devtools.build.lib.util.AbruptExitException;
+import com.google.devtools.build.lib.util.ExitCode;
+import com.google.devtools.build.lib.util.io.AsynchronousFileOutputStream;
+import java.io.IOException;
+
+/**
+ * Module providing on-demand spawn logging.
+ */
+public final class SpawnLogModule extends BlazeModule {
+
+  private static final class SpawnLogContextConsumer implements ActionContextConsumer {
+    @Override
+    public void populate(SpawnActionContextMaps.Builder builder) {
+      builder.strategyByContextMap().put(SpawnLogContext.class, "");
+    }
+  }
+
+  private SpawnLogContext spawnLogContext;
+
+  @Override
+  public void executorInit(CommandEnvironment env, BuildRequest request, ExecutorBuilder builder) {
+    env.getEventBus().register(this);
+    ExecutionOptions executionOptions = env.getOptions().getOptions(ExecutionOptions.class);
+    if (executionOptions != null
+        && executionOptions.executionLogFile != null
+        && !executionOptions.executionLogFile.isEmpty()) {
+      try {
+        spawnLogContext = new SpawnLogContext(
+            env.getExecRoot(),
+            new AsynchronousFileOutputStream(executionOptions.executionLogFile));
+      } catch (IOException e) {
+        env.getReporter().handle(Event.error(e.getMessage()));
+        env.getBlazeModuleEnvironment().exit(new AbruptExitException(ExitCode.COMMAND_LINE_ERROR));
+      }
+      builder.addActionContext(spawnLogContext);
+      builder.addActionContextConsumer(new SpawnLogContextConsumer());
+    } else {
+      spawnLogContext = null;
+    }
+  }
+
+  @Override
+  public void afterCommand() {
+    if (spawnLogContext != null) {
+      try {
+        spawnLogContext.close();
+      } catch (IOException e) {
+        throw new RuntimeException(e);
+      } finally {
+        spawnLogContext = null;
+      }
+    }
+  }
+}
diff --git a/src/main/java/com/google/devtools/build/lib/exec/AbstractSpawnStrategy.java b/src/main/java/com/google/devtools/build/lib/exec/AbstractSpawnStrategy.java
index fee7f52e6b..c516b7875a 100644
--- a/src/main/java/com/google/devtools/build/lib/exec/AbstractSpawnStrategy.java
+++ b/src/main/java/com/google/devtools/build/lib/exec/AbstractSpawnStrategy.java
@@ -31,6 +31,7 @@ import com.google.devtools.build.lib.actions.SpawnActionContext;
 import com.google.devtools.build.lib.actions.SpawnResult;
 import com.google.devtools.build.lib.actions.SpawnResult.Status;
 import com.google.devtools.build.lib.actions.Spawns;
+import com.google.devtools.build.lib.events.Event;
 import com.google.devtools.build.lib.exec.SpawnCache.CacheHandle;
 import com.google.devtools.build.lib.exec.SpawnRunner.ProgressStatus;
 import com.google.devtools.build.lib.exec.SpawnRunner.SpawnExecutionContext;
@@ -86,6 +87,7 @@ public abstract class AbstractSpawnStrategy implements SandboxedSpawnActionConte
       cache = SpawnCache.NO_CACHE;
     }
     SpawnResult spawnResult;
+    ExecException ex = null;
     try {
       try (CacheHandle cacheHandle = cache.lookup(spawn, context)) {
         if (cacheHandle.hasResult()) {
@@ -101,6 +103,30 @@ public abstract class AbstractSpawnStrategy implements SandboxedSpawnActionConte
       }
     } catch (IOException e) {
       throw new EnvironmentalExecException("Unexpected IO error.", e);
+    } catch (SpawnExecException e) {
+      ex = e;
+      spawnResult = e.getSpawnResult();
+      // Log the Spawn and re-throw.
+    }
+
+    SpawnLogContext spawnLogContext = actionExecutionContext.getContext(SpawnLogContext.class);
+    if (spawnLogContext != null) {
+      try {
+        spawnLogContext.logSpawn(
+            spawn,
+            actionExecutionContext.getActionInputFileCache(),
+            context.getInputMapping(),
+            context.getTimeout(),
+            spawnResult);
+      } catch (IOException e) {
+        actionExecutionContext
+            .getEventHandler()
+            .handle(
+                Event.warn("Exception " + e + " while logging properties of " + spawn.toString()));
+      }
+    }
+    if (ex != null) {
+      throw ex;
     }
 
     if (spawnResult.status() != Status.SUCCESS) {
diff --git a/src/main/java/com/google/devtools/build/lib/exec/ExecutionOptions.java b/src/main/java/com/google/devtools/build/lib/exec/ExecutionOptions.java
index 8c7e2e1248..b7f1b340bf 100644
--- a/src/main/java/com/google/devtools/build/lib/exec/ExecutionOptions.java
+++ b/src/main/java/com/google/devtools/build/lib/exec/ExecutionOptions.java
@@ -275,6 +275,16 @@ public class ExecutionOptions extends OptionsBase {
   )
   public boolean enableCriticalPathProfiling;
 
+  @Option(
+    name = "experimental_execution_log_file",
+    defaultValue = "",
+    category = "verbosity",
+    documentationCategory = OptionDocumentationCategory.UNCATEGORIZED,
+    effectTags = {OptionEffectTag.UNKNOWN},
+    help = "Log the executed spawns into this file as delimited Spawn protos."
+  )
+  public String executionLogFile;
+
   /** Converter for the --flaky_test_attempts option. */
   public static class TestAttemptsConverter extends PerLabelOptions.PerLabelOptionsConverter {
     private static final int MIN_VALUE = 1;
diff --git a/src/main/java/com/google/devtools/build/lib/exec/SpawnLogContext.java b/src/main/java/com/google/devtools/build/lib/exec/SpawnLogContext.java
new file mode 100644
index 0000000000..c5952350bc
--- /dev/null
+++ b/src/main/java/com/google/devtools/build/lib/exec/SpawnLogContext.java
@@ -0,0 +1,254 @@
+// Copyright 2018 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.exec;
+
+import com.google.common.base.Preconditions;
+import com.google.common.hash.HashCode;
+import com.google.devtools.build.lib.actions.ActionContext;
+import com.google.devtools.build.lib.actions.ActionInput;
+import com.google.devtools.build.lib.actions.ExecutionStrategy;
+import com.google.devtools.build.lib.actions.MetadataProvider;
+import com.google.devtools.build.lib.actions.Spawn;
+import com.google.devtools.build.lib.actions.SpawnResult;
+import com.google.devtools.build.lib.actions.Spawns;
+import com.google.devtools.build.lib.actions.cache.Metadata;
+import com.google.devtools.build.lib.actions.cache.VirtualActionInput;
+import com.google.devtools.build.lib.analysis.platform.PlatformInfo;
+import com.google.devtools.build.lib.cmdline.Label;
+import com.google.devtools.build.lib.exec.Protos.Digest;
+import com.google.devtools.build.lib.exec.Protos.File;
+import com.google.devtools.build.lib.exec.Protos.Platform;
+import com.google.devtools.build.lib.exec.Protos.SpawnExec;
+import com.google.devtools.build.lib.util.io.MessageOutputStream;
+import com.google.devtools.build.lib.vfs.Dirent;
+import com.google.devtools.build.lib.vfs.FileSystem;
+import com.google.devtools.build.lib.vfs.Path;
+import com.google.devtools.build.lib.vfs.PathFragment;
+import com.google.devtools.build.lib.vfs.Symlinks;
+import com.google.protobuf.TextFormat;
+import com.google.protobuf.TextFormat.ParseException;
+import java.io.ByteArrayOutputStream;
+
+import java.io.IOException;
+import java.time.Duration;
+import java.util.ArrayList;
+import java.util.Collections;
+import java.util.Comparator;
+import java.util.List;
+import java.util.Map;
+import java.util.SortedMap;
+import java.util.TreeMap;
+import java.util.TreeSet;
+import java.util.function.Consumer;
+import java.util.logging.Level;
+import java.util.logging.Logger;
+import javax.annotation.Nullable;
+
+/**
+ * A logging utility for spawns.
+ */
+@ExecutionStrategy(
+    name = {"spawn-log"},
+    contextType = SpawnLogContext.class
+)
+public class SpawnLogContext implements ActionContext {
+
+  private static final Logger logger = Logger.getLogger(SpawnLogContext.class.getName());
+  private final Path execRoot;
+  private final MessageOutputStream executionLog;
+
+  public SpawnLogContext(Path execRoot, MessageOutputStream executionLog) {
+    this.execRoot = execRoot;
+    this.executionLog = executionLog;
+  }
+
+  /** Log the executed spawn to the output stream. */
+  public void logSpawn(
+      Spawn spawn,
+      MetadataProvider metadataProvider,
+      SortedMap<PathFragment, ActionInput> inputMap,
+      Duration timeout,
+      SpawnResult result)
+      throws IOException {
+    SortedMap<Path, ActionInput> existingOutputs = listExistingOutputs(spawn);
+    SpawnExec.Builder builder = SpawnExec.newBuilder();
+    builder.addAllCommandArgs(spawn.getArguments());
+
+    Map<String, String> env = spawn.getEnvironment();
+    // Sorting the environment pairs by variable name.
+    TreeSet<String> variables = new TreeSet<>(env.keySet());
+    for (String var : variables) {
+      builder.addEnvironmentVariablesBuilder().setName(var).setValue(env.get(var));
+    }
+
+    try {
+      for (Map.Entry<PathFragment, ActionInput> e : inputMap.entrySet()) {
+        ActionInput input = e.getValue();
+        Path inputPath = execRoot.getRelative(input.getExecPathString());
+        if (inputPath.isDirectory()) {
+          listDirectoryContents(inputPath, (file) -> builder.addInputs(file), metadataProvider);
+        } else {
+          Digest digest = computeDigest(input, null, metadataProvider);
+          builder.addInputsBuilder().setPath(input.getExecPathString()).setDigest(digest);
+        }
+      }
+    } catch (IOException e) {
+      logger.log(Level.WARNING, "Error computing spawn inputs", e);
+    }
+    ArrayList<String> outputPaths = new ArrayList<>();
+    for (ActionInput output : spawn.getOutputFiles()) {
+      outputPaths.add(output.getExecPathString());
+    }
+    Collections.sort(outputPaths);
+    builder.addAllListedOutputs(outputPaths);
+    for (Map.Entry<Path, ActionInput> e : existingOutputs.entrySet()) {
+      Path path = e.getKey();
+      if (path.isDirectory()) {
+        listDirectoryContents(path, (file) -> builder.addActualOutputs(file), metadataProvider);
+      } else {
+        File.Builder outputBuilder = builder.addActualOutputsBuilder();
+        outputBuilder.setPath(path.relativeTo(execRoot).toString());
+        try {
+          outputBuilder.setDigest(computeDigest(e.getValue(), path, metadataProvider));
+        } catch (IOException ex) {
+          logger.log(Level.WARNING, "Error computing spawn event output properties", ex);
+        }
+      }
+    }
+    builder.setRemotable(Spawns.mayBeExecutedRemotely(spawn));
+
+    PlatformInfo execPlatform = spawn.getExecutionPlatform();
+    if (execPlatform != null && execPlatform.remoteExecutionProperties() != null) {
+      builder.setPlatform(
+          buildPlatform(execPlatform.label(), execPlatform.remoteExecutionProperties()));
+    }
+    if (result.status() != SpawnResult.Status.SUCCESS) {
+      builder.setStatus(result.status().toString());
+    }
+    if (!timeout.isZero()) {
+      builder.setTimeoutMillis(timeout.toMillis());
+    }
+    builder.setCacheable(Spawns.mayBeCached(spawn));
+    builder.setExitCode(result.exitCode());
+    builder.setRemoteCacheHit(result.isCacheHit());
+    builder.setRunner(result.getRunnerName());
+    String progressMessage = spawn.getResourceOwner().getProgressMessage();
+    if (progressMessage != null) {
+      builder.setProgressMessage(progressMessage);
+    }
+    builder.setMnemonic(spawn.getMnemonic());
+    executionLog.write(builder.build());
+  }
+
+  public void close() throws IOException {
+    executionLog.close();
+  }
+
+  private static Platform buildPlatform(Label platformLabel, @Nullable String platformDescription) {
+    Platform.Builder platformBuilder = Platform.newBuilder();
+    try {
+      if (platformDescription != null) {
+        TextFormat.getParser().merge(platformDescription, platformBuilder);
+      }
+    } catch (ParseException e) {
+      throw new IllegalArgumentException(
+          String.format(
+              "Failed to parse remote_execution_properties from platform %s", platformLabel),
+          e);
+    }
+    return platformBuilder.build();
+  }
+
+  private SortedMap<Path, ActionInput> listExistingOutputs(Spawn spawn) {
+    TreeMap<Path, ActionInput> result = new TreeMap<>();
+    for (ActionInput output : spawn.getOutputFiles()) {
+      Path outputPath = execRoot.getRelative(output.getExecPathString());
+      // TODO(olaola): once symlink API proposal is implemented, report symlinks here.
+      if (outputPath.exists()) {
+        result.put(outputPath, output);
+      }
+    }
+    return result;
+  }
+
+  private void listDirectoryContents(
+      Path path, Consumer<File> addFile, MetadataProvider metadataProvider) {
+    try {
+      // TODO(olaola): once symlink API proposal is implemented, report symlinks here.
+      List<Dirent> sortedDirent = new ArrayList<>(path.readdir(Symlinks.NOFOLLOW));
+      sortedDirent.sort(Comparator.comparing(Dirent::getName));
+      for (Dirent dirent : sortedDirent) {
+        String name = dirent.getName();
+        Path child = path.getRelative(name);
+        if (dirent.getType() == Dirent.Type.DIRECTORY) {
+          listDirectoryContents(child, addFile, metadataProvider);
+        } else {
+          addFile.accept(
+              File.newBuilder()
+                  .setPath(child.relativeTo(execRoot).toString())
+                  .setDigest(computeDigest(null, child, metadataProvider))
+                  .build());
+        }
+      }
+    } catch (IOException e) {
+      logger.log(Level.WARNING, "Error computing spawn event file properties", e);
+    }
+  }
+
+  /**
+   * Computes the digest of the given ActionInput or corresponding path. Will try to access the
+   * Metadata cache first, if it is available, and fall back to digesting the contents manually.
+   */
+  private Digest computeDigest(
+      @Nullable ActionInput input, @Nullable Path path, MetadataProvider metadataProvider)
+      throws IOException {
+    Preconditions.checkArgument(input != null || path != null);
+    FileSystem.HashFunction hashFunction = execRoot.getFileSystem().getDigestFunction();
+    Digest.Builder digest = Digest.newBuilder().setHashFunctionName(hashFunction.toString());
+    if (input != null) {
+      if (input instanceof VirtualActionInput) {
+        ByteArrayOutputStream buffer = new ByteArrayOutputStream();
+        ((VirtualActionInput) input).writeTo(buffer);
+        byte[] blob = buffer.toByteArray();
+        return digest
+            .setHash(hashFunction.getHash().hashBytes(blob).toString())
+            .setSizeBytes(blob.length)
+            .build();
+      }
+      // Try to access the cached metadata, otherwise fall back to local computation.
+      try {
+        Metadata metadata = metadataProvider.getMetadata(input);
+        if (metadata != null) {
+          byte[] hash = metadata.getDigest();
+          if (hash != null) {
+            return digest
+                .setHash(HashCode.fromBytes(hash).toString())
+                .setSizeBytes(metadata.getSize())
+                .build();
+          }
+        }
+      } catch (IOException | IllegalStateException e) {
+        // Pass through to local computation.
+      }
+    }
+    if (path == null) {
+      path = execRoot.getRelative(input.getExecPath());
+    }
+    // Compute digest manually.
+    return digest
+        .setHash(HashCode.fromBytes(path.getDigest()).toString())
+        .setSizeBytes(path.getFileSize())
+        .build();
+  }
+}
diff --git a/src/main/java/com/google/devtools/build/lib/util/io/AsynchronousFileOutputStream.java b/src/main/java/com/google/devtools/build/lib/util/io/AsynchronousFileOutputStream.java
index 70284d08c9..531fe4ba21 100644
--- a/src/main/java/com/google/devtools/build/lib/util/io/AsynchronousFileOutputStream.java
+++ b/src/main/java/com/google/devtools/build/lib/util/io/AsynchronousFileOutputStream.java
@@ -45,7 +45,7 @@ import java.util.concurrent.atomic.AtomicReference;
  * close future.
  */
 @ThreadSafety.ThreadSafe
-public class AsynchronousFileOutputStream extends OutputStream {
+public class AsynchronousFileOutputStream extends OutputStream implements MessageOutputStream {
   private final AsynchronousFileChannel ch;
   private final WriteCompletionHandler completionHandler = new WriteCompletionHandler();
   // The offset in the file to begin the next write at.
@@ -83,6 +83,7 @@ public class AsynchronousFileOutputStream extends OutputStream {
    * multiple calls to write on the underlying stream, so we have to provide this method here
    * instead of the caller using it directly.
    */
+  @Override
   public void write(Message m) {
     Preconditions.checkNotNull(m);
     final int size = m.getSerializedSize();
diff --git a/src/main/java/com/google/devtools/build/lib/util/io/MessageOutputStream.java b/src/main/java/com/google/devtools/build/lib/util/io/MessageOutputStream.java
new file mode 100644
index 0000000000..56868cb45b
--- /dev/null
+++ b/src/main/java/com/google/devtools/build/lib/util/io/MessageOutputStream.java
@@ -0,0 +1,31 @@
+// Copyright 2018 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.util.io;
+
+import com.google.protobuf.Message;
+import java.io.IOException;
+
+/**
+ * A variation of OutputStream for protobuf messages.
+ */
+public interface MessageOutputStream {
+  /**
+   * Writes a delimited protocol buffer message in the same format as {@link
+   * MessageLite#writeDelimitedTo(java.io.OutputStream)}.
+   */
+  void write(Message m) throws IOException;
+
+  /** Closes the underlying stream, following writes will fail. */
+  void close() throws IOException;
+}