Closed Bug 1353599 Opened 7 years ago Closed 7 years ago

Intermittent test_about_private_browsing.py TestAboutPrivateBrowsing.testCheckAboutPrivateBrowsing | TimeoutException: Timeout loading page after 300000ms

Categories

(Testing :: Firefox UI Tests, defect)

Product:
Testing
Component:
Firefox UI Tests
Version:
Version 3
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(firefox-esr52 unaffected, firefox54 wontfix, firefox55 wontfix, firefox56 fixed)

Status:
RESOLVED FIXED
Milestone:
mozilla56
Tracking Flags:
Tracking Status
firefox-esr52 --- unaffected
firefox54 --- wontfix
firefox55 --- wontfix
firefox56 --- fixed

People

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

References

(Depends on 1 open bug)

Details

(Keywords: intermittent-failure, regression, Whiteboard: [stockwell fixed:race])

Attachments

(1 file)

temporarily disable test
744 bytes, patch
gbrown
: review+
Details | Diff | Splinter Review 
This happens when the test tried to load `about:privatebrowsing`:

[task 2017-04-04T21:23:23.103541Z] 21:23:23     INFO - Traceback (most recent call last):
[task 2017-04-04T21:23:23.103628Z] 21:23:23     INFO -   File "/home/worker/workspace/build/venv/local/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 166, in run
[task 2017-04-04T21:23:23.103682Z] 21:23:23     INFO -     testMethod()
[task 2017-04-04T21:23:23.103763Z] 21:23:23     INFO -   File "/home/worker/workspace/build/tests/firefox-ui/tests/functional/private_browsing/test_about_private_browsing.py", line 35, in testCheckAboutPrivateBrowsing
[task 2017-04-04T21:23:23.103813Z] 21:23:23     INFO -     self.marionette.navigate('about:privatebrowsing')
[task 2017-04-04T21:23:23.103881Z] 21:23:23     INFO -   File "/home/worker/workspace/build/venv/local/lib/python2.7/site-packages/marionette_driver/marionette.py", line 1721, in navigate
[task 2017-04-04T21:23:23.103928Z] 21:23:23     INFO -     self._send_message("get", {"url": url})
[task 2017-04-04T21:23:23.103992Z] 21:23:23     INFO -   File "/home/worker/workspace/build/venv/local/lib/python2.7/site-packages/marionette_driver/decorators.py", line 23, in _
[task 2017-04-04T21:23:23.104035Z] 21:23:23     INFO -     return func(*args, **kwargs)
[task 2017-04-04T21:23:23.104671Z] 21:23:23     INFO -   File "/home/worker/workspace/build/venv/local/lib/python2.7/site-packages/marionette_driver/marionette.py", line 735, in _send_message
[task 2017-04-04T21:23:23.105472Z] 21:23:23     INFO -     self._handle_error(err)
[task 2017-04-04T21:23:23.106038Z] 21:23:23     INFO -   File "/home/worker/workspace/build/venv/local/lib/python2.7/site-packages/marionette_driver/marionette.py", line 768, in _handle_error
[task 2017-04-04T21:23:23.106451Z] 21:23:23     INFO -     raise errors.lookup(error)(message, stacktrace=stacktrace)

Actually there are the following lines right before:

[task 2017-04-04T21:23:19.396901Z] 21:23:19     INFO -  JavaScript error: chrome://marionette/content/proxy.js, line 195: NS_ERROR_ILLEGAL_VALUE: Component returned failure code: 0x80070057 (NS_ERROR_ILLEGAL_VALUE) [nsIMessageSender.sendAsyncMessage]

So this is related to bug 1353635, and we might need a fix for bug 1336137 (including the case when the framescript got reloaded).
Depends on: 1336137, 1353635
Hm, whereby there is also the following line:

> Full message: TypeError: NetworkError when attempting to fetch resource.

