Ahmed Kachkach [:akachkach] Assignee
	Description • 10 years ago

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

	Ahmed Kachkach [:akachkach] Assignee
	Comment 1 • 10 years ago

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)

	Ahmed Kachkach [:akachkach] Assignee
	Comment 2 • 10 years ago

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

	Ahmed Kachkach [:akachkach] Assignee
	Comment 3 • 10 years ago

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.

	Ahmed Kachkach [:akachkach] Assignee
	Comment 4 • 10 years ago

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

	Andrew Halberstadt [:ahal]
	Comment 5 • 10 years ago

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

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

Lgtm!

	Andrew Halberstadt [:ahal]
	Comment 6 • 10 years ago

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

	Chris Manchester (limited bugmail, email directly)
	Comment 7 • 10 years ago

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.

	Ahmed Kachkach [:akachkach] Assignee
	Comment 8 • 10 years ago

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

	Chris Manchester (limited bugmail, email directly)
	Comment 9 • 10 years ago

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?

	Chris Manchester (limited bugmail, email directly)
	Comment 10 • 10 years ago

(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

	Chris Manchester (limited bugmail, email directly)
	Comment 11 • 10 years ago

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

	Andrew Halberstadt [:ahal]
	Comment 12 • 10 years ago

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

	Andrew Halberstadt [:ahal]
	Comment 13 • 10 years ago

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

	Ahmed Kachkach [:akachkach] Assignee
	Comment 14 • 10 years ago

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

	Andrew Halberstadt [:ahal]
	Comment 15 • 10 years ago

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.

	Ahmed Kachkach [:akachkach] Assignee
	Comment 16 • 10 years ago

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?

	Chris Manchester (limited bugmail, email directly)
	Comment 17 • 10 years ago

Ok to land the mozharness changes in the meantime?

	Ahmed Kachkach [:akachkach] Assignee
	Comment 18 • 10 years ago

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

	Andrew Halberstadt [:ahal]
	Comment 19 • 10 years ago

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.

	Ahmed Kachkach [:akachkach] Assignee
	Comment 20 • 10 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.

	Andrew Halberstadt [:ahal]
	Comment 21 • 10 years ago

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?

	Chris Manchester (limited bugmail, email directly)
	Comment 22 • 10 years ago

Mozharness patch:

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

	Ahmed Kachkach [:akachkach] Assignee
	Comment 23 • 10 years ago

Only passing logger options now.

	Andrew Halberstadt [:ahal]
	Comment 24 • 10 years ago

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?

	Ahmed Kachkach [:akachkach] Assignee
	Comment 25 • 10 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 ?

	Ahmed Kachkach [:akachkach] Assignee
	Comment 26 • 10 years ago

woops, sorry :jmaher, wanted to ping :chmanchester

	Chris Manchester (limited bugmail, email directly)
	Comment 27 • 10 years ago

(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

	Justin Wood (:Callek)
	Comment 28 • 10 years ago

something here is now in production

	Ahmed Kachkach [:akachkach] Assignee
	Comment 29 • 10 years ago

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

	Carsten Book [:Tomcat]
	Comment 30 • 10 years ago

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!

	Ahmed Kachkach [:akachkach] Assignee
	Comment 31 • 10 years ago

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.

	Ahmed Kachkach [:akachkach] Assignee
	Comment 32 • 10 years ago

A couple small changes to fix a bug.

Try run: https://tbpl.mozilla.org/?tree=Try&rev=9e6c0ea152ee

	Ahmed Kachkach [:akachkach] Assignee
	Comment 33 • 10 years ago

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

	Justin Wood (:Callek)
	Comment 34 • 10 years ago

something(s) here went to production today

	Chris Manchester (limited bugmail, email directly)
	Comment 35 • 10 years ago

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.

	Ahmed Kachkach [:akachkach] Assignee
	Comment 36 • 10 years ago

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

	Ahmed Kachkach [:akachkach] Assignee
	Comment 37 • 10 years ago

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

	Ahmed Kachkach [:akachkach] Assignee
	Comment 38 • 10 years ago

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

	Andrew Halberstadt [:ahal]
	Comment 39 • 10 years ago

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.

	Ahmed Kachkach [:akachkach] Assignee
	Comment 40 • 10 years ago

Thanks Andrew!

	Ryan VanderMeulen [:RyanVM]
	Comment 41 • 10 years ago

Needs rebasing.

	Ahmed Kachkach [:akachkach] Assignee
	Comment 42 • 10 years ago

rebased.

(conflict probably caused by bug 1050148 landing)

	Ahmed Kachkach [:akachkach] Assignee
	Comment 43 • 10 years ago

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

	Martijn Wargers (dead)
	Comment 44 • 10 years ago

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

	Ahmed Kachkach [:akachkach] Assignee
	Comment 45 • 10 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.

	Ahmed Kachkach [:akachkach] Assignee
	Comment 46 • 10 years ago

carry r+ forward;

Updated to fix a bug caused by a bad merge.

https://tbpl.mozilla.org/?tree=Try&rev=cac16f5fd5a6

	Andrew Halberstadt [:ahal]
	Comment 47 • 10 years ago

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

	James Graham [:jgraham]
	Comment 48 • 10 years ago

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.

	Andrew Halberstadt [:ahal]
	Comment 49 • 10 years ago

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

	Ahmed Kachkach [:akachkach] Assignee
	Comment 50 • 10 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.)

	Ahmed Kachkach [:akachkach] Assignee
	Comment 51 • 10 years ago

carry r+ forward;

Rebased the patch. Should be ready to land now.

Try run: https://tbpl.mozilla.org/?tree=Try&rev=be16c18b8d0f

	Ahmed Kachkach [:akachkach] Assignee
	Comment 52 • 10 years ago

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

	Ryan VanderMeulen [:RyanVM]
	Comment 53 • 10 years ago

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

	Ryan VanderMeulen [:RyanVM]
	Comment 54 • 10 years ago

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

	Ryan VanderMeulen [:RyanVM]
	Comment 55 • 10 years ago

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