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

Discussion in 'General' started by edge, May 3, 2020.

  1. edge

    edge Active Member Moderator

    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.
     
  2. Steini86

    Steini86 Active Member

    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.
     
    edge likes this.
  3. edge

    edge Active Member Moderator

    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....
     
  4. till

    till Super Moderator Staff Member ISPConfig Developer

    Please check the fail2ban log if you find any bans for the hostname 'localhost' inside or for the localhost IP or your own IP.
     
    edge likes this.
  5. edge

    edge Active Member Moderator

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

    nhybgtvfr Well-Known Member HowtoForge Supporter

    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….
     
    Steini86 and edge like this.
  7. edge

    edge Active Member Moderator

    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.
     
  8. edge

    edge Active Member Moderator

    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.
     
  9. Croydon

    Croydon ISPConfig Developer ISPConfig Developer

    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?
     
    edge likes this.
  10. Jesse Norell

    Jesse Norell ISPConfig Developer Staff Member ISPConfig Developer

    Possibly there's some clue in there, but I don't see it offhand; my guess is all that (timeouts/failed connections) are symptoms of the actual problem. Look further up in the logs before that starts and see if you find anything.
     
    edge and Th0m like this.
  11. Steini86

    Steini86 Active Member

    Code:
    systemctl status amavis
    journalctl -xbo short -u amavis
    (or amavisd, depending on your system)
     
    edge likes this.
  12. edge

    edge Active Member Moderator

    @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.
     
  13. Jesse Norell

    Jesse Norell ISPConfig Developer Staff Member ISPConfig Developer

    You could setup up something to monitor it, eg. monit can connect to a port, talk the smtp protocol, and take some action when there's a failure. Maybe run once per minute and just send you an email when there's a problem, so you have a good timeframe to check logs.
     
    edge likes this.
  14. edge

    edge Active Member Moderator

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

    edge Active Member Moderator

    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.
     
  16. Jesse Norell

    Jesse Norell ISPConfig Developer Staff Member ISPConfig Developer

    You can deliver the email to port 10026, or use msmtp to send via an alternate smtp server.
     
    edge likes this.
  17. edge

    edge Active Member Moderator

    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.
     
  18. edge

    edge Active Member Moderator

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

    Jesse Norell ISPConfig Developer Staff Member ISPConfig Developer

    Please just use email for that purpose (easy to find my addr via searching or I think it's in the jk_updater_ipsc script among others).
     
    edge likes this.
  20. edge

    edge Active Member Moderator

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

Share This Page