Closed Bug 758878 Opened 12 years ago Closed 12 years ago

MS Office 365 - IMAP & Pop- not saving to Sent folder, due to server closing connection immediately after QUIT

Categories

(MailNews Core :: Networking: IMAP, defect)

Product:
MailNews Core
Component:
Networking: IMAP
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(thunderbird14 fixed, thunderbird15 fixed)

Status:
RESOLVED FIXED
Milestone:
Thunderbird 16.0
Tracking Flags:
Tracking Status
thunderbird14 --- fixed
thunderbird15 --- fixed

People

(Reporter: anjeyelf, Assigned: Bienvenu)

Details

(Whiteboard: [has protocol log])

Attachments

(6 files, 1 obsolete file)

Trace output from wireshark
38.99 KB, text/plain
Details
Second trace from wireshark
23.56 KB, text/plain
Details
wireshark trace pcap file (all worked)
11.71 KB, application/octet-stream
Details
email sent but no IMAP sent copy and timeout received
10.32 KB, application/octet-stream
Details
window showing error
196.62 KB, image/jpeg
Details
only log errors
1.36 KB, patch
neil
: review+
standard8
: approval-comm-aurora+
standard8
: approval-comm-beta+
Details | Diff | Splinter Review 
User Agent: Mozilla/5.0 (Windows NT 6.0; rv:12.0) Gecko/20100101 Firefox/12.0
Build ID: 20120420145725

Steps to reproduce:

Reporting problem people are experiencing with:
Sent emails not saving to sent folder in Local Folders.
MS Office 365 server.
ISP (BT Business) 

Also same people reporting an issue with 'time out' when sending.



Actual results:

quote from:
https://getsatisfaction.com/mozilla_messaging/topics/ms_office_365_servers_and_thunderbird_smtp_issues_please_help?utm_content=topic_link&utm_medium=email&utm_source=reply_notification

"The issue is that Thunderbird think it hasn't sent it so doesn't save/upload a copy to the sent folder.

I have been analysing the packets coming in/out of the interface. Have ten failed attempts and one succesful (they are very rare!!).

Looking through the trace it fails when the PC receives the RST,ACK from the server, but when it works the RST,ACK is still there and the next packet is the call to the IMAP server to copy the email to the sent folder. Basically the RST,ACK is the final packet in the uploading of the email and when thunderbird receives this should then move on to uploading the email. Could it be a bug????

This was all working until it was moved to Office365 and I am subscribed to about 40 folders on my IMAP server!!!

I can send the traces if anyone wants to look at them. I used wireshark to capture them."

Also:
quote from:
https://getsatisfaction.com/mozilla_messaging/topics/help_need_a_genius_saviour_at_my_wits_end_now
"having done some more tests the emails are actually sending to people even though i get the failed reply but the email just stays on the screen instead of going into my sent items folder??
"




Expected results:

The sent email should have been copied to the Sent folder.
Can you produce an IMAP log from Thunderbird like this:
https://wiki.mozilla.org/MailNews:Logging ?
Use NSPR_LOG_MODULES=imap:5.
Component: General → Networking: IMAP
Product: Thunderbird → MailNews Core
QA Contact: general → networking.imap
I will attempt the above for you. I also have the traces which were caught with wireshark.
This is what I did to generate the following.

Logged smtp:3 imap:5 and timestamp

Created an email from my SMTP account (pskivens@btconnect.com) and sent it to an IMAP account also on the same Thunderbird account. You can see the SMTP leave and arrive in the second account even though I got the error message. I have cut and pasted all packets from when the email was sent until received by Thunderbird. The timeout was displayed as an error and no copy was sent to my other IMAP account (bluewellthemebeds.co.uk)

Have pasted the relevant section here to make it clearer. 
Email subject test email 2
Email conent testestestestestestestestestest

2012-05-30 15:01:39.161000 UTC - 0[1d0f140]: SMTP entering state: 0
2012-05-30 15:01:39.161000 UTC - 0[1d0f140]: SMTP Response: 334 VXNlcm5hbWU6
2012-05-30 15:01:39.161000 UTC - 0[1d0f140]: SMTP entering state: 13
2012-05-30 15:01:39.161000 UTC - 0[1d0f140]: SMTP entering state: 16
2012-05-30 15:01:39.161000 UTC - 0[1d0f140]: Logging suppressed for this command (it probably contained authentication information)
2012-05-30 15:01:39.255000 UTC - 0[1d0f140]: SMTP entering state: 0
2012-05-30 15:01:39.255000 UTC - 0[1d0f140]: SMTP Response: 334 UGFzc3dvcmQ6
2012-05-30 15:01:39.255000 UTC - 0[1d0f140]: SMTP entering state: 18
2012-05-30 15:01:39.255000 UTC - 0[1d0f140]: SMTP entering state: 17
2012-05-30 15:01:39.255000 UTC - 0[1d0f140]: Logging suppressed for this command (it probably contained authentication information)
2012-05-30 15:01:41.985000 UTC - 0[1d0f140]: SMTP entering state: 0
2012-05-30 15:01:41.985000 UTC - 0[1d0f140]: SMTP Response: 235 2.7.0 Authentication successful
2012-05-30 15:01:41.985000 UTC - 0[1d0f140]: SMTP entering state: 18
2012-05-30 15:01:41.985000 UTC - 0[1d0f140]: SMTP entering state: 3
2012-05-30 15:01:41.985000 UTC - 0[1d0f140]: SMTP Send: MAIL FROM:<pskivens@btconnect.com> SIZE=491

2012-05-30 15:01:42.156000 UTC - 0[1d0f140]: SMTP entering state: 0
2012-05-30 15:01:42.156000 UTC - 0[1d0f140]: SMTP Response: 250 2.1.0 Sender OK
2012-05-30 15:01:42.156000 UTC - 0[1d0f140]: SMTP entering state: 5
2012-05-30 15:01:42.156000 UTC - 0[1d0f140]: SMTP Send: RCPT TO:<paul@firstforideas.co.uk>

2012-05-30 15:01:42.328000 UTC - 0[1d0f140]: SMTP entering state: 0
2012-05-30 15:01:42.328000 UTC - 0[1d0f140]: SMTP Response: 250 2.1.5 Recipient OK
2012-05-30 15:01:42.328000 UTC - 0[1d0f140]: SMTP entering state: 6
2012-05-30 15:01:42.328000 UTC - 0[1d0f140]: SMTP Send: DATA

2012-05-30 15:01:42.499000 UTC - 0[1d0f140]: SMTP entering state: 0
2012-05-30 15:01:42.499000 UTC - 0[1d0f140]: SMTP Response: 354 Start mail input; end with <CRLF>.<CRLF>
2012-05-30 15:01:42.499000 UTC - 0[1d0f140]: SMTP entering state: 7
2012-05-30 15:01:42.499000 UTC - 0[1d0f140]: SMTP entering state: 8
2012-05-30 15:01:42.499000 UTC - 0[1d0f140]: SMTP Send: .

2012-05-30 15:01:44.527000 UTC - 0[1d0f140]: SMTP entering state: 0
2012-05-30 15:01:44.527000 UTC - 0[1d0f140]: SMTP Response: 250 2.6.0 <4FC63652.7050301@btconnect.com> [InternalId=55116388] Queued mail for delivery
2012-05-30 15:01:44.527000 UTC - 0[1d0f140]: SMTP entering state: 9
2012-05-30 15:01:44.527000 UTC - 0[1d0f140]: SMTP Send: QUIT

2012-05-30 15:01:44.527000 UTC - 0[1d0f140]: SMTP entering state: 0
2012-05-30 15:02:04.380000 UTC - 3060[8006fc0]: ReadNextLine [stream=83e72e8 nb=12 needmore=0]
2012-05-30 15:02:04.380000 UTC - 3060[8006fc0]: 8489c00:mail.firstforideas.co.uk:S-INBOX:CreateNewLineFromSocket: * 2 EXISTS

2012-05-30 15:02:04.380000 UTC - 3060[8006fc0]: ReadNextLine [stream=83e72e8 nb=12 needmore=0]
2012-05-30 15:02:04.380000 UTC - 3060[8006fc0]: 8489c00:mail.firstforideas.co.uk:S-INBOX:CreateNewLineFromSocket: * 1 RECENT

2012-05-30 15:02:04.380000 UTC - 3060[8006fc0]: 8489c00:mail.firstforideas.co.uk:S-INBOX:SendData: DONE

