Closed
Bug 1758200
Opened 3 years ago
Closed 3 years ago
Intermittent [tier 2] Wd ccov TEST-UNEXPECTED-TIMEOUT | expected OK [after "Browser process stopped: exit status: 11"]
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=370006771&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/XASkP8QxQ_K5wktZ2tR_Fw/runs/0/artifacts/public/logs/live_backing.log
[task 2022-03-04T19:09:27.095Z] 19:09:27 INFO - PID 6770 | 1646420967094 webdriver::server DEBUG Teardown session
[task 2022-03-04T19:09:27.104Z] 19:09:27 INFO - PID 6770 | 1646420967103 Marionette DEBUG Closed connection 0
[task 2022-03-04T19:09:27.146Z] 19:09:27 INFO - PID 6770 | ###!!! [Child][PContentChild] Error: RunMessage(msgname=PContent::Msg_DestroyBrowsingContextGroup) Channel closing: too late to send/recv, messages will be lost
[task 2022-03-04T19:09:27.148Z] 19:09:27 INFO - PID 6770 | ###!!! [Parent][PCompositorManagerParent] Error: RunMessage(msgname=PCompositorBridge::Msg___delete__) Channel closing: too late to send/recv, messages will be lost
[task 2022-03-04T19:09:27.150Z] 19:09:27 INFO - PID 6770 | ###!!! [Parent][PImageBridgeParent] Error: RunMessage(msgname=PImageBridge::Msg_WillClose) Channel closing: too late to send/recv, messages will be lost
[task 2022-03-04T19:09:27.461Z] 19:09:27 INFO - PID 6770 | [CodeCoverage] Setting handlers for process 9001.
[task 2022-03-04T19:09:35.052Z] 19:09:35 INFO - PID 6770 | ###!!! [Parent][PCompositorManagerParent] Error: RunMessage(msgname=PCompositorBridge::Msg___delete__) Channel closing: too late to send/recv, messages will be lost
[task 2022-03-04T19:09:42.098Z] 19:09:42 INFO - PID 6770 | console.error: (new Error("SessionFile is closed", "resource:///modules/sessionstore/SessionFile.jsm", 443))
[task 2022-03-04T19:09:45.025Z] 19:09:45 INFO - PID 6770 | WARNING: At least one completion condition is taking too long to complete. Conditions: [{"name":"ContentParent: id=7fabc79cdc00","state":{"remoteTypePrefix":"prealloc"},"filename":"/builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp","lineNumber":3566,"stack":["resource://gre/modules/nsAsyncShutdown.jsm:addBlocker:162"]},{"name":"ContentParent: id=7fabc79cb900","state":{"remoteTypePrefix":"prealloc"},"filename":"/builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp","lineNumber":3566,"stack":["resource://gre/modules/nsAsyncShutdown.jsm:addBlocker:162"]}] Barrier: profile-before-change
[task 2022-03-04T19:10:20.873Z] 19:10:20 INFO - PID 6770 | JavaScript error: resource://gre/modules/CrashManager.jsm, line 898: AbortError: IOUtils: Shutting down and refusing additional I/O tasks
[task 2022-03-04T19:10:36.026Z] 19:10:36 INFO - PID 6770 | FATAL ERROR: AsyncShutdown timeout in profile-before-change Conditions: [{"name":"ContentParent: id=7fabc79cdc00","state":{"remoteTypePrefix":"prealloc"},"filename":"/builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp","lineNumber":3566,"stack":["resource://gre/modules/nsAsyncShutdown.jsm:addBlocker:162"]},{"name":"ContentParent: id=7fabc79cb900","state":{"remoteTypePrefix":"prealloc"},"filename":"/builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp","lineNumber":3566,"stack":["resource://gre/modules/nsAsyncShutdown.jsm:addBlocker:162"]}] At least one completion condition failed to complete within a reasonable amount of time. Causing a crash to ensure that we do not leave the user with an unresponsive process draining resources.
[task 2022-03-04T19:10:36.027Z] 19:10:36 INFO - PID 6770 | [Parent 8839, Main Thread] ###!!! ABORT: file /builds/worker/checkouts/gecko/dom/ipc/ContentParent.cpp:3566
[task 2022-03-04T19:10:36.029Z] 19:10:36 INFO - PID 6770 | ExceptionHandler::GenerateDump cloned child 9031
[task 2022-03-04T19:10:36.030Z] 19:10:36 INFO - PID 6770 | ExceptionHandler::SendContinueSignalToChild sent continue signal to child
[task 2022-03-04T19:10:36.030Z] 19:10:36 INFO - PID 6770 | ExceptionHandler::WaitForContinueSignal waiting for continue signal...
[task 2022-03-04T19:10:36.150Z] 19:10:36 INFO - PID 6770 | 1646421036149 geckodriver::browser DEBUG Browser process stopped: exit status: 11
[task 2022-03-04T19:10:36.151Z] 19:10:36 INFO - PID 6770 | 1646421036150 webdriver::server DEBUG <- 200 OK {"value":null}
[task 2022-03-04T19:10:36.152Z] 19:10:36 INFO - PID 6770 | 1646421036151 webdriver::server DEBUG -> POST /session {"capabilities": {"alwaysMatch": {"moz:firefoxOptions": {"args": ["--profile", "/tmp/tmpdg32aglx.mozrunner"], "binary": "/builds/worker/workspace/build/application/firefox/firefox"}, "unhandledPromptBehavior": "dismiss and notify"}}}
[task 2022-03-04T19:10:36.154Z] 19:10:36 INFO - PID 6770 | 1646421036151 geckodriver::capabilities DEBUG Trying to read firefox version from ini files
[task 2022-03-04T19:10:36.154Z] 19:10:36 INFO - PID 6770 | 1646421036151 geckodriver::capabilities DEBUG Found version 99.0a1
[task 2022-03-04T19:10:36.155Z] 19:10:36 INFO - PID 6770 | 1646421036152 geckodriver::browser DEBUG Backing up prefs to "/tmp/tmpdg32aglx.mozrunner/user.geckodriver_backup"
[task 2022-03-04T19:10:36.160Z] 19:10:36 INFO - PID 6770 | 1646421036159 mozrunner::runner INFO Running command: "/builds/worker/workspace/build/application/firefox/firefox" "--marionette" "--profile" "/tmp/tmpdg32aglx.mozrunner" "-no-remote"
[task 2022-03-04T19:10:36.161Z] 19:10:36 INFO - PID 6770 | 1646421036159 geckodriver::marionette DEBUG Waiting 60s to connect to browser on 127.0.0.1
[task 2022-03-04T19:10:36.162Z] 19:10:36 INFO - PID 6770 | 1646421036160 geckodriver::browser TRACE Failed to open /tmp/tmpdg32aglx.mozrunner/MarionetteActivePort
[task 2022-03-04T19:10:36.162Z] 19:10:36 INFO - PID 6770 | 1646421036160 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-03-04T19:10:36.204Z] 19:10:36 INFO - PID 6770 | [CodeCoverage] Setting handlers for process 9032.
[task 2022-03-04T19:10:36.205Z] 19:10:36 INFO - PID 6770 | *** You are running in headless mode.
[task 2022-03-04T19:10:36.261Z] 19:10:36 INFO - PID 6770 | 1646421036260 geckodriver::browser TRACE Failed to open /tmp/tmpdg32aglx.mozrunner/MarionetteActivePort
[task 2022-03-04T19:10:36.262Z] 19:10:36 INFO - PID 6770 | 1646421036260 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-03-04T19:10:36.361Z] 19:10:36 INFO - PID 6770 | 1646421036360 geckodriver::browser TRACE Failed to open /tmp/tmpdg32aglx.mozrunner/MarionetteActivePort
[task 2022-03-04T19:10:36.362Z] 19:10:36 INFO - PID 6770 | 1646421036360 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-03-04T19:10:36.456Z] 19:10:36 INFO - PID 6770 | 1646421036455 Marionette INFO Marionette enabled
[task 2022-03-04T19:10:36.461Z] 19:10:36 INFO - PID 6770 | 1646421036460 geckodriver::browser TRACE Failed to open /tmp/tmpdg32aglx.mozrunner/MarionetteActivePort
[task 2022-03-04T19:10:36.462Z] 19:10:36 INFO - PID 6770 | 1646421036460 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-03-04T19:10:36.561Z] 19:10:36 INFO - PID 6770 | 1646421036560 geckodriver::browser TRACE Failed to open /tmp/tmpdg32aglx.mozrunner/MarionetteActivePort
[task 2022-03-04T19:10:36.562Z] 19:10:36 INFO - PID 6770 | 1646421036560 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-03-04T19:10:36.661Z] 19:10:36 INFO - PID 6770 | 1646421036660 geckodriver::browser TRACE Failed to open /tmp/tmpdg32aglx.mozrunner/MarionetteActivePort
[task 2022-03-04T19:10:36.662Z] 19:10:36 INFO - PID 6770 | 1646421036660 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-03-04T19:10:36.761Z] 19:10:36 INFO - PID 6770 | 1646421036760 geckodriver::browser TRACE Failed to open /tmp/tmpdg32aglx.mozrunner/MarionetteActivePort
[task 2022-03-04T19:10:36.762Z] 19:10:36 INFO - PID 6770 | 1646421036760 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-03-04T19:10:36.861Z] 19:10:36 INFO - PID 6770 | 1646421036860 geckodriver::browser TRACE Failed to open /tmp/tmpdg32aglx.mozrunner/MarionetteActivePort
[task 2022-03-04T19:10:36.862Z] 19:10:36 INFO - PID 6770 | 1646421036860 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-03-04T19:10:36.962Z] 19:10:36 INFO - PID 6770 | 1646421036961 geckodriver::browser TRACE Failed to open /tmp/tmpdg32aglx.mozrunner/MarionetteActivePort
[task 2022-03-04T19:10:36.963Z] 19:10:36 INFO - PID 6770 | 1646421036961 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-03-04T19:10:37.028Z] 19:10:37 INFO - PID 6770 | [GFX1-]: RenderCompositorSWGL failed mapping default framebuffer, no dt
[task 2022-03-04T19:10:37.062Z] 19:10:37 INFO - PID 6770 | 1646421037061 geckodriver::browser TRACE Failed to open /tmp/tmpdg32aglx.mozrunner/MarionetteActivePort
[task 2022-03-04T19:10:37.063Z] 19:10:37 INFO - PID 6770 | 1646421037061 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-03-04T19:10:37.162Z] 19:10:37 INFO - PID 6770 | 1646421037161 geckodriver::browser TRACE Failed to open /tmp/tmpdg32aglx.mozrunner/MarionetteActivePort
[task 2022-03-04T19:10:37.163Z] 19:10:37 INFO - PID 6770 | 1646421037161 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-03-04T19:10:37.263Z] 19:10:37 INFO - PID 6770 | 1646421037261 geckodriver::browser TRACE Failed to open /tmp/tmpdg32aglx.mozrunner/MarionetteActivePort
[task 2022-03-04T19:10:37.264Z] 19:10:37 INFO - PID 6770 | 1646421037261 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-03-04T19:10:37.362Z] 19:10:37 INFO - PID 6770 | 1646421037361 geckodriver::browser TRACE Failed to open /tmp/tmpdg32aglx.mozrunner/MarionetteActivePort
[task 2022-03-04T19:10:37.363Z] 19:10:37 INFO - PID 6770 | 1646421037361 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-03-04T19:10:37.463Z] 19:10:37 INFO - PID 6770 | 1646421037461 geckodriver::browser TRACE Failed to open /tmp/tmpdg32aglx.mozrunner/MarionetteActivePort
[task 2022-03-04T19:10:37.463Z] 19:10:37 INFO - PID 6770 | 1646421037461 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-03-04T19:10:37.563Z] 19:10:37 INFO - PID 6770 | 1646421037561 geckodriver::browser TRACE Failed to open /tmp/tmpdg32aglx.mozrunner/MarionetteActivePort
[task 2022-03-04T19:10:37.564Z] 19:10:37 INFO - PID 6770 | 1646421037562 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-03-04T19:10:37.600Z] 19:10:37 INFO - PID 6770 | 1646421037598 Marionette TRACE Received observer notification marionette-startup-requested
[task 2022-03-04T19:10:37.601Z] 19:10:37 INFO - PID 6770 | 1646421037599 Marionette TRACE Waiting until startup recorder finished recording startup scripts...
[task 2022-03-04T19:10:37.637Z] 19:10:37 INFO - PID 6770 | 1646421037636 Marionette TRACE All scripts recorded.
[task 2022-03-04T19:10:37.640Z] 19:10:37 INFO - PID 6770 | 1646421037638 Marionette INFO Listening on port 33762
[task 2022-03-04T19:10:37.641Z] 19:10:37 INFO - PID 6770 | 1646421037639 Marionette DEBUG Marionette is listening
[task 2022-03-04T19:10:37.662Z] 19:10:37 INFO - PID 6770 | Read port: 33762
[task 2022-03-04T19:10:37.669Z] 19:10:37 INFO - PID 6770 | 1646421037668 Marionette DEBUG Accepted connection 0 from 127.0.0.1:46828
[task 2022-03-04T19:10:37.671Z] 19:10:37 INFO - PID 6770 | 1646421037670 geckodriver::marionette DEBUG Connection to Marionette established on 127.0.0.1:33762.
[task 2022-03-04T19:10:37.677Z] 19:10:37 INFO - PID 6770 | 1646421037675 Marionette DEBUG 0 -> [0,1,"WebDriver:NewSession",{"unhandledPromptBehavior":"dismiss and notify"}]
[task 2022-03-04T19:10:37.886Z] 19:10:37 INFO - PID 6770 | 1646421037885 RemoteAgent TRACE [30] No navigation detected: about:blank
[task 2022-03-04T19:10:37.895Z] 19:10:37 INFO - PID 6770 | 1646421037893 Marionette DEBUG 0 <- [1,1,null,{"sessionId":"9efc08c0-6cd2-4e34-8f26-9d66357e1f02","capabilities":{"browserName":"firefox","browserVersion":"99.0a ... x.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"proxy":{}}}]
[task 2022-03-04T19:10:37.902Z] 19:10:37 INFO - PID 6770 | 1646421037900 webdriver::server DEBUG <- 200 OK {"value":{"sessionId":"9efc08c0-6cd2-4e34-8f26-9d66357e1f02","capabilities":{"acceptInsecureCerts":false,"browserName":"firefox","browserVersion":"99.0a1","moz:accessibilityChecks":false,"moz:buildID":"20220304180627","moz:geckodriverVersion":"0.30.0","moz:headless":true,"moz:processID":9032,"moz:profile":"/tmp/tmpdg32aglx.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"pageLoadStrategy":"normal","platformName":"linux","platformVersion":"4.4.0-1014-aws","proxy":{},"setWindowRect":true,"strictFileInteractability":false,"timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"unhandledPromptBehavior":"dismiss and notify"}}}
[task 2022-03-04T19:10:37.904Z] 19:10:37 INFO - PID 6770 | 1646421037901 webdriver::server DEBUG -> POST /session/9efc08c0-6cd2-4e34-8f26-9d66357e1f02/window/rect {"width": 800, "height": 600}
[task 2022-03-04T19:10:37.904Z] 19:10:37 INFO - PID 6770 | 1646421037903 Marionette DEBUG 0 -> [0,2,"WebDriver:SetWindowRect",{"height":600,"width":800}]
[task 2022-03-04T19:10:37.906Z] 19:10:37 INFO - PID 6770 | 1646421037904 Marionette DEBUG 0 <- [1,2,null,{"x":0,"y":0,"width":800,"height":600}]
[task 2022-03-04T19:10:37.906Z] 19:10:37 INFO - PID 6770 | 1646421037905 webdriver::server DEBUG <- 200 OK {"value":{"x":0,"y":0,"width":800,"height":600}}
[task 2022-03-04T19:10:37.907Z] 19:10:37 INFO - PID 6770 | 1646421037906 webdriver::server DEBUG -> POST /session/9efc08c0-6cd2-4e34-8f26-9d66357e1f02/window/rect {"x": 100, "y": 100}
[task 2022-03-04T19:10:37.909Z] 19:10:37 INFO - PID 6770 | 1646421037908 Marionette DEBUG 0 -> [0,3,"WebDriver:SetWindowRect",{"x":100,"y":100}]
[task 2022-03-04T19:10:37.911Z] 19:10:37 INFO - PID 6770 | 1646421037910 Marionette DEBUG 0 <- [1,3,null,{"x":100,"y":100,"width":800,"height":600}]
[task 2022-03-04T19:10:37.912Z] 19:10:37 INFO - PID 6770 | 1646421037910 webdriver::server DEBUG <- 200 OK {"value":{"x":100,"y":100,"width":800,"height":600}}
[task 2022-03-04T19:10:37.915Z] 19:10:37 INFO - PID 6770 | 1646421037912 webdriver::server DEBUG -> POST /session/9efc08c0-6cd2-4e34-8f26-9d66357e1f02/execute/async {"script": "\n let dialog_type = arguments[0];\n let text = arguments[1];\n\n setTimeout(function() {\n if (dialog_type == 'prompt') {\n window.dialog_return_value = window[dialog_type](text, '');\n } else {\n window.dialog_return_value = window[dialog_type](text);\n }\n }, 0);\n ", "args": ["alert", "alert"]}
[task 2022-03-04T19:10:37.916Z] 19:10:37 INFO - PID 6770 | 1646421037914 Marionette DEBUG 0 -> [0,4,"WebDriver:ExecuteAsyncScript",{"args":["alert","alert"],"script":"\n let dialog_type = arguments[0];\n ... window.dialog_return_value = window[dialog_type](text);\n }\n }, 0);\n "}]
[task 2022-03-04T19:15:15.513Z] 19:15:15 INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/execute_script/user_prompts.py | expected OK
[task 2022-03-04T19:15:15.513Z] 19:15:15 INFO - TEST-INFO took 365002ms
[task 2022-03-04T19:15:15.514Z] 19:15:15 INFO - Restarting browser for new test group
[task 2022-03-04T19:15:15.730Z] 19:15:15 INFO - Closing logging queue
[task 2022-03-04T19:15:15.730Z] 19:15:15 INFO - queue closed
[task 2022-03-04T19:15:15.734Z] 19:15:15 INFO - PID 9129 | 1646421315732 geckodriver INFO Listening on 127.0.0.1:44692
[task 2022-03-04T19:15:15.735Z] 19:15:15 INFO - Starting runner
[task 2022-03-04T19:15:16.061Z] 19:15:16 INFO - TEST-START | /webdriver/tests/find_elements/find.py
| Comment hidden (Intermittent Failures Robot) |
|
||
Comment 2•3 years ago
|
||
It looks like that the following command never returned:
session.execute_async_script("""
let dialog_type = arguments[0];
let text = arguments[1];
setTimeout(function() {
if (dialog_type == 'prompt') {
window.dialog_return_value = window[dialog_type](text, '');
} else {
window.dialog_return_value = window[dialog_type](text);
}
}, 0);
""", args=(dialog_type, text))
I wonder how this can even work given that we never call resolve(). So the script should basically timeout every time.
|
|
||
Updated•3 years ago
|
Summary: Intermittent [tier 2] TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/execute_script/user_prompts.py | expected OK → Intermittent [tier 2] Wd TEST-UNEXPECTED-TIMEOUT | expected OK [missing call to resolve in create_dialog]
|
|
||
Comment 3•3 years ago
|
||
Note that resolve doesn't need to be called because when the user prompt gets opened any WebDriver command automatically returns. So this was a red herring.
As Julian pointed out the former Firefox instance exited with a code of 11, so maybe this caused some side-effect for Firefox when started again.
Summary: Intermittent [tier 2] Wd TEST-UNEXPECTED-TIMEOUT | expected OK [missing call to resolve in create_dialog] → Intermittent [tier 2] Wd ccov TEST-UNEXPECTED-TIMEOUT | expected OK [after "Browser process stopped: exit status: 11"]
|
||
Comment 4•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 5•2 years ago
|
||
Moving bug to Remote Protocol::Marionette component per bug 1815831.
Component: geckodriver → Marionette
Product: Testing → Remote Protocol
You need to log in
before you can comment on or make changes to this bug.
Description
•