383517 - Parallel retrieval (i.e. multiple accounts) of email for pop accounts fails with large numbers of messages - possible one stream which has not completed be closed by the other

Status: RESOLVED DUPLICATE of bug 707933

(MailNews Core :: Networking: POP, defect)

Description

[pseudo_daoist]

User-Agent:       Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.8.1.4) Gecko/20070515 Firefox/2.0.0.4 Mnenhy/0.7.5.666
Build Identifier: 

When there are three or more accounts each with more than 10K messages to retrieve, Thunderbird chokes up and does not retrieve any messages. [It just sits there using between 20% and 100% CPU.]

If accounts are deleted, then recreated, to emulate sequentially retrieval, all messages are retrieved.

Request:  Add a toggle to force sequential retrieval of email.



Reproducible: Always

Steps to Reproduce:
1.Configure Thunderbird to retrieve email from 3+ accounts;
2.Ensure that there are at least 10K messages in each account;
3.Start Thunderbird;
4. Watch it hum, without retrieving any email.
Actual Results:  
Thunderbird sits there until killed --- which can be between 4 and 24 hours later.

One then gets to manually emulate "forced sequential access".  No fun, if you dont' delete everything related to a specific mail account.

Expected Results:  
Unattended retrieval of email.

Give user the option to force sequential retrieval of email. Whilst slower, it is much more reliable, and will eventually retrieve all email. 

[The default for email retrieval can be left as parallel retrieval.]

Comment 1

[Steve Simms]

Are you still having this problem with the current version of Thunderbird?

Are the accounts POP or IMAP?

Comment 2

[pseudo_daoist]

Pop accounts.

Currently, I'm using a different email client for each account.

Comment 3

[pseudo_daoist]

I just tried it with OpenSolaris & Thunderbird version 2.0.0.16 (20080908).
I still have to baby sit Thunderbird, creating and deleting accounts manually, restarting Thunderbird each time, for it to more or less correctly retrieve email. More or less, because Thunderbird downloads the each message between two and five times.

All accounts on POP.

jonathon

Comment 4

[Wayne Mery (:wsmwk)]

(why is this in accounts?)

-> pop

Comment 5

[Martin Mokrejs]

I have myself only 2 POP3 accounts in use but one more without Automatic download of messages. I agree that mailer tries to download from both accounts simultaneously. I propose to introduce a check whether the target accounts are on a same host. If yes, download the second account after the first download finished. If they are located on different hosts, of course proceed in parallel.
happens with seamonkey-1.1.x and 2.0.4.

Comment 6

[Wayne Mery (:wsmwk)]

please create a pop log file and attach the file to this bug. Thanks
https://wiki.mozilla.org/MailNews:Logging

Comment 7

[Wayne Mery (:wsmwk)]

closing incomplete for lack of information. if you feel this change was made in error, please update the bug.

Comment 8

[Martin Mokrejs]

Attachment: pop3-masked-email.log

I had both pop3 accounts without any email, so you cannot probably see that the two pop3 connection could have overlapped each other in time. However, I wonder what those errors mean because both password I provided without typos, and mailer did not complain to me through GUI that either of them would be wrong. It looks mailer just needs to re-try for an unknown reason.

Comment 9

[Martin Mokrejs]

Attachment: pop3-fecthed_two_and_one_email.log

In this I fetched two email from account "user" and one from account "other". I hope you can see that the connection to account other should be only initiated after connection to "user" closed - because both accounts are hosted on a same server so no reason to have two concurrent connection fighting for the network bandwidth.

This was a pop3:5 log but filtered using "grep -v RECV". If you wanted another log-level or something from the RECV lines, please let me know.

Comment 10

[Martin Mokrejs]

The emails were sent and received by:

Mozilla/5.0 (X11; U; Linux i686; en-US; rv:1.9.1.11) Gecko/20100813 Gentoo/2.0.6 SeaMonkey/2.0.6

Comment 11

[Wayne Mery (:wsmwk)]

Preetham, Nikolay, your thoughts on this?

Comment 12

[Wayne Mery (:wsmwk)]

Martin, do you still see this issue?

Comment 13

