1421799 - Make 'mach' log format the default for |mach test| and |mach mochitest|

Status: RESOLVED FIXED

(Testing :: General, enhancement)

Description

[Andrew Halberstadt [:ahal]]

Currently running |mach test| or |mach mochitest| uses the 'tbpl' format by default. The mach format tends to be a bit nicer to read on a terminal with color support, it would be good to use this by default.

It needs a bit of cleaning up though, it can be a bit verbose and seems to print None into the thread field a fair amount. This bug will first clean the format up a bit, and then make it the default.

Comment 1

[Andrew Halberstadt [:ahal]]

Attachment: Bug 1421799 - [reftest] Log 'GECKO(<pid>)' instead of 'ProcessReader' for process_output log actions

Review commit: https://reviewboard.mozilla.org/r/206002/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/206002/

Comment 2

[Andrew Halberstadt [:ahal]]

Attachment: Bug 1421799 - [mochitest] Stop printing NOW RUNNING messages

The suite name is no part of the suite_start message and can be printed via a
mozlog formatter. We shouldn't be printing this directly to stdout from |mach
mochitest|.

Review commit: https://reviewboard.mozilla.org/r/206004/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/206004/

Comment 3

[Andrew Halberstadt [:ahal]]

Attachment: Bug 1421799 - [mozlog] Improve the 'mach' formatter

This makes several changes to make the 'mach' format cleaner and easier to
read. Some of the changes include:

* No longer print the 'action' no matter what. Printing the action for things
  like 'log' or 'process_output' was redundant and caused verbosity. Now this
  is done on a case by case basis (things like TEST-START/TEST-END will still
  have their actions printed).
* Color coded the process id for 'process_output' actions. This is a dim cyan
  to avoid conflicts with other actions.
* No longer quoting 'process_output' messages
* No longer printing thread information. In 99% of the case, this was just
  dumping 'MainThread' over and over again. Perhaps printing this could be an
  option on the formatter.
* Muted timestamps to help the important parts stand out better
* Colorized suite summary headings
* Unexpected statuses in _format_expected() are always red (never yellow).
  This is to help make it stand out from all the other yellow text that gets
  printed.
* Internal cleanup/refactoring

Review commit: https://reviewboard.mozilla.org/r/206006/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/206006/

Comment 4

[Andrew Halberstadt [:ahal]]

Attachment: Bug 1421799 - [test] Add mozlog logging arguments to |mach test| and |mach mochitest|

Review commit: https://reviewboard.mozilla.org/r/206008/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/206008/

Comment 5

[Andrew Halberstadt [:ahal]]

Attachment: Bug 1421799 - [test] Make the 'mach' formatter the default when running |mach test| and |mach mochitest|

Review commit: https://reviewboard.mozilla.org/r/206010/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/206010/

Comment 6

[Andrew Halberstadt [:ahal]]

Attachment: Example screenshot of new 'mach' format

Comment 7

[Andrew Halberstadt [:ahal]]

This still depends on bug 1209463, but that bug shouldn't affect this bug too much, so might as well get the review process started.

Comment 8

[Andrew Halberstadt [:ahal]]

Comment on attachment 8935154 [details]
Bug 1421799 - [reftest] Log 'GECKO(<pid>)' instead of 'ProcessReader' for process_output log actions

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/206002/diff/1-2/

Comment 9

[Andrew Halberstadt [:ahal]]

Comment on attachment 8935155 [details]
Bug 1421799 - [mochitest] Stop printing NOW RUNNING messages

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/206004/diff/1-2/

Comment 10

[Andrew Halberstadt [:ahal]]

Comment on attachment 8935156 [details]
Bug 1421799 - [mozlog] Improve the 'mach' formatter

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/206006/diff/1-2/

Comment 11

[Andrew Halberstadt [:ahal]]

Comment on attachment 8935157 [details]
Bug 1421799 - [test] Add mozlog logging arguments to |mach test| and |mach mochitest|

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/206008/diff/1-2/

Comment 12

[Andrew Halberstadt [:ahal]]

Comment on attachment 8935158 [details]
Bug 1421799 - [test] Make the 'mach' formatter the default when running |mach test| and |mach mochitest|

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/206010/diff/1-2/

Comment 13

[Geoff Brown [:gbrown]]

Comment on attachment 8935154 [details]
Bug 1421799 - [reftest] Log 'GECKO(<pid>)' instead of 'ProcessReader' for process_output log actions

https://reviewboard.mozilla.org/r/206002/#review212018

Comment 14

[Geoff Brown [:gbrown]]

Comment on attachment 8935155 [details]
Bug 1421799 - [mochitest] Stop printing NOW RUNNING messages

https://reviewboard.mozilla.org/r/206004/#review212126

Just voicing my opinion...no need to act on it.

::: testing/mochitest/mach_commands.py
(Diff revision 2)
>          for (flavor, subsuite), tests in sorted(suites.items()):
>              fobj = ALL_FLAVORS[flavor]
> -            msg = fobj['aliases'][0]
> -            if subsuite:
> -                msg = '{} with subsuite {}'.format(msg, subsuite)
> -            print(NOW_RUNNING.format(msg))

I'm a little uncomfortable with removing this completely...I find it helpful to see the subsuite, when running multiple subsuites.

Comment 15

[Geoff Brown [:gbrown]]

Comment on attachment 8935156 [details]
Bug 1421799 - [mozlog] Improve the 'mach' formatter

https://reviewboard.mozilla.org/r/206006/#review212134

::: testing/mozbase/mozlog/mozlog/formatters/machformatter.py:52
(Diff revision 2)
>  
>          s = super(MachFormatter, self).__call__(data)
>          if s is None:
>              return
>  
> -        time = format_seconds(self._time(data))
> +        time = self.term.dim_blue(format_seconds(self._time(data)))

This feels a little "hard coded". I think it would be nice if there was one place in the code that mapped colours:

 time_color = blue
 error_color = red
 
...but I'm not clear on how to do that cleanly, and unsure if it is worth the effort.

Comment 16

[Geoff Brown [:gbrown]]

Comment on attachment 8935157 [details]
Bug 1421799 - [test] Add mozlog logging arguments to |mach test| and |mach mochitest|

https://reviewboard.mozilla.org/r/206008/#review212138

Comment 17

[Geoff Brown [:gbrown]]

Comment on attachment 8935158 [details]
Bug 1421799 - [test] Make the 'mach' formatter the default when running |mach test| and |mach mochitest|

https://reviewboard.mozilla.org/r/206010/#review212140

Seems like a good change -- looking forward to it.

Comment 18

[Geoff Brown [:gbrown]]

I could not apply your patches cleanly, so didn't test these at all, but the changes look reasonable and I really like the look of your screenshot -- good stuff!

Comment 19

[Andrew Halberstadt [:ahal]]

Comment on attachment 8935155 [details]
Bug 1421799 - [mochitest] Stop printing NOW RUNNING messages

https://reviewboard.mozilla.org/r/206004/#review212126

> I'm a little uncomfortable with removing this completely...I find it helpful to see the subsuite, when running multiple subsuites.

Later on in this patch series, the mach formatter will print the suite name (including mochitest subsuite) as part of the SUITE_START message. It's not as visible as this though.

The main reason I removed it was that it's mochitest specific, so when running `mach test` it's a little weird that it gets printed for some suites but not others. I'd also like to implement a terminal footer like |mach build| has which would have the currently running suite highlighted. I think this would be a better way of displaying this information, though I guess we could leave the current `print` statement as is until that gets landed.

Comment 20

[Andrew Halberstadt [:ahal]]

Comment on attachment 8935156 [details]
Bug 1421799 - [mozlog] Improve the 'mach' formatter

https://reviewboard.mozilla.org/r/206006/#review212134

> This feels a little "hard coded". I think it would be nice if there was one place in the code that mapped colours:
> 
>  time_color = blue
>  error_color = red
>  
> ...but I'm not clear on how to do that cleanly, and unsure if it is worth the effort.

Yeah, ideally I'd like to do something like mercurial does, and allow colors to be tweaked in `machrc`. Maybe we could allow users to specify something like:

    [colors]
    log.suite_start = yellow
    log.process_output = blue
    ...

I don't want to scope bloat this bug though, I filed bug 1424287 to tackle it in a follow up.

Comment 21

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/bbe4d2292f86
[reftest] Log 'GECKO(<pid>)' instead of 'ProcessReader' for process_output log actions r=gbrown
https://hg.mozilla.org/integration/autoland/rev/afe14ec646ab
[mochitest] Stop printing NOW RUNNING messages r=gbrown
https://hg.mozilla.org/integration/autoland/rev/2de335c0287a
[mozlog] Improve the 'mach' formatter r=gbrown
https://hg.mozilla.org/integration/autoland/rev/629e467a07be
[test] Add mozlog logging arguments to |mach test| and |mach mochitest| r=gbrown
https://hg.mozilla.org/integration/autoland/rev/7fb20bced076
[test] Make the 'mach' formatter the default when running |mach test| and |mach mochitest| r=gbrown

Comment 22

[Dorel Luca [:dluca]]

Backed out 5 changesets (bug 1421799) for failing browser-chrome on Linux and OSX and for failing autophone-mochitest on Android r=backout on a CLOSED TREE

https://treeherder.mozilla.org/logviewer.html#?job_id=151644980&repo=autoland&lineNumber=1892

https://hg.mozilla.org/integration/autoland/rev/61190fb111086d6db7efa0af1aed0e345016e25f

https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=7fb20bced07629eb683f79951f325ff07c07c8dc

Comment 23

[Andrew Halberstadt [:ahal]]

Attachment: Bug 1421799 - [test_archive] Add 'mozterm' to common.tests.zip

Review commit: https://reviewboard.mozilla.org/r/207786/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/207786/

Comment 24

[Andrew Halberstadt [:ahal]]

Comment on attachment 8935154 [details]
Bug 1421799 - [reftest] Log 'GECKO(<pid>)' instead of 'ProcessReader' for process_output log actions

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/206002/diff/2-3/

Comment 25

[Andrew Halberstadt [:ahal]]

Comment on attachment 8935155 [details]
Bug 1421799 - [mochitest] Stop printing NOW RUNNING messages

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/206004/diff/2-3/

Comment 26

[Andrew Halberstadt [:ahal]]

Comment on attachment 8935156 [details]
Bug 1421799 - [mozlog] Improve the 'mach' formatter

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/206006/diff/2-3/

Comment 27

[Andrew Halberstadt [:ahal]]

Comment on attachment 8935157 [details]
Bug 1421799 - [test] Add mozlog logging arguments to |mach test| and |mach mochitest|

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/206008/diff/2-3/

Comment 28

[Andrew Halberstadt [:ahal]]

Comment on attachment 8935158 [details]
Bug 1421799 - [test] Make the 'mach' formatter the default when running |mach test| and |mach mochitest|

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/206010/diff/2-3/

Comment 29

[Andrew Halberstadt [:ahal]]

Comment on attachment 8937078 [details]
Bug 1421799 - [test_archive] Add 'mozterm' to common.tests.zip

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/207786/diff/1-2/

Comment 30

[Andrew Halberstadt [:ahal]]

Comment on attachment 8935154 [details]
Bug 1421799 - [reftest] Log 'GECKO(<pid>)' instead of 'ProcessReader' for process_output log actions

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/206002/diff/3-4/

Comment 31

[Andrew Halberstadt [:ahal]]

Comment on attachment 8935155 [details]
Bug 1421799 - [mochitest] Stop printing NOW RUNNING messages

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/206004/diff/3-4/

Comment 32

[Andrew Halberstadt [:ahal]]

Comment on attachment 8935156 [details]
Bug 1421799 - [mozlog] Improve the 'mach' formatter

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/206006/diff/3-4/

Comment 33

[Andrew Halberstadt [:ahal]]

Comment on attachment 8935157 [details]
Bug 1421799 - [test] Add mozlog logging arguments to |mach test| and |mach mochitest|

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/206008/diff/3-4/

Comment 34

[Andrew Halberstadt [:ahal]]

Comment on attachment 8935158 [details]
Bug 1421799 - [test] Make the 'mach' formatter the default when running |mach test| and |mach mochitest|

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/206010/diff/3-4/

Comment 35

[Andrew Halberstadt [:ahal]]

This was happening because I forgot to add mozterm to the test package. Sorry about that. This looks to be fixed with the latest series:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=ce94b85bdeee612db9c87734ede29860b75d1d4f

Comment 36

[Andrew Halberstadt [:ahal]]

Still broken on Android.

Comment 37

[Andrew Halberstadt [:ahal]]

Comment on attachment 8937078 [details]
Bug 1421799 - [test_archive] Add 'mozterm' to common.tests.zip

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/207786/diff/2-3/

Comment 38

[Andrew Halberstadt [:ahal]]

Comment on attachment 8935154 [details]
Bug 1421799 - [reftest] Log 'GECKO(<pid>)' instead of 'ProcessReader' for process_output log actions

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/206002/diff/4-5/

Comment 39

[Andrew Halberstadt [:ahal]]

Comment on attachment 8935155 [details]
Bug 1421799 - [mochitest] Stop printing NOW RUNNING messages

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/206004/diff/4-5/

Comment 40

[Andrew Halberstadt [:ahal]]

Comment on attachment 8935156 [details]
Bug 1421799 - [mozlog] Improve the 'mach' formatter

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/206006/diff/4-5/

Comment 41

[Andrew Halberstadt [:ahal]]

Comment on attachment 8935157 [details]
Bug 1421799 - [test] Add mozlog logging arguments to |mach test| and |mach mochitest|

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/206008/diff/4-5/

Comment 42

[Geoff Brown [:gbrown]]

Comment on attachment 8937078 [details]
Bug 1421799 - [test_archive] Add 'mozterm' to common.tests.zip

https://reviewboard.mozilla.org/r/207786/#review214468

Comment 43

[Andrew Halberstadt [:ahal]]

Comment on attachment 8937078 [details]
Bug 1421799 - [test_archive] Add 'mozterm' to common.tests.zip

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/207786/diff/3-4/

Comment 44

[Andrew Halberstadt [:ahal]]

Comment on attachment 8935154 [details]
Bug 1421799 - [reftest] Log 'GECKO(<pid>)' instead of 'ProcessReader' for process_output log actions

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/206002/diff/5-6/

Comment 45

[Andrew Halberstadt [:ahal]]

Comment on attachment 8935155 [details]
Bug 1421799 - [mochitest] Stop printing NOW RUNNING messages

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/206004/diff/5-6/

Comment 46

[Andrew Halberstadt [:ahal]]

Comment on attachment 8935156 [details]
Bug 1421799 - [mozlog] Improve the 'mach' formatter

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/206006/diff/5-6/

Comment 47

[Andrew Halberstadt [:ahal]]

Comment on attachment 8935157 [details]
Bug 1421799 - [test] Add mozlog logging arguments to |mach test| and |mach mochitest|

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/206008/diff/5-6/

Comment 48

[Andrew Halberstadt [:ahal]]

Latest push rebases on top of central. May have gone a little overboard on the try testing, but everything looks good:
https://treeherder.mozilla.org/#/jobs?repo=try&author=[e-mail]&fromchange=798107446a2a230cff31c265306b1068c20275ac&tochange=eed4e8ad38fd7460cd4d549a537af780e96bbc1a

Comment 49

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/e028f677bc80
[test_archive] Add 'mozterm' to common.tests.zip r=gbrown
https://hg.mozilla.org/integration/autoland/rev/8c1f1ab754a5
[reftest] Log 'GECKO(<pid>)' instead of 'ProcessReader' for process_output log actions r=gbrown
https://hg.mozilla.org/integration/autoland/rev/88dca5c8cfac
[mochitest] Stop printing NOW RUNNING messages r=gbrown
https://hg.mozilla.org/integration/autoland/rev/18b4fa241936
[mozlog] Improve the 'mach' formatter r=gbrown
https://hg.mozilla.org/integration/autoland/rev/f9f32474fdaf
[test] Add mozlog logging arguments to |mach test| and |mach mochitest| r=gbrown

Comment 50

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

Backed out for failing firefox ui functional tests:

https://hg.mozilla.org/integration/autoland/rev/9dcfb0365f3c758f9edbea67d94614cd582c1559

Push with failures: https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=b91ce5ed4d3597cf627b49c96def71ba63f1cc7d&filter-resultStatus=usercancel&filter-resultStatus=runnable&filter-resultStatus=testfailed&filter-resultStatus=busted&filter-resultStatus=exception
Failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=153886422&repo=autoland
> Invalid requirement: '../tools/mozterm'

There are also failures for autophone on the push of this bug, but those jobs didn't run for the pushes before that: https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=f9f32474fdaf5914832d256293ee1f98c6bf2561&filter-resultStatus=usercancel&filter-resultStatus=runnable&filter-resultStatus=testfailed&filter-resultStatus=busted&filter-resultStatus=exception

Comment 51

[Andrew Halberstadt [:ahal]]

The autophone failures are being fixed in the upstream repo (it's out of tree). I guess I missed the firefox ui tests in my try run. I guess those don't use the tests.zip? Adding a new package dependency is proving to be more of a pain than I was hoping :(

Comment 52

[Andrew Halberstadt [:ahal]]

The firefox-ui-tests broke because the mozharness script wasn't configured to extract the 'mozterm' directory from the tests.zip. The autophone issue should also be fixed, just waiting on try results for both.

Comment 53

[Andrew Halberstadt [:ahal]]

Autophone retriggers on my failing push are coming back green:
https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=f9f32474fdaf5914832d256293ee1f98c6bf2561&filter-searchStr=autophone

Here's a new try run with firefox-ui tests fixed:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=70d7e9795255bae9f13f0f2600e05a2df951a70e

Comment 54

[Andrew Halberstadt [:ahal]]

Comment on attachment 8937078 [details]
Bug 1421799 - [test_archive] Add 'mozterm' to common.tests.zip

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/207786/diff/4-5/

Comment 55

[Andrew Halberstadt [:ahal]]

Comment on attachment 8935154 [details]
Bug 1421799 - [reftest] Log 'GECKO(<pid>)' instead of 'ProcessReader' for process_output log actions

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/206002/diff/6-7/

Comment 56

[Andrew Halberstadt [:ahal]]

Comment on attachment 8935155 [details]
Bug 1421799 - [mochitest] Stop printing NOW RUNNING messages

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/206004/diff/6-7/

Comment 57

[Andrew Halberstadt [:ahal]]

Comment on attachment 8935156 [details]
Bug 1421799 - [mozlog] Improve the 'mach' formatter

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/206006/diff/6-7/

Comment 58

[Andrew Halberstadt [:ahal]]

Comment on attachment 8935157 [details]
Bug 1421799 - [test] Add mozlog logging arguments to |mach test| and |mach mochitest|

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/206008/diff/6-7/

Comment 59

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/5ee21ac1a6ec
[test_archive] Add 'mozterm' to common.tests.zip r=gbrown
https://hg.mozilla.org/integration/autoland/rev/419ba12cc0c8
[reftest] Log 'GECKO(<pid>)' instead of 'ProcessReader' for process_output log actions r=gbrown
https://hg.mozilla.org/integration/autoland/rev/0ad440c6f93b
[mochitest] Stop printing NOW RUNNING messages r=gbrown
https://hg.mozilla.org/integration/autoland/rev/cee49b47add0
[mozlog] Improve the 'mach' formatter r=gbrown
https://hg.mozilla.org/integration/autoland/rev/9b58dffaaa49
[test] Add mozlog logging arguments to |mach test| and |mach mochitest| r=gbrown

Comment 60

[Noemi Erli[:noemi_erli]]

https://hg.mozilla.org/mozilla-central/rev/5ee21ac1a6ec
https://hg.mozilla.org/mozilla-central/rev/419ba12cc0c8
https://hg.mozilla.org/mozilla-central/rev/0ad440c6f93b
https://hg.mozilla.org/mozilla-central/rev/cee49b47add0
https://hg.mozilla.org/mozilla-central/rev/9b58dffaaa49

Comment 61

[Henrik Skupin [:whimboo][⌚️UTC+2] (away July 24th - August 16th)]

Andrew, where is the code of mozterm and are we planning to add it to the tree?

Comment 62

[Andrew Halberstadt [:ahal]]

It is in the tree under python/mozterm.

Comment 63

[Henrik Skupin [:whimboo][⌚️UTC+2] (away July 24th - August 16th)]

(In reply to Andrew Halberstadt [:ahal] from comment #62)
> It is in the tree under python/mozterm.

Oh, I didn't thought about this folder. Would you mind to add a URL to the setup.py which points to the source? Right now it is not clear on PyPI where the source is located.

Comment 64

[Yulia Startsev [:yulia] OOO until July 2026]

This is really awesome. I just don't know how to use it... is it possible to get this output already? how does one turn it on?

Comment 65

[Mike Ratcliffe [:miker] [:mratcliffe] [:mikeratcliffe]]

./mach mochitest devtools/client/storage/test/browser_storage_dynamic_updates_cookies.js --log-mach=-

You can also set an alias:
alias mochitest='./mach mochitest --log-mach=-'

Comment 66

[Andrew Halberstadt [:ahal]]

Oh, that's embarrassing. This bug was supposed to make the 'mach' format default, but 'tbpl' is still the default:
https://searchfox.org/mozilla-central/source/testing/mach_commands.py#67

I must have accidentally blown over that change while resolving conflicts or something and because I had:

[test]
format=mach

in my ~/.mozbuild/machrc, I never noticed. I'll file a new bug to get this fixed. If you want this on in the meantime, feel free to add the above to your machrc too (you may need to create it).

Also to note, reftest will still be excluded from this format as it is not compatible with the reftest-analyzer.