Open Bug 1620724 Opened 4 years ago Updated 2 years ago

Intermittent TEST-UNEXPECTED-TIMEOUT | devtools/client/webconsole/test/browser/browser_jsterm_completion_bracket.js | application timed out after 370 seconds with no output

Categories

(DevTools :: Console, defect, P5)

defect

Tracking

(Not tracked)

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Regression)

Details

(Keywords: intermittent-failure, leave-open, regression, Whiteboard: [stockwell disabled])

Attachments

(1 file)

Filed by: nerli [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=292060444&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/Id9sGmBNTICMkYDzfxg6CQ/runs/0/artifacts/public/logs/live_backing.log


[task 2020-03-06T23:37:16.065Z] 23:37:16 INFO - TEST-PASS | devtools/client/webconsole/test/browser/browser_jsterm_completion_bracket.js | Test filtering with template literal and string - completeNode is empty -
[task 2020-03-06T23:37:16.065Z] 23:37:16 INFO - Test that filtering is case insensitive - test popup opening
[task 2020-03-06T23:37:16.065Z] 23:37:16 INFO - Buffered messages finished
[task 2020-03-06T23:37:16.066Z] 23:37:16 ERROR - TEST-UNEXPECTED-TIMEOUT | devtools/client/webconsole/test/browser/browser_jsterm_completion_bracket.js | application timed out after 370 seconds with no output
[task 2020-03-06T23:37:16.066Z] 23:37:16 ERROR - Force-terminating active process(es).
[task 2020-03-06T23:37:16.066Z] 23:37:16 INFO - Determining child pids from psutil...
[task 2020-03-06T23:37:16.066Z] 23:37:16 INFO - [4216]
[task 2020-03-06T23:37:16.066Z] 23:37:16 INFO - ==> process 4216 launched child process 5780 ("Z:\task_1583534332\build\application\firefox\firefox.exe" -contentproc --channel="4216.0.1306129185\300983939" -childID 1 -isForBrowser -prefsHandle 2196 -prefMapHandle 2188 -prefsLen 1 -prefMapSize 231142 -parentBuildID 20200306215136 -appdir "Z:\task_1583534332\build\application\firefox\browser" - 4216 "\.\pipe\gecko-crash-server-pipe.4216" 2240 tab)
[task 2020-03-06T23:37:16.066Z] 23:37:16 INFO - ==> process 4216 launched child process 4088 ("Z:\task_1583534332\build\application\firefox\firefox.exe" -contentproc --channel="4216.6.731114109\1866264740" -childID 2 -isForBrowser -prefsHandle 2448 -prefMapHandle 2444 -prefsLen 463 -prefMapSize 231142 -parentBuildID 20200306215136 -appdir "Z:\task_1583534332\build\application\firefox\browser" - 4216 "\.\pipe\gecko-crash-server-pipe.4216" 2460 tab)
[task 2020-03-06T23:37:16.066Z] 23:37:16 INFO - ==> process 4216 launched child process 5116 ("Z:\task_1583534332\build\application\firefox\firefox.exe" -contentproc --channel="4216.12.652952767\1258775980" -childID 3 -isForBrowser -prefsHandle 4628 -prefMapHandle 4616 -prefsLen 524 -prefMapSize 231142 -parentBuildID 20200306215136 -appdir "Z:\task_1583534332\build\application\firefox\browser" - 4216 "\.\pipe\gecko-crash-server-pipe.4216" 4640 tab)
[task 2020-03-06T23:37:16.067Z] 23:37:16 INFO - ==> process 4216 launched child process 2824 ("Z:\task_1583534332\build\application\firefox\firefox.exe" -contentproc --channel="4216.18.1258662355\557615127" -childID 4 -isForBrowser -prefsHandle 3556 -prefMapHandle 3392 -prefsLen 10749 -prefMapSize 231142 -parentBuildID 20200306215136 -appdir "Z:\task_1583534332\build\application\firefox\browser" - 4216 "\.\pipe\gecko-crash-server-pipe.4216" 4504 tab)
[task 2020-03-06T23:37:16.067Z] 23:37:16 INFO - ==> process 4216 launched child process 2356 ("Z:\task_1583534332\build\application\firefox\firefox.exe" -contentproc --channel="4216.24.1245120136\919735417" -childID 5 -isForBrowser -prefsHandle 3064 -prefMapHandle 3052 -prefsLen 10849 -prefMapSize 231142 -parentBuildID 20200306215136 -appdir "Z:\task_1583534332\build\application\firefox\browser" - 4216 "\.\pipe\gecko-crash-server-pipe.4216" 2680 tab)
[task 2020-03-06T23:37:16.067Z] 23:37:16 INFO - ==> process 4216 launched child process 4540 ("Z:\task_1583534332\build\application\firefox\firefox.exe" -contentproc --channel="4216.30.371593163\1437321909" -childID 6 -isForBrowser -prefsHandle 3972 -prefMapHandle 3524 -prefsLen 10938 -prefMapSize 231142 -parentBuildID 20200306215136 -appdir "Z:\task_1583534332\build\application\firefox\browser" - 4216 "\.\pipe\gecko-crash-server-pipe.4216" 4580 tab)
[task 2020-03-06T23:37:16.067Z] 23:37:16 INFO - ==> process 4216 launched child process 3840 ("Z:\task_1583534332\build\application\firefox\firefox.exe" -contentproc --channel="4216.36.566680292\397016332" -childID 7 -isForBrowser -prefsHandle 2648 -prefMapHandle 3940 -prefsLen 10938 -prefMapSize 231142 -parentBuildID 20200306215136 -appdir "Z:\task_1583534332\build\application\firefox\browser" - 4216 "\.\pipe\gecko-crash-server-pipe.4216" 3764 tab)
[task 2020-03-06T23:37:16.067Z] 23:37:16 INFO - ==> process 4216 launched child process 5784 ("Z:\task_1583534332\build\application\firefox\firefox.exe" -contentproc --channel="4216.42.542280001\205201020" -childID 8 -isForBrowser -prefsHandle 4292 -prefMapHandle 4092 -prefsLen 11018 -prefMapSize 231142 -parentBuildID 20200306215136 -appdir "Z:\task_1583534332\build\application\firefox\browser" - 4216 "\.\pipe\gecko-crash-server-pipe.4216" 3772 tab)
[task 2020-03-06T23:37:16.067Z] 23:37:16 INFO - ==> process 4216 launched child process 2404 ("Z:\task_1583534332\build\application\firefox\firefox.exe" -contentproc --channel="4216.48.2069272118\1250651720" -childID 9 -isForBrowser -prefsHandle 3256 -prefMapHandle 3364 -prefsLen 11018 -prefMapSize 231142 -parentBuildID 20200306215136 -appdir "Z:\task_1583534332\build\application\firefox\browser" - 4216 "\.\pipe\gecko-crash-server-pipe.4216" 3940 tab)
[task 2020-03-06T23:37:16.067Z] 23:37:16 INFO - Found child pids: set([3840, 2404, 2824, 4540, 5784, 4088, 5780, 4216, 2356, 5116])
[task 2020-03-06T23:37:16.067Z] 23:37:16 INFO - Killing process: 3840

See Also: → 1620622
See Also: → 1622141

This has 108 total failures in the last 7 days: https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2020-03-16&endday=2020-03-23&tree=trunk&bug=1620724 It fails only on windows7-32 debug.
Recent log: https://treeherder.mozilla.org/logviewer.html#?job_id=294279369&repo=autoland

[task 2020-03-23T00:24:39.202Z] 00:24:39     INFO - TEST-PASS | devtools/client/webconsole/test/browser/browser_jsterm_completion_bracket.js | Test filtering with simple quote and string - completeNode is empty - 
[task 2020-03-23T00:24:39.203Z] 00:24:39     INFO - Test filtering with template literal and string - test popup opening
[task 2020-03-23T00:24:39.203Z] 00:24:39     INFO - Buffered messages finished
[task 2020-03-23T00:24:39.203Z] 00:24:39    ERROR - TEST-UNEXPECTED-TIMEOUT | devtools/client/webconsole/test/browser/browser_jsterm_completion_bracket.js | application timed out after 370 seconds with no output
[task 2020-03-23T00:24:39.204Z] 00:24:39    ERROR - Force-terminating active process(es).
[task 2020-03-23T00:24:39.204Z] 00:24:39     INFO - Determining child pids from psutil...
[task 2020-03-23T00:24:39.204Z] 00:24:39     INFO - [3536]
[task 2020-03-23T00:24:39.204Z] 00:24:39     INFO - ==> process 3536 launched child process 4928 ("Z:\task_1584919073\build\application\firefox\firefox.exe" -contentproc --channel="3536.0.1782727154\1636331769" -childID 1 -isForBrowser -prefsHandle 2160 -prefMapHandle 2152 -prefsLen 1 -prefMapSize 231689 -parentBuildID 20200322231804 -appdir "Z:\task_1584919073\build\application\firefox\browser" - 3536 "\\.\pipe\gecko-crash-server-pipe.3536" 2204 tab)
[task 2020-03-23T00:24:39.205Z] 00:24:39     INFO - ==> process 3536 launched child process 4400 ("Z:\task_1584919073\build\application\firefox\firefox.exe" -contentproc --channel="3536.6.2138239463\1833135750" -childID 2 -isForBrowser -prefsHandle 2456 -prefMapHandle 2452 -prefsLen 507 -prefMapSize 231689 -parentBuildID 20200322231804 -appdir "Z:\task_1584919073\build\application\firefox\browser" - 3536 "\\.\pipe\gecko-crash-server-pipe.3536" 2468 tab)
[task 2020-03-23T00:24:39.206Z] 00:24:39     INFO - ==> process 3536 launched child process 5484 ("Z:\task_1584919073\build\application\firefox\firefox.exe" -contentproc --channel="3536.12.1521665805\187313441" -childID 3 -isForBrowser -prefsHandle 4188 -prefMapHandle 4176 -prefsLen 568 -prefMapSize 231689 -parentBuildID 20200322231804 -appdir "Z:\task_1584919073\build\application\firefox\browser" - 3536 "\\.\pipe\gecko-crash-server-pipe.3536" 4200 tab)
[task 2020-03-23T00:24:39.206Z] 00:24:39     INFO - ==> process 3536 launched child process 3028 ("Z:\task_1584919073\build\application\firefox\firefox.exe" -contentproc --channel="3536.18.1735291669\1385629739" -childID 4 -isForBrowser -prefsHandle 2800 -prefMapHandle 2796 -prefsLen 10622 -prefMapSize 231689 -parentBuildID 20200322231804 -appdir "Z:\task_1584919073\build\application\firefox\browser" - 3536 "\\.\pipe\gecko-crash-server-pipe.3536" 2988 tab)
[task 2020-03-23T00:24:39.207Z] 00:24:39     INFO - ==> process 3536 launched child process 3132 ("Z:\task_1584919073\build\application\firefox\firefox.exe" -contentproc --channel="3536.24.100850857\1713425621" -childID 5 -isForBrowser -prefsHandle 3984 -prefMapHandle 4020 -prefsLen 10884 -prefMapSize 231689 -parentBuildID 20200322231804 -appdir "Z:\task_1584919073\build\application\firefox\browser" - 3536 "\\.\pipe\gecko-crash-server-pipe.3536" 4024 tab)
[task 2020-03-23T00:24:39.207Z] 00:24:39     INFO - ==> process 3536 launched child process 3752 ("Z:\task_1584919073\build\application\firefox\firefox.exe" -contentproc --channel="3536.30.200473545\230271422" -childID 6 -isForBrowser -prefsHandle 4112 -prefMapHandle 2956 -prefsLen 10984 -prefMapSize 231689 -parentBuildID 20200322231804 -appdir "Z:\task_1584919073\build\application\firefox\browser" - 3536 "\\.\pipe\gecko-crash-server-pipe.3536" 3512 tab)
[task 2020-03-23T00:24:39.207Z] 00:24:39     INFO - ==> process 3536 launched child process 5964 ("Z:\task_1584919073\build\application\firefox\firefox.exe" -contentproc --channel="3536.36.1190720678\592058576" -childID 7 -isForBrowser -prefsHandle 2964 -prefMapHandle 2900 -prefsLen 11073 -prefMapSize 231689 -parentBuildID 20200322231804 -appdir "Z:\task_1584919073\build\application\firefox\browser" - 3536 "\\.\pipe\gecko-crash-server-pipe.3536" 4604 tab)
[task 2020-03-23T00:24:39.207Z] 00:24:39     INFO - ==> process 3536 launched child process 5052 ("Z:\task_1584919073\build\application\firefox\firefox.exe" -contentproc --channel="3536.42.1065686546\1951634221" -childID 8 -isForBrowser -prefsHandle 3332 -prefMapHandle 4120 -prefsLen 11073 -prefMapSize 231689 -parentBuildID 20200322231804 -appdir "Z:\task_1584919073\build\application\firefox\browser" - 3536 "\\.\pipe\gecko-crash-server-pipe.3536" 4124 tab)
[task 2020-03-23T00:24:39.207Z] 00:24:39     INFO - ==> process 3536 launched child process 2516 ("Z:\task_1584919073\build\application\firefox\firefox.exe" -contentproc --channel="3536.48.162121191\1059164682" -childID 9 -isForBrowser -prefsHandle 2900 -prefMapHandle 4568 -prefsLen 11153 -prefMapSize 231689 -parentBuildID 20200322231804 -appdir "Z:\task_1584919073\build\application\firefox\browser" - 3536 "\\.\pipe\gecko-crash-server-pipe.3536" 1220 tab)
[task 2020-03-23T00:24:39.210Z] 00:24:39     INFO - ==> process 3536 launched child process 4104 ("Z:\task_1584919073\build\application\firefox\firefox.exe" -contentproc --channel="3536.54.30243802\1219594398" -childID 10 -isForBrowser -prefsHandle 3616 -prefMapHandle 3740 -prefsLen 11153 -prefMapSize 231689 -parentBuildID 20200322231804 -appdir "Z:\task_1584919073\build\application\firefox\browser" - 3536 "\\.\pipe\gecko-crash-server-pipe.3536" 3872 tab)
[task 2020-03-23T00:24:39.210Z] 00:24:39     INFO - Found child pids: set([4928, 4400, 3752, 5964, 5052, 5484, 3536, 4104, 3028, 2516, 3132])
[task 2020-03-23T00:24:39.210Z] 00:24:39     INFO - Killing process: 4928
[task 2020-03-23T00:24:39.210Z] 00:24:39     INFO - TEST-INFO | started process screenshot
[task 2020-03-23T00:24:39.273Z] 00:24:39     INFO - TEST-INFO | screenshot: exit 0
[task 2020-03-23T00:24:39.412Z] 00:24:39     INFO - Killing process: 4400
[task 2020-03-23T00:24:39.412Z] 00:24:39     INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-03-23T00:24:39.512Z] 00:24:39     INFO - Killing process: 3752
[task 2020-03-23T00:24:39.512Z] 00:24:39     INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-03-23T00:24:39.607Z] 00:24:39     INFO - Killing process: 5964
[task 2020-03-23T00:24:39.607Z] 00:24:39     INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-03-23T00:24:39.702Z] 00:24:39     INFO - Killing process: 5052
[task 2020-03-23T00:24:39.702Z] 00:24:39     INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-03-23T00:24:39.789Z] 00:24:39     INFO - Killing process: 5484
[task 2020-03-23T00:24:39.789Z] 00:24:39     INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-03-23T00:24:39.890Z] 00:24:39     INFO - Killing process: 3536
[task 2020-03-23T00:24:39.890Z] 00:24:39     INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-03-23T00:24:40.105Z] 00:24:40     INFO - Killing process: 4104
[task 2020-03-23T00:24:40.105Z] 00:24:40     INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-03-23T00:24:40.106Z] 00:24:40  WARNING - mozcrash kill_pid(): unable to get handle for pid 4104: 87
[task 2020-03-23T00:24:40.106Z] 00:24:40     INFO - Killing process: 3028
[task 2020-03-23T00:24:40.107Z] 00:24:40     INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-03-23T00:24:40.107Z] 00:24:40  WARNING - mozcrash kill_pid(): unable to get handle for pid 3028: 87
[task 2020-03-23T00:24:40.107Z] 00:24:40     INFO - Killing process: 2516
[task 2020-03-23T00:24:40.108Z] 00:24:40     INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-03-23T00:24:40.108Z] 00:24:40  WARNING - mozcrash kill_pid(): unable to get handle for pid 2516: 87
[task 2020-03-23T00:24:40.109Z] 00:24:40     INFO - Killing process: 3132
[task 2020-03-23T00:24:40.109Z] 00:24:40     INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-03-23T00:24:40.109Z] 00:24:40  WARNING - mozcrash kill_pid(): unable to get handle for pid 3132: 87
[task 2020-03-23T00:24:40.109Z] 00:24:40     INFO - psutil found pid 4400 dead
[task 2020-03-23T00:24:40.110Z] 00:24:40     INFO - psutil found pid 3752 dead
[task 2020-03-23T00:24:40.110Z] 00:24:40     INFO - psutil found pid 4104 dead
[task 2020-03-23T00:24:40.110Z] 00:24:40     INFO - psutil found pid 5964 dead
[task 2020-03-23T00:24:40.110Z] 00:24:40     INFO - psutil found pid 3028 dead
[task 2020-03-23T00:24:40.111Z] 00:24:40     INFO - psutil found pid 3132 dead
[task 2020-03-23T00:24:40.111Z] 00:24:40     INFO - psutil found pid 2516 dead
[task 2020-03-23T00:24:40.111Z] 00:24:40     INFO - psutil found pid 4928 dead
[task 2020-03-23T00:24:40.111Z] 00:24:40     INFO - psutil found pid 5484 dead
[task 2020-03-23T00:24:40.111Z] 00:24:40     INFO - psutil found pid 5052 dead
[task 2020-03-23T00:24:40.111Z] 00:24:40     INFO - psutil found pid 3536 dead
[task 2020-03-23T00:24:40.112Z] 00:24:40     INFO - Killing process: 2228
[task 2020-03-23T00:24:40.112Z] 00:24:40     INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-03-23T00:24:40.112Z] 00:24:40  WARNING - mozcrash kill_pid(): unable to terminate pid 2228: 5
[task 2020-03-23T00:24:40.112Z] 00:24:40     INFO - psutil found pid 2228 dead
[task 2020-03-23T00:24:40.159Z] 00:24:40     INFO - TEST-INFO | Main app process: exit 1
[task 2020-03-23T00:24:40.159Z] 00:24:40    ERROR - TEST-UNEXPECTED-FAIL | ShutdownLeaks | process() called before end of test suite
[task 2020-03-23T00:24:40.159Z] 00:24:40     INFO - TEST-INFO | Confirming we saw 174 DOCSHELL created and 158 destroyed log strings.
[task 2020-03-23T00:24:40.160Z] 00:24:40     INFO - TEST-INFO | Confirming we saw 473 DOMWINDOW created and 437 destroyed log strings.
[task 2020-03-23T00:24:40.160Z] 00:24:40     INFO - Buffered messages finished
[task 2020-03-23T00:24:40.160Z] 00:24:40    ERROR - TEST-UNEXPECTED-FAIL | devtools/client/webconsole/test/browser/browser_jsterm_completion_bracket.js | application terminated with exit code 1

Nicholas, could you try and fix it as it will be soon on the disable-recommended bugs list (>150 failures in last 30 days). Thank you.

Flags: needinfo?(nchevobbe)
Regressed by: 1609942
Whiteboard: [stockwell needswork:owner]
Has Regression Range: --- → yes
Whiteboard: [stockwell disable-recommended] → [stockwell needswork:owner]
Assignee: nobody → dvarga
Status: NEW → ASSIGNED
Pushed by malexandru@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/326a0419dcee
Disable browser_jsterm_completion_bracket.js on win 7 debug  for frequent failures. r=jmaher
Keywords: leave-open
Whiteboard: [stockwell disable-recommended] → [stockwell disabled]
Flags: needinfo?(nchevobbe)

The bug assignee didn't login in Bugzilla in the last 7 months.
:nchevobbe, could you have a look please?
For more information, please visit auto_nag documentation.

Assignee: dvarga → nobody
Status: ASSIGNED → NEW
Flags: needinfo?(nchevobbe)
Flags: needinfo?(nchevobbe)
Severity: normal → S3
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: