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