[Martin Mokrejs]

(In reply to Wayne Mery (:wsmwk) from comment #12)
> Martin, do you still see this issue?

I just turned on the logging for my two pop3 accounts BUT on TWO DIFFERENT target servers. But, as this bug report is about serialization of pop3 connections, I am confirming this still DOES happen. And yes, automatically if two accounts have same target IP, the yet to be written serialization code should be enabled, so that the two connections do not compete for same bandwidth in parallel.

Would be nice if the pop3 log file at debug level 5 (https://wiki.mozilla.org/MailNews:Logging) recorded more clearly on each line what target IP:port is the line referring to.

Comment 14

[Martin Mokrejs]

(In reply to Martin Mokrejs from comment #13)

Forgot to say what I have at the moment:

Build identifier: Mozilla/5.0 (X11; Linux x86_64; rv:11.0) Gecko/20120319 Firefox/11.0 SeaMonkey/2.8

Comment 15

[Phoenix]

Removed closeme whiteboard, as reporter provided needed logs

Comment 16

[Wayne Mery (:wsmwk)]

Parkhideh, can you take a look at the protocol logs?

Comment 17

[Parkhideh]

(In reply to pseudo_daoist from comment #3)
> I just tried it with OpenSolaris & Thunderbird version 2.0.0.16 (20080908).
> I still have to baby sit Thunderbird, creating and deleting accounts
> manually, restarting Thunderbird each time, for it to more or less correctly
> retrieve email. More or less, because Thunderbird downloads the each message
> between two and five times.
> 
> All accounts on POP.
> 
> jonathon

Jonathon, it is seven years and 15 versions later;  but if you are still having this problem, there is a "simpler" workaround than shutting down the mail client.
1) In Server Settings check the "Check for new messages at startup" and "Check for new messages every ..."
2) Do not check the "Automatically download new messages" and "Fetch headers only"

      Now you will see in bold or colour when you have messages for each mail box.
  
3) Click on the arrow on the right hand side of "Get Mail" button (NOT the Get Mail button); a drop down list will show up and you can select which mail box.

It is not an ideal solution, but a better method than what you described as "restarting Thunderbird each time,".  In my work the only annoyance is at the startup.  That is when every mailbox has mail and I have to babysit it by clicking one at a time.  Later on it is not any trouble because one or two mailboxes will have mail at any given moment.

Comment 18

[Parkhideh]

(In reply to Wayne Mery (:wsmwk) from comment #16)
> Parkhideh, can you take a look at the protocol logs?

After cleaning the confusing state reports; what we get, and I do wish IP and process ID was logged (see comments 9 and 13, by Martin), is a sequence of actions that looks correct, but may be incorrect because we do not know on which thread or instance this has happened.

1- Clearly Authorization is sent for both accounts. Seq.# 6 & 12
2- Seq. 33 to 70 is done on USER "other"
3- Seq. 361 to 638 is done on USER "user" 
4- Now comes confusion:  Who is deleted in Seq. 674 ?
5- According to Martin, "user" has two e-mails; but I cannot tell that from the log.
6- So I venture a guess that the program is confused, like I, from Seq. 674 to 3684.
7- Working it backward from Seq. 3684 to 674 does clear up some confusion, only because we are told "user" had two e-mails.
8- Seq. 3684 to 2663 shows, bottoms up: Quit("user") / Dele 2(delete e-mail #2 "user") / Quit("other")
9- That leaves the two DELE 1 on Seq. 674 and 2655.  I like to think 674 is for "user" because a QUIT does not follow it and RETR 2 comes next.  But does it matter?  Only if I knew when the message stream is closed, I can answer that.

10- The potential problem that I see is where both streams are active, after seq. 638.  It is possible that the one which has not completed be closed by the other, through errors like looking for an IP instead of process or channel number (if the reported error here is unique to same server case).  It is also possible to incorrectly close the stream if reported error occurs in all cases of large e-mails and never on very short e-mails.

11- I find it odd that, from seq. 3701 to the end, only USER "other" is accessed and USER "user" is not.  This is possible if they have different time intervals for "Check for new messages every ...".  Or could it be that the process for USER "user" is waiting on a dead stream?

12- In conclusion if the log file shows release of the message stream (tell me if it is there and I have missed it) with the IP of the server plus id of the process; then two test logs would be very useful:
      a) Three e-mail boxes; two on the same server, one on a different one.
      b) Test one with several one line e-mails for all.
      c) Test two with several large e-mail files; I think 10K was suggested so lets go for 100K. :)

