Emails are silently discarded on 554 reply to STARTTLS

Bug #1215882 reported by Nikolaus Rath on 2013-08-23
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Mozilla Thunderbird
Confirmed
Critical
thunderbird (Ubuntu)
Undecided
Unassigned

Bug Description

It seems that emails are silently discarded when the remote SMTP server replies with an error on STARTTLS. Here is an example smtp log created with NSPR_LOG_MODULES='smtp:5,timestamp':

2013-08-23 11:10:25.548708 UTC - 43480896[7fe10164b370]: SMTP Connecting to: mail.trialphaenergy.com
2013-08-23 11:10:26.513993 UTC - 43480896[7fe10164b370]: SMTP entering state: 0
2013-08-23 11:10:26.514026 UTC - 43480896[7fe10164b370]: SMTP Response: 220 mail.trialphaenergy.com Microsoft ESMTP MAIL Service ready at Fri, 23 Aug 2013 04:10:25 -0700
2013-08-23 11:10:26.514047 UTC - 43480896[7fe10164b370]: SMTP entering state: 14
2013-08-23 11:10:26.514069 UTC - 43480896[7fe10164b370]: SMTP Send: EHLO [10.11.206.9]
2013-08-23 11:10:27.144751 UTC - 43480896[7fe10164b370]: SMTP entering state: 0
2013-08-23 11:10:27.144791 UTC - 43480896[7fe10164b370]: SMTP Response: 250-mail.trialphaenergy.com Hello [10.11.10.19]
2013-08-23 11:10:27.144808 UTC - 43480896[7fe10164b370]: SMTP entering state: 0
2013-08-23 11:10:27.144817 UTC - 43480896[7fe10164b370]: SMTP Response: 250-SIZE
2013-08-23 11:10:27.144828 UTC - 43480896[7fe10164b370]: SMTP entering state: 0
2013-08-23 11:10:27.144839 UTC - 43480896[7fe10164b370]: SMTP Response: 250-PIPELINING
2013-08-23 11:10:27.144846 UTC - 43480896[7fe10164b370]: SMTP entering state: 0
2013-08-23 11:10:27.144851 UTC - 43480896[7fe10164b370]: SMTP Response: 250-DSN
2013-08-23 11:10:27.144857 UTC - 43480896[7fe10164b370]: SMTP entering state: 0
2013-08-23 11:10:27.144862 UTC - 43480896[7fe10164b370]: SMTP Response: 250-ENHANCEDSTATUSCODES
2013-08-23 11:10:27.144868 UTC - 43480896[7fe10164b370]: SMTP entering state: 0
2013-08-23 11:10:27.144885 UTC - 43480896[7fe10164b370]: SMTP Response: 250-STARTTLS
2013-08-23 11:10:27.144889 UTC - 43480896[7fe10164b370]: SMTP entering state: 0
2013-08-23 11:10:27.144893 UTC - 43480896[7fe10164b370]: SMTP Response: 250-AUTH NTLM
2013-08-23 11:10:27.144897 UTC - 43480896[7fe10164b370]: SMTP entering state: 0
2013-08-23 11:10:27.144900 UTC - 43480896[7fe10164b370]: SMTP Response: 250-8BITMIME
2013-08-23 11:10:27.144904 UTC - 43480896[7fe10164b370]: SMTP entering state: 0
2013-08-23 11:10:27.144920 UTC - 43480896[7fe10164b370]: SMTP Response: 250-BINARYMIME
2013-08-23 11:10:27.144926 UTC - 43480896[7fe10164b370]: SMTP entering state: 0
2013-08-23 11:10:27.144931 UTC - 43480896[7fe10164b370]: SMTP Response: 250 CHUNKING
2013-08-23 11:10:27.144936 UTC - 43480896[7fe10164b370]: SMTP entering state: 4
2013-08-23 11:10:27.144961 UTC - 43480896[7fe10164b370]: SMTP entering state: 21
2013-08-23 11:10:27.144968 UTC - 43480896[7fe10164b370]: SMTP Send: STARTTLS
2013-08-23 11:10:27.757848 UTC - 43480896[7fe10164b370]: SMTP entering state: 0
2013-08-23 11:10:27.757881 UTC - 43480896[7fe10164b370]: SMTP Response: 554 Policy violation. Email Session ID: {521742ED-1-F0B0B0A-FFFF}
2013-08-23 11:10:27.757893 UTC - 43480896[7fe10164b370]: SMTP entering state: 19
2013-08-23 11:10:27.757900 UTC - 43480896[7fe10164b370]: SMTP entering state: 21
2013-08-23 11:10:27.757905 UTC - 43480896[7fe10164b370]: SMTP Send: QUIT
2013-08-23 11:10:27.757915 UTC - 43480896[7fe10164b370]: SMTP entering state: 0

The UI, however, gives no indication of failure and closes the compose window after the apparent successful submission to the smtp server.

If the user has not configured a Sent folder this results in data loss. Even if the user has configured a sent folder, he receives no indication that the email has not been sent.

