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