Closed
Bug 1815081
Opened 3 years ago
Closed 2 years ago
Intermittent Automation Error: Received unexpected exception while running application | marionette_driver.errors.SessionNotCreatedException: TimeoutError: No applicable application window found after 4500 ms
Categories
(Testing :: Mochitest, defect, P5)
Testing
Mochitest
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=404612122&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/IPYUACF_RxqP9EP6ZCexKQ/runs/0/artifacts/public/logs/live_backing.log
[task 2023-02-04T20:50:18.568Z] 20:50:18 INFO - TEST-START | dom/canvas/test/webgl-conf/generated/test_2_conformance__textures__misc__texture-video-transparent.html
[task 2023-02-04T20:50:18.569Z] 20:50:18 INFO - TEST-SKIP | dom/canvas/test/webgl-conf/generated/test_2_conformance__textures__misc__texture-video-transparent.html | took 0ms
[task 2023-02-04T20:50:18.569Z] 20:50:18 INFO - Running manifest: dom/canvas/test/webgl-conf/generated-mochitest.ini
[task 2023-02-04T20:50:18.569Z] 20:50:18 INFO - The following extra prefs will be set:
[task 2023-02-04T20:50:18.569Z] 20:50:18 INFO - media.seamless-looping-video=false
[task 2023-02-04T20:50:19.014Z] 20:50:19 INFO - PID 22193 | pk12util: PKCS12 IMPORT SUCCESSFUL
[task 2023-02-04T20:50:19.209Z] 20:50:19 INFO - MochitestServer : launching ['/opt/worker/tasks/task_167554225210960/build/tests/bin/xpcshell', '-g', '/opt/worker/tasks/task_167554225210960/build/application/Firefox NightlyDebug.app/Contents/Resources', '-f', '/opt/worker/tasks/task_167554225210960/build/tests/bin/components/httpd.js', '-e', "const _PROFILE_PATH = '/var/folders/px/f29wyd4d3wqg4tc0lv4k0f0m000014/T/tmpeeoo1jgv.mozrunner'; const _SERVER_PORT = '8888'; const _SERVER_ADDR = '127.0.0.1'; const _TEST_PREFIX = undefined; const _DISPLAY_RESULTS = false;", '-f', '/opt/worker/tasks/task_167554225210960/build/tests/mochitest/server.js']
[task 2023-02-04T20:50:19.210Z] 20:50:19 INFO - runtests.py | Server pid: 22194
[task 2023-02-04T20:50:19.212Z] 20:50:19 INFO - runtests.py | Websocket server pid: 22195
[task 2023-02-04T20:50:19.217Z] 20:50:19 INFO - runtests.py | SSL tunnel pid: 22196
[task 2023-02-04T20:50:19.376Z] 20:50:19 INFO - Couldn't convert chrome URL: chrome://branding/locale/brand.properties
[task 2023-02-04T20:50:19.377Z] 20:50:19 INFO - [Parent 22194, Main Thread] WARNING: Could not get the program name for a cubeb stream.: 'NS_SUCCEEDED(rv)', file /builds/worker/checkouts/gecko/dom/media/CubebUtils.cpp:430
[task 2023-02-04T20:50:19.438Z] 20:50:19 INFO - runtests.py | Running with scheme: http
[task 2023-02-04T20:50:19.439Z] 20:50:19 INFO - runtests.py | Running with e10s: True
[task 2023-02-04T20:50:19.439Z] 20:50:19 INFO - runtests.py | Running with fission: True
[task 2023-02-04T20:50:19.439Z] 20:50:19 INFO - runtests.py | Running with cross-origin iframes: False
[task 2023-02-04T20:50:19.440Z] 20:50:19 INFO - runtests.py | Running with serviceworker_e10s: True
[task 2023-02-04T20:50:19.440Z] 20:50:19 INFO - runtests.py | Running with socketprocess_e10s: False
[task 2023-02-04T20:50:19.440Z] 20:50:19 INFO - runtests.py | Running tests: start.
[task 2023-02-04T20:50:19.440Z] 20:50:19 INFO -
[task 2023-02-04T20:50:19.451Z] 20:50:19 WARNING - Found 'firefox' running before starting test browser!
[task 2023-02-04T20:50:19.452Z] 20:50:19 WARNING - {'username': 'cltbld', 'name': 'firefox', 'cmdline': ['/opt/worker/tasks/task_167551854593189/build/application/Firefox NightlyDebug.app/Contents/MacOS/firefox', '-marionette', '-foreground', '-profile', '/var/folders/px/f29wyd4d3wqg4tc0lv4k0f0m000014/T/tmp3z4j94jt.mozrunner'], 'ppid': 1, 'pid': 12389}
[task 2023-02-04T20:50:19.452Z] 20:50:19 WARNING -
[task 2023-02-04T20:50:19.452Z] 20:50:19 INFO - Application command: /opt/worker/tasks/task_167554225210960/build/application/Firefox NightlyDebug.app/Contents/MacOS/firefox -marionette -foreground -profile /var/folders/px/f29wyd4d3wqg4tc0lv4k0f0m000014/T/tmpeeoo1jgv.mozrunner
[task 2023-02-04T20:50:19.456Z] 20:50:19 INFO - runtests.py | Application pid: 22197
[task 2023-02-04T20:50:19.456Z] 20:50:19 INFO - TEST-INFO | started process GECKO(22197)
[task 2023-02-04T20:50:19.499Z] 20:50:19 INFO - GECKO(22197) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /var/folders/px/f29wyd4d3wqg4tc0lv4k0f0m000014/T/tmpeeoo1jgv.mozrunner/runtests_leaks.log
[task 2023-02-04T20:50:19.500Z] 20:50:19 INFO - GECKO(22197) | [22197, Main Thread] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp:345
[task 2023-02-04T20:50:19.557Z] 20:50:19 INFO - GECKO(22197) | [22197, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005 (NS_ERROR_FAILURE): file /builds/worker/checkouts/gecko/toolkit/xre/nsXREDirProvider.cpp:478
[task 2023-02-04T20:50:19.579Z] 20:50:19 INFO - GECKO(22197) | [Parent 22197, Main Thread] WARNING: Rejected attempt to change type of pref extensions.formautofill.creditCards.available's user value from bool to string: file /builds/worker/checkouts/gecko/modules/libpref/Preferences.cpp:1820
[task 2023-02-04T20:50:19.609Z] 20:50:19 INFO - GECKO(22197) | [Parent 22197, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005 (NS_ERROR_FAILURE): file /builds/worker/checkouts/gecko/toolkit/xre/nsXREDirProvider.cpp:478
[task 2023-02-04T20:50:19.643Z] 20:50:19 INFO - GECKO(22197) | [Parent 22197, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005 (NS_ERROR_FAILURE): file /builds/worker/checkouts/gecko/toolkit/xre/nsXREDirProvider.cpp:478
[task 2023-02-04T20:50:19.644Z] 20:50:19 INFO - GECKO(22197) | [Parent 22197, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005 (NS_ERROR_FAILURE): file /builds/worker/checkouts/gecko/toolkit/xre/nsXREDirProvider.cpp:478
[task 2023-02-04T20:50:20.072Z] 20:50:20 INFO - GECKO(22197) | [WARN rkv::backend::impl_safe::environment] `load_ratio()` is irrelevant for this storage backend.
[task 2023-02-04T20:50:20.271Z] 20:50:20 INFO - GECKO(22197) | GL_VENDOR: Intel Inc.
[task 2023-02-04T20:50:20.272Z] 20:50:20 INFO - GECKO(22197) | mVendor: Intel
[task 2023-02-04T20:50:20.272Z] 20:50:20 INFO - GECKO(22197) | GL_RENDERER: Intel(R) UHD Graphics 630
[task 2023-02-04T20:50:20.273Z] 20:50:20 INFO - GECKO(22197) | mRenderer: Unknown
[task 2023-02-04T20:50:20.273Z] 20:50:20 INFO - GECKO(22197) | mIsMesa: 0
[task 2023-02-04T20:50:20.286Z] 20:50:20 INFO - GECKO(22197) | [Parent 22197, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005 (NS_ERROR_FAILURE): file /builds/worker/checkouts/gecko/toolkit/xre/nsXREDirProvider.cpp:478
[task 2023-02-04T20:50:20.288Z] 20:50:20 INFO - GECKO(22197) | 1675543820287 Marionette INFO Marionette enabled
[task 2023-02-04T20:50:20.307Z] 20:50:20 INFO - GECKO(22197) | [Parent 22197, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005 (NS_ERROR_FAILURE): file /builds/worker/checkouts/gecko/toolkit/xre/nsXREDirProvider.cpp:478
[task 2023-02-04T20:50:20.323Z] 20:50:20 INFO - GECKO(22197) | 1675543820323 Marionette TRACE Received observer notification final-ui-startup
[task 2023-02-04T20:50:20.325Z] 20:50:20 INFO - GECKO(22197) | [Parent 22197, Main Thread] WARNING: failed to bind socket: file /builds/worker/checkouts/gecko/netwerk/base/nsServerSocket.cpp:400
[task 2023-02-04T20:50:20.326Z] 20:50:20 INFO - GECKO(22197) | 1675543820325 Marionette FATAL Marionette server failed to start: Error: Could not bind to port 2828 (NS_ERROR_SOCKET_ADDRESS_IN_USE)(chrome://remote/content/marionette/server.sys.mjs:77:17) JS Stack trace: set acceptConnections@sys.mjs:77:17
[task 2023-02-04T20:50:20.327Z] 20:50:20 INFO - GECKO(22197) | start@sys.mjs:107:5
[task 2023-02-04T20:50:20.327Z] 20:50:20 INFO - GECKO(22197) | init@sys.mjs:226:19
[task 2023-02-04T20:50:20.327Z] 20:50:20 INFO - GECKO(22197) | observe@sys.mjs:178:20
[task 2023-02-04T20:50:20.495Z] 20:50:20 INFO - GECKO(22197) | 1675543820494 Marionette TRACE Received observer notification quit-application
[task 2023-02-04T20:50:24.090Z] 20:50:24 INFO - Traceback (most recent call last):
[task 2023-02-04T20:50:24.090Z] 20:50:24 INFO - File "/opt/worker/tasks/task_167554225210960/build/tests/mochitest/runtests.py", line 3554, in doTests
[task 2023-02-04T20:50:24.091Z] 20:50:24 INFO - crashAsPass=options.crashAsPass,
[task 2023-02-04T20:50:24.091Z] 20:50:24 INFO - File "/opt/worker/tasks/task_167554225210960/build/tests/mochitest/runtests.py", line 2714, in runApp
[task 2023-02-04T20:50:24.091Z] 20:50:24 INFO - self.marionette.start_session()
[task 2023-02-04T20:50:24.091Z] 20:50:24 INFO - File "/opt/worker/tasks/task_167554225210960/build/venv/lib/python3.7/site-packages/marionette_driver/decorators.py", line 24, in _
[task 2023-02-04T20:50:24.091Z] 20:50:24 INFO - return func(*args, **kwargs)
[task 2023-02-04T20:50:24.092Z] 20:50:24 INFO - File "/opt/worker/tasks/task_167554225210960/build/venv/lib/python3.7/site-packages/marionette_driver/marionette.py", line 1258, in start_session
[task 2023-02-04T20:50:24.092Z] 20:50:24 INFO - resp = self._send_message("WebDriver:NewSession", capabilities)
[task 2023-02-04T20:50:24.092Z] 20:50:24 INFO - File "/opt/worker/tasks/task_167554225210960/build/venv/lib/python3.7/site-packages/marionette_driver/decorators.py", line 24, in _
[task 2023-02-04T20:50:24.092Z] 20:50:24 INFO - return func(*args, **kwargs)
[task 2023-02-04T20:50:24.093Z] 20:50:24 INFO - File "/opt/worker/tasks/task_167554225210960/build/venv/lib/python3.7/site-packages/marionette_driver/marionette.py", line 663, in _send_message
[task 2023-02-04T20:50:24.093Z] 20:50:24 INFO - self._handle_error(err)
[task 2023-02-04T20:50:24.093Z] 20:50:24 INFO - File "/opt/worker/tasks/task_167554225210960/build/venv/lib/python3.7/site-packages/marionette_driver/marionette.py", line 675, in _handle_error
[task 2023-02-04T20:50:24.093Z] 20:50:24 INFO - raise errors.lookup(error)(message, stacktrace=stacktrace)
[task 2023-02-04T20:50:24.093Z] 20:50:24 INFO - marionette_driver.errors.SessionNotCreatedException: TimeoutError: No applicable application window found after 4500 ms
[task 2023-02-04T20:50:24.093Z] 20:50:24 INFO - stacktrace:
[task 2023-02-04T20:50:24.093Z] 20:50:24 INFO - RemoteError@chrome://remote/content/shared/RemoteError.sys.mjs:8:8
[task 2023-02-04T20:50:24.094Z] 20:50:24 INFO - WebDriverError@chrome://remote/content/shared/webdriver/Errors.sys.mjs:180:5
[task 2023-02-04T20:50:24.094Z] 20:50:24 INFO - TimeoutError@chrome://remote/content/shared/webdriver/Errors.sys.mjs:469:5
[task 2023-02-04T20:50:24.094Z] 20:50:24 INFO - bail@chrome://remote/content/marionette/sync.sys.mjs:211:19
[task 2023-02-04T20:50:24.094Z] 20:50:24 ERROR - Automation Error: Received unexpected exception while running application
[task 2023-02-04T20:50:24.094Z] 20:50:24 ERROR -
[task 2023-02-04T20:50:24.203Z] 20:50:24 INFO - Stopping web server
[task 2023-02-04T20:50:24.223Z] 20:50:24 INFO - Server shut down.
[task 2023-02-04T20:50:24.336Z] 20:50:24 INFO - Web server killed.
[task 2023-02-04T20:50:24.336Z] 20:50:24 INFO - Stopping web socket server
[task 2023-02-04T20:50:24.503Z] 20:50:24 INFO - Stopping ssltunnel
[task 2023-02-04T20:50:24.630Z] 20:50:24 INFO - leakcheck | Processing log file /var/folders/px/f29wyd4d3wqg4tc0lv4k0f0m000014/T/tmpeeoo1jgv.mozrunner/runtests_leaks.log
[task 2023-02-04T20:50:24.630Z] 20:50:24 INFO - TEST-INFO | leakcheck | default process: leak threshold set at 0 bytes
[task 2023-02-04T20:50:24.630Z] 20:50:24 INFO - TEST-INFO | leakcheck | tab process: leak threshold set at 0 bytes
[task 2023-02-04T20:50:24.631Z] 20:50:24 INFO - TEST-INFO | leakcheck | gmplugin process: leak threshold set at 20000 bytes
[task 2023-02-04T20:50:24.631Z] 20:50:24 INFO - TEST-INFO | leakcheck | gpu process: leak threshold set at 0 bytes
[task 2023-02-04T20:50:24.632Z] 20:50:24 INFO - TEST-INFO | leakcheck | vr process: leak threshold set at 0 bytes
[task 2023-02-04T20:50:24.632Z] 20:50:24 INFO - TEST-INFO | leakcheck | rdd process: leak threshold set at 0 bytes
[task 2023-02-04T20:50:24.633Z] 20:50:24 INFO - TEST-INFO | leakcheck | socket process: leak threshold set at 0 bytes
[task 2023-02-04T20:50:24.633Z] 20:50:24 INFO - TEST-INFO | leakcheck | sandboxbroker process: leak threshold set at 0 bytes
[task 2023-02-04T20:50:24.633Z] 20:50:24 INFO - TEST-INFO | leakcheck | forkserver process: leak threshold set at 0 bytes
[task 2023-02-04T20:50:24.634Z] 20:50:24 INFO - TEST-INFO | leakcheck | utility process: leak threshold set at 0 bytes
[task 2023-02-04T20:50:24.634Z] 20:50:24 INFO - leakcheck | Processing leak log file /var/folders/px/f29wyd4d3wqg4tc0lv4k0f0m000014/T/tmpeeoo1jgv.mozrunner/runtests_leaks.log
[task 2023-02-04T20:50:24.634Z] 20:50:24 INFO - TEST-UNEXPECTED-FAIL | leakcheck | default missing output line for total leaks!
[task 2023-02-04T20:50:24.635Z] 20:50:24 INFO - runtests.py | Running tests: end.
[task 2023-02-04T20:50:24.641Z] 20:50:24 INFO - Buffered messages finished
[task 2023-02-04T20:50:24.642Z] 20:50:24 INFO - 0 INFO TEST-START | Shutdown
[task 2023-02-04T20:50:24.642Z] 20:50:24 INFO - 1 INFO Passed: 0
[task 2023-02-04T20:50:24.642Z] 20:50:24 INFO - 2 INFO Failed: 0
[task 2023-02-04T20:50:24.642Z] 20:50:24 INFO - 3 INFO Todo: 0
[task 2023-02-04T20:50:24.643Z] 20:50:24 INFO - 4 INFO Mode: e10s
[task 2023-02-04T20:50:24.643Z] 20:50:24 INFO - 5 INFO SimpleTest FINISHED
[task 2023-02-04T20:50:24.643Z] 20:50:24 INFO - Buffered messages finished
[task 2023-02-04T20:50:24.643Z] 20:50:24 INFO - SUITE-END | took 6s
[task 2023-02-04T20:50:24.667Z] 20:50:24 ERROR - Return code: 1
[task 2023-02-04T20:50:24.667Z] 20:50:24 INFO - TinderboxPrint: mochitest-mochitest-webgl2-core<br/>24/0/0
[task 2023-02-04T20:50:24.667Z] 20:50:24 ERROR - # TBPL FAILURE #
[task 2023-02-04T20:50:24.667Z] 20:50:24 WARNING - setting return code to 2
[task 2023-02-04T20:50:24.668Z] 20:50:24 ERROR - The mochitest suite: mochitest-webgl2-core ran with return status: FAILURE
[task 2023-02-04T20:50:24.668Z] 20:50:24 INFO - Running post-action listener: _package_coverage_data
[task 2023-02-04T20:50:24.668Z] 20:50:24 INFO - Running post-action listener: _resource_record_post_action
[task 2023-02-04T20:50:24.668Z] 20:50:24 INFO - Running post-action listener: process_java_coverage_data
[task 2023-02-04T20:50:24.668Z] 20:50:24 INFO - [mozharness: 2023-02-04 20:50:24.668428Z] Finished run-tests step (success)
[task 2023-02-04T20:50:24.668Z] 20:50:24 INFO - [mozharness: 2023-02-04 20:50:24.668490Z] Running uninstall step.
[task 2023-02-04T20:50:24.668Z] 20:50:24 INFO - Running pre-action listener: _resource_record_pre_action
[task 2023-02-04T20:50:24.668Z] 20:50:24 INFO - Running main action method: uninstall
[task 2023-02-04T20:50:24.668Z] 20:50:24 INFO - Skipping uninstall for non-MSIX test
[task 2023-02-04T20:50:24.668Z] 20:50:24 INFO - Running post-action listener: _resource_record_post_action
[task 2023-02-04T20:50:24.668Z] 20:50:24 INFO - [mozharness: 2023-02-04 20:50:24.668731Z] Finished uninstall step (success)
[task 2023-02-04T20:50:24.668Z] 20:50:24 INFO - Running post-run listener: _resource_record_post_run
[task 2023-02-04T20:50:24.732Z] 20:50:24 INFO - instance_metadata.json not found; unable to determine instance type
[task 2023-02-04T20:50:24.733Z] 20:50:24 INFO - Validating Perfherder data against /opt/worker/tasks/task_167554225210960/mozharness/external_tools/performance-artifact-schema.json
[task 2023-02-04T20:50:24.736Z] 20:50:24 INFO - PERFHERDER_DATA: {"framework": {"name": "job_resource_usage"}, "suites": [{"name": "mochitest.mochitest-webgl2-core.1.overall", "extraOptions": ["e10s", "buildbot-unknown"], "subtests": [{"name": "cpu_percent", "value": 12.231182795698922}, {"name": "io_write_bytes", "value": 371011584}, {"name": "io.read_bytes", "value": 3014656}, {"name": "io_write_time", "value": 732}, {"name": "io_read_time", "value": 155}]}, {"name": "mochitest.mochitest-webgl2-core.1.start-pulseaudio", "subtests": [{"name": "time", "value": 0.0004429817199707031}, {"name": "cpu_percent", "value": 0}]}, {"name": "mochitest.mochitest-webgl2-core.1.install", "subtests": [{"name": "time", "value": 26.057105779647827}, {"name": "cpu_percent", "value": 13.516319444444447}]}, {"name": "mochitest.mochitest-webgl2-core.1.stage-files", "subtests": [{"name": "time", "value": 0.00026607513427734375}, {"name": "cpu_percent", "value": 0}]}, {"name": "mochitest.mochitest-webgl2-core.1.run-tests", "subtests": [{"name": "time", "value": 6.952602863311768}, {"name": "cpu_percent", "value": 6.63611111111111}]}, {"name": "mochitest.mochitest-webgl2-core.1.uninstall", "subtests": [{"name": "time", "value": 0.0001468658447265625}, {"name": "cpu_percent", "value": 0}]}]}
[task 2023-02-04T20:50:24.736Z] 20:50:24 INFO - Total resource usage - Wall time: 33s; CPU: Can't collect data; Read bytes: 3014656; Write bytes: 371011584; Read time: 155; Write time: 732
[task 2023-02-04T20:50:24.736Z] 20:50:24 INFO - TinderboxPrint: I/O read bytes / time<br/>3,014,656 / 155
[task 2023-02-04T20:50:24.736Z] 20:50:24 INFO - TinderboxPrint: I/O write bytes / time<br/>371,011,584 / 732
[task 2023-02-04T20:50:24.736Z] 20:50:24 INFO - TinderboxPrint: CPU idle<br/>343.0 (87.8%)
[task 2023-02-04T20:50:24.736Z] 20:50:24 INFO - TinderboxPrint: CPU system<br/>5.5 (1.4%)
[task 2023-02-04T20:50:24.736Z] 20:50:24 INFO - TinderboxPrint: CPU user<br/>42.3 (10.8%)
[task 2023-02-04T20:50:24.736Z] 20:50:24 INFO - TinderboxPrint: Swap in / out<br/>334,376,960 / 0
[task 2023-02-04T20:50:24.736Z] 20:50:24 INFO - start-pulseaudio - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2023-02-04T20:50:24.737Z] 20:50:24 INFO - install - Wall time: 26s; CPU: 14%; Read bytes: 320859648; Write bytes: 314683392; Read time: 22187; Write time: 579
[task 2023-02-04T20:50:24.737Z] 20:50:24 INFO - stage-files - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2023-02-04T20:50:24.737Z] 20:50:24 INFO - run-tests - Wall time: 7s; CPU: 7%; Read bytes: 544768; Write bytes: 32120832; Read time: 41; Write time: 68
[task 2023-02-04T20:50:24.737Z] 20:50:24 INFO - uninstall - Wall time: 0s; CPU: Can't collect data; Read bytes: 0; Write bytes: 0; Read time: 0; Write time: 0
[task 2023-02-04T20:50:24.746Z] 20:50:24 WARNING - returning nonzero exit status 2
[taskcluster 2023-02-04T20:50:24.775Z] Exit Code: 2
[taskcluster 2023-02-04T20:50:24.775Z] User Time: 1m37.829373s
[taskcluster 2023-02-04T20:50:24.775Z] Kernel Time: 21.488519s
[taskcluster 2023-02-04T20:50:24.775Z] Wall Time: 2m38.158255s
[taskcluster 2023-02-04T20:50:24.775Z] Result: FAILED
[taskcluster 2023-02-04T20:50:24.775Z] === Task Finished ===
[taskcluster 2023-02-04T20:50:24.775Z] Task Duration: 2m38.163758s
[taskcluster 2023-02-04T20:50:24.886Z] Uploading artifact public/logs/localconfig.json from file logs/localconfig.json with content encoding "gzip", mime type "application/json" and expiry 2024-02-04T20:32:25.885Z
[taskcluster 2023-02-04T20:50:25.132Z] Uploading artifact public/test_info/manifests.list from file build/blobber_upload_dir/manifests.list with content encoding "gzip", mime type "text/plain; charset=utf-8" and expiry 2024-02-04T20:32:25.885Z
[taskcluster 2023-02-04T20:50:25.223Z] Uploading artifact public/test_info/mochitest-webgl2-core_errorsummary.log from file build/blobber_upload_dir/mochitest-webgl2-core_errorsummary.log with content encoding "gzip", mime type "text/plain" and expiry 2024-02-04T20:32:25.885Z
[taskcluster 2023-02-04T20:50:25.315Z] Uploading artifact public/test_info/mochitest-webgl2-core_raw.log from file build/blobber_upload_dir/mochitest-webgl2-core_raw.log with content encoding "gzip", mime type "text/plain" and expiry 2024-02-04T20:32:25.885Z
[taskcluster 2023-02-04T20:50:25.487Z] Uploading artifact public/test_info/resource-usage.json from file build/blobber_upload_dir/resource-usage.json with content encoding "gzip", mime type "application/json" and expiry 2024-02-04T20:32:25.885Z
[taskcluster 2023-02-04T20:50:25.661Z] Uploading artifact public/test_info/system-info.log from file build/blobber_upload_dir/system-info.log with content encoding "gzip", mime type "text/plain" and expiry 2024-02-04T20:32:25.885Z
[taskcluster 2023-02-04T20:50:25.784Z] Uploading redirect artifact public/logs/live.log to URL https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/IPYUACF_RxqP9EP6ZCexKQ/runs/0/artifacts/public%2Flogs%2Flive_backing.log with mime type "text/plain; charset=utf-8" and expiry 2024-02-04T20:32:25.885Z
[taskcluster:error] exit status 2
| Comment hidden (Intermittent Failures Robot) |
|
||
Updated•3 years ago
|
Component: Graphics: CanvasWebGL → Marionette
Product: Core → Testing
See Also: → 1798447
Summary: Intermittent leakcheck | default missing output line for total leaks! → Intermittent Automation Error: Received unexpected exception while running application | marionette_driver.errors.SessionNotCreatedException: TimeoutError: No applicable application window found after 4500 ms
|
||
Comment 2•3 years ago
|
||
The underlying problem here can be found at:
https://treeherder.mozilla.org/logviewer?job_id=404612122&repo=autoland&lineNumber=1606-1607
[task 2023-02-04T20:50:19.451Z] 20:50:19 WARNING - Found 'firefox' running before starting test browser!
[task 2023-02-04T20:50:19.452Z] 20:50:19 WARNING - {'username': 'cltbld', 'name': 'firefox', 'cmdline': ['/opt/worker/tasks/task_167551854593189/build/application/Firefox NightlyDebug.app/Contents/MacOS/firefox', '-marionette', '-foreground', '-profile', '/var/folders/px/f29wyd4d3wqg4tc0lv4k0f0m000014/T/tmp3z4j94jt.mozrunner'], 'ppid': 1, 'pid': 12389}
That means a former Firefox process hasn't been shutdown correctly and it has Marionette enabled as well. As such Marionette of the newly spawned Firefox process cannot create the server socket.
Geoff, is there a reason why we do not try to kill this left-over Firefox process? If that cannot be done we may consider using different ports for Marionette for each Firefox instance to prevent such collisions. Best here would then be to wait for bug 1750630. Please let me know what you think.
Component: Marionette → Mochitest
Flags: needinfo?(gbrown)
|
||
Comment 3•3 years ago
|
||
I think the main consideration for not killing firefox is, what if you are running 'mach test' locally and you have firefox open in the background?
I suppose even in an automated test environment, there might be a good reason for firefox to be running...and it isn't necessarily a problem for the tests running in another browser instance.
Rather than killing anything called "firefox" before a test starts, I'd prefer that the harness ensures it kills anything it starts. But I imagine mochitests already try to do that...
I scanned some current green mochitest logs and found the firefox warning in some successful test runs:
https://firefoxci.taskcluster-artifacts.net/crAjnb25QXudAFF3oVY0mA/0/public/logs/live_backing.log
I think that's a child process, left over from a previous manifest run?
The log in comment 2 is more puzzling to me: In that case I don't think runtests.py has run firefox yet, but it finds an old one...is the task finding processes left-over from another task?
Flags: needinfo?(gbrown)
See Also: → 1415247
|
|
||
Comment 4•3 years ago
|
||
Yes, that is what I think myself as well. Some other task that was running before might have left running the process and not killed it. I assume it is probably not possible to figure out which task that was?
As such I would propose that we block this bug on bug 1750630 and wait until Marionette can select a system-allocated free port.
What do you think?
| Comment hidden (Intermittent Failures Robot) |
|
||
Comment 7•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
•