CGatePro@mail.stalker.com Mailing List Archive

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

From:	sjakie <ssjakie@gmail.com>
Subject:	Bad SMTP prompt at the host, smtp closing connection during sending
Date:	Wed, 24 Jun 2009 07:15:35 -0700
To:	CGatePro

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
21:45:05.740 4 DNR-019765(mx3.xs4all.nl) A[0]: mx3.xs4all.nl=[194.109.24.134]
21:45:05.740 4 SMTP-001643(jer.demon.nl) connecting to [194.109.24.134]:25
21:45:07.255 5 SMTP-001643(jer.demon.nl) inp: 220-***********************************************************************************************
21:45:07.255 5 SMTP-001643(jer.demon.nl) inp: *******************************************************
21:45:07.255 3 SMTP-001643(jer.demon.nl) Expected '220 ...' at [194.109.24.134]:25, got:*******************************************************
21:45:07.255 5 SMTP-001643(jer.demon.nl) out: QUIT\r\n
21:45:07.255 5 SMTP-001643(jer.demon.nl) inp: ************************************************************
21:45:07.255 4 SMTP-001643(jer.demon.nl) closing connection
21:45:07.255 4 SMTP-001643(jer.demon.nl) resolving 'mx4.xs4all.nl'
21:45:07.255 5 DNR-019766(mx4.xs4all.nl) A-request
21:45:07.255 4 DNR-019766(mx4.xs4all.nl) A-request -> udp:[192.168.20.10]:53
21:45:07.255 5 DNR-019766(mx4.xs4all.nl) got 47 bytes from [192.168.20.10]:53: 4D 36 81 80 00 01 00 01 00 00 00 00 03 6D 78 34 06 78 73 34 61 6C 6C 02 6E 6C 00 00 01 00 01 C0 0C 00 01 00 01 00 00 11 E3 00 04 C2 6D 18 8B
21:45:07.255 5 DNR-019766(mx4.xs4all.nl) A:OK
21:45:07.255 4 DNR-019766(mx4.xs4all.nl) A[0]: mx4.xs4all.nl=[194.109.24.139]
21:45:07.255 4 SMTP-001643(jer.demon.nl) connecting to [194.109.24.139]:25
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
21:45:08.896 4 SMTP(@192.168.20.154:jer.demon.nl) re-enqueue
21:45:08.896 5 SMTP waiting: @192.168.20.154:somedomain.com @192.168.20.154:home.nl xs4all.nl active:
21:45:08.896 5 SMTP(@192.168.20.154:somedomain.com) is first in queue with 392 second(s) delay
21:45:08.896 4 SMTP-001643(jer.demon.nl) releasing stream
21:45:21.053 2 TLS-002482 session released
21:45:21.053 2 TLS-002480 session released
21:45:21.053 2 TLS-002478 session released
21:45:21.053 2 TLS-002481 session released
21:45:23.896 5 SMTP stream thread finished

