Closed
Bug 1758355
Opened 2 years ago
Closed 2 years ago
Intermittent non-asan [tier 2] TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/new_session/create_alwaysMatch.py | expected OK
Categories
(Remote Protocol :: Marionette, defect, P5)
Remote Protocol
Marionette
Tracking
(Not tracked)
RESOLVED
DUPLICATE
of bug 1779759
People
(Reporter: intermittent-bug-filer, Unassigned)
References
(Blocks 1 open bug)
Details
(Keywords: intermittent-failure)
Filed by: imoraru [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=370190471&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/DzoVlI96RJej8e7Z_Mhjeg/runs/0/artifacts/public/logs/live_backing.log
[task 2022-03-07T12:50:29.169Z] 12:50:29 INFO - STDOUT: tests/web-platform/tests/webdriver/tests/new_session/create_alwaysMatch.py::test_valid[test:extension-abc]
[task 2022-03-07T12:50:29.169Z] 12:50:29 INFO - PID 7624 | 1646657429166 geckodriver::capabilities DEBUG Found version 99.0a1
[task 2022-03-07T12:50:29.170Z] 12:50:29 INFO - PID 7624 | 1646657429167 geckodriver::browser DEBUG Backing up prefs to "C:\\Users\\task_164665527541773\\AppData\\Local\\Temp\\tmp9punbe_b.mozrunner\\user.geckodriver_backup"
[task 2022-03-07T12:50:29.182Z] 12:50:29 INFO - PID 7624 | 1646657429182 mozrunner::runner INFO Running command: "Z:\\task_164665527541773\\build\\application\\firefox\\firefox.exe" "--marionette" "--profile" "C:\\Users\\task_164665527541773\\AppData\\Local\\Temp\\tmp9punbe_b.mozrunner" "-no-remote"
[task 2022-03-07T12:50:29.185Z] 12:50:29 INFO - PID 7624 | 1646657429184 geckodriver::marionette DEBUG Waiting 60s to connect to browser on 127.0.0.1
[task 2022-03-07T12:50:29.186Z] 12:50:29 INFO - PID 7624 | 1646657429184 geckodriver::browser TRACE Failed to open C:\Users\task_164665527541773\AppData\Local\Temp\tmp9punbe_b.mozrunner\MarionetteActivePort
[task 2022-03-07T12:50:29.186Z] 12:50:29 INFO - PID 7624 | 1646657429184 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-03-07T12:50:29.276Z] 12:50:29 INFO - PID 7624 | *** You are running in headless mode.
[task 2022-03-07T12:50:29.302Z] 12:50:29 INFO - PID 7624 | 1646657429303 geckodriver::browser TRACE Failed to open C:\Users\task_164665527541773\AppData\Local\Temp\tmp9punbe_b.mozrunner\MarionetteActivePort
[task 2022-03-07T12:50:29.304Z] 12:50:29 INFO - PID 7624 | 1646657429303 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-03-07T12:50:29.411Z] 12:50:29 INFO - PID 7624 | 1646657429412 geckodriver::browser TRACE Failed to open C:\Users\task_164665527541773\AppData\Local\Temp\tmp9punbe_b.mozrunner\MarionetteActivePort
[task 2022-03-07T12:50:29.413Z] 12:50:29 INFO - PID 7624 | 1646657429412 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-03-07T12:50:29.520Z] 12:50:29 INFO - PID 7624 | 1646657429520 geckodriver::browser TRACE Failed to open C:\Users\task_164665527541773\AppData\Local\Temp\tmp9punbe_b.mozrunner\MarionetteActivePort
[task 2022-03-07T12:50:29.522Z] 12:50:29 INFO - PID 7624 | 1646657429520 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-03-07T12:50:29.582Z] 12:50:29 INFO - PID 7624 | 1646657429588 Marionette INFO Marionette enabled
[task 2022-03-07T12:50:29.634Z] 12:50:29 INFO - PID 7624 | 1646657429634 geckodriver::browser TRACE Failed to open C:\Users\task_164665527541773\AppData\Local\Temp\tmp9punbe_b.mozrunner\MarionetteActivePort
[task 2022-03-07T12:50:29.636Z] 12:50:29 INFO - PID 7624 | 1646657429634 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-03-07T12:50:29.743Z] 12:50:29 INFO - PID 7624 | 1646657429743 geckodriver::browser TRACE Failed to open C:\Users\task_164665527541773\AppData\Local\Temp\tmp9punbe_b.mozrunner\MarionetteActivePort
[task 2022-03-07T12:50:29.745Z] 12:50:29 INFO - PID 7624 | 1646657429743 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-03-07T12:50:29.853Z] 12:50:29 INFO - PID 7624 | 1646657429854 geckodriver::browser TRACE Failed to open C:\Users\task_164665527541773\AppData\Local\Temp\tmp9punbe_b.mozrunner\MarionetteActivePort
[task 2022-03-07T12:50:29.856Z] 12:50:29 INFO - PID 7624 | 1646657429854 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-03-07T12:50:29.969Z] 12:50:29 INFO - PID 7624 | 1646657429969 geckodriver::browser TRACE Failed to open C:\Users\task_164665527541773\AppData\Local\Temp\tmp9punbe_b.mozrunner\MarionetteActivePort
[task 2022-03-07T12:50:29.970Z] 12:50:29 INFO - PID 7624 | 1646657429969 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-03-07T12:50:30.077Z] 12:50:30 INFO - PID 7624 | 1646657430078 geckodriver::browser TRACE Failed to open C:\Users\task_164665527541773\AppData\Local\Temp\tmp9punbe_b.mozrunner\MarionetteActivePort
[task 2022-03-07T12:50:30.079Z] 12:50:30 INFO - PID 7624 | 1646657430078 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-03-07T12:50:30.186Z] 12:50:30 INFO - PID 7624 | 1646657430187 geckodriver::browser TRACE Failed to open C:\Users\task_164665527541773\AppData\Local\Temp\tmp9punbe_b.mozrunner\MarionetteActivePort
[task 2022-03-07T12:50:30.189Z] 12:50:30 INFO - PID 7624 | 1646657430187 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-03-07T12:50:30.295Z] 12:50:30 INFO - PID 7624 | 1646657430296 geckodriver::browser TRACE Failed to open C:\Users\task_164665527541773\AppData\Local\Temp\tmp9punbe_b.mozrunner\MarionetteActivePort
[task 2022-03-07T12:50:30.297Z] 12:50:30 INFO - PID 7624 | 1646657430296 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-03-07T12:50:30.308Z] 12:50:30 INFO - PID 7624 | [GFX1-]: RenderCompositorSWGL failed mapping default framebuffer, no dt
[task 2022-03-07T12:50:30.409Z] 12:50:30 INFO - PID 7624 | 1646657430410 geckodriver::browser TRACE Failed to open C:\Users\task_164665527541773\AppData\Local\Temp\tmp9punbe_b.mozrunner\MarionetteActivePort
[task 2022-03-07T12:50:30.411Z] 12:50:30 INFO - PID 7624 | 1646657430410 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-03-07T12:50:30.525Z] 12:50:30 INFO - PID 7624 | 1646657430526 geckodriver::browser TRACE Failed to open C:\Users\task_164665527541773\AppData\Local\Temp\tmp9punbe_b.mozrunner\MarionetteActivePort
[task 2022-03-07T12:50:30.527Z] 12:50:30 INFO - PID 7624 | 1646657430526 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-03-07T12:50:30.641Z] 12:50:30 INFO - PID 7624 | 1646657430641 geckodriver::browser TRACE Failed to open C:\Users\task_164665527541773\AppData\Local\Temp\tmp9punbe_b.mozrunner\MarionetteActivePort
[task 2022-03-07T12:50:30.643Z] 12:50:30 INFO - PID 7624 | 1646657430641 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-03-07T12:50:30.757Z] 12:50:30 INFO - PID 7624 | 1646657430757 geckodriver::browser TRACE Failed to open C:\Users\task_164665527541773\AppData\Local\Temp\tmp9punbe_b.mozrunner\MarionetteActivePort
[task 2022-03-07T12:50:30.759Z] 12:50:30 INFO - PID 7624 | 1646657430757 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-03-07T12:50:30.872Z] 12:50:30 INFO - PID 7624 | 1646657430873 geckodriver::browser TRACE Failed to open C:\Users\task_164665527541773\AppData\Local\Temp\tmp9punbe_b.mozrunner\MarionetteActivePort
[task 2022-03-07T12:50:30.875Z] 12:50:30 INFO - PID 7624 | 1646657430873 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-03-07T12:50:30.995Z] 12:50:30 INFO - PID 7624 | 1646657430995 geckodriver::browser TRACE Failed to open C:\Users\task_164665527541773\AppData\Local\Temp\tmp9punbe_b.mozrunner\MarionetteActivePort
[task 2022-03-07T12:50:30.996Z] 12:50:30 INFO - PID 7624 | 1646657430995 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-03-07T12:50:31.110Z] 12:50:31 INFO - PID 7624 | 1646657431111 geckodriver::browser TRACE Failed to open C:\Users\task_164665527541773\AppData\Local\Temp\tmp9punbe_b.mozrunner\MarionetteActivePort
[task 2022-03-07T12:50:31.113Z] 12:50:31 INFO - PID 7624 | 1646657431111 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-03-07T12:50:31.226Z] 12:50:31 INFO - PID 7624 | 1646657431226 geckodriver::browser TRACE Failed to open C:\Users\task_164665527541773\AppData\Local\Temp\tmp9punbe_b.mozrunner\MarionetteActivePort
[task 2022-03-07T12:50:31.228Z] 12:50:31 INFO - PID 7624 | 1646657431226 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-03-07T12:50:31.342Z] 12:50:31 INFO - PID 7624 | 1646657431342 geckodriver::browser TRACE Failed to open C:\Users\task_164665527541773\AppData\Local\Temp\tmp9punbe_b.mozrunner\MarionetteActivePort
[task 2022-03-07T12:50:31.344Z] 12:50:31 INFO - PID 7624 | 1646657431342 geckodriver::marionette TRACE Retrying in 100ms
[task 2022-03-07T12:50:31.357Z] 12:50:31 INFO - PID 7624 | 1646657431365 Marionette TRACE Received observer notification marionette-startup-requested
[task 2022-03-07T12:50:31.367Z] 12:50:31 INFO - PID 7624 | 1646657431366 Marionette TRACE Waiting until startup recorder finished recording startup scripts...
[task 2022-03-07T12:50:31.411Z] 12:50:31 INFO - PID 7624 | 1646657431424 Marionette TRACE All scripts recorded.
[task 2022-03-07T12:50:31.430Z] 12:50:31 INFO - PID 7624 | 1646657431429 Marionette INFO Listening on port 61158
[task 2022-03-07T12:50:31.432Z] 12:50:31 INFO - PID 7624 | 1646657431431 Marionette DEBUG Marionette is listening
[task 2022-03-07T12:50:31.460Z] 12:50:31 INFO - PID 7624 | Read port: 61158
[task 2022-03-07T12:50:31.464Z] 12:50:31 INFO - PID 7624 | 1646657431471 Marionette DEBUG Accepted connection 0 from 127.0.0.1:61161
[task 2022-03-07T12:50:31.475Z] 12:50:31 INFO - PID 7624 | 1646657431477 geckodriver::marionette DEBUG Connection to Marionette established on 127.0.0.1:61158.
[task 2022-03-07T12:50:31.487Z] 12:50:31 INFO - PID 7624 | 1646657431486 Marionette DEBUG 0 -> [0,1,"WebDriver:NewSession",{"test:extension":"abc"}]
[task 2022-03-07T12:50:31.500Z] 12:50:31 INFO - PID 7624 | 1646657431502 RemoteAgent TRACE [30] Document already finished loading: about:blank
[task 2022-03-07T12:50:31.517Z] 12:50:31 INFO - PID 7624 | 1646657431517 Marionette DEBUG 0 <- [1,1,null,{"sessionId":"ed7c9ee7-7531-425d-b628-c9fba9be97eb","capabilities":{"browserName":"firefox","browserVersion":"99.0a ... ownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"test:extension":"abc","proxy":{}}}]
[task 2022-03-07T12:50:31.530Z] 12:50:31 INFO - PID 7624 | 1646657431526 webdriver::server DEBUG <- 200 OK {"value":{"sessionId":"ed7c9ee7-7531-425d-b628-c9fba9be97eb","capabilities":{"acceptInsecureCerts":false,"browserName":"firefox","browserVersion":"99.0a1","moz:accessibilityChecks":false,"moz:buildID":"20220307093830","moz:geckodriverVersion":"0.30.0","moz:headless":true,"moz:processID":804,"moz:profile":"C:\\Users\\task_164665527541773\\AppData\\Local\\Temp\\tmp9punbe_b.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true,"pageLoadStrategy":"normal","platformName":"windows","platformVersion":"10.0","proxy":{},"setWindowRect":true,"strictFileInteractability":false,"test:extension":"abc","timeouts":{"implicit":0,"pageLoad":300000,"script":30000},"unhandledPromptBehavior":"dismiss and notify"}}}
[task 2022-03-07T12:50:31.531Z] 12:50:31 INFO - STDOUT: PASSED
[task 2022-03-07T12:50:31.532Z] 12:50:31 INFO - PID 7624 | 1646657431529 webdriver::server DEBUG -> DELETE /session/ed7c9ee7-7531-425d-b628-c9fba9be97eb
[task 2022-03-07T12:50:31.533Z] 12:50:31 INFO - PID 7624 | 1646657431532 Marionette DEBUG 0 -> [0,2,"Marionette:Quit",{"flags":["eForceQuit"]}]
[task 2022-03-07T12:50:31.534Z] 12:50:31 INFO - PID 7624 | 1646657431533 Marionette INFO Stopped listening on port 61158
[task 2022-03-07T12:50:31.642Z] 12:50:31 INFO - PID 7624 | 1646657431645 Marionette TRACE Received observer notification quit-application
[task 2022-03-07T12:50:31.647Z] 12:50:31 INFO - PID 7624 | 1646657431645 Marionette TRACE Received observer notification quit-application
[task 2022-03-07T12:50:31.648Z] 12:50:31 INFO - PID 7624 | 1646657431645 Marionette DEBUG Marionette stopped listening
[task 2022-03-07T12:50:31.659Z] 12:50:31 INFO - PID 7624 | 1646657431658 Marionette DEBUG 0 <- [1,2,null,{"cause":"shutdown","forced":false}]
[task 2022-03-07T12:50:31.695Z] 12:50:31 INFO - PID 7624 | 1646657431695 webdriver::server DEBUG Teardown session
[task 2022-03-07T12:50:31.697Z] 12:50:31 INFO - PID 7624 | ###!!! [Parent][PCompositorManagerParent] Error: RunMessage(msgname=PCompositorBridge::Msg___delete__) Channel closing: too late to send/recv, messages will be lost
[task 2022-03-07T12:50:31.702Z] 12:50:31 INFO - PID 7624 | ###!!! [Parent][PImageBridgeParent] Error: RunMessage(msgname=PImageBridge::Msg_WillClose) Channel closing: too late to send/recv, messages will be lost
[task 2022-03-07T12:50:31.703Z] 12:50:31 INFO - PID 7624 | 1646657431703 Marionette DEBUG Closed connection 0
[task 2022-03-07T12:50:32.597Z] 12:50:32 INFO - PID 7624 | JavaScript error: resource://gre/modules/TerminatorTelemetry.jsm, line 71: AbortError: IOUtils: Shutting down and refusing additional I/O tasks
[task 2022-03-07T12:50:34.393Z] 12:50:34 INFO - PID 7624 | Waiting in WillDestroyCurrentMessageLoop for pid 828
[task 2022-03-07T12:50:37.615Z] 12:50:37 INFO - PID 7624 | Waiting in WillDestroyCurrentMessageLoop for pid 1732
[task 2022-03-07T12:50:37.631Z] 12:50:37 INFO - PID 7624 | Waiting in WillDestroyCurrentMessageLoop for pid 5232
[task 2022-03-07T12:50:37.631Z] 12:50:37 INFO - PID 7624 | Waiting in WillDestroyCurrentMessageLoop for pid 1852
[task 2022-03-07T12:50:37.632Z] 12:50:37 INFO - PID 7624 | Waiting in WillDestroyCurrentMessageLoop for pid 4908
[task 2022-03-07T12:50:37.632Z] 12:50:37 INFO - PID 7624 | Waiting in WillDestroyCurrentMessageLoop for pid 5988
[task 2022-03-07T12:50:44.190Z] 12:50:44 INFO - TEST-UNEXPECTED-TIMEOUT | /webdriver/tests/new_session/create_alwaysMatch.py | expected OK
[task 2022-03-07T12:50:44.190Z] 12:50:44 INFO - TEST-INFO took 365010ms
[task 2022-03-07T12:50:44.664Z] 12:50:44 INFO - Closing logging queue
[task 2022-03-07T12:50:44.664Z] 12:50:44 INFO - queue closed
[task 2022-03-07T12:50:45.185Z] 12:50:45 INFO - PID 2916 | 1646657444693 geckodriver INFO Listening on 127.0.0.1:49808
[task 2022-03-07T12:50:45.188Z] 12:50:45 INFO - Starting runner
[task 2022-03-07T12:50:45.971Z] 12:50:45 INFO - TEST-START | /webdriver/tests/new_session/create_firstMatch.py
|
||
Comment 1•2 years ago
|
||
Chris, could have the following Javascript failure delayed the shutdown of Firefox which finally ended in a timeout by the wptrunner?
JavaScript error: resource://gre/modules/TerminatorTelemetry.jsm, line 71: AbortError: IOUtils: Shutting down and refusing additional I/O tasks
If not this is a dupe of bug 1630162.
Flags: needinfo?(chutten)
|
||
Comment 2•2 years ago
|
||
That's in an observer notification, so I can't imagine it would have such an effect. :dthayer, the file contains some probes you own: do you know more about this?
Flags: needinfo?(chutten) → needinfo?(dothayer)
| Comment hidden (Intermittent Failures Robot) |
|
||
Updated•2 years ago
|
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → DUPLICATE
|
|
||
Comment 5•2 years ago
|
||
(In reply to Henrik Skupin (:whimboo) [⌚️UTC+2] from comment #1)
Chris, could have the following Javascript failure delayed the shutdown of Firefox which finally ended in a timeout by the wptrunner?
JavaScript error: resource://gre/modules/TerminatorTelemetry.jsm, line 71: AbortError: IOUtils: Shutting down and refusing additional I/O tasks
(In reply to Chris H-C :chutten from comment #2)
That's in an observer notification, so I can't imagine it would have such an effect. :dthayer, the file contains some probes you own: do you know more about this?
This particular issue got actually fixed by bug 1779759.
Given since no more failure occurred I would tend to mark it as dupe of that bug.
Flags: needinfo?(dothayer)
|
||
Comment 6•1 year 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
•