ddmlib/testrunner/InstrumentationResultParser.java

/*
 * Copyright (C) 2008 The Android Open Source Project
 *
 * Licensed under the Apache License, Version 2.0 (the "License");
 * you may not use this file except in compliance with the License.
 * You may obtain a copy of the License at
 *
 *      http://www.apache.org/licenses/LICENSE-2.0
 *
 * Unless required by applicable law or agreed to in writing, software
 * distributed under the License is distributed on an "AS IS" BASIS,
 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
 * See the License for the specific language governing permissions and
 * limitations under the License.
 */

package com.android.ddmlib.testrunner;

import com.android.ddmlib.IShellOutputReceiver;
import com.android.ddmlib.Log;
import com.android.ddmlib.MultiLineReceiver;

import java.util.ArrayList;
import java.util.Collection;
import java.util.HashMap;
import java.util.HashSet;
import java.util.Map;
import java.util.Set;
import java.util.regex.Matcher;
import java.util.regex.Pattern;

/**
 * Parses the 'raw output mode' results of an instrumentation test run from shell and informs a
 * ITestRunListener of the results.
 *
 * <p>Expects the following output:
 *
 * <p>If fatal error occurred when attempted to run the tests:
 * <pre>
 * INSTRUMENTATION_STATUS: Error=error Message
 * INSTRUMENTATION_FAILED:
 * </pre>
 * <p>or
 * <pre>
 * INSTRUMENTATION_RESULT: shortMsg=error Message
 * </pre>
 *
 * <p>Otherwise, expect a series of test results, each one containing a set of status key/value
 * pairs, delimited by a start(1)/pass(0)/fail(-2)/error(-1) status code result. At end of test
 * run, expects that the elapsed test time in seconds will be displayed
 *
 * <p>For example:
 * <pre>
 * INSTRUMENTATION_STATUS_CODE: 1
 * INSTRUMENTATION_STATUS: class=com.foo.FooTest
 * INSTRUMENTATION_STATUS: test=testFoo
 * INSTRUMENTATION_STATUS: numtests=2
 * INSTRUMENTATION_STATUS: stack=com.foo.FooTest#testFoo:312
 *    com.foo.X
 * INSTRUMENTATION_STATUS_CODE: -2
 * ...
 *
 * Time: X
 * </pre>
 * <p>Note that the "value" portion of the key-value pair may wrap over several text lines
 */
public class InstrumentationResultParser extends MultiLineReceiver {

    /** Relevant test status keys. */
    private static class StatusKeys {
        private static final String TEST = "test";
        private static final String CLASS = "class";
        private static final String STACK = "stack";
        private static final String NUMTESTS = "numtests";
        private static final String ERROR = "Error";
        private static final String SHORTMSG = "shortMsg";
    }

    /** The set of expected status keys. Used to filter which keys should be stored as metrics */
    private static final Set<String> KNOWN_KEYS = new HashSet<String>();
    static {
        KNOWN_KEYS.add(StatusKeys.TEST);
        KNOWN_KEYS.add(StatusKeys.CLASS);
        KNOWN_KEYS.add(StatusKeys.STACK);
        KNOWN_KEYS.add(StatusKeys.NUMTESTS);
        KNOWN_KEYS.add(StatusKeys.ERROR);
        KNOWN_KEYS.add(StatusKeys.SHORTMSG);
        // unused, but regularly occurring status keys.
        KNOWN_KEYS.add("stream");
        KNOWN_KEYS.add("id");
        KNOWN_KEYS.add("current");
    }

    /** Test result status codes. */
    private static class StatusCodes {
        private static final int FAILURE = -2;
        private static final int START = 1;
        private static final int ERROR = -1;
        private static final int OK = 0;
        private static final int IN_PROGRESS = 2;
    }

    /** Prefixes used to identify output. */
    private static class Prefixes {
        private static final String STATUS = "INSTRUMENTATION_STATUS: ";
        private static final String STATUS_CODE = "INSTRUMENTATION_STATUS_CODE: ";
        private static final String STATUS_FAILED = "INSTRUMENTATION_FAILED: ";
        private static final String CODE = "INSTRUMENTATION_CODE: ";
        private static final String RESULT = "INSTRUMENTATION_RESULT: ";
        private static final String TIME_REPORT = "Time: ";
    }

