434642 - Thunderbird hangs in IMAP: TellThreadToDie monitor deadlock

Status: RESOLVED DUPLICATE of bug 476960

(MailNews Core :: Networking: IMAP, defect)

Description

[Dan Mosedale (:dmosedale, :dmose)]

I've regularly been seeing hangs in Thunderbird.  The UI thread stack looks like this:

#0  0x96be5a2e in semaphore_wait_signal_trap ()
#1  0x96bed505 in pthread_mutex_lock ()
#2  0x0057eefb in PR_Lock (lock=0x6097f4) at /Users/dmose/s/aviary-trunk/mozilla/nsprpub/pr/src/pthreads/ptsynch.c:206
#3  0x0057fbd4 in PR_EnterMonitor (mon=0x6097f0) at /Users/dmose/s/aviary-trunk/mozilla/nsprpub/pr/src/pthreads/ptsynch.c:531
#4  0x00569294 in PR_CEnterMonitor (address=0xe34600) at /Users/dmose/s/aviary-trunk/mozilla/nsprpub/pr/src/threads/prcmon.c:380
#5  0x1ba2ec05 in nsImapProtocol::CloseStreams (this=0xe34600) at /Users/dmose/s/aviary-trunk/mozilla/mailnews/imap/src/nsImapProtocol.cpp:1003
#6  0x003c51df in NS_InvokeByIndex_P (that=0xe3468c, methodIndex=3, paramCount=0, params=0x0) at /Users/dmose/s/aviary-trunk/mozilla/xpcom/reflect/xptcall/src/md/unix/xptcinvoke_unixish_x86.cpp:179
#7  0x003b44a4 in nsProxyObjectCallInfo::Run (this=0x1f38a140) at /Users/dmose/s/aviary-trunk/mozilla/xpcom/proxy/src/nsProxyEvent.cpp:181
#8  0x003aaac2 in nsThread::ProcessNextEvent (this=0x62e7a0, mayWait=0, result=0xbfffe104) at /Users/dmose/s/aviary-trunk/mozilla/xpcom/threads/nsThread.cpp:510
#9  0x00335bdc in NS_ProcessPendingEvents_P (thread=0x62e7a0, timeout=20) at nsThreadUtils.cpp:180
#10 0x12ab45db in nsBaseAppShell::NativeEventCallback (this=0x65ee80) at /Users/dmose/s/aviary-trunk/mozilla/widget/src/xpwidgets/nsBaseAppShell.cpp:121
#11 0x12a704ac in nsAppShell::ProcessGeckoEvents (aInfo=0x65ee80) at /Users/dmose/s/aviary-trunk/mozilla/widget/src/cocoa/nsAppShell.mm:302
#12 0x909b262e in CFRunLoopRunSpecific ()
#13 0x909b2d18 in CFRunLoopRunInMode ()
#14 0x91f7f6a0 in RunCurrentEventLoopInMode ()
#15 0x91f7f4b9 in ReceiveNextEventCommon ()
#16 0x91f7f32d in BlockUntilNextEventMatchingListInMode ()
#17 0x90f0e7d9 in _DPSNextEvent ()
#18 0x90f0e08e in -[NSApplication nextEventMatchingMask:untilDate:inMode:dequeue:] ()
#19 0x90f070c5 in -[NSApplication run] ()
#20 0x12a6e7f0 in nsAppShell::Run (this=0x65ee80) at /Users/dmose/s/aviary-trunk/mozilla/widget/src/cocoa/nsAppShell.mm:591
#21 0x12d2b33c in nsAppStartup::Run (this=0x66a090) at /Users/dmose/s/aviary-trunk/mozilla/toolkit/components/startup/src/nsAppStartup.cpp:181
#22 0x000f748d in XRE_main (argc=1, argv=0xbffff730, aAppData=0x60d920) at /Users/dmose/s/aviary-trunk/mozilla/toolkit/xre/nsAppRunner.cpp:3170
#23 0x0000277b in main (argc=1, argv=0xbffff730) at /Users/dmose/s/aviary-trunk/mozilla/mail/app/nsMailApp.cpp:103

This IMAP thread:

#0  0x96be5a2e in semaphore_wait_signal_trap ()
#1  0x96c17dc6 in _pthread_cond_wait ()
#2  0x96c5d8bb in pthread_cond_wait ()
#3  0x0057f742 in PR_WaitCondVar (cvar=0x1ccbe310, timeout=4294967295) at /Users/dmose/s/aviary-trunk/mozilla/nsprpub/pr/src/pthreads/ptsynch.c:405
#4  0x0057fe83 in PR_Wait (mon=0x1f35c380, timeout=4294967295) at /Users/dmose/s/aviary-trunk/mozilla/nsprpub/pr/src/pthreads/ptsynch.c:584
#5  0x00375d1b in nsAutoMonitor::Wait (this=0xb0556558, interval=4294967295) at nsAutoLock.h:340
#6  0x003a8c88 in nsEventQueue::GetEvent (this=0x1d24a158, mayWait=1, result=0xb05565fc) at /Users/dmose/s/aviary-trunk/mozilla/xpcom/threads/nsEventQueue.cpp:85
#7  0x003ab5bc in nsThread::nsChainedEventQueue::GetEvent (this=0x1d24a150, mayWait=1, event=0xb05565fc) at nsThread.h:112
#8  0x003aaa28 in nsThread::ProcessNextEvent (this=0x1e266b60, mayWait=1, result=0xb055665c) at /Users/dmose/s/aviary-trunk/mozilla/xpcom/threads/nsThread.cpp:501
#9  0x00335a7a in NS_ProcessNextEvent_P (thread=0x1e266b60, mayWait=1) at nsThreadUtils.cpp:227
#10 0x003b5816 in nsProxyEventObject::CallMethod (this=0x1f34c730, methodIndex=3, methodInfo=0xdb5278, params=0xb0556724) at /Users/dmose/s/aviary-trunk/mozilla/xpcom/proxy/src/nsProxyEventObject.cpp:260
#11 0x003c54c2 in PrepareAndDispatch (self=0x170ad5c0, methodIndex=3, args=0xb0556844) at /Users/dmose/s/aviary-trunk/mozilla/xpcom/reflect/xptcall/src/md/unix/xptcstubs_unixish_x86.cpp:93
#12 0x003c5521 in nsXPTCStubBase::Stub3 (this=0x170ad5c0) at xptcstubsdef.inc:1
#13 0x1ba2d4f4 in nsImapProtocol::TellThreadToDie (this=0xe34600, isSafeToClose=0) at /Users/dmose/s/aviary-trunk/mozilla/mailnews/imap/src/nsImapProtocol.cpp:1108
#14 0x1ba31ef1 in nsImapProtocol::CreateNewLineFromSocket (this=0xe34600) at /Users/dmose/s/aviary-trunk/mozilla/mailnews/imap/src/nsImapProtocol.cpp:4388
#15 0x1ba437d0 in nsImapServerResponseParser::GetNextLineForParser (this=0xe3475c, nextLine=0xe34764) at /Users/dmose/s/aviary-trunk/mozilla/mailnews/imap/src/nsImapServerResponseParser.cpp:125
#16 0x1b9ca759 in nsIMAPGenericParser::AdvanceToNextLine (this=0xe3475c) at /Users/dmose/s/aviary-trunk/mozilla/mailnews/imap/src/nsIMAPGenericParser.cpp:182
#17 0x1b9ca8fa in nsIMAPGenericParser::AdvanceToNextToken (this=0xe3475c) at /Users/dmose/s/aviary-trunk/mozilla/mailnews/imap/src/nsIMAPGenericParser.cpp:153
#18 0x1ba43c23 in nsImapServerResponseParser::ParseIMAPServerResponse (this=0xe3475c, currentCommand=0x1e253978 "4 logout\r\n", aIgnoreBadAndNOResponses=0) at /Users/dmose/s/aviary-trunk/mozilla/mailnews/imap/src/nsImapServerResponseParser.cpp:234
#19 0x1ba1d5cb in nsImapProtocol::ParseIMAPandCheckForNewMail (this=0xe34600, commandString=0x0, aIgnoreBadAndNOResponses=0) at /Users/dmose/s/aviary-trunk/mozilla/mailnews/imap/src/nsImapProtocol.cpp:1637
#20 0x1ba230d5 in nsImapProtocol::Logout (this=0xe34600, shuttingDown=1, waitForResponse=1) at /Users/dmose/s/aviary-trunk/mozilla/mailnews/imap/src/nsImapProtocol.cpp:5838
#21 0x1ba2d4a7 in nsImapProtocol::TellThreadToDie (this=0xe34600, isSafeToClose=0) at /Users/dmose/s/aviary-trunk/mozilla/mailnews/imap/src/nsImapProtocol.cpp:1102
#22 0x1ba3b88b in nsImapProtocol::ProcessCurrentURL (this=0xe34600) at /Users/dmose/s/aviary-trunk/mozilla/mailnews/imap/src/nsImapProtocol.cpp:1598
#23 0x1ba2d0d5 in nsImapProtocol::ImapThreadMainLoop (this=0xe34600) at /Users/dmose/s/aviary-trunk/mozilla/mailnews/imap/src/nsImapProtocol.cpp:1211
#24 0x1ba3579e in nsImapProtocol::Run (this=0xe34600) at /Users/dmose/s/aviary-trunk/mozilla/mailnews/imap/src/nsImapProtocol.cpp:975
#25 0x003aaac2 in nsThread::ProcessNextEvent (this=0x1e266b60, mayWait=1, result=0xb0556ecc) at /Users/dmose/s/aviary-trunk/mozilla/xpcom/threads/nsThread.cpp:510
#26 0x00335a7a in NS_ProcessNextEvent_P (thread=0x1e266b60, mayWait=1) at nsThreadUtils.cpp:227
#27 0x003aacd1 in nsThread::ThreadFunc (arg=0x1e266b60) at /Users/dmose/s/aviary-trunk/mozilla/xpcom/threads/nsThread.cpp:254
#28 0x005862c0 in _pt_root (arg=0x19cde520) at /Users/dmose/s/aviary-trunk/mozilla/nsprpub/pr/src/pthreads/ptthread.c:221
#29 0x96c16c55 in _pthread_start ()
#30 0x96c16b12 in thread_start ()

is in the monitor in frame 21 (the first call to TellThreadToDie).

From the end of the IMAP connection log:

-1339387904[1f38f5c0]: 2011d800:mail.mozilla.com:S-Bugs:CreateNewLineFromSocket: 18 OK UID STORE completed
-1336578048[19cde520]: ReadNextLine [stream=170a6bec nb=0 needmore=1]
-1336578048[19cde520]: e34600:mail.meer.net:NA:CreateNewLineFromSocket: clearing IMAP_CONNECTION_IS_OPEN - rv = 804b000e

0x804b000e is NS_ERROR_NET_RESET, which is presumably a TCP connection reset packet.

Apparently, the call to m_transport->IsAlive is (incorrectly? -- need to investigate connection reset / Necko / NSPR semantics here) returning true.

bienvenu suggests that checking the connection status in addition to isAlive would be a good idea regardless of underlying transport semantics, because this code gets called to clean up idle connections as well, and we don't know whether those are alive or not.

Marking as blocking-3.0a2+ because (for me, at least) it's happening often enough at the moment to make Tb unusable.

Comment 1

[Dan Mosedale (:dmosedale, :dmose)]

bienvenu's suggested fix worked.  However, the behavior in nightlies (which don't have the fix) has disappeared, so it appears to be triggered by some transient and unusual network or server condition.  Furthermore, it turns out that 3.0a1 had this problem as well.  Since I'm not aware of any other reports of this bug, I suspect it's something pretty specific to my situation.  Changing from blocking-3.0a2+ to blocking-3.0+.

Comment 2

[David :Bienvenu]

I think it's OK to try to drive this patch forward, though. If it happened to you, it's probably happening to other users out there...

Comment 3

[Emre Birol]

dmose: Can you attach the full imap protocol log if you still have it. 

Comment 4

[Dan Mosedale (:dmosedale, :dmose)]

bienvenu: agreed; I just wouldn't hold back the next alpha if this were the last remaining bug, thus the flag change.

emre: unfortunately, I was forced to reboot my mac, and it got deleted from /tmp

Comment 5

[Dan Mosedale (:dmosedale, :dmose)]

Attachment: check connection status before trying to logout, v1

Comment 6

[Dan Mosedale (:dmosedale, :dmose)]

Attachment: check connection status before trying to logout, v2 (checked in)

Fix inverted logic.  Will test with protocol log to verify before requesting review.

Comment 7

[Dan Mosedale (:dmosedale, :dmose)]

Comment on attachment 322998 [details] [diff] [review]
check connection status before trying to logout, v2 (checked in)


Verified by IMAP protocol logging that we do indeed logout when quitting with this patch; requesting review.

Comment 8

[David :Bienvenu]

Comment on attachment 322998 [details] [diff] [review]
check connection status before trying to logout, v2 (checked in)


great, thx

Comment 9

[Dan Mosedale (:dmosedale, :dmose)]

Fix checked in.

Comment 10

[Dan Mosedale (:dmosedale, :dmose)]

I've been seeing more freezes, tracked them down to an almost identical stack trace, and realized that this patch didn't really fix the problem, it merely narrowed a race condition.  There's still a period of time between when we call GetConnectionStatus and when the "logout" command happens on the main thread when the connection could go bad, and therefore cause us to deadlock.  It's possible that the right thing to do is issue the logout command on the IMAP thread.  I'd be interested in hearing thoughts from folks who know this code better than me.

Comment 11

[Dan Mosedale (:dmosedale, :dmose)]

OK, I was somewhat confused when I wrote the above.  The logout command is already happening on the connection there.  But there's still a race here that needs to be pinned down.

Comment 12

[Dan Mosedale (:dmosedale, :dmose)]

I haven't been seeing this lately, and since noone else has reported seeing it, having it block 3.0a2 doesn't make much sense.

Comment 13

[Wayne Mery (:wsmwk)]

related to recently reported 2.0.19 Bug 479773 ?

Comment 14

[David :Bienvenu]

pretty sure this is a dup.