Closed Bug 466933 Opened 16 years ago Closed 14 years ago

Error with "Get Mail" or "Get all Messages" after resuming from computer's sleep mode - "This folder is being processed. Please wait until processing is complete to get messages" [pop]

Categories

(Thunderbird :: Mail Window Front End, defect)

Product:
Thunderbird
Component:
Mail Window Front End
Type:
defect
Priority:
Not set
Severity:
major

Tracking

(blocking-thunderbird3.1 -, thunderbird3.1 rc1-fixed)

Status:
RESOLVED FIXED
Tracking Flags:
Tracking Status
blocking-thunderbird3.1 --- -
thunderbird3.1 --- rc1-fixed

People

(Reporter: mitra_lists, Assigned: Bienvenu)

References

(
URL
)

Details

(Whiteboard: [duptome][gs])

Attachments

(3 files, 2 obsolete files)

tail pf Pop log
88.59 KB, text/plain
Details
log about server busy, and fix one case where it could get stale
6.31 KB, patch
Details | Diff | Splinter Review
fix for test case
9.50 KB, patch
standard8
: review+
standard8
: superreview+
standard8
: approval-thunderbird3.1+
Details | Diff | Splinter Review 
User-Agent:       Mozilla/5.0 (Macintosh; U; Intel Mac OS X 10.5; en-GB; rv:1.9.0.4) Gecko/2008102920 Firefox/3.0.4
Build Identifier: Mozilla/5.0 (Macintosh; U; Intel Mac OS X 10.5; en-US; rv:1.9.1b2pre) Gecko/20081125 Shredder/3.0b1pre

After I resume from sleep, I frequently get a "This Folder is being processed". Sometimes it is on one account, sometimes on multiple. In all cases the message appears when you click "Get mail" or "Get All Mail" and the problem doesn't go away, i.e. it does not appear that some background task is happening and just not appearing in the status bar.  

In all cases restarting Shredder clears the problem.

Reproducible: Sometimes

Steps to Reproduce:
1.Put computer to sleep ; bring back
2.Click Get Mail
3.
Actual Results:  
Folder is being processd message

Expected Results:  
Getting mail 

I don't believe this is the same problem as Bug 436939 (a bad UI choice imho), nor with 152675 (something internal). They all have distinctly different symptoms though I guess its possible they have the same internal cause.
when it goes to sleep, is thunderbird going offline?
at the point where I click on "Get All Mail" it is certainly online, and I have not manually set it back to online.

So it doesn't appear to (unless it goes offline, and comes back online when it wakes up before the windows are shown) 

- Mitra
Depends on: 471077
Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.1pre) Gecko/20090627 Shredder/3.0b3pre

With the above nightly, I got the error message "This folder is being processed" after resuming from sleep mode. However, that might be coincidence, so I'm not sure if that's enough to confirm this bug. As described in comment #0, only after restarting TB you can get messages again. Going online and offline in TB (click in lower-left corner) doesn't help either.

I made the following interesting observation:
When this happens, not all mail accounts are affected.
All of those accounts which toss the error message have "Check for new messages every 10 minutes" checked in the account settings (and "check for new messages at startup" mostly unchecked, but not all of them). At the same time, some other accounts successfully fetched new messages when I pressed F5 to "Get mail". MOST of the succeeding ones did NOT have "Check for new messages every 10 minutes" checked (nor "check for new messages at startup"). Unfortunately, there's one account that breaks the rule, and asked me for a password even though it DID have "check for new messages every 10 minutes" checked. Strangely, it's just the account for which I have forgotten the password, and, more strangely, in normal operation it has never asked me for a password although it's supposed to check every 10 mins for new mail. I leave it to you to draw conclusions. With my very limited knowledge on this, I do suspect that automatical getting of mails every x mins might have an influence on this bug. Maybe automatic fetching is interrupted somehow (e.g. by sleep mode) and that causes the bug.
Summary: After sleep - Folder is being processed → Error with "Get Mail" or "Get all Messages" after resuming from computer's sleep mode - "This folder is being processed. Please wait until processing is complete to get messages"
Another observation was that while this bug was happening, Thunderbird help menu showed "Downloading Shredder 3.0b3pre" with the rotating dots (what's the term again?), and never finished with that download.
FTR, that's the throbber
I am now regularly getting this after resuming from computer's sleep mode - therefore, I think this bug has the best summary and we should try clear up and dupe similar bugs against this.

(In reply to comment #5)
The throbber was incidental and does not appear to be connected with this bug. Although, perhaps someone could double-check how automatical updates interact with online/offline states and sleep mode.
Status: UNCONFIRMED → NEW
Ever confirmed: true
(In reply to comment #7)
> I am now regularly getting this after resuming from computer's sleep mode -
Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.3a1pre) Gecko/20090912 Shredder/3.1a1pre
Severity: normal → major
OS: Mac OS X → All
Hardware: PowerPC → All
Version: unspecified → Trunk
(In reply to comment #0)
> Reproducible: Sometimes
> Steps to Reproduce:
> 1.Put computer to sleep ; bring back
> 2.Click Get Mail
> Actual Results:  
> Folder is being processed message

It sounds that similar situation to Bug 323520(connection error while RETR) happened at step 1.

To Mitra Ardron(bug opener) and Thomas D.:

Can you get POP3 log(or IMAP log if IMAP) with timestamp for first screening of problem?
> NSPR logging on Mac OS X : http://www.mozilla.org/projects/netlib/http/http-debugging.html
> Get POP3 log : https://wiki.mozilla.org/MailNews:Logging
> Timestamp of NSPR log : See Bug 402793 Comment #17
> POP3 connection state : http://kb.mozillazine.org/Session_logging_for_mail/news
> POP3 command : http://tools.ietf.org/html/rfc1939
Attach log file to this bug via "Add an attachment" link of this bug. Never paste long data to bug, please.
I haven't seen this bug for a long time.
Thanks, Wada, for looking into this and providing the information about logging, including the timestamp, which is available both in the 1.9.1 Branch (3.0x) and in Trunk (3.1x).

I have both branch and trunk set up with logging and timestamp, so the trap is set and now I'm waiting for the bug to return. Of course, when you want it, it doesn't come. Also I haven't been able to reproduce it by initiating computer's sleep mode manually. Which points to the fact that some sort of automatical checking or downloading of mails must get collide with sleepmode or get confused in the resume phase. I'll let you when I see the bug again. I saw it this morning, but I didn't have logging activated.
This bug has started appearing again, regularly - quite frequently after resuming from sleep. 

I notice there is nothing in the Status line - but then the status line is pretty useless for telling you what is going on anyway - especially if you've got multiple accounts. 

Comment #10 doesn't help the "POP3 log" documentation talks about how to get an IMAP log.  I'm on a Mac, and all the accounts are POP3, what exactly do you want me to do.
(In reply to comment #13)
> the "POP3 log" documentation talks about how to get an IMAP log. 

MailNews:Logging says;
> Main Logging options within MailNews
>    * mime
>    * imap
>    * nntp
>    * smtp
>    * pop3
>    * ldap 
And presented examples to readers.
> Environment Variables to set
>   1. NSPR_LOG_MODULES - Module name and level separated by colon
>          * Example: "imap:5"
>          * Example: "ldap:5,smtp:3" 
I believe readers ordinally can understand that "pop3:5" is for POP3 and "pop3:5,imap3:5" is for POP3 & IMAP by these examples.

> I'm on a Mac, (snip)

You can't find description about "how to get NSPR log on Mac OS X"?
There is no instruction for Mac OS X users in MailNews:Logging.
Read "OSX" section in http-debugging.html which I pointed with "NSPR logging on Mac OS X", please.
Mitra follow these :

close thunderbird

Open a terminal.app and type on three different lines :
export NSPR_LOG_MODULES=pop:5,timestamp
export NSPR_LOG_FILE=pop.log
/Applications/Thunderbird.app/Contents/MacOS/thunderbird-bin &

this should create a pop.log file in your home diretory.
(In reply to comment #15)
> Mitra follow these :
> 
> close thunderbird
> 
> Open a terminal.app and type on three different lines :
> export NSPR_LOG_MODULES=pop:5,timestamp

needs to be =pop3
Ok - since the 23rd I've been running it from the shell, with the log, and of course :-) now I'm not seeing the problem. 

- Mitra
Attached file tail pf Pop log — 
Ok - woke the computer from sleep after a night's rest ... and it gave me this error, attachment is the last 1000 lines of the log (I can send more if its needed).
Whiteboard: [has protocol log]
Attachment #405125 - Attachment mime type: application/octet-stream → text/plain
(In reply to comment #19)
> *** Bug 152675 has been marked as a duplicate of this bug. ***

See bug 152675 comment 96 for explanation in what way bug 152675 is a duplicate.
(In reply to comment #18)
> tail pf Pop log 
> attachment is the last 1000 lines of the log (I can send more if its needed).

POP3 download itself is very normal in the attached log.
  Single mail arrives, RETR it, DLET it, then QUIT.

> Ok - woke the computer from sleep after a night's rest ... and it gave me this
> error, 

See meta bug 498274 comment #2, and enable "dialog just before auto-compact".
Is dialog before auto-compact displayed during wake-up?
mail.purge.ask was already true, and I don't remember ever seeing the dialog
i don't see in any of the comments that this has been happening in 3.0.1

Mozilla/5.0 (Macintosh; U; Intel Mac OS X 10.6; en-US; rv:1.9.1.7) Gecko/20100111 Thunderbird/3.0.1

i experienced this problem this morning for the nth time, restarted thunderbird as normally fixes this.  forcing a sleep does not seem to cause the problem.

i have the pop3 log turned on now, and have the mail.purge settings changed as per comment 21, nothing to report, yet.
I have this problem without putting the computer to sleep.
I imported all my email (300,000 messages) from Eudora 7.1, which worked well BTW. 

The first time I checked my mail my pop mailbox had 2000 messages and it downloaded a few and timed out. I clicked on check mail again and this time it said there were a few less than 2000 messages and my folders started popping up with a dialog box saying "This folder is being processed. Please wait until processing is complete to get messages."

I have gone through this process 100 times over a 2 hours and a half and I am only half way through my email. Eudora 7 would have completed it in one pass in a minute or so. Each time it only grabs about 10 messages. I am definitely online. I even shutdown and restarted Eudora 8 Beta 8 and the folders immediately display this message as it check the email.

What is this "restarting Shredder" thing that supposedly might clear this up?
We have a few other bugs with the same error message :

1) we should dup them to this one
2) I'm requesting blocking because this impede's the user ability to read emails
3) Roland is this frequently reported on gsfn ?
blocking-thunderbird3.1: --- → ?
Whiteboard: [has protocol log] → [has protocol log] [duptome]
I'd love to get this fix, but while we have a few bugs, it doesn't seem to clearly meet the criteria of "makes the upgrade experience from TB2 very painful for a large number of users", so marking as blocking-, wanted+.
blocking-thunderbird3.1: ? → -
Flags: wanted-thunderbird+
I would guess that the number of users who put  their machine to sleep is very large, and having a machine that you think is fetching mail every 10 mins, but isn't fetching it all would probably meet the category of painful - its painful even if you know and understand what is happening, its super painful if you don't know what is happening and all you get is a message that "This folder is being processed" and you don't realize that  the only way to restore TB to functionality is to quit TB and restart.
this bug "makes the upgrade experience from TB2 very painful" for me ... i open & close my laptop several times a day, and this bug bites me about 50% of the time ... meaning i have to close and re-open TB2 every other time i close my laptop.

i don't know if i'm part of a large number of users, but i've been using thunderbird since ... well, it was part of netscape communicator 4 in 1996 ... and this is the first mailreader release that i've used that has made me actively consider migrating back to TB 1.x .

i've already voted for this bug; if it's going to remain considered blocking-, let all of us who find this "very painful" know when it's finally fixed so we can go back to TB 1.x now, and we can come back and try again when we get word that this has been fixed.
I, too, find this bug "makes the upgrade experience from TB2 very painful".  I have several accounts that I monitor and the yahoo mail accounts (still my main accounts) have this problem.  The others do not seem to have it. 

As cited above, I use a laptop and a netbook and open and close several times a day.  I need to know IF I HAVE NEW MAIL OR NOT -- This is a REALLY BIG PROBLEM  and VERY PAINFUL.!!! 

Kindly give it the level of attention that it deserves for the loyal supportive users who have been with you "from the beginning".  FIX IT, PLEASE.
(In reply to comment #26)
> We have a few other bugs with the same error message :
> 
> 1) we should dup them to this one
> 2) I'm requesting blocking because this impede's the user ability to read
> emails
> 3) Roland is this frequently reported on gsfn ?

1. http://gsfn.us/t/p3l5 , "Mac OS X 10.6.2 after wake from sleep - This folder is being processed. Please wait until processing is complete to get messages." seems to be identical to this problem and 17 people have this problem
2. http://gsfn.us/t/pnxl , "No mail being received - TB3.0 on Mac: Alert: This folder is being processed." seems to be the same problem as #1 and 6 people have this problem
3. http://gsfn.us/t/pngx , "This folder is being processed. Please wait until processing is complete to get messages." - It seems that Shari and Allan and at least 10 out of 46 (10 is a guess) have this problem
4. http://gsfn.us/t/qaz3 , "Nagging processing folder problem" - Another Allan has this problem on Mac OS X, Steve Butler has it on Windows 7 with ASUS EEE Laptop, 12 others say they have it (so my guess is 2 of the 12 have the resume on sleep)
5. http://gsfn.us/t/puzy "Very slow, can't receive or send, This folder is being processed..." - Charlotte Haines seems to have the problem and 4 others claim they have it but my guess is only 1 out of 4 have the laptop sleep/resume

So by my (I think conservative) guesstimate, 36 people in GS have the "Folder is being processed problem on sleep and then resume" problem (The generic "Folder is being processed" is a very vague problem that also occurs because of anti-virus interference). It definitely seems to be a problem on the Mac (or maybe they are the ones who complain? Although there seems to be a problem with Windows laptops too just not as frequently reported on GS

Finally I may have missed some topics in GS. Since I searched for Folder is being processed and sometimes users don't tag or put that in the title or description so my search wouldn't have found it! And also GS users aren't as precise in their problem description as Bugzilla users so there could be others in GS who just aren't able to describe it properly!

All in all a definite issue that I am going to start monitoring (I hardly ever do close/sleep and I don't run Snow Leopard, just Leopard and the problem at least from GS seems to happen in Snow Leopard more than Leopard and more than Windows but it does happen in Windows)

Summary:
1. it's a real problem
2. workaround: restart thunderbird
3. really would be nice to be able to reproduce this/characterize this and then fix in 3.1
URL: http://kb.mozillazine.org/Folder_bein... → http://kb.mozillazine.org/Folder_bein...
Whiteboard: [has protocol log] [duptome] → [has protocol log] [duptome][gs]
Agreed ...

In terms of reproduction, there are a number of us who reported it who could collaborate with anyone testing this (e.g. with statements turning up in the Activitiy Manager or Error Console or a log on disk) - since anyone who uses sleep sees this frequently it shouldn't be hard to catch. 

- Mitra
At the very least, we should relnote it.  Folks who are seeing this in Thunderbird 3, did/do you also see it in Thunderbird 2?
Keywords: relnote
I was having this problem all the time and submitted a bug a while ago. But since upgrading to Thunderbird 3.04 it has stopped happening. I assume the bug was fixed? I am using Lightning as well.
Gary, nothing specifically has been fixed in 3.0.4. Do you have a mixture of imap and pop3 accounts? I don't know offhand what has changed in gecko, so that's a bit of a wildcard.
I've been running nightly for a long time (year or more) and I only started seeing it frequently at the point i filed the bug.  It might have been happening before that, but certainly not at the level to cause the annoyance / usability issues that it does now.
FYI.
Following is bugs found by search at B.M.O for; bug summary contains all string of "This folder is being processed", and status is open, and changed within one year. 
> bug 101584 Improve alert for compact folder interruption by biff/auto get msgs. Currently "This folder is being processed. Please wait until processing is complete to get messages."
> bug 323520 POP3 download stuck in "This folder is being processed" when server drops connection after RETR
> bug 392680 Clicking Get Mail twice (while first round not finished) returns modal "This Folder is being processed" modal dialog / error message
> bug 466933 Error with "Get Mail" or "Get all Messages" after resuming from computer's sleep mode - "This folder is being processed. Please wait until processing is complete to get messages"
> bug 534403 Thunderbird 3.0 Mac hangs and will not allow mail collection until rebooted. Intermittent problem. msg "this folder is being processed"

By the way, why additional data for diagnosis is still not provided by bug opener and "me too" posters, even though problem looks to occur frequently or regularly, and problem looks to be reproduced several times by intentional sleep/wakeup or suspend/resume?
Wada - what additional information do you want - remember most bug posters are NOT developers, and once you've checked Error Console and Activity Manager there isn't much more can be posted without a DEVELOPER giving instructions as to what to do.
I had recently reported that this bug had cleared up when I upgraded to Thunderbird 3.04. I spoke too soon. It seemed to have cleared up, but today it's happening again. Restarting Thunderbird fixes it but I notice when I close it down I get a "error writing to calendar" message. Don't know it that's related but I get it quite often I think when this happens.
I have several email accounts I access through Thunderbird. Gmails, hotmails, and local. All pop or pop3.
Gary, are you using Lightning?
Yes, I'm using Lightning/1.0b1
(In reply to comment #39)
> Wada - what additional information do you want (snip)

As seen in bug list I pasted, there are atleast three kinds of known issues;
> (1) bug 101584 : contention between mail download and compact (temporary error)
> (2) bug 323520 : server drops connection after RETR (restart of Tb looks needed. deadlock?)
> (3) bug 392680 Clicking Get Mail twice (it looks temporary error)
I asked questions about (1), and, by your answer, it was found that (1) was irrelevant to your problem. And, by your POP3 log, it was found that (2) didn't occur when you got SMTP log. So, your case may be similar situation to (3).
  - POP3 serer access just after wakeup occurs.
    It usualy happens because sleep time is usually not so short.
  - Because "check for new messages" is timer-pop event, it may happen
    multiple times, if "setinterval" like mechanism instead of "settimeout,
    and settimeout again after POP3 access".
  - While Tb is trying to access POP3 server, you did "Get Msgs".
But gussing of "what kind of problem happened in your case" is still very hard. So, at least your observation of phenomenon is required for first problem analysis step.
  - Temporary error(Get Msgs after a while works) or permanent error(restart
    of Tb or re-boot of OS is required).
  - When problem occurred, download was in progress or not.
  - Problem occurs even with new profile, with smaller number of POP3 accounts,
    or not. Problem occurs even with -safe-mode, or not.
  - Environment:
    What kind of accounts are defined, how many accouns are defined, ...,
    What value is specified in "check for new messages every NNN minutes",
    Problem occurs only when small NNN(like 1), or not,
    and so on.
However, it's still not so clear, because you didn't state about them clearly, and because multiple cases seems to be reported to this bug.

Phenomenon by above three bugs can't be hooked by SMTP log only, as seen in SMTP log you attached to this bug. So, getting NSPR log with all:5 and quick check of NSPR log by reporter himself is needed(log size becomes huge due to all:5, so local check is required first).
Can you get NSPR log with "timestamp,all:5", check log for something wrong or internal error while wakeup, remove log lines before sleep and after Get Msgs till termination of Tb?
Can you get NSPR log with "timestamp,all:5" when your problem occurs?
Hi Wada - I still find it very hard to understand your messages, what you are asking me to do, and what information you want - maybe a language barrier, or maybe just that you assume that I am a developer with more knowledge of the system than I have, but I'll try and answer your questiosn.

1: I see only ONE problem reported here, and impacts multiple people - over a period of longer than a year, thought it comes and goes with different releases (and usually gets addressed by programmers at a time when it isn't happening!). Note that the status on this bug is still marked as New and I don't have permissions to change it!

The bug relates specifically to sleep and restart. Its not the same as your #3 (bug 392680) which is more of a temporary UI problem, that occurs when the user clicks "Get Mail" when its already checking.

Answering your questions above:
- Temporary or Permanent:   PERMANENT, a restart of TB is required. 
- Whether download was in progress or not - I don't know, its possible.
- With new profile - no idea, as an intermittent problem its not something that can be proved that way easily. 
- "-safe-mode" no idea what that means, how to set it, or what functionality that would disable when used.
- Environment: in my case I've got two pop3 accounts, no imap, news or calender. One account checks every 2 minutes, the other every 10 mins. 

To obtain a log, I will follow the process by Ludovic in Comment #15 and Wayne in Comment #16 . Note I did this before and the log uploaded (in Comment #18) was reported as normal by yourself in Comment #21

Maybe some other reporters of the bug could do that as well and see if they catch anything.
(In reply to comment #44)
> - "-safe-mode" no idea what that means, how to set it, or what functionality
> that would disable when used.

Start Tb with -safe-mode parameter. Tb runs with all extensions(add-on) disabled. Read http://kb.mozillazine.org/Safe_mode , plese.
Mitra Ardron, can you afford to use Tb without add-on in your daily use?

> - Environment: (snip) or calender.

Do you use Lightning?
I do not use Lightning - 

I will run with -safe-mode for a while, its hard because TB is (for me) almost unusable without ShowInOut (works around the absence of "Correspondant") JunQuilla (to get decent junk mail handling) and StarMoveContact (to allow filing of new email addresses to specific address books) // note that ShowInOut and StarMoveContact are both fixes to bugs that they've been trying to get integrated for a long time.
Mitra, I can try to generate a try server build with a little additional logging to try to figure this out. Basically, the INBOX file is getting locked, and the lock isn't getting released, but we don't know what the code path is that causes this. I put my windows machine to sleep every night with TB running, and I never have an issue when I restart. But, it's directly connected to the network. I haven't seen this issue on my Mac either, though I don't use it as much.
Thanks David, 
If its useful to you to know .... I'm running off the nightlies, so currently...

Mozilla/5.0 (Macintosh; U; Intel Mac OS X 10.6; en-US; rv:1.9.1.9) Gecko/20100405 Shredder/3.0.5pre

With the dependence on add-on's to fix some of the long-time bugs/deficiencies in TB I wonder if that adds to the instability, and difficulty of tracking down/replicating bugs that a lot of people see - is it easy to log the Add-on's as well in that build?
Mitra Ardron(bug opener):
One request to you.
If you encountered your problem next time during your daily use of Tb, please check next.
 (1) Problem occurs, which is permanent, restart of Tb is required to recover.
 (2) File/Offline/Work Offline
     If dialog which asks "Download or not" appeared, reply No, please.
 (3) File/Offline, uncheck "Work Offline" (go back to "Work Online" mode)
     If dialog which asks "send (unsent) mails or not", reply No, please.
 (4) Try "Get Mail" or "Get All New Messages" again.
Does mail download work? Or dialog of "This folder is being processed. ..." is still displayed by Tb?
 (5) If problem persists, restart Tb, please.
Mitra, one of the nice things about JunQuilla is the "Uncertain" folder, which still works if JunQuilla is disabled.

But it just occurs to me, that JunQuilla might be making things worse for you, but I'm not sure it has anything to do with this bug - it opens every .msf file which makes the folder pane scroll slower. This also bloats memory - after startup with JunQuilla I'm at 346MB, vs 90MB with JunQuilla  disabled!
Hi WADA - yes - understood and I will try this, either with the nightly, or with David's build if I have it by then. 

Is anyone else of those who reported this bug able to test as well? Would speed up the results we can get to the developers.

Wayne - I wonder why JunQuilla opens all the folders? It should only need to access the inbox, I forget who the author is now? I see 205Mb of memory use, but I don't notice TB slowing down.
In answer to WADA's questions in Comment #49

Put to sleep for about 45 mins 

1: Permanent - nothing is happening, it doesn't change if I wait. 

2: File->Offline->Work Offline: No dialog appeared.

3: File -> Offline -> Work Offline (i.e. turning it back to Online): No dialog appeared

4: get Mail: Same message (folder being processed)  appears

5: Quit TB: started again: (Get Mail now works as usual)

Do you want me to try something else?  David do you have a version for me to try?

End of pop log is below - looks identical to successful POP's before it, i.e. it looks like the POP3 session completed correctly, prior to sleep. 


2010-04-08 04:02:04.978924 UTC - -1601407776[260b930]: Entering NET_ProcessPop3 20
2010-04-08 04:02:04.978954 UTC - -1601407776[260b930]: POP3: Entering state: 1
2010-04-08 04:02:04.978965 UTC - -1601407776[260b930]: POP3: Entering state: 2
2010-04-08 04:02:04.978976 UTC - -1601407776[260b930]: POP3: Entering state: 4
2010-04-08 04:02:04.978989 UTC - -1601407776[260b930]: RECV: +OK Dovecot ready.
2010-04-08 04:02:04.979008 UTC - -1601407776[260b930]: POP3: Entering state: 28
2010-04-08 04:02:04.979031 UTC - -1601407776[260b930]: SEND: CAPA
2010-04-08 04:02:05.716539 UTC - -1601407776[260b930]: Entering NET_ProcessPop3 67
2010-04-08 04:02:05.716564 UTC - -1601407776[260b930]: POP3: Entering state: 3
2010-04-08 04:02:05.716575 UTC - -1601407776[260b930]: RECV: +OK
2010-04-08 04:02:05.716611 UTC - -1601407776[260b930]: POP3: Entering state: 29
2010-04-08 04:02:05.716620 UTC - -1601407776[260b930]: RECV: CAPA
2010-04-08 04:02:05.716628 UTC - -1601407776[260b930]: POP3: Entering state: 29
2010-04-08 04:02:05.716636 UTC - -1601407776[260b930]: RECV: TOP
2010-04-08 04:02:05.716643 UTC - -1601407776[260b930]: POP3: Entering state: 29
2010-04-08 04:02:05.716650 UTC - -1601407776[260b930]: RECV: UIDL
2010-04-08 04:02:05.716657 UTC - -1601407776[260b930]: POP3: Entering state: 29
2010-04-08 04:02:05.716665 UTC - -1601407776[260b930]: RECV: RESP-CODES
2010-04-08 04:02:05.716673 UTC - -1601407776[260b930]: POP3: Entering state: 29
2010-04-08 04:02:05.716681 UTC - -1601407776[260b930]: RECV: PIPELINING
2010-04-08 04:02:05.716688 UTC - -1601407776[260b930]: POP3: Entering state: 29
2010-04-08 04:02:05.716695 UTC - -1601407776[260b930]: RECV: USER
2010-04-08 04:02:05.716702 UTC - -1601407776[260b930]: POP3: Entering state: 29
2010-04-08 04:02:05.716710 UTC - -1601407776[260b930]: RECV: SASL PLAIN
2010-04-08 04:02:05.716723 UTC - -1601407776[260b930]: POP3: Entering state: 29
2010-04-08 04:02:05.716731 UTC - -1601407776[260b930]: RECV: .
2010-04-08 04:02:05.716738 UTC - -1601407776[260b930]: POP3: Entering state: 30
2010-04-08 04:02:05.787203 UTC - -1601407776[260b930]: POP3: Entering state: 5
2010-04-08 04:02:05.787382 UTC - -1601407776[260b930]: SEND: AUTH PLAIN
2010-04-08 04:02:06.091691 UTC - -1601407776[260b930]: Entering NET_ProcessPop3 4
2010-04-08 04:02:06.091726 UTC - -1601407776[260b930]: POP3: Entering state: 3
2010-04-08 04:02:06.091742 UTC - -1601407776[260b930]: RECV: + 
2010-04-08 04:02:06.091755 UTC - -1601407776[260b930]: POP3: Entering state: 31
2010-04-08 04:02:06.091767 UTC - -1601407776[260b930]: POP3: Entering state: 6
2010-04-08 04:02:06.091827 UTC - -1601407776[260b930]: Logging suppressed for this command (it probably contained authentication information)
2010-04-08 04:02:06.477774 UTC - -1601407776[260b930]: Entering NET_ProcessPop3 16
2010-04-08 04:02:06.477803 UTC - -1601407776[260b930]: POP3: Entering state: 3
2010-04-08 04:02:06.477818 UTC - -1601407776[260b930]: RECV: +OK Logged in.
2010-04-08 04:02:06.477830 UTC - -1601407776[260b930]: POP3: Entering state: 31
2010-04-08 04:02:06.477841 UTC - -1601407776[260b930]: POP3: Entering state: 7
2010-04-08 04:02:06.477862 UTC - -1601407776[260b930]: SEND: STAT
2010-04-08 04:02:06.813626 UTC - -1601407776[260b930]: Entering NET_ProcessPop3 9
2010-04-08 04:02:06.813651 UTC - -1601407776[260b930]: POP3: Entering state: 3
2010-04-08 04:02:06.813662 UTC - -1601407776[260b930]: RECV: +OK 0 0
2010-04-08 04:02:06.813672 UTC - -1601407776[260b930]: POP3: Entering state: 8
2010-04-08 04:02:06.814253 UTC - -1601407776[260b930]: POP3: Entering state: 22
2010-04-08 04:02:06.814273 UTC - -1601407776[260b930]: SEND: QUIT
2010-04-08 04:02:07.258702 UTC - -1601407776[260b930]: Entering NET_ProcessPop3 18
2010-04-08 04:02:07.258732 UTC - -1601407776[260b930]: POP3: Entering state: 3
2010-04-08 04:02:07.258746 UTC - -1601407776[260b930]: RECV: +OK Logging out.
2010-04-08 04:02:07.258760 UTC - -1601407776[260b930]: POP3: Entering state: 40
2010-04-08 04:02:07.258770 UTC - -1601407776[260b930]: POP3: Entering state: 23
2010-04-08 04:02:07.300582 UTC - -1601407776[260b930]: POP3: Entering state: 25
(In reply to comment #52)
> 4: get Mail: Same message (folder being processed)  appears
> 5: Quit TB: started again: (Get Mail now works as usual)

Thanks for checking. New finding of "Work Offline/Work Online can not be a recovery procedure from your problem" is important and valuable.

> Do you want me to try something else?

Yes. Can you get NSPR log with next setting?
> export NSPR_LOG_MODULES=timestamp,MSGDB:5
(1) Enable NSPR logging, restart Tb, use Tb for a while.
(2) Sleep a while, wakeup, Get Msgs, terminate Tb, save log file.
    (no need to reproduce your problem)
By MSGDB:5, number of opened MsgDB(corresponds to mail folder) is logged.
Is funny phenomenon seen in log? (such as too many opened DB, number of opened DB looks increasing infinitely)

By the way, what add-on or plugin do you mean by "calender" which you use?
Mitra/WADA, can you hold off on new logs, etc? I don't think they're going to help. I was able to reproduce the issue on my macbook. I just need some time to try to diagnose it here.
Ok - I'm running with MSGDB:5 as requested and can post the log if/when needed.

WADA: I do *NOT* run a calender - see Comment #44 "- Environment: in my case I've got two pop3 accounts, no imap, news or calender."
Mitra, are you using the global inbox (pop3 mail gets put in the local folders inbox for both your accounts), or per-account inboxes? Do you have any mail filters that move messages to other folders?

I saw this happen once, but after a few hours it cleared itself up, which was very odd. I've got some logging in my own build, but I suspect it will only tell me that the lock was not released, not *why* the lock was not released. I'll submit a try server build request in a few minutes with extra POP3 logging, and a little bit of extra error handling that might help with the bug.
Mitra, there will be a try server build up in a couple hours here (assuming the build succeeds), with my e-mail address on it, that might help diagnose and/or fix the issue. it's a trunk build. If you could try running with it with POP3 logging turned on and report back, that would be very helpful, thx!
Assignee: nobody → bienvenu
I'm running with local folders, 

Yes - I do have filters that move messages to other folders

I don't know what a "try server build" is, (though I can guess) - can you give me a URL to look for it on.  

I've also emailed directly four other people who reported the bug in this thread to see if we can look for similarities / differences. 

- Mitra
http://s3.mozillamessaging.com/build/try-server/2010-04-09_08:20-bienvenu@nventure.com-1270825958/bienvenu@nventure.com-1270825958-mail-try-mac.dmg

This is a trunk build, so it will blow away your global database, unfortunately, and re-index all your mail. (3.1 will do the same when it comes out...)
Just checking ... what do you mean about blowing away the global database - or did you mean "Globa" i.e. the index for the search - that's fine, I just want to check I'm not going to lose data.
I mean gloda, the index for search; you won't lose any data, but your cpu won't get much sleep :-)
(In reply to comment #27)
> I'd love to get this fix, but while we have a few bugs, it doesn't seem to
> clearly meet the criteria of "makes the upgrade experience from TB2 very
> painful for a large number of users", so marking as blocking-, wanted+.

- in view of at least 36 gsn reports per comment 32
- in view of several similar/duplicate bugs
- in support of comment 26 and many more on this bug,
- because of the pretty regular / frequent occurence of this bug
- because of the deceptive error message that advises users to wait (forever)
I conclude (against comment 27) that this bug clearly has the potential "to make the upgrade experience from TB2 very painful for a large number of users". 

Therefore, I can only support Ludovic's request of comment 26 to make this a blocker:
> I'm requesting blocking because this impede's the user ability to read emails

(in reply to comment 58 and Mitra's mail)
Mitra, thanks for your engagement in this. I'm still seeing this bug in more or less regular intervals (not every time when resuming from sleep mode), on my WinXP install. I couldn't guarantee that it's a perfectly clean install with a perfectly clean profile.
I'm using Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.1.9) Gecko/20100406 Lightning/1.0b1 Shredder/3.0.5pre. + filterbar prototype addon
I use have separate pop3 accounts, and 1 imap, a news-acc (rarely used), and a feed account. I usually only check my main pop3 account, so that's where I meet the error.

hth, Thomas
Thomas D., if you'd like to help, you could try the try server build http://s3.mozillamessaging.com/build/try-server/2010-04-09_08:20-bienvenu@nventure.com-1270825958/bienvenu@nventure.com-1270825958-mail-try-win32.installer.exe with POP3 protocol logging turned on, and report back your findings, that would be helpful.
David - I've sent you email with an attachment of a log file showing the problem with your distribution.
After talking to Mitra, and looking at the log, I believe the issue is that we've left the server in a busy state, not that the folder is locked. nsPop3Service::RunPopUrl is bailing out because aServer->GetServerBusy(&serverBusy) is saying that the server is busy. I'll look at the code and see if I can see the issue, or where to add more logging.
David - are you suggesting that the POP server is in the dodgy state? Or some internal (to TB) data structure is? 

Because if it was the Pop server wouldn't you be logging a failed attempt to connect to it, and also pop servers in the wrong state would typically time-out, and that example log had a 4-hour delay between going to sleep and reconnecting.
Mitra, sorry, serverBusy is client-side state; nothing to do with the pop3 server itself.

The only way I can see this failing is if we start running a url, but don't get an OnStopRequest, and don't get into the POP3_FREE state. I'll try to add some logging to see if that's happening.
Mitra, there will be an other try server build available in a couple hours, if all goes well with the build. I'll try to remember to post a link if&when the build succeeds.
Attachment #438091 - Attachment is obsolete: true
David:Bienvenu, is bug 323520(original bug 323520 comment #0 and bug 323520 comment #3) same problem?
WADA, I don't think so. I think that bug is a little misleading, because the log just showed us continually trying to authenticate, which means we really are busy with the server, and doesn't match the bug summary.  I don't know if that bug still happens, either the one in the log, or the one as described by the summary.
(In reply to comment #70)

I see. One more question.
Is description of bug 323520 comment #3 for same issue as this bug? Or for similar issue but in different condition/situation?
(In reply to comment #71)

> I see. One more question.
> Is description of bug 323520 comment #3 for same issue as this bug? Or for
> similar issue but in different condition/situation?

I don't believe that comment is valid (anymore?).
David - what is the URL for the version you want me to try - the number of versions at http://ftp.mozilla.org/pub/mozilla.org/thunderbird/nightly/ is a bit confusing.
Mitra, you can find a link to the build at http://tinderbox.mozilla.org/showbuilds.cgi?tree=ThunderbirdTry
Hi David - it doesn't seem to be logging at all. pop.log is empty even after a (succcessful) Get Mail.

I'm running it with the script below, which was previously working fine. 

#!/bin/bash
# export NSPR_LOG_MODULES=pop3:5,timestamp,MSGDB:5
export NSPR_LOG_MODULES=pop3:5,timestamp
export NSPR_LOG_FILE=pop.log
cd /Users/mitra/Desktop
newfile=pop.log.`DATE "+%Y%m%d%H%M"`
mv pop.log $newfile
/Applications/Shredder.app/Contents/MacOS/thunderbird-bin &
Sorry, weird - this time - same script - and its logging fine.
Thomas, thanks for the comments.  While you're right that there's an important bug here (and I very much hope we can get it fixed for 3.1), I still believe it can't block, largely because we don't know of any developer who can reliably reproduce it and because it's not at all clear that a large number of Tb2 upgraders are going to hit it.
Thomas D, are you running with POP3 logging turned on, and this try server build? http://s3.mozillamessaging.com/build/try-server/2010-04-14_01:10-bugzilla@standard8.plus.com-bienvenu-extra-logging/bugzilla@standard8.plus.com-bienvenu-extra-logging-mail-try-win32.installer.exe

If you (or anyone else) can reproduce this with a try server build w/ extra logging, and generate a log, that would be tremendously helpful.
(In reply to comment #77)
> it doesn't seem to be logging at all. pop.log is empty even after a (succcessful) Get Mail.
(In reply to comment #78)
> Sorry, weird - this time - same script - and its logging fine. 

Mitra Ardron, did you terminate Tb? As buffering is used by default, you need to disable buffering if you want to see recent log lines in log file always while Tb is running.
> http://www.mozilla.org/projects/nspr/reference/html/prlog.html#25315
> export NSPR_LOG_MODULES=sync,timestamp,pop3:5
Hi Wada - yes, I did terminate it (Shredder/QuitShredder), and still got a zero size log that time - I also just got a real log of the bug, with the new tryserver, and forwarded to David.

- Mitra
Mitra, I've generated an other try server build. This has the same logging as before, but it also shuts down running pop3 protocol connections when we get notified that we're offline. Please let me know if it helps, and if you still see the issue, a log would be helpful. thx!
this makes us close running pop3 connections when we go offline. I suspect that in some cases, when we wake up, we're online, but discover relatively quickly that we're actually offline, but that offline notification might happen after we've started a pop3 url.
I frequently encounter this bug and I've always thought it was because TB was trying to get mail before the wifi system had completed waking up. I've  noticed that if I manually do a get mail too soon I'll get the same problem. Have to restart TB to fix it.
Mitra, any news (good or bad) from running with the latest try server build?
Comment on attachment 441109 [details] [diff] [review]
same as before, plus close pop3 connections when we go offline

Might as well get the review process started for this. I can't think of a unit test for this because I don't know how to recreate the issue. But I'm pretty hopeful that this will help...it also has a few improvements to our error handling, and some useful logging.
Attachment #441109 - Flags: superreview?(bugzilla)
Attachment #441109 - Flags: review?(bugzilla)
Hi David

I haven't seen a problem since using this build.  I'll keep running it (with logging) for a while, and see what happens. 

- Mitra
Mitra, thx, that's pretty good news.
Whiteboard: [has protocol log] [duptome][gs] → [has patch for review] [duptome][gs]
I'm running under Mac OS X 10.5 and after sleep, TB would have the  "folder is being processed" message.  The build from comment #88 seems to have fixed this problem.
I'd love to get this into nightlies soon so that all those users can have it.
This patch seems to break test_pop3ServerBrokenCRAMDisconnect.js in debug mode, it fails with the following assertion:

###!!! ASSERTION: no channel: 'm_request', file /Users/moztest/comm/main/src/mailnews/base/util/nsMsgProtocol.cpp, line 767
I see this as well...I'll try to fix it.
test_pop3ServerBrokenCRAMDisconnect.js is basically broken, or rather, the underlying pop3 code is known to be broken in the failure case caused by the test, and my changes merely trigger an assertion about that known failure. This bug fix is a lot more important than the test and its failure, so I'm tempted to just turn the assertion into a warning, but I'll spend a little time trying to see if I can fix the underlying bug.

        Attachment #441109 -
        Attachment is obsolete: true

        Attachment #444408 -
        Flags: superreview?(bugzilla)

        Attachment #444408 -
        Flags: review?(bugzilla)

        Attachment #441109 -
        Flags: superreview?(bugzilla)

        Attachment #441109 -
        Flags: review?(bugzilla)

    
    

    
  
Comment on attachment 444408 [details] [diff] [review]
fix for test case

This patch tweaks the test a bit to close the socket the way other tests do, though that's just for consistency's sake. The fix that makes the test pass is to check in OnStopRequest if we've gotten here due to a dropped connection, and make an other pass through the state machine, which cleans up the protocol object, so we don't hit the assertion when closing cached connections.

    
    

    
  
(In reply to comment #99)
> The fix that makes the test pass is to check in OnStopRequest if we've gotten here due to a dropped connection,
> and make an other pass through the state machine, which cleans up the protocol object,
> so we don't hit the assertion when closing cached connections.

Question to David :Bienvenu.
What is meaning of the "cached connections" for POP3 server in this bug's problem. Multiple POP3 accounts on same server is involved? Does the "cached connections" mean "re-use or share of same socket for different POP3 accounts on same server"? Is TLS/SSL(or StartTLS) involved in issue?

    
    

    
  
cached connections just means existing pop3 protocol objects. POP3 doesn't cache connections, and in this case, the actual network connection has been dropped, but the pop3 protocol object did not get cleaned up.

        Attachment #444408 -
        Flags: superreview?(bugzilla)

        Attachment #444408 -
        Flags: superreview+

        Attachment #444408 -
        Flags: review?(bugzilla)

        Attachment #444408 -
        Flags: review+

    
    

    
  
Comment on attachment 444408 [details] [diff] [review]
fix for test case

I'm guessing you want this in 3.1 as well, a=Standard8 for that.

        Attachment #444408 -
        Flags: approval-thunderbird3.1+

    
    

    
  
fixed on trunk and 3.1 branch.
Status: NEW → RESOLVED
Closed: 14 years ago

          status-thunderbird3.1:
          --- → rc1-fixed
Resolution: --- → FIXED

    
  
Keywords: relnote
Whiteboard: [has patch for review] [duptome][gs] → [duptome][gs]
Depends on: 599609

    
  
Summary: Error with "Get Mail" or "Get all Messages" after resuming from computer's sleep mode - "This folder is being processed. Please wait until processing is complete to get messages" → Error with "Get Mail" or "Get all Messages" after resuming from computer's sleep mode - "This folder is being processed. Please wait until processing is complete to get messages" [pop]

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






  

    
  







  

    

      
Attachment

      

      
      
      
      
    

    

      

        

          

            
General

            

              Creator: 



            

            
Created: 

            
Updated: 

            
Size: