Intermittent Mn/MnH win7-32 Automation Error: mozprocess timed out after 1000 seconds running (Exiting due to channel error)
Categories
(Testing :: Marionette Client and Harness, defect, P5)
Tracking
(Not tracked)
People
(Reporter: intermittent-bug-filer, Unassigned)
References
Details
(Keywords: intermittent-failure, regression, Whiteboard: [blocked by bug 1521447][stockwell unknown])
#[markdown(off)]
Filed by: hskupin [at] mozilla.com
https://treeherder.mozilla.org/logviewer.html#?job_id=227439568&repo=mozilla-central
Comment 1•6 years ago
|
||
Failures here are all happening due to channel errors:
22:59:37 INFO - 1549753177844 Marionette DEBUG 3 -> [0,6,"WebDriver:DeleteSession",{}]
22:59:37 INFO - 1549753177847 Marionette DEBUG 3 <- [1,6,null,{"value":null}]
22:59:37 INFO - Exiting due to channel error.
Maybe this is a hang in ProcessChild::QuickExit()
?
James, could you have a look at this problem given that you added this feature? Currently this is a high frequent intermittent failure on Windows7 32bit only.
Here the current intermittent view (note that all failures have been classified for bug 1391545 so far:
Comment 2•6 years ago
|
||
There is actually bug 1521447, which covers the underlying problem in Firefox. So lets move the discussion over there.
Updated•6 years ago
|
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 6•6 years ago
|
||
There are 25 total failures in the last 7 days and 56 total failures in the last 30 days on windows7-32 all build types.
Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=232947961&repo=mozilla-inbound&lineNumber=31556
23:55:04 INFO - TEST-START | testing\marionette\harness\marionette_harness\tests\unit\test_profile_management.py TestQuitRestartWithWorkspace.test_restart_clean_creates_new_profile
23:55:04 INFO - 1552175704222 Marionette DEBUG 3 -> [0,2,"WebDriver:DeleteSession",{}]
23:55:04 INFO - 1552175704223 Marionette DEBUG 3 <- [1,2,null,{"value":null}]
23:55:04 INFO - 1552175704224 Marionette DEBUG Closed connection 3
23:55:04 INFO - 1552175704226 Marionette DEBUG Accepted connection 4 from 127.0.0.1:50862
23:55:04 INFO - 1552175704227 Marionette DEBUG 4 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
23:55:04 INFO - 1552175704236 Marionette TRACE [2147483649] Frame script loaded
23:55:04 INFO - 1552175704236 Marionette TRACE [2147483649] Frame script registered
23:55:04 INFO - 1552175704237 Marionette DEBUG 4 <- [1,1,null,{"sessionId":"3b60a8ae-46f9-442b-b630-de822a3c4784","capabilities":{"browserName":"firefox","browserVersion":"67.0a ... s\tmphxmqek.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
23:55:04 INFO - 1552175704238 Marionette DEBUG 4 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
23:55:04 INFO - 1552175704239 Marionette DEBUG 4 <- [1,2,null,{"value":null}]
23:55:04 INFO - 1552175704239 Marionette DEBUG 4 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
23:55:04 INFO - 1552175704240 Marionette DEBUG 4 <- [1,3,null,{"value":null}]
23:55:04 INFO - 1552175704241 Marionette DEBUG 4 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
23:55:04 INFO - 1552175704242 Marionette DEBUG 4 <- [1,4,null,{"value":null}]
23:55:04 INFO - 1552175704243 Marionette DEBUG 4 -> [0,5,"Marionette:GetContext",{}]
23:55:04 INFO - 1552175704244 Marionette DEBUG 4 <- [1,5,null,{"value":"content"}]
23:55:04 INFO - 1552175704244 Marionette DEBUG 4 -> [0,6,"WebDriver:DeleteSession",{}]
23:55:04 INFO - 1552175704245 Marionette DEBUG 4 <- [1,6,null,{"value":null}]
23:55:04 INFO - Exiting due to channel error.
00:11:44 INFO - Automation Error: mozprocess timed out after 1000 seconds running ['Z:\task_1552174753\build\venv\Scripts\python', '-u', 'Z:\task_1552174753\build\tests\marionette\harness\marionette_harness\runtests.py', '--gecko-log=-', '-vv', '--log-raw=Z:\task_1552174753\build\blobber_upload_dir\marionette_raw.log', '--log-errorsummary=Z:\task_1552174753\build\blobber_upload_dir\marionette_errorsummary.log', '--log-html=Z:\task_1552174753\build\blobber_upload_dir\report.html', '--binary=Z:\task_1552174753\build\application\firefox\firefox.exe', '--address=localhost:2828', '--symbols-path=https://queue.taskcluster.net/v1/task/XU6DI-5ORXamUIeWbGpjiw/artifacts/public/build/target.crashreporter-symbols.zip', 'Z:\task_1552174753\build\tests\marionette\tests\testing\marionette\harness\marionette_harness\tests\unit-tests.ini']
00:11:44 ERROR - timed out after 1000 seconds of no output
00:11:44 ERROR - Return code: 572
00:11:44 INFO - TinderboxPrint: marionette<br/><em class="testfail">T-FAIL</em>
00:11:44 INFO - gecko.log not found
00:11:44 INFO - TinderboxPrint: marionette<br/><em class="testfail">T-FAIL</em>
00:11:44 INFO - Marionette exited with return code 572: FAILURE
00:11:44 ERROR - # TBPL FAILURE #
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 9•6 years ago
|
||
There have been 34 failures within the last 7 days, all of them on Windows 7 x32
recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=234664378&repo=mozilla-central&lineNumber=41748
23:14:41 INFO - TEST-START | testing\marionette\harness\marionette_harness\tests\unit\test_profile_management.py TestSwitchProfileWithWorkspace.test_clone_existing_profile
23:14:41 INFO - 1552950881840 Marionette DEBUG Closed connection 4
23:14:41 INFO - 1552950881841 Marionette DEBUG Accepted connection 5 from 127.0.0.1:51121
23:14:41 INFO - 1552950881843 Marionette DEBUG 5 -> [0,1,"WebDriver:NewSession",{"strictFileInteractability":true}]
23:14:41 INFO - 1552950881847 Marionette TRACE [2147483649] Frame script loaded
23:14:41 INFO - 1552950881848 Marionette TRACE [2147483649] Frame script registered
23:14:41 INFO - 1552950881851 Marionette DEBUG 5 <- [1,1,null,{"sessionId":"06ae1982-9c61-4e77-aee5-3cf73a68c9ac","capabilities":{"browserName":"firefox","browserVersion":"68.0a ... p\tmpxy_98u.mozrunner","moz:shutdownTimeout":60000,"moz:useNonSpecCompliantPointerOrigin":false,"moz:webdriverClick":true}}]
23:14:41 INFO - 1552950881853 Marionette DEBUG 5 -> [0,2,"WebDriver:SetTimeouts",{"script":30000}]
23:14:41 INFO - 1552950881854 Marionette DEBUG 5 <- [1,2,null,{"value":null}]
23:14:41 INFO - 1552950881859 Marionette DEBUG 5 -> [0,3,"WebDriver:SetTimeouts",{"pageLoad":300000}]
23:14:41 INFO - 1552950881862 Marionette DEBUG 5 <- [1,3,null,{"value":null}]
23:14:41 INFO - 1552950881863 Marionette DEBUG 5 -> [0,4,"WebDriver:SetTimeouts",{"implicit":0}]
23:14:41 INFO - 1552950881864 Marionette DEBUG 5 <- [1,4,null,{"value":null}]
23:14:41 INFO - Exiting due to channel error.
23:14:41 INFO - Exiting due to channel error.
23:31:21 INFO - Automation Error: mozprocess timed out after 1000 seconds running ['Z:\task_1552950053\build\venv\Scripts\python', '-u', 'Z:\task_1552950053\build\tests\marionette\harness\marionette_harness\runtests.py', '--gecko-log=-', '-vv', '--log-raw=Z:\task_1552950053\build\blobber_upload_dir\marionette_raw.log', '--log-errorsummary=Z:\task_1552950053\build\blobber_upload_dir\marionette_errorsummary.log', '--log-html=Z:\task_1552950053\build\blobber_upload_dir\report.html', '--binary=Z:\task_1552950053\build\application\firefox\firefox.exe', '--address=localhost:2828', '--symbols-path=Z:\task_1552950053\build\symbols', 'Z:\task_1552950053\build\tests\marionette\tests\testing\marionette\harness\marionette_harness\tests\unit-tests.ini']
23:31:21 ERROR - timed out after 1000 seconds of no output
23:31:21 ERROR - Return code: 572
23:31:21 INFO - TinderboxPrint: marionette<br/><em class="testfail">T-FAIL</em>
23:31:21 INFO - gecko.log not found
23:31:21 INFO - TinderboxPrint: marionette<br/><em class="testfail">T-FAIL</em>
23:31:21 INFO - Marionette exited with return code 572: FAILURE
23:31:21 ERROR - # TBPL FAILURE #
Comment hidden (Intermittent Failures Robot) |
Comment 11•6 years ago
|
||
There have been 35 failures within the last 7 days, all of them on Windows 7 x32 and windows7-32-shippable.
recent log: https://treeherder.mozilla.org/logviewer.html#?job_id=236375311&repo=autoland
Comment hidden (Intermittent Failures Robot) |
Comment 13•6 years ago
|
||
There are 36 total failures in the last 7 days on windows7-32 debug and windows7-32-shippable opt
Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=238505991&repo=autoland&lineNumber=42667
21:53:46 INFO - Exiting due to channel error.
21:53:46 INFO - Exiting due to channel error.
22:10:26 INFO - Automation Error: mozprocess timed out after 1000 seconds running ['Z:\task_1554499995\build\venv\Scripts\python', '-u', 'Z:\task_1554499995\build\tests\marionette\harness\marionette_harness\runtests.py', '--gecko-log=-', '-vv', '--log-raw=Z:\task_1554499995\build\blobber_upload_dir\marionette_raw.log', '--log-errorsummary=Z:\task_1554499995\build\blobber_upload_dir\marionette_errorsummary.log', '--log-html=Z:\task_1554499995\build\blobber_upload_dir\report.html', '--binary=Z:\task_1554499995\build\application\firefox\firefox.exe', '--address=localhost:2828', '--symbols-path=Z:\task_1554499995\build\symbols', 'Z:\task_1554499995\build\tests\marionette\tests\testing\marionette\harness\marionette_harness\tests\unit-tests.ini']
22:10:26 ERROR - timed out after 1000 seconds of no output
22:10:26 ERROR - Return code: 572
22:10:26 INFO - TinderboxPrint: marionette<br/><em class="testfail">T-FAIL</em>
22:10:26 INFO - gecko.log not found
22:10:26 INFO - TinderboxPrint: marionette<br/><em class="testfail">T-FAIL</em>
22:10:26 INFO - Marionette exited with return code 572: FAILURE
22:10:26 ERROR - # TBPL FAILURE #
22:10:26 WARNING - setting return code to 2
22:10:26 INFO - Running post-action listener: _package_coverage_data
22:10:26 INFO - Running post-action listener: _resource_record_post_action
22:10:26 INFO - Running post-action listener: process_java_coverage_data
22:10:26 INFO - [mozharness: 2019-04-05 22:10:26.641000Z] Finished run-tests step (success)
22:10:26 INFO - Running post-run listener: _resource_record_post_run
22:10:26 INFO - Total resource usage - Wall time: 1370s; CPU: 5.0%; Read bytes: 1987837952; Write bytes: 766724096; Read time: 19; Write time: 29
22:10:26 INFO - TinderboxPrint: CPU usage<br/>5.2%
22:10:26 INFO - TinderboxPrint: I/O read bytes / time<br/>1,987,837,952 / 19
22:10:26 INFO - TinderboxPrint: I/O write bytes / time<br/>766,724,096 / 29
22:10:26 INFO - TinderboxPrint: CPU idle<br/>10,387.7 (94.8%)
22:10:26 INFO - TinderboxPrint: CPU system<br/>123.7 (1.1%)
22:10:26 INFO - TinderboxPrint: CPU user<br/>447.2 (4.1%)
22:10:26 INFO - install - Wall time: 4s; CPU: 11.0%; Read bytes: 0; Write bytes: 89935872; Read time: 0; Write time: 1
22:10:26 INFO - run-tests - Wall time: 1367s; CPU: 5.0%; Read bytes: 1987837952; Write bytes: 530973184; Read time: 19; Write time: 27
22:10:27 WARNING - returning nonzero exit status 2
[taskcluster 2019-04-05T22:10:27.384Z] Exit Code: 2
[taskcluster 2019-04-05T22:10:27.384Z] User Time: 0s
[taskcluster 2019-04-05T22:10:27.384Z] Kernel Time: 0s
[taskcluster 2019-04-05T22:10:27.384Z] Wall Time: 30m10.3206193s
[taskcluster 2019-04-05T22:10:27.384Z] Result: FAILED
[taskcluster 2019-04-05T22:10:27.384Z] === Task Finished ===
[taskcluster 2019-04-05T22:10:27.384Z] Task Duration: 30m10.3236202s
[taskcluster 2019-04-05T22:10:28.310Z] Uploading artifact public/logs/localconfig.json from file logs\localconfig.json with content encoding "gzip", mime type "application/octet-stream" and expiry 2020-04-04T20:38:55.177Z
[taskcluster 2019-04-05T22:10:29.356Z] Uploading artifact public/test_info/marionette_errorsummary.log from file build\blobber_upload_dir\marionette_errorsummary.log with content encoding "gzip", mime type "text/plain" and expiry 2020-04-04T20:38:55.177Z
[taskcluster 2019-04-05T22:10:29.896Z] Uploading artifact public/test_info/marionette_raw.log from file build\blobber_upload_dir\marionette_raw.log with content encoding "gzip", mime type "text/plain" and expiry 2020-04-04T20:38:55.177Z
[taskcluster 2019-04-05T22:10:31.084Z] Uploading artifact public/test_info/report.html from file build\blobber_upload_dir\report.html with content encoding "gzip", mime type "text/html; charset=utf-8" and expiry 2020-04-04T20:38:55.177Z
[taskcluster 2019-04-05T22:10:31.583Z] Uploading artifact public/test_info/resource-usage.json from file build\blobber_upload_dir\resource-usage.json with content encoding "gzip", mime type "application/octet-stream" and expiry 2020-04-04T20:38:55.177Z
[taskcluster 2019-04-05T22:10:32.831Z] Uploading redirect artifact public/logs/live.log to URL https://queue.taskcluster.net/v1/task/SsM8Vy_pQpSPxC4PLNEvDg/runs/0/artifacts/public/logs/live_backing.log with mime type "text/plain; charset=utf-8" and expiry 2020-04-04T20:38:55.177Z
[taskcluster:error] exit status 2
Henrik is this something you can take a look at? Will it be fixed with bug 1521447?
Comment hidden (Intermittent Failures Robot) |
Comment 15•6 years ago
|
||
(In reply to Andreea Pavel [:apavel] from comment #13)
Henrik is this something you can take a look at? Will it be fixed with bug 1521447?
This is all blocked by bug 1521447, right. There is nothing I can do at this point. I'm also not sure if gbrown or bc had luck the last weeks to get closer to the problem.
![]() |
||
Comment 16•6 years ago
|
||
I updated bug 1521447 just now, but just with thoughts and feelings: I don't have any concrete progress to report, and haven't been finding time to get back to that investigation.
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 26•6 years ago
|
||
Cosmin, can we please stop classifying failures against this bug which are not Marionette related? Thanks.
Updated•6 years ago
|
Comment 27•6 years ago
|
||
(In reply to Henrik Skupin (:whimboo) [⌚️UTC+2] from comment #26)
Cosmin, can we please stop classifying failures against this bug which are not Marionette related? Thanks.
I removed the classifications for the ones that were not marionette related.
Comment 28•6 years ago
|
||
Yes, sorry about that.
Comment hidden (Intermittent Failures Robot) |
Comment 30•6 years ago
|
||
Note that all the failures for MacOS are related to bug 1495621. With the backout of the appropriate patch it's all good again.
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 79•5 years ago
|
||
Most of the recent failures where all due to bug 1638148. The offending patch got backed out.
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 100•4 years ago
|
||
All the failures happen due to the following error:
[task 2020-12-18T04:58:46.105Z] 04:58:46 INFO - Exiting due to channel error.
[task 2020-12-18T04:58:46.105Z] 04:58:46 INFO - Exiting due to channel error.
[task 2020-12-18T04:58:46.112Z] 04:58:46 INFO - [5732, Main Thread] WARNING: Could not setup crash reporting
[task 2020-12-18T04:58:46.112Z] 04:58:46 INFO - : file /builds/worker/checkouts/gecko/toolkit/xre/nsEmbedFunctions.cpp:521
[task 2020-12-18T04:58:46.112Z] 04:58:46 INFO - [5732, IPC I/O Child] WARNING: failed to create pipe: 2: file /builds/worker/checkouts/gecko/ipc/chromium/src/chrome/common/ipc_channel_win.cc:238
[task 2020-12-18T04:58:46.113Z] 04:58:46 INFO - [5732, IPC I/O Child] WARNING: Unable to create pipe named "4368.13.70523074\1684086862" in client mode.: file /builds/worker/checkouts/gecko/ipc/chromium/src/chrome/common/ipc_channel_win.cc:71
[task 2020-12-18T05:15:26.133Z] 05:15:26 INFO - Automation Error: mozprocess timed out after 1000 seconds running ...
That refers to the following code:
James, it's been a while since you changed that code on bug 1354200, but do you have an idea why QuickExit() doesn't work here and causes a hang?
Comment 101•4 years ago
|
||
In cases when we don't hang forever (see bug 1675175) the Marionette server in Firefox and its active socket connection gets actually closed:
https://treeherder.mozilla.org/logviewer?job_id=324937807&repo=autoland&lineNumber=21661-21673
[task 2020-12-18T15:10:21.234Z] 15:10:21 INFO - 1608304221233 Marionette TRACE [82] Frame script loaded
[task 2020-12-18T15:10:21.253Z] 15:10:21 INFO - 1608304221242 Marionette TRACE Detected remoteness change. New browsing context: 82
[task 2020-12-18T15:10:30.549Z] 15:10:30 INFO - DEBUG: Adding blocker SessionFile: Finish writing Session Restore data for phase profile-before-change
[task 2020-12-18T15:10:30.552Z] 15:10:30 INFO - DEBUG: Completed blocker SessionFile: Finish writing Session Restore data for phase profile-before-change
[task 2020-12-18T15:10:32.547Z] 15:10:32 INFO - DEBUG: Adding blocker JSON store: writing data for phase profile-before-change
[task 2020-12-18T15:14:12.613Z] 15:14:12 INFO - DEBUG: Adding blocker places.sqlite#1: PlacesUtils: promiseKeywordsCache (1) for phase places.sqlite#1: waiting for clients
[task 2020-12-18T15:14:12.613Z] 15:14:12 INFO - DEBUG: Completed blocker places.sqlite#1: PlacesUtils: promiseKeywordsCache (1) for phase places.sqlite#1: waiting for clients
[task 2020-12-18T15:16:21.332Z] 15:16:21 INFO - 1608304581326 Marionette DEBUG Closed connection 20
[task 2020-12-18T15:17:32.351Z] 15:17:32 INFO - Exiting due to channel error.
[task 2020-12-18T15:17:32.351Z] 15:17:32 INFO - Exiting due to channel error.
[task 2020-12-18T15:17:32.478Z] 15:17:32 ERROR - TEST-UNEXPECTED-ERROR | testing/marionette/harness/marionette_harness/tests/unit/test_navigation.py TestNavigate.test_type_to_remote_tab | IOError: Process killed because the connection to Marionette server is lost. Check gecko.log for errors (Reason: Connection timed out after 360.0s)
Maybe there are cases when we leak the socket thread during quick shutdown?
(In reply to Henrik Skupin (:whimboo) [⌚️UTC+2] from comment #100)
All the failures happen due to the following error:
[task 2020-12-18T04:58:46.105Z] 04:58:46 INFO - Exiting due to channel error. [task 2020-12-18T04:58:46.105Z] 04:58:46 INFO - Exiting due to channel error. [task 2020-12-18T04:58:46.112Z] 04:58:46 INFO - [5732, Main Thread] WARNING: Could not setup crash reporting [task 2020-12-18T04:58:46.112Z] 04:58:46 INFO - : file /builds/worker/checkouts/gecko/toolkit/xre/nsEmbedFunctions.cpp:521 [task 2020-12-18T04:58:46.112Z] 04:58:46 INFO - [5732, IPC I/O Child] WARNING: failed to create pipe: 2: file /builds/worker/checkouts/gecko/ipc/chromium/src/chrome/common/ipc_channel_win.cc:238 [task 2020-12-18T04:58:46.113Z] 04:58:46 INFO - [5732, IPC I/O Child] WARNING: Unable to create pipe named "4368.13.70523074\1684086862" in client mode.: file /builds/worker/checkouts/gecko/ipc/chromium/src/chrome/common/ipc_channel_win.cc:71 [task 2020-12-18T05:15:26.133Z] 05:15:26 INFO - Automation Error: mozprocess timed out after 1000 seconds running ...
That refers to the following code:
James, it's been a while since you changed that code on bug 1354200, but do you have an idea why QuickExit() doesn't work here and causes a hang?
No idea, sorry. I'm not sure who still knows about that stuff. Maybe @aklotz due to the windowsness here?
Comment 103•4 years ago
•
|
||
From the documentation for TerminateProcess:
This function stops execution of all threads within the process and requests cancellation of all pending I/O. The terminated process cannot exit until all pending I/O has been completed or canceled. When a process terminates, its kernel object is not destroyed until all processes that have open handles to the process have released those handles.
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 106•4 years ago
|
||
Aaron, so it means that some Firefox process doesn't quit because there is some I/O that cannot be completed within 15 (and more) minutes during a shutdown? Would there be a way to figure out which process that is? Or is it not worth investigating this issue given the low amount of failures and that it only happens on Windows 7?
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 113•4 years ago
|
||
Aaron, do you have any further feedback to my last question? Thanks.
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 117•4 years ago
|
||
(In reply to Henrik Skupin (:whimboo) [⌚️UTC+1] from comment #106)
Aaron, so it means that some Firefox process doesn't quit because there is some I/O that cannot be completed within 15 (and more) minutes during a shutdown? Would there be a way to figure out which process that is? Or is it not worth investigating this issue given the low amount of failures and that it only happens on Windows 7?
I guess I should back up and ask: are we piping any of Firefox's std handles? My train of thought here is that maybe it's waiting on a write to stdout to complete or something...
Comment hidden (Intermittent Failures Robot) |
Comment 119•4 years ago
|
||
Hm, there seems to be something that's wrong in recent jobs. After the call to WebDriver:DeleteSession
it just stops and no further logging appears until the covered failure by this bug. The question is if we really don't execute any following command, after creating a new session, or if stdout simply hangs and/or is not logged.
At least what I can see now is that the hang doesn't seem to happen when requesting a quit, but just after a test ended. Given that I have more important test failures to investigate that bug will be sitting on the back burner.
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment hidden (Intermittent Failures Robot) |
Comment 128•3 years ago
|
||
No more failures within the last year. As such closing as WFM.
Updated•2 years ago
|
Comment 129•2 years ago
|
||
Description
•