Not sure if that is related.
[task 2017-05-28T11:22:27.752101Z] 11:22:27     INFO -  1495970547749	Marionette	TRACE	81 -> [0,84,"get",{"url":"about:privatebrowsing"}]
[task 2017-05-28T11:22:27.759752Z] 11:22:27     INFO -  1495970547756	Marionette	DEBUG	Received DOM event "beforeunload" for "about:"
[task 2017-05-28T11:22:27.795444Z] 11:22:27     INFO -  1495970547793	Marionette	DEBUG	Received DOM event "pagehide" for "about:"
[task 2017-05-28T11:22:27.796770Z] 11:22:27     INFO -  1495970547793	Marionette	DEBUG	Received DOM event "unload" for "about:"
[task 2017-05-28T11:22:27.798974Z] 11:22:27     INFO -  ++DOCSHELL 0x7fb3e7493800 == 1 [pid = 1903] [id = {c3a06a58-8e0c-4dc4-991f-6ebb9cdd347b}]
[task 2017-05-28T11:22:27.875699Z] 11:22:27     INFO -  1495970547866	Marionette	DEBUG	Received observer notification "outer-window-destroyed" for "293"
[task 2017-05-28T11:22:27.875833Z] 11:22:27     INFO -  ++DOMWINDOW == 1 (0x7fb3e74a5000) [pid = 1903] [serial = 1] [outer = (nil)]
[task 2017-05-28T11:22:28.098488Z] 11:22:28     INFO -  ++DOMWINDOW == 2 (0x7fb3dac68800) [pid = 1903] [serial = 2] [outer = 0x7fb3e74a5000]
[task 2017-05-28T11:22:28.134121Z] 11:22:28     INFO -  1495970548127	Marionette	DEBUG	loaded listener.js
[..]
[task 2017-05-28T11:27:29.510079Z] 11:27:29     INFO -  1495970849507	Marionette	TRACE	81 <- [1,84,{"error":"timeout","message":"Timeout loading page after 300000ms","stacktrace":"WebDriverError@chrome://marionette/content/error.js:222:5\nTimeoutError@chrome://marionette/content/error.js:472:5\nnotify@chrome://marionette/content/listener.js:297:17\n"},null]

There is no further DOM event for the page load being received after the frame script got reloaded. Maybe it's a race between reloading the frame script, and registering the DOM events.
Depends on: 1368434
this bug is failing @ 15failures/day+, I would like to see this fixed or disable next week.  I see it depends on bug 1368434 which has no action for almost 3 weeks.

:whimboo- can you get this resolved next week?
Flags: needinfo?(hskupin)
Whiteboard: [stockwell needswork]
:whimboo any updates here?
(In reply to Joel Maher ( :jmaher) from comment #13)
> :whimboo any updates here?

It has the same underlying issue as bug 1360446 (TestLegacyClick.test_click). Not sure when I will have this fixed.
Flags: needinfo?(hskupin)
The test actually started to fail on April 4th but with a low intermittent failure rate. So it looks like a regression from bug 1291320.

But what I wonder is what actually caused such a high spike of failures between June 9th and 11th:

https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1353599&startday=2017-04-03&endday=2017-06-21&tree=all
Blocks: 1291320
status-firefox54: --- → wontfix
status-firefox55: --- → affected
status-firefox56: --- → affected
status-firefox-esr52: --- → unaffected
Keywords: regression
this is still failing often, about 40 failures since Monday- I assume the same rate as last week- is there a potential fix upcoming for this bug?
Flags: needinfo?(hskupin)
This still depends on a fix for bug 1368434 most likely.
Flags: needinfo?(hskupin)
given there is no action in bug 1368434 for 11 days, I have little confidence this will get fixed soon- Given the failure rate is high for coming on 2 weeks in a row, I would like to disable this test.
Attachment #8880807 - Flags: review?(gbrown) → review+
Pushed by jmaher@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/755b2bdfc2ad
Intermittent test_about_private_browsing.py TestAboutPrivateBrowsing.testCheckAboutPrivateBrowsing. temporarily disable. r=gbrown
https://hg.mozilla.org/mozilla-central/rev/755b2bdfc2ad
Status: NEW → RESOLVED
Closed: 7 years ago
status-firefox56: affected → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla56
Not fixed, but the test got disabled.
Status: RESOLVED → REOPENED
status-firefox56: fixed → disabled
Resolution: FIXED → ---
Whiteboard: [stockwell needswork] → [stockwell disabled]
This failure was actually fixed by my patch on bug 1368434.
Assignee: nobody → hskupin
Status: REOPENED → RESOLVED
Closed: 7 years ago → 7 years ago
status-firefox56: disabled → fixed
Keywords: leave-open
Resolution: --- → FIXED
Whiteboard: [stockwell disabled] → [stockwell fixed:race]
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: