Closed Bug 1472506 Opened 3 years ago Closed 2 years ago

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

Categories

(WebExtensions :: General, defect, P5)

defect

Tracking

(Not tracked)

RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure)

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 ===
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → INCOMPLETE
Recent log failure:

https://treeherder.mozilla.org/logviewer.html#?job_id=191773414&repo=mozilla-inbound&lineNumber=2882
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
Status: REOPENED → RESOLVED
Closed: 3 years ago3 years ago
Resolution: --- → INCOMPLETE
Fail reappeared on autoland

Log link: https://treeherder.mozilla.org/logviewer.html#?job_id=200103596&repo=autoland&lineNumber=3046
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
Status: REOPENED → RESOLVED
Closed: 3 years ago3 years ago
Resolution: --- → INCOMPLETE
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...
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 3 years ago3 years ago
Resolution: --- → INCOMPLETE

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 - async
shutdown@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 - async
uninstall@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 - async
timeoutFn@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.

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