https://tbpl.mozilla.org/php/getParsedLog.php?id=31584358&tree=Mozilla-Inbound slave: t-xp32-ix-083 13:37:00 INFO - 14923 INFO TEST-START | chrome://mochitests/content/chrome/js/xpconnect/tests/chrome/test_sandboxImport.xul 13:37:00 INFO - ++DOMWINDOW == 36 (0F1A97B0) [pid = 1568] [serial = 2644] [outer = 0EC00C98] 13:37:00 INFO - 14924 INFO TEST-PASS | chrome://mochitests/content/chrome/js/xpconnect/tests/chrome/test_sandboxImport.xul | importFunction works 13:37:00 INFO - 14925 INFO TEST-PASS | chrome://mochitests/content/chrome/js/xpconnect/tests/chrome/test_sandboxImport.xul | importFunction works 13:37:00 INFO - 14926 INFO TEST-PASS | chrome://mochitests/content/chrome/js/xpconnect/tests/chrome/test_sandboxImport.xul | right type of wrapper 13:37:00 INFO - 14927 INFO TEST-PASS | chrome://mochitests/content/chrome/js/xpconnect/tests/chrome/test_sandboxImport.xul | unbound importFunction works 13:37:00 INFO - 14928 INFO TEST-PASS | chrome://mochitests/content/chrome/js/xpconnect/tests/chrome/test_sandboxImport.xul | didn't import into our global 13:37:00 INFO - 14929 INFO TEST-INFO | MEMORY STAT vsize after test: 530485248 13:37:00 INFO - 14930 INFO TEST-INFO | MEMORY STAT vsizeMaxContiguous after test: 679411712 13:37:00 INFO - 14931 INFO TEST-INFO | MEMORY STAT residentFast after test: 301223936 13:37:01 INFO - 14932 INFO TEST-END | chrome://mochitests/content/chrome/js/xpconnect/tests/chrome/test_sandboxImport.xul | finished in 158ms 13:37:01 INFO - ++DOMWINDOW == 37 (12D84B20) [pid = 1568] [serial = 2645] [outer = 0EC00C98] 13:37:01 INFO - 14933 INFO TEST-START | chrome://mochitests/content/chrome/js/xpconnect/tests/chrome/test_scriptSettings.xul 13:37:01 INFO - ++DOMWINDOW == 38 (12C5D8E0) [pid = 1568] [serial = 2646] [outer = 0EC00C98] 13:37:01 INFO - ++DOCSHELL 13FBE0A0 == 12 [pid = 1568] [id = 507] 13:37:01 INFO - ++DOMWINDOW == 39 (14049BE8) [pid = 1568] [serial = 2647] [outer = 00000000] 13:37:01 INFO - [Parent 1568] WARNING: Subdocument container has no frame: file c:/builds/moz2_slave/m-in-w32-d-0000000000000000000/build/layout/base/nsDocumentViewer.cpp, line 2366 13:37:01 INFO - ++DOMWINDOW == 40 (0F0BE9E0) [pid = 1568] [serial = 2648] [outer = 14049BE8] 13:37:01 INFO - 14934 INFO TEST-PASS | chrome://mochitests/content/chrome/js/xpconnect/tests/chrome/test_scriptSettings.xul | smoketest 13:37:01 INFO - 14935 INFO TEST-PASS | chrome://mochitests/content/chrome/js/xpconnect/tests/chrome/test_scriptSettings.xul | cross-compartment sb non-scripted 13:37:01 INFO - 14936 INFO TEST-PASS | chrome://mochitests/content/chrome/js/xpconnect/tests/chrome/test_scriptSettings.xul | cross-compartment win non-scripted 13:37:01 INFO - 14937 INFO TEST-PASS | chrome://mochitests/content/chrome/js/xpconnect/tests/chrome/test_scriptSettings.xul | cross-compartment sb scripted 13:37:01 INFO - 14938 INFO TEST-PASS | chrome://mochitests/content/chrome/js/xpconnect/tests/chrome/test_scriptSettings.xul | cross-compartment win scripted 13:37:01 INFO - 14939 INFO TEST-PASS | chrome://mochitests/content/chrome/js/xpconnect/tests/chrome/test_scriptSettings.xul | eval sb 13:37:01 INFO - 14940 INFO TEST-PASS | chrome://mochitests/content/chrome/js/xpconnect/tests/chrome/test_scriptSettings.xul | eval iwin 13:37:01 INFO - 14941 INFO TEST-INFO | chrome://mochitests/content/chrome/js/xpconnect/tests/chrome/test_scriptSettings.xul | Generated callback: simple bound 13:37:01 INFO - 14942 INFO TEST-PASS | chrome://mochitests/content/chrome/js/xpconnect/tests/chrome/test_scriptSettings.xul | Callback got the right incumbent global: simple bound 13:37:01 INFO - 14943 INFO TEST-PASS | chrome://mochitests/content/chrome/js/xpconnect/tests/chrome/test_scriptSettings.xul | Bound method returns the right global 13:37:01 INFO - 14944 INFO TEST-INFO | chrome://mochitests/content/chrome/js/xpconnect/tests/chrome/test_scriptSettings.xul | Generated callback: same-global setTimeout 13:37:01 INFO - [Parent 1568] WARNING: NS_ENSURE_TRUE(NS_SUCCEEDED(rv) && subjPrincipal) failed: file c:/builds/moz2_slave/m-in-w32-d-0000000000000000000/build/docshell/base/nsDocShell.cpp, line 8588 13:37:01 INFO - 14945 INFO TEST-PASS | chrome://mochitests/content/chrome/js/xpconnect/tests/chrome/test_scriptSettings.xul | Callback got the right incumbent global: same-global setTimeout 13:37:01 INFO - 14946 INFO TEST-INFO | chrome://mochitests/content/chrome/js/xpconnect/tests/chrome/test_scriptSettings.xul | Generated callback: cross-global setTimeout by |window| 13:37:01 INFO - ++DOMWINDOW == 41 (1461A5A8) [pid = 1568] [serial = 2649] [outer = 14049BE8] 13:37:07 INFO - --DOMWINDOW == 40 (12D99190) [pid = 1568] [serial = 2637] [outer = 00000000] [url = http://mochi.test:8888/tests/js/xpconnect/tests/mochitest/file_nodelists.html] 13:37:13 INFO - --DOMWINDOW == 39 (15531098) [pid = 1568] [serial = 2642] [outer = 00000000] [url = chrome://mochitests/content/chrome/js/xpconnect/tests/chrome/test_precisegc.xul] 13:37:13 INFO - --DOMWINDOW == 38 (12D84B20) [pid = 1568] [serial = 2645] [outer = 00000000] [url = chrome://mochikit/content/tests/SimpleTest/iframe-between-tests.html] 13:37:13 INFO - --DOMWINDOW == 37 (0F1A97B0) [pid = 1568] [serial = 2644] [outer = 00000000] [url = chrome://mochitests/content/chrome/js/xpconnect/tests/chrome/test_sandboxImport.xul] 13:37:13 INFO - --DOMWINDOW == 36 (0F0BE9E0) [pid = 1568] [serial = 2648] [outer = 00000000] [url = about:blank] 13:37:43 INFO - NOTE: child process received `Goodbye', closing down 13:37:43 INFO - NPP_Destroy 13:37:43 INFO - NPP_Destroy 13:37:43 INFO - NPP_Destroy 13:37:43 INFO - NPP_Destroy 13:37:43 INFO - NPP_Destroy 13:37:43 INFO - NPP_Destroy 13:37:43 INFO - NPP_Destroy 13:37:43 INFO - nsStringStats 13:37:43 INFO - => mAllocCount: 167 13:37:43 INFO - => mReallocCount: 1 13:37:43 INFO - => mFreeCount: 167 13:37:43 INFO - => mShareCount: 159 13:37:43 INFO - => mAdoptCount: 0 13:37:43 INFO - => mAdoptFreeCount: 0 13:37:43 INFO - => Process ID: 3148, Thread ID: 3248 13:39:14 INFO - [Parent 1568] WARNING: 1 sort operation has occurred for the SQL statement '0xecdc1f8'. See https://developer.mozilla.org/En/Storage/Warnings details.: file c:/builds/moz2_slave/m-in-w32-d-0000000000000000000/build/storage/src/mozStoragePrivateHelpers.cpp, line 109 13:39:45 INFO - [Parent 1568] WARNING: 1 sort operation has occurred for the SQL statement '0x13c8bbb8'. See https://developer.mozilla.org/En/Storage/Warnings details.: file c:/builds/moz2_slave/m-in-w32-d-0000000000000000000/build/storage/src/mozStoragePrivateHelpers.cpp, line 109 13:39:45 INFO - [Parent 1568] WARNING: 1 sort operation has occurred for the SQL statement '0xecdc1f8'. See https://developer.mozilla.org/En/Storage/Warnings details.: file c:/builds/moz2_slave/m-in-w32-d-0000000000000000000/build/storage/src/mozStoragePrivateHelpers.cpp, line 109 13:39:45 INFO - [Parent 1568] WARNING: 1 sort operation has occurred for the SQL statement '0xdc30f20'. See https://developer.mozilla.org/En/Storage/Warnings details.: file c:/builds/moz2_slave/m-in-w32-d-0000000000000000000/build/storage/src/mozStoragePrivateHelpers.cpp, line 109 13:39:45 INFO - [Parent 1568] WARNING: 1 sort operation has occurred for the SQL statement '0x1331b610'. See https://developer.mozilla.org/En/Storage/Warnings details.: file c:/builds/moz2_slave/m-in-w32-d-0000000000000000000/build/storage/src/mozStoragePrivateHelpers.cpp, line 109 13:39:45 INFO - [Parent 1568] WARNING: 1 sort operation has occurred for the SQL statement '0xeca2c10'. See https://developer.mozilla.org/En/Storage/Warnings details.: file c:/builds/moz2_slave/m-in-w32-d-0000000000000000000/build/storage/src/mozStoragePrivateHelpers.cpp, line 109 13:42:13 INFO - SCREENSHOT: [SEE ATTACHMENT] 13:42:14 INFO - 14947 ERROR TEST-UNEXPECTED-FAIL | chrome://mochitests/content/chrome/js/xpconnect/tests/chrome/test_scriptSettings.xul | Test timed out. 13:42:14 INFO - 14948 INFO TEST-INFO | MEMORY STAT vsize after test: 524881920 13:42:14 INFO - 14949 INFO TEST-INFO | MEMORY STAT vsizeMaxContiguous after test: 679411712 13:42:14 INFO - 14950 INFO TEST-INFO | MEMORY STAT residentFast after test: 297107456 13:42:14 INFO - 14951 INFO TEST-END | chrome://mochitests/content/chrome/js/xpconnect/tests/chrome/test_scriptSettings.xul | finished in 312423ms 13:42:14 INFO - ++DOMWINDOW == 37 (12560B78) [pid = 1568] [serial = 2650] [outer = 0EC00C98] 13:42:14 INFO - 14952 INFO TEST-START | chrome://mochitests/content/chrome/js/xpconnect/tests/chrome/test_weakmap_keys_preserved.xul

Hm, so according to the log, we successfully invoke setTimeout here: https://hg.mozilla.org/integration/mozilla-inbound/file/c996211971a8/js/xpconnect/tests/chrome/test_scriptSettings.xul#l73 But then, apparently, the callback is never invoked. Boris, can you take a quick look at my handling of |iwin| here and let me know if there's anything I'm doing that might be causing it to eat timeouts? I'm just using the about:blank document, but I'd assumed that would be fine.

Hrm. You may be being screwed by our brokenness around about:blank. In particular, we create the initial about:blank, then we load _another_ about:blank. It should reuse the inner, but... Can you just put all of the test code except waitForExplicitFinish into window.onload and see if that helps?

(In reply to Boris Zbarsky [:bz] from comment #3) > Hrm. > > You may be being screwed by our brokenness around about:blank. In > particular, we create the initial about:blank, then we load _another_ > about:blank. It should reuse the inner, but... > > Can you just put all of the test code except waitForExplicitFinish into > window.onload and see if that helps? Thanks for the tip. Bug 937317 was backed out, and I'll do that in the relanded version. Hopefully this bug doesn't reappear.

Looks like whatever you did worked, because we haven't seen any failures since bug 937317 relanded :)