Closed
Bug 1782867
Opened 3 years ago
Closed 3 years ago
Intermittent TEST-UNEXPECTED-TIMEOUT | devtools/client/framework/browser-toolbox/test/browser_browser_toolbox_unavailable_children.js (finished) | application timed out after 370 seconds with no output | Force-terminating active process(es).
Categories
(DevTools :: Framework, defect, P5)
DevTools
Framework
Tracking
(Not tracked)
RESOLVED
DUPLICATE
of bug 1782568
People
(Reporter: intermittent-bug-filer, Unassigned)
Details
(Keywords: intermittent-failure)
Filed by: nfay [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=386222856&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/LEA-zRt_S4mR-HGKx6Z4Ng/runs/0/artifacts/public/logs/live_backing.log
[task 2022-08-03T04:16:24.950Z] 04:16:24 INFO - TEST-OK | devtools/client/framework/browser-toolbox/test/browser_browser_toolbox_unavailable_children.js | took 13378ms
[task 2022-08-03T04:16:24.958Z] 04:16:24 INFO - GECKO(2616) | [Child 2641: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 103a57800 == 1 [pid = 2641] [id = 5]
[task 2022-08-03T04:16:24.958Z] 04:16:24 INFO - GECKO(2616) | [Child 2641: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 1 (10119bf10) [pid = 2641] [serial = 11] [outer = 0]
[task 2022-08-03T04:16:24.959Z] 04:16:24 INFO - GECKO(2616) | [Child 2641: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (103a57c00) [pid = 2641] [serial = 12] [outer = 10119bf10]
[task 2022-08-03T04:16:24.978Z] 04:16:24 INFO - checking window state
[task 2022-08-03T04:16:24.978Z] 04:16:24 INFO - GECKO(2616) | must wait for focus
[task 2022-08-03T04:16:25.472Z] 04:16:25 INFO - GECKO(2616) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /var/folders/zx/7g2d_ks9053f0vk5jmsl43pm000014/T/tmpmfd1804m.mozrunner/runtests_leaks_tab_pid2729.log
[task 2022-08-03T04:16:25.472Z] 04:16:25 INFO - GECKO(2616) | [2729, Main Thread] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp:339
[task 2022-08-03T04:16:25.517Z] 04:16:25 INFO - GECKO(2616) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /var/folders/zx/7g2d_ks9053f0vk5jmsl43pm000014/T/tmpmfd1804m.mozrunner/runtests_leaks_tab_pid2730.log
[task 2022-08-03T04:16:25.518Z] 04:16:25 INFO - GECKO(2616) | [2730, Main Thread] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp:339
[task 2022-08-03T04:16:25.564Z] 04:16:25 INFO - GECKO(2616) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /var/folders/zx/7g2d_ks9053f0vk5jmsl43pm000014/T/tmpmfd1804m.mozrunner/runtests_leaks_tab_pid2731.log
[task 2022-08-03T04:16:25.564Z] 04:16:25 INFO - GECKO(2616) | [2731, Main Thread] WARNING: XPCOM_MEM_BLOAT_LOG is set, disabling native allocations.: file /builds/worker/checkouts/gecko/tools/profiler/core/platform.cpp:339
[task 2022-08-03T04:16:28.173Z] 04:16:28 INFO - GECKO(2616) | [Parent 2616: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 13111d400 == 5 [pid = 2616] [id = 10] [url = about:srcdoc]
[task 2022-08-03T04:16:28.646Z] 04:16:28 INFO - GECKO(2616) | [Parent 2616: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 11 (105a1f430) [pid = 2616] [serial = 27] [outer = 0] [url = about:srcdoc]
[task 2022-08-03T04:16:29.045Z] 04:16:29 INFO - GECKO(2616) | [Child 2618: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 11 (10719c0e0) [pid = 2618] [serial = 19] [outer = 0] [url = moz-extension://67af7658-6d8a-4759-8f7c-9b16a4d2d563/sidebar.html]
[task 2022-08-03T04:16:32.983Z] 04:16:32 INFO - GECKO(2616) | [Parent 2616: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 10 (131122c00) [pid = 2616] [serial = 28] [outer = 0] [url = about:blank]
[task 2022-08-03T04:16:33.618Z] 04:16:33 INFO - GECKO(2616) | [Child 2618: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 10 (10ab5cc00) [pid = 2618] [serial = 21] [outer = 0] [url = moz-extension://67af7658-6d8a-4759-8f7c-9b16a4d2d563/sidebar.html]
[task 2022-08-03T04:16:33.706Z] 04:16:33 INFO - GECKO(2616) | [Child 2619: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 104a36000 == 0 [pid = 2619] [id = 9] [url = about:blank]
[task 2022-08-03T04:16:33.928Z] 04:16:33 INFO - GECKO(2616) | [Child 2619: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 1 (10429c650) [pid = 2619] [serial = 24] [outer = 0] [url = about:blank]
[task 2022-08-03T04:16:38.116Z] 04:16:38 INFO - GECKO(2616) | [Child 2619: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 0 (104a36800) [pid = 2619] [serial = 25] [outer = 0] [url = about:blank]
[task 2022-08-03T04:20:43.667Z] 04:20:43 INFO - GECKO(2616) | [2022-08-03T04:20:43Z WARN rkv::backend::impl_safe::environment] `load_ratio()` is irrelevant for this storage backend.
[task 2022-08-03T04:20:43.703Z] 04:20:43 INFO - Console message: [JavaScript Error: "Invalid ETag value "undefined"" {file: "resource://services-settings/SyncHistory.jsm" line: 52}]
[task 2022-08-03T04:20:43.703Z] 04:20:43 INFO - store@resource://services-settings/SyncHistory.jsm:52:13
[task 2022-08-03T04:20:43.703Z] 04:20:43 INFO -
[task 2022-08-03T04:22:43.815Z] 04:22:43 INFO - GECKO(2616) | 1659500563814 addons.xpi ERROR System addon update list error Error: got node name: html, expected: updates
[task 2022-08-03T04:22:43.816Z] 04:22:43 INFO - Console message: [JavaScript Error: "1659500563814 addons.xpi ERROR System addon update list error Error: got node name: html, expected: updates" {file: "resource://gre/modules/Log.jsm" line: 724}]
[task 2022-08-03T04:22:43.816Z] 04:22:43 INFO - append@resource://gre/modules/Log.jsm:724:12
[task 2022-08-03T04:22:43.816Z] 04:22:43 INFO - log@resource://gre/modules/Log.jsm:380:16
[task 2022-08-03T04:22:43.816Z] 04:22:43 INFO - error@resource://gre/modules/Log.jsm:388:10
[task 2022-08-03T04:22:43.817Z] 04:22:43 INFO - updateSystemAddons/res<@resource://gre/modules/addons/XPIInstall.jsm:4086:25
[task 2022-08-03T04:22:43.817Z] 04:22:43 INFO -
[task 2022-08-03T04:28:53.883Z] 04:28:53 INFO - Buffered messages finished
[task 2022-08-03T04:28:53.883Z] 04:28:53 ERROR - TEST-UNEXPECTED-TIMEOUT | devtools/client/framework/browser-toolbox/test/browser_browser_toolbox_unavailable_children.js (finished) | application timed out after 370 seconds with no output
[task 2022-08-03T04:28:53.884Z] 04:28:53 ERROR - Force-terminating active process(es).
[task 2022-08-03T04:28:53.884Z] 04:28:53 INFO - Determining child pids from psutil...
[task 2022-08-03T04:28:53.886Z] 04:28:53 INFO - [2618, 2619, 2625, 2641, 2729, 2730, 2731]
[task 2022-08-03T04:28:53.886Z] 04:28:53 INFO - ==> process 2616 launched child process 2618
[task 2022-08-03T04:28:53.887Z] 04:28:53 INFO - ==> process 2616 launched child process 2619
[task 2022-08-03T04:28:53.887Z] 04:28:53 INFO - ==> process 2616 launched child process 2625
[task 2022-08-03T04:28:53.887Z] 04:28:53 INFO - ==> process 2616 launched child process 2626
[task 2022-08-03T04:28:53.888Z] 04:28:53 INFO - ==> process 2616 launched child process 2627
[task 2022-08-03T04:28:53.888Z] 04:28:53 INFO - ==> process 2616 launched child process 2628
[task 2022-08-03T04:28:53.888Z] 04:28:53 INFO - ==> process 2616 launched child process 2641
[task 2022-08-03T04:28:53.889Z] 04:28:53 INFO - ==> process 2616 launched child process 2642
[task 2022-08-03T04:28:53.889Z] 04:28:53 INFO - ==> process 2616 launched child process 2653
[task 2022-08-03T04:28:53.889Z] 04:28:53 INFO - ==> process 2616 launched child process 2654
[task 2022-08-03T04:28:53.890Z] 04:28:53 INFO - ==> process 2616 launched child process 2697
[task 2022-08-03T04:28:53.890Z] 04:28:53 INFO - ==> process 2616 launched child process 2698
[task 2022-08-03T04:28:53.890Z] 04:28:53 INFO - ==> process 2616 launched child process 2699
[task 2022-08-03T04:28:53.891Z] 04:28:53 INFO - ==> process 2616 launched child process 2700
[task 2022-08-03T04:28:53.891Z] 04:28:53 INFO - ==> process 2616 launched child process 2723
[task 2022-08-03T04:28:53.891Z] 04:28:53 INFO - ==> process 2616 launched child process 2729
[task 2022-08-03T04:28:53.892Z] 04:28:53 INFO - ==> process 2616 launched child process 2730
[task 2022-08-03T04:28:53.892Z] 04:28:53 INFO - ==> process 2616 launched child process 2731
[task 2022-08-03T04:28:53.892Z] 04:28:53 INFO - Found child pids: {2625, 2626, 2627, 2628, 2723, 2729, 2730, 2731, 2697, 2698, 2699, 2700, 2641, 2642, 2618, 2619, 2653, 2654}
[task 2022-08-03T04:28:53.893Z] 04:28:53 INFO - Failed to get child procs
[task 2022-08-03T04:28:53.893Z] 04:28:53 INFO - Killing process: 2625
[task 2022-08-03T04:28:53.893Z] 04:28:53 INFO - TEST-INFO | started process screencapture
[task 2022-08-03T04:28:54.163Z] 04:28:54 INFO - TEST-INFO | screencapture: exit 0
[task 2022-08-03T04:28:54.164Z] 04:28:54 INFO - Killing process: 2626
[task 2022-08-03T04:28:54.164Z] 04:28:54 INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-08-03T04:28:54.164Z] 04:28:54 INFO - Can't trigger Breakpad, process no longer exists
[task 2022-08-03T04:28:54.165Z] 04:28:54 INFO - Killing process: 2627
[task 2022-08-03T04:28:54.165Z] 04:28:54 INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-08-03T04:28:54.166Z] 04:28:54 INFO - Can't trigger Breakpad, process no longer exists
[task 2022-08-03T04:28:54.166Z] 04:28:54 INFO - Killing process: 2628
[task 2022-08-03T04:28:54.167Z] 04:28:54 INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-08-03T04:28:54.167Z] 04:28:54 INFO - Can't trigger Breakpad, process no longer exists
[task 2022-08-03T04:28:54.167Z] 04:28:54 INFO - Killing process: 2723
[task 2022-08-03T04:28:54.168Z] 04:28:54 INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-08-03T04:28:54.168Z] 04:28:54 INFO - Can't trigger Breakpad, process no longer exists
[task 2022-08-03T04:28:54.168Z] 04:28:54 INFO - Killing process: 2729
[task 2022-08-03T04:28:54.169Z] 04:28:54 INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-08-03T04:28:54.169Z] 04:28:54 INFO - Killing process: 2730
[task 2022-08-03T04:28:54.169Z] 04:28:54 INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-08-03T04:28:54.170Z] 04:28:54 INFO - Killing process: 2731
[task 2022-08-03T04:28:54.170Z] 04:28:54 INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-08-03T04:28:54.171Z] 04:28:54 INFO - Killing process: 2697
[task 2022-08-03T04:28:54.171Z] 04:28:54 INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-08-03T04:28:54.171Z] 04:28:54 INFO - Can't trigger Breakpad, process no longer exists
[task 2022-08-03T04:28:54.172Z] 04:28:54 INFO - Killing process: 2698
[task 2022-08-03T04:28:54.172Z] 04:28:54 INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-08-03T04:28:54.172Z] 04:28:54 INFO - Can't trigger Breakpad, process no longer exists
[task 2022-08-03T04:28:54.173Z] 04:28:54 INFO - Killing process: 2699
[task 2022-08-03T04:28:54.173Z] 04:28:54 INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-08-03T04:28:54.173Z] 04:28:54 INFO - Can't trigger Breakpad, process no longer exists
[task 2022-08-03T04:28:54.174Z] 04:28:54 INFO - Killing process: 2700
[task 2022-08-03T04:28:54.174Z] 04:28:54 INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-08-03T04:28:54.175Z] 04:28:54 INFO - Can't trigger Breakpad, process no longer exists
[task 2022-08-03T04:28:54.175Z] 04:28:54 INFO - Killing process: 2641
[task 2022-08-03T04:28:54.175Z] 04:28:54 INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-08-03T04:28:54.176Z] 04:28:54 INFO - Killing process: 2642
[task 2022-08-03T04:28:54.176Z] 04:28:54 INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-08-03T04:28:54.177Z] 04:28:54 INFO - Can't trigger Breakpad, process no longer exists
[task 2022-08-03T04:28:54.177Z] 04:28:54 INFO - Killing process: 2618
[task 2022-08-03T04:28:54.177Z] 04:28:54 INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-08-03T04:28:54.178Z] 04:28:54 INFO - Killing process: 2619
[task 2022-08-03T04:28:54.178Z] 04:28:54 INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-08-03T04:28:54.178Z] 04:28:54 INFO - Killing process: 2653
[task 2022-08-03T04:28:54.179Z] 04:28:54 INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-08-03T04:28:54.179Z] 04:28:54 INFO - Can't trigger Breakpad, process no longer exists
[task 2022-08-03T04:28:54.179Z] 04:28:54 INFO - Killing process: 2654
[task 2022-08-03T04:28:54.180Z] 04:28:54 INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-08-03T04:28:54.180Z] 04:28:54 INFO - Can't trigger Breakpad, process no longer exists
[task 2022-08-03T04:28:54.181Z] 04:28:54 INFO - Killing process: 2616
[task 2022-08-03T04:28:54.181Z] 04:28:54 INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-08-03T04:28:54.358Z] 04:28:54 INFO - psutil found pid 2616 dead
[task 2022-08-03T04:28:54.359Z] 04:28:54 INFO - TEST-INFO | Main app process: exit 0
[task 2022-08-03T04:28:54.360Z] 04:28:54 ERROR - TEST-UNEXPECTED-FAIL | ShutdownLeaks | process() called before end of test suite
[task 2022-08-03T04:28:54.360Z] 04:28:54 INFO - TEST-INFO | Confirming we saw 43 DOCSHELL created and 30 destroyed log strings.
[task 2022-08-03T04:28:54.361Z] 04:28:54 INFO - TEST-INFO | Confirming we saw 111 DOMWINDOW created and 84 destroyed log strings.
[task 2022-08-03T04:28:54.361Z] 04:28:54 INFO - runtests.py | Application ran for: 0:14:42.115851
|
||
Comment 1•3 years ago
|
||
It seems that the test itself actually finished long before the timeout is hit:
TEST-OK | devtools/client/framework/browser-toolbox/test/browser_browser_toolbox_unavailable_children.js | took 13378ms
But then we wait for several minutes during the test teardown (so I'm guessing somewhere in the harness?)
I notice that we have a whole class of similar intermittents: https://bugzilla.mozilla.org/buglist.cgi?quicksearch=TEST-UNEXPECTED-TIMEOUT%20%7C%20devtools%2Fclient%2Fframework%2Fbrowser-toolbox&list_id=16166788
Most of them show the same pattern: the test finishes early enough, but we still get a timeout. Given that all those tests start a multiprocess browser toolbox, they might be attempting to debug a new target while we try to shut down the test? In any case I think this is not an issue specific to this new test but something that can happen to any of the Browser Toolbox tests under devtools/client/framework/browser-toolbox/test/
| Comment hidden (Intermittent Failures Robot) |
|
||
Updated•3 years ago
|
Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → DUPLICATE
You need to log in
before you can comment on or make changes to this bug.
Description
•