Add structured logging command line arguments for mochitest/mach

RESOLVED FIXED in Firefox 33

Status

defect
RESOLVED FIXED
5 years ago
5 years ago

People

(Reporter: akachkach, Assigned: akachkach)

Tracking

unspecified
mozilla34
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox33 fixed, firefox34 fixed)

Details

Attachments

(2 attachments, 16 obsolete attachments)

6.19 KB, patch
cmanchester
: review+
Details | Diff | Splinter Review
75.42 KB, patch
akachkach
: review+
Details | Diff | Splinter Review
Posted patch WIP patch (obsolete) — Splinter Review
When bug 886570 lands, we'll have to do some changes to expose the structured logs using mozlog.structured.commandline
Posted patch WIP patch (obsolete) — Splinter Review
Working on desktop (both with mach, and in TBPL). Should work (soon) for android/b2g, still testing (Try run: https://tbpl.mozilla.org/?tree=Try&rev=0a9c0cc85863)
Attachment #8457652 - Attachment is obsolete: true
Posted patch commandline.patch (obsolete) — Splinter Review
Patch to support commandline arguments for structured logging with the mochitest suite (not many changes from the last patch, just testing again now that bug 886570 landed).

Try push: https://tbpl.mozilla.org/?tree=Try&rev=0b13b9f648b3
Attachment #8457818 - Attachment is obsolete: true
Attachment #8459924 - Flags: review?(cmanchester)
This adds a raw_log_file variable that can be used in in-tree mozharness configs. (This will probably be used by other suites, so I added a set of suites that use that variable)

PS: ignore the previous try run! This mozharness patch must land first before we can expose the structured logs via blobber.
Attachment #8459927 - Flags: review?(cmanchester)
Posted patch mozharness_scripts.patch (obsolete) — Splinter Review
Updated the previous patch to always include the vars. (simpler this way)
Attachment #8459927 - Attachment is obsolete: true
Attachment #8459927 - Flags: review?(cmanchester)
Attachment #8459938 - Flags: review?(cmanchester)
Attachment #8459938 - Flags: review?(cmanchester) → review?(ahalberstadt)
Comment on attachment 8459938 [details] [diff] [review]
mozharness_scripts.patch

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

Lgtm!
Attachment #8459938 - Flags: review?(ahalberstadt) → review+
At Ahmed's request I pushed these patches to ash-mozharness and Ash. Results here:
https://tbpl.mozilla.org/?tree=Ash&rev=59f661f6896f
Comment on attachment 8459938 [details] [diff] [review]
mozharness_scripts.patch

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

::: scripts/android_emulator_unittest.py
@@ +402,5 @@
>              # self.symbols_path when downloading/extracting.
>              'symbols_path': self.symbols_path,
>              'modules_dir': dirs['abs_modules_dir'],
>              'installer_path': self.installer_path,
> +            'raw_log_file': os.path.join(dirs['abs_blob_upload_dir'], 'mochitest_structured.log')

I don't know how important the filenames will end up being, but let's use a name other than mochitest for these as they're used across test harnesses.
Woops, forgot it would be used by the other test suites. Fixed!
Attachment #8459938 - Attachment is obsolete: true
Attachment #8460532 - Flags: review?(cmanchester)
Comment on attachment 8459924 [details] [diff] [review]
commandline.patch

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

When I agreed to review this I didn't realize the extent of the change, so maybe ahal can sign off on this once you have a patch that runs ok in automation.

The get_default_logger was added to mozlog.structured for exactly the case where you'd otherwise have to pass a logger everywhere. With clever use of that api I think you could dispatch with a lot of these modifications.

::: testing/mochitest/mach_commands.py
@@ +152,2 @@
>          options = parser.parse_args([])[0]
> +        complete_options, _ = parser.parse_args()

Anything else to try to avoid this? Does it break if you just refrain from passing the empty list above?

@@ +269,2 @@
>          options, args = opts.parse_args([])
> +        complete_options, _ = opts.parse_args()

Again here.

@@ +269,5 @@
>          options, args = opts.parse_args([])
> +        complete_options, _ = opts.parse_args()
> +        logger = structured.commandline.setup_logging('mochitest-desktop-{}'.format(suite), complete_options, {})
> +
> +        # Only add the tbpl logger if a handler isn't already logging to stdout

Update this comment explaining why we do this. The mach formatter just got an upgrade to give better info for failures, maybe we can use it by default from here on out?

@@ +631,5 @@
>      return func
>  
>  
> +st_parser = argparse.ArgumentParser()
> +structured.commandline.add_logging_group(st_parser)

I'd prefix this with an underscore.

::: testing/mochitest/runtests.py
@@ +1767,5 @@
>  
>    class OutputHandler(object):
>      """line output handler for mozrunner"""
> +    def __init__(self, harness, utilityPath, symbolsPath=None, dump_screen_on_timeout=True, dump_screen_on_fail=False,
> +                 shutdownLeaks=None, lsanLeaks=None, bisectChunk=None):

Unrelated change?

::: testing/mochitest/runtestsremote.py
@@ +29,4 @@
>  
>  SCRIPT_DIR = os.path.abspath(os.path.realpath(os.path.dirname(__file__)))
>  
> +module_logger = logging.getLogger('MochitestRemote')

Unstructured logging?
Attachment #8459924 - Flags: review?(cmanchester)
Attachment #8460532 - Flags: review?(cmanchester) → review+
(In reply to Andrew Halberstadt [:ahal] from comment #6)
> At Ahmed's request I pushed these patches to ash-mozharness and Ash. Results
> here:
> https://tbpl.mozilla.org/?tree=Ash&rev=59f661f6896f

Looks like you need to update to push to build/ash-mozharness
(In reply to Chris Manchester [:chmanchester] from comment #10)
> (In reply to Andrew Halberstadt [:ahal] from comment #6)
> > At Ahmed's request I pushed these patches to ash-mozharness and Ash. Results
> > here:
> > https://tbpl.mozilla.org/?tree=Ash&rev=59f661f6896f
> 
> Looks like you need to update to push to build/ash-mozharness

I pushed the patch to build/ash-mozharness and re-triggered jobs on various platforms.
(In reply to Ahmed Kachkach [:akachkach] from comment #8)
> Created attachment 8460532 [details] [diff] [review]
> mozharness_scripts.patch
> 
> Woops, forgot it would be used by the other test suites. Fixed!

Maybe we should do your original idea of --log-raw=%(blob_upload_dir)s/mochitest-structured.log

I guess it isn't all that important for now.
Posted patch commandline.patch (obsolete) — Splinter Review
Fixes that little bug that made some jobs orange and the issues raised by chmanchester.
Attachment #8459924 - Attachment is obsolete: true
Attachment #8461065 - Flags: review?(ahalberstadt)
Blocks: 1042933
Comment on attachment 8461065 [details] [diff] [review]
commandline.patch

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

I think instead of doing all the log setup in mach_commands.py and then passing in a log variable to runtests*.py, we should just do the log setup in runtests*.py. There is a guideline that mach commands should contain as little logic as possible (not that we are very good at following that guideline). This way it would also work for people running the runtests*.py files directly.
Attachment #8461065 - Flags: review?(ahalberstadt) → review-
Posted patch commandline.patch (obsolete) — Splinter Review
Moved the logging config code inside MochitestUtilsMixin, and indeed it's way cleaner this way (less code duplication). Also removed double calls to parse_args().

If you have b2g/android working on your local setup, could you test to see if they're still working correctly working?
Attachment #8461065 - Attachment is obsolete: true
Attachment #8461730 - Flags: review?(ahalberstadt)
Ok to land the mozharness changes in the meantime?
Posted patch commandline.patch (obsolete) — Splinter Review
woops, that was just a change that I forgot to revert. Here's the updated patch.
Attachment #8461730 - Attachment is obsolete: true
Attachment #8461730 - Flags: review?(ahalberstadt)
Attachment #8461778 - Flags: review?
Attachment #8461778 - Flags: review? → review?(ahalberstadt)
Comment on attachment 8461778 [details] [diff] [review]
commandline.patch

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

Sorry to r- again, but I really dislike the "pass the options" dict everywhere pattern. Why are you passing it throughout runtestsb2g.py? It looks like it isn't even being used?

Also I think I prefer the global log variable approach instead of passing it around to every class and function defined in the file. Though I guess both ways are a bit yucky, so I'd be ok if you left it.
Attachment #8461778 - Flags: review?(ahalberstadt) → review-
The options were already passed everywhere, I just pass them to the constructor now (so the logger configuration can be done there). In runtestsb2g, the options are just passed to the parent class so the logger can be instantiated.
I know they were, I spent a fair amount of time trying to make it so runtestsb2g.py *didn't* pass them around everywhere :). I'd also like to stop passing it around everywhere in runtests.py, but haven't had time for that yet.

Maybe instead of passing in options, could you pass in "logger_args" or something like that?
Only passing logger options now.
Attachment #8461778 - Attachment is obsolete: true
Attachment #8463631 - Flags: review?(ahalberstadt)
Comment on attachment 8463631 [details] [diff] [review]
0001-Bug-1039833-Add-structured-logging-command-line-argu.patch

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

Thanks! You may want to run this through try if you haven't already.. especially for that decoding change in mozdevice (I'd run all android tests).

::: testing/mochitest/runtestsremote.py
@@ +3,5 @@
>  # file, You can obtain one at http://mozilla.org/MPL/2.0/.
>  
>  import base64
>  import json
> +import logging

How come we're still using logging? Is there more work needed on android first?
Attachment #8463631 - Flags: review?(ahalberstadt) → review+
Some logging is done before the structured logger can be configured (for verifying the command line options), so I first initialize that logger as a non-structured logger and then change it to a structured one after the structured logger is instantiated.

But maybe I can make that cleaner by using structured.get_default_logger? I'll give it a go.

@jmaher: Are the changes to mozharness in production? Did a try push and it's busted: https://tbpl.mozilla.org/?tree=Try&rev=8cb536298e61

A try push I did yesterday was also busted, in the exception of Android 2.3 : https://tbpl.mozilla.org/?tree=Try&rev=887e2c847f15 (but no structured logs exposed); is the config different for that platform ?
Flags: needinfo?(jmaher)
woops, sorry :jmaher, wanted to ping :chmanchester
Flags: needinfo?(jmaher) → needinfo?(cmanchester)
(In reply to Ahmed Kachkach [:akachkach] from comment #26)
> woops, sorry :jmaher, wanted to ping :chmanchester

(In reply to Ahmed Kachkach [:akachkach] from comment #25)
> Some logging is done before the structured logger can be configured (for
> verifying the command line options), so I first initialize that logger as a
> non-structured logger and then change it to a structured one after the
> structured logger is instantiated.
> 
> But maybe I can make that cleaner by using structured.get_default_logger?
> I'll give it a go.
> 
> @jmaher: Are the changes to mozharness in production? Did a try push and
> it's busted: https://tbpl.mozilla.org/?tree=Try&rev=8cb536298e61

Looking at http://hg.mozilla.org/build/mozharness/summary I don't think so. We push to "default" and every so often it get merged to "production".

> 
> A try push I did yesterday was also busted, in the exception of Android 2.3
> : https://tbpl.mozilla.org/?tree=Try&rev=887e2c847f15 (but no structured
> logs exposed); is the config different for that platform ?

They appear to use config/mozharness/android_arm_config.py
Flags: needinfo?(cmanchester)
something here is now in production
carry r+ forward

Forgot to add the config args to android_arm in the previous patch.

Try run: https://tbpl.mozilla.org/?tree=Try&rev=9b32741bf605
Attachment #8463631 - Attachment is obsolete: true
Attachment #8464266 - Flags: review+
Keywords: checkin-needed
sorry patch failed to apply: 

adding 1039833 to series file
renamed 1039833 -> 0001-Bug-1039833-Add-structured-logging-command-line-argu.patch
applying 0001-Bug-1039833-Add-structured-logging-command-line-argu.patch
patching file testing/mochitest/runtests.py
Hunk #28 FAILED at 1759
Hunk #31 succeeded at 2050 with fuzz 2 (offset -2 lines).
1 out of 31 hunks FAILED -- saving rejects to file testing/mochitest/runtests.py.rej
patching file testing/mochitest/runtestsb2g.py
Hunk #3 FAILED at 179
Hunk #6 FAILED at 360
2 out of 6 hunks FAILED -- saving rejects to file testing/mochitest/runtestsb2g.py.rej
patching file testing/mochitest/runtestsremote.py
Hunk #11 FAILED at 600
Hunk #12 FAILED at 640
2 out of 12 hunks FAILED -- saving rejects to file testing/mochitest/runtestsremote.py.rej
patch failed, unable to continue (try -v)
patch failed, rejects left in working dir
errors during apply, please fix and refresh 0001-Bug-1039833-Add-structured-logging-command-line-argu.patch

could you take a look and maybe rebase against a current tree, thanks!
Keywords: checkin-needed
Bug 1044206 landed some changes that weren't compatible with this patch, so I worked on updating it today.

Asking chmanchester to review this to make sure it doesn't cancel his patch.
Attachment #8464266 - Attachment is obsolete: true
Attachment #8465011 - Flags: review?(cmanchester)
A couple small changes to fix a bug.

Try run: https://tbpl.mozilla.org/?tree=Try&rev=9e6c0ea152ee
Attachment #8465011 - Attachment is obsolete: true
Attachment #8465011 - Flags: review?(cmanchester)
Attachment #8465198 - Flags: review?(cmanchester)
Note: 'will have to avoid falling into this regression when we land this => bug 1046566
something(s) here went to production today
Comment on attachment 8465198 [details] [diff] [review]
0001-Bug-1039833-Add-structured-logging-command-line-argu.patch

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

This is sort of unfortunate because the patch now has a lot of changes from calls to "log.*" to "self.log.*" that are not changing anything, but I'm fairly sure this doesn't re-regress bug 1044206. It looks like you'll need to un-bitrot wrt bug 1046566 before landing.

::: testing/mochitest/runtests.py
@@ +425,5 @@
> +      structured_logger.add_handler(handler)
> +
> +    self.message_logger = MessageLogger(logger=structured_logger)
> +
> +    self.structured_logger = structured_logger

With this patch self.structured_logger goes unused, right?

@@ +764,5 @@
>            options.testingModulesDir)
>  
>      # Call installChromeJar().
>      if not os.path.isdir(os.path.join(SCRIPT_DIR, self.jarDir)):
> +      self.log.error(message="TEST-UNEXPECTED-FAIL | invalid setup: missing mochikit extension")

The kwarg isn't right now that self.log is an unstructured logger.

::: testing/mozbase/mozdevice/mozdevice/devicemanagerSUT.py
@@ +234,5 @@
>                      try:
>                          # Wait up to a second for socket to become ready for reading...
>                          if select.select([self._sock], [], [], select_timeout)[0]:
>                              temp = self._sock.recv(1024)
> +                            self._logger.debug(u"response: %s" % temp.decode('utf8', 'replace'))

This might not be necessary now that bug 1042921 has landed.
Attachment #8465198 - Flags: review?(cmanchester) → review+
I'm going to try to fix a couple other mochitest bugs before landing this.
carry r+ forward.

unbitrot + fixed kwarg "message" (since we're now using an unstructured log for that part)

Try run (done yesterday, did something important land since then? didn't get any merge conflicts):
https://tbpl.mozilla.org/?tree=Try&rev=8b98b91a4058
Attachment #8465198 - Attachment is obsolete: true
Attachment #8468843 - Flags: review+
Keywords: checkin-needed
woops, forgot to ask ahal to make sure it works as expected. (thanks!)
Flags: needinfo?(ahalberstadt)
Keywords: checkin-needed
I tested locally on Linux debug and nothing seems to have regressed. Leak checking still works and assertion counting was already broken.

Assuming nothing was broken in the try run, I think this is good to land.
Flags: needinfo?(ahalberstadt)
Thanks Andrew!
Status: NEW → ASSIGNED
Keywords: checkin-needed
Needs rebasing.
Keywords: checkin-needed
rebased.

(conflict probably caused by bug 1050148 landing)
Attachment #8468843 - Attachment is obsolete: true
Attachment #8470120 - Flags: review+
Keywords: checkin-needed
Blocks: 1050855
Some recent changes have broken this patch with robocop, will post an updated version when I figure this out.
Keywords: checkin-needed
Ahmed, does your patch add help info, e.g., when you do ./mach mochitest-plain --help, does it haven an entry for --log-raw?
Since help info is (apparently) "hardcoded" in mochitest_options.py, and the structured logging args are added "dynamically" by the mochitest parser, it doesn't work for now.

NEEDINFOing jgraham since he knows more about the command line integration.
Flags: needinfo?(james)
carry r+ forward;

Updated to fix a bug caused by a bad merge.

https://tbpl.mozilla.org/?tree=Try&rev=cac16f5fd5a6
Attachment #8470120 - Attachment is obsolete: true
Attachment #8470451 - Flags: review+
--help will only show the arguments defined in the mach_commands.py file (help should show up if you run `python runtests.py --help`). So if this is something we want people to be able to do via mach, we'll have to explicitly add the command options there.
It shouldn't be necessary to explicitly define the options in the mach_commands.py file. The very easiest option is just to make mach_commands use the parser option to @Command to define all command line arguments and kill the unnecessary repetition.

If that's too big a change at the moment, anything defined via parser= will be added to the explicit option. So you can create an empty parser and pass that to commandline.add_logging_group() like:

logging_parser = argparse.ArgumentsParser()
commandline.add_logging_group(logging_parser)
@Command[...], parser=logging_parser)
@CommandArgument[...]

Any arguments added will always include their defined help options.
Flags: needinfo?(james)
Yeah, that's what I meant. Explicitly add them to the parser because they don't get picked up automatically.
So, I think I just needed to refresh my build. The help commands appear when I do runtests.py --help or ./mach mochitest-plain --help :


Output Logging:
  Each option represents a possible logging format and takes a filename to
  write that format to, or '-' to write to stdout.

  --log-unittest LOG_UNITTEST
                        Unittest style output
  --log-raw LOG_RAW     Raw structured log messages
  --log-html LOG_HTML   HTML report
  --log-tbpl LOG_TBPL   TBPL style log format
  --log-xunit LOG_XUNIT
                        xUnit compatible XML
  --log-mach LOG_MACH   Human-readable output
  --log-mach-level LOG_MACH_LEVEL
                        A least log level to subscribe to for the given
                        formatter (debug, info, error, etc.)
  --log-tbpl-level LOG_TBPL_LEVEL
                        A least log level to subscribe to for the given
                        formatter (debug, info, error, etc.)
carry r+ forward;

Rebased the patch. Should be ready to land now.

Try run: https://tbpl.mozilla.org/?tree=Try&rev=be16c18b8d0f
Attachment #8470451 - Attachment is obsolete: true
Attachment #8471071 - Flags: review+
carry r+ forward;
rebased + small fix.

Try run looks good:  https://tbpl.mozilla.org/?rev=6d7549303751&tree=Try
Btw, it looks like those aren't related to this patch, but I see some exceptions in the android jobs: "<bound method PandaTest.run_command of <__main__.PandaTest object at 0x2033a10>> failed after 1 tries!"
Attachment #8471071 - Attachment is obsolete: true
Attachment #8472520 - Flags: review+
Keywords: checkin-needed
https://hg.mozilla.org/mozilla-central/rev/1db4be77a409
Status: ASSIGNED → RESOLVED
Closed: 5 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla34
Depends on: 1056329
You need to log in before you can comment on or make changes to this bug.