Topic: Help needed to diagnose problem

[ianhobson]

Hi,

My SME7.0Pre1 server has started not to handle outgoing SMTP mail, and I can't work out what is wrong.

(The sending machine has just been rebuilt - new M/B, CPU and Memory, reinstalled O/S and many programs, so lots has changed there. To the best of my knowledge nothing changed on SME end. I need help diagnosing the trouble.)

Here is the SMTP log of one attempt at sending the message. Below that is the log from my mail program.

Last time this happened, I deleted the email and others then cleared. The one that is stuck is a small, one page, text only thing. The previously stuck message was to the same contact.

Any ideas anyone?

Regards and thanks

Ian

My PC is 192.168.0.73.

2006-04-03 10:07:02.465699500 8651 trying to get config for timeout
2006-04-03 10:09:01.400729500 4764 Accepted connection 3/40 from 192.168.0.73 / pc-00073.ianhobson.co.uk
2006-04-03 10:09:01.408812500 8670 Connection from pc-00073.ianhobson.co.uk [192.168.0.73]
2006-04-03 10:09:01.413420500 8670 running plugin (connect): check_earlytalker
2006-04-03 10:09:01.418423500 8670 trying to get config for memory_threshold
2006-04-03 10:09:02.425261500 8670 check_earlytalker plugin: remote host said nothing spontaneous, proceeding
2006-04-03 10:09:02.430226500 8670 Plugin check_earlytalker, hook connect returned DECLINED,
2006-04-03 10:09:02.430238500 8670 running plugin (connect): check_relay
2006-04-03 10:09:02.430243500 8670 trying to get config for relayclients
2006-04-03 10:09:02.433373500 8670 trying to get config for morerelayclients
2006-04-03 10:09:02.436034500 8670 Plugin check_relay, hook connect returned DECLINED,
2006-04-03 10:09:02.437537500 8670 running plugin (connect): check_norelay
2006-04-03 10:09:02.439573500 8670 trying to get config for norelayclients
2006-04-03 10:09:02.442887500 8670 Plugin check_norelay, hook connect returned DECLINED,
2006-04-03 10:09:02.444601500 8670 trying to get config for smtpgreeting
2006-04-03 10:09:02.446576500 8670 trying to get config for me
2006-04-03 10:09:02.449631500 8670 220 ianhobson.co.uk ESMTP qpsmtpd 0.31-dev ready; send us your mail, but not your spam.
2006-04-03 10:09:02.452056500 8670 trying to get config for timeoutsmtpd
2006-04-03 10:09:02.454095500 8670 trying to get config for timeout
2006-04-03 10:09:02.456460500 8670 dispatching EHLO mars.ianhobson.co.uk
2006-04-03 10:09:02.458892500 8670 running plugin (ehlo): check_spamhelo
2006-04-03 10:09:02.460967500 8670 trying to get config for badhelo
2006-04-03 10:09:02.464397500 8670 Plugin check_spamhelo, hook ehlo returned DECLINED,
2006-04-03 10:09:02.466657500 8670 trying to get config for me
2006-04-03 10:09:02.468444500 8670 trying to get config for databytes
2006-04-03 10:09:02.471231500 8670 250-ianhobson.co.uk Hi pc-00073.ianhobson.co.uk [192.168.0.73]
2006-04-03 10:09:02.472937500 8670 250-PIPELINING
2006-04-03 10:09:02.474469500 8670 250 8BITMIME
2006-04-03 10:09:02.604218500 8670 dispatching MAIL FROM:<Ian@ianhobson.co.uk>
2006-04-03 10:09:02.609216500 8670 trying to get config for memory_threshold
2006-04-03 10:09:02.609703500 8670 full from_parameter: FROM:<Ian@ianhobson.co.uk>
2006-04-03 10:09:02.611238500 8670 from email address : [<Ian@ianhobson.co.uk>]
2006-04-03 10:09:02.615505500 8670 running plugin (mail): require_resolvable_fromhost
2006-04-03 10:09:02.617958500 8670 trying to get config for invalid_resolvable_fromhost
2006-04-03 10:09:02.620490500 8670 trying to get config for require_resolvable_fromhost
2006-04-03 10:09:02.623640500 8670 Plugin require_resolvable_fromhost, hook mail returned DECLINED,
2006-04-03 10:09:02.625107500 8670 running plugin (mail): check_badmailfrom
2006-04-03 10:09:02.627050500 8670 trying to get config for badmailfrom
2006-04-03 10:09:02.630064500 8670 Plugin check_badmailfrom, hook mail returned DECLINED,
2006-04-03 10:09:02.632299500 8670 getting mail from <Ian@ianhobson.co.uk>
2006-04-03 10:09:02.633912500 8670 250 <Ian@ianhobson.co.uk>, sender OK - how exciting to get mail from you!
2006-04-03 10:09:02.636543500 8670 dispatching RCPT TO:<coach@willow.demon.co.uk>
2006-04-03 10:09:02.638719500 8670 to email address : [<coach@willow.demon.co.uk>]
2006-04-03 10:09:02.640666500 8670 running plugin (rcpt): check_badmailfrom
2006-04-03 10:09:02.642703500 8670 Plugin check_badmailfrom, hook rcpt returned DECLINED,
2006-04-03 10:09:02.644203500 8670 running plugin (rcpt): check_badrcptto_patterns
2006-04-03 10:09:02.646383500 8670 Plugin check_badrcptto_patterns, hook rcpt returned DECLINED,
2006-04-03 10:09:02.647861500 8670 running plugin (rcpt): check_badrcptto
2006-04-03 10:09:02.649982500 8670 Plugin check_badrcptto, hook rcpt returned DECLINED,
2006-04-03 10:09:02.651576500 8670 running plugin (rcpt): rcpt_ok
2006-04-03 10:09:02.653785500 8670 trying to get config for me
2006-04-03 10:09:02.655467500 8670 trying to get config for rcpthosts
2006-04-03 10:09:02.659366500 8670 trying to get config for morercpthosts
2006-04-03 10:09:02.661820500 8670 Plugin rcpt_ok, hook rcpt returned OK,
2006-04-03 10:09:02.663603500 8670 250 <coach@willow.demon.co.uk>, recipient ok
2006-04-03 10:09:02.665684500 8670 dispatching DATA
2006-04-03 10:09:02.667933500 8670 354 go ahead
2006-04-03 10:09:02.669699500 8670 trying to get config for databytes
2006-04-03 10:09:02.671259500 8670 max_size: 0 / size: 0
2006-04-03 10:09:02.673740500 8670 trying to get config for timeout
2006-04-03 10:10:47.194716500 4764 Accepted connection 4/40 from 81.103.221.46 / mta06-winn.ispmail.ntl.com

