Bug 1034267 - Structured Logging for robocop. r=gbrown
authorAhmed Kachkach <ahmed.kachkach@gmail.com>
Tue, 29 Jul 2014 14:11:00 +0200
changeset 218398 f3a5a084d90e9c1373b0153a6ab64c32ceebe0ad
parent 218397 d6f4c1ab65b67540376327484d901370191dccc4
child 218399 2110743da2b99a0a9550e32d5197c8a87b4f297b
push id3979
push userraliiev@mozilla.com
push dateMon, 13 Oct 2014 16:35:44 +0000
treeherdermozilla-beta@30f2cc610691 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersgbrown
bugs1034267
milestone34.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
Bug 1034267 - Structured Logging for robocop. r=gbrown
build/mobile/remoteautomation.py
build/mobile/robocop/FennecMochitestAssert.java
build/mobile/robocop/StructuredLogger.java
testing/mochitest/mach_commands.py
testing/mochitest/runtests.py
testing/mochitest/runtestsb2g.py
testing/mochitest/runtestsremote.py
--- a/build/mobile/remoteautomation.py
+++ b/build/mobile/remoteautomation.py
@@ -261,17 +261,17 @@ class RemoteAutomation(Automation):
                 return
 
             # We only keep the last (unfinished) line in the buffer
             self.logBuffer = lines[-1]
             del lines[-1]
             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':
                         self.lastTestSeen = message['test']
                 messages += parsed_messages
             return messages
 
         @property
--- a/build/mobile/robocop/FennecMochitestAssert.java
+++ b/build/mobile/robocop/FennecMochitestAssert.java
@@ -20,54 +20,63 @@ public class FennecMochitestAssert imple
     private boolean mLogStarted = false;
 
     // Used to write the test-start/test-end log lines
     private String mLogTestName = "";
 
     // 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);
+    }
+
+    public void dumpLog(String message, Throwable t) {
+        mLogger.error(message + " - " + t.toString());
     }
 
     /** Write information to a logfile and logcat */
-    public void dumpLog(String message, Throwable t) {
-        FennecNativeDriver.log(FennecNativeDriver.LogLevel.INFO, message, t);
+    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. */
     public void setLogFile(String filename) {
         FennecNativeDriver.setLogFile(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 = "";
         }
     }
 
     public void setTestName(String testName) {
         String[] nameParts = testName.split("\\.");
         mLogTestName = nameParts[nameParts.length - 1];
         mStartTime = SystemClock.uptimeMillis();
 
-        dumpLog("TEST-START | " + mLogTestName);
+        mLogger.testStart(mLogTestName);
     }
 
     class testInfo {
         public boolean mResult;
         public String mName;
         public String mDiag;
         public boolean mTodo;
         public boolean mInfo;
@@ -76,72 +85,68 @@ public class FennecMochitestAssert imple
             mName = n;
             mDiag = d;
             mTodo = t;
             mInfo = 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
         } else if (test.mTodo) {
             mTodo++;
         } else if (isError) {
             mFailed++;
         } else {
             mPassed++;
         }
         if (isError) {
+            String message = "TEST-UNEXPECTED-" + failStatus + " | " + mLogTestName + " | "
+                    + test.mName + " - " + test.mDiag;
             junit.framework.Assert.fail(message);
         }
     }
 
     public void endTest() {
         String message;
 
         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);
     }
 
     public void is(Object actual, Object expected, String name) {
         boolean pass = checkObjectsEqual(actual, expected);
         ok(pass, name, getEqualString(actual, expected, pass));
     }
 
@@ -188,17 +193,17 @@ public class FennecMochitestAssert imple
             return true;
         } else {
             return false;
         }
     }
 
     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);
     }
 
     public void todo_is(Object actual, Object expected, String name) {
         boolean pass = checkObjectsEqual(actual, expected);
         todo(pass, name, getEqualString(actual, expected, pass));
     }
 
@@ -240,12 +245,11 @@ public class FennecMochitestAssert imple
     private String getNotEqualString(Object a, Object b, boolean pass) {
         if(pass) {
             return a + " should not equal " + b;
         }
         return "didn't expect " + a + ", but got it";
     }
 
     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);
     }
 }
