Amavisd – debugging and logging startup failures

Recently, I wrote an article about amavisd not running with Postfix, and getting a “Connection refused to 127.0.0.1” error message that wasn’t easy to diagnose. Yesterday, I ran into another problem with amavisd refusing to start properly, and I wasn’t readily able to figure out why. By default, amavisd logs to your mail log, which for me is located at /var/log/mail.log, but could be different for you based on your syslogger preferences. The thing is, though, that it will not log start-up errors there. So basically, one is seemingly left in the dark if you start amavisd and then realise it isn’t running immediately thereafter.

I decided to take a look at the init script for amavisd, and saw that there were some non-standard functions in it:


# grep 'extra_commands' /etc/init.d/amavisd
extra_commands="debug debug_sa"

These extra commands map to the following functions:


debug() {
ebegin "Starting ${progname} in debug mode"
"${prog}" debug
eend $?
}

debug_sa() {
ebegin "Starting ${progname} in debug-sa mode"
"${prog}" debug-sa
eend $?
}

Though these extra commands may be Gentoo-specific, they are pretty easy to implement on other distributions by directly calling the binary itself. For instance, if you wanted the debug function, it would be the location of the binary with ‘debug’ appended to it. On my system, that would be:


/usr/sbin/amavisd -c $LOCATION_OF_CONFIG_FILE debug

replacing the $LOCATION_OF_CONFIG_FILE with your actual config file location.

When I started amavisd in debug mode, the start-up problem that it was having became readily apparent:


# /etc/init.d/amavisd debug
* Starting amavisd-new in debug mode ...
Jun 18 12:48:21.948 /usr/sbin/amavisd[4327]: logging initialized, log level 5, syslog: amavis.mail
Jun 18 12:48:21.948 /usr/sbin/amavisd[4327]: starting. /usr/sbin/amavisd at amavisd-new-2.10.1 (20141025), Unicode aware, LANG="en_GB.UTF-8"

Jun 18 12:48:22.200 /usr/sbin/amavisd[4327]: Net::Server: 2015/06/18-12:48:22 Amavis (type Net::Server::PreForkSimple) starting! pid(4327)
Jun 18 12:48:22.200 /usr/sbin/amavisd[4327]: (!)Net::Server: 2015/06/18-12:48:22 Unresolveable host [::1]:10024 - could not load IO::Socket::INET6: Can't locate Socket6.pm in @INC (you may need to install the Socket6 module) (@INC contains: lib /etc/perl /usr/local/lib64/perl5/5.20.2/x86_64-linux /usr/local/lib64/perl5/5.20.2 /usr/lib64/perl5/vendor_perl/5.20.2/x86_64-linux /usr/lib64/perl5/vendor_perl/5.20.2 /usr/local/lib64/perl5 /usr/lib64/perl5/vendor_perl/5.20.1/x86_64-linux /usr/lib64/perl5/vendor_perl/5.20.1 /usr/lib64/perl5/vendor_perl /usr/lib64/perl5/5.20.2/x86_64-linux /usr/lib64/perl5/5.20.2) at /usr/lib64/perl5/vendor_perl/5.20.1/Net/Server/Proto.pm line 122.\n\n at line 82 in file /usr/lib64/perl5/vendor_perl/5.20.1/Net/Server/Proto.pm
Jun 18 12:48:22.200 /usr/sbin/amavisd[4327]: Net::Server: 2015/06/18-12:48:22 Server closing!

In that code block, the actual error (in bold text) indicates that it couldn’t find the Perl module IO:Socket::INET6. This problem was easily fixed in Gentoo with emerge -av dev-perl/IO-Socket-INET6, but could be rectified by installing the module from your distribution’s repositories, or by using CPAN. In my case, it was caused by my recent compilation and installation of a new kernel that, this time, included IPV6 support.

The point of my post, however, wasn’t about my particular problem with amavisd starting, but rather how one can debug start-up problems with the daemon. Hopefully, if you run into woes with amavisd logging, these debug options will help you track down the problem.

Cheers,
Zach

6 comments

Skip to comment form

    • Toralf Förster on Friday, 19 June 2015 at 17:10
    • Reply

    >> This problem was easily fixed in Gentoo with emerge -av
    Under Gentoo this is the temp fix – eventually the appropriate ebuild has to be adopted IMO.

      • Zach on Friday, 19 June 2015 at 18:42
        Author
      • Reply

      Hi Toralf,

      Thanks for your comment. I don’t know that it needs to be put into the ebuild, per se, because amavisd doesn’t require IPV6. It can even be disabled by removing references to IPV6 addresses within the @mynetworks directive block:


      @mynetworks = qw( 127.0.0.0/8 [::1] [FE80::]/10 [FEC0::]/10
      10.0.0.0/8 172.16.0.0/12 192.168.0.0/16 );

      So, I guess it could be controlled with the global ‘ipv6’ USE flag, and ship different default /etc/amavisd.conf files depending on whether the flag is enabled or disabled.

      Thoughts?

      Cheers,
      Zach

        • Toralf Förster on Saturday, 20 June 2015 at 06:09
        • Reply

        yep, something in that direction. ANd exactly that falg is needed.
        I had for a long time USE=-ipv6 set to verify, that packages won’t configure ipv6 values, eg https://bugs.gentoo.org/show_bug.cgi?id=524726 .

          • Zach on Monday, 22 June 2015 at 11:29
            Author
          • Reply

          Good points, Toralf. I have filed bug 552860 for the RFE.

          Cheers,
          Zach

  1. oh so explanation amavisd not running with Postfix, thanks for his exposure

      • Zach on Wednesday, 12 August 2015 at 10:13
        Author
      • Reply

      You’re welcome. Hopefully the additional logging will help diagnose startup errors.

      Cheers,
      Zach

Leave a Reply

Your email address will not be published.