Mon, 3 Apr 2006 10:08:22 Mail connection to jupiter closed, 0 messages transmitted
Mon, 3 Apr 2006 10:08:51 Starting to send mail to jupiter
Mon, 3 Apr 2006 10:10:15 Error on closing
 -- Winsock ERROR : Connection aborted
Mon, 3 Apr 2006 10:10:15 Mail connection to jupiter closed, 0 messages transmitted
Mon, 3 Apr 2006 10:10:53 Starting to send mail to jupiter

[byte]

First thing and most important have you reported this to the bug tracker? if not you will need to do so...

Secondly you may want to upgrade to 7.0rc1 as the problem you reported may have been a bug?!

[ianhobson]

Hi byte, thanks for your input.

I have not reported it to the bug tracker because
a) It was working, and SME has not changed.
b) Outlook Express still works through the same SME.

Therefore I am reasonably confident there is no relevant bug in SME. Until I suspect SME this has no place in the SME bug tracker.

(And I am not about to go through the pain of upgrading the firewall until 7.0 goes live unless I have to. ).

Further info - disabling the SMTP proxy in SME,and changing the mail program's credentials to use the ISP's SMTP server directly, and all works fine.

Looking like SME doesn't like Turnpike 6.05 when it was happy with 6.02.

Regards
Ian

[JonB]

Ian,

It looks like you haven't included all the logs for the PID 8670. You will probably find them a bit further down in the log file.

Without the rest it is hard to say what the problem is but so far there is no problem.

Jon

[ianhobson]

Hi JonB

You are right - there are two more lines rather later, refereing to 8670.

2006-04-03 10:29:02.931252500 8670 Connection Timed Out
2006-04-03 10:29:03.421648500 4764 cleaning up after 8670

I'm not 100% sure, but it might be related, so I'll include the info anyway...

All the problems have been sending mail to the same person at demon. Both direct and via an email address that is forwarded.
He collected his email this moring and I have not a had a problem since, and have sent him three emails to prove things.

Was his mail box full? He says not - hasn't had much mail today, and I think not becasue I didn't get a mail-box full bounce.

Still puzzled.

Ian

[CharlieBrady]

Was his mail box full?

It's got nothing to do with his mailbox. qpsmtpd never received the message, so certainly nothing tried to deliver it to his mailbox. The problem is in the sending program (or the system it runs on). See the WINSOCK error in the log you quoted.

If qpsmtpd doesn't receive the message content, then it obviously can't do anything useful with it.