1 /* 2 * Copyright (C) 2022 The Android Open Source Project 3 * 4 * Licensed under the Apache License, Version 2.0 (the "License"); 5 * you may not use this file except in compliance with the License. 6 * You may obtain a copy of the License at 7 * 8 * http://www.apache.org/licenses/LICENSE-2.0 9 * 10 * Unless required by applicable law or agreed to in writing, software 11 * distributed under the License is distributed on an "AS IS" BASIS, 12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 13 * See the License for the specific language governing permissions and 14 * limitations under the License. 15 */ 16 package com.android.tradefed.testtype.bazel; 17 18 import com.android.annotations.VisibleForTesting; 19 import com.android.tradefed.config.ConfigurationDescriptor; 20 import com.android.tradefed.config.Option; 21 import com.android.tradefed.config.OptionClass; 22 import com.android.tradefed.device.DeviceNotAvailableException; 23 import com.android.tradefed.invoker.IInvocationContext; 24 import com.android.tradefed.invoker.InvocationContext; 25 import com.android.tradefed.invoker.TestInformation; 26 import com.android.tradefed.invoker.logger.InvocationMetricLogger; 27 import com.android.tradefed.invoker.logger.InvocationMetricLogger.InvocationMetricKey; 28 import com.android.tradefed.invoker.tracing.CloseableTraceScope; 29 import com.android.tradefed.invoker.tracing.TracePropagatingExecutorService; 30 import com.android.tradefed.log.ITestLogger; 31 import com.android.tradefed.log.LogUtil.CLog; 32 import com.android.tradefed.result.FailureDescription; 33 import com.android.tradefed.result.FileInputStreamSource; 34 import com.android.tradefed.result.ITestInvocationListener; 35 import com.android.tradefed.result.LogDataType; 36 import com.android.tradefed.result.error.ErrorIdentifier; 37 import com.android.tradefed.result.error.TestErrorIdentifier; 38 import com.android.tradefed.result.proto.ProtoResultParser; 39 import com.android.tradefed.result.proto.TestRecordProto.FailureStatus; 40 import com.android.tradefed.result.proto.TestRecordProto.TestRecord; 41 import com.android.tradefed.testtype.IRemoteTest; 42 import com.android.tradefed.util.AbiUtils; 43 import com.android.tradefed.util.FileUtil; 44 import com.android.tradefed.util.ZipUtil; 45 import com.android.tradefed.util.proto.TestRecordProtoUtil; 46 47 import com.google.common.collect.BiMap; 48 import com.google.common.collect.HashBiMap; 49 import com.google.common.collect.HashMultimap; 50 import com.google.common.collect.ImmutableBiMap; 51 import com.google.common.collect.Maps; 52 import com.google.common.collect.SetMultimap; 53 import com.google.common.io.CharStreams; 54 import com.google.common.io.MoreFiles; 55 import com.google.common.io.Resources; 56 import com.google.devtools.build.lib.buildeventstream.BuildEventStreamProtos; 57 import com.google.protobuf.InvalidProtocolBufferException; 58 59 import java.io.File; 60 import java.io.FileWriter; 61 import java.io.IOException; 62 import java.io.FileOutputStream; 63 import java.lang.ProcessBuilder.Redirect; 64 import java.net.URI; 65 import java.net.URISyntaxException; 66 import java.nio.file.Files; 67 import java.nio.file.Path; 68 import java.nio.file.Paths; 69 import java.time.Duration; 70 import java.util.ArrayList; 71 import java.util.Collection; 72 import java.util.Collections; 73 import java.util.List; 74 import java.util.Map.Entry; 75 import java.util.Map; 76 import java.util.Properties; 77 import java.util.Set; 78 import java.util.concurrent.ExecutorService; 79 import java.util.concurrent.Executors; 80 import java.util.concurrent.TimeUnit; 81 import java.util.function.Consumer; 82 import java.util.stream.Collectors; 83 import java.util.stream.Stream; 84 import java.util.zip.ZipFile; 85 86 /** Test runner for executing Bazel tests. */ 87 @OptionClass(alias = "bazel-test") 88 public final class BazelTest implements IRemoteTest { 89 90 public static final String QUERY_ALL_TARGETS = "query_all_targets"; 91 public static final String QUERY_MAP_MODULES_TO_TARGETS = "query_map_modules_to_targets"; 92 public static final String RUN_TESTS = "run_tests"; 93 public static final String BUILD_TEST_ARG = "bazel-build"; 94 public static final String TEST_TAG_TEST_ARG = "bazel-test"; 95 public static final String BRANCH_TEST_ARG = "bazel-branch"; 96 public static final int BAZEL_TESTS_FAILED_RETURN_CODE = 3; 97 98 // Add method excludes to TF's global filters since Bazel doesn't support target-specific 99 // arguments. See https://github.com/bazelbuild/rules_go/issues/2784. 100 // TODO(b/274787592): Integrate with Bazel's test filtering to filter specific test cases. 101 public static final String GLOBAL_EXCLUDE_FILTER_TEMPLATE = 102 "--test_arg=--global-filters:exclude-filter=%s"; 103 104 private static final Duration BAZEL_QUERY_TIMEOUT = Duration.ofMinutes(5); 105 private static final String TEST_NAME = BazelTest.class.getName(); 106 // Bazel internally calls the test output archive file "test.outputs__outputs.zip", the double 107 // underscore is part of this name. 108 private static final String TEST_UNDECLARED_OUTPUTS_ARCHIVE_NAME = "test.outputs__outputs.zip"; 109 private static final String PROTO_RESULTS_FILE_NAME = "proto-results"; 110 111 private final List<Path> mTemporaryPaths = new ArrayList<>(); 112 private final List<LogFileWithType> mLogFiles = new ArrayList<>(); 113 private final Properties mProperties; 114 private final ProcessStarter mProcessStarter; 115 private final Path mTemporaryDirectory; 116 private final ExecutorService mExecutor; 117 118 private Path mRunTemporaryDirectory; 119 private Path mBazelOutputRoot; 120 private Path mJavaTempOutput; 121 122 private enum FilterType { 123 MODULE, 124 TEST_CASE 125 }; 126 127 @Option( 128 name = "bazel-test-command-timeout", 129 description = "Timeout for running the Bazel test.") 130 private Duration mBazelCommandTimeout = Duration.ofHours(1L); 131 132 @Option( 133 name = "bazel-test-suite-root-dir", 134 description = 135 "Name of the environment variable set by CtsTestLauncher indicating the" 136 + " location of the root bazel-test-suite dir.") 137 private String mSuiteRootDirEnvVar = "BAZEL_SUITE_ROOT"; 138 139 @Option( 140 name = "bazel-startup-options", 141 description = "List of startup options to be passed to Bazel.") 142 private final List<String> mBazelStartupOptions = new ArrayList<>(); 143 144 @Option( 145 name = "bazel-test-extra-args", 146 description = "List of extra arguments to be passed to Bazel") 147 private final List<String> mBazelTestExtraArgs = new ArrayList<>(); 148 149 @Option( 150 name = "bazel-max-idle-timout", 151 description = "Max idle timeout in seconds for bazel commands.") 152 private Duration mBazelMaxIdleTimeout = Duration.ofSeconds(30L); 153 154 @Option(name = "exclude-filter", description = "Test modules to exclude when running tests.") 155 private final List<String> mExcludeTargets = new ArrayList<>(); 156 157 @Option(name = "include-filter", description = "Test modules to include when running tests.") 158 private final List<String> mIncludeTargets = new ArrayList<>(); 159 160 @Option( 161 name = "bazel-query", 162 description = "Bazel query to return list of tests, defaults to all deviceless tests") 163 private String mBazelQuery = "kind(tradefed_deviceless_test, tests(//...))"; 164 165 @Option( 166 name = "report-cached-test-results", 167 description = "Whether or not to report cached test results.") 168 private boolean mReportCachedTestResults = true; 169 170 @Option( 171 name = "report-cached-modules-sparsely", 172 description = "Whether to only report module level events for cached test modules.") 173 private boolean mReportCachedModulesSparsely = false; 174 BazelTest()175 public BazelTest() { 176 this(new DefaultProcessStarter(), System.getProperties()); 177 } 178 179 @VisibleForTesting BazelTest(ProcessStarter processStarter, Properties properties)180 BazelTest(ProcessStarter processStarter, Properties properties) { 181 mProcessStarter = processStarter; 182 mExecutor = TracePropagatingExecutorService.create(Executors.newCachedThreadPool()); 183 mProperties = properties; 184 mTemporaryDirectory = Paths.get(properties.getProperty("java.io.tmpdir")); 185 } 186 187 @Override run(TestInformation testInfo, ITestInvocationListener listener)188 public void run(TestInformation testInfo, ITestInvocationListener listener) 189 throws DeviceNotAvailableException { 190 191 List<FailureDescription> runFailures = new ArrayList<>(); 192 long startTime = System.currentTimeMillis(); 193 RunStats stats = new RunStats(); 194 195 try { 196 initialize(); 197 logWorkspaceContents(); 198 runTestsAndParseResults(testInfo, listener, runFailures, stats); 199 } catch (AbortRunException e) { 200 runFailures.add(e.getFailureDescription()); 201 } catch (IOException | InterruptedException e) { 202 runFailures.add(throwableToTestFailureDescription(e)); 203 } 204 205 listener.testModuleStarted(testInfo.getContext()); 206 listener.testRunStarted(TEST_NAME, 0); 207 reportRunFailures(runFailures, listener); 208 listener.testRunEnded(System.currentTimeMillis() - startTime, Collections.emptyMap()); 209 listener.testModuleEnded(); 210 211 addTestLogs(listener); 212 stats.addInvocationAttributes(testInfo.getContext()); 213 cleanup(); 214 } 215 initialize()216 private void initialize() throws IOException { 217 mRunTemporaryDirectory = Files.createTempDirectory(mTemporaryDirectory, "bazel-test-"); 218 mBazelOutputRoot = createTemporaryDirectory("java-tmp-out"); 219 mJavaTempOutput = createTemporaryDirectory("bazel-tmp-out"); 220 } 221 logWorkspaceContents()222 private void logWorkspaceContents() throws IOException { 223 Path workspaceDirectory = resolveWorkspacePath(); 224 225 try (Stream<String> files = 226 Files.walk(workspaceDirectory) 227 .filter(Files::isRegularFile) 228 .map(x -> workspaceDirectory.relativize(x).toString())) { 229 230 Path outputFile = createLogFile("workspace-contents"); 231 try (FileWriter writer = new FileWriter(outputFile.toAbsolutePath().toString())) { 232 for (String file : (Iterable<String>) () -> files.iterator()) { 233 writer.write(file); 234 writer.write(System.lineSeparator()); 235 } 236 } 237 } 238 } 239 runTestsAndParseResults( TestInformation testInfo, ITestInvocationListener listener, List<FailureDescription> runFailures, RunStats stats)240 private void runTestsAndParseResults( 241 TestInformation testInfo, 242 ITestInvocationListener listener, 243 List<FailureDescription> runFailures, 244 RunStats stats) 245 throws IOException, InterruptedException { 246 247 Path workspaceDirectory = resolveWorkspacePath(); 248 249 BiMap<String, String> modulesToTargets = listTestModulesToTargets(workspaceDirectory); 250 if (modulesToTargets.isEmpty()) { 251 throw new AbortRunException( 252 "No targets found, aborting", 253 FailureStatus.DEPENDENCY_ISSUE, 254 TestErrorIdentifier.TEST_ABORTED); 255 } 256 257 Path bepFile = createTemporaryFile("BEP_output"); 258 259 Process bazelTestProcess = 260 startTests(testInfo, modulesToTargets.values(), workspaceDirectory, bepFile); 261 262 try (BepFileTailer tailer = BepFileTailer.create(bepFile)) { 263 bazelTestProcess.onExit().thenRun(() -> tailer.stop()); 264 reportTestResults(listener, testInfo, runFailures, tailer, stats, modulesToTargets); 265 } 266 267 // Note that if Bazel exits without writing the 'last' BEP message marker we won't get to 268 // here since the above reporting code throws. 269 int bazelTestExitCode = bazelTestProcess.waitFor(); 270 271 // TODO(b/296923373): If there is any parsing issue for a specific module consider reporting 272 // a generic module failure for that module. 273 if (bazelTestExitCode == BAZEL_TESTS_FAILED_RETURN_CODE) { 274 CLog.w("Bazel exited with exit code: %d, some tests failed.", bazelTestExitCode); 275 return; 276 } 277 278 if (bazelTestExitCode == 0) { 279 return; 280 } 281 282 throw new AbortRunException( 283 String.format("%s command failed. Exit code: %d", RUN_TESTS, bazelTestExitCode), 284 FailureStatus.DEPENDENCY_ISSUE, 285 TestErrorIdentifier.TEST_ABORTED); 286 } 287 reportTestResults( ITestInvocationListener listener, TestInformation testInfo, List<FailureDescription> runFailures, BepFileTailer tailer, RunStats stats, BiMap<String, String> modulesToTargets)288 void reportTestResults( 289 ITestInvocationListener listener, 290 TestInformation testInfo, 291 List<FailureDescription> runFailures, 292 BepFileTailer tailer, 293 RunStats stats, 294 BiMap<String, String> modulesToTargets) 295 throws InterruptedException, IOException { 296 297 try (CloseableTraceScope ignored = new CloseableTraceScope("reportTestResults")) { 298 reportTestResultsNoTrace( 299 listener, testInfo, runFailures, tailer, stats, modulesToTargets); 300 } 301 } 302 reportTestResultsNoTrace( ITestInvocationListener listener, TestInformation testInfo, List<FailureDescription> runFailures, BepFileTailer tailer, RunStats stats, BiMap<String, String> modulesToTargets)303 void reportTestResultsNoTrace( 304 ITestInvocationListener listener, 305 TestInformation testInfo, 306 List<FailureDescription> runFailures, 307 BepFileTailer tailer, 308 RunStats stats, 309 BiMap<String, String> modulesToTargets) 310 throws InterruptedException, IOException { 311 312 BuildEventStreamProtos.BuildEvent event; 313 while ((event = tailer.nextEvent()) != null) { 314 if (event.getLastMessage()) { 315 return; 316 } 317 318 if (!event.hasTestResult()) { 319 continue; 320 } 321 322 stats.addTestResult(event.getTestResult()); 323 324 if (!mReportCachedTestResults && isTestResultCached(event.getTestResult())) { 325 continue; 326 } 327 328 try { 329 reportEventsInTestOutputsArchive( 330 event, listener, testInfo.getContext(), modulesToTargets); 331 } catch (IOException 332 | InterruptedException 333 | URISyntaxException 334 | IllegalArgumentException e) { 335 runFailures.add( 336 throwableToInfraFailureDescription(e) 337 .setErrorIdentifier(TestErrorIdentifier.OUTPUT_PARSER_ERROR)); 338 } 339 } 340 341 throw new AbortRunException( 342 "Unexpectedly hit end of BEP file without receiving last message", 343 FailureStatus.INFRA_FAILURE, 344 TestErrorIdentifier.OUTPUT_PARSER_ERROR); 345 } 346 isTestResultCached(BuildEventStreamProtos.TestResult result)347 private static boolean isTestResultCached(BuildEventStreamProtos.TestResult result) { 348 return result.getCachedLocally() || result.getExecutionInfo().getCachedRemotely(); 349 } 350 createBazelCommand(Path workspaceDirectory, String tmpDirPrefix)351 private ProcessBuilder createBazelCommand(Path workspaceDirectory, String tmpDirPrefix) 352 throws IOException { 353 354 List<String> command = new ArrayList<>(); 355 356 command.add(workspaceDirectory.resolve("bazel.sh").toAbsolutePath().toString()); 357 command.add( 358 "--host_jvm_args=-Djava.io.tmpdir=%s" 359 .formatted(mJavaTempOutput.toAbsolutePath().toString())); 360 command.add( 361 "--output_user_root=%s".formatted(mBazelOutputRoot.toAbsolutePath().toString())); 362 command.add("--max_idle_secs=%d".formatted(mBazelMaxIdleTimeout.toSeconds())); 363 364 ProcessBuilder builder = new ProcessBuilder(command); 365 366 builder.directory(workspaceDirectory.toFile()); 367 368 return builder; 369 } 370 listTestModulesToTargets(Path workspaceDirectory)371 private BiMap<String, String> listTestModulesToTargets(Path workspaceDirectory) 372 throws IOException, InterruptedException { 373 374 try (CloseableTraceScope ignored = new CloseableTraceScope("listTestModulesToTargets")) { 375 return listTestModulesToTargetsNoTrace(workspaceDirectory); 376 } 377 } 378 listTestModulesToTargetsNoTrace(Path workspaceDirectory)379 private BiMap<String, String> listTestModulesToTargetsNoTrace(Path workspaceDirectory) 380 throws IOException, InterruptedException { 381 382 // We need to query all tests targets first in a separate Bazel query call since 'cquery 383 // tests(...)' doesn't work in the Atest Bazel workspace. 384 List<String> allTestTargets = queryAllTestTargets(workspaceDirectory); 385 CLog.i("Found %d test targets in workspace", allTestTargets.size()); 386 387 BiMap<String, String> moduleToTarget = 388 queryModulesToTestTargets(workspaceDirectory, allTestTargets); 389 390 Set<String> moduleExcludes = groupTargetsByType(mExcludeTargets).get(FilterType.MODULE); 391 Set<String> moduleIncludes = groupTargetsByType(mIncludeTargets).get(FilterType.MODULE); 392 393 if (!moduleIncludes.isEmpty() && !moduleExcludes.isEmpty()) { 394 throw new AbortRunException( 395 "Invalid options: cannot set both module-level include filters and module-level" 396 + " exclude filters.", 397 FailureStatus.DEPENDENCY_ISSUE, 398 TestErrorIdentifier.TEST_ABORTED); 399 } 400 401 if (!moduleIncludes.isEmpty()) { 402 return Maps.filterKeys(moduleToTarget, s -> moduleIncludes.contains(s)); 403 } 404 405 if (!moduleExcludes.isEmpty()) { 406 return Maps.filterKeys(moduleToTarget, s -> !moduleExcludes.contains(s)); 407 } 408 409 return moduleToTarget; 410 } 411 queryAllTestTargets(Path workspaceDirectory)412 private List<String> queryAllTestTargets(Path workspaceDirectory) 413 throws IOException, InterruptedException { 414 415 Path logFile = createLogFile("%s-log".formatted(QUERY_ALL_TARGETS)); 416 417 ProcessBuilder builder = createBazelCommand(workspaceDirectory, QUERY_ALL_TARGETS); 418 419 builder.command().add("query"); 420 builder.command().add(mBazelQuery); 421 422 builder.redirectError(Redirect.appendTo(logFile.toFile())); 423 424 Process queryProcess = startProcess(QUERY_ALL_TARGETS, builder, BAZEL_QUERY_TIMEOUT); 425 List<String> queryLines = readProcessLines(queryProcess); 426 427 waitForSuccessfulProcess(queryProcess, QUERY_ALL_TARGETS); 428 429 return queryLines; 430 } 431 queryModulesToTestTargets( Path workspaceDirectory, List<String> allTestTargets)432 private BiMap<String, String> queryModulesToTestTargets( 433 Path workspaceDirectory, List<String> allTestTargets) 434 throws IOException, InterruptedException { 435 436 Path cqueryTestTargetsFile = createTemporaryFile("test_targets"); 437 Files.write(cqueryTestTargetsFile, String.join("+", allTestTargets).getBytes()); 438 439 Path cqueryFormatFile = createTemporaryFile("format_module_name_to_test_target"); 440 try (FileOutputStream os = new FileOutputStream(cqueryFormatFile.toFile())) { 441 Resources.copy( 442 Resources.getResource("config/format_module_name_to_test_target.cquery"), os); 443 } 444 445 Path logFile = createLogFile("%s-log".formatted(QUERY_MAP_MODULES_TO_TARGETS)); 446 ProcessBuilder builder = 447 createBazelCommand(workspaceDirectory, QUERY_MAP_MODULES_TO_TARGETS); 448 449 builder.command().add("cquery"); 450 builder.command().add("--query_file=%s".formatted(cqueryTestTargetsFile.toAbsolutePath())); 451 builder.command().add("--output=starlark"); 452 builder.command().add("--starlark:file=%s".formatted(cqueryFormatFile.toAbsolutePath())); 453 builder.redirectError(Redirect.appendTo(logFile.toFile())); 454 455 Process process = startProcess(QUERY_MAP_MODULES_TO_TARGETS, builder, BAZEL_QUERY_TIMEOUT); 456 457 List<String> queryLines = readProcessLines(process); 458 459 waitForSuccessfulProcess(process, QUERY_MAP_MODULES_TO_TARGETS); 460 461 return parseModulesToTargets(queryLines); 462 } 463 readProcessLines(Process process)464 private List<String> readProcessLines(Process process) throws IOException { 465 return CharStreams.readLines(process.inputReader()); 466 } 467 parseModulesToTargets(Collection<String> lines)468 private BiMap<String, String> parseModulesToTargets(Collection<String> lines) { 469 BiMap<String, String> moduleToTarget = HashBiMap.create(lines.size()); 470 StringBuilder errorMessage = new StringBuilder(); 471 for (String line : lines) { 472 // Query output format is: "module_name //bazel/test:target" if a test target is a 473 // TF test, "" otherwise, so only count proper targets. 474 if (line.isEmpty()) { 475 continue; 476 } 477 478 String[] splitLine = line.split(" "); 479 480 if (splitLine.length != 2) { 481 throw new AbortRunException( 482 String.format( 483 "Unrecognized output from %s command: %s", 484 QUERY_MAP_MODULES_TO_TARGETS, line), 485 FailureStatus.DEPENDENCY_ISSUE, 486 TestErrorIdentifier.TEST_ABORTED); 487 } 488 489 String moduleName = splitLine[0]; 490 String targetName = splitLine[1]; 491 492 String duplicateEntry; 493 if ((duplicateEntry = moduleToTarget.get(moduleName)) != null) { 494 errorMessage.append( 495 "Multiple test targets found for module %s: %s, %s\n" 496 .formatted(moduleName, duplicateEntry, targetName)); 497 continue; 498 } 499 500 moduleToTarget.put(moduleName, targetName); 501 } 502 503 if (errorMessage.length() != 0) { 504 throw new AbortRunException( 505 errorMessage.toString(), 506 FailureStatus.DEPENDENCY_ISSUE, 507 TestErrorIdentifier.TEST_ABORTED); 508 } 509 return ImmutableBiMap.copyOf(moduleToTarget); 510 } 511 startTests( TestInformation testInfo, Collection<String> testTargets, Path workspaceDirectory, Path bepFile)512 private Process startTests( 513 TestInformation testInfo, 514 Collection<String> testTargets, 515 Path workspaceDirectory, 516 Path bepFile) 517 throws IOException { 518 519 Path logFile = createLogFile("%s-log".formatted(RUN_TESTS)); 520 Path bazelTraceFile = createLogFile("bazel-trace", ".perfetto-trace", LogDataType.PERFETTO); 521 522 ProcessBuilder builder = createBazelCommand(workspaceDirectory, RUN_TESTS); 523 524 builder.command().addAll(mBazelStartupOptions); 525 builder.command().add("test"); 526 builder.command().addAll(testTargets); 527 528 builder.command().add("--build_event_binary_file=%s".formatted(bepFile.toAbsolutePath())); 529 530 builder.command().add("--generate_json_trace_profile"); 531 builder.command().add("--profile=%s".formatted(bazelTraceFile.toAbsolutePath().toString())); 532 533 builder.command().add("--test_arg=--test-tag=%s".formatted(TEST_TAG_TEST_ARG)); 534 builder.command().add("--test_arg=--build-id=%s".formatted(BUILD_TEST_ARG)); 535 builder.command().add("--test_arg=--branch=%s".formatted(BRANCH_TEST_ARG)); 536 537 builder.command().addAll(mBazelTestExtraArgs); 538 539 Set<String> testFilters = groupTargetsByType(mExcludeTargets).get(FilterType.TEST_CASE); 540 for (String test : testFilters) { 541 builder.command().add(GLOBAL_EXCLUDE_FILTER_TEMPLATE.formatted(test)); 542 } 543 builder.redirectErrorStream(true); 544 builder.redirectOutput(Redirect.appendTo(logFile.toFile())); 545 546 return startProcess(RUN_TESTS, builder, mBazelCommandTimeout); 547 } 548 groupTargetsByType(List<String> targets)549 private static SetMultimap<FilterType, String> groupTargetsByType(List<String> targets) { 550 Map<FilterType, List<String>> groupedMap = 551 targets.stream() 552 .collect( 553 Collectors.groupingBy( 554 s -> 555 s.contains(" ") 556 ? FilterType.TEST_CASE 557 : FilterType.MODULE)); 558 559 SetMultimap<FilterType, String> groupedMultiMap = HashMultimap.create(); 560 for (Entry<FilterType, List<String>> entry : groupedMap.entrySet()) { 561 groupedMultiMap.putAll(entry.getKey(), entry.getValue()); 562 } 563 564 return groupedMultiMap; 565 } 566 startAndWaitForSuccessfulProcess( String processTag, ProcessBuilder builder, Duration processTimeout)567 private Process startAndWaitForSuccessfulProcess( 568 String processTag, ProcessBuilder builder, Duration processTimeout) 569 throws InterruptedException, IOException { 570 571 Process process = startProcess(processTag, builder, processTimeout); 572 waitForSuccessfulProcess(process, processTag); 573 return process; 574 } 575 startProcess(String processTag, ProcessBuilder builder, Duration timeout)576 private Process startProcess(String processTag, ProcessBuilder builder, Duration timeout) 577 throws IOException { 578 579 CLog.i("Running command for %s: %s", processTag, new ProcessDebugString(builder)); 580 String traceTag = "Process:" + processTag; 581 Process process = mProcessStarter.start(processTag, builder); 582 583 // We wait for the process in a separate thread so that we can trace its execution time. 584 // Another alternative could be to start/stop tracing with explicit calls but these would 585 // have to be done on the same thread as required by the tracing facility. 586 mExecutor.submit( 587 () -> { 588 try (CloseableTraceScope unused = new CloseableTraceScope(traceTag)) { 589 if (waitForProcessUninterruptibly(process, timeout)) { 590 return; 591 } 592 593 CLog.e("%s command timed out and is being destroyed", processTag); 594 process.destroy(); 595 596 // Give the process a grace period to properly shut down before forcibly 597 // terminating it. We _could_ deduct this time from the total timeout but 598 // it's overkill. 599 if (!waitForProcessUninterruptibly(process, Duration.ofSeconds(5))) { 600 CLog.w( 601 "%s command did not terminate normally after the grace period" 602 + " and is being forcibly destroyed", 603 processTag); 604 process.destroyForcibly(); 605 } 606 607 // We wait for the process as it may take it some time to terminate and 608 // otherwise skew the trace results. 609 waitForProcessUninterruptibly(process); 610 CLog.i("%s command timed out and was destroyed", processTag); 611 } 612 }); 613 614 return process; 615 } 616 waitForSuccessfulProcess(Process process, String processTag)617 private void waitForSuccessfulProcess(Process process, String processTag) 618 throws InterruptedException { 619 620 if (process.waitFor() == 0) { 621 return; 622 } 623 624 throw new AbortRunException( 625 String.format("%s command failed. Exit code: %d", processTag, process.exitValue()), 626 FailureStatus.DEPENDENCY_ISSUE, 627 TestErrorIdentifier.TEST_ABORTED); 628 } 629 reportEventsInTestOutputsArchive( BuildEventStreamProtos.BuildEvent event, ITestInvocationListener listener, IInvocationContext context, BiMap<String, String> modulesToTargets)630 private void reportEventsInTestOutputsArchive( 631 BuildEventStreamProtos.BuildEvent event, 632 ITestInvocationListener listener, 633 IInvocationContext context, 634 BiMap<String, String> modulesToTargets) 635 throws IOException, InvalidProtocolBufferException, InterruptedException, 636 URISyntaxException { 637 638 try (CloseableTraceScope ignored = 639 new CloseableTraceScope("reportEventsInTestOutputsArchive")) { 640 reportEventsInTestOutputsArchiveNoTrace(event, listener, context, modulesToTargets); 641 } 642 } 643 reportEventsInTestOutputsArchiveNoTrace( BuildEventStreamProtos.BuildEvent event, ITestInvocationListener listener, IInvocationContext context, BiMap<String, String> modulesToTargets)644 private void reportEventsInTestOutputsArchiveNoTrace( 645 BuildEventStreamProtos.BuildEvent event, 646 ITestInvocationListener listener, 647 IInvocationContext context, 648 BiMap<String, String> modulesToTargets) 649 throws IOException, InvalidProtocolBufferException, InterruptedException, 650 URISyntaxException { 651 652 BuildEventStreamProtos.TestResult result = event.getTestResult(); 653 BuildEventStreamProtos.File outputsFile = 654 result.getTestActionOutputList().stream() 655 .filter(file -> file.getName().equals(TEST_UNDECLARED_OUTPUTS_ARCHIVE_NAME)) 656 .findAny() 657 .orElseThrow(() -> new IOException("No test output archive found")); 658 659 URI uri = new URI(outputsFile.getUri()); 660 661 File zipFile = new File(uri.getPath()); 662 Path outputFilesDir = Files.createTempDirectory(mRunTemporaryDirectory, "output_zip-"); 663 Path delimiter = Paths.get(BRANCH_TEST_ARG, BUILD_TEST_ARG, TEST_TAG_TEST_ARG); 664 listener = new LogPathUpdatingListener(listener, delimiter, outputFilesDir); 665 666 try { 667 String filePrefix = "tf-test-process-"; 668 ZipUtil.extractZip(new ZipFile(zipFile), outputFilesDir.toFile()); 669 670 // Test timed out, report as failure and upload any test output found for debugging 671 if (result.getStatus() == BuildEventStreamProtos.TestStatus.TIMEOUT) { 672 reportTimedOutTestResults(event, outputFilesDir, modulesToTargets, listener); 673 return; 674 } 675 676 File protoResult = outputFilesDir.resolve(PROTO_RESULTS_FILE_NAME).toFile(); 677 TestRecord record = TestRecordProtoUtil.readFromFile(protoResult); 678 679 if (mReportCachedModulesSparsely && isTestResultCached(result)) { 680 listener = new SparseTestListener(listener); 681 } 682 683 // Tradefed does not report the invocation trace to the proto result file so we have to 684 // explicitly re-add it here. 685 List<Consumer<ITestInvocationListener>> extraLogCalls = new ArrayList<>(); 686 extraLogCalls.addAll(collectInvocationLogCalls(context, record, filePrefix)); 687 extraLogCalls.addAll(collectTraceFileLogCalls(outputFilesDir, filePrefix)); 688 689 BazelTestListener bazelListener = 690 new BazelTestListener(listener, extraLogCalls, isTestResultCached(result)); 691 parseResultsToListener(bazelListener, context, record, filePrefix); 692 } finally { 693 FileUtil.recursiveDelete(outputFilesDir.toFile()); 694 } 695 } 696 reportTimedOutTestResults( BuildEventStreamProtos.BuildEvent event, Path outputFilesDir, BiMap<String, String> modulesToTargets, ITestInvocationListener listener)697 private static void reportTimedOutTestResults( 698 BuildEventStreamProtos.BuildEvent event, 699 Path outputFilesDir, 700 BiMap<String, String> modulesToTargets, 701 ITestInvocationListener listener) 702 throws IOException { 703 String label = event.getId().getTestResult().getLabel(); 704 String module = modulesToTargets.inverse().get("@" + label); 705 706 IInvocationContext moduleContext = new InvocationContext(); 707 String abi = AbiUtils.getHostAbi().iterator().next(); 708 moduleContext.addInvocationAttribute("module-id", abi + " " + module); 709 moduleContext.addInvocationAttribute("module-abi", abi); 710 moduleContext.addInvocationAttribute("module-name", module); 711 ConfigurationDescriptor descriptor = new ConfigurationDescriptor(); 712 descriptor.addMetadata("module-name", module); 713 descriptor.setModuleName(module); 714 moduleContext.setConfigurationDescriptor(descriptor); 715 716 listener.testModuleStarted(moduleContext); 717 listener.testRunStarted(module, 0); 718 listener.testRunFailed( 719 FailureDescription.create( 720 "Test timed out, results cannot be processed, but any outputs" 721 + " generated will be uploaded.", 722 FailureStatus.TIMED_OUT) 723 .setErrorIdentifier(TestErrorIdentifier.TEST_BINARY_TIMED_OUT)); 724 listener.testRunEnded(0L, Collections.emptyMap()); 725 uploadTestModuleOutputs(listener, outputFilesDir, module); 726 listener.testModuleEnded(); 727 } 728 uploadTestModuleOutputs( ITestInvocationListener listener, Path outputFilesDir, String module)729 private static void uploadTestModuleOutputs( 730 ITestInvocationListener listener, Path outputFilesDir, String module) 731 throws IOException { 732 try (Stream<Path> testOutputs = 733 Files.walk(outputFilesDir).filter(x -> Files.isRegularFile(x))) { 734 testOutputs.forEach( 735 testOutput -> { 736 try (FileInputStreamSource source = 737 new FileInputStreamSource(testOutput.toFile())) { 738 listener.testLog( 739 module + "-" + testOutput.getFileName().toString(), 740 LogDataType.TEXT, 741 source); 742 } 743 }); 744 } 745 } 746 collectInvocationLogCalls( IInvocationContext context, TestRecord record, String filePrefix)747 private static List<Consumer<ITestInvocationListener>> collectInvocationLogCalls( 748 IInvocationContext context, TestRecord record, String filePrefix) { 749 750 InvocationLogCollector logCollector = new InvocationLogCollector(); 751 parseResultsToListener(logCollector, context, record, filePrefix); 752 return logCollector.getLogCalls(); 753 } 754 parseResultsToListener( ITestInvocationListener listener, IInvocationContext context, TestRecord record, String filePrefix)755 private static void parseResultsToListener( 756 ITestInvocationListener listener, 757 IInvocationContext context, 758 TestRecord record, 759 String filePrefix) { 760 761 ProtoResultParser parser = new ProtoResultParser(listener, context, false, filePrefix); 762 // Avoid merging serialized invocation attributes into the current invocation context. 763 // Not doing so adds misleading information on the top-level invocation 764 // such as bad timing data. See b/284294864. 765 parser.setMergeInvocationContext(false); 766 parser.processFinalizedProto(record); 767 } 768 collectTraceFileLogCalls( Path outputFilesDir, String filePrefix)769 private static List<Consumer<ITestInvocationListener>> collectTraceFileLogCalls( 770 Path outputFilesDir, String filePrefix) throws IOException { 771 772 List<Consumer<ITestInvocationListener>> logCalls = new ArrayList<>(); 773 774 try (Stream<Path> traceFiles = 775 Files.walk(outputFilesDir) 776 .filter(x -> MoreFiles.getFileExtension(x).equals("perfetto-trace"))) { 777 778 traceFiles.forEach( 779 traceFile -> { 780 logCalls.add( 781 (ITestInvocationListener l) -> { 782 l.testLog( 783 filePrefix + traceFile.getFileName().toString(), 784 // We don't mark this file as a PERFETTO log to 785 // avoid having its contents automatically merged in 786 // the top-level invocation's trace. The merge 787 // process is wonky and makes the resulting trace 788 // difficult to read. 789 // TODO(b/284328869): Switch to PERFETTO log type 790 // once traces are properly merged. 791 LogDataType.TEXT, 792 new FileInputStreamSource(traceFile.toFile())); 793 }); 794 }); 795 } 796 return logCalls; 797 } 798 reportRunFailures( List<FailureDescription> runFailures, ITestInvocationListener listener)799 private void reportRunFailures( 800 List<FailureDescription> runFailures, ITestInvocationListener listener) { 801 802 if (runFailures.isEmpty()) { 803 return; 804 } 805 806 for (FailureDescription runFailure : runFailures) { 807 CLog.e(runFailure.getErrorMessage()); 808 } 809 810 FailureDescription reportedFailure = runFailures.get(0); 811 listener.testRunFailed( 812 FailureDescription.create( 813 String.format( 814 "The run had %d failures, the first of which was: %s\n" 815 + "See the subprocess-host_log for more details.", 816 runFailures.size(), reportedFailure.getErrorMessage()), 817 reportedFailure.getFailureStatus()) 818 .setErrorIdentifier(reportedFailure.getErrorIdentifier())); 819 } 820 resolveWorkspacePath()821 private Path resolveWorkspacePath() { 822 String suiteRootPath = mProperties.getProperty(mSuiteRootDirEnvVar); 823 if (suiteRootPath == null || suiteRootPath.isEmpty()) { 824 throw new AbortRunException( 825 "Bazel Test Suite root directory not set, aborting", 826 FailureStatus.DEPENDENCY_ISSUE, 827 TestErrorIdentifier.TEST_ABORTED); 828 } 829 830 // TODO(b/233885171): Remove resolve once workspace archive is updated. 831 return Paths.get(suiteRootPath).resolve("android-bazel-suite/out/atest_bazel_workspace"); 832 } 833 addTestLogs(ITestLogger logger)834 private void addTestLogs(ITestLogger logger) { 835 for (LogFileWithType logFile : mLogFiles) { 836 try (FileInputStreamSource source = 837 new FileInputStreamSource(logFile.getPath().toFile(), true)) { 838 logger.testLog(logFile.getPath().toFile().getName(), logFile.getType(), source); 839 } 840 } 841 } 842 cleanup()843 private void cleanup() { 844 FileUtil.recursiveDelete(mRunTemporaryDirectory.toFile()); 845 } 846 847 interface ProcessStarter { start(String processTag, ProcessBuilder builder)848 Process start(String processTag, ProcessBuilder builder) throws IOException; 849 } 850 851 private static final class DefaultProcessStarter implements ProcessStarter { 852 @Override start(String processTag, ProcessBuilder builder)853 public Process start(String processTag, ProcessBuilder builder) throws IOException { 854 return builder.start(); 855 } 856 } 857 createTemporaryDirectory(String prefix)858 private Path createTemporaryDirectory(String prefix) throws IOException { 859 return Files.createTempDirectory(mRunTemporaryDirectory, prefix); 860 } 861 createTemporaryFile(String prefix)862 private Path createTemporaryFile(String prefix) throws IOException { 863 return Files.createTempFile(mRunTemporaryDirectory, prefix, ""); 864 } 865 createLogFile(String name)866 private Path createLogFile(String name) throws IOException { 867 return createLogFile(name, ".txt", LogDataType.TEXT); 868 } 869 createLogFile(String name, String extension, LogDataType type)870 private Path createLogFile(String name, String extension, LogDataType type) throws IOException { 871 Path logPath = Files.createTempFile(mRunTemporaryDirectory, name, extension); 872 873 mLogFiles.add(new LogFileWithType(logPath, type)); 874 875 return logPath; 876 } 877 throwableToTestFailureDescription(Throwable t)878 private static FailureDescription throwableToTestFailureDescription(Throwable t) { 879 return FailureDescription.create(t.getMessage()) 880 .setCause(t) 881 .setFailureStatus(FailureStatus.TEST_FAILURE); 882 } 883 throwableToInfraFailureDescription(Exception e)884 private static FailureDescription throwableToInfraFailureDescription(Exception e) { 885 return FailureDescription.create(e.getMessage()) 886 .setCause(e) 887 .setFailureStatus(FailureStatus.INFRA_FAILURE); 888 } 889 waitForProcessUninterruptibly(Process process, Duration timeout)890 private static boolean waitForProcessUninterruptibly(Process process, Duration timeout) { 891 long remainingNanos = timeout.toNanos(); 892 long end = System.nanoTime() + remainingNanos; 893 boolean interrupted = false; 894 895 try { 896 while (true) { 897 try { 898 return process.waitFor(remainingNanos, TimeUnit.NANOSECONDS); 899 } catch (InterruptedException e) { 900 interrupted = true; 901 remainingNanos = end - System.nanoTime(); 902 } 903 } 904 } finally { 905 if (interrupted) { 906 Thread.currentThread().interrupt(); 907 } 908 } 909 } 910 waitForProcessUninterruptibly(Process process)911 private static int waitForProcessUninterruptibly(Process process) { 912 boolean interrupted = false; 913 914 try { 915 while (true) { 916 try { 917 return process.waitFor(); 918 } catch (InterruptedException e) { 919 interrupted = true; 920 } 921 } 922 } finally { 923 if (interrupted) { 924 Thread.currentThread().interrupt(); 925 } 926 } 927 } 928 929 private static final class AbortRunException extends RuntimeException { 930 private final FailureDescription mFailureDescription; 931 AbortRunException( String errorMessage, FailureStatus failureStatus, ErrorIdentifier errorIdentifier)932 public AbortRunException( 933 String errorMessage, FailureStatus failureStatus, ErrorIdentifier errorIdentifier) { 934 this( 935 FailureDescription.create(errorMessage, failureStatus) 936 .setErrorIdentifier(errorIdentifier)); 937 } 938 AbortRunException(FailureDescription failureDescription)939 public AbortRunException(FailureDescription failureDescription) { 940 super(failureDescription.getErrorMessage()); 941 mFailureDescription = failureDescription; 942 } 943 getFailureDescription()944 public FailureDescription getFailureDescription() { 945 return mFailureDescription; 946 } 947 } 948 949 private static final class ProcessDebugString { 950 951 private final ProcessBuilder mBuilder; 952 ProcessDebugString(ProcessBuilder builder)953 ProcessDebugString(ProcessBuilder builder) { 954 mBuilder = builder; 955 } 956 toString()957 public String toString() { 958 return String.join(" ", mBuilder.command()); 959 } 960 } 961 962 private static final class LogFileWithType { 963 private final Path mPath; 964 private final LogDataType mType; 965 LogFileWithType(Path path, LogDataType type)966 public LogFileWithType(Path path, LogDataType type) { 967 mPath = path; 968 mType = type; 969 } 970 getPath()971 public Path getPath() { 972 return mPath; 973 } 974 getType()975 public LogDataType getType() { 976 return mType; 977 } 978 } 979 980 private static final class RunStats { 981 982 private int mCachedTestResults; 983 addTestResult(BuildEventStreamProtos.TestResult e)984 void addTestResult(BuildEventStreamProtos.TestResult e) { 985 if (isTestResultCached(e)) { 986 mCachedTestResults++; 987 } 988 } 989 addInvocationAttributes(IInvocationContext context)990 void addInvocationAttributes(IInvocationContext context) { 991 InvocationMetricLogger.addInvocationMetrics( 992 InvocationMetricKey.CACHED_MODULE_RESULTS_COUNT, 993 Integer.toString(mCachedTestResults)); 994 } 995 } 996 } 997