Closed Bug 1778689 Opened 2 years ago Closed 2 years ago

pop3 Failed to send because socket state is closed

Categories

(MailNews Core :: Networking: POP, defect)

Thunderbird 102
defect

Tracking

(Not tracked)

RESOLVED WORKSFORME

People

(Reporter: arekm, Unassigned)

References

(Blocks 1 open bug)

Details

User Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/103.0.0.0 Safari/537.36

Steps to reproduce:

Thunderbird 102.0.1.

Receinving new mail from pop3 account. This started happening with 102.0 release.

Actual results:

While fetching "Error with account my@email
Unable to write the email to the mailbox. Make sure the file system allows you write privileges, and you have enough disk space to copy the mailbox."

keeps popping up over and over. Clicking "ok" - it pops again. I can do nothing in thunderbird now because it keeps poping up again and again. Main UI is then blocked - nothing can be done there.

From debugging:

627 fewer lines
mailnews.pop3.46: C: RETR 18548 Pop3Client.jsm:424:20
mailnews.pop3.46: S: +OK 26612 oct Pop3Client.jsm:302:18
mailnews.pop3.46: S: ets

Return-Path:

[...]

f3x8fHh4eHV1dXNzc3FxcXBwc Pop3Client.jsm:302:18
ailnews.pop3.46: Got an error name=pop3MessageWriteError Pop3Client.jsm:1231:18
_actionError resource:///modules/Pop3Client.jsm:1231
_actionRetrResponse resource:///modules/Pop3Client.jsm:1176
read resource:///modules/LineReader.jsm:51
_actionRetrResponse resource:///modules/Pop3Client.jsm:1169
_onData resource:///modules/Pop3Client.jsm:304
mailnews.pop3.46: Done with status=2147500037 Pop3Client.jsm:1262:18
mailnews.pop3.46: Folder lock released. Pop3Client.jsm:1275:20
mailnews.pop3.46: C: QUIT Pop3Client.jsm:424:20
mailnews.pop3.46:
S: G9vb2xsbGtra2lpaWZmZmNjY2JiYmBgYFtbW1NTU1FRUUtLS0hI

[...]
cKOUIpcY…
Pop3Client.jsm:302:18
mailnews.pop3.46: Connection closed. Pop3Client.jsm:325:18

On server side I see connection properly closed:

Jul 8 13:16:58 mbox dovecot[1389]: pop3(ar): pid=<26697> session=<dqhhVEnjpcNb6rD6>, expunge: box=INBOX, uid=703, msgid=, size=3268
Jul 8 13:16:58 mbox dovecot[1389]: pop3(ar): pid=<26697> session=<dqhhVEnjpcNb6rD6>, expunge: box=INBOX, uid=703, msgid=, size=3281
Jul 8 13:16:58 mbox dovecot[1389]: pop3(ar): pid=<26697> session=<dqhhVEnjpcNb6rD6>, expunge: box=INBOX, uid=703, msgid=<f2b397e846d1fa3ac6e4e3aec9e01549@example.com>, size=3788
Jul 8 13:16:58 mbox dovecot[1389]: pop3(ar): pid=<26697> session=<dqhhVEnjpcNb6rD6>, Disconnected: Logged out top=0/0, retr=73/1446102, del=531/19224, size=1268154976, in=6102, out=2451499

then with each "OK" on "Error with account" I'm getting

mailnews.pop3.46: Got an error name=pop3MessageWriteError Pop3Client.jsm:1231:18
_actionError resource:///modules/Pop3Client.jsm:1231
_actionRetrResponse resource:///modules/Pop3Client.jsm:1176
read resource:///modules/LineReader.jsm:51
_actionRetrResponse resource:///modules/Pop3Client.jsm:1169
_onData resource:///modules/Pop3Client.jsm:304
mailnews.pop3.46: Done with status=2147500037 Pop3Client.jsm:1262:18
mailnews.pop3.46: Folder lock released. Pop3Client.jsm:1275:20
mailnews.pop3.46: C: QUIT Pop3Client.jsm:424:20
mailnews.pop3.46: Failed to send because socket state is closed Pop3Client.jsm:428:20

and over

mailnews.pop3.46: Got an error name=pop3MessageWriteError Pop3Client.jsm:1231:18
mailnews.pop3.46: Done with status=2147500037 Pop3Client.jsm:1262:18
mailnews.pop3.46: Folder lock released. Pop3Client.jsm:1275:20
mailnews.pop3.46: C: QUIT Pop3Client.jsm:424:20
mailnews.pop3.46: Failed to send because socket state is closed Pop3Client.jsm:428:20

and over

mailnews.pop3.46: Got an error name=pop3MessageWriteError Pop3Client.jsm:1231:18

Looks like is is trying to use already closed connection.

Expected results:

Should normally fetch messages over pop3 without errors.

Failed to send because socket state is closed

This error is harmless.

Looks like is is trying to use already closed connection.

I don't think so, it's not in the logs you pasted, but if you look closer at your console, there will be Connecting to ... every time, which means a new connection is established.

As I mentioned in bug 1778329, what is important is the

...
mailnews.pop3.0: Folder lock acquired uri=mailbox://test@pop3.localhost/Inbox.
...
mailnews.pop3.0: Folder lock released.

When the error dialog shows up (let's say t1), go back to find the last Folder lock acquired log (let's say t0), please share the logs between t0 and t1, thanks.

"and over" is a moment where I was clicking "Ok" in "Error with account" error message popup. I see no "Connecting to" between. I'll save entire log next time when this happens.

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

2022-07-11_1317_mass-mark-TB102found

Blocks: tb102found

Did it ever happen again?

Yes, after system restart and macos restoring thunderbird but I didn't have console activated (so no logs) and couldn't click it in menu when it happened (due to main window not accessible when error message pops up).

I've seen this message occasionally, including out of the blue today. I have one account set for automatic (timed) polling to get new messages, and we poll a few others on demand (including the timed one sometimes). Usually, only valid emails come down, but -- unpredictably -- once in a while we'll get a bunch of duplicate messages for an account.

Today I manually polled the timed account and for no reason it attempted to download 7 duplicate messages. (I know because there was nothing new in the account -- and I know that because I haven't sent to it in a while.) The status line flipped through the usual connection info and said "Downloading 1 of 7" before quickly erasing the status line and popping up the error: "Unable to write the email to the mailbox. Make sure... (etc)" I cancelled the popup and tried the poll again. This time it attempted 4 messages, and they came down OK -- all dups as expected.

This is just one of several bugs that seem to pop up at random and then disappear as though fixed. I'm now running TB 103.0.2 and this is this bug's first occurrence under that version. I tried several of our other accounts (including this one yet again) and none gave dups. But next Tuesday one of them will.

FYI, running Windows 7 Pro (32 bit) and Norton Security AV. TB accounts are all POP3 using MBOX.

Severity: -- → S3
Flags: needinfo?(arekm)
Whiteboard: [closeme 2022-10-01][needs protocol log]

Don't have anything new since I didn't get this error anymore. I assume it got fixed in some later release.

Flags: needinfo?(arekm)

Thanks for the update

Status: UNCONFIRMED → RESOLVED
Closed: 2 years ago
Resolution: --- → WORKSFORME
Whiteboard: [closeme 2022-10-01][needs protocol log]

Sorry, in my Comment 6, I quoted the version of my Firefox. At the time (since 10-Aug-2022), I had been running TB 102.1.1.

In any case, I likewise have not seen this popup in awhile -- now running TB 102.2.2 and I presume fixed.

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