450128 - Imap connection "spam" makes client "unresponsive", executing same command over and over

Status: RESOLVED INVALID

(MailNews Core :: Networking: IMAP, defect)

Description

[Felix]

User-Agent:       Mozilla/5.0 (Windows; U; Windows NT 5.1; en-GB; rv:1.9.0.1) Gecko/2008070208 Firefox/3.0.1
Build Identifier: version 2.0.0.16 (20080708)

some background on my last 3 posts on the forums
http://forums.mozillazine.org/search.php?search_id=egosearch

in a nutshell: TB on IMAP behaves weird (pardon me):

- previously downloaded messages disappear and reappear after restart
- commands such as move to folder, load message, any interaction with the server just don't happen
- TB can get hung in task manager even after exiting

it seems to be because of some connection spam issue where TB starts executing the same command over and over, like 200k times in a very short time until I restart it. 

wireshark log below


Reproducible: Always

Steps to Reproduce:
1. start my TB
2. wait from 2 minutes to 2 days
3. TB gets unresponsive, wireshark shows the above, and then I restart TB until it happens again

not a good description I know,happy to provide any insight on my system, please ask. have the exact same setup on a laptop, no issues there AFAICT. new office PC, no fun. 
Actual Results:  
TB gets "unresponsive"

Expected Results:  
it stays responsive, sorry no more detail on this. 


 232510 30404.185215         IMAP     Request: 75123 UID fetch 79350 (UID RFC822.SIZE BODY.PEEK[])
 232511 30404.189065         IMAP     Response: 75123 OK FETCH completed.
 232512 30404.189210         IMAP     Request: 75124 UID fetch 79350 (UID RFC822.SIZE BODY.PEEK[])
 232513 30404.192757         IMAP     Response: 75124 OK FETCH completed.
 232514 30404.192903         IMAP     Request: 75125 UID fetch 79350 (UID RFC822.SIZE BODY.PEEK[])
 232515 30404.196967         IMAP     Response: 75125 OK FETCH completed.
 232516 30404.197102         IMAP     Request: 75126 UID fetch 79350 (UID RFC822.SIZE BODY.PEEK[])
 232517 30404.200553         IMAP     Response: 75126 OK FETCH completed.
 232518 30404.200716         IMAP     Request: 75127 UID fetch 79350 (UID RFC822.SIZE BODY.PEEK[])
 232519 30404.204300         IMAP     Response: 75127 OK FETCH completed.
 232520 30404.204433         IMAP     Request: 75128 UID fetch 79350 (UID RFC822.SIZE BODY.PEEK[])
 232521 30404.208466         IMAP     Response: 75128 OK FETCH completed.
 232522 30404.208680         IMAP     Request: 75129 UID fetch 79350 (UID RFC822.SIZE BODY.PEEK[])
 232523 30404.220591         IMAP     Response: 75129 OK FETCH completed.
 232524 30404.220705         IMAP     Request: 75130 UID fetch 79350 (UID RFC822.SIZE BODY.PEEK[])
 232525 30404.224371         IMAP     Response: 75130 OK FETCH completed.
 232526 30404.224509         IMAP     Request: 75131 UID fetch 79350 (UID RFC822.SIZE BODY.PEEK[])
 232527 30404.227790         IMAP     Response: 75131 OK FETCH completed.
 232528 30404.227922         IMAP     Request: 75132 UID fetch 79350 (UID RFC822.SIZE BODY.PEEK[])
 232529 30404.232073         IMAP     Response: 75132 OK FETCH completed.

happy to provide more detail on this, a lot in the forum posts too. did not get any answers on the forums. I have a lot of patience to supply data points to please ask.

Comment 1

[WADA:World Anti-bad-Duping Agency]

> 2. wait from 2 minutes to 2 days
> 3. TB gets unresponsive

Is DHCP is used for PC's IP address determination? Address change by DHCP(due to expiration) occurred during the "from 2 minutes to 2 days"?

> 3. TB gets unresponsive
> - TB can get hung in task manager even after exiting

Other report says that lack of one loopback connection of loopback connection pair was observed when above combination occured.
When problem occurs, what does "NETSTAT -b -o" say?

> Example of NETSTAT -b -o 
>(1st pair)
> 1-a) TCP HP-Note-PC:3229 localhost:3230 ESTABLISHED 6028 [thunderbird.exe]
> 1-b) TCP HP-Note-PC:3230 localhost:3229 ESTABLISHED 6028 [thunderbird.exe] 
>(2nd pair)
> 2-a) TCP HP-Note-PC:3231 localhost:3232 ESTABLISHED 6028 [thunderbird.exe]
> 2-b) TCP HP-Note-PC:3232 localhost:3231 ESTABLISHED 6028 [thunderbird.exe]

Comment 2

[Felix]

bug made a no show today so faron my main machine, will run netstat when it does. 

