Closed Bug 1364245 Opened 4 years ago Closed 4 years ago

Intermittent test_navigation.py TestPageLoadStrategy.test_eager | AssertionError: 'interactive' != u'complete'

Categories

(Testing :: Marionette, defect)

Version 3
defect
Not set
normal

Tracking

(firefox54 fixed, firefox55 fixed)

RESOLVED FIXED
mozilla55
Tracking Status
firefox54 --- fixed
firefox55 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: whimboo)

References

Details

(Keywords: intermittent-failure, Whiteboard: [fennec-scouting] [stockwell fixed])

Attachments

(1 file)

Whiteboard: [fennec-scouting]
New testcase as landed by my patch on bug 937659. Here details from the log:

05-11 02:14:50.675 I/Gecko   (  725): 1494494090677	Marionette	TRACE	104 -> [0,2,"get",{"url":"http://172.17.0.5:55183/slow_resource.html"}]
05-11 02:14:50.836 I/Gecko   (  725): 1494494090838	Marionette	DEBUG	Received DOM event "beforeunload" for "http://172.17.0.5:55183/windowHandles.html"
05-11 02:14:50.955 I/Gecko   (  725): AndroidBridge::GetCurrentNetworkInformation
05-11 02:14:51.165 I/Gecko   (  725): 1494494091169	Marionette	DEBUG	Received DOM event "pagehide" for "http://172.17.0.5:55183/windowHandles.html"
05-11 02:14:51.195 I/Gecko   (  725): 1494494091198	Marionette	DEBUG	Received DOM event "unload" for "http://172.17.0.5:55183/windowHandles.html"
05-11 02:14:51.225 I/Gecko   (  725): ++DOMWINDOW == 27 (0x6891c800) [pid = 725] [serial = 272] [outer = 0x6866cc00]
05-11 02:14:52.015 I/Gecko   (  725): AndroidBridge::GetCurrentNetworkInformation
05-11 02:14:53.165 I/Gecko   (  725): 1494494093167	Marionette	DEBUG	Received DOM event "DOMContentLoaded" for "http://172.17.0.5:55183/slow_resource.html"
05-11 02:14:53.455 I/Gecko   (  725): 1494494093460	Marionette	TRACE	104 <- [1,2,null,{}]

For eager mode we correctly wait until `DOMContentLoaded` was received, and returned from `get`. The issue here seems to be located in slow_resource.html:

> <img src="/slow?delay=1" id="slow" />

A delay of 1s is simply too short and slow running browsers will already have a readyState of `complete` when the readyState is checked in the Python code.
Blocks: 937659
Attachment #8867099 - Flags: review?(ato)
Comment on attachment 8867099 [details]
Bug 1364245 - Extend delay for slow loading resource testcase to prevent intermittent.

https://reviewboard.mozilla.org/r/138700/#review142028
Attachment #8867099 - Flags: review?(ato) → review+
Assignee: nobody → hskupin
Pushed by hskupin@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/555b205831e7
Extend delay for slow loading resource testcase to prevent intermittent. r=ato
The patch as landed doesn't fix the problem completely. Here an excerpt:


05-12 19:17:00.528 I/Gecko   (  723): 1494641820534	Marionette	DEBUG	Received DOM event "DOMContentLoaded" for "http://172.17.0.5:35756/slow_resource.html"
05-12 19:17:00.818 I/Gecko   (  723): 1494641820825	Marionette	TRACE	111 <- [1,2,null,{}]
05-12 19:17:00.978 I/Gecko   (  723): 1494641820987	Marionette	TRACE	111 -> [0,3,"getCurrentUrl",{}]
05-12 19:17:05.848 I/Gecko   (  723): 1494641825851	Marionette	TRACE	111 <- [1,3,null,{"value":"http://172.17.0.5:35756/slow_resource.html"}]
05-12 19:17:07.998 I/Gecko   (  723): 1494641828002	Marionette	TRACE	111 -> [0,4,"executeScript",{"scriptTimeout":null,"newSandbox":true,"args":[],"filename":"test_navigation.py","script":"return window.document.readyState;","sandbox":null,"line":101}]
05-12 19:17:08.259 I/Gecko   (  723): 1494641828258	Marionette	TRACE	111 <- [1,4,null,{"value":"complete"}]
0

So we have to get switch the readyState check with the getCurrentUrl call. Looks like retrieving the URL takes up to 5s!
Status: NEW → ASSIGNED
Keywords: leave-open
Hm, whereby I would say that we should get the patch backed out, so I can do a complete one. Can someone please do it? Thanks.
Backout by ryanvm@gmail.com:
https://hg.mozilla.org/integration/autoland/rev/909472858413
Backed out changeset 555b205831e7 because it didn't fully fix the problem.
Whiteboard: [fennec-scouting] → [fennec-scouting] [stockwell needswork]
The latest changes seem to work fine:

05-16 00:09:29.522 I/Gecko   (  721): 1494918569526	Marionette	TRACE	169 -> [0,2,"get",{"url":"http://172.17.0.5:48180/slow_resource.html"}]
[..]
05-16 00:09:32.682 I/Gecko   (  721): 1494918572686	Marionette	DEBUG	Received DOM event "DOMContentLoaded" for "http://172.17.0.5:48180/slow_resource.html"
05-16 00:09:32.972 I/Gecko   (  721): 1494918572977	Marionette	TRACE	169 <- [1,2,null,{}]
05-16 00:09:33.202 I/Gecko   (  721): 1494918573206	Marionette	TRACE	169 -> [0,3,"executeScript",{"scriptTimeout":null,"newSandbox":true,"args":[],"filename":"test_navigation.py","script":"return window.document.readyState;","sandbox":null,"line":101}]
05-16 00:09:33.673 I/Gecko   (  721): 1494918573678	Marionette	TRACE	169 <- [1,3,null,{"value":"interactive"}]
05-16 00:09:33.822 I/Gecko   (  721): 1494918573829	Marionette	TRACE	169 -> [0,4,"getCurrentUrl",{}]
05-16 00:09:34.043 I/Gecko   (  721): 1494918574048	Marionette	TRACE	169 <- [1,4,null,{"value":"http://172.17.0.5:48180/slow_resource.html"}]

Not a single failure was happening even with a lot of retriggers.
Andreas, can you please have a look at the patch again? Thanks.
Flags: needinfo?(ato)
Still looks fine to me.
Flags: needinfo?(ato)
Pushed by hskupin@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/8e62027f76d4
Extend delay for slow loading resource testcase to prevent intermittent. r=ato
Status: ASSIGNED → RESOLVED
Closed: 4 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla55
Whiteboard: [fennec-scouting] [stockwell needswork] → [fennec-scouting] [stockwell fixed]
Depends on: 1378191
No longer depends on: 1378191
Removing leave-open keyword from resolved bugs, per :sylvestre.
Keywords: leave-open
You need to log in before you can comment on or make changes to this bug.