Public bug reported:
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 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]>
---
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
** Affects: amavisd-new (Ubuntu)
Importance: Undecided
Status: New
** Tags: apport-collected yakkety
--
You received this bug notification because you are a member of Ubuntu
Bugs, which is subscribed to Ubuntu.
https://bugs.launchpad.net/bugs/1643249
Title:
Amavisd-new refuses to start (Can't connect to TCP port 10024 on
127.0.0.1 [Permission denied])
To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu/+source/amavisd-new/+bug/1643249/+subscriptions
--
ubuntu-bugs mailing list
[email protected]
https://lists.ubuntu.com/mailman/listinfo/ubuntu-bugs