occured on my laptop though same setup, thought that machine was safe, it reolved itself after a while (20mintues? i was in a meeting)

both on DHCP yes. will do netstat when I catch it. 

Comment 3

[Felix]

here is netstat I replaced IP_ADDRESS. I just let this run for a few seconds. how can I get timestamps on this?

Proto  Local Address          Foreign Address        State           PID
TCP    THEOVERMIND:3179       IP_ADDRESS:imap      ESTABLISHED     2680
  [thunderbird.exe]

 TCP    THEOVERMIND:3175       localhost:3176         ESTABLISHED     2680
  [thunderbird.exe]

  TCP    THEOVERMIND:3176       localhost:3175         ESTABLISHED     2680
  [thunderbird.exe]

  TCP    THEOVERMIND:3177       localhost:3178         ESTABLISHED     2680
  [thunderbird.exe]

  TCP    THEOVERMIND:3178       localhost:3177         ESTABLISHED     2680
  [thunderbird.exe]

  TCP    THEOVERMIND:3255       IP_ADDRESS:imap      CLOSE_WAIT      2680
  [thunderbird.exe]

  TCP    THEOVERMIND:3333       IP_ADDRESS:imap      CLOSE_WAIT      2680
  [thunderbird.exe]

wow. wireshark is already on 1m+ packets in 45 minutes. started at ~100k packets at 67572 seconds now at 1.1m 70297 seconds. 

Comment 4

[Felix]

ran it again as I realized it finishes itself, so maybeI missed something:

 Proto  Local Address          Foreign Address        State           PID
 TCP    THEOVERMIND:3179       IP_ADDRESS:imap      ESTABLISHED     2680
 [thunderbird.exe]
 TCP    THEOVERMIND:3175       localhost:3176         ESTABLISHED     2680
 [thunderbird.exe]
 TCP    THEOVERMIND:3176       localhost:3175         ESTABLISHED     2680
 [thunderbird.exe]
 TCP    THEOVERMIND:3177       localhost:3178         ESTABLISHED     2680
 [thunderbird.exe]
 TCP    THEOVERMIND:3178       localhost:3177         ESTABLISHED     2680
 [thunderbird.exe]
 TCP    THEOVERMIND:3255       IP_ADDRESS:imap      CLOSE_WAIT      2680
 [thunderbird.exe]
 TCP    THEOVERMIND:3333       IP_ADDRESS:imap      CLOSE_WAIT      2680
 [thunderbird.exe]

cool wireshark just ran out of memory ;-)

Comment 5

[Felix]

BTW, TB shows the hourglass cursor, will restart it now. I bet this comes back.

also not sure I mentioned this properly, the main performance issue other than this is that messages keep disappearing during sessions. and I have to restart TB for them to be downloaded "again", then they appear starred as NEW even on a previous day. 

Comment 6

[WADA:World Anti-bad-Duping Agency]

(In reply to comment #3)
> TCP THEOVERMIND:3255 IP_ADDRESS:imap CLOSE_WAIT 2680 [thunderbird.exe]
> TCP THEOVERMIND:3333 IP_ADDRESS:imap CLOSE_WAIT 2680 [thunderbird.exe]
(In reply to comment #4)
> TCP THEOVERMIND:3255 IP_ADDRESS:imap CLOSE_WAIT 2680 [thunderbird.exe]
> TCP THEOVERMIND:3333 IP_ADDRESS:imap CLOSE_WAIT 2680 [thunderbird.exe]

There is no loss of a loopback connection of loopback connection pair.
But CLOSE_WAIT status for connection with IMAP is seen.
It looks for me that hang or wait while connection termination upon Resume.
Get Tb's IMAP protocol log, and check IMAP flow during Suspend/Resume. 
See Bug 402793 Comment #1 for getting log.
See http://www.faqs.org/rfcs/rfc3501.html for IMAP command/response. 

Comment 7

[Felix]

hey there, been tryin session logging before, can't get it to work. here is my .bat file which launches TB but writes no log. have also tried non-clever log naming ones that also wrote no log. 

set mydate=%date:~-4,4%%date:~-7,2%%date:~-10,2%
set mytime=%time:~0,2%%time:~+3,2%

set NSPR_LOG_FILE=c:\thunderbird_%mydate%_%mytime%.log

setenv NSPR_LOG_MODULES imap:5
SET    NSPR_LOG_MODULES=imap:5
setenv NSPR_LOG_MODULES imap:5,smtp:5
SET    NSPR_LOG_MODULES=imap:5,smtp:5

start /d "c:\program files\mozilla thunderbird" thunderbird.exe


need to figure out how to make that work first. 

Comment 8

[Roberto Colmegna]

I have similar behavior. Sometimes I receive spam in mbox; when TB (2.0.0.19)
retrieve the BODY of the messages from the mailbox i note that
1) it receive some bodies (it's all OK)
2) it receive the spam body
3) it receive another NON-spam body and the client drop the connection