--- a/build/mobile/robocop/StructuredLogger.java
+++ b/build/mobile/robocop/StructuredLogger.java
@@ -39,16 +39,20 @@ public class StructuredLogger {
         mComponent = component;
         mCallback = callback;
     }
 
     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());
     }
 
     public void suiteStart(List<String> tests, Map<String, Object> runInfo) {
         HashMap<String, Object> data = new HashMap<String, Object>();
         data.put("tests", tests);
         if (runInfo != null) {
--- a/testing/mochitest/mach_commands.py
+++ b/testing/mochitest/mach_commands.py
@@ -368,16 +368,18 @@ class MochitestRunner(MozbuildObject):
 
         self.log_manager.disable_unstructured()
         if runner.message_logger.errors:
             result = 1
             runner.message_logger.logger.warning("The following tests failed:")
             for error in runner.message_logger.errors:
                 runner.message_logger.logger.log_raw(error)
 
+        runner.message_logger.finish()
+
         return result
 
 
 def MochitestCommand(func):
     """Decorator that adds shared command arguments to mochitest commands."""
 
     # This employs light Python magic. Keep in mind a decorator is just a
     # function that takes a function, does something with it, then returns a
--- a/testing/mochitest/runtests.py
+++ b/testing/mochitest/runtests.py
@@ -1772,18 +1772,16 @@ class Mochitest(MochitestUtilsMixin):
     if self.nsprLogs:
       with zipfile.ZipFile("%s/nsprlog.zip" % browserEnv["MOZ_UPLOAD_DIR"], "w", zipfile.ZIP_DEFLATED) as logzip:
         for logfile in glob.glob("%s/nspr*.log*" % tempfile.gettempdir()):
           logzip.write(logfile)
           os.remove(logfile)
 
     log.info("runtests.py | Running tests: end.")
 
-    self.message_logger.finish()
-
     if self.manifest is not None:
       self.cleanup(options)
 
     return status
 
   def handleTimeout(self, timeout, proc, utilityPath, debuggerInfo, browserProcessId, testPath=None):
     """handle process output timeout"""
     # TODO: bug 913975 : _processOutput should call self.processOutputLine one more time one timeout (I think)
@@ -2055,12 +2053,15 @@ def main():
     # parsing error
     sys.exit(1)
 
   options.utilityPath = mochitest.getFullPath(options.utilityPath)
   options.certPath = mochitest.getFullPath(options.certPath)
   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()
--- a/testing/mochitest/runtestsb2g.py
+++ b/testing/mochitest/runtestsb2g.py
@@ -201,17 +201,16 @@ class B2GMochitest(MochitestUtilsMixin):
             log.error("Automation Error: Received unexpected exception while running application\n")
             if hasattr(self, 'runner'):
                 self.runner.check_for_crashes()
             status = 1
 
         self.stopServers()
 
         log.info("runtestsb2g.py | Running tests: end.")
-        self.message_logger.finish()
 
         if manifest is not None:
             self.cleanup(manifest, options)
         return status
 
     def getGMPPluginPath(self, options):
         # TODO: bug 1043403
         return None
@@ -361,16 +360,18 @@ def run_remote_mochitests(parser, option
         traceback.print_exc()
         mochitest.stopServers()
         try:
             mochitest.cleanup(None, options)
         except:
             pass
         retVal = 1
 
+    mochitest.message_logger.finish()
+
     sys.exit(retVal)
 
 def run_desktop_mochitests(parser, options):
     # create our Marionette instance
     marionette_args = {}
     if options.marionette:
         host, port = options.marionette.split(':')
         marionette_args['host'] = host
@@ -386,17 +387,20 @@ def run_desktop_mochitests(parser, optio
     if options == None:
         sys.exit(1)
 
     if options.desktop and not options.profile:
         raise Exception("must specify --profile when specifying --desktop")
 
     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()
     options, args = parser.parse_args()
 
     if options.desktop:
         run_desktop_mochitests(parser, options)
     else:
--- a/testing/mochitest/runtestsremote.py
+++ b/testing/mochitest/runtestsremote.py
@@ -572,86 +572,16 @@ class MochiRemote(Mochitest):
         # it trying to set up ssltunnel as well
         kwargs['runSSLTunnel'] = False
 
         if 'quiet' in kwargs:
             kwargs.pop('quiet')
 
         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}
     auto = RemoteAutomation(None, "fennec", processArgs=process_args)
     parser = RemoteOptions(auto)
     options, args = parser.parse_args()
 
     if (options.dm_trans == "adb"):
@@ -669,18 +599,17 @@ def main():
 
     productPieces = options.remoteProductName.split('.')
     if (productPieces != None):
         auto.setProduct(productPieces[0])
     else:
         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):
         sys.exit(1)
 
     logParent = os.path.dirname(options.remoteLogFile)
     dm.mkDir(logParent);
     auto.setRemoteLog(options.remoteLogFile)
@@ -715,16 +644,18 @@ def main():
         mp.read(options.robocopIni)
         robocop_tests = mp.active_tests(exists=False, **mozinfo.info)
         tests = []
         my_tests = tests
         for test in robocop_tests:
             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))
             start = int(round((options.thisChunk-1) * tests_per_chunk))
             end = int(round(options.thisChunk * tests_per_chunk))
             if end > len(tests):
                 end = len(tests)
             my_tests = tests[start:end]
@@ -846,14 +777,15 @@ def main():
             mochitest.stopServers()
             try:
                 mochitest.cleanup(options)
             except devicemanager.DMError:
                 # device error cleaning up... oh well!
                 pass
             retVal = 1
 
+    message_logger.finish()
     mochitest.printDeviceInfo(printLogcat=True)
 
     sys.exit(retVal)
 
 if __name__ == "__main__":
     main()