1198616 - "TimeoutException: Timed out after 5 seconds" in test_safe_browsing_notification.py and test_safe_browsing_warning_pages.py

Status: RESOLVED FIXED

(Testing :: Firefox UI Tests, defect, P1)

Description

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Looks like this failure happens because the target page has not been loaded within 5s:

Traceback (most recent call last):
  File "c:\jenkins\workspace\mozilla-aurora_functional\venv\lib\site-packages\marionette\marionette_test.py", line 296, in run
    testMethod()
  File "c:\jenkins\workspace\mozilla-aurora_functional\venv\Lib\site-packages\firefox_ui_tests\functional\security\test_safe_browsing_notification.py", line 73, in test_notification_bar
    self.check_not_badware_button(button_property, report_page)
  File "c:\jenkins\workspace\mozilla-aurora_functional\venv\Lib\site-packages\firefox_ui_tests\functional\security\test_safe_browsing_notification.py", line 113, in check_not_badware_button
    Wait(self.marionette).until(lambda mn: report_page in mn.get_url())
  File "c:\jenkins\workspace\mozilla-aurora_functional\venv\lib\site-packages\marionette_driver\wait.py", line 143, in until
    cause=last_exc)

TimeoutException: TimeoutException: Timed out after 5.0 seconds


I don't think that we should limit the Wait call to 5min given that this test is accessing remote content. We should increase the timeout or use a local page if possible.

Comment 1

[Legacy TBPL/Treeherder Robot]

log: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-aurora&job_id=1072146
repository: mozilla-aurora
start_time: 2015-08-25T05:03:32
who: mail[at]hskupin[dot]info
machine: mm-win-7-32-3.qa.scl3.mozilla.com
buildname: non-buildbot windows7-32 test Firefox UI Test - functional (en-US)
revision: 8d8bbb549655

TEST-UNEXPECTED-ERROR | test_safe_browsing_notification.py TestSafeBrowsingNotificationBar.test_notification_bar | TimeoutException: TimeoutException: Timed out after 5.0 seconds

Comment 2

[Legacy TBPL/Treeherder Robot]

log: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-aurora&job_id=1062099
repository: mozilla-aurora
start_time: 2015-08-21T05:13:12
who: mail[at]hskupin[dot]info
machine: mm-osx-106-1.qa.scl3.mozilla.com
buildname: non-buildbot osx-10-6 test Firefox UI Test - remote (de)
revision: d8d62e273a8c

Comment 3

[Legacy TBPL/Treeherder Robot]

log: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-central&job_id=2077564
repository: mozilla-central
start_time: 2015-08-26T07:26:34
who: mail[at]hskupin[dot]info
machine: mm-win-7-32-2.qa.scl3.mozilla.com
buildname: non-buildbot windows7-32 test Firefox UI Test - functional (en-US)
revision: f61c3cc0eb8b

TEST-UNEXPECTED-ERROR | test_safe_browsing_notification.py TestSafeBrowsingNotificationBar.test_notification_bar | TimeoutException: TimeoutException: Timed out after 5.1 seconds

Comment 4

[Legacy TBPL/Treeherder Robot]

log: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-central&job_id=2127025
repository: mozilla-central
start_time: 2015-09-03T05:52:58
who: hskupin[at]gmail[dot]com
machine: mm-ub-1404-32-3.qa.scl3.mozilla.com
buildname: non-buildbot linux32 test Firefox UI Test - functional (en-US)
revision: a6786bf8d71d

TEST-UNEXPECTED-ERROR | test_safe_browsing_warning_pages.py TestSafeBrowsingWarningPages.test_warning_pages | TimeoutException: TimeoutException: Timed out after 5.0 seconds

Comment 5

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Interestingly this issue doesn't appear for latest release. It may be a regression in DNS name resolution because watching the tests makes that visible that we wait a long time in looking up ...

Comment 6

[Henrik Skupin [:whimboo][⌚️UTC+2]]

No more failures since the fix on bug 1201715 has been landed. Looks like we got this fixed.

Comment 7

[Legacy TBPL/Treeherder Robot]

log: https://treeherder.mozilla.org/logviewer.html#?repo=mozilla-beta&job_id=502129
repository: mozilla-beta
start_time: 2015-09-07T19:48:25
who: hskupin[at]gmail[dot]com
machine: mm-osx-106-1.qa.scl3.mozilla.com
buildname: non-buildbot osx-10-6 test Firefox UI Test - functional (it)
revision: 4ed5ddd4ab04

Comment 8

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Doesn't look to be fixed. At least not for beta and maybe even release and esr38. I should go and further backport the fix on bug 1201715 for those branches. Reopening bug for now.

Comment 9

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Well, actually this is a page load issue which occurs after 30s. So this is valid and might have been a network issue around that time. The underlying issue was fixed by the patch on the other bug for aurora and beta too.

Comment 10

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Not actually fixed. We still get those failures for the tests at least on mozilla-central from time to time.

Comment 11

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Maybe this failure is related to the "Service not available" 503 failure we currently get due to the migration process of that domain.

Comment 12

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Ok, so the problem here is indeed a slow loading page. We check that the button is no longer available after clicking on it. But if the remote server is slow in serving the page, the current page is not getting unloaded. So we should better check for the new page being loaded first, and then do the button not existent check.

Comment 13

[Henrik Skupin [:whimboo][⌚️UTC+2]]

So we cannot flip those lines because we won't detect a page load. So a solution would be:

-        Wait(self.marionette).until(expected.element_stale(button))
+        Wait(self.marionette, timeout=self.browser.timeout_page_load).until(
+            expected.element_stale(button))

I will check later if there is a better option for us.

Comment 14

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Attachment: Github PR

Simple fix to ensure we do not fail in case of slow connection times to remote servers.

Comment 15

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Bumping priority because nearly all tests were failing today with that failure. Orange factor will add a comment about that in the next couple of days I assume.

Comment 16

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Merged to mozilla-central as:
https://github.com/mozilla/firefox-ui-tests/commit/ed85accfe2465706026cab2748502c2f92af9b6e

Backports will happen later or tomorrow.

Comment 17

[Intermittent Failures Robot]

42 automation job failures were associated with this bug yesterday.

Repository breakdown:
* mozilla-aurora: 32
* mozilla-central: 10

Platform breakdown:
* linux64: 8
* osx-10-6: 7
* osx-10-10: 7
* osx-10-11: 6
* osx-10-9: 5
* linux32: 3
* windows7-64: 2
* windowsxp: 1
* windows8-64: 1
* windows8-32: 1
* windows7-32: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1198616&startday=2015-10-29&endday=2015-10-29&tree=all

Comment 18

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Actually this slowness is related to broken network routing and handled by bug 1170832. But we should harden our tests anyway.

Comment 19

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Backported to all other branches:

https://github.com/mozilla/firefox-ui-tests/commit/bb0a9ebdd6fa72289dc4fb3a39e1420e0b1cc53d (aurora)
https://github.com/mozilla/firefox-ui-tests/commit/62d0e9d7f2b90cf3aa881e8bcbb6d7e11ac0f765 (beta)
https://github.com/mozilla/firefox-ui-tests/commit/f18beb68e55b23f57eaaadeb81f44dcb280f9858 (release)
https://github.com/mozilla/firefox-ui-tests/commit/1213b59dfacf5aec2b7fb077d13f5a3c96b1a96f (esr38)

Comment 20

[Intermittent Failures Robot]

42 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-aurora: 32
* mozilla-central: 10

Platform breakdown:
* linux64: 8
* osx-10-6: 7
* osx-10-10: 7
* osx-10-11: 6
* osx-10-9: 5
* linux32: 3
* windows7-64: 2
* windowsxp: 1
* windows8-64: 1
* windows8-32: 1
* windows7-32: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1198616&startday=2015-10-26&endday=2015-11-01&tree=all