urgent: Mail appears sent in Outlook but is never reaching recipient

S

Sam chen

Hello,

I met a very wierd problem with outlook 2002, here is my settings:

Client: outlook 2002 + Bynari plugin (for calendar and Task)

Server: postfix + cyrus-imapd + Active Directory authentication and mail
address query

some users complain sometimes (not alltimes) they sent email, the email
seemed ok, and it went to "Sent Items", but the recipient did not receive
it.

I checked the server log, there is no log for these emails, and can not set
the postfix log to debug mode, because this will make the server extremely
busy. So I enable outlook logging, the following is the logging of a one of
these email:
====================================================================================================
2007.03.07 10:42:56 Callback::ExecuteThread[THIS: 0022fb30] (00001000)
returns 00000000
2007.03.07 10:42:56 Callback::LogText[THIS: 0022fb30] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 10:42:56 "CSMTPPutTask: Begin execution")
2007.03.07 10:42:56 Callback::LogText[THIS: 0022fb30] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 10:42:56 "SMTP PH: Connecting to SMTP server")
2007.03.07 10:42:56 Callback::ExecuteThread[THIS: 0022fb30] (00001000)
returns 00000000
2007.03.07 10:42:56 Callback::LogText[THIS: 0022fb30] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 10:42:56 "SMTP: Finding host")
2007.03.07 10:42:56 Callback::LogText[THIS: 0022fb30] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 10:42:56 "SMTP: Connected to host")
2007.03.07 10:42:56 Callback::LogText[THIS: 0022fb30] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 10:42:56 "SMTP: <rx> 220 mail2.lifestyles.net")
2007.03.07 10:42:56 Callback::LogText[THIS: 0022fb30] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 10:42:56 "SMTP: [tx] EHLO HOWKS407")
2007.03.07 10:42:56 Callback::LogText[THIS: 0022fb30] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 10:42:56 "SMTP: <rx> 250-mail2.lifestyles.net")
2007.03.07 10:42:56 Callback::LogText[THIS: 0022fb30] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 10:42:56 "SMTP: <rx> 250-PIPELINING")
2007.03.07 10:42:56 Callback::LogText[THIS: 0022fb30] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 10:42:56 "SMTP: <rx> 250-SIZE 7240000")
2007.03.07 10:42:56 Callback::LogText[THIS: 0022fb30] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 10:42:56 "SMTP: <rx> 250-ETRN")
2007.03.07 10:42:56 Callback::LogText[THIS: 0022fb30] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 10:42:56 "SMTP: <rx> 250-STARTTLS")
2007.03.07 10:42:56 Callback::LogText[THIS: 0022fb30] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 10:42:56 "SMTP: <rx> 250-AUTH PLAIN LOGIN
GSSAPI")
2007.03.07 10:42:56 Callback::LogText[THIS: 0022fb30] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 10:42:56 "SMTP: <rx> 250-AUTH=PLAIN LOGIN
GSSAPI")
2007.03.07 10:42:56 Callback::LogText[THIS: 0022fb30] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 10:42:56 "SMTP: <rx> 250 8BITMIME")
2007.03.07 10:42:56 Callback::LogText[THIS: 0022fb30] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 10:42:56 "SMTP: Authorizing to server")
2007.03.07 10:42:56 Callback::LogText[THIS: 0022fb30] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 10:42:56 "SMTP: [tx] AUTH LOGIN")
2007.03.07 10:42:56 Callback::LogText[THIS: 0022fb30] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 10:42:56 "SMTP: <rx> 334 VXNlcm5hbWU6")
2007.03.07 10:42:56 Callback::LogText[THIS: 0022fb30] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 10:42:56 "SMTP: [tx] Y2xp")
2007.03.07 10:42:56 Callback::LogText[THIS: 0022fb30] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 10:42:56 "SMTP: <rx> 334 UGFzc3dvcmQ6")
2007.03.07 10:42:56 Callback::LogText[THIS: 0022fb30] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 10:42:56 "SMTP: [tx] *****")
2007.03.07 10:42:56 Callback::LogText[THIS: 0022fb30] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 10:42:56 "SMTP: <rx> 235 Authentication
successful")
2007.03.07 10:42:56 Callback::LogText[THIS: 0022fb30] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 10:42:56 "SMTP: Authorized to host")
2007.03.07 10:42:56 Callback::LogText[THIS: 0022fb30] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 10:42:56 "SMTP: Connected to host")
2007.03.07 10:42:56 Callback::ReportStatus[THIS: 0022fb30]
(ulAsynchPhase = RSF_CONNECTED) Progress = 1/4
2007.03.07 10:42:56 Callback::LogText[THIS: 0022fb30] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 10:42:56 "SMTP: [tx] MAIL FROM: <[email protected]>")
2007.03.07 10:42:56 Callback::LogText[THIS: 0022fb30] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 10:42:56 "SMTP: <rx> 250 Ok")
2007.03.07 10:42:56 Callback::ReportStatus[THIS: 0022fb30]
(ulAsynchPhase = RSF_INPROGRESS) Progress = 2/5
2007.03.07 10:42:56 Callback::LogText[THIS: 0022fb30] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 10:42:56 "SMTP: [tx] RCPT TO: <[email protected]>")
2007.03.07 10:42:56 Callback::LogText[THIS: 0022fb30] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 10:42:56 "SMTP: <rx> 250 Ok")
2007.03.07 10:42:56 Callback::ReportStatus[THIS: 0022fb30]
(ulAsynchPhase = RSF_INPROGRESS) Progress = 3/6
2007.03.07 10:42:56 Callback::LogText[THIS: 0022fb30] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 10:42:56 "SMTP: [tx] DATA")
2007.03.07 10:42:56 Callback::LogText[THIS: 0022fb30] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 10:42:56 "SMTP: <rx> 354 Please start mail
input.")
2007.03.07 10:42:58 ResourceObject [THIS: 00142940]: Synchronize called
(flags = 00000001)
2007.03.07 10:42:58 ResourceObject [THIS: 00142940]: Synch operation
queued
2007.03.07 10:44:11 Callback::ReportStatus[THIS: 0022fb30]
(ulAsynchPhase = RSF_COMPLETED, hrStatus = 0x00000000)

==================================================================================================
the following is a normal email log:

2007.03.07 12:25:08 Callback::ExecuteThread[THIS: 04876da8] (00001000)
returns 00000000
2007.03.07 12:25:08 Callback::LogText[THIS: 04876da8] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 12:25:08 "CSMTPPutTask: Begin execution")
2007.03.07 12:25:08 Callback::LogText[THIS: 04876da8] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 12:25:08 "SMTP PH: Connecting to SMTP server")
2007.03.07 12:25:08 Callback::ExecuteThread[THIS: 04876da8] (00001000)
returns 00000000
2007.03.07 12:25:08 Callback::LogText[THIS: 04876da8] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 12:25:08 "SMTP: Finding host")
2007.03.07 12:25:08 Callback::LogText[THIS: 04876da8] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 12:25:08 "SMTP: Connected to host")
2007.03.07 12:25:08 Callback::LogText[THIS: 04876da8] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 12:25:08 "SMTP: <rx> 220 mail2.lifestyles.net")
2007.03.07 12:25:08 Callback::LogText[THIS: 04876da8] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 12:25:08 "SMTP: [tx] EHLO HOWKS407")
2007.03.07 12:25:08 Callback::LogText[THIS: 04876da8] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 12:25:08 "SMTP: <rx> 250-mail2.lifestyles.net")
2007.03.07 12:25:08 Callback::LogText[THIS: 04876da8] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 12:25:08 "SMTP: <rx> 250-PIPELINING")
2007.03.07 12:25:08 Callback::LogText[THIS: 04876da8] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 12:25:08 "SMTP: <rx> 250-SIZE 7240000")
2007.03.07 12:25:08 Callback::LogText[THIS: 04876da8] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 12:25:08 "SMTP: <rx> 250-ETRN")
2007.03.07 12:25:08 Callback::LogText[THIS: 04876da8] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 12:25:08 "SMTP: <rx> 250-STARTTLS")
2007.03.07 12:25:08 Callback::LogText[THIS: 04876da8] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 12:25:08 "SMTP: <rx> 250-AUTH PLAIN LOGIN
GSSAPI")
2007.03.07 12:25:08 Callback::LogText[THIS: 04876da8] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 12:25:08 "SMTP: <rx> 250-AUTH=PLAIN LOGIN
GSSAPI")
2007.03.07 12:25:08 Callback::LogText[THIS: 04876da8] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 12:25:08 "SMTP: <rx> 250 8BITMIME")
2007.03.07 12:25:08 Callback::LogText[THIS: 04876da8] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 12:25:08 "SMTP: Authorizing to server")
2007.03.07 12:25:08 Callback::LogText[THIS: 04876da8] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 12:25:08 "SMTP: [tx] AUTH LOGIN")
2007.03.07 12:25:08 Callback::LogText[THIS: 04876da8] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 12:25:08 "SMTP: <rx> 334 VXNlcm5hbWU6")
2007.03.07 12:25:08 Callback::LogText[THIS: 04876da8] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 12:25:08 "SMTP: [tx] Y2xp")
2007.03.07 12:25:08 Callback::LogText[THIS: 04876da8] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 12:25:08 "SMTP: <rx> 334 UGFzc3dvcmQ6")
2007.03.07 12:25:08 Callback::LogText[THIS: 04876da8] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 12:25:08 "SMTP: [tx] *****")
2007.03.07 12:25:08 Callback::LogText[THIS: 04876da8] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 12:25:08 "SMTP: <rx> 235 Authentication
successful")
2007.03.07 12:25:08 Callback::LogText[THIS: 04876da8] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 12:25:08 "SMTP: Authorized to host")
2007.03.07 12:25:08 Callback::LogText[THIS: 04876da8] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 12:25:08 "SMTP: Connected to host")
2007.03.07 12:25:08 Callback::ReportStatus[THIS: 04876da8]
(ulAsynchPhase = RSF_CONNECTED) Progress = 1/4
2007.03.07 12:25:08 Callback::LogText[THIS: 04876da8] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 12:25:08 "SMTP: [tx] MAIL FROM: <[email protected]>")
2007.03.07 12:25:08 Callback::LogText[THIS: 04876da8] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 12:25:08 "SMTP: <rx> 250 Ok")
2007.03.07 12:25:08 Callback::ReportStatus[THIS: 04876da8]
(ulAsynchPhase = RSF_INPROGRESS) Progress = 2/5
2007.03.07 12:25:08 Callback::LogText[THIS: 04876da8] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 12:25:08 "SMTP: [tx] RCPT TO: <[email protected]>")
2007.03.07 12:25:08 Callback::LogText[THIS: 04876da8] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 12:25:08 "SMTP: <rx> 250 Ok")
2007.03.07 12:25:08 Callback::LogText[THIS: 04876da8] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 12:25:08 "SMTP: [tx] RCPT TO: <[email protected]>")
2007.03.07 12:25:08 Callback::LogText[THIS: 04876da8] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 12:25:08 "SMTP: <rx> 250 Ok")
2007.03.07 12:25:08 Callback::ReportStatus[THIS: 04876da8]
(ulAsynchPhase = RSF_INPROGRESS) Progress = 3/6
2007.03.07 12:25:08 Callback::LogText[THIS: 04876da8] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 12:25:08 "SMTP: [tx] DATA")
2007.03.07 12:25:08 Callback::LogText[THIS: 04876da8] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 12:25:08 "SMTP: <rx> 354 Please start mail
input.")
2007.03.07 12:25:08 Callback::LogText[THIS: 04876da8] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 12:25:08 "SMTP: [tx]
..")
2007.03.07 12:25:08 Callback::LogText[THIS: 04876da8] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 12:25:08 "SMTP: <rx> 250 Mail queued for
delivery.")
2007.03.07 12:25:08 Callback::ReportStatus[THIS: 04876da8]
(ulAsynchPhase = RSF_INPROGRESS) Progress = 4/7
2007.03.07 12:25:08 Callback::ReportStatus[THIS: 04876da8]
(ulAsynchPhase = RSF_COMPLETED, hrStatus = 0x00000000)

==============================================================================================================

So, the problem email miss this part:

Callback::LogText[THIS: 04876da8] (flags = LTF_TRACE, hr = 00000000, code =
00000000,
2007.03.07 12:25:08 "SMTP: [tx]
..")
2007.03.07 12:25:08 Callback::LogText[THIS: 04876da8] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 12:25:08 "SMTP: <rx> 250 Mail queued for
delivery.")
2007.03.07 12:25:08 Callback::ReportStatus[THIS: 04876da8]
(ulAsynchPhase = RSF_INPROGRESS) Progress = 4/7

So, my question is: was the outlook busy at that time? Because the server
responsed (rx), and it's the outlook's turn to response (tx), but there was
no tx from outlook, and after a bit of time, the outlook take as this email
has been sent out, so put it to the sent items.

And when the user send this email again, it will go through (the recipient
can receive the email).

Is this the outlook problem or postfix problem?

Thank you very much.
 
F

F.H. Muffman

Sam said:
So, the problem email miss this part:

Callback::LogText[THIS: 04876da8] (flags = LTF_TRACE, hr = 00000000,
code = 00000000,
2007.03.07 12:25:08 "SMTP: [tx]
.")
2007.03.07 12:25:08 Callback::LogText[THIS: 04876da8] (flags =
LTF_TRACE, hr = 00000000, code = 00000000,
2007.03.07 12:25:08 "SMTP: <rx> 250 Mail queued for
delivery.")
2007.03.07 12:25:08 Callback::ReportStatus[THIS: 04876da8]
(ulAsynchPhase = RSF_INPROGRESS) Progress = 4/7

So, my question is: was the outlook busy at that time? Because the
server responsed (rx), and it's the outlook's turn to response (tx),
but there was no tx from outlook, and after a bit of time, the
outlook take as this email has been sent out, so put it to the sent
items.
And when the user send this email again, it will go through (the
recipient can receive the email).

Is this the outlook problem or postfix problem?
Click to expand...

Maybe either, to be honest (but I'd lean towards a network hardware issue).

Personally, I would dig up a network trace program so I could read the
packets being sent and received and run that on both the client and the
server and compare what is being sent and recieved on each. But that's just
because I can read a network trace better than I can read that log,
especially since you know that the client recieved a response to the DATA
command, but did it actually send the mail message? There's no way to be
sure looking at that log.

Are you able to reproduce the problem at will? It doesn't sound it, but I
figured I'd ask.
 

Ask a Question

Want to reply to this thread or ask your own question?

You'll need to choose a username for the site, which only take a couple of moments. After that, you can post your question and our members will help you out.

Ask a Question

Similar Threads

Wierd E-Mail Problem 1
550 Administrative prohibition 5
0x800CCC97 receiving mail 7
Repost: OPMLog.log: failed connection to mail server 2
outlook won't send multiple recipients (e.g., 5)--have OPMLog.log 1
Outlook sending e-mail problems 6
Outlook 2002 sends test message ok but fails an sending a message within Outlook 1
Error 0x8007007E and 0x8004210A in Outlook 2002 on TS session 1

Top