<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>