Bug 1034267 - Structured Logging for robocop. r=gbrown, a=test-only
authorAhmed Kachkach <ahmed.kachkach@gmail.com>
Tue, 29 Jul 2014 14:11:00 +0200
changeset 217484 1e06f748a672c1b52fc896e934c0554da0dd87c7
parent 217483 ee1695fc5e0b98fd664a58ce7053fa4244ad01f4
child 217485 76460bbfb47f1edc14ebf4c3b75d5096d801a0ca
push id515
push userraliiev@mozilla.com
push dateMon, 06 Oct 2014 12:51:51 +0000
treeherdermozilla-release@267c7a481bef [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersgbrown, test-only
bugs1034267
milestone33.0a2
Bug 1034267 - Structured Logging for robocop. r=gbrown, a=test-only
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
@@ -373,16 +373,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
@@ -1774,18 +1774,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)
@@ -2077,12 +2075,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]
@@ -847,14 +778,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()