This is filtered from Martin's log:
Seq.#    Action
6	 SEND	 AUTH
12	 SEND	 AUTH
17	 SEND	 CAPA
22	 SEND	 CAPA
33	 SEND	 USER other
38	 Logging suppressed for this command (it probably contained authentication information)	
43	 SEND	 STAT
48	 SEND	 LIST
56	 SEND	 UIDL
65	 SEND	 RETR 1
69	 Opening message stream	 MSG_IncorporateBegin
70	 Done opening message stream!	
361	 SEND	 USER user
368	 Logging suppressed for this command (it probably contained authentication information)	
375	 SEND	 STAT
404	 SEND	 LIST
523	 SEND	 UIDL
601	 SEND	 RETR 1
637	 Opening message stream	 MSG_IncorporateBegin
638	 Done opening message stream!	
674	 SEND	 DELE 1
682	 SEND	 RETR 2
708	 Opening message stream	 MSG_IncorporateBegin
709	 Done opening message stream!	
2655	 SEND	 DELE 1
2663	 SEND	 QUIT
3678	 SEND	 DELE 2
3684	 SEND	 QUIT
3695	 SEND	 CAPA
3701	 SEND	 USER other
3706	 Logging suppressed for this command (it probably contained authentication information)	
3711	 SEND	 STAT
3716	 SEND	 QUIT
3727	 SEND	 CAPA
3733	 SEND	 USER other
3738	 Logging suppressed for this command (it probably contained authentication information)	
3743	 SEND	 STAT
3748	 SEND	 QUIT
3759	 SEND	 CAPA
3765	 SEND	 USER other
3770	 Logging suppressed for this command (it probably contained authentication information)	
3775	 SEND	 STAT
3780	 SEND	 QUIT
3791	 SEND	 CAPA
3797	 SEND	 USER other
3802	 Logging suppressed for this command (it probably contained authentication information)	
3807	 SEND	 STAT
3812	 SEND	 QUIT
3823	 SEND	 CAPA
3829	 SEND	 USER other
3834	 Logging suppressed for this command (it probably contained authentication information)	
3839	 SEND	 STAT
3844	 SEND	 QUIT

Comment 19

[Martin Mokrejs]