2012-05-30 15:02:04.396000 UTC - 3060[8006fc0]: ReadNextLine [stream=83e72e8 nb=22 needmore=0]
2012-05-30 15:02:04.396000 UTC - 3060[8006fc0]: 8489c00:mail.firstforideas.co.uk:S-INBOX:CreateNewLineFromSocket: 10 OK IDLE completed

2012-05-30 15:02:04.396000 UTC - 3060[8006fc0]: 8489c00:mail.firstforideas.co.uk:S-INBOX:ProcessCurrentURL: entering
2012-05-30 15:02:04.396000 UTC - 3060[8006fc0]: 8489c00:mail.firstforideas.co.uk:S-INBOX:ProcessCurrentURL:imap://paul@mail.firstforideas.co.uk:143/select%3E.INBOX:  = currentUrl
2012-05-30 15:02:04.396000 UTC - 3060[8006fc0]: 8489c00:mail.firstforideas.co.uk:S-INBOX:SendData: 11 noop

2012-05-30 15:02:04.411000 UTC - 3060[8006fc0]: ReadNextLine [stream=83e72e8 nb=22 needmore=0]
2012-05-30 15:02:04.411000 UTC - 3060[8006fc0]: 8489c00:mail.firstforideas.co.uk:S-INBOX:CreateNewLineFromSocket: 11 OK NOOP completed

2012-05-30 15:02:04.411000 UTC - 3060[8006fc0]: 8489c00:mail.firstforideas.co.uk:S-INBOX:SendData: 12 getquotaroot "INBOX"

2012-05-30 15:02:04.443000 UTC - 3060[8006fc0]: ReadNextLine [stream=83e72e8 nb=28 needmore=0]
2012-05-30 15:02:04.443000 UTC - 3060[8006fc0]: 8489c00:mail.firstforideas.co.uk:S-INBOX:CreateNewLineFromSocket: * QUOTAROOT "INBOX" "ROOT"

2012-05-30 15:02:04.443000 UTC - 3060[8006fc0]: ReadNextLine [stream=83e72e8 nb=37 needmore=0]
2012-05-30 15:02:04.443000 UTC - 3060[8006fc0]: 8489c00:mail.firstforideas.co.uk:S-INBOX:CreateNewLineFromSocket: * QUOTA "ROOT" (STORAGE 304 102396)

2012-05-30 15:02:04.443000 UTC - 3060[8006fc0]: ReadNextLine [stream=83e72e8 nb=24 needmore=0]
2012-05-30 15:02:04.443000 UTC - 3060[8006fc0]: 8489c00:mail.firstforideas.co.uk:S-INBOX:CreateNewLineFromSocket: 12 OK GETQUOTAROOT Ok.

2012-05-30 15:02:04.443000 UTC - 3060[8006fc0]: 8489c00:mail.firstforideas.co.uk:S-INBOX:SendData: 13 UID fetch 83:* (FLAGS)

2012-05-30 15:02:04.458000 UTC - 3060[8006fc0]: ReadNextLine [stream=83e72e8 nb=36 needmore=0]
2012-05-30 15:02:04.458000 UTC - 3060[8006fc0]: 8489c00:mail.firstforideas.co.uk:S-INBOX:CreateNewLineFromSocket: * 2 FETCH (UID 83 FLAGS (\Recent))

2012-05-30 15:02:04.458000 UTC - 3060[8006fc0]: ReadNextLine [stream=83e72e8 nb=24 needmore=0]
2012-05-30 15:02:04.458000 UTC - 3060[8006fc0]: 8489c00:mail.firstforideas.co.uk:S-INBOX:CreateNewLineFromSocket: 13 OK FETCH completed.

2012-05-30 15:02:04.458000 UTC - 3060[8006fc0]: 8489c00:mail.firstforideas.co.uk:S-INBOX:SendData: 14 UID fetch 83 (UID RFC822.SIZE FLAGS BODY.PEEK[HEADER.FIELDS (From To Cc Bcc Subject Date Message-ID Priority X-Priority References Newsgroups In-Reply-To Content-Type)])

