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);