(In reply to Parkhideh from comment #18)
> (In reply to Wayne Mery (:wsmwk) from comment #16)
> > Parkhideh, can you take a look at the protocol logs?
> 
> After cleaning the confusing state reports; what we get, and I do wish IP
> and process ID was logged (see comments 9 and 13, by Martin), is a sequence
> of actions that looks correct, but may be incorrect because we do not know
> on which thread or instance this has happened.
> 
> 1- Clearly Authorization is sent for both accounts. Seq.# 6 & 12
> 2- Seq. 33 to 70 is done on USER "other"
> 3- Seq. 361 to 638 is done on USER "user" 
> 4- Now comes confusion:  Who is deleted in Seq. 674 ?
> 5- According to Martin, "user" has two e-mails; but I cannot tell that from
> the log.
> 6- So I venture a guess that the program is confused, like I, from Seq. 674
> to 3684.

This only underscores without a useful logs file format this is wasting our times. I will be guessing as well because I did the test 2 years ago.

First of all, the "Seq. 674." seems to be a line number in the second attachment (pop3-fecthed_two_and_one_email.log). 

> 7- Working it backward from Seq. 3684 to 674 does clear up some confusion,
> only because we are told "user" had two e-mails.
> 8- Seq. 3684 to 2663 shows, bottoms up: Quit("user") / Dele 2(delete e-mail
> #2 "user") / Quit("other")
> 9- That leaves the two DELE 1 on Seq. 674 and 2655.  I like to think 674 is
> for "user" because a QUIT does not follow it and RETR 2 comes next.  But
> does it matter?  Only if I knew when the message stream is closed, I can
> answer that.

I think your interpretation is right and I admire you have put so much effort into the old **** logs. Anyway, regarding your point 9 I also believe that "user" had one email and that the connection was meanwhile closed/blocked.

In general, when seamonkey stop automatically fetching emails into one of my accounts what helps to "fix" the broken state is to manually check via POP3 for new emails on some other/not-broken account (actually all my accounts use OPO3, only). This somehow flushes the states inside seamonkey and the blocked account can be after that also manually queried for new emails and since then, the automatic checks works again. So, let's conclude the "user" account went into this bad state and couldn't communicate anymore. In the partial test I did not rescue the account via manual POP3-fetches. That would make the logs only more complicated to interpret.

> 
> 10- The potential problem that I see is where both streams are active, after
> seq. 638.  It is possible that the one which has not completed be closed by
> the other, through errors like looking for an IP instead of process or
> channel number (if the reported error here is unique to same server case). 

Hmm, I used qmail pop3 daemon at that time on the server, I would hope it is using same meaningful error codes, from some RFC specs ...

I think I saw already in bugzilla some reports like this, that seamonkey mailer is mixing IP addresses and error codes together. :(

> It is also possible to incorrectly close the stream if reported error occurs
> in all cases of large e-mails and never on very short e-mails.

I think, in general, the accounts in seamonkey get blocked "randomly" and there does not even have to be an email in the target pop3 mailbox. It is my guess, though.

> 
> 11- I find it odd that, from seq. 3701 to the end, only USER "other" is
> accessed and USER "user" is not.  This is possible if they have different
> time intervals for "Check for new messages every ...".  Or could it be that
> the process for USER "user" is waiting on a dead stream?

Yes, I believe this was the case why I bothered to report the issue. Really, my accounts sometimes get blocked. I am not sure what timings I used two years ago on automated fetches, sorry. I used to have 1 minute vs. 2 minutes, later move d to 1 minute vs. 10 minute scenario. What was in action during the tests I really remember.

> 
> 12- In conclusion if the log file shows release of the message stream (tell
> me if it is there and I have missed it) with the IP of the server plus id of
> the process; then two test logs would be very useful:

I don't understand why you raise these questions here. If you wanted to say that it is a good idea to re-test after an improvement patch lands in the tree, then I could re-test. Sorry, meanwhile moved to a different pop3 server but maybe can reproduce the issues anyway. Dunno.

>       a) Three e-mail boxes; two on the same server, one on a different one.
>       b) Test one with several one line e-mails for all.
>       c) Test two with several large e-mail files; I think 10K was suggested
> so lets go for 100K. :)
> 
> This is filtered from Martin's log:
> Seq.#    Action
> 6	 SEND	 AUTH
> 12	 SEND	 AUTH
> 17	 SEND	 CAPA
> 22	 SEND	 CAPA
> 33	 SEND	 USER other
> 38	 Logging suppressed for this command (it probably contained
> authentication information)	
> 43	 SEND	 STAT
> 48	 SEND	 LIST
> 56	 SEND	 UIDL
> 65	 SEND	 RETR 1
> 69	 Opening message stream	 MSG_IncorporateBegin
> 70	 Done opening message stream!	
> 361	 SEND	 USER user
> 368	 Logging suppressed for this command (it probably contained
> authentication information)	
> 375	 SEND	 STAT
> 404	 SEND	 LIST
> 523	 SEND	 UIDL
> 601	 SEND	 RETR 1
> 637	 Opening message stream	 MSG_IncorporateBegin
> 638	 Done opening message stream!	
> 674	 SEND	 DELE 1
> 682	 SEND	 RETR 2
> 708	 Opening message stream	 MSG_IncorporateBegin
> 709	 Done opening message stream!	
> 2655	 SEND	 DELE 1
> 2663	 SEND	 QUIT
> 3678	 SEND	 DELE 2
> 3684	 SEND	 QUIT
> 3695	 SEND	 CAPA
> 3701	 SEND	 USER other
> 3706	 Logging suppressed for this command (it probably contained
> authentication information)	
> 3711	 SEND	 STAT
> 3716	 SEND	 QUIT
> 3727	 SEND	 CAPA
> 3733	 SEND	 USER other
> 3738	 Logging suppressed for this command (it probably contained
> authentication information)	
> 3743	 SEND	 STAT
> 3748	 SEND	 QUIT
> 3759	 SEND	 CAPA
> 3765	 SEND	 USER other
> 3770	 Logging suppressed for this command (it probably contained
> authentication information)	
> 3775	 SEND	 STAT
> 3780	 SEND	 QUIT
> 3791	 SEND	 CAPA
> 3797	 SEND	 USER other
> 3802	 Logging suppressed for this command (it probably contained
> authentication information)	
> 3807	 SEND	 STAT
> 3812	 SEND	 QUIT
> 3823	 SEND	 CAPA
> 3829	 SEND	 USER other
> 3834	 Logging suppressed for this command (it probably contained
> authentication information)	
> 3839	 SEND	 STAT
> 3844	 SEND	 QUIT


