1 /* 2 * Copyright (C) 2016 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.util; 17 18 import com.android.tradefed.build.IBuildInfo; 19 import com.android.tradefed.invoker.IInvocationContext; 20 import com.android.tradefed.invoker.logger.InvocationMetricLogger; 21 import com.android.tradefed.invoker.logger.InvocationMetricLogger.InvocationGroupMetricKey; 22 import com.android.tradefed.invoker.logger.InvocationMetricLogger.InvocationMetricKey; 23 import com.android.tradefed.invoker.logger.TfObjectTracker; 24 import com.android.tradefed.invoker.tracing.ActiveTrace; 25 import com.android.tradefed.invoker.tracing.TracingLogger; 26 import com.android.tradefed.log.LogUtil.CLog; 27 import com.android.tradefed.metrics.proto.MetricMeasurement.Metric; 28 import com.android.tradefed.result.FailureDescription; 29 import com.android.tradefed.result.FileInputStreamSource; 30 import com.android.tradefed.result.ILogSaverListener; 31 import com.android.tradefed.result.ITestInvocationListener; 32 import com.android.tradefed.result.InputStreamSource; 33 import com.android.tradefed.result.LogDataType; 34 import com.android.tradefed.result.LogFile; 35 import com.android.tradefed.result.TestDescription; 36 import com.android.tradefed.result.proto.TestRecordProto.FailureStatus; 37 import com.android.tradefed.testtype.suite.ModuleDefinition; 38 import com.android.tradefed.util.SubprocessEventHelper.BaseTestEventInfo; 39 import com.android.tradefed.util.SubprocessEventHelper.FailedTestEventInfo; 40 import com.android.tradefed.util.SubprocessEventHelper.InvocationEndedEventInfo; 41 import com.android.tradefed.util.SubprocessEventHelper.InvocationFailedEventInfo; 42 import com.android.tradefed.util.SubprocessEventHelper.InvocationStartedEventInfo; 43 import com.android.tradefed.util.SubprocessEventHelper.LogAssociationEventInfo; 44 import com.android.tradefed.util.SubprocessEventHelper.SkippedTestEventInfo; 45 import com.android.tradefed.util.SubprocessEventHelper.TestEndedEventInfo; 46 import com.android.tradefed.util.SubprocessEventHelper.TestLogEventInfo; 47 import com.android.tradefed.util.SubprocessEventHelper.TestModuleStartedEventInfo; 48 import com.android.tradefed.util.SubprocessEventHelper.TestRunEndedEventInfo; 49 import com.android.tradefed.util.SubprocessEventHelper.TestRunFailedEventInfo; 50 import com.android.tradefed.util.SubprocessEventHelper.TestRunStartedEventInfo; 51 import com.android.tradefed.util.SubprocessEventHelper.TestStartedEventInfo; 52 import com.android.tradefed.util.proto.TfMetricProtoUtil; 53 54 import com.google.common.base.Splitter; 55 import com.google.common.base.Strings; 56 57 import org.json.JSONException; 58 import org.json.JSONObject; 59 60 import java.io.BufferedReader; 61 import java.io.Closeable; 62 import java.io.File; 63 import java.io.FileNotFoundException; 64 import java.io.FileOutputStream; 65 import java.io.FileReader; 66 import java.io.IOException; 67 import java.io.InputStreamReader; 68 import java.net.ServerSocket; 69 import java.net.Socket; 70 import java.util.ArrayList; 71 import java.util.HashMap; 72 import java.util.HashSet; 73 import java.util.List; 74 import java.util.Map; 75 import java.util.Set; 76 import java.util.concurrent.Semaphore; 77 import java.util.concurrent.TimeUnit; 78 import java.util.regex.Matcher; 79 import java.util.regex.Pattern; 80 81 /** 82 * Extends {@link FileOutputStream} to parse the output before writing to the file so we can 83 * generate the test events on the launcher side. 84 */ 85 public class SubprocessTestResultsParser implements Closeable { 86 87 private ITestInvocationListener mListener; 88 89 private TestDescription mCurrentTestCase = null; 90 private IInvocationContext mCurrentModuleContext = null; 91 private String mCurrentRunName = null; 92 private InvocationFailedEventInfo mReportedInvocationFailedEventInfo = null; 93 94 private Pattern mPattern = null; 95 private Map<String, EventHandler> mHandlerMap = null; 96 private EventReceiverThread mEventReceiver = null; 97 private IInvocationContext mContext = null; 98 private Long mStartTime = null; 99 // Ignore the testLog events, rely only on logAssociation 100 private boolean mIgnoreTestLog = true; 101 // Keep track of which files we received TEST_LOG event from. 102 private Set<String> mTestLogged = new HashSet<>(); 103 104 /** Relevant test status keys. */ 105 public static class StatusKeys { 106 public static final String INVOCATION_FAILED = "INVOCATION_FAILED"; 107 public static final String TEST_ASSUMPTION_FAILURE = "TEST_ASSUMPTION_FAILURE"; 108 public static final String TEST_ENDED = "TEST_ENDED"; 109 public static final String TEST_FAILED = "TEST_FAILED"; 110 public static final String TEST_IGNORED = "TEST_IGNORED"; 111 public static final String TEST_SKIPPED = "TEST_SKIPPED"; 112 public static final String TEST_STARTED = "TEST_STARTED"; 113 public static final String TEST_RUN_ENDED = "TEST_RUN_ENDED"; 114 public static final String TEST_RUN_FAILED = "TEST_RUN_FAILED"; 115 public static final String TEST_RUN_STARTED = "TEST_RUN_STARTED"; 116 public static final String TEST_MODULE_STARTED = "TEST_MODULE_STARTED"; 117 public static final String TEST_MODULE_ENDED = "TEST_MODULE_ENDED"; 118 public static final String TEST_LOG = "TEST_LOG"; 119 public static final String LOG_ASSOCIATION = "LOG_ASSOCIATION"; 120 public static final String INVOCATION_STARTED = "INVOCATION_STARTED"; 121 public static final String INVOCATION_ENDED = "INVOCATION_ENDED"; 122 } 123 124 /** 125 * Internal receiver thread class with a socket. 126 */ 127 private class EventReceiverThread extends Thread { 128 private ServerSocket mSocket; 129 // initial state: 1 permit available, joins that don't wait for connection will succeed 130 private Semaphore mSemaphore = new Semaphore(1); 131 private boolean mShouldParse = true; 132 EventReceiverThread()133 public EventReceiverThread() throws IOException { 134 super("EventReceiverThread"); 135 mSocket = new ServerSocket(0); 136 } 137 getLocalPort()138 protected int getLocalPort() { 139 return mSocket.getLocalPort(); 140 } 141 142 /** @return True if parsing completes before timeout (optionally waiting for connection). */ await(long millis, boolean waitForConnection)143 boolean await(long millis, boolean waitForConnection) throws InterruptedException { 144 // As only 1 permit is available prior to connecting, changing the number of permits 145 // requested controls whether the receiver will wait for a connection. 146 int permits = waitForConnection ? 2 : 1; 147 if (mSemaphore.tryAcquire(permits, millis, TimeUnit.MILLISECONDS)) { 148 mSemaphore.release(permits); 149 return true; 150 } 151 return false; 152 } 153 cancel()154 public void cancel() throws IOException { 155 if (mSocket != null) { 156 mSocket.close(); 157 } 158 } 159 160 /** 161 * When reaching some issues, we might want to terminate the buffer of the socket to spy 162 * which events are still in the pipe. 163 */ stopParsing()164 public void stopParsing() { 165 mShouldParse = false; 166 } 167 168 @Override run()169 public void run() { 170 Socket client = null; 171 BufferedReader in = null; 172 try { 173 client = mSocket.accept(); 174 mSemaphore.acquire(); // connected: 0 permits available, all joins will wait 175 in = new BufferedReader(new InputStreamReader(client.getInputStream())); 176 String event = null; 177 while ((event = in.readLine()) != null) { 178 try { 179 if (mShouldParse) { 180 CLog.d("received event: '%s'", event); 181 parse(event); 182 } else { 183 CLog.d("Skipping parsing of event: '%s'", event); 184 } 185 } catch (JSONException e) { 186 CLog.e(e); 187 } 188 } 189 } catch (IOException | InterruptedException e) { 190 CLog.e(e); 191 } finally { 192 StreamUtil.close(in); 193 mSemaphore.release(2); // finished: 2 permits available, all joins succeed 194 } 195 CLog.d("EventReceiverThread done."); 196 } 197 } 198 199 /** 200 * Wait for the event receiver to finish processing events. Will wait even if a connection 201 * wasn't established, i.e. processing hasn't begun yet. 202 * 203 * @param millis timeout in milliseconds. 204 * @return True if receiver thread terminate before timeout, False otherwise. 205 */ joinReceiver(long millis)206 public boolean joinReceiver(long millis) { 207 return joinReceiver(millis, true); 208 } 209 210 /** 211 * Wait for the event receiver to finish processing events. 212 * 213 * @param millis timeout in milliseconds. 214 * @param waitForConnection False to skip waiting if a connection was never established. 215 * @return True if receiver thread terminate before timeout, False otherwise. 216 */ joinReceiver(long millis, boolean waitForConnection)217 public boolean joinReceiver(long millis, boolean waitForConnection) { 218 if (mEventReceiver != null) { 219 try { 220 CLog.i("Waiting for events to finish being processed."); 221 if (!mEventReceiver.await(millis, waitForConnection)) { 222 mEventReceiver.stopParsing(); 223 CLog.e("Event receiver thread did not complete. Some events may be missing."); 224 return false; 225 } 226 } catch (InterruptedException e) { 227 CLog.e(e); 228 throw new RuntimeException(e); 229 } 230 } 231 return true; 232 } 233 234 /** 235 * Returns the socket receiver that was open. -1 if none. 236 */ getSocketServerPort()237 public int getSocketServerPort() { 238 if (mEventReceiver != null) { 239 return mEventReceiver.getLocalPort(); 240 } 241 return -1; 242 } 243 244 /** Whether or not to ignore testLog events and only rely on logAssociation. */ setIgnoreTestLog(boolean ignoreTestLog)245 public void setIgnoreTestLog(boolean ignoreTestLog) { 246 mIgnoreTestLog = ignoreTestLog; 247 } 248 249 @Override close()250 public void close() throws IOException { 251 if (mEventReceiver != null) { 252 mEventReceiver.cancel(); 253 } 254 } 255 256 /** 257 * Constructor for the result parser 258 * 259 * @param listener {@link ITestInvocationListener} where to report the results 260 * @param streaming if True, a socket receiver will be open to receive results. 261 * @param context a {@link IInvocationContext} information about the invocation 262 */ SubprocessTestResultsParser( ITestInvocationListener listener, boolean streaming, IInvocationContext context)263 public SubprocessTestResultsParser( 264 ITestInvocationListener listener, boolean streaming, IInvocationContext context) 265 throws IOException { 266 this(listener, context); 267 if (streaming) { 268 mEventReceiver = new EventReceiverThread(); 269 mEventReceiver.start(); 270 } 271 } 272 273 /** 274 * Constructor for the result parser 275 * 276 * @param listener {@link ITestInvocationListener} where to report the results 277 * @param context a {@link IInvocationContext} information about the invocation 278 */ SubprocessTestResultsParser( ITestInvocationListener listener, IInvocationContext context)279 public SubprocessTestResultsParser( 280 ITestInvocationListener listener, IInvocationContext context) { 281 mListener = listener; 282 mContext = context; 283 StringBuilder sb = new StringBuilder(); 284 sb.append(StatusKeys.INVOCATION_FAILED).append("|"); 285 sb.append(StatusKeys.TEST_ASSUMPTION_FAILURE).append("|"); 286 sb.append(StatusKeys.TEST_ENDED).append("|"); 287 sb.append(StatusKeys.TEST_FAILED).append("|"); 288 sb.append(StatusKeys.TEST_IGNORED).append("|"); 289 sb.append(StatusKeys.TEST_STARTED).append("|"); 290 sb.append(StatusKeys.TEST_RUN_ENDED).append("|"); 291 sb.append(StatusKeys.TEST_RUN_FAILED).append("|"); 292 sb.append(StatusKeys.TEST_RUN_STARTED).append("|"); 293 sb.append(StatusKeys.TEST_MODULE_STARTED).append("|"); 294 sb.append(StatusKeys.TEST_MODULE_ENDED).append("|"); 295 sb.append(StatusKeys.TEST_LOG).append("|"); 296 sb.append(StatusKeys.LOG_ASSOCIATION).append("|"); 297 sb.append(StatusKeys.INVOCATION_STARTED).append("|"); 298 sb.append(StatusKeys.INVOCATION_ENDED); 299 String patt = String.format("(.*)(%s)( )(.*)", sb.toString()); 300 mPattern = Pattern.compile(patt); 301 302 // Create Handler map for each event 303 mHandlerMap = new HashMap<String, EventHandler>(); 304 mHandlerMap.put(StatusKeys.INVOCATION_FAILED, new InvocationFailedEventHandler()); 305 mHandlerMap.put(StatusKeys.TEST_ASSUMPTION_FAILURE, 306 new TestAssumptionFailureEventHandler()); 307 mHandlerMap.put(StatusKeys.TEST_ENDED, new TestEndedEventHandler()); 308 mHandlerMap.put(StatusKeys.TEST_FAILED, new TestFailedEventHandler()); 309 mHandlerMap.put(StatusKeys.TEST_IGNORED, new TestIgnoredEventHandler()); 310 mHandlerMap.put(StatusKeys.TEST_SKIPPED, new TestSkippedEventHandler()); 311 mHandlerMap.put(StatusKeys.TEST_STARTED, new TestStartedEventHandler()); 312 mHandlerMap.put(StatusKeys.TEST_RUN_ENDED, new TestRunEndedEventHandler()); 313 mHandlerMap.put(StatusKeys.TEST_RUN_FAILED, new TestRunFailedEventHandler()); 314 mHandlerMap.put(StatusKeys.TEST_RUN_STARTED, new TestRunStartedEventHandler()); 315 mHandlerMap.put(StatusKeys.TEST_MODULE_STARTED, new TestModuleStartedEventHandler()); 316 mHandlerMap.put(StatusKeys.TEST_MODULE_ENDED, new TestModuleEndedEventHandler()); 317 mHandlerMap.put(StatusKeys.TEST_LOG, new TestLogEventHandler()); 318 mHandlerMap.put(StatusKeys.LOG_ASSOCIATION, new LogAssociationEventHandler()); 319 mHandlerMap.put(StatusKeys.INVOCATION_STARTED, new InvocationStartedEventHandler()); 320 mHandlerMap.put(StatusKeys.INVOCATION_ENDED, new InvocationEndedEventHandler()); 321 } 322 parseFile(File file)323 public void parseFile(File file) { 324 BufferedReader reader = null; 325 try { 326 reader = new BufferedReader(new FileReader(file)); 327 } catch (FileNotFoundException e) { 328 CLog.e(e); 329 throw new RuntimeException(e); 330 } 331 ArrayList<String> listString = new ArrayList<String>(); 332 String line = null; 333 try { 334 while ((line = reader.readLine()) != null) { 335 listString.add(line); 336 } 337 reader.close(); 338 } catch (IOException e) { 339 CLog.e(e); 340 throw new RuntimeException(e); 341 } 342 processNewLines(listString.toArray(new String[listString.size()])); 343 } 344 345 /** 346 * call parse on each line of the array to extract the events if any. 347 */ processNewLines(String[] lines)348 public void processNewLines(String[] lines) { 349 for (String line : lines) { 350 try { 351 parse(line); 352 } catch (JSONException e) { 353 CLog.e("Exception while parsing"); 354 CLog.e(e); 355 throw new RuntimeException(e); 356 } 357 } 358 } 359 360 /** 361 * Parse a line, if it matches one of the events, handle it. 362 */ parse(String line)363 private void parse(String line) throws JSONException { 364 Matcher matcher = mPattern.matcher(line); 365 if (matcher.find()) { 366 EventHandler handler = mHandlerMap.get(matcher.group(2)); 367 if (handler != null) { 368 handler.handleEvent(matcher.group(4)); 369 } else { 370 CLog.w("No handler found matching: %s", matcher.group(2)); 371 } 372 } 373 } 374 checkCurrentTestId(String className, String testName)375 private void checkCurrentTestId(String className, String testName) { 376 if (mCurrentTestCase == null) { 377 mCurrentTestCase = new TestDescription(className, testName); 378 CLog.w("Calling a test event without having called testStarted."); 379 } 380 } 381 382 /** 383 * Interface for event handling 384 */ 385 interface EventHandler { handleEvent(String eventJson)386 public void handleEvent(String eventJson) throws JSONException; 387 } 388 389 private class TestRunStartedEventHandler implements EventHandler { 390 @Override handleEvent(String eventJson)391 public void handleEvent(String eventJson) throws JSONException { 392 TestRunStartedEventInfo rsi = new TestRunStartedEventInfo(new JSONObject(eventJson)); 393 if (rsi.mAttempt != null) { 394 mListener.testRunStarted( 395 rsi.mRunName, rsi.mTestCount, rsi.mAttempt, rsi.mStartTime); 396 } else { 397 mListener.testRunStarted(rsi.mRunName, rsi.mTestCount); 398 } 399 mCurrentRunName = rsi.mRunName; 400 } 401 } 402 403 private class TestRunFailedEventHandler implements EventHandler { 404 @Override handleEvent(String eventJson)405 public void handleEvent(String eventJson) throws JSONException { 406 TestRunFailedEventInfo rfi = new TestRunFailedEventInfo(new JSONObject(eventJson)); 407 if (rfi.mFailure != null) { 408 mListener.testRunFailed(rfi.mFailure); 409 } else { 410 mListener.testRunFailed(rfi.mReason); 411 } 412 } 413 } 414 415 private class TestRunEndedEventHandler implements EventHandler { 416 @Override handleEvent(String eventJson)417 public void handleEvent(String eventJson) throws JSONException { 418 try { 419 TestRunEndedEventInfo rei = new TestRunEndedEventInfo(new JSONObject(eventJson)); 420 // TODO: Parse directly as proto. 421 mListener.testRunEnded( 422 rei.mTime, TfMetricProtoUtil.upgradeConvert(rei.mRunMetrics, true)); 423 } finally { 424 mCurrentRunName = null; 425 mCurrentTestCase = null; 426 } 427 } 428 } 429 430 private class InvocationFailedEventHandler implements EventHandler { 431 @Override handleEvent(String eventJson)432 public void handleEvent(String eventJson) throws JSONException { 433 InvocationFailedEventInfo ifi = 434 new InvocationFailedEventInfo(new JSONObject(eventJson)); 435 if (ifi.mFailure != null) { 436 mListener.invocationFailed(ifi.mFailure); 437 } else { 438 mListener.invocationFailed(ifi.mCause); 439 } 440 mReportedInvocationFailedEventInfo = ifi; 441 } 442 } 443 444 private class TestStartedEventHandler implements EventHandler { 445 @Override handleEvent(String eventJson)446 public void handleEvent(String eventJson) throws JSONException { 447 TestStartedEventInfo bti = new TestStartedEventInfo(new JSONObject(eventJson)); 448 mCurrentTestCase = new TestDescription(bti.mClassName, bti.mTestName); 449 if (bti.mStartTime != null) { 450 mListener.testStarted(mCurrentTestCase, bti.mStartTime); 451 } else { 452 mListener.testStarted(mCurrentTestCase); 453 } 454 } 455 } 456 457 private class TestFailedEventHandler implements EventHandler { 458 @Override handleEvent(String eventJson)459 public void handleEvent(String eventJson) throws JSONException { 460 FailedTestEventInfo fti = new FailedTestEventInfo(new JSONObject(eventJson)); 461 checkCurrentTestId(fti.mClassName, fti.mTestName); 462 mListener.testFailed(mCurrentTestCase, fti.mFailure); 463 } 464 } 465 466 private class TestEndedEventHandler implements EventHandler { 467 @Override handleEvent(String eventJson)468 public void handleEvent(String eventJson) throws JSONException { 469 try { 470 TestEndedEventInfo tei = new TestEndedEventInfo(new JSONObject(eventJson)); 471 checkCurrentTestId(tei.mClassName, tei.mTestName); 472 if (tei.mEndTime != null) { 473 mListener.testEnded( 474 mCurrentTestCase, 475 tei.mEndTime, 476 TfMetricProtoUtil.upgradeConvert(tei.mRunMetrics)); 477 } else { 478 mListener.testEnded( 479 mCurrentTestCase, TfMetricProtoUtil.upgradeConvert(tei.mRunMetrics)); 480 } 481 } finally { 482 mCurrentTestCase = null; 483 } 484 } 485 } 486 487 private class TestIgnoredEventHandler implements EventHandler { 488 @Override handleEvent(String eventJson)489 public void handleEvent(String eventJson) throws JSONException { 490 BaseTestEventInfo baseTestIgnored = new BaseTestEventInfo(new JSONObject(eventJson)); 491 checkCurrentTestId(baseTestIgnored.mClassName, baseTestIgnored.mTestName); 492 mListener.testIgnored(mCurrentTestCase); 493 } 494 } 495 496 private class TestSkippedEventHandler implements EventHandler { 497 @Override handleEvent(String eventJson)498 public void handleEvent(String eventJson) throws JSONException { 499 SkippedTestEventInfo skipped = new SkippedTestEventInfo(new JSONObject(eventJson)); 500 checkCurrentTestId(skipped.mClassName, skipped.mTestName); 501 mListener.testSkipped(mCurrentTestCase, skipped.skipReason); 502 } 503 } 504 505 private class TestAssumptionFailureEventHandler implements EventHandler { 506 @Override handleEvent(String eventJson)507 public void handleEvent(String eventJson) throws JSONException { 508 FailedTestEventInfo FailedAssumption = 509 new FailedTestEventInfo(new JSONObject(eventJson)); 510 checkCurrentTestId(FailedAssumption.mClassName, FailedAssumption.mTestName); 511 mListener.testAssumptionFailure(mCurrentTestCase, FailedAssumption.mTrace); 512 } 513 } 514 515 private class TestModuleStartedEventHandler implements EventHandler { 516 @Override handleEvent(String eventJson)517 public void handleEvent(String eventJson) throws JSONException { 518 TestModuleStartedEventInfo module = 519 new TestModuleStartedEventInfo(new JSONObject(eventJson)); 520 mCurrentModuleContext = module.mModuleContext; 521 mListener.testModuleStarted(module.mModuleContext); 522 } 523 } 524 525 private class TestModuleEndedEventHandler implements EventHandler { 526 @Override handleEvent(String eventJson)527 public void handleEvent(String eventJson) throws JSONException { 528 if (mCurrentModuleContext == null) { 529 CLog.w("Calling testModuleEnded when testModuleStarted was not called."); 530 } 531 mListener.testModuleEnded(); 532 mCurrentModuleContext = null; 533 } 534 } 535 536 private class TestLogEventHandler implements EventHandler { 537 @Override handleEvent(String eventJson)538 public void handleEvent(String eventJson) throws JSONException { 539 TestLogEventInfo logInfo = new TestLogEventInfo(new JSONObject(eventJson)); 540 if (mIgnoreTestLog) { 541 FileUtil.deleteFile(logInfo.mDataFile); 542 return; 543 } 544 String name = String.format("subprocess-%s", logInfo.mDataName); 545 try (InputStreamSource data = new FileInputStreamSource(logInfo.mDataFile, true)) { 546 mListener.testLog(name, logInfo.mLogType, data); 547 mTestLogged.add(logInfo.mDataName); 548 } 549 } 550 } 551 552 private class LogAssociationEventHandler implements EventHandler { 553 @Override handleEvent(String eventJson)554 public void handleEvent(String eventJson) throws JSONException { 555 LogAssociationEventInfo assosInfo = 556 new LogAssociationEventInfo(new JSONObject(eventJson)); 557 LogFile file = assosInfo.mLoggedFile; 558 if (Strings.isNullOrEmpty(file.getPath())) { 559 CLog.e("Log '%s' was registered but without a path.", assosInfo.mDataName); 560 return; 561 } 562 File path = new File(file.getPath()); 563 String name = String.format("subprocess-%s", assosInfo.mDataName); 564 if (Strings.isNullOrEmpty(file.getUrl()) && path.exists()) { 565 if (mTestLogged.contains(assosInfo.mDataName)) { 566 CLog.d( 567 "Already called testLog on %s, ignoring the logAssociation.", 568 assosInfo.mDataName); 569 return; 570 } 571 try (InputStreamSource source = new FileInputStreamSource(path)) { 572 LogDataType type = file.getType(); 573 CLog.d("Logging %s from subprocess: %s ", assosInfo.mDataName, file.getPath()); 574 if (ActiveTrace.TRACE_KEY.equals(assosInfo.mDataName) 575 && LogDataType.PERFETTO.equals(type)) { 576 CLog.d("Log the subprocess trace"); 577 TracingLogger.getActiveTrace().addSubprocessTrace(path); 578 } 579 mListener.testLog(name, type, source); 580 } 581 } else { 582 CLog.d( 583 "Logging %s from subprocess. url: %s, path: %s", 584 name, file.getUrl(), file.getPath()); 585 if (mListener instanceof ILogSaverListener) { 586 ((ILogSaverListener) mListener).logAssociation(name, assosInfo.mLoggedFile); 587 } 588 } 589 } 590 } 591 592 private class InvocationStartedEventHandler implements EventHandler { 593 @Override handleEvent(String eventJson)594 public void handleEvent(String eventJson) throws JSONException { 595 InvocationStartedEventInfo eventStart = 596 new InvocationStartedEventInfo(new JSONObject(eventJson)); 597 if (mContext.getTestTag() == null || "stub".equals(mContext.getTestTag())) { 598 mContext.setTestTag(eventStart.mTestTag); 599 } 600 mStartTime = eventStart.mStartTime; 601 } 602 } 603 604 private class InvocationEndedEventHandler implements EventHandler { 605 @Override handleEvent(String eventJson)606 public void handleEvent(String eventJson) throws JSONException { 607 JSONObject json = new JSONObject(eventJson); 608 InvocationEndedEventInfo eventEnd = new InvocationEndedEventInfo(json); 609 // Add build attributes to the primary build (the first build 610 // provider of the running configuration). 611 List<IBuildInfo> infos = mContext.getBuildInfos(); 612 if (!infos.isEmpty()) { 613 Map<String, String> attributes = eventEnd.mBuildAttributes; 614 for (InvocationGroupMetricKey groupKey : InvocationGroupMetricKey.values()) { 615 Set<String> attKeys = new HashSet<>(attributes.keySet()); 616 for (String attKey : attKeys) { 617 if (attKey.startsWith(groupKey.toString() + ":")) { 618 String value = attributes.remove(attKey); 619 String group = attKey.split(":", 2)[1]; 620 if (groupKey.shouldAdd()) { 621 try { 622 InvocationMetricLogger.addInvocationMetrics( 623 groupKey, group, Long.parseLong(value)); 624 } catch (NumberFormatException e) { 625 CLog.d( 626 "Key %s doesn't have a number value, was: %s.", 627 groupKey, value); 628 InvocationMetricLogger.addInvocationMetrics( 629 groupKey, group, value); 630 } 631 } else { 632 InvocationMetricLogger.addInvocationMetrics(groupKey, group, value); 633 } 634 attributes.remove(attKey); 635 } 636 } 637 } 638 for (InvocationMetricKey key : InvocationMetricKey.values()) { 639 if (!attributes.containsKey(key.toString())) { 640 continue; 641 } 642 String val = attributes.remove(key.toString()); 643 if (key.shouldAdd()) { 644 try { 645 InvocationMetricLogger.addInvocationMetrics(key, Long.parseLong(val)); 646 } catch (NumberFormatException e) { 647 CLog.d("Key %s doesn't have a number value, was: %s.", key, val); 648 // If it's not a number then, let the string concatenate 649 InvocationMetricLogger.addInvocationMetrics(key, val); 650 } 651 } else { 652 InvocationMetricLogger.addInvocationMetrics(key, val); 653 } 654 attributes.remove(key.toString()); 655 } 656 if (attributes.containsKey(TfObjectTracker.TF_OBJECTS_TRACKING_KEY)) { 657 String val = attributes.get(TfObjectTracker.TF_OBJECTS_TRACKING_KEY); 658 for (String pair : Splitter.on(",").split(val)) { 659 if (!pair.contains("=")) { 660 continue; 661 } 662 String[] pairSplit = pair.split("="); 663 try { 664 TfObjectTracker.directCount(pairSplit[0], Long.parseLong(pairSplit[1])); 665 } catch (NumberFormatException e) { 666 CLog.e(e); 667 continue; 668 } 669 } 670 attributes.remove(TfObjectTracker.TF_OBJECTS_TRACKING_KEY); 671 } 672 infos.get(0).addBuildAttributes(attributes); 673 } 674 } 675 } 676 677 /** 678 * Returns the start time associated with the invocation start event from the subprocess 679 * invocation. 680 */ getStartTime()681 public Long getStartTime() { 682 return mStartTime; 683 } 684 685 /** Returns the test that is currently in progress. */ getCurrentTest()686 public TestDescription getCurrentTest() { 687 return mCurrentTestCase; 688 } 689 690 /** Returns whether or not an invocation failed was reported. */ reportedInvocationFailed()691 public boolean reportedInvocationFailed() { 692 return (mReportedInvocationFailedEventInfo != null); 693 } 694 695 /** Returns reported invocation failure event info. */ getReportedInvocationFailedEventInfo()696 public InvocationFailedEventInfo getReportedInvocationFailedEventInfo() { 697 return mReportedInvocationFailedEventInfo; 698 } 699 700 /** Complete and close any left open events */ completeModuleEvents()701 public void completeModuleEvents() { 702 if (mCurrentRunName == null && mCurrentModuleContext != null) { 703 String moduleId = 704 mCurrentModuleContext 705 .getAttributes() 706 .getUniqueMap() 707 .get(ModuleDefinition.MODULE_ID); 708 mListener.testRunStarted(moduleId, 0); 709 } 710 if (mCurrentTestCase != null) { 711 FailureDescription failure = 712 FailureDescription.create( 713 "Run was interrupted after starting, results are incomplete."); 714 mListener.testFailed(mCurrentTestCase, failure); 715 mListener.testEnded(mCurrentTestCase, new HashMap<String, Metric>()); 716 } 717 if (mCurrentModuleContext != null || mCurrentRunName != null) { 718 FailureDescription failure = 719 FailureDescription.create( 720 "Run was interrupted after starting, results are incomplete.", 721 FailureStatus.INFRA_FAILURE); 722 mListener.testRunFailed(failure); 723 mListener.testRunEnded(0L, new HashMap<String, Metric>()); 724 mCurrentRunName = null; 725 } 726 if (mCurrentModuleContext != null) { 727 mListener.testModuleEnded(); 728 } 729 } 730 } 731