Bug 1034272 - Convert cppunittests to structured logging.;r=ted
authorChris Manchester <cmanchester@mozilla.com>
Thu, 10 Jul 2014 09:33:39 -0400
changeset 200219 ecded1b76db35b9c13e5a4b1c50d10edcb8fe3cb
parent 200218 a357afff88300587c1905f01819c777f461af7eb
child 200220 0126e7c4b29f113eb010fa4a7b226788bc957509
push idunknown
push userunknown
push dateunknown
reviewersted
bugs1034272
milestone34.0a1
Bug 1034272 - Convert cppunittests to structured logging.;r=ted
testing/mach_commands.py
testing/remotecppunittests.py
testing/runcppunittests.py
--- a/testing/mach_commands.py
+++ b/testing/mach_commands.py
@@ -248,37 +248,39 @@ class MachCommands(MachCommandBase):
     @Command('cppunittest', category='testing',
         description='Run cpp unit tests (C++ tests).')
     @CommandArgument('test_files', nargs='*', metavar='N',
         help='Test to run. Can be specified as one or more files or ' \
             'directories, or omitted. If omitted, the entire test suite is ' \
             'executed.')
 
     def run_cppunit_test(self, **params):
+        from mozlog.structured import commandline
         import runcppunittests as cppunittests
-        import logging
+
+        log = commandline.setup_logging("cppunittest",
+                                        {},
+                                        {"tbpl": sys.stdout})
 
         if len(params['test_files']) == 0:
             testdir = os.path.join(self.distdir, 'cppunittests')
             progs = cppunittests.extract_unittests_from_args([testdir], None)
         else:
             progs = cppunittests.extract_unittests_from_args(params['test_files'], None)
 
         # See if we have crash symbols
         symbols_path = os.path.join(self.distdir, 'crashreporter-symbols')
         if not os.path.isdir(symbols_path):
             symbols_path = None
 
         tester = cppunittests.CPPUnitTests()
         try:
-            result = tester.run_tests(progs, self.bindir, symbols_path)
-        except Exception, e:
-            self.log(logging.ERROR, 'cppunittests',
-                {'exception': str(e)},
-                'Caught exception running cpp unit tests: {exception}')
+            result = tester.run_tests(progs, self.bindir, symbols_path, interactive=True)
+        except Exception as e:
+            log.error("Caught exception running cpp unit tests: %s" % str(e))
             result = False
 
         return 0 if result else 1
 
 @CommandProvider
 class CheckSpiderMonkeyCommand(MachCommandBase):
     @Command('check-spidermonkey', category='testing', description='Run SpiderMonkey tests (JavaScript engine).')
     @CommandArgument('--valgrind', action='store_true', help='Run jit-test suite with valgrind flag')
--- a/testing/remotecppunittests.py
+++ b/testing/remotecppunittests.py
@@ -4,30 +4,29 @@
 # License, v. 2.0. If a copy of the MPL was not distributed with this
 # file, You can obtain one at http://mozilla.org/MPL/2.0/.
 
 import os, sys
 import subprocess
 import tempfile
 from zipfile import ZipFile
 import runcppunittests as cppunittests
-import mozcrash, mozlog
+import mozcrash
 import mozfile
 import StringIO
 import posixpath
 from mozdevice import devicemanager, devicemanagerADB, devicemanagerSUT
+from mozlog import structured
 
 try:
     from mozbuild.base import MozbuildObject
     build_obj = MozbuildObject.from_environment()
 except ImportError:
     build_obj = None
 
-log = mozlog.getLogger('remotecppunittests')
-
 class RemoteCPPUnitTests(cppunittests.CPPUnitTests):
     def __init__(self, devmgr, options, progs):
         cppunittests.CPPUnitTests.__init__(self)
         self.options = options
         self.device = devmgr
         self.remote_test_root = self.device.deviceRoot + "/cppunittests"
         self.remote_bin_dir = posixpath.join(self.remote_test_root, "b")
         self.remote_tmp_dir = posixpath.join(self.remote_test_root, "tmp")