ProblemType: Bug
DistroRelease: Ubuntu 13.04
Package: thunderbird 17.0.8+build1-0ubuntu0.13.04.1
ProcVersionSignature: Ubuntu 3.8.0-27.40-generic 3.8.13.4
Uname: Linux 3.8.0-27-generic x86_64
AddonCompatCheckDisabled: False
ApportVersion: 2.9.2-0ubuntu8.3
Architecture: amd64
AudioDevicesInUse:
 USER PID ACCESS COMMAND
 /dev/snd/controlC0: nikratio 2425 F.... pulseaudio
BuildID: 20130803220711
Channel: Unavailable
Date: Fri Aug 23 13:05:30 2013
ForcedLayersAccel: False
IfupdownConfig:
 # interfaces(5) file used by ifup(8) and ifdown(8)
 auto lo
 iface lo inet loopback
InstallationDate: Installed on 2013-07-30 (23 days ago)
InstallationMedia: Ubuntu 13.04 "Raring Ringtail" - Release amd64 (20130424)
MarkForUpload: True
PrefSources:
 prefs.js
 /usr/lib/mozilla/extensions/{3550f703-e582-4d05-9a08-453d09bdfdc6}/{847b3a00-7ab1-11d4-8f02-006008948af5}/defaults/preferences/enigmail.js
 /usr/lib/mozilla/extensions/{3550f703-e582-4d05-9a08-453d09bdfdc6}/{847b3a00-7ab1-11d4-8f02-006008948af5}/defaults/preferences/000system.js
Prefs:
 extensions.lastAppVersion: "17.0.8" (prefs.js)
 network.cookie.prefsMigrated: true (prefs.js)
 places.database.lastMaintenance: 1377252192 (prefs.js)
 places.history.expiration.transient_current_max_pages: 104858 (prefs.js)
 privacy.donottrackheader.enabled: true (prefs.js)
ProcEnviron:
 TERM=xterm
 PATH=(custom, no user)
 XDG_RUNTIME_DIR=<set>
 LANG=en_US.UTF-8
 SHELL=/bin/bash
Profiles: Profile0 (Default) - LastVersion=17.0.8/20130803220711
RelatedPackageVersions:
 icedtea-7-plugin 1.3.2-1ubuntu1.1
 totem-mozilla 3.6.3-0ubuntu6
 rhythmbox-mozilla 2.98-0ubuntu5
RunningIncompatibleAddons: False
SourcePackage: thunderbird
UpgradeStatus: No upgrade log present (probably fresh install)
dmi.bios.date: 02/04/2013
dmi.bios.vendor: LENOVO
dmi.bios.version: G6ET93WW (2.53 )
dmi.board.asset.tag: Not Available
dmi.board.name: 3444F8U
dmi.board.vendor: LENOVO
dmi.board.version: Win8 Pro DPK TPG
dmi.chassis.asset.tag: No Asset Information
dmi.chassis.type: 10
dmi.chassis.vendor: LENOVO
dmi.chassis.version: Not Available
dmi.modalias: dmi:bvnLENOVO:bvrG6ET93WW(2.53):bd02/04/2013:svnLENOVO:pn3444F8U:pvrThinkPadX1Carbon:rvnLENOVO:rn3444F8U:rvrWin8ProDPKTPG:cvnLENOVO:ct10:cvrNotAvailable:
dmi.product.name: 3444F8U
dmi.product.version: ThinkPad X1 Carbon
dmi.sys.vendor: LENOVO

User Agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:14.0) Gecko/20100101 Firefox/14.0.1
Build ID: 20120713134347

Steps to reproduce:

