Intermittent testing/firefox-ui/tests/functional/security/test_ssl_disabled_error_page.py TestSSLDisabledErrorPage.test_ssl_disabled_error_page | AssertionError: 'tls-v1-0' not found in u'Secure Connection Failed'

RESOLVED FIXED in Firefox -esr60

Status

defect
P1
normal
RESOLVED FIXED
Last year
11 months ago

People

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

Tracking

({intermittent-failure})

Version 3
mozilla63
Points:
---
Dependency tree / graph
Bug Flags:
in-testsuite +

Firefox Tracking Flags

(firefox-esr60 fixed, firefox62 fixed, firefox63 fixed)

Details

Attachments

(1 attachment)

Filed by: ncsoregi [at] mozilla.com

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

https://queue.taskcluster.net/v1/task/Rg5J-LwcQVira26YJkv3yw/runs/0/artifacts/public/logs/live_backing.log

[task 2018-07-26T22:45:37.643Z] 22:45:37     INFO -  [Parent 796, Main Thread] WARNING: Remote iframe not rendered: file /builds/worker/workspace/build/src/layout/ipc/RenderFrameParent.cpp, line 182
[task 2018-07-26T22:45:37.705Z] 22:45:37     INFO -  1532645137702	Marionette	TRACE	16 <- [1,73,null,{"value":"iVBORw0KGgoAAAANSUhEUgAABQAAAAQQCAYAAAC9RfbYAAAgAElEQVR4nOzd3Ytc95ng8b4cyMUO+QfWVwENE5yQwWtwsk4Y2AEjSMYX ... D9bAZAnkejd48BqgRAAAAAWE8A3LH1NUlgLQEQAAAA1hMAD5j5qiowTgAEAACA9QRA4DYEQAAAAFhPAARuQwAEAACA9f4Hx4AjpPTW4yEAAAAASUVORK5CYII="}]
[task 2018-07-26T22:45:37.766Z] 22:45:37     INFO -  1532645137760	Marionette	TRACE	16 -> [0,74,"Marionette:SetContext",{"value":"chrome"}]
[task 2018-07-26T22:45:37.773Z] 22:45:37     INFO -  1532645137763	Marionette	TRACE	16 <- [1,74,null,{"value":null}]
[task 2018-07-26T22:45:37.781Z] 22:45:37     INFO -  --DOMWINDOW == 31 (0xdc265b40) [pid = 796] [serial = 67] [outer = (nil)] [url = about:about]
[task 2018-07-26T22:45:37.783Z] 22:45:37     INFO -  --DOMWINDOW == 30 (0xdc265a10) [pid = 796] [serial = 63] [outer = (nil)] [url = about:about]
[task 2018-07-26T22:45:37.792Z] 22:45:37     INFO -  --DOMWINDOW == 29 (0xdc265680) [pid = 796] [serial = 59] [outer = (nil)] [url = about:about]
[task 2018-07-26T22:45:37.796Z] 22:45:37     INFO -  1532645137775	Marionette	TRACE	16 -> [0,75,"Marionette:GetContext",{}]
[task 2018-07-26T22:45:37.802Z] 22:45:37     INFO -  1532645137778	Marionette	TRACE	16 <- [1,75,null,{"value":"chrome"}]
[task 2018-07-26T22:45:37.804Z] 22:45:37     INFO -  1532645137784	Marionette	TRACE	16 -> [0,76,"Marionette:SetContext",{"value":"content"}]
[task 2018-07-26T22:45:37.805Z] 22:45:37     INFO -  1532645137786	Marionette	TRACE	16 <- [1,76,null,{"value":null}]
[task 2018-07-26T22:45:37.807Z] 22:45:37     INFO -  1532645137790	Marionette	TRACE	16 -> [0,77,"WebDriver:GetPageSource",{}]
[task 2018-07-26T22:45:37.884Z] 22:45:37     INFO -  1532645137880	Marionette	TRACE	16 <- [1,77,null,{"value":"<html><head>\n  <meta name=\"viewport\" content=\"width=device-width, initial-scale=1\">\n  <link rel=\" ... div id=\"content\">\n  <h1 style=\"font-size: 12vw;\">\n    tls-v1-0.<br>badssl.com\n  </h1>\n</div>\n\n\n\n</body></html>"}]
[task 2018-07-26T22:45:37.888Z] 22:45:37     INFO -  1532645137884	Marionette	TRACE	16 -> [0,78,"Marionette:SetContext",{"value":"chrome"}]
[task 2018-07-26T22:45:37.891Z] 22:45:37     INFO -  1532645137887	Marionette	TRACE	16 <- [1,78,null,{"value":null}]
[task 2018-07-26T22:45:37.929Z] 22:45:37     INFO - TEST-UNEXPECTED-FAIL | testing/firefox-ui/tests/functional/security/test_ssl_disabled_error_page.py TestSSLDisabledErrorPage.test_ssl_disabled_error_page | AssertionError: 'tls-v1-0' not found in u'Secure Connection Failed'
[task 2018-07-26T22:45:37.929Z] 22:45:37     INFO - Traceback (most recent call last):
[task 2018-07-26T22:45:37.929Z] 22:45:37     INFO -   File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 159, in run
[task 2018-07-26T22:45:37.930Z] 22:45:37     INFO -     testMethod()
[task 2018-07-26T22:45:37.930Z] 22:45:37     INFO -   File "/builds/worker/workspace/build/tests/firefox-ui/tests/testing/firefox-ui/tests/functional/security/test_ssl_disabled_error_page.py", line 60, in test_ssl_disabled_error_page
[task 2018-07-26T22:45:37.930Z] 22:45:37     INFO -     self.assertIn('tls-v1-0', el.get_property('innerText'))
[task 2018-07-26T22:45:37.930Z] 22:45:37     INFO - TEST-INFO took 5601ms
The problem here seems to be that clicking the preferences reset button in the net error page sometimes seem to not raise the `AboutNetErrorResetPreferences` custom event, and this misses to refresh the page even after 300s, and still marks the page as securely failed:

