From 4350dd886d052379f963732c1e15cff502da57b6 Mon Sep 17 00:00:00 2001 From: Ahmed Kachkach Date: Tue, 29 Jul 2014 14:11:00 +0200 Subject: [PATCH] Bug 1034267 - Structured Logging for robocop. r=gbrown --- build/mobile/remoteautomation.py | 2 +- .../mobile/robocop/FennecMochitestAssert.java | 74 +++++++++--------- build/mobile/robocop/StructuredLogger.java | 4 + testing/mochitest/mach_commands.py | 2 + testing/mochitest/runtests.py | 7 +- testing/mochitest/runtestsb2g.py | 8 +- testing/mochitest/runtestsremote.py | 76 +------------------ 7 files changed, 60 insertions(+), 113 deletions(-) diff --git a/build/mobile/remoteautomation.py b/build/mobile/remoteautomation.py index 1eab11cf0c1..1592f0f19d6 100644 --- a/build/mobile/remoteautomation.py +++ b/build/mobile/remoteautomation.py @@ -266,7 +266,7 @@ class RemoteAutomation(Automation): 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': diff --git a/build/mobile/robocop/FennecMochitestAssert.java b/build/mobile/robocop/FennecMochitestAssert.java index a7a74d2c340..b373b0bf6a6 100644 --- a/build/mobile/robocop/FennecMochitestAssert.java +++ b/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); + } + + 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. */ @@ -44,15 +55,13 @@ public class FennecMochitestAssert implements Assert { 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 class FennecMochitestAssert implements Assert { mLogTestName = nameParts[nameParts.length - 1]; mStartTime = SystemClock.uptimeMillis(); - dumpLog("TEST-START | " + mLogTestName); + mLogger.testStart(mLogTestName); } class testInfo { @@ -81,21 +90,22 @@ public class FennecMochitestAssert implements Assert { } - 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 @@ public class FennecMochitestAssert implements Assert { mPassed++; } if (isError) { + String message = "TEST-UNEXPECTED-" + failStatus + " | " + mLogTestName + " | " + + test.mName + " - " + test.mDiag; junit.framework.Assert.fail(message); } } @@ -116,27 +128,20 @@ public class FennecMochitestAssert implements Assert { 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 @@ public class FennecMochitestAssert implements Assert { 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 @@ public class FennecMochitestAssert implements Assert { } 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); } } diff --git a/build/mobile/robocop/StructuredLogger.java b/build/mobile/robocop/StructuredLogger.java index 3b4b86aa97e..87d5a3c250f 100644 --- a/build/mobile/robocop/StructuredLogger.java +++ b/build/mobile/robocop/StructuredLogger.java @@ -44,6 +44,10 @@ public class StructuredLogger { this(name, component, new StandardLoggerCallback()); } + public StructuredLogger(String name, LoggerCallback callback) { + this(name, null, callback); + } + public StructuredLogger(String name) { this(name, null, new StandardLoggerCallback()); } diff --git a/testing/mochitest/mach_commands.py b/testing/mochitest/mach_commands.py index 3cf0fe9669d..8ed8d0ed149 100644 --- a/testing/mochitest/mach_commands.py +++ b/testing/mochitest/mach_commands.py @@ -373,6 +373,8 @@ class MochitestRunner(MozbuildObject): for error in runner.message_logger.errors: runner.message_logger.logger.log_raw(error) + runner.message_logger.finish() + return result diff --git a/testing/mochitest/runtests.py b/testing/mochitest/runtests.py index bc395f88c51..2441fa3374c 100644 --- a/testing/mochitest/runtests.py +++ b/testing/mochitest/runtests.py @@ -1777,8 +1777,6 @@ class Mochitest(MochitestUtilsMixin): 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() diff --git a/testing/mochitest/runtestsb2g.py b/testing/mochitest/runtestsb2g.py index e8796ae0d55..719709e4760 100644 --- a/testing/mochitest/runtestsb2g.py +++ b/testing/mochitest/runtestsb2g.py @@ -206,7 +206,6 @@ class B2GMochitest(MochitestUtilsMixin): 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() diff --git a/testing/mochitest/runtestsremote.py b/testing/mochitest/runtestsremote.py index 496567df3a4..75c3f75c63a 100644 --- a/testing/mochitest/runtestsremote.py +++ b/testing/mochitest/runtestsremote.py @@ -577,76 +577,6 @@ class MochiRemote(Mochitest): 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)