1702360 - IMAP CONNECTION PROBLEMS ON SEND

Status: RESOLVED FIXED

(MailNews Core :: Networking: SMTP, defect)

Description

[Matt Weatherford]

Attachment: Screen Shot 2021-03-31 at 3.52.32 PM.png

User Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/14.0.3 Safari/605.1.15

Steps to reproduce:

try to send mail with IMAP with OAUTH2

get long timeouts and errors about connection/auth failures to IMAP.gmail.com

Actual results:

fails to write to sent folder, but message appears to send.
incoming mail is working fine with server

See this message: "Your message was sent but a copy was not placed in your sent folder (Sent Mail) due to network or file access errors.
You can retry or save the message locally to Local Folders/Sent [e-mail] GMAIL."
Note that my SMTP server is not google and uses a username/password login, whereas my gmail connection uses OAUTH2 tokens.

This worked fine on the past 6 months worth of betas on the beta channel. Something changed.

Comment 1

[Ping Chen [:rnons] (away)]

Attachment: Bug 1702360 - Add more debug logs to MessageSend.jsm. r=mkmelin

Comment 2

[Ping Chen [:rnons] (away)]

Hi Matt, I can't reproduce this, the patch is only adding debug logs. Do I understand correctly that you have two mail accounts? In the "Copies & Folders" setting of your [e-mail] account, you set "Place a copy in:" to the Sent folder of your GMail account?

Does the error happen every time, what happens if you click the Retry button?

Comment 3

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/comm-central/rev/462e577460bf
Add more debug logs to MessageSend.jsm. r=mkmelin

Comment 4

[Matt Weatherford]

Ping, Im am on OS X if that helps. I have several Mac systems that have this problem, both are on Mac OS X Catalina with thunderbird 88 beta 1
But they are likely copies of my. thunderbird account settings.

I have at many imap mail accounts in my thunderbird setup - I think there are at least 6 in the instance I am using on my iMac
Most are gmail based, but one or more may be outlook O365 in IMAP mode. I use those rarely though, my primary work is in the IMAP/OAUTH2/Gmail accounts

I checked my settings and yes, the folders setting on "place a copy in:" is set to "sent mail on Gmail account"

I would be happy to schedule a zoom/screen share if that is useful

What other debug info can I send you?

Comment 5

[Matt Weatherford]

And if I click "retry" over and over, it still fails. Activity monitor shows IMAP authentication failures and timeouts

I have occasionally got the "retry" button to work - and I think it always works if I choose. "Save locally"

Comment 6

[Matt Weatherford]

Clarification: I think the message sends, its just the "save in sent folder" piece that is failing.

Comment 7

[Matt Weatherford]

I have just found some problems with my internet connection at home (very slow dns lookups, possibly one or more DNS server offline) that could be causing this problem. Please don't spend any more time on this until I resolve those issues. But yes, more debug information is always helpful.

Comment 8

[Ping Chen [:rnons] (away)]

To see the debug logs, please try TB nightly or wait for 89. You can copy your current profile folder to a new folder and use it for nightly. Set mailnews.send.loglevel to All, then when sending a mail, logs containing mailnews.send should show up in the Console tab of devtools.

Copying to a configured folder or a local folder is a step happens after sending to the SMTP server. With the logs hopefully we can get the error code in the copying process, so we can understand the problem better. Thanks.

Comment 9

[Matt Weatherford]

I am still having the problem after exhaustive debug on my home internet. Everything on my home internet is verified fine now.
Wife's tbird stable on Ubuntu 20.04 on same internet conn is working without issue (she uses OAuth2 v/gmail, but not gmail apps for edu, and using gmail's smtp)

I have installed tbird thunderbird-89.0a1.en-US.mac.dmg and set up my account from scratch.

I still see long delays in writing to sent folder, but havent seen the error yet.

forgive me, I havent done tbird debug in a while, how do I set that setting? "Set mailnews.send.loglevel to All". ???
LMK how to turn on that setting for Tbird nightly, and I'll provide more detail

thanks to you, and to all Tbird devs - I love me some birdcage

Matt

Comment 10

[José M. Muñoz]

Can someone please link to bug 1701864, bug 1702840, bug 1701268 and bug 1701996 which all report sending problems in TB 88.

Comment 11

[José M. Muñoz]

... and bug 1702838.

Comment 12

[Ping Chen [:rnons] (away)]

