CGatePro@mail.stalker.com Mailing List Archive

Mailing List CGatePro@mail.stalker.com Message #98158

From:	Lyle Giese <lyle@lcrcomputer.net>
Subject:	Re: Bad SMTP prompt at the host, smtp closing connection during sending
Date:	Wed, 24 Jun 2009 10:46:18 -0500
To:	cgatepro@mail.stalker.com

sjakie wrote:

We have problems sending emails to some providers (among them xs4all.nl). It looks like CommunigatePro is closing connection while handshaking. We are not blacklisted. It looks like our ptr's are ok. Looked over a lot of the AUTH settings. Unfortunately, no solution yet. Multihoming could be an issue, however, untill 3 weeks earlier it all seemed ok with same settings and multihoming.

This is the bounce message:

Reporting-MTA: dns; researchsoftware.nl

Original-Recipient: rfc822;<sjaak@xs4all.nl>
Final-Recipient: rfc822;<sjaak@xs4all.nl>
Action: failed
Status: 4.0.0

Failed to deliver to 'sjaak@xs4all.nl'
SMTP module(domain @192.168.20.154:xs4all.nl) reports:
mx2.xs4all.nl: Bad SMTP prompt at the host

We have a firewall/router and 192.168.20.154 is our mail server IP (natted, WAN IP is 87.249.111.154). I have listed here two log sections from our mail server:

21:45:02.661 5 SMTP waiting: @192.168.20.154:somedomain.com @192.168.20.154:home.nl xs4all.nl active: @192.168.20.154:jer.demon.nl
21:45:02.661 5 SMTP(@192.168.20.154:somedomain.com) is first in queue with 398 second(s) delay
21:45:02.661 4 SMTP sending to @192.168.20.154:jer.demon.nl
21:45:02.661 5 SMTP new VStream created, n=1
21:45:02.661 5 SMTP waiting(get): @192.168.20.154:somedomain.com @192.168.20.154:home.nl xs4all.nl active: @192.168.20.154:jer.demon.nl
21:45:02.661 5 SMTP(@192.168.20.154:somedomain.com) is first in queue with 398 second(s) delay
21:45:02.661 5 SMTP stream thread started
21:45:02.661 5 SMTP-001643() started
21:45:02.661 5 SMTP-001643(jer.demon.nl) processing
21:45:02.661 5 DNR-019762(jer.demon.nl) MX-request
21:45:02.661 4 DNR-019762(jer.demon.nl) MX-request -> udp:[192.168.20.10]:53
21:45:02.677 5 DNR-019762(jer.demon.nl) got 152 bytes from [192.168.20.10]:53: 4D 32 81 80 00 01 00 04 00 02 00 00 03 6A 65 72 05 64 65 6D 6F 6E 02 6E 6C 00 00 0F 00 01 C0 0C 00 0F 00 01 00 00 0E 10 00 0F 00 64 03 6D 78 31 06 78 73 34 61 6C 6C C0 16 C0 0C 00 0F 00 01 00 00 0E 10 00 08 00 64 03 6D
21:45:02.677 5 DNR-019762(jer.demon.nl) MX:OK
21:45:02.677 4 DNR-019762(jer.demon.nl) MX[0]: jer.demon.nl(pty 100) = mx1.xs4all.nl
21:45:02.677 4 DNR-019762(jer.demon.nl) MX[1]: jer.demon.nl(pty 100) = mx2.xs4all.nl
21:45:02.677 4 DNR-019762(jer.demon.nl) MX[2]: jer.demon.nl(pty 100) = mx3.xs4all.nl
21:45:02.677 4 DNR-019762(jer.demon.nl) MX[3]: jer.demon.nl(pty 100) = mx4.xs4all.nl
21:45:02.677 5 SMTP-001643(jer.demon.nl) 4 relay(s) found:mx1.xs4all.nl mx2.xs4all.nl mx3.xs4all.nl
21:45:02.677 4 SMTP-001643(jer.demon.nl) resolving 'mx1.xs4all.nl'
21:45:02.677 5 DNR-019763(mx1.xs4all.nl) A-request
21:45:02.677 4 DNR-019763(mx1.xs4all.nl) A-request -> udp:[192.168.20.10]:53
21:45:02.677 5 DNR-019763(mx1.xs4all.nl) got 47 bytes from [192.168.20.10]:53: 4D 33 81 80 00 01 00 01 00 00 00 00 03 6D 78 31 06 78 73 34 61 6C 6C 02 6E 6C 00 00 01 00 01 C0 0C 00 01 00 01 00 00 11 E8 00 04 C2 6D 18 84
21:45:02.677 5 DNR-019763(mx1.xs4all.nl) A:OK
21:45:02.677 4 DNR-019763(mx1.xs4all.nl) A[0]: mx1.xs4all.nl=[194.109.24.132]
21:45:02.677 4 SMTP-001643(jer.demon.nl) connecting to [194.109.24.132]:25
21:45:04.208 5 SMTP-001643(jer.demon.nl) inp: 220-***********************************************************************************************
21:45:04.208 5 SMTP-001643(jer.demon.nl) inp: *******************************************************
21:45:04.208 3 SMTP-001643(jer.demon.nl) Expected '220 ...' at [194.109.24.132]:25, got:*******************************************************
21:45:04.208 5 SMTP-001643(jer.demon.nl) out: QUIT\r\n
21:45:04.208 5 SMTP-001643(jer.demon.nl) inp: ************************************************************
21:45:04.208 4 SMTP-001643(jer.demon.nl) closing connection
21:45:04.208 4 SMTP-001643(jer.demon.nl) resolving 'mx2.xs4all.nl'
21:45:04.208 5 DNR-019764(mx2.xs4all.nl) A-request
21:45:04.208 4 DNR-019764(mx2.xs4all.nl) A-request -> udp:[192.168.20.10]:53
21:45:04.208 5 DNR-019764(mx2.xs4all.nl) got 47 bytes from [192.168.20.10]:53: 4D 34 81 80 00 01 00 01 00 00 00 00 03 6D 78 32 06 78 73 34 61 6C 6C 02 6E 6C 00 00 01 00 01 C0 0C 00 01 00 01 00 00 11 E6 00 04 C2 6D 18 8A
21:45:04.208 5 DNR-019764(mx2.xs4all.nl) A:OK
21:45:04.208 4 DNR-019764(mx2.xs4all.nl) A[0]: mx2.xs4all.nl=[194.109.24.138]
21:45:04.208 4 SMTP-001643(jer.demon.nl) connecting to [194.109.24.138]:25
21:45:05.740 5 SMTP-001643(jer.demon.nl) inp: 220-***********************************************************************************************
21:45:05.740 5 SMTP-001643(jer.demon.nl) inp: *******************************************************
21:45:05.740 3 SMTP-001643(jer.demon.nl) Expected '220 ...' at [194.109.24.138]:25, got:*******************************************************
21:45:05.740 5 SMTP-001643(jer.demon.nl) out: QUIT\r\n
21:45:05.740 5 SMTP-001643(jer.demon.nl) inp: ************************************************************
21:45:05.740 4 SMTP-001643(jer.demon.nl) closing connection
21:45:05.740 4 SMTP-001643(jer.demon.nl) resolving 'mx3.xs4all.nl'
21:45:05.740 5 DNR-019765(mx3.xs4all.nl) A-request
21:45:05.740 4 DNR-019765(mx3.xs4all.nl) A-request -> udp:[192.168.20.10]:53
21:45:05.740 5 DNR-019765(mx3.xs4all.nl) got 47 bytes from [192.168.20.10]:53: 4D 35 81 80 00 01 00 01 00 00 00 00 03 6D 78 33 06 78 73 34 61 6C 6C 02 6E 6C 00 00 01 00 01 C0 0C 00 01 00 01 00 00 11 E5 00 04 C2 6D 18 86
21:45:05.740 5 DNR-019765(mx3.xs4all.nl) A:OK

