Closed
Bug 1692370
Opened 5 years ago
Closed 5 years ago
Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestNavigate.test_type_to_non_remote_tab | IOError: Process killed because the connection to Marionette server is lost [Hang in Wait.until()]
Categories
(Testing :: Marionette Client and Harness, defect, P5)
Testing
Marionette Client and Harness
Tracking
(Not tracked)
RESOLVED
INCOMPLETE
People
(Reporter: intermittent-bug-filer, Unassigned)
Details
(Keywords: intermittent-failure)
Filed by: apavel [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=329703044&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/Z8-O5SbSTOCg69uUOHwHPw/runs/0/artifacts/public/logs/live_backing.log
[task 2021-02-11T23:08:40.260Z] 23:08:40 INFO - testing boolean attribute <video loop>
[task 2021-02-11T23:08:40.267Z] 23:08:40 INFO - 1613084920247 Marionette DEBUG 233 <- [1,58,null,{"value":"true"}]
[task 2021-02-11T23:08:40.267Z] 23:08:40 INFO - 1613084920248 Marionette DEBUG 233 -> [0,59,"WebDriver:Navigate",{"url":"data:text/html;charset=utf-8,%3Cvideo%20loop%3E"}]
[task 2021-02-11T23:08:40.267Z] 23:08:40 INFO - 1613084920250 Marionette TRACE Received event beforeunload for data:text/html;charset=utf-8,%3Cvideo%20controls%3E
[task 2021-02-11T23:08:40.267Z] 23:08:40 INFO - 1613084920253 Marionette TRACE Received event pagehide for data:text/html;charset=utf-8,%3Cvideo%20controls%3E
[task 2021-02-11T23:08:40.274Z] 23:08:40 INFO - DEBUG: Adding blocker Transaction (48) for phase content-prefs.sqlite#0: waiting for clients
[task 2021-02-11T23:08:40.281Z] 23:08:40 INFO - 1613084920264 Marionette TRACE [17] MarionetteEvents actor created for window id 2147483686
[task 2021-02-11T23:08:40.281Z] 23:08:40 INFO - 1613084920264 Marionette TRACE Received event DOMContentLoaded for data:text/html;charset=utf-8,%3Cvideo%20loop%3E
[task 2021-02-11T23:08:40.281Z] 23:08:40 INFO - DEBUG: Completed blocker Transaction (48) for phase content-prefs.sqlite#0: waiting for clients
[task 2021-02-11T23:08:40.281Z] 23:08:40 INFO - 1613084920265 Marionette TRACE Received event pageshow for data:text/html;charset=utf-8,%3Cvideo%20loop%3E
[task 2021-02-11T23:08:40.281Z] 23:08:40 INFO - JavaScript err1613084920266 Marionette DEBUG 233 <- [1,59,null,{"value":null}]
[task 2021-02-11T23:08:40.281Z] 23:08:40 INFO - or: resource://gre/actors/PictureInPictureChild.jsm, line 453: TypeError: can't access property "requestIdleCallback", this.contentWindow is null
[task 2021-02-11T23:08:40.281Z] 23:08:40 INFO - 1613084920268 Marionette DEBUG 233 -> [0,60,"WebDriver:FindElement",{"using":"tag name","value":"video"}]
[task 2021-02-11T23:08:40.281Z] 23:08:40 INFO - 1613084920269 Marionette TRACE [17] MarionetteCommands actor created for window id 2147483686
[task 2021-02-11T23:08:40.281Z] 23:08:40 INFO - 1613084920270 Marionette DEBUG 233 <- [1,60,null,{"value":{"element-6066-11e4-a52e-4f735466cecf":"c8f4de62-e500-47b3-a949-791c5311837d"}}]
[task 2021-02-11T23:08:40.284Z] 23:08:40 INFO - 1613084920270 Marionette DEBUG 233 -> [0,61,"WebDriver:GetElementAttribute",{"id":"c8f4de62-e500-47b3-a949-791c5311837d","name":"loop"}]
[task 2021-02-11T23:08:40.287Z] 23:08:40 INFO - testing boolean attribute <video muted>
[task 2021-02-11T23:08:40.290Z] 23:08:40 INFO - 1613084920274 Marionette DEBUG 233 <- [1,61,null,{"value":"true"}]
[task 2021-02-11T23:08:40.290Z] 23:08:40 INFO - 1613084920276 Marionette DEBUG 233 -> [0,62,"WebDriver:Navigate",{"url":"data:text/html;charset=utf-8,%3Cvideo%20muted%3E"}]
[task 2021-02-11T23:08:40.290Z] 23:08:40 INFO - 1613084920279 Marionette TRACE Received event beforeunload for data:text/html;charset=utf-8,%3Cvideo%20loop%3E
[task 2021-02-11T23:08:40.297Z] 23:08:40 INFO - 1613084920282 Marionette TRACE Received event pagehide for data:text/html;charset=utf-8,%3Cvideo%20loop%3E
[task 2021-02-11T23:08:40.300Z] 23:08:40 INFO - DEBUG: Adding blocker Transaction (49) for phase content-prefs.sqlite#0: waiting for clients
[task 2021-02-11T23:08:40.300Z] 23:08:40 INFO - DEBUG: Completed blocker Transaction (49) for phase content-prefs.sqlite#0: waiting for clients
[task 2021-02-11T23:08:40.303Z] 23:08:40 INFO - 1613084920293 Marionette TRACE [17] MarionetteEvents actor created for window id 2147483687
[task 2021-02-11T23:08:40.310Z] 23:08:40 INFO - 1613084920294 Marionette TRACE Received event DOMContentLoaded for data:text/html;charset=utf-8,%3Cvideo%20muted%3E
[task 2021-02-11T23:08:40.310Z] 23:08:40 INFO - JavaScript error: resource://gre/actors/PictureInPictureChild.jsm, line 453:1613084920295 Marionette TRACE Received event pageshow for data:text/html;charset=utf-8,%3Cvideo%20muted%3E
[task 2021-02-11T23:08:40.310Z] 23:08:40 INFO - TypeError: can't access property "requestIdleCallback", this.contentWindow is null
[task 2021-02-11T23:08:40.310Z] 23:08:40 INFO - 1613084920296 Marionette DEBUG 233 <- [1,62,null,{"value":null}]
[task 2021-02-11T23:08:40.310Z] 23:08:40 INFO - 1613084920298 Marionette DEBUG 233 -> [0,63,"WebDriver:FindElement",{"using":"tag name","value":"video"}]
[task 2021-02-11T23:08:40.310Z] 23:08:40 INFO - 1613084920300 Marionette TRACE [17] MarionetteCommands actor created for window id 2147483687
[task 2021-02-11T23:08:40.313Z] 23:08:40 INFO - 1613084920300 Marionette DEBUG 233 <- [1,63,null,{"value":{"element-6066-11e4-a52e-4f735466cecf":"d32f3603-2b98-41e1-a951-8403f7082228"}}]
[task 2021-02-11T23:08:40.313Z] 23:08:40 INFO - 1613084920301 Marionette DEBUG 233 -> [0,64,"WebDriver:GetElementAttribute",{"id":"d32f3603-2b98-41e1-a951-8403f7082228","name":"muted"}]
[task 2021-02-11T23:08:40.313Z] 23:08:40 INFO - testing boolean attribute <details open>
[task 2021-02-11T23:08:40.313Z] 23:08:40 INFO - 1613084920302 Marionette DEBUG 233 <- [1,64,null,{"value":"true"}]
[task 2021-02-11T23:08:40.316Z] 23:08:40 INFO - 1613084920302 Marionette DEBUG 233 -> [0,65,"WebDriver:Navigate",{"url":"data:text/html;charset=utf-8,%3Cdetails%20open%3E"}]
[task 2021-02-11T23:08:40.316Z] 23:08:40 INFO - 1613084920304 Marionette TRACE Received event beforeunload for data:text/html;charset=utf-8,%3Cvideo%20muted%3E
[task 2021-02-11T23:08:40.323Z] 23:08:40 INFO - DEBUG: Adding blocker SessionFile: Finish writing Session Restore data for phase profile-before-change
[task 2021-02-11T23:08:40.326Z] 23:08:40 INFO - 1613084920313 Marionette TRACE Received event pagehide for data:text/html;charset=utf-8,%3Cvideo%20muted%3E
[task 2021-02-11T23:08:40.326Z] 23:08:40 INFO - DEBUG: Completed blocker SessionFile: Finish writing Session Restore data for phase profile-before-change
[task 2021-02-11T23:08:40.333Z] 23:08:40 INFO - 1613084920318 Marionette TRACE [17] MarionetteEvents actor created for window id 2147483688
[task 2021-02-11T23:08:40.333Z] 23:08:40 INFO - DEBUG: Adding blocker Transaction (50) for phase content-prefs.sqlite#0: waiting for clients
[task 2021-02-11T23:08:40.333Z] 23:08:40 INFO - 1613084920319 Marionette TRACE Received event DOMContentLoaded for data:text/html;charset=utf-8,%3Cdetails%20open%3E
[task 2021-02-11T23:08:40.333Z] 23:08:40 INFO - 1613084920320 Marionette TRACE Received event pageshow for data:text/html;charset=utf-8,%3Cdetails%20open%3E
[task 2021-02-11T23:08:40.333Z] 23:08:40 INFO - 1613084920320 Marionette DEBUG 233 <- [1,65,null,{"value":null}]
[task 2021-02-11T23:08:40.333Z] 23:08:40 INFO - JavaScript error: resource://gre/actors/PictureInPictureChild.jsm, line 569: TypeError: can't access property "removeEventListener", this.contentWindow is null
[task 2021-02-11T23:08:40.340Z] 23:08:40 INFO - DEBUG: Completed blocker Transaction (50) for phase content-prefs.sqlite#0: waiting for clients
[task 2021-02-11T23:08:40.340Z] 23:08:40 INFO - 1613084920328 Marionette DEBUG 233 -> [0,66,"WebDriver:FindElement",{"using":"tag name","value":"details"}]
[task 2021-02-11T23:08:40.340Z] 23:08:40 INFO - 1613084920330 Marionette TRACE [17] MarionetteCommands actor created for window id 2147483688
[task 2021-02-11T23:08:40.343Z] 23:08:40 INFO - 1613084920330 Marionette DEBUG 233 <- [1,66,null,{"value":{"element-6066-11e4-a52e-4f735466cecf":"2674d3bd-eb98-46b8-a150-7fceefce665e"}}]
[task 2021-02-11T23:08:40.343Z] 23:08:40 INFO - 1613084920331 Marionette DEBUG 233 -> [0,67,"WebDriver:GetElementAttribute",{"id":"2674d3bd-eb98-46b8-a150-7fceefce665e","name":"open"}]
[task 2021-02-11T23:08:40.343Z] 23:08:40 INFO - 1613084920332 Marionette DEBUG 233 <- [1,67,null,{"value":"true"}]
[task 2021-02-11T23:08:40.343Z] 23:08:40 INFO - testing boolean attribute <dialog open>```
|
||
Comment 1•5 years ago
|
||
Note that the above excerpt of the failure is wrong. Here the correct section from the log:
[task 2021-02-11T23:09:53.360Z] 23:09:53 INFO - 1613084993356 Marionette DEBUG 20 -> [0,30,"WebDriver:GetCurrentURL",{}]
[task 2021-02-11T23:09:53.360Z] 23:09:53 INFO - 1613084993357 Marionette DEBUG 20 <- [1,30,null,{"value":"about:robots"}]
[task 2021-02-11T23:09:53.367Z] 23:09:53 INFO - DEBUG: Adding blocker Transaction (11) for phase content-prefs.sqlite#0: waiting for clients
[task 2021-02-11T23:09:53.402Z] 23:09:53 INFO - DEBUG: Completed blocker Transaction (11) for phase content-prefs.sqlite#0: waiting for clients
[task 2021-02-11T23:09:53.417Z] 23:09:53 INFO - 1613084993413 Marionette TRACE [80] MarionetteEvents actor created for window id 95
[task 2021-02-11T23:17:04.587Z] 23:17:04 INFO - [GFX1-]: Receive IPC close with reason=AbnormalShutdown
[task 2021-02-11T23:17:04.587Z] 23:17:04 INFO - Exiting due to channel error.
[task 2021-02-11T23:17:04.588Z] 23:17:04 INFO - [GFX1-]: Receive IPC close with reason=AbnormalShutdown
[task 2021-02-11T23:17:04.608Z] 23:17:04 INFO - [Child 2184, IPC I/O Child] WARNING: pipe error: 232: file /builds/worker/checkouts/gecko/ipc/chromium/src/chrome/common/ipc_channel_win.cc
[task 2021-02-11T23:17:04.723Z] 23:17:04 ERROR - TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestNavigate.test_type_to_non_remote_tab | IOError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors (Reason: Connection timed out after 360.0s)
So WebDriver:GetCurrentURL returned but then we had a mystic stall of the test execution. No further command is send. As it looks like we hang in Wait.until() here:
Summary: Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestNavigate.test_type_to_non_remote_tab | IOError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors (Reason: time out → Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestNavigate.test_type_to_non_remote_tab | IOError: Process killed because the connection to Marionette server is lost [Hang in Wait.until()]
| Comment hidden (Intermittent Failures Robot) |
|
||
Comment 3•5 years ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.
Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → INCOMPLETE
|
||
Updated•3 years ago
|
Product: Testing → Remote Protocol
|
|
||
Comment 4•3 years ago
|
||
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.
Description
•