2012-05-30 15:02:04.474000 UTC - 3060[8006fc0]: ReadNextLine [stream=83e72e8 nb=212 needmore=0]
2012-05-30 15:02:04.474000 UTC - 3060[8006fc0]: 8489c00:mail.firstforideas.co.uk:S-INBOX:CreateNewLineFromSocket: * 2 FETCH (UID 83 RFC822.SIZE 2511 FLAGS (\Recent) BODY[HEADER.FIELDS ("From" "To" "Cc" "Bcc" "Subject" "Date" "Message-ID" "Priority" "X-Priority" "References" "Newsgroups" "In-Reply-To" "Content-Type")] {250}

2012-05-30 15:02:04.474000 UTC - 3060[8006fc0]: 8489c00:mail.firstforideas.co.uk:S-INBOX:STREAM:OPEN Size: 2511: Begin Message Download Stream
2012-05-30 15:02:04.474000 UTC - 3060[8006fc0]: ReadNextLine [stream=83e72e8 nb=46 needmore=0]
2012-05-30 15:02:04.474000 UTC - 3060[8006fc0]: 8489c00:mail.firstforideas.co.uk:S-INBOX:CreateNewLineFromSocket: Message-ID: <4FC63652.7050301@btconnect.com>

2012-05-30 15:02:04.474000 UTC - 3060[8006fc0]: ReadNextLine [stream=83e72e8 nb=39 needmore=0]
2012-05-30 15:02:04.474000 UTC - 3060[8006fc0]: 8489c00:mail.firstforideas.co.uk:S-INBOX:CreateNewLineFromSocket: Date: Wed, 30 May 2012 16:01:38 +0100

2012-05-30 15:02:04.474000 UTC - 3060[8006fc0]: ReadNextLine [stream=83e72e8 nb=45 needmore=0]
2012-05-30 15:02:04.474000 UTC - 3060[8006fc0]: 8489c00:mail.firstforideas.co.uk:S-INBOX:CreateNewLineFromSocket: From: Paul Skivens <pskivens@btconnect.com>

2012-05-30 15:02:04.474000 UTC - 3060[8006fc0]: ReadNextLine [stream=83e72e8 nb=32 needmore=0]
2012-05-30 15:02:04.474000 UTC - 3060[8006fc0]: 8489c00:mail.firstforideas.co.uk:S-INBOX:CreateNewLineFromSocket: To: <paul@firstforideas.co.uk>

2012-05-30 15:02:04.474000 UTC - 3060[8006fc0]: ReadNextLine [stream=83e72e8 nb=23 needmore=0]
2012-05-30 15:02:04.474000 UTC - 3060[8006fc0]: 8489c00:mail.firstforideas.co.uk:S-INBOX:CreateNewLineFromSocket: Subject: test email 2

2012-05-30 15:02:04.474000 UTC - 3060[8006fc0]: ReadNextLine [stream=83e72e8 nb=63 needmore=0]
2012-05-30 15:02:04.474000 UTC - 3060[8006fc0]: 8489c00:mail.firstforideas.co.uk:S-INBOX:CreateNewLineFromSocket: Content-Type: text/plain; charset="ISO-8859-1"; format=flowed

2012-05-30 15:02:04.474000 UTC - 3060[8006fc0]: ReadNextLine [stream=83e72e8 nb=2 needmore=0]
2012-05-30 15:02:04.474000 UTC - 3060[8006fc0]: 8489c00:mail.firstforideas.co.uk:S-INBOX:CreateNewLineFromSocket: 

2012-05-30 15:02:04.474000 UTC - 3060[8006fc0]: ReadNextLine [stream=83e72e8 nb=3 needmore=0]
2012-05-30 15:02:04.474000 UTC - 3060[8006fc0]: 8489c00:mail.firstforideas.co.uk:S-INBOX:CreateNewLineFromSocket: )

2012-05-30 15:02:04.474000 UTC - 3060[8006fc0]: 8489c00:mail.firstforideas.co.uk:S-INBOX:STREAM:CLOSE: Normal Message End Download Stream
2012-05-30 15:02:04.474000 UTC - 3060[8006fc0]: ReadNextLine [stream=83e72e8 nb=24 needmore=0]
2012-05-30 15:02:04.474000 UTC - 3060[8006fc0]: 8489c00:mail.firstforideas.co.uk:S-INBOX:CreateNewLineFromSocket: 14 OK FETCH completed.
Just as an added comment I did successfully send an email once.

The server I connected to was 157.56.240.134 (bl2prd0710.outlook.com)

I don't know if you could approach microsoft to see if there is anything different with the setup of that server???
Please note that this error only occured after BT switched us to MS Office 365 and the outlook servers. Before then I was using the BT servers which worked fine and only the occasional hiccup.

This is a serious problem as I have no sent record of any emails.
I have tried changing the outgoing server to bl2prd0710.outlook.com to see if that consistently works but that also fails so seems intermittent but nearly all emails fail to be saved as sent emails.
This is the trace I managed to take when it worked to one server. I have not been able to replicate since!!!. I have a second showing the failed attempts which I will upload seperately
This shows the failed attempt but as you will see Thunderbird receives exactly the same RST,ACK from the server. (same seq and ack number every time). This time I received the timeout error and did not save a copy to the IMAP server
Bienvenu, can you make up anything from the log in comment 3? Is the SMTP properly closed. The user says something about RST,ACK packets. Maybe the connection is broken in a strange way so that TB does not see the last reply from the server (after QUIT) so thinks the send is still pending?
Whiteboard: [has protocol log]
It will be much easier to diagnose if files was not exported text but pcap files from wireshark.
This is the trace when it worked ok. (I have removed the packets for the encrypted handshake for privacy)
This is the trace of the failure. Trace was stopped when the timeout error appeared on screen.
Attachment #628659 - Attachment mime type: text/plain → application/octet-stream
Attachment #628660 - Attachment mime type: text/plain → application/octet-stream
RST, ACK only appears on SMTP session so it not releveant.
in pcap dump where is email is not saved, no IMAP packets, only submission 587 port. As this is just part of session (not just after app started), maybe IMAP tcp session terminated early, which I cannot see from these dumps.

Maybe try to change max server connection from 5 to 1 and see if that change anything.
I started this capture before sending the email. This was the process.

Started capture on local interface
Pressed Send on compose email screen
Mail sending progress window comes up
mail sends and is updated in bottom left of compase email window
immediately comes up with error about SMTP timeout
Stop capture on interface.

This is all the network traffic. My point was that the data coming from the server is the same but for some reason thunderbird is reporting a timeout issue and does not send the copy as sent as it, for some reason??, believes the email is not sent so does not contact or try to contact the IMAP server.

The RST, ACK is always the last packet in 10 different attempts of sending an email. The email is successfully sent EVERY time but the same error report comes up EVERY time. I will do a screen capture showing the error.
just found out if you move the error message the sending progress bar is still there! You can see it in the screen image
Attached image window showing error — 
this shows the error. Clearly stating email sent and SMTP timeout which are mutually exclusive!!!!
As far as session timing out with IMAP etc. This all happens while I am still getting email received by the IMAP server so no the session has not timed out. I have sent an email to one IMAP account and that has been received while the error message is still up. It is an issue with the SMTP connection and for some reason Thunderbird is confused over whether the message has been sent or not!
Sorry my bad, misunderstood problem at first. 
Yep it's kinda strange to see RST packet from server at that point (should be closed propertly). it could be some kinda issue with NSS and encrypted connection, but that just my guess here.
Could this be raised with Microsoft?? Have set my settings back to old BT server with less security and works no problem. This is causing me and a lot of hassle and there are a lot of other people on thunderbird out there and there will be a lot of issues as everyone connected to BT will be moved to smtp.outlook.com so needs to be sorted asap!!!!!! that is millions of users!
ah, I see, we're not getting a response to the QUIT command. I suppose we could figure out some way of making that a non-fatal error, as far as determining if the message was sent or not. Getting hold of someone at MS might be tough. You could try on your end with BT -> MS.
Status: UNCONFIRMED → NEW
Ever confirmed: true
I've requested a try server build with a patch to essentially ignore errors with QUIT, and also to reduce the timeout waiting for the QUIT response.  Builds should show up here - http://ftp.mozilla.org/pub/mozilla.org/thunderbird/try-builds/bienvenu@nventure.com-cd83489bc37a - these are TB 12.01 builds + my patch.
Attached patch possible fix (obsolete) — — Splinter Review 
this ignores errors sending QUIT after sending a message, and shortens the timeout to 5 seconds, in case the SMTP server is not going to respond to the QUIT command, no sense in making the user wait 60 seconds for that.
Assignee: nobody → dbienvenu
That even looks like my comment 9 could be right :)
(In reply to :aceman from comment #23)
> That even looks like my comment 9 could be right :)

