Closed Bug 275840 Opened 20 years ago Closed 19 years ago

Thunderbird sometimes does not correctly issue IMAP DONE commands to exit out of IDLE mode

Categories

(Thunderbird :: General, defect)

Product:
Thunderbird
Component:
General
Platform:
x86
Windows XP
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(Not tracked)

Status:
RESOLVED EXPIRED

People

(Reporter: dan, Assigned: mscott)

Details

Attachments

(3 files, 1 obsolete file)

Courier's Debug.log showing the problem
16.32 KB, text/plain
Details
Trimmed version of the Zipped log file
34.28 KB, application/octet-stream
Details
Log from machine directly connected
6.21 KB, text/plain
Details 
In thunderbird, sometimes I will send a message and then Thunderbird says there
was an error copying the message to the sent folder. Size does not matter.
Message could be 15MB or 2KB. After enabling the debug log on my IMAP server
(courier-imap-3.0.8) the log file clearly shows that Thunderbird is not even
getting out of IDLE mode. An excerpt from a log file (the whole file is attached):

READ: NUMBER: 51
READ: ATOM: IDLE
READ: EOL
WRITE: + entering idle mode


<multiple attempts to save message - Notice no APPEND or DONE commands?>
<restart imap server here, forcing Thunderbird to Re-Logon>

WRITE: 1 OK LOGIN Ok.

READ: NUMBER: 2
READ: ATOM: APPEND
READ: QUOTED_STRING: INBOX.Sent
READ: ATOM: \Seen
READ: RPAREN
WRITE: + OK


I am not an expert in the IMAP protoocl but I imagine what is happening is that 
Thunderbird is not issuing the DONE command to exit idle mode before trying to
issue the APPEND command. I tried enabling the Log for IMAP in Thunderbird, but
the log does not seem to form correctly. There is always a TON of blank space at
the top of the log file. Roughly 80-90% of the file is blank space.

    
    

    
  
I'd need a client-side protocol log - I don't know why you're getting a bunch of
blank space, though other folks have had the same problem. - what did you set
your log tmp file to?

    
    

    
  
I can try to get you a log. I am getting some really odd logs though. I had
deleted the log file, and then when I reopened Thunderbird it created a 0 byte
file. No worries, right? The file is in append mode and just has not been
flushed to disk. So get the error again after trying to send ONE message (which
failed to go to Sent Items of course), and pressing Cancel twice (once to not
retry sending, and once to say do not go back to the edit window), I closed
Thunderbird. Went to the log folder. The IMAP.LOG file is there alright, and it
has a size alright. 46.7MB of size!!!!!!! So I zipped it up. I will attach the
zip shortly.


    
    

    
  
if it has a ton of blank space at the beginning of the log, could you remove
that before zipping it up?

    
  

        Attachment #169457 -
        Attachment mime type: text/plain → application/zip

    
    

    
  
Did not get your note about removing the blank space till after I had sent the
log. But I'll make a new one w/o the blank space. Should be there soon.


    
    

    
  


  
Notice how small it is compared to the 46.7MB?

    
  

        Attachment #169457 -
        Attachment is obsolete: true

    
    

    
  
ok, I don't think that has anything to do with the IDLE command. Your server
loooks like it's dropping connections, probably because you've exceeded your
connection limit. Can you go into the advanced server settings in thunderbird
for your imap server, and change the number of cached connections from 5 to 4,
and restart thunderbird?

This has been a long-standing problem. I thought I'd fixed this to put up a
better error message 

Re the blanks in the log, I think that's an NSPR issue (i.e., the equivalent of
an OS error, from thunderbird's point of view - way below and beyond our control)

    
    

    
  
Nothing is showing a dropped connection except the Courier Debug log and I
stated there that I manually restarted it because it is the only way to make it
save the message. As far as dropping the connection, Nope. I've strace'd the
prodcess handling the mail box and I see a lot of data going back and forth on
one of those  times. Each time I press OK to retry, the same data sequence goes
back and forth from what I can see in the Strace. If it helps, I can try to
capture a strace of the server running that mailbox. My connection limit is no
where near exceeded. I have 2 connections active at last check. That's it. TWO.

    
    

    
  
2824[3b67e48]: 3b55240:venus.eglifamily.dnsalias.net:NA:CreateNewLineFromSocket:
clearing IMAP_CONNECTION_IS_OPEN - rv = 80470002
2824[3b67e48]: 3b55240:venus.eglifamily.dnsalias.net:NA:TellThreadToDie: close
socket connection
2824[3b67e48]: 3b55240:venus.eglifamily.dnsalias.net:NA:CreateNewLineFromSocket:
(null)

this means the connection went bad - you'll see that twice in the log, so both
connections were bad. Do you have a router or firewall or VPN that might be
killing your connection?

    
    

    
  
nothing like that. The machine is behind a simple SOHO wireless router with all
ports forwarded to my gateway (small linux machine). From there port 143 is
forwarded to the mail server. That is the entire path. If it says the connection
went bad, then something is screwy because if the connection was bad, why would
clicking on the OK button produce more input to the daemon?

    
    

    
  
if you click OK, then we try again with an other connection, which produces more
traffic...

    
    

    
  
I am sorry but that is not how I understand socket behavior. If a daemon is
running and is attached to a specific connection, when that socket is closed,
would it not then allow the daemon to close? And if a new connection is used,
that would cause a new copy of the daemon to run to bind to that connection,
right? That is not what I am seeing.

Maybe I'm understanding things wrong. If so please explain to me. But my
understanding is that when a daemon is listening to a port for connections, when
a new connection comes in it forks off a new copy of itself connected to that
connection. 

    
    

    
  
I'm just talking about what the imap code is seeing - when we cache a
connection, and then try to re-use it later, we ask the networking code if the
socket is still alive, in its estimation. In your case, I think the networking
code is telling us the socket is *not* alive. In this case, we don't send a DONE
to get out of IDLE, because our networking code tells us the socket is dead, so
sending DONE is pointless...

What's going on beyond that, I can't say. Routers and gateways could timeout
connections, I suppose, though normally it's firewalls that seem to do that.

    
    

    
  
I guess the point I'm trying to get at is that if the connection was dead, why
would the APPEND command go out on the same connection vs opening up a new
connection like it does when I restart the daemon, thus killing it's children
and therefore closing the connections they were holding open? When I get the
error and I restart the daemon, I see Thunderbird log in and then issue the
append command. But if I do not restart the daemon and only watch the process
that has that mailbox open, then I see traffic back and forth when I hit OK. Now
yes I understand that hitting OK re-issues the append request. But my point is
if Thunderbird thinks the connection is invalid, why isn't it disconnecting that
link (dispose of it from the cache?) and opening a new connection to the server?
Why is it continuing to send data on that connection?


    
    

    
  
Here's the relevant section of the log you sent, which I'm basing my comments
on. I don't see the client sending any APPEND command or data. Maybe you're
describing behaviour you didn't capture in a log?

2824[3b67e48]:
3b55240:venus.eglifamily.dnsalias.net:NA:ProcessCurrentURL:imap://dan%40frankenstein-cpu%2Ecom@venus.eglifamily.dnsalias.net:143/appendmsgfromfile%3E.INBOX.Sent:
 = currentUrl
2824[3b67e48]: ReadNextLine [stream=3b7be78 nb=0 needmore=1]
2824[3b67e48]: ReadNextLine [stream=3b7be78 nb=0 needmore=0]
2824[3b67e48]: 3b55240:venus.eglifamily.dnsalias.net:NA:CreateNewLineFromSocket:
clearing IMAP_CONNECTION_IS_OPEN - rv = 80470002
2824[3b67e48]: 3b55240:venus.eglifamily.dnsalias.net:NA:TellThreadToDie: close
socket connection
2824[3b67e48]: 3b55240:venus.eglifamily.dnsalias.net:NA:CreateNewLineFromSocket:
(null)
0[2744d8]: 3b83cb8:venus.eglifamily.dnsalias.net:NA:SetupWithUrl: clearing
IMAP_CONNECTION_IS_OPEN
1432[36f7920]: ImapThreadMainLoop entering [this=3b83cb8]
1432[36f7920]: 3b83cb8:venus.eglifamily.dnsalias.net:NA:ProcessCurrentURL: entering
1432[36f7920]:
3b83cb8:venus.eglifamily.dnsalias.net:NA:ProcessCurrentURL:imap://dan%40frankenstein-cpu%2Ecom@venus.eglifamily.dnsalias.net:143/appendmsgfromfile%3E.INBOX.Sent:
 = currentUrl
