Closed Bug 1242234 Opened 4 years ago Closed 4 years ago

Intermittent e10s browser_webconsole_netlogging.js | Method is correct - Got GET, expected POST

Categories

(DevTools :: Console, defect, P1)

defect

Tracking

(e10s+, firefox47 fixed, firefox48 fixed)

RESOLVED FIXED
Firefox 48
Tracking Status
e10s + ---
firefox47 --- fixed
firefox48 --- fixed

People

(Reporter: philor, Assigned: sjakthol)

References

(Blocks 1 open bug)

Details

(Keywords: intermittent-failure, Whiteboard: [btpp-fix-now][e10s-orangeblockers])

Attachments

(1 file)

Might be related to Bug 1234287
Blocks: 1234287
Blocks: e10s-tests
tracking-e10s: --- → +
Flags: needinfo?(lclark)
See Bug 1242318
Flags: needinfo?(lclark)
Priority: -- → P1
Whiteboard: [btpp-fix-now]
See Also: → 1242318
Whiteboard: [btpp-fix-now] → [btpp-fix-now][e10s-orangeblockers]
Flags: needinfo?(mrbkap)
Keywords: leave-open
Whiteboard: [btpp-fix-now][e10s-orangeblockers] → [btpp-fix-now][e10s-orangeblockers][test disabled on e10s]
Flags: needinfo?(mrbkap)
I'm seeing these failures again after re-enabling it in Bug 1239920, like: https://treeherder.mozilla.org/#/jobs?repo=try&revision=4145b5b8c69d&selectedJob=18815889.

11:53:01     INFO -  241 INFO TEST-UNEXPECTED-FAIL | devtools/client/webconsole/test/browser_webconsole_netlogging.js | Method is correct - Got GET, expected POST
11:53:01     INFO -  Stack trace:
11:53:01     INFO -      chrome://mochikit/content/browser-test.js:test_is:967
11:53:01     INFO -      chrome://mochitests/content/browser/devtools/client/webconsole/test/browser_webconsole_netlogging.js:testFormSubmission:106
---
11:53:01     INFO -  242 INFO TEST-UNEXPECTED-FAIL | devtools/client/webconsole/test/browser_webconsole_netlogging.js | Uncaught exception - at chrome://mochitests/content/browser/devtools/client/webconsole/test/browser_webconsole_netlogging.js:107 - TypeError: postData.postData.text is undefined

So I guess this was a different intermittent failure than the one that was fixed on the same test in Bug 1239920.
Whiteboard: [btpp-fix-now][e10s-orangeblockers][test disabled on e10s] → [btpp-fix-now][e10s-orangeblockers]
I've reproduced this a couple of time in chaos mode with --run-until-failure.  Sure enough, a GET request is happening on the same URL when we are waiting for a POST:

{"_type":"NetworkEvent","timeStamp":1459381246485,"node":{"clipboardText":"GET http://example.com/browser/devtools/client/webconsole/test/test-network-request.html [HTTP/1.1 200 OK 0ms]","timestamp":1459381246485,"category":0,"severity":3,"_connectionId":"server1.conn47.child1/netEvent28","url":"http://example.com/browser/devtools/client/webconsole/test/test-network-request.html"},"actor":"server1.conn47.child1/netEvent28","discardRequestBody":true,"discardResponseBody":false,"startedDateTime":"2016-03-30T23:40:46.485Z","request":{"url":"http://example.com/browser/devtools/client/webconsole/test/test-network-request.html","method":"GET","headersSize":0},"isXHR":false,"response":{"httpVersion":"HTTP/1.1","status":200,"statusText":"OK","headersSize":0,"remoteAddress":"","remotePort":"","content":{"mimeType":"text/html"},"bodySize":1342,"transferredSize":1342},"timings":{},"updates":["requestHeaders","requestCookies","responseStart","eventTimings","securityInfo","responseHeaders","responseCookies","responseContent"],"private":false,"fromCache":true,"fromServiceWorker":false,"totalTime":0,"securityInfo":"insecure"}

What's not clear to me is if this is a request that hadn't completed on a previous tab due to a timing difference in e10s, or if it's surfacing some kind of bug where the POST request doesn't always happen on a form submit (seems unlikely).

Trying a couple of different things on this push: https://treeherder.mozilla.org/#/jobs?repo=try&revision=9b6fa04c9520
I guess the problem here is that loadPageAndGetHud() [1] resolves once the console message about the request is rendered. However, I think that the message is logged immediately when enough info has been received instead of waiting for all updates (like headers, body, timings).

By the time we call waitForFinishedRequest(PAGE_REQUEST_PREDICATE) [2], the initial request is still pending and the resulting promise is resolved once the initial GET request finishes instead of the POST from the form submission.

The likely fix is to wrap the loadPageAndGetHud() call with waitForFinishedRequest(PAGE_REQUEST_PREDICATE) like it's done for the first subtest [3].

[1] https://dxr.mozilla.org/mozilla-central/source/devtools/client/webconsole/test/head.js#113
[2] https://dxr.mozilla.org/mozilla-central/source/devtools/client/webconsole/test/browser_webconsole_netlogging.js#91
[3] https://dxr.mozilla.org/mozilla-central/source/devtools/client/webconsole/test/browser_webconsole_netlogging.js#24
Also, the e10s intermittency is most likely caused by the fact that the network request updates for the console go through quite a many hoops in e10s mode. If I'm not that badly mistaken, the requests are observed in parent process and they are sent to content process to the console actor, which sends them to the parent process debugger server via a message manager and finally the debugger server sends them over the RDP to the client.

Given that the 'load' event loadPageAndGetHud() waits comes directly from child to parent and there's quite a many updates coming after the initial packet, waitForFinishedRequest() is most likely to be called while the updates for the original request is still pending.
The problem with this test is that loadPageAndGetHud() resolves once the console
message about the request is rendered. However, the message is logged immediately
when enough info has been received instead of waiting for all updates, such as
headers, body and timings, to be received.

By the time the test calls waitForFinishedRequest(PAGE_REQUEST_PREDICATE), the
initial request is still pending and the resulting promise resolves once
the initial GET request finishes instead of the POST request triggered by
the form submission causing the test failures.

Review commit: https://reviewboard.mozilla.org/r/43517/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/43517/
Attachment #8736664 - Flags: review?(lclark)
Try: https://treeherder.mozilla.org/#/jobs?repo=try&revision=f62eee01fb1a
Assignee: nobody → sjakthol
Status: NEW → ASSIGNED
That could be it.  The push in Comment 16 seems promising if the current patch doesn't end up fixing it: https://treeherder.mozilla.org/#/jobs?repo=try&revision=9b6fa04c9520 / https://hg.mozilla.org/try/rev/36184a62823bdc92a1ab25bc46c80da835299638.  Basically it closes each tab before proceeding to the next task.
Comment on attachment 8736664 [details]
MozReview Request: Bug 1242234 - Wait for page load to finish before continuing in browser_webconsole_netlogging.js. r?linclark

https://reviewboard.mozilla.org/r/43517/#review40175

Nice! I have an outstanding treeherder job that looks pretty similar, so I think this one is good to go.

Thanks so much for your work on this Sami!
Attachment #8736664 - Flags: review?(lclark) → review+
Brian, I think you should go ahead and land that patch too even if the intermittent is gone. It makes thing easier to debug in the future as the subtests don't have that much overlap with each other (like something goes wrong in the first tab while second test is running).
ni? for Comment 23 so I don't lose track of it
Flags: needinfo?(bgrinstead)
https://hg.mozilla.org/mozilla-central/rev/5174488b2a59
Status: ASSIGNED → RESOLVED
Closed: 4 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 48
(In reply to Sami Jaktholm from comment #23)
> Brian, I think you should go ahead and land that patch too even if the
> intermittent is gone. It makes thing easier to debug in the future as the
> subtests don't have that much overlap with each other (like something goes
> wrong in the first tab while second test is running).

Filed Bug 1264804
Flags: needinfo?(bgrinstead)
Priority: P1 → --
Priority: -- → P1
Product: Firefox → DevTools
You need to log in before you can comment on or make changes to this bug.