(In reply to Matt Weatherford from comment #9)

forgive me, I havent done tbird debug in a while, how do I set that setting? "Set mailnews.send.loglevel to All". ???
LMK how to turn on that setting for Tbird nightly, and I'll provide more detail

On the Preferences page, search for Config Editor, open it, then search for mailnews.send.loglevel, double click it to edit the value to All. After that, when sending a mail, you should see debug logs.

It might worth to click the Console Setting (the gear icon on the top right of devtools), to turn on Show timestamps, so that we can tell from the logs how much time each step takes.

Comment 13

[Ping Chen [:rnons] (away)]

Hi Matt, do you still have the old profile which you can reproduce this bug? Can you check the values of mailnews.send.jsmodule and mailnews.smtp.jsmodule, they should both be true.

Comment 14

[Matt Weatherford]

Attachment: Error console, Tbird 88b2 save to "sent folder" issue

Both were already set to true. I have done the above (on (not-nightly)  tbird 88beta2) -  Im now trying to figure out where the useful logs are so I can put them here. I am still having the issue. 

Heres some stuff from the error console, does this look right?

Comment 15

[Matt Weatherford]

Attachment: tbird 88b2 - save to gmail sent folder failure

Both were already set to true. I have done the above (on (not-nightly)  tbird 88beta2) -  Im now trying to figure out where the useful logs are so I can put them here. I am still having the issue. 

Heres some stuff from the error console, does this look right?

Comment 16

[Matt Weatherford]

Both were already set to true. I have done the above (on (not-nightly) tbird 88beta2) - Im now trying to figure out where the useful logs are so I can put them here. I am still having the issue.

Heres some stuff from the error console, does this look right? https://pastebin.com/9xDUC8Bk

BTW: your log upload paste/S3 setup didn't work for me, I got errors. Hence PasteBin

Matt

Comment 17

[Ping Chen [:rnons] (away)]

NS_ERROR_NOT_AVAILABLE: PreferDisplayName: undefined - not a boolean 2 AddrBookCard.jsm:166
    getPropertyAsBool resource:///modules/AddrBookCard.jsm:166
    openWindowPrompt resource:///actors/PromptParent.jsm:161
    receiveMessage resource:///actors/PromptParent.jsm:108
    openPrompt resource://gre/modules/Prompter.jsm:1174
    openPromptSync resource://gre/modules/Prompter.jsm:1054
    confirmEx resource://gre/modules/Prompter.jsm:1449
    notifyListenerOnStopCopy resource:///modules/MessageSend.jsm:430

This seems related, I will look into the code and ask for your help later. Thanks.

Comment 18

[Ping Chen [:rnons] (away)]

I can't figure out what's wrong. Are you OK with using the nightly for the moment, and after a new beta release, let's debug it again?

Alternatively, you can run TB from the terminal with MOZ_LOG=MsgCopyService:5 ./Applications/Thunderbird.app --devtools, when sending a mail, some logs like the following will be printed in the terminal

[Parent 22465: Main Thread]: I/MsgCopyService request 7f84e32ba8e0 DoCopy - src  dest 
[Parent 22465: Main Thread]: I/MsgCopyService NotifyCompletion - src  dest 
[Parent 22465: Main Thread]: I/MsgCopyService request 7f84e32ba8e0 Clearing OK request - src  dest 

Comment 19

[José M. Muñoz]

"PreferDisplayName: undefined - not a boolean - AddrBookCard.jsm:166" --> See bug 1652274.

Comment 20

[Matt Weatherford]

Attachment: Error console

Im on nightly this am (89alpha1). and not seeing the problem. Heres the error console:

Comment 21

[Matt Weatherford]

Im on nightly this am (89alpha1). and not seeing the problem any more, saving to "Sent-messages" works as expected on send. Heres the error console, attached,

89.0a1 (2021-04-06) (64-bit). Mac OS X

Comment 22

[Wayne Mery (:wsmwk)]

rnons, we're going to build beta 3 on Monday. Is this patch not quite ready?

Comment 23

[José M. Muñoz]

The changeset from comment #3 is just adding more logging. The issue was likely fixed in bug 1701804. It would make sense to take the changeset to beta so the logging there is consistent with trunk and also so that the other bugs can be uplifted without merge conflicts. The reporter confirmed that it's now working in Daily comment #21.

Comment 24

[Ping Chen [:rnons] (away)]

Comment on attachment 9212982 [details]
Bug 1702360 - Add more debug logs to MessageSend.jsm. r=mkmelin

[Approval Request Comment]
Regression caused by (bug #): bug 1211292
User impact if declined: Not enough debug log when sending failed
Testing completed (on c-c, etc.): c-c
Risk to taking this patch (and alternatives if risky): low

Comment 25

[Wayne Mery (:wsmwk)]

Comment on attachment 9212982 [details]
Bug 1702360 - Add more debug logs to MessageSend.jsm. r=mkmelin

[Triage Comment]
Approved for beta

Comment 26

[Matt Weatherford]

Attachment: 89.0a1 nightly Error console

Just tried sending w/Tbird Daily:  89.0a1 (2021-04-10) (64-bit) Mac OS X - Catalina 10.15.7

Looks good

Will try the next beta when it comes out. Thank you all !  


There were a few errors in the console, the attachment errors came from an "Edit an old sent message as new"

Comment 27

[Matt Weatherford]

Just tried sending w/Tbird Daily: 89.0a1 (2021-04-10) (64-bit) Mac OS X - Catalina 10.15.7

Looks good

Will try the next beta when it comes out. Thank you all !

There were a few errors in the console, the attachment errors came from an "Edit an old sent message as new"

Comment 28

[Ping Chen [:rnons] (away)]

(In reply to Matt Weatherford from comment #27)

There were a few errors in the console, the attachment errors came from an "Edit an old sent message as new"

How many attachments does the old sent message contain? Does it work if you try to download the attachments?

If downloading works, please file a new bug, set mailnews.send.loglevel to All in the config editor, so that all debug logs are printed.

When you see this error message mailnews.send: Failed to fetch attachment: name=Attached Message Part, url=file:///var/folders/xm/8lwg19ys5h302lr_rbsftlxr0000gn/T/nsmail-1.txt MimePart.jsm:161:29, if you go to the tmp folder /var/folders/xm/8lwg19ys5h302lr_rbsftlxr0000gn/T/, are there any nsmail* files?

Comment 29

[Rob Lemley [:rjl]]

Thunderbird 88.0b3:
https://hg.mozilla.org/releases/comm-beta/rev/482ddce91ef0

Comment 30

[Matt Weatherford]

Confirming that 88.0b3 (64-bit) on OS X NO LONGER HAS THIS PROBLEM

Thank you !
Matt

p.s. I'm including some logs below - looks like the extra logging is working too

NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIAutoCompleteInput.popup] LoginManagerChild.jsm:194
NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIAbDirectory.search] AbAutoCompleteSearch.jsm:211
NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIAutoCompleteInput.popup] LoginManagerChild.jsm:194
NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIAbDirectory.search] AbAutoCompleteSearch.jsm:211
NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIAutoCompleteInput.popup] LoginManagerChild.jsm:194
NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIAbDirectory.search] AbAutoCompleteSearch.jsm:211
NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIAutoCompleteInput.popup] 2 LoginManagerChild.jsm:194
Prompter: internal dialogs not available in this context. Falling back to window prompt. Prompter.jsm:1033
mailnews.send: Creating message file MessageSend.jsm:117:25
mailnews.send: Message file created MessageSend.jsm:138:25
mailnews.send: Processing fcc; folderUri=imap://[e-mail]/[Gmail]/Drafts MessageSend.jsm:864:25
mailnews.send: fcc file created MessageSend.jsm:896:25
mailnews.send: startCopyOperation MessageSend.jsm:908:25
mailnews.send: notifyListenerOnStartCopy MessageSend.jsm:366:25
mailnews.send: notifyListenerOnStopCopy; status=0 MessageSend.jsm:384:25
mailnews.send: Clean up temporary files MessageSend.jsm:980:25
NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIAutoCompleteInput.popup] LoginManagerChild.jsm:194
Prompter: internal dialogs not available in this context. Falling back to window prompt. Prompter.jsm:1033
mailnews.send: Creating message file MessageSend.jsm:117:25
mailnews.send: Message file created MessageSend.jsm:138:25
mailnews.send: Delivering mail message MessageSend.jsm:1021:25
mailnews.smtp: S: 220 smtp.washington.edu ESMTP Sendmail 8.14.4+UW20.07/8.14.4+UW19.10; Wed, 14 Apr 2021 21:53:26 -0700

