Closed Bug 1445624 Opened 2 years ago Closed 2 years ago

Make mach formatter more usable

Categories

(Testing :: Mozbase, enhancement)

enhancement
Not set

Tracking

(firefox61 fixed)

RESOLVED FIXED
mozilla61
Tracking Status
firefox61 --- fixed

People

(Reporter: Gijs, Assigned: ahal)

References

(Depends on 3 open bugs)

Details

Attachments

(3 files)

(In reply to J. Ryan Stinnett [:jryans] (use ni?) from bug 1443557 comment #0)
> The mach formatter is easier for humans with its colored output and other
> nice things.
> 
> For some reason, it's not enabled by default.  It seems like most developers
> would benefit from having it on, but may not be aware of it.
> 
> Can we enable it by default, at least when a terminal / tty is present?


I have several issues with this change:

0) There was no announcement to either dev-platform or fx-dev, and it's not obvious from the bug that changed this how to switch back to something that I find usable.
1) I get no coloured output (on Windows), so at least that bit hasn't materialized.
2) failure summaries (after the test finishes) now omit the values that failed. So I get the custom message the assertion provides, but not the expected and actual values (for Assert.equal() or equivalent), which makes it harder to find out what failed. For those values, I have to dig through the actual test log.
3) successful messages are no longer logged, making it impossible to figure out what failed at-a-glance based on the test output, especially if assertion messages are used multiple times within 1 test file. On the other hand, some other stuff *is* logged (e.g. repetitive "must wait for focus" messages, the marionette startup spam, `pipe error` crap after the test run finishes).
4) test failures are logged only at the end, so even though the test says "entering test bound" and then "leaving test bound", these offer no help as to when the assertion failure happened, either.
5) output isn't easily scannable like it was before - there is no useful ALLCAPS prefix on lines, I have to look for bits that look something like:


Some assertion message
----------------------
Expected PASS, got FAIL
Got 0, expected 1
Stack trace:
...

6) multiple failures have no clear separator, because of (5). So my output now looks like:

Some assertion message
----------------------
Expected PASS, got FAIL
Got 0, expected 1
Stack trace:
...
Some other assertion message
----------------------------

The faux underline for the assertion message actually makes it *harder* to correctly associate stacks to the relevant assertion message, because it separates the message from the rest of the information, rather than separating it from the previous failed assertion.



Please can we address this so that debugging tests can be less painful.
Thanks for the feedback, in the meantime feel free to add:

[test]
format=tbpl

to your ~/.mozbuild/machrc if you want the old format back by default.

0) I'll send a quick note
1) This is handled by the underlying blessings library. I think I remember seeing colours on my Windows machine, but I'll see if I can suss out why it isn't working for you. I can see how this format without colours would be a pain.
2-4) I'll look into these, if the tbpl formatter can provide this information, it shouldn't be hard for the mach formatter to do it as well.
5-6) These would get fixed by the colourization, but it could still be made better.
Summary: Make mach formatter not suck → Make mach formatter more usable
Depends on: 1445653
Colourization on Windows will be tricky, though anyone sufficiently motivated could probably get it working. I filed bug 1445653 with my findings. Colourization should work out of the box with WSL.
(In reply to :Gijs from comment #0)

> 3) successful messages are no longer logged, making it impossible to figure
> out what failed at-a-glance based on the test output, especially if
> assertion messages are used multiple times within 1 test file. On the other
> hand, some other stuff *is* logged (e.g. repetitive "must wait for focus"
> messages, the marionette startup spam, `pipe error` crap after the test run
> finishes).

I also miss the expected failures from the new output. These are the lines produced by todo() calls in the test, they used to be logged as "TEST-FAIL" (and "TEST-UNEXPECTED-FAIL" for what is now just shown as "FAIL").

Having color is very nice, but having the text output be significantly different between try results and local runs makes comparing what happens on try with what happens locally unnecessarily difficult.
I've fixed most of the complaints in a local patch so far, it's looking much better. That said I'm on the fence about something. Issue #3 and comment 3 are the same thing, by default the mach format doesn't log TEST_STATUS messages unless it's a failure. This behaviour can be changed by doing this:

./mach mochitest --log-mach-verbose

(I know this is long and unintuitive, but put that aside for now)

So with the above command you'll see all subtest statuses (included passing ones and known fails). Now I could switch the default around so it matches the tbpl formatter. I.e, subtest statuses will be shown by default, and they could be turned off with `--log-mach-compact`. The problem is that personally I really dislike this behaviour. Some tests spew thousands of subtest results, and if everything passes it makes the logs huge unnecessarily.

In my local patch, the stack (including line number of the failing assert) is always printed. So using the 'TEST-PASS' markers to find the assertion shouldn't be necessary. Is this an acceptable work around to resolving issue #3?

As far as Florian's comment goes, is the existence of --log-mach-verbose good enough for the case you actually *want* to see passing subtests?

I'll push my patches up to mozreview tomorrow so you guys can play around with it and give further feedback if you want.
Assignee: nobody → ahalberstadt
Status: NEW → ASSIGNED
(In reply to Andrew Halberstadt [:ahal] from comment #4)

> In my local patch, the stack (including line number of the failing assert)
> is always printed. So using the 'TEST-PASS' markers to find the assertion
> shouldn't be necessary. Is this an acceptable work around to resolving issue
> #3?

This doesn't help when a test runs something using a loop, so no.

> As far as Florian's comment goes, is the existence of --log-mach-verbose
> good enough for the case you actually *want* to see passing subtests?

I don't think developing a test locally should require using a command line parameter to see the output.

Let's take a step back and think about use cases. Am I correct in guessing that the reason why you want less output is that you run plenty of tests (a whole folder or a whole test suite at once) and want the output to mostly be about whether tests pass or not, and to give some progress indication (so show which test is running and which test has finished)?
If so, you would probably also want to remove the INFO lines (generated using info() calls in mochitests). It's currently surprising to see by default the output for info() but not for todo().

For the use cases I care about (developing new tests, or debugging a specific test failure, I really want to see the whole output. So, suggestions (mostly inspired from the xpcshell behavior) :
- show by default the whole output when running a single test
- while a test is running, buffer the whole output, and as soon as there's a failure, print the content of the buffer, and then use verbose logging for the rest of the test.
- always use the verbose logging for the tests that call SimpleTest.requestCompleteLog();
Those are good points. Buffering 'log' messages as well as 'test_status' and dumping the full thing on error sounds like the best of both worlds. Implementing this properly is going to be fairly challenging (ideally I'd like to refactor the tbpl formatter's implementation into something re-useable). So I'll file a separate bug, and hopefully I'll be able to find some time to tackle it.

Enabling verbose mode when only running a single test should be easy to do at least.
Depends on: 1446965
Comment on attachment 8960341 [details]
Bug 1445624 - [mozlog] Add some tests for the mach formatter,

https://reviewboard.mozilla.org/r/229088/#review234860


Code analysis found 3 defects in this patch:
 - 3 defects found by mozlint

You can run this analysis locally with:
 - `./mach lint path/to/file` (JS/Python)


If you see a problem in this automated review, please report it here: http://bit.ly/2y9N9Vx


::: testing/mozbase/mozlog/tests/test_formatters.py:5
(Diff revision 1)
> +# This Source Code Form is subject to the terms of the Mozilla Public
> +# License, v. 2.0. If a copy of the MPL was not distributed with this
> +# file, You can obtain one at http://mozilla.org/MPL/2.0/.
> +
> +from __future__ import absolute_import, unicode_literals

Error: Missing from __future__ import print_function [py2: require print_function]

::: testing/mozbase/mozlog/tests/test_formatters.py:45
(Diff revision 1)
> +        ('mach', {'verbose': True}, """
> + 0:00.00 SUITE_START: running 3 tests
> + 0:00.00 TEST_START: test_foo
> + 0:00.00 TEST_END: OK
> + 0:00.00 TEST_START: test_bar
> + 0:00.00 TEST_STATUS: a subtest PASS 

Error: Trailing whitespace [flake8: W291]

::: testing/mozbase/mozlog/tests/test_formatters.py:107
(Diff revision 1)
> +expected 0 got 1
> + 0:00.00 TEST_START: test_bar
> + 0:00.00 TEST_STATUS: a subtest FAIL expected 0 got 1
> +    SimpleTest.is@SimpleTest/SimpleTest.js:312:5
> +    @caps/tests/mochitest/test_bug246699.html:53:1
> + 0:00.00 TEST_STATUS: another subtest TIMEOUT 

Error: Trailing whitespace [flake8: W291]
This patch series addresses many (but not all) of the problems brought up here.

The windows colourization issue will be handled in bug 1445653 (though I probably won't have time to push on this). The test_status/log buffering related issues will be handled in bug 1446965 (I'd like to fix this soonish, but won't have time immediately). At least this series turns off buffering when specifying a single test, so hopefully it's a little less urgent to fix.
Comment on attachment 8960341 [details]
Bug 1445624 - [mozlog] Add some tests for the mach formatter,

https://reviewboard.mozilla.org/r/229088/#review234860

> Error: Missing from __future__ import print_function [py2: require print_function]

This was fixed in the next commit, though I'll add it to this one before landing.

> Error: Trailing whitespace [flake8: W291]

These trailing whitespaces are part of the format, fixing it would cause the test to fail. Since the format was fixed in the next commit, best to just drop these.
What's happening here?

gbrown@mozpad:~/src$ ./mach test testing/mochitest/tests/Harness_sanity/test_sanitySimpletest.html
 0:00.33 INFO Checking for ssltunnel processes...
 0:00.35 INFO Checking for xpcshell processes...
 0:00.37 SUITE_START: mochitest-plain - running 1 tests
 0:00.37 INFO Running manifest: testing/mochitest/tests/Harness_sanity/mochitest.ini
pk12util: PKCS12 IMPORT SUCCESSFUL
 0:01.14 INFO MochitestServer : launching [u'/home/gbrown/objdirs/firefox/dist/bin/xpcshell', '-g', u'/home/gbrown/objdirs/firefox/dist/bin', '-f', u'/home/gbrown/objdirs/firefox/dist/bin/components/httpd.js', '-e', "const _PROFILE_PATH = '/tmp/tmpgYD1tZ.mozrunner'; const _SERVER_PORT = '8888'; const _SERVER_ADDR = '127.0.0.1'; const _TEST_PREFIX = undefined; const _DISPLAY_RESULTS = true;", '-f', '/home/gbrown/objdirs/firefox/_tests/testing/mochitest/server.js']
 0:01.14 INFO runtests.py | Server pid: 8820
 0:01.15 INFO runtests.py | Websocket server pid: 8823
 0:01.17 INFO runtests.py | SSL tunnel pid: 8829
 0:01.22 INFO runtests.py | Running with e10s: True
 0:01.22 INFO runtests.py | Running tests: start.

 0:01.24 WARNING Found 'firefox' running before starting test browser!
 0:01.24 WARNING {'username': 'gbrown', 'cmdline': ['/usr/lib/firefox/firefox'], 'ppid': 1768, 'pid': 2686, 'name': 'firefox'}

 0:01.24 INFO Application command: /home/gbrown/objdirs/firefox/dist/bin/firefox -marionette -foreground -profile /tmp/tmpgYD1tZ.mozrunner
 0:01.25 INFO runtests.py | Application pid: 8852
 0:01.25 Started process `GECKO(8852)`
 0:01.62 GECKO(8852) 1521576779970	Marionette	DEBUG	Received observer notification profile-after-change
 0:01.74 GECKO(8852) 1521576780089	Marionette	DEBUG	Received observer notification command-line-startup
 0:01.74 GECKO(8852) 1521576780089	Marionette	DEBUG	Received observer notification nsPref:changed
 0:02.79 GECKO(8852) 1521576781131	Marionette	DEBUG	Received observer notification sessionstore-windows-restored
 0:02.98 GECKO(8852) 1521576781329	Marionette	DEBUG	New connections are accepted
 0:02.98 GECKO(8852) 1521576781330	Marionette	INFO	Listening on port 2828
 0:03.06 GECKO(8852) 1521576781409	Marionette	DEBUG	Accepted connection 0 from 127.0.0.1:49310
 0:03.06 GECKO(8852) 1521576781413	Marionette	DEBUG	Closed connection 0
 0:03.06 GECKO(8852) 1521576781413	Marionette	DEBUG	Accepted connection 1 from 127.0.0.1:49312
 0:03.07 GECKO(8852) 1521576781415	Marionette	TRACE	1 -> [0,1,"newSession",{}]
 0:03.10 GECKO(8852) 1521576781445	Marionette	DEBUG	Register listener.js for window 2147483649
 0:03.10 GECKO(8852) 1521576781452	Marionette	TRACE	1 <- [1,1,null,{"sessionId":"52cea1bb-5702-4dfb-a261-8276f4d00745","capabilities":{"browserName":"firefox","browserVersion":"61.0a ... ssID":8852,"moz:profile":"/tmp/tmpgYD1tZ.mozrunner","moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
 0:03.12 GECKO(8852) 1521576781465	Marionette	TRACE	1 -> [0,2,"addon:install",{"path":"/tmp/tmpMDRS8f.zip","temporary":false}]
 0:03.17 GECKO(8852) 1521576781515	Marionette	TRACE	1 <- [1,2,null,{"value":"special-powers@mozilla.org"}]
 0:03.19 GECKO(8852) 1521576781534	Marionette	TRACE	1 -> [0,3,"addon:install",{"path":"/tmp/tmpLGQ4Oa.zip","temporary":false}]
 0:03.23 GECKO(8852) 1521576781570	Marionette	TRACE	1 <- [1,3,null,{"value":"mochikit@mozilla.org"}]
 0:03.23 GECKO(8852) 1521576781577	Marionette	TRACE	1 -> [0,4,"getContext",{}]
 0:03.23 GECKO(8852) 1521576781577	Marionette	TRACE	1 <- [1,4,null,{"value":"content"}]
 0:03.23 GECKO(8852) 1521576781579	Marionette	TRACE	1 -> [0,5,"setContext",{"value":"chrome"}]
 0:03.23 GECKO(8852) 1521576781579	Marionette	TRACE	1 <- [1,5,null,{}]
 0:03.24 GECKO(8852) 1521576781584	Marionette	TRACE	1 -> [0,6,"executeScript",{"scriptTimeout":null,"newSandbox":true,"args":[{"testUrl":"http://mochi.test:8888/tests?autorun=1&conso ...  = new CustomEvent('mochitest-load', {'detail': [flavor, url]});\nwin.dispatchEvent(ev);\n","sandbox":"default","line":1749}]
 0:03.24 GECKO(8852) 1521576781590	Marionette	TRACE	1 <- [1,6,null,{"value":null}]
 0:03.25 GECKO(8852) 1521576781594	Marionette	TRACE	1 -> [0,7,"setContext",{"value":"content"}]
 0:03.25 GECKO(8852) 1521576781594	Marionette	TRACE	1 <- [1,7,null,{}]
 0:03.27 GECKO(8852) 1521576781612	Marionette	TRACE	1 -> [0,8,"deleteSession",{}]
 0:03.27 GECKO(8852) 1521576781614	Marionette	TRACE	1 <- [1,8,null,{}]
 0:03.27 INFO runtests.py | Waiting for browser...
 0:03.28 GECKO(8852) 1521576781623	Marionette	DEBUG	Closed connection 1
 0:03.48 INFO SimpleTest START
 0:03.49 TEST_START: testing/mochitest/tests/Harness_sanity/test_sanitySimpletest.html
 0:04.54 INFO Profile::SimpleTestLoadTime: 28
 0:04.55 INFO Logging some info
 0:04.56 PASS test ok - This should be true
 0:04.56 PASS is() test failed
 0:04.56 PASS isnot() test failed
mozlog.structuredlog: Failure calling log handler:
Traceback (most recent call last):
  File "/home/gbrown/src/testing/mozbase/mozlog/mozlog/structuredlog.py", line 246, in _handle_log
    handler(data)
  File "/home/gbrown/src/testing/mozbase/mozlog/mozlog/handlers/base.py", line 96, in __call__
    formatted = self.formatter(data)
  File "/home/gbrown/src/testing/mozbase/mozlog/mozlog/handlers/base.py", line 65, in __call__
    return self.inner(item)
  File "/home/gbrown/src/testing/mozbase/mozlog/mozlog/formatters/machformatter.py", line 49, in __call__
    s = super(MachFormatter, self).__call__(data)
  File "/home/gbrown/src/testing/mozbase/mozlog/mozlog/reader.py", line 74, in __call__
    return handler(data)
  File "/home/gbrown/src/testing/mozbase/mozlog/mozlog/formatters/machformatter.py", line 233, in test_status
    return self._format_status(test, data).rstrip('\n')
  File "/home/gbrown/src/testing/mozbase/mozlog/mozlog/formatters/machformatter.py", line 101, in _format_status
    data["status"], data.get("expected", data["status"])), name)
  File "/home/gbrown/src/testing/mozbase/mozlog/mozlog/formatters/machformatter.py", line 96, in _format_expected
    return color(status)
  File "/home/gbrown/src/third_party/python/blessings/blessings/__init__.py", line 476, in __call__
    'formatting call like bright_red_on_white(...).' % args)
TypeError: A native or nonexistent capability template received u'EXPECTED-FAIL' when it was expecting ints. You probably misspelled a formatting call like bright_red_on_white(...).

mozlog.structuredlog: Failure calling log handler:
Traceback (most recent call last):
  File "/home/gbrown/src/testing/mozbase/mozlog/mozlog/structuredlog.py", line 246, in _handle_log
    handler(data)
  File "/home/gbrown/src/testing/mozbase/mozlog/mozlog/handlers/base.py", line 96, in __call__
    formatted = self.formatter(data)
  File "/home/gbrown/src/testing/mozbase/mozlog/mozlog/handlers/base.py", line 65, in __call__
    return self.inner(item)
  File "/home/gbrown/src/testing/mozbase/mozlog/mozlog/formatters/machformatter.py", line 49, in __call__
    s = super(MachFormatter, self).__call__(data)
  File "/home/gbrown/src/testing/mozbase/mozlog/mozlog/reader.py", line 74, in __call__
    return handler(data)
  File "/home/gbrown/src/testing/mozbase/mozlog/mozlog/formatters/machformatter.py", line 233, in test_status
    return self._format_status(test, data).rstrip('\n')
  File "/home/gbrown/src/testing/mozbase/mozlog/mozlog/formatters/machformatter.py", line 101, in _format_status
    data["status"], data.get("expected", data["status"])), name)
  File "/home/gbrown/src/testing/mozbase/mozlog/mozlog/formatters/machformatter.py", line 96, in _format_expected
    return color(status)
  File "/home/gbrown/src/third_party/python/blessings/blessings/__init__.py", line 476, in __call__
    'formatting call like bright_red_on_white(...).' % args)
TypeError: A native or nonexistent capability template received u'EXPECTED-FAIL' when it was expecting ints. You probably misspelled a formatting call like bright_red_on_white(...).

mozlog.structuredlog: Failure calling log handler:
Traceback (most recent call last):
  File "/home/gbrown/src/testing/mozbase/mozlog/mozlog/structuredlog.py", line 246, in _handle_log
    handler(data)
  File "/home/gbrown/src/testing/mozbase/mozlog/mozlog/handlers/base.py", line 96, in __call__
    formatted = self.formatter(data)
  File "/home/gbrown/src/testing/mozbase/mozlog/mozlog/handlers/base.py", line 65, in __call__
    return self.inner(item)
  File "/home/gbrown/src/testing/mozbase/mozlog/mozlog/formatters/machformatter.py", line 49, in __call__
    s = super(MachFormatter, self).__call__(data)
  File "/home/gbrown/src/testing/mozbase/mozlog/mozlog/reader.py", line 74, in __call__
    return handler(data)
  File "/home/gbrown/src/testing/mozbase/mozlog/mozlog/formatters/machformatter.py", line 233, in test_status
    return self._format_status(test, data).rstrip('\n')
  File "/home/gbrown/src/testing/mozbase/mozlog/mozlog/formatters/machformatter.py", line 101, in _format_status
    data["status"], data.get("expected", data["status"])), name)
  File "/home/gbrown/src/testing/mozbase/mozlog/mozlog/formatters/machformatter.py", line 96, in _format_expected
    return color(status)
  File "/home/gbrown/src/third_party/python/blessings/blessings/__init__.py", line 476, in __call__
    'formatting call like bright_red_on_white(...).' % args)
TypeError: A native or nonexistent capability template received u'EXPECTED-FAIL' when it was expecting ints. You probably misspelled a formatting call like bright_red_on_white(...).

 0:04.57 PASS Clipboard has the given value: 'a'
 0:04.57 PASS waitForClipboard should work
 0:04.57 PASS createEl did not create element as expected
 0:04.57 PASS $ helper did not get element as expected
 0:04.57 PASS computedStyle did not get right display value
 0:04.59 GECKO(8852) MEMORY STAT vsizeMaxContiguous not supported in this build configuration.
 0:04.59 GECKO(8852) MEMORY STAT | vsize 1557MB | residentFast 138MB | heapAllocated 21MB
 0:04.59 INFO Profile::SimpleTestRunTime: 46
 0:04.59 GECKO(8852) JavaScript error: , line 0: uncaught exception: i am an uncaught exception
 0:04.60 TEST_END: Test OK. Subtests passed 8/11. Unexpected 0
 0:04.61 INFO TEST-START | Shutdown
 0:04.61 INFO Passed:  8
 0:04.61 INFO Failed:  0
 0:04.61 INFO Todo:    3
 0:04.61 INFO Mode:    e10s
 0:04.61 INFO Slowest: 1112ms - /tests/testing/mochitest/tests/Harness_sanity/test_sanitySimpletest.html
...
Comment on attachment 8960341 [details]
Bug 1445624 - [mozlog] Add some tests for the mach formatter,

https://reviewboard.mozilla.org/r/229088/#review235228
Attachment #8960341 - Flags: review?(gbrown) → review+
Looks like I used term.orange as the colour when it should have been term.yellow. The tests didn't catch this because they aren't running in a tty, so all calls to the terminal are stubbed out. Good catch, thanks for testing!

This is a good reminder that these kinds of errors will go uncaught by the tests. I'll re-push a fix.
Comment on attachment 8960343 [details]
Bug 1445624 - [test] Make sure verbose logging is enabled when running a single test,

https://reviewboard.mozilla.org/r/229092/#review235580
Attachment #8960343 - Flags: review?(gbrown) → review+
Comment on attachment 8960342 [details]
Bug 1445624 - [mozlog] Various improvements and fixes to the mach formatter,

https://reviewboard.mozilla.org/r/229090/#review235582

Looks OK and I can't break it now!
Attachment #8960342 - Flags: review?(gbrown) → review+
Pushed by ahalberstadt@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/96e150823d32
[mozlog] Add some tests for the mach formatter, r=gbrown
https://hg.mozilla.org/integration/autoland/rev/61a14c8bcfcf
[mozlog] Various improvements and fixes to the mach formatter, r=gbrown
https://hg.mozilla.org/integration/autoland/rev/a348763a5ee1
[test] Make sure verbose logging is enabled when running a single test, r=gbrown
https://hg.mozilla.org/mozilla-central/rev/96e150823d32
https://hg.mozilla.org/mozilla-central/rev/61a14c8bcfcf
https://hg.mozilla.org/mozilla-central/rev/a348763a5ee1
Status: ASSIGNED → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla61
You need to log in before you can comment on or make changes to this bug.