The DELE command did not succeed. Error marking a message as deleted.
Categories
(MailNews Core :: Networking: POP, defect, P1)
Tracking
(thunderbird_esr91 unaffected, thunderbird_esr102 fixed, thunderbird103 fixed)
Tracking | Status | |
---|---|---|
thunderbird_esr91 | --- | unaffected |
thunderbird_esr102 | --- | fixed |
thunderbird103 | --- | fixed |
People
(Reporter: rachel, Assigned: rnons)
References
(Blocks 1 open bug, Regression)
Details
(Keywords: regression)
Attachments
(1 file)
48 bytes,
text/x-phabricator-request
|
wsmwk
:
approval-comm-beta+
wsmwk
:
approval-comm-esr102+
|
Details | Review |
User Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:91.0) Gecko/20100101 Firefox/91.0
Steps to reproduce:
With TB 102 beta we occasionally get this error:
The DELE command did not succeed. Error marking a message as deleted.
The error console has:
mailnews.pop3.5: Got an error name=pop3DeleFailure Pop3Client.jsm:1231:18
_actionError resource:///modules/Pop3Client.jsm:1231
_actionDeleteResponse resource:///modules/Pop3Client.jsm:1217
_onData resource:///modules/Pop3Client.jsm:304
Looks like this is coming from the server, but it's the same server that was used with TB 91 and it's unlikely that it changed. After dismissing the error we can't see anything abnormal. If there were an error deleting a message from the server, one would expect that it will be downloaded again, but that doesn't appear to be the case.
Assignee | ||
Comment 1•2 years ago
|
||
I checked the code just now, we don't send DELE
if a uidl is not returned in this session. So seems like a timing issue
C: UIDL
S: 1 uidl1
..
99 uidl99
C: RETR 1
S: ...
// When handling uidl1-98, uidl99 somehow get removed from server.
C: DELE 99
S: error
Well, this is only my guess. Do you get a server error message when this happens? (Sorry, I forgot to log it)
If it happens a lot, I can remove the error dialog, the error is not actionable so doesn't seem helpful to me.
Reporter | ||
Comment 2•2 years ago
|
||
(In reply to Ping Chen (:rnons) from comment #1)
Do you get a server error message when this happens? (Sorry, I forgot to log it)
Where would we get this? With logging turned on?
If it happens a lot, I can remove the error dialog, the error is not actionable so doesn't seem helpful to me.
It happens occasionally, like once or twice a week. Did the C++ version also issue this error?
Assignee | ||
Comment 3•2 years ago
|
||
(In reply to Rachel Martin from comment #2)
(In reply to Ping Chen (:rnons) from comment #1)
Do you get a server error message when this happens? (Sorry, I forgot to log it)
Where would we get this? With logging turned on?
Set mailnews.pop3.loglevel
to All
, thanks.
If it happens a lot, I can remove the error dialog, the error is not actionable so doesn't seem helpful to me.
It happens occasionally, like once or twice a week. Did the C++ version also issue this error?
The C++ code is here https://searchfox.org/comm-central/rev/97fafb8294c5f9c9c65d33888a03f89a10b0b19e/mailnews/local/src/nsPop3Protocol.cpp#3443
Updated•2 years ago
|
Comment 4•2 years ago
|
||
(In reply to Ping Chen (:rnons) from comment #1)
I checked the code just now, we don't send
DELE
if a uidl is not returned in this session. So seems like a timing issue
// When handling uidl1-98, uidl99 somehow get removed from server. C: DELE 99 S: error
It could be. Perhaps via a parallel connection of a 2nd client.
However, this would be a serious failure of the server:
RFC 1939 - 5. The TRANSACTION State
| Once the client has successfully identified itself to the POP3 server
| and the POP3 server has locked and opened the appropriate maildrop,
| the POP3 session is now in the TRANSACTION state. The client may now
| issue any of the following POP3 commands repeatedly. After each
| command, the POP3 server issues a response. Eventually, the client
| issues the QUIT command and the POP3 session enters the UPDATE state.
The e-mail list must not change during the TRANSACTION state.
It is thinkable that we do not want to delete all messages at all. But if on the server one of the front mails was removed, the correlation doesn't fit anymore!
(1(1¢)
If it happens a lot, I can remove the error dialog, the error is not actionable so doesn't seem helpful to me.
I also don't see how we could respond in any meaningful way here.
For a great solution, we would need to reset the status (RSET
), re-read and -match the UIDL, and start the deletion process all from scratch.
But, holy moly...
Comment 5•2 years ago
|
||
(In reply to Ping Chen (:rnons) from comment #1)
If it happens a lot, I can remove the error dialog, the error is not actionable so doesn't seem helpful to me.
Another thought: What happens in case of an error message?
- The connection is terminated and the e-mails remain on the server, or
- is the QUIT command executed despite the error and the mails are deleted?
Reporter | ||
Comment 6•2 years ago
|
||
We will supply the POP3 log when it happens again, we've already set the logging option to be prepared.
Assignee | ||
Comment 7•2 years ago
|
||
It could be. Perhaps via a parallel connection of a 2nd client.
However, this would be a serious failure of the server:
The message can also be removed by an IMAP connection or a filter.
Another thought: What happens in case of an error message?
Yes, quit is sent on error. But if the uidl is still on the server, because d
flag is still associated with it in our popstate.dat, DELE
will be sent the next time. https://searchfox.org/comm-central/rev/fe6b350f9bdd45dd40a35a43a18ac3af7f605b41/mailnews/local/src/Pop3Client.jsm#1269
We will supply the POP3 log when it happens again, we've already set the logging option to be prepared.
Thanks, with logging turned on, you can also check whether the specific uidl is returned in the UIDL
response.
Comment 8•2 years ago
|
||
(In reply to Ping Chen (:rnons) from comment #7)
Yes, quit is sent on error. But if the uidl is still on the server, because
d
flag is still associated with it in our popstate.dat,DELE
will be sent the next time. https://searchfox.org/comm-central/rev/fe6b350f9bdd45dd40a35a43a18ac3af7f605b41/mailnews/local/src/Pop3Client.jsm#1269
However, I'm more concerned about the fact that due to the incorrect assignment, messages are deleted that were not marked for deletion.
Reporter | ||
Updated•2 years ago
|
Reporter | ||
Comment 9•2 years ago
|
||
(In reply to Rachel Martin from comment #6)
We will supply the POP3 log when it happens again, we've already set the logging option to be prepared.
BTW, it has not happened since this comment was written.
Reporter | ||
Comment 10•2 years ago
|
||
OK, so this morning it happened again. It's hard to copy all the console messages since the context menu options "copy all" and "save all to file" are broken (TypeError: toolbox is null - context-menu.js:341:42). Also, the logging contains the full message text and sadly also the passwords are logged. It's actually quite difficult to compile this information since it contains heaps of private data.
Assuming that in mailnews.pop3.NN the NN identifies all actions taken for a specific account, here are the lines for the faulty behaviour:
08:46:24.649 mailnews.pop3.0: Connecting to pop://mail.SSSS:995 7 Pop3Client.jsm:129:18
08:46:26.468 mailnews.pop3.0: S: +OK POP3 perditon ready on ::ffff:192.168.0.12 0003fbce
08:46:26.853 mailnews.pop3.0: C: CAPA Pop3Client.jsm:424:20
08:46:26.909 mailnews.pop3.0: S: +OK Capability list follows, mate
08:46:26.909 mailnews.pop3.0: Possible auth methods: USERPASS Pop3Client.jsm:501:18
08:46:26.910 mailnews.pop3.0: Current auth method: USERPASS Pop3Client.jsm:577:18
08:46:26.910 mailnews.pop3.0: C: USER UUUU Pop3Client.jsm:424:20
08:46:26.956 mailnews.pop3.0: S: +OK USER UUUU set, mate
08:46:26.963 mailnews.pop3.0: C: PASS XXXX Pop3Client.jsm:424:20
08:46:27.072 mailnews.pop3.0: S: +OK You are so in
08:46:27.072 mailnews.pop3.0: C: STAT Pop3Client.jsm:424:20
08:46:27.131 mailnews.pop3.0: S: +OK 9 208444
08:46:27.131 mailnews.pop3.0: Folder lock acquired uri=mailbox://UUUU@SSSS/Inbox. Pop3Client.jsm:866:22
08:46:27.131 mailnews.pop3.0: C: LIST Pop3Client.jsm:424:20
08:46:27.357 mailnews.pop3.0: S: +OK 9 messages:
08:46:27.358 mailnews.pop3.0: C: UIDL Pop3Client.jsm:424:20
08:46:27.502 mailnews.pop3.0: S: +OK
08:46:27.502 mailnews.pop3.0: C: RETR 1 Pop3Client.jsm:424:20
08:46:27.572 mailnews.pop3.0: S: +OK 2817 octets
08:46:28.269 mailnews.pop3.0: C: DELE 1 Pop3Client.jsm:424:20
08:46:31.752 mailnews.pop3.0: S: +OK Marked to be deleted.
08:46:31.752 mailnews.pop3.0: C: RETR 2 Pop3Client.jsm:424:20
08:46:32.056 mailnews.pop3.0: C: DELE 2 Pop3Client.jsm:424:20
08:46:32.150 mailnews.pop3.0: S: +OK Marked to be deleted.
08:46:32.150 mailnews.pop3.0: C: RETR 3 Pop3Client.jsm:424:20
08:46:32.328 mailnews.pop3.0: C: DELE 3 Pop3Client.jsm:424:20
08:46:32.370 mailnews.pop3.0: S: +OK Marked to be deleted.
08:46:32.370 mailnews.pop3.0: C: RETR 4 Pop3Client.jsm:424:20
08:46:32.424 mailnews.pop3.0: S: +OK 58478 octets
08:46:32.481 mailnews.pop3.0: C: DELE 4 Pop3Client.jsm:424:20
08:46:32.539 mailnews.pop3.0: S: +OK Marked to be deleted.
08:46:32.539 mailnews.pop3.0: C: RETR 5 Pop3Client.jsm:424:20
08:46:32.688 mailnews.pop3.0: C: DELE 5 Pop3Client.jsm:424:20
08:46:32.733 mailnews.pop3.0: S: +OK Marked to be deleted.
08:46:32.733 mailnews.pop3.0: C: RETR 6 Pop3Client.jsm:424:20
08:46:32.775 mailnews.pop3.0: S: +OK 11363 octets
08:46:32.820 mailnews.pop3.0: C: DELE 6 Pop3Client.jsm:424:20
08:46:32.875 mailnews.pop3.0: S: +OK Marked to be dele Pop3Client.jsm:302:18
mailnews.pop3.0: Got an error name=pop3DeleFailure Pop3Client.jsm:1231:18
08:46:32.875 mailnews.pop3.0: Done with status=2147500037 Pop3Client.jsm:1262:18
08:46:32.875 mailnews.pop3.0: Folder lock released. Pop3Client.jsm:1275:20
08:46:32.875 mailnews.pop3.0: C: QUIT Pop3Client.jsm:424:20
08:46:32.917 mailnews.pop3.0: S: ted.
08:46:32.917 mailnews.pop3.0: Connection closed. Pop3Client.jsm:325:18
We've kept the full log in case you need more information. In summary, it looks like there are 9 messages, 1-6 are retrieved and deleted, during the deletion of 6, the message is somewhat truncated +OK Marked to be dele
with the missing ted
being logged later. The error is 0x80004005 (2147500037) - NS_ERROR_FAILURE. After that, the connection is closed, presumably, the remaining 3 messages are retrieved later.
Assignee | ||
Comment 11•2 years ago
|
||
The logs are very helpful, I think the problem is the response to DELE 6
is somehow broken into two chunks (two ondata events). The ted
chunk doesn't begin with +OK
so is seen as an error.
Perhaps I need to use _lineReader
to handle every response. Will make a fix, thanks.
Assignee | ||
Comment 12•2 years ago
|
||
(In reply to Ping Chen (:rnons) from comment #11)
The logs are very helpful, I think the problem is the response to
DELE 6
is somehow broken into two chunks (two ondata events). Theted
chunk doesn't begin with+OK
so is seen as an error.
It's the +OK Marked to be dele
part that failed let matches = /^(\+OK|-ERR|\+) ?(.*)\r\n([^]*)/.exec(str);
because of no \r\n
.
Assignee | ||
Comment 13•2 years ago
|
||
Prevent unexpected error when a response is broken into multiple ondata events..
Updated•2 years ago
|
Reporter | ||
Comment 14•2 years ago
|
||
Initialise this._pendingPayload
somewhere? Or you rely on it to be undefined
first time around?
Assignee | ||
Comment 15•2 years ago
•
|
||
Yes, I'm relying on it being undefined at first. It doesn't matter a lot because it's only used inside _onData.
Updated•2 years ago
|
Updated•2 years ago
|
Reporter | ||
Comment 16•2 years ago
|
||
As Martin pointed out, it would be more robust to split the buffer at CRLF, process the line before and keep the rest for later.
Assignee | ||
Updated•2 years ago
|
Comment 17•2 years ago
|
||
Pushed by nicolai@thunderbird.net:
https://hg.mozilla.org/comm-central/rev/81727230c4f8
Start parsing server response in Pop3Client only when \r\n is found. r=freaktechnik
Assignee | ||
Comment 18•2 years ago
|
||
Comment on attachment 9283345 [details]
Bug 1774732 - Start parsing server response in Pop3Client only when \r\n is found. r=#thunderbird-reviewers
[Approval Request Comment]
Regression caused by (bug #): bug 1707548
User impact if declined: In some rare cases, successful server responses are parsed as error.
Testing completed (on c-c, etc.): c-c
Risk to taking this patch (and alternatives if risky): low
Comment 19•2 years ago
|
||
Comment on attachment 9283345 [details]
Bug 1774732 - Start parsing server response in Pop3Client only when \r\n is found. r=#thunderbird-reviewers
[Triage Comment]
Approved for beta
Comment 20•2 years ago
|
||
bugherder uplift |
Thunderbird 103.0b4:
https://hg.mozilla.org/releases/comm-beta/rev/4253f9a4cd83
Comment 21•2 years ago
|
||
Comment on attachment 9283345 [details]
Bug 1774732 - Start parsing server response in Pop3Client only when \r\n is found. r=#thunderbird-reviewers
[Approval Request Comment]
Regression caused by (bug #): bug 1707548
User impact if declined: In some rare cases, successful server responses are parsed as error.
Testing completed (on c-c, etc.): 103.0b4
Risk to taking this patch (and alternatives if risky): low
Comment 22•2 years ago
|
||
Comment on attachment 9283345 [details]
Bug 1774732 - Start parsing server response in Pop3Client only when \r\n is found. r=#thunderbird-reviewers
[Triage Comment]
Approved for esr102
Thomas and/or Ping, can you test this and confirm fixed with no ill effects with the candidate build? (available over the weekend)
Comment 23•2 years ago
|
||
bugherder uplift |
Thunderbird 102.0.2:
https://hg.mozilla.org/releases/comm-esr102/rev/35c7fe92ab45
Assignee | ||
Comment 24•2 years ago
|
||
confirm fixed
I don't think the problem can be reproduced on all pop3 servers. I haven't noticed anything broken by the fix so far.
Description
•