host 127.0.0.1[127.0.0.1] refused to talk to me

Discuss your pilot or production implementation with other Zimbra admins or our engineers.
Post Reply
mack3457
Posts: 12
Joined: Fri Jun 05, 2015 8:37 am

host 127.0.0.1[127.0.0.1] refused to talk to me

Post by mack3457 »

Hi,

for some reasons I rebooted our mail server with zimbra 8.8.15 this morning, but since then, no more mails are sent.

The error:

Code: Select all

Jul 31 14:59:28 is36 postfix/dkimmilter/smtpd[1556]: 7C2A7305599A6: client=xxx.yyy.zzz[aaa.bbb.ccc.ddd]
Jul 31 14:59:28 is36 postfix/cleanup[1553]: 7C2A7305599A6: message-id=<864568258.183.1627736368399.JavaMail.zimbra@ifis.cs.tu-bs.de>
Jul 31 14:59:28 is36 postfix/qmgr[20875]: 7C2A7305599A6: from=<mack@yyy.zzz>, size=1792, nrcpt=1 (queue active)
Jul 31 14:59:28 is36 postfix/smtp[1554]: 70DEB305599A3: to=<mack@th-mack.de>, relay=127.0.0.1[127.0.0.1]:10030, delay=0.1, delays=0.02/0.02/0.01/0.05, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 7C2A7305599A6)
Jul 31 14:59:28 is36 postfix/qmgr[20875]: 70DEB305599A3: removed
Jul 31 14:59:28 is36 postfix/dkimmilter/smtpd[1556]: disconnect from xxx.yyy.zzz[aaa.bbb.ccc.ddd] ehlo=2 starttls=1 mail=1 rcpt=1 data=1 quit=1 commands=7
Jul 31 14:59:28 is36 postfix/error[31796]: 7C2A7305599A6: to=<mack@th-mack.de>, relay=none, delay=0.05, delays=0.05/0/0/0, dsn=4.7.1, status=deferred (delivery temporarily suspended: host 127.0.0.1[127.0.0.1] refused to talk to me: 554 5.7.1 <xxx.yyy.zzz[aaa.bbb.ccc.ddd]>: Client host rejected: Access denied)
...
Jul 31 15:08:38 is36 postfix/qmgr[20875]: 7C2A7305599A6: from=<mack@yyy.zzz>, size=1792, nrcpt=1 (queue active)
...
Jul 31 15:08:38 is36 postfix/smtp[10252]: 7C2A7305599A6: to=<mack@th-mack.de>, relay=127.0.0.1[127.0.0.1]:10025, delay=550, delays=550/0.02/0.01/0, dsn=4.7.1, status=deferred (host 127.0.0.1[127.0.0.1] refused to talk to me: 554 5.7.1 <xxx.yyy.zzz[aaa.bbb.ccc.ddd]>: Client host rejected: Access denied)
So, the last line hints at amavis, which I disabled then, but anyway, the third last line ("Access denied") remains.

I don't understand, what it's telling me and where to look at. Postfix says, the server is trying to connect to localhost (what port?) and localhost denies the access to it - what is responsible for this behaviour and where to look for some misconfiguration?

Thanks
Thomas Mack
mack3457
Posts: 12
Joined: Fri Jun 05, 2015 8:37 am

Re: host 127.0.0.1[127.0.0.1] refused to talk to me

Post by mack3457 »

I see one problem currently, which is amavisd not reacting to 127.0.0.1 properly (immediately closing connection), but only on ::1:

Code: Select all

[root@is36 ~]# telnet 127.0.0.1 10026
Trying 127.0.0.1...
Connected to 127.0.0.1.
Escape character is '^]'.
Connection closed by foreign host.
[root@is36 ~]# telnet ::1 10026
Trying ::1...
Connected to ::1.
Escape character is '^]'.
220 [::1] ESMTP amavisd-new service ready
quit
221 2.0.0 [::1] amavisd-new closing transmission channel
Connection closed by foreign host.
[root@is36 ~]#
This was obviously the reason for messages like:

Code: Select all

Jul 31 21:59:55 is36 postfix/error[5420]: 6A15E30502EB9: to=<mack@th-mack.de>, relay=none, delay=3325, delays=3325/0/0/0, dsn=4.4.2, status=deferred (delivery temporarily suspended: lost connection with 127.0.0.1[127.0.0.1] while receiving the initial server greeting)
So, I set content_filter of postfix to smtp-amavis:[::1]:10024, which resolved this problem.
I wasn't able to get amavisd reacting properly to 127.0.0.1:10024 / 10026 though - don't know the reason.