SmtpClient.jsm:426:17
mailnews.smtp: C: EHLO [127.0.0.1] SmtpClient.jsm:559:19
mailnews.smtp: S: 250-smtp.washington.edu Hello [10.104.137.48], pleased to meet you

250-ENHANCEDSTATUSCODES

250-PIPELINING

250-EXPN

250-VERB

250-8BITMIME

250-SIZE 60000000

250-DSN

250-ETRN

250-AUTH GSSAPI PLAIN LOGIN

250-DELIVERBY

250 HELP

SmtpClient.jsm:426:17
mailnews.smtp: Possible auth methods: PLAIN,LOGIN SmtpClient.jsm:851:17
mailnews.smtp: Maximum allowd message size: 60000000 SmtpClient.jsm:857:19
mailnews.smtp: Current auth method: PLAIN SmtpClient.jsm:625:17
mailnews.smtp: Authentication via AUTH PLAIN SmtpClient.jsm:640:21
mailnews.smtp: C: Logging suppressed (it probably contained auth information) SmtpClient.jsm:555:19
mailnews.smtp: S: 235 2.0.0 OK Authenticated

SmtpClient.jsm:426:17
mailnews.smtp: Authentication successful. SmtpClient.jsm:1060:17
mailnews.smtp: C: MAIL FROM:<[e-mail]> BODY=8BITMIME SIZE=1536 RET=FULL ENVID=<[e-mail]> SmtpClient.jsm:559:19
mailnews.smtp: S: 250 2.1.0 <[e-mail]>... Sender ok