23:43:46.162 5 SMTP [0.0.0.0]:25 <- [10.10.10.1]:1141 connection request. socket=324
23:43:46.162 4 SMTPI-013868([10.10.10.1]) got connection on [192.168.20.154]:25(researchsoftware.nl) from [10.10.10.1]:1141
23:43:46.162 5 SMTPI-013868([10.10.10.1]) out: 220 researchsoftware.nl ESMTP CommuniGate Pro 5.1.16 is glad to see you!\r\n
23:43:46.162 5 SMTPI-013868([10.10.10.1]) inp: EHLO PC03
23:43:46.162 5 SMTPI-013868([10.10.10.1]) out: 250-researchsoftware.nl domain name should be qualified PC03\r\n250-DSN\r\n250-SIZE\r\n250-STARTTLS\r\n250-AUTH LOGIN PLAIN CRAM-MD5 DIGEST-MD5 GSSAPI MSN NTLM\r\n250-ETRN\r\n250-TURN\r\n250-ATRN\r\n250-NO-SOLICITING\r\n250-HELP\r\n250-PIPELINING\r\n250
23:43:46.177 5 SMTPI-013868([10.10.10.1]) inp: AUTH NTLM
23:43:46.177 5 SMTPI-013868([10.10.10.1]) SASL-0(NTLM) out:
23:43:46.177 5 SMTPI-013868([10.10.10.1]) out: 334 \r\n
23:43:46.193 5 SMTPI-013868([10.10.10.1]) inp: TlRMTVNTUAABAAAAB4IIogAAAAAAAAAAAAAAAAAAAAAFASgKAAAADw==
23:43:46.193 5 SMTPI-013868([10.10.10.1]) SASL-0(NTLM) inp: 4E 54 4C 4D 53 53 50 00 01 00 00 00 07 82 08 A2 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 05 01 28 0A 00 00 00 0F
23:43:46.193 5 SMTPI-013868([10.10.10.1]) SASL-1(NTLM) out: 4E 54 4C 4D 53 53 50 00 02 00 00 00 00 00 00 00 30 00 00 00 05 82 00 A2 38 36 38 34 32 36 38 34 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
23:43:46.193 5 SMTPI-013868([10.10.10.1]) out: 334 TlRMTVNTUAACAAAAAAAAADAAAAAFggCiODY4NDI2ODQAAAAAAAAAAAAAAAAAAAAA\r\n
23:43:46.208 5 SMTPI-013868([10.10.10.1]) inp: *
23:43:46.208 5 SMTPI-013868([10.10.10.1]) out: 535 SASL protocol has been interrupted\r\n
23:43:46.224 5 SMTPI-013868([10.10.10.1]) inp: AUTH DIGEST-MD5
23:43:46.224 5 SMTPI-013868([10.10.10.1]) SASL-0(DIGEST-MD5) out: nonce="13868a1245793426aresearchsoftware.nl",qop="auth",charset=utf-8,algorithm=md5-sess
23:43:46.224 5 SMTPI-013868([10.10.10.1]) out: 334 bm9uY2U9IjEzODY4YTEyNDU3OTM0MjZhcmVzZWFyY2hzb2Z0d2FyZS5ubCIscW9wPSJhdXRoIixjaGFyc2V0PXV0Zi04LGFsZ29yaXRobT1tZDUtc2Vzcw==\r\n
23:43:46.240 5 SMTPI-013868([10.10.10.1]) inp: dXNlcm5hbWU9InN1YXQlcmVzZWFyY2hzb2Z0d2FyZS5jb20iLHJlYWxtPSIiLG5vbmNlPSIxMzg2OGExMjQ1NzkzNDI2YXJlc2VhcmNoc29mdHdhcmUubmwiLGRpZ2VzdC11cmk9InNtdHAvbWFpbC5yZXNlYXJjaHNvZnR3YXJlLmNvbSIsY25vbmNlPSJjZGNmOTU3YWYyYTY2NjdkMjcyZTEzNzZiMjRkMDc2YSIsbmM9MDAwMDAwMDEsc
23:43:46.240 5 SMTPI-013868([10.10.10.1]) SASL-0(DIGEST-MD5) inp: username="sjaak%researchsoftware.com",realm="",nonce="13868a1245793426aresearchsoftware.nl",digest-uri="smtp/mail.researchsoftware.com",cnonce="cdcf957af2a6667d272e1376b24d076a",nc=00000001,response=bf444058c7d34ad55632e6b6e2a011d9,qop
23:43:46.240 2 ROUTER LOCAL: 'sjaak%researchsoftware.com' accepted: '' at 'sjaak'
23:43:46.240 4 ACCOUNT(sjaak) login(SMTP) from [10.10.10.1]
23:43:46.240 2 SMTPI-013868([10.10.10.1]) 'sjaak@researchsoftware.nl' connected from [10.10.10.1]:1141
23:43:46.240 5 SMTPI-013868([10.10.10.1]) SASL-3(DIGEST-MD5) out: rspauth=98a66fb89d93032d02669501811154fd
23:43:46.240 5 SMTPI-013868([10.10.10.1]) out: 334 cnNwYXV0aD05OGE2NmZiODlkOTMwMzJkMDI2Njk1MDE4MTExNTRmZA==\r\n
23:43:46.255 5 SMTPI-013868([10.10.10.1]) inp:
23:43:46.255 5 SMTPI-013868([10.10.10.1]) SASL-3(DIGEST-MD5) inp:
23:43:46.255 2 SMTPI-013868([10.10.10.1]) 'sjaak@researchsoftware.nl' disconnected ([10.10.10.1]:1141)
23:43:46.255 5 SMTPI-013868([10.10.10.1]) out: 235 sjaak relaying authenticated\r\n
23:43:46.255 5 SMTPI-013868([10.10.10.1]) inp: MAIL FROM: <info@researchsoftware.com>
23:43:46.255 2 ROUTER LOCAL: 'info@researchsoftware.com' accepted: '' at 'sjaak'
23:43:46.255 5 SMTPI-013868([10.10.10.1]) out: 250 info@researchsoftware.com sender accepted\r\n
23:43:46.271 5 SMTPI-013868([10.10.10.1]) inp: RCPT TO: <sjaak@xs4all.nl>
23:43:46.271 2 ROUTER SMTP: 'sjaak@xs4all.nl' accepted: 'sjaak@xs4all.nl' at 'xs4all.nl'
23:43:46.271 5 SMTPI-013868([10.10.10.1]) out: 250 sjaak@xs4all.nl will relay mail for an authenticated user\r\n
23:43:46.287 5 SMTPI-013868([10.10.10.1]) inp: DATA
23:43:46.287 5 SMTPI-013868([10.10.10.1]) out: 354 Enter mail, end with "." on a line by itself\r\n
23:43:46.505 2 SMTPI-013868([10.10.10.1]) [6427365] received(sjaak), 6339 bytes
23:43:46.505 5 SMTPI-013868([10.10.10.1]) out: 250 6427365 message accepted for delivery\r\n
23:43:46.505 2 ROUTER SMTP: '<sjaak@xs4all.nl>' accepted: 'sjaak@xs4all.nl' at 'xs4all.nl'
23:43:46.505 2 QUEUE([6427365]) from <info@researchsoftware.com>, 6339 bytes (<010101c9f44b$ab18e5f0$014ab1d0$@com>)
23:43:46.505 4 QUEUE([6427365]) enqueued, nTotal=14
23:43:46.505 4 QUEUE([6427365]) opened, nOpen=1
23:43:46.505 4 QUEUE([6427365]) applying server rules
23:43:46.505 4 SMTP(@192.168.20.154:xs4all.nl) [6427365] enqueueing (waiting)
23:43:46.505 5 SMTP waiting: @192.168.20.154:jer.demon.nl @192.168.20.154:creacontechnologies.com @192.168.20.154:home.nl active:
23:43:46.505 5 SMTP(@192.168.20.154:jer.demon.nl) is first in queue with 88 second(s) delay
23:43:46.505 2 QUEUE([6427365]) enqueued
23:43:46.505 4 QUEUE([6427365]) closed, nOpen=0
23:43:47.396 4 MAILBOX(sjaak/Sent) text mailbox opened
23:43:47.396 4 MAILBOX(sjaak/Sent) opened
23:43:47.396 4 ACCOUNT(sjaak) added size=5446, total=356459694
23:43:47.396 2 MAILBOX(sjaak/Sent) {169} appended @18672181: 61+5385(0) bytes
23:43:47.396 4 MAILBOX(sjaak/Sent) text mailbox closed
23:43:49.287 5 SMTPI-013868([10.10.10.1]) inp: QUIT
23:43:49.287 5 SMTPI-013868([10.10.10.1]) out: 221 researchsoftware.nl CommuniGate Pro SMTP closing connection\r\n
23:43:49.287 4 SMTPI-013868([10.10.10.1]) closing connection
23:43:49.287 4 SMTPI-013868([10.10.10.1]) releasing stream
23:43:56.756 5 SMTP stream thread finished

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