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)
Tracking
(firefox-esr78 unaffected, firefox82 wontfix, firefox83 wontfix, firefox84 fixed)
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
[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
Comment hidden (Intermittent Failures Robot) |
Comment 2•5 years ago
|
||
Comment 3•3 years ago
|
||
New occurrence: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=316741197&repo=autoland&lineNumber=23450
Assignee | ||
Updated•3 years ago
|
Comment hidden (Intermittent Failures Robot) |
Assignee | ||
Comment 5•3 years ago
|
||
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.
Assignee | ||
Comment 6•3 years ago
|
||
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
.
I cannot reproduce this with actors enabled.
Assignee | ||
Comment 8•3 years ago
|
||
This is without actors. Actors don't work in CI yet. See the intermittent view.
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.
Assignee | ||
Comment 10•3 years ago
|
||
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?
Comment hidden (Intermittent Failures Robot) |
Yep, I see an intermittent hang locally at GetCurrentURL
. I'll poke around a bit and get back to you.
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Assignee | ||
Comment 15•3 years ago
|
||
Handling the AbortError
for the actor implementation should also fix it.
Comment hidden (Intermittent Failures Robot) |
Assignee | ||
Comment 17•3 years ago
|
||
We are going to enable actors for Fission jobs most likely tomorrow. Lets revisit this failure by early next week.
Comment hidden (Intermittent Failures Robot) |
Assignee | ||
Comment 19•3 years ago
|
||
This failure has indeed been fixed by my patch on bug 1660168.
Updated•3 years ago
|
Updated•2 years ago
|
Updated•10 months ago
|
Comment 20•10 months ago
|
||
Moving bug to Testing::Marionette Client and Harness component per bug 1815831.
Description
•