Closed
Bug 1818415
Opened 2 years ago
Closed 2 years ago
Intermittent [tier 2] TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/take_element_screenshot/user_prompts.py | expected OK (timeout in WebDriver:Navigate)
Categories
(Remote Protocol :: Marionette, defect, P5)
Remote Protocol
Marionette
Tracking
(Not tracked)
RESOLVED
INCOMPLETE
People
(Reporter: intermittent-bug-filer, Unassigned)
References
Details
(Keywords: intermittent-failure)
Filed by: imoraru [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=406581184&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/csNKMFwtTe2ylw-TAd9hQg/runs/0/artifacts/public/logs/live_backing.log
[task 2023-02-22T23:03:33.370Z] 23:03:33 INFO - STDOUT: tests/web-platform/tests/webdriver/tests/take_element_screenshot/user_prompts.py::test_accept_and_notify[capabilities0-alert-None]
[task 2023-02-22T23:03:33.371Z] 23:03:33 INFO - PID 524 | 1677107013369 webdriver::server DEBUG -> DELETE /session/b78840bc-d335-4d57-a026-38fa87dd7698
[task 2023-02-22T23:03:33.371Z] 23:03:33 INFO - PID 524 | 1677107013370 Marionette DEBUG 0 -> [0,71,"Marionette:Quit",{"flags":["eForceQuit"]}]
[task 2023-02-22T23:03:33.372Z] 23:03:33 INFO - PID 524 | 1677107013371 Marionette INFO Stopped listening on port 43895
[task 2023-02-22T23:03:33.373Z] 23:03:33 INFO - PID 524 | 1677107013373 Marionette TRACE [11] MarionetteCommands actor destroyed for window id 6442450947
[task 2023-02-22T23:03:33.447Z] 23:03:33 INFO - PID 524 | 1677107013446 Marionette TRACE Received observer notification quit-application
[task 2023-02-22T23:03:33.455Z] 23:03:33 INFO - PID 524 | 1677107013454 Marionette TRACE Received observer notification quit-application
[task 2023-02-22T23:03:33.455Z] 23:03:33 INFO - PID 524 | 1677107013454 Marionette DEBUG Marionette stopped listening
[task 2023-02-22T23:03:33.457Z] 23:03:33 INFO - PID 524 | 1677107013456 Marionette DEBUG 0 <- [1,71,null,{"cause":"shutdown","forced":false,"in_app":true}]
[task 2023-02-22T23:03:33.513Z] 23:03:33 INFO - PID 524 | 1677107013512 webdriver::server DEBUG Teardown session
[task 2023-02-22T23:03:33.519Z] 23:03:33 INFO - PID 524 | 1677107013518 Marionette DEBUG Closed connection 0
[task 2023-02-22T23:03:48.455Z] 23:03:48 INFO - PID 524 | console.error: (new Error("SessionFile is closed", "resource:///modules/sessionstore/SessionFile.sys.mjs", 370))
[task 2023-02-22T23:03:51.419Z] 23:03:51 INFO - PID 524 | WARNING: At least one completion condition is taking too long to complete. Conditions: [{"name":"ContentParent: id=7ff2b96e3b00","state":{"remoteTypePrefix":"prealloc"},"filename":"/builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp","lineNumber":3930,"stack":""}] Barrier: profile-before-change
[task 2023-02-22T23:04:43.580Z] 23:04:43 INFO - PID 524 | 1677107083579 mozrunner::runner DEBUG Killing process 1386
[task 2023-02-22T23:04:43.593Z] 23:04:43 INFO - PID 524 | 1677107083592 geckodriver::browser DEBUG Browser process stopped: signal: 9 (SIGKILL)
[task 2023-02-22T23:04:43.594Z] 23:04:43 INFO - PID 524 | 1677107083592 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2023-02-22T23:04:43.596Z] 23:04:43 INFO - PID 524 | 1677107083594 webdriver::server DEBUG -> POST /session {"capabilities": {"alwaysMatch": {"moz:firefoxOptions": {"args": ["--profile", "/tmp/tmp81q5fvzm.mozrunner"], "binary": "/builds/worker/workspace/build/application/firefox/firefox"}, "unhandledPromptBehavior": "accept and notify"}}}
[task 2023-02-22T23:04:43.596Z] 23:04:43 INFO - PID 524 | 1677107083594 geckodriver::capabilities DEBUG Trying to read firefox version from ini files
[task 2023-02-22T23:04:43.597Z] 23:04:43 INFO - PID 524 | 1677107083594 geckodriver::capabilities DEBUG Found version 112.0a1
[task 2023-02-22T23:04:43.597Z] 23:04:43 INFO - PID 524 | 1677107083595 geckodriver::browser DEBUG Backing up prefs to "/tmp/tmp81q5fvzm.mozrunner/user.geckodriver_backup"
[task 2023-02-22T23:04:43.602Z] 23:04:43 INFO - PID 524 | 1677107083601 mozrunner::runner INFO Running command: "/builds/worker/workspace/build/application/firefox/firefox" "--marionette" "--profile" "/tmp/tmp81q5fvzm.mozrunner" "-no-remote"
[task 2023-02-22T23:04:43.603Z] 23:04:43 INFO - PID 524 | 1677107083601 geckodriver::marionette DEBUG Waiting 60s to connect to browser on 127.0.0.1
[task 2023-02-22T23:04:43.604Z] 23:04:43 INFO - PID 524 | 1677107083601 geckodriver::browser TRACE Failed to open /tmp/tmp81q5fvzm.mozrunner/MarionetteActivePort
[task 2023-02-22T23:04:43.604Z] 23:04:43 INFO - PID 524 | 1677107083601 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-02-22T23:04:43.668Z] 23:04:43 INFO - PID 524 | [CodeCoverage] Setting handlers for process 1655.
[task 2023-02-22T23:04:43.703Z] 23:04:43 INFO - PID 524 | 1677107083702 geckodriver::browser TRACE Failed to open /tmp/tmp81q5fvzm.mozrunner/MarionetteActivePort
[task 2023-02-22T23:04:43.704Z] 23:04:43 INFO - PID 524 | 1677107083702 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-02-22T23:04:43.803Z] 23:04:43 INFO - PID 524 | 1677107083802 geckodriver::browser TRACE Failed to open /tmp/tmp81q5fvzm.mozrunner/MarionetteActivePort
[task 2023-02-22T23:04:43.804Z] 23:04:43 INFO - PID 524 | 1677107083802 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-02-22T23:04:43.903Z] 23:04:43 INFO - PID 524 | 1677107083902 geckodriver::browser TRACE Failed to open /tmp/tmp81q5fvzm.mozrunner/MarionetteActivePort
[task 2023-02-22T23:04:43.904Z] 23:04:43 INFO - PID 524 | 1677107083902 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-02-22T23:04:44.003Z] 23:04:44 INFO - PID 524 | 1677107084002 geckodriver::browser TRACE Failed to open /tmp/tmp81q5fvzm.mozrunner/MarionetteActivePort
[task 2023-02-22T23:04:44.004Z] 23:04:44 INFO - PID 524 | 1677107084002 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-02-22T23:04:44.103Z] 23:04:44 INFO - PID 524 | 1677107084102 geckodriver::browser TRACE Failed to open /tmp/tmp81q5fvzm.mozrunner/MarionetteActivePort
[task 2023-02-22T23:04:44.104Z] 23:04:44 INFO - PID 524 | 1677107084102 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-02-22T23:04:44.204Z] 23:04:44 INFO - PID 524 | 1677107084202 geckodriver::browser TRACE Failed to open /tmp/tmp81q5fvzm.mozrunner/MarionetteActivePort
[task 2023-02-22T23:04:44.204Z] 23:04:44 INFO - PID 524 | 1677107084202 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-02-22T23:04:44.304Z] 23:04:44 INFO - PID 524 | 1677107084303 geckodriver::browser TRACE Failed to open /tmp/tmp81q5fvzm.mozrunner/MarionetteActivePort
[task 2023-02-22T23:04:44.304Z] 23:04:44 INFO - PID 524 | 1677107084303 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-02-22T23:04:44.404Z] 23:04:44 INFO - PID 524 | 1677107084403 geckodriver::browser TRACE Failed to open /tmp/tmp81q5fvzm.mozrunner/MarionetteActivePort
[task 2023-02-22T23:04:44.404Z] 23:04:44 INFO - PID 524 | 1677107084403 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-02-22T23:04:44.504Z] 23:04:44 INFO - PID 524 | 1677107084503 geckodriver::browser TRACE Failed to open /tmp/tmp81q5fvzm.mozrunner/MarionetteActivePort
[task 2023-02-22T23:04:44.505Z] 23:04:44 INFO - PID 524 | 1677107084503 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-02-22T23:04:44.604Z] 23:04:44 INFO - PID 524 | 1677107084603 geckodriver::browser TRACE Failed to open /tmp/tmp81q5fvzm.mozrunner/MarionetteActivePort
[task 2023-02-22T23:04:44.605Z] 23:04:44 INFO - PID 524 | 1677107084603 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-02-22T23:04:44.704Z] 23:04:44 INFO - PID 524 | 1677107084703 geckodriver::browser TRACE Failed to open /tmp/tmp81q5fvzm.mozrunner/MarionetteActivePort
[task 2023-02-22T23:04:44.705Z] 23:04:44 INFO - PID 524 | 1677107084703 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-02-22T23:04:44.804Z] 23:04:44 INFO - PID 524 | 1677107084803 geckodriver::browser TRACE Failed to open /tmp/tmp81q5fvzm.mozrunner/MarionetteActivePort
[task 2023-02-22T23:04:44.805Z] 23:04:44 INFO - PID 524 | 1677107084803 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-02-22T23:04:44.905Z] 23:04:44 INFO - PID 524 | 1677107084904 geckodriver::browser TRACE Failed to open /tmp/tmp81q5fvzm.mozrunner/MarionetteActivePort
[task 2023-02-22T23:04:44.905Z] 23:04:44 INFO - PID 524 | 1677107084904 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-02-22T23:04:45.005Z] 23:04:45 INFO - PID 524 | 1677107085004 geckodriver::browser TRACE Failed to open /tmp/tmp81q5fvzm.mozrunner/MarionetteActivePort
[task 2023-02-22T23:04:45.005Z] 23:04:45 INFO - PID 524 | 1677107085004 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-02-22T23:04:45.105Z] 23:04:45 INFO - PID 524 | 1677107085104 geckodriver::browser TRACE Failed to open /tmp/tmp81q5fvzm.mozrunner/MarionetteActivePort
[task 2023-02-22T23:04:45.106Z] 23:04:45 INFO - PID 524 | 1677107085104 geckodriver::marionette TRACE Retrying in 100ms
[task 2023-02-22T23:04:45.117Z] 23:04:45 INFO - PID 524 | 1677107085116 Marionette INFO Marionette enabled
[task 2023-02-22T23:04:45.119Z] 23:04:45 INFO - PID 524 | 1677107085118 Marionette TRACE Received observer notification final-ui-startup
[task 2023-02-22T23:04:45.120Z] 23:04:45 INFO - PID 524 | 1677107085119 Marionette INFO Listening on port 46433
[task 2023-02-22T23:04:45.120Z] 23:04:45 INFO - PID 524 | 1677107085119 Marionette DEBUG Marionette is listening
[task 2023-02-22T23:04:45.205Z] 23:04:45 INFO - PID 524 | Read port: 46433
[task 2023-02-22T23:04:45.239Z] 23:04:45 INFO - PID 524 | 1677107085238 Marionette DEBUG Accepted connection 0 from 127.0.0.1:46810
[task 2023-02-22T23:04:45.248Z] 23:04:45 INFO - PID 524 | 1677107085247 geckodriver::marionette DEBUG Connection to Marionette established on 127.0.0.1:46433.
[task 2023-02-22T23:04:45.382Z] 23:04:45 INFO - PID 524 | 1677107085381 Marionette DEBUG 0 -> [0,1,"WebDriver:NewSession",{"unhandledPromptBehavior":"accept and notify"}]
[task 2023-02-22T23:04:45.385Z] 23:04:45 INFO - PID 524 | 1677107085384 Marionette DEBUG Waiting for initial application window
[task 2023-02-22T23:04:45.391Z] 23:04:45 INFO - PID 524 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-02-22T23:04:45.773Z] 23:04:45 INFO - PID 524 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-02-22T23:04:46.920Z] 23:04:46 INFO - PID 524 | console.error: ({})
[task 2023-02-22T23:04:47.043Z] 23:04:47 INFO - PID 524 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-02-22T23:04:47.045Z] 23:04:47 INFO - PID 524 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-02-22T23:04:47.073Z] 23:04:47 INFO - PID 524 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-02-22T23:04:47.077Z] 23:04:47 INFO - PID 524 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-02-22T23:04:47.104Z] 23:04:47 INFO - PID 524 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-02-22T23:04:47.239Z] 23:04:47 INFO - PID 524 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-02-22T23:04:47.389Z] 23:04:47 INFO - PID 524 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-02-22T23:04:47.402Z] 23:04:47 INFO - PID 524 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-02-22T23:04:47.655Z] 23:04:47 INFO - PID 524 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-02-22T23:04:47.656Z] 23:04:47 INFO - PID 524 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-02-22T23:04:47.657Z] 23:04:47 INFO - PID 524 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-02-22T23:04:47.729Z] 23:04:47 INFO - PID 524 | 1677107087728 Marionette TRACE Received observer notification browser-idle-startup-tasks-finished
[task 2023-02-22T23:04:47.736Z] 23:04:47 INFO - PID 524 | 1677107087735 RemoteAgent TRACE [3] ProgressListener Start: expectNavigation=false resolveWhenStarted=false unloadTimeout=3200 waitForExplicitStart=false
[task 2023-02-22T23:04:47.736Z] 23:04:47 INFO - PID 524 | 1677107087735 RemoteAgent TRACE [3] ProgressListener Setting unload timer (3200ms)
[task 2023-02-22T23:04:50.937Z] 23:04:50 INFO - PID 524 | 1677107090936 RemoteAgent TRACE [3] ProgressListener No navigation detected: about:blank
[task 2023-02-22T23:04:50.938Z] 23:04:50 INFO - PID 524 | 1677107090936 RemoteAgent TRACE [3] ProgressListener Stop: has error=false
[task 2023-02-22T23:04:50.954Z] 23:04:50 INFO - PID 524 | 1677107090952 Marionette DEBUG 0 <- [1,1,null,{"sessionId":"0fadd915-94dc-498c-81e9-c14ace96988f","capabilities":{"browserName":"firefox","browserVersion":"112.0a1","platformName":"linux","acceptInsecureCerts":false,"pageLoadStrategy":"normal","setWindowRect":true,"timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"strictFileInteractability":false,"unhandledPromptBehavior":"accept and notify","moz:accessibilityChecks":false,"moz:buildID":"20230222214030","moz:headless":false,"moz:platformVersion":"4.4.0-1014-aws","moz:processID":1655,"moz:profile":"/tmp/tmp81q5fvzm.mozrunner","moz:shutdownTimeout":180000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"moz:windowless":false,"proxy":{}}}]
[task 2023-02-22T23:04:50.960Z] 23:04:50 INFO - PID 524 | 1677107090958 webdriver::server DEBUG <- 200 OK {"value":{"sessionId":"0fadd915-94dc-498c-81e9-c14ace96988f","capabilities":{"acceptInsecureCerts":false,"browserNa ... actability":false,"timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"unhandledPromptBehavior":"accept and notify"}}}
[task 2023-02-22T23:04:50.961Z] 23:04:50 INFO - PID 524 | 1677107090960 webdriver::server DEBUG -> POST /session/0fadd915-94dc-498c-81e9-c14ace96988f/window/rect {"width": 800, "height": 600}
[task 2023-02-22T23:04:50.969Z] 23:04:50 INFO - PID 524 | 1677107090961 Marionette DEBUG 0 -> [0,2,"WebDriver:SetWindowRect",{"height":600,"width":800}]
[task 2023-02-22T23:04:50.970Z] 23:04:50 INFO - PID 524 | 1677107090963 Marionette TRACE Requested window geometry matches
[task 2023-02-22T23:04:50.972Z] 23:04:50 INFO - PID 524 | 1677107090964 Marionette DEBUG 0 <- [1,2,null,{"x":0,"y":0,"width":800,"height":600}]
[task 2023-02-22T23:04:50.973Z] 23:04:50 INFO - PID 524 | 1677107090969 webdriver::server DEBUG <- 200 OK {"value":{"x":0,"y":0,"width":800,"height":600}}
[task 2023-02-22T23:04:50.973Z] 23:04:50 INFO - PID 524 | 1677107090971 webdriver::server DEBUG -> POST /session/0fadd915-94dc-498c-81e9-c14ace96988f/window/rect {"x": 100, "y": 100}
[task 2023-02-22T23:04:50.975Z] 23:04:50 INFO - PID 524 | 1677107090974 Marionette DEBUG 0 -> [0,3,"WebDriver:SetWindowRect",{"x":100,"y":100}]
[task 2023-02-22T23:04:50.979Z] 23:04:50 INFO - PID 524 | 1677107090978 RemoteAgent TRACE Received DOM event MozUpdateWindowPos for [object WindowRoot]
[task 2023-02-22T23:04:50.980Z] 23:04:50 INFO - PID 524 | 1677107090979 Marionette TRACE Requested window geometry matches
[task 2023-02-22T23:04:50.983Z] 23:04:50 INFO - PID 524 | 1677107090983 Marionette DEBUG 0 <- [1,3,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2023-02-22T23:04:50.985Z] 23:04:50 INFO - PID 524 | 1677107090983 webdriver::server DEBUG <- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2023-02-22T23:04:50.987Z] 23:04:50 INFO - PID 524 | 1677107090986 webdriver::server DEBUG -> POST /session/0fadd915-94dc-498c-81e9-c14ace96988f/url {"url": "http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Cinput%2F%3E&mime=text%2Fhtml&charset=UTF-8"}
[task 2023-02-22T23:04:50.988Z] 23:04:50 INFO - PID 524 | 1677107090987 Marionette DEBUG 0 -> [0,4,"WebDriver:Navigate",{"url":"http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Cinput%2F%3E&mime=text%2Fhtml&charset=UTF-8"}]
[task 2023-02-22T23:04:50.998Z] 23:04:50 INFO - PID 524 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-02-22T23:04:51.026Z] 23:04:51 INFO - PID 524 | 1677107091025 Marionette TRACE Remoteness change detected. Set new top-level browsing context to 3
[task 2023-02-22T23:05:07.027Z] 23:05:07 INFO - PID 524 | ALSA lib seq_hw.c:466:(snd_seq_hw_open) open /dev/snd/seq failed: No such file or directory
[task 2023-02-22T23:09:15.156Z] 23:09:15 INFO - PID 524 | console.error: (new Error("Polling for changes failed: Unexpected content-type \"text/plain;charset=US-ASCII\".", "resource://services-settings/remote-settings.sys.mjs", 325))
[task 2023-02-22T23:09:31.722Z] 23:09:31 INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/take_element_screenshot/user_prompts.py | expected OK
[task 2023-02-22T23:09:31.757Z] 23:09:31 INFO - TEST-INFO took 365003ms
[task 2023-02-22T23:09:31.758Z] 23:09:31 INFO - Restarting browser for new test group
[task 2023-02-22T23:09:31.908Z] 23:09:31 INFO - Closing logging queue
[task 2023-02-22T23:09:31.908Z] 23:09:31 INFO - queue closed
[task 2023-02-22T23:09:31.921Z] 23:09:31 INFO - PID 1770 | 1677107371919 geckodriver INFO Listening on 127.0.0.1:57316
[task 2023-02-22T23:09:31.922Z] 23:09:31 INFO - Starting runner
[task 2023-02-22T23:09:32.163Z] 23:09:32 INFO - TEST-START | /_mozilla/webdriver/bidi/interface/interface.py
|
||
Comment 1•2 years ago
|
||
Hi Henrik! Can you please take a look at this? Not sure what the issue is here.
I see that there is some kind of hang here:
[task 2023-02-22T23:04:50.988Z] 23:04:50 INFO - PID 524 | 1677107090987 Marionette DEBUG 0 -> [0,4,"WebDriver:Navigate",{"url":"http://web-platform.test:8000/webdriver/tests/support/inline.py?doc=%3C%21doctype+html%3E%0A%3Cmeta+charset%3DUTF-8%3E%0A%3Cinput%2F%3E&mime=text%2Fhtml&charset=UTF-8"}]
[task 2023-02-22T23:04:50.998Z] 23:04:50 INFO - PID 524 | console.error: (new Error("Unexpected content-type \"text/plain;charset=US-ASCII\"", "resource://services-settings/Utils.jsm", 407))
[task 2023-02-22T23:04:51.026Z] 23:04:51 INFO - PID 524 | 1677107091025 Marionette TRACE Remoteness change detected. Set new top-level browsing context to 3
[task 2023-02-22T23:05:07.027Z] 23:05:07 INFO - PID 524 | ALSA lib seq_hw.c:466:(snd_seq_hw_open) open /dev/snd/seq failed: No such file or directory
[task 2023-02-22T23:09:15.156Z] 23:09:15 INFO - PID 524 | console.error: (new Error("Polling for changes failed: Unexpected content-type \"text/plain;charset=US-ASCII\".", "resource://services-settings/remote-settings.sys.mjs", 325))
[task 2023-02-22T23:09:31.722Z] 23:09:31 INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/take_element_screenshot/user_prompts.py | expected OK
[task 2023-02-22T23:09:31.757Z] 23:09:31 INFO - TEST-INFO took 365003ms
If you could change the bug summary to better reflect the real issue at hand, so we could quickly identify it in the event of future failures, that would be great.
Thank you!
Flags: needinfo?(hskupin)
|
||
Comment 2•2 years ago
|
||
Here a link to the actual lines in the log:
https://treeherder.mozilla.org/logviewer?job_id=406581184&repo=mozilla-central&lineNumber=106221-106226
The problem is that the navigation takes a very long time and we do not get any page load events from Firefox, most likely because of a remoteness change. We detect that but not sure if we actually stay on the right browsing context.
As such given that we do not have tests where any navigation should take longer than 10s I wonder if we reduce the default Page Load Timeout for WebDriver classic tests from the default 300s to maybe 30s (to allow slow running builds to complete as well). With such a change the above problem would turn into a navigation timeout instead including a better error message to use.
For WebDriver BiDi we don't have such a timeout yet (GitHub issue). So we may have to add such timeout support to the protocol, or have the WebDriver BiDi Python client canceling a request after a given amount of time.
Happy to hear feedback from others. At latest we should discuss next week in the triage meeting.
Component: geckodriver → Marionette
Flags: needinfo?(hskupin)
Product: Testing → Remote Protocol
Summary: Intermittent [tier 2] TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/take_element_screenshot/user_prompts.py | expected OK → Intermittent [tier 2] TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/take_element_screenshot/user_prompts.py | expected OK (timeout in WebDriver:Navigate)
Whiteboard: [webdriver:triage]
|
|
||
Comment 3•2 years ago
|
||
There is actually bug 1760554 already to get the navigation timeout reduced.
Depends on: 1760554
Whiteboard: [webdriver:triage]
| Comment hidden (Intermittent Failures Robot) |
|
||
Comment 5•2 years ago
|
||
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → INCOMPLETE
You need to log in
before you can comment on or make changes to this bug.
Description
•