Skip to content

Commit bfe0b9c

Browse files
coeuvrecopybara-github
coeuvre
authored and
copybara-github
committed
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
1 parent 46a8e09 commit bfe0b9c

File tree

4 files changed

+76
-60
lines changed

4 files changed

+76
-60
lines changed

‎src/main/java/com/google/devtools/build/lib/dynamic/BUILD

+1
Original file line numberDiff line numberDiff line change
@@ -17,6 +17,7 @@ java_library(
1717
"//src/main/java/com/google/devtools/build/lib:build-request-options",
1818
"//src/main/java/com/google/devtools/build/lib:runtime",
1919
"//src/main/java/com/google/devtools/build/lib/actions",
20+
"//src/main/java/com/google/devtools/build/lib/actions:artifacts",
2021
"//src/main/java/com/google/devtools/build/lib/actions:execution_requirements",
2122
"//src/main/java/com/google/devtools/build/lib/concurrent",
2223
"//src/main/java/com/google/devtools/build/lib/events",

‎src/main/java/com/google/devtools/build/lib/dynamic/DynamicSpawnStrategy.java

+36-44
Original file line numberDiff line numberDiff line change
@@ -25,6 +25,8 @@
2525
import com.google.common.util.concurrent.MoreExecutors;
2626
import com.google.devtools.build.lib.actions.ActionContext;
2727
import com.google.devtools.build.lib.actions.ActionExecutionContext;
28+
import com.google.devtools.build.lib.actions.ActionExecutionMetadata;
29+
import com.google.devtools.build.lib.actions.Artifact;
2830
import com.google.devtools.build.lib.actions.DynamicStrategyRegistry;
2931
import com.google.devtools.build.lib.actions.DynamicStrategyRegistry.DynamicMode;
3032
import com.google.devtools.build.lib.actions.EnvironmentalExecException;
@@ -52,7 +54,6 @@
5254
import java.util.concurrent.CancellationException;
5355
import java.util.concurrent.ExecutionException;
5456
import java.util.concurrent.ExecutorService;
55-
import java.util.concurrent.TimeUnit;
5657
import java.util.concurrent.atomic.AtomicBoolean;
5758
import java.util.concurrent.atomic.AtomicReference;
5859
import java.util.function.Function;
@@ -221,10 +222,7 @@ public ImmutableList<SpawnResult> exec(
221222
return nonDynamicResults;
222223
}
223224

224-
// Extra logging to debug b/194373457
225-
logger.atInfo().atMostEvery(1, TimeUnit.SECONDS).log(
226-
"Spawn %s dynamically executed both ways", spawn.getResourceOwner().describe());
227-
debugLog("Dynamic execution of %s beginning%n", spawn.getResourceOwner().prettyPrint());
225+
debugLog("Dynamic execution of %s beginning%n", getSpawnReadableId(spawn));
228226
// else both can exec. Fallthrough to below.
229227

230228
AtomicReference<DynamicMode> strategyThatCancelled = new AtomicReference<>(null);
@@ -265,14 +263,9 @@ public ImmutableList<SpawnResult> exec(
265263
tryScheduleLocalJob();
266264
}
267265
}
268-
logger.atInfo().atMostEvery(1, TimeUnit.SECONDS).log(
269-
"Dynamic execution of %s ended with local %s, remote %s%n",
270-
spawn.getResourceOwner().prettyPrint(),
271-
localBranch.isCancelled() ? "cancelled" : "done",
272-
remoteBranch.isCancelled() ? "cancelled" : "done");
273266
debugLog(
274267
"Dynamic execution of %s ended with local %s, remote %s%n",
275-
spawn.getResourceOwner().prettyPrint(),
268+
getSpawnReadableId(spawn),
276269
localBranch.isCancelled() ? "cancelled" : "done",
277270
remoteBranch.isCancelled() ? "cancelled" : "done");
278271
}
@@ -382,35 +375,21 @@ private ImmutableList<SpawnResult> maybeExecuteNonDynamically(
382375
.build();
383376
debugLog(
384377
"Dynamic execution of %s can be done neither locally nor remotely%n",
385-
spawn.getResourceOwner().prettyPrint());
378+
getSpawnReadableId(spawn));
386379
throw new UserExecException(failure);
387380
} else if (!localCanExec && remoteCanExec) {
388-
// Extra logging to debug b/194373457
389-
logger.atInfo().atMostEvery(1, TimeUnit.SECONDS).log(
390-
"Dynamic execution of %s can only be done remotely: Local execution policy %s it, "
391-
+ "local strategies are %s.%n",
392-
spawn.getResourceOwner().prettyPrint(),
393-
executionPolicy.canRunLocally() ? "allows" : "forbids",
394-
dynamicStrategyRegistry.getDynamicSpawnActionContexts(spawn, DynamicMode.LOCAL));
395381
debugLog(
396382
"Dynamic execution of %s can only be done remotely: Local execution policy %s it, "
397383
+ "local strategies are %s.%n",
398-
spawn.getResourceOwner().prettyPrint(),
384+
getSpawnReadableId(spawn),
399385
executionPolicy.canRunLocally() ? "allows" : "forbids",
400386
dynamicStrategyRegistry.getDynamicSpawnActionContexts(spawn, DynamicMode.LOCAL));
401387
return RemoteBranch.runRemotely(spawn, actionExecutionContext, null, delayLocalExecution);
402388
} else if (localCanExec && !remoteCanExec) {
403-
// Extra logging to debug b/194373457
404-
logger.atInfo().atMostEvery(1, TimeUnit.SECONDS).log(
405-
"Dynamic execution of %s can only be done locally: Remote execution policy %s it, "
406-
+ "remote strategies are %s.%n",
407-
spawn.getResourceOwner().prettyPrint(),
408-
executionPolicy.canRunRemotely() ? "allows" : "forbids",
409-
dynamicStrategyRegistry.getDynamicSpawnActionContexts(spawn, REMOTE));
410389
debugLog(
411390
"Dynamic execution of %s can only be done locally: Remote execution policy %s it, "
412391
+ "remote strategies are %s.%n",
413-
spawn.getResourceOwner().prettyPrint(),
392+
getSpawnReadableId(spawn),
414393
executionPolicy.canRunRemotely() ? "allows" : "forbids",
415394
dynamicStrategyRegistry.getDynamicSpawnActionContexts(spawn, REMOTE));
416395
return LocalBranch.runLocally(
@@ -503,7 +482,7 @@ static ImmutableList<SpawnResult> waitBranches(
503482
Event.info(
504483
String.format(
505484
"Cancelling remote branch of %s after local exception %s",
506-
spawn.getResourceOwner().prettyPrint(), e.getMessage())));
485+
getSpawnReadableId(spawn), e.getMessage())));
507486
}
508487
remoteBranch.cancel();
509488
throw e;
@@ -515,9 +494,7 @@ static ImmutableList<SpawnResult> waitBranches(
515494
throw new AssertionError(
516495
String.format(
517496
"Neither branch of %s cancelled the other one. Local was %s and remote was %s.",
518-
spawn.getResourceOwner().getPrimaryOutput().prettyPrint(),
519-
localBranch.branchState(),
520-
remoteBranch.branchState()));
497+
getSpawnReadableId(spawn), localBranch.branchState(), remoteBranch.branchState()));
521498
} else if (localResult != null) {
522499
return localResult;
523500
} else if (remoteResult != null) {
@@ -528,9 +505,7 @@ static ImmutableList<SpawnResult> waitBranches(
528505
throw new AssertionError(
529506
String.format(
530507
"Neither branch of %s completed. Local was %s and remote was %s.",
531-
spawn.getResourceOwner().getPrimaryOutput().prettyPrint(),
532-
localBranch.branchState(),
533-
remoteBranch.branchState()));
508+
getSpawnReadableId(spawn), localBranch.branchState(), remoteBranch.branchState()));
534509
}
535510
}
536511

@@ -558,9 +533,8 @@ private static ImmutableList<SpawnResult> waitBranch(
558533
.handle(
559534
Event.info(
560535
String.format(
561-
"Null results from %s branch of %s",
562-
mode,
563-
branch.getSpawn().getResourceOwner().getPrimaryOutput().prettyPrint())));
536+
"Null results from %s branch of %s",
537+
mode, getSpawnReadableId(branch.getSpawn()))));
564538
}
565539
return spawnResults;
566540
} catch (CancellationException e) {
@@ -571,8 +545,7 @@ private static ImmutableList<SpawnResult> waitBranch(
571545
Event.info(
572546
String.format(
573547
"CancellationException of %s branch of %s, returning null",
574-
mode,
575-
branch.getSpawn().getResourceOwner().getPrimaryOutput().prettyPrint())));
548+
mode, getSpawnReadableId(branch.getSpawn()))));
576549
}
577550
return null;
578551
} catch (ExecutionException e) {
@@ -591,8 +564,7 @@ private static ImmutableList<SpawnResult> waitBranch(
591564
String.format(
592565
"Caught InterruptedException from ExecException for %s branch of %s, which"
593566
+ " may cause a crash.",
594-
mode,
595-
branch.getSpawn().getResourceOwner().getPrimaryOutput().prettyPrint())));
567+
mode, getSpawnReadableId(branch.getSpawn()))));
596568
return null;
597569
} else {
598570
// Even though we cannot enforce this in the future's signature (but we do in Branch#call),
@@ -661,9 +633,9 @@ static void stopBranch(
661633
.handle(
662634
Event.info(
663635
String.format(
664-
"%s action finished %sly and was %s",
665-
cancellingBranch.getSpawn().getMnemonic(),
636+
"%s branch of %s finished and was %s",
666637
strategyThatCancelled.get(),
638+
getSpawnReadableId(cancellingBranch.getSpawn()),
667639
cancellingBranch.isCancelled() ? "cancelled" : "not cancelled")));
668640
}
669641

@@ -712,4 +684,24 @@ public void usedContext(ActionContext.ActionContextRegistry actionContextRegistr
712684
public String toString() {
713685
return "dynamic";
714686
}
687+
688+
private static String getSpawnReadableId(Spawn spawn) {
689+
ActionExecutionMetadata action = spawn.getResourceOwner();
690+
if (action == null) {
691+
return spawn.getMnemonic();
692+
}
693+
694+
Artifact primaryOutput = action.getPrimaryOutput();
695+
// In some cases, primary output could be null despite the method promises. And in that case, we
696+
// can't use action.prettyPrint as it assumes a non-null primary output.
697+
if (primaryOutput == null) {
698+
String label = "";
699+
if (action.getOwner() != null && action.getOwner().getLabel() != null) {
700+
label = " " + action.getOwner().getLabel().toString();
701+
}
702+
return spawn.getMnemonic() + label;
703+
}
704+
705+
return primaryOutput.prettyPrint();
706+
}
715707
}

‎src/test/java/com/google/devtools/build/lib/dynamic/BUILD

+1
Original file line numberDiff line numberDiff line change
@@ -25,6 +25,7 @@ java_test(
2525
"//src/main/java/com/google/devtools/build/lib/vfs",
2626
"//src/main/java/com/google/devtools/build/lib/vfs:pathfragment",
2727
"//src/main/protobuf:failure_details_java_proto",
28+
"//src/test/java/com/google/devtools/build/lib/actions/util",
2829
"//src/test/java/com/google/devtools/build/lib/exec/util",
2930
"//src/test/java/com/google/devtools/build/lib/testutil",
3031
"//src/test/java/com/google/devtools/build/lib/testutil:TestUtils",

‎src/test/java/com/google/devtools/build/lib/dynamic/DynamicSpawnStrategyUnitTest.java

+38-16
Original file line numberDiff line numberDiff line change
@@ -29,6 +29,7 @@
2929

3030
import com.google.common.collect.ImmutableList;
3131
import com.google.devtools.build.lib.actions.ActionExecutionContext;
32+
import com.google.devtools.build.lib.actions.Artifact;
3233
import com.google.devtools.build.lib.actions.Artifact.SourceArtifact;
3334
import com.google.devtools.build.lib.actions.ArtifactRoot;
3435
import com.google.devtools.build.lib.actions.ArtifactRoot.RootType;
@@ -41,6 +42,7 @@
4142
import com.google.devtools.build.lib.actions.SpawnResult;
4243
import com.google.devtools.build.lib.actions.SpawnResult.Status;
4344
import com.google.devtools.build.lib.actions.UserExecException;
45+
import com.google.devtools.build.lib.actions.util.ActionsTestUtil;
4446
import com.google.devtools.build.lib.events.Event;
4547
import com.google.devtools.build.lib.events.ExtendedEventHandler;
4648
import com.google.devtools.build.lib.exec.ExecutionPolicy;
@@ -85,12 +87,24 @@ public class DynamicSpawnStrategyUnitTest {
8587
private Scratch scratch;
8688
private Path execDir;
8789
private ArtifactRoot rootDir;
90+
private Artifact output1;
91+
private Artifact output2;
8892

8993
@Before
9094
public void initMocks() throws IOException {
9195
scratch = new Scratch();
9296
execDir = scratch.dir("/base/exec");
9397
rootDir = ArtifactRoot.asDerivedRoot(execDir, RootType.Output, "root");
98+
output1 =
99+
Artifact.DerivedArtifact.create(
100+
rootDir,
101+
rootDir.getExecPath().getRelative("dir/output1.txt"),
102+
ActionsTestUtil.NULL_ARTIFACT_OWNER);
103+
output2 =
104+
Artifact.DerivedArtifact.create(
105+
rootDir,
106+
rootDir.getExecPath().getRelative("dir/output2.txt"),
107+
ActionsTestUtil.NULL_ARTIFACT_OWNER);
94108
MockitoAnnotations.initMocks(this);
95109
// Mockito can't see that we want the function to return Optional.empty() instead
96110
// of null on apply by default (thanks generic type erasure). Set that up ourselves.
@@ -119,7 +133,7 @@ public void exec_remoteOnlySpawn_doesNotExecLocalPostProcessingSpawn() throws Ex
119133
when(remote.exec(remoteSpawnCaptor.capture(), any(), any()))
120134
.thenReturn(ImmutableList.of(SUCCESSFUL_SPAWN_RESULT));
121135
ActionExecutionContext actionExecutionContext = createMockActionExecutionContext(local, remote);
122-
Spawn spawn = new SpawnBuilder().build();
136+
Spawn spawn = new SpawnBuilder().withOwnerPrimaryOutput(output1).build();
123137

124138
ImmutableList<SpawnResult> results = dynamicSpawnStrategy.exec(spawn, actionExecutionContext);
125139

@@ -131,7 +145,8 @@ public void exec_remoteOnlySpawn_doesNotExecLocalPostProcessingSpawn() throws Ex
131145

132146
@Test
133147
public void exec_remoteOnlySpawn_noneCanExec_fails() throws Exception {
134-
Spawn spawn = new SpawnBuilder().withMnemonic("TheThing").build();
148+
Spawn spawn =
149+
new SpawnBuilder().withMnemonic("TheThing").withOwnerPrimaryOutput(output1).build();
135150
DynamicSpawnStrategy dynamicSpawnStrategy =
136151
createDynamicSpawnStrategy(
137152
ExecutionPolicy.REMOTE_EXECUTION_ONLY, mockGetPostProcessingSpawn);
@@ -153,8 +168,9 @@ public void exec_remoteOnlySpawn_noneCanExec_fails() throws Exception {
153168

154169
@Test
155170
public void exec_localOnlySpawn_runsLocalPostProcessingSpawn() throws Exception {
156-
Spawn spawn = new SpawnBuilder("command").build();
157-
Spawn postProcessingSpawn = new SpawnBuilder("extra_command").build();
171+
Spawn spawn = new SpawnBuilder("command").withOwnerPrimaryOutput(output1).build();
172+
Spawn postProcessingSpawn =
173+
new SpawnBuilder("extra_command").withOwnerPrimaryOutput(output2).build();
158174
DynamicSpawnStrategy dynamicSpawnStrategy =
159175
createDynamicSpawnStrategy(
160176
ExecutionPolicy.LOCAL_EXECUTION_ONLY, ignored -> Optional.of(postProcessingSpawn));
@@ -187,7 +203,8 @@ public void exec_failedLocalSpawn_doesNotExecLocalPostProcessingSpawn() throws E
187203

188204
@Test
189205
public void exec_localOnlySpawn_noneCanExec_fails() throws Exception {
190-
Spawn spawn = new SpawnBuilder().withMnemonic("TheThing").build();
206+
Spawn spawn =
207+
new SpawnBuilder().withMnemonic("TheThing").withOwnerPrimaryOutput(output1).build();
191208
DynamicSpawnStrategy dynamicSpawnStrategy =
192209
createDynamicSpawnStrategy(
193210
ExecutionPolicy.LOCAL_EXECUTION_ONLY, mockGetPostProcessingSpawn);
@@ -230,7 +247,7 @@ private void testExecFailedLocalSpawnDoesNotExecLocalPostProcessingSpawn(SpawnRe
230247
.thenReturn(ImmutableList.of(failedResult));
231248
SandboxedSpawnStrategy remote = createMockSpawnStrategy();
232249
ActionExecutionContext actionExecutionContext = createMockActionExecutionContext(local, remote);
233-
Spawn spawn = new SpawnBuilder().build();
250+
Spawn spawn = new SpawnBuilder().withOwnerPrimaryOutput(output1).build();
234251

235252
ImmutableList<SpawnResult> results = dynamicSpawnStrategy.exec(spawn, actionExecutionContext);
236253

@@ -241,8 +258,9 @@ private void testExecFailedLocalSpawnDoesNotExecLocalPostProcessingSpawn(SpawnRe
241258

242259
@Test
243260
public void exec_runAnywhereSpawn_runsLocalPostProcessingSpawn() throws Exception {
244-
Spawn spawn = new SpawnBuilder().build();
245-
Spawn postProcessingSpawn = new SpawnBuilder("extra_command").build();
261+
Spawn spawn = new SpawnBuilder().withOwnerPrimaryOutput(output1).build();
262+
Spawn postProcessingSpawn =
263+
new SpawnBuilder("extra_command").withOwnerPrimaryOutput(output2).build();
246264
DynamicSpawnStrategy dynamicSpawnStrategy =
247265
createDynamicSpawnStrategy(
248266
ExecutionPolicy.ANYWHERE, ignored -> Optional.of(postProcessingSpawn));
@@ -278,7 +296,7 @@ public void exec_runAnywhereSpawn_runsLocalPostProcessingSpawn() throws Exceptio
278296

279297
@Test
280298
public void exec_runAnywhereSpawn_allowsIgnoringFailure() throws Exception {
281-
Spawn spawn = new SpawnBuilder().build();
299+
Spawn spawn = new SpawnBuilder().withOwnerPrimaryOutput(output1).build();
282300
checkState(
283301
executorServiceForCleanup == null,
284302
"Creating the DynamicSpawnStrategy twice in the same test is not supported.");
@@ -325,7 +343,7 @@ public void exec_runAnywhereSpawn_allowsIgnoringFailure() throws Exception {
325343

326344
@Test
327345
public void exec_runAnywhereSpawn_notAlwaysIgnoringFailure() throws Exception {
328-
Spawn spawn = new SpawnBuilder().build();
346+
Spawn spawn = new SpawnBuilder().withOwnerPrimaryOutput(output1).build();
329347
checkState(
330348
executorServiceForCleanup == null,
331349
"Creating the DynamicSpawnStrategy twice in the same test is not supported.");
@@ -372,7 +390,8 @@ public void exec_runAnywhereSpawn_notAlwaysIgnoringFailure() throws Exception {
372390

373391
@Test
374392
public void exec_localOnlySpawn_skipFirst_isRun() throws Exception {
375-
Spawn spawn = new SpawnBuilder().withMnemonic("TheThing").build();
393+
Spawn spawn =
394+
new SpawnBuilder().withMnemonic("TheThing").withOwnerPrimaryOutput(output1).build();
376395
DynamicExecutionOptions options = new DynamicExecutionOptions();
377396
options.skipFirstBuild = true;
378397
DynamicSpawnStrategy dynamicSpawnStrategy =
@@ -391,7 +410,8 @@ public void exec_localOnlySpawn_skipFirst_isRun() throws Exception {
391410

392411
@Test
393412
public void exec_runAnywhereSpawn_skipFirst_onlyRemote() throws Exception {
394-
Spawn spawn = new SpawnBuilder().withMnemonic("TheThing").build();
413+
Spawn spawn =
414+
new SpawnBuilder().withMnemonic("TheThing").withOwnerPrimaryOutput(output1).build();
395415
DynamicExecutionOptions options = new DynamicExecutionOptions();
396416
options.skipFirstBuild = true;
397417
DynamicSpawnStrategy dynamicSpawnStrategy =
@@ -450,7 +470,7 @@ public void waitBranches_givesDebugOutputIfBothCancelled() throws Exception {
450470

451471
@Test
452472
public void exec_runAnywhereSpawn_localCantExec_runsRemote() throws Exception {
453-
Spawn spawn = new SpawnBuilder().build();
473+
Spawn spawn = new SpawnBuilder().withOwnerPrimaryOutput(output1).build();
454474
DynamicSpawnStrategy dynamicSpawnStrategy =
455475
createDynamicSpawnStrategy(ExecutionPolicy.ANYWHERE, mockGetPostProcessingSpawn);
456476
SandboxedSpawnStrategy local = createMockSpawnStrategy(false);
@@ -476,8 +496,9 @@ public void exec_runAnywhereSpawn_localCantExec_runsRemote() throws Exception {
476496

477497
@Test
478498
public void exec_runAnywhereSpawn_remoteCantExec_runsLocal() throws Exception {
479-
Spawn spawn = new SpawnBuilder().build();
480-
Spawn postProcessingSpawn = new SpawnBuilder("extra_command").build();
499+
Spawn spawn = new SpawnBuilder().withOwnerPrimaryOutput(output1).build();
500+
Spawn postProcessingSpawn =
501+
new SpawnBuilder("extra_command").withOwnerPrimaryOutput(output2).build();
481502
DynamicSpawnStrategy dynamicSpawnStrategy =
482503
createDynamicSpawnStrategy(
483504
ExecutionPolicy.ANYWHERE, ignored -> Optional.of(postProcessingSpawn));
@@ -506,7 +527,8 @@ public void exec_runAnywhereSpawn_remoteCantExec_runsLocal() throws Exception {
506527

507528
@Test
508529
public void exec_runAnywhereSpawn_noneCanExec_fails() throws Exception {
509-
Spawn spawn = new SpawnBuilder().withMnemonic("TheThing").build();
530+
Spawn spawn =
531+
new SpawnBuilder().withMnemonic("TheThing").withOwnerPrimaryOutput(output1).build();
510532
DynamicSpawnStrategy dynamicSpawnStrategy =
511533
createDynamicSpawnStrategy(ExecutionPolicy.ANYWHERE, mockGetPostProcessingSpawn);
512534
SandboxedSpawnStrategy local = createMockSpawnStrategy(false);

0 commit comments

Comments
 (0)