Closed Bug 1616953 Opened 5 years ago Closed 4 years ago

Intermittent TEST-UNEXPECTED-TIMEOUT | toolkit/mozapps/extensions/test/xpinstall/browser_installchrome.js | application timed out after 370 seconds with no output

Categories

(Toolkit :: Add-ons Manager, defect, P5)

Product:
Toolkit
Component:
Add-ons Manager
Type:
defect

Tracking

()

Status:
RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure)

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

[task 2020-02-20T18:24:32.260Z] 18:24:32 INFO - TEST-PASS | toolkit/mozapps/extensions/test/xpinstall/browser_installchrome.js | Should have seen the expected number of installs started -
[task 2020-02-20T18:24:32.260Z] 18:24:32 INFO - Console message: [JavaScript Error: "The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol." {file: "http://example.com/browser/toolkit/mozapps/extensions/test/xpinstall/installchrome.html?%20http%3A%2F%2Fexample.com%2Fbrowser%2Ftoolkit%2Fmozapps%2Fextensions%2Ftest%2Fxpinstall%2Famosigned.xpi" line: 0}]
[task 2020-02-20T18:24:32.261Z] 18:24:32 INFO - Console message: 1582222691148 addons.xpi DEBUG Download started for http://example.com/browser/toolkit/mozapps/extensions/test/xpinstall/amosigned.xpi to file C:\Users\task_1582220244\AppData\Local\Temp\tmp-z2c.xpi
[task 2020-02-20T18:24:32.261Z] 18:24:32 INFO - Console message: 1582222691149 addons.xpi DEBUG Download of http://example.com/browser/toolkit/mozapps/extensions/test/xpinstall/amosigned.xpi completed.
[task 2020-02-20T18:24:32.261Z] 18:24:32 INFO - Console message: 1582222691217 addons.repository DEBUG cacheAddons: enabled false IDs ["amosigned-xpi@tests.mozilla.org"]
[task 2020-02-20T18:24:32.261Z] 18:24:32 INFO - Buffered messages finished
[task 2020-02-20T18:24:32.261Z] 18:24:32 ERROR - TEST-UNEXPECTED-TIMEOUT | toolkit/mozapps/extensions/test/xpinstall/browser_installchrome.js | application timed out after 370 seconds with no output
[task 2020-02-20T18:24:32.262Z] 18:24:32 ERROR - Force-terminating active process(es).
[task 2020-02-20T18:24:32.262Z] 18:24:32 INFO - Determining child pids from psutil...
[task 2020-02-20T18:24:32.266Z] 18:24:32 INFO - [6996]
[task 2020-02-20T18:24:32.266Z] 18:24:32 INFO - ==> process 6996 launched child process 6248 ("Z:\task_1582220244\build\application\firefox\firefox.exe" -contentproc --channel="6996.0.1577796852\933978069" -parentBuildID 20200220163543 -prefsHandle 2260 -prefMapHandle 2252 -prefsLen 1 -prefMapSize 228845 -greomni "Z:\task_1582220244\build\application\firefox\omni.ja" -appomni "Z:\task_1582220244\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1582220244\build\application\firefox\browser" - 6996 "\.\pipe\gecko-crash-server-pipe.6996" 2316 gpu)
[task 2020-02-20T18:24:32.266Z] 18:24:32 INFO - ==> process 6996 launched child process 5748 ("Z:\task_1582220244\build\application\firefox\firefox.exe" -contentproc --channel="6996.6.881607712\1976470283" -childID 1 -isForBrowser -prefsHandle 2892 -prefMapHandle 2888 -prefsLen 1391 -prefMapSize 228845 -parentBuildID 20200220163543 -greomni "Z:\task_1582220244\build\application\firefox\omni.ja" -appomni "Z:\task_1582220244\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1582220244\build\application\firefox\browser" - 6996 "\.\pipe\gecko-crash-server-pipe.6996" 2900 tab)
[task 2020-02-20T18:24:32.267Z] 18:24:32 INFO - ==> process 6996 launched child process 8992 ("Z:\task_1582220244\build\application\firefox\firefox.exe" -contentproc --channel="6996.13.1835930750\1454360243" -childID 2 -isForBrowser -prefsHandle 3136 -prefMapHandle 3128 -prefsLen 1857 -prefMapSize 228845 -parentBuildID 20200220163543 -greomni "Z:\task_1582220244\build\application\firefox\omni.ja" -appomni "Z:\task_1582220244\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1582220244\build\application\firefox\browser" - 6996 "\.\pipe\gecko-crash-server-pipe.6996" 3160 tab)
[task 2020-02-20T18:24:32.267Z] 18:24:32 INFO - ==> process 6996 launched child process 2084 ("Z:\task_1582220244\build\application\firefox\firefox.exe" -contentproc --channel="6996.20.94453031\1503443827" -childID 3 -isForBrowser -prefsHandle 3376 -prefMapHandle 3372 -prefsLen 1918 -prefMapSize 228845 -parentBuildID 20200220163543 -greomni "Z:\task_1582220244\build\application\firefox\omni.ja" -appomni "Z:\task_1582220244\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1582220244\build\application\firefox\browser" - 6996 "\.\pipe\gecko-crash-server-pipe.6996" 3308 tab)
[task 2020-02-20T18:24:32.267Z] 18:24:32 INFO - ==> process 6996 launched child process 5016 ("Z:\task_1582220244\build\application\firefox\firefox.exe" -contentproc --channel="6996.27.582843583\1235958376" -childID 4 -isForBrowser -prefsHandle 4408 -prefMapHandle 4388 -prefsLen 11648 -prefMapSize 228845 -parentBuildID 20200220163543 -greomni "Z:\task_1582220244\build\application\firefox\omni.ja" -appomni "Z:\task_1582220244\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1582220244\build\application\firefox\browser" - 6996 "\.\pipe\gecko-crash-server-pipe.6996" 4476 tab)
[task 2020-02-20T18:24:32.267Z] 18:24:32 INFO - ==> process 6996 launched child process 6548 ("Z:\task_1582220244\build\application\firefox\firefox.exe" -contentproc --channel="6996.34.431367183\767653493" -childID 5 -isForBrowser -prefsHandle 4812 -prefMapHandle 4808 -prefsLen 11671 -prefMapSize 228845 -parentBuildID 20200220163543 -greomni "Z:\task_1582220244\build\application\firefox\omni.ja" -appomni "Z:\task_1582220244\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1582220244\build\application\firefox\browser" - 6996 "\.\pipe\gecko-crash-server-pipe.6996" 4768 tab)
[task 2020-02-20T18:24:32.267Z] 18:24:32 INFO - ==> process 6996 launched child process 8824 ("Z:\task_1582220244\build\application\firefox\firefox.exe" -contentproc --channel="6996.41.997353237\173768848" -childID 6 -isForBrowser -prefsHandle 4920 -prefMapHandle 4928 -prefsLen 11721 -prefMapSize 228845 -parentBuildID 20200220163543 -greomni "Z:\task_1582220244\build\application\firefox\omni.ja" -appomni "Z:\task_1582220244\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1582220244\build\application\firefox\browser" - 6996 "\.\pipe\gecko-crash-server-pipe.6996" 4812 tab)
[task 2020-02-20T18:24:32.268Z] 18:24:32 INFO - ==> process 6996 launched child process 8204 ("Z:\task_1582220244\build\application\firefox\firefox.exe" -contentproc --channel="6996.48.888630775\704088518" -childID 7 -isForBrowser -prefsHandle 5252 -prefMapHandle 5248 -prefsLen 11671 -prefMapSize 228845 -parentBuildID 20200220163543 -greomni "Z:\task_1582220244\build\application\firefox\omni.ja" -appomni "Z:\task_1582220244\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1582220244\build\application\firefox\browser" - 6996 "\.\pipe\gecko-crash-server-pipe.6996" 5260 tab)
[task 2020-02-20T18:24:32.268Z] 18:24:32 INFO - ==> process 6996 launched child process 8520 ("Z:\task_1582220244\build\application\firefox\firefox.exe" -contentproc --channel="6996.55.870896631\1270228767" -childID 8 -isForBrowser -prefsHandle 5408 -prefMapHandle 5248 -prefsLen 11721 -prefMapSize 228845 -parentBuildID 20200220163543 -greomni "Z:\task_1582220244\build\application\firefox\omni.ja" -appomni "Z:\task_1582220244\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1582220244\build\application\firefox\browser" - 6996 "\.\pipe\gecko-crash-server-pipe.6996" 5412 tab)
[task 2020-02-20T18:24:32.268Z] 18:24:32 INFO - ==> process 6996 launched child process 8452 ("Z:\task_1582220244\build\application\firefox\firefox.exe" -contentproc --channel="6996.62.445532330\1377708653" -childID 9 -isForBrowser -prefsHandle 5628 -prefMapHandle 5612 -prefsLen 11671 -prefMapSize 228845 -parentBuildID 20200220163543 -greomni "Z:\task_1582220244\build\application\firefox\omni.ja" -appomni "Z:\task_1582220244\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1582220244\build\application\firefox\browser" - 6996 "\.\pipe\gecko-crash-server-pipe.6996" 5248 tab)
[task 2020-02-20T18:24:32.268Z] 18:24:32 INFO - Found child pids: set([8992, 2084, 8452, 6248, 8520, 6548, 8204, 8824, 5748, 5016, 6996])
[task 2020-02-20T18:24:32.268Z] 18:24:32 INFO - Killing process: 8992
[task 2020-02-20T18:24:32.268Z] 18:24:32 INFO - TEST-INFO | started process screenshot

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → INCOMPLETE

This is still happening.

Recent failure: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=301521386&repo=autoland&lineNumber=4710

[task 2020-05-09T05:41:18.631Z] 05:41:18     INFO - TEST-START | toolkit/mozapps/extensions/test/xpinstall/browser_installchrome.js
[task 2020-05-09T05:47:29.272Z] 05:47:29     INFO - Buffered messages logged at 05:41:18
[task 2020-05-09T05:47:29.272Z] 05:47:29     INFO - TEST-PASS | toolkit/mozapps/extensions/test/xpinstall/browser_installchrome.js | Should have seen the expected number of installs started - 
[task 2020-05-09T05:47:29.272Z] 05:47:29     INFO - Console message: [JavaScript Error: "The character encoding of the HTML document was not declared. The document will render with garbled text in some browser configurations if the document contains characters from outside the US-ASCII range. The character encoding of the page must be declared in the document or in the transfer protocol." {file: "http://example.com/browser/toolkit/mozapps/extensions/test/xpinstall/installchrome.html?%20http%3A%2F%2Fexample.com%2Fbrowser%2Ftoolkit%2Fmozapps%2Fextensions%2Ftest%2Fxpinstall%2Famosigned.xpi" line: 0}]
[task 2020-05-09T05:47:29.272Z] 05:47:29     INFO - Buffered messages logged at 05:41:19
[task 2020-05-09T05:47:29.273Z] 05:47:29     INFO - Console message: 1589002879022	addons.xpi	DEBUG	Download started for http://example.com/browser/toolkit/mozapps/extensions/test/xpinstall/amosigned.xpi to file C:\Users\task_1588998445\AppData\Local\Temp\tmp-d7c.xpi
[task 2020-05-09T05:47:29.273Z] 05:47:29     INFO - Console message: 1589002879023	addons.xpi	DEBUG	Download of http://example.com/browser/toolkit/mozapps/extensions/test/xpinstall/amosigned.xpi completed.
[task 2020-05-09T05:47:29.273Z] 05:47:29     INFO - Console message: 1589002879198	addons.repository	DEBUG	cacheAddons: enabled false IDs ["amosigned-xpi@tests.mozilla.org"]
[task 2020-05-09T05:47:29.273Z] 05:47:29     INFO - Buffered messages finished
[task 2020-05-09T05:47:29.273Z] 05:47:29    ERROR - TEST-UNEXPECTED-TIMEOUT | toolkit/mozapps/extensions/test/xpinstall/browser_installchrome.js | application timed out after 370 seconds with no output
[task 2020-05-09T05:47:29.273Z] 05:47:29    ERROR - Force-terminating active process(es).
[task 2020-05-09T05:47:29.274Z] 05:47:29     INFO - Determining child pids from psutil...
[task 2020-05-09T05:47:29.274Z] 05:47:29     INFO - [3824]
[task 2020-05-09T05:47:29.276Z] 05:47:29     INFO - ==> process 3824 launched child process 10256 ("Z:\task_1588998445\build\application\firefox\firefox.exe" -contentproc --channel="3824.0.989284938\665511970" -parentBuildID 20200509034758 -prefsHandle 2188 -prefMapHandle 2164 -prefsLen 1 -prefMapSize 232832 -appdir "Z:\task_1588998445\build\application\firefox\browser" - 3824  gpu)
[task 2020-05-09T05:47:29.276Z] 05:47:29     INFO - ==> process 3824 launched child process 8480 ("Z:\task_1588998445\build\application\firefox\firefox.exe" -contentproc --channel="3824.6.985133133\191239052" -childID 1 -isForBrowser -prefsHandle 1968 -prefMapHandle 1988 -prefsLen 1779 -prefMapSize 232832 -parentBuildID 20200509034758 -appdir "Z:\task_1588998445\build\application\firefox\browser" - 3824  tab)
[task 2020-05-09T05:47:29.277Z] 05:47:29     INFO - ==> process 3824 launched child process 3032 ("Z:\task_1588998445\build\application\firefox\firefox.exe" -contentproc --channel="3824.13.1200413380\2060265723" -childID 2 -isForBrowser -prefsHandle 4832 -prefMapHandle 4828 -prefsLen 2193 -prefMapSize 232832 -parentBuildID 20200509034758 -appdir "Z:\task_1588998445\build\application\firefox\browser" - 3824  tab)
[task 2020-05-09T05:47:29.277Z] 05:47:29     INFO - ==> process 3824 launched child process 9720 ("Z:\task_1588998445\build\application\firefox\firefox.exe" -contentproc --channel="3824.20.186301827\396144046" -childID 3 -isForBrowser -prefsHandle 4968 -prefMapHandle 4972 -prefsLen 2233 -prefMapSize 232832 -parentBuildID 20200509034758 -appdir "Z:\task_1588998445\build\application\firefox\browser" - 3824  tab)
[task 2020-05-09T05:47:29.277Z] 05:47:29     INFO - ==> process 3824 launched child process 6792 ("Z:\task_1588998445\build\application\firefox\firefox.exe" -contentproc --channel="3824.27.782629415\1501410294" -childID 4 -isForBrowser -prefsHandle 4736 -prefMapHandle 3636 -prefsLen 11980 -prefMapSize 232832 -parentBuildID 20200509034758 -appdir "Z:\task_1588998445\build\application\firefox\browser" - 3824  tab)
[task 2020-05-09T05:47:29.277Z] 05:47:29     INFO - ==> process 3824 launched child process 4632 ("Z:\task_1588998445\build\application\firefox\firefox.exe" -contentproc --channel="3824.34.1686543882\1355237874" -childID 5 -isForBrowser -prefsHandle 4756 -prefMapHandle 5244 -prefsLen 12003 -prefMapSize 232832 -parentBuildID 20200509034758 -appdir "Z:\task_1588998445\build\application\firefox\browser" - 3824  tab)
[task 2020-05-09T05:47:29.277Z] 05:47:29     INFO - Found child pids: set([8480, 10256, 4632, 6792, 3824, 9720, 3032])
[task 2020-05-09T05:47:29.277Z] 05:47:29     INFO - Killing process: 8480
[task 2020-05-09T05:47:29.277Z] 05:47:29     INFO - TEST-INFO | started process screenshot
[task 2020-05-09T05:47:29.512Z] 05:47:29     INFO - TEST-INFO | screenshot: exit 0
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Status: REOPENED → RESOLVED
Closed: 5 years ago → 5 years ago
Resolution: --- → INCOMPLETE

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Status: REOPENED → RESOLVED
Closed: 5 years ago → 5 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Status: REOPENED → RESOLVED
Closed: 5 years ago → 5 years ago
Resolution: --- → INCOMPLETE

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=321761033&repo=autoland&lineNumber=7634

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Status: REOPENED → RESOLVED
Closed: 5 years ago → 5 years ago
Resolution: --- → INCOMPLETE

New occurrence: https://treeherder.mozilla.org/logviewer?job_id=325947108&repo=autoland&lineNumber=7062

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Status: REOPENED → RESOLVED
Closed: 5 years ago → 4 years ago
Resolution: --- → INCOMPLETE

This is still hapening.

Recent failure: https://treeherder.mozilla.org/logviewer?job_id=330618667&repo=autoland&lineNumber=8723

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

Status: REOPENED → RESOLVED
Closed: 4 years ago → 4 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.