Open Bug 1796037 Opened 3 years ago Updated 3 years ago

Thunderbird clears popstate.dat file unexpectedly - S: -ERR Message can not load

Categories

(MailNews Core :: Networking: POP, defect)

Product:
MailNews Core
Component:
Networking: POP
Version:
Thunderbird 102
Type:
defect

Tracking

(Not tracked)

Status:
UNCONFIRMED

People

(Reporter: ruralhunter, Unassigned)

Details

Attachments

(1 file)

tb.zip
1.11 MB, application/zip
Details

User Agent: Mozilla/5.0 (X11; Linux x86_64; rv:106.0) Gecko/20100101 Firefox/106.0

Steps to reproduce:

I always keeps updating Thunderbird to the latest version. Recently(I don't remember from when, maybe 2 months also) Thunderbird started to download old mails sometimes. It does download all the old mails at one time. Sometimes it gets only new mails and sometime it gets several hundred of old mails from different time period. Till one day, TB stopped to get any mails, it reports a mail server error "Message can not load" everytime I tried to receive mails.
I googled the problem and tried to set the MOZ_LOG env variables to get the pop3 logs but it didn't work. Then I found the popstate.dat file is much smaller than the one in my backup(1.2MB vs 1.6MB). I believe that should not happen though I don't know why. So I replaced the popstate.dat with my backup. It behaves normally for a few days/weeks(only receiving new mails). Of course I also got old mails since the backup but that's expected.
But one day, it started to get old mails again and several days later it stopped to get mails with the same error finally. I found the popstate.dat is totally empty this time. So I tried to use the backup again. But this time it doesn't work. Each time I retries to receive mails TB reports the same error. In the mean time, the popstate.dat shrinks from 1.6MB to 900KB.
I then followed the suggestion of http://forums.mozillazine.org/viewtopic.php?p=14941586#p14941586 to disable the new js module. But I still get the same error. One difference is that the popstate.dat does not shrink. This time, the MOZ_LOG setting works and I can get the pop3 log. It's like this when the error occurs:
2022-10-17 09:39:39.190000 UTC - [Parent 12088: Main Thread]: I/POP3 [this=2394fb80] RECV: 23503 ZC2717-HBDyiad6Xuj7nUWU1ieFcm
2022-10-17 09:39:39.190000 UTC - [Parent 12088: Main Thread]: I/POP3 [this=2394fb80] Entering state: 12
2022-10-17 09:39:39.190000 UTC - [Parent 12088: Main Thread]: I/POP3 [this=2394fb80] RECV: 23504 ZC4017-ZWmEn7FsKJnVjhV2_bCfEcm
2022-10-17 09:39:39.190000 UTC - [Parent 12088: Main Thread]: I/POP3 [this=2394fb80] Entering state: 12
2022-10-17 09:39:39.190000 UTC - [Parent 12088: Main Thread]: I/POP3 [this=2394fb80] RECV: 23505 ZC0117-Ex8j2vQStQRIGMAiy81Acm
2022-10-17 09:39:39.191000 UTC - [Parent 12088: Main Thread]: I/POP3 [this=2394fb80] Entering state: 12
2022-10-17 09:39:39.191000 UTC - [Parent 12088: Main Thread]: I/POP3 [this=2394fb80] RECV: 23506 ZL4117-xMhRoI58vA1BuCNAgzsHJcm
2022-10-17 09:39:39.191000 UTC - [Parent 12088: Main Thread]: I/POP3 [this=2394fb80] Entering state: 12
2022-10-17 09:39:39.191000 UTC - [Parent 12088: Main Thread]: I/POP3 [this=2394fb80] RECV: 23507 ZC0217-aWXHHjAp12Yr3kUmZUEQHcm
2022-10-17 09:39:39.191000 UTC - [Parent 12088: Main Thread]: I/POP3 [this=2394fb80] Entering state: 12
2022-10-17 09:39:39.191000 UTC - [Parent 12088: Main Thread]: I/POP3 [this=2394fb80] RECV: 23508 ZL2917-0Nxt1fvlhjd6hxx_L2qhccm
2022-10-17 09:39:39.191000 UTC - [Parent 12088: Main Thread]: I/POP3 [this=2394fb80] Entering state: 12
2022-10-17 09:39:39.191000 UTC - [Parent 12088: Main Thread]: I/POP3 [this=2394fb80] RECV: .
2022-10-17 09:39:39.191000 UTC - [Parent 12088: Main Thread]: I/POP3 [this=2394fb80] Entering state: 15
2022-10-17 09:39:39.206000 UTC - [Parent 12088: Main Thread]: I/POP3 [this=2394fb80] Entering state: 18
2022-10-17 09:39:39.206000 UTC - [Parent 12088: Main Thread]: I/POP3 [this=2394fb80] SEND: RETR 1
2022-10-17 09:39:39.311000 UTC - [Parent 12088: Main Thread]: I/POP3 [this=2394fb80] Entering NET_ProcessPop3 27
2022-10-17 09:39:39.311000 UTC - [Parent 12088: Main Thread]: I/POP3 [this=2394fb80] Entering state: 3
2022-10-17 09:39:39.311000 UTC - [Parent 12088: Main Thread]: I/POP3 [this=2394fb80] RECV: -ERR Message can not load

There might be a problem with my mail provider(pop.exmail.qq.com) on some mail. I guess if it's the server error causes the problem of popstate.dat handling.

Component: Untriaged → Networking: POP
Product: Thunderbird → MailNews Core

(you probably meant to pick version 102)

Version: Thunderbird 103 → Thunderbird 102

Please let a pop3 log with pop3 js active. https://wiki.mozilla.org/MailNews:Logging + popstate.dat before and after

Attached file tb.zip —

OK, see the attachement.
pop3log.txt is the pop3 log from the error console.
popstate.dat.before is the state file before open thunderbird which is around 1.6MB
popstate.dat.after is after Thunderbird checks mail, which shrinks to 975KB

It says: mailnews.pop3.2: S: -ERR Message can not load

So some error happened on the server. Nothing we can do about that. Possibly there is some bug in when we write known state to popstate.dat in error situations.

Summary: Thunderbird clears popstate.dat file unexpectedly → Thunderbird clears popstate.dat file unexpectedly - S: -ERR Message can not load

I don't think so. At least the client shouldn't clear the popstate.dat if there is any server error.

As a workaround for the RETR error, you can put k <UIDL> <timestamp> (e.g. k ZC2727-EBydET8tTP0hvSZ2hb0iG2c 1588756083) in your popstate.dat, so that TB will not try to fetch it next time.

For the size change of popstate.dat, I see two reasons:

  1. some UIDLs in popstate.dat.before no longer exist on the server
  2. some UIDLs in popstate.dat.before were marked as deleted (those lines beginning with d)

I'm not sure in which case popstate.dat will become empty, will check the code. If you happen to have the logs when it become empty, please upload again. Thanks.

OK, thanks. I will try your workaround.
But for this: "some UIDLs in popstate.dat.before no longer exist on the server", I didn't delete any mail on the server. Not sure if it's the server lost my mails but I doubt that.

I found this https://www.zhihu.com/question/26978610/answer/1521786145
My guess is your server only allows fetching the most recent for example 90 days of mails, but somehow UIDL returns all mails.

No, as I stated in the decription of this issue, I received very old duplicate mails. There was some problem with QQ mail server and I experieced the same error before. Their customer service helped me to find and delete the problematic mail(with 'ERR Message can not load') on the server at that time. But there was no problem with Thunderbird's popstate.dat then. Now just this same problem happened again but Thunderbird messed up the popstate.dat this time.

One question regards your workaround, I can not find which mail ID causes the error in the log. The log just list more than 200000 IDs and then follows the error:
1 xxxxxxxxxxx
2 xxxxxxxxxxx

23625 xxxxxxxxxxx
Which one is the problem? The last one? I tried to add it to the popstate but it didn't help

How about Thunderbird just skip the mail with server error? Is that possible?

From the old log:
2022-10-17 09:39:39.191000 UTC - [Parent 12088: Main Thread]: I/POP3 [this=2394fb80] Entering state: 12
2022-10-17 09:39:39.191000 UTC - [Parent 12088: Main Thread]: I/POP3 [this=2394fb80] RECV: .
2022-10-17 09:39:39.191000 UTC - [Parent 12088: Main Thread]: I/POP3 [this=2394fb80] Entering state: 15
2022-10-17 09:39:39.206000 UTC - [Parent 12088: Main Thread]: I/POP3 [this=2394fb80] Entering state: 18
2022-10-17 09:39:39.206000 UTC - [Parent 12088: Main Thread]: I/POP3 [this=2394fb80] SEND: RETR 1
2022-10-17 09:39:39.311000 UTC - [Parent 12088: Main Thread]: I/POP3 [this=2394fb80] Entering NET_ProcessPop3 27
2022-10-17 09:39:39.311000 UTC - [Parent 12088: Main Thread]: I/POP3 [this=2394fb80] Entering state: 3
2022-10-17 09:39:39.311000 UTC - [Parent 12088: Main Thread]: I/POP3 [this=2394fb80] RECV: -ERR Message can not load

The RECV command follows a '.'. Is that the server sending a problematic mail id?

The UIDL response is like <sequence> <uidl>, then RETR <sequence> is used to fetch a message.
Since RETR 1 failed, you should look for the 1 <uidl1> line, and put uidl1 into popstate.dat

(In reply to RuralHunter from comment #11)

How about Thunderbird just skip the mail with server error? Is that possible?

It's possible, but we still need to show the error message. Which means you will see the same error dialogs every time.

The RECV command follows a '.'. Is that the server sending a problematic mail id?

\r\n.\r\n is the end of response mark in POP3 protocol.

OK, thanks a lot. I found the ID and now thunderbird starts to get mails again, though with many old mails.

"It's possible, but we still need to show the error message. Which means you will see the same error dialogs every time."
I would rather to see this instead of totally not working.

Btw, I reverted back to the old non-js module since I worry about the popstate.dat shrinking again.

hmm...after receiving the mail with the old pop3 module, the popstate.dat also shrinks from 1650KB to 1038KB.
Strangely, I can not get pop3 logs with MOZ_LOG and MOZ_LOG_FILE env variables this time. The log file is created but it's empty.

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

Attachment

General

Creator:
Created:
Updated:
Size: