I just caught a mochitest harness timeout, at successful completion of the "mochitest-plain" suite. This was a TryServer unittest box, with a build from http://hg.mozilla.org/try/rev/49075fda9273 (basically m-c tip, plus a small patch for bug 523188, which I don't think could be related to the timeout). http://tinderbox.mozilla.org/showlog.cgi?log=MozillaTry/1256025049.1256033027.11498.gz WINNT 5.2 try hg unit test on 2009/10/20 00:50:49 { ... 124665 INFO TEST-PASS | /tests/uriloader/exthandler/tests/mochitest/test_unsafeBidiChars.xhtml | The filename should be correctly sanitized 124667 INFO Passed: 118792 124668 INFO Failed: 0 124669 INFO Todo: 1451 124670 INFO SimpleTest FINISHED command timed out: 300 seconds without output } This is basically the same sort of issue as bug 505718. I'm filing this as a separate bug, though, because bug 505718 had some patches land, and was then apparently fixed for awhile... until now... which makes me think this new occurrence has a different root cause.

I've got patches in bug 501034 which should help us get stacks for these hangs.

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1276566653.1276568457.4180.gz WINNT 5.2 mozilla-central debug test mochitests-1/5 on 2010/06/14 18:50:53 s: win32-slave35

The last two logs (comment 11 and comment 12) both have a stack on thread 0 that has some recursion that looks pretty bad; the following five frames are repeated multiple times in the stack on that thread: 13 xul.dll!nsThread::Shutdown() [nsThread.cpp:81525a39fac5 : 477 + 0xa] eip = 0x11186b55 esp = 0x0012d6c0 ebp = 0x0012d720 Found by: call frame info 14 xul.dll!nsBuiltinDecoder::Stop() [nsBuiltinDecoder.cpp:81525a39fac5 : 133 + 0x1b] eip = 0x10b6d72f esp = 0x0012d728 ebp = 0x0012d734 Found by: call frame info 15 xul.dll!nsRunnableMethodImpl<void ( nsBuiltinDecoder::*)(void),1>::Run() [nsThreadUtils.h:81525a39fac5 : 347 + 0xd] eip = 0x10b6fa7a esp = 0x0012d73c ebp = 0x0012d73c Found by: call frame info 16 xul.dll!nsThread::ProcessNextEvent(int,int *) [nsThread.cpp:81525a39fac5 : 547 + 0x18] eip = 0x11186efa esp = 0x0012d744 ebp = 0x0012d778 Found by: call frame info 17 xul.dll!NS_ProcessNextEvent_P(nsIThread *,int) [nsThreadUtils.cpp:81525a39fac5 : 250 + 0x15] eip = 0x11131823 esp = 0x0012d780 ebp = 0x0012d794 Found by: call frame info Since nsBuiltinDecoder is involved, moving to Video/Audio.

Note that the recent stacks may be different from the old ones; if the old ones don't have the breakpad hang stacks, they're probably not useful anyway.

... again, nsBuiltinDecoder repeatedly in the stack

The log in comment 2 also has nsBuiltinDecoder on the stack (although only once). Likewise only once in comment 3. It's also possible this is a debug-only deadlock between nsBuiltinDecoder code and the Windows stack walking code (and/or possibly something else), given the stacks.

Looks like we're failing to shutdown the nsBuiltinDecoderStateMachine thread. This is because: 1. sa_stream_drain(), called by nsAudioStream::Drain() at the end of AudioLoop() is not returning. This is the root cause of this hang. While we drain the audio stream at the end of the audio loop, we hold the audio monitor, but the drain is not returning, so the audio thread ends up holding the audio monitor indefinitely. 2. While the state machine thread is shutting down (in nsBuiltinDecoderStateMachine::StopPlayback()), it attempts to take the audio monitor before destroying the audio stream. It can't, because the audio thread stuck in sa_stream_drain() still holds it. So the state machine thread waits on the audio monitor. 3. Because the state machine thread can't shutdown due to the audio monitor being held, when nsBuiltinDecoder::Stop() calls nsIThread::Shutdown() on the state machine thread, Stop() just idles on the main thread event loop, and eventually causes FF to timeout. So the root cause is sa_stream_drain() isn't returning for some reason.

I wonder if after pushing the last audio chunk to the hardware, the audio stream was paused by the state machine thread? Then the "while not finished playing, sleep()" loop in sa_stream_drain() could loop forever.

(In reply to comment #19) > I wonder if after pushing the last audio chunk to the hardware, the audio > stream was paused by the state machine thread? Then the "while not finished > playing, sleep()" loop in sa_stream_drain() could loop forever. The only way I can imagine this happening is if the waveapi never called us back to let us know a block has finished playing, which seems unlikely...

The instance in comment 31 occurred on Linux rather than Windows, but I am noting it here as the stack looks similar, with nsBuiltinDecoder apparently failing to shut down properly - could this be a non-Windows-specific issue? Thread 0 (crashed) 0 libxul.so!nsAutoRefCnt::operator nsrefcnt [nsISupportsImpl.h : 254 + 0x1] eip = 0x00f695e7 esp = 0xbfb62248 ebp = 0xbfb62278 ebx = 0x03271134 esi = 0x0260dc94 edi = 0x02380eb6 eax = 0x0ab35c64 ecx = 0x00000003 edx = 0x0259754c efl = 0x00200202 Found by: given as instruction pointer in context 1 libxul.so!nsRunnable::AddRef [nsThreadUtils.cpp : 55 + 0xd] eip = 0x0259756c esp = 0xbfb62250 ebp = 0xbfb62278 ebx = 0x03271134 esi = 0x0260dc94 edi = 0x02380eb6 Found by: call frame info 2 libxul.so!nsRefPtr<nsIRunnable>::nsRefPtr [nsAutoPtr.h : 993 + 0x15] eip = 0x00fc12d1 esp = 0xbfb62280 ebp = 0xbfb62288 ebx = 0x03271134 esi = 0x0260dc94 edi = 0x02380eb6 Found by: call frame info 3 libxul.so!nsEventQueue::PutEvent [nsEventQueue.cpp:198709160138 : 109 + 0x11] eip = 0x0260afc9 esp = 0xbfb62290 ebp = 0xbfb622d8 ebx = 0x03271134 esi = 0x0260dc94 edi = 0x02380eb6 Found by: call frame info 4 libxul.so!nsThread::nsChainedEventQueue::PutEvent [nsThread.cpp:198709160138 : 671 + 0x14] eip = 0x0260c548 esp = 0xbfb622e0 ebp = 0xbfb62308 ebx = 0x03271134 esi = 0x0260dc94 edi = 0x02380eb6 Found by: call frame info 5 libxul.so!nsThread::PutEvent [nsThread.cpp:198709160138 : 374 + 0x14] eip = 0x0260c682 esp = 0xbfb62310 ebp = 0xbfb62368 ebx = 0x03271134 esi = 0x0260dc94 edi = 0x02380eb6 Found by: call frame info 6 libxul.so!nsThread::Dispatch [nsThread.cpp:198709160138 : 418 + 0x11] eip = 0x0260deb5 esp = 0xbfb62370 ebp = 0xbfb623a8 ebx = 0x03271134 esi = 0x0260dc94 edi = 0x02380eb6 Found by: call frame info 7 libxul.so!nsBaseAppShell::OnProcessNextEvent [nsBaseAppShell.cpp:198709160138 : 329 + 0x2b] eip = 0x022b0316 esp = 0xbfb623b0 ebp = 0xbfb623f8 ebx = 0x03271134 esi = 0x0260dc94 edi = 0x02380eb6 Found by: call frame info 8 libxul.so!nsThread::ProcessNextEvent [nsThread.cpp:198709160138 : 517 + 0x61] eip = 0x0260cb39 esp = 0xbfb62400 ebp = 0xbfb62468 ebx = 0x03271134 esi = 0x096a4dec edi = 0x02380eb6 Found by: call frame info 9 libxul.so!NS_ProcessNextEvent_P [nsThreadUtils.cpp : 250 + 0x1f] eip = 0x02596f78 esp = 0xbfb62470 ebp = 0xbfb624a8 ebx = 0x03271134 esi = 0x0e9386d0 edi = 0x02380eb6 Found by: call frame info 10 libxul.so!nsThread::Shutdown [nsThread.cpp:198709160138 : 477 + 0x12] eip = 0x0260dbd2 esp = 0xbfb624b0 ebp = 0xbfb62538 ebx = 0x03271134 esi = 0x0e9386d0 edi = 0x02380eb6 Found by: call frame info 11 libxul.so!nsBuiltinDecoder::Stop [nsBuiltinDecoder.cpp:198709160138 : 133 + 0x1b] eip = 0x01ad480d esp = 0xbfb62540 ebp = 0xbfb62558 ebx = 0x03271134 esi = 0x096a4dec edi = 0x02380eb6 Found by: call frame info 12 libxul.so!nsRunnableMethodImpl<void (nsBuiltinDecoder::*)(), true>::Run [nsThreadUtils.h : 347 + 0x4e] eip = 0x01ad5615 esp = 0xbfb62560 ebp = 0xbfb62568 ebx = 0x03271134 esi = 0x096a4dec edi = 0x02380eb6 Found by: call frame info 13 libxul.so!nsThread::ProcessNextEvent [nsThread.cpp:198709160138 : 547 + 0x18] eip = 0x0260cc3b esp = 0xbfb62570 ebp = 0xbfb625d8 ebx = 0x03271134 esi = 0x096a4dec edi = 0x02380eb6 Found by: call frame info 14 libxul.so!NS_ProcessNextEvent_P [nsThreadUtils.cpp : 250 + 0x1f] eip = 0x02596f78 esp = 0xbfb625e0 ebp = 0xbfb62618 ebx = 0x03271134 esi = 0x0f9293b0 edi = 0x02380eb6 Found by: call frame info 15 libxul.so!nsThread::Shutdown [nsThread.cpp:198709160138 : 477 + 0x12] eip = 0x0260dbd2 esp = 0xbfb62620 ebp = 0xbfb626a8 ebx = 0x03271134 esi = 0x0f9293b0 edi = 0x02380eb6 Found by: call frame info 16 libxul.so!nsBuiltinDecoder::Stop [nsBuiltinDecoder.cpp:198709160138 : 133 + 0x1b] eip = 0x01ad480d esp = 0xbfb626b0 ebp = 0xbfb626c8 ebx = 0x03271134 esi = 0x096a4dec edi = 0x02380eb6 Found by: call frame info 17 libxul.so!nsRunnableMethodImpl<void (nsBuiltinDecoder::*)(), true>::Run [nsThreadUtils.h : 347 + 0x4e] eip = 0x01ad5615 esp = 0xbfb626d0 ebp = 0xbfb626d8 ebx = 0x03271134 esi = 0x096a4dec edi = 0x02380eb6 Found by: call frame info 18 libxul.so!nsThread::ProcessNextEvent [nsThread.cpp:198709160138 : 547 + 0x18] eip = 0x0260cc3b esp = 0xbfb626e0 ebp = 0xbfb62748 ebx = 0x03271134 esi = 0x096a4dec edi = 0x02380eb6 Found by: call frame info 19 libxul.so!NS_ProcessNextEvent_P [nsThreadUtils.cpp : 250 + 0x1f] eip = 0x02596f78 esp = 0xbfb62750 ebp = 0xbfb62788 ebx = 0x03271134 esi = 0x00000001 edi = 0x02380eb6 Found by: call frame info 20 libxul.so!mozilla::ipc::MessagePump::Run [MessagePump.cpp:198709160138 : 110 + 0x15] eip = 0x02411bb8 esp = 0xbfb62790 ebp = 0xbfb627d8 ebx = 0x03271134 esi = 0x00000001 edi = 0x02380eb6 Found by: call frame info

Yes, seems to happen on both Windows and Linux now.

Comment 36 has "nsWaveDecoder::Stop" in the stack. I'm guessing that it's the same bug, since it's manifesting in the same way and it's in *some* media decoder's "Stop" method. Thread 0 (crashed) 0 libxul.so + 0x2dae87 eip = 0x00f5ae87 esp = 0xbff0778c ebp = 0xbff077a8 ebx = 0x032a16f4 esi = 0x02606020 edi = 0x02379a4e eax = 0xbff077f8 ecx = 0x00000010 edx = 0x68afa02a efl = 0x00200286 Found by: given as instruction pointer in context 1 libxul.so!nsThread::PutEvent [nsThread.cpp:d2efed071e64 : 380 + 0xa] eip = 0x02604a85 esp = 0xbff077b0 ebp = 0xbff07808 Found by: previous frame's frame pointer 2 libxul.so!nsThread::Dispatch [nsThread.cpp:d2efed071e64 : 418 + 0x11] eip = 0x02606241 esp = 0xbff07810 ebp = 0xbff07848 ebx = 0x032a16f4 Found by: call frame info 3 libxul.so!nsBaseAppShell::OnProcessNextEvent [nsBaseAppShell.cpp:d2efed071e64 : 329 + 0x2b] eip = 0x022a7e6e esp = 0xbff07850 ebp = 0xbff07898 ebx = 0x032a16f4 Found by: call frame info 4 libxul.so!nsThread::ProcessNextEvent [nsThread.cpp:d2efed071e64 : 517 + 0x61] eip = 0x02604ec5 esp = 0xbff078a0 ebp = 0xbff07908 ebx = 0x032a16f4 esi = 0x09e6ab54 Found by: call frame info 5 libxul.so!NS_ProcessNextEvent_P [nsThreadUtils.cpp : 250 + 0x1f] eip = 0x0258f304 esp = 0xbff07910 ebp = 0xbff07948 ebx = 0x032a16f4 esi = 0x0f124530 Found by: call frame info 6 libxul.so!nsThread::Shutdown [nsThread.cpp:d2efed071e64 : 477 + 0x12] eip = 0x02605f5e esp = 0xbff07950 ebp = 0xbff079d8 ebx = 0x032a16f4 esi = 0x0f124530 Found by: call frame info 7 libxul.so!nsWaveDecoder::Stop [nsWaveDecoder.cpp:d2efed071e64 : 1376 + 0x1b] eip = 0x01b25c21 esp = 0xbff079e0 ebp = 0xbff079e8 ebx = 0x032a16f4 esi = 0x09e6ab54 Found by: call frame info 8 libxul.so!nsRunnableMethodImpl<void (nsWaveDecoder::*)(), true>::Run [nsThreadUtils.h : 347 + 0x4e] eip = 0x01b27f75 esp = 0xbff079f0 ebp = 0xbff079f8 ebx = 0x032a16f4 esi = 0x09e6ab54 Found by: call frame info 9 libxul.so!nsThread::ProcessNextEvent [nsThread.cpp:d2efed071e64 : 547 + 0x18] eip = 0x02604fc7 esp = 0xbff07a00 ebp = 0xbff07a68 ebx = 0x032a16f4 esi = 0x09e6ab54 Found by: call frame info 10 libxul.so!NS_ProcessNextEvent_P [nsThreadUtils.cpp : 250 + 0x1f] eip = 0x0258f304 esp = 0xbff07a70 ebp = 0xbff07aa8 ebx = 0x032a16f4 esi = 0x00000001 Found by: call frame info 11 libxul.so!mozilla::ipc::MessagePump::Run [MessagePump.cpp:d2efed071e64 : 110 + 0x15] eip = 0x0240b314 esp = 0xbff07ab0 ebp = 0xbff07af8 ebx = 0x032a16f4 esi = 0x00000001 Found by: call frame info 12 libxul.so!MessageLoop::RunInternal [message_loop.cc:d2efed071e64 : 219 + 0x22] eip = 0x0266ea73 esp = 0xbff07b00 ebp = 0xbff07b28 ebx = 0x032a16f4 esi = 0x09ff4270 Found by: call frame info 13 libxul.so!MessageLoop::RunHandler [message_loop.cc:d2efed071e64 : 202 + 0xa] eip = 0x0266ea8b esp = 0xbff07b30 ebp = 0xbff07b38 ebx = 0x032a16f4 esi = 0x09ff4270 Found by: call frame info 14 libxul.so!MessageLoop::Run [message_loop.cc:d2efed071e64 : 176 + 0xa] eip = 0x0266eaef esp = 0xbff07b40 ebp = 0xbff07b58 ebx = 0x032a16f4 esi = 0x09ff4270 Found by: call frame info 15 libxul.so!nsBaseAppShell::Run [nsBaseAppShell.cpp:d2efed071e64 : 180 + 0xc] eip = 0x022a7498 esp = 0xbff07b60 ebp = 0xbff07b98 ebx = 0x032a16f4 esi = 0x09ff4270 Found by: call frame info 16 libxul.so!nsAppStartup::Run [nsAppStartup.cpp:d2efed071e64 : 191 + 0x1b] eip = 0x01fee005 esp = 0xbff07ba0 ebp = 0xbff07bd8 ebx = 0x032a16f4 esi = 0x09ff4270 Found by: call frame info 17 libxul.so!XRE_main [nsAppRunner.cpp:d2efed071e64 : 3673 + 0x1b] eip = 0x00f7d3e0 esp = 0xbff07be0 ebp = 0xbff08178 ebx = 0x032a16f4 esi = 0x09ff4270 Found by: call frame info 18 firefox-bin!main [nsBrowserApp.cpp:d2efed071e64 : 158 + 0x1d] eip = 0x08048e42 esp = 0xbff08180 ebp = 0xbff081e8 ebx = 0x0804baf4 esi = 0x09dfeee0 edi = 0x025efdcc Found by: call frame info 19 libc-2.11.so + 0x16bb5 eip = 0x0061cbb6 esp = 0xbff08200 ebp = 0xbff08278 ebx = 0x00776ff4 esi = 0x00000000 edi = 0x00000000 Found by: call frame info 20 firefox-bin + 0x9f0 eip = 0x080489f1 esp = 0xbff08280 ebp = 0x00000000 Found by: previous frame's frame pointer 21 firefox-bin!Output [nsBrowserApp.cpp:d2efed071e64 : 77 + 0x5] eip = 0x08048b42 esp = 0xbff08284 ebp = 0x00000000 Found by: stack scanning 22 ld-2.11.so + 0xecef eip = 0x00ad4cf0 esp = 0xbff08298 ebp = 0x00000000 Found by: stack scanning

This bug has only recently started to appear on Linux. (In reply to comment #37) > Comment 36 has "nsWaveDecoder::Stop" in the stack. I'm guessing that it's the > same bug, since it's manifesting in the same way and it's in *some* media > decoder's "Stop" method. Note that thread 17 has nsWaveStateMachine::Run() calling nsAudioStream::Drain() on the stack. Drain() isn't returning, it's getting stuck somewhere in pulseaudio. This is a known issue in pulseaudio, which is fixed in newer versions. bug 574190 is on file to upgrade pulseaudio on the test machines, but no progress has been made on it.

I think the mochitest timeout in this log http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1286905610.1286908872.22741.gz might be an instance of this bug (or at least related). The stacktrace doesn't have nsWaveDecoder on the stack, but like the other failures here, this one happened after media test timeouts in mochitests-1 (test_seek.html, test_seek_out_of_range.html, test_timeupdate_small_files.html), AND the full log shows assertion-failures (before the timeout) inside of nsWaveDecoder::Stop, like this: { ###!!! ASSERTION: Want to fire mutation events, but it's not safe: '(aNode->IsNodeOfType(nsINode::eCONTENT) && static_cast<nsIContent*>(aNode)-> IsInNativeAnonymousSubtree()) || sScriptBlockerCount == sRemovableScriptBlockerCount', file /builds/slave/mozilla-central-linux64-debug/build/content/base/src/nsContentUtils.cpp, line 3660 nsContentUtils::HasMutationListeners [content/base/src/nsContentUtils.cpp:3663] nsINode::doInsertChildAt [content/base/src/nsGenericElement.cpp:3619] nsGenericElement::InsertChildAt [content/base/src/nsGenericElement.cpp:3543] nsSVGUseElement::CreateAnonymousContent [content/svg/content/src/nsSVGUseElement.cpp:372] nsSVGUseFrame::CreateAnonymousContent [layout/svg/base/src/nsSVGUseFrame.cpp:177] nsCSSFrameConstructor::GetAnonymousContent [layout/base/nsCSSFrameConstructor.cpp:3929] nsCSSFrameConstructor::ProcessChildren [layout/base/nsCSSFrameConstructor.cpp:9518] nsCSSFrameConstructor::ConstructFrameFromItemInternal [layout/base/nsCSSFrameConstructor.cpp:3812] nsCSSFrameConstructor::ConstructFramesFromItem [layout/base/nsCSSFrameConstructor.cpp:5475] nsCSSFrameConstructor::ConstructFramesFromItemList [layout/base/nsCSSFrameConstructor.cpp:9457] nsCSSFrameConstructor::ContentAppended [layout/base/nsCSSFrameConstructor.cpp:6657] nsCSSFrameConstructor::CreateNeededFrames [layout/base/nsCSSFrameConstructor.cpp:6326] nsCSSFrameConstructor::CreateNeededFrames [layout/base/nsCSSFrameConstructor.cpp:6348] PresShell::FlushPendingNotifications [layout/base/nsPresShell.cpp:4874] nsRefreshDriver::Notify [layout/base/nsRefreshDriver.cpp:293] nsTimerImpl::Fire [xpcom/threads/nsTimerImpl.cpp:428] nsTimerEvent::Run [xpcom/threads/nsTimerImpl.cpp:519] nsThread::ProcessNextEvent [xpcom/threads/nsThread.cpp:547] NS_ProcessNextEvent_P [nsThreadUtils.cpp:250] nsThread::Shutdown [xpcom/threads/nsThread.cpp:476] nsWaveDecoder::Stop [content/media/wave/nsWaveDecoder.cpp:1379] nsRunnableMethodImpl<void (nsWaveDecoder::*)(), true>::Run [nsThreadUtils.h:348] nsThread::ProcessNextEvent [xpcom/threads/nsThread.cpp:547] NS_ProcessNextEvent_P [nsThreadUtils.cpp:250] nsThread::Shutdown [xpcom/threads/nsThread.cpp:476] nsWaveDecoder::Stop [content/media/wave/nsWaveDecoder.cpp:1379] nsRunnableMethodImpl<void (nsWaveDecoder::*)(), true>::Run [nsThreadUtils.h:348] nsThread::ProcessNextEvent [xpcom/threads/nsThread.cpp:547] NS_ProcessNextEvent_P [nsThreadUtils.cpp:250] nsThread::Shutdown [xpcom/threads/nsThread.cpp:476] nsWaveDecoder::Stop [content/media/wave/nsWaveDecoder.cpp:1379] nsRunnableMethodImpl<void (nsWaveDecoder::*)(), true>::Run [nsThreadUtils.h:348] nsThread::ProcessNextEvent [xpcom/threads/nsThread.cpp:547] NS_ProcessNextEvent_P [nsThreadUtils.cpp:250] nsThread::Shutdown [xpcom/threads/nsThread.cpp:476] nsWaveDecoder::Stop [content/media/wave/nsWaveDecoder.cpp:1379] nsRunnableMethodImpl<void (nsWaveDecoder::*)(), true>::Run [nsThreadUtils.h:348] nsThread::ProcessNextEvent [xpcom/threads/nsThread.cpp:547] NS_ProcessNextEvent_P [nsThreadUtils.cpp:250] mozilla::ipc::MessagePump::Run [ipc/glue/MessagePump.cpp:110] MessageLoop::RunInternal [ipc/chromium/src/base/message_loop.cc:220] MessageLoop::RunHandler [ipc/chromium/src/base/message_loop.cc:203] MessageLoop::Run [ipc/chromium/src/base/message_loop.cc:176] nsBaseAppShell::Run [widget/src/xpwidgets/nsBaseAppShell.cpp:186] nsAppStartup::Run [toolkit/components/startup/src/nsAppStartup.cpp:191] XRE_main [toolkit/xre/nsAppRunner.cpp:3670] main [browser/app/nsBrowserApp.cpp:158] libc.so.6 + 0x1eb1d }

(In reply to comment #41) > I think the mochitest timeout in this log > > http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1286905610.1286908872.22741.gz > might be an instance of this bug (or at least related). > Yes it is. You can see nsWaveDecoder::Stop() on the main thread stack several times, and you can also see some threads which are blocked in sa_stream_write() in nsAudioStream::Drain(). This happens when an audio stream of the Wave backend never returns from an audio write, and is one if the known bugs in out-of-date pulseaudio libraries.

Marking as fixed by bug 573924. If this recurs, please file a new bug.