1763491 - Thunderbird stops getting POP3 messages until restarted: "The account xxx is being processed. Please wait until processing is complete to get messages"

Status: RESOLVED WORKSFORME

(MailNews Core :: Networking: POP, defect, P1)

Description

[doug2]

Attachment: gmail.jpg photo of error

User Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:99.0) Gecko/20100101 Firefox/99.0

Steps to reproduce:

Running Daily 101.0a1 on Win 10 64 bit. Mail stops coming in. Use F5 to request new mail. Receive persistent error "The account xxx is being processed. Please wait ..." (forever). Only remedy is to kill TB and restart.

Actual results:

see above.

Expected results:

Mail should be retrieved on set schedule or any time using Get new mail or F5.

Comment 1

[Magnus Melin [:mkmelin]]

IMAP or POP3?

Comment 2

[doug2]

pop3

Comment 3

[Magnus Melin [:mkmelin]]

Please attach a pop3 protocol log. https://wiki.mozilla.org/MailNews:Logging

Comment 4

[doug2]

​Gmail: Host contacted, sending login information ... <no further status. Have to restart TB to continue or wait for next auto status>
pop3 log level set to ALL but no Pop3 log entries?
Error log:

Exception { name: "NS_ERROR_FAILURE", message: "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsISecretDecoderRing.decryptString]", result: 2147500037, filename: "chrome://openpgp/content/modules/masterpass.jsm", lineNumber: 230, columnNumber: 0, data: null, stack: "_readPasswordFromFile@chrome://openpgp/content/modules/masterpass.jsm:230:16\n", location: XPCWrappedNative_NoHelper }
RNP.jsm:47:15
NS_ERROR_NOT_AVAILABLE: PreferDisplayName: undefined - not a boolean AddrBookCard.jsm:180
NS_ERROR_NOT_AVAILABLE: PreferDisplayName: undefined - not a boolean 2 AddrBookCard.jsm:180
NS_ERROR_NOT_AVAILABLE: PreferDisplayName: undefined - not a boolean AddrBookCard.jsm:180
NS_ERROR_NOT_AVAILABLE: PreferDisplayName: undefined - not a boolean AddrBookCard.jsm:180
NS_ERROR_NOT_AVAILABLE: PreferDisplayName: undefined - not a boolean AddrBookCard.jsm:180
NS_ERROR_NOT_AVAILABLE
NS_ERROR_NOT_AVAILABLE: PreferDisplayName: undefined - not a boolean AddrBookCard.jsm:180
NS_ERROR_NOT_AVAILABLE: PreferDisplayName: undefined - not a boolean 2 AddrBookCard.jsm:180
NS_ERROR_NOT_AVAILABLE: PreferDisplayName: undefined - not a boolean AddrBookCard.jsm:180
NS_ERROR_MALFORMED_URI: Component returned failure code: 0x804b000a (NS_ERROR_MALFORMED_URI) [nsIIOService.newURI] FaviconLoader.jsm:420
uncaught exception: 2147500036

Comment 5

[doug2]

error pop3serverbusy - the only error shown
seems to occur at first get mail in AM. Next time I will grab log and also test port 995 with telnet

Comment 6

[doug2]

Attachment: pop3error202205`3.png

Comment 7

[doug2]

Attachment: error log no download

Comment 8

[doug2]

First request for new mail returned pop3serverbusy - see error log
Repeated requests to get new mail returned nothing. - see error log
Shut down TB and restarted. Received 16 pcs of mail.

Comment 9

[doug2]

Attachment: status message - frozen

Attempting to auto-download new mail. Status frozen.

Comment 10

[doug2]

Attachment: TB-nodownload20220514.txt

error log associated with frozen status.

Comment 11

[doug2]

No instances of this problem so far with 101.0b4.

Comment 12

[doug2]

Attachment: Pop3serverbusy20220525.txt

Error Log pop3serverbusy but not busy

Comment 13

[Magnus Melin [:mkmelin]]

I guess this bug is about handling the folder busy situation more gracefully (unclear how). I notice nsIPop3Sink is still c++. That functionality should be rewritten in js as well.

Comment 14

[Ping Chen [:rnons] (away)]

Attachment: Bug 1763491 - Add some logs to Pop3Client to help fix pop3ServerBusy error. r=mkmelin

Comment 15

[Ping Chen [:rnons] (away)]

(In reply to Magnus Melin [:mkmelin] from comment #13)

I notice nsIPop3Sink is still c++. That functionality should be rewritten in js as well.

I don't think it's good to rewrite protocol layer and storage layer at the same time. I think this is a bug in Pop3Client, the release function is somehow not called.

The patch added some logs

mailnews.pop3.0: Folder lock acquired. 
mailnews.pop3.0: Folder lock released.  
mailnews.pop3.1: Folder lock acquired. 
mailnews.pop3.1: Folder lock released.

Two changes:

1. the last part of mailnews.pop3.1 is logger id, in this case 1
2. lock acquired should be always paired with lock released

Comment 16

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/comm-central/rev/2869d1728193
Add some logs to Pop3Client to help fix pop3ServerBusy error. r=mkmelin

Comment 17

[doug2]

Attachment: Pop3server-stopped.txt

opened TB, no new mail. Requested download, status host contacted ... no further activity.

Comment 18

[Wayne Mery (:wsmwk)]

There are other reports of this I think.

Comment 19

[Thomas D. (:thomas8)]

Ping, anything interesting in reporter's latest log (comment 17) or from similar bugs below?
doug2, are you using either Global Inbox (available from old, deep settings) or Unified inbox (available via primary UI)?

(In reply to Wayne Mery (:wsmwk) from comment #18)

There are other reports of this I think.

From my search, here they are:

Bug 707933 - Global inbox, Local Folders, access not serialized/synchronized when automatically checking multiple POP3 accounts every n minutes causing POP3_MESSAGE_FOLDER_BUSY error "This folder is being processed. Please wait until processing is complete..."

Bug 1636851 - Randomly deleting most of my POP3 Inbox file, circa 68.5.0. "The account xxxx is being processed. Please wait until processing is complete to get messages."

Bug 707933 looks interesting wrt this bug.
Bug 1636851 has too many twists, but (reported only 2 years back) perhaps interesting background for current POP issues.

Comment 20

[doug2]

Have had cases in the last week of TB (beta) "stuck" in "processing." I failed to capture error log. Had to shut down & restart TB to clear. Next time it happens, I will capture logs and post.

Comment 21

[Magnus Melin [:mkmelin]]

xref bug 1779306

Comment 22

[Thomas D. (:thomas8)]

(In reply to doug2 from comment #20)

Have had cases in the last week of TB (beta) "stuck" in "processing." I failed to capture error log. Had to shut down & restart TB to clear. Next time it happens, I will capture logs and post.

That's great!

(In reply to Thomas D. (:thomas8) from comment #19)

doug2, are you using either Global Inbox (available from old, deep settings) or Unified Folders inbox (available via primary UI)?

Could you also answer this?

Comment 23

[doug2]

No, I have never used Global Inbox. I think I tried Unified Folders once recently and went back to standard.

Comment 24

[Dan Pernokis]

This problem has persisted in discussions for at least the past 11 years. It exists right now in TB 91.11.0 and I have no reason to suspect it would be fixed in 102 -- the fact that you see the screen means it still happens in some form or other. But I can't test it because using the GET MESSAGES button seems to trigger multiple downloads thereafter until relaunch, so for now I've disabled all accounts from linking to the GM button.

See Bug 707933 for a very long discussion of the hanging process and the screen popups, and the need to allow the screen to time out and continue...

Comment 25

[doug2]

Running 104.0b3 64 bit on Win 11 (current). Just went through a multi-day error log and found no Pop errors. In the recent past, I have had instances when get mail seemed "stalled" (no mail waiting in early AM), but get messages worked. Most recently, mail is waiting in early AM. I can't say for certain that the problem no longer exists, but it is much less of an issue than when I had to restart TB to get mail.

Comment 26

[doug2]

Attachment: TB20220819.txt

Error log - Win 11 64, TB 104.0b3 stalled

Comment 27

[Wayne Mery (:wsmwk)]

comment 19's list https://bugzilla.mozilla.org/buglist.cgi?quicksearch=707933%20822625%201636851%201763491%20&list_id=16184981 appears to be is a complete list according to https://mzl.la/3AMCKhP

Could js-pop somehow have made bug 707933 worse?

Comment 28

[Ping Chen [:rnons] (away)]

(In reply to doug2 from comment #26)

Created attachment 9290634 [details]
TB20220819.txt

Error log - Win 11 64, TB 104.0b3 stalled

06:41:27.959 mailnews.pop3.925: Connecting to pop://pop.gmail.com:995 Pop3Client.jsm:125:18
06:41:27.960 mailnews.pop3.926: Connecting to pop://pop.googlemail.com:995 2 Pop3Client.jsm:125:18
...
06:42:13.514 mailnews.pop3.926: error { target: TCPSocket, isTrusted: true, name: "ConnectionRefusedError", message: "Network", errorCode: 2152398861, srcElement: TCPSocket, currentTarget: TCPSocket, eventPhase: 2, bubbles: false, cancelable: false, … } ConnectionRefusedError Network 2152398861

Can you change the hostname of all your gmail servers to pop.gmail.com?

Comment 29

[doug2]

Attachment: tb outfgoing server options

Comment 30

[doug2]

done. (Although TB and Google consider gmail and googlemail equivalent - see the Outgoing mail server function in settings)

Comment 31

[doug2]

Attachment: TB2022081924.txt

TB 104.0b4 pop3 windows 11 no mail early am. see file attached

Comment 32

[Arthur K. (he/him)]

(In reply to Ping Chen (:rnons) from comment #28)

(In reply to doug2 from comment #26)

Created attachment 9290634 [details]
TB20220819.txt

Error log - Win 11 64, TB 104.0b3 stalled

06:41:27.959 mailnews.pop3.925: Connecting to pop://pop.gmail.com:995 Pop3Client.jsm:125:18
06:41:27.960 mailnews.pop3.926: Connecting to pop://pop.googlemail.com:995 2 Pop3Client.jsm:125:18
...
06:42:13.514 mailnews.pop3.926: error { target: TCPSocket, isTrusted: true, name: "ConnectionRefusedError", message: "Network", errorCode: 2152398861, srcElement: TCPSocket, currentTarget: TCPSocket, eventPhase: 2, bubbles: false, cancelable: false, … } ConnectionRefusedError Network 2152398861

Can you change the hostname of all your gmail servers to pop.gmail.com?

Is it worth doug2 testing with 105.0b1 if / when it's offered? Wondering if bug 1781721 made any difference for him.

Comment 33

[Wayne Mery (:wsmwk)]

(In reply to Arthur K. [He/Him] from comment #32)

...
Is it worth doug2 testing with 105.0b1 if / when it's offered?

I expect it will be offered with 24 hours. If it is resolved, then it is likely bug 1779306.

Comment 34

[Dan Pernokis]

And will it finally resolve Bug 707933 as well? (See my Comment 24 above...)

Comment 35

[Arthur K. (he/him)]

(In reply to Dan Pernokis from comment #34)

And will it finally resolve Bug 707933 as well? (See my Comment 24 above...)

Have you by chance ever had Error Console open (ctrl-shift-j) and seen if there's any useful info there in terms of error messages, etc? Could be worth exploring for more insight.

Comment 36

[doug2]

Attachment: TN20220824b.txt

May be irrelevant to this issue - mail stopped flowing at 08:46:57 AM local time (CDT) to approx 10:20 AM following sent mail. No auto downloads processed. (set to every few minutes, <10). No errors in log.
Requested mail - 23 pcs downloaded.

Comment 37

[doug2]

(In reply to Arthur K. [He/Him] from comment #32)

(In reply to Ping Chen (:rnons) from comment #28)

(In reply to doug2 from comment #26)

Created attachment 9290634 [details]
TB20220819.txt

Is it worth doug2 testing with 105.0b1 if / when it's offered? Wondering if bug 1781721 made any difference for him.

I am on the beta channel and run with all the builds. The problem is that I don't have a way to force it to happen. I have been keeping the error console running.

Comment 38

[Dan Pernokis]

Doug, if you want to force the popup of the busy-being-processed message, just click GET MESSAGES two or three times in quick succession so that two or three polling sequences start up. If you have a number of accounts, there will be a collision somewhere and you will see the popup PDQ.

Comment 39

[Dan Pernokis]

Regarding the initial point of this bug that automatic polling & fetching suddenly stops, I've recently noticed something that might provide a clue.

Sometimes when I fetch (manually poll) an account, TB will take quite awhile, and on occasion hang and not finish bringing everything in. I see this when the status bar says TB is connected & downloading AND the progress bar shows a "scanning" pattern rather than a progressive slider. But sooner or later something (such as another poll, or clicking on a folder or message) causes the status bar to erase itself. All that's left is the progress bar in its "scan" format.

During times when certain versions of TB 102 didn't show the progress bar, imagine what you would see: Nothing! No status to say something was connected, and no scanning progress bar. Yet TB would be sitting there polling or hanging or whatever -- and perhaps be frozen or hung as has been described here, all-the-while looking absolutely normal to the user. (If TB thinks it is polling, why would it poll something else? So it just waits... and waits... and waits.) Now that the progress bar is again operable, I occasionally see scans "happening" even when status is blank -- so it is probably hung.

Don't know why this happens, only that it does.

Comment 40

[Matt]

(In reply to doug2 from comment #36)

Created attachment 9291377 [details]
TN20220824b.txt

May be irrelevant to this issue - mail stopped flowing at 08:46:57 AM local time (CDT) to approx 10:20 AM following sent mail. No auto downloads processed. (set to every few minutes, <10). No errors in log.
Requested mail - 23 pcs downloaded.

Set all pop accounts to a minimum or 10 minutes for polling. hotmail simply refuses connections more frequently than that and given the overheads involved in some setups, polling may not actually complete in less than 10 minutes. Especially if you have 8 or 10 Gb inbox that your antivirus product of choice is scanning all day every day because it does not get done before a change starts again.

Comment 41

[Wayne Mery (:wsmwk)]

Still happening with beta 105 ?

Comment 42

[doug2]

I have not seen this problem in a long time. I recommend closing it. There are times when mail has not come in for a while and I need to request mail, but that works. Thanks.

Comment 43

[Wayne Mery (:wsmwk)]

Thanks for the update.

Comment 44

[Dan Pernokis]

I still see the BUSY pop-up on TB 102.2.2, as recently as this morning. And if other internals are somehow "stopping" mail from being polled until user interaction, that isn't good and the problem isn't really fixed.

Anyone relying on an automated inbound system -- say, unattended receiving mail and using filters to automatically forward & distribute it -- will be out of luck as this will severely curtail their system.