[SOLVED] "refused to talk to me: 421 Timed out" from one server

[kusu]

Hi

We are running zimbra 6.0.5 on Ubuntu 8.04 (64 bit) on VMWare. This works basically fine and we are well able to send and receive mails from all over the planet.

However, there's one server that we are unable to send mail to. When we send mail to that server, the mail gets deferred and finally fails. The mail log file contains error messages of the type

May 28 15:38:05 blumchzhrs06 postfix/smtp[3401]: 546F3EC28A: to=<xxx@colomeargentina.com>, relay=mail.colomeargentina.com[216.59.32.116]:25, delay=84461, delays=84371/0/90/0, dsn=4.0.0, status=deferred (host mail.colomeargentina.com[216.59.32.116] refused to talk to me: 421 Timed out)

When I telnet the same server (216.59.32.116) from our zimbra server, I can send it a mail manually, so I don't think our IP is blocked.

Can anyone provide any advice?

Regards

Kurt

[kusu]

I have delved further into this and found some additional information. When looking at the traffic between our server and the remote server using a packet sniffer, I see that the following data is exchanged

No.     Time        Source                Destination           Protocol Info
      1 0.000000    192.168.0.16          216.59.32.116         TCP      48316 > smtp [SYN] Seq=0 Win=5840 Len=0 MSS=1460 TSV=445464778 TSER=0 WS=7
     2 0.123442    216.59.32.116         192.168.0.16          TCP      smtp > 48316 [SYN, ACK] Seq=0 Ack=1 Win=5792 Len=0 MSS=1350 TSV=463179547 TSER=445464778 WS=7
     3 0.123557    192.168.0.16          216.59.32.116         TCP      48316 > smtp [ACK] Seq=1 Ack=1 Win=5888 Len=0 TSV=445464790 TSER=463179547
     4 0.255545    216.59.32.116         192.168.0.16          SMTP     S: 220 us16.toservers.com ESMTP Postfix 2.7.40
     5 0.255648    192.168.0.16          216.59.32.116         TCP      48316 > smtp [ACK] Seq=1 Ack=46 Win=5888 Len=0 TSV=445464803 TSER=463179580
      6 0.255719    192.168.0.16          216.59.32.116         SMTP     C: EHLO eblum.ch
      7 0.494721    216.59.32.116         192.168.0.16          TCP      smtp > 48316 [ACK] Seq=46 Ack=16 Win=5888 Len=0 TSV=463179640 TSER=445464803
      8 0.495159    216.59.32.116         192.168.0.16          SMTP     S: 502 Error: command not implemented | \000
      9 0.495287    192.168.0.16          216.59.32.116         SMTP     C: HELO eblum.ch
     10 0.617947    216.59.32.116         192.168.0.16          SMTP     S: 250 towebs
     11 0.648879    192.168.0.16          216.59.32.116         TCP      48316 > smtp [ACK] Seq=31 Ack=95 Win=5888 Len=0 TSV=445464843 TSER=463179671
     12 90.618160   216.59.32.116         192.168.0.16          SMTP     S: 421 Timed out
     13 90.618292   192.168.0.16          216.59.32.116         TCP      48316 > smtp [ACK] Seq=31 Ack=110 Win=5888 Len=0 TSV=445473840 TSER=463202171
     14 90.618549   216.59.32.116         192.168.0.16          TCP      smtp > 48316 [FIN, ACK] Seq=110 Ack=31 Win=5888 Len=0 TSV=463202171 TSER=445464843
     15 90.629865   192.168.0.16          216.59.32.116         SMTP     C: QUIT
     16 90.629873   192.168.0.16          216.59.32.116         TCP      48316 > smtp [FIN, ACK] Seq=37 Ack=111 Win=5888 Len=0 TSV=445473841 TSER=463202171
     17 90.751692   216.59.32.116         192.168.0.16          TCP      smtp > 48316 [RST] Seq=111 Win=0 Len=0

In other words, the SMTP traffic looks as follows:

1. Our Server connects.
2. Their server: us16.toservers.com ESMTP Postfix 2.7.40
3. Our server: EHLO eblum.ch
4. Their server: 502 Error: command not implemented
5. Our server: HELO eblum.ch
6. Their server: 250 towebs
7. Their server: 421 Timed out
8. Our server: QUIT

It seems their server is right to time out, because about 90 seconds pass between steps 6 and 7.

Why is zimbra not replying to "250 towebs"?

Kurt

[kusu]

I have now enabled smtp debuggin with that peer:

postconf -e debug_peer_list=colomeargentina.com
postconf -e debug_peer_level=3
postfix reload

and syslog says:

May 31 05:14:18 blumchzhrs06 postfix/qmgr[25678]: 88B72EC28B: from=<xxx@eblum.ch>, size=6880, nrcpt=1 (queue active)
May 31 05:14:18 blumchzhrs06 postfix/smtp[25024]: vstream_buf_get_ready: fd 12 got 45
May 31 05:14:18 blumchzhrs06 postfix/smtp[25024]: < mail.colomeargentina.com[216.59.32.116]:25: 220 us16.toservers.com ESMTP Postfix 2.7.40
May 31 05:14:18 blumchzhrs06 postfix/smtp[25024]: > mail.colomeargentina.com[216.59.32.116]:25: EHLO eblum.ch
May 31 05:14:18 blumchzhrs06 postfix/smtp[25024]: vstream_fflush_some: fd 12 flush 15
May 31 05:14:18 blumchzhrs06 postfix/smtp[25024]: vstream_buf_get_ready: fd 12 got 37
May 31 05:14:18 blumchzhrs06 postfix/smtp[25024]: < mail.colomeargentina.com[216.59.32.116]:25: 502 Error: command not implemented
May 31 05:14:18 blumchzhrs06 postfix/smtp[25024]: > mail.colomeargentina.com[216.59.32.116]:25: HELO eblum.ch
May 31 05:14:18 blumchzhrs06 postfix/smtp[25024]: vstream_fflush_some: fd 12 flush 15
May 31 05:14:18 blumchzhrs06 postfix/smtp[25024]: vstream_buf_get_ready: fd 12 got 12
May 31 05:14:18 blumchzhrs06 postfix/smtp[25024]: < mail.colomeargentina.com[216.59.32.116]:25: 
May 31 05:15:48 blumchzhrs06 postfix/smtp[25024]: vstream_buf_get_ready: fd 12 got 15
May 31 05:15:48 blumchzhrs06 postfix/smtp[25024]: < mail.colomeargentina.com[216.59.32.116]:25: 421 Timed out

Hence, interestingly, it appears that zimbra receives 12 bytes (vstream_buf_get_ready: fd 12 got 12), probably the "250 towebs\r\n", but then says
May 31 05:14:18 blumchzhrs06 postfix/smtp[25024]: < mail.colomeargentina.com[216.59.32.116]:25:

where have the 12 bytes are missing.

I am presently trying to find out why the EHLO command fails even so the remote server advertises ESMTP. We are sitting behind a CISCO firewall, that might be the reason, but I have no control over that.

I have tried from another zimbra server not behind that firewall, and from there things work perfectly.

Anyway, even if the EHLO command fails, zimbra goes back to HELO and that should work. I have no real idea why the above communication fails. In particular, the two lines

May 31 05:14:18 blumchzhrs06 postfix/smtp[25024]: vstream_buf_get_ready: fd 12 got 12
May 31 05:14:18 blumchzhrs06 postfix/smtp[25024]: < mail.colomeargentina.com[216.59.32.116]:25:

seem to be contradictory because the first one says to have received 12 bytes while the second one reports an empty string.

Does anyone have any clue?

[veronica]

Its for the reason you have your IP listed as blacklist see

Network Tools: DNS,IP,Email

[kusu]

Veronica

Its for the reason you have your IP listed as blacklist see

Nope, 216.59.32.116 is listed, and that is THEIR address (i.e. the receiver's address). OURS is not listed.

Anyway, I now got our ISP to remove SMTP-Inspection in the Cicso firewall, and first experiments show that the problem has been solved by that. Even though I don't know why we got such strange effects.

Kurt

[phoenix]

Anyway, I now got our ISP to remove SMTP-Inspection in the Cicso firewall, and first experiments show that the problem has been solved by that. Even though I don't know why we got such strange effects.

The problem with port 25 inspection on CISCO firewalls and mail servers is well know (if you do a google search) and is also mentioned on these forums. I'd suggest anyone that has problems with their mail server and has a CISCO in front of it should investigate that problem first.