@@ -105,49 +104,53 @@ class RemoteCPPUnitTests(cppunittests.CP
         if self.options.add_env:
             for envdef in self.options.add_env:
                 envdef_parts = envdef.split("=", 1)
                 if len(envdef_parts) == 2:
                     env[envdef_parts[0]] = envdef_parts[1]
                 elif len(envdef_parts) == 1:
                     env[envdef_parts[0]] = ""
                 else:
-                    print >> sys.stderr, "warning: invalid --addEnv option skipped: "+envdef
+                    self.log.warning("invalid --addEnv option skipped: %s" % envdef)
 
         return env
 
-    def run_one_test(self, prog, env, symbols_path=None):
+    def run_one_test(self, prog, env, symbols_path=None, interactive=False):
         """
         Run a single C++ unit test program remotely.
 
         Arguments:
         * prog: The path to the test program to run.
         * env: The environment to use for running the program.
         * symbols_path: A path to a directory containing Breakpad-formatted
                         symbol files for producing stack traces on crash.
 
         Return True if the program exits with a zero status, False otherwise.
         """
         basename = os.path.basename(prog)
         remote_bin = posixpath.join(self.remote_bin_dir, basename)
-        log.info("Running test %s", basename)
+        self.log.test_start(basename)
         buf = StringIO.StringIO()
         returncode = self.device.shell([remote_bin], buf, env=env, cwd=self.remote_home_dir,
                                        timeout=cppunittests.CPPUnitTests.TEST_PROC_TIMEOUT)
-        print >> sys.stdout, buf.getvalue()
+        self.log.process_output(basename, "\n%s" % buf.getvalue(),
+                                command=[remote_bin])
         with mozfile.TemporaryDirectory() as tempdir:
             self.device.getDirectory(self.remote_home_dir, tempdir)
             if mozcrash.check_for_crashes(tempdir, symbols_path,
                                           test_name=basename):
-                log.testFail("%s | test crashed", basename)
+                self.log.test_end(basename, status='CRASH', expected='PASS')
                 return False
         result = returncode == 0
         if not result:
-            log.testFail("%s | test failed with return code %s",
-                         basename, returncode)
+            self.log.test_end(basename, status='FAIL', expected='PASS',
+                              message=("test failed with return code %d" %
+                                       returncode))
+        else:
+            self.log.test_end(basename, status='PASS', expected='PASS')
         return result
 
 class RemoteCPPUnittestOptions(cppunittests.CPPUnittestOptions):
     def __init__(self):
         cppunittests.CPPUnittestOptions.__init__(self)
         defaults = {}
 
         self.add_option("--deviceIP", action="store",
@@ -199,16 +202,17 @@ class RemoteCPPUnittestOptions(cppunitte
                     type = "string", dest = "add_env",
                     help = "additional remote environment variable definitions (eg. --addEnv \"somevar=something\")")
         defaults["add_env"] = None
 
         self.set_defaults(**defaults)
 
 def main():
     parser = RemoteCPPUnittestOptions()
+    structured.commandline.add_logging_group(parser)
     options, args = parser.parse_args()
     if not args:
         print >>sys.stderr, """Usage: %s <test binary> [<test binary>...]""" % sys.argv[0]
         sys.exit(1)
     if options.local_lib is not None and not os.path.isdir(options.local_lib):
         print >>sys.stderr, """Error: --localLib directory %s not found""" % options.local_lib
         sys.exit(1)
     if options.local_apk is not None and not os.path.isfile(options.local_apk):
@@ -238,16 +242,22 @@ def main():
                 runner.cleanup()
                 runner.wait()
             raise
     else:
         dm = devicemanagerSUT.DeviceManagerSUT(options.device_ip, options.device_port, deviceRoot=options.remote_test_root)
         if not options.device_ip:
             print "Error: you must provide a device IP to connect to via the --deviceIP option"
             sys.exit(1)
+
+    log = structured.commandline.setup_logging("remotecppunittests",
+                                               options,
+                                               {"tbpl": sys.stdout})
+
+
     options.xre_path = os.path.abspath(options.xre_path)
     progs = cppunittests.extract_unittests_from_args(args, options.manifest_file)
     tester = RemoteCPPUnitTests(dm, options, progs)
     try:
         result = tester.run_tests(progs, options.xre_path, options.symbols_path)
     except Exception, e:
         log.error(str(e))
         result = False
--- a/testing/runcppunittests.py
+++ b/testing/runcppunittests.py
@@ -2,62 +2,81 @@
 #
 # This Source Code Form is subject to the terms of the Mozilla Public
 # License, v. 2.0. If a copy of the MPL was not distributed with this
 # file, You can obtain one at http://mozilla.org/MPL/2.0/.
 
 from __future__ import with_statement
 import sys, os, tempfile, shutil
 from optparse import OptionParser
-import mozprocess, mozinfo, mozlog, mozcrash, mozfile
+import mozprocess
+import mozinfo
+import mozcrash
+import mozfile
 from contextlib import contextmanager
-
-log = mozlog.getLogger('cppunittests')
+from mozlog import structured
+from subprocess import PIPE
 
 class CPPUnitTests(object):
     # Time (seconds) to wait for test process to complete
     TEST_PROC_TIMEOUT = 900
     # Time (seconds) in which process will be killed if it produces no output.
     TEST_PROC_NO_OUTPUT_TIMEOUT = 300
 
-    def run_one_test(self, prog, env, symbols_path=None):
+    def run_one_test(self, prog, env, symbols_path=None, interactive=False):
         """
         Run a single C++ unit test program.
 
         Arguments:
         * prog: The path to the test program to run.
         * env: The environment to use for running the program.
         * symbols_path: A path to a directory containing Breakpad-formatted
                         symbol files for producing stack traces on crash.
 
         Return True if the program exits with a zero status, False otherwise.
         """
         basename = os.path.basename(prog)
-        log.info("Running test %s", basename)
+        self.log.test_start(basename)
         with mozfile.TemporaryDirectory() as tempdir:
-            proc = mozprocess.ProcessHandler([prog],
-                                             cwd=tempdir,
-                                             env=env)
+            if interactive:
+                # For tests run locally, via mach, print output directly
+                proc = mozprocess.ProcessHandler([prog],
+                                                 cwd=tempdir,
+                                                 env=env,
+                                                 storeOutput=False)
+            else:
+                proc = mozprocess.ProcessHandler([prog],
+                                                 cwd=tempdir,
+                                                 env=env,
+                                                 storeOutput=True,
+                                                 processOutputLine=lambda _: None)
             #TODO: After bug 811320 is fixed, don't let .run() kill the process,
             # instead use a timeout in .wait() and then kill to get a stack.
             proc.run(timeout=CPPUnitTests.TEST_PROC_TIMEOUT,
                      outputTimeout=CPPUnitTests.TEST_PROC_NO_OUTPUT_TIMEOUT)
             proc.wait()
+            if proc.output:
+                output = "\n%s" % "\n".join(proc.output)
+                self.log.process_output(proc.pid, output, command=[prog])
             if proc.timedOut:
-                log.testFail("%s | timed out after %d seconds",
-                             basename, CPPUnitTests.TEST_PROC_TIMEOUT)
+                message = "timed out after %d seconds" % CPPUnitTests.TEST_PROC_TIMEOUT
+                self.log.test_end(basename, status='TIMEOUT', expected='PASS',
+                                  message=message)
                 return False
             if mozcrash.check_for_crashes(tempdir, symbols_path,
                                           test_name=basename):
-                log.testFail("%s | test crashed", basename)
+                self.log.test_end(basename, status='CRASH', expected='PASS')
                 return False
             result = proc.proc.returncode == 0
             if not result:
-                log.testFail("%s | test failed with return code %d",
-                             basename, proc.proc.returncode)
+                self.log.test_end(basename, status='FAIL', expected='PASS',
+                                  message=("test failed with return code %d" %
+                                           proc.proc.returncode))
+            else:
+                self.log.test_end(basename, status='PASS', expected='PASS')
             return result
 
     def build_core_environment(self, env = {}):
         """
         Add environment variables likely to be used across all platforms, including remote systems.
         """
         env["MOZILLA_FIVE_HOME"] = self.xre_path
         env["MOZ_XRE_DIR"] = self.xre_path
@@ -89,49 +108,53 @@ class CPPUnitTests(object):
                 env[pathvar] = "%s%s%s" % (self.xre_path, os.pathsep, env[pathvar])
             else:
                 env[pathvar] = self.xre_path
 
         # Use llvm-symbolizer for ASan if available/required
         llvmsym = os.path.join(self.xre_path, "llvm-symbolizer")
         if os.path.isfile(llvmsym):
             env["ASAN_SYMBOLIZER_PATH"] = llvmsym
-            log.info("ASan using symbolizer at %s", llvmsym)
+            self.log.info("ASan using symbolizer at %s" % llvmsym)
         else:
-            log.info("Failed to find ASan symbolizer at %s", llvmsym)
+            self.log.info("Failed to find ASan symbolizer at %s" % llvmsym)
 
         return env
 
-    def run_tests(self, programs, xre_path, symbols_path=None):
+    def run_tests(self, programs, xre_path, symbols_path=None, interactive=False):
         """
         Run a set of C++ unit test programs.
 
         Arguments:
         * programs: An iterable containing paths to test programs.
         * xre_path: A path to a directory containing a XUL Runtime Environment.
         * symbols_path: A path to a directory containing Breakpad-formatted
                         symbol files for producing stack traces on crash.
 
         Returns True if all test programs exited with a zero status, False
         otherwise.
         """
         self.xre_path = xre_path
+        self.log = structured.structuredlog.get_default_logger()
+        self.log.suite_start(programs)
         env = self.build_environment()
         pass_count = 0
         fail_count = 0
         for prog in programs:
-            single_result = self.run_one_test(prog, env, symbols_path)
+            single_result = self.run_one_test(prog, env, symbols_path, interactive)
             if single_result:
                 pass_count += 1
             else:
                 fail_count += 1
+        self.log.suite_end()
 
-        log.info("Result summary:")
-        log.info("Passed: %d" % pass_count)
-        log.info("Failed: %d" % fail_count)
+        # Mozharness-parseable summary formatting.
+        self.log.info("Result summary:")
+        self.log.info("cppunittests INFO | Passed: %d" % pass_count)
+        self.log.info("cppunittests INFO | Failed: %d" % fail_count)
         return fail_count == 0
 
 class CPPUnittestOptions(OptionParser):
     def __init__(self):
         OptionParser.__init__(self)
         self.add_option("--xre-path",
                         action = "store", type = "string", dest = "xre_path",
                         default = None,
@@ -166,29 +189,35 @@ def extract_unittests_from_args(args, ma
             progs.extend([os.path.abspath(os.path.join(p, x)) for x in os.listdir(p) if not x in skipped_progs])
         elif p not in skipped_progs:
             progs.append(os.path.abspath(p))
 
     return progs
 
 def main():
     parser = CPPUnittestOptions()
+    structured.commandline.add_logging_group(parser)
     options, args = parser.parse_args()
     if not args:
         print >>sys.stderr, """Usage: %s <test binary> [<test binary>...]""" % sys.argv[0]
         sys.exit(1)
     if not options.xre_path:
         print >>sys.stderr, """Error: --xre-path is required"""
         sys.exit(1)
-        
+
+    log = structured.commandline.setup_logging("cppunittests",
+                                               options,
+                                               {"tbpl": sys.stdout})
+
     progs = extract_unittests_from_args(args, options.manifest_file)
     options.xre_path = os.path.abspath(options.xre_path)
     tester = CPPUnitTests()
+
     try:
         result = tester.run_tests(progs, options.xre_path, options.symbols_path)
-    except Exception, e:
+    except Exception as e:
         log.error(str(e))
         result = False
+
     sys.exit(0 if result else 1)
 
 if __name__ == '__main__':
     main()
-