BTW, have you seen the DOS-line endings in the file? I use vim editor and it displays them as ^M .

Comment 20

[Parkhideh]

(In reply to Martin Mokrejs from comment #19)
I recommend all to read comments 182 to 206 of bug 419009;  it is a fun read when in good humour.**

Martin, I comment and reply in order of priority:

> 
> BTW, have you seen the DOS-line endings in the file? I use vim editor and it
> displays them as ^M .

- Your line endings are ^M ^J pair  (CrLf); but this could be the work of the downloader.


> (In reply to Parkhideh from comment #18)
> > (In reply to Wayne Mery (:wsmwk) from comment #16)
> > > Parkhideh, can you take a look at the protocol logs?
> > 

- I too am a draftee and not a volunteer.  Wayne every now and then does it to me to keep up my blood pressure.  :)


> > 12- In conclusion if the log file shows release of the message stream (tell
> > me if it is there and I have missed it) with the IP of the server plus id of
> > the process; then two test logs would be very useful:
> 
> I don't understand why you raise these questions here. If you wanted to say
> that it is a good idea to re-test after an improvement patch lands in the
> tree, then I could re-test. Sorry, meanwhile moved to a different pop3
> server but maybe can reproduce the issues anyway. Dunno.

- First, I was very deliberate in not asking you for more log files.  We both know that the logger has to provide more useful information before anyone wastes more time on its output.
- Isn't in funny that we all move away from Mozilla.  It is as if the developers are paid by the competition to shoe off the die hard.  I wonder who foots the bill?
- Why did I ask and set the test condition?  Because deep down I too hope for a caring professional to show up, and I wanted to document what I will not remember in ten years.  And that date is not an exaggeration, neither in my remembering nor in someone showing up sooner. :)

Finally a comment, 
  a) lets remember that in comment 17 to Jonathon, my method of avoiding the trap is outlined.  I have used it for the past 13 years on PC; and have avoided all things Mozilla on Mobile.

  b) a little pow wow among us who see Bugzilla as a placebo and not a professional forum:
     Why would anyone program the e-mail download in parallel threads?
     i) If client is connected via a dialup, as I am, then the limitation is in Client to ISP link.  Parallel download does no good.
     ii) If client is on high speed LAN to the server, then the bottle neck is on server's disk access.  In real time 8 milli-seconds of seek time.  Does it really matter?  The reader has to read the first e-mail, in seconds or minutes, if hundreds of these 8 milliseconds delays occur before next e-mail is available, who cares?
     iii) If we were on token ring, with some certainty I could make this example, have three e-mail accounts, first two have a mail of 10 M byte and the last just a few bytes; then parallel process could have delivered the third one well before the other two, assuming Mozillans know how to use the tokens.  But on Ethernet, it is a big maybe.  Maybe the short one shows up before others or maybe it shows up after.  So what is to be gained by the complexity of this download procedure?
[Would it not be funny if they have placed a scheduler blocking the threads and that is the reason for all this mess.  I am not making this up; it happened, and it is still there in bug 413165 with two threads.*]

     Now this is not for you Martin but for that imaginary professional; Dear comrade, do not touch the code except to disable the parallel process, or limiting it to a process of ONE.  I have tested the system through comment 17 and guarantee that a single process has worked well.  Since nothing is to be gained by us mortals, please do no more than what is asked.  I give the credit to Jonathon for asking for it in the original description; but expand the request for all cases.

Wayne, 
    Now would you be kind enough to release me?  :)

**  for you this read is compulsory before reading the next lines.  :)

* and what is happening with my proposal for bug 413165 ?  A professional forum would have either accepted and implemented it or pointed out the deficiencies of the proposal.  Silence is a form of an insult, if I thought better of them.  :)

Comment 21

[Wayne Mery (:wsmwk)]

Parkhideh, thanks for looking at this!  After this, yes, you are released :)

So the decision here about steps to reproduce is that:
1. this does NOT require Global Inbox to be enabled?
2. this requires least two pop accounts on the same server?

Does it *require* both "Automatically download new messages" and "Fetch headers only"?
Or is the comment about "Fetch headers only" just general advice because it causes numerous problems?  (which I don't disagree with)

And is there anything else to add to STR?



(In reply to Parkhideh from comment #20)
>...
> Wayne, 
>     Now would you be kind enough to release me?  :)
> 
> **  for you this read is compulsory before reading the next lines.  :)
> 
> * and what is happening with my proposal for bug 413165 ? 

If you are asking for a technical assessment it's beyond my skill level.

> A professional
> forum would have either accepted and implemented it or pointed out the
> deficiencies of the proposal.  Silence is a form of an insult, if I thought
> better of them.  :)

It is not an insult. There is no longer a "key" imap developers actively watching. And many cc on the bug are busy working on various other bits in Thunderbird.

If your proposal is something you'd like wada to comment on, then using "needinfo" is the new way to get someone's attention.

Comment 22

[Phoenix]

Hi Jonathon, do you still see this problem?

Comment 23

[Phoenix]

Resolved per whiteboard

Comment 24

[pseudo_daoist]

My impression was that this bug report had been closed with "Won't Fix", or something similar back in 2009.  

In personal emails with Thunderbird developers, I was advised that inasmuch as Thunderbird was _NOT_ an e-mail client, expecting Thunderbird to retrieve email was expecting the program to do something that it _was not designed to do_. 

FWIW, this specific bug report is what convinced me that filing bug reports for FLOSS was a complete, utter, and absolute waste of my time, energy, and effort.

Comment 25

[Wayne Mery (:wsmwk)]

Perhaps more than anything this bug highlights that some areas of Thunderbird pop are fragile, i.e. it is not without bugs. 

On the other hand, I think it would be a rare occurence than anyone would have ~10k messages in their pop account. (Or at least, they shouldn't have that much if they care about pop performance)


(In reply to pseudo_daoist from comment #24)
> My impression was that this bug report had been closed with "Won't Fix", or
> something similar back in 2009.  

There was only one inconsequential comment in 2009


(In reply to Martin Mokrejs from comment #13)
> ...
> Would be nice if the pop3 log file at debug level 5
> (https://wiki.mozilla.org/MailNews:Logging) recorded more clearly on each
> line what target IP:port is the line referring to.

this is bug 1075149


> In personal emails with Thunderbird developers, I was advised that inasmuch as Thunderbird was _NOT_ 
> an e-mail client, expecting Thunderbird to retrieve email was expecting the program to do something 
> that it _was not designed to do_. 

I don't think there is a developer comment here that suggests this. (Which is not saying it should, only that there is a lack of information or accurate citation of the design goals or code)

Comment 26

[Ludovic Hirlimann [:Usul]]

Removing myslef on all the bugs I'm cced on. Please NI me if you need something on MailNews Core bugs from me.

Comment 27

[Wayne Mery (:wsmwk)]

I don't know whether this still exists, but I tried anyway to find (possibly) obvoiusly related bug reports and didn't come up with much, just bug 929281

Note bug 1075149 which improves pop logging was fixed in version 45

Comment 28

[Wayne Mery (:wsmwk)]

All the reporters are gone. Seems like anything still remaining today would be covered by bug 707933