When I send a mail using an incorrect smtp server (e.g. I have stmp.telenet.be configured but I'm at a customer whose ISP only accepts relay.skynet.be), and the server sends an error message instead of just timing out,

Actual results:

I get an error message (as I used to get), but instead of keeping the composer window open, the composer window is closed and the mail (which has not been sent succesfully) ends up in my SentMail.

Expected results:

Before the latest update, I would get an error message but the composer window would remain open so:
- I would know that sending failed
- I could try again with the correct smtp server

Created attachment 648680
An example of an SMTP error message which I refer to

Duplicate of bug 780086 ?

(In reply to Rob from comment #1)
> An example of an SMTP error message which I refer to

"relaying denied" is seen in screen shot.
"relaying denied" is usually 550 or 5.7.1 from SMTP server o Tb, and mail is rejected by SMTP server. See bug 228198 for it.
In that bug, no one referred to phenomenon like "composition window is closed and mail is saved in Sent".
And, there similar bugs were opened consecutively.
  bug 775999, bug 780086, bug 780124(this bug)
Perhaps a regression by a Tb release.
Setting dependency of those bugs for ease of tracking and analysis.

Can you persistently reproduce "relaying denied" from SMTP server?

4-th bug, Bug 780115 for "too many open connections error from SMTP server".
"Save to Sent folder" in such case may be a protection from loss of composing mail in case of abnormal termiation of mail composition window.

Unable to produce problem in Tb 14.0.0 on Win-XP, by 553 to MAIL FROM: from Yahoo! SMTP server(Yahoo! rejects From: address other than assiged mail address).
When error occurred, dialog for the error was opened, and composition window was still kept after close of the dialog.
(SMTP log)
> 00000022 0.71450758 [6064] 0[210f140]: PLAIN auth
> 00000023 0.71459109 [6064] 0[210f140]: Logging suppressed for this command (it probably contained authentication information)
> 00000024 0.80845976 [6064] 0[210f140]: SMTP entering state: 0
> 00000025 0.80857205 [6064] 0[210f140]: SMTP Response: 235 OK, go ahead
> 00000026 0.80865669 [6064] 0[210f140]: SMTP entering state: 18
> 00000027 0.80873466 [6064] 0[210f140]: SMTP Login response, code 235
> 00000028 0.80880642 [6064] 0[210f140]: SMTP entering state: 3
> 00000029 0.80890781 [6064] 0[210f140]: SMTP Send: MAIL FROM:<z-01@x.x.x> SIZE=350
> 00000030 0.91729367 [6064] 0[210f140]: SMTP entering state: 0
> 00000031 0.91737914 [6064] 0[210f140]: SMTP Response: 553 From address not verified - see http://help.yahoo.com/l/us/yahoo/mail/original/manage/sendfrom-07.html
> 00000032 0.91746324 [6064] 0[210f140]: SMTP entering state: 5
> 00000033 6.38465023 [6064] 0[210f140]: SMTP Send: QUIT
> 00000034 6.38476753 [6064] 0[210f140]: SMTP entering state: 0
> 00000035 6.57907629 [6064] 0[210f140]: SMTP entering state: 0
> 00000036 6.57912779 [6064] 0[210f140]: SMTP Response: 221 Service Closing transmission
> 00000037 6.57919836 [6064] 0[210f140]: SMTP entering state: 11
> 00000038 6.58548069 [6064] 0[210f140]: SMTP entering state: 12
> 00000039 6.58557463 [6064] 0[210f140]: SMTP connection error quitting 80004004, ignoring

As seen in log, "error to QUIT" takes 5 seconds. It was probably because I kept dialog open for 5 seconds. Tb looks to issue QUIT after dialog close. And, 221 is normally returned to QUIT after 200 msec from SMTP server.

Can you get SMTP log? (see bug 402793 comment #28 for getting log)
QUIT sequence is normal when error occurs?

Auto-save may be relivant. Do you enable auto-save? If yes, was auto-save invoked before your send operation?
(Check "Show confirmation dialog when messages are saved" at Copis&Folders)

Problem was reproduced by 553 to MAIL FROM:, with keep error dialog open for long time.
(1) Send, 553 to MAIL FROM: from smtp.mail.yahoo.com
(2) Error dialog is opened. Keep it open
(3) Wait for while, netstat /n /b /o
    Confirm "no connection between Tb and smtp.mail.yahoo.com"
(4) OK at error dialog
    => Mail was saved to Sent folder, and composition window was closed

Log with SET NSPR_LOG_MODULES=timestamp,smtp:5,MsgCopyService:5
> 00000022 0.50886804 [6064] 0[210f140]: PLAIN auth
> 00000023 0.50891578 [6064] 0[210f140]: Logging suppressed for this command (it probably contained authentication information)
> 00000024 0.60844296 [6064] 0[210f140]: SMTP entering state: 0
> 00000025 0.60849607 [6064] 0[210f140]: SMTP Response: 235 OK, go ahead
> 00000026 0.60854828 [6064] 0[210f140]: SMTP entering state: 18
> 00000027 0.60859132 [6064] 0[210f140]: SMTP Login response, code 235
> 00000028 0.60863435 [6064] 0[210f140]: SMTP entering state: 3
> 00000029 0.60869664 [6064] 0[210f140]: SMTP Send: MAIL FROM:<z-01@x.x.x> SIZE=350
> 00000030 0.72535086 [6064] 0[210f140]: SMTP entering state: 0
> 00000031 0.72543770 [6064] 0[210f140]: SMTP Response: 553 From address not verified - see http://help.yahoo.com/l/us/yahoo/mail/original/manage/sendfrom-07.html
> 00000032 0.72552711 [6064] 0[210f140]: SMTP entering state: 5
> 00000033 283.92575073 [6064] 0[210f140]: SMTP Send: QUIT
> 00000034 283.92584229 [6064] 0[210f140]: SMTP entering state: 0
> 00000035 283.92593384 [6064] 0[210f140]: SMTP Send: QUIT
> 00000036 283.93383789 [6064] 0[210f140]: request 50b8b40 DoCopy - src dest mailbox://x.x.x/Sent numItems 0 type=1
> 00000037 284.00128174 [6064] 0[210f140]: NotifyCompletion - src dest mailbox://x.x.x/Sent
> 00000038 284.00137329 [6064] 0[210f140]: request 50b8b40 Clearing OK request - src dest mailbox://x.x.x/Sent numItems 0 type=1

Confirming.

*** Bug 775999 has been marked as a duplicate of this bug. ***

*** Bug 780086 has been marked as a duplicate of this bug. ***

*** Bug 780115 has been marked as a duplicate of this bug. ***

I have an smtp log:

0[110f140]: SMTP Connecting to: smtp.telenet.be
0[110f140]: SMTP entering state: 0
0[110f140]: SMTP Response: 421 gerard.telenet-ops.be bizsmtp 91.183.175.114 relaying denied
0[110f140]: SMTP entering state: 14
0[110f140]: SMTP Send: QUIT
0[110f140]: SMTP entering state: 0
0[110f140]: SMTP Send: QUIT

Re. auto-save: I don't know, I can't find the menu item you mention (I have a localized version of Thunderbird). Can you post a screenshot?

(In reply to Rob from comment #11)
> Re. auto-save: I don't know, I can't find the menu item you mention (I have
> a localized version of Thunderbird). Can you post a screenshot?

Found it. There's no check mark in the 'Show confirmation dialog' box.

I have installed Thunderbird 15 Beta 3 in Windows 7 Professional x86, and the same problem still happens.

Not fixed in TB 15.0 release, and a very, very annoying bug for those of us who need to change smtp servers often when at other customers' sites.

Can someone affected follow the instrctions at http://www.rumblingedge.com/2009/02/24/howto-find-regression-windows-through-manual-binary-search/ , so we can figure out what broke this ?

Ludovic, I think the bug must be new since Thunderbird 14 (unless the particular mail server which gives the error messages has changed his behaviour recently).

*** Bug 788188 has been marked as a duplicate of this bug. ***

*** Bug 795338 has been marked as a duplicate of this bug. ***

A relevant change : patch for bug 758878(status-thunderbird14: fixed)
Was problem exposed by the patch?
I can't think so, because the patch merely added following code, and because "SMTP connection error quitting ..." was not logged when this bug occurred although it was logged when this bug didn't occur...
> + // ignore errors handling the QUIT command so fcc can continue.
> + if (m_sendDone && NS_FAILED(aStatus))
> + {
> + PR_LOG(SMTPLogModule, PR_LOG_ALWAYS,
> + ("SMTP connection error quitting %lx, ignoring ", aStatus));
> + aStatus = NS_OK;
> + }

nsSmtpProtocol.cpp is only module changed by bug 758878, and file revisions is following.
> http://hg.mozilla.org/comm-central/log/45ccb6afce84/mailnews/compose/src/nsSmtpProtocol.cpp
Affected by change such as "Switch comm-central from using nsnull to nullptr", "Change types to nsresult", "Make more nsSmtpProtocol methods return nsresult"?

Regression window: (checked by thunderbird-14.0a1.en-US.win32.zip)
(a) Good :
    /pub/mozilla.org/thunderbird/nightly/2012/04/2012-03-19-03-00-43-comm-central
(b) Bad :
    /pub/mozilla.org/thunderbird/nightly/2012/04/2012-03-20-03-01-27-comm-central

Changes pushed after 2012-04-19 00:00:00, before 2012-04-20 06:00:00
> http://hg.mozilla.org/comm-central/pushloghtml?startdate=2012-04-19+00%3A00&enddate=2012-04-20+06%3A00

*** Bug 795529 has been marked as a duplicate of this bug. ***

*** Bug 792930 has been marked as a duplicate of this bug. ***

*** Bug 792803 has been marked as a duplicate of this bug. ***

*** Bug 793154 has been marked as a duplicate of this bug. ***

Correct Regression window: (checked by thunderbird-14.0a1.en-US.win32.zip)
(a) Good :
    /pub/mozilla.org/thunderbird/nightly/2012/03/2012-03-19-03-00-43-comm-central
(b) Bad :
    /pub/mozilla.org/thunderbird/nightly/2012/03/2012-03-20-03-01-27-comm-central

Correct Changes pushed after 2012-03-19 00:00:00, before 2012-03-20 06:00:00.
> http://hg.mozilla.org/comm-central/pushloghtml?startdate=2012-03-19+00%3A00&enddate=2012-03-20+06%3A00

Sorry for mistake.

Regression by patch for bug 554044(Target Milestone: Thunderbird 14.0)?

To see "Copy to Sent" and "Socket close" by NSPR log, use following parameter.
  NSPR_LOG_MODULES=timestamp,smtp:5,MsgCopyService:5,nsSocketTransport:5
No connection between Tb and SMTP server can be observed by "netstat /n /b /o". It usually has "CLOSE_WAIT" status intead of "ESTABLISHED" after "Socket close" by Tb.

cc-ing to Mark Banner who is ownwer of bug 554044.

Happy to see something move here. Sorry that I couldn't find the time to do the regression test myself.

If necessary, I can test nightly builds to see if this is solved. Just let us know.

I frequently receive this error in my laptop at work when I send an email.

However, at home: the same Exchange account (through IMAP), same operating system (Windows 7 x64) and same Seamonkey version 2.13, but this error doesn't happen here at home.

I don't understand the reason, what's happening it in my laptop at work and not in my pc at home, maybe the intranet environment?

*** Bug 797814 has been marked as a duplicate of this bug. ***

*** Bug 813537 has been marked as a duplicate of this bug. ***

*** Bug 783352 has been marked as a duplicate of this bug. ***

Smtp Yahoo: resources temporarily unavailable

Thunderbird moves to sent folder as if everything is fine. Message did not go through.

38 comments hidden view all 165 comments
Nikolaus Rath (nrath) wrote :
Download full text (3.6 KiB)

User Agent: Mozilla/5.0 (X11; Linux x86_64; rv:17.0) Gecko/20130806 Firefox/17.0 Iceweasel/17.0.8 (Nightly/Aurora)
Build ID: 20130806234539

Steps to reproduce:

It seems that emails are silently discarded when the remote SMTP server replies with an error on STARTTLS. Here is an example smtp log created with NSPR_LOG_MODULES='smtp:5,timestamp':

2013-08-23 11:10:25.548708 UTC - 43480896[7fe10164b370]: SMTP Connecting to: mail.trialphaenergy.com
2013-08-23 11:10:26.513993 UTC - 43480896[7fe10164b370]: SMTP entering state: 0
2013-08-23 11:10:26.514026 UTC - 43480896[7fe10164b370]: SMTP Response: 220 mail.trialphaenergy.com Microsoft ESMTP MAIL Service ready at Fri, 23 Aug 2013 04:10:25 -0700
2013-08-23 11:10:26.514047 UTC - 43480896[7fe10164b370]: SMTP entering state: 14
2013-08-23 11:10:26.514069 UTC - 43480896[7fe10164b370]: SMTP Send: EHLO [10.11.206.9]
2013-08-23 11:10:27.144751 UTC - 43480896[7fe10164b370]: SMTP entering state: 0
2013-08-23 11:10:27.144791 UTC - 43480896[7fe10164b370]: SMTP Response: 250-mail.trialphaenergy.com Hello [10.11.10.19]
2013-08-23 11:10:27.144808 UTC - 43480896[7fe10164b370]: SMTP entering state: 0
2013-08-23 11:10:27.144817 UTC - 43480896[7fe10164b370]: SMTP Response: 250-SIZE
2013-08-23 11:10:27.144828 UTC - 43480896[7fe10164b370]: SMTP entering state: 0
2013-08-23 11:10:27.144839 UTC - 43480896[7fe10164b370]: SMTP Response: 250-PIPELINING
2013-08-23 11:10:27.144846 UTC - 43480896[7fe10164b370]: SMTP entering state: 0
2013-08-23 11:10:27.144851 UTC - 43480896[7fe10164b370]: SMTP Response: 250-DSN
2013-08-23 11:10:27.144857 UTC - 43480896[7fe10164b370]: SMTP entering state: 0
2013-08-23 11:10:27.144862 UTC - 43480896[7fe10164b370]: SMTP Response: 250-ENHANCEDSTATUSCODES
2013-08-23 11:10:27.144868 UTC - 43480896[7fe10164b370]: SMTP entering state: 0
2013-08-23 11:10:27.144885 UTC - 43480896[7fe10164b370]: SMTP Response: 250-STARTTLS
2013-08-23 11:10:27.144889 UTC - 43480896[7fe10164b370]: SMTP entering state: 0
2013-08-23 11:10:27.144893 UTC - 43480896[7fe10164b370]: SMTP Response: 250-AUTH NTLM
2013-08-23 11:10:27.144897 UTC - 43480896[7fe10164b370]: SMTP entering state: 0
2013-08-23 11:10:27.144900 UTC - 43480896[7fe10164b370]: SMTP Response: 250-8BITMIME
2013-08-23 11:10:27.144904 UTC - 43480896[7fe10164b370]: SMTP entering state: 0
2013-08-23 11:10:27.144920 UTC - 43480896[7fe10164b370]: SMTP Response: 250-BINARYMIME
2013-08-23 11:10:27.144926 UTC - 43480896[7fe10164b370]: SMTP entering state: 0
2013-08-23 11:10:27.144931 UTC - 43480896[7fe10164b370]: SMTP Response: 250 CHUNKING
2013-08-23 11:10:27.144936 UTC - 43480896[7fe10164b370]: SMTP entering state: 4
2013-08-23 11:10:27.144961 UTC - 43480896[7fe10164b370]: SMTP entering state: 21
2013-08-23 11:10:27.144968 UTC - 43480896[7fe10164b370]: SMTP Send: STARTTLS
2013-08-23 11:10:27.757848 UTC - 43480896[7fe10164b370]: SMTP entering state: 0
2013-08-23 11:10:27.757881 UTC - 43480896[7fe10164b370]: SMTP Response: 554 Policy violation. Email Session ID: {521742ED-1-F0B0B0A-FFFF}
2013-08-23 11:10:27.757893 UTC - 43480896[7fe10164b370]: SMTP entering state: 19
2013-08-23 11:10:27.757900 UTC - 43480896[7fe10164b370]: SMTP entering state: 21
2013-08-23 11:10:27.757...

Read more...

Changed in thunderbird:
importance: Unknown → Medium
status: Unknown → New

This problem occurs even when 4XX error on greeting.
Dup of bug 780124.

*** This bug has been marked as a duplicate of bug 780124 ***

Changed in thunderbird:
status: New → Invalid
122 comments hidden view all 165 comments

(In reply to WADA from comment #120)
> (In reply to Rob from comment #118)
> > I've found WADA's comment 26 to be correct (snip)
>
> Does it mean that you were distrustful about my comment #26 until you did
> duplication test :-)
> Thanks for your dupliction test. As known by comment #26, I did mistake in
> cooment #21.

*points at Wayne Mery* *points at comment 94* *winks suggestively*

(Off-Topic) Oh, who were distrustful of it was Wayne :-)

By the way, it looks for me;
- Before some changes :
  When QUIT was issued due to error while Tb tries to send mail data to SMTP server,
  Tb went to "send QUIT step" again with keeping "error staus",
  in case of that some error occurs while sending QUIT after original error.
  This can be a Quirks for bypassing hard-to-resolve problem.
- After some changes :
  According to some comments arround change which was done in the regression window,
  it seems for me that a reason why such change was made is to resolve "QUIT loop" problem,
  which may be caused by the Quirks.

Without co-operation of who did changes around SMTP code during the regression window, I can say/do nothing. But ...

I'm having the same problem. The SMTP server at my work only works when I'm at work or connected through a VPN. When I am not on the right network, the server refuses to accept any outgoing mail. Thunderbird displays an error message, but copies the unsent message to the Sent folder anyway. I poked around and discovered that this is what's happening:

1. Thunderbird connects to smtp.umail.utah.edu.

2. Before Thunderbird sends anything, the server sends "554 ipo4smtp.cc.utah.edu".

3. nsSmtpProtocol::ExtensionLoginResponse sees the error and alerts the user "An error occurred while sending mail: The mail server sent an incorrect greeting: ipo0smtp.cc.utah.edu."

4. nsSmtpProtocol::ProcessProtocolState sees the error, sends "QUIT", and queues the SMTP_ERROR_DONE state.

5. The server hangs up without acknowledging the QUIT.

6. nsSmtpProtocol::OnStopRequest stops the SMTP state machine without ever running nsSmtpProtocol::ProcessProtocolState in the SMTP_ERROR_DONE state.

7. Thunderbird thinks the message was sent and copies it to the Sent folder.

This is very similar to bug 200647. The server (which is a Microsoft SMTP Server) is transgressing RFC 5321 section 3.1, but for the sake of the user, Thunderbird should gracefully handle the abrupt hangup.

I agree with WADA that https://hg.mozilla.org/comm-central/rev/6a883737262a from bug 554044 is to blame. That revision set m_sendDone to true in step 4. Previously m_sendDone was false if there was an error, which triggered the error handling code for bug 200647 in step 6.

Created attachment 8801912
[PATCH] Gracefully handle SMTP servers that send a bad greeting and hang up.

This patch fixes the problem. It was really hard for me to wrap my head around this code, so feedback is appreciated. Right now m_sendDone == m_nextStateAfterResponse == SMTP_DONE || m_nextStateAfterResponse == SMTP_ERROR_DONE, and I decided to not change that. Keeping the existing m_sendDone semantics allowed me to fix (without duplicating code) the related case where there is a network failure (not a clean hangup) while sending QUIT after an error.

Instead of showing a second error dialog for NS_ERROR_NET_INTERRUPT like in old versions of Thunderbird, I chose to set NS_ERROR_BUT_DONT_SHOW_ALERT because one error dialog is enough, and the NS_ERROR_NET_INTERRUPT dialog was not helpful: "The message could not be sent because the connection to Outgoing server (SMTP) smtp.umail.utah.edu was lost in the middle of the transaction. Try again."

Users will still get an NS_ERROR_NET_INTERRUPT dialog as long as the interruption didn't happen while trying to gracefully shut down after a previous error.

https://treeherder.mozilla.org/#/jobs?repo=try-comm-central&revision=bf65cbeb6018

Comment on attachment 8801912
[PATCH] Gracefully handle SMTP servers that send a bad greeting and hang up.

If Magnus does not get to this, I'll look at it. It would be great to get this fixed.

Comment on attachment 8801912
[PATCH] Gracefully handle SMTP servers that send a bad greeting and hang up.

I spent a few hours looking at this today, getting to the point where I could also reproduce and view the problem and proposed solution. So I'll do the review of this.

Created attachment 8805031
Don't claim we are done when we failed

Here's my recommendation. When I looked at this, I asked myself "Why are we relying on complex tests of protocol state to see if we succeeded? There should be a variable that makes it clear!" Well actually there is such a variable, but it is set to succeeded in QUIT when QUIT is also used to close the connection after a failure. This patch just moves the test to the points where we know that we succeeded.

Comment on attachment 8805031
Don't claim we are done when we failed

Review of attachment 8805031:
-----------------------------------------------------------------

Hi Kent, thanks for looking into this. If we are going to change the semantics of m_sendDone, it would be better to pass an aSendDone parameter to SendQuit and set m_nextStateAfterResponse based on aSendDone. However, there is still the problem of popping up 2 dialogs when only 1 of them has useful information.

Comment on attachment 8801912
[PATCH] Gracefully handle SMTP servers that send a bad greeting and hang up.

Review of attachment 8801912:
-----------------------------------------------------------------

As a general statement, you are trying to fix two problems here. One is a really important problem, which is the fact that TB claims it sent when it did not. The other is not so important, too many error messages. The solution to the first is being held up by discussions of how to handle the second. Let's not try to solve the second here but in a different bug.

So, where do we go from here? Unfortunately all of the core people are really frazzled at the moment getting ready for an impending release, so I'm going to have to short circuit this process to move it forward, as we would really like to get this fix landed. (It could also backport to TB 45). So I'm going to give additional comments on my approach, and bring in another reviewer to evaluate where we are at.

I'm happy to give you credit for this bug regardless of what approach that we take, but if you are not happy with my approach (as indicated by a feedback-), and we end up going that way, then I'll probably need to reassign the bug to myself rather than land something in your name that you do not approve of.

In any case, you've played a critical role in getting this bug to be fixed, so I want to sincerely thank you for being the catalyst to get this fixed.

::: mailnews/base/util/nsMsgProtocol.cpp
@@ +39,5 @@
> #include "nsAlgorithm.h"
> #include "mozilla/Services.h"
> #include <algorithm>
> #include "nsContentSecurityManager.h"
> +#include "nsComposeStrings.h"

You should not include a file from a specific protocol in this file which is used for a generic protocol.

::: mailnews/compose/src/nsSmtpProtocol.cpp
@@ +422,5 @@
> MOZ_LOG(SMTPLogModule, mozilla::LogLevel::Info,
> + ("SMTP connection error %lx while quitting", aStatus));
> + if (m_nextStateAfterResponse == SMTP_ERROR_DONE)
> + // if we were going to abort fcc even if the QUIT had succeeded, abort it
> + aStatus = NS_ERROR_BUT_DONT_SHOW_ALERT;

On the issue of too many error messages, actually the protocol code is supposed to handle this using m_urlErrorState, which is set to NS_ERROR_BUT_DONT_SHOW_ALERT after the alert shows that is the primary error message. So the existing code already had a mechanism to try to handle this. Trying to also fix it here is really a kludge. If you want to fix this, you need to figure out why the existing method is not doing what you want.

I also really dislike having protocol state information being used outside of the tight protocol state machine. Yes they did it above, but I also dislike it there.

@@ +445,5 @@
> + // for example, see bug 780124
> + MOZ_LOG(SMTPLogModule, mozilla::LogLevel::Info,
> + ("SMTP connection dropped while attempting graceful failure"));
> + nsMsgAsyncWriteProtocol::OnStopRequest(nullptr, ctxt,
> + NS_ERROR_BUT_DONT_SHOW_ALERT);

Again, this is not the right place to fix this.

Comment on attachment 8805031
Don't claim we are done when we failed

Jorg, could you look at this? I could make the changes suggested by Alex if you want, but I'm not sure that I see the point.

(In reply to Kent James (:rkent) from comment #132)
> Jorg, could you look at this? I could make the changes suggested by Alex if
> you want, but I'm not sure that I see the point.
We're talking about this, right?
=== Quote from copmment #130?
If we are going to change the semantics of m_sendDone, it would be better to pass an aSendDone parameter to SendQuit and set m_nextStateAfterResponse based on aSendDone.
===
Would that be hard to do and then we've got two solutions to chose from and comment on?

Comment on attachment 8805031
Don't claim we are done when we failed

Review of attachment 8805031:
-----------------------------------------------------------------

I've looked at this now and I think Kent's solution to separate the setting of m_sendDone from SendQuit() is simple and transparent. Alex, where did you plan to set 'm_nextStateAfterResponse'?

::: mailnews/compose/src/nsSmtpProtocol.cpp
@@ +606,5 @@
> NS_ENSURE_SUCCESS(rv, rv);
> bool verifyingLogon = false;
> smtpUrl->GetVerifyLogon(&verifyingLogon);
> + if (verifyingLogon) {
> + m_sendDone = true; // We did what we were attempting.

Please move the inline comment above the line like this:

// Just verifying the ability to logon was done/succeeded(?)
// so we pretend the send (which we didn't do) was
// a success.
m_sendDone = true;

Created attachment 8805631
change-m_sendDone-semantics.diff

Kent, this is how I would improve upon your patch. But my fear is that if we change the m_sendDone semantics, it will require complicated code to fix the two-dialogs problem, and so the two-dialogs problem will never be fixed.

> You should not include a file from a specific protocol in this file which is
> used for a generic protocol.

We can avoid referencing NS_ERROR_BUT_DONT_SHOW_ALERT in nsMsgProtocol::OnStopRequest by simply deleting the NS_ASSERTION from nsMsgProtocol::OnStopRequest. We'd have to do this anyway if we change the m_sendDone semantics.

> On the issue of too many error messages, actually the protocol code is
> supposed to handle this using m_urlErrorState, which is set to
> NS_ERROR_BUT_DONT_SHOW_ALERT after the alert shows that is the primary error
> message. So the existing code already had a mechanism to try to handle this.
> Trying to also fix it here is really a kludge. If you want to fix this, you
> need to figure out why the existing method is not doing what you want.

The protocol code is okay except that it has no way to tell the rest of the mail-sending code that an alert should not be shown for a network error following another error. The only solution I can see is to make nsSmtpProtocol::OnStopRequest change the error to NS_ERROR_BUT_DONT_SHOW_ALERT if m_nextStateAfterResponse == SMTP_ERROR_DONE.

Don't get me wrong; I am really happy to see movement on this bug, and I agree that pretty much anything would be better than what we have now.

Comment on attachment 8805631
change-m_sendDone-semantics.diff

I don't want to lose track of the need for me to look at this.

Comment on attachment 8805031
Don't claim we are done when we failed

Cancelling this for now since there is an alternative patch.

*** Bug 941101 has been marked as a duplicate of this bug. ***

*** Bug 1270425 has been marked as a duplicate of this bug. ***

This problem is happening to me with frequency. My company uses a Microsoft Exchange cloud based server and it frequently replies with a 4.4.2 error and the message is not sent, instead of being queued. People using other mail clients dont experience any problems.

Does setting mailnews.sendInBackground to true will have influence in this problem?

*** Bug 1299129 has been marked as a duplicate of this bug. ***

*** Bug 1304987 has been marked as a duplicate of this bug. ***

*** Bug 1088558 has been marked as a duplicate of this bug. ***

Any progress on this?
I have not had this problem for a very long time until last Friday when TB 52.03.00 gave
"An error occurred while sending mail. The mail server responded: 5.2.1 : AOL will not accept delivery of this message.. Please check the message and try again.
Delivering mail 100%"
The error message stayed open until cancelled (a major improvement on before), on closing the error message the unsent message closed and was moved to sent folder, the message was not sent.
The problem still ocurred with message content "test" but only ocurred whilst using a Hull Trains wifi connection.

Comment on attachment 8805631
change-m_sendDone-semantics.diff

All I can say is that the review request does not show up in Kent's review queue. Strange. So that's why this has fallen trough the cracks. So let me cancel the request and request it again.

Created attachment 8923289
780124-gds-review-changes0.patch

In conjunction with Bug 1390442 and Bug 1409678, which are closely related to this bug (maybe duplicates, at least in terms of the resulting fix), I have a proposed modified patch that fixes these problems:

The following activities have a similar result:
A network stream error occurs while sending email.
A fatal SMTP reply errors occur while sending email.
A password is requested when sending and is entered incorrectly. Cancel button is clicked on the 3-button login dialog before re-entering the correct password.
A password is requested when sending and Cancel button is clicked instead of OK.
A password is requested when sending and is entered incorrectly. Then on the password re-entry prompt, just click cancel instead of OK.
Account A configured to use, e.g., yahoo's smtp server. Yahoo doesn't like this. Send an email from account A and take some time to read the error message while the connection times-out. (This is the cause of this bug.)

The message is not sent but the message appears in the Sent folder.

This has a different result:
When sending, enter bad password on 1st prompt. On next password re-entry prompt enter bad password again. Then cancel on login 3-button screen.

Leaves "Sending messages - ..." with Connected to smtp.mail..... box with progress bar moving left to right. Cancel "Sending Message--..." and progress bar remains. Then cancel progress bar window. Write (compose) window still present but read only! Send button and menus gray (disabled). In this case, message is not moved to Sent and Write window can only be dismissed.

The attached patch does basically what the previous patch did in addition to fixing the read-only write window problem. I have also done a lot of testing to diagnose the problem and verify the fixes.

Comment on attachment 8923289
780124-gds-review-changes0.patch

I don't know how I inherited this. Let's see whether Kent responds within a month. Looking at comment #131, he knows a whole lot more about this than I do.

Kent: What's the story with <email address hidden>?

This problem has really been throwing me for a loop. CenturyLink for some reason is frequently issuing 421 errors. Because of the way Tbird was acting, I thought it was just a warning and since it copied the message to the "sent" folder, I had a record of sending the message, though it never went anywhere. Really awful to tell people you had replied to them and yet you actually had not.

Comment on attachment 8923289
780124-gds-review-changes0.patch

Review of attachment 8923289:
-----------------------------------------------------------------

Like Kent's patch, Gene's patch fixes the major problem and would be OK to commit to Thunderbird, although it pops up two error dialogs when one is enough.

*** Bug 1390442 has been marked as a duplicate of this bug. ***

*** Bug 1409678 has been marked as a duplicate of this bug. ***

*** Bug 1469179 has been marked as a duplicate of this bug. ***

*** Bug 1002598 has been marked as a duplicate of this bug. ***

154 comments hidden view all 165 comments
Paul White (paulw2u) wrote :

Updated upstream bug report

Changed in thunderbird:
importance: Medium → Unknown
status: Invalid → Unknown
155 comments hidden view all 165 comments

*** Bug 1488017 has been marked as a duplicate of this bug. ***

Comment on attachment 8805631
change-m_sendDone-semantics.diff

Ben, here comes another hard one. As you can see, many votes, many duplicates, apparently two problems, the second one is some doubled-up message, different approaches where one party puts r-/f- on the patches of the other. Magnus and I decided to give you the honourable task to cut though it and favourise one patch or tweak it into shape.

Comment on attachment 8923289
780124-gds-review-changes0.patch

And this one. Most likely the patches have bitrot. Enjoy ;-)

Sure thing. The fixes don't look too complex, so I guess the trickiness is understanding the larger context and side effects. A good excuse to dive into another part of the code I've not looked at much yet!

Looks like Kent's patch (attachment 8805031) is the base upon every one agrees. Then we have to improved versions. Gene does a lot of testing, see comment #147 (!!) and even Axel agreed that it might be the way forward (comment #150). Maybe you can work out what the "two dialogue" problem is and move it to a new bug/patch.

Created attachment 9046887
badsmtpd.py

A little script to implement a badly-behaving smtp server which responds to MAIL commands with "554 Go away!", then disconnects.

Usage:
Run it locally, then set your outgoing STMP server to localhost:6502

(with this script I can confirm the copy-to-sent-mail-after-an-error behaviour, so I'm looking at the fixes now).

Changed in thunderbird:
importance: Unknown → Critical
status: Unknown → Confirmed
Displaying first 40 and last 40 comments. View all 165 comments or add a comment.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.