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.testtype; 17 18 import com.android.ddmlib.testrunner.ITestRunListener; 19 import com.android.tradefed.log.LogUtil.CLog; 20 import com.android.tradefed.result.ITestLifeCycleReceiver; 21 import com.android.tradefed.result.TestDescription; 22 23 import org.json.JSONArray; 24 import org.json.JSONException; 25 import org.json.JSONObject; 26 27 import java.text.ParseException; 28 import java.text.SimpleDateFormat; 29 import java.util.ArrayList; 30 import java.util.Collection; 31 import java.util.Collections; 32 import java.util.Date; 33 import java.util.HashMap; 34 import java.util.Iterator; 35 import java.util.Map; 36 import java.util.Map.Entry; 37 38 /** 39 * Interprets the output of tests run with Python's unit test framework and translates it into 40 * calls on a series of {@link ITestRunListener}s. Output from these tests follows this 41 * EBNF grammar: 42 */ 43 public class VtsMultiDeviceTestResultParser { 44 45 // Parser state 46 String[] mAllLines; 47 String mCurrentLine; 48 int mLineNum; 49 ParserState mCurrentParseState = ParserState.TEST_CASE_ENTRY; 50 51 // Current test state 52 String mTestClass; 53 TestDescription mCurrentTestId; 54 String mCurrentTraceback; 55 long mTotalElapsedTime = 0; 56 57 // General state 58 private Map<TestDescription, String> mTestResultCache; 59 private final Collection<ITestLifeCycleReceiver> mListeners; 60 private String mRunName = null; 61 private String mCurrentTestName = null; 62 private int mTotalTestCount = 0; 63 64 // Variables to keep track of state for unit test 65 private int mNumTestsRun = 0; 66 private int mNumTestsExpected = 1; 67 68 // Constant tokens that appear in the result grammar. 69 static final String CASE_OK = "ok"; 70 static final String RUN_OK = "OK"; 71 static final String RUN_FAILED = "FAILED"; 72 static final String TEST_CASE = "[Test Case]"; 73 static final String PASS = "PASS"; 74 static final String FAIL = "FAIL"; 75 static final String TIMEOUT = "TIMEOUT"; 76 static final String SKIP = "SKIP"; 77 static final String ERROR = "ERROR"; 78 static final String END_PATTERN = "<=========="; 79 static final String BEGIN_PATTERN = "==========>"; 80 81 // constants for parsing json file 82 static final String RESULTS = "Results"; 83 static final String BEGIN_TIME = "Begin Time"; 84 static final String DETAILS = "Details"; 85 static final String TABLES = "Tables"; 86 static final String END_TIME = "End Time"; 87 static final String TEST_CLASS = "Test Class"; 88 static final String TEST_NAME = "Test Name"; 89 static final String RESULT = "Result"; 90 static final String CLASS_ERRORS = "Class Errors"; 91 92 // default message for test failure 93 static final String UNKNOWN_ERROR = "Unknown error."; 94 static final String UNKNOWN_FAILURE = "Unknown failure."; 95 static final String UNKNOWN_TIMEOUT = "Unknown timeout."; 96 97 // Enumeration for parser state. 98 static enum ParserState { 99 TEST_CASE_ENTRY, 100 COMPLETE, 101 TEST_RUN 102 } 103 104 private class PythonUnitTestParseException extends Exception { PythonUnitTestParseException(String reason)105 public PythonUnitTestParseException(String reason) { 106 super(reason); 107 } 108 } 109 VtsMultiDeviceTestResultParser(ITestLifeCycleReceiver listener, String runName)110 public VtsMultiDeviceTestResultParser(ITestLifeCycleReceiver listener, String runName) { 111 mListeners = new ArrayList<>(1); 112 mListeners.add(listener); 113 mRunName = runName; 114 mTestResultCache = new HashMap<>(); 115 } 116 processNewLines(String[] lines)117 public void processNewLines(String[] lines) { 118 init(lines); 119 120 // extract the test class name if pattern matches for the first line 121 String[] toks = mCurrentLine.split(" "); 122 if (toks.length < 3 || !toks[toks.length - 1].equals(END_PATTERN) || !toks[toks.length - 3]. 123 equals(BEGIN_PATTERN)) { 124 try { 125 parseError(BEGIN_PATTERN); 126 } catch (PythonUnitTestParseException e) { 127 e.printStackTrace(); 128 } 129 } else { 130 mTestClass = toks[toks.length - 2]; 131 } 132 133 // parse all lines 134 for (String line : lines) { 135 if (line.length() == 0 || !line.contains(TEST_CASE)) { 136 continue; 137 } 138 mCurrentLine = line; 139 try { 140 parse(); 141 } catch (PythonUnitTestParseException e) { 142 e.printStackTrace(); 143 } 144 } 145 146 // current state should not be in TEST_RUN state; if it's then mark for timeout. 147 if (mCurrentParseState.equals(ParserState.TEST_RUN)) { 148 markTestTimeout(); 149 } 150 summary(lines); 151 completeTestRun(); 152 mNumTestsRun++; 153 } 154 155 /** 156 * Called by parent when adb session is complete. 157 */ done()158 public void done() { 159 if (mNumTestsRun < mNumTestsExpected) { 160 handleTestRunFailed(String.format("Test run failed. Expected %d tests, received %d", 161 mNumTestsExpected, mNumTestsRun)); 162 } 163 } 164 165 /** 166 * Process an instrumentation run failure 167 * 168 * @param errorMsg The message to output about the nature of the error 169 */ handleTestRunFailed(String errorMsg)170 private void handleTestRunFailed(String errorMsg) { 171 errorMsg = (errorMsg == null ? "Unknown error" : errorMsg); 172 CLog.e(String.format("Test run failed: %s", errorMsg)); 173 174 Map<String, String> emptyMap = Collections.emptyMap(); 175 for (ITestLifeCycleReceiver listener : mListeners) { 176 listener.testFailed(mCurrentTestId, FAIL); 177 listener.testEnded(mCurrentTestId, emptyMap); 178 } 179 180 // Report the test run failed 181 for (ITestLifeCycleReceiver listener : mListeners) { 182 listener.testRunFailed(errorMsg); 183 } 184 } 185 init(String[] lines)186 void init(String[] lines) { 187 mAllLines = lines; 188 mLineNum = 0; 189 mCurrentLine = mAllLines[0]; 190 } 191 192 /** 193 * This method parses individual lines and calls functions based on the parsing state. 194 * @throws PythonUnitTestParseException 195 */ parse()196 void parse() throws PythonUnitTestParseException { 197 try { 198 switch(mCurrentParseState) { 199 case TEST_CASE_ENTRY: 200 registerTest(); 201 mCurrentParseState = ParserState.TEST_RUN; 202 break; 203 case TEST_RUN: 204 if (testRun()) { 205 mCurrentParseState = ParserState.COMPLETE; 206 } else { 207 // incomplete test due to timeout. 208 mCurrentParseState = ParserState.TEST_CASE_ENTRY; 209 parse(); 210 } 211 break; 212 case COMPLETE: 213 mCurrentParseState = ParserState.TEST_CASE_ENTRY; 214 parse(); 215 break; 216 default: 217 break; 218 } 219 } catch (ArrayIndexOutOfBoundsException e) { 220 CLog.d("Underlying error in testResult: " + e); 221 throw new PythonUnitTestParseException("FailMessage"); 222 } 223 } 224 225 /** 226 * This is called whenever the parser state is {@link ParserState#TEST_RUN} 227 */ testRun()228 private boolean testRun() { 229 // process the test case 230 String[] toks = mCurrentLine.split(" "); 231 // check the last token 232 String lastToken = toks[toks.length - 1]; 233 if (lastToken.equals(PASS)){ 234 markTestSuccess(); 235 return true; 236 } else if (lastToken.equals(FAIL)){ 237 markTestFailure(); 238 return true; 239 } else if (lastToken.equals(SKIP)){ 240 // SKIP is not a recognized test type in TradeFed. 241 return true; 242 } else { 243 markTestTimeout(); 244 return false; 245 } 246 } 247 248 /** 249 * This method is called when parser is at {@link ParserState#TEST_CASE_ENTRY}} stage and 250 * this registers a new test case. 251 */ registerTest()252 private void registerTest() { 253 // process the test case 254 String[] toks = mCurrentLine.split(" "); 255 mCurrentTestName = toks[toks.length - 1]; 256 mCurrentTestId = new TestDescription(mTestClass, mCurrentTestName); 257 mTotalTestCount++; 258 } 259 /** 260 * Called at the end of the parsing to calculate the {@link #mTotalElapsedTime} 261 * 262 * @param lines The corresponding logs. 263 */ summary(String[] lines)264 void summary(String[] lines) { 265 if (lines == null || lines.length == 0) { 266 mTotalElapsedTime = 0; 267 return; 268 } 269 270 Date startDate = getDate(lines, true); 271 Date endDate = getDate(lines, false); 272 273 if (startDate == null || endDate == null) { 274 mTotalElapsedTime = 0; 275 return; 276 } 277 mTotalElapsedTime = endDate.getTime() - startDate.getTime(); 278 } 279 280 /** 281 * Return the time in milliseconds to calculate the time elapsed in a particular test. 282 * 283 * @param lines The logs that need to be parsed. 284 * @param calculateStartDate flag which is true if we need to calculate start date. 285 * @return {Date} the start and end time corresponding to a test. 286 */ getDate(String[] lines, boolean calculateStartDate)287 private Date getDate(String[] lines, boolean calculateStartDate) { 288 Date date = null; 289 int begin = calculateStartDate ? 0 : lines.length - 1; 290 int diff = calculateStartDate ? 1 : -1; 291 292 for (int index = begin; index >= 0 && index < lines.length; index += diff) { 293 lines[index].trim(); 294 String[] toks = lines[index].split(" "); 295 296 // set the start time from the first line 297 // the loop should continue if exception occurs, else it can break 298 if (toks.length < 3) { 299 continue; 300 } 301 String time = toks[2]; 302 SimpleDateFormat sdf = new SimpleDateFormat("HH:mm:ss.SSS"); 303 try { 304 date = sdf.parse(time); 305 } catch (ParseException e) { 306 continue; 307 } 308 break; 309 } 310 return date; 311 } 312 completeTestRun()313 boolean completeTestRun() { 314 for (ITestLifeCycleReceiver listener : mListeners) { 315 // do testRunStarted 316 listener.testRunStarted(mCurrentTestName, mTotalTestCount); 317 318 // mark each test passed or failed 319 for (Entry<TestDescription, String> test : mTestResultCache.entrySet()) { 320 listener.testStarted(test.getKey()); 321 if (test.getValue() == PASS) { 322 listener.testEnded(test.getKey(), Collections.<String, String>emptyMap()); 323 } else if (test.getValue() == TIMEOUT) { 324 listener.testFailed(test.getKey(), test.getValue()); 325 // Always call testEnded at the end of the test case 326 listener.testEnded(test.getKey(), Collections.emptyMap()); 327 } else if (test.getValue() == SKIP) { 328 listener.testAssumptionFailure(test.getKey(), test.getValue()); 329 // Always call testEnded at the end of the test case 330 listener.testEnded(test.getKey(), Collections.emptyMap()); 331 } else { 332 listener.testFailed(test.getKey(), test.getValue()); 333 // Always call testEnded at the end of the test case 334 listener.testEnded(test.getKey(), Collections.emptyMap()); 335 } 336 } 337 listener.testRunEnded(mTotalElapsedTime, Collections.<String, String>emptyMap()); 338 } 339 return true; 340 } 341 printJsonTable(String name, JSONArray table)342 private static void printJsonTable(String name, JSONArray table) throws JSONException { 343 ArrayList<Integer> columnLength = new ArrayList<Integer>(); 344 for (int rowIndex = 0; rowIndex < table.length(); rowIndex++) { 345 JSONArray row = table.getJSONArray(rowIndex); 346 for (int colIndex = 0; colIndex < row.length(); colIndex++) { 347 if (columnLength.size() == colIndex) { 348 columnLength.add(1); 349 } 350 if (!row.isNull(colIndex)) { 351 int len = row.getString(colIndex).length(); 352 if (columnLength.get(colIndex) < len) { 353 columnLength.set(colIndex, len); 354 } 355 } 356 } 357 } 358 StringBuilder sb = new StringBuilder(name + "\n"); 359 for (int rowIndex = 0; rowIndex < table.length(); rowIndex++) { 360 JSONArray row = table.getJSONArray(rowIndex); 361 for (int colIndex = 0; colIndex < row.length(); colIndex++) { 362 String cell = row.isNull(colIndex) ? "" : row.getString(colIndex); 363 if (colIndex > 0) { 364 sb.append(" "); 365 } 366 int padLength = columnLength.get(colIndex) - cell.length(); 367 for (int padCount = 0; padCount < padLength; padCount++) { 368 sb.append(" "); 369 } 370 sb.append(cell); 371 } 372 sb.append("\n"); 373 } 374 CLog.d("JSON table: %s", sb.toString()); 375 } 376 377 /** 378 * This method parses the json object and summarizes the test result through listener. 379 * @param object 380 * @throws RuntimeException 381 */ processJsonFile(JSONObject object)382 public void processJsonFile(JSONObject object) throws RuntimeException { 383 try { 384 JSONArray results = object.getJSONArray(RESULTS); 385 if (results == null) { 386 results = new JSONArray(); 387 } 388 for (ITestLifeCycleReceiver listener : mListeners) { 389 long elapsedTime; 390 if (results.length() > 0) { 391 long firstBeginTime = (long) results.getJSONObject(0).get(BEGIN_TIME); 392 long lastEndTime = 393 (long) results.getJSONObject(results.length() - 1).get(END_TIME); 394 elapsedTime = lastEndTime - firstBeginTime; 395 } else { 396 elapsedTime = 0; 397 CLog.e("JSONArray is null."); 398 } 399 400 int nNonSkippedTests = 0; 401 for (int index = 0; index < results.length(); index++) { 402 JSONObject resultObject = results.getJSONObject(index); 403 String result = (String) resultObject.get(RESULT); 404 if (!result.equals(SKIP)) { 405 nNonSkippedTests++; 406 } 407 } 408 409 listener.testRunStarted(mRunName, nNonSkippedTests); 410 411 for (int index = 0; index < results.length(); index++) { 412 JSONObject resultObject = results.getJSONObject(index); 413 String result = (String) resultObject.get(RESULT); 414 String testClass = (String) resultObject.get(TEST_CLASS); 415 String testName = (String) resultObject.get(TEST_NAME); 416 long beginTime = (long) results.getJSONObject(index).get(BEGIN_TIME); 417 long endTime = (long) results.getJSONObject(index).get(END_TIME); 418 String details = 419 resultObject.isNull(DETAILS) ? "" : resultObject.getString(DETAILS); 420 421 // mark test started 422 TestDescription TestDescription = new TestDescription(testClass, testName); 423 424 /* SKIP is not recognized in TF. Does not report result instead. */ 425 if (!result.equals(SKIP)) { 426 listener.testStarted(TestDescription, beginTime); 427 428 switch (result) { 429 case PASS: 430 break; 431 case ERROR: 432 /* Error is reported by the VTS runner when an unexpected exception 433 happened during test execution. It could be due to: a framework 434 bug, an unhandled I/O, a TCP error, or a bug in test module or 435 template execution code. Error thus does not necessarily indicate 436 a test failure or a bug in device implementation. Since error is 437 not yet recognized in TF, it is converted to FAIL. */ 438 case TIMEOUT: 439 /* Timeout is not recognized in TF. Use FAIL instead. */ 440 case FAIL: 441 /* Indicates a test failure. */ 442 listener.testFailed(TestDescription, 443 details.isEmpty() ? UNKNOWN_FAILURE : details); 444 break; 445 default: 446 listener.testFailed(TestDescription, 447 "Internal error: Cannot recognize test result type. Details: " 448 + details); 449 break; 450 } 451 452 listener.testEnded(TestDescription, endTime, Collections.emptyMap()); 453 } 454 455 if (!resultObject.isNull(TABLES)) { 456 JSONObject tables = resultObject.getJSONObject(TABLES); 457 Iterator<String> iter = tables.keys(); 458 while (iter.hasNext()) { 459 String key = iter.next(); 460 printJsonTable(key, tables.getJSONArray(key)); 461 } 462 } 463 } 464 465 if (!object.isNull(CLASS_ERRORS)) { 466 listener.testRunFailed(object.getString(CLASS_ERRORS)); 467 } 468 listener.testRunEnded(elapsedTime, Collections.<String, String>emptyMap()); 469 } 470 } catch (JSONException e) { 471 CLog.e("Exception occurred: %s", e); 472 } 473 } 474 475 /** 476 * This is called whenever the program encounters unexpected tokens in parsing. 477 * 478 * @param expected The string that was expected. 479 * @throws PythonUnitTestParseException 480 */ parseError(String expected)481 private void parseError(String expected) 482 throws PythonUnitTestParseException { 483 throw new PythonUnitTestParseException( 484 String.format("Expected \"%s\" on line %d, found %s instead", 485 expected, mLineNum + 1, mCurrentLine)); 486 } 487 markTestSuccess()488 private void markTestSuccess() { 489 mTestResultCache.put(mCurrentTestId, PASS); 490 } 491 markTestFailure()492 private void markTestFailure() { 493 mTestResultCache.put(mCurrentTestId, FAIL); 494 } 495 496 /** 497 * This method is called whenever the current test doesn't finish as expected and runs out 498 * of time. 499 */ markTestTimeout()500 private void markTestTimeout() { 501 mTestResultCache.put(mCurrentTestId, TIMEOUT); 502 } 503 isCancelled()504 public boolean isCancelled() { 505 return false; 506 } 507 } 508