Closed Bug 1640746 Opened 1 year ago Closed 10 months ago

Intermittent browser/components/extensions/test/browser/browser_ext_slow_script.js | Test timed out - Extension left running at test shutdown

Categories

(WebExtensions :: Untriaged, defect, P5)

defect

Tracking

(firefox84 fixed, firefox85 fixed)

RESOLVED FIXED
85 Branch
Tracking Status
firefox84 --- fixed
firefox85 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: apavel)

Details

(Keywords: intermittent-failure, Whiteboard: [stockwell unknown])

Attachments

(1 file, 1 obsolete file)

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


[task 2020-05-25T20:17:17.046Z] 20:17:17 INFO - TEST-START | browser/components/extensions/test/browser/browser_ext_slow_script.js
[task 2020-05-25T20:18:02.058Z] 20:18:02 INFO - TEST-INFO | started process screenshot
[task 2020-05-25T20:18:02.138Z] 20:18:02 INFO - TEST-INFO | screenshot: exit 0
[task 2020-05-25T20:18:02.138Z] 20:18:02 INFO - Buffered messages logged at 20:17:17
[task 2020-05-25T20:18:02.138Z] 20:18:02 INFO - Entering test bound test_slow_content_script
[task 2020-05-25T20:18:02.138Z] 20:18:02 INFO - Extension loaded
[task 2020-05-25T20:18:02.138Z] 20:18:02 INFO - Console message: Warning: attempting to write 25801 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.
[task 2020-05-25T20:18:02.138Z] 20:18:02 INFO - Buffered messages finished
[task 2020-05-25T20:18:02.139Z] 20:18:02 INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/browser_ext_slow_script.js | Test timed out -
[task 2020-05-25T20:18:02.139Z] 20:18:02 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-05-25T20:18:02.139Z] 20:18:02 INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/browser_ext_slow_script.js | Extension left running at test shutdown -
[task 2020-05-25T20:18:02.139Z] 20:18:02 INFO - Stack trace:
[task 2020-05-25T20:18:02.139Z] 20:18:02 INFO - chrome://mochikit/content/browser-test.js:test_ok:1299
[task 2020-05-25T20:18:02.139Z] 20:18:02 INFO - chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:ExtensionTestUtils.loadExtension/<:117
[task 2020-05-25T20:18:02.139Z] 20:18:02 INFO - chrome://mochikit/content/browser-test.js:nextTest:550
[task 2020-05-25T20:18:02.139Z] 20:18:02 INFO - chrome://mochikit/content/browser-test.js:timeoutFn:1190
[task 2020-05-25T20:18:02.139Z] 20:18:02 INFO - setTimeout handlerchrome://mochikit/content/browser-test.js:Tester_execTest:1137
[task 2020-05-25T20:18:02.139Z] 20:18:02 INFO - chrome://mochikit/content/browser-test.js:nextTest/<:927
[task 2020-05-25T20:18:02.139Z] 20:18:02 INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:918
[task 2020-05-25T20:18:10.092Z] 20:18:10 INFO - Console message: [JavaScript Error: "Timeout while waiting for extension child to shutdown: "Slow Script Extension" (ID: bbc352c4cad6fcb09299c5fc9771b4a3971a39c8@temporary-addon, moz-extension://66f7426c-eab2-4a59-8b3e-b8b598675616/)" {file: "resource://gre/modules/Extension.jsm" line: 2636}]
[task 2020-05-25T20:18:10.092Z] 20:18:10 INFO - shutdown@resource://gre/modules/Extension.jsm:2636:10
[task 2020-05-25T20:18:10.092Z] 20:18:10 INFO - async
shutdown@resource://gre/modules/Extension.jsm:1703:39
[task 2020-05-25T20:18:10.092Z] 20:18:10 INFO - callBootstrapMethod@resource://gre/modules/addons/XPIProvider.jsm:1819:33
[task 2020-05-25T20:18:10.092Z] 20:18:10 INFO - _shutdown@resource://gre/modules/addons/XPIProvider.jsm:1948:17
[task 2020-05-25T20:18:10.092Z] 20:18:10 INFO - asyncshutdown@resource://gre/modules/addons/XPIProvider.jsm:1941:33
[task 2020-05-25T20:18:10.092Z] 20:18:10 INFO - _uninstall@resource://gre/modules/addons/XPIProvider.jsm:2026:18
[task 2020-05-25T20:18:10.092Z] 20:18:10 INFO - uninstall@resource://gre/modules/addons/XPIProvider.jsm:2021:17
[task 2020-05-25T20:18:10.092Z] 20:18:10 INFO - uninstallAddon@resource://gre/modules/addons/XPIInstall.jsm:4550:25
[task 2020-05-25T20:18:10.092Z] 20:18:10 INFO - uninstall@resource://gre/modules/addons/XPIDatabase.jsm:1227:23
[task 2020-05-25T20:18:10.092Z] 20:18:10 INFO - shutdown@resource://testing-common/ExtensionTestCommon.jsm:191:16
[task 2020-05-25T20:18:10.092Z] 20:18:10 INFO - receiveMessage@resource://specialpowers/SpecialPowersParent.jsm:1113:26
[task 2020-05-25T20:18:10.092Z] 20:18:10 INFO - JSActor query
unload@resource://specialpowers/SpecialPowersChild.jsm:2075:19
[task 2020-05-25T20:18:10.093Z] 20:18:10 INFO - ExtensionTestUtils.loadExtension/<@chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:118:23
[task 2020-05-25T20:18:10.093Z] 20:18:10 INFO - nextTest@chrome://mochikit/content/browser-test.js:550:35
[task 2020-05-25T20:18:10.093Z] 20:18:10 INFO - asynctimeoutFn@chrome://mochikit/content/browser-test.js:1190:18
[task 2020-05-25T20:18:10.093Z] 20:18:10 INFO - setTimeout handler
Tester_execTest@chrome://mochikit/content/browser-test.js:1137:80
[task 2020-05-25T20:18:10.093Z] 20:18:10 INFO - nextTest/<@chrome://mochikit/content/browser-test.js:927:14
[task 2020-05-25T20:18:10.093Z] 20:18:10 INFO - SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:918:23
[task 2020-05-25T20:18:10.093Z] 20:18:10 INFO -
[task 2020-05-25T20:18:10.093Z] 20:18:10 INFO - Console message: Warning: attempting to write 25703 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.
[task 2020-05-25T20:24:20.104Z] 20:24:20 INFO - Buffered messages finished
[task 2020-05-25T20:24:20.104Z] 20:24:20 ERROR - TEST-UNEXPECTED-TIMEOUT | browser/components/extensions/test/browser/browser_ext_slow_script.js | application timed out after 370 seconds with no output
[task 2020-05-25T20:24:20.104Z] 20:24:20 ERROR - Force-terminating active process(es).
[task 2020-05-25T20:24:20.104Z] 20:24:20 INFO - Determining child pids from psutil...
[task 2020-05-25T20:24:20.109Z] 20:24:20 INFO - [3764]
[task 2020-05-25T20:24:20.110Z] 20:24:20 INFO - ==> process 3764 launched child process 9736 ("Z:\task_1590437004\build\application\firefox\firefox.exe" -contentproc --channel="3764.0.60865217\1333812585" -parentBuildID 20200525183231 -prefsHandle 2172 -prefMapHandle 2068 -prefsLen 1 -prefMapSize 234914 -appdir "Z:\task_1590437004\build\application\firefox\browser" - 3764 "\.\pipe\gecko-crash-server-pipe.3764" 2244 gpu)
[task 2020-05-25T20:24:20.110Z] 20:24:20 INFO - ==> process 3764 launched child process 7128 ("Z:\task_1590437004\build\application\firefox\firefox.exe" -contentproc --channel="3764.6.1135541827\712683699" -childID 1 -isForBrowser -prefsHandle 2136 -prefMapHandle 2124 -prefsLen 1779 -prefMapSize 234914 -parentBuildID 20200525183231 -appdir "Z:\task_1590437004\build\application\firefox\browser" - 3764 "\.\pipe\gecko-crash-server-pipe.3764" 2844 tab)
[task 2020-05-25T20:24:20.110Z] 20:24:20 INFO - ==> process 3764 launched child process 7296 ("Z:\task_1590437004\build\application\firefox\firefox.exe" -contentproc --channel="3764.13.1211350090\760418854" -childID 2 -isForBrowser -prefsHandle 3132 -prefMapHandle 3128 -prefsLen 1823 -prefMapSize 234914 -parentBuildID 20200525183231 -appdir "Z:\task_1590437004\build\application\firefox\browser" - 3764 "\.\pipe\gecko-crash-server-pipe.3764" 3152 tab)
[task 2020-05-25T20:24:20.110Z] 20:24:20 INFO - ==> process 3764 launched child process 1708 ("Z:\task_1590437004\build\application\firefox\firefox.exe" -contentproc --channel="3764.20.1799512701\1582898284" -childID 3 -isForBrowser -prefsHandle 6172 -prefMapHandle 6168 -prefsLen 1823 -prefMapSize 234914 -parentBuildID 20200525183231 -appdir "Z:\task_1590437004\build\application\firefox\browser" - 3764 "\.\pipe\gecko-crash-server-pipe.3764" 6180 tab)
[task 2020-05-25T20:24:20.110Z] 20:24:20 INFO - ==> process 3764 launched child process 7460 ("Z:\task_1590437004\build\application\firefox\firefox.exe" -contentproc --channel="3764.27.191676174\860959457" -childID 4 -isForBrowser -prefsHandle 5552 -prefMapHandle 5684 -prefsLen 11217 -prefMapSize 234914 -parentBuildID 20200525183231 -appdir "Z:\task_1590437004\build\application\firefox\browser" - 3764 "\.\pipe\gecko-crash-server-pipe.3764" 5228 tab)
[task 2020-05-25T20:24:20.111Z] 20:24:20 INFO - ==> process 3764 launched child process 5088 ("Z:\task_1590437004\build\application\firefox\firefox.exe" -contentproc --channel="3764.34.116132977\435842988" -childID 5 -isForBrowser -prefsHandle 4716 -prefMapHandle 5936 -prefsLen 11535 -prefMapSize 234914 -parentBuildID 20200525183231 -appdir "Z:\task_1590437004\build\application\firefox\browser" - 3764 "\.\pipe\gecko-crash-server-pipe.3764" 3972 tab)
[task 2020-05-25T20:24:20.111Z] 20:24:20 INFO - ==> process 3764 launched child process 8004 ("Z:\task_1590437004\build\application\firefox\firefox.exe" -contentproc --channel="3764.41.337154264\234496038" -childID 6 -isForBrowser -prefsHandle 3580 -prefMapHandle 4896 -prefsLen 11536 -prefMapSize 234914 -parentBuildID 20200525183231 -appdir "Z:\task_1590437004\build\application\firefox\browser" - 3764 "\.\pipe\gecko-crash-server-pipe.3764" 3444 tab)
[task 2020-05-25T20:24:20.112Z] 20:24:20 INFO - ==> process 3764 launched child process 10808 ("Z:\task_1590437004\build\application\firefox\firefox.exe" -contentproc --channel="3764.48.1413846731\1406039988" -childID 7 -isForBrowser -prefsHandle 5624 -prefMapHandle 5764 -prefsLen 12949 -prefMapSize 234914 -parentBuildID 20200525183231 -appdir "Z:\task_1590437004\build\application\firefox\browser" - 3764 "\.\pipe\gecko-crash-server-pipe.3764" 6108 tab)
[task 2020-05-25T20:24:20.112Z] 20:24:20 INFO - ==> process 3764 launched child process 7268 ("Z:\task_1590437004\build\application\firefox\firefox.exe" -contentproc --channel="3764.55.643053614\1592970660" -childID 8 -isForBrowser -prefsHandle 3688 -prefMapHandle 3868 -prefsLen 13634 -prefMapSize 234914 -parentBuildID 20200525183231 -appdir "Z:\task_1590437004\build\application\firefox\browser" - 3764 "\.\pipe\gecko-crash-server-pipe.3764" 4572 tab)
[task 2020-05-25T20:24:20.112Z] 20:24:20 INFO - ==> process 3764 launched child process 5684 ("Z:\task_1590437004\build\application\firefox\firefox.exe" -contentproc --channel="3764.62.612599932\1792425397" -childID 9 -isForBrowser -prefsHandle 6404 -prefMapHandle 6400 -prefsLen 14243 -prefMapSize 234914 -parentBuildID 20200525183231 -appdir "Z:\task_1590437004\build\application\firefox\browser" - 3764 "\.\pipe\gecko-crash-server-pipe.3764" 4804 tab)
[task 2020-05-25T20:24:20.113Z] 20:24:20 INFO - ==> process 3764 launched child process 10972 ("Z:\task_1590437004\build\application\firefox\firefox.exe" -contentproc --channel="3764.69.1701924836\1377527231" -childID 10 -isForBrowser -prefsHandle 3332 -prefMapHandle 4996 -prefsLen 14709 -prefMapSize 234914 -parentBuildID 20200525183231 -appdir "Z:\task_1590437004\build\application\firefox\browser" - 3764 "\.\pipe\gecko-crash-server-pipe.3764" 5148 tab)
[task 2020-05-25T20:24:20.113Z] 20:24:20 INFO - ==> process 3764 launched child process 3448 ("Z:\task_1590437004\build\application\firefox\plugin-container.exe" --channel="3764.76.419178363\2127420406" "C:\Users\task_1590437004\AppData\Local\Temp\tmpexizq0.mozrunner\plugins\nptest.dll" "C:\Users\task_1590437004\AppData\LocalLow\Mozilla\Temp-{4c2afa08-cc11-4bc1-adeb-a1aa12a9989b}" "Z:\task_1590437004\AppData\Roaming\Adobe\" -appdir "Z:\task_1590437004\build\application\firefox\browser" 1942C98CAB5724E0 3764 "\.\pipe\gecko-crash-server-pipe.3764" 3484 plugin)
[task 2020-05-25T20:24:20.114Z] 20:24:20 INFO - ==> process 3764 launched child process 4684 ("Z:\task_1590437004\build\application\firefox\firefox.exe" -contentproc --channel="3764.81.56322901\413333476" -childID 11 -isForBrowser -prefsHandle 11152 -prefMapHandle 9812 -prefsLen 14659 -prefMapSize 234914 -parentBuildID 20200525183231 -appdir "Z:\task_1590437004\build\application\firefox\browser" - 3764 "\.\pipe\gecko-crash-server-pipe.3764" 9820 tab)
[task 2020-05-25T20:24:20.114Z] 20:24:20 INFO - ==> process 3764 launched child process 6052 ("Z:\task_1590437004\build\application\firefox\firefox.exe" -contentproc --channel="3764.88.1584947420\317506623" -childID 12 -isForBrowser -prefsHandle 3264 -prefMapHandle 10096 -prefsLen 15262 -prefMapSize 234914 -parentBuildID 20200525183231 -appdir "Z:\task_1590437004\build\application\firefox\browser" - 3764 "\.\pipe\gecko-crash-server-pipe.3764" 11212 tab)
[task 2020-05-25T20:24:20.114Z] 20:24:20 INFO - ==> process 3764 launched child process 10568 ("Z:\task_1590437004\build\application\firefox\firefox.exe" -contentproc --channel="3764.95.1589773688\325689048" -childID 13 -isForBrowser -prefsHandle 9520 -prefMapHandle 9524 -prefsLen 15262 -prefMapSize 234914 -parentBuildID 20200525183231 -appdir "Z:\task_1590437004\build\application\firefox\browser" - 3764 "\.\pipe\gecko-crash-server-pipe.3764" 7796 tab)
[task 2020-05-25T20:24:20.114Z] 20:24:20 INFO - ==> process 3764 launched child process 5024 ("Z:\task_1590437004\build\application\firefox\firefox.exe" -contentproc --channel="3764.102.1144952548\1309955436" -childID 14 -isForBrowser -prefsHandle 7516 -prefMapHandle 12744 -prefsLen 15452 -prefMapSize 234914 -parentBuildID 20200525183231 -appdir "Z:\task_1590437004\build\application\firefox\browser" - 3764 "\.\pipe\gecko-crash-server-pipe.3764" 9380 tab)
[task 2020-05-25T20:24:20.115Z] 20:24:20 INFO - Found child pids: set([7296, 5088, 5024, 7460, 4684, 9736, 3448, 10568, 1708, 7268, 5684, 10808, 3764, 7128, 8004, 6052, 10972])
[task 2020-05-25T20:24:20.115Z] 20:24:20 INFO - Failed to get child procs
[task 2020-05-25T20:24:20.115Z] 20:24:20 INFO - Killing process: 7296
[task 2020-05-25T20:24:20.115Z] 20:24:20 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-05-25T20:24:20.115Z] 20:24:20 INFO - mozcrash Writing a dump to c:\users\task_1590437004\appdata\local\temp\tmpexizq0.mozrunner\minidumps\5ebd6782-ae05-4a98-9fb6-bd657c5a4c52.dmp for [7296]
[task 2020-05-25T20:24:20.205Z] 20:24:20 INFO - Killing process: 5088
[task 2020-05-25T20:24:20.205Z] 20:24:20 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-05-25T20:24:20.205Z] 20:24:20 INFO - mozcrash Writing a dump to c:\users\task_1590437004\appdata\local\temp\tmpexizq0.mozrunner\minidumps\b248e403-4977-46eb-a7ec-28ffc2a4dad5.dmp for [5088]
[task 2020-05-25T20:24:20.210Z] 20:24:20 WARNING - mozcrash unable to dump minidump file for pid 5088: -2147024597
[task 2020-05-25T20:24:20.210Z] 20:24:20 WARNING - mozcrash kill_pid(): unable to terminate pid 5088: 5
[task 2020-05-25T20:24:20.210Z] 20:24:20 INFO - Killing process: 5024
[task 2020-05-25T20:24:20.210Z] 20:24:20 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-05-25T20:24:20.210Z] 20:24:20 INFO - mozcrash Writing a dump to c:\users\task_1590437004\appdata\local\temp\tmpexizq0.mozrunner\minidumps\4bb9325d-aaa0-4028-9805-bf25f4fd61fe.dmp for [5024]
[task 2020-05-25T20:24:20.280Z] 20:24:20 INFO - Killing process: 7460
[task 2020-05-25T20:24:20.280Z] 20:24:20 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-05-25T20:24:20.280Z] 20:24:20 INFO - mozcrash Writing a dump to c:\users\task_1590437004\appdata\local\temp\tmpexizq0.mozrunner\minidumps\05dee120-1ae1-437a-a7b2-cf46b9f263ab.dmp for [7460]
[task 2020-05-25T20:24:20.361Z] 20:24:20 INFO - Killing process: 4684
[task 2020-05-25T20:24:20.361Z] 20:24:20 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-05-25T20:24:20.361Z] 20:24:20 INFO - mozcrash Writing a dump to c:\users\task_1590437004\appdata\local\temp\tmpexizq0.mozrunner\minidumps\0ca2a723-01c0-4d44-823a-0d1e725aa109.dmp for [4684]
[task 2020-05-25T20:24:20.366Z] 20:24:20 WARNING - mozcrash unable to dump minidump file for pid 4684: -2147024597
[task 2020-05-25T20:24:20.366Z] 20:24:20 WARNING - mozcrash kill_pid(): unable to terminate pid 4684: 5
[task 2020-05-25T20:24:20.367Z] 20:24:20 INFO - Killing process: 9736
[task 2020-05-25T20:24:20.367Z] 20:24:20 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-05-25T20:24:20.367Z] 20:24:20 INFO - mozcrash Writing a dump to c:\users\task_1590437004\appdata\local\temp\tmpexizq0.mozrunner\minidumps\d1d303c5-3816-4a9b-b5ab-1133efbed690.dmp for [9736]
[task 2020-05-25T20:24:20.549Z] 20:24:20 INFO - Killing process: 3448
[task 2020-05-25T20:24:20.549Z] 20:24:20 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-05-25T20:24:20.550Z] 20:24:20 INFO - mozcrash Writing a dump to c:\users\task_1590437004\appdata\local\temp\tmpexizq0.mozrunner\minidumps\a740b978-e25e-4f62-8227-7ca68e3c6068.dmp for [3448]

