Closed Bug 1774732 Opened 2 years ago Closed 2 years ago

The DELE command did not succeed. Error marking a message as deleted.

Categories

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

Thunderbird 102

Tracking

(thunderbird_esr91 unaffected, thunderbird_esr102 fixed, thunderbird103 fixed)

RESOLVED FIXED
104 Branch
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)

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.

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.

(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?

(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

Component: Networking: SMTP → Networking: POP

(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...

(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?

We will supply the POP3 log when it happens again, we've already set the logging option to be prepared.

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.

(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.

Blocks: tb102found
See Also: → 1776727

(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.

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.

Flags: needinfo?(remotenonsense)

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.

Flags: needinfo?(remotenonsense)

(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). The ted 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.

Prevent unexpected error when a response is broken into multiple ondata events..

Assignee: nobody → remotenonsense
Status: UNCONFIRMED → ASSIGNED
Ever confirmed: true

Initialise this._pendingPayload somewhere? Or you rely on it to be undefined first time around?

Yes, I'm relying on it being undefined at first. It doesn't matter a lot because it's only used inside _onData.

Priority: -- → P1

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.

Target Milestone: --- → 104 Branch

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

Status: ASSIGNED → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED

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

Attachment #9283345 - Flags: approval-comm-beta?

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

Attachment #9283345 - Flags: approval-comm-beta? → approval-comm-beta+

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

Attachment #9283345 - Flags: approval-comm-esr102?

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)

Flags: needinfo?(remotenonsense)
Flags: needinfo?(bugzilla2007)
Attachment #9283345 - Flags: approval-comm-esr102? → approval-comm-esr102+

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.

Flags: needinfo?(remotenonsense)

^^

Flags: needinfo?(bugzilla2007)
Regressions: 1883760
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: