1736147 - High frequency testing/marionette/harness/marionette_harness/tests/unit/test_marionette.py TestMarionette.test_single_active_session | AssertionError: 1 != None

Status: RESOLVED FIXED

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

Description

[Treeherder Bug Filer]

Filed by: ccozmuta [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=354998107&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/eShKqHJZSaKYZqPqrx2iPQ/runs/0/artifacts/public/logs/live_backing.log

---

[task 2021-10-16T10:34:01.818Z] 10:34:01     INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_marionette.py TestMarionette.test_single_active_session
[task 2021-10-16T10:34:01.819Z] 10:34:01     INFO -  1634380441818	Marionette	DEBUG	Accepted connection 2 from 127.0.0.1:49346
[task 2021-10-16T10:34:01.819Z] 10:34:01     INFO -  1634380441819	Marionette	DEBUG	2 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2021-10-16T10:34:01.821Z] 10:34:01     INFO -  1634380441821	Marionette	DEBUG	2 <- [1,1,null,{"sessionId":"84f4903f-57cf-4b3c-84bd-76a2b08ff17b","capabilities":{"browserName":"firefox","browserVersion":"95.0a ... i.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"proxy":{}}}]
[task 2021-10-16T10:34:01.822Z] 10:34:01     INFO -  1634380441821	Marionette	DEBUG	2 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
[task 2021-10-16T10:34:01.822Z] 10:34:01     INFO -  1634380441822	Marionette	DEBUG	2 <- [1,2,null,{"value":null}]
[task 2021-10-16T10:34:01.823Z] 10:34:01     INFO -  1634380441822	Marionette	DEBUG	2 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2021-10-16T10:34:01.823Z] 10:34:01     INFO -  1634380441822	Marionette	DEBUG	2 <- [1,3,null,{"value":null}]
[task 2021-10-16T10:34:01.823Z] 10:34:01     INFO -  1634380441823	Marionette	DEBUG	2 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2021-10-16T10:34:01.823Z] 10:34:01     INFO -  1634380441823	Marionette	DEBUG	2 <- [1,4,null,{"value":null}]
[task 2021-10-16T10:34:01.825Z] 10:34:01     INFO -  1634380441824	Marionette	DEBUG	2 -> [0,5,"WebDriver:ExecuteScript",{"script":"return 1","args":[],"newSandbox":true,"sandbox":"default","line":59,"filename":"tests/testing/marionette/harness/marionette_harness/tests/unit/test_marionette.py"}]
[task 2021-10-16T10:34:01.863Z] 10:34:01     INFO -  1634380441862	Marionette	TRACE	[19] MarionetteCommands actor created for window id 12
[task 2021-10-16T10:34:01.870Z] 10:34:01     INFO -  1634380441870	Marionette	DEBUG	2 <- [1,5,null,{"value":null}]
[task 2021-10-16T10:34:01.880Z] 10:34:01     INFO -  1634380441879	Marionette	DEBUG	2 -> [0,6,"Marionette:GetContext",{}]
[task 2021-10-16T10:34:01.880Z] 10:34:01     INFO -  1634380441880	Marionette	DEBUG	2 <- [1,6,null,{"value":"content"}]
[task 2021-10-16T10:34:01.880Z] 10:34:01     INFO -  1634380441880	Marionette	DEBUG	2 -> [0,7,"Marionette:SetContext",{"value":"chrome"}]
[task 2021-10-16T10:34:01.881Z] 10:34:01     INFO -  1634380441880	Marionette	DEBUG	2 <- [1,7,null,{"value":null}]
[task 2021-10-16T10:34:01.881Z] 10:34:01     INFO -  1634380441881	Marionette	DEBUG	2 -> [0,8,"WebDriver:TakeScreenshot",{"id":null,"full":true,"hash":false,"scroll":true}]
[task 2021-10-16T10:34:01.882Z] 10:34:01     INFO -  1634380441882	Marionette	TRACE	[16] MarionetteCommands actor created for window id 4
[task 2021-10-16T10:34:01.948Z] 10:34:01     INFO -  1634380441947	Marionette	DEBUG	2 <- [1,8,null,{"value":"iVBORw0KGgoAAAANSUhEUgAABQAAAAPNCAYAAADWQsenAAAgAElEQVR4nOy9aVRUZ8Ku3T/PWie9zvkBa6X5I+85y279VsjX3XpePUlO/ ... AAAADGBCAAAAAAjAlAAAAAABgTgAAAAAAwJgABAAAAYEwAAgAAAMCYAAQAAACAMQEIAAAAAGMCEAAAAADGBCAAAAAAjAW/ULxLiOZ4CwAAAABJRU5ErkJggg=="}]
[task 2021-10-16T10:34:01.953Z] 10:34:01     INFO -  1634380441953	Marionette	DEBUG	2 -> [0,9,"Marionette:SetContext",{"value":"content"}]
[task 2021-10-16T10:34:01.954Z] 10:34:01     INFO -  1634380441953	Marionette	DEBUG	2 <- [1,9,null,{"value":null}]
[task 2021-10-16T10:34:01.954Z] 10:34:01     INFO -  1634380441954	Marionette	DEBUG	2 -> [0,10,"Marionette:GetContext",{}]
[task 2021-10-16T10:34:01.954Z] 10:34:01     INFO -  1634380441954	Marionette	DEBUG	2 <- [1,10,null,{"value":"content"}]
[task 2021-10-16T10:34:01.955Z] 10:34:01     INFO -  1634380441954	Marionette	DEBUG	2 -> [0,11,"Marionette:SetContext",{"value":"content"}]
[task 2021-10-16T10:34:01.955Z] 10:34:01     INFO -  1634380441955	Marionette	DEBUG	2 <- [1,11,null,{"value":null}]
[task 2021-10-16T10:34:01.956Z] 10:34:01     INFO -  1634380441955	Marionette	DEBUG	2 -> [0,12,"WebDriver:GetPageSource",{}]
[task 2021-10-16T10:34:01.956Z] 10:34:01     INFO -  1634380441956	Marionette	TRACE	[19] MarionetteCommands actor created for window id 4294967297
[task 2021-10-16T10:34:01.957Z] 10:34:01     INFO -  1634380441956	Marionette	DEBUG	2 <- [1,12,null,{"value":"<html><head></head><body></body></html>"}]
[task 2021-10-16T10:34:01.957Z] 10:34:01     INFO -  1634380441957	Marionette	DEBUG	2 -> [0,13,"Marionette:SetContext",{"value":"content"}]
[task 2021-10-16T10:34:01.957Z] 10:34:01     INFO -  1634380441957	Marionette	DEBUG	2 <- [1,13,null,{"value":null}]
[task 2021-10-16T10:34:01.987Z] 10:34:01     INFO - TEST-UNEXPECTED-FAIL | testing/marionette/harness/marionette_harness/tests/unit/test_marionette.py TestMarionette.test_single_active_session | AssertionError: 1 != None
[task 2021-10-16T10:34:01.987Z] 10:34:01     INFO - Traceback (most recent call last):
[task 2021-10-16T10:34:01.987Z] 10:34:01     INFO -   File "/opt/worker/tasks/task_163438036645133/build/venv/lib/python3.7/site-packages/marionette_harness/marionette_test/testcases.py", line 202, in run
[task 2021-10-16T10:34:01.987Z] 10:34:01     INFO -     testMethod()
[task 2021-10-16T10:34:01.987Z] 10:34:01     INFO -   File "/opt/worker/tasks/task_163438036645133/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_marionette.py", line 59, in test_single_active_session
[task 2021-10-16T10:34:01.987Z] 10:34:01     INFO -     self.assertEqual(1, self.marionette.execute_script("return 1"))
[task 2021-10-16T10:34:01.987Z] 10:34:01     INFO - TEST-INFO took 139ms
[task 2021-10-16T10:34:01.987Z] 10:34:01     INFO -  1634380441959	Marionette	DEBUG	2 -> [0,14,"WebDriver:DeleteSession",{}]
[task 2021-10-16T10:34:01.988Z] 10:34:01     INFO -  1634380441959	Marionette	DEBUG	2 <- [1,14,null,{"value":null}]
[task 2021-10-16T10:34:01.988Z] 10:34:01     INFO -  1634380441960	Marionette	DEBUG	Closed connection 2
[task 2021-10-16T10:34:01.988Z] 10:34:01     INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_report.py TestReport.test_pass

Comment 1

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

As it looks like the landing of https://treeherder.mozilla.org/jobs?repo=autoland&searchStr=mn&revision=b0ea805e58e7c711b0494d644e936932dccdd4d7 has caused this particular failure.

It's also the Execute Script function which is affected. It's run right after startup of Firefox so we might hit the same problem as what we have seen before in Wd2 headless jobs. Note that the test as run before has also just been landed (bug 1735162) so that we haven't seen the failure before.

As such I think that we should really check or await the final completion state of an ongoing page load of the very first tab in Marionette when starting a new session.

Comment 2

[Intermittent Failures Robot]

17 failures in 3315 pushes (0.005 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 13
• mozilla-central: 2
• try: 2

Platform and build breakdown:

• macosx1015-64-qr: 13
  • opt: 13
• macosx1015-64-shippable-qr: 3
  • opt: 3
• macosx1015-64-devedition-qr: 1
  • opt: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1736147&startday=2021-10-11&endday=2021-10-17&tree=all

Comment 3

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

Requires bug 1736323 to be fixed.

Comment 4

[Intermittent Failures Robot]

16 failures in 3186 pushes (0.005 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• autoland: 6
• mozilla-central: 3
• try: 7

Platform and build breakdown:

• macosx1015-64-qr: 6
  • opt: 6
• macosx1015-64-shippable-qr: 8
  • opt: 8
• macosx1015-64-devedition-qr: 2
  • opt: 2

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1736147&startday=2021-10-18&endday=2021-10-24&tree=all

Comment 5

[Intermittent Failures Robot]

7 failures in 2845 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 7

Platform and build breakdown:

• macosx1015-64-devedition-qr: 4
  • opt: 4
• macosx1015-64-shippable-qr: 3
  • opt: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1736147&startday=2021-10-25&endday=2021-10-31&tree=all

Comment 6

[Intermittent Failures Robot]

26 failures in 3030 pushes (0.009 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• try: 6
• mozilla-beta: 20

Platform and build breakdown:

• macosx1015-64-shippable-qr: 13
  • opt: 13
• macosx1015-64-devedition-qr: 13
  • opt: 13

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1736147&startday=2021-11-01&endday=2021-11-07&tree=all

Comment 7

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

This is fixed on mozilla-central but still affected on beta. It needs the upcoming fix from bug 1739008.

Comment 8

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

(In reply to Henrik Skupin (:whimboo) [⌚️UTC+1] from comment #7)

This is fixed on mozilla-central but still affected on beta. It needs the upcoming fix from bug 1739008.

Well, my patch from bug 1736323 didn't land on beta yet. As such this is still occurring on beta. We will uplift the patches soon.

Comment 9

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

The fix from bug 1736323 got uplifted to beta as:
https://hg.mozilla.org/releases/mozilla-beta/rev/d76cabaec0c1

Comment 10

[Intermittent Failures Robot]

11 failures in 2723 pushes (0.004 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-beta: 11

Platform and build breakdown:

• macosx1015-64-devedition-qr: 5
  • opt: 5
• macosx1015-64-shippable-qr: 6
  • opt: 6

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1736147&startday=2021-11-08&endday=2021-11-14&tree=all

Comment 11

[BMO Automation]

Moving bug to Testing::Marionette Client and Harness component per bug 1815831.