1432[36f7920]: ReadNextLine [stream=38f12a0 nb=0 needmore=1]
1432[36f7920]: ReadNextLine [stream=38f12a0 nb=0 needmore=0]
1432[36f7920]: 3b83cb8:venus.eglifamily.dnsalias.net:NA:CreateNewLineFromSocket:
clearing IMAP_CONNECTION_IS_OPEN - rv = 80470002
1432[36f7920]: 3b83cb8:venus.eglifamily.dnsalias.net:NA:TellThreadToDie: close
socket connection
1432[36f7920]: 3b83cb8:venus.eglifamily.dnsalias.net:NA:CreateNewLineFromSocket:
(null)
2824[3b67e48]: 3b55240:venus.eglifamily.dnsalias.net:NA:ProcessCurrentURL:
aborting queued urls
2824[3b67e48]: ImapThreadMainLoop leaving [this=3b55240]
1432[36f7920]: 3b83cb8:venus.eglifamily.dnsalias.net:NA:ProcessCurrentURL:
aborting queued urls
1432[36f7920]: ImapThreadMainLoop leaving [this=3b83cb8]
0[2744d8]: 22fbfc0:eglifamily.dnsalas.net:S-INBOX.Bugs:SendData: DONE

0[2744d8]: 22fbfc0:eglifamily.dnsalas.net:S-INBOX.Bugs:SendData:TellThreadToDie:
59 close

0[2744d8]: 22fbfc0:eglifamily.dnsalas.net:S-INBOX.Bugs:SendData:TellThreadToDie:
60 logout

0[2744d8]: 22fbfc0:eglifamily.dnsalas.net:S-INBOX.Bugs:TellThreadToDie: close
socket connection
0[2744d8]: 29f4f60:eglifamily.dnsalas.net:S-INBOX:SendData: DONE

0[2744d8]: 29f4f60:eglifamily.dnsalas.net:S-INBOX:SendData:TellThreadToDie: 22 close

0[2744d8]: 29f4f60:eglifamily.dnsalas.net:S-INBOX:SendData:TellThreadToDie: 23
logout

0[2744d8]: 29f4f60:eglifamily.dnsalas.net:S-INBOX:TellThreadToDie: close socket
connection
2804[2891428]: ImapThreadMainLoop leaving [this=29f4f60]
0[2744d8]: 2d1c1d8:venus.eglifamily.dnsalias.net:S-INBOX:SendData: DONE

0[2744d8]:
2d1c1d8:venus.eglifamily.dnsalias.net:S-INBOX:SendData:TellThreadToDie: 32 close

0[2744d8]:
2d1c1d8:venus.eglifamily.dnsalias.net:S-INBOX:SendData:TellThreadToDie: 33 logout

0[2744d8]: 2d1c1d8:venus.eglifamily.dnsalias.net:S-INBOX:TellThreadToDie: close
socket connection
3840[2d1cc10]: ImapThreadMainLoop leaving [this=2d1c1d8]
0[2744d8]: 2d2f830:venus.frankenstein-cpu.com:S-INBOX:SendData: DONE

0[2744d8]: 2d2f830:venus.frankenstein-cpu.com:S-INBOX:SendData:TellThreadToDie:
16 close

0[2744d8]: 2d2f830:venus.frankenstein-cpu.com:S-INBOX:SendData:TellThreadToDie:
17 logout

0[2744d8]: 2d2f830:venus.frankenstein-cpu.com:S-INBOX:TellThreadToDie: close
socket connection
3440[28916b8]: ImapThreadMainLoop leaving [this=22fbfc0]
3640[2891570]: ImapThreadMainLoop leaving [this=2d2f830]




    
    

    
  
I am describing behavior not there true. But either way, the same question still
stand. If Thunderbird thinks the connection is no longer valid, why is it still
using it instead of removing it and initiating a new connection? I can get a
strace to show you that the same daemon process is receiving data every time I
hit the OK button. And since Courier uses the fork() behavior I mentioned
before, then if the connection is destroyed the fork()'ed daemon should die.

    
    

    
  
sorry, looking in the log again, I was right the first time. It looks to me like
we are trying to create a new connection, and it gets established, and then the
courier server kicks us off. This is usually because we've exceeded the limit
allowed per ip address, which is 4 in some courier servers (we cache up to 5,
which is wny I suggested reducing that number to 4)

this is the new connection part:
0[2744d8]: 3b55240:venus.eglifamily.dnsalias.net:NA:SetupWithUrl: clearing
IMAP_CONNECTION_IS_OPEN


2824[3b67e48]: ImapThreadMainLoop entering [this=3b55240]
2824[3b67e48]: 3b55240:venus.eglifamily.dnsalias.net:NA:ProcessCurrentURL: entering
2824[3b67e48]:
3b55240:venus.eglifamily.dnsalias.net:NA:ProcessCurrentURL:imap://dan%40frankenstein-cpu%2Ecom@venus.eglifamily.dnsalias.net:143/appendmsgfromfile%3E.INBOX.Sent:
 = currentUrl
2824[3b67e48]: ReadNextLine [stream=3b7be78 nb=0 needmore=1]
2824[3b67e48]: ReadNextLine [stream=3b7be78 nb=0 needmore=0]

*************************************************************
here, we've established a connection, and then immediately get kicked off:

2824[3b67e48]: 3b55240:venus.eglifamily.dnsalias.net:NA:CreateNewLineFromSocket:
clearing IMAP_CONNECTION_IS_OPEN - rv = 80470002
2824[3b67e48]: 3b55240:venus.eglifamily.dnsalias.net:NA:TellThreadToDie: close
socket connection
2824[3b67e48]: 3b55240:venus.eglifamily.dnsalias.net:NA:CreateNewLineFromSocket:
(null)

Since I can't see all your log because of the empty parts, I can't tell how many
connections have been made, but I will tell you that every folder you click on,
we cache a new connection, so if you open four different folders, and then try
to send some mail, that will try to open a fifth connection.

    
    

    
  
Well It is most certainly not what you have been describing because I am getting
it now on thunderbird while directly connected to the server, going through
nothing more than a simple ethernet switch. It's happened twice, but of course I
did not remember to activate logging on my machine here. I'll activate logging
to see if it happens again sometime. In the mean time, I'm still thinking that
there is some kind of glitch in Thunderbird's networking code. After all the
question I asked has never been answered. If Thunderbird believes the connection
to be invalid, why does it not close the connection on this end, then re-open a
new connection?

    
    

    
  
if a tcp connection is dead, there's no reason or way to "close" it. We do open
a new one (or re-use an existing, cached one, more likely)

    
    

    
  
which is my whole point. If a TCP connection is dead, a new one should be
initiated, yes? Thunderbird ISN'T initiating a new connection, meerly re-using
the "dead" connection. If it's dead, how can it be re-used?



    
    

    
  
I'm not sure if this is what's happening to you (it's not what I see in your
log, but iirc, you haven't given me a log that corresponds to some of what
you've described, which leaves me at a distinct disadvantage :-( ) but sometimes
we can't tell that a connection is dead, because the other side hasn't ended the
connection - it has just died without cleaning up properly...in that case, we
try to re-run the url when it eventually fails because we have a cached
connection that turns out to be dead...

In either case, we do try to either open a new connection, or re-use an existing
connection. In other words, the code tries to do what you're describing. Why
it's not happening for you is a mystery. 

    
    

    
  
Well I'm at a loss too. I'd be happy to run some kind of debug version if it
would help. I love thunderbird and want to do whatever I can to make it better.
As it is I run with log level 5 on IMAP on both my laptop and my desktop at
home. The next time it happens at home I will post a log file here. In the mean
time, if you have any suggestions, ideas to try, or if you want to make a debug
version I'll be happy to do what ever I can.

    
    

    
  


  
this log fragment shows not only the same behavior occuring on the directly
connected machine, ruling out any idea of a router or gateway or anything
closing the connection, but shows that the connection is infact still valid
despite thunderbird thinking that the connection is not valid. This is shown by
the fact that towards the end of the file, we see where I had to restart
courier-imap to get the message to save to Sent, and we SEE the server saying
"BYE" and that it was shutdown by a signal.

    
    

    
  
It's getting worse. Lately 9 out of 10 messages fail to send till I restart the
imap server. Then THAT message gets saved fine, and future messages fail.
SOMETIMES I can get 2 or 3 in before it starts giving me the error again.

    
    

    
  
> we see where I had to restart
>courier-imap to get the message to save to Sent, and we SEE the server saying
>"BYE" and that it was shutdown by a signal.

I think you're getting the connections confused. In the log, you'll see us try
to use connection 976 to do the append, and find out it's not alive any more.

976[4271918]: 3c36d98:venus:NA:ProcessCurrentURL: entering
976[4271918]:
3c36d98:venus:NA:ProcessCurrentURL:imap://dan%40frankenstein-cpu%2Ecom@venus:143/appendmsgfromfile%3E.INBOX.Sent:
 = currentUrl
976[4271918]: ReadNextLine [stream=2c3b228 nb=0 needmore=0]
976[4271918]: 3c36d98:venus:NA:CreateNewLineFromSocket: clearing
IMAP_CONNECTION_IS_OPEN - rv = 80470002
976[4271918]: 3c36d98:venus:NA:TellThreadToDie: close socket connection
976[4271918]: 3c36d98:venus:NA:CreateNewLineFromSocket: (null)

then, when you kill the server, we see bye responses for connections 2288,1832,
and 2016 , but not 976, which is the connection we decided was dead. Also, not
908, which is weird if you really restarted the server.)

Did you ever humour me and try going into the advanced imap server settings and
limiting the number of cached connections that thunderbird will make to 4,
instead of the default 5?

    
    

    
  
I had set the limit from 5 to 4, but that didn't fix it. I had to turn it down
to 2 to fix it, and it seems this is a known problem on the courier list (why no
one told me before yesterday I don't know). Appearently, acording to the folks
on the Courier-imap list, Thunderbird does not properly handle a connection
denial. I don't have many more details than that at the moment, and am trying to
obtain more. However, it seems that this particular problem crops up every once
in a while on the courier list. Occasionally with the result of crashing the server.



    
    

    
  
This is an automated message, with ID "auto-resolve01".

This bug has had no comments for a long time. Statistically, we have found that
bug reports that have not been confirmed by a second user after three months are
highly unlikely to be the source of a fix to the code.

While your input is very important to us, our resources are limited and so we
are asking for your help in focussing our efforts. If you can still reproduce
this problem in the latest version of the product (see below for how to obtain a
copy) or, for feature requests, if it's not present in the latest version and
you still believe we should implement it, please visit the URL of this bug
(given at the top of this mail) and add a comment to that effect, giving more
reproduction information if you have it.

If it is not a problem any longer, you need take no action. If this bug is not
changed in any way in the next two weeks, it will be automatically resolved.
Thank you for your help in this matter.

The latest beta releases can be obtained from:
Firefox:     http://www.mozilla.org/projects/firefox/
Thunderbird: http://www.mozilla.org/products/thunderbird/releases/1.5beta1.html
Seamonkey:   http://www.mozilla.org/projects/seamonkey/


    
    

    
  
This bug has been automatically resolved after a period of inactivity (see above
comment). If anyone thinks this is incorrect, they should feel free to reopen it.
Status: UNCONFIRMED → RESOLVED
Closed: 19 years ago
Resolution: --- → EXPIRED

          You need to log in
          before you can comment on or make changes to this bug.
        






  

    
  







  

    

      
Attachment

      

      
      
      
      
    

    

      

        

          

            
General

            

              Creator: 



            

            
Created: 

            
Updated: 

            
Size: