1 /* 2 * Copyright (C) 2018 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.result.proto; 17 18 import com.android.tradefed.build.IBuildInfo; 19 import com.android.tradefed.invoker.IInvocationContext; 20 import com.android.tradefed.invoker.InvocationContext; 21 import com.android.tradefed.invoker.logger.InvocationMetricLogger; 22 import com.android.tradefed.invoker.logger.InvocationMetricLogger.InvocationGroupMetricKey; 23 import com.android.tradefed.invoker.logger.InvocationMetricLogger.InvocationMetricKey; 24 import com.android.tradefed.invoker.logger.TfObjectTracker; 25 import com.android.tradefed.invoker.proto.InvocationContext.Context; 26 import com.android.tradefed.invoker.tracing.ActiveTrace; 27 import com.android.tradefed.invoker.tracing.TracingLogger; 28 import com.android.tradefed.log.LogUtil.CLog; 29 import com.android.tradefed.metrics.proto.MetricMeasurement.Metric; 30 import com.android.tradefed.result.ActionInProgress; 31 import com.android.tradefed.result.FailureDescription; 32 import com.android.tradefed.result.FileInputStreamSource; 33 import com.android.tradefed.result.ILogSaverListener; 34 import com.android.tradefed.result.ITestInvocationListener; 35 import com.android.tradefed.result.InputStreamSource; 36 import com.android.tradefed.result.LogDataType; 37 import com.android.tradefed.result.LogFile; 38 import com.android.tradefed.result.TestDescription; 39 import com.android.tradefed.result.error.ErrorIdentifier; 40 import com.android.tradefed.result.error.InfraErrorIdentifier; 41 import com.android.tradefed.result.proto.LogFileProto.LogFileInfo; 42 import com.android.tradefed.result.proto.TestRecordProto.ChildReference; 43 import com.android.tradefed.result.proto.TestRecordProto.DebugInfo; 44 import com.android.tradefed.result.proto.TestRecordProto.DebugInfoContext; 45 import com.android.tradefed.result.proto.TestRecordProto.FailureStatus; 46 import com.android.tradefed.result.proto.TestRecordProto.SkipReason; 47 import com.android.tradefed.result.proto.TestRecordProto.TestRecord; 48 import com.android.tradefed.testtype.suite.ModuleDefinition; 49 import com.android.tradefed.util.FileUtil; 50 import com.android.tradefed.util.MultiMap; 51 import com.android.tradefed.util.SerializationUtil; 52 import com.android.tradefed.util.proto.TestRecordProtoUtil; 53 54 import com.google.common.base.Splitter; 55 import com.google.common.base.Strings; 56 import com.google.protobuf.Any; 57 import com.google.protobuf.InvalidProtocolBufferException; 58 import com.google.protobuf.Timestamp; 59 60 import java.io.File; 61 import java.io.IOException; 62 import java.lang.reflect.InvocationTargetException; 63 import java.lang.reflect.Method; 64 import java.util.HashMap; 65 import java.util.HashSet; 66 import java.util.List; 67 import java.util.Map.Entry; 68 import java.util.Set; 69 70 import javax.annotation.Nonnull; 71 72 /** Parser for the Tradefed results proto format. */ 73 public class ProtoResultParser { 74 75 private ITestInvocationListener mListener; 76 private String mCurrentRunName = null; 77 private TestDescription mCurrentTestCase = null; 78 /** 79 * We don't always want to report the invocation level events again. If we are within an 80 * invocation scope we should not report it again. 81 */ 82 private boolean mReportInvocation = false; 83 /** In some cases we do not need to forward the logs. */ 84 private boolean mReportLogs = true; 85 /** Prefix that will be added to the files logged through the parser. */ 86 private String mFilePrefix; 87 /** The context from the invocation in progress, not the proto one. */ 88 private IInvocationContext mMainContext; 89 90 private boolean mQuietParsing = true; 91 private boolean mSkipParsingAccounting = false; 92 93 private boolean mInvocationStarted = false; 94 /** Track whether or not invocationFailed was called. */ 95 private boolean mInvocationFailed = false; 96 97 private boolean mInvocationEnded = false; 98 private boolean mFirstModule = true; 99 /** Track the name of the module in progress. */ 100 private String mModuleInProgress = null; 101 102 private IInvocationContext mModuleContext = null; 103 104 private boolean mMergeInvocationContext = true; 105 106 /** Ctor. */ ProtoResultParser( ITestInvocationListener listener, IInvocationContext context, boolean reportInvocation)107 public ProtoResultParser( 108 ITestInvocationListener listener, 109 IInvocationContext context, 110 boolean reportInvocation) { 111 this(listener, context, reportInvocation, "subprocess-"); 112 } 113 114 /** Ctor. */ ProtoResultParser( ITestInvocationListener listener, IInvocationContext context, boolean reportInvocation, String prefixForFile)115 public ProtoResultParser( 116 ITestInvocationListener listener, 117 IInvocationContext context, 118 boolean reportInvocation, 119 String prefixForFile) { 120 mListener = listener; 121 mMainContext = context; 122 mReportInvocation = reportInvocation; 123 mFilePrefix = prefixForFile; 124 } 125 126 /** Enumeration representing the current level of the proto being processed. */ 127 public enum TestLevel { 128 INVOCATION, 129 MODULE, 130 TEST_RUN, 131 TEST_CASE 132 } 133 134 /** Sets whether or not to print when events are received. */ setQuiet(boolean quiet)135 public void setQuiet(boolean quiet) { 136 mQuietParsing = quiet; 137 } 138 setSkipParsingAccounting(boolean skip)139 public void setSkipParsingAccounting(boolean skip) { 140 mSkipParsingAccounting = skip; 141 } 142 143 /** Sets whether or not we should report the logs. */ setReportLogs(boolean reportLogs)144 public void setReportLogs(boolean reportLogs) { 145 mReportLogs = reportLogs; 146 } 147 148 /** 149 * Enable or disable merging the serialized invocation context with the main context that this 150 * object is initialized with. 151 * 152 * <p>Note that disabling invocation-level reporting via the {@code reportInvocation} 153 * constructor parameter still merges context information and requires explicitly using this 154 * method to disable the behavior. 155 * 156 * <p>TODO(b/288001953): Revisit the proper API for accomplishing this. 157 * 158 * @return the previous state 159 * @see #ProtoResultParser 160 */ setMergeInvocationContext(boolean enabled)161 public boolean setMergeInvocationContext(boolean enabled) { 162 boolean previousContext = mMergeInvocationContext; 163 mMergeInvocationContext = enabled; 164 return previousContext; 165 } 166 167 /** 168 * Main entry function that takes the finalized completed proto and replay its results. 169 * 170 * @param finalProto The final {@link TestRecord} to be parsed. 171 */ processFinalizedProto(TestRecord finalProto)172 public void processFinalizedProto(TestRecord finalProto) { 173 if (!finalProto.getParentTestRecordId().isEmpty()) { 174 throw new IllegalArgumentException("processFinalizedProto only expect a root proto."); 175 } 176 177 // Invocation Start 178 handleInvocationStart(finalProto); 179 180 evalChildrenProto(finalProto.getChildrenList(), false); 181 // Invocation End 182 handleInvocationEnded(finalProto); 183 } 184 185 /** 186 * Main entry function where each proto is presented to get parsed into Tradefed events. 187 * 188 * @param currentProto The current {@link TestRecord} to be parsed. 189 * @return True if the proto processed was a module. 190 */ processNewProto(TestRecord currentProto)191 public TestLevel processNewProto(TestRecord currentProto) { 192 // Handle initial root proto 193 if (currentProto.getParentTestRecordId().isEmpty()) { 194 handleRootProto(currentProto); 195 return TestLevel.INVOCATION; 196 } else if (currentProto.hasDescription()) { 197 // If it has a Any Description with Context then it's a module 198 handleModuleProto(currentProto); 199 return TestLevel.MODULE; 200 } else if (mCurrentRunName == null 201 || currentProto.getTestRecordId().equals(mCurrentRunName)) { 202 // Need to track the parent test run id to make sure we need testRunEnd or testRunFail 203 handleTestRun(currentProto); 204 return TestLevel.TEST_RUN; 205 } else { 206 // Test cases handling 207 handleTestCase(currentProto); 208 return TestLevel.TEST_CASE; 209 } 210 } 211 212 /** 213 * In case of parsing proto files directly, handle direct parsing of them as a sequence. 214 * Associated with {@link FileProtoResultReporter} when reporting a sequence of files. 215 * 216 * @param protoFile The proto file to be parsed. 217 * @throws IOException 218 */ processFileProto(File protoFile)219 public void processFileProto(File protoFile) throws IOException { 220 TestRecord record = null; 221 try { 222 record = TestRecordProtoUtil.readFromFile(protoFile); 223 } catch (InvalidProtocolBufferException e) { 224 // Log the proto that failed to parse 225 try (FileInputStreamSource protoFail = new FileInputStreamSource(protoFile, true)) { 226 mListener.testLog("failed-result-protobuf", LogDataType.PB, protoFail); 227 } 228 throw e; 229 } 230 if (!mInvocationStarted) { 231 handleInvocationStart(record); 232 mInvocationStarted = true; 233 } else if (record.getParentTestRecordId().isEmpty()) { 234 handleInvocationEnded(record); 235 } else { 236 evalProto(record, false); 237 } 238 } 239 240 /** Returns whether or not the parsing reached an invocation ended. */ invocationEndedReached()241 public boolean invocationEndedReached() { 242 return mInvocationEnded; 243 } 244 245 /** Returns the id of the module in progress. Returns null if none in progress. */ getModuleInProgress()246 public String getModuleInProgress() { 247 return mModuleInProgress; 248 } 249 250 /** Returns whether or not the invocation failed has been reported. */ hasInvocationFailed()251 public boolean hasInvocationFailed() { 252 return mInvocationFailed; 253 } 254 255 /** 256 * If needed to ensure consistent reporting, complete the events of the module, run and methods. 257 */ completeModuleEvents()258 public void completeModuleEvents() { 259 if (mCurrentRunName == null && getModuleInProgress() != null) { 260 mListener.testRunStarted(getModuleInProgress(), 0); 261 } 262 if (mCurrentTestCase != null) { 263 FailureDescription failure = 264 FailureDescription.create( 265 "Run was interrupted after starting, results are incomplete."); 266 mListener.testFailed(mCurrentTestCase, failure); 267 mListener.testEnded(mCurrentTestCase, new HashMap<String, Metric>()); 268 } 269 if (getModuleInProgress() != null || mCurrentRunName != null) { 270 FailureDescription failure = 271 FailureDescription.create( 272 "Module was interrupted after starting, results are incomplete.", 273 FailureStatus.INFRA_FAILURE); 274 mListener.testRunFailed(failure); 275 mListener.testRunEnded(0L, new HashMap<String, Metric>()); 276 mCurrentRunName = null; 277 } 278 if (getModuleInProgress() != null) { 279 mListener.testModuleEnded(); 280 } 281 } 282 evalChildrenProto(List<ChildReference> children, boolean isInRun)283 private void evalChildrenProto(List<ChildReference> children, boolean isInRun) { 284 for (ChildReference child : children) { 285 TestRecord childProto = child.getInlineTestRecord(); 286 evalProto(childProto, isInRun); 287 } 288 } 289 evalProto(TestRecord childProto, boolean isInRun)290 private void evalProto(TestRecord childProto, boolean isInRun) { 291 if (isInRun) { 292 // test case 293 String[] info = childProto.getTestRecordId().split("#", 2); 294 TestDescription description = new TestDescription(info[0], info[1]); 295 mListener.testStarted(description, timeStampToMillis(childProto.getStartTime())); 296 handleTestCaseEnd(description, childProto); 297 } else { 298 boolean inRun = false; 299 if (childProto.hasDescription()) { 300 // Module start 301 handleModuleStart(childProto); 302 } else { 303 // run start 304 handleTestRunStart(childProto); 305 inRun = true; 306 } 307 evalChildrenProto(childProto.getChildrenList(), inRun); 308 if (childProto.hasDescription()) { 309 // Module end 310 handleModuleProto(childProto); 311 } else { 312 // run end 313 handleTestRunEnd(childProto); 314 } 315 } 316 } 317 318 /** Handles the root of the invocation: They have no parent record id. */ handleRootProto(TestRecord rootProto)319 private void handleRootProto(TestRecord rootProto) { 320 if (rootProto.hasEndTime()) { 321 handleInvocationEnded(rootProto); 322 } else { 323 handleInvocationStart(rootProto); 324 } 325 } 326 handleInvocationStart(TestRecord startInvocationProto)327 private void handleInvocationStart(TestRecord startInvocationProto) { 328 // invocation starting 329 Any anyDescription = startInvocationProto.getDescription(); 330 if (!anyDescription.is(Context.class)) { 331 throw new RuntimeException("Expected Any description of type Context"); 332 } 333 IInvocationContext receivedContext; 334 try { 335 receivedContext = InvocationContext.fromProto(anyDescription.unpack(Context.class)); 336 mergeInvocationContext(mMainContext, receivedContext); 337 } catch (InvalidProtocolBufferException e) { 338 throw new RuntimeException(e); 339 } 340 341 log("Invocation started proto"); 342 if (!mReportInvocation) { 343 CLog.d("Skipping invocation start reporting."); 344 return; 345 } 346 // Only report invocation start if enabled 347 mListener.invocationStarted(receivedContext); 348 } 349 handleInvocationEnded(TestRecord endInvocationProto)350 private void handleInvocationEnded(TestRecord endInvocationProto) { 351 // Still report the logs even if not reporting the invocation level. 352 handleLogs(endInvocationProto); 353 354 if (mInvocationEnded) { 355 CLog.d("Re-entry in invocationEnded, most likely for subprocess final logs."); 356 return; 357 } 358 359 // Get final context in case it changed. 360 Any anyDescription = endInvocationProto.getDescription(); 361 if (!anyDescription.is(Context.class)) { 362 throw new RuntimeException( 363 String.format( 364 "Expected Any description of type Context, was %s", anyDescription)); 365 } 366 try { 367 IInvocationContext context = 368 InvocationContext.fromProto(anyDescription.unpack(Context.class)); 369 mergeInvocationContext(mMainContext, context); 370 } catch (InvalidProtocolBufferException e) { 371 throw new RuntimeException(e); 372 } 373 374 if (endInvocationProto.hasDebugInfo()) { 375 DebugInfo debugInfo = endInvocationProto.getDebugInfo(); 376 FailureDescription failure = FailureDescription.create(debugInfo.getErrorMessage()); 377 if (!TestRecordProto.FailureStatus.UNSET.equals( 378 endInvocationProto.getDebugInfo().getFailureStatus())) { 379 failure.setFailureStatus(debugInfo.getFailureStatus()); 380 } 381 parseDebugInfoContext(endInvocationProto.getDebugInfo(), failure); 382 if (endInvocationProto.getDebugInfo().hasDebugInfoContext()) { 383 String errorType = 384 endInvocationProto.getDebugInfo().getDebugInfoContext().getErrorType(); 385 if (!Strings.isNullOrEmpty(errorType)) { 386 try { 387 Throwable invocationError = 388 (Throwable) SerializationUtil.deserialize(errorType); 389 failure.setCause(invocationError); 390 if (invocationError instanceof OutOfMemoryError) { 391 failure.setErrorIdentifier(InfraErrorIdentifier.OUT_OF_MEMORY_ERROR); 392 } 393 } catch (IOException e) { 394 CLog.e("Failed to deserialize the invocation exception:"); 395 CLog.e(e); 396 failure.setCause(new RuntimeException(failure.getErrorMessage())); 397 } 398 } 399 } 400 CLog.d("Invocation failed with: %s", failure); 401 mListener.invocationFailed(failure); 402 mInvocationFailed = true; 403 } 404 if (endInvocationProto.hasSkipReason()) { 405 SkipReason reason = endInvocationProto.getSkipReason(); 406 CLog.d("Invocation skipped with: %s", reason); 407 mListener.invocationSkipped( 408 new com.android.tradefed.result.skipped.SkipReason( 409 reason.getReason(), reason.getTrigger())); 410 } 411 412 log("Invocation ended proto"); 413 mInvocationEnded = true; 414 if (!mReportInvocation) { 415 CLog.d("Skipping invocation ended reporting."); 416 return; 417 } 418 // Only report invocation ended if enabled 419 long elapsedTime = 420 timeStampToMillis(endInvocationProto.getEndTime()) 421 - timeStampToMillis(endInvocationProto.getStartTime()); 422 mListener.invocationEnded(elapsedTime); 423 } 424 425 /** Handles module level of the invocation: They have a Description for the module context. */ handleModuleProto(TestRecord moduleProto)426 private void handleModuleProto(TestRecord moduleProto) { 427 if (moduleProto.hasEndTime()) { 428 handleModuleEnded(moduleProto); 429 } else { 430 handleModuleStart(moduleProto); 431 } 432 } 433 handleModuleStart(TestRecord moduleProto)434 private void handleModuleStart(TestRecord moduleProto) { 435 Any anyDescription = moduleProto.getDescription(); 436 if (!anyDescription.is(Context.class)) { 437 throw new RuntimeException("Expected Any description of type Context"); 438 } 439 try { 440 IInvocationContext moduleContext = 441 InvocationContext.fromProto(anyDescription.unpack(Context.class)); 442 String message = "Test module started proto"; 443 if (moduleContext.getAttributes().containsKey(ModuleDefinition.MODULE_ID)) { 444 String moduleId = 445 moduleContext 446 .getAttributes() 447 .getUniqueMap() 448 .get(ModuleDefinition.MODULE_ID); 449 message += (": " + moduleId); 450 mModuleInProgress = moduleId; 451 } 452 log(message); 453 mModuleContext = moduleContext; 454 mListener.testModuleStarted(moduleContext); 455 if (mFirstModule) { 456 mFirstModule = false; 457 // Parse the build attributes once after invocation start to update the BuildInfo 458 mergeBuildInfo(mMainContext, moduleContext); 459 } 460 } catch (InvalidProtocolBufferException e) { 461 throw new RuntimeException(e); 462 } 463 } 464 handleModuleEnded(TestRecord moduleProto)465 private void handleModuleEnded(TestRecord moduleProto) { 466 handleLogs(moduleProto); 467 log("Test module ended proto"); 468 try { 469 Any anyDescription = moduleProto.getDescription(); 470 IInvocationContext moduleContext = 471 InvocationContext.fromProto(anyDescription.unpack(Context.class)); 472 // Merge attributes 473 mModuleContext.addInvocationAttributes(moduleContext.getAttributes()); 474 } catch (InvalidProtocolBufferException e) { 475 throw new RuntimeException(e); 476 } 477 mListener.testModuleEnded(); 478 mModuleInProgress = null; 479 mModuleContext = null; 480 } 481 482 /** Handles the test run level of the invocation. */ handleTestRun(TestRecord runProto)483 private void handleTestRun(TestRecord runProto) { 484 // If the proto end-time is present we are evaluating the end of a test run. 485 if (runProto.hasEndTime()) { 486 handleTestRunEnd(runProto); 487 mCurrentRunName = null; 488 } else { 489 // If the end-time is not populated yet we are dealing with the start of a run. 490 mCurrentRunName = runProto.getTestRecordId(); 491 handleTestRunStart(runProto); 492 } 493 } 494 handleTestRunStart(TestRecord runProto)495 private void handleTestRunStart(TestRecord runProto) { 496 String id = runProto.getTestRecordId(); 497 log( 498 "Test run started proto: %s. Expected tests: %s. Attempt: %s", 499 id, runProto.getNumExpectedChildren(), runProto.getAttemptId()); 500 mListener.testRunStarted( 501 id, 502 (int) runProto.getNumExpectedChildren(), 503 (int) runProto.getAttemptId(), 504 timeStampToMillis(runProto.getStartTime())); 505 } 506 handleTestRunEnd(TestRecord runProto)507 private void handleTestRunEnd(TestRecord runProto) { 508 // If we find debugging information, the test run failed and we reflect it. 509 if (runProto.hasDebugInfo()) { 510 DebugInfo debugInfo = runProto.getDebugInfo(); 511 FailureDescription failure = FailureDescription.create(debugInfo.getErrorMessage()); 512 if (!TestRecordProto.FailureStatus.UNSET.equals( 513 runProto.getDebugInfo().getFailureStatus())) { 514 failure.setFailureStatus(debugInfo.getFailureStatus()); 515 } 516 517 parseDebugInfoContext(debugInfo, failure); 518 519 mListener.testRunFailed(failure); 520 log("Test run failure proto: %s", failure.toString()); 521 } 522 handleLogs(runProto); 523 log("Test run ended proto: %s", runProto.getTestRecordId()); 524 long elapsedTime = 525 timeStampToMillis(runProto.getEndTime()) 526 - timeStampToMillis(runProto.getStartTime()); 527 HashMap<String, Metric> metrics = new HashMap<>(runProto.getMetricsMap()); 528 mListener.testRunEnded(elapsedTime, metrics); 529 } 530 531 /** Handles the test cases level of the invocation. */ handleTestCase(TestRecord testcaseProto)532 private void handleTestCase(TestRecord testcaseProto) { 533 String[] info = testcaseProto.getTestRecordId().split("#", 2); 534 TestDescription description = new TestDescription(info[0], info[1]); 535 if (testcaseProto.hasEndTime()) { 536 // Allow end event that also report start in one go. When using 537 // StreamProtoResultReporter we can save some socket communication 538 // by reporting test cases start and end at the same time in some instances. 539 if (mCurrentTestCase == null) { 540 log("Test case started proto: %s", description.toString()); 541 mListener.testStarted(description, timeStampToMillis(testcaseProto.getStartTime())); 542 } 543 handleTestCaseEnd(description, testcaseProto); 544 mCurrentTestCase = null; 545 } else { 546 log("Test case started proto: %s", description.toString()); 547 mListener.testStarted(description, timeStampToMillis(testcaseProto.getStartTime())); 548 mCurrentTestCase = description; 549 } 550 } 551 handleTestCaseEnd(TestDescription description, TestRecord testcaseProto)552 private void handleTestCaseEnd(TestDescription description, TestRecord testcaseProto) { 553 DebugInfo debugInfo = testcaseProto.getDebugInfo(); 554 switch (testcaseProto.getStatus()) { 555 case FAIL: 556 FailureDescription failure = 557 FailureDescription.create(testcaseProto.getDebugInfo().getErrorMessage()); 558 if (!TestRecordProto.FailureStatus.UNSET.equals( 559 testcaseProto.getDebugInfo().getFailureStatus())) { 560 failure.setFailureStatus(testcaseProto.getDebugInfo().getFailureStatus()); 561 } 562 563 parseDebugInfoContext(debugInfo, failure); 564 565 mListener.testFailed(description, failure); 566 log("Test case failed proto: %s - %s", description.toString(), failure.toString()); 567 break; 568 case ASSUMPTION_FAILURE: 569 FailureDescription assumption = 570 FailureDescription.create(testcaseProto.getDebugInfo().getErrorMessage()); 571 if (!TestRecordProto.FailureStatus.UNSET.equals( 572 testcaseProto.getDebugInfo().getFailureStatus())) { 573 assumption.setFailureStatus(testcaseProto.getDebugInfo().getFailureStatus()); 574 } 575 576 parseDebugInfoContext(debugInfo, assumption); 577 578 mListener.testAssumptionFailure(description, assumption); 579 log( 580 "Test case assumption failure proto: %s - %s", 581 description.toString(), testcaseProto.getDebugInfo().getTrace()); 582 break; 583 case IGNORED: 584 mListener.testIgnored(description); 585 log("Test case ignored proto: %s", description.toString()); 586 break; 587 case PASS: 588 if (testcaseProto.hasSkipReason()) { 589 log( 590 "Test case skipped proto: %s", 591 description.toString(), testcaseProto.getSkipReason()); 592 mListener.testSkipped( 593 description, 594 new com.android.tradefed.result.skipped.SkipReason( 595 testcaseProto.getSkipReason().getReason(), 596 testcaseProto.getSkipReason().getTrigger())); 597 } 598 break; 599 default: 600 throw new RuntimeException( 601 String.format( 602 "Received unexpected test status %s.", testcaseProto.getStatus())); 603 } 604 handleLogs(testcaseProto); 605 HashMap<String, Metric> metrics = new HashMap<>(testcaseProto.getMetricsMap()); 606 log("Test case ended proto: %s", description.toString()); 607 mListener.testEnded(description, timeStampToMillis(testcaseProto.getEndTime()), metrics); 608 } 609 timeStampToMillis(Timestamp stamp)610 private long timeStampToMillis(Timestamp stamp) { 611 return stamp.getSeconds() * 1000L + (stamp.getNanos() / 1000000L); 612 } 613 handleLogs(TestRecord proto)614 private void handleLogs(TestRecord proto) { 615 if (!(mListener instanceof ILogSaverListener)) { 616 return; 617 } 618 ILogSaverListener logger = (ILogSaverListener) mListener; 619 for (Entry<String, Any> entry : proto.getArtifactsMap().entrySet()) { 620 try { 621 LogFileInfo info = entry.getValue().unpack(LogFileInfo.class); 622 LogDataType dataType = null; 623 try { 624 dataType = LogDataType.valueOf(info.getLogType()); 625 } catch (NullPointerException | IllegalArgumentException e) { 626 dataType = LogDataType.TEXT; 627 } 628 LogFile file = 629 new LogFile( 630 info.getPath(), 631 info.getUrl(), 632 info.getIsCompressed(), 633 dataType, 634 info.getSize()); 635 if (Strings.isNullOrEmpty(file.getPath())) { 636 CLog.e("Log '%s' was registered but without a path.", entry.getKey()); 637 continue; 638 } 639 File path = new File(file.getPath()); 640 if (Strings.isNullOrEmpty(file.getUrl()) && path.exists()) { 641 LogDataType type = file.getType(); 642 if (mReportLogs) { 643 try (InputStreamSource source = new FileInputStreamSource(path)) { 644 log( 645 "Logging %s [type: %s]from subprocess: %s ", 646 entry.getKey(), type, file.getPath()); 647 logger.testLog(mFilePrefix + entry.getKey(), type, source); 648 } 649 } 650 if (entry.getKey().startsWith(ActiveTrace.TRACE_KEY) 651 && LogDataType.PERFETTO.equals(type)) { 652 CLog.d("Log the subprocess trace"); 653 TracingLogger.getActiveTrace().addSubprocessTrace(path); 654 FileUtil.deleteFile(path); 655 } 656 } else { 657 if (entry.getKey().startsWith(ActiveTrace.TRACE_KEY) 658 && LogDataType.PERFETTO.equals(file.getType()) 659 && path.exists()) { 660 CLog.d("Log the subprocess trace"); 661 TracingLogger.getActiveTrace().addSubprocessTrace(path); 662 } 663 if (mReportLogs) { 664 log( 665 "Logging %s [type: %s] from subprocess. url: %s, path: %s [exists:" 666 + " %s]", 667 entry.getKey(), 668 file.getType(), 669 file.getUrl(), 670 file.getPath(), 671 path.exists()); 672 logger.logAssociation(mFilePrefix + entry.getKey(), file); 673 } 674 } 675 } catch (InvalidProtocolBufferException e) { 676 CLog.e("Couldn't unpack %s as a LogFileInfo", entry.getKey()); 677 CLog.e(e); 678 } 679 } 680 } 681 mergeBuildInfo( IInvocationContext receiverContext, IInvocationContext endInvocationContext)682 private void mergeBuildInfo( 683 IInvocationContext receiverContext, IInvocationContext endInvocationContext) { 684 if (receiverContext == null) { 685 return; 686 } 687 // Gather attributes of build infos 688 for (IBuildInfo info : receiverContext.getBuildInfos()) { 689 String name = receiverContext.getBuildInfoName(info); 690 IBuildInfo endInvocationInfo = endInvocationContext.getBuildInfo(name); 691 if (endInvocationInfo == null) { 692 CLog.e("No build info named: %s", name); 693 continue; 694 } 695 info.addBuildAttributes(endInvocationInfo.getBuildAttributes()); 696 } 697 } 698 699 /** 700 * Copy the build info and invocation attributes from the proto context to the current 701 * invocation context 702 * 703 * @param receiverContext The context receiving the attributes 704 * @param endInvocationContext The context providing the attributes 705 */ mergeInvocationContext( IInvocationContext receiverContext, IInvocationContext endInvocationContext)706 private void mergeInvocationContext( 707 IInvocationContext receiverContext, IInvocationContext endInvocationContext) { 708 if (!mMergeInvocationContext) { 709 CLog.d("Skipping merging invocation context"); 710 return; 711 } 712 if (receiverContext == null) { 713 return; 714 } 715 mergeBuildInfo(receiverContext, endInvocationContext); 716 717 try { 718 Method unlock = InvocationContext.class.getDeclaredMethod("unlock"); 719 unlock.setAccessible(true); 720 unlock.invoke(receiverContext); 721 unlock.setAccessible(false); 722 } catch (NoSuchMethodException 723 | SecurityException 724 | IllegalAccessException 725 | IllegalArgumentException 726 | InvocationTargetException e) { 727 CLog.e("Couldn't unlock the main context. Skip copying attributes"); 728 return; 729 } 730 // Copy invocation attributes 731 MultiMap<String, String> attributes = endInvocationContext.getAttributes(); 732 // Parse the invocation metric group first. 733 for (InvocationGroupMetricKey groupKey : InvocationGroupMetricKey.values()) { 734 Set<String> attKeys = new HashSet<>(attributes.keySet()); 735 for (String attKey : attKeys) { 736 if (attKey.startsWith(groupKey.toString() + ":")) { 737 if (attributes.get(attKey) == null) { 738 continue; 739 } 740 List<String> values = attributes.get(attKey); 741 attributes.remove(attKey); 742 if (mSkipParsingAccounting) { 743 continue; 744 } 745 String group = attKey.split(":", 2)[1]; 746 for (String val : values) { 747 if (groupKey.shouldAdd()) { 748 try { 749 InvocationMetricLogger.addInvocationMetrics( 750 groupKey, group, Long.parseLong(val)); 751 } catch (NumberFormatException e) { 752 CLog.d( 753 "Key %s doesn't have a number value, was: %s.", 754 groupKey, val); 755 InvocationMetricLogger.addInvocationMetrics(groupKey, group, val); 756 } 757 } else { 758 InvocationMetricLogger.addInvocationMetrics(groupKey, group, val); 759 } 760 } 761 } 762 } 763 } 764 for (InvocationMetricKey key : InvocationMetricKey.values()) { 765 if (!attributes.containsKey(key.toString())) { 766 continue; 767 } 768 List<String> values = attributes.get(key.toString()); 769 attributes.remove(key.toString()); 770 771 if (mSkipParsingAccounting) { 772 continue; 773 } 774 if (values == null) { 775 continue; 776 } 777 for (String val : values) { 778 if (key.shouldAdd()) { 779 try { 780 InvocationMetricLogger.addInvocationMetrics(key, Long.parseLong(val)); 781 } catch (NumberFormatException e) { 782 CLog.d("Key %s doesn't have a number value, was: %s.", key, val); 783 InvocationMetricLogger.addInvocationMetrics(key, val); 784 } 785 } else { 786 InvocationMetricLogger.addInvocationMetrics(key, val); 787 } 788 } 789 } 790 if (attributes.containsKey(TfObjectTracker.TF_OBJECTS_TRACKING_KEY)) { 791 List<String> values = attributes.remove(TfObjectTracker.TF_OBJECTS_TRACKING_KEY); 792 if (!mSkipParsingAccounting) { 793 for (String val : values) { 794 for (String pair : Splitter.on(",").split(val)) { 795 if (!pair.contains("=")) { 796 continue; 797 } 798 String[] pairSplit = pair.split("="); 799 try { 800 TfObjectTracker.directCount(pairSplit[0], Long.parseLong(pairSplit[1])); 801 } catch (NumberFormatException e) { 802 CLog.e(e); 803 continue; 804 } 805 } 806 } 807 } 808 } 809 CLog.d("Adding following properties: %s", attributes.entries()); 810 receiverContext.addInvocationAttributes(attributes); 811 } 812 log(String format, Object... obj)813 private void log(String format, Object... obj) { 814 if (!mQuietParsing) { 815 CLog.d(format, obj); 816 } 817 } 818 parseDebugInfoContext(DebugInfo debugInfo, FailureDescription failure)819 private void parseDebugInfoContext(DebugInfo debugInfo, FailureDescription failure) { 820 if (!debugInfo.hasDebugInfoContext()) { 821 return; 822 } 823 DebugInfoContext debugContext = debugInfo.getDebugInfoContext(); 824 if (!Strings.isNullOrEmpty(debugContext.getActionInProgress())) { 825 try { 826 ActionInProgress value = 827 ActionInProgress.valueOf(debugContext.getActionInProgress()); 828 failure.setActionInProgress(value); 829 } catch (IllegalArgumentException parseError) { 830 CLog.e(parseError); 831 } 832 } 833 if (!Strings.isNullOrEmpty(debugContext.getDebugHelpMessage())) { 834 failure.setDebugHelpMessage(debugContext.getDebugHelpMessage()); 835 } 836 if (!Strings.isNullOrEmpty(debugContext.getOrigin())) { 837 failure.setOrigin(debugContext.getOrigin()); 838 } 839 String errorName = debugContext.getErrorName(); 840 long errorCode = debugContext.getErrorCode(); 841 if (!Strings.isNullOrEmpty(errorName)) { 842 // Most of the implementations will be Enums which represent the name/code. 843 // But since there might be several Enum implementation of ErrorIdentifier, we can't 844 // parse back the name to the Enum so instead we stub create a pre-populated 845 // ErrorIdentifier to carry the infos. 846 ErrorIdentifier errorId = 847 new ErrorIdentifier() { 848 @Override 849 public String name() { 850 return errorName; 851 } 852 853 @Override 854 public long code() { 855 return errorCode; 856 } 857 858 @Override 859 public @Nonnull FailureStatus status() { 860 FailureStatus status = failure.getFailureStatus(); 861 return (status == null ? FailureStatus.UNSET : status); 862 } 863 }; 864 failure.setErrorIdentifier(errorId); 865 } 866 } 867 } 868