Closed Bug 1582736 Opened 5 years ago Closed 4 years ago

High frequency testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestTLSNavigation.test_deactivation | AssertionError: InsecureCertificateException not raised

Categories

(Testing :: Marionette Client and Harness, defect, P5)

Product:
Testing
Component:
Marionette Client and Harness
Version:
Version 3
Platform:
All
macOS
Type:
defect

Tracking

(firefox-esr78 fixed, firefox81 wontfix, firefox82 fixed)

Status:
RESOLVED FIXED
Milestone:
82 Branch
Tracking Flags:
Tracking Status
firefox-esr78 --- fixed
firefox81 --- wontfix
firefox82 --- fixed

People

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

References

(Regression)

Details

(Keywords: intermittent-failure, regression, Whiteboard: [marionette-fission-mvp][simple])

Attachments

(2 files)

Bug 1582736 - [marionette] Navigation tests of TestTLSNavigation needs to run in their own tab.
47 bytes, text/x-phabricator-request
Details | Review
Bug 1582736 - Open new tab per navigation when testing acceptInsecureCerts
47 bytes, text/x-phabricator-request
Details | Review

Filed by: dvarga [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=267637733&repo=autoland
Full log: https://queue.taskcluster.net/v1/task/bG8E5OPYRN-r2PuievHgLQ/runs/0/artifacts/public/logs/live_backing.log

[task 2019-09-20T12:09:14.517Z] 12:09:14     INFO -  1568981354509	Marionette	DEBUG	Accepted connection 44 from 127.0.0.1:51138
[task 2019-09-20T12:09:14.518Z] 12:09:14     INFO -  1568981354512	Marionette	DEBUG	44 -> [0,1,"WebDriver:NewSession",{"acceptInsecureCerts":false}]
[task 2019-09-20T12:09:14.519Z] 12:09:14     INFO -  1568981354513	Marionette	TRACE	[68] Frame script loaded
[task 2019-09-20T12:09:14.519Z] 12:09:14     INFO -  1568981354513	Marionette	TRACE	[68] Frame script registered
[task 2019-09-20T12:09:14.519Z] 12:09:14     INFO -  1568981354514	Marionette	DEBUG	44 <- [1,1,null,{"sessionId":"e56d2cb7-8dc0-a643-a752-bc31ea0f2fde","capabilities":{"browserName":"firefox","browserVersion":"71.0a ... /T/tmp7h2l0x.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
[task 2019-09-20T12:09:14.523Z] 12:09:14     INFO -  1568981354518	Marionette	DEBUG	44 -> [0,2,"WebDriver:Navigate",{"url":"https://127.0.0.1:50167/test.html"}]
[task 2019-09-20T12:09:14.523Z] 12:09:14     INFO -  1568981354520	Marionette	TRACE	[68] Received DOM event beforeunload for https://127.0.0.1:50167/test.html
[task 2019-09-20T12:09:14.550Z] 12:09:14     INFO -  1568981354529	Marionette	TRACE	[68] Received DOM event pagehide for https://127.0.0.1:50167/test.html
[task 2019-09-20T12:09:14.550Z] 12:09:14     INFO -  1568981354535	Marionette	TRACE	[68] Received DOM event DOMContentLoaded for https://127.0.0.1:50167/test.html
[task 2019-09-20T12:09:14.551Z] 12:09:14     INFO -  1568981354543	Marionette	TRACE	[68] Received DOM event pageshow for https://127.0.0.1:50167/test.html
[task 2019-09-20T12:09:14.551Z] 12:09:14     INFO -  1568981354544	Marionette	DEBUG	44 <- [1,2,null,{"value":null}]
[task 2019-09-20T12:09:14.551Z] 12:09:14     INFO -  1568981354546	Marionette	DEBUG	44 -> [0,3,"WebDriver:DeleteSession",{}]
[task 2019-09-20T12:09:14.555Z] 12:09:14     INFO - TEST-UNEXPECTED-FAIL | testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestTLSNavigation.test_deactivation | AssertionError: InsecureCertificateException not raised
[task 2019-09-20T12:09:14.555Z] 12:09:14     INFO - Traceback (most recent call last):
[task 2019-09-20T12:09:14.555Z] 12:09:14     INFO -   File "/Users/cltbld/tasks/task_1568981137/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 159, in run
[task 2019-09-20T12:09:14.555Z] 12:09:14     INFO -     testMethod()
[task 2019-09-20T12:09:14.555Z] 12:09:14     INFO -   File "/Users/cltbld/tasks/task_1568981137/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py", line 751, in test_deactivation
[task 2019-09-20T12:09:14.555Z] 12:09:14     INFO -     session.navigate(invalid_cert_url)
[task 2019-09-20T12:09:14.555Z] 12:09:14     INFO - TEST-INFO took 296ms
[task 2019-09-20T12:09:14.556Z] 12:09:14     INFO -  1568981354547	Marionette	DEBUG	44 <- [1,3,null,{"value":null}]
[task 2019-09-20T12:09:14.556Z] 12:09:14     INFO -  1568981354549	Marionette	DEBUG	Closed connection 44
[task 2019-09-20T12:09:14.561Z] 12:09:14     INFO -  1568981354556	Marionette	DEBUG	Accepted connection 45 from 127.0.0.1:51140
[task 2019-09-20T12:09:14.562Z] 12:09:14     INFO -  1568981354557	Marionette	DEBUG	45 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2019-09-20T12:09:14.562Z] 12:09:14     INFO -  1568981354558	Marionette	TRACE	[68] Frame script loaded
[task 2019-09-20T12:09:14.562Z] 12:09:14     INFO -  1568981354559	Marionette	TRACE	[68] Frame script registered
[task 2019-09-20T12:09:14.565Z] 12:09:14     INFO -  1568981354560	Marionette	DEBUG	45 <- [1,1,null,{"sessionId":"5bc248c6-1962-1947-829a-0e3d5149dc97","capabilities":{"browserName":"firefox","browserVersion":"71.0a ... /T/tmp7h2l0x.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
[task 2019-09-20T12:09:14.565Z] 12:09:14     INFO -  1568981354562	Marionette	DEBUG	45 -> [0,2,"WebDriver:DeleteSession",{}]
[task 2019-09-20T12:09:14.565Z] 12:09:14     INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestTLSNavigation.test_navigate_by_click
[task 2019-09-20T12:09:14.569Z] 12:09:14     INFO -  1568981354563	Marionette	DEBUG	45 <- [1,2,null,{"value":null}]
[task 2019-09-20T12:09:14.569Z] 12:09:14     INFO -  1568981354564	Marionette	DEBUG	Closed connection 45
[task 2019-09-20T12:09:14.569Z] 12:09:14     INFO -  1568981354564	Marionette	DEBUG	Accepted connection 46 from 127.0.0.1:51141
[task 2019-09-20T12:09:14.570Z] 12:09:14     INFO -  1568981354565	Marionette	DEBUG	46 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2019-09-20T12:09:14.570Z] 12:09:14     INFO -  1568981354569	Marionette	TRACE	[68] Frame script loaded
[task 2019-09-20T12:09:14.574Z] 12:09:14     INFO -  1568981354570	Marionette	TRACE	[68] Frame script registered
[task 2019-09-20T12:09:14.574Z] 12:09:14     INFO -  1568981354570	Marionette	DEBUG	46 <- [1,1,null,{"sessionId":"f3de63b2-66c2-bf41-8a46-eef26e41e8fd","capabilities":{"browserName":"firefox","browserVersion":"71.0a ... /T/tmp7h2l0x.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
[task 2019-09-20T12:09:14.574Z] 12:09:14     INFO -  1568981354571	Marionette	DEBUG	46 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
[task 2019-09-20T12:09:14.574Z] 12:09:14     INFO -  1568981354571	Marionette	DEBUG	46 <- [1,2,null,{"value":null}]
[task 2019-09-20T12:09:14.574Z] 12:09:14     INFO -  1568981354572	Marionette	DEBUG	46 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2019-09-20T12:09:14.577Z] 12:09:14     INFO -  1568981354572	Marionette	DEBUG	46 <- [1,3,null,{"value":null}]
[task 2019-09-20T12:09:14.578Z] 12:09:14     INFO -  1568981354573	Marionette	DEBUG	46 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2019-09-20T12:09:14.578Z] 12:09:14     INFO -  1568981354573	Marionette	DEBUG	46 <- [1,4,null,{"value":null}]
[task 2019-09-20T12:09:14.580Z] 12:09:14     INFO -  1568981354574	Marionette	DEBUG	46 -> [0,5,"WebDriver:DeleteSession",{}]
[task 2019-09-20T12:09:14.580Z] 12:09:14     INFO -  1568981354575	Marionette	DEBUG	46 <- [1,5,null,{"value":null}]
[task 2019-09-20T12:09:14.580Z] 12:09:14     INFO -  1568981354579	Marionette	DEBUG	Accepted connection 47 from 127.0.0.1:51142
[task 2019-09-20T12:09:14.580Z] 12:09:14     INFO -  1568981354579	Marionette	DEBUG	Closed connection 46
[task 2019-09-20T12:09:14.588Z] 12:09:14     INFO -  1568981354580	Marionette	DEBUG	47 -> [0,1,"WebDriver:NewSession",{"acceptInsecureCerts":true}]
[task 2019-09-20T12:09:14.588Z] 12:09:14     INFO -  1568981354580	Marionette	WARN	TLS certificate errors will be ignored for this session
[task 2019-09-20T12:09:14.588Z] 12:09:14     INFO -  1568981354585	Marionette	TRACE	[68] Frame script loaded
[task 2019-09-20T12:09:14.589Z] 12:09:14     INFO -  1568981354586	Marionette	TRACE	[68] Frame script registered

This looks to be MacOS only.

OS: Unspecified → macOS
Hardware: Unspecified → All

Not sure if this could be related to the landing of bug 1577428 about 25 days ago. This failure started only 10 days ago. Also only on MacOS.

Dana, have there been other changes for certificate overrides in the last 10 days, maybe specifically for MacOS?

Flags: needinfo?(dkeeler)

Not that I can think of, no. There was an NSS update around that time: https://hg.mozilla.org/mozilla-central/rev/2f369bea151c (that said, I don't think any of those changes would cause this).
Other changesets that may have caused this:
https://hg.mozilla.org/mozilla-central/rev/0cf57171638c
https://hg.mozilla.org/mozilla-central/rev/aa5fe350630a

Flags: needinfo?(dkeeler)

In failing tests I can see the following page navigation event:

https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=298158159&repo=autoland&lineNumber=20811-20815

[task 2020-04-17T21:04:03.010Z] 21:04:03     INFO -  1587157443007	Marionette	DEBUG	44 -> [0,2,"WebDriver:Navigate",{"url":"https://127.0.0.1:32916/test.html"}]
[task 2020-04-17T21:04:03.017Z] 21:04:03     INFO -  1587157443013	Marionette	TRACE	[68] Received DOM event beforeunload for https://127.0.0.1:32916/test.html
[task 2020-04-17T21:04:03.037Z] 21:04:03     INFO -  1587157443035	Marionette	TRACE	[68] Received DOM event pagehide for https://127.0.0.1:32916/test.html
[task 2020-04-17T21:04:03.078Z] 21:04:03     INFO -  1587157443074	Marionette	TRACE	[68] Received DOM event DOMContentLoaded for https://127.0.0.1:32916/test.html
[task 2020-04-17T21:04:03.099Z] 21:04:03     INFO -  1587157443096	Marionette	TRACE	[68] Received DOM event pageshow for https://127.0.0.1:32916/test.html

And when it's working the following is displayed:

[task 2020-04-20T16:12:10.936Z] 16:12:10     INFO -  1587399130926	Marionette	DEBUG	45 -> [0,2,"WebDriver:Navigate",{"url":"https://127.0.0.1:49337/test.html"}]
[task 2020-04-20T16:12:10.936Z] 16:12:10     INFO -  1587399130931	Marionette	TRACE	[68] Received DOM event beforeunload for https://127.0.0.1:49337/test.html
[task 2020-04-20T16:12:10.957Z] 16:12:10     INFO -  1587399130950	Marionette	TRACE	[68] Received DOM event beforeunload for https://127.0.0.1:49337/test.html
[task 2020-04-20T16:12:10.964Z] 16:12:10     INFO -  1587399130955	Marionette	TRACE	[68] Received DOM event pagehide for https://127.0.0.1:49337/test.html
[task 2020-04-20T16:12:10.999Z] 16:12:10     INFO -  1587399130987	Marionette	TRACE	[68] Received DOM event DOMContentLoaded for about:certerror?e=nssBadCert&u=https%3A//127.0.0.1%3A49337/test.html&c=UTF-8&f=regular&d=%20

It means we do not get an error page displayed in the failing case. Right before those checks we run in unsafe mode, which means that we install our nsICertOverrideService handler, but then remove it. But maybe that somehow fails internally? We don't get an actual error for that in Marionette.

https://searchfox.org/mozilla-central/rev/d2cec90777d573585f8477d5170892e5dcdfb0ab/testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py#733-748

(In reply to Dana Keeler (she/her) (use needinfo) (:keeler for reviews) from comment #5)

Not that I can think of, no. There was an NSS update around that time: https://hg.mozilla.org/mozilla-central/rev/2f369bea151c (that said, I don't think any of those changes would cause this).
Other changesets that may have caused this:
https://hg.mozilla.org/mozilla-central/rev/0cf57171638c
https://hg.mozilla.org/mozilla-central/rev/aa5fe350630a

Also cc'ing Johann in case he has an idea.

Johann, could you please check comment 36? Thanks.

Flags: needinfo?(jhofmann)

Dana, which kind of MOZ_LOG's I would have to use to actually retrieve helpful information to get this failure fixed? Thanks.

Flags: needinfo?(jhofmann) → needinfo?(dkeeler)

pipnss and certverifier, but if the problem is we're not seeing an error, I don't know how helpful those will be.

Flags: needinfo?(dkeeler)

This fails with a high frequency: https://treeherder.mozilla.org/#/jobs?repo=autoland&searchStr=os%2Cx%2C10.14%2Copt%2Ctest-macosx1014-64%2Fopt-marionette-e10s%2Cmn&tochange=d281ed9906a8f0e143239e31a1afad48f6c96617&fromchange=14b95c9e82c48adb34edddad5b203a4b83d3b8d5&selectedTaskRun=B5rywlmJTN2s_cbAN5XmHg.0

Summary: Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestTLSNavigation.test_deactivation | AssertionError: InsecureCertificateException not raised → High frequency testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestTLSNavigation.test_deactivation | AssertionError: InsecureCertificateException not raised

Because TestTLSNavigation is not based off BaseNavigationTestCase
each of its tests is run inside the initial tab. This could cause
bad interactions between tests and should be avoided.

Assignee: nobody → hskupin
Status: NEW → ASSIGNED

I just attached a first patch which might help here in regards the amount of intermittent failures. At least that's what I hope for. By running each o the tests in their own tab we have test isolation, which was not the case before.

Keywords: leave-open

Interestingly the patch on bug 1493108 made the failure to happen way more often.

Regressed by: 1493108
Pushed by hskupin@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/ae1e1eca3f54
[marionette] Navigation tests of TestTLSNavigation needs to run in their own tab. r=marionette-reviewers,maja_zf

The frequency remained on the same level.

Flags: needinfo?(hskupin)

Maja, while I'm away would you mind checking if running each of the navigation commands in a separate tab would help here? Maybe there is some kind of bfcache issue causing this problem when running it all in the same tab.

Flags: needinfo?(hskupin) → needinfo?(mjzffr)
Pushed by mjzffr@gmail.com:
https://hg.mozilla.org/integration/autoland/rev/cc64d4bc6baa
Open new tab per navigation when testing acceptInsecureCerts r=marionette-reviewers,jgraham
See Also: → 1665981

Thanks Maja for getting this fixed! As it looks like this works for now.

Dana, could you imagine that there is a race when enabling/disabling certificate overrides while loading the same URL multiple times in a row with cert checks enabled/disabled in the same tab? Maybe a problem with BFCache or such? Right now we worked around the problem by loading each page always in a new tab. I'm happy to file a new bug to get it further investigated if needed.

Assignee: hskupin → mjzffr
Status: ASSIGNED → RESOLVED
Closed: 4 years ago
status-firefox81: affected → unaffected
status-firefox82: affected → fixed
Flags: needinfo?(dkeeler)
Keywords: leave-open
Resolution: --- → FIXED
Whiteboard: [marionette-fission-mvp][simple]
Target Milestone: --- → 82 Branch
No longer blocks: 1658384

I don't know enough about BFCache to know if that's happening.

Flags: needinfo?(dkeeler)

Ryan, why has the revision for Open new tab per navigation when testing acceptInsecureCerts been reopened in Phabricator?

Flags: needinfo?(ryanvm)

This got backed out from esr78 for TestTLSNavigation failures:

https://hg.mozilla.org/releases/mozilla-esr78/rev/2ae7761ced3111cac22d9c1986e5dd100adebb04

Push with failures: https://treeherder.mozilla.org/#/jobs?repo=mozilla-esr78&resultStatus=testfailed%2Cbusted%2Cexception&revision=eaed3647025cf1f48228df545d78590c67f3635e
Failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=316767167&repo=mozilla-esr78

TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestTLSNavigation.test_deactivation | AttributeError: 'TestTLSNavigation' object has no attribute 'close_all_tabs'

status-firefox-esr78: fixed → affected
Flags: needinfo?(mjzffr)

Turns out it helps if you uplift both patches from the bug instead of just the last one. Sorry for the hassle and noise. 🤦‍♂️

Flags: needinfo?(ryanvm)
Flags: needinfo?(mjzffr)

\o/ I'm glad that I procrastinated with this n-i ;)
Thanks, Ryan.

Has Regression Range: --- → yes
Product: Testing → Remote Protocol
Moving bug to Testing::Marionette Client and Harness component per bug 1815831.
Component: Marionette → Marionette Client and Harness
Product: Remote Protocol → Testing
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: