1472506 - Intermittent browser/components/extensions/test/browser/test-oop-extensions/browser_ext_slow_script.js | Test timed out -

Status: RESOLVED INCOMPLETE

(WebExtensions :: General, defect, P5)

Description

[Treeherder Bug Filer]

Filed by: btara [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=185800098&repo=autoland

https://queue.taskcluster.net/v1/task/IByQl4t-S8a7aYSbQVCqVQ/runs/0/artifacts/public/logs/live_backing.log

23:33:06     INFO -  534 INFO TEST-START | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_slow_script.js
23:33:06     INFO -  GECKO(5472) | [Parent 5472, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
23:33:06     INFO -  GECKO(5472) | [Child 5664, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 346
23:33:51     INFO -  TEST-INFO | started process screenshot
23:33:51     INFO -  TEST-INFO | screenshot: exit 0
23:33:51     INFO -  Buffered messages logged at 23:33:06
23:33:51     INFO -  535 INFO Entering test bound test_slow_content_script
23:33:51     INFO -  536 INFO Extension loaded
23:33:51     INFO -  537 INFO Console message: Warning: attempting to write 16053 bytes to preference extensions.webextensions.uuids. This is bad for general performance and memory usage. Such an amount of data should rather be written to an external file. This preference will not be sent to any content processes.
23:33:51     INFO -  538 INFO Console message: [JavaScript Warning: "Use of nsIFile in content process is deprecated." {file: "resource://gre/modules/FileUtils.jsm" line: 170}]
23:33:51     INFO -  Buffered messages finished
23:33:51    ERROR -  539 INFO TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_slow_script.js | Test timed out -
23:33:51     INFO -  Not taking screenshot here: see the one that was previously logged
23:33:51    ERROR -  540 INFO TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_slow_script.js | Extension left running at test shutdown -
23:33:51     INFO -  Stack trace:
23:33:51     INFO -  chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:ExtensionTestUtils.loadExtension/<:109
23:33:51     INFO -  chrome://mochikit/content/browser-test.js:nextTest:699
23:33:51     INFO -  chrome://mochikit/content/browser-test.js:timeoutFn:1195
23:33:51     INFO -  setTimeout handler*chrome://mochikit/content/browser-test.js:Tester_execTest:1157
23:33:51     INFO -  chrome://mochikit/content/browser-test.js:nextTest/<:991
23:33:51     INFO -  chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:795
23:33:59     INFO -  541 INFO Console message: [JavaScript Error: "Timeout while waiting for extension child to shutdown: "Slow Script Extension" (ID: 0f0f10d070fefa9aa127ae75a220ea0cd0cd1b5f@temporary-addon, moz-extension://64f50575-2a52-4a88-87bf-88fa3f48e16d/)" {file: "resource://gre/modules/Extension.jsm" line: 1832}]
23:33:59     INFO -  shutdown@resource://gre/modules/Extension.jsm:1832:7
23:33:59     INFO -  async*shutdown@resource://gre/modules/Extension.jsm:1195:18
23:33:59     INFO -  callBootstrapMethod@resource://gre/modules/addons/XPIProvider.jsm:1588:20
23:33:59     INFO -  async*_shutdown@resource://gre/modules/addons/XPIProvider.jsm:1724:12
23:33:59     INFO -  async*shutdown@resource://gre/modules/addons/XPIProvider.jsm:1717:28
23:33:59     INFO -  async*_uninstall@resource://gre/modules/addons/XPIProvider.jsm:1802:13
23:33:59     INFO -  async*uninstall@resource://gre/modules/addons/XPIProvider.jsm:1797:12
23:33:59     INFO -  uninstallAddon@resource://gre/modules/addons/XPIInstall.jsm:3993:15
23:33:59     INFO -  async*uninstall@resource://gre/modules/addons/XPIDatabase.jsm:1012:12
23:33:59     INFO -  async*shutdown@resource://testing-common/ExtensionTestCommon.jsm:151:5
23:33:59     INFO -  _receiveMessageAPI@chrome://mochikit/content/tests/SimpleTest/SpecialPowersObserverAPI.js:647:9
23:33:59     INFO -  ChromePowers.prototype._receiveMessage@chrome://mochikit/content/tests/SimpleTest/ChromePowers.js:83:14
23:33:59     INFO -  ChromePowers.prototype._sendAsyncMessage@chrome://mochikit/content/tests/SimpleTest/ChromePowers.js:45:3
23:33:59     INFO -  unload@chrome://mochikit/content/tests/SimpleTest/specialpowersAPI.js:2043:9
23:33:59     INFO -  ExtensionTestUtils.loadExtension/<@chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:110:14
23:33:59     INFO -  nextTest@chrome://mochikit/content/browser-test.js:699:30
23:33:59     INFO -  async*timeoutFn@chrome://mochikit/content/browser-test.js:1195:9
23:33:59     INFO -  setTimeout handler*Tester_execTest@chrome://mochikit/content/browser-test.js:1157:9
23:33:59     INFO -  nextTest/<@chrome://mochikit/content/browser-test.js:991:9
23:33:59     INFO -  SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:795:59
23:33:59     INFO -  542 INFO Console message: Warning: attempting to write 15955 bytes to preference extensions.webextensions.uuids. This is bad for general performance and memory usage. Such an amount of data should rather be written to an external file. This preference will not be sent to any content processes.
23:40:09     INFO -  Buffered messages finished
23:40:09  WARNING -  TEST-UNEXPECTED-TIMEOUT | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_slow_script.js | application timed out after 370 seconds with no output
23:40:09     INFO -  543 ERROR Force-terminating active process(es).
23:40:09     INFO -  Determining child pids from psutil...
23:40:09     INFO -  [2536, 3656, 2404, 4248, 6100, 2708]
23:40:09     INFO -  ==> process 5472 launched child process 1188 ("Z:\task_1530400491\build\application\firefox\firefox.exe" -contentproc --channel="5472.0.2081002330\53179654" -childID 1 -isForBrowser -prefsHandle 1764 -prefsLen 16366 -schedulerPrefs 0001,2 -parentBuildID 20180630215631 -greomni "Z:\task_1530400491\build\application\firefox\omni.ja" -appomni "Z:\task_1530400491\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1530400491\build\application\firefox\browser" - 5472 "\\.\pipe\gecko-crash-server-pipe.5472" 1804 tab)
23:40:09     INFO -  ==> process 5472 launched child process 2404 ("Z:\task_1530400491\build\application\firefox\firefox.exe" -contentproc --channel="5472.6.1372630678\1871162962" -childID 2 -isForBrowser -prefsHandle 2152 -prefsLen 16366 -schedulerPrefs 0001,2 -parentBuildID 20180630215631 -greomni "Z:\task_1530400491\build\application\firefox\omni.ja" -appomni "Z:\task_1530400491\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1530400491\build\application\firefox\browser" - 5472 "\\.\pipe\gecko-crash-server-pipe.5472" 2164 tab)
23:40:09     INFO -  ==> process 5472 launched child process 2536 ("Z:\task_1530400491\build\application\firefox\firefox.exe" -contentproc --channel="5472.12.1501379370\1724034585" -childID 3 -isForBrowser -prefsHandle 1784 -prefsLen 17676 -schedulerPrefs 0001,2 -parentBuildID 20180630215631 -greomni "Z:\task_1530400491\build\application\firefox\omni.ja" -appomni "Z:\task_1530400491\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1530400491\build\application\firefox\browser" - 5472 "\\.\pipe\gecko-crash-server-pipe.5472" 2392 tab)
23:40:09     INFO -  ==> process 5472 launched child process 3656 ("Z:\task_1530400491\build\application\firefox\firefox.exe" -contentproc --channel="5472.18.196358396\1733018084" -childID 4 -isForBrowser -prefsHandle 3008 -prefsLen 22655 -schedulerPrefs 0001,2 -parentBuildID 20180630215631 -greomni "Z:\task_1530400491\build\application\firefox\omni.ja" -appomni "Z:\task_1530400491\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1530400491\build\application\firefox\browser" - 5472 "\\.\pipe\gecko-crash-server-pipe.5472" 2888 tab)
23:40:09     INFO -  ==> process 5472 launched child process 5664 ("Z:\task_1530400491\build\application\firefox\firefox.exe" -contentproc --channel="5472.24.966870875\1482341648" -childID 5 -isForBrowser -prefsHandle 3276 -prefsLen 22656 -schedulerPrefs 0001,2 -parentBuildID 20180630215631 -greomni "Z:\task_1530400491\build\application\firefox\omni.ja" -appomni "Z:\task_1530400491\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1530400491\build\application\firefox\browser" - 5472 "\\.\pipe\gecko-crash-server-pipe.5472" 2984 tab)
23:40:09     INFO -  ==> process 5472 launched child process 4864 ("Z:\task_1530400491\build\application\firefox\plugin-container.exe" --channel="5472.30.1510196081\883120807" "C:\Users\task_1530400491\AppData\Local\Temp\tmp0cqrax.mozrunner\plugins\nptest.dll" -greomni "Z:\task_1530400491\build\application\firefox\omni.ja" -appomni "Z:\task_1530400491\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1530400491\build\application\firefox\browser" - 5472 "\\.\pipe\gecko-crash-server-pipe.5472" 2632 plugin)
23:40:09     INFO -  ==> process 5472 launched child process 2708 ("Z:\task_1530400491\build\application\firefox\plugin-container.exe" --channel="5472.34.484662457\1530252048" "C:\Users\task_1530400491\AppData\Local\Temp\tmp0cqrax.mozrunner\plugins\npswftest.dll" -greomni "Z:\task_1530400491\build\application\firefox\omni.ja" -appomni "Z:\task_1530400491\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1530400491\build\application\firefox\browser" - 5472 "\\.\pipe\gecko-crash-server-pipe.5472" 2676 plugin)
23:40:09     INFO -  ==> process 5472 launched child process 5004 ("Z:\task_1530400491\build\application\firefox\firefox.exe" -contentproc --channel="5472.38.1570313849\1791459448" -childID 6 -isForBrowser -prefsHandle 4424 -prefsLen 24645 -schedulerPrefs 0001,2 -parentBuildID 20180630215631 -greomni "Z:\task_1530400491\build\application\firefox\omni.ja" -appomni "Z:\task_1530400491\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1530400491\build\application\firefox\browser" - 5472 "\\.\pipe\gecko-crash-server-pipe.5472" 1940 tab)
23:40:09     INFO -  ==> process 5472 launched child process 4248 ("Z:\task_1530400491\build\application\firefox\firefox.exe" -contentproc --channel="5472.44.1762547011\538606346" -childID 7 -isForBrowser -prefsHandle 3836 -prefsLen 24645 -schedulerPrefs 0001,2 -parentBuildID 20180630215631 -greomni "Z:\task_1530400491\build\application\firefox\omni.ja" -appomni "Z:\task_1530400491\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1530400491\build\application\firefox\browser" - 5472 "\\.\pipe\gecko-crash-server-pipe.5472" 2040 tab)
23:40:09     INFO -  ==> process 5472 launched child process 6100 ("Z:\task_1530400491\build\application\firefox\firefox.exe" -contentproc --channel="5472.50.424588407\496565593" -childID 8 -isForBrowser -prefsHandle 3368 -prefsLen 24756 -schedulerPrefs 0001,2 -parentBuildID 20180630215631 -greomni "Z:\task_1530400491\build\application\firefox\omni.ja" -appomni "Z:\task_1530400491\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1530400491\build\application\firefox\browser" - 5472 "\\.\pipe\gecko-crash-server-pipe.5472" 3308 tab)
23:40:09     INFO -  Found child pids: set([5664, 4864, 1188, 2404, 2536, 5004, 3656, 6100, 4248, 2708])
23:40:09     INFO -  Failed to get child procs
23:40:09     INFO -  Killing process: 5664
23:40:09     INFO -  Not taking screenshot here: see the one that was previously logged
23:40:09     INFO -  mozcrash kill_pid(): unable to terminate pid 5664: 5
23:40:09     INFO -  Killing process: 4864
23:40:09     INFO -  Not taking screenshot here: see the one that was previously logged
23:40:09     INFO -  mozcrash kill_pid(): unable to terminate pid 4864: 5
23:40:09     INFO -  Killing process: 1188
23:40:09     INFO -  Not taking screenshot here: see the one that was previously logged
23:40:09     INFO -  mozcrash kill_pid(): unable to terminate pid 1188: 5
23:40:09     INFO -  Killing process: 2404
23:40:09     INFO -  Not taking screenshot here: see the one that was previously logged
23:40:09     INFO -  mozcrash kill_pid(): wait failed (-1) terminating pid 2404: error 5
23:40:09     INFO -  Killing process: 2536
23:40:09     INFO -  Not taking screenshot here: see the one that was previously logged
23:40:09     INFO -  mozcrash kill_pid(): wait failed (-1) terminating pid 2536: error 5
23:40:09     INFO -  Killing process: 5004
23:40:09     INFO -  Not taking screenshot here: see the one that was previously logged
23:40:09     INFO -  mozcrash kill_pid(): unable to terminate pid 5004: 5
23:40:09     INFO -  Killing process: 3656
23:40:09     INFO -  Not taking screenshot here: see the one that was previously logged
23:40:09     INFO -  mozcrash kill_pid(): wait failed (-1) terminating pid 3656: error 5
23:40:09     INFO -  Killing process: 6100
23:40:09     INFO -  Not taking screenshot here: see the one that was previously logged
23:40:10     INFO -  mozcrash kill_pid(): wait failed (-1) terminating pid 6100: error 5
23:40:10     INFO -  Killing process: 4248
23:40:10     INFO -  Not taking screenshot here: see the one that was previously logged
23:40:10     INFO -  mozcrash kill_pid(): wait failed (-1) terminating pid 4248: error 5
23:40:10     INFO -  Killing process: 2708
23:40:10     INFO -  Not taking screenshot here: see the one that was previously logged
23:40:10     INFO -  mozcrash kill_pid(): wait failed (-1) terminating pid 2708: error 5
23:40:10     INFO -  Killing process: 5472
23:40:10     INFO -  Not taking screenshot here: see the one that was previously logged
23:40:10     INFO -  mozcrash kill_pid(): wait failed (-1) terminating pid 5472: error 5
23:40:10     INFO -  psutil found pid 5472 dead
23:44:44     INFO -  JavaScript error: jar:file:///Z:/task_1530400491/build/application/firefox/omni.ja!/components/nsPlacesExpiration.js, line 804: TypeError: this._db is undefined
23:53:44     INFO -  JavaScript error: jar:file:///Z:/task_1530400491/build/application/firefox/omni.ja!/components/nsPlacesExpiration.js, line 804: TypeError: this._db is undefined
00:02:44     INFO -  JavaScript error: jar:file:///Z:/task_1530400491/build/application/firefox/omni.ja!/components/nsPlacesExpiration.js, line 804: TypeError: this._db is undefined
00:11:44     INFO -  JavaScript error: jar:file:///Z:/task_1530400491/build/application/firefox/omni.ja!/components/nsPlacesExpiration.js, line 804: TypeError: this._db is undefined
00:20:44     INFO -  JavaScript error: jar:file:///Z:/task_1530400491/build/application/firefox/omni.ja!/components/nsPlacesExpiration.js, line 804: TypeError: this._db is undefined
[taskcluster:error] Aborting task...
[taskcluster 2018-07-01T00:22:02.049Z] SUCCESS: The process with PID 5656 (child process of PID 4100) has been terminated.
[taskcluster 2018-07-01T00:22:02.049Z] SUCCESS: The process with PID 3552 (child process of PID 4100) has been terminated.
[taskcluster 2018-07-01T00:22:02.049Z] SUCCESS: The process with PID 1140 (child process of PID 4100) has been terminated.
[taskcluster 2018-07-01T00:22:02.049Z] SUCCESS: The process with PID 5976 (child process of PID 3144) has been terminated.
[taskcluster 2018-07-01T00:22:02.049Z] SUCCESS: The process with PID 4100 (child process of PID 3144) has been terminated.
[taskcluster 2018-07-01T00:22:02.049Z] SUCCESS: The process with PID 3144 (child process of PID 4836) has been terminated.
[taskcluster 2018-07-01T00:22:02.049Z] SUCCESS: The process with PID 4836 (child process of PID 1056) has been terminated.
[taskcluster 2018-07-01T00:22:02.049Z] 
[taskcluster 2018-07-01T00:22:02.050Z] === Task Finished ===

Comment 1

[Intermittent Failures Robot]

1 failures in 718 pushes (0.001 failures/push) were associated with this bug in the last 7 days.    

Repository breakdown:
* autoland: 1

Platform breakdown:
* windows7-32: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1472506&startday=2018-06-25&endday=2018-07-01&tree=trunk

Comment 2

[Firefox Bug Husbandry Bot]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup

Comment 3

[Cristian Brindusan [:cbrindusan]]

Recent log failure:

https://treeherder.mozilla.org/logviewer.html#?job_id=191773414&repo=mozilla-inbound&lineNumber=2882

Comment 4

[Firefox Bug Husbandry Bot]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup

Comment 5

[Narcis Beleuzu [:NarcisB]]

Fail reappeared on autoland

Log link: https://treeherder.mozilla.org/logviewer.html#?job_id=200103596&repo=autoland&lineNumber=3046

Comment 6

[Intermittent Failures Robot]

1 failures in 2902 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:
* autoland: 1

Platform breakdown:
* windows7-32: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1472506&startday=2018-09-17&endday=2018-09-23&tree=all

Comment 7

[Intermittent Failures Robot]

8 failures in 2708 pushes (0.003 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-inbound: 8

Platform breakdown:
* linux32: 2
* linux64: 6

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1472506&startday=2018-10-01&endday=2018-10-07&tree=all

Comment 8

[Firefox Bug Husbandry Bot]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup

Comment 9

[Firefox Bug Husbandry Bot]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup

Comment 10

[Daniel Varga [:dvarga]]

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=218395732&repo=mozilla-inbound&lineNumber=3411

19:37:47     INFO - Buffered messages logged at 19:37:02
19:37:47     INFO - Entering test bound test_slow_content_script
19:37:47     INFO - Extension loaded
19:37:47     INFO - Console message: Warning: attempting to write 21660 bytes to preference extensions.webextensions.uuids. This is bad for general performance and memory usage. Such an amount of data should rather be written to an external file. This preference will not be sent to any content processes.
19:37:47     INFO - Buffered messages finished
19:37:47     INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_slow_script.js | Test timed out - 
19:37:47     INFO - Not taking screenshot here: see the one that was previously logged
19:37:47     INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_slow_script.js | Extension left running at test shutdown - 
19:37:47     INFO - Stack trace:
19:37:47     INFO - chrome://mochikit/content/browser-test.js:test_ok:1305
19:37:47     INFO - chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:ExtensionTestUtils.loadExtension/<:109
19:37:47     INFO - chrome://mochikit/content/browser-test.js:nextTest:705
19:37:47     INFO - chrome://mochikit/content/browser-test.js:timeoutFn:1203
19:37:47     INFO - setTimeout handler*chrome://mochikit/content/browser-test.js:Tester_execTest:1165
19:37:47     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:995
19:37:47     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:focusedOrLoaded/<:803
19:37:55     INFO - Console message: [JavaScript Error: "Timeout while waiting for extension child to shutdown: "Slow Script Extension" (ID: 603d39caaeae55166140d29c2724f1eaaafa1f98@temporary-addon, moz-extension://fa1ecd3b-c65f-4924-bc8a-8cf9671e2a92/)" {file: "resource://gre/modules/Extension.jsm" line: 2022}]
19:37:55     INFO - shutdown@resource://gre/modules/Extension.jsm:2022:7
19:37:55     INFO - async*shutdown@resource://gre/modules/Extension.jsm:1251:24
19:37:55     INFO - async*callBootstrapMethod@resource://gre/modules/addons/XPIProvider.jsm:1639:20
19:37:55     INFO - async*_shutdown@resource://gre/modules/addons/XPIProvider.jsm:1767:12
19:37:55     INFO - async*shutdown@resource://gre/modules/addons/XPIProvider.jsm:1760:28
19:37:55     INFO - async*_uninstall@resource://gre/modules/addons/XPIProvider.jsm:1845:13
19:37:55     INFO - async*uninstall@resource://gre/modules/addons/XPIProvider.jsm:1840:12
19:37:55     INFO - uninstallAddon@resource://gre/modules/addons/XPIInstall.jsm:3827:15
19:37:55     INFO - async*uninstall@resource://gre/modules/addons/XPIDatabase.jsm:968:12
19:37:55     INFO - async*shutdown@resource://testing-common/ExtensionTestCommon.jsm:148:5
19:37:55     INFO - _receiveMessageAPI@chrome://mochikit/content/tests/SimpleTest/SpecialPowersObserverAPI.js:644:9
19:37:55     INFO - ChromePowers.prototype._receiveMessage@chrome://mochikit/content/tests/SimpleTest/ChromePowers.js:81:14
19:37:55     INFO - ChromePowers.prototype._sendAsyncMessage@chrome://mochikit/content/tests/SimpleTest/ChromePowers.js:43:3
19:37:55     INFO - unload@chrome://mochikit/content/tests/SimpleTest/specialpowersAPI.js:2075:9
19:37:55     INFO - ExtensionTestUtils.loadExtension/<@chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:110:14
19:37:55     INFO - nextTest@chrome://mochikit/content/browser-test.js:705:30
19:37:55     INFO - async*timeoutFn@chrome://mochikit/content/browser-test.js:1203:9
19:37:55     INFO - setTimeout handler*Tester_execTest@chrome://mochikit/content/browser-test.js:1165:9
19:37:55     INFO - nextTest/<@chrome://mochikit/content/browser-test.js:995:9
19:37:55     INFO - focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:803:59
19:37:55     INFO - 
19:37:55     INFO - Console message: Warning: attempting to write 21562 bytes to preference extensions.webextensions.uuids. This is bad for general performance and memory usage. Such an amount of data should rather be written to an external file. This preference will not be sent to any content processes.
19:44:05     INFO - Buffered messages finished
19:44:05    ERROR - TEST-UNEXPECTED-TIMEOUT | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_slow_script.js | application timed out after 370 seconds with no output
19:44:05    ERROR - Force-terminating active process(es).
19:44:05     INFO - Determining child pids from psutil...

Comment 11

[Intermittent Failures Robot]

1 failures in 2648 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-inbound: 1

Platform breakdown:
* windows7-32: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1472506&startday=2018-12-17&endday=2018-12-23&tree=all

Comment 12

[Firefox Bug Husbandry Bot]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup

Comment 13

[Daniel Varga [:dvarga]]

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=224076302&repo=mozilla-inbound&lineNumber=2765

19:12:07 INFO - TEST-START | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_simple.js
19:12:07 INFO - GECKO(4368) | MEMORY STAT | vsize 1151MB | vsizeMaxContiguous 244MB | residentFast 560MB | heapAllocated 238MB
19:12:07 INFO - TEST-OK | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_simple.js | took 112ms
19:12:07 INFO - checking window state
19:12:07 INFO - TEST-START | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_slow_script.js
19:12:08 INFO - GECKO(4368) | [Parent 4524, Gecko_IOThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 332
19:12:08 INFO - GECKO(4368) | [Child 5976, Chrome_ChildThread] WARNING: pipe error: 109: file z:/build/build/src/ipc/chromium/src/chrome/common/ipc_channel_win.cc, line 332
19:12:53 INFO - TEST-INFO | started process screenshot
19:12:53 INFO - TEST-INFO | screenshot: exit 0
19:12:53 INFO - Buffered messages logged at 19:12:07
19:12:53 INFO - Entering test bound test_slow_content_script
19:12:53 INFO - Buffered messages logged at 19:12:08
19:12:53 INFO - Extension loaded
19:12:53 INFO - Console message: Warning: attempting to write 21660 bytes to preference extensions.webextensions.uuids. This is bad for general performance and memory usage. Such an amount of data should rather be written to an external file. This preference will not be sent to any content processes.
19:12:53 INFO - Buffered messages finished
19:12:53 INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_slow_script.js | Test timed out -
19:12:53 INFO - Not taking screenshot here: see the one that was previously logged
19:12:53 INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/test-oop-extensions/browser_ext_slow_script.js | Extension left running at test shutdown -
19:12:53 INFO - Stack trace:
19:12:53 INFO - chrome://mochikit/content/browser-test.js:test_ok:1307
19:12:53 INFO - chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:ExtensionTestUtils.loadExtension/<:109
19:12:53 INFO - chrome://mochikit/content/browser-test.js:nextTest:707
19:12:53 INFO - chrome://mochikit/content/browser-test.js:timeoutFn:1205
19:12:53 INFO - setTimeout handlerchrome://mochikit/content/browser-test.js:Tester_execTest:1167
19:12:53 INFO - chrome://mochikit/content/browser-test.js:nextTest/<:997
19:12:53 INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:803
19:13:01 INFO - Console message: [JavaScript Error: "Timeout while waiting for extension child to shutdown: "Slow Script Extension" (ID: cc515472592154862adaacc85dce6c833098eb01@temporary-addon, moz-extension://979f82ca-71ea-48f4-9d77-b5bbb7379ef9/)" {file: "resource://gre/modules/Extension.jsm" line: 2015}]
19:13:01 INFO - shutdown@resource://gre/modules/Extension.jsm:2015:7
19:13:01 INFO - asyncshutdown@resource://gre/modules/Extension.jsm:1260:24
19:13:01 INFO - asynccallBootstrapMethod@resource://gre/modules/addons/XPIProvider.jsm:1637:26
19:13:01 INFO - async_shutdown@resource://gre/modules/addons/XPIProvider.jsm:1757:12
19:13:01 INFO - asyncshutdown@resource://gre/modules/addons/XPIProvider.jsm:1750:28
19:13:01 INFO - async_uninstall@resource://gre/modules/addons/XPIProvider.jsm:1835:13
19:13:01 INFO - asyncuninstall@resource://gre/modules/addons/XPIProvider.jsm:1830:12
19:13:01 INFO - uninstallAddon@resource://gre/modules/addons/XPIInstall.jsm:3827:15
19:13:01 INFO - asyncuninstall@resource://gre/modules/addons/XPIDatabase.jsm:968:12
19:13:01 INFO - asyncshutdown@resource://testing-common/ExtensionTestCommon.jsm:148:5
19:13:01 INFO - _receiveMessageAPI@chrome://mochikit/content/tests/SimpleTest/SpecialPowersObserverAPI.js:645:9
19:13:01 INFO - ChromePowers.prototype._receiveMessage@chrome://mochikit/content/tests/SimpleTest/ChromePowers.js:81:14
19:13:01 INFO - ChromePowers.prototype._sendAsyncMessage@chrome://mochikit/content/tests/SimpleTest/ChromePowers.js:43:3
19:13:01 INFO - unload@chrome://mochikit/content/tests/SimpleTest/specialpowersAPI.js:2069:9
19:13:01 INFO - ExtensionTestUtils.loadExtension/<@chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:110:14
19:13:01 INFO - nextTest@chrome://mochikit/content/browser-test.js:707:30
19:13:01 INFO - asynctimeoutFn@chrome://mochikit/content/browser-test.js:1205:9
19:13:01 INFO - setTimeout handler*Tester_execTest@chrome://mochikit/content/browser-test.js:1167:9
19:13:01 INFO - nextTest/<@chrome://mochikit/content/browser-test.js:997:9
19:13:01 INFO - SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:803:59
19:13:01 INFO -
19:13:01 INFO - Console message: Warning: attempting to write 21562 bytes to preference extensions.webextensions.uuids. This is bad for general performance and memory usage. Such an amount of data should rather be written to an external file. This preference will not be sent to any content processes.

Comment 14

[Intermittent Failures Robot]

1 failures in 2383 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-inbound: 1

Platform breakdown:

• windows7-32: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1472506&startday=2019-01-21&endday=2019-01-27&tree=all

Comment 15

[Intermittent Failures Robot]

1 failures in 2658 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform breakdown:

• windows7-32: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1472506&startday=2019-02-04&endday=2019-02-10&tree=all

Comment 16

[Firefox Bug Husbandry Bot]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup