1039833 - Add structured logging command line arguments for mochitest/mach

Status: RESOLVED FIXED

(Testing :: Mochitest, defect)

Description

[Ahmed Kachkach [:akachkach]]

Attachment: WIP patch

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

Comment 1

[Ahmed Kachkach [:akachkach]]

Attachment: 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)

Comment 2

[Ahmed Kachkach [:akachkach]]

Attachment: 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

Comment 3

[Ahmed Kachkach [:akachkach]]

Attachment: 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.

Comment 4

[Ahmed Kachkach [:akachkach]]

Attachment: mozharness_scripts.patch

Updated the previous patch to always include the vars. (simpler this way)

Comment 5

[Andrew Halberstadt [:ahal]]

Comment on attachment 8459938 [details] [diff] [review]
mozharness_scripts.patch

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

Lgtm!

Comment 6

[Andrew Halberstadt [:ahal]]

At Ahmed's request I pushed these patches to ash-mozharness and Ash. Results here:
https://tbpl.mozilla.org/?tree=Ash&rev=59f661f6896f

Comment 7

[Chris Manchester (limited bugmail, email directly)]

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.

Comment 8

[Ahmed Kachkach [:akachkach]]

Attachment: mozharness_scripts.patch

Woops, forgot it would be used by the other test suites. Fixed!

Comment 9

[Chris Manchester (limited bugmail, email directly)]

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?

Comment 10

[Chris Manchester (limited bugmail, email directly)]

(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

Comment 11

[Chris Manchester (limited bugmail, email directly)]

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

Comment 12

[Andrew Halberstadt [:ahal]]

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

Comment 13

[Andrew Halberstadt [:ahal]]

Some of the re-triggers came back orange:
https://tbpl.mozilla.org/php/getParsedLog.php?id=44413809&tree=Ash&full=1#error0

Comment 14

[Ahmed Kachkach [:akachkach]]

Attachment: commandline.patch

Fixes that little bug that made some jobs orange and the issues raised by chmanchester.

Comment 15

[Andrew Halberstadt [:ahal]]

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.

Comment 16

[Ahmed Kachkach [:akachkach]]

Attachment: 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?

Comment 17

[Chris Manchester (limited bugmail, email directly)]

Ok to land the mozharness changes in the meantime?

Comment 18

[Ahmed Kachkach [:akachkach]]

Attachment: commandline.patch

woops, that was just a change that I forgot to revert. Here's the updated patch.

Comment 19

[Andrew Halberstadt [:ahal]]

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.

Comment 20

[Ahmed Kachkach [:akachkach]]

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.

Comment 21

[Andrew Halberstadt [:ahal]]

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?

Comment 22

[Chris Manchester (limited bugmail, email directly)]

Mozharness patch:

https://hg.mozilla.org/build/mozharness/rev/c7c9a537ecff

Comment 23

[Ahmed Kachkach [:akachkach]]

Attachment: 0001-Bug-1039833-Add-structured-logging-command-line-argu.patch

Only passing logger options now.

Comment 24

[Andrew Halberstadt [:ahal]]

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?

Comment 25

[Ahmed Kachkach [:akachkach]]

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 ?

Comment 26

[Ahmed Kachkach [:akachkach]]

woops, sorry :jmaher, wanted to ping :chmanchester

Comment 27

[Chris Manchester (limited bugmail, email directly)]

(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

Comment 28

[Justin Wood (:Callek)]

something here is now in production

Comment 29

[Ahmed Kachkach [:akachkach]]

Attachment: 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

Comment 30

[Carsten Book [:Tomcat]]

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!

Comment 31

[Ahmed Kachkach [:akachkach]]

Attachment: 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.

Comment 32

[Ahmed Kachkach [:akachkach]]

Attachment: 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

Comment 33

[Ahmed Kachkach [:akachkach]]

Note: 'will have to avoid falling into this regression when we land this => bug 1046566

Comment 34

[Justin Wood (:Callek)]

something(s) here went to production today

Comment 35

[Chris Manchester (limited bugmail, email directly)]

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.

Comment 36

[Ahmed Kachkach [:akachkach]]

I'm going to try to fix a couple other mochitest bugs before landing this.

Comment 37

[Ahmed Kachkach [:akachkach]]

Attachment: 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

Comment 38

[Ahmed Kachkach [:akachkach]]

woops, forgot to ask ahal to make sure it works as expected. (thanks!)

Comment 39

[Andrew Halberstadt [:ahal]]

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.

Comment 40

[Ahmed Kachkach [:akachkach]]

Thanks Andrew!

Comment 41

[Ryan VanderMeulen [:RyanVM]]

Needs rebasing.

Comment 42

[Ahmed Kachkach [:akachkach]]

Attachment: 0001-Bug-1039833-Add-structured-logging-command-line-argu.patch

rebased.

(conflict probably caused by bug 1050148 landing)

Comment 43

[Ahmed Kachkach [:akachkach]]

Some recent changes have broken this patch with robocop, will post an updated version when I figure this out.

Comment 44

[Martijn Wargers (dead)]

Ahmed, does your patch add help info, e.g., when you do ./mach mochitest-plain --help, does it haven an entry for --log-raw?

Comment 45

[Ahmed Kachkach [:akachkach]]

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.

Comment 46

[Ahmed Kachkach [:akachkach]]

Attachment: 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

Comment 47

[Andrew Halberstadt [:ahal]]

--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.

Comment 48

[James Graham [:jgraham]]

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.

Comment 49

[Andrew Halberstadt [:ahal]]

Yeah, that's what I meant. Explicitly add them to the parser because they don't get picked up automatically.

Comment 50

[Ahmed Kachkach [:akachkach]]

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

Comment 51

[Ahmed Kachkach [:akachkach]]

Attachment: 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

Comment 52

[Ahmed Kachkach [:akachkach]]

Attachment: 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!"

Comment 53

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/1db4be77a409

Comment 54

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/1db4be77a409

Comment 55

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/7d0337de2e15