    private final Collection<ITestRunListener> mTestListeners;

    /**
     * Test result data
     */
    private static class TestResult {
        private Integer mCode = null;
        private String mTestName = null;
        private String mTestClass = null;
        private String mStackTrace = null;
        private Integer mNumTests = null;

        /** Returns true if all expected values have been parsed */
        boolean isComplete() {
            return mCode != null && mTestName != null && mTestClass != null;
        }

        /** Provides a more user readable string for TestResult, if possible */
        @Override
        public String toString() {
            StringBuilder output = new StringBuilder();
            if (mTestClass != null ) {
                output.append(mTestClass);
                output.append('#');
            }
            if (mTestName != null) {
                output.append(mTestName);
            }
            if (output.length() > 0) {
                return output.toString();
            }
            return "unknown result";
        }
    }

    /** the name to provide to {@link ITestRunListener#testRunStarted(String, int)} */
    private final String mTestRunName;

    /** Stores the status values for the test result currently being parsed */
    private TestResult mCurrentTestResult = null;

    /** Stores the status values for the test result last parsed */
    private TestResult mLastTestResult = null;

    /** Stores the current "key" portion of the status key-value being parsed. */
    private String mCurrentKey = null;

    /** Stores the current "value" portion of the status key-value being parsed. */
    private StringBuilder mCurrentValue = null;

    /** True if start of test has already been reported to listener. */
    private boolean mTestStartReported = false;

    /** True if the completion of the test run has been detected. */
    private boolean mTestRunFinished = false;

    /** True if test run failure has already been reported to listener. */
    private boolean mTestRunFailReported = false;

    /** The elapsed time of the test run, in milliseconds. */
    private long mTestTime = 0;

    /** True if current test run has been canceled by user. */
    private boolean mIsCancelled = false;

    /** The number of tests currently run  */
    private int mNumTestsRun = 0;

    /** The number of tests expected to run  */
    private int mNumTestsExpected = 0;

    /** True if the parser is parsing a line beginning with "INSTRUMENTATION_RESULT" */
    private boolean mInInstrumentationResultKey = false;

    /**
     * Stores key-value pairs under INSTRUMENTATION_RESULT header, these are printed at the
     * end of a test run, if applicable
     */
    private Map<String, String> mInstrumentationResultBundle = new HashMap<String, String>();

    /**
     * Stores key-value pairs of metrics emitted during the execution of each test case.  Note that
     * standard keys that are stored in the TestResults class are filtered out of this Map.
     */
    private Map<String, String> mTestMetrics = new HashMap<String, String>();

    private static final String LOG_TAG = "InstrumentationResultParser";

    /** Error message supplied when no parseable test results are received from test run. */
    static final String NO_TEST_RESULTS_MSG = "No test results";

    /** Error message supplied when a test start bundle is parsed, but not the test end bundle. */
    static final String INCOMPLETE_TEST_ERR_MSG_PREFIX = "Test failed to run to completion";
    static final String INCOMPLETE_TEST_ERR_MSG_POSTFIX = "Check device logcat for details";

    /** Error message supplied when the test run is incomplete. */
    static final String INCOMPLETE_RUN_ERR_MSG_PREFIX = "Test run failed to complete";

    /**
     * Creates the InstrumentationResultParser.
     *
     * @param runName the test run name to provide to
     *            {@link ITestRunListener#testRunStarted(String, int)}
     * @param listeners informed of test results as the tests are executing
     */
    public InstrumentationResultParser(String runName, Collection<ITestRunListener> listeners) {
        mTestRunName = runName;
        mTestListeners = new ArrayList<ITestRunListener>(listeners);
    }

    /**
     * Creates the InstrumentationResultParser for a single listener.
     *
     * @param runName the test run name to provide to
     *            {@link ITestRunListener#testRunStarted(String, int)}
     * @param listener informed of test results as the tests are executing
     */
    public InstrumentationResultParser(String runName, ITestRunListener listener) {
        mTestRunName = runName;
        mTestListeners = new ArrayList<ITestRunListener>(1);
        mTestListeners.add(listener);
    }

    /**
     * Processes the instrumentation test output from shell.
     *
     * @see MultiLineReceiver#processNewLines
     */
    @Override
    public void processNewLines(String[] lines) {
        for (String line : lines) {
            parse(line);
            // in verbose mode, dump all adb output to log
            Log.v(LOG_TAG, line);
        }
    }

    /**
     * Parse an individual output line. Expects a line that is one of:
     * <ul>
     * <li>
     * The start of a new status line (starts with Prefixes.STATUS or Prefixes.STATUS_CODE),
     * and thus there is a new key=value pair to parse, and the previous key-value pair is
     * finished.
     * </li>
     * <li>
     * A continuation of the previous status (the "value" portion of the key has wrapped
     * to the next line).
     * </li>
     * <li> A line reporting a fatal error in the test run (Prefixes.STATUS_FAILED) </li>
     * <li> A line reporting the total elapsed time of the test run. (Prefixes.TIME_REPORT) </li>
     * </ul>
     *
     * @param line  Text output line
     */
    private void parse(String line) {
        if (line.startsWith(Prefixes.STATUS_CODE)) {
            // Previous status key-value has been collected. Store it.
            submitCurrentKeyValue();
            mInInstrumentationResultKey = false;
            parseStatusCode(line);
        } else if (line.startsWith(Prefixes.STATUS)) {
            // Previous status key-value has been collected. Store it.
            submitCurrentKeyValue();
            mInInstrumentationResultKey = false;
            parseKey(line, Prefixes.STATUS.length());
        } else if (line.startsWith(Prefixes.RESULT)) {
            // Previous status key-value has been collected. Store it.
            submitCurrentKeyValue();
            mInInstrumentationResultKey = true;
            parseKey(line, Prefixes.RESULT.length());
        } else if (line.startsWith(Prefixes.STATUS_FAILED) ||
                   line.startsWith(Prefixes.CODE)) {
            // Previous status key-value has been collected. Store it.
            submitCurrentKeyValue();
            mInInstrumentationResultKey = false;
            // these codes signal the end of the instrumentation run
            mTestRunFinished = true;
            // just ignore the remaining data on this line
        } else if (line.startsWith(Prefixes.TIME_REPORT)) {
            parseTime(line);
        } else {
            if (mCurrentValue != null) {
                // this is a value that has wrapped to next line.
                mCurrentValue.append("\r\n");
                mCurrentValue.append(line);
            } else if (line.trim().length() > 0){
                Log.d(LOG_TAG, "unrecognized line " + line);
            }
        }
    }

    /**
     * Stores the currently parsed key-value pair in the appropriate place.
     */
    private void submitCurrentKeyValue() {
        if (mCurrentKey != null && mCurrentValue != null) {
            String statusValue = mCurrentValue.toString();
            if (mInInstrumentationResultKey) {
                if (!KNOWN_KEYS.contains(mCurrentKey)) {
                    mInstrumentationResultBundle.put(mCurrentKey, statusValue);
                } else if (mCurrentKey.equals(StatusKeys.SHORTMSG)) {
                    // test run must have failed
                    handleTestRunFailed(String.format("Instrumentation run failed due to '%1$s'",
                            statusValue));
                }
            } else {
                TestResult testInfo = getCurrentTestInfo();

                if (mCurrentKey.equals(StatusKeys.CLASS)) {
                    testInfo.mTestClass = statusValue.trim();
                } else if (mCurrentKey.equals(StatusKeys.TEST)) {
                    testInfo.mTestName = statusValue.trim();
                } else if (mCurrentKey.equals(StatusKeys.NUMTESTS)) {
                    try {
                        testInfo.mNumTests = Integer.parseInt(statusValue);
                    } catch (NumberFormatException e) {
                        Log.w(LOG_TAG, "Unexpected integer number of tests, received "
                                + statusValue);
                    }
                } else if (mCurrentKey.equals(StatusKeys.ERROR)) {
                    // test run must have failed
                    handleTestRunFailed(statusValue);
                } else if (mCurrentKey.equals(StatusKeys.STACK)) {
                    testInfo.mStackTrace = statusValue;
                } else if (!KNOWN_KEYS.contains(mCurrentKey)) {
                    // Not one of the recognized key/value pairs, so dump it in mTestMetrics
                    mTestMetrics.put(mCurrentKey, statusValue);
                }
            }

            mCurrentKey = null;
            mCurrentValue = null;
        }
    }

