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 completel (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 protected]>, a=rsa-sha256, c=relaxed/relaxed,
s=20120113, [email protected], 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 protected]> -> <[email protected]>, 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 protected]>
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 protected]" 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 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=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 protected]> ->
<[email protected]>