The mail sending problem remains for now, seems to be similar, but I don't find the configuration for it.

Code: Select all

Aug  1 00:03:40 is36 postfix/smtp[27374]: deliver_request_get: file active/CE89630518B82
Aug  1 00:03:40 is36 postfix/smtp[27374]: deliver_message: from mack@ifis.cs.tu-bs.de
--> Aug  1 00:03:40 is36 postfix/smtp[27374]: smtp_parse_destination: [127.0.0.1]:10026 smtp
--> Aug  1 00:03:40 is36 postfix/smtp[27374]: connecting to 127.0.0.1 port 10026
Aug  1 00:03:40 is36 postfix/smtp[27374]: smtp_addr_one: host 127.0.0.1
Aug  1 00:03:40 is36 postfix/smtp[27374]: begin 127.0.0.1 address list
Aug  1 00:03:40 is36 postfix/smtp[27374]: pref    0 host 127.0.0.1/127.0.0.1
Aug  1 00:03:40 is36 postfix/smtp[27374]: end 127.0.0.1 address list
Aug  1 00:03:40 is36 postfix/smtp[27374]: global TLS level: may
Aug  1 00:03:40 is36 postfix/smtp[27374]: ctable_locate: install entry key [i]....[/i]=:127.0.0.1:10026:
Aug  1 00:03:40 is36 postfix/smtp[27374]: smtp_connect_addr: trying: 127.0.0.1[127.0.0.1] port 10026...
Aug  1 00:03:40 is36 postfix/smtp[27374]: vstream_tweak_tcp: TCP_MAXSEG 21845
Aug  1 00:03:40 is36 postfix/smtp[27374]: fd=15: stream buffer size old=0 new=43690
Aug  1 00:03:40 is36 postfix/smtp[27374]: smtp_stream_setup: maxtime=300 enable_deadline=0
Aug  1 00:03:40 is36 postfix/smtp[27374]: smtp_get: EOF
Aug  1 00:03:40 is36 postfix/smtp[27374]: connect to subsystem private/defer
Aug  1 00:03:40 is36 postfix/smtp[27374]: send attr nrequest = 0
Aug  1 00:03:40 is36 postfix/smtp[27374]: send attr flags = 0
Aug  1 00:03:40 is36 postfix/smtp[27374]: send attr queue_id = CE89630518B82
Aug  1 00:03:40 is36 postfix/smtp[27374]: send attr original_recipient = mack@yyy.zzz
Aug  1 00:03:40 is36 postfix/smtp[27374]: send attr recipient = mack@yyy.zzz
Aug  1 00:03:40 is36 postfix/smtp[27374]: send attr offset = 696
Aug  1 00:03:40 is36 postfix/smtp[27374]: send attr dsn_orig_rcpt = rfc822;mack@yyy.zzz
Aug  1 00:03:40 is36 postfix/smtp[27374]: send attr notify_flags = 0
Aug  1 00:03:40 is36 postfix/smtp[27374]: send attr status = 4.4.2
Aug  1 00:03:40 is36 postfix/smtp[27374]: send attr diag_type =
Aug  1 00:03:40 is36 postfix/smtp[27374]: send attr diag_text =
Aug  1 00:03:40 is36 postfix/smtp[27374]: send attr mta_type =
Aug  1 00:03:40 is36 postfix/smtp[27374]: send attr mta_mname =
Aug  1 00:03:40 is36 postfix/smtp[27374]: send attr action = delayed
--> Aug  1 00:03:40 is36 postfix/smtp[27374]: send attr reason = lost connection with 127.0.0.1[127.0.0.1] while receiving the initial server greeting
Aug  1 00:03:40 is36 postfix/smtp[27374]: private/defer socket: wanted attribute: status
Aug  1 00:03:40 is36 postfix/smtp[27374]: input attribute name: status
Aug  1 00:03:40 is36 postfix/smtp[27374]: input attribute value: 0
Again, from 127.0.0.1:10026 I don't get a reasonable reply. For whatever reason.

Thomas Mack
mack3457
Posts: 12
Joined: Fri Jun 05, 2015 8:37 am

Re: host 127.0.0.1[127.0.0.1] refused to talk to me

Post by mack3457 »

This problem is very obscure.

Replaying even an earlier backup didn't resolve it, so I had to set up a new system and migrate all users and mailboxes etc. to the new system, which runs fine now.

Something must have changed, which was only activated by a reboot. Don't know, how long this problem existed, as the server had been running at least half a year or one year without reboot.

Why so ever e.g. amavisd was returning immediately after a connect to 127.0.0.1:10024 but not after ::1 port 10024, this now works as well.

Thomas Mack
Post Reply