Closed
Bug 1716891
Opened 3 years ago
Closed 3 years ago
Intermittent testing/firefox-ui/tests/functional/sessionstore/test_restore_windows_after_restart_and_quit.py TestSessionStoreDisabled.test_no_restore_with_quit | marionette_driver.errors.TimeoutException: TimedPromise timed out after 300000 ms
Categories
(Testing :: Firefox UI Tests, defect, P5)
Testing
Firefox UI Tests
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=343000407&repo=mozilla-beta
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/bdnv6xrcRBqChdIHq6UYdg/runs/0/artifacts/public/logs/live_backing.log
[task 2021-06-16T20:24:21.994Z] 20:24:21 INFO - TEST-START | testing/firefox-ui/tests/functional/sessionstore/test_restore_windows_after_restart_and_quit.py TestSessionStoreDisabled.test_no_restore_with_quit
[task 2021-06-16T20:24:21.997Z] 20:24:21 INFO - 1623875061996 Marionette DEBUG Accepted connection 2 from 127.0.0.1:60076
[task 2021-06-16T20:24:22.007Z] 20:24:22 INFO - 1623875062005 Marionette DEBUG 2 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2021-06-16T20:24:22.008Z] 20:24:22 INFO - 1623875062008 Marionette DEBUG 2 <- [1,1,null,{"sessionId":"b9e6473d-49a9-40f8-ac67-158208966cfc","capabilities":{"browserName":"firefox","browserVersion":"90.0" ... f.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"proxy":{}}}]
[task 2021-06-16T20:24:22.015Z] 20:24:22 INFO - 1623875062013 Marionette DEBUG 2 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
[task 2021-06-16T20:24:22.016Z] 20:24:22 INFO - 1623875062013 Marionette DEBUG 2 <- [1,2,null,{"value":null}]
[task 2021-06-16T20:24:22.016Z] 20:24:22 INFO - 1623875062014 Marionette DEBUG 2 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2021-06-16T20:24:22.016Z] 20:24:22 INFO - 1623875062014 Marionette DEBUG 2 <- [1,3,null,{"value":null}]
[task 2021-06-16T20:24:22.018Z] 20:24:22 INFO - 1623875062015 Marionette DEBUG 2 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2021-06-16T20:24:22.020Z] 20:24:22 INFO - 1623875062019 Marionette DEBUG 2 <- [1,4,null,{"value":null}]
[task 2021-06-16T20:24:22.022Z] 20:24:22 INFO - 1623875062021 Marionette DEBUG 2 -> [0,5,"WebDriver:GetChromeWindowHandle",{}]
[task 2021-06-16T20:24:22.022Z] 20:24:22 INFO - 1623875062022 Marionette DEBUG 2 <- [1,5,null,{"value":"9d845430-f447-4fd0-85ec-b00cc891b7b7"}]
[task 2021-06-16T20:24:22.024Z] 20:24:22 INFO - 1623875062024 Marionette DEBUG 2 -> [0,6,"WebDriver:GetChromeWindowHandles",{}]
[task 2021-06-16T20:24:22.024Z] 20:24:22 INFO - 1623875062024 Marionette DEBUG 2 <- [1,6,null,["9d845430-f447-4fd0-85ec-b00cc891b7b7"]]
[task 2021-06-16T20:24:22.026Z] 20:24:22 INFO - 1623875062026 Marionette DEBUG 2 -> [0,7,"WebDriver:GetWindowHandle",{}]
[task 2021-06-16T20:24:22.027Z] 20:24:22 INFO - 1623875062026 Marionette DEBUG 2 <- [1,7,null,{"value":"fdf301bb-0129-415c-b9dd-f7fa28f06cf9"}]
[task 2021-06-16T20:24:22.029Z] 20:24:22 INFO - 1623875062029 Marionette DEBUG 2 -> [0,8,"WebDriver:GetWindowHandles",{}]
[task 2021-06-16T20:24:22.030Z] 20:24:22 INFO - 1623875062029 Marionette DEBUG 2 <- [1,8,null,["fdf301bb-0129-415c-b9dd-f7fa28f06cf9"]]
[task 2021-06-16T20:24:22.033Z] 20:24:22 INFO - 1623875062033 Marionette DEBUG 2 -> [0,9,"Marionette:SetContext",{"value":"chrome"}]
[task 2021-06-16T20:24:22.035Z] 20:24:22 INFO - 1623875062033 Marionette DEBUG 2 <- [1,9,null,{"value":null}]
[task 2021-06-16T20:24:22.037Z] 20:24:22 INFO - 1623875062036 Marionette DEBUG 2 -> [0,10,"Marionette:GetContext",{}]
[task 2021-06-16T20:24:22.037Z] 20:24:22 INFO - 1623875062037 Marionette DEBUG 2 <- [1,10,null,{"value":"chrome"}]
[task 2021-06-16T20:24:22.040Z] 20:24:22 INFO - 1623875062039 Marionette DEBUG 2 -> [0,11,"Marionette:SetContext",{"value":"chrome"}]
[task 2021-06-16T20:24:22.040Z] 20:24:22 INFO - 1623875062040 Marionette DEBUG 2 <- [1,11,null,{"value":null}]
[task 2021-06-16T20:24:22.044Z] 20:24:22 INFO - 1623875062043 Marionette DEBUG 2 -> [0,12,"WebDriver:ExecuteScript",{"script":"let prefInterface = Components.classes[\"@mozilla.org/preferences-service;1\"]\n ... ox":true,"sandbox":"default","line":895,"filename":"../../venv/lib/python3.6/site-packages/marionette_driver/marionette.py"}]
[task 2021-06-16T20:24:22.046Z] 20:24:22 INFO - 1623875062046 Marionette TRACE [7] MarionetteCommands actor created for window id 2
[task 2021-06-16T20:24:22.047Z] 20:24:22 INFO - 1623875062047 Marionette DEBUG 2 <- [1,12,null,{"value":false}]
[task 2021-06-16T20:24:22.049Z] 20:24:22 INFO - 1623875062048 Marionette DEBUG 2 -> [0,13,"Marionette:SetContext",{"value":"chrome"}]
[task 2021-06-16T20:24:28.377Z] 20:24:28 INFO - 1623875068376 Marionette TRACE [51] Received event DOMContentLoaded for http://127.0.0.1:37537/layout/mozilla_mission.html
[task 2021-06-16T20:24:28.423Z] 20:24:28 INFO - 1623875068423 Marionette WARN Ignoring event 'pageshow' because document has an invalid readyState of 'interactive'.
[task 2021-06-16T20:29:28.172Z] 20:29:28 INFO - 1623875368172 Marionette DEBUG 1 <- [1,63,{"error":"timeout","message":"TimedPromise timed out after 300000 ms","stacktrace":"WebDriverError@chrome://marionette/ ... .js:181:5\nTimeoutError@chrome://marionette/content/error.js:450:5\nbail@chrome://marionette/content/sync.js:229:19\n"},null]
[task 2021-06-16T20:29:28.174Z] 20:29:28 INFO - 1623875368174 Marionette DEBUG 1 -> [0,64,"Marionette:SetContext",{"value":"chrome"}]
[task 2021-06-16T20:29:28.176Z] 20:29:28 INFO - 1623875368174 Marionette DEBUG 1 <- [1,64,null,{"value":null}]
[task 2021-06-16T20:29:28.177Z] 20:29:28 INFO - 1623875368177 Marionette DEBUG 1 -> [0,65,"Marionette:GetContext",{}]
[task 2021-06-16T20:29:28.178Z] 20:29:28 INFO - 1623875368177 Marionette DEBUG 1 <- [1,65,null,{"value":"chrome"}]
[task 2021-06-16T20:29:28.179Z] 20:29:28 INFO - 1623875368179 Marionette DEBUG 1 -> [0,66,"Marionette:SetContext",{"value":"chrome"}]
[task 2021-06-16T20:29:28.180Z] 20:29:28 INFO - 1623875368179 Marionette DEBUG 1 <- [1,66,null,{"value":null}]
[task 2021-06-16T20:29:28.181Z] 20:29:28 INFO - 1623875368181 Marionette DEBUG 1 -> [0,67,"WebDriver:TakeScreenshot",{"id":null,"full":true,"hash":false,"scroll":true}]
[task 2021-06-16T20:29:28.183Z] 20:29:28 INFO - 1623875368182 Marionette TRACE [49] MarionetteCommands actor created for window id 49
[task 2021-06-16T20:29:28.239Z] 20:29:28 INFO - 1623875368238 Marionette DEBUG 1 <- [1,67,null,{"value":"iVBORw0KGgoAAAANSUhEUgAABQAAAAQQCAYAAAC9RfbYAAAgAElEQVR4nOy9eVhU98H2TxJNVFQEVxSXmLg3alZNTGqetPklTZr0aZI2 ... AAAAAAjAlAAAAAABgTgAAAAAAwJgABAAAAYEwAAgAAAMCYAAQAAACAMQEIAAAAAGMCEAAAAADGBCAAAAAAjAlAAAAAABgLDBe2Sp+cw/AAAAAASUVORK5CYII="}]
[task 2021-06-16T20:29:28.281Z] 20:29:28 INFO - 1623875368280 Marionette DEBUG 1 -> [0,68,"Marionette:SetContext",{"value":"chrome"}]
[task 2021-06-16T20:29:28.282Z] 20:29:28 INFO - 1623875368281 Marionette DEBUG 1 <- [1,68,null,{"value":null}]
[task 2021-06-16T20:29:28.283Z] 20:29:28 INFO - 1623875368282 Marionette DEBUG 1 -> [0,69,"Marionette:GetContext",{}]
[task 2021-06-16T20:29:28.284Z] 20:29:28 INFO - 1623875368282 Marionette DEBUG 1 <- [1,69,null,{"value":"chrome"}]
[task 2021-06-16T20:29:28.285Z] 20:29:28 INFO - 1623875368284 Marionette DEBUG 1 -> [0,70,"Marionette:SetContext",{"value":"content"}]
[task 2021-06-16T20:29:28.285Z] 20:29:28 INFO - 1623875368284 Marionette DEBUG 1 <- [1,70,null,{"value":null}]
[task 2021-06-16T20:29:28.286Z] 20:29:28 INFO - 1623875368285 Marionette DEBUG 1 -> [0,71,"WebDriver:GetPageSource",{}]
[task 2021-06-16T20:29:28.289Z] 20:29:28 INFO - 1623875368288 Marionette TRACE [51] MarionetteCommands actor created for window id 17179869185
[task 2021-06-16T20:29:28.293Z] 20:29:28 INFO - 1623875368289 Marionette DEBUG 1 <- [1,71,null,{"value":"<html dir=\"ltr\" lang=\"en\"><head>\n <title>Mozilla Mission</title>\n <link rel=\"shortcut icon\ ... <a href=\"mozilla_contribute.html\">Find out how you can help</a>.\n </p>\n </div>\n\n\n</body></html>"}]
[task 2021-06-16T20:29:28.299Z] 20:29:28 INFO - 1623875368291 Marionette DEBUG 1 -> [0,72,"Marionette:SetContext",{"value":"chrome"}]
[task 2021-06-16T20:29:28.300Z] 20:29:28 INFO - 1623875368291 Marionette DEBUG 1 <- [1,72,null,{"value":null}]
[task 2021-06-16T20:29:28.389Z] 20:29:28 INFO - TEST-UNEXPECTED-ERROR | testing/firefox-ui/tests/functional/sessionstore/test_restore_windows_after_restart_and_quit.py TestSessionStoreDisabled.test_no_restore_with_quit | marionette_driver.errors.TimeoutException: TimedPromise timed out after 300000 ms
[task 2021-06-16T20:29:28.389Z] 20:29:28 INFO - stacktrace:
[task 2021-06-16T20:29:28.389Z] 20:29:28 INFO - WebDriverError@chrome://marionette/content/error.js:181:5
[task 2021-06-16T20:29:28.389Z] 20:29:28 INFO - TimeoutError@chrome://marionette/content/error.js:450:5
[task 2021-06-16T20:29:28.389Z] 20:29:28 INFO - bail@chrome://marionette/content/sync.js:229:19
[task 2021-06-16T20:29:28.389Z] 20:29:28 INFO - Traceback (most recent call last):
[task 2021-06-16T20:29:28.389Z] 20:29:28 INFO - File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_harness/marionette_test/testcases.py", line 195, in run
[task 2021-06-16T20:29:28.389Z] 20:29:28 INFO - self.setUp()
[task 2021-06-16T20:29:28.389Z] 20:29:28 INFO - File "/builds/worker/workspace/build/tests/firefox-ui/tests/testing/firefox-ui/tests/functional/sessionstore/session_store_test_case.py", line 80, in setUp
[task 2021-06-16T20:29:28.389Z] 20:29:28 INFO - self.open_windows(self.private_windows, is_private=True)
[task 2021-06-16T20:29:28.389Z] 20:29:28 INFO - File "/builds/worker/workspace/build/tests/firefox-ui/tests/testing/firefox-ui/tests/functional/sessionstore/session_store_test_case.py", line 129, in open_windows
[task 2021-06-16T20:29:28.389Z] 20:29:28 INFO - self.open_tabs(win, urls)
[task 2021-06-16T20:29:28.389Z] 20:29:28 INFO - File "/builds/worker/workspace/build/tests/firefox-ui/tests/testing/firefox-ui/tests/functional/sessionstore/session_store_test_case.py", line 152, in open_tabs
[task 2021-06-16T20:29:28.389Z] 20:29:28 INFO - self.marionette.navigate(url)
[task 2021-06-16T20:29:28.389Z] 20:29:28 INFO - File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/marionette.py", line 1516, in navigate
[task 2021-06-16T20:29:28.389Z] 20:29:28 INFO - self._send_message("WebDriver:Navigate", {"url": url})
[task 2021-06-16T20:29:28.389Z] 20:29:28 INFO - File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/decorators.py", line 27, in _
[task 2021-06-16T20:29:28.389Z] 20:29:28 INFO - return func(*args, **kwargs)
[task 2021-06-16T20:29:28.389Z] 20:29:28 INFO - File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/marionette.py", line 629, in _send_message
[task 2021-06-16T20:29:28.389Z] 20:29:28 INFO - self._handle_error(err)
[task 2021-06-16T20:29:28.389Z] 20:29:28 INFO - File "/builds/worker/workspace/build/venv/lib/python3.6/site-packages/marionette_driver/marionette.py", line 651, in _handle_error
[task 2021-06-16T20:29:28.389Z] 20:29:28 INFO - raise errors.lookup(error)(message, stacktrace=stacktrace)
[task 2021-06-16T20:29:28.389Z] 20:29:28 INFO - TEST-INFO took 306298ms
[task 2021-06-16T20:29:28.390Z] 20:29:28 INFO - 1623875368322 Marionette DEBUG 1 -> [0,73,"WebDriver:DeleteSession",{}]
[task 2021-06-16T20:29:28.390Z] 20:29:28 INFO - 1623875368324 Marionette DEBUG 1 <- [1,73,null,{"value":null}]
[task 2021-06-16T20:29:28.391Z] 20:29:28 INFO - 1623875368326 Marionette DEBUG Closed connection 1
| Comment hidden (Intermittent Failures Robot) |
|
||
Comment 2•3 years ago
|
||
There was a problem in loading the page:
task 2021-06-16T20:24:28.377Z] 20:24:28 INFO - 1623875068376 Marionette TRACE [51] Received event DOMContentLoaded for http://127.0.0.1:37537/layout/mozilla_mission.html
[task 2021-06-16T20:24:28.423Z] 20:24:28 INFO - 1623875068423 Marionette WARN Ignoring event 'pageshow' because document has an invalid readyState of 'interactive'.
[task 2021-06-16T20:29:28.172Z] 20:29:28 INFO - 1623875368172 Marionette DEBUG 1 <- [1,63,{"error":"timeout","message":"TimedPromise timed out after 300000 ms","stacktrace":"WebDriverError@chrome://marionette/ ... .js:181:5\nTimeoutError@chrome://marionette/content/error.js:450:5\nbail@chrome://marionette/content/sync.js:229:19\n"},null]
Most likely a one time issue.
|
||
Comment 3•3 years ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.
Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → INCOMPLETE
|
||
Comment 4•3 years ago
|
||
Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=346294041&repo=mozilla-central&lineNumber=1724
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
| Comment hidden (Intermittent Failures Robot) |
|
|
||
Comment 6•3 years ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.
Status: REOPENED → RESOLVED
Closed: 3 years ago → 3 years ago
Resolution: --- → INCOMPLETE
You need to log in
before you can comment on or make changes to this bug.
Description
•