amavisd giving me a hard time! Sometimes connect to 127.0.0.1[127.0.0.1]:10024: Connection refused)

I've been having this problem for some time now. It happens after several days of uptime.
System: Debian Buster (10) (server is mainly used for email and has 4GB of RAM)

Problem: After some days all of a sudden (connect to 127.0.0.1[127.0.0.1]:10024: Connection refused)
Note that port 10024 sometimes shows 10026

Today at 08:47:34 it happend again. (email addresses / domains and IP's are partly masked)

Code:

root@server:/var/log# cat mail.info | grep 08:47:34
May  3 08:47:34 server postfix/smtpd[4176]: NOQUEUE: filter: RCPT from d12.ABC.com[12.34.56.78]: <[email protected]>: Sender address triggers FILTER amavis:[127.0.0.1]:10026; from=<[email protected]> to=<[email protected]> proto=ESMTP helo=<d12.ABC.com>
May  3 08:47:34 server postfix/smtpd[4176]: NOQUEUE: filter: RCPT from d12.ABC.com[12.34.56.78]: <[email protected]>: Sender address triggers FILTER amavis:[127.0.0.1]:10024; from=<[email protected]> to=<[email protected]> proto=ESMTP helo=<d12.ABC.com>
May  3 08:47:34 server postfix/smtpd[4176]: 24920281EE3: client=d12.ABC.com[12.34.56.78]
May  3 08:47:34 server postfix/cleanup[4187]: 24920281EE3: message-id=<[email protected]>
May  3 08:47:34 server postfix/qmgr[1117]: 24920281EE3: from=<[email protected]>, size=131829, nrcpt=1 (queue active)
May  3 08:47:34 server postfix/smtp[4188]: connect to 127.0.0.1[127.0.0.1]:10024: Connection refused
May  3 08:47:34 server postfix/smtp[4188]: 24920281EE3: to=<[email protected]>, relay=none, delay=0.63, delays=0.61/0.02/0/0, dsn=4.4.1, status=deferred (connect to 127.0.0.1[127.0.0.1]:10024: Connection refused)
May  3 08:47:34 server postfix/smtpd[4176]: disconnect from d12.ABC.com[12.34.56.78] ehlo=2 starttls=1 mail=1 rcpt=1 data=1 quit=1 commands=7

mailq will show that the above message in being held.

netstat shows me that amavisd is running on 10026 and 10024

Code:

root@server:/home/noel# netstat -tap | grep 10026
tcp        0      0 localhost.localdo:10026 0.0.0.0:*               LISTEN      4579/amavisd-new (m
tcp6       0      0 localhost:10026         [::]:*                  LISTEN      4579/amavisd-new (m
root@server:/home/noel# netstat -tap | grep 10024
tcp        0      0 localhost.localdo:10024 0.0.0.0:*               LISTEN      4579/amavisd-new (m
tcp6       0      0 localhost:10024         [::]:*                  LISTEN      4579/amavisd-new (m
tcp6       0      0 localhost:10024         localhost:47018         TIME_WAIT   - 

Lets test the connection on 127.0.0.1 to 10026 and 10024

Code:

root@server:/home/noel# telnet 127.0.0.1 10026
Trying 127.0.0.1...
telnet: Unable to connect to remote host: Connection refused
root@server:/home/noel# telnet 127.0.0.1 10024
Trying 127.0.0.1...
telnet: Unable to connect to remote host: Connection refused

Now lets try the same but with localhost

Code:

root@server:~# telnet localhost 10026
Trying ::1...
Connected to localhost.localdomain.
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@server:~# telnet localhost 10024
Trying ::1...
Connected to localhost.localdomain.
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.

Restarting / loading amavisd does not solve the problem. I sometimes need to restart the server several times to get it to work.

When all is working, telnet to 127.0.0.1 on port 10026 and 10024 are working fine!

Code:

root@server:~# telnet 127.0.0.1 10026
Trying 127.0.0.1...
Connected to 127.0.0.1.
Escape character is '^]'.
220 [127.0.0.1] ESMTP amavisd-new service ready
quit
221 2.0.0 [127.0.0.1] amavisd-new closing transmission channel
Connection closed by foreign host.
root@server:~# telnet 127.0.0.1 10024
Trying 127.0.0.1...
Connected to 127.0.0.1.
Escape character is '^]'.
220 [127.0.0.1] ESMTP amavisd-new service ready
quit
221 2.0.0 [127.0.0.1] amavisd-new closing transmission channel
Connection closed by foreign host.

syslog does unfortunately not give me any more info :-(

Anyone here who might have a clue of what is going on? I'm lost.

 

Connection with localhost is done via IPv6 in your example. So it seems that IPv4 stops working for you.
From your netstat command, amavis listens on localhost for ipv6 and localhost.localdo for ipv4. Do you have localhost.localdo configured in /etc/hosts file? (for IPv4 and IPv6)? If you don't find the error there, post hosts file.

Also: https://www.pixelstech.net/article/1538275121-Difference-between-localhost-and-127-0-0-1

So it could also be a firewall issue. Maybe you have fail2ban running or something else and it blocks your own PC.

 

Hi Steini86.
Thank you for your input.

No localhost.localdo in hosts file.
The hosts file looks like so (note that I changed the IP and domain)

Code:

127.0.0.1       localhost.localdomain   localhost
12.34.567.890   server.changed.com        server
# The following lines are desirable for IPv6 capable hosts
::1     localhost ip6-localhost ip6-loopback
ff02::1 ip6-allnodes
ff02::2 ip6-allrouters

I have no clue where it's getting localhost.localdo from, but it does show it in netstat as local address :-/
I've now added localhost.localdo to the hosts file, and now I can ping this too.

I do have fail2ban running, but did disable it when the problem was there, and did not make any difference.
Same for the firewall.

The strange thing is that this problem happens about every 5 days of uptime.

I'm so lost here....

 

No '127.0.0.1' and / or 'localhost' in the fail2ban log(s). :-(

 

I don't believe it is using localhost.localdo

I believe that what you're seeing here:
tcp 0 0 localhost.localdo:10026 0.0.0.0:*
is it truncating the display of
tcp 0 0 localhost.localdomain:100026 0.0.0.0.*
so that it can fit the port number in the 23 character space it has available for that field.

just out of interest, if you can find a specific time from where it changes from working to not working, check in syslog for that time and a bit earlier for any memory problems. I've seen similar amavis/clamav warnings on a small vps that was only for email, so it didn't have a lot of memory, and I did see oom messages getting logged, not seen any amavis/clamav since I doubled the ram on that vps….

 

Thank you for the info. The truncating sounds logical.
I'm going to have another look at the syslog files, and see if I see anything out of the ordinary.
The mail serer does have 4GB. I think that this should be enough... However... I might add some more just to make sure this is not causing the problem.

 

Grrr. again connect to 127.0.0.1[127.0.0.1]:10024: Connection refused.
This is starting to pi** me off.
No clue why this is happening, but this might have to do with it.

Code:

May  5 02:24:11 server amavis[29419]: (29419-09) (!)connect to 127.0.0.1:* failed, attempt #1: Can't connect to socket 127.0.0.1:* using module IO::Socket::IP: Connection timed out
May  5 02:24:11 server amavis[29419]: (29419-09) mail_via_smtp: session failed: All attempts (1) failed connecting to smtp:127.0.0.1:*
May  5 02:24:11 server amavis[29419]: (29419-09) get_deadline fwd-end-chkpnt - deadline in 448.3 s, set to 269.000 s
May  5 02:24:11 server amavis[29419]: (29419-09) prolong_timer fwd-end-chkpnt: timer 269, was 0, deadline in 448.3 s
May  5 02:24:11 server amavis[29419]: (29419-09) (!)CZ57oYHwOguT FWD from <[email protected]> -> <[email protected]>,  451 4.5.0 From MTA() during fwd-connect (All attempts (1) failed connecting to smtp:127.0.0.1:*): id=29419$
May  5 02:24:11 server amavis[29419]: (29419-09) get_deadline forwarding - deadline in 448.3 s, set to 269.000 s
May  5 02:24:11 server amavis[29419]: (29419-09) prolong_timer forwarding: timer 269, was 269, deadline in 448.3 s
May  5 02:24:11 server amavis[29419]: (29419-09) DSN: sender is credible (dkim), SA: 3.199, <[email protected]>
May  5 02:24:11 server amavis[29419]: (29419-09) lookup [spam_crediblefrom_dsn_cutoff_level_bysender] => undef, "[email protected]" does not match
May  5 02:24:11 server amavis[29419]: (29419-09) dsn: . 451 MtaTempFailed <[email protected]> -> <[email protected]>: on_succ=0, on_dly=1, on_fail=1, never=0, warn_sender=, DSN_passed_on=0, destiny=-4, mta_resp: "451 4.5.0 id$
May  5 02:24:11 server amavis[29419]: (29419-09) DSN: TMPFAIL . 451 MtaTempFailed, not to be reported: <[email protected]> -> <[email protected]>
May  5 02:24:11 server amavis[29419]: (29419-09) delivery_status_notification: notif 0 bytes, suppressed: no
May  5 02:24:11 server amavis[29419]: (29419-09) one_response_for_all, per_recip_capable: N, suppressed: N
May  5 02:24:11 server amavis[29419]: (29419-09) notif=N, suppressed=0, ndn_needed=, exit=, 451 4.5.0 id=29419-09 - Temporary MTA failure on relaying, From MTA() during fwd-connect (All attempts (1) failed connecting to smtp:127.0.0.1:*$
May  5 02:24:11 server amavis[29419]: (29419-09) get_deadline delivery-notification - deadline in 448.3 s, set to 269.000 s
May  5 02:24:11 server amavis[29419]: (29419-09) prolong_timer delivery-notification: timer 269, was 269, deadline in 448.3 s
May  5 02:24:11 server amavis[29419]: (29419-09) status counters: InMsgsStatus{TempFailed,TempFailedInbound}
May  5 02:24:11 server amavis[29419]: (29419-09) get_deadline snmp-counters - deadline in 448.3 s, set to 269.000 s
May  5 02:24:11 server amavis[29419]: (29419-09) prolong_timer snmp-counters: timer 269, was 269, deadline in 448.3 s
May  5 02:24:11 server amavis[29419]: (29419-09) orcpt_encode rfc822, [email protected], smtputf8
May  5 02:24:11 server amavis[29419]: (29419-09) oldest_public_ip_addr_from_received: 222.78.222.19
May  5 02:24:11 server amavis[29419]: (29419-09) Blocked MTA-BLOCKED {TempFailedInbound}, [212.54.42.123]:60320 [222.78.222.19] <[email protected]> -> <[email protected]>, Queue-ID: 82B6A281F13, Message-ID: <wmbu82ZnlmeAFWbyV$
May  5 02:24:11 server amavis[29419]: (29419-09) get_deadline main_log_entry - deadline in 448.3 s, set to 269.000 s
May  5 02:24:11 server amavis[29419]: (29419-09) prolong_timer main_log_entry: timer 269, was 269, deadline in 448.3 s
May  5 02:24:11 server amavis[29419]: (29419-09) TIMING-SA total 259 ms - parse: 8 (3.2%), extract_message_metadata: 18 (6.8%), get_uri_detail_list: 1.06 (0.4%), tests_pri_-1000: 22 (8.7%), tests_pri_-950: 0.76 (0.3%), tests_pri_-900: 0$
May  5 02:24:11 server amavis[29419]: (29419-09) updating snmp variables in BDB
May  5 02:24:11 server amavis[29419]: (29419-09) get_deadline check done - deadline in 448.3 s, set to 269.000 s
May  5 02:24:11 server amavis[29419]: (29419-09) prolong_timer check done: timer 269, was 269, deadline in 448.3 s
May  5 02:24:11 server amavis[29419]: (29419-09) sending SMTP response: "451 4.5.0 id=29419-09 - Temporary MTA failure on relaying, From MTA() during fwd-connect (All attempts (1) failed connecting to smtp:127.0.0.1:*): id=29419-09"
May  5 02:24:11 server amavis[29419]: (29419-09) ESMTP> 451 4.5.0 id=29419-09 - Temporary MTA failure on relaying, From MTA() during fwd-connect (All attempts (1) failed connecting to smtp:127.0.0.1:*): id=29419-09
May  5 02:24:11 server amavis[29419]: (29419-09) switch_to_client_time 480 s, smtp response sent
May  5 02:24:11 server amavis[29419]: (29419-09) TempDir::strip: /var/lib/amavis/tmp/amavis-20200505T022340-29419-5RV1_Upb
May  5 02:24:11 server amavis[29419]: (29419-09) rmdir_recursively: /var/lib/amavis/tmp/amavis-20200505T022340-29419-5RV1_Upb/parts, excl=1
May  5 02:24:11 server amavis[29419]: (29419-09) size: 5654, TIMING [total 31798 ms] - SMTP greeting: 2.3 (0%)0, SMTP EHLO: 1.7 (0%)0, SMTP pre-MAIL: 2.0 (0%)0, mkdir tempdir: 2.0 (0%)0, create email.txt: 0.3 (0%)0, SMTP MAIL: 1.8 (0%)0$
May  5 02:24:11 server amavis[29419]: (29419-09) idle_proc, 6: was busy, 31780.7 ms, total idle 572.632 s, busy 31.830 s
May  5 02:24:11 server amavis[29419]: (29419-09) idle_proc, 5: was idle, 0.1 ms, total idle 572.632 s, busy 31.830 s
May  5 02:24:11 server amavis[29419]: (29419-09) ESMTP< QUIT\r\n
May  5 02:24:11 server amavis[29419]: (29419-09) get_deadline switch_to_my_time(rx SMTP QUIT) - deadline in 480.0 s, set to 288.000 s
May  5 02:24:11 server amavis[29419]: (29419-09) prolong_timer switch_to_my_time(rx SMTP QUIT): timer 288, was 480, deadline in 480.0 s
May  5 02:24:11 server amavis[29419]: (29419-09) ESMTP> 221 2.0.0 [127.0.0.1] amavisd-new closing transmission channel
May  5 02:24:11 server amavis[29419]: (29419-09) switch_to_client_time 480 s, smtp response sent
May  5 02:24:11 server amavis[29419]: (29419-09) SMTP session over, timer stopped
May  5 02:24:11 server amavis[29419]: (29419-09) exiting process_request
May  5 02:24:11 server amavis[29419]: (29419-09) idle_proc, bye: was busy, 1.3 ms, total idle 572.632 s, busy 31.831 s
May  5 02:24:11 server amavis[29419]: (29419-09) load: 5 %, total idle 572.632 s, busy 31.831 s

I did not find much info about this till now.

 

Could you check any more logs that might contain amavis data (e. g. the deamon.log)? Maybe there is some error just before the problem begins that you have not seen in logs, yet.

Is it just Amavis failing in these situation or aren't you able to use -h 127.0.0.1 for mysql, too at that times?

 

Code:

systemctl status amavis
journalctl -xbo short -u amavis

(or amavisd, depending on your system)

 

@Croydon It's only amavis.. And the strange thing is that amavis is running and the port is open when this is happening!
@Jesse Norell Believe me.. I've done this many times already. I might look over something so I'm going to do it again.

 

@Steini86 I just did a reboot, but will give the commands when the error happens again.

 

I did already.. Sending email will not work as this is one of the problems when the error happens.
I've set monit up to send me a telegram message.

 

That would be an option, but as I've now set monit up to send a telegram push notification to my phone I will leave it as is.

 

@Jesse Norell I would like to send you a PM, but your have disabled it :-(

 

I've send you an email Jesse. That is if it's the correct email address.