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

Reinhold Kainhofer reinhold.kainhofer at gmail.com
Sat Nov 19 23:46:03 CET 2016


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 at 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 at server /etc/sysctl.d # lsof -i :10024
    root at 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 completel (in sysctl), then suddently amavisd-new 
is able to connect to  port 10024 on the IP4 address 127.0.0.1 (localhost):

    root at 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:
    <reinhold.kainhofer at gmail.com>, a=rsa-sha256, c=relaxed/relaxed,
    s=20120113, i=@gmail.com, 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
    <reinhold.kainhofer at gmail.com> -> <reinhold at kainhofer.com>,  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, <reinhold.kainhofer at gmail.com>
    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,
    "reinhold.kainhofer at gmail.com" 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
    <reinhold.kainhofer at gmail.com> -> <reinhold at kainhofer.com>:
    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: <reinhold.kainhofer at gmail.com> ->
    <reinhold at kainhofer.com>


-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.amavis.org/pipermail/amavis-users/attachments/20161119/db8756db/attachment.html>


More information about the amavis-users mailing list