Closed
Bug 1816763
Opened 1 year ago
Closed 1 year ago
Intermittent testing/marionette/harness/marionette_harness/tests/unit/test_findelement_chrome.py TestElementsChrome.test_timeout_XUL | marionette_driver.errors.NoSuchElementException: Unable to locate element: myid
Categories
(Testing :: Marionette Client and Harness, defect, P5)
Testing
Marionette Client and Harness
Tracking
(Not tracked)
RESOLVED
INCOMPLETE
People
(Reporter: intermittent-bug-filer, Unassigned)
References
(Depends on 1 open bug)
Details
(Keywords: intermittent-failure)
Filed by: ctuns [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=405617991&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/A0CxNtmXSfS1hwKh_Da5gA/runs/0/artifacts/public/logs/live_backing.log
[task 2023-02-14T18:36:40.877Z] 18:36:40 INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_findelement_chrome.py TestElementsChrome.test_timeout_XUL
[task 2023-02-14T18:36:40.878Z] 18:36:40 INFO - 1676399800878 Marionette DEBUG Accepted connection 518 from 127.0.0.1:50603
[task 2023-02-14T18:36:40.897Z] 18:36:40 INFO - 1676399800898 Marionette DEBUG 518 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
[task 2023-02-14T18:36:40.899Z] 18:36:40 INFO - 1676399800899 Marionette DEBUG Waiting for initial application window
[task 2023-02-14T18:36:40.900Z] 18:36:40 INFO - 1676399800900 RemoteAgent TRACE [467] ProgressListener Start: expectNavigation=false resolveWhenStarted=false unloadTimeout=3200 waitForExplicitStart=false
[task 2023-02-14T18:36:40.901Z] 18:36:40 INFO - 1676399800900 RemoteAgent TRACE [467] ProgressListener Setting unload timer (3200ms)
[task 2023-02-14T18:36:40.901Z] 18:36:40 INFO - 1676399800900 RemoteAgent TRACE [467] Document already finished loading: data:application/xhtml+xml,%3C%21DOCTYPE%20html%20PUBLIC%20%22-//W3C//DTD%20XHTML%201.0%20Strict//EN%22%0A%20%20%20%20%22http ... 0A%20%20%3Cbody%3E%0A%20%20%20%20%3Cdiv%3E%3Cp%3Efoo%3C/p%3E%20%3Cp%3Ebar%3C/p%3E%3C/div%3E%0A%20%20%3C/body%3E%0A%3C/html%3E
[task 2023-02-14T18:36:40.902Z] 18:36:40 INFO - 1676399800900 RemoteAgent TRACE [467] ProgressListener Stop: has error=false
[task 2023-02-14T18:36:40.903Z] 18:36:40 INFO - 1676399800903 Marionette DEBUG 518 <- [1,1,null,{"sessionId":"7496cbf7-3eda-4058-ba9d-f8d9ed909a79","capabilities":{"browserName":"firefox","browserVersion":"112.0a1","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":"20230214161440","moz:headless":false,"moz:platformVersion":"10.0","moz:processID":7608,"moz:profile":"C:\\Users\\task_167639935268182\\AppData\\Local\\Temp\\tmpe1lyc2qk.mozrunner","moz:shutdownTimeout":180000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"moz:windowless":false,"proxy":{}}}]
[task 2023-02-14T18:36:40.904Z] 18:36:40 INFO - 1676399800904 Marionette DEBUG 518 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
[task 2023-02-14T18:36:40.904Z] 18:36:40 INFO - 1676399800904 Marionette DEBUG 518 <- [1,2,null,{"value":null}]
[task 2023-02-14T18:36:40.905Z] 18:36:40 INFO - 1676399800905 Marionette DEBUG 518 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
[task 2023-02-14T18:36:40.905Z] 18:36:40 INFO - 1676399800905 Marionette DEBUG 518 <- [1,3,null,{"value":null}]
[task 2023-02-14T18:36:40.906Z] 18:36:40 INFO - 1676399800906 Marionette DEBUG 518 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
[task 2023-02-14T18:36:40.906Z] 18:36:40 INFO - 1676399800906 Marionette DEBUG 518 <- [1,4,null,{"value":null}]
[task 2023-02-14T18:36:40.907Z] 18:36:40 INFO - 1676399800907 Marionette DEBUG 518 -> [0,5,"Marionette:GetContext",{}]
[task 2023-02-14T18:36:40.907Z] 18:36:40 INFO - 1676399800907 Marionette DEBUG 518 <- [1,5,null,{"value":"content"}]
[task 2023-02-14T18:36:40.908Z] 18:36:40 INFO - 1676399800908 Marionette DEBUG 518 -> [0,6,"Marionette:SetContext",{"value":"chrome"}]
[task 2023-02-14T18:36:40.908Z] 18:36:40 INFO - 1676399800908 Marionette DEBUG 518 <- [1,6,null,{"value":null}]
[task 2023-02-14T18:36:40.909Z] 18:36:40 INFO - 1676399800909 Marionette DEBUG 518 -> [0,7,"WebDriver:GetWindowHandle",{}]
[task 2023-02-14T18:36:40.909Z] 18:36:40 INFO - 1676399800909 Marionette DEBUG 518 <- [1,7,null,{"value":"58fd4db3-6d2a-41b6-8e0c-58cca8db8261"}]
[task 2023-02-14T18:36:40.910Z] 18:36:40 INFO - 1676399800910 Marionette DEBUG 518 -> [0,8,"Marionette:SetContext",{"value":"content"}]
[task 2023-02-14T18:36:40.910Z] 18:36:40 INFO - 1676399800910 Marionette DEBUG 518 <- [1,8,null,{"value":null}]
[task 2023-02-14T18:36:40.911Z] 18:36:40 INFO - 1676399800911 Marionette DEBUG 518 -> [0,9,"Marionette:GetContext",{}]
[task 2023-02-14T18:36:40.911Z] 18:36:40 INFO - 1676399800911 Marionette DEBUG 518 <- [1,9,null,{"value":"content"}]
[task 2023-02-14T18:36:40.912Z] 18:36:40 INFO - 1676399800912 Marionette DEBUG 518 -> [0,10,"Marionette:SetContext",{"value":"chrome"}]
[task 2023-02-14T18:36:40.912Z] 18:36:40 INFO - 1676399800912 Marionette DEBUG 518 <- [1,10,null,{"value":null}]
[task 2023-02-14T18:36:40.913Z] 18:36:40 INFO - 1676399800913 Marionette DEBUG 518 -> [0,11,"WebDriver:GetWindowHandles",{}]
[task 2023-02-14T18:36:40.913Z] 18:36:40 INFO - 1676399800913 Marionette DEBUG 518 <- [1,11,null,["58fd4db3-6d2a-41b6-8e0c-58cca8db8261"]]
[task 2023-02-14T18:36:40.914Z] 18:36:40 INFO - 1676399800914 Marionette DEBUG 518 -> [0,12,"Marionette:SetContext",{"value":"content"}]
[task 2023-02-14T18:36:40.915Z] 18:36:40 INFO - 1676399800915 Marionette DEBUG 518 <- [1,12,null,{"value":null}]
[task 2023-02-14T18:36:40.915Z] 18:36:40 INFO - 1676399800916 Marionette DEBUG 518 -> [0,13,"Marionette:GetContext",{}]
[task 2023-02-14T18:36:40.916Z] 18:36:40 INFO - 1676399800916 Marionette DEBUG 518 <- [1,13,null,{"value":"content"}]
[task 2023-02-14T18:36:40.917Z] 18:36:40 INFO - 1676399800916 Marionette DEBUG 518 -> [0,14,"Marionette:SetContext",{"value":"content"}]
[task 2023-02-14T18:36:40.917Z] 18:36:40 INFO - 1676399800917 Marionette DEBUG 518 <- [1,14,null,{"value":null}]
[task 2023-02-14T18:36:40.917Z] 18:36:40 INFO - 1676399800917 Marionette DEBUG 518 -> [0,15,"WebDriver:GetWindowHandle",{}]
[task 2023-02-14T18:36:40.918Z] 18:36:40 INFO - 1676399800917 Marionette DEBUG 518 <- [1,15,null,{"value":"a488b131-5a90-402c-a645-e1f83a064a28"}]
[task 2023-02-14T18:36:40.918Z] 18:36:40 INFO - 1676399800918 Marionette DEBUG 518 -> [0,16,"Marionette:SetContext",{"value":"content"}]
[task 2023-02-14T18:36:40.919Z] 18:36:40 INFO - 1676399800918 Marionette DEBUG 518 <- [1,16,null,{"value":null}]
[task 2023-02-14T18:36:40.919Z] 18:36:40 INFO - 1676399800919 Marionette DEBUG 518 -> [0,17,"Marionette:GetContext",{}]
[task 2023-02-14T18:36:40.919Z] 18:36:40 INFO - 1676399800919 Marionette DEBUG 518 <- [1,17,null,{"value":"content"}]
[task 2023-02-14T18:36:40.920Z] 18:36:40 INFO - 1676399800920 Marionette DEBUG 518 -> [0,18,"Marionette:SetContext",{"value":"content"}]
[task 2023-02-14T18:36:40.920Z] 18:36:40 INFO - 1676399800920 Marionette DEBUG 518 <- [1,18,null,{"value":null}]
[task 2023-02-14T18:36:40.921Z] 18:36:40 INFO - 1676399800921 Marionette DEBUG 518 -> [0,19,"WebDriver:GetWindowHandles",{}]
[task 2023-02-14T18:36:40.921Z] 18:36:40 INFO - 1676399800921 Marionette DEBUG 518 <- [1,19,null,["a488b131-5a90-402c-a645-e1f83a064a28"]]
[task 2023-02-14T18:36:40.922Z] 18:36:40 INFO - 1676399800922 Marionette DEBUG 518 -> [0,20,"Marionette:SetContext",{"value":"content"}]
[task 2023-02-14T18:36:40.922Z] 18:36:40 INFO - 1676399800922 Marionette DEBUG 518 <- [1,20,null,{"value":null}]
[task 2023-02-14T18:36:40.923Z] 18:36:40 INFO - 1676399800923 Marionette DEBUG 518 -> [0,21,"Marionette:SetContext",{"value":"chrome"}]
[task 2023-02-14T18:36:40.923Z] 18:36:40 INFO - 1676399800923 Marionette DEBUG 518 <- [1,21,null,{"value":null}]
[task 2023-02-14T18:36:40.924Z] 18:36:40 INFO - 1676399800923 Marionette DEBUG 518 -> [0,22,"Marionette:GetContext",{}]
[task 2023-02-14T18:36:40.924Z] 18:36:40 INFO - 1676399800923 Marionette DEBUG 518 <- [1,22,null,{"value":"chrome"}]
[task 2023-02-14T18:36:40.924Z] 18:36:40 INFO - 1676399800924 Marionette DEBUG 518 -> [0,23,"Marionette:SetContext",{"value":"chrome"}]
[task 2023-02-14T18:36:40.925Z] 18:36:40 INFO - 1676399800924 Marionette DEBUG 518 <- [1,23,null,{"value":null}]
[task 2023-02-14T18:36:40.925Z] 18:36:40 INFO - 1676399800925 Marionette DEBUG 518 -> [0,24,"Marionette:GetContext",{}]
[task 2023-02-14T18:36:40.925Z] 18:36:40 INFO - 1676399800925 Marionette DEBUG 518 <- [1,24,null,{"value":"chrome"}]
[task 2023-02-14T18:36:40.926Z] 18:36:40 INFO - 1676399800926 Marionette DEBUG 518 -> [0,25,"Marionette:SetContext",{"value":"chrome"}]
[task 2023-02-14T18:36:40.926Z] 18:36:40 INFO - 1676399800926 Marionette DEBUG 518 <- [1,25,null,{"value":null}]
[task 2023-02-14T18:36:40.927Z] 18:36:40 INFO - 1676399800927 Marionette DEBUG 518 -> [0,26,"WebDriver:GetWindowHandles",{}]
[task 2023-02-14T18:36:40.927Z] 18:36:40 INFO - 1676399800927 Marionette DEBUG 518 <- [1,26,null,["58fd4db3-6d2a-41b6-8e0c-58cca8db8261"]]
[task 2023-02-14T18:36:40.928Z] 18:36:40 INFO - 1676399800928 Marionette DEBUG 518 -> [0,27,"Marionette:SetContext",{"value":"chrome"}]
[task 2023-02-14T18:36:40.928Z] 18:36:40 INFO - 1676399800928 Marionette DEBUG 518 <- [1,27,null,{"value":null}]
[task 2023-02-14T18:36:40.931Z] 18:36:40 INFO - 1676399800932 Marionette DEBUG 518 -> [0,28,"Marionette:GetContext",{}]
[task 2023-02-14T18:36:40.932Z] 18:36:40 INFO - 1676399800932 Marionette DEBUG 518 <- [1,28,null,{"value":"chrome"}]
[task 2023-02-14T18:36:40.934Z] 18:36:40 INFO - 1676399800934 Marionette DEBUG 518 -> [0,29,"Marionette:SetContext",{"value":"content"}]
[task 2023-02-14T18:36:40.935Z] 18:36:40 INFO - 1676399800935 Marionette DEBUG 518 <- [1,29,null,{"value":null}]
[task 2023-02-14T18:36:40.935Z] 18:36:40 INFO - 1676399800935 Marionette DEBUG 518 -> [0,30,"WebDriver:GetWindowHandles",{}]
[task 2023-02-14T18:36:40.936Z] 18:36:40 INFO - 1676399800935 Marionette DEBUG 518 <- [1,30,null,["a488b131-5a90-402c-a645-e1f83a064a28"]]
[task 2023-02-14T18:36:40.936Z] 18:36:40 INFO - 1676399800936 Marionette DEBUG 518 -> [0,31,"Marionette:SetContext",{"value":"chrome"}]
[task 2023-02-14T18:36:40.937Z] 18:36:40 INFO - 1676399800936 Marionette DEBUG 518 <- [1,31,null,{"value":null}]
[task 2023-02-14T18:36:40.937Z] 18:36:40 INFO - 1676399800937 Marionette DEBUG 518 -> [0,32,"Marionette:GetContext",{}]
[task 2023-02-14T18:36:40.937Z] 18:36:40 INFO - 1676399800937 Marionette DEBUG 518 <- [1,32,null,{"value":"chrome"}]
[task 2023-02-14T18:36:40.938Z] 18:36:40 INFO - 1676399800938 Marionette DEBUG 518 -> [0,33,"Marionette:SetContext",{"value":"chrome"}]
[task 2023-02-14T18:36:40.938Z] 18:36:40 INFO - 1676399800938 Marionette DEBUG 518 <- [1,33,null,{"value":null}]
[task 2023-02-14T18:36:40.939Z] 18:36:40 INFO - 1676399800939 Marionette DEBUG 518 -> [0,34,"WebDriver:ExecuteAsyncScript",{"script":"let [url, focus, resolve] = arguments;\n\n function waitForEvent(target, type, args) {\n ret ... await focused;\n }\n\n resolve(win.docShell.browsingContext.id);\n })();","args":["chrome://remote/content/marionette/test.xhtml",false],"newSandbox":true,"sandbox":"default","scriptTimeout":null,"line":166,"filename":"Z:\\task_167639935268182\\build\\venv\\lib\\site-packages\\marionette_harness\\runner\\mixins\\window_manager.py"}]
[task 2023-02-14T18:36:40.940Z] 18:36:40 INFO - 1676399800940 RemoteAgent TRACE WebDriverProcessData actor created for PID 7608
[task 2023-02-14T18:36:40.941Z] 18:36:40 INFO - 1676399800940 Marionette TRACE [1] MarionetteCommands actor created for window id 2
[task 2023-02-14T18:36:40.942Z] 18:36:40 INFO - 1676399800947 Marionette TRACE Received observer notification domwindowopened
[task 2023-02-14T18:36:40.950Z] 18:36:40 INFO - ** Received DOM event activate for [object Window]
[task 2023-02-14T18:36:40.953Z] 18:36:40 INFO - ** Received DOM event focus for [object HTMLDocument]
[task 2023-02-14T18:36:40.960Z] 18:36:40 INFO - ** Received DOM event activate for [object Window]
[task 2023-02-14T18:36:40.961Z] 18:36:40 INFO - ** Received DOM event focus for [object HTMLDocument]
[task 2023-02-14T18:36:40.961Z] 18:36:40 INFO - 1676399800964 Marionette DEBUG 518 <- [1,34,null,{"value":520}]
[task 2023-02-14T18:36:40.997Z] 18:36:40 INFO - 1676399800999 Marionette DEBUG 518 -> [0,35,"Marionette:SetContext",{"value":"chrome"}]
[task 2023-02-14T18:36:41.000Z] 18:36:41 INFO - 1676399801000 Marionette DEBUG 518 <- [1,35,null,{"value":null}]
[task 2023-02-14T18:36:41.033Z] 18:36:41 INFO - 1676399801047 Marionette DEBUG 518 -> [0,36,"Marionette:GetContext",{}]
[task 2023-02-14T18:36:41.048Z] 18:36:41 INFO - 1676399801047 Marionette DEBUG 518 <- [1,36,null,{"value":"chrome"}]
[task 2023-02-14T18:36:41.074Z] 18:36:41 INFO - 1676399801088 Marionette DEBUG 518 -> [0,37,"Marionette:SetContext",{"value":"chrome"}]
[task 2023-02-14T18:36:41.089Z] 18:36:41 INFO - 1676399801089 Marionette DEBUG 518 <- [1,37,null,{"value":null}]
[task 2023-02-14T18:36:41.195Z] 18:36:41 INFO - 1676399801195 Marionette DEBUG 518 -> [0,38,"WebDriver:GetWindowHandles",{}]
[task 2023-02-14T18:36:41.196Z] 18:36:41 INFO - 1676399801196 Marionette DEBUG 518 <- [1,38,null,["58fd4db3-6d2a-41b6-8e0c-58cca8db8261","6f487d5b-4e1a-4ab3-8b57-4e309d67ed1a"]]
[task 2023-02-14T18:36:41.201Z] 18:36:41 INFO - 1676399801201 Marionette DEBUG 518 -> [0,39,"Marionette:SetContext",{"value":"chrome"}]
[task 2023-02-14T18:36:41.202Z] 18:36:41 INFO - 1676399801201 Marionette DEBUG 518 <- [1,39,null,{"value":null}]
[task 2023-02-14T18:36:41.203Z] 18:36:41 INFO - 1676399801202 Marionette DEBUG 518 -> [0,40,"Marionette:GetContext",{}]
[task 2023-02-14T18:36:41.203Z] 18:36:41 INFO - 1676399801202 Marionette DEBUG 518 <- [1,40,null,{"value":"chrome"}]
[task 2023-02-14T18:36:41.205Z] 18:36:41 INFO - 1676399801205 Marionette DEBUG 518 -> [0,41,"Marionette:SetContext",{"value":"chrome"}]
[task 2023-02-14T18:36:41.205Z] 18:36:41 INFO - 1676399801205 Marionette DEBUG 518 <- [1,41,null,{"value":null}]
[task 2023-02-14T18:36:41.206Z] 18:36:41 INFO - 1676399801206 Marionette DEBUG 518 -> [0,42,"WebDriver:GetWindowHandles",{}]
[task 2023-02-14T18:36:41.207Z] 18:36:41 INFO - 1676399801206 Marionette DEBUG 518 <- [1,42,null,["58fd4db3-6d2a-41b6-8e0c-58cca8db8261","6f487d5b-4e1a-4ab3-8b57-4e309d67ed1a"]]
[task 2023-02-14T18:36:41.208Z] 18:36:41 INFO - 1676399801208 Marionette DEBUG 518 -> [0,43,"Marionette:SetContext",{"value":"chrome"}]
[task 2023-02-14T18:36:41.208Z] 18:36:41 INFO - 1676399801208 Marionette DEBUG 518 <- [1,43,null,{"value":null}]
[task 2023-02-14T18:36:41.209Z] 18:36:41 INFO - 1676399801209 Marionette DEBUG 518 -> [0,44,"Marionette:GetContext",{}]
[task 2023-02-14T18:36:41.209Z] 18:36:41 INFO - 1676399801209 Marionette DEBUG 518 <- [1,44,null,{"value":"chrome"}]
[task 2023-02-14T18:36:41.211Z] 18:36:41 INFO - 1676399801210 Marionette DEBUG 518 -> [0,45,"Marionette:SetContext",{"value":"chrome"}]
[task 2023-02-14T18:36:41.211Z] 18:36:41 INFO - 1676399801210 Marionette DEBUG 518 <- [1,45,null,{"value":null}]
[task 2023-02-14T18:36:41.213Z] 18:36:41 INFO - 1676399801212 Marionette DEBUG 518 -> [0,46,"WebDriver:ExecuteScript",{"script":"const { windowManager } = ChromeUtils.importESModule(\n \"chrome://remote/content/shared/WindowManager.sys.m ... nst win = windowManager.findWindowByHandle(arguments[0]).win;\n return win.document.readyState == \"complete\";","args":["6f487d5b-4e1a-4ab3-8b57-4e309d67ed1a"],"newSandbox":true,"sandbox":"default","line":95,"filename":"Z:\\task_167639935268182\\build\\venv\\lib\\site-packages\\marionette_harness\\runner\\mixins\\window_manager.py"}]
[task 2023-02-14T18:36:41.216Z] 18:36:41 INFO - 1676399801216 Marionette DEBUG 518 <- [1,46,null,{"value":true}]
[task 2023-02-14T18:36:41.217Z] 18:36:41 INFO - 1676399801216 Marionette DEBUG 518 -> [0,47,"Marionette:SetContext",{"value":"chrome"}]
[task 2023-02-14T18:36:41.217Z] 18:36:41 INFO - 1676399801217 Marionette DEBUG 518 <- [1,47,null,{"value":null}]
[task 2023-02-14T18:36:41.218Z] 18:36:41 INFO - 1676399801217 Marionette DEBUG 518 -> [0,48,"Marionette:GetContext",{}]
[task 2023-02-14T18:36:41.218Z] 18:36:41 INFO - 1676399801218 Marionette DEBUG 518 <- [1,48,null,{"value":"chrome"}]
[task 2023-02-14T18:36:41.218Z] 18:36:41 INFO - 1676399801218 Marionette DEBUG 518 -> [0,49,"Marionette:SetContext",{"value":"chrome"}]
[task 2023-02-14T18:36:41.219Z] 18:36:41 INFO - 1676399801218 Marionette DEBUG 518 <- [1,49,null,{"value":null}]
[task 2023-02-14T18:36:41.219Z] 18:36:41 INFO - 1676399801219 Marionette DEBUG 518 -> [0,50,"WebDriver:SwitchToWindow",{"handle":"6f487d5b-4e1a-4ab3-8b57-4e309d67ed1a","focus":true}]
[task 2023-02-14T18:36:41.220Z] 18:36:41 INFO - 1676399801220 Marionette DEBUG 518 <- [1,50,null,{"value":null}]
[task 2023-02-14T18:36:41.220Z] 18:36:41 INFO - 1676399801220 Marionette DEBUG 518 -> [0,51,"WebDriver:FindElement",{"value":"myid","using":"id"}]
[task 2023-02-14T18:36:41.221Z] 18:36:41 INFO - 1676399801221 Marionette TRACE [520] MarionetteCommands actor created for window id 1051
[task 2023-02-14T18:36:41.223Z] 18:36:41 INFO - 1676399801222 Marionette DEBUG 518 <- [1,51,{"error":"no such element","message":"Unable to locate element: myid","stacktrace":"RemoteError@chrome://remote/content/shared/RemoteError.sys.mjs:8:8\nWebDriverError@chrome://remote/content/shared/webdriver/Er ... ote/content/shared/webdriver/Errors.sys.mjs:392:5\nelement.find/</<@chrome://remote/content/marionette/element.sys.mjs:134:16\n"},null]
[task 2023-02-14T18:36:41.223Z] 18:36:41 INFO - 1676399801223 Marionette DEBUG 518 -> [0,52,"WebDriver:SetTimeouts",{"implicit":4000}]
[task 2023-02-14T18:36:41.223Z] 18:36:41 INFO - 1676399801223 Marionette DEBUG 518 <- [1,52,null,{"value":null}]
[task 2023-02-14T18:36:41.225Z] 18:36:41 INFO - 1676399801224 Marionette DEBUG 518 -> [0,53,"WebDriver:ExecuteScript",{"script":"window.setTimeout(function () {\n var b = window.document.createXULElement('button');\n b.id = 'myid';\n document.getElementById('things').appendChild(b);\n }, 1000);","args":[],"newSandbox":true,"sandbox":"default","line":153,"filename":"Z:\\task_167639935268182\\build\\tests\\marionette\\tests\\testing\\marionette\\harness\\marionette_harness\\tests\\unit\\test_findelement_chrome.py"}]
[task 2023-02-14T18:36:41.228Z] 18:36:41 INFO - 1676399801228 Marionette DEBUG 518 <- [1,53,null,{"value":null}]
[task 2023-02-14T18:36:41.228Z] 18:36:41 INFO - 1676399801229 Marionette DEBUG 518 -> [0,54,"WebDriver:FindElement",{"value":"myid","using":"id"}]
[task 2023-02-14T18:36:46.348Z] 18:36:46 INFO - 1676399806352 Marionette DEBUG 518 <- [1,54,{"error":"no such element","message":"Unable to locate element: myid","stacktrace":"RemoteError@chrome://remote/content/shared/RemoteError.sys.mjs:8:8\nWebDriverError@chrome://remote/content/shared/webdriver/Er ... ote/content/shared/webdriver/Errors.sys.mjs:392:5\nelement.find/</<@chrome://remote/content/marionette/element.sys.mjs:134:16\n"},null]
[task 2023-02-14T18:36:46.489Z] 18:36:46 INFO - 1676399806489 Marionette DEBUG 518 -> [0,55,"Marionette:GetContext",{}]
[task 2023-02-14T18:36:46.490Z] 18:36:46 INFO - 1676399806490 Marionette DEBUG 518 <- [1,55,null,{"value":"chrome"}]
[task 2023-02-14T18:36:46.491Z] 18:36:46 INFO - 1676399806491 Marionette DEBUG 518 -> [0,56,"Marionette:SetContext",{"value":"chrome"}]
[task 2023-02-14T18:36:46.491Z] 18:36:46 INFO - 1676399806491 Marionette DEBUG 518 <- [1,56,null,{"value":null}]
[task 2023-02-14T18:36:46.492Z] 18:36:46 INFO - 1676399806492 Marionette DEBUG 518 -> [0,57,"WebDriver:TakeScreenshot",{"id":null,"full":true,"hash":false,"scroll":true}]
[task 2023-02-14T18:36:46.504Z] 18:36:46 INFO - 1676399806505 Marionette DEBUG 518 <- [1,57,null,{"value":"iVBORw0KGgoAAAANSUhEUgAAAL0AAAHXCAYAAADpz1u4AAAWUklEQVR4Xu2dQWwVVdvHT7efLtBVaWvQFX4GFo1NikiMoQoGFxaFbjQYpZLUhSksqAmhJk0wwgKIM ... RQPrSUHMgLQSQXksS1FEaAaQvDTUH0kIA6bUkQR2lEUD60lBzIC0EkF5LEtRRGgGkLw01B9JCAOm1JEEdpRFA+tJQcyAtBP4fArQdi8hCeoMAAAAASUVORK5CYII="}]
[task 2023-02-14T18:36:46.506Z] 18:36:46 INFO - 1676399806506 Marionette DEBUG 518 -> [0,58,"Marionette:SetContext",{"value":"chrome"}]
[task 2023-02-14T18:36:46.506Z] 18:36:46 INFO - 1676399806506 Marionette DEBUG 518 <- [1,58,null,{"value":null}]
[task 2023-02-14T18:36:46.507Z] 18:36:46 INFO - 1676399806507 Marionette DEBUG 518 -> [0,59,"Marionette:GetContext",{}]
[task 2023-02-14T18:36:46.507Z] 18:36:46 INFO - 1676399806507 Marionette DEBUG 518 <- [1,59,null,{"value":"chrome"}]
[task 2023-02-14T18:36:46.508Z] 18:36:46 INFO - 1676399806508 Marionette DEBUG 518 -> [0,60,"Marionette:SetContext",{"value":"content"}]
[task 2023-02-14T18:36:46.508Z] 18:36:46 INFO - 1676399806508 Marionette DEBUG 518 <- [1,60,null,{"value":null}]
[task 2023-02-14T18:36:46.509Z] 18:36:46 INFO - 1676399806509 Marionette DEBUG 518 -> [0,61,"WebDriver:GetPageSource",{}]
[task 2023-02-14T18:36:46.510Z] 18:36:46 INFO - 1676399806509 Marionette DEBUG 518 <- [1,61,{"error":"no such window","message":"Browsing context has been discarded","stacktrace":"RemoteError@chrome://remote/content/shared/RemoteError.sys.mjs:8:8\nWebDriverError@chrome://remote/content/shared/webdriver/Er ... ote/content/marionette/server.sys.mjs:250:9\n_onJSONObjectReady/<@chrome://remote/content/marionette/transport.sys.mjs:496:20\n"},null]
[task 2023-02-14T18:36:46.510Z] 18:36:46 INFO - 1676399806510 Marionette DEBUG 518 -> [0,62,"Marionette:SetContext",{"value":"chrome"}]
[task 2023-02-14T18:36:46.511Z] 18:36:46 INFO - 1676399806510 Marionette DEBUG 518 <- [1,62,null,{"value":null}]
[task 2023-02-14T18:36:46.511Z] 18:36:46 INFO - Failed to gather test failure debug: Browsing context has been discarded
[task 2023-02-14T18:36:46.511Z] 18:36:46 INFO - stacktrace:
[task 2023-02-14T18:36:46.511Z] 18:36:46 INFO - RemoteError@chrome://remote/content/shared/RemoteError.sys.mjs:8:8
[task 2023-02-14T18:36:46.512Z] 18:36:46 INFO - WebDriverError@chrome://remote/content/shared/webdriver/Errors.sys.mjs:180:5
[task 2023-02-14T18:36:46.512Z] 18:36:46 INFO - NoSuchWindowError@chrome://remote/content/shared/webdriver/Errors.sys.mjs:434:5
[task 2023-02-14T18:36:46.512Z] 18:36:46 INFO - assert.that/<@chrome://remote/content/shared/webdriver/Assert.sys.mjs:485:13
[task 2023-02-14T18:36:46.512Z] 18:36:46 INFO - assert.open@chrome://remote/content/shared/webdriver/Assert.sys.mjs:147:4
[task 2023-02-14T18:36:46.513Z] 18:36:46 INFO - GeckoDriver.prototype.getPageSource@chrome://remote/content/marionette/driver.sys.mjs:915:15
[task 2023-02-14T18:36:46.513Z] 18:36:46 INFO - despatch@chrome://remote/content/marionette/server.sys.mjs:303:40
[task 2023-02-14T18:36:46.513Z] 18:36:46 INFO - execute@chrome://remote/content/marionette/server.sys.mjs:276:16
[task 2023-02-14T18:36:46.513Z] 18:36:46 INFO - onPacket/<@chrome://remote/content/marionette/server.sys.mjs:249:20
[task 2023-02-14T18:36:46.514Z] 18:36:46 INFO - onPacket@chrome://remote/content/marionette/server.sys.mjs:250:9
[task 2023-02-14T18:36:46.514Z] 18:36:46 INFO - _onJSONObjectReady/<@chrome://remote/content/marionette/transport.sys.mjs:496:20
[task 2023-02-14T18:36:46.515Z] 18:36:46 ERROR - TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_findelement_chrome.py TestElementsChrome.test_timeout_XUL | marionette_driver.errors.NoSuchElementException: Unable to locate element: myid
[task 2023-02-14T18:36:46.515Z] 18:36:46 INFO - stacktrace:
[task 2023-02-14T18:36:46.515Z] 18:36:46 INFO - RemoteError@chrome://remote/content/shared/RemoteError.sys.mjs:8:8
[task 2023-02-14T18:36:46.516Z] 18:36:46 INFO - WebDriverError@chrome://remote/content/shared/webdriver/Errors.sys.mjs:180:5
[task 2023-02-14T18:36:46.516Z] 18:36:46 INFO - NoSuchElementError@chrome://remote/content/shared/webdriver/Errors.sys.mjs:392:5
[task 2023-02-14T18:36:46.516Z] 18:36:46 INFO - element.find/</<@chrome://remote/content/marionette/element.sys.mjs:134:16
[task 2023-02-14T18:36:46.516Z] 18:36:46 INFO - Traceback (most recent call last):
[task 2023-02-14T18:36:46.517Z] 18:36:46 INFO - File "Z:\task_167639935268182\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 198, in run
[task 2023-02-14T18:36:46.517Z] 18:36:46 INFO - testMethod()
[task 2023-02-14T18:36:46.517Z] 18:36:46 INFO - File "Z:\task_167639935268182\build\venv\lib\site-packages\marionette_harness\marionette_test\testcases.py", line 48, in wrapper
[task 2023-02-14T18:36:46.517Z] 18:36:46 INFO - return func(self, *args, **kwargs)
[task 2023-02-14T18:36:46.518Z] 18:36:46 INFO - File "Z:\task_167639935268182\build\tests\marionette\tests\testing\marionette\harness\marionette_harness\tests\unit\test_findelement_chrome.py", line 161, in test_timeout
[task 2023-02-14T18:36:46.518Z] 18:36:46 INFO - found_el = self.marionette.find_element(By.ID, "myid")
[task 2023-02-14T18:36:46.518Z] 18:36:46 INFO - File "Z:\task_167639935268182\build\venv\lib\site-packages\marionette_driver\marionette.py", line 1843, in find_element
[task 2023-02-14T18:36:46.519Z] 18:36:46 INFO - return self._send_message("WebDriver:FindElement", body, key="value")
[task 2023-02-14T18:36:46.519Z] 18:36:46 INFO - File "Z:\task_167639935268182\build\venv\lib\site-packages\marionette_driver\decorators.py", line 24, in _
[task 2023-02-14T18:36:46.519Z] 18:36:46 INFO - return func(*args, **kwargs)
[task 2023-02-14T18:36:46.519Z] 18:36:46 INFO - File "Z:\task_167639935268182\build\venv\lib\site-packages\marionette_driver\marionette.py", line 663, in _send_message
[task 2023-02-14T18:36:46.520Z] 18:36:46 INFO - self._handle_error(err)
[task 2023-02-14T18:36:46.520Z] 18:36:46 INFO - File "Z:\task_167639935268182\build\venv\lib\site-packages\marionette_driver\marionette.py", line 675, in _handle_error
[task 2023-02-14T18:36:46.520Z] 18:36:46 INFO - raise errors.lookup(error)(message, stacktrace=stacktrace)
[task 2023-02-14T18:36:46.520Z] 18:36:46 INFO - TEST-INFO took 5635ms
[task 2023-02-14T18:36:46.521Z] 18:36:46 INFO - 1676399806514 Marionette DEBUG 518 -> [0,63,"Marionette:GetContext",{}]
[task 2023-02-14T18:36:46.521Z] 18:36:46 INFO - 1676399806514 Marionette DEBUG 518 <- [1,63,null,{"value":"chrome"}]
[task 2023-02-14T18:36:46.522Z] 18:36:46 INFO - 1676399806515 Marionette DEBUG 518 -> [0,64,"Marionette:SetContext",{"value":"chrome"}]
[task 2023-02-14T18:36:46.522Z] 18:36:46 INFO - 1676399806515 Marionette DEBUG 518 <- [1,64,null,{"value":null}]
[task 2023-02-14T18:36:46.522Z] 18:36:46 INFO - 1676399806516 Marionette DEBUG 518 -> [0,65,"WebDriver:GetWindowHandles",{}]
[task 2023-02-14T18:36:46.523Z] 18:36:46 INFO - 1676399806516 Marionette DEBUG 518 <- [1,65,null,["58fd4db3-6d2a-41b6-8e0c-58cca8db8261","6f487d5b-4e1a-4ab3-8b57-4e309d67ed1a"]]
[task 2023-02-14T18:36:46.523Z] 18:36:46 INFO - 1676399806517 Marionette DEBUG 518 -> [0,66,"Marionette:SetContext",{"value":"chrome"}]
[task 2023-02-14T18:36:46.523Z] 18:36:46 INFO - 1676399806517 Marionette DEBUG 518 <- [1,66,null,{"value":null}]
[task 2023-02-14T18:36:46.524Z] 18:36:46 INFO - 1676399806518 Marionette DEBUG 518 -> [0,67,"WebDriver:SwitchToWindow",{"handle":"6f487d5b-4e1a-4ab3-8b57-4e309d67ed1a","focus":true}]
[task 2023-02-14T18:36:46.524Z] 18:36:46 INFO - 1676399806518 Marionette DEBUG 518 <- [1,67,null,{"value":null}]
[task 2023-02-14T18:36:46.524Z] 18:36:46 INFO - 1676399806519 Marionette DEBUG 518 -> [0,68,"WebDriver:CloseChromeWindow",{}]
[task 2023-02-14T18:36:46.536Z] 18:36:46 INFO - 1676399806539 Marionette TRACE Received observer notification xul-window-destroyed
[task 2023-02-14T18:36:46.540Z] 18:36:46 INFO - 1676399806539 Marionette DEBUG 518 <- [1,68,null,["58fd4db3-6d2a-41b6-8e0c-58cca8db8261"]]
[task 2023-02-14T18:36:46.547Z] 18:36:46 INFO - 1676399806547 Marionette TRACE [520] MarionetteCommands actor destroyed for window id 1051
[task 2023-02-14T18:36:46.548Z] 18:36:46 INFO - 1676399806548 Marionette DEBUG 518 -> [0,69,"WebDriver:SwitchToWindow",{"handle":"58fd4db3-6d2a-41b6-8e0c-58cca8db8261","focus":true}]
[task 2023-02-14T18:36:46.548Z] 18:36:46 INFO - 1676399806548 Marionette DEBUG 518 <- [1,69,null,{"value":null}]
[task 2023-02-14T18:36:46.549Z] 18:36:46 INFO - DEBUG: Adding blocker Transaction (26) for phase places.sqlite#0: waiting for clients
[task 2023-02-14T18:36:46.550Z] 18:36:46 INFO - 1676399806550 Marionette DEBUG 518 -> [0,70,"Marionette:GetContext",{}]
[task 2023-02-14T18:36:46.550Z] 18:36:46 INFO - 1676399806550 Marionette DEBUG 518 <- [1,70,null,{"value":"chrome"}]
[task 2023-02-14T18:36:46.551Z] 18:36:46 INFO - 1676399806551 Marionette DEBUG 518 -> [0,71,"Marionette:SetContext",{"value":"chrome"}]
[task 2023-02-14T18:36:46.552Z] 18:36:46 INFO - 1676399806552 Marionette DEBUG 518 <- [1,71,null,{"value":null}]
[task 2023-02-14T18:36:46.552Z] 18:36:46 INFO - 1676399806553 Marionette DEBUG 518 -> [0,72,"WebDriver:GetWindowHandles",{}]
[task 2023-02-14T18:36:46.553Z] 18:36:46 INFO - 1676399806553 Marionette DEBUG 518 <- [1,72,null,["58fd4db3-6d2a-41b6-8e0c-58cca8db8261"]]
[task 2023-02-14T18:36:46.554Z] 18:36:46 INFO - 1676399806554 Marionette DEBUG 518 -> [0,73,"Marionette:SetContext",{"value":"chrome"}]
[task 2023-02-14T18:36:46.554Z] 18:36:46 INFO - 1676399806554 Marionette DEBUG 518 <- [1,73,null,{"value":null}]
[task 2023-02-14T18:36:46.555Z] 18:36:46 INFO - 1676399806555 Marionette DEBUG 518 -> [0,74,"Marionette:GetContext",{}]
[task 2023-02-14T18:36:46.555Z] 18:36:46 INFO - 1676399806555 Marionette DEBUG 518 <- [1,74,null,{"value":"chrome"}]
[task 2023-02-14T18:36:46.556Z] 18:36:46 INFO - 1676399806556 Marionette DEBUG 518 -> [0,75,"Marionette:SetContext",{"value":"content"}]
[task 2023-02-14T18:36:46.556Z] 18:36:46 INFO - 1676399806556 Marionette DEBUG 518 <- [1,75,null,{"value":null}]
[task 2023-02-14T18:36:46.557Z] 18:36:46 INFO - 1676399806557 Marionette DEBUG 518 -> [0,76,"WebDriver:GetWindowHandles",{}]
[task 2023-02-14T18:36:46.557Z] 18:36:46 INFO - 1676399806557 Marionette DEBUG 518 <- [1,76,null,["a488b131-5a90-402c-a645-e1f83a064a28"]]
[task 2023-02-14T18:36:46.558Z] 18:36:46 INFO - 1676399806558 Marionette DEBUG 518 -> [0,77,"Marionette:SetContext",{"value":"chrome"}]
[task 2023-02-14T18:36:46.558Z] 18:36:46 INFO - 1676399806558 Marionette DEBUG 518 <- [1,77,null,{"value":null}]
[task 2023-02-14T18:36:46.558Z] 18:36:46 INFO - 1676399806558 Marionette DEBUG 518 -> [0,78,"WebDriver:DeleteSession",{}]
[task 2023-02-14T18:36:46.559Z] 18:36:46 INFO - 1676399806559 Marionette TRACE [1] MarionetteCommands actor destroyed for window id 2
[task 2023-02-14T18:36:46.561Z] 18:36:46 INFO - 1676399806561 Marionette DEBUG 518 <- [1,78,null,{"value":null}]
[task 2023-02-14T18:36:46.562Z] 18:36:46 INFO - 1676399806561 Marionette DEBUG Closed connection 518
[task 2023-02-14T18:36:46.562Z] 18:36:46 INFO - TEST-START | testing/marionette/harness/marionette_harness/tests/unit/test_findelement_chrome.py TestElementsChrome.test_xpath_XHTML
| Comment hidden (Intermittent Failures Robot) |
|
||
Comment 2•1 year ago
|
||
The exact failure happens at:
https://treeherder.mozilla.org/logviewer?job_id=405617991&repo=mozilla-central&lineNumber=34845-34848
[task 2023-02-14T18:36:41.225Z] 18:36:41 INFO - 1676399801224 Marionette DEBUG 518 -> [0,53,"WebDriver:ExecuteScript",{"script":"window.setTimeout(function () {\n var b = window.document.createXULElement('button');\n b.id = 'myid';\n document.getElementById('things').appendChild(b);\n }, 1000);","args":[],"newSandbox":true,"sandbox":"default","line":153,"filename":"Z:\\task_167639935268182\\build\\tests\\marionette\\tests\\testing\\marionette\\harness\\marionette_harness\\tests\\unit\\test_findelement_chrome.py"}]
[task 2023-02-14T18:36:41.228Z] 18:36:41 INFO - 1676399801228 Marionette DEBUG 518 <- [1,53,null,{"value":null}]
[task 2023-02-14T18:36:41.228Z] 18:36:41 INFO - 1676399801229 Marionette DEBUG 518 -> [0,54,"WebDriver:FindElement",{"value":"myid","using":"id"}]
[task 2023-02-14T18:36:46.348Z] 18:36:46 INFO - 1676399806352 Marionette DEBUG 518 <- [1,54,{"error":"no such element","message":"Unable to locate element: myid","stacktrace":"RemoteError@chrome://remote/content/shared/RemoteError.sys.mjs:8:8\nWebDriverError@chrome://remote/content/shared/webdriver/Er ... ote/content/shared/webdriver/Errors.sys.mjs:392:5\nelement.find/</<@chrome://remote/content/marionette/element.sys.mjs:134:16\n"},null]
We have a delayed insert by 1s via setTimeout() of the element via a call to execute script. Given that the implicit wait is set to 4s I could only imagine that the callback hasn't been run due to some reason. Note that this test failure happens for a CCOV build that is slow anyway.
|
||
Comment 3•1 year ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.
Status: NEW → RESOLVED
Closed: 1 year ago
Resolution: --- → INCOMPLETE
|
|
||
Comment 4•1 year ago
|
||
If it happens again we may be able to use the RunInfo that we want to add via bug 1814128.
Depends on: 1814128
You need to log in
before you can comment on or make changes to this bug.
Description
•