Note: if there isn't NON-spam AFTER spam the client sent a LOGOUT command (not
sent if there isn't spam in INBOX)

Sniffing the network level I notice that, in the third case, client send to the server a TCP/RESET packet (ie: isn't the server which drop the connection).

Comment 9

[Roberto Colmegna]

debug relative to comment #8:

-----
<snip>
3920[25bcf70]: ReadNextLine [stream=24ca100 nb=10 needmore=0]
3920[25bcf70]: 25b6410:127.0.0.1:S-INBOX:CreateNewLineFromSocket: </table>

3920[25bcf70]: ReadNextLine [stream=24ca100 nb=16 needmore=0]
3920[25bcf70]: 25b6410:127.0.0.1:S-INBOX:CreateNewLineFromSocket: </BODY></HTML>

3920[25bcf70]: 25b6410:127.0.0.1:S-INBOX:STREAM:CLOSE: Normal Message End Download Stream
3920[25bcf70]: 25b6410:127.0.0.1:S-INBOX:PARSER:Internal Syntax Error on line: %s: </BODY></HTML>

3920[25bcf70]: 25b6410:127.0.0.1:S-INBOX:SendData: 8 logout

3920[25bcf70]: ReadNextLine [stream=24ca100 nb=16 needmore=0]
3920[25bcf70]: 25b6410:127.0.0.1:S-INBOX:CreateNewLineFromSocket: </BODY></HTML>

3920[25bcf70]: 25b6410:127.0.0.1:S-INBOX:STREAM:CLOSE: Normal Message End Download Stream
3920[25bcf70]: 25b6410:127.0.0.1:S-INBOX:PARSER:Internal Syntax Error on line: %s: </BODY></HTML>

3920[25bcf70]: 25b6410:127.0.0.1:S-INBOX:SendData: 8 logout

3920[25bcf70]: ReadNextLine [stream=24ca100 nb=57 needmore=0]
3920[25bcf70]: 25b6410:127.0.0.1:S-INBOX:CreateNewLineFromSocket: )* 87 FETCH (UID 90581 RFC822.SIZE 42331 BODY[] {42331}

3920[25bcf70]: 25b6410:127.0.0.1:NA:TellThreadToDie: close socket connection
3920[25bcf70]: ImapThreadMainLoop leaving [this=25b6410]

----

Comment 10

[Wayne Mery (:wsmwk)]

Roberto, felix, do you see this issue when using version 3?

Comment 11

[Wayne Mery (:wsmwk)]

(felix's email address is dead - so we might not hear back from him)

Comment 12

[Roberto Colmegna]

In my case it was appears due to a bugged reply of IMAP-server (inconsistent message returned on FETCH due to wrong spam format) which produce a 
misbehavior on TB-side.

Comment 13

[WADA:World Anti-bad-Duping Agency]

(In reply to comment #12)
> which produce a misbehavior on TB-side.

It can't be said "misbehavior on TB-side".
1. Server returned </table> and indicator of "end of data"
   => STREAM:CLOSE: Normal Message End Download Stream
2. As indicator of "end of data" is received, Tb tries to check return code.
      OK: ..., NO: ..., BAD: ...
   However, server continued to send mail data of </BODY></HTML>.  
   => PARSER:Internal Syntax Error on line: %s: </BODY></HTML>
3. Tb sent "logout", because something wrong at server was detected.
4. Because server is still mail data send mode or status send mode,
   sever still returned </BODY></HTML>, * 87 FETCH, etc.
   "SendData: 8 logout" is seen twice. It looks retry of "logout".
5. Finally, connection was closed by Tb or server. (probably by Tb, as you say)
   => TellThreadToDie: close socket connection

If infinite loop of "sending logout" by Tb occurs in this case, it can be said "misbehavior on TB-side". If too many retries of "sending logout" instead of infinite retry loop, it can be said "bad behaviour of Tb", and it is better to be improved.
Did infinite loop of "sending logout" by Tb occur?

Following is sample flow in RFC 3501.
> http://tools.ietf.org/html/rfc3501#section-8
> C:    a004 fetch 12 body[header]
> S:    * 12 FETCH (BODY[HEADER] {342}
> S:    Date: Wed, 17 Jul 1996 02:23:25 -0700 (PDT)
>(snip)
> S:    Content-Type: TEXT/PLAIN; CHARSET=US-ASCII
> S:
> S:    )
> S:    a004 OK FETCH completed
I guess server returned 0x00(NULL) in the spam mail.

Comment 14

[Wayne Mery (:wsmwk)]

wada, so this is confirmable?

felix, I removed the mozillazine link http://forums.mozillazine.org/search.php?search_id=egosearch because it depends on being logged in to *your* mz account. are you felix200?

Comment 15

[Wayne Mery (:wsmwk)]

invalid per comment 12 (unless wada disagrees)