200181 - nsImapProtocol::OnStopRequest() doesn't fire anymore when server drops the connection

Status: RESOLVED FIXED

(MailNews Core :: Networking: IMAP, defect, P2)

Description

[Ere Maijala (slow)]

I believe this problem has been there since bug 190106 or thereabouts. The
problem with server closing the connection going unnoticed was first fought in
bug 120106, but now this is different. The fact that the server has closed the
connection isn't realised before Moz tries to fetch the next message or so and
there's actually BYE from server sitting in the queue. I breakpointed
OnStopRequest() but it isn't called when the server disconnects. 

This, once again, causes empty messages to be displayed instead of the real
content. It can also happen without an alert to the user in a way that it seems
the message actually is empty (which almost caused me to mail someone to ask for
a resend). The problem is usual with UW-IMAP where a second connection attempt
kills the first connection.

Comment 1

[Ere Maijala (slow)]

This is a constant pita, causing messages to be displayed blank and other
problems when the connection closure is not handled when it happens. Darin, do
you have any ideas about this?

Comment 2

[Darin Fisher]

i cannot seem to reproduce this bug.  i added code to necko to simulate random
failures from PR_Connect and PR_Read.  in both cases
nsImapProtocol::OnStopRequest is always called.

ere: can you please test out a more recent trunk build and if this problem
persists can you explain how to repro?  thx!

Comment 3

[Ere Maijala (slow)]

My debug build just finished. I set a breakpoint into
nsImapProtocol::OnStopRequest, loaded a message and killed imapd (uw-imapd).
OnStopRequest() didn't fire. I was a bit vague in my initial explanation as it
_does_ fire when the next request is made (moved to another message), but then
it's too late. It used to fire right away when the connection was dropped. Now
it thinks the connection is still fine and hoses everything with it when trying
to still use it.

Comment 4

[Darin Fisher]

ok, i'll give the same a try...

Comment 5

[Darin Fisher]

Ere: can you reproduce this bug now that the patch for bug 200391 has landed?

Comment 6

[Ere Maijala (slow)]

Unfortunately yes. Now it looks like OnStopRequest() is never hit. I can see
OnStartRequest() called appropriately, but nothing on OnStopRequest().

Comment 7

[Darin Fisher]

Ere: can you enable logging in your build... you can do this with any nightly
build or with your debug CVS build:

open a DOS prompt and type:

C:\> set NSPR_LOG_MODULES=IMAP:5,nsSocketTransport:5
C:\> set NSPR_LOG_FILE=c:\log.txt

then run mozilla from the DOS prompt:

C:\> cd \path\to\mozilla
C:\path\to\mozilla\> .\mozilla.exe

repro the problem and exit.  if you could either upload log.txt to this bug
report or send it to me directly that would be great.  thanks!!

Comment 8

[Darin Fisher]

ok, from the log file ere sent me, i get what's going on here.  the problem is
that nsImapProtocol::OnStopRequest is only executed when a socket read fails,
and not when a socket write fails.  i think we just need to factor the code in
OnStopRequest into a helper method (like HandleSocketError or something like
that).  then we can call that method from OnStopRequest or SendData when an
error occurs.

Comment 9

[Darin Fisher]

Attachment: v0 patch

this patch might do the trick, but i haven't yet fully tested it.

ere: can you try out this patch?  thanks!

Comment 10

[Ere Maijala (slow)]

I tried it, but it didn't help. I actually didn't get _any_ hits on
OnStopRequest(). And main loop was exited only after I changed to another
message (which displayed blank).

Comment 11

[Darin Fisher]

ere: ok, thanks for giving it a try.  time to try something different ;-)

Comment 12

[Darin Fisher]

probably not going to have any opportunity to fix this for 1.4 final...

bienvenu: you interested in investigating this?

Comment 13

[Ere Maijala (slow)]

Eek :( Darin, what should fire OnStopRequest? nsInputStreamPump?

Comment 14

[Darin Fisher]

Ere: well, the problem is that IMAP is writing to the sockets synchronously, but
reading from them asynchronously.  OnStartRequest, OnDataAvailable,
OnStopRequest only correspond to asynchronous reading (and those functions are
called from the nsInputStreamPump).  in this bug there seems to be two problems.
 1) failures during write don't seem to generate an error dialog, and 2)
failures while idle don't seem to get picked up.  the problem with (1) should
have been addressed by my patch, but i think what you are seeing is a result of
(2).  to fix that we need to always be polling the socket.  that's going to be
some work to implement i think.  i already have a bug about doing that for all
sockets anyways.j

Comment 15

[David :Bienvenu]

Darin, I'm not quite sure what you mean about the implications of reading
asynchronously and writing synchronously re this bug.  If we both read and wrote
synchronously or async, would that allow us to fix this? At the time we redid
IMAP for Necko, I think we had to read the data asynchronously - the code would
really prefer to both read and write the data synchronously. It's also probably
possible for us to write the data asynchronously using the same trick we use to
read the data asynchronously. In fact, since we're reading the data
asynchronously, we might not care about writing it synchronously at all.

If that's clear as mud, I should say that all the imap code is written as if
reads and writes were synchronous because in 4.x, they were, but in Mozilla, the
CreateNewLineFromSocket code actually pumps events waiting for data to be put in
the stream from OnDataAvailable calls. Given that, I don't think we care if
writes are synchronous, since we're faking synchronous reads. (though maybe
there would be horrible race conditions if we made writes async, I don't know...)

But maybe there's a simpler fix - if there's a "BYE" sitting in our input
stream, maybe we could simply check for data in our input stream before issuing
commands and read it - that would error out much sooner.

Finally, Ere, is it Mozilla that's making simultaneous connections to the same
folder? I have a patch that addresses a race condition in the multiple
connection protection code that I could attach here. I think it should help a
lot, but there might still be a problem (though I've only seen it when I'm
sitting on an assertion for a long time). The checking all folders for new mail
really stresses out the multiple connection protection code.

Comment 16

[Ere Maijala (slow)]

For me it would sound good to check for input before trying to start handling of
a new command. Could it be done in CanHandleUrl()? If there was a problem, it
could just return false. It should also check for a connection that has been
lost without any input (a network hickup for example) in addition to BYE. 

The problem for me has usually been two clients on two different machines
accessing the same folder, so no problem in the multiple connection protection
as far as I know. Another source of problems is a connection that just breaks
unexpectedly. That happens once in a while (and more often with a wlan it seems).

Comment 17

[David :Bienvenu]

::CanHandleUrl would be ideal, if we can work out the thread-safety issues
(CanHandleUrl is called from the UI thread but m_inputStream is referenced by
the UI thread, though in theory we can use the isBusy flag). Darin, (or Ere),
how do we check if the connection has simply been dropped/lost?

Comment 18

[Ere Maijala (slow)]

Well, that's what I'd like to know too. Traditionally OnStopRequest() fired when
the connection was lost, but after the changes it doesn't get called anymore.
Actually, after sending BYE the server will drop the connection anyway, right?
Maybe it would suffice to check that the connection is ok. 

Comment 19

[David :Bienvenu]

yes, the server would drop the connection after sending BYE. However, I think
some sort of polling would be required to find out that the connection had gone
away.

Comment 20

[David :Bienvenu]

I talked to Darin a little more. One thing we can do is call
nsISocketTransport::IsAlive before using a cached connection. If that works, we
should be able to catch 99% of the cases where the server has disconnected. The
other thing we can do is do unbuffered writes to the socket, and if we get an
error on the first write from a cached connection, try to silently reconnect.

Comment 21

[David :Bienvenu]

Attachment: proposed fix (from IMAP pov)

This patch makes it so the IMAP code won't try to re-use a connection that's
not alive. In theory, this means we'll just try to open a new connection if the
UW server has dropped us. Ere, can you test this? It looks like the code that
calls ::CanHandleUrl does the right thing when it gets an error, but I haven't
tried the error case.

Comment 22

[Ere Maijala (slow)]

Comment on attachment 125610 [details] [diff] [review]
proposed fix (from IMAP pov)

Well, it doesn't make OnStopRequest fire but that doesn't matter as the patch
works great anyway. And thumbs up for fixing isSafeToClose :)
r=[e-mail]

Comment 23

[Ere Maijala (slow)]

*** Bug 195106 has been marked as a duplicate of this bug. ***

Comment 24

[David :Bienvenu]

fix checked in, sr=sspitzer, thx for testing this, Ere. Darin, thx for the tip,
and do you want to leave this bug open?

Comment 25

[Darin Fisher]

david: yeah, it's probably still possible to "see" this bug if the server
happens to drop the connection between the IsAlive check and the attempt to read
from the connection.  we should probably leave this bug open since the patch is
really only a workaround.

Comment 26

[Darin Fisher]

-> default owner

Comment 27

[J. Paul Reed [:preed]]

Is this bug still present in 1.4.1? I see a fix was checked in, but I'm hitting
either this (or something very similar to it) with 1.4.1 and an MS Exchange server.

Comment 28

[Darin Fisher]

hmm.. i don't know about 1.4.1, but since bienvenu landed his patch for 218874,
nsImapProtocol::OnStopRequest no longer exists.  so, maybe this bug is fixed on
the trunk?

Comment 29

[David :Bienvenu]

is anyone still having this problem on the trunk? I.e., not noticing that the
server has dropped the connection?

Comment 30

[J. Paul Reed [:preed]]

I'll give it a try today; would a Thunderbird nightly have it, or would I have
to grab a 1.5 nightly?

Comment 31

[David :Bienvenu]

yes, a thunderbird nightly would have it.

Comment 32

[Darin Fisher]

uh, but last i checked there aren't any nightly trunk builds for thunderbird. 
there are only ~weekly builds of the 1.5 branch.  i think you should try a
normal nightly trunk build of mozilla:

  ftp://ftp.mozilla.org/pub/mozilla.org/mozilla/nightly/latest-trunk/

thx!

Comment 33

[J. Paul Reed [:preed]]

I'm currently testing with the latest 1.5 build from
http://ftp.mozilla.org/pub/mozilla.org/mozilla/nightly/latest-1.5/, which is:

Mozilla/5.0 (X11; U; Linux i686; en-US; rv:1.5) Gecko/20031007

I tried to use the latest trunk build, but it kept crashing on page loads to
bmo... so it wasn't imminently usable.

The fix looks to be checked in awhile ago, so maybe it's in 1.5? I guess we'll
see. ;-)

Comment 34

[J. Paul Reed [:preed]]

After having used build 2003101305 (Mozilla/5.0 (X11; U; Linux i686; en-US;
rv:1.6a) Gecko/20031013) for about a week, I've only run into this problem once
maybe, and it could've been something else that one time (I wasn't really paying
attention when it happened.)

I think that fix, whether or not it was a workaround, is working for now.

Comment 35

[David :Bienvenu]

ok, thx, marking fixed.

Comment 36

[J. Paul Reed [:preed]]

Hrm; I've been using the same build for a few weeks now and I've been seemingly
hitting this again, but much less frequently (maybe 1-2 times a day as opposed
to 1-2 times an hour).

Could there be a corner case that's being missed?

Comment 37

[Ere Maijala (slow)]

Confirming. I left Moz running at work when going home and there were two cases
when a message load didn't complete (just kept spinning) before moving to
another message and back, and one case where junk mail controls didn't run
properly. Most of the time it worked fine though.

Comment 38

[J. Paul Reed [:preed]]

This is much worse with thunderbird 0.5; back to 1-2 times/hour.

Comment 39

[Wayne Mery (:wsmwk)]

are the primary symptoms of this as described in comment 1?  "causes empty messages to be displayed instead of the real content. It can also happen without an alert to the user in a way that it seems the message actually is empty (which almost caused me to mail someone to ask for a resend). The problem is usual with UW-IMAP where a second connection attempt kills the first connection."

And, is the problem gone since preed's last comment?

Comment 40

[Ere Maijala (slow)]

That's at least one symptom and it can happen with other servers too. I'm not sure if it causes other problems.

I'm still occasionally seeing empty messages. It often happens when shuffling around large messages with attachments, but sometimes also with smaller ones. It's not that often, but it's still there.

Comment 41

[Wayne Mery (:wsmwk)]

bienvenu, don't we have another bug like this, with more recent activity?

Comment 42

[David :Bienvenu]

(In reply to comment #41)
> bienvenu, don't we have another bug like this, with more recent activity?

Not that I know of, no. I don't think this bug is particularly useful anymore - there may be symptoms that look like some of the symptoms in this bug, but a lot has changed since this bug was filed.

Comment 43

[Wayne Mery (:wsmwk)]

agreed. => FIXED for the original issue, checkin comment 24