> [task 2018-08-09T08:33:17.103Z] 08:33:17     INFO -  1533803597096	Marionette	TRACE	16 -> [0,65,"WebDriver:FindElement",{"using":"id","value":"prefResetButton"}]
> [task 2018-08-09T08:33:17.126Z] 08:33:17     INFO -  1533803597124	Marionette	TRACE	16 <- [1,65,null,{"value":{"element-6066-11e4-a52e-4f735466cecf":"cb8132bd-89a6-474c-991a-b0fde0d6f960"}}]
> [task 2018-08-09T08:33:17.134Z] 08:33:17     INFO -  1533803597130	Marionette	TRACE	16 -> [0,66,"WebDriver:ElementClick",{"id":"cb8132bd-89a6-474c-991a-b0fde0d6f960"}]
> [task 2018-08-09T08:33:17.446Z] 08:33:17     INFO -  1533803597440	Marionette	DEBUG	[30064771073] Canceled page load listener because no navigation has been detected
..
> [task 2018-08-09T08:33:17.651Z] 08:33:17     INFO -  1533803597645	Marionette	TRACE	16 -> [0,69,"WebDriver:GetElementProperty",{"id":"f444be28-2d62-4c3b-95dc-dd5a110077d9","name":"innerText"}]
> [task 2018-08-09T08:33:17.659Z] 08:33:17     INFO -  1533803597656	Marionette	TRACE	16 <- [1,69,null,{"value":"Secure Connection Failed"}]

Johann, do you have an idea what's going on here? Or where we could get some more debugging to investigate the problem? Thanks.
Flags: needinfo?(jhofmann)
Jonathan added this code back in the day, cc'ing him.

Are you sure that it's the custom event not firing? Since this is all async maybe your test should wait for the prefs to update?

That's the only thing that immediately comes to my mind. Other than that I couldn't imagine why this wouldn't work.
Flags: needinfo?(jhofmann)
(In reply to Johann Hofmann [:johannh] from comment #5)
> Are you sure that it's the custom event not firing? Since this is all async
> maybe your test should wait for the prefs to update?

Hm, ok. So I had another look at the test, and maybe we indeed have a race condition here. The test clicks the button to reset the preference. Then we expect a page to load, and check the `<h1>` element for it's `innerText`.

This is probably not a good idea given that if the page load is delayed, and the current page also has a `<h1>` element, the call to `Wait()` will return immediately. As such the `innerText` has the value from before clicking the button, which clearly would explain this test failure.

I will rewrite the test, so that it waits for the button to become stale, and then check for the `<h1>` element.
Assignee: nobody → hskupin
Status: NEW → ASSIGNED
Flags: needinfo?(jhofmann)
Priority: P5 → P1
I was able to see this failure when modifying the test to not click the button. So my suspicion was correct, and we do not wait until the error page has been unloaded.
Flags: needinfo?(jhofmann)
Currently the test doesn't wait for the restore button to become stale,
and as such the call to find_element will return immediately with a
reference to a "h1" element on the error page.
Attachment #9002705 - Flags: review?(ato) → review+
Pushed by hskupin@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/6f2e61c51d4b
[fxui] Fix test_ssl_disabled_error_page to correctly wait for page load. r=ato
https://hg.mozilla.org/mozilla-central/rev/6f2e61c51d4b
Status: ASSIGNED → RESOLVED
Closed: 11 months ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla63
Even we haven't seen a failure yet for esr60, it would be good to have this test-only patch uplifted. It should apply cleanly.
Whiteboard: [checkin-needed-esr60]
You need to log in before you can comment on or make changes to this bug.