573589 - Mozmill's log output format should match other testing systems'

Status: VERIFIED FIXED

(Testing Graveyard :: Mozmill, defect)

Description

[Heather Arthur [:harth]]

Right now Mozmill's log output (with the --showall option) is a JSONy format, it should look more like mochitest, retest, etc. output so we can reuse log parsing code.

mozmill:
DEBUG:mozmill:Test Pass: {u'function': u'Controller.assertJS("subject.isBookmarked == false")'}
DEBUG:mozmill:Test Pass: {u'function': u'Controller.open()'}

mochitest:
2258 INFO TEST-PASS | /tests/dom/tests/mochitest/ajax/mochikit/test_Mochikit.html | toggleElementClass 2: baz bar
2259 INFO TEST-PASS | /tests/dom/tests/mochitest/ajax/mochikit/test_Mochikit.html | toggleElementClass 3: baz bar

Comment 1

[Heather Arthur [:harth]]

actually, we could keep the JSON for now and just change the first part:

INFO TEST-PASS |
firefox/testBookmarks/testAddBookmarkToMenu.js |
{u'function':
u'Controller.assertJS("subject.isBookmarked == false")'}

Comment 2

[Henrik Skupin [:whimboo][⌚️UTC+2]]

(In reply to comment #0)
> mochitest:
> 2258 INFO TEST-PASS |

So what's the number here? Also which different types are possible beside 'INFO'? Same for the test status. If we change something we should have the same expressions like Mochitests.

> /tests/dom/tests/mochitest/ajax/mochikit/test_Mochikit.html |

The question here is, do we wanna have an absolute or relative path. For Brasstacks we will use the relative path, which is a result from the Result Data project. What do we wanna have here?

(In reply to comment #1)
> actually, we could keep the JSON for now and just change the first part:

I would vote to keep the JSON format too. If you really don't wanna have it for your output we should consider to add another command line option.

Comment 3

[Jeff Hammel]

(In reply to comment #2)
> (In reply to comment #0)
> > mochitest:
> > 2258 INFO TEST-PASS |
> 
> So what's the number here? Also which different types are possible beside
> 'INFO'? Same for the test status. If we change something we should have the
> same expressions like Mochitests.

AFAIK the number can be ignored here.  I've started documenting the log format here: https://developer.mozilla.org/en/Test_log_format . Please feel free to add to it.  INFO, INFO TEST-PASS, and INFO TEST-UNEXPECTED-FAIL are probably sufficient to start (and TEST-START and finishing).
 
> > /tests/dom/tests/mochitest/ajax/mochikit/test_Mochikit.html |
> 
> The question here is, do we wanna have an absolute or relative path. For
> Brasstacks we will use the relative path, which is a result from the Result
> Data project. What do we wanna have here?

+1 to relative paths (e.g. tests/firefox/blah.js).  Anyone disagree?
 
> (In reply to comment #1)
> > actually, we could keep the JSON for now and just change the first part:
> 
> I would vote to keep the JSON format too. If you really don't wanna have it for
> your output we should consider to add another command line option.

I see no reason not to keep JSON in the third column.  The third column seems pretty free form and most harness specific.

Comment 4

[Henrik Skupin [:whimboo][⌚️UTC+2]]

(In reply to comment #3)
> > I would vote to keep the JSON format too. If you really don't wanna have it for
> > your output we should consider to add another command line option.
> 
> I see no reason not to keep JSON in the third column.  The third column seems
> pretty free form and most harness specific.

Well, I talk about the default logging output with --show-all specified for Mozmill. Other consumers will be happy to still have JSON formatted logging output.

Comment 5

[Jeff Hammel]

(In reply to comment #1)
> actually, we could keep the JSON for now and just change the first part:
> 
> INFO TEST-PASS |
> firefox/testBookmarks/testAddBookmarkToMenu.js |
> {u'function':
> u'Controller.assertJS("subject.isBookmarked == false")'}

We (by which I mean probably me) should clean this up and make it real JSON.  e.g. 'function' and not u'function' . https://bugzilla.mozilla.org/show_bug.cgi?id=573853 seemed to imply there was quoting issues too.

Comment 6

[Jeff Hammel]

I think I might have confused myself.  Currently we list the test as well as the file it is in:

Test Failed : testVerifyDefaultBookmarks in /home/jhammel/mozmill/src/mozmill-tests/firefox/restartTests/testDefaultBookmarks/test1.js

So ignoring the absolute path (which will become relative) how should the tests within the file be noted?

A few options:

- Use a separator.  A : for example:

TEST-UNEXPECTED-FAIL | firefox/restartTests/testDefaultBookmarks/test1.js:testVerifyDefaultBookmarks | ...

- ignore the actual test and just display the file.  Probably bad if the tests are atomic:

TEST-UNEXPECTED-FAIL | firefox/restartTests/testDefaultBookmarks/test1.js | ...

- push the individual test to the third column.  could be misleading:

TEST-UNEXPECTED-FAIL | firefox/restartTests/testDefaultBookmarks/test1.js | testVerifyDefaultBookmarks ...

- other?

I'd love feedback on this.  I forgot if we ever came to a conclusion here.

Comment 7

[Henrik Skupin [:whimboo][⌚️UTC+2]]

(In reply to comment #6)
> - Use a separator.  A : for example:
> 
> TEST-UNEXPECTED-FAIL |
> firefox/restartTests/testDefaultBookmarks/test1.js:testVerifyDefaultBookmarks 

Having spaces around the colon would make it more readable. I would vote for it.

> - ignore the actual test and just display the file.  Probably bad if the tests
> are atomic:
> 
> TEST-UNEXPECTED-FAIL | firefox/restartTests/testDefaultBookmarks/test1.js | 

Yes, it's not a good option.

> - push the individual test to the third column.  could be misleading:
> 
> TEST-UNEXPECTED-FAIL | firefox/restartTests/testDefaultBookmarks/test1.js |
> testVerifyDefaultBookmarks ...

IMO we should have the test module and test function in some way connected with each other. 

> - other?
> 
> I'd love feedback on this.  I forgot if we ever came to a conclusion here.

I like option 1 with everthing in a line and a colon with spaces around.

Comment 8

[Jeff Hammel]

a cosmetic fix is "working" as of http://github.com/k0s/mozmill/commit/0bf917cf93f4bae2c798f2da825750a7e5559509 ; However, I get strangely duplicated results:

(mozmill)> mozmill-restart -b ~/firefox/firefox -t mozmill-tests/firefox/restartTests/testDefaultBookmarks/ 
TEST-UNEXPECTED-FAIL | /home/jhammel/mozmill/src/mozmill-tests/firefox/restartTests/testDefaultBookmarks/test1.js | testVerifyDefaultBookmarks
TEST-UNEXPECTED-FAIL | /home/jhammel/mozmill/src/mozmill-tests/firefox/restartTests/testDefaultBookmarks/test1.js | testVerifyDefaultBookmarks
INFO Passed: 2
INFO Failed: 2
INFO Skipped: 0

Not sure what is going on here, if this is an anomaly of restart tests or if there are two failures in one test. IMHO, failure of one test should be singly reported.

Also, --showall is still an utter mess and the path to the tests should be a relative path.  Working on it

Comment 9

[Jeff Hammel]

A naive (but working, at least in the default case) conversion to real JSON for the log is here:

http://github.com/k0s/mozmill/commit/4756eb0a9fcdf78bd7e725500890ced2e481b059

If this breaks we can workaround

Comment 10

[Henrik Skupin [:whimboo][⌚️UTC+2]]

(In reply to comment #8)
> TEST-UNEXPECTED-FAIL |
> /home/jhammel/mozmill/src/mozmill-tests/firefox/restartTests/testDefaultBookmarks/test1.js

Where is the test itself which fails? That should definitely be part of the output.

Comment 11

[Jeff Hammel]

(In reply to comment #10)
> (In reply to comment #8)
> > TEST-UNEXPECTED-FAIL |
> > /home/jhammel/mozmill/src/mozmill-tests/firefox/restartTests/testDefaultBookmarks/test1.js
> 
> Where is the test itself which fails? That should definitely be part of the
> output.

You didn't paste enough; it is on the next line (same line in console, bugzilla just wraps):

TEST-UNEXPECTED-FAIL |
/home/jhammel/mozmill/src/mozmill-tests/firefox/restartTests/testDefaultBookmarks/test1.js
| testVerifyDefaultBookmarks

Comment 12

[Henrik Skupin [:whimboo][⌚️UTC+2]]

(In reply to comment #11)
> TEST-UNEXPECTED-FAIL |
> /home/jhammel/mozmill/src/mozmill-tests/firefox/restartTests/testDefaultBookmarks/test1.js
> | testVerifyDefaultBookmarks

No. What we are seeing here is:

Test module:   /firefox/restartTests/testDefaultBookmarks/test1.js
Test function: testVerifyDefaultBookmarks
Test:          ???

TEST-UNEXPECTED-FAIL should tell about the line where the failure happened. Something like:

timeout exceeded for waitForEval('subject.getPane() == 'installs'')

Comment 13

[Jeff Hammel]

(In reply to comment #12)
> (In reply to comment #11)
> > TEST-UNEXPECTED-FAIL |
> > /home/jhammel/mozmill/src/mozmill-tests/firefox/restartTests/testDefaultBookmarks/test1.js
> > | testVerifyDefaultBookmarks
> 
> No. What we are seeing here is:
> 
> Test module:   /firefox/restartTests/testDefaultBookmarks/test1.js
> Test function: testVerifyDefaultBookmarks
> Test:          ???
> 
> TEST-UNEXPECTED-FAIL should tell about the line where the failure happened.
> Something like:
> 
> timeout exceeded for waitForEval('subject.getPane() == 'installs'')

What I've done is a straight port of what is already there.  The existing code ( http://github.com/mozautomation/mozmill/blob/master/mozmill/mozmill/__init__.py#L229 ) does this:

print "Test Failed : %s in %s" % (test['name'], test['filename'])

The log-format branch does this:

print "TEST-UNEXPECTED-FAIL | %s | %s" % (test['filename'], test['name'])

I think this bug is about a straight port of existing functionality to match the other testing systems.  I'm cleaning up some things, like making real JSON instead of python's repr, but don't intend on adding in much new functionality.  New functionality should be additionally ticketed.

Comment 14

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Well, checking the output for --showall shows me that the important part is right before the "Test Failed" line:

ERROR:mozmill:Test Failure: {u'exception': {u'message': u"timeout exceeded for waitForEval('subject.getAttribute('focused') == 'true'')" ...
Test Failed : testAccessLocationBarHistory in /Volumes/data/testing/mozmill/mozilla1.9.2/firefox/testAwesomeBar/testAccessLocationBar.js

Browser chrome tests only have one single test function, right? With Mozmill we can have multiple test functions inside a module. So we need one more level of reporting. That said the current log format isn't sufficient and the important parts are not part of the output. Or will the "ERROR:mozmill:Test Failure" line still be printed?

Comment 15

[Jeff Hammel]

(In reply to comment #14)
> Well, checking the output for --showall shows me that the important part is
> right before the "Test Failed" line:
> 
> ERROR:mozmill:Test Failure: {u'exception': {u'message': u"timeout exceeded for
> waitForEval('subject.getAttribute('focused') == 'true'')" ...
> Test Failed : testAccessLocationBarHistory in
> /Volumes/data/testing/mozmill/mozilla1.9.2/firefox/testAwesomeBar/testAccessLocationBar.js
> 
> Browser chrome tests only have one single test function, right? With Mozmill we
> can have multiple test functions inside a module. So we need one more level of
> reporting. That said the current log format isn't sufficient and the important
> parts are not part of the output. Or will the "ERROR:mozmill:Test Failure" line
> still be printed?

Yes, I'm working on the logging formatting right now.  Its a bit harrier and will require more restructuring.  So if you use --showall or --showerrors then the above will still be printed but it will probably look more like:

ERROR | Test Failure | {'exception': {'message': "timeout exceeded for
waitForEval('subject.getAttribute('focused') == 'true'')" ...
TEST-UNEXPECTED-FAIL |  firefox/testAwesomeBar/testAccessLocationBar.js | testAccessLocationBarHistory

Or similar.  The first line may change;  ERROR is not used in the same way as the other test harnesses, so I'm not sure how to match here.

Comment 16

[Jeff Hammel]

Status update:

I've gotten things a little better:

(mozmill)> mozmill -b ~/firefox/firefox -t src/mozmill-tests/firefox/testGeneral/ --showall
INFO | register | true
INFO | mozmill.startRunner | true
INFO | mozmill.setModule | "currentModule"
INFO | mozmill.setState | "currentState"
INFO | mozmill.setTest | {"name": "setupModule", "filename": "/home/jhammel/mozmill/src/mozmill-tests/firefox/testGeneral/testBackForwardButtons.js"}
INFO | mozmill.endTest | {"passes": [], "fails": [], "name": "setupModule", "filename": "/home/jhammel/mozmill/src/mozmill-tests/firefox/testGeneral/testBackForwardButtons.js", "failed": 0, "passed": 0}
INFO | mozmill.setState | "currentState"
INFO | mozmill.setTest | {"name": "testBackandForward", "filename": "/home/jhammel/mozmill/src/mozmill-tests/firefox/testGeneral/testBackForwardButtons.js"}
DEBUG | Test Pass: {"function": "Controller.open()"}
DEBUG | Test Pass: {"function": "Controller.waitForPageLoad()"}
DEBUG | Test Pass: {"function": "Controller.waitForElement()"}
DEBUG | Test Pass: {"function": "Controller.open()"}
DEBUG | Test Pass: {"function": "Controller.waitForPageLoad()"}
DEBUG | Test Pass: {"function": "Controller.waitForElement()"}
DEBUG | Test Pass: {"function": "Controller.open()"}
DEBUG | Test Pass: {"function": "Controller.waitForPageLoad()"}
DEBUG | Test Pass: {"function": "Controller.waitForElement()"}
DEBUG | Test Pass: {"function": "Controller.goBack()"}
DEBUG | Test Pass: {"function": "Controller.waitForPageLoad()"}
DEBUG | Test Pass: {"function": "Controller.waitForElement()"}
DEBUG | Test Pass: {"function": "Controller.goBack()"}
DEBUG | Test Pass: {"function": "Controller.waitForPageLoad()"}
DEBUG | Test Pass: {"function": "Controller.waitForElement()"}
DEBUG | Test Pass: {"function": "Controller.goForward()"}
DEBUG | Test Pass: {"function": "Controller.waitForPageLoad()"}
DEBUG | Test Pass: {"function": "Controller.waitForElement()"}
DEBUG | Test Pass: {"function": "Controller.goForward()"}
DEBUG | Test Pass: {"function": "Controller.waitForPageLoad()"}
DEBUG | Test Pass: {"function": "Controller.waitForElement()"}
INFO | mozmill.endTest | {"passes": [{"function": "Controller.open()"}, {"function": "Controller.waitForPageLoad()"}, {"function": "Controller.waitForElement()"}, {"function": "Controller.open()"}, {"function": "Controller.waitForPageLoad()"}, {"function": "Controller.waitForElement()"}, {"function": "Controller.open()"}, {"function": "Controller.waitForPageLoad()"}, {"function": "Controller.waitForElement()"}, {"function": "Controller.goBack()"}, {"function": "Controller.waitForPageLoad()"}, {"function": "Controller.waitForElement()"}, {"function": "Controller.goBack()"}, {"function": "Controller.waitForPageLoad()"}, {"function": "Controller.waitForElement()"}, {"function": "Controller.goForward()"}, {"function": "Controller.waitForPageLoad()"}, {"function": "Controller.waitForElement()"}, {"function": "Controller.goForward()"}, {"function": "Controller.waitForPageLoad()"}, {"function": "Controller.waitForElement()"}], "fails": [], "name": "testBackandForward", "filename": "/home/jhammel/mozmill/src/mozmill-tests/firefox/testGeneral/testBackForwardButtons.js", "failed": 0, "passed": 21}
INFO | mozmill.setState | "currentState"
INFO | mozmill.setModule | "currentModule"
INFO | mozmill.setState | "currentState"
INFO | mozmill.setTest | {"name": "setupModule", "filename": "/home/jhammel/mozmill/src/mozmill-tests/firefox/testGeneral/testStopReloadButtons.js"}
INFO | mozmill.endTest | {"passes": [], "fails": [], "name": "setupModule", "filename": "/home/jhammel/mozmill/src/mozmill-tests/firefox/testGeneral/testStopReloadButtons.js", "failed": 0, "passed": 0}
INFO | mozmill.setState | "currentState"
INFO | mozmill.setTest | {"name": "testStopAndReload", "filename": "/home/jhammel/mozmill/src/mozmill-tests/firefox/testGeneral/testStopReloadButtons.js"}
DEBUG | Test Pass: {"function": "Controller.open()"}
DEBUG | Test Pass: {"function": "Controller.waitForPageLoad()"}
DEBUG | Test Pass: {"function": "Controller.open()"}
DEBUG | Test Pass: {"function": "Controller.click()"}
DEBUG | Test Pass: {"function": "Controller.assertNodeNotExist()"}
DEBUG | Test Pass: {"function": "Controller.open()"}
DEBUG | Test Pass: {"function": "Controller.waitForPageLoad()"}
DEBUG | Test Pass: {"function": "Controller.waitForElement()"}
INFO | mozmill.endTest | {"passes": [{"function": "Controller.open()"}, {"function": "Controller.waitForPageLoad()"}, {"function": "Controller.open()"}, {"function": "Controller.click()"}, {"function": "Controller.assertNodeNotExist()"}, {"function": "Controller.open()"}, {"function": "Controller.waitForPageLoad()"}, {"function": "Controller.waitForElement()"}], "fails": [], "name": "testStopAndReload", "filename": "/home/jhammel/mozmill/src/mozmill-tests/firefox/testGeneral/testStopReloadButtons.js", "failed": 0, "passed": 8}
INFO | mozmill.setState | "currentState"
INFO | mozmill.setModule | "currentModule"
INFO | mozmill.setState | "currentState"
INFO | mozmill.setTest | {"name": "setupModule", "filename": "/home/jhammel/mozmill/src/mozmill-tests/firefox/testGeneral/testGoogleSuggestions.js"}
INFO | mozmill.endTest | {"passes": [], "fails": [], "name": "setupModule", "filename": "/home/jhammel/mozmill/src/mozmill-tests/firefox/testGeneral/testGoogleSuggestions.js", "failed": 0, "passed": 0}
INFO | mozmill.setState | "currentState"
INFO | mozmill.setTest | {"name": "testGoogleSuggestedTerms", "filename": "/home/jhammel/mozmill/src/mozmill-tests/firefox/testGeneral/testGoogleSuggestions.js"}
DEBUG | Test Pass: {"function": "Controller.open()"}
DEBUG | Test Pass: {"function": "Controller.waitForPageLoad()"}
DEBUG | Test Pass: {"function": "Controller.type()"}
DEBUG | Test Pass: {"function": "Controller.waitForElement()"}
DEBUG | Test Pass: {"function": "Controller.click()"}
DEBUG | Test Pass: {"function": "Controller.click()"}
DEBUG | Test Pass: {"function": "Controller.waitForPageLoad()"}
DEBUG | Test Pass: {"function": "Controller.waitForElement()"}
DEBUG | Test Pass: {"function": "Controller.waitForElement()"}
INFO | mozmill.endTest | {"passes": [{"function": "Controller.open()"}, {"function": "Controller.waitForPageLoad()"}, {"function": "Controller.type()"}, {"function": "Controller.waitForElement()"}, {"function": "Controller.click()"}, {"function": "Controller.click()"}, {"function": "Controller.waitForPageLoad()"}, {"function": "Controller.waitForElement()"}, {"function": "Controller.waitForElement()"}], "fails": [], "name": "testGoogleSuggestedTerms", "filename": "/home/jhammel/mozmill/src/mozmill-tests/firefox/testGeneral/testGoogleSuggestions.js", "failed": 0, "passed": 9}
INFO | mozmill.persist
INFO Passed: 6
INFO Failed: 0
INFO Skipped: 0
INFO | mozmill.endRunner | true

All of the DEBUG notes will have to be changed to the correct information.  i.e. INFO TEST-PASS in these cases

We don't have any delimination for tests starting and ending.  We should.

I'm going to continue down the path for now of doing this in a minimally-invasive way, but am getting worried that I'll have to tear up a lot before the end.

Comment 17

[Jeff Hammel]

More interim results, maybe even usable (for now):

(mozmill)> mozmill -b ~/firefox/firefox -t src/mozmill-tests/firefox/testGeneral/ --showall
INFO | register | true
INFO | mozmill.startRunner | true
INFO | mozmill.setModule | "currentModule"
INFO | mozmill.setState | "currentState"
TEST-START | /home/jhammel/mozmill/src/mozmill-tests/firefox/testGeneral/testBackForwardButtons.js | setupModule
INFO | mozmill.setTest | {"name": "setupModule", "filename": "/home/jhammel/mozmill/src/mozmill-tests/firefox/testGeneral/testBackForwardButtons.js"}
TEST-PASS | /home/jhammel/mozmill/src/mozmill-tests/firefox/testGeneral/testBackForwardButtons.js | setupModule
INFO | mozmill.endTest | {"passes": [], "fails": [], "name": "setupModule", "filename": "/home/jhammel/mozmill/src/mozmill-tests/firefox/testGeneral/testBackForwardButtons.js", "failed": 0, "passed": 0}
INFO | mozmill.setState | "currentState"
TEST-START | /home/jhammel/mozmill/src/mozmill-tests/firefox/testGeneral/testBackForwardButtons.js | testBackandForward
INFO | mozmill.setTest | {"name": "testBackandForward", "filename": "/home/jhammel/mozmill/src/mozmill-tests/firefox/testGeneral/testBackForwardButtons.js"}
INFO | Step Pass: {"function": "Controller.open()"}
INFO | Step Pass: {"function": "Controller.waitForPageLoad()"}
INFO | Step Pass: {"function": "Controller.waitForElement()"}
INFO | Step Pass: {"function": "Controller.open()"}
INFO | Step Pass: {"function": "Controller.waitForPageLoad()"}
INFO | Step Pass: {"function": "Controller.waitForElement()"}
INFO | Step Pass: {"function": "Controller.open()"}
INFO | Step Pass: {"function": "Controller.waitForPageLoad()"}
INFO | Step Pass: {"function": "Controller.waitForElement()"}
INFO | Step Pass: {"function": "Controller.goBack()"}
INFO | Step Pass: {"function": "Controller.waitForPageLoad()"}
INFO | Step Pass: {"function": "Controller.waitForElement()"}
INFO | Step Pass: {"function": "Controller.goBack()"}
INFO | Step Pass: {"function": "Controller.waitForPageLoad()"}
INFO | Step Pass: {"function": "Controller.waitForElement()"}
INFO | Step Pass: {"function": "Controller.goForward()"}
INFO | Step Pass: {"function": "Controller.waitForPageLoad()"}
INFO | Step Pass: {"function": "Controller.waitForElement()"}
INFO | Step Pass: {"function": "Controller.goForward()"}
INFO | Step Pass: {"function": "Controller.waitForPageLoad()"}
INFO | Step Pass: {"function": "Controller.waitForElement()"}
TEST-PASS | /home/jhammel/mozmill/src/mozmill-tests/firefox/testGeneral/testBackForwardButtons.js | testBackandForward
INFO | mozmill.endTest | {"passes": [{"function": "Controller.open()"}, {"function": "Controller.waitForPageLoad()"}, {"function": "Controller.waitForElement()"}, {"function": "Controller.open()"}, {"function": "Controller.waitForPageLoad()"}, {"function": "Controller.waitForElement()"}, {"function": "Controller.open()"}, {"function": "Controller.waitForPageLoad()"}, {"function": "Controller.waitForElement()"}, {"function": "Controller.goBack()"}, {"function": "Controller.waitForPageLoad()"}, {"function": "Controller.waitForElement()"}, {"function": "Controller.goBack()"}, {"function": "Controller.waitForPageLoad()"}, {"function": "Controller.waitForElement()"}, {"function": "Controller.goForward()"}, {"function": "Controller.waitForPageLoad()"}, {"function": "Controller.waitForElement()"}, {"function": "Controller.goForward()"}, {"function": "Controller.waitForPageLoad()"}, {"function": "Controller.waitForElement()"}], "fails": [], "name": "testBackandForward", "filename": "/home/jhammel/mozmill/src/mozmill-tests/firefox/testGeneral/testBackForwardButtons.js", "failed": 0, "passed": 21}
INFO | mozmill.setState | "currentState"
INFO | mozmill.setModule | "currentModule"
INFO | mozmill.setState | "currentState"
TEST-START | /home/jhammel/mozmill/src/mozmill-tests/firefox/testGeneral/testStopReloadButtons.js | setupModule
INFO | mozmill.setTest | {"name": "setupModule", "filename": "/home/jhammel/mozmill/src/mozmill-tests/firefox/testGeneral/testStopReloadButtons.js"}
TEST-PASS | /home/jhammel/mozmill/src/mozmill-tests/firefox/testGeneral/testStopReloadButtons.js | setupModule
INFO | mozmill.endTest | {"passes": [], "fails": [], "name": "setupModule", "filename": "/home/jhammel/mozmill/src/mozmill-tests/firefox/testGeneral/testStopReloadButtons.js", "failed": 0, "passed": 0}
INFO | mozmill.setState | "currentState"
TEST-START | /home/jhammel/mozmill/src/mozmill-tests/firefox/testGeneral/testStopReloadButtons.js | testStopAndReload
INFO | mozmill.setTest | {"name": "testStopAndReload", "filename": "/home/jhammel/mozmill/src/mozmill-tests/firefox/testGeneral/testStopReloadButtons.js"}
INFO | Step Pass: {"function": "Controller.open()"}
INFO | Step Pass: {"function": "Controller.waitForPageLoad()"}
INFO | Step Pass: {"function": "Controller.open()"}
INFO | Step Pass: {"function": "Controller.click()"}
INFO | Step Pass: {"function": "Controller.assertNodeNotExist()"}
INFO | Step Pass: {"function": "Controller.open()"}
INFO | Step Pass: {"function": "Controller.waitForPageLoad()"}
INFO | Step Pass: {"function": "Controller.waitForElement()"}
TEST-PASS | /home/jhammel/mozmill/src/mozmill-tests/firefox/testGeneral/testStopReloadButtons.js | testStopAndReload
INFO | mozmill.endTest | {"passes": [{"function": "Controller.open()"}, {"function": "Controller.waitForPageLoad()"}, {"function": "Controller.open()"}, {"function": "Controller.click()"}, {"function": "Controller.assertNodeNotExist()"}, {"function": "Controller.open()"}, {"function": "Controller.waitForPageLoad()"}, {"function": "Controller.waitForElement()"}], "fails": [], "name": "testStopAndReload", "filename": "/home/jhammel/mozmill/src/mozmill-tests/firefox/testGeneral/testStopReloadButtons.js", "failed": 0, "passed": 8}
INFO | mozmill.setState | "currentState"
INFO | mozmill.setModule | "currentModule"
INFO | mozmill.setState | "currentState"
TEST-START | /home/jhammel/mozmill/src/mozmill-tests/firefox/testGeneral/testGoogleSuggestions.js | setupModule
INFO | mozmill.setTest | {"name": "setupModule", "filename": "/home/jhammel/mozmill/src/mozmill-tests/firefox/testGeneral/testGoogleSuggestions.js"}
TEST-PASS | /home/jhammel/mozmill/src/mozmill-tests/firefox/testGeneral/testGoogleSuggestions.js | setupModule
INFO | mozmill.endTest | {"passes": [], "fails": [], "name": "setupModule", "filename": "/home/jhammel/mozmill/src/mozmill-tests/firefox/testGeneral/testGoogleSuggestions.js", "failed": 0, "passed": 0}
INFO | mozmill.setState | "currentState"
TEST-START | /home/jhammel/mozmill/src/mozmill-tests/firefox/testGeneral/testGoogleSuggestions.js | testGoogleSuggestedTerms
INFO | mozmill.setTest | {"name": "testGoogleSuggestedTerms", "filename": "/home/jhammel/mozmill/src/mozmill-tests/firefox/testGeneral/testGoogleSuggestions.js"}
INFO | Step Pass: {"function": "Controller.open()"}
INFO | Step Pass: {"function": "Controller.waitForPageLoad()"}
INFO | Step Pass: {"function": "Controller.type()"}
INFO | Step Pass: {"function": "Controller.waitForElement()"}
INFO | Step Pass: {"function": "Controller.click()"}
INFO | Step Pass: {"function": "Controller.click()"}
INFO | Step Pass: {"function": "Controller.waitForPageLoad()"}
INFO | Step Pass: {"function": "Controller.waitForElement()"}
INFO | Step Pass: {"function": "Controller.waitForElement()"}
TEST-PASS | /home/jhammel/mozmill/src/mozmill-tests/firefox/testGeneral/testGoogleSuggestions.js | testGoogleSuggestedTerms
INFO | mozmill.endTest | {"passes": [{"function": "Controller.open()"}, {"function": "Controller.waitForPageLoad()"}, {"function": "Controller.type()"}, {"function": "Controller.waitForElement()"}, {"function": "Controller.click()"}, {"function": "Controller.click()"}, {"function": "Controller.waitForPageLoad()"}, {"function": "Controller.waitForElement()"}, {"function": "Controller.waitForElement()"}], "fails": [], "name": "testGoogleSuggestedTerms", "filename": "/home/jhammel/mozmill/src/mozmill-tests/firefox/testGeneral/testGoogleSuggestions.js", "failed": 0, "passed": 9}
INFO | mozmill.persist
INFO Passed: 6
INFO Failed: 0
INFO Skipped: 0
INFO | mozmill.endRunner | true

Comment 18

[Jeff Hammel]

Notes on https://bugzilla.mozilla.org/show_bug.cgi?id=573589#c17 :

 - the lines that start with INFO |(or conceivably DEBUG |, WARNING |, etc) are done through python's logging module;  the lines that start with TEST-PASS, TEST-START, or just plain INFO are plain old print statements.

 - the 'INFO | Step Pass: ' lines (or could be Test Failure, Test Skip....maybe these should also be 'Step'?) are have special handlers in our LoggerListener: http://github.com/k0s/mozmill/blob/log-format/mozmill/mozmill/__init__.py#L88 ; the others (like 'INFO | mozmill.persist') are handled by a fallback handler

 - my recommendation is to make the fallback handler log at the DEBUG level (changing http://github.com/k0s/mozmill/blob/log-format/mozmill/mozmill/__init__.py#L98 ) and setting the logger not to display DEBUG messages, at least with any existing CLI switch.  (They will still go to the log file, if one is specified.) If they are important, then probably not the best idea.  If some of them are important, we should make a special handler for these and throw away the others.  This will make tests less noisy.  
 
 - similarly, we could log at DEBUG output already handled by other handlers.  e.g. mozmill.endTest is handled explicitly (printing here 'TEST-PASS' or e.g. 'TEST-UNEXPECTED-FAIL' if Something Bad Happened) as well as by the logging handler. Again, depends on if we want to display this information.

 - currently, we have no notion of TEST-KNOWN-FAIL

 - this is pretty flexible and we can change it if any of this is not to taste.  To me, with the caveat of logging things like 'INFO | mozmill.persist' at DEBUG and possibly logging at DEBUG events handled by other handlers, this is fine.  If we want a really radical change, it might require drastically changing how we use python logging or even rolling our own logger (not hard, but I only want to go down that route if we really want to).  But it depends on how adequate this is and what changes need to be made.

 - despite how it looks on bugzilla, each of these really is one line

 - once we are happy with this, I really need to write up the logging format.  Logs are only useful if you know what you're looking at! (at https://developer.mozilla.org/en/Mozmill ) Don't let me close this bug without doing that! (or at least re-ticketing)

Comment 19

[cmtalbert]

(In reply to comment #18)
> Notes on https://bugzilla.mozilla.org/show_bug.cgi?id=573589#c17 :
> 
>  - the lines that start with INFO |(or conceivably DEBUG |, WARNING |, etc) are
> done through python's logging module;  the lines that start with TEST-PASS,
> TEST-START, or just plain INFO are plain old print statements.
> 
>  - the 'INFO | Step Pass: ' lines (or could be Test Failure, Test Skip....maybe
> these should also be 'Step'?) are have special handlers in our LoggerListener:
> http://github.com/k0s/mozmill/blob/log-format/mozmill/mozmill/__init__.py#L88 ;
> the others (like 'INFO | mozmill.persist') are handled by a fallback handler
> 
>  - my recommendation is to make the fallback handler log at the DEBUG level
> (changing
> http://github.com/k0s/mozmill/blob/log-format/mozmill/mozmill/__init__.py#L98 )
> and setting the logger not to display DEBUG messages, at least with any
> existing CLI switch.  (They will still go to the log file, if one is
> specified.) If they are important, then probably not the best idea.  If some of
> them are important, we should make a special handler for these and throw away
> the others.  This will make tests less noisy.  
> 
I think it makes sense not to log the DEBUG stuff by default.  We should only do that if we absolutely need that information, perhaps that is what --showall should do.

Normal logging (without --showall) should just show passes and fails and information lines.

>  - similarly, we could log at DEBUG output already handled by other handlers. 
> e.g. mozmill.endTest is handled explicitly (printing here 'TEST-PASS' or e.g.
> 'TEST-UNEXPECTED-FAIL' if Something Bad Happened) as well as by the logging
> handler. Again, depends on if we want to display this information.
>
We definitely need TEST-PASS and TEST-UNEXPECTED-FAIL printed all the time. I don't care how we do it or in what log handler.  Not sure if I understand the problem.
 
>  - currently, we have no notion of TEST-KNOWN-FAIL
> 
Neither does mochitest.  We'll cross that bridge when we get there.

>  - this is pretty flexible and we can change it if any of this is not to taste.
>  To me, with the caveat of logging things like 'INFO | mozmill.persist' at
> DEBUG and possibly logging at DEBUG events handled by other handlers, this is
> fine.  If we want a really radical change, it might require drastically
> changing how we use python logging or even rolling our own logger (not hard,
> but I only want to go down that route if we really want to).  But it depends on
> how adequate this is and what changes need to be made.
>
I think this stuff in comment 17 looks great.  What does it look like when a test fails?

>  - once we are happy with this, I really need to write up the logging format. 
> Logs are only useful if you know what you're looking at! (at
> https://developer.mozilla.org/en/Mozmill ) Don't let me close this bug without
> doing that! (or at least re-ticketing)
Will do.

Comment 20

[Jeff Hammel]

(In reply to comment #19)
> (In reply to comment #18)
<snip/>
> >  - my recommendation is to make the fallback handler log at the DEBUG level
> > (changing
> > http://github.com/k0s/mozmill/blob/log-format/mozmill/mozmill/__init__.py#L98 )
> > and setting the logger not to display DEBUG messages, at least with any
> > existing CLI switch.  (They will still go to the log file, if one is
> > specified.) If they are important, then probably not the best idea.  If some of
> > them are important, we should make a special handler for these and throw away
> > the others.  This will make tests less noisy.  
> > 
> I think it makes sense not to log the DEBUG stuff by default.  We should only
> do that if we absolutely need that information, perhaps that is what --showall
> should do.
> 
> Normal logging (without --showall) should just show passes and fails and
> information lines.

Currently (as in, on my log-format branch) we have --showerrors (which shows everything logged at level error and above, as well as the print statements [see below]) and --showall (which really does show everything).  Not specifying any of these only logs CRITICAL events....I'm not sure if we even have any of these.  

I've gone ahead and made unknown events log at DEBUG and left everything else as it is. So user-facing, no change here.

> >  - similarly, we could log at DEBUG output already handled by other handlers. 
> > e.g. mozmill.endTest is handled explicitly (printing here 'TEST-PASS' or e.g.
> > 'TEST-UNEXPECTED-FAIL' if Something Bad Happened) as well as by the logging
> > handler. Again, depends on if we want to display this information.
> >
> We definitely need TEST-PASS and TEST-UNEXPECTED-FAIL printed all the time. I
> don't care how we do it or in what log handler.  Not sure if I understand the
> problem.

No problem at all, just choices.  Currently, TEST-UNEXPECTED-FAIL and WARNING (for skips) are always printed.  TEST-PASS (and TEST-START) is only printed if --showerrors or --showall is specified.  (Which is a new feature:  these used to not be printed at all). Note that the are printed -- that is, with print -- and not with the logger.  Not sure if this makes a difference for our purposes. (or as Clint pointed out, we can always file additional bugs to refine our logging output).

http://github.com/k0s/mozmill/blob/log-format/mozmill/mozmill/__init__.py#L253

I'll make both TEST-PASS and TEST-START print always

> >  - currently, we have no notion of TEST-KNOWN-FAIL
> > 
> Neither does mochitest.  We'll cross that bridge when we get there.

Sounds good.
 
> >  - this is pretty flexible and we can change it if any of this is not to taste.
> >  To me, with the caveat of logging things like 'INFO | mozmill.persist' at
> > DEBUG and possibly logging at DEBUG events handled by other handlers, this is
> > fine.  If we want a really radical change, it might require drastically
> > changing how we use python logging or even rolling our own logger (not hard,
> > but I only want to go down that route if we really want to).  But it depends on
> > how adequate this is and what changes need to be made.
> >
> I think this stuff in comment 17 looks great.  What does it look like when a
> test fails?

It will be similar except some

INFO | Test failed: <stuff>
TEST-UNEXPECTED-FAIL | stuff | stuff

similar to the other tests

> >  - once we are happy with this, I really need to write up the logging format. 
> > Logs are only useful if you know what you're looking at! (at
> > https://developer.mozilla.org/en/Mozmill ) Don't let me close this bug without
> > doing that! (or at least re-ticketing)
> Will do.

Comment 21

[Jeff Hammel]

Attachment: first round of making logging better

this will get logging into a better state.  There's still a lot up in the air, but subsequent issues should be ticketed....subsequently, unless there's a show-stopper here

Comment 22

[cmtalbert]

Comment on attachment 457450 [details] [diff] [review]
first round of making logging better

>+        # TODO:  document this behaviour!
What do you mean?  The restart tests are documented.  They are numbered sequentially test1, test2 and so on, with restarts in between.
>         if os.path.isfile(os.path.join(test_dir, 'testPre.js')):   
>             pre_test = os.path.join(test_dir, 'testPre.js')
>             post_test = os.path.join(test_dir, 'testPost.js') 
>@@ -469,6 +489,9 @@ class MozMillRestart(MozMill):
> 
>         self.report_document = None
> 
>+        # XXX this allows for only one sub-level of test directories
>+        # is this a spec or a side-effect?
>+        # If the former, it should be documented
It's by design and it is documented on MDC.

>         test_dirs = [d for d in os.listdir(os.path.abspath(os.path.expanduser(test_dir))) 
>                      if d.startswith('test') and os.path.isdir(os.path.join(test_dir, d))]
>         

This looks good.  I'd expand the first comment and actually document what its doing.  The second comment I'd remove entirely.

r=ctalbert

Comment 23

[Henrik Skupin [:whimboo][⌚️UTC+2]]

(In reply to comment #22)
> >+        # TODO:  document this behaviour!
> What do you mean?  The restart tests are documented.  They are numbered
> sequentially test1, test2 and so on, with restarts in between.
> >         if os.path.isfile(os.path.join(test_dir, 'testPre.js')):   
> >             pre_test = os.path.join(test_dir, 'testPre.js')
> >             post_test = os.path.join(test_dir, 'testPost.js') 

testPre.js and testPost.js were the former way to run tests. I don't think that we need those anymore because they aren't really helpful. I would suggest to remove those in another bug.

Comment 24

[Jeff Hammel]

pushed to master and 1.4.2

http://github.com/mozautomation/mozmill/commit/71460c51ad87d26c855cf61c4ee52db4f5cadee5

http://github.com/mozautomation/mozmill/commit/9ffd3ad46af0c182e055d26afaf58c4845565013

Comment 25

[Jeff Hammel]

(In reply to comment #22)
> Comment on attachment 457450 [details] [diff] [review]
> first round of making logging better
> 
> >+        # TODO:  document this behaviour!
> What do you mean?  The restart tests are documented.  They are numbered
> sequentially test1, test2 and so on, with restarts in between.

If this is on devmo, then a link should go here. If not, it should be documented there and a link should go here.  I didn't think it was enough to warrant more than a comment in passing.  While I did not exhaustively search, I spent some time trying to find this and explanation for the comment below in devmo without success.

> >         if os.path.isfile(os.path.join(test_dir, 'testPre.js')):   
> >             pre_test = os.path.join(test_dir, 'testPre.js')
> >             post_test = os.path.join(test_dir, 'testPost.js') 
> >@@ -469,6 +489,9 @@ class MozMillRestart(MozMill):
> > 
> >         self.report_document = None
> > 
> >+        # XXX this allows for only one sub-level of test directories
> >+        # is this a spec or a side-effect?
> >+        # If the former, it should be documented
> It's by design and it is documented on MDC.

Again, I couldn't find it on devmo.  Where is this?  And why is this?  At least how it is in the code, the one sub-level of test directories seems pretty arbitrary.

> >         test_dirs = [d for d in os.listdir(os.path.abspath(os.path.expanduser(test_dir))) 
> >                      if d.startswith('test') and os.path.isdir(os.path.join(test_dir, d))]
> >         
> 
> This looks good.  I'd expand the first comment and actually document what its
> doing.  The second comment I'd remove entirely.
> 
> r=ctalbert

I punted on fixing the comments, although I can file separately if desired, as I couldn't find where things were actually documented.

Comment 26

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Wow, the new output looks fantastic. You get much more information as before in a really clean way. Thanks Jeff for working on that. Tested with --show-errors, --showall, and none additional option.