Add structured logging command line arguments for mochitest/mach

RESOLVED FIXED in Firefox 33

Status

Testing
Mochitest
RESOLVED FIXED
3 years ago
3 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
chmanchester
: review+
Details | Diff | Splinter Review
75.42 KB, patch
akachkach
: review+
Details | Diff | Splinter Review
(Assignee)

Description

3 years ago
Created attachment 8457652 [details] [diff] [review]
WIP patch

When bug 886570 lands, we'll have to do some changes to expose the structured logs using mozlog.structured.commandline
(Assignee)

Comment 1

3 years ago
Created attachment 8457818 [details] [diff] [review]
WIP patch

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
(Assignee)

Comment 2

3 years ago
Created attachment 8459924 [details] [diff] [review]
commandline.patch

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)
(Assignee)

Comment 3

3 years ago
Created attachment 8459927 [details] [diff] [review]
0001-Bug-1039833-Structured-logging-with-commandline-args.patch

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)
(Assignee)

Comment 4

3 years ago
Created attachment 8459938 [details] [diff] [review]
mozharness_scripts.patch

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)
(Assignee)

Updated

3 years ago
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.
(Assignee)

Comment 8

3 years ago
Created attachment 8460532 [details] [diff] [review]
mozharness_scripts.patch

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.
Some of the re-triggers came back orange:
https://tbpl.mozilla.org/php/getParsedLog.php?id=44413809&tree=Ash&full=1#error0
(Assignee)

Comment 14

3 years ago
Created attachment 8461065 [details] [diff] [review]
commandline.patch

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)

Updated

3 years ago
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-
(Assignee)

Comment 16

3 years ago
Created attachment 8461730 [details] [diff] [review]
commandline.patch

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?
(Assignee)

Comment 18

3 years ago
Created attachment 8461778 [details] [diff] [review]
commandline.patch

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?
(Assignee)

Updated

3 years ago
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-
(Assignee)

Comment 20

3 years ago
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?
Mozharness patch:

https://hg.mozilla.org/build/mozharness/rev/c7c9a537ecff
(Assignee)

Comment 23

3 years ago
Created attachment 8463631 [details] [diff] [review]
0001-Bug-1039833-Add-structured-logging-command-line-argu.patch

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+
(Assignee)

Comment 25

3 years ago
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)
(Assignee)

Comment 26

3 years ago
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
(Assignee)

Comment 29

3 years ago
Created attachment 8464266 [details] [diff] [review]
0001-Bug-1039833-Add-structured-logging-command-line-argu.patch

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+
(Assignee)

Updated

3 years ago
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
(Assignee)

Comment 31

3 years ago
Created attachment 8465011 [details] [diff] [review]
0001-Bug-1039833-Add-structured-logging-command-line-argu.patch

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)
(Assignee)

Comment 32

3 years ago
Created attachment 8465198 [details] [diff] [review]
0001-Bug-1039833-Add-structured-logging-command-line-argu.patch

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)
(Assignee)

Comment 33

3 years ago
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+
(Assignee)

Comment 36

3 years ago
I'm going to try to fix a couple other mochitest bugs before landing this.
(Assignee)

Comment 37

3 years ago
Created attachment 8468843 [details] [diff] [review]
0001-Bug-1039833-Add-structured-logging-command-line-argu.patch

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+
(Assignee)

Updated

3 years ago
Keywords: checkin-needed
(Assignee)

Comment 38

3 years ago
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)
(Assignee)

Comment 40

3 years ago
Thanks Andrew!
Status: NEW → ASSIGNED
Keywords: checkin-needed
Needs rebasing.
Keywords: checkin-needed
(Assignee)

Comment 42

3 years ago
Created attachment 8470120 [details] [diff] [review]
0001-Bug-1039833-Add-structured-logging-command-line-argu.patch

rebased.

(conflict probably caused by bug 1050148 landing)
Attachment #8468843 - Attachment is obsolete: true
Attachment #8470120 - Flags: review+
(Assignee)

Updated

3 years ago
Keywords: checkin-needed
(Assignee)

Updated

3 years ago
Blocks: 1050855
(Assignee)

Comment 43

3 years ago
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?
(Assignee)

Comment 45

3 years ago
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)
(Assignee)

Comment 46

3 years ago
Created attachment 8470451 [details] [diff] [review]
0001-Bug-1039833-Add-structured-logging-command-line-argu.patch

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.
(Assignee)

Comment 50

3 years ago
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.)
(Assignee)

Comment 51

3 years ago
Created attachment 8471071 [details] [diff] [review]
0001-Bug-1039833-Add-structured-logging-command-line-argu.patch

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+
(Assignee)

Comment 52

3 years ago
Created attachment 8472520 [details] [diff] [review]
0001-Bug-1039833-Add-structured-logging-command-line-argu.patch

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+
(Assignee)

Updated

3 years ago
Keywords: checkin-needed
https://hg.mozilla.org/integration/mozilla-inbound/rev/1db4be77a409
Keywords: checkin-needed
https://hg.mozilla.org/mozilla-central/rev/1db4be77a409
Status: ASSIGNED → RESOLVED
Last Resolved: 3 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla34
https://hg.mozilla.org/releases/mozilla-aurora/rev/7d0337de2e15
status-firefox33: --- → fixed
status-firefox34: --- → fixed
(Assignee)

Updated

3 years ago
Depends on: 1056329
You need to log in before you can comment on or make changes to this bug.