#omitted some recipients -mbw

SmtpClient.jsm:426:17
mailnews.smtp: Adding recipient... SmtpClient.jsm:1154:19
mailnews.smtp: C: RCPT TO:<[e-mail]> SmtpClient.jsm:559:19
mailnews.smtp: S: 250 2.1.5 <[e-mail]>... Recipient ok

SmtpClient.jsm:426:17
mailnews.smtp: Adding recipient... SmtpClient.jsm:1154:19
mailnews.smtp: C: RCPT TO:<[e-mail]> SmtpClient.jsm:559:19
mailnews.smtp: S: 250 2.1.5 <[e-mail]>... Recipient ok

SmtpClient.jsm:426:17
mailnews.smtp: Adding recipient... SmtpClient.jsm:1154:19
mailnews.smtp: C: RCPT TO:<[e-mail]> SmtpClient.jsm:559:19
mailnews.smtp: S: 250 2.1.5 <[e-mail]>... Recipient ok

SmtpClient.jsm:426:17
mailnews.smtp: RCPT TO done, proceeding with payload SmtpClient.jsm:1145:21
mailnews.smtp: C: DATA SmtpClient.jsm:559:19
mailnews.smtp: S: 354 Enter mail, end with "." on a line by itself

SmtpClient.jsm:426:17
mailnews.smtp: Sending 1536 bytes of payload SmtpClient.jsm:535:17
mailnews.send: OnStopRunningUrl; exitCode=0 MessageSend.jsm:1277:25
mailnews.smtp: S: 250 2.0.0 13F4rQfj004388 Message accepted for delivery

SmtpClient.jsm:426:17
mailnews.smtp: Message sent successfully. SmtpClient.jsm:1214:21
mailnews.send: Delivery exit processing; exitCode=0 MessageSend.jsm:542:25
mailnews.send: notifyListenerOnStopSending; status=0 MessageSend.jsm:490:25
mailnews.send: Processing fcc; folderUri=imap://[e-mail]/[Gmail]/Sent Mail MessageSend.jsm:864:25
mailnews.send: fcc file created MessageSend.jsm:896:25
mailnews.send: startCopyOperation MessageSend.jsm:908:25
mailnews.send: notifyListenerOnStartCopy MessageSend.jsm:366:25
mailnews.smtp: Closing connection... SmtpClient.jsm:182:17
mailnews.smtp: Idling while waiting for new connections... SmtpClient.jsm:1224:19
mailnews.smtp: Socket closed. SmtpClient.jsm:467:17
mailnews.send: notifyListenerOnStopCopy; status=0 MessageSend.jsm:384:25
mailnews.send: onStopOperation; status=0 MessageSend.jsm:517:25
mailnews.send: Clean up temporary files MessageSend.jsm:980:25
NS_ERROR_NOT_AVAILABLE: PreferDisplayName: undefined - not a boolean 11 AddrBookCard.jsm:166

​

Comment 31

[Ping Chen [:rnons] (away)]

Thanks for confirming.