Fix frame handling of assertions to report the test function and not a module as top frame

VERIFIED FIXED

Status

VERIFIED FIXED
8 years ago
2 years ago

People

(Reporter: whimboo, Assigned: cmtalbert)

Tracking

Details

(Whiteboard: [mozmill-2.0+])

Attachments

(1 attachment, 2 obsolete attachments)

(Reporter)

Description

8 years ago
At the moment when you execute the tests for the new assertions module you will see that the top frame is still not accurate. The failure is reported in the assertion module itself and not in the test:

Step Pass: {"pass": {"function": "Expect__test", "message": " (AssertionError). assert.equal for [true, false, true is not equal to false]", "lineNumber": 113, "fileName": "resource://mozmill/modules/assertions.js"}}

That's exactly what I have changed with my stack walker in our own module. That's kinda important.
(Reporter)

Comment 1

8 years ago
The output we currently have in our own assertion module is:

INFO | Step Pass: {"pass": {"function": "testAssert", "message": "assert.equal for [true, false, true is not equal to false]", "lineNumber": 132, "fileName": "file:///Volumes/data/testing/mozmill/api-refactor/modules/tests/test_assertions.js"}}
(Assignee)

Comment 2

8 years ago
Looks like this is already solved in mochitest, we should check out simpletest.js to see how they do it.
Whiteboard: [mozmill-2.0?] → [mozmill-2.0+]
Assignee: nobody → fayearthur+bugs
Status: NEW → ASSIGNED
(Assignee)

Comment 3

7 years ago
(In reply to comment #2)
> Looks like this is already solved in mochitest, we should check out
> simpletest.js to see how they do it.

So, this isn't done in mochitest.  Mochitest doesn't report stacks.  Because we are truly reporting stacks we are bound by what is on the stack.  Since you'll always have the data you need in the stack, you only have one extra function on the stack.  So, let's just move on and focus on more import issues.

recommending WONTFIX
Status: ASSIGNED → RESOLVED
Last Resolved: 7 years ago
Resolution: --- → WONTFIX
(Reporter)

Comment 4

7 years ago
I have to reopen this bug because the current situation is not satisfying. Any info or error message you get will report a pass/fail in assertions.js but not at the exact place of the test or module:

INFO | Step Pass: {"function": "controller.waitForPageLoad()"}
ERROR | Test Failure: {"fail": {"function": "Expect__test", "message": "Element 'hplog' has been found. - got 'false'", "lineNumber": 113, "fileName": "resource://mozmill/modules/assertions.js"}}
INFO | Step Pass: {"function": "Controller.open()"}
INFO | Step Pass: {"function": "controller.waitFor()"}
INFO | Step Pass: {"function": "controller.waitForPageLoad()"}
INFO | Step Pass: {"pass": {"function": "Expect__test", "message": "Element 'search-q' has been found. - got 'true'", "lineNumber": 113, "fileName": "resource://mozmill/modules/assertions.js"}}
INFO | Step Pass: {"function": "Controller.open()"}
INFO | Step Pass: {"function": "controller.waitFor()"}
INFO | Step Pass: {"function": "controller.waitForPageLoad()"}
INFO | Step Pass: {"pass": {"function": "Expect__test", "message": "Element 'firefox' has been found. - got 'true'", "lineNumber": 113, "fileName": "resource://mozmill/modules/assertions.js"}}

That's absolutely not helpful for debugging and works fine in our API rewrite.
Status: RESOLVED → REOPENED
Resolution: WONTFIX → ---
(Assignee)

Comment 5

7 years ago
I'm going to look into this as I said in the mozmill meeting.  Probably look at it early next week sept 26 or so...
Assignee: fayearthur+bugs → ctalbert
(Assignee)

Comment 6

7 years ago
Created attachment 563619 [details] [diff] [review]
wip

So, this is the direction I'm thinking of going.  There is a lot of code in here, and a lot of it is still debugging because I'm still working through everything.  Here are the changes:

* pprint didn't output any stacks, ever.  The if statement in pprint was wrong and group(3) was always None.  fixed that
* added a little test that blows up so I can see what stacks we are reporting
* added my usual file log debugging cause I can't live without it (going to remove)
* added in Henrik's code from api-refactor for stack munging.

And here is the big change:
It reports the file name, message, and linenumber of the failure in the test file that called into assertions.js.  I think this is the most important part of what Henrik wanted.  I tried using the stripStackInformation funciton as well, but it made a royal mess of the stack and I couldn't make heads or tails of what I was looking at afterward.

So, my compromise is thus: we report the test file, filename, and message from the file under test, but for the stack variable, we report the full JS stack in normal JSON, with all it's information.  I think this gives us the best of both worlds, and since we can depend on the JS stack format not really changing, we can change our tools to properly show format it so that it's not the ugly beast it looks like below.  (This means I'll be changing pprint in logger.py to properly format it).

Here's an example of what this all looks like (not pretty printed, obviously):

(mozmill2.0)ctalbert@mozilla-ThinkPad-X201s:~/projects/mozmill$ mozmill -b ~/tools/nightly/firefox -t mutt/mutt/tests/js/test_expectstack.js
TEST-START | mutt/mutt/tests/js/test_expectstack.js | setupModule
TEST-START | mutt/mutt/tests/js/test_expectstack.js | testExpectStack
INFO | Step Pass: {"function": "Controller.open()"}
ERROR | Test Failure: {"fail": {"function": "Expect__test", "message": "Element foobar_the_friendly has been found. - got 'false'", "lineNumber": 13, "stack": {"caller": {"caller": {"caller": {"caller": {"caller": {"caller": {"caller": {"caller": {"caller": {"caller": {"caller": {"caller": null, "name": null, "language": 2, "sourceLine": null, "languageName": "JavaScript", "filename": "resource://jsbridge/modules/nspr-server.js", "lineNumber": 59}, "name": null, "language": 1, "sourceLine": null, "languageName": "C++", "filename": null, "lineNumber": 0}, "name": null, "language": 2, "sourceLine": null, "languageName": "JavaScript", "filename": "resource://jsbridge/modules/bridge.js", "lineNumber": 139}, "name": null, "language": 2, "sourceLine": null, "languageName": "JavaScript", "filename": "resource://jsbridge/modules/bridge.js", "lineNumber": 135}, "name": null, "language": 2, "sourceLine": null, "languageName": "JavaScript", "filename": "resource://mozmill/modules/frame.js", "lineNumber": 568}, "name": null, "language": 2, "sourceLine": null, "languageName": "JavaScript", "filename": "resource://mozmill/modules/frame.js", "lineNumber": 465}, "name": null, "language": 2, "sourceLine": null, "languageName": "JavaScript", "filename": "resource://mozmill/modules/frame.js", "lineNumber": 542}, "name": null, "language": 2, "sourceLine": null, "languageName": "JavaScript", "filename": "resource://mozmill/modules/frame.js", "lineNumber": 497}, "name": null, "language": 2, "sourceLine": null, "languageName": "JavaScript", "filename": "resource://mozmill/modules/frame.js -> file:///home/ctalbert/projects/mozmill/mutt/mutt/tests/js/test_expectstack.js", "lineNumber": 13}, "name": null, "language": 1, "sourceLine": null, "languageName": "C++", "filename": null, "lineNumber": 0}, "name": "Expect_ok", "language": 2, "sourceLine": null, "languageName": "JavaScript", "filename": "resource://mozmill/stdlib/securable-module.js -> resource://mozmill/modules/assertions.js", "lineNumber": 180}, "name": "Expect__test", "language": 2, "sourceLine": null, "languageName": "JavaScript", "filename": "resource://mozmill/stdlib/securable-module.js -> resource://mozmill/modules/assertions.js", "lineNumber": 133}, "fileName": "file:///home/ctalbert/projects/mozmill/mutt/mutt/tests/js/test_expectstack.js"}}
TEST-UNEXPECTED-FAIL | mutt/mutt/tests/js/test_expectstack.js | testExpectStack
INFO | Passed: 0
INFO | Failed: 1
INFO | Skipped: 0

What do y'all think?
Attachment #563619 - Flags: feedback?(jhammel)
(Assignee)

Updated

7 years ago
Status: REOPENED → ASSIGNED

Comment 7

7 years ago
Comment on attachment 563619 [details] [diff] [review]
wip

Looks great to me!

IMHO you might as well check in filelog.js.  We're going to need to fix our debugging story at some point, but i don't see any reason not to include the file now. (Obviously not the places you utilize it.)
Attachment #563619 - Flags: feedback?(jhammel) → feedback+
(Assignee)

Comment 8

7 years ago
Created attachment 563877 [details] [diff] [review]
a final-ish patch

Ok, here's a final.  This is the output now:

(mozmill2.0)ctalbert@mozilla-ThinkPad-X201s:~/projects/mozmill$ mozmill -b ~/tools/nightly/firefox -t mutt/mutt/tests/js/test_expectstack.js --format=pprint-color
TEST-START | mutt/mutt/tests/js/test_expectstack.js | setupModule
TEST-START | mutt/mutt/tests/js/test_expectstack.js | testExpectStack
INFO | Step Pass: {
  "function": "Controller.open()"
}
ERROR | Test Failure: {
  "fail": {
    "function": "Expect__test", 
    "message": "Element foobar_the_friendly has been found. - got 'false'", 
    "lineNumber": 13, 
    "stack": {
      "filename": "resource://mozmill/stdlib/securable-module.js -> resource://mozmill/modules/assertions.js", 
      "languageName": "JavaScript", 
      "name": "Expect__test", 
      "caller": {
        "filename": "resource://mozmill/stdlib/securable-module.js -> resource://mozmill/modules/assertions.js", 
        "languageName": "JavaScript", 
        "name": "Expect_ok", 
        "caller": {
          "caller": {
            "caller": {
              "caller": {
                "caller": {
                  "caller": {
                    "caller": {
                      "caller": {
                        "caller": {
                          "caller": {
                            "languageName": "JavaScript", 
                            "filename": "resource://jsbridge/modules/nspr-server.js", 
                            "lineNumber": 59
                          }, 
                          "languageName": "C++", 
                          "filename": null, 
                          "lineNumber": 0
                        }, 
                        "languageName": "JavaScript", 
                        "filename": "resource://jsbridge/modules/bridge.js", 
                        "lineNumber": 139
                      }, 
                      "languageName": "JavaScript", 
                      "filename": "resource://jsbridge/modules/bridge.js", 
                      "lineNumber": 135
                    }, 
                    "languageName": "JavaScript", 
                    "filename": "resource://mozmill/modules/frame.js", 
                    "lineNumber": 568
                  }, 
                  "languageName": "JavaScript", 
                  "filename": "resource://mozmill/modules/frame.js", 
                  "lineNumber": 465
                }, 
                "languageName": "JavaScript", 
                "filename": "resource://mozmill/modules/frame.js", 
                "lineNumber": 542
              }, 
              "languageName": "JavaScript", 
              "filename": "resource://mozmill/modules/frame.js", 
              "lineNumber": 497
            }, 
            "languageName": "JavaScript", 
            "filename": "resource://mozmill/modules/frame.js -> file:///home/ctalbert/projects/mozmill/mutt/mutt/tests/js/test_expectstack.js", 
            "lineNumber": 13
          }, 
          "languageName": "C++", 
          "filename": null, 
          "lineNumber": 0
        }, 
        "lineNumber": 168
      }, 
      "lineNumber": 121
    }, 
    "fileName": "file:///home/ctalbert/projects/mozmill/mutt/mutt/tests/js/test_expectstack.js"
  }
}
TEST-UNEXPECTED-FAIL | mutt/mutt/tests/js/test_expectstack.js | testExpectStack
INFO | Passed: 0
INFO | Failed: 1
INFO | Skipped: 0
Attachment #563619 - Attachment is obsolete: true
Attachment #563877 - Flags: review?(jhammel)

Comment 9

7 years ago
Comment on attachment 563877 [details] [diff] [review]
a final-ish patch

Looks great :) I assume this works with the existing mutt tests?
Attachment #563877 - Flags: review?(jhammel) → review+
(Assignee)

Comment 10

7 years ago
Created attachment 564394 [details] [diff] [review]
Final patch with test

Same patch, with test
Attachment #563877 - Attachment is obsolete: true
Attachment #564394 - Flags: review?(jhammel)

Comment 11

7 years ago
Comment on attachment 564394 [details] [diff] [review]
Final patch with test

Looks good.

Traditionally the pattern is for python test that need JS resources to put the test in the tests/python directory, but as it stands is probably fine
Attachment #564394 - Flags: review?(jhammel) → review+
(Assignee)

Comment 12

7 years ago
(In reply to Jeff Hammel [:jhammel] from comment #11)
> Comment on attachment 564394 [details] [diff] [review] [diff] [details] [review]
> Final patch with test
> 
> Looks good.
> 
> Traditionally the pattern is for python test that need JS resources to put
> the test in the tests/python directory, but as it stands is probably fine

Oh currently all the tests I was aware of reference the javascript tests out of the js/ subdirectory.  We could start pulling those over into the python/ directory I suppose.  

Anyhow, left as is for the moment and landed: https://github.com/mozautomation/mozmill/commit/0bb9d541549e54bf0754dde982fa824d6f6242a0
Status: ASSIGNED → RESOLVED
Last Resolved: 7 years ago7 years ago
Resolution: --- → FIXED

Comment 13

7 years ago
Sorry I thought there were some there but indeed you are right.  My mistake.
(Assignee)

Updated

7 years ago
Duplicate of this bug: 681347
(Reporter)

Comment 15

7 years ago
Looks good. Thanks Clint for this patch. It makes it a way better to understand failures.
Status: RESOLVED → VERIFIED
Product: Testing → Testing Graveyard
You need to log in before you can comment on or make changes to this bug.