Amavisd-new refuses to start (Can't connect to TCP port 10024 on 127.0.0.1 [Permission denied])

[Reinhold Kainhofer]

Hello,
Yesterday I upgrded my Ubuntu server to Ubuntu 16.10 and together with it the amavis installation (amavisd-new-2.10.1 (20141025) as packaged by the latest Ubuntu release, libnet-server-perl is version 2.008-3). Now, amavisd-new no longer starts up during boot, and it also can't be started manually. The log files and the output of "amavisd-new debug" shows this:

    root@server /etc/sysctl.d # amavisd-new debug
    Nov 19 23:12:33.454 server.kainhofer.com /usr/sbin/amavisd-new[10518]: logging initialized, log level 0, syslog: amavis.mail
    Nov 19 23:12:33.454 server.kainhofer.com /usr/sbin/amavisd-new[10518]: starting. /usr/sbin/amavisd-new at server.kainhofer.com amavisd-new-2.10.1 (20141025), Unicode aware, LANG="en_US.UTF-8"
    Nov 19 23:12:33.454 server.kainhofer.com /usr/sbin/amavisd-new[10518]: perl=5.022002, user=, EUID: 110 (110); group=, EGID: 118 118 (118 118)
    Nov 19 23:12:33.480 server.kainhofer.com /usr/sbin/amavisd-new[10518]: INFO: no optional modules: unicore::lib::Nt::De.pl Unix::Getrusage
    Nov 19 23:12:33.480 server.kainhofer.com /usr/sbin/amavisd-new[10518]: SpamControl: attempting to load scanner SpamAssassin, module Amavis::SpamControl::SpamAssassin
    Nov 19 23:12:33.480 server.kainhofer.com /usr/sbin/amavisd-new[10518]: SpamControl: scanner SpamAssassin, module Amavis::SpamControl::SpamAssassin
    Nov 19 23:12:33.589 server.kainhofer.com /usr/sbin/amavisd-new[10518]: INFO: SA version: 3.4.1, 3.004001, no optional modules: Razor2::Client::Agent Image::Info Image::Info::GIF Image::Info::JPEG Image::Info::PNG Image::Info::BMP Image::Info::TIFF
    Nov 19 23:12:33.590 server.kainhofer.com /usr/sbin/amavisd-new[10518]: SpamControl: init_pre_chroot on SpamAssassin done
    Nov 19 23:12:33.590 server.kainhofer.com /usr/sbin/amavisd-new[10518]: socket module IO::Socket::IP, protocol families available: INET, INET6
    Nov 19 23:12:33.590 server.kainhofer.com /usr/sbin/amavisd-new[10518]: bind to /var/lib/amavis/amavisd.sock|unix, 127.0.0.1:10024/tcp, [::1]:10024/tcp, 127.0.0.1:10026/tcp, [::1]:10026/tcp
    Nov 19 23:12:33.590 server.kainhofer.com /usr/sbin/amavisd-new[10518]: Net::Server: 2016/11/19-23:12:33 Amavis (type Net::Server::PreForkSimple) starting! pid(10518)
    Use of uninitialized value in subroutine entry at /usr/share/perl5/Net/Server/Proto.pm line 125.
    Use of uninitialized value in subroutine entry at /usr/share/perl5/Net/Server/Proto.pm line 125.
    Nov 19 23:12:33.592 server.kainhofer.com /usr/sbin/amavisd-new[10518]: Net::Server: Binding to UNIX socket file "/var/lib/amavis/amavisd.sock"
    Nov 19 23:12:33.592 server.kainhofer.com /usr/sbin/amavisd-new[10518]: Net::Server: Binding to TCP port 10024 on host 127.0.0.1 with IPv4
    Nov 19 23:12:33.593 server.kainhofer.com /usr/sbin/amavisd-new[10518]: (!)Net::Server: 2016/11/19-23:12:33 Can't connect to TCP port 10024 on 127.0.0.1 [Permission denied]\n at line 68 in file /usr/share/perl5/Net/Server/Proto/TCP.pm
    Nov 19 23:12:33.593 server.kainhofer.com /usr/sbin/amavisd-new[10518]: Net::Server: 2016/11/19-23:12:33 Server closing!

So it claims it cannot bind to its listening port 10024 (in the past it was perfectly able to do this). I made sure nothing else was listening on port 10024:

    root@server /etc/sysctl.d # lsof -i :10024
    root@server /etc/sysctl.d # netstat -a |grep 1002
    tcp 0 0 localhost:10023 0.0.0.0:* LISTEN
    tcp 0 0 localhost:10025 0.0.0.0:* LISTEN
    tcp 0 0 localhost:10027 0.0.0.0:* LISTEN

I do not have SELinux or apparmor running, and the ufw firewall was also temporarily disabled for these tests.

It is not a general problem of the port being denied/blocked, because a simple other perl app binding to port 10024 (http://xmodulo.com/how-to-write-simple-tcp-server-and-client-in-perl.html with the port changed from 7777 to 10024) is perfectly able to bind to port 10024. So my guess is that there is again some incompatibility with the latest Net::Server module

Best regards,

Reinhold

PS: If I disable ipv6 completely (in sysctl), then suddently amavisd-new is able to connect to port 10024 on the IP4 address 127.0.0.1 (localhost):

    root@server /etc/sysctl.d # amavisd-new debug
    Nov 19 23:23:25.848 server.kainhofer.com /usr/sbin/amavisd-new[11877]: logging initialized, log level 0, syslog: amavis.mail
    Nov 19 23:23:25.848 server.kainhofer.com /usr/sbin/amavisd-new[11877]: starting. /usr/sbin/amavisd-new at server.kainhofer.com amavisd-new-2.10.1 (20141025), Unicode aware, LANG="en_US.UTF-8"
    Nov 19 23:23:25.848 server.kainhofer.com /usr/sbin/amavisd-new[11877]: perl=5.022002, user=, EUID: 110 (110); group=, EGID: 118 118 (118 118)
    Nov 19 23:23:25.875 server.kainhofer.com /usr/sbin/amavisd-new[11877]: INFO: no optional modules: unicore::lib::Nt::De.pl Unix::Getrusage
    Nov 19 23:23:25.876 server.kainhofer.com /usr/sbin/amavisd-new[11877]: SpamControl: attempting to load scanner SpamAssassin, module Amavis::SpamControl::SpamAssassin
    Nov 19 23:23:25.876 server.kainhofer.com /usr/sbin/amavisd-new[11877]: SpamControl: scanner SpamAssassin, module Amavis::SpamControl::SpamAssassin
    Nov 19 23:23:25.987 server.kainhofer.com /usr/sbin/amavisd-new[11877]: INFO: SA version: 3.4.1, 3.004001, no optional modules: Razor2::Client::Agent Image::Info Image::Info::GIF Image::Info::JPEG Image::Info::PNG Image::Info::BMP Image::Info::TIFF
    Nov 19 23:23:25.987 server.kainhofer.com /usr/sbin/amavisd-new[11877]: SpamControl: init_pre_chroot on SpamAssassin done
    Nov 19 23:23:25.987 server.kainhofer.com /usr/sbin/amavisd-new[11877]: socket module IO::Socket::IP, protocol families available: INET
    Nov 19 23:23:25.987 server.kainhofer.com /usr/sbin/amavisd-new[11877]: bind to /var/lib/amavis/amavisd.sock|unix, 127.0.0.1:10024/tcp, 127.0.0.1:10026/tcp
    Nov 19 23:23:25.987 server.kainhofer.com /usr/sbin/amavisd-new[11877]: Net::Server: 2016/11/19-23:23:25 Amavis (type Net::Server::PreForkSimple) starting! pid(11877)
    Nov 19 23:23:25.989 server.kainhofer.com /usr/sbin/amavisd-new[11877]: Net::Server: Binding to UNIX socket file "/var/lib/amavis/amavisd.sock"
    Nov 19 23:23:25.989 server.kainhofer.com /usr/sbin/amavisd-new[11877]: Net::Server: Binding to TCP port 10024 on host 127.0.0.1 with IPv4
    Nov 19 23:23:25.990 server.kainhofer.com /usr/sbin/amavisd-new[11877]: Net::Server: Binding to TCP port 10026 on host 127.0.0.1 with IPv4
    Nov 19 23:23:25.990 server.kainhofer.com /usr/sbin/amavisd-new[11877]: Net::Server: Group Not Defined. Defaulting to EGID '118 118'
    Nov 19 23:23:25.990 server.kainhofer.com /usr/sbin/amavisd-new[11877]: Net::Server: User Not Defined. Defaulting to EUID '110'
    Nov 19 23:23:25.990 server.kainhofer.com /usr/sbin/amavisd-new[11877]: Net::Server: Setting up serialization via flock
    Nov 19 23:23:25.990 server.kainhofer.com /usr/sbin/amavisd-new[11877]: after_chroot_init: EUID: 110 (110); EGID: 118 118 (118 118)
    Nov 19 23:23:25.990 server.kainhofer.com /usr/sbin/amavisd-new[11877]: config files read: /usr/share/amavis/conf.d/10-debian_scripts, /usr/share/amavis/conf.d/20-package, /etc/amavis/conf.d/01-debian, /etc/amavis/conf.d/05-domain_id, /etc/amavis/conf.d/05-node_id, /etc/amavis/conf.d/15-av_scanners, /etc/amavis/conf.d/15-content_filter_mode, /etc/amavis/conf.d/20-debian_defaults, /etc/amavis/conf.d/21-ubuntu_defaults, /etc/amavis/conf.d/25-amavis_helpers, /etc/amavis/conf.d/30-template_localization, /etc/amavis/conf.d/40-policy_banks, /etc/amavis/conf.d/50-user

However, even then there are several errors from amavisd-new (and the mail is still stuck in postfix):

    [...]

    Nov 19 23:37:34.857 server.kainhofer.com /usr/sbin/amavisd-new[11884]: (11884-07) trace: ESMTP://[127.0.0.1]:58410 < ESMTPS://[209.85.210.179]:36286 < SMTP://x < ESMTPSA://91.115.19.82
    Nov 19 23:37:34.857 server.kainhofer.com /usr/sbin/amavisd-new[11884]: (11884-07) dkim: public key s=20120113 d=gmail.com, error: Unrecognised protocol udp at /usr/share/perl5/Net/DNS/Resolver/Base.pm line 936. at /usr/share/perl5/Mail/DKIM/DNS.pm line 156, <GEN32> line 8995.
    Nov 19 23:37:34.857 server.kainhofer.com /usr/sbin/amavisd-new[11884]: (11884-07) dkim: FAILED Author+Sender+MailFrom signature by d=gmail.com, From: <email address hidden>, a=rsa-sha256, c=relaxed/relaxed, s=20120113, <email address hidden>, invalid (public key: Unrecognised protocol udp at /usr/share/perl5/Net/DNS/Resolver/Base.pm line 936. at /usr/share/perl5/Mail/DKIM/DNS.pm line 156, <GEN32> line 8995.)
    Nov 19 23:37:34.858 server.kainhofer.com /usr/sbin/amavisd-new[11884]: (11884-07) Original mail size: 2716; quota set to: 1358000 bytes (fmin=5, fmax=500, qmin=102400, qmax=314572800)
    [...]

    Nov 19 23:37:34.883 server.kainhofer.com /usr/sbin/amavisd-new[11884]: (11884-07) CALLING SA check (0)
    rules: failed to run NO_DNS_FOR_FROM RBL test, skipping:
            (Unrecognised protocol udp at /usr/share/perl5/Mail/SpamAssassin/DnsResolver.pm line 420.)
    spf: lookup failed: Unrecognised protocol udp at /usr/share/perl5/Mail/SpamAssassin/DnsResolver.pm line 420.
    [...]
    Nov 19 23:37:34.933 server.kainhofer.com /usr/sbin/amavisd-new[11884]: (11884-07) get_deadline fwd_init - deadline in 479.9 s, set to 480.000 s
    Nov 19 23:37:34.933 server.kainhofer.com /usr/sbin/amavisd-new[11884]: (11884-07) smtp session: setting up a new session
    Nov 19 23:37:34.933 server.kainhofer.com /usr/sbin/amavisd-new[11884]: (11884-07) establish_or_refresh, state: down
    Nov 19 23:37:34.933 server.kainhofer.com /usr/sbin/amavisd-new[11884]: (11884-07) new socket using IO::Socket::IP to [127.0.0.1]:10025, timeout 35
    Nov 19 23:37:34.933 server.kainhofer.com /usr/sbin/amavisd-new[11884]: (11884-07) (!)connect to 127.0.0.1:* failed, attempt #1: Unrecognised protocol tcp at /usr/sbin/amavisd-new line 8118.
    Nov 19 23:37:34.934 server.kainhofer.com /usr/sbin/amavisd-new[11884]: (11884-07) mail_via_smtp: session failed: All attempts (1) failed connecting to smtp:127.0.0.1:*
    Nov 19 23:37:34.934 server.kainhofer.com /usr/sbin/amavisd-new[11884]: (11884-07) get_deadline fwd-end-chkpnt - deadline in 479.9 s, set to 288.000 s
    Nov 19 23:37:34.934 server.kainhofer.com /usr/sbin/amavisd-new[11884]: (11884-07) prolong_timer fwd-end-chkpnt: timer 288, was 0, deadline in 479.9 s
    Nov 19 23:37:34.934 server.kainhofer.com /usr/sbin/amavisd-new[11884]: (11884-07) (!)CtDipLcUY4lD FWD from <email address hidden> -> <email address hidden>, 451 4.5.0 From MTA() during fwd-connect (All attempts (1) failed connecting to smtp:127.0.0.1:*): id=11884-07
    Nov 19 23:37:34.934 server.kainhofer.com /usr/sbin/amavisd-new[11884]: (11884-07) get_deadline forwarding - deadline in 479.9 s, set to 288.000 s
    Nov 19 23:37:34.934 server.kainhofer.com /usr/sbin/amavisd-new[11884]: (11884-07) prolong_timer forwarding: timer 288, was 288, deadline in 479.9 s
    Nov 19 23:37:34.934 server.kainhofer.com /usr/sbin/amavisd-new[11884]: (11884-07) DSN: sender NOT credible, SA: 1.312, <email address hidden>
    Nov 19 23:37:34.934 server.kainhofer.com /usr/sbin/amavisd-new[11884]: (11884-07) lookup: (scalar) matches, result="100"
    Nov 19 23:37:34.935 server.kainhofer.com /usr/sbin/amavisd-new[11884]: (11884-07) lookup [spam_dsn_cutoff_level_bysender] => true, "<email address hidden>" matches, result="100", matching_key="(constant:100)"
    Nov 19 23:37:34.935 server.kainhofer.com /usr/sbin/amavisd-new[11884]: (11884-07) dsn: . 451 MtaTempFailed <email address hidden> -> <email address hidden>: 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=11884-07 - Temporary MTA failure on relaying, From MTA() during fwd-connect (All attempts (1) failed connecting to smtp:127.0.0.1:*): id=11884-07"
    Nov 19 23:37:34.935 server.kainhofer.com /usr/sbin/amavisd-new[11884]: (11884-07) DSN: TMPFAIL . 451 MtaTempFailed, not to be reported: <email address hidden> -> <email address hidden>
---
ApportVersion: 2.20.3-0ubuntu8
Architecture: amd64
DistroRelease: Ubuntu 16.10
Package: amavisd-new 1:2.10.1-4ubuntu1
PackageArchitecture: all
ProcVersionSignature: Ubuntu 4.8.0-27.29-generic 4.8.1
Tags: yakkety
Uname: Linux 4.8.0-27-generic x86_64
UpgradeStatus: Upgraded to yakkety on 2016-11-19 (0 days ago)
UserGroups:

_MarkForUpload: True
mtime.conffile..etc.amavis.conf.d.50-user: 2016-11-19T23:28:26.739773

[Reinhold Kainhofer (reinhold)]

apport information

[Reinhold Kainhofer (reinhold)]

apport information

[Reinhold Kainhofer (reinhold)]

apport information

[Reinhold Kainhofer (reinhold)]

apport information

[Reinhold Kainhofer (reinhold)]

BTW: Manually installing the trusty (14.04) package of amavisd-new (version 1:2.7.1-2ubuntu3) on Yakkety seems to work. Amavis properly starts and mails are finally delivered.

[Reinhold Kainhofer (reinhold)]

After upgrading that server to Ubuntu 18.04, I still get the same error trying to start amavis (amavisd-new 1:2.11.0-1ubuntu1).

However, at the Redhat bug tracker, there is a similar issue reported and the suggested fix there also works for me:
In /etc/amavis/conf.d/50-user simply add
    $inet_socket_bind = '127.0.0.1';

After that, amavis is able to properly bind to ports 10024 and 10026 and start up without issue.

[Reinhold Kainhofer (reinhold)]

Correction: Amavis from Ubuntu 18.04 with inet_socket_bind set is properly starting up, but postfix is not able to connect.

My original workaround of downgrading to version 2.7.1 from the trusty repository still works on Ubuntu 18.04.

[Athos Ribeiro (athos-ribeiro)]

I could not reproduce this issue in a clean bionic installation. OTOH, I could not reproduce it in a clean yakkety installation either.

Is anyone still affected by this issue?

Reinhold, if you are still affected here, would you be able to provide a reproducer for the issue that shows it still affects bionic or any later version of Ubuntu?

Until then, I am decreasing the importance of this bug (since no one else seems to be affected) and marking it as incomplete. Once we get confirmation this still affects anyone in bionic or later, feel free to reset the status of this issue.

[Launchpad Janitor (janitor)]

[Expired for amavisd-new (Ubuntu) because there has been no activity for 60 days.]