    /**
     * A utility method to return the test metrics from the current test case execution and get
     * ready for the next one.
     */
    private Map<String, String> getAndResetTestMetrics() {
        Map<String, String> retVal = mTestMetrics;
        mTestMetrics = new HashMap<String, String>();
        return retVal;
    }

    private TestResult getCurrentTestInfo() {
        if (mCurrentTestResult == null) {
            mCurrentTestResult = new TestResult();
        }
        return mCurrentTestResult;
    }

    private void clearCurrentTestInfo() {
        mLastTestResult = mCurrentTestResult;
        mCurrentTestResult = null;
    }

    /**
     * Parses the key from the current line.
     * Expects format of "key=value".
     *
     * @param line full line of text to parse
     * @param keyStartPos the starting position of the key in the given line
     */
    private void parseKey(String line, int keyStartPos) {
        int endKeyPos = line.indexOf('=', keyStartPos);
        if (endKeyPos != -1) {
            mCurrentKey = line.substring(keyStartPos, endKeyPos).trim();
            parseValue(line, endKeyPos + 1);
        }
    }

    /**
     * Parses the start of a key=value pair.
     *
     * @param line - full line of text to parse
     * @param valueStartPos - the starting position of the value in the given line
     */
    private void parseValue(String line, int valueStartPos) {
        mCurrentValue = new StringBuilder();
        mCurrentValue.append(line.substring(valueStartPos));
    }

    /**
     * Parses out a status code result.
     */
    private void parseStatusCode(String line) {
        String value = line.substring(Prefixes.STATUS_CODE.length()).trim();
        TestResult testInfo = getCurrentTestInfo();
        testInfo.mCode = StatusCodes.ERROR;
        try {
            testInfo.mCode = Integer.parseInt(value);
        } catch (NumberFormatException e) {
            Log.w(LOG_TAG, "Expected integer status code, received: " + value);
            testInfo.mCode = StatusCodes.ERROR;
        }
        if (testInfo.mCode != StatusCodes.IN_PROGRESS) {
            // this means we're done with current test result bundle
            reportResult(testInfo);
            clearCurrentTestInfo();
        }
    }

    /**
     * Returns true if test run canceled.
     *
     * @see IShellOutputReceiver#isCancelled()
     */
    public boolean isCancelled() {
        return mIsCancelled;
    }

    /**
     * Requests cancellation of test run.
     */
    public void cancel() {
        mIsCancelled = true;
    }

    /**
     * Reports a test result to the test run listener. Must be called when a individual test
     * result has been fully parsed.
     *
     * @param statusMap key-value status pairs of test result
     */
    private void reportResult(TestResult testInfo) {
        if (!testInfo.isComplete()) {
            Log.w(LOG_TAG, "invalid instrumentation status bundle " + testInfo.toString());
            return;
        }
        reportTestRunStarted(testInfo);
        TestIdentifier testId = new TestIdentifier(testInfo.mTestClass, testInfo.mTestName);
        Map<String, String> metrics;

        switch (testInfo.mCode) {
            case StatusCodes.START:
                for (ITestRunListener listener : mTestListeners) {
                    listener.testStarted(testId);
                }
                break;
            case StatusCodes.FAILURE:
                metrics = getAndResetTestMetrics();
                for (ITestRunListener listener : mTestListeners) {
                    listener.testFailed(ITestRunListener.TestFailure.FAILURE, testId,
                        getTrace(testInfo));

                    listener.testEnded(testId, metrics);
                }
                mNumTestsRun++;
                break;
            case StatusCodes.ERROR:
                metrics = getAndResetTestMetrics();
                for (ITestRunListener listener : mTestListeners) {
                    listener.testFailed(ITestRunListener.TestFailure.ERROR, testId,
                        getTrace(testInfo));
                    listener.testEnded(testId, metrics);
                }
                mNumTestsRun++;
                break;
            case StatusCodes.OK:
                metrics = getAndResetTestMetrics();
                for (ITestRunListener listener : mTestListeners) {
                    listener.testEnded(testId, metrics);
                }
                mNumTestsRun++;
                break;
            default:
                metrics = getAndResetTestMetrics();
                Log.e(LOG_TAG, "Unknown status code received: " + testInfo.mCode);
                for (ITestRunListener listener : mTestListeners) {
                    listener.testEnded(testId, metrics);
                }
                mNumTestsRun++;
            break;
        }

    }

    /**
     * Reports the start of a test run, and the total test count, if it has not been previously
     * reported.
     *
     * @param testInfo current test status values
     */
    private void reportTestRunStarted(TestResult testInfo) {
        // if start test run not reported yet
        if (!mTestStartReported && testInfo.mNumTests != null) {
            for (ITestRunListener listener : mTestListeners) {
                listener.testRunStarted(mTestRunName, testInfo.mNumTests);
            }
            mNumTestsExpected = testInfo.mNumTests;
            mTestStartReported = true;
        }
    }

    /**
     * Returns the stack trace of the current failed test, from the provided testInfo.
     */
    private String getTrace(TestResult testInfo) {
        if (testInfo.mStackTrace != null) {
            return testInfo.mStackTrace;
        } else {
            Log.e(LOG_TAG, "Could not find stack trace for failed test ");
            return new Throwable("Unknown failure").toString();
        }
    }

    /**
     * Parses out and store the elapsed time.
     */
    private void parseTime(String line) {
        final Pattern timePattern = Pattern.compile(String.format("%s\\s*([\\d\\.]+)",
                Prefixes.TIME_REPORT));
        Matcher timeMatcher = timePattern.matcher(line);
        if (timeMatcher.find()) {
            String timeString = timeMatcher.group(1);
            try {
                float timeSeconds = Float.parseFloat(timeString);
                mTestTime = (long) (timeSeconds * 1000);
            } catch (NumberFormatException e) {
                Log.w(LOG_TAG, String.format("Unexpected time format %1$s", line));
            }
        } else {
            Log.w(LOG_TAG, String.format("Unexpected time format %1$s", line));
        }
    }

    /**
     * Process a instrumentation run failure
     */
    void handleTestRunFailed(String errorMsg) {
        errorMsg = (errorMsg == null ? "Unknown error" : errorMsg);
        Log.i(LOG_TAG, String.format("test run failed: '%1$s'", errorMsg));
        if (mLastTestResult != null &&
            mLastTestResult.isComplete() &&
            StatusCodes.START == mLastTestResult.mCode) {

            // received test start msg, but not test complete
            // assume test caused this, report as test failure
            TestIdentifier testId = new TestIdentifier(mLastTestResult.mTestClass,
                    mLastTestResult.mTestName);
            for (ITestRunListener listener : mTestListeners) {
                listener.testFailed(ITestRunListener.TestFailure.ERROR, testId,
                    String.format("%1$s. Reason: '%2$s'. %3$s", INCOMPLETE_TEST_ERR_MSG_PREFIX,
                            errorMsg, INCOMPLETE_TEST_ERR_MSG_POSTFIX));
                listener.testEnded(testId, getAndResetTestMetrics());
            }
        }
        for (ITestRunListener listener : mTestListeners) {
            if (!mTestStartReported) {
                // test run wasn't started - must have crashed before it started
                listener.testRunStarted(mTestRunName, 0);
            }
            listener.testRunFailed(errorMsg);
            listener.testRunEnded(mTestTime, mInstrumentationResultBundle);
        }
        mTestStartReported = true;
        mTestRunFailReported = true;
    }

    /**
     * Called by parent when adb session is complete.
     */
    @Override
    public void done() {
        super.done();
        if (!mTestRunFailReported) {
            handleOutputDone();
        }
    }

    /**
     * Handles the end of the adb session when a test run failure has not been reported yet
     */
    private void handleOutputDone() {
        if (!mTestStartReported && !mTestRunFinished) {
            // no results
            handleTestRunFailed(NO_TEST_RESULTS_MSG);
        } else if (mNumTestsExpected > mNumTestsRun) {
            final String message =
                String.format("%1$s. Expected %2$d tests, received %3$d",
                        INCOMPLETE_RUN_ERR_MSG_PREFIX, mNumTestsExpected, mNumTestsRun);
            handleTestRunFailed(message);
        } else {
            for (ITestRunListener listener : mTestListeners) {
                if (!mTestStartReported) {
                    // test run wasn't started, but it finished successfully. Must be a run with
                    // no tests
                    listener.testRunStarted(mTestRunName, 0);
                }
                listener.testRunEnded(mTestTime, mInstrumentationResultBundle);
            }
        }
    }
}