Closed Bug 1532589 Opened 5 years ago Closed 3 years ago

Intermittent [tier2] Mn-fis testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestPageLoadStrategy.test_none | IOError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors

Categories

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

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

Tracking

(firefox-esr78 unaffected, firefox82 wontfix, firefox83 wontfix, firefox84 fixed)

Status:
RESOLVED FIXED
Tracking Flags:
Tracking Status
firefox-esr78 --- unaffected
firefox82 --- wontfix
firefox83 --- wontfix
firefox84 --- fixed

People

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

References

(Regression)

Details

(Keywords: intermittent-failure, regression)

#[markdown(off)]
Filed by: btara [at] mozilla.com

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

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

[task 2019-03-05T11:11:39.332Z] 11:11:39 INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestPageLoadStrategy.test_none
[task 2019-03-05T11:11:39.336Z] 11:11:39 INFO - 1551784299328 Marionette DEBUG 22 <- [1,12,null,{"value":null}]
[task 2019-03-05T11:11:39.337Z] 11:11:39 INFO - 1551784299334 Marionette DEBUG Closed connection 22
[task 2019-03-05T11:11:39.337Z] 11:11:39 INFO - 1551784299335 Marionette DEBUG Accepted connection 23 from 127.0.0.1:33992
[task 2019-03-05T11:11:39.341Z] 11:11:39 INFO - 1551784299338 Marionette DEBUG 23 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2019-03-05T11:11:39.342Z] 11:11:39 INFO - 1551784299340 Marionette TRACE [30064771073] Frame script loaded
[task 2019-03-05T11:11:39.343Z] 11:11:39 INFO - 1551784299341 Marionette TRACE [30064771073] Frame script registered
[task 2019-03-05T11:11:39.347Z] 11:11:39 INFO - 1551784299343 Marionette DEBUG 23 <- [1,1,null,{"sessionId":"d5422bde-05a6-4ab0-80ba-753220ce7519","capabilities":{"browserName":"firefox","browserVersion":"67.0a ... mp/tmpsOkK0V.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
[task 2019-03-05T11:11:39.347Z] 11:11:39 INFO - 1551784299345 Marionette DEBUG 23 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
[task 2019-03-05T11:11:39.347Z] 11:11:39 INFO - 1551784299346 Marionette DEBUG 23 <- [1,2,null,{"value":null}]
[task 2019-03-05T11:11:39.351Z] 11:11:39 INFO - 1551784299348 Marionette DEBUG 23 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2019-03-05T11:11:39.352Z] 11:11:39 INFO - 1551784299349 Marionette DEBUG 23 <- [1,3,null,{"value":null}]
[task 2019-03-05T11:11:39.353Z] 11:11:39 INFO - 1551784299350 Marionette DEBUG 23 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2019-03-05T11:11:39.353Z] 11:11:39 INFO - 1551784299350 Marionette DEBUG 23 <- [1,4,null,{"value":null}]
[task 2019-03-05T11:11:39.354Z] 11:11:39 INFO - 1551784299352 Marionette DEBUG 23 -> [0,5,"WebDriver:GetChromeWindowHandle",{}]
[task 2019-03-05T11:11:39.356Z] 11:11:39 INFO - 1551784299353 Marionette DEBUG 23 <- [1,5,null,{"value":"1"}]
[task 2019-03-05T11:11:39.359Z] 11:11:39 INFO - 1551784299356 Marionette DEBUG 23 -> [0,6,"WebDriver:GetChromeWindowHandles",{}]
[task 2019-03-05T11:11:39.360Z] 11:11:39 INFO - 1551784299357 Marionette DEBUG 23 <- [1,6,null,["1"]]
[task 2019-03-05T11:11:39.361Z] 11:11:39 INFO - 1551784299358 Marionette DEBUG 23 -> [0,7,"WebDriver:GetWindowHandle",{}]
[task 2019-03-05T11:11:39.362Z] 11:11:39 INFO - 1551784299358 Marionette DEBUG 23 <- [1,7,null,{"value":"30064771073"}]
[task 2019-03-05T11:11:39.370Z] 11:11:39 INFO - 1551784299362 Marionette DEBUG 23 -> [0,8,"WebDriver:GetWindowHandles",{}]
[task 2019-03-05T11:11:39.370Z] 11:11:39 INFO - 1551784299363 Marionette DEBUG 23 <- [1,8,null,["30064771073"]]
[task 2019-03-05T11:11:39.371Z] 11:11:39 INFO - 1551784299364 Marionette DEBUG 23 -> [0,9,"WebDriver:GetWindowHandles",{}]
[task 2019-03-05T11:11:39.371Z] 11:11:39 INFO - 1551784299364 Marionette DEBUG 23 <- [1,9,null,["30064771073"]]
[task 2019-03-05T11:11:39.371Z] 11:11:39 INFO - 1551784299365 Marionette DEBUG 23 -> [0,10,"WebDriver:NewWindow",{"type":"tab","focus":false}]
[task 2019-03-05T11:11:39.386Z] 11:11:39 INFO - 1551784299380 Marionette TRACE [8589934654] Frame script loaded
[task 2019-03-05T11:11:39.387Z] 11:11:39 INFO - 1551784299381 Marionette TRACE Received DOM event TabOpen for [object XULElement]
[task 2019-03-05T11:11:39.427Z] 11:11:39 INFO - 1551784299419 Marionette TRACE [8589934654] Frame script registered
[task 2019-03-05T11:11:39.435Z] 11:11:39 INFO - 1551784299430 Marionette DEBUG 23 <- [1,10,null,{"handle":"8589934654","type":"tab"}]
[task 2019-03-05T11:11:39.436Z] 11:11:39 INFO - 1551784299431 Marionette DEBUG 23 -> [0,11,"WebDriver:GetWindowHandles",{}]
[task 2019-03-05T11:11:39.437Z] 11:11:39 INFO - 1551784299432 Marionette DEBUG 23 <- [1,11,null,["30064771073","8589934654"]]
[task 2019-03-05T11:11:39.438Z] 11:11:39 INFO - 1551784299433 Marionette DEBUG 23 -> [0,12,"WebDriver:GetWindowHandles",{}]
[task 2019-03-05T11:11:39.439Z] 11:11:39 INFO - 1551784299434 Marionette DEBUG 23 <- [1,12,null,["30064771073","8589934654"]]
[task 2019-03-05T11:11:39.440Z] 11:11:39 INFO - 1551784299436 Marionette DEBUG 23 -> [0,13,"WebDriver:SwitchToWindow",{"focus":true,"name":"8589934654"}]
[task 2019-03-05T11:11:39.456Z] 11:11:39 INFO - 1551784299449 Marionette DEBUG 23 <- [1,13,null,{"value":null}]
[task 2019-03-05T11:11:39.472Z] 11:11:39 INFO - 1551784299462 Marionette DEBUG 23 -> [0,14,"WebDriver:GetTimeouts",{}]
[task 2019-03-05T11:11:39.473Z] 11:11:39 INFO - 1551784299462 Marionette DEBUG 23 <- [1,14,null,{"implicit":0,"pageLoad":300000,"script":30000}]
[task 2019-03-05T11:11:39.474Z] 11:11:39 INFO - 1551784299463 Marionette DEBUG 23 -> [0,15,"WebDriver:ExecuteScript",{"script":"return window.history.length;","newSandbox":true,"args":[],"filename":"tests/testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py","sandbox":"default","line":74}]
[task 2019-03-05T11:11:39.476Z] 11:11:39 INFO - 1551784299465 Marionette DEBUG 23 <- [1,15,null,{"value":1}]
[task 2019-03-05T11:11:39.477Z] 11:11:39 INFO - 1551784299466 Marionette DEBUG 23 -> [0,16,"WebDriver:DeleteSession",{}]
[task 2019-03-05T11:11:39.478Z] 11:11:39 INFO - 1551784299467 Marionette DEBUG 23 <- [1,16,null,{"value":null}]
[task 2019-03-05T11:11:39.480Z] 11:11:39 INFO - 1551784299469 Marionette DEBUG Closed connection 23
[task 2019-03-05T11:11:39.481Z] 11:11:39 INFO - 1551784299469 Marionette DEBUG Accepted connection 24 from 127.0.0.1:33994
[task 2019-03-05T11:11:39.482Z] 11:11:39 INFO - 1551784299477 Marionette DEBUG 24 -> [0,1,"WebDriver:NewSession",{"pageLoadStrategy":"none"}]
[task 2019-03-05T11:11:39.483Z] 11:11:39 INFO - 1551784299479 Marionette TRACE [30064771073] Frame script loaded
[task 2019-03-05T11:11:39.484Z] 11:11:39 INFO - 1551784299481 Marionette TRACE [30064771073] Frame script registered
[task 2019-03-05T11:11:39.487Z] 11:11:39 INFO - 1551784299483 Marionette TRACE [8589934654] Frame script loaded
[task 2019-03-05T11:11:39.488Z] 11:11:39 INFO - 1551784299485 Marionette TRACE [8589934654] Frame script registered
[task 2019-03-05T11:11:39.496Z] 11:11:39 INFO - 1551784299488 Marionette DEBUG 24 <- [1,1,null,{"sessionId":"ce8fc18b-4047-4861-8f58-a6d96101cbaa","capabilities":{"browserName":"firefox","browserVersion":"67.0a ... mp/tmpsOkK0V.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
[task 2019-03-05T11:11:39.497Z] 11:11:39 INFO - 1551784299492 Marionette DEBUG 24 -> [0,2,"WebDriver:Navigate",{"url":"http://127.0.0.1:32999/slow_resource.html"}]
[task 2019-03-05T11:11:39.512Z] 11:11:39 INFO - 1551784299508 Marionette DEBUG 24 <- [1,2,null,{"value":null}]
[task 2019-03-05T11:11:39.513Z] 11:11:39 INFO - 1551784299510 Marionette DEBUG 24 -> [0,3,"WebDriver:DeleteSession",{}]
[task 2019-03-05T11:11:39.513Z] 11:11:39 INFO - 1551784299512 Marionette DEBUG 24 <- [1,3,null,{"value":null}]
[task 2019-03-05T11:11:39.517Z] 11:11:39 INFO - 1551784299515 Marionette DEBUG Accepted connection 25 from 127.0.0.1:33998
[task 2019-03-05T11:11:39.519Z] 11:11:39 INFO - 1551784299515 Marionette DEBUG Closed connection 24
[task 2019-03-05T11:11:39.520Z] 11:11:39 INFO - 1551784299517 Marionette DEBUG 25 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2019-03-05T11:11:39.521Z] 11:11:39 INFO - 1551784299519 Marionette TRACE [30064771073] Frame script loaded
[task 2019-03-05T11:11:39.525Z] 11:11:39 INFO - 1551784299522 Marionette TRACE [8589934654] Frame script loaded
[task 2019-03-05T11:11:39.528Z] 11:11:39 INFO - 1551784299526 Marionette TRACE [30064771073] Frame script registered
[task 2019-03-05T11:11:39.530Z] 11:11:39 INFO - 1551784299526 Marionette TRACE [8589934654] Frame script registered
[task 2019-03-05T11:11:39.531Z] 11:11:39 INFO - 1551784299527 Marionette DEBUG 25 <- [1,1,null,{"sessionId":"93e0af2c-08d4-4831-8f38-bc130d35b644","capabilities":{"browserName":"firefox","browserVersion":"67.0a ... mp/tmpsOkK0V.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
[task 2019-03-05T11:11:39.533Z] 11:11:39 INFO - 1551784299530 Marionette DEBUG 25 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
[task 2019-03-05T11:11:39.535Z] 11:11:39 INFO - 1551784299531 Marionette DEBUG 25 <- [1,2,null,{"value":null}]
[task 2019-03-05T11:11:39.536Z] 11:11:39 INFO - 1551784299532 Marionette DEBUG 25 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2019-03-05T11:11:39.538Z] 11:11:39 INFO - 1551784299532 Marionette DEBUG 25 <- [1,3,null,{"value":null}]
[task 2019-03-05T11:11:39.540Z] 11:11:39 INFO - 1551784299533 Marionette DEBUG 25 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2019-03-05T11:11:39.541Z] 11:11:39 INFO - 1551784299533 Marionette DEBUG 25 <- [1,4,null,{"value":null}]
[task 2019-03-05T11:11:39.545Z] 11:11:39 INFO - 1551784299539 Marionette DEBUG 25 -> [0,5,"WebDriver:SwitchToParentFrame",{}]
[task 2019-03-05T11:11:39.646Z] 11:11:39 INFO - 1551784299644 Marionette TRACE [38654705665] Frame script loaded
[task 2019-03-05T11:11:39.662Z] 11:11:39 INFO - 1551784299656 Marionette TRACE [38654705665] Frame script registered
[task 2019-03-05T11:17:39.624Z] 11:17:39 INFO - 1551784659619 Marionette DEBUG Closed connection 25
[task 2019-03-05T11:18:50.692Z] 11:18:50 INFO - TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestPageLoadStrategy.test_none | IOError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors (Reason: Connection timed out after 360.0s)
[task 2019-03-05T11:18:50.693Z] 11:18:50 INFO - Traceback (most recent call last):
[task 2019-03-05T11:18:50.693Z] 11:18:50 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_harness/marionette_test/testcases.py", line 190, in run
[task 2019-03-05T11:18:50.694Z] 11:18:50 INFO - self.tearDown()
[task 2019-03-05T11:18:50.694Z] 11:18:50 INFO - File "/builds/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py", line 769, in tearDown
[task 2019-03-05T11:18:50.694Z] 11:18:50 INFO - super(TestPageLoadStrategy, self).tearDown()
[task 2019-03-05T11:18:50.695Z] 11:18:50 INFO - File "/builds/worker/workspace/build/tests/marionette/tests/testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py", line 66, in tearDown
[task 2019-03-05T11:18:50.695Z] 11:18:50 INFO - self.marionette.switch_to_parent_frame()
[task 2019-03-05T11:18:50.696Z] 11:18:50 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 1544, in switch_to_parent_frame
[task 2019-03-05T11:18:50.697Z] 11:18:50 INFO - self._send_message("WebDriver:SwitchToParentFrame")
[task 2019-03-05T11:18:50.697Z] 11:18:50 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 36, in _
[task 2019-03-05T11:18:50.697Z] 11:18:50 INFO - m._handle_socket_failure()
[task 2019-03-05T11:18:50.699Z] 11:18:50 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 849, in _handle_socket_failure
[task 2019-03-05T11:18:50.699Z] 11:18:50 INFO - reraise(IOError, message.format(returncode=returncode, reason=val), tb)
[task 2019-03-05T11:18:50.700Z] 11:18:50 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/decorators.py", line 26, in _
[task 2019-03-05T11:18:50.700Z] 11:18:50 INFO - return func(*args, **kwargs)
[task 2019-03-05T11:18:50.701Z] 11:18:50 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/marionette.py", line 761, in _send_message
[task 2019-03-05T11:18:50.702Z] 11:18:50 INFO - msg = self.client.request(name, params)
[task 2019-03-05T11:18:50.702Z] 11:18:50 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/transport.py", line 273, in request
[task 2019-03-05T11:18:50.703Z] 11:18:50 INFO - return self.receive()
[task 2019-03-05T11:18:50.704Z] 11:18:50 INFO - File "/builds/worker/workspace/build/venv/lib/python2.7/site-packages/marionette_driver/transport.py", line 183, in receive
[task 2019-03-05T11:18:50.704Z] 11:18:50 INFO - raise socket.timeout("Connection timed out after {}s".format(self.socket_timeout))
[task 2019-03-05T11:18:50.705Z] 11:18:50 INFO - TEST-INFO took 431359ms

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup

Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → INCOMPLETE

New occurrence: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=316741197&repo=autoland&lineNumber=23450

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Summary: Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestPageLoadStrategy.test_none | IOError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors (Reason: Connection timed out → Intermittent [tier2] Mn-fis testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestPageLoadStrategy.test_none | IOError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors

The failures as happened since Friday are caused by my patch on bug 1667377, and all depend on a fix for bug 1519354, or an earlier fix for bug 1664881.

status-firefox83: --- → affected
Depends on: 1519354, 1664881
Regressed by: 1667377

It would be good to know how this actually behaves with the actors enabled. Maja, is that something you could have a look at? If it also hangs we have to get bug 1519354 fixed, and get it nominated for marionette-fission-mvp.

Flags: needinfo?(mjzffr)

I cannot reproduce this with actors enabled.

Flags: needinfo?(mjzffr)

This is without actors. Actors don't work in CI yet. See the intermittent view.

Flags: needinfo?(mjzffr)

Your original need-info sounds like a request to check whether this also fails with actors enabled:

It would be good to know how this actually behaves with the actors enabled. Maja, is that something you could have a look at?

I'm going to guess that you're actually asking whether I can investigate this intermittent in general: sure, I'll add it to my backlog for next week.

Flags: needinfo?(mjzffr)

Yes, sorry. It was misleading.

So where you actually able to see the hang (without actors) yourself? If yes, is is reproducible?

The problem actually comes from:

[task 2020-09-27T18:44:47.495Z] 18:44:47     INFO -  1601232287494	Marionette	DEBUG	27 -> [0,4,"WebDriver:GetCurrentURL",{}]
[task 2020-09-27T18:44:47.497Z] 18:44:47     INFO -  1601232287496	Marionette	TRACE	[90] Frame script unloaded
[task 2020-09-27T18:44:47.505Z] 18:44:47     INFO -  [Child 7124, Main Thread] WARNING: NS_ENSURE_TRUE(browserChrome) failed: file /builds/worker/checkouts/gecko/docshell/base/nsDocShell.cpp, line 12022
[task 2020-09-27T18:44:47.513Z] 18:44:47     INFO -  1601232287507	Marionette	TRACE	[90] Frame script loaded
[task 2020-09-27T18:44:47.530Z] 18:44:47     INFO -  1601232287517	Marionette	TRACE	Detected remoteness change. New browsing context: 90

Maybe we should try to get bug 1664881 implemented, and maybe skip the test with Fission for now?

Yep, I see an intermittent hang locally at GetCurrentURL. I'll poke around a bit and get back to you.

Handling the AbortError for the actor implementation should also fix it.

Status: REOPENED → NEW
Depends on: 1671347

We are going to enable actors for Fission jobs most likely tomorrow. Lets revisit this failure by early next week.

Depends on: 1660168
Flags: needinfo?(mjzffr)

This failure has indeed been fixed by my patch on bug 1660168.

Assignee: nobody → hskupin
Status: NEW → RESOLVED
Closed: 5 years ago → 3 years ago
status-firefox83: affected → wontfix
status-firefox84: --- → fixed
Resolution: --- → FIXED
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.