Closed Bug 1034272 Opened 5 years ago Closed 5 years ago

Integrate Structured Logging with CPP unit tests

Categories

(Testing :: Mozbase, defect)

x86
macOS
defect
Not set

Tracking

(Not tracked)

RESOLVED FIXED
mozilla34

People

(Reporter: chmanchester, Assigned: chmanchester)

References

(Blocks 1 open bug)

Details

Attachments

(1 file, 1 obsolete file)

No description provided.
Something like this. Calling .decode("utf-8", "replace") is a bit of a shot in the dark, but seems to do the right thing.

A promising try run:
https://tbpl.mozilla.org/?tree=Try&rev=8eaaee641f91
Attachment #8453763 - Flags: review?(ted)
Assignee: nobody → cmanchester
Status: NEW → ASSIGNED
Comment on attachment 8453763 [details] [diff] [review]
Convert cppunittests to structured logging.

Review of attachment 8453763 [details] [diff] [review]:
-----------------------------------------------------------------

::: testing/runcppunittests.py
@@ +60,2 @@
>                  return False
>              if mozcrash.check_for_crashes(tempdir, symbols_path,

mozcrash will produced unstructured output until bug 1023371 is fixed. Once it is we will want to adjust the call here to work with the new design.
Depends on: 1023371
Comment on attachment 8453763 [details] [diff] [review]
Convert cppunittests to structured logging.

Review of attachment 8453763 [details] [diff] [review]:
-----------------------------------------------------------------

r=me with some fixup

::: testing/runcppunittests.py
@@ +6,5 @@
>  
>  from __future__ import with_statement
>  import sys, os, tempfile, shutil
>  from optparse import OptionParser
> +import mozprocess, mozinfo, mozcrash, mozfile

Can you split these to one-per-line while you're here?

@@ +50,5 @@
>              proc.run(timeout=CPPUnitTests.TEST_PROC_TIMEOUT,
>                       outputTimeout=CPPUnitTests.TEST_PROC_NO_OUTPUT_TIMEOUT)
>              proc.wait()
> +            if proc.output:
> +                output = "\n".join(proc.output).decode("utf-8", "replace")

This seems like it's almost certainly going to produce bogus or confusing output in some cases, but I guess we can cross that bridge when we get to it. It shouldn't *break*, anyway, which I suppose is the most important thing.

@@ +51,5 @@
>                       outputTimeout=CPPUnitTests.TEST_PROC_NO_OUTPUT_TIMEOUT)
>              proc.wait()
> +            if proc.output:
> +                output = "\n".join(proc.output).decode("utf-8", "replace")
> +                self.log.process_output(proc.pid, output, command=[prog])

Is this going to always stuff the program output into the structured log? I guess that matches the current behavior?

@@ +56,4 @@
>              if proc.timedOut:
> +                message = "timed out after %d seconds" % CPPUnitTests.TEST_PROC_TIMEOUT
> +                self.log.test_end(basename, status='TIMEOUT', expected='PASS',
> +                             message=message)

The indentation here looks wonky.

@@ +65,5 @@
>              result = proc.proc.returncode == 0
>              if not result:
> +                self.log.test_end(basename, status='FAIL', expected='PASS',
> +                             message=("%s | test failed with return code %d" %
> +                                      (basename, proc.proc.returncode)))

Kind of sucks that we have to stuff the pipe character in there to get the output we expect. Can we not just feed the right arguments in and get what we want out of the mach formatter?

@@ +116,5 @@
>  
>          return env
>  
> +    def run_tests(self, programs, xre_path, symbols_path=None, interactive=False,
> +                  log=None):

If you're going to use a default of None here you should initialize self.log to something sensible down below. Maybe factor out the setup_logging call from main into a function you can call to get a logger?

@@ +146,5 @@
> +        # Yes, this must be hardcoded -- the summary is the same for
> +        # desktop and mobile.
> +        self.log.info("Result summary:")
> +        self.log.info("cppunittests INFO | Passed: %d" % pass_count)
> +        self.log.info("cppunittests INFO | Failed: %d" % fail_count)

Can you file a followup to pull this into a mozbase method if we rely on it? "log.mozbase_sumary(pass_count, fail_count)" or something like that.

@@ +197,5 @@
>      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"""

Uh, I don't think you want this change.

@@ +208,5 @@
>      progs = extract_unittests_from_args(args, options.manifest_file)
>      options.xre_path = os.path.abspath(options.xre_path)
>      tester = CPPUnitTests()
> +
> +    log.suite_start(progs)

I think you want to put suite_{start,end} inside run_tests, since as-written they're not being called when you run via mach.
Attachment #8453763 - Flags: review?(ted) → review+
Patch updated with review feedback. I'd like to deal with bug 1043039 and possibly bug 1023371 before landing this.
Attachment #8453763 - Attachment is obsolete: true
Comment on attachment 8461211 [details] [diff] [review]
Convert cppunittests to structured logging.

r=ted
Attachment #8461211 - Flags: review+
Depends on: 1043039
This has been hanging around a while. I did a pretty thorough try run last night, and it looks ok: https://tbpl.mozilla.org/?tree=Try&rev=3a5aa2506290

I'm going to do a sanity check of the output, but I'm inclined to land this and deal with mozcrash integration in a follow up.
The mozcrash bug is waiting for a second round of review. I would like to land that soon in any case, but I'm not sure whether or not it has to block this.
https://hg.mozilla.org/mozilla-central/rev/ecded1b76db3
Status: ASSIGNED → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla34
You need to log in before you can comment on or make changes to this bug.