Assignee: nobody → apavel
Status: NEW → ASSIGNED

Shane can you please assign someone to take a look at this?

There are 52 total failures in the last 7 days on

  • linux1804-64 opt
  • linux1804-64-shippable opt
  • windows10-64-qr opt
  • windows10-64-shippable opt
  • macosx1014-64-qr opt

Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=321730664&repo=mozilla-central&lineNumber=5823

[task 2020-11-13T18:26:13.974Z] 18:26:13 INFO - TEST-START | browser/components/extensions/test/browser/browser_ext_slow_script.js
[task 2020-11-13T18:26:58.983Z] 18:26:58 INFO - TEST-INFO | started process screenshot
[task 2020-11-13T18:26:59.062Z] 18:26:59 INFO - TEST-INFO | screenshot: exit 0
[task 2020-11-13T18:26:59.062Z] 18:26:59 INFO - Buffered messages logged at 18:26:13
[task 2020-11-13T18:26:59.062Z] 18:26:59 INFO - Entering test bound test_slow_content_script
[task 2020-11-13T18:26:59.062Z] 18:26:59 INFO - Buffered messages logged at 18:26:14
[task 2020-11-13T18:26:59.062Z] 18:26:59 INFO - Extension loaded
[task 2020-11-13T18:26:59.062Z] 18:26:59 INFO - Console message: Warning: attempting to write 25748 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.
[task 2020-11-13T18:26:59.063Z] 18:26:59 INFO - Buffered messages finished
[task 2020-11-13T18:26:59.063Z] 18:26:59 INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/browser_ext_slow_script.js | Test timed out -
[task 2020-11-13T18:26:59.063Z] 18:26:59 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-11-13T18:26:59.063Z] 18:26:59 INFO - TEST-UNEXPECTED-FAIL | browser/components/extensions/test/browser/browser_ext_slow_script.js | Extension left running at test shutdown -
[task 2020-11-13T18:26:59.063Z] 18:26:59 INFO - Stack trace:
[task 2020-11-13T18:26:59.063Z] 18:26:59 INFO - chrome://mochikit/content/browser-test.js:test_ok:1304
[task 2020-11-13T18:26:59.063Z] 18:26:59 INFO - chrome://mochikit/content/tests/SimpleTest/ExtensionTestUtils.js:ExtensionTestUtils.loadExtension/<:117
[task 2020-11-13T18:26:59.063Z] 18:26:59 INFO - chrome://mochikit/content/browser-test.js:nextTest:555
[task 2020-11-13T18:27:07.009Z] 18:27:07 INFO - Console message: [JavaScript Error: "Timeout while waiting for extension child to shutdown: "Slow Script Extension" (ID: 4a46ce559e2bbbe3a791fc2edb9bac5376eb0ccf@temporary-addon, moz-extension://2bd310ae-9030-4b5b-a938-b94a5d8bfbcc/)" {file: "resource://gre/modules/Extension.jsm" line: 2742}]
[task 2020-11-13T18:27:07.009Z] 18:27:07 INFO - shutdown@resource://gre/modules/Extension.jsm:2742:10
[task 2020-11-13T18:27:07.009Z] 18:27:07 INFO -
[task 2020-11-13T18:27:07.009Z] 18:27:07 INFO - Console message: Warning: attempting to write 25650 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.
[task 2020-11-13T18:27:56.754Z] 18:27:56 INFO - GECKO(764) | 1605292076743 addons.xpi ERROR System addon update list error Error: got node name: html, expected: updates
[task 2020-11-13T18:27:56.754Z] 18:27:56 INFO - Console message: [JavaScript Error: "1605292076743 addons.xpi ERROR System addon update list error Error: got node name: html, expected: updates" {file: "resource://gre/modules/Log.jsm" line: 723}]
[task 2020-11-13T18:27:56.754Z] 18:27:56 INFO - append@resource://gre/modules/Log.jsm:723:12
[task 2020-11-13T18:27:56.754Z] 18:27:56 INFO - log@resource://gre/modules/Log.jsm:379:16
[task 2020-11-13T18:27:56.754Z] 18:27:56 INFO - error@resource://gre/modules/Log.jsm:387:10
[task 2020-11-13T18:27:56.754Z] 18:27:56 INFO - updateSystemAddons/res<@resource://gre/modules/addons/XPIInstall.jsm:4015:25
[task 2020-11-13T18:27:56.754Z] 18:27:56 INFO -
[task 2020-11-13T18:34:06.752Z] 18:34:06 INFO - Buffered messages finished
[task 2020-11-13T18:34:06.752Z] 18:34:06 ERROR - TEST-UNEXPECTED-TIMEOUT | browser/components/extensions/test/browser/browser_ext_slow_script.js | application timed out after 370 seconds with no output
[task 2020-11-13T18:34:06.752Z] 18:34:06 ERROR - Force-terminating active process(es).
[task 2020-11-13T18:34:06.752Z] 18:34:06 INFO - Determining child pids from psutil...
[task 2020-11-13T18:34:06.756Z] 18:34:06 INFO - [3436]

Assignee: apavel → nobody
Status: ASSIGNED → NEW
Flags: needinfo?(mixedpuppy)
Whiteboard: [stockwell needswork:owner]
Assignee: nobody → apavel
Status: NEW → ASSIGNED

There's an exception in the logs I would like to look at before disabling this test. Will keep ni on myself to look at today.

If the try run above is good, lets go with that patch rather than disable. If it is not good, go ahead and disable but be sure to leave this bug open.

Flags: needinfo?(mixedpuppy) → needinfo?(apavel)
Attachment #9187770 - Attachment is obsolete: true
Pushed by apavel@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/e985959bbaff
fix intermittent timeout when testing addon hang r=jmaher
Flags: needinfo?(apavel)
Status: ASSIGNED → RESOLVED
Closed: 10 months ago
Resolution: --- → FIXED
Target Milestone: --- → 85 Branch
You need to log in before you can comment on or make changes to this bug.