Phil Ringnalda (:philor) Reporter
	Description • 8 years ago

https://treeherder.mozilla.org/logviewer.html#?job_id=3158634&repo=mozilla-central

	Brian Grinstead [:bgrins]
	Comment 1 • 8 years ago

Might be related to Bug 1234287

	Lin Clark [:linclark]
	Comment 6 • 8 years ago

See Bug 1242318

	Pulsebot
	Comment 10 • 8 years ago

https://hg.mozilla.org/integration/mozilla-inbound/rev/48587fef6fb6

	Ryan VanderMeulen [:RyanVM]
	Comment 11 • 8 years ago
bugherder

https://hg.mozilla.org/mozilla-central/rev/48587fef6fb6

	Ryan VanderMeulen [:RyanVM]
	Comment 12 • 8 years ago

https://hg.mozilla.org/releases/mozilla-aurora/rev/1aef5889d381

	Brian Grinstead [:bgrins]
	Comment 13 • 8 years ago

I've re-enabled this test on fx-team in Bug 1239920 with: https://hg.mozilla.org/integration/fx-team/rev/5d52be560679 because I believe the two changesets landed there will stop the intermittent:

https://hg.mozilla.org/integration/fx-team/rev/abf28569fff7
https://hg.mozilla.org/integration/fx-team/rev/e04ad44074eb

	Brian Grinstead [:bgrins]
	Comment 15 • 8 years ago

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.

	Brian Grinstead [:bgrins]
	Comment 16 • 8 years ago

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

	Sami Jaktholm Assignee
	Comment 17 • 8 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

	Sami Jaktholm Assignee
	Comment 18 • 8 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.

	Sami Jaktholm Assignee
	Comment 19 • 8 years ago

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/

	Sami Jaktholm Assignee
	Comment 20 • 8 years ago

Try: https://treeherder.mozilla.org/#/jobs?repo=try&revision=f62eee01fb1a

	Brian Grinstead [:bgrins]
	Comment 21 • 8 years ago

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.

	Lin Clark [:linclark]
	Comment 22 • 8 years ago

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!

	Sami Jaktholm Assignee
	Comment 23 • 8 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).

	Pulsebot
	Comment 24 • 8 years ago

https://hg.mozilla.org/integration/fx-team/rev/5174488b2a59

	Brian Grinstead [:bgrins]
	Comment 25 • 8 years ago

ni? for Comment 23 so I don't lose track of it

	Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)
	Comment 26 • 8 years ago
bugherder

https://hg.mozilla.org/mozilla-central/rev/5174488b2a59

	Ryan VanderMeulen [:RyanVM]
	Comment 27 • 8 years ago
bugherder uplift

https://hg.mozilla.org/releases/mozilla-aurora/rev/53ae6c43eee2

	Brian Grinstead [:bgrins]
	Comment 29 • 8 years ago

(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