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.log.LogUtil.CLog; 21 import com.android.tradefed.result.FileInputStreamSource; 22 import com.android.tradefed.result.ILogSaverListener; 23 import com.android.tradefed.result.ITestInvocationListener; 24 import com.android.tradefed.result.InputStreamSource; 25 import com.android.tradefed.result.TestDescription; 26 import com.android.tradefed.util.SubprocessEventHelper.BaseTestEventInfo; 27 import com.android.tradefed.util.SubprocessEventHelper.FailedTestEventInfo; 28 import com.android.tradefed.util.SubprocessEventHelper.InvocationEndedEventInfo; 29 import com.android.tradefed.util.SubprocessEventHelper.InvocationFailedEventInfo; 30 import com.android.tradefed.util.SubprocessEventHelper.InvocationStartedEventInfo; 31 import com.android.tradefed.util.SubprocessEventHelper.LogAssociationEventInfo; 32 import com.android.tradefed.util.SubprocessEventHelper.TestEndedEventInfo; 33 import com.android.tradefed.util.SubprocessEventHelper.TestLogEventInfo; 34 import com.android.tradefed.util.SubprocessEventHelper.TestModuleStartedEventInfo; 35 import com.android.tradefed.util.SubprocessEventHelper.TestRunEndedEventInfo; 36 import com.android.tradefed.util.SubprocessEventHelper.TestRunFailedEventInfo; 37 import com.android.tradefed.util.SubprocessEventHelper.TestRunStartedEventInfo; 38 import com.android.tradefed.util.SubprocessEventHelper.TestStartedEventInfo; 39 import com.android.tradefed.util.proto.TfMetricProtoUtil; 40 41 import org.json.JSONException; 42 import org.json.JSONObject; 43 44 import java.io.BufferedReader; 45 import java.io.Closeable; 46 import java.io.File; 47 import java.io.FileNotFoundException; 48 import java.io.FileOutputStream; 49 import java.io.FileReader; 50 import java.io.IOException; 51 import java.io.InputStreamReader; 52 import java.net.ServerSocket; 53 import java.net.Socket; 54 import java.util.ArrayList; 55 import java.util.HashMap; 56 import java.util.List; 57 import java.util.Map; 58 import java.util.concurrent.CountDownLatch; 59 import java.util.concurrent.TimeUnit; 60 import java.util.regex.Matcher; 61 import java.util.regex.Pattern; 62 63 /** 64 * Extends {@link FileOutputStream} to parse the output before writing to the file so we can 65 * generate the test events on the launcher side. 66 */ 67 public class SubprocessTestResultsParser implements Closeable { 68 69 private ITestInvocationListener mListener; 70 71 private TestDescription mCurrentTest = null; 72 private IInvocationContext mCurrentModuleContext = null; 73 74 private Pattern mPattern = null; 75 private Map<String, EventHandler> mHandlerMap = null; 76 private EventReceiverThread mEventReceiver = null; 77 private IInvocationContext mContext = null; 78 private Long mStartTime = null; 79 80 /** Relevant test status keys. */ 81 public static class StatusKeys { 82 public static final String INVOCATION_FAILED = "INVOCATION_FAILED"; 83 public static final String TEST_ASSUMPTION_FAILURE = "TEST_ASSUMPTION_FAILURE"; 84 public static final String TEST_ENDED = "TEST_ENDED"; 85 public static final String TEST_FAILED = "TEST_FAILED"; 86 public static final String TEST_IGNORED = "TEST_IGNORED"; 87 public static final String TEST_STARTED = "TEST_STARTED"; 88 public static final String TEST_RUN_ENDED = "TEST_RUN_ENDED"; 89 public static final String TEST_RUN_FAILED = "TEST_RUN_FAILED"; 90 public static final String TEST_RUN_STARTED = "TEST_RUN_STARTED"; 91 public static final String TEST_MODULE_STARTED = "TEST_MODULE_STARTED"; 92 public static final String TEST_MODULE_ENDED = "TEST_MODULE_ENDED"; 93 public static final String TEST_LOG = "TEST_LOG"; 94 public static final String LOG_ASSOCIATION = "LOG_ASSOCIATION"; 95 public static final String INVOCATION_STARTED = "INVOCATION_STARTED"; 96 public static final String INVOCATION_ENDED = "INVOCATION_ENDED"; 97 } 98 99 /** 100 * Internal receiver thread class with a socket. 101 */ 102 private class EventReceiverThread extends Thread { 103 private ServerSocket mSocket; 104 private CountDownLatch mCountDown; 105 private boolean mShouldParse = true; 106 EventReceiverThread()107 public EventReceiverThread() throws IOException { 108 super("EventReceiverThread"); 109 mSocket = new ServerSocket(0); 110 mCountDown = new CountDownLatch(1); 111 } 112 getLocalPort()113 protected int getLocalPort() { 114 return mSocket.getLocalPort(); 115 } 116 getCountDown()117 protected CountDownLatch getCountDown() { 118 return mCountDown; 119 } 120 cancel()121 public void cancel() throws IOException { 122 if (mSocket != null) { 123 mSocket.close(); 124 } 125 } 126 127 /** 128 * When reaching some issues, we might want to terminate the buffer of the socket to spy 129 * which events are still in the pipe. 130 */ stopParsing()131 public void stopParsing() { 132 mShouldParse = false; 133 } 134 135 @Override run()136 public void run() { 137 Socket client = null; 138 BufferedReader in = null; 139 try { 140 client = mSocket.accept(); 141 in = new BufferedReader(new InputStreamReader(client.getInputStream())); 142 String event = null; 143 while ((event = in.readLine()) != null) { 144 try { 145 if (mShouldParse) { 146 CLog.d("received event: '%s'", event); 147 parse(event); 148 } else { 149 CLog.d("Skipping parsing of event: '%s'", event); 150 } 151 } catch (JSONException e) { 152 CLog.e(e); 153 } 154 } 155 } catch (IOException e) { 156 CLog.e(e); 157 } finally { 158 StreamUtil.close(in); 159 mCountDown.countDown(); 160 } 161 CLog.d("EventReceiverThread done."); 162 } 163 } 164 165 /** 166 * If the event receiver is being used, ensure that we wait for it to terminate. 167 * 168 * @param millis timeout in milliseconds. 169 * @return True if receiver thread terminate before timeout, False otherwise. 170 */ joinReceiver(long millis)171 public boolean joinReceiver(long millis) { 172 if (mEventReceiver != null) { 173 try { 174 CLog.i("Waiting for events to finish being processed."); 175 if (!mEventReceiver.getCountDown().await(millis, TimeUnit.MILLISECONDS)) { 176 mEventReceiver.stopParsing(); 177 CLog.e("Event receiver thread did not complete. Some events may be missing."); 178 return false; 179 } 180 } catch (InterruptedException e) { 181 CLog.e(e); 182 throw new RuntimeException(e); 183 } 184 } 185 return true; 186 } 187 188 /** 189 * Returns the socket receiver that was open. -1 if none. 190 */ getSocketServerPort()191 public int getSocketServerPort() { 192 if (mEventReceiver != null) { 193 return mEventReceiver.getLocalPort(); 194 } 195 return -1; 196 } 197 198 @Override close()199 public void close() throws IOException { 200 if (mEventReceiver != null) { 201 mEventReceiver.cancel(); 202 } 203 } 204 205 /** 206 * Constructor for the result parser 207 * 208 * @param listener {@link ITestInvocationListener} where to report the results 209 * @param streaming if True, a socket receiver will be open to receive results. 210 * @param context a {@link IInvocationContext} information about the invocation 211 */ SubprocessTestResultsParser( ITestInvocationListener listener, boolean streaming, IInvocationContext context)212 public SubprocessTestResultsParser( 213 ITestInvocationListener listener, boolean streaming, IInvocationContext context) 214 throws IOException { 215 this(listener, context); 216 if (streaming) { 217 mEventReceiver = new EventReceiverThread(); 218 mEventReceiver.start(); 219 } 220 } 221 222 /** 223 * Constructor for the result parser 224 * 225 * @param listener {@link ITestInvocationListener} where to report the results 226 * @param context a {@link IInvocationContext} information about the invocation 227 */ SubprocessTestResultsParser( ITestInvocationListener listener, IInvocationContext context)228 public SubprocessTestResultsParser( 229 ITestInvocationListener listener, IInvocationContext context) { 230 mListener = listener; 231 mContext = context; 232 StringBuilder sb = new StringBuilder(); 233 sb.append(StatusKeys.INVOCATION_FAILED).append("|"); 234 sb.append(StatusKeys.TEST_ASSUMPTION_FAILURE).append("|"); 235 sb.append(StatusKeys.TEST_ENDED).append("|"); 236 sb.append(StatusKeys.TEST_FAILED).append("|"); 237 sb.append(StatusKeys.TEST_IGNORED).append("|"); 238 sb.append(StatusKeys.TEST_STARTED).append("|"); 239 sb.append(StatusKeys.TEST_RUN_ENDED).append("|"); 240 sb.append(StatusKeys.TEST_RUN_FAILED).append("|"); 241 sb.append(StatusKeys.TEST_RUN_STARTED).append("|"); 242 sb.append(StatusKeys.TEST_MODULE_STARTED).append("|"); 243 sb.append(StatusKeys.TEST_MODULE_ENDED).append("|"); 244 sb.append(StatusKeys.TEST_LOG).append("|"); 245 sb.append(StatusKeys.LOG_ASSOCIATION).append("|"); 246 sb.append(StatusKeys.INVOCATION_STARTED).append("|"); 247 sb.append(StatusKeys.INVOCATION_ENDED); 248 String patt = String.format("(.*)(%s)( )(.*)", sb.toString()); 249 mPattern = Pattern.compile(patt); 250 251 // Create Handler map for each event 252 mHandlerMap = new HashMap<String, EventHandler>(); 253 mHandlerMap.put(StatusKeys.INVOCATION_FAILED, new InvocationFailedEventHandler()); 254 mHandlerMap.put(StatusKeys.TEST_ASSUMPTION_FAILURE, 255 new TestAssumptionFailureEventHandler()); 256 mHandlerMap.put(StatusKeys.TEST_ENDED, new TestEndedEventHandler()); 257 mHandlerMap.put(StatusKeys.TEST_FAILED, new TestFailedEventHandler()); 258 mHandlerMap.put(StatusKeys.TEST_IGNORED, new TestIgnoredEventHandler()); 259 mHandlerMap.put(StatusKeys.TEST_STARTED, new TestStartedEventHandler()); 260 mHandlerMap.put(StatusKeys.TEST_RUN_ENDED, new TestRunEndedEventHandler()); 261 mHandlerMap.put(StatusKeys.TEST_RUN_FAILED, new TestRunFailedEventHandler()); 262 mHandlerMap.put(StatusKeys.TEST_RUN_STARTED, new TestRunStartedEventHandler()); 263 mHandlerMap.put(StatusKeys.TEST_MODULE_STARTED, new TestModuleStartedEventHandler()); 264 mHandlerMap.put(StatusKeys.TEST_MODULE_ENDED, new TestModuleEndedEventHandler()); 265 mHandlerMap.put(StatusKeys.TEST_LOG, new TestLogEventHandler()); 266 mHandlerMap.put(StatusKeys.LOG_ASSOCIATION, new LogAssociationEventHandler()); 267 mHandlerMap.put(StatusKeys.INVOCATION_STARTED, new InvocationStartedEventHandler()); 268 mHandlerMap.put(StatusKeys.INVOCATION_ENDED, new InvocationEndedEventHandler()); 269 } 270 parseFile(File file)271 public void parseFile(File file) { 272 BufferedReader reader = null; 273 try { 274 reader = new BufferedReader(new FileReader(file)); 275 } catch (FileNotFoundException e) { 276 CLog.e(e); 277 throw new RuntimeException(e); 278 } 279 ArrayList<String> listString = new ArrayList<String>(); 280 String line = null; 281 try { 282 while ((line = reader.readLine()) != null) { 283 listString.add(line); 284 } 285 reader.close(); 286 } catch (IOException e) { 287 CLog.e(e); 288 throw new RuntimeException(e); 289 } 290 processNewLines(listString.toArray(new String[listString.size()])); 291 } 292 293 /** 294 * call parse on each line of the array to extract the events if any. 295 */ processNewLines(String[] lines)296 public void processNewLines(String[] lines) { 297 for (String line : lines) { 298 try { 299 parse(line); 300 } catch (JSONException e) { 301 CLog.e("Exception while parsing"); 302 CLog.e(e); 303 throw new RuntimeException(e); 304 } 305 } 306 } 307 308 /** 309 * Parse a line, if it matches one of the events, handle it. 310 */ parse(String line)311 private void parse(String line) throws JSONException { 312 Matcher matcher = mPattern.matcher(line); 313 if (matcher.find()) { 314 EventHandler handler = mHandlerMap.get(matcher.group(2)); 315 if (handler != null) { 316 handler.handleEvent(matcher.group(4)); 317 } else { 318 CLog.w("No handler found matching: %s", matcher.group(2)); 319 } 320 } 321 } 322 checkCurrentTestId(String className, String testName)323 private void checkCurrentTestId(String className, String testName) { 324 if (mCurrentTest == null) { 325 mCurrentTest = new TestDescription(className, testName); 326 CLog.w("Calling a test event without having called testStarted."); 327 } 328 } 329 330 /** 331 * Interface for event handling 332 */ 333 interface EventHandler { handleEvent(String eventJson)334 public void handleEvent(String eventJson) throws JSONException; 335 } 336 337 private class TestRunStartedEventHandler implements EventHandler { 338 @Override handleEvent(String eventJson)339 public void handleEvent(String eventJson) throws JSONException { 340 TestRunStartedEventInfo rsi = new TestRunStartedEventInfo(new JSONObject(eventJson)); 341 if (rsi.mAttempt != null && rsi.mAttempt != 0) { 342 mListener.testRunStarted(rsi.mRunName, rsi.mTestCount, rsi.mAttempt); 343 } else { 344 mListener.testRunStarted(rsi.mRunName, rsi.mTestCount); 345 } 346 } 347 } 348 349 private class TestRunFailedEventHandler implements EventHandler { 350 @Override handleEvent(String eventJson)351 public void handleEvent(String eventJson) throws JSONException { 352 TestRunFailedEventInfo rfi = new TestRunFailedEventInfo(new JSONObject(eventJson)); 353 mListener.testRunFailed(rfi.mReason); 354 } 355 } 356 357 private class TestRunEndedEventHandler implements EventHandler { 358 @Override handleEvent(String eventJson)359 public void handleEvent(String eventJson) throws JSONException { 360 try { 361 TestRunEndedEventInfo rei = new TestRunEndedEventInfo(new JSONObject(eventJson)); 362 // TODO: Parse directly as proto. 363 mListener.testRunEnded( 364 rei.mTime, TfMetricProtoUtil.upgradeConvert(rei.mRunMetrics)); 365 } finally { 366 mCurrentTest = null; 367 } 368 } 369 } 370 371 private class InvocationFailedEventHandler implements EventHandler { 372 @Override handleEvent(String eventJson)373 public void handleEvent(String eventJson) throws JSONException { 374 InvocationFailedEventInfo ifi = 375 new InvocationFailedEventInfo(new JSONObject(eventJson)); 376 mListener.invocationFailed(ifi.mCause); 377 } 378 } 379 380 private class TestStartedEventHandler implements EventHandler { 381 @Override handleEvent(String eventJson)382 public void handleEvent(String eventJson) throws JSONException { 383 TestStartedEventInfo bti = new TestStartedEventInfo(new JSONObject(eventJson)); 384 mCurrentTest = new TestDescription(bti.mClassName, bti.mTestName); 385 if (bti.mStartTime != null) { 386 mListener.testStarted(mCurrentTest, bti.mStartTime); 387 } else { 388 mListener.testStarted(mCurrentTest); 389 } 390 } 391 } 392 393 private class TestFailedEventHandler implements EventHandler { 394 @Override handleEvent(String eventJson)395 public void handleEvent(String eventJson) throws JSONException { 396 FailedTestEventInfo fti = new FailedTestEventInfo(new JSONObject(eventJson)); 397 checkCurrentTestId(fti.mClassName, fti.mTestName); 398 mListener.testFailed(mCurrentTest, fti.mTrace); 399 } 400 } 401 402 private class TestEndedEventHandler implements EventHandler { 403 @Override handleEvent(String eventJson)404 public void handleEvent(String eventJson) throws JSONException { 405 try { 406 TestEndedEventInfo tei = new TestEndedEventInfo(new JSONObject(eventJson)); 407 checkCurrentTestId(tei.mClassName, tei.mTestName); 408 if (tei.mEndTime != null) { 409 mListener.testEnded( 410 mCurrentTest, 411 tei.mEndTime, 412 TfMetricProtoUtil.upgradeConvert(tei.mRunMetrics)); 413 } else { 414 mListener.testEnded( 415 mCurrentTest, TfMetricProtoUtil.upgradeConvert(tei.mRunMetrics)); 416 } 417 } finally { 418 mCurrentTest = null; 419 } 420 } 421 } 422 423 private class TestIgnoredEventHandler implements EventHandler { 424 @Override handleEvent(String eventJson)425 public void handleEvent(String eventJson) throws JSONException { 426 BaseTestEventInfo baseTestIgnored = new BaseTestEventInfo(new JSONObject(eventJson)); 427 checkCurrentTestId(baseTestIgnored.mClassName, baseTestIgnored.mTestName); 428 mListener.testIgnored(mCurrentTest); 429 } 430 } 431 432 private class TestAssumptionFailureEventHandler implements EventHandler { 433 @Override handleEvent(String eventJson)434 public void handleEvent(String eventJson) throws JSONException { 435 FailedTestEventInfo FailedAssumption = 436 new FailedTestEventInfo(new JSONObject(eventJson)); 437 checkCurrentTestId(FailedAssumption.mClassName, FailedAssumption.mTestName); 438 mListener.testAssumptionFailure(mCurrentTest, FailedAssumption.mTrace); 439 } 440 } 441 442 private class TestModuleStartedEventHandler implements EventHandler { 443 @Override handleEvent(String eventJson)444 public void handleEvent(String eventJson) throws JSONException { 445 TestModuleStartedEventInfo module = 446 new TestModuleStartedEventInfo(new JSONObject(eventJson)); 447 mCurrentModuleContext = module.mModuleContext; 448 mListener.testModuleStarted(module.mModuleContext); 449 } 450 } 451 452 private class TestModuleEndedEventHandler implements EventHandler { 453 @Override handleEvent(String eventJson)454 public void handleEvent(String eventJson) throws JSONException { 455 if (mCurrentModuleContext == null) { 456 CLog.w("Calling testModuleEnded when testModuleStarted was not called."); 457 } 458 mListener.testModuleEnded(); 459 mCurrentModuleContext = null; 460 } 461 } 462 463 private class TestLogEventHandler implements EventHandler { 464 @Override handleEvent(String eventJson)465 public void handleEvent(String eventJson) throws JSONException { 466 TestLogEventInfo logInfo = new TestLogEventInfo(new JSONObject(eventJson)); 467 String name = String.format("subprocess-%s", logInfo.mDataName); 468 try (InputStreamSource data = new FileInputStreamSource(logInfo.mDataFile, true)) { 469 mListener.testLog(name, logInfo.mLogType, data); 470 } 471 } 472 } 473 474 private class LogAssociationEventHandler implements EventHandler { 475 @Override handleEvent(String eventJson)476 public void handleEvent(String eventJson) throws JSONException { 477 LogAssociationEventInfo assosInfo = 478 new LogAssociationEventInfo(new JSONObject(eventJson)); 479 if (mListener instanceof ILogSaverListener) { 480 ((ILogSaverListener) mListener) 481 .logAssociation(assosInfo.mDataName, assosInfo.mLoggedFile); 482 } 483 } 484 } 485 486 private class InvocationStartedEventHandler implements EventHandler { 487 @Override handleEvent(String eventJson)488 public void handleEvent(String eventJson) throws JSONException { 489 InvocationStartedEventInfo eventStart = 490 new InvocationStartedEventInfo(new JSONObject(eventJson)); 491 if (mContext.getTestTag() == null || "stub".equals(mContext.getTestTag())) { 492 mContext.setTestTag(eventStart.mTestTag); 493 } 494 mStartTime = eventStart.mStartTime; 495 } 496 } 497 498 private class InvocationEndedEventHandler implements EventHandler { 499 @Override handleEvent(String eventJson)500 public void handleEvent(String eventJson) throws JSONException { 501 JSONObject json = new JSONObject(eventJson); 502 InvocationEndedEventInfo eventEnd = new InvocationEndedEventInfo(json); 503 // Add build attributes to the primary build (the first build 504 // provider of the running configuration). 505 List<IBuildInfo> infos = mContext.getBuildInfos(); 506 if (!infos.isEmpty()) { 507 infos.get(0).addBuildAttributes(eventEnd.mBuildAttributes); 508 } 509 } 510 } 511 512 /** 513 * Returns the start time associated with the invocation start event from the subprocess 514 * invocation. 515 */ getStartTime()516 public Long getStartTime() { 517 return mStartTime; 518 } 519 520 /** Returns the test that is currently in progress. */ getCurrentTest()521 public TestDescription getCurrentTest() { 522 return mCurrentTest; 523 } 524 } 525