Yes, you're right, that's what the log was showing...
Hey Roland, this could turn out to be a support issue.
I am using Vista home premium x32(pity me please!!!) 

Couldn't see a 32bit version= for windows?? Does that matter?

Please confirm and will download and test tomorrow
Just read the comment about me talking to BT to try and get through to MS :D that made me laugh! The BT help desk people will just say we do not support thunderbird and ask if I have rebooted my PC.

I have a mate who used to work with MS. Will try and get a contact number for someone who could actually answer a techie question!
I'll try to get a win32 build. I requested one, or tried to, anyway :-(
win32 builds are backed up - they should show up at some point. I'll check occasionally and update the bug when they show up.
ok, builds failed. I'll try again...
Comment on attachment 628796 [details] [diff] [review]
possible fix

apparently BT.com is rolling out servers with this bug, so Neil might be interested in this patch for his countrymen :-)
Attachment #628796 - Flags: review?(neil)
Comment on attachment 628796 [details] [diff] [review]
possible fix

>+  // ignore errors handling the QUIT command so fcc can continue.
>+  if (m_sendDone)
>+  {
>+    PR_LOG(SMTPLogModule, PR_LOG_ALWAYS,
>+     ("SMTP connection error quitting %lx, ignoring ", aStatus));
>+    aStatus = NS_OK;
>+  }
Do you want to see this message on successful quits?
If so, then the log message is confusing and needs improvement.
If not, then do you need to add an NS_FAILED(aStatus) here?
Also, would this block be better placed in the else clause below?
Attached patch only log errors — — Splinter Review 
you're right, I only want to log errors.
Attachment #628796 - Attachment is obsolete: true
Attachment #628796 - Flags: review?(neil)
Attachment #630981 - Flags: review?(neil)
Comment on attachment 630981 [details] [diff] [review]
only log errors

>+     ("SMTP connection error quitting %lx, ignoring ", aStatus));
OK, so in that case, I would have written something like
"SMTP connection error %lx after send done (ignoring)"
Not that it's important ;-)
Attachment #630981 - Flags: review?(neil) → review+
Comment on attachment 630981 [details] [diff] [review]
only log errors

[Approval Request Comment]
If BT really is rolling out this bug, we could cut down on support issues quite a bit by getting this in tb 14 and 15.
Attachment #630981 - Flags: approval-comm-beta?
Attachment #630981 - Flags: approval-comm-aurora?
fixed on trunk http://hg.mozilla.org/comm-central/rev/223e89649e75
Status: NEW → RESOLVED
Closed: 12 years ago
OS: Windows Vista → All
Hardware: x86 → All
Resolution: --- → FIXED
Target Milestone: --- → Thunderbird 16.0
Let me know a link to the fixed 32bit version so I can download when ready and I will retest and take traces again for you. Using a workaround using my own VPS server as the SMTP server for a different account!!

Thanks
(In reply to Paul from comment #38)
> Let me know a link to the fixed 32bit version so I can download when ready
> and I will retest and take traces again for you. Using a workaround using my
> own VPS server as the SMTP server for a different account!!

Paul, the try server build I linked to earlier:
try server build here - http://ftp.mozilla.org/pub/mozilla.org/thunderbird/try-builds/bienvenu@nventure.com-27f3e6591ede/try-comm-central-win32/

is probably better to run than the nightly builds that will have this fix starting tomorrow, because the try server build is tb 13 with a couple small changes.
Comment on attachment 630981 [details] [diff] [review]
only log errors

This seems a reasonable thing to do anyway, so a=me to get it out for some testing.
Attachment #630981 - Flags: approval-comm-beta?
Attachment #630981 - Flags: approval-comm-beta+
Attachment #630981 - Flags: approval-comm-aurora?
Attachment #630981 - Flags: approval-comm-aurora+
Summary: MS Office 365 - IMAP & Pop- not saving to Sent folder. → MS Office 365 - IMAP & Pop- not saving to Sent folder, due to server closing connection immediately after QUIT
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: