Closed
Bug 1869133
Opened 1 year ago
Closed 1 year ago
Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_execute_script.py TestExecuteContent.test_window_set_timeout_is_not_cancelled | single tracking bug
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, intermittent-testcase)
Filed by: imoraru [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=439517199&repo=mozilla-beta
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/ff6XYkMWRv2mikLKVyIfRA/runs/0/artifacts/public/logs/live_backing.log
[task 2023-12-09T20:58:19.998Z] 20:58:19 INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_execute_script.py TestExecuteContent.test_window_set_timeout_is_not_cancelled
[task 2023-12-09T20:58:19.999Z] 20:58:19 INFO - 1702155499999 Marionette DEBUG Accepted connection 180 from 127.0.0.1:50639
[task 2023-12-09T20:58:20.021Z] 20:58:20 INFO - 1702155500022 Marionette DEBUG 180 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2023-12-09T20:58:20.023Z] 20:58:20 INFO - 1702155500023 Marionette DEBUG Waiting for initial application window
[task 2023-12-09T20:58:20.024Z] 20:58:20 INFO - 1702155500024 RemoteAgent TRACE [296] ProgressListener Start: expectNavigation=false resolveWhenStarted=false unloadTimeout=40000 waitForExplicitStart=false
[task 2023-12-09T20:58:20.024Z] 20:58:20 INFO - 1702155500024 RemoteAgent TRACE [296] ProgressListener Setting unload timer (40000ms)
[task 2023-12-09T20:58:20.025Z] 20:58:20 INFO - 1702155500024 RemoteAgent TRACE [296] Document already finished loading: data:text/html;charset=utf-8,%3Cp%3Efoo%3C/p%3E%20%3Cp%3Ebar%3C/p%3E
[task 2023-12-09T20:58:20.025Z] 20:58:20 INFO - 1702155500024 RemoteAgent TRACE [296] ProgressListener Stop: has error=false
[task 2023-12-09T20:58:20.028Z] 20:58:20 INFO - 1702155500027 Marionette DEBUG 180 <- [1,1,null,{"sessionId":"0ef7040c-9227-4bf9-8400-2bf86382a098","capabilities":{"browserName":"firefox","browserVersion":"121.0","platformName":"windows","acceptInsecureCerts":false,"pageLoadStrategy":"normal","setWindowRect":true,"timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"strictFileInteractability":true,"unhandledPromptBehavior":"dismiss and notify","moz:accessibilityChecks":false,"moz:buildID":"20231209200911","moz:headless":false,"moz:platformVersion":"10.0","moz:processID":8288,"moz:profile":"C:\\Users\\task_170215480859458\\AppData\\Local\\Temp\\tmpyxo5r7ga.mozrunner","moz:shutdownTimeout":60000,"moz:webdriverClick":true,"moz:windowless":false,"proxy":{}}}]
[task 2023-12-09T20:58:20.028Z] 20:58:20 INFO - 1702155500028 Marionette DEBUG 180 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
[task 2023-12-09T20:58:20.029Z] 20:58:20 INFO - 1702155500028 Marionette DEBUG 180 <- [1,2,null,{"value":null}]
[task 2023-12-09T20:58:20.030Z] 20:58:20 INFO - 1702155500029 Marionette DEBUG 180 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2023-12-09T20:58:20.030Z] 20:58:20 INFO - 1702155500030 Marionette DEBUG 180 <- [1,3,null,{"value":null}]
[task 2023-12-09T20:58:20.031Z] 20:58:20 INFO - 1702155500031 Marionette DEBUG 180 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2023-12-09T20:58:20.031Z] 20:58:20 INFO - 1702155500031 Marionette DEBUG 180 <- [1,4,null,{"value":null}]
[task 2023-12-09T20:58:20.033Z] 20:58:20 INFO - 1702155500032 Marionette DEBUG 180 -> [0,5,"WebDriver:Navigate",{"url":"data:text/html;charset=utf-8,%0A%20%20%20%20%20%20%20%20%20%20%20%20%3Cscript%3E%0A%20%20%20%20%20%20%20%20%20%20%20%20window ... %20%20%20%20setTimeout%28%28%29%20%3D%3E%20%2B%2Bwindow.n%2C%204000%29%3B%0A%20%20%20%20%20%20%20%20%20%20%20%20%3C/script%3E"}]
[task 2023-12-09T20:58:20.035Z] 20:58:20 INFO - 1702155500035 Marionette TRACE [296] Received event beforeunload for data:text/html;charset=utf-8,%3Cp%3Efoo%3C/p%3E%20%3Cp%3Ebar%3C/p%3E
[task 2023-12-09T20:58:20.052Z] 20:58:20 INFO - 1702155500061 Marionette TRACE Remoteness change detected. Set new top-level browsing context to 298
[task 2023-12-09T20:58:20.068Z] 20:58:20 INFO - 1702155500067 Marionette TRACE [298] Received event beforeunload for about:blank
[task 2023-12-09T20:58:20.068Z] 20:58:20 INFO - 1702155500068 Marionette TRACE [298] Received event pagehide for about:blank
[task 2023-12-09T20:58:20.079Z] 20:58:20 INFO - DEBUG: Adding blocker Transaction (64) for phase content-prefs.sqlite#0: waiting for clients
[task 2023-12-09T20:58:20.088Z] 20:58:20 INFO - 1702155500088 Marionette TRACE [298] Received event DOMContentLoaded for data:text/html;charset=utf-8,%0A%20%20%20%20%20%20%20%20%20%20%20%20%3Cscript%3E%0A%20%20%20%20%20%20%20%20%20%20%20%20window ... %20%20%20%20setTimeout%28%28%29%20%3D%3E%20%2B%2Bwindow.n%2C%204000%29%3B%0A%20%20%20%20%20%20%20%20%20%20%20%20%3C/script%3E
[task 2023-12-09T20:58:20.090Z] 20:58:20 INFO - 1702155500089 Marionette TRACE [298] Received event pageshow for data:text/html;charset=utf-8,%0A%20%20%20%20%20%20%20%20%20%20%20%20%3Cscript%3E%0A%20%20%20%20%20%20%20%20%20%20%20%20window ... %20%20%20%20setTimeout%28%28%29%20%3D%3E%20%2B%2Bwindow.n%2C%204000%29%3B%0A%20%20%20%20%20%20%20%20%20%20%20%20%3C/script%3E
[task 2023-12-09T20:58:20.090Z] 20:58:20 INFO - 1702155500090 Marionette DEBUG 180 <- [1,5,null,{"value":null}]
[task 2023-12-09T20:58:20.096Z] 20:58:20 INFO - DEBUG: Completed blocker Transaction (64) for phase content-prefs.sqlite#0: waiting for clients
[task 2023-12-09T20:58:20.098Z] 20:58:20 INFO - 1702155500097 Marionette DEBUG 180 -> [0,6,"WebDriver:ExecuteScript",{"script":"return window.n","args":[],"newSandbox":true,"sandbox":null,"line":404,"filename":"Z:\\task_170215480859458\\build\\tests\\marionette\\tests\\testing\\marionette\\harness\\marionette_harness\\tests\\unit\\test_execute_script.py"}]
[task 2023-12-09T20:58:20.098Z] 20:58:20 INFO - 1702155500098 RemoteAgent TRACE WebDriverProcessData actor created for PID 8448
[task 2023-12-09T20:58:20.099Z] 20:58:20 INFO - 1702155500098 Marionette TRACE [298] MarionetteCommands actor created for window id 8589934605
[task 2023-12-09T20:58:20.101Z] 20:58:20 INFO - 1702155500101 Marionette DEBUG 180 <- [1,6,null,{"value":0}]
[task 2023-12-09T20:58:20.103Z] 20:58:20 INFO - 1702155500103 Marionette DEBUG 180 -> [0,7,"WebDriver:ExecuteScript",{"script":"return window.n","args":[],"newSandbox":true,"sandbox":null,"line":386,"filename":"Z:\\task_170215480859458\\build\\tests\\marionette\\tests\\testing\\marionette\\harness\\marionette_harness\\tests\\unit\\test_execute_script.py"}]
[task 2023-12-09T20:58:20.108Z] 20:58:20 INFO - 1702155500107 Marionette DEBUG 180 <- [1,7,null,{"value":0}]
<...>
[task 2023-12-09T20:58:27.998Z] 20:58:27 INFO - 1702155508000 Marionette DEBUG 180 -> [0,76,"WebDriver:ExecuteScript",{"script":"return window.n","args":[],"newSandbox":true,"sandbox":null,"line":386,"filename":"Z:\\task_170215480859458\\build\\tests\\marionette\\tests\\testing\\marionette\\harness\\marionette_harness\\tests\\unit\\test_execute_script.py"}]
[task 2023-12-09T20:58:28.006Z] 20:58:28 INFO - 1702155508006 Marionette DEBUG 180 <- [1,76,null,{"value":0}]
[task 2023-12-09T20:58:28.108Z] 20:58:28 INFO - 1702155508110 Marionette DEBUG 180 -> [0,77,"Marionette:GetContext",{}]
[task 2023-12-09T20:58:28.111Z] 20:58:28 INFO - 1702155508110 Marionette DEBUG 180 <- [1,77,null,{"value":"content"}]
[task 2023-12-09T20:58:28.112Z] 20:58:28 INFO - 1702155508111 Marionette DEBUG 180 -> [0,78,"Marionette:SetContext",{"value":"chrome"}]
[task 2023-12-09T20:58:28.112Z] 20:58:28 INFO - 1702155508112 Marionette DEBUG 180 <- [1,78,null,{"value":null}]
[task 2023-12-09T20:58:28.113Z] 20:58:28 INFO - 1702155508113 Marionette DEBUG 180 -> [0,79,"WebDriver:TakeScreenshot",{"id":null,"full":true,"hash":false,"scroll":true}]
[task 2023-12-09T20:58:28.118Z] 20:58:28 INFO - 1702155508118 RemoteAgent TRACE WebDriverProcessData actor created for PID 8288
[task 2023-12-09T20:58:28.119Z] 20:58:28 INFO - 1702155508118 Marionette TRACE [1] MarionetteCommands actor created for window id 2
[task 2023-12-09T20:58:28.139Z] 20:58:28 INFO - [GFX3-]: Creating null Skia image from null SourceSurface
[task 2023-12-09T20:58:28.186Z] 20:58:28 INFO - 1702155508189 Marionette DEBUG 180 <- [1,79,null,{"value":"iVBORw0KGgoAAAANSUhEUgAABQAAAAPQCAYAAABpCtbiAAAgAElEQVR4XuzdB5gmRYE38Fo2L5gICoKIGQOgSPLQU1BA5RPjKSjqiZ6eIngG9DxFFEyInopiOsEzf ... dCRAgQIAAAQIECBAgQIAAAQIECEQBB2AEEydAgAABAgQIECBAgAABAgQIECDwJOAAfFpLVwIECBAgQIAAAQIECBAgQIAAAQJRYGw0cNLR9RjmAAAAAElFTkSuQmCC"}]
[task 2023-12-09T20:58:28.194Z] 20:58:28 INFO - 1702155508193 Marionette DEBUG 180 -> [0,80,"Marionette:SetContext",{"value":"content"}]
[task 2023-12-09T20:58:28.194Z] 20:58:28 INFO - 1702155508194 Marionette DEBUG 180 <- [1,80,null,{"value":null}]
[task 2023-12-09T20:58:28.195Z] 20:58:28 INFO - 1702155508195 Marionette DEBUG 180 -> [0,81,"Marionette:GetContext",{}]
[task 2023-12-09T20:58:28.196Z] 20:58:28 INFO - 1702155508195 Marionette DEBUG 180 <- [1,81,null,{"value":"content"}]
[task 2023-12-09T20:58:28.197Z] 20:58:28 INFO - 1702155508196 Marionette DEBUG 180 -> [0,82,"Marionette:SetContext",{"value":"content"}]
[task 2023-12-09T20:58:28.197Z] 20:58:28 INFO - 1702155508197 Marionette DEBUG 180 <- [1,82,null,{"value":null}]
[task 2023-12-09T20:58:28.198Z] 20:58:28 INFO - 1702155508198 Marionette DEBUG 180 -> [0,83,"WebDriver:GetPageSource",{}]
[task 2023-12-09T20:58:28.200Z] 20:58:28 INFO - 1702155508200 Marionette DEBUG 180 <- [1,83,null,{"value":"<html><head><script>\n window.n = 0;\n setTimeout(() => ++window.n, 4000);\n </script></head><body></body></html>"}]
[task 2023-12-09T20:58:28.201Z] 20:58:28 INFO - 1702155508201 Marionette DEBUG 180 -> [0,84,"Marionette:SetContext",{"value":"content"}]
[task 2023-12-09T20:58:28.201Z] 20:58:28 INFO - 1702155508201 Marionette DEBUG 180 <- [1,84,null,{"value":null}]
[task 2023-12-09T20:58:28.204Z] 20:58:28 ERROR - TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_execute_script.py TestExecuteContent.test_window_set_timeout_is_not_cancelled | marionette_driver.errors.TimeoutException: Timed out after 8.0 seconds with message: Scheduled setTimeout event was cancelled by call to execute_script
[task 2023-12-09T20:58:28.205Z] 20:58:28 INFO - Traceback (most recent call last):
[task 2023-12-09T20:58:28.205Z] 20:58:28 INFO - File "Z:\task_170215480859458\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 198, in run
[task 2023-12-09T20:58:28.205Z] 20:58:28 INFO - testMethod()
[task 2023-12-09T20:58:28.205Z] 20:58:28 INFO - File "Z:\task_170215480859458\build\tests\marionette\tests\testing\marionette\harness\marionette_harness\tests\unit\test_execute_script.py", line 409, in test_window_set_timeout_is_not_cancelled
[task 2023-12-09T20:58:28.206Z] 20:58:28 INFO - Wait(self.marionette, timeout=8).until(
[task 2023-12-09T20:58:28.206Z] 20:58:28 INFO - File "Z:\task_170215480859458\build\venv\lib\site-packages\marionette_driver\wait.py", line 153, in until
[task 2023-12-09T20:58:28.206Z] 20:58:28 INFO - raise errors.TimeoutException(
[task 2023-12-09T20:58:28.206Z] 20:58:28 INFO - TEST-INFO took 8204ms
[task 2023-12-09T20:58:28.207Z] 20:58:28 INFO - 1702155508205 Marionette DEBUG 180 -> [0,85,"WebDriver:GetAlertText",{}]
[task 2023-12-09T20:58:28.207Z] 20:58:28 INFO - 1702155508205 Marionette DEBUG 180 <- [1,85,{"error":"no such alert","message":"","stacktrace":"RemoteError@chrome://remote/content/shared/RemoteError.sys.mjs:8:8\nWebDriverError@chrome://remote/content/shared/webdriver/Er ... ote/content/marionette/server.sys.mjs:263:9\n_onJSONObjectReady/<@chrome://remote/content/marionette/transport.sys.mjs:494:20\n"},null]
[task 2023-12-09T20:58:28.207Z] 20:58:28 INFO - 1702155508207 Marionette DEBUG 180 -> [0,86,"WebDriver:DeleteSession",{}]
[task 2023-12-09T20:58:28.208Z] 20:58:28 INFO - 1702155508208 Marionette TRACE [1] MarionetteCommands actor destroyed for window id 2
[task 2023-12-09T20:58:28.208Z] 20:58:28 INFO - 1702155508208 Marionette TRACE [298] MarionetteCommands actor destroyed for window id 8589934605
[task 2023-12-09T20:58:28.210Z] 20:58:28 INFO - 1702155508210 Marionette DEBUG 180 <- [1,86,null,{"value":null}]
[task 2023-12-09T20:58:28.211Z] 20:58:28 INFO - 1702155508211 Marionette DEBUG Closed connection 180
[task 2023-12-09T20:58:28.216Z] 20:58:28 INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_expected.py TestExpected.test_element_displayed
| Comment hidden (Intermittent Failures Robot) |
|
||
Comment 2•1 year ago
|
||
Just a single failure so far. So lets observe. The actual failure message is:
Timed out after 8.0 seconds with message: Scheduled setTimeout event was cancelled by call to execute_script
|
||
Comment 3•1 year ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit BugBot documentation.
Status: NEW → RESOLVED
Closed: 1 year ago
Resolution: --- → INCOMPLETE
You need to log in
before you can comment on or make changes to this bug.
Description
•