Make spawn id consistent in the debug log of dynamic execution.
Also removed rate-limited but unconditional logs that are not needed anymore.
PiperOrigin-RevId: 430695139
diff --git a/src/main/java/com/google/devtools/build/lib/dynamic/BUILD b/src/main/java/com/google/devtools/build/lib/dynamic/BUILD
index b781e21..e18c75c 100644
--- a/src/main/java/com/google/devtools/build/lib/dynamic/BUILD
+++ b/src/main/java/com/google/devtools/build/lib/dynamic/BUILD
@@ -17,6 +17,7 @@
"//src/main/java/com/google/devtools/build/lib:build-request-options",
"//src/main/java/com/google/devtools/build/lib:runtime",
"//src/main/java/com/google/devtools/build/lib/actions",
+ "//src/main/java/com/google/devtools/build/lib/actions:artifacts",
"//src/main/java/com/google/devtools/build/lib/actions:execution_requirements",
"//src/main/java/com/google/devtools/build/lib/concurrent",
"//src/main/java/com/google/devtools/build/lib/events",
diff --git a/src/main/java/com/google/devtools/build/lib/dynamic/DynamicSpawnStrategy.java b/src/main/java/com/google/devtools/build/lib/dynamic/DynamicSpawnStrategy.java
index accd03b..84706f9 100644
--- a/src/main/java/com/google/devtools/build/lib/dynamic/DynamicSpawnStrategy.java
+++ b/src/main/java/com/google/devtools/build/lib/dynamic/DynamicSpawnStrategy.java
@@ -25,6 +25,8 @@
import com.google.common.util.concurrent.MoreExecutors;
import com.google.devtools.build.lib.actions.ActionContext;
import com.google.devtools.build.lib.actions.ActionExecutionContext;
+import com.google.devtools.build.lib.actions.ActionExecutionMetadata;
+import com.google.devtools.build.lib.actions.Artifact;
import com.google.devtools.build.lib.actions.DynamicStrategyRegistry;
import com.google.devtools.build.lib.actions.DynamicStrategyRegistry.DynamicMode;
import com.google.devtools.build.lib.actions.EnvironmentalExecException;
@@ -52,7 +54,6 @@
import java.util.concurrent.CancellationException;
import java.util.concurrent.ExecutionException;
import java.util.concurrent.ExecutorService;
-import java.util.concurrent.TimeUnit;
import java.util.concurrent.atomic.AtomicBoolean;
import java.util.concurrent.atomic.AtomicReference;
import java.util.function.Function;
@@ -221,10 +222,7 @@
return nonDynamicResults;
}
- // Extra logging to debug b/194373457
- logger.atInfo().atMostEvery(1, TimeUnit.SECONDS).log(
- "Spawn %s dynamically executed both ways", spawn.getResourceOwner().describe());
- debugLog("Dynamic execution of %s beginning%n", spawn.getResourceOwner().prettyPrint());
+ debugLog("Dynamic execution of %s beginning%n", getSpawnReadableId(spawn));
// else both can exec. Fallthrough to below.
AtomicReference<DynamicMode> strategyThatCancelled = new AtomicReference<>(null);
@@ -265,14 +263,9 @@
tryScheduleLocalJob();
}
}
- logger.atInfo().atMostEvery(1, TimeUnit.SECONDS).log(
- "Dynamic execution of %s ended with local %s, remote %s%n",
- spawn.getResourceOwner().prettyPrint(),
- localBranch.isCancelled() ? "cancelled" : "done",
- remoteBranch.isCancelled() ? "cancelled" : "done");
debugLog(
"Dynamic execution of %s ended with local %s, remote %s%n",
- spawn.getResourceOwner().prettyPrint(),
+ getSpawnReadableId(spawn),
localBranch.isCancelled() ? "cancelled" : "done",
remoteBranch.isCancelled() ? "cancelled" : "done");
}
@@ -382,35 +375,21 @@
.build();
debugLog(
"Dynamic execution of %s can be done neither locally nor remotely%n",
- spawn.getResourceOwner().prettyPrint());
+ getSpawnReadableId(spawn));
throw new UserExecException(failure);
} else if (!localCanExec && remoteCanExec) {
- // Extra logging to debug b/194373457
- logger.atInfo().atMostEvery(1, TimeUnit.SECONDS).log(
- "Dynamic execution of %s can only be done remotely: Local execution policy %s it, "
- + "local strategies are %s.%n",
- spawn.getResourceOwner().prettyPrint(),
- executionPolicy.canRunLocally() ? "allows" : "forbids",
- dynamicStrategyRegistry.getDynamicSpawnActionContexts(spawn, DynamicMode.LOCAL));
debugLog(
"Dynamic execution of %s can only be done remotely: Local execution policy %s it, "
+ "local strategies are %s.%n",
- spawn.getResourceOwner().prettyPrint(),
+ getSpawnReadableId(spawn),
executionPolicy.canRunLocally() ? "allows" : "forbids",
dynamicStrategyRegistry.getDynamicSpawnActionContexts(spawn, DynamicMode.LOCAL));
return RemoteBranch.runRemotely(spawn, actionExecutionContext, null, delayLocalExecution);
} else if (localCanExec && !remoteCanExec) {
- // Extra logging to debug b/194373457
- logger.atInfo().atMostEvery(1, TimeUnit.SECONDS).log(
- "Dynamic execution of %s can only be done locally: Remote execution policy %s it, "
- + "remote strategies are %s.%n",
- spawn.getResourceOwner().prettyPrint(),
- executionPolicy.canRunRemotely() ? "allows" : "forbids",
- dynamicStrategyRegistry.getDynamicSpawnActionContexts(spawn, REMOTE));
debugLog(
"Dynamic execution of %s can only be done locally: Remote execution policy %s it, "
+ "remote strategies are %s.%n",
- spawn.getResourceOwner().prettyPrint(),
+ getSpawnReadableId(spawn),
executionPolicy.canRunRemotely() ? "allows" : "forbids",
dynamicStrategyRegistry.getDynamicSpawnActionContexts(spawn, REMOTE));
return LocalBranch.runLocally(
@@ -503,7 +482,7 @@
Event.info(
String.format(
"Cancelling remote branch of %s after local exception %s",
- spawn.getResourceOwner().prettyPrint(), e.getMessage())));
+ getSpawnReadableId(spawn), e.getMessage())));
}
remoteBranch.cancel();
throw e;
@@ -515,9 +494,7 @@
throw new AssertionError(
String.format(
"Neither branch of %s cancelled the other one. Local was %s and remote was %s.",
- spawn.getResourceOwner().getPrimaryOutput().prettyPrint(),
- localBranch.branchState(),
- remoteBranch.branchState()));
+ getSpawnReadableId(spawn), localBranch.branchState(), remoteBranch.branchState()));
} else if (localResult != null) {
return localResult;
} else if (remoteResult != null) {
@@ -528,9 +505,7 @@
throw new AssertionError(
String.format(
"Neither branch of %s completed. Local was %s and remote was %s.",
- spawn.getResourceOwner().getPrimaryOutput().prettyPrint(),
- localBranch.branchState(),
- remoteBranch.branchState()));
+ getSpawnReadableId(spawn), localBranch.branchState(), remoteBranch.branchState()));
}
}
@@ -558,9 +533,8 @@
.handle(
Event.info(
String.format(
- "Null results from %s branch of %s",
- mode,
- branch.getSpawn().getResourceOwner().getPrimaryOutput().prettyPrint())));
+ "Null results from %s branch of %s",
+ mode, getSpawnReadableId(branch.getSpawn()))));
}
return spawnResults;
} catch (CancellationException e) {
@@ -571,8 +545,7 @@
Event.info(
String.format(
"CancellationException of %s branch of %s, returning null",
- mode,
- branch.getSpawn().getResourceOwner().getPrimaryOutput().prettyPrint())));
+ mode, getSpawnReadableId(branch.getSpawn()))));
}
return null;
} catch (ExecutionException e) {
@@ -591,8 +564,7 @@
String.format(
"Caught InterruptedException from ExecException for %s branch of %s, which"
+ " may cause a crash.",
- mode,
- branch.getSpawn().getResourceOwner().getPrimaryOutput().prettyPrint())));
+ mode, getSpawnReadableId(branch.getSpawn()))));
return null;
} else {
// Even though we cannot enforce this in the future's signature (but we do in Branch#call),
@@ -661,9 +633,9 @@
.handle(
Event.info(
String.format(
- "%s action finished %sly and was %s",
- cancellingBranch.getSpawn().getMnemonic(),
+ "%s branch of %s finished and was %s",
strategyThatCancelled.get(),
+ getSpawnReadableId(cancellingBranch.getSpawn()),
cancellingBranch.isCancelled() ? "cancelled" : "not cancelled")));
}
@@ -712,4 +684,24 @@
public String toString() {
return "dynamic";
}
+
+ private static String getSpawnReadableId(Spawn spawn) {
+ ActionExecutionMetadata action = spawn.getResourceOwner();
+ if (action == null) {
+ return spawn.getMnemonic();
+ }
+
+ Artifact primaryOutput = action.getPrimaryOutput();
+ // In some cases, primary output could be null despite the method promises. And in that case, we
+ // can't use action.prettyPrint as it assumes a non-null primary output.
+ if (primaryOutput == null) {
+ String label = "";
+ if (action.getOwner() != null && action.getOwner().getLabel() != null) {
+ label = " " + action.getOwner().getLabel().toString();
+ }
+ return spawn.getMnemonic() + label;
+ }
+
+ return primaryOutput.prettyPrint();
+ }
}
diff --git a/src/test/java/com/google/devtools/build/lib/dynamic/BUILD b/src/test/java/com/google/devtools/build/lib/dynamic/BUILD
index da711eb8..3096db2 100644
--- a/src/test/java/com/google/devtools/build/lib/dynamic/BUILD
+++ b/src/test/java/com/google/devtools/build/lib/dynamic/BUILD
@@ -25,6 +25,7 @@
"//src/main/java/com/google/devtools/build/lib/vfs",
"//src/main/java/com/google/devtools/build/lib/vfs:pathfragment",
"//src/main/protobuf:failure_details_java_proto",
+ "//src/test/java/com/google/devtools/build/lib/actions/util",
"//src/test/java/com/google/devtools/build/lib/exec/util",
"//src/test/java/com/google/devtools/build/lib/testutil",
"//src/test/java/com/google/devtools/build/lib/testutil:TestUtils",
diff --git a/src/test/java/com/google/devtools/build/lib/dynamic/DynamicSpawnStrategyUnitTest.java b/src/test/java/com/google/devtools/build/lib/dynamic/DynamicSpawnStrategyUnitTest.java
index c76eddf..62063a4 100644
--- a/src/test/java/com/google/devtools/build/lib/dynamic/DynamicSpawnStrategyUnitTest.java
+++ b/src/test/java/com/google/devtools/build/lib/dynamic/DynamicSpawnStrategyUnitTest.java
@@ -29,6 +29,7 @@
import com.google.common.collect.ImmutableList;
import com.google.devtools.build.lib.actions.ActionExecutionContext;
+import com.google.devtools.build.lib.actions.Artifact;
import com.google.devtools.build.lib.actions.Artifact.SourceArtifact;
import com.google.devtools.build.lib.actions.ArtifactRoot;
import com.google.devtools.build.lib.actions.ArtifactRoot.RootType;
@@ -41,6 +42,7 @@
import com.google.devtools.build.lib.actions.SpawnResult;
import com.google.devtools.build.lib.actions.SpawnResult.Status;
import com.google.devtools.build.lib.actions.UserExecException;
+import com.google.devtools.build.lib.actions.util.ActionsTestUtil;
import com.google.devtools.build.lib.events.Event;
import com.google.devtools.build.lib.events.ExtendedEventHandler;
import com.google.devtools.build.lib.exec.ExecutionPolicy;
@@ -85,12 +87,24 @@
private Scratch scratch;
private Path execDir;
private ArtifactRoot rootDir;
+ private Artifact output1;
+ private Artifact output2;
@Before
public void initMocks() throws IOException {
scratch = new Scratch();
execDir = scratch.dir("/base/exec");
rootDir = ArtifactRoot.asDerivedRoot(execDir, RootType.Output, "root");
+ output1 =
+ Artifact.DerivedArtifact.create(
+ rootDir,
+ rootDir.getExecPath().getRelative("dir/output1.txt"),
+ ActionsTestUtil.NULL_ARTIFACT_OWNER);
+ output2 =
+ Artifact.DerivedArtifact.create(
+ rootDir,
+ rootDir.getExecPath().getRelative("dir/output2.txt"),
+ ActionsTestUtil.NULL_ARTIFACT_OWNER);
MockitoAnnotations.initMocks(this);
// Mockito can't see that we want the function to return Optional.empty() instead
// of null on apply by default (thanks generic type erasure). Set that up ourselves.
@@ -119,7 +133,7 @@
when(remote.exec(remoteSpawnCaptor.capture(), any(), any()))
.thenReturn(ImmutableList.of(SUCCESSFUL_SPAWN_RESULT));
ActionExecutionContext actionExecutionContext = createMockActionExecutionContext(local, remote);
- Spawn spawn = new SpawnBuilder().build();
+ Spawn spawn = new SpawnBuilder().withOwnerPrimaryOutput(output1).build();
ImmutableList<SpawnResult> results = dynamicSpawnStrategy.exec(spawn, actionExecutionContext);
@@ -131,7 +145,8 @@
@Test
public void exec_remoteOnlySpawn_noneCanExec_fails() throws Exception {
- Spawn spawn = new SpawnBuilder().withMnemonic("TheThing").build();
+ Spawn spawn =
+ new SpawnBuilder().withMnemonic("TheThing").withOwnerPrimaryOutput(output1).build();
DynamicSpawnStrategy dynamicSpawnStrategy =
createDynamicSpawnStrategy(
ExecutionPolicy.REMOTE_EXECUTION_ONLY, mockGetPostProcessingSpawn);
@@ -153,8 +168,9 @@
@Test
public void exec_localOnlySpawn_runsLocalPostProcessingSpawn() throws Exception {
- Spawn spawn = new SpawnBuilder("command").build();
- Spawn postProcessingSpawn = new SpawnBuilder("extra_command").build();
+ Spawn spawn = new SpawnBuilder("command").withOwnerPrimaryOutput(output1).build();
+ Spawn postProcessingSpawn =
+ new SpawnBuilder("extra_command").withOwnerPrimaryOutput(output2).build();
DynamicSpawnStrategy dynamicSpawnStrategy =
createDynamicSpawnStrategy(
ExecutionPolicy.LOCAL_EXECUTION_ONLY, ignored -> Optional.of(postProcessingSpawn));
@@ -187,7 +203,8 @@
@Test
public void exec_localOnlySpawn_noneCanExec_fails() throws Exception {
- Spawn spawn = new SpawnBuilder().withMnemonic("TheThing").build();
+ Spawn spawn =
+ new SpawnBuilder().withMnemonic("TheThing").withOwnerPrimaryOutput(output1).build();
DynamicSpawnStrategy dynamicSpawnStrategy =
createDynamicSpawnStrategy(
ExecutionPolicy.LOCAL_EXECUTION_ONLY, mockGetPostProcessingSpawn);
@@ -230,7 +247,7 @@
.thenReturn(ImmutableList.of(failedResult));
SandboxedSpawnStrategy remote = createMockSpawnStrategy();
ActionExecutionContext actionExecutionContext = createMockActionExecutionContext(local, remote);
- Spawn spawn = new SpawnBuilder().build();
+ Spawn spawn = new SpawnBuilder().withOwnerPrimaryOutput(output1).build();
ImmutableList<SpawnResult> results = dynamicSpawnStrategy.exec(spawn, actionExecutionContext);
@@ -241,8 +258,9 @@
@Test
public void exec_runAnywhereSpawn_runsLocalPostProcessingSpawn() throws Exception {
- Spawn spawn = new SpawnBuilder().build();
- Spawn postProcessingSpawn = new SpawnBuilder("extra_command").build();
+ Spawn spawn = new SpawnBuilder().withOwnerPrimaryOutput(output1).build();
+ Spawn postProcessingSpawn =
+ new SpawnBuilder("extra_command").withOwnerPrimaryOutput(output2).build();
DynamicSpawnStrategy dynamicSpawnStrategy =
createDynamicSpawnStrategy(
ExecutionPolicy.ANYWHERE, ignored -> Optional.of(postProcessingSpawn));
@@ -278,7 +296,7 @@
@Test
public void exec_runAnywhereSpawn_allowsIgnoringFailure() throws Exception {
- Spawn spawn = new SpawnBuilder().build();
+ Spawn spawn = new SpawnBuilder().withOwnerPrimaryOutput(output1).build();
checkState(
executorServiceForCleanup == null,
"Creating the DynamicSpawnStrategy twice in the same test is not supported.");
@@ -325,7 +343,7 @@
@Test
public void exec_runAnywhereSpawn_notAlwaysIgnoringFailure() throws Exception {
- Spawn spawn = new SpawnBuilder().build();
+ Spawn spawn = new SpawnBuilder().withOwnerPrimaryOutput(output1).build();
checkState(
executorServiceForCleanup == null,
"Creating the DynamicSpawnStrategy twice in the same test is not supported.");
@@ -372,7 +390,8 @@
@Test
public void exec_localOnlySpawn_skipFirst_isRun() throws Exception {
- Spawn spawn = new SpawnBuilder().withMnemonic("TheThing").build();
+ Spawn spawn =
+ new SpawnBuilder().withMnemonic("TheThing").withOwnerPrimaryOutput(output1).build();
DynamicExecutionOptions options = new DynamicExecutionOptions();
options.skipFirstBuild = true;
DynamicSpawnStrategy dynamicSpawnStrategy =
@@ -391,7 +410,8 @@
@Test
public void exec_runAnywhereSpawn_skipFirst_onlyRemote() throws Exception {
- Spawn spawn = new SpawnBuilder().withMnemonic("TheThing").build();
+ Spawn spawn =
+ new SpawnBuilder().withMnemonic("TheThing").withOwnerPrimaryOutput(output1).build();
DynamicExecutionOptions options = new DynamicExecutionOptions();
options.skipFirstBuild = true;
DynamicSpawnStrategy dynamicSpawnStrategy =
@@ -450,7 +470,7 @@
@Test
public void exec_runAnywhereSpawn_localCantExec_runsRemote() throws Exception {
- Spawn spawn = new SpawnBuilder().build();
+ Spawn spawn = new SpawnBuilder().withOwnerPrimaryOutput(output1).build();
DynamicSpawnStrategy dynamicSpawnStrategy =
createDynamicSpawnStrategy(ExecutionPolicy.ANYWHERE, mockGetPostProcessingSpawn);
SandboxedSpawnStrategy local = createMockSpawnStrategy(false);
@@ -476,8 +496,9 @@
@Test
public void exec_runAnywhereSpawn_remoteCantExec_runsLocal() throws Exception {
- Spawn spawn = new SpawnBuilder().build();
- Spawn postProcessingSpawn = new SpawnBuilder("extra_command").build();
+ Spawn spawn = new SpawnBuilder().withOwnerPrimaryOutput(output1).build();
+ Spawn postProcessingSpawn =
+ new SpawnBuilder("extra_command").withOwnerPrimaryOutput(output2).build();
DynamicSpawnStrategy dynamicSpawnStrategy =
createDynamicSpawnStrategy(
ExecutionPolicy.ANYWHERE, ignored -> Optional.of(postProcessingSpawn));
@@ -506,7 +527,8 @@
@Test
public void exec_runAnywhereSpawn_noneCanExec_fails() throws Exception {
- Spawn spawn = new SpawnBuilder().withMnemonic("TheThing").build();
+ Spawn spawn =
+ new SpawnBuilder().withMnemonic("TheThing").withOwnerPrimaryOutput(output1).build();
DynamicSpawnStrategy dynamicSpawnStrategy =
createDynamicSpawnStrategy(ExecutionPolicy.ANYWHERE, mockGetPostProcessingSpawn);
SandboxedSpawnStrategy local = createMockSpawnStrategy(false);