Anyone any clue.. Thanks in advance for looking at this problem.
Sjaak

Sjaak,

From the logs, when your server connects to mx1.xs4all.nl, it gets back:

21:45:08.896 5 SMTP-001643(jer.demon.nl) inp: 220-***********************************************************************************************

21:45:08.896 5 SMTP-001643(jer.demon.nl) inp: *******************************************************

21:45:08.896 3 SMTP-001643(jer.demon.nl) Expected '220 ...' at [194.109.24.139]:25, got:*******************************************************
21:45:08.896 5 SMTP-001643(jer.demon.nl) out: QUIT\r\n
21:45:08.896 5 SMTP-001643(jer.demon.nl) inp: ************************************************************
21:45:08.896 4 SMTP-001643(jer.demon.nl) closing connection

Note that the '******************************************' are split across two lines and the second line does not have a 220 in front of it. Which is what CGPro is complaining about 'Expected '220 ...'.

But when I telnet to mx1.xs4all.nl from here, I get:

lyle@mail3a:~> telnet mx1.xs4all.nl 25
Trying 194.109.24.132...
Connected to mx1.xs4all.nl.
Escape character is '^]'.
220-mxdrop117.xs4all.nl ESMTP Sendmail 8.13.8/8.13.8; Wed, 24 Jun 2009 17:37:05 +0200 (CEST) NO UBE
220-This SMTP server is operated by XS4ALL Internet BV,
220-   Diemen, The Netherlands. XS4ALL Internet BV prohibits
220-   the use of this or any other XS4ALL systems or services
220-   for the transmission of Unsolicited Bulk E-mail (UBE).
220- Questions about delivery-problems should be directed to
220    the appropriate RFC 2142 mailbox addresses.
quit
221 2.0.0 mxdrop117.xs4all.nl closing connection
Connection closed by foreign host.

Where are the '******************' coming from in your logs? Are you using any Cisco gear with SMTP fixup invoked?

Lyle Giese
LCR Computer Services, Inc.