Bug 1034267 - Structured Logging for robocop. r=gbrown

build/mobile/remoteautomation.py

@@ -266,7 +266,7 @@ def read_stdout(self):
             messages = []
             for line in lines:
                 # This passes the line to the logger (to be logged or buffered)
-                # and returns a list of structured messages (dict) or None, depending on the log
+                # and returns a list of structured messages (dict)
                 parsed_messages = self.messageLogger.write(line)
                 for message in parsed_messages:
                     if message['action'] == 'test_start':

build/mobile/robocop/FennecMochitestAssert.java

@@ -25,17 +25,28 @@ public class FennecMochitestAssert implements Assert {
     // Measure the time it takes to run test case
     private long mStartTime = 0;
 
-    public FennecMochitestAssert() {
-    }
+    // Structured logger
+    private StructuredLogger mLogger;
 
     /** Write information to a logfile and logcat */
     public void dumpLog(String message) {
-        FennecNativeDriver.log(FennecNativeDriver.LogLevel.INFO, message);
+        mLogger.info(message);
     }
 
-    /** Write information to a logfile and logcat */
     public void dumpLog(String message, Throwable t) {
-        FennecNativeDriver.log(FennecNativeDriver.LogLevel.INFO, message, t);
+        mLogger.error(message + " - " + t.toString());
+    }
+
+    /** Write information to a logfile and logcat */
+    static class DumpLogCallback implements StructuredLogger.LoggerCallback {
+        public void call(String output) {
+            FennecNativeDriver.log(FennecNativeDriver.LogLevel.INFO, output);
+        }
+    }
+
+
+    public FennecMochitestAssert() {
+        mLogger = new StructuredLogger("robocop", new DumpLogCallback());
     }
 
     /** Set the filename used for dumpLog. */
@@ -44,15 +55,13 @@ public void setLogFile(String filename) {
 
         String message;
         if (!mLogStarted) {
-            dumpLog("SimpleTest START");
+            mLogger.info("SimpleTest START");
             mLogStarted = true;
         }
 
         if (mLogTestName != "") {
             long diff = SystemClock.uptimeMillis() - mStartTime;
-            message = "TEST-END | " + mLogTestName;
-            message += " | finished in " + diff + "ms";
-            dumpLog(message);
+            mLogger.testEnd(mLogTestName, "OK", "finished in " + diff + "ms");
             mLogTestName = "";
         }
     }
@@ -62,7 +71,7 @@ public void setTestName(String testName) {
         mLogTestName = nameParts[nameParts.length - 1];
         mStartTime = SystemClock.uptimeMillis();
 
-        dumpLog("TEST-START | " + mLogTestName);
+        mLogger.testStart(mLogTestName);
     }
 
     class testInfo {
@@ -81,21 +90,22 @@ public testInfo(boolean r, String n, String d, boolean t, boolean i) {
 
     }
 
-    private void _logMochitestResult(testInfo test, String passString, String failString) {
+    /** Used to log a subtest's result.
+     * test represents the subtest (an assertion).
+     * passStatus and passExpected are the actual status and the expected status if the assertion is true.
+     * failStatus and failExpected are the actual status and the expected status otherwise.
+     */
+    private void _logMochitestResult(testInfo test, String passStatus, String passExpected, String failStatus, String failExpected) {
         boolean isError = true;
-        String resultString = failString;
         if (test.mResult || test.mTodo) {
             isError = false;
         }
         if (test.mResult)
         {
-            resultString = passString;
+            mLogger.testStatus(mLogTestName, test.mName, passStatus, passExpected, test.mDiag);
+        } else {
+            mLogger.testStatus(mLogTestName, test.mName, failStatus, failExpected, test.mDiag);
         }
-        String diag = test.mName;
-        if (test.mDiag != null) diag += " - " + test.mDiag;
-
-        String message = resultString + " | " + mLogTestName + " | " + diag;
-        dumpLog(message);
 
         if (test.mInfo) {
             // do not count TEST-INFO messages
@@ -107,6 +117,8 @@ private void _logMochitestResult(testInfo test, String passString, String failSt
             mPassed++;
         }
         if (isError) {
+            String message = "TEST-UNEXPECTED-" + failStatus + " | " + mLogTestName + " | "
+                    + test.mName + " - " + test.mDiag;
             junit.framework.Assert.fail(message);
         }
     }
@@ -116,27 +128,20 @@ public void endTest() {
 
         if (mLogTestName != "") {
             long diff = SystemClock.uptimeMillis() - mStartTime;
-            message = "TEST-END | " + mLogTestName;
-            message += " | finished in " + diff + "ms";
-            dumpLog(message);
+            mLogger.testEnd(mLogTestName, "OK", "finished in " + diff + "ms");
             mLogTestName = "";
         }
 
-        message = "TEST-START | Shutdown";
-        dumpLog(message);
-        message = "Passed: " + Integer.toString(mPassed);
-        dumpLog(message);
-        message = "Failed: " + Integer.toString(mFailed);
-        dumpLog(message);
-        message = "Todo: " + Integer.toString(mTodo);
-        dumpLog(message);
-        message = "SimpleTest FINISHED";
-        dumpLog(message);
+        mLogger.info("TEST-START | Shutdown");
+        mLogger.info("Passed: " + Integer.toString(mPassed));
+        mLogger.info("Failed: " + Integer.toString(mFailed));
+        mLogger.info("Todo: " + Integer.toString(mTodo));
+        mLogger.info("SimpleTest FINISHED");
     }
 
     public void ok(boolean condition, String name, String diag) {
         testInfo test = new testInfo(condition, name, diag, false, false);
-        _logMochitestResult(test, "TEST-PASS", "TEST-UNEXPECTED-FAIL");
+        _logMochitestResult(test, "PASS", "PASS", "FAIL", "PASS");
         mTestList.add(test);
     }
 
@@ -193,7 +198,7 @@ private boolean checkPixel(int actual, int r, int g, int b) {
 
     public void todo(boolean condition, String name, String diag) {
         testInfo test = new testInfo(condition, name, diag, true, false);
-        _logMochitestResult(test, "TEST-UNEXPECTED-PASS", "TEST-KNOWN-FAIL");
+        _logMochitestResult(test, "PASS", "FAIL", "FAIL", "FAIL");
         mTestList.add(test);
     }
 
@@ -245,7 +250,6 @@ private String getNotEqualString(Object a, Object b, boolean pass) {
     }
 
     public void info(String name, String message) {
-        testInfo test = new testInfo(true, name, message, false, true);
-        _logMochitestResult(test, "TEST-INFO", "INFO FAILED?");
+        mLogger.info(name + " | " + message);
     }
 }

build/mobile/robocop/StructuredLogger.java

@@ -44,6 +44,10 @@ public StructuredLogger(String name, String component) {
         this(name, component, new StandardLoggerCallback());
     }
 
+    public StructuredLogger(String name,  LoggerCallback callback) {
+        this(name, null, callback);
+    }
+
     public StructuredLogger(String name) {
         this(name, null, new StandardLoggerCallback());
     }

testing/mochitest/mach_commands.py

@@ -373,6 +373,8 @@ def run_desktop_test(self, context, suite=None, test_paths=None, debugger=None,
             for error in runner.message_logger.errors:
                 runner.message_logger.logger.log_raw(error)
 
+        runner.message_logger.finish()
+
         return result
 
 

testing/mochitest/runtests.py

@@ -1777,8 +1777,6 @@ def doTests(self, options, onLaunch=None, testsToFilter=None):
 
     log.info("runtests.py | Running tests: end.")
 
-    self.message_logger.finish()
-
     if self.manifest is not None:
       self.cleanup(options)
 
@@ -2060,7 +2058,10 @@ def main():
   if options.symbolsPath and not isURL(options.symbolsPath):
     options.symbolsPath = mochitest.getFullPath(options.symbolsPath)
 
-  sys.exit(mochitest.runTests(options))
+  return_code = mochitest.runTests(options)
+  mochitest.message_logger.finish()
+
+  sys.exit(return_code)
 
 if __name__ == "__main__":
   main()

testing/mochitest/runtestsb2g.py

@@ -206,7 +206,6 @@ def on_output(line):
         self.stopServers()
 
         log.info("runtestsb2g.py | Running tests: end.")
-        self.message_logger.finish()
 
         if manifest is not None:
             self.cleanup(manifest, options)
@@ -366,6 +365,8 @@ def run_remote_mochitests(parser, options):
             pass
         retVal = 1
 
+    mochitest.message_logger.finish()
+
     sys.exit(retVal)
 
 def run_desktop_mochitests(parser, options):
@@ -391,7 +392,10 @@ def run_desktop_mochitests(parser, options):
 
     options.browserArgs += ['-marionette']
 
-    sys.exit(mochitest.runTests(options, onLaunch=mochitest.startTests))
+    retVal = mochitest.runTests(options, onLaunch=mochitest.startTests)
+    mochitest.message_logger.finish()
+
+    sys.exit(retVal)
 
 def main():
     parser = B2GOptions()

testing/mochitest/runtestsremote.py

@@ -577,76 +577,6 @@ def runApp(self, *args, **kwargs):
 
         return self._automation.runApp(*args, **kwargs)
 
-class RobocopMochiRemote(MochiRemote):
-    """This class maintains compatibility with the robocop logging system
-    that is still unstructured."""
-
-    def addLogData(self):
-        with open(self.localLog) as currentLog:
-            data = currentLog.readlines()
-
-        restart = re.compile('SimpleTest START.*')
-        reend = re.compile('TEST-START . Shutdown.*')
-        refail = re.compile('TEST-UNEXPECTED-FAIL.*')
-        start_found = False
-        end_found = False
-        fail_found = False
-        for line in data:
-            if reend.match(line):
-                end_found = True
-                start_found = False
-                break
-
-            if start_found and not end_found:
-                self.logMessages.append(line)
-
-            if restart.match(line):
-                start_found = True
-            if refail.match(line):
-                fail_found = True
-        result = 0
-        if fail_found:
-            result = 1
-        if not end_found:
-            log.error("Automation Error: Missing end of test marker (process crashed?)")
-            result = 1
-        return result
-
-    def printLog(self):
-        passed = 0
-        failed = 0
-        todo = 0
-        incr = 1
-        logFile = []
-        logFile.append("0 INFO SimpleTest START")
-        for line in self.logMessages:
-            if line.startswith("TEST-PASS"):
-                passed += 1
-            elif line.startswith("TEST-UNEXPECTED"):
-                failed += 1
-            elif line.startswith("TEST-KNOWN"):
-                todo += 1
-            incr += 1
-
-        logFile.append("%s INFO TEST-START | Shutdown" % incr)
-        incr += 1
-        logFile.append("%s INFO Passed: %s" % (incr, passed))
-        incr += 1
-        logFile.append("%s INFO Failed: %s" % (incr, failed))
-        incr += 1
-        logFile.append("%s INFO Todo: %s" % (incr, todo))
-        incr += 1
-        logFile.append("%s INFO SimpleTest FINISHED" % incr)
-
-        # TODO: Consider not printing to stdout because we might be duplicating output
-        print '\n'.join(logFile)
-        with open(self.localLog, 'w') as localLog:
-            localLog.write('\n'.join(logFile))
-
-        if failed > 0:
-            return 1
-        return 0
-
 def main():
     message_logger = MessageLogger(logger=log)
     process_args = {'messageLogger': message_logger}
@@ -674,8 +604,7 @@ def main():
         auto.setProduct(options.remoteProductName)
     auto.setAppName(options.remoteappname)
 
-    mochitest_cls = RobocopMochiRemote if options.robocopIni != "" else MochiRemote
-    mochitest = mochitest_cls(auto, dm, options, message_logger)
+    mochitest = MochiRemote(auto, dm, options, message_logger)
 
     options = parser.verifyOptions(options, mochitest)
     if (options == None):
@@ -720,6 +649,8 @@ def main():
             tests.append(test['name'])
         # suite_start message when running robocop tests
         log.suite_start(tests)
+        # turning buffering off as it's not used in robocop
+        message_logger.buffering = False
 
         if options.totalChunks:
             tests_per_chunk = math.ceil(len(tests) / (options.totalChunks * 1.0))
@@ -851,6 +782,7 @@ def main():
                 pass
             retVal = 1
 
+    message_logger.finish()
     mochitest.printDeviceInfo(printLogcat=True)
 
     sys.exit(retVal)