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 id27337
push useremorley@mozilla.com
push dateTue, 19 Aug 2014 12:40:34 +0000
treeherdermozilla-central@a38daccaa557 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersted
bugs1034272
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 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()
-