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

RESOLVED FIXED in Firefox 47

Status

DevTools
Console
P1
normal
RESOLVED FIXED
3 years ago
a month ago

People

(Reporter: philor, Assigned: Sami Jaktholm)

Tracking

(Blocks: 1 bug, {intermittent-failure})

unspecified
Firefox 48
intermittent-failure
Dependency tree / graph

Firefox Tracking Flags

(e10s+, firefox47 fixed, firefox48 fixed)

Details

(Whiteboard: [btpp-fix-now][e10s-orangeblockers])

MozReview Requests

Submitter Diff Changes Open Issues Last Updated
Loading...
Error loading review requests:

Attachments

(1 attachment)

Might be related to Bug 1234287
Blocks: 1234287

Updated

3 years ago
Blocks: 984139
tracking-e10s: --- → +

Comment 2

3 years ago
11 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-inbound: 5
* mozilla-central: 2
* fx-team: 2
* mozilla-aurora: 1
* b2g-inbound: 1

Platform breakdown:
* linux64: 6
* linux32: 5

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1242234&startday=2016-01-25&endday=2016-01-31&tree=all

Comment 3

3 years ago
29 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* fx-team: 11
* mozilla-inbound: 8
* try: 5
* mozilla-central: 3
* mozilla-aurora: 2

Platform breakdown:
* linux64: 12
* linux32: 11
* windows7-32: 6

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1242234&startday=2016-02-01&endday=2016-02-07&tree=all

Comment 4

3 years ago
34 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-inbound: 15
* fx-team: 9
* mozilla-aurora: 4
* try: 3
* mozilla-central: 3

Platform breakdown:
* windows7-32: 22
* linux32: 6
* linux64: 5
* android-4-3-armv7-api15: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1242234&startday=2016-02-08&endday=2016-02-14&tree=all

Comment 5

2 years ago
22 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-inbound: 10
* fx-team: 7
* mozilla-aurora: 5

Platform breakdown:
* linux32: 9
* windows7-32: 7
* linux64: 6

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1242234&startday=2016-02-22&endday=2016-02-28&tree=all
Flags: needinfo?(lclark)
See Bug 1242318
Flags: needinfo?(lclark)

Comment 7

2 years ago
48 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-inbound: 16
* fx-team: 13
* try: 9
* mozilla-aurora: 9
* mozilla-central: 1

Platform breakdown:
* linux32: 19
* linux64: 13
* windows7-32: 10
* osx-10-10: 4
* windows8-64: 1
* osx-10-6: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1242234&startday=2016-02-29&endday=2016-03-06&tree=all

Updated

2 years ago
Priority: -- → P1
Whiteboard: [btpp-fix-now]

Comment 8

2 years ago
43 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-inbound: 21
* fx-team: 8
* try: 4
* mozilla-central: 4
* mozilla-beta: 3
* mozilla-aurora: 3

Platform breakdown:
* windows7-32: 16
* linux32: 14
* linux64: 10
* osx-10-10: 3

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1242234&startday=2016-03-07&endday=2016-03-13&tree=all
See Also: → bug 1242318
Whiteboard: [btpp-fix-now] → [btpp-fix-now][e10s-orangeblockers]

Comment 9

2 years ago
49 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-inbound: 20
* mozilla-aurora: 12
* fx-team: 10
* try: 3
* mozilla-central: 2
* mozilla-beta: 2

Platform breakdown:
* linux64: 21
* windows7-32: 14
* linux32: 11
* osx-10-10: 3

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1242234&startday=2016-03-14&endday=2016-03-20&tree=all

Updated

2 years ago
Flags: needinfo?(mrbkap)
Keywords: leave-open
Whiteboard: [btpp-fix-now][e10s-orangeblockers] → [btpp-fix-now][e10s-orangeblockers][test disabled on e10s]
https://hg.mozilla.org/releases/mozilla-aurora/rev/1aef5889d381
status-firefox47: --- → disabled
status-firefox48: --- → disabled

Comment 14

2 years ago
34 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-inbound: 10
* mozilla-aurora: 9
* fx-team: 5
* mozilla-beta: 4
* try: 3
* mozilla-central: 2
* ash: 1

Platform breakdown:
* linux64: 15
* linux32: 15
* windows7-32: 2
* osx-10-10: 2

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1242234&startday=2016-03-21&endday=2016-03-27&tree=all

Updated

2 years ago
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
(Assignee)

Comment 17

2 years ago
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
(Assignee)

Comment 18

2 years ago
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.
(Assignee)

Comment 19

2 years ago
Created attachment 8736664 [details]
MozReview Request: Bug 1242234 - Wait for page load to finish before continuing in browser_webconsole_netlogging.js. r?linclark

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)
(Assignee)

Comment 20

2 years ago
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+

Updated

2 years ago
Keywords: leave-open → checkin-needed
(Assignee)

Comment 23

2 years ago
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)

Comment 26

2 years ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/5174488b2a59
Status: ASSIGNED → RESOLVED
Last Resolved: 2 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 48
status-firefox47: disabled → affected
status-firefox48: disabled → fixed

Comment 27

2 years ago
bugherderuplift
https://hg.mozilla.org/releases/mozilla-aurora/rev/53ae6c43eee2
status-firefox47: affected → fixed

Comment 28

2 years ago
14 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-inbound: 5
* mozilla-beta: 4
* try: 3
* mozilla-central: 1
* fx-team: 1

Platform breakdown:
* linux64: 6
* linux32: 5
* osx-10-10: 3

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1242234&startday=2016-03-28&endday=2016-04-03&tree=all
Blocks: 1264804
(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)

Updated

2 years ago
Priority: P1 → --

Updated

2 years ago
Priority: -- → P1

Updated

a month ago
Product: Firefox → DevTools
You need to log in before you can comment on or make changes to this bug.