Closed
Bug 1898422
Opened 1 year ago
Closed 1 year ago
Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_execute_async_script.py | marionette_driver.errors.ScriptTimeoutException: Timed out after 1000 ms
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: tszentpeteri [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=459298837&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/AZoKWmFYSXW0jBbndH2MUg/runs/0/artifacts/public/logs/live_backing.log
[task 2024-05-23T04:44:31.398Z] 04:44:31 INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_execute_async_script.py TestExecuteAsyncChrome.test_script_timeout_no_timeout_error
[task 2024-05-23T04:44:31.399Z] 04:44:31 INFO - 1716439471398 Marionette DEBUG Closed connection 67
[task 2024-05-23T04:44:31.403Z] 04:44:31 INFO - 1716439471403 Marionette DEBUG Accepted connection 68 from 127.0.0.1:50436
[task 2024-05-23T04:44:31.407Z] 04:44:31 INFO - 1716439471407 Marionette DEBUG 68 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2024-05-23T04:44:31.409Z] 04:44:31 INFO - 1716439471409 Marionette DEBUG Waiting for initial application window
[task 2024-05-23T04:44:31.412Z] 04:44:31 INFO - 1716439471412 RemoteAgent TRACE [98] ProgressListener Start: expectNavigation=false resolveWhenStarted=false unloadTimeout=40000 waitForExplicitStart=false
[task 2024-05-23T04:44:31.413Z] 04:44:31 INFO - 1716439471412 RemoteAgent TRACE [98] ProgressListener Setting unload timer (40000ms)
[task 2024-05-23T04:44:31.413Z] 04:44:31 INFO - 1716439471412 RemoteAgent TRACE [98] Wait for initial navigation: isInitial=false, isLoadingDocument=false
[task 2024-05-23T04:44:31.413Z] 04:44:31 INFO - 1716439471412 RemoteAgent TRACE [98] Document already finished loading: http://127.0.0.1:49917/test.html
[task 2024-05-23T04:44:31.414Z] 04:44:31 INFO - 1716439471412 RemoteAgent TRACE [98] ProgressListener Stop: has error=false url=http://127.0.0.1:49917/test.html
[task 2024-05-23T04:44:31.421Z] 04:44:31 INFO - 1716439471419 Marionette DEBUG 68 <- [1,1,null,{"sessionId":"2a6928f9-e6d3-46d4-8ab9-6285c6b44cf9","capabilities":{"browserName":"firefox","browserVersion":"128.0a1","platformName":"windows","acceptInsecureCerts":false,"pageLoadStrategy":"normal","setWindowRect":true,"timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"strictFileInteractability":true,"unhandledPromptBehavior":"dismiss and notify","userAgent":"Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:128.0) Gecko/20100101 Firefox/128.0","moz:accessibilityChecks":false,"moz:buildID":"20240523041055","moz:headless":false,"moz:platformVersion":"10.0","moz:processID":8260,"moz:profile":"C:\\Users\\task_171643887765338\\AppData\\Local\\Temp\\tmpegi35iut.mozrunner","moz:shutdownTimeout":60000,"moz:webdriverClick":true,"moz:windowless":false,"proxy":{}}}]
[task 2024-05-23T04:44:31.426Z] 04:44:31 INFO - 1716439471425 Marionette DEBUG 68 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
[task 2024-05-23T04:44:31.428Z] 04:44:31 INFO - 1716439471427 Marionette DEBUG 68 <- [1,2,null,{"value":null}]
[task 2024-05-23T04:44:31.431Z] 04:44:31 INFO - 1716439471431 Marionette DEBUG 68 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2024-05-23T04:44:31.432Z] 04:44:31 INFO - 1716439471432 Marionette DEBUG 68 <- [1,3,null,{"value":null}]
[task 2024-05-23T04:44:31.437Z] 04:44:31 INFO - 1716439471437 Marionette DEBUG 68 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2024-05-23T04:44:31.438Z] 04:44:31 INFO - 1716439471438 Marionette DEBUG 68 <- [1,4,null,{"value":null}]
[task 2024-05-23T04:44:31.442Z] 04:44:31 INFO - 1716439471441 Marionette DEBUG 68 -> [0,5,"WebDriver:SetTimeouts",{"script":1000}]
[task 2024-05-23T04:44:31.443Z] 04:44:31 INFO - 1716439471443 Marionette DEBUG 68 <- [1,5,null,{"value":null}]
[task 2024-05-23T04:44:31.449Z] 04:44:31 INFO - 1716439471448 Marionette DEBUG 68 -> [0,6,"Marionette:SetContext",{"value":"chrome"}]
[task 2024-05-23T04:44:31.450Z] 04:44:31 INFO - 1716439471449 Marionette DEBUG 68 <- [1,6,null,{"value":null}]
[task 2024-05-23T04:44:31.453Z] 04:44:31 INFO - 1716439471452 Marionette DEBUG 68 -> [0,7,"WebDriver:GetTimeouts",{}]
[task 2024-05-23T04:44:31.453Z] 04:44:31 INFO - 1716439471453 Marionette DEBUG 68 <- [1,7,null,{"implicit":0,"pageLoad":300000,"script":1000}]
[task 2024-05-23T04:44:31.459Z] 04:44:31 INFO - 1716439471458 Marionette DEBUG 68 -> [0,8,"WebDriver:SetTimeouts",{"script":1000}]
[task 2024-05-23T04:44:31.459Z] 04:44:31 INFO - 1716439471459 Marionette DEBUG 68 <- [1,8,null,{"value":null}]
[task 2024-05-23T04:44:31.465Z] 04:44:31 INFO - 1716439471463 Marionette DEBUG 68 -> [0,9,"WebDriver:ExecuteAsyncScript",{"script":"var callback = arguments[arguments.length - 1];\n setTimeout(function() { callback(true); }, 500);","args":[],"newSandbox":true,"sandbox":"default","scriptTimeout":1000,"line":55,"filename":"D:\\task_171643887765338\\build\\tests\\marionette\\tests\\testing\\marionette\\harness\\marionette_harness\\tests\\unit\\test_execute_async_script.py"}]
[task 2024-05-23T04:44:31.467Z] 04:44:31 INFO - 1716439471467 RemoteAgent TRACE WebDriverProcessData actor created for PID 8260
[task 2024-05-23T04:44:31.468Z] 04:44:31 INFO - 1716439471467 Marionette TRACE [1] MarionetteCommands actor created for window id 2
[task 2024-05-23T04:44:32.542Z] 04:44:32 INFO - 1716439472541 Marionette DEBUG 68 <- [1,9,{"error":"script timeout","message":"Timed out after 1000 ms","stacktrace":"RemoteError@chrome://remote/content/shared/RemoteError.sys.mjs:8:8\nWebDriverError@chrome://remote/content/shared/webdriver/Er ... scriptTimeoutID<@chrome://remote/content/marionette/evaluate.sys.mjs:97:11\nnotify@resource://gre/modules/Timer.sys.mjs:49:17\n"},null]
[task 2024-05-23T04:44:32.597Z] 04:44:32 INFO - 1716439472596 Marionette DEBUG 68 -> [0,10,"WebDriver:SetTimeouts",{"script":1000}]
[task 2024-05-23T04:44:32.597Z] 04:44:32 INFO - 1716439472597 Marionette DEBUG 68 <- [1,10,null,{"value":null}]
[task 2024-05-23T04:44:32.604Z] 04:44:32 INFO - 1716439472604 Marionette DEBUG 68 -> [0,11,"Marionette:GetContext",{}]
[task 2024-05-23T04:44:32.605Z] 04:44:32 INFO - 1716439472604 Marionette DEBUG 68 <- [1,11,null,{"value":"chrome"}]
[task 2024-05-23T04:44:32.645Z] 04:44:32 INFO - 1716439472645 Marionette DEBUG 68 -> [0,12,"Marionette:SetContext",{"value":"chrome"}]
[task 2024-05-23T04:44:32.646Z] 04:44:32 INFO - 1716439472646 Marionette DEBUG 68 <- [1,12,null,{"value":null}]
[task 2024-05-23T04:44:32.648Z] 04:44:32 INFO - 1716439472648 Marionette DEBUG 68 -> [0,13,"WebDriver:TakeScreenshot",{"id":null,"full":true,"hash":false,"scroll":true}]
[task 2024-05-23T04:44:32.676Z] 04:44:32 INFO - [GFX3-]: Creating null Skia image from null SourceSurface
[task 2024-05-23T04:44:32.733Z] 04:44:32 INFO - 1716439472732 Marionette DEBUG 68 <- [1,13,null,{"value":"iVBORw0KGgoAAAANSUhEUgAABQAAAAPQCAYAAABpCtbiAAAgAElEQVR4XuzdB7gcVaEH8BNIA0KRiNIkIkVKaNJFaQ9QiiKCghUEhCAdKyCoqIgKBFAkqCgWpNkAB ... AAAECBAgQIECAAAECBAgQIECgIOAALKygAwECBAgQIECAAAECBAgQIECAAIGTgAPwBCuWAAECBAgQIECAAAECBAgQIECAQEFgU+nyluQdS5kAAAAASUVORK5CYII="}]
[task 2024-05-23T04:44:32.750Z] 04:44:32 INFO - [Child 7932, Main Thread] WARNING: JSWindowActorChild::SendRawMessage (Conduits, ConduitClosed) not sent: !CanSend() || !mManager || !mManager->CanSend(): file /builds/worker/checkouts/gecko/dom/ipc/jsactor/JSWindowActorChild.cpp:61
[task 2024-05-23T04:44:32.754Z] 04:44:32 INFO - 1716439472753 Marionette DEBUG 68 -> [0,14,"Marionette:SetContext",{"value":"chrome"}]
[task 2024-05-23T04:44:32.754Z] 04:44:32 INFO - 1716439472754 Marionette DEBUG 68 <- [1,14,null,{"value":null}]
[task 2024-05-23T04:44:32.809Z] 04:44:32 INFO - 1716439472808 Marionette DEBUG 68 -> [0,15,"Marionette:GetContext",{}]
[task 2024-05-23T04:44:32.809Z] 04:44:32 INFO - 1716439472809 Marionette DEBUG 68 <- [1,15,null,{"value":"chrome"}]
[task 2024-05-23T04:44:32.863Z] 04:44:32 INFO - 1716439472862 Marionette DEBUG 68 -> [0,16,"Marionette:SetContext",{"value":"content"}]
[task 2024-05-23T04:44:32.863Z] 04:44:32 INFO - 1716439472862 Marionette DEBUG 68 <- [1,16,null,{"value":null}]
[task 2024-05-23T04:44:32.915Z] 04:44:32 INFO - 1716439472915 Marionette DEBUG 68 -> [0,17,"WebDriver:GetPageSource",{}]
[task 2024-05-23T04:44:32.923Z] 04:44:32 INFO - 1716439472922 RemoteAgent TRACE WebDriverProcessData actor created for PID 8176
[task 2024-05-23T04:44:32.924Z] 04:44:32 INFO - 1716439472923 Marionette TRACE [98] MarionetteCommands actor created for window id 8589934594
[task 2024-05-23T04:44:32.969Z] 04:44:32 INFO - 1716439472968 Marionette DEBUG 68 <- [1,17,null,{"value":"<html><head>\n<title>Marionette Test</title>\n<style>\ninput[type=text], input[type=button] {\n appearance: none;\n}\n</style>\n</h ... disabled=\"\">\n <input id=\"createDivButton\" type=\"button\" value=\"create a div\" onclick=\"addDelayedElement()\">\n\n\n</body></html>"}]
[task 2024-05-23T04:44:33.022Z] 04:44:33 INFO - 1716439473021 Marionette DEBUG 68 -> [0,18,"Marionette:SetContext",{"value":"chrome"}]
[task 2024-05-23T04:44:33.023Z] 04:44:33 INFO - 1716439473022 Marionette DEBUG 68 <- [1,18,null,{"value":null}]
[task 2024-05-23T04:44:33.028Z] 04:44:33 ERROR - TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_execute_async_script.py TestExecuteAsyncChrome.test_script_timeout_no_timeout_error | marionette_driver.errors.ScriptTimeoutException: Timed out after 1000 ms
[task 2024-05-23T04:44:33.028Z] 04:44:33 INFO - stacktrace:
[task 2024-05-23T04:44:33.028Z] 04:44:33 INFO - RemoteError@chrome://remote/content/shared/RemoteError.sys.mjs:8:8
[task 2024-05-23T04:44:33.029Z] 04:44:33 INFO - WebDriverError@chrome://remote/content/shared/webdriver/Errors.sys.mjs:193:5
[task 2024-05-23T04:44:33.029Z] 04:44:33 INFO - ScriptTimeoutError@chrome://remote/content/shared/webdriver/Errors.sys.mjs:694:5
[task 2024-05-23T04:44:33.030Z] 04:44:33 INFO - evaluate.sandbox/timeoutPromise</scriptTimeoutID<@chrome://remote/content/marionette/evaluate.sys.mjs:97:11
[task 2024-05-23T04:44:33.030Z] 04:44:33 INFO - notify@resource://gre/modules/Timer.sys.mjs:49:17
[task 2024-05-23T04:44:33.031Z] 04:44:33 INFO - Traceback (most recent call last):
[task 2024-05-23T04:44:33.031Z] 04:44:33 INFO - File "D:\task_171643887765338\build\venv\Lib\site-packages\marionette_harness\marionette_test\testcases.py", line 198, in run
[task 2024-05-23T04:44:33.031Z] 04:44:33 INFO - testMethod()
[task 2024-05-23T04:44:33.032Z] 04:44:33 INFO - File "D:\task_171643887765338\build\tests\marionette\tests\testing\marionette\harness\marionette_harness\tests\unit\test_execute_async_script.py", line 55, in test_script_timeout_no_timeout_error
[task 2024-05-23T04:44:33.032Z] 04:44:33 INFO - self.marionette.execute_async_script(
[task 2024-05-23T04:44:33.032Z] 04:44:33 INFO - File "D:\task_171643887765338\build\venv\Lib\site-packages\marionette_driver\marionette.py", line 1929, in execute_async_script
[task 2024-05-23T04:44:33.033Z] 04:44:33 INFO - rv = self._send_message("WebDriver:ExecuteAsyncScript", body, key="value")
[task 2024-05-23T04:44:33.033Z] 04:44:33 INFO - ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
[task 2024-05-23T04:44:33.033Z] 04:44:33 INFO - File "D:\task_171643887765338\build\venv\Lib\site-packages\marionette_driver\decorators.py", line 24, in _
[task 2024-05-23T04:44:33.033Z] 04:44:33 INFO - return func(*args, **kwargs)
[task 2024-05-23T04:44:33.034Z] 04:44:33 INFO - ^^^^^^^^^^^^^^^^^^^^^
[task 2024-05-23T04:44:33.034Z] 04:44:33 INFO - File "D:\task_171643887765338\build\venv\Lib\site-packages\marionette_driver\marionette.py", line 776, in _send_message
[task 2024-05-23T04:44:33.034Z] 04:44:33 INFO - self._handle_error(err)
[task 2024-05-23T04:44:33.035Z] 04:44:33 INFO - File "D:\task_171643887765338\build\venv\Lib\site-packages\marionette_driver\marionette.py", line 788, in _handle_error
[task 2024-05-23T04:44:33.035Z] 04:44:33 INFO - raise errors.lookup(error)(message, stacktrace=stacktrace)
[task 2024-05-23T04:44:33.035Z] 04:44:33 INFO - TEST-INFO took 1628ms
[task 2024-05-23T04:44:33.064Z] 04:44:33 INFO - 1716439473064 Marionette DEBUG 68 -> [0,19,"WebDriver:GetAlertText",{}]
[task 2024-05-23T04:44:33.066Z] 04:44:33 INFO - 1716439473065 Marionette DEBUG 68 <- [1,19,{"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 2024-05-23T04:44:33.130Z] 04:44:33 INFO - 1716439473130 Marionette DEBUG 68 -> [0,20,"WebDriver:DeleteSession",{}]
[task 2024-05-23T04:44:33.132Z] 04:44:33 INFO - 1716439473132 Marionette TRACE [1] MarionetteCommands actor destroyed for window id 2
[task 2024-05-23T04:44:33.133Z] 04:44:33 INFO - 1716439473133 Marionette TRACE [98] MarionetteCommands actor destroyed for window id 8589934594
[task 2024-05-23T04:44:33.136Z] 04:44:33 INFO - 1716439473136 Marionette DEBUG 68 <- [1,20,null,{"value":null}]
[task 2024-05-23T04:44:33.139Z] 04:44:33 INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_execute_async_script.py TestExecuteAsyncChrome.test_script_timeout_reset_after_timeout_error
|
||
Comment 1•1 year ago
|
||
The script evaluation contains a call to setTimeout with a 500ms delay. Given that this is a debug build there might have been some further delay due to slower execution times. We probably should increase the script timeout a bit for the test test_script_timeout_no_timeout_error. I assume that 2000ms should be totally enough. Otherwise we probably can also use the timeout multiplier which would better accommodate different build types.
| Comment hidden (Intermittent Failures Robot) |
|
||
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
•