<html>
<head>
<meta http-equiv="content-type" content="text/html; charset=utf-8">
</head>
<body bgcolor="#FFFFFF" text="#000000">
Hello,<br>
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:<br>
<blockquote><tt><br>
root@server /etc/sysctl.d # amavisd-new debug</tt><tt><br>
</tt><tt>Nov 19 23:12:33.454 server.kainhofer.com
/usr/sbin/amavisd-new[10518]: logging initialized, log level 0,
syslog: amavis.mail</tt><tt><br>
</tt><tt>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"</tt><tt><br>
</tt><tt>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)</tt><tt><br>
</tt><tt>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</tt><tt><br>
</tt><tt>Nov 19 23:12:33.480 server.kainhofer.com
/usr/sbin/amavisd-new[10518]: SpamControl: attempting to load
scanner SpamAssassin, module Amavis::SpamControl::SpamAssassin</tt><tt><br>
</tt><tt>Nov 19 23:12:33.480 server.kainhofer.com
/usr/sbin/amavisd-new[10518]: SpamControl: scanner SpamAssassin,
module Amavis::SpamControl::SpamAssassin</tt><tt><br>
</tt><tt>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::<a class="moz-txt-link-freetext" href="Info::GIF">Info::GIF</a> Image::<a class="moz-txt-link-freetext" href="Info::JPEG">Info::JPEG</a> Image::<a class="moz-txt-link-freetext" href="Info::PNG">Info::PNG</a>
Image::<a class="moz-txt-link-freetext" href="Info::BMP">Info::BMP</a> Image::<a class="moz-txt-link-freetext" href="Info::TIFF">Info::TIFF</a></tt><tt><br>
</tt><tt>Nov 19 23:12:33.590 server.kainhofer.com
/usr/sbin/amavisd-new[10518]: SpamControl: init_pre_chroot on
SpamAssassin done</tt><tt><br>
</tt><tt>Nov 19 23:12:33.590 server.kainhofer.com
/usr/sbin/amavisd-new[10518]: socket module IO::Socket::IP,
protocol families available: INET, INET6</tt><tt><br>
</tt><tt>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</tt><tt><br>
</tt><tt>Nov 19 23:12:33.590 server.kainhofer.com
/usr/sbin/amavisd-new[10518]: <a class="moz-txt-link-freetext" href="Net::Server">Net::Server</a>: 2016/11/19-23:12:33
Amavis (type <a class="moz-txt-link-freetext" href="Net::Server::PreForkSimple">Net::Server::PreForkSimple</a>) starting! pid(10518)</tt><tt><br>
</tt><tt>Use of uninitialized value in subroutine entry at
/usr/share/perl5/Net/Server/Proto.pm line 125.</tt><tt><br>
</tt><tt>Use of uninitialized value in subroutine entry at
/usr/share/perl5/Net/Server/Proto.pm line 125.</tt><tt><br>
</tt><tt>Nov 19 23:12:33.592 server.kainhofer.com
/usr/sbin/amavisd-new[10518]: <a class="moz-txt-link-freetext" href="Net::Server">Net::Server</a>: Binding to UNIX
socket file "/var/lib/amavis/amavisd.sock"</tt><tt><br>
</tt><tt>Nov 19 23:12:33.592 server.kainhofer.com
/usr/sbin/amavisd-new[10518]: <a class="moz-txt-link-freetext" href="Net::Server">Net::Server</a>: Binding to TCP port
10024 on host 127.0.0.1 with IPv4</tt><tt><br>
</tt><tt>Nov 19 23:12:33.593 server.kainhofer.com
/usr/sbin/amavisd-new[10518]: (!)<a class="moz-txt-link-freetext" href="Net::Server">Net::Server</a>:
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</tt><tt><br>
</tt><tt>Nov 19 23:12:33.593 server.kainhofer.com
/usr/sbin/amavisd-new[10518]: <a class="moz-txt-link-freetext" href="Net::Server">Net::Server</a>: 2016/11/19-23:12:33
Server closing!</tt></blockquote>
<p><br>
</p>
<p>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:</p>
<blockquote>
<p><tt>root@server /etc/sysctl.d # lsof -i :10024</tt><tt><br>
</tt><tt>root@server /etc/sysctl.d # netstat -a |grep 1002</tt><tt><br>
</tt><tt>tcp 0 0 localhost:10023
0.0.0.0:* LISTEN </tt><tt><br>
</tt><tt>tcp 0 0 localhost:10025
0.0.0.0:* LISTEN </tt><tt><br>
</tt><tt>tcp 0 0 localhost:10027
0.0.0.0:* LISTEN </tt><tt><br>
</tt></p>
</blockquote>
<p><br>
</p>
<p>I do not have SELinux or apparmor running, and the ufw firewall
was also temporarily disabled for these tests.<br>
</p>
<p>It is not a general problem of the port being denied/blocked,
because a simple other perl app binding to port 10024
(<a class="moz-txt-link-freetext" href="http://xmodulo.com/how-to-write-simple-tcp-server-and-client-in-perl.html">http://xmodulo.com/how-to-write-simple-tcp-server-and-client-in-perl.html</a>
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 <a class="moz-txt-link-freetext" href="Net::Server">Net::Server</a> module<br>
</p>
<p>Best regards,</p>
<p>Reinhold</p>
<p><br>
</p>
<p>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):</p>
<blockquote><tt>root@server /etc/sysctl.d # amavisd-new debug</tt><br>
<tt>Nov 19 23:23:25.848 server.kainhofer.com
/usr/sbin/amavisd-new[11877]: logging initialized, log level 0,
syslog: amavis.mail</tt><br>
<tt>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"</tt><br>
<tt>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)</tt><br>
<tt>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</tt><br>
<tt>Nov 19 23:23:25.876 server.kainhofer.com
/usr/sbin/amavisd-new[11877]: SpamControl: attempting to load
scanner SpamAssassin, module Amavis::SpamControl::SpamAssassin</tt><br>
<tt>Nov 19 23:23:25.876 server.kainhofer.com
/usr/sbin/amavisd-new[11877]: SpamControl: scanner SpamAssassin,
module Amavis::SpamControl::SpamAssassin</tt><br>
<tt>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::<a class="moz-txt-link-freetext" href="Info::GIF">Info::GIF</a> Image::<a class="moz-txt-link-freetext" href="Info::JPEG">Info::JPEG</a> Image::<a class="moz-txt-link-freetext" href="Info::PNG">Info::PNG</a>
Image::<a class="moz-txt-link-freetext" href="Info::BMP">Info::BMP</a> Image::<a class="moz-txt-link-freetext" href="Info::TIFF">Info::TIFF</a></tt><br>
<tt>Nov 19 23:23:25.987 server.kainhofer.com
/usr/sbin/amavisd-new[11877]: SpamControl: init_pre_chroot on
SpamAssassin done</tt><br>
<tt>Nov 19 23:23:25.987 server.kainhofer.com
/usr/sbin/amavisd-new[11877]: socket module IO::Socket::IP,
protocol families available: INET</tt><br>
<tt>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</tt><br>
<tt>Nov 19 23:23:25.987 server.kainhofer.com
/usr/sbin/amavisd-new[11877]: <a class="moz-txt-link-freetext" href="Net::Server">Net::Server</a>: 2016/11/19-23:23:25
Amavis (type <a class="moz-txt-link-freetext" href="Net::Server::PreForkSimple">Net::Server::PreForkSimple</a>) starting! pid(11877)</tt><br>
<tt>Nov 19 23:23:25.989 server.kainhofer.com
/usr/sbin/amavisd-new[11877]: <a class="moz-txt-link-freetext" href="Net::Server">Net::Server</a>: Binding to UNIX
socket file "/var/lib/amavis/amavisd.sock"</tt><br>
<tt>Nov 19 23:23:25.989 server.kainhofer.com
/usr/sbin/amavisd-new[11877]: <a class="moz-txt-link-freetext" href="Net::Server">Net::Server</a>: Binding to TCP port
10024 on host 127.0.0.1 with IPv4</tt><br>
<tt>Nov 19 23:23:25.990 server.kainhofer.com
/usr/sbin/amavisd-new[11877]: <a class="moz-txt-link-freetext" href="Net::Server">Net::Server</a>: Binding to TCP port
10026 on host 127.0.0.1 with IPv4</tt><br>
<tt>Nov 19 23:23:25.990 server.kainhofer.com
/usr/sbin/amavisd-new[11877]: <a class="moz-txt-link-freetext" href="Net::Server">Net::Server</a>: Group Not Defined.
Defaulting to EGID '118 118'</tt><br>
<tt>Nov 19 23:23:25.990 server.kainhofer.com
/usr/sbin/amavisd-new[11877]: <a class="moz-txt-link-freetext" href="Net::Server">Net::Server</a>: User Not Defined.
Defaulting to EUID '110'</tt><br>
<tt>Nov 19 23:23:25.990 server.kainhofer.com
/usr/sbin/amavisd-new[11877]: <a class="moz-txt-link-freetext" href="Net::Server">Net::Server</a>: Setting up
serialization via flock</tt><br>
<tt>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)</tt><br>
<tt>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</tt><br>
</blockquote>
<p><br>
</p>
<p>However, even then there are several errors from amavisd-new (and
the mail is still stuck in postfix):</p>
<blockquote>
<p><tt>[...]</tt></p>
<p><tt>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
< <a class="moz-txt-link-freetext" href="SMTP://x">SMTP://x</a> < ESMTPSA://91.115.19.82</tt><tt><br>
</tt><tt>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.</tt><tt><br>
</tt><tt>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:
<a class="moz-txt-link-rfc2396E" href="mailto:reinhold.kainhofer@gmail.com"><reinhold.kainhofer@gmail.com></a>, a=rsa-sha256,
c=relaxed/relaxed, s=20120113, <a class="moz-txt-link-abbreviated" href="mailto:i=@gmail.com">i=@gmail.com</a>, 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.)</tt><tt><br>
</tt><tt>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)</tt><tt><br>
</tt><tt>[...]</tt></p>
<p><tt>Nov 19 23:37:34.883 server.kainhofer.com
/usr/sbin/amavisd-new[11884]: (11884-07) CALLING SA check (0)</tt><tt><br>
</tt><tt>rules: failed to run NO_DNS_FOR_FROM RBL test,
skipping:</tt><tt><br>
</tt><tt> (Unrecognised protocol udp at
/usr/share/perl5/Mail/SpamAssassin/DnsResolver.pm line 420.)</tt><tt><br>
</tt><tt>spf: lookup failed: Unrecognised protocol udp at
/usr/share/perl5/Mail/SpamAssassin/DnsResolver.pm line 420.</tt><tt><br>
</tt><tt>[...]</tt></p>
<tt>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</tt><tt><br>
</tt><tt>Nov 19 23:37:34.933 server.kainhofer.com
/usr/sbin/amavisd-new[11884]: (11884-07) smtp session: setting
up a new session</tt><tt><br>
</tt><tt>Nov 19 23:37:34.933 server.kainhofer.com
/usr/sbin/amavisd-new[11884]: (11884-07) establish_or_refresh,
state: down</tt><tt><br>
</tt><tt>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</tt><tt><br>
</tt><tt>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.</tt><tt><br>
</tt><tt>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:*</tt><tt><br>
</tt><tt>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</tt><tt><br>
</tt><tt>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</tt><tt><br>
</tt><tt>Nov 19 23:37:34.934 server.kainhofer.com
/usr/sbin/amavisd-new[11884]: (11884-07) (!)CtDipLcUY4lD FWD
from <a class="moz-txt-link-rfc2396E" href="mailto:reinhold.kainhofer@gmail.com"><reinhold.kainhofer@gmail.com></a> ->
<a class="moz-txt-link-rfc2396E" href="mailto:reinhold@kainhofer.com"><reinhold@kainhofer.com></a>, 451 4.5.0 From MTA() during
fwd-connect (All attempts (1) failed connecting to
smtp:127.0.0.1:*): id=11884-07</tt><tt><br>
</tt><tt>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</tt><tt><br>
</tt><tt>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</tt><tt><br>
</tt><tt>Nov 19 23:37:34.934 server.kainhofer.com
/usr/sbin/amavisd-new[11884]: (11884-07) DSN: sender NOT
credible, SA: 1.312, <a class="moz-txt-link-rfc2396E" href="mailto:reinhold.kainhofer@gmail.com"><reinhold.kainhofer@gmail.com></a></tt><tt><br>
</tt><tt>Nov 19 23:37:34.934 server.kainhofer.com
/usr/sbin/amavisd-new[11884]: (11884-07) lookup: (scalar)
matches, result="100"</tt><tt><br>
</tt><tt>Nov 19 23:37:34.935 server.kainhofer.com
/usr/sbin/amavisd-new[11884]: (11884-07) lookup
[spam_dsn_cutoff_level_bysender] => true,
<a class="moz-txt-link-rfc2396E" href="mailto:reinhold.kainhofer@gmail.com">"reinhold.kainhofer@gmail.com"</a> matches, result="100",
matching_key="(constant:100)"</tt><tt><br>
</tt><tt>Nov 19 23:37:34.935 server.kainhofer.com
/usr/sbin/amavisd-new[11884]: (11884-07) dsn: . 451
MtaTempFailed <a class="moz-txt-link-rfc2396E" href="mailto:reinhold.kainhofer@gmail.com"><reinhold.kainhofer@gmail.com></a> ->
<a class="moz-txt-link-rfc2396E" href="mailto:reinhold@kainhofer.com"><reinhold@kainhofer.com></a>: 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"</tt><tt><br>
</tt><tt>Nov 19 23:37:34.935 server.kainhofer.com
/usr/sbin/amavisd-new[11884]: (11884-07) DSN: TMPFAIL . 451
MtaTempFailed, not to be reported:
<a class="moz-txt-link-rfc2396E" href="mailto:reinhold.kainhofer@gmail.com"><reinhold.kainhofer@gmail.com></a> ->
<a class="moz-txt-link-rfc2396E" href="mailto:reinhold@kainhofer.com"><reinhold@kainhofer.com></a></tt><tt><br>
</tt></blockquote>
<p><br>
</p>
</body>
</html>