1057618 - Intermittent test_headers.html | application timed out after 330 seconds with no output

Status: RESOLVED WORKSFORME

(Core :: DOM: Core & HTML, defect)

Description

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://tbpl.mozilla.org/php/getParsedLog.php?id=46566929&tree=Mozilla-Inbound
Rev4 MacOSX Snow Leopard 10.6 mozilla-inbound debug test mochitest-3 on 2014-08-22 08:11:14 PDT for push 2ee31951b96f

slave: t-snow-r4-0018



08:17:18     INFO -  22475 INFO TEST-START | /tests/dom/plugins/test/mochitest/test_hanging.html
08:17:18     INFO -  22476 INFO ++DOMWINDOW == 74 (0x123c90800) [pid = 971] [serial = 808] [outer = 0x12b94d000]
08:17:18     INFO -  22477 INFO ++DOCSHELL 0x12e0b6800 == 19 [pid = 971] [id = 116]
08:17:18     INFO -  22478 INFO ++DOMWINDOW == 75 (0x12bf4d400) [pid = 971] [serial = 809] [outer = 0x0]
08:17:18     INFO -  22479 INFO [Parent 971] WARNING: NS_ENSURE_TRUE(nsContentUtils::GetCurrentJSContext()) failed: file /builds/slave/m-in-osx64-d-00000000000000000/build/docshell/base/nsDocShell.cpp, line 8847
08:17:18     INFO -  22480 INFO ++DOMWINDOW == 76 (0x12bf50400) [pid = 971] [serial = 810] [outer = 0x12bf4d400]
08:17:18     INFO -  22481 INFO For application/x-test found plugin Test.plugin
08:17:18     INFO -  22482 INFO XPCOM_MEM_BLOAT_LOG: /var/folders/dH/dHWTBHC+FbCwitJmOFQmqE+++-k/-Tmp-/tmpTpJ_yX.mozrunner/runtests_leaks.log
08:17:18     INFO -  22483 INFO Writing to log: /var/folders/dH/dHWTBHC+FbCwitJmOFQmqE+++-k/-Tmp-/tmpTpJ_yX.mozrunner/runtests_leaks_plugin_pid989.log
08:17:23     INFO -  22484 INFO [Parent 971] WARNING: Failed to send message!: file /builds/slave/m-in-osx64-d-00000000000000000/build/dom/plugins/ipc/PluginScriptableObjectParent.cpp, line 165
08:17:23     INFO -  22485 INFO ###!!! [Parent][MessageChannel::Call] Error: Channel timeout: cannot send/recv
08:17:23     INFO -  22486 INFO ###!!! [Parent][MessageChannel::Call] Error: Channel timeout: cannot send/recv
08:17:23     INFO -  22487 INFO [Parent 971] WARNING: Failed to send message!: file /builds/slave/m-in-osx64-d-00000000000000000/build/dom/plugins/ipc/PluginScriptableObjectParent.cpp, line 165
08:17:23     INFO -  22488 INFO [989] ###!!! ABORT: Aborting on channel error.: file /builds/slave/m-in-osx64-d-00000000000000000/build/ipc/glue/MessageChannel.cpp, line 1611
08:17:23     INFO -  22489 INFO [989] ###!!! ASSERTION: Cannot call AnnotateCrashReport in child processes from non-main thread.: 'Error', file /builds/slave/m-in-osx64-d-00000000000000000/build/toolkit/crashreporter/nsExceptionHandler.cpp, line 1711
08:17:52     INFO -  22490 INFO NS_DebugBreak [xpcom/base/nsDebugImpl.cpp:418]
08:17:52     INFO -  22491 INFO mozilla::ipc::MessageChannel::OnChannelErrorFromLink() [ipc/glue/MessageChannel.cpp:1613]
08:17:52     INFO -  22492 INFO mozilla::ipc::ProcessLink::OnChannelError() [xpcom/glue/Monitor.h:36]
08:17:52     INFO -  22493 INFO IPC::Channel::ChannelImpl::OnFileCanReadWithoutBlocking(int) [ipc/chromium/src/chrome/common/ipc_channel_posix.cc:858]
08:17:52     INFO -  22494 INFO event_base_loop [ipc/chromium/src/third_party/libevent/event.c:1355]
08:17:52     INFO -  22495 INFO base::MessagePumpLibevent::Run(base::MessagePump::Delegate*) [ipc/chromium/src/base/message_pump_libevent.cc:332]
08:17:52     INFO -  22496 INFO MessageLoop::Run() [ipc/chromium/src/base/message_loop.cc:504]
08:17:52     INFO -  22497 INFO base::Thread::ThreadMain() [ipc/chromium/src/base/thread.cc:171]
08:17:52     INFO -  22498 INFO ThreadFunc [ipc/chromium/src/base/platform_thread_posix.cc:39]
08:17:52     INFO -  22499 INFO libSystem.B.dylib + 0x39fd6
08:17:52     INFO -  22500 INFO [989] ###!!! ASSERTION: Cannot call AnnotateCrashReport in child processes from non-main thread.: 'Error', file /builds/slave/m-in-osx64-d-00000000000000000/build/toolkit/crashreporter/nsExceptionHandler.cpp, line 1661
08:17:52     INFO -  22501 INFO NS_DebugBreak [xpcom/string/nsTSubstring.h:95]
08:17:52     INFO -  22502 INFO mozilla::ipc::MessageChannel::OnChannelErrorFromLink() [ipc/glue/MessageChannel.cpp:1613]
08:17:52     INFO -  22503 INFO mozilla::ipc::ProcessLink::OnChannelError() [xpcom/glue/Monitor.h:36]
08:17:52     INFO -  22504 INFO IPC::Channel::ChannelImpl::OnFileCanReadWithoutBlocking(int) [ipc/chromium/src/chrome/common/ipc_channel_posix.cc:858]
08:17:52     INFO -  22505 INFO event_base_loop [ipc/chromium/src/third_party/libevent/event.c:1355]
08:17:52     INFO -  22506 INFO base::MessagePumpLibevent::Run(base::MessagePump::Delegate*) [ipc/chromium/src/base/message_pump_libevent.cc:332]
08:17:52     INFO -  22507 INFO MessageLoop::Run() [ipc/chromium/src/base/message_loop.cc:504]
08:17:52     INFO -  22508 INFO base::Thread::ThreadMain() [ipc/chromium/src/base/thread.cc:171]
08:17:52     INFO -  22509 INFO ThreadFunc [ipc/chromium/src/base/platform_thread_posix.cc:39]
08:17:52     INFO -  22510 INFO libSystem.B.dylib + 0x39fd6
08:17:52     INFO -  22511 INFO mozilla::ipc::ProcessLink::OnChannelError() [xpcom/glue/Monitor.h:36]
08:17:52     INFO -  22512 INFO IPC::Channel::ChannelImpl::OnFileCanReadWithoutBlocking(int) [ipc/chromium/src/chrome/common/ipc_channel_posix.cc:858]
08:17:52     INFO -  22513 INFO event_base_loop [ipc/chromium/src/third_party/libevent/event.c:1355]
08:17:52     INFO -  22514 INFO base::MessagePumpLibevent::Run(base::MessagePump::Delegate*) [ipc/chromium/src/base/message_pump_libevent.cc:332]
08:17:52     INFO -  22515 INFO MessageLoop::Run() [ipc/chromium/src/base/message_loop.cc:504]
08:17:52     INFO -  22516 INFO base::Thread::ThreadMain() [ipc/chromium/src/base/thread.cc:171]
08:17:52     INFO -  22517 INFO ThreadFunc [ipc/chromium/src/base/platform_thread_posix.cc:39]
08:17:52     INFO -  22518 INFO libSystem.B.dylib + 0x39fd6
08:17:52     INFO -  22519 INFO [989] ###!!! ABORT: Aborting on channel error.: file /builds/slave/m-in-osx64-d-00000000000000000/build/ipc/glue/MessageChannel.cpp, line 1611
08:17:52     INFO -  22520 INFO Hit MOZ_CRASH() at /builds/slave/m-in-osx64-d-00000000000000000/build/memory/mozalloc/mozalloc_abort.cpp:30
08:17:52     INFO -  22521 INFO ###!!! [Parent][MessageChannel] Error: Channel timeout: cannot send/recv
08:17:52     INFO -  22522 INFO ###!!! [Parent][MessageChannel::Call] Error: Channel timeout: cannot send/recv
08:17:52     INFO -  22523 INFO ###!!! [Parent][MessageChannel::Call] Error: Channel timeout: cannot send/recv
08:17:52     INFO -  22524 INFO ++DOMWINDOW == 77 (0x11ecab800) [pid = 971] [serial = 811] [outer = 0x12bf4d400]
08:17:52     INFO -  22525 INFO For application/x-test found plugin Test.plugin
08:17:52     INFO -  22526 INFO DMD[990] $DMD = '(null)'
08:17:52     INFO -  22527 INFO DMD[990] DMD is not enabled
08:17:52     INFO -  22528 INFO [990] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/slave/m-in-osx64-d-00000000000000000/build/xpcom/base/nsTraceRefcnt.cpp, line 148
08:17:52     INFO -  22529 INFO [990] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/slave/m-in-osx64-d-00000000000000000/build/xpcom/base/nsTraceRefcnt.cpp, line 148
08:17:52     INFO -  22530 INFO [990] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/slave/m-in-osx64-d-00000000000000000/build/xpcom/base/nsTraceRefcnt.cpp, line 148
08:17:52     INFO -  22531 INFO [990] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/slave/m-in-osx64-d-00000000000000000/build/xpcom/base/nsTraceRefcnt.cpp, line 148
08:17:52     INFO -  22532 INFO [990] WARNING: XPCOM objects created/destroyed from static ctor/dtor: file /builds/slave/m-in-osx64-d-00000000000000000/build/xpcom/base/nsTraceRefcnt.cpp, line 148
08:17:52     INFO -  22533 INFO ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /var/folders/dH/dHWTBHC+FbCwitJmOFQmqE+++-k/-Tmp-/tmpTpJ_yX.mozrunner/runtests_leaks_plugin_pid990.log
08:17:52     INFO -  22534 INFO [loaded plugin /private/var/folders/dH/dHWTBHC+FbCwitJmOFQmqE+++-k/-Tmp-/tmpTpJ_yX.mozrunner/plugins/Test.plugin]
08:17:52     INFO -  22535 INFO TEST-OK | /tests/dom/plugins/test/mochitest/test_hanging.html | took 6823ms
08:17:52     INFO -  22536 INFO ++DOMWINDOW == 78 (0x1289d8800) [pid = 971] [serial = 812] [outer = 0x12b94d000]




08:46:29     INFO -  60919 INFO --DOMWINDOW == 9 (0x10a108400) [pid = 971] [serial = 10796] [outer = 0x0] [url = http://mochi.test:8888/tests/SimpleTest/iframe-between-tests.html]
08:46:29     INFO -  60920 INFO --DOMWINDOW == 8 (0x11ca88400) [pid = 971] [serial = 10790] [outer = 0x0] [url = http://mochi.test:8888/tests/SimpleTest/iframe-between-tests.html]
08:46:29     INFO -  60921 INFO --DOMWINDOW == 7 (0x12b559000) [pid = 971] [serial = 12] [outer = 0x0] [url = http://mochi.test:8888/tests/?autorun=1&closeWhenDone=1&consoleLevel=INFO&totalChunks=5&thisChunk=3&chunkByDir=4&hideResultsTable=1&manifestFile=tests.json&dumpOutputDirectory=%2Fvar%2Ffolders%2FdH%2FdHWTBHC%2BFbCwitJmOFQmqE%2B%2B%2B-k%2F-Tmp-]
08:46:29     INFO -  60922 INFO --DOMWINDOW == 6 (0x12b94d000) [pid = 971] [serial = 13] [outer = 0x0] [url = about:blank]
08:46:29     INFO -  60923 INFO --DOMWINDOW == 5 (0x123c94800) [pid = 971] [serial = 7] [outer = 0x0] [url = http://mochi.test:8888/tests/?autorun=1&closeWhenDone=1&consoleLevel=INFO&totalChunks=5&thisChunk=3&chunkByDir=4&hideResultsTable=1&manifestFile=tests.json&dumpOutputDirectory=%2Fvar%2Ffolders%2FdH%2FdHWTBHC%2BFbCwitJmOFQmqE%2B%2B%2B-k%2F-Tmp-]
08:46:29     INFO -  60924 INFO --DOMWINDOW == 4 (0x10a032400) [pid = 971] [serial = 10784] [outer = 0x0] [url = http://mochi.test:8888/tests/SimpleTest/iframe-between-tests.html]
08:46:29     INFO -  60925 INFO --DOMWINDOW == 3 (0x1099c8000) [pid = 971] [serial = 10779] [outer = 0x0] [url = http://mochi.test:8888/tests/dom/tests/mochitest/dom-level2-html/test_table50.html]
08:46:29     INFO -  60926 INFO --DOMWINDOW == 2 (0x11ca11400) [pid = 971] [serial = 10803] [outer = 0x0] [url = http://mochi.test:8888/tests/dom/tests/mochitest/fetch/test_headers.html]
08:46:29     INFO -  60927 INFO --DOMWINDOW == 1 (0x11fa67800) [pid = 971] [serial = 4] [outer = 0x0] [url = about:blank]
08:46:29     INFO -  60928 INFO --DOMWINDOW == 0 (0x11fa66800) [pid = 971] [serial = 3] [outer = 0x0] [url = chrome://browser/content/browser.xul]
08:46:29     INFO -  60929 INFO [Parent 971] WARNING: Extra shutdown CC: 'i < NORMAL_SHUTDOWN_COLLECTIONS', file /builds/slave/m-in-osx64-d-00000000000000000/build/xpcom/base/nsCycleCollector.cpp, line 3531
08:46:30     INFO -  60930 INFO [Parent 971] WARNING: '!compMgr', file /builds/slave/m-in-osx64-d-00000000000000000/build/xpcom/glue/nsComponentManagerUtils.cpp, line 63
08:52:00     INFO -  60931 INFO TEST-START | Shutdown
08:52:00     INFO -  60932 INFO Passed:  43556
08:52:00     INFO -  60933 INFO Failed:  0
08:52:00     INFO -  60934 INFO Todo:    393
08:52:00     INFO -  60935 INFO Slowest: 41100ms - /tests/dom/tests/mochitest/ajax/jquery/test_jQuery.html
08:52:00     INFO -  60936 INFO SimpleTest FINISHED
08:52:00     INFO -  60937 INFO TEST-INFO | Ran 1 Loops
08:52:00     INFO -  60938 INFO SimpleTest FINISHED
08:52:00  WARNING -  TEST-UNEXPECTED-TIMEOUT | /tests/dom/tests/mochitest/fetch/test_headers.html | application timed out after 330 seconds with no output
08:52:01     INFO -  TEST-INFO | screencapture: exit 0
09:08:40     INFO - Automation Error: mozprocess timed out after 1000 seconds running ['/builds/slave/talos-slave/test/build/venv/bin/python', '-u', '/builds/slave/talos-slave/test/build/tests/mochitest/runtests.py', '--total-chunks', '5', '--this-chunk', '3', '--appname=/builds/slave/talos-slave/test/build/application/FirefoxNightlyDebug.app/Contents/MacOS/firefox', '--utility-path=tests/bin', '--extra-profile-file=tests/bin/plugins', '--symbols-path=/builds/slave/talos-slave/test/build/symbols', '--certificate-path=tests/certs', '--autorun', '--close-when-done', '--console-level=INFO', '--quiet', '--log-raw=/builds/slave/talos-slave/test/build/blobber_upload_dir/raw_structured_logs.log', '--chunk-by-dir=4']
09:08:41    ERROR - timed out after 1000 seconds of no output
09:08:41    ERROR - Return code: -9
09:08:41     INFO - TinderboxPrint: mochitest-plain-chunked<br/>43556/0/393
09:08:41  WARNING - # TBPL WARNING #
09:08:41  WARNING - The mochitest suite: plain-chunked ran with return status: WARNING
09:08:41     INFO - Running post-action listener: _resource_record_post_action
09:08:41     INFO - Running post-run listener: _resource_record_post_run
09:08:41     INFO - Running post-run listener: _upload_blobber_files
09:08:41     INFO - Blob upload gear active.
09:08:41     INFO - Preparing to upload files from /builds/slave/talos-slave/test/build/blobber_upload_dir.

Comment 1

[Ben Kelly [:bkelly, not reviewing]]

Might be related to my recent landing. Ni to remind myself to look next week.

Comment 2

[Ben Kelly [:bkelly, not reviewing]]

Given this hasn't reproduced again in tbpl in the last two months, I don't think its enough of priority for me to look at it any time soon.  Clearing the NI flag for now.

Comment 3

[Ed Morley [:emorley]]

Inactive; closing (see bug 1180138).