Recently I was updating amavisd and other portions of the mail stack on one of my mail servers (running Gentoo Linux). This particular set of updates didn’t go as smoothly as I would have liked primarily due to the acct-user/amavis package being created on Thursday, 13 February 2020 as a part of the ongoing effort to standardise user accounts used within applications. Some other problems with the upgrade of amavisd (to version 2.12.0-r1) and the mail stack were that some dependencies were erroneously removed from the ebuild (bug 710842) and (though not directly related) permissions within the new amavis user’s home directory being inadequate for ClamAV to successfully run. I will address these problems and their respective fixes below.
Missing dependencies in 2.12.0-r1 (bug 710842)
Some of the Perl modules (since amavisd-new is written in Perl) were erroneously removed from the dependency list in version 2.12.0-r1. The fix here was to simply reinstall the modules manually, which in my case entailed:
emerge -av MIME-tools Net-Server Mail-DKIM MailTools Net-LibIDNHowever, my situation required one additional module that wasn’t mentioned in the bug, and was discovered when trying to manually start amavisd because of this error message:
# /usr/sbin/amavisd
Problem in Amavis::Unpackers code: Can't locate Archive/Zip.pm in @INC (you may need to install the Archive::Zip module) (@INC contains: /etc/perl /usr/local/lib64/perl5/5.30.1/x86_64-linux /usr/local/lib64/perl5/5.30.1 /usr/lib64/perl5/vendor_perl/5.30.1/x86_64-linux /usr/lib64/perl5/vendor_perl/5.30.1 /usr/local/lib64/perl5 /usr/lib64/perl5/vendor_perl/5.30.0/x86_64-linux /usr/lib64/perl5/vendor_perl/5.30.0 /usr/lib64/perl5/vendor_perl/5.28.0 /usr/lib64/perl5/vendor_perl/5.26.2 /usr/lib64/perl5/vendor_perl/5.26.1 /usr/lib64/perl5/vendor_perl/5.24.0 /usr/lib64/perl5/vendor_perl /usr/lib64/perl5/5.30.1/x86_64-linux /usr/lib64/perl5/5.30.1) at (eval 101) line 47.
BEGIN failed--compilation aborted at (eval 101) line 47.That one was also simple enough to solve by installing dev-perl/Archive-Zip:
emerge -av dev-perl/Archive-ZipFortunately, this ‘missing dependencies’ problem was fixed with version 2.12.0-r2.
Changes in the ‘amavis’ user’s home directory
With the addition of the acct-user/amavis package, a few things changes about the default setup for the ‘amavis’ user. When installing that package, Portage warns about some steps that need to be implemented in order to make amavis work again after migrating its home directory from /var/amavis/ to /var/lib/amavishome. Even after following those steps, I saw the following error message when starting amavis:
Feb 27 00:08:31 [amavis] socket module IO::Socket::IP, protocol families available: INET, INET6
Feb 27 00:08:31 [amavis] will bind to /var/amavis/amavisd.sock|unix, 127.0.0.1:10024/tcp, [::1]:10024/tcp
Feb 27 00:08:31 [amavis] sd_notify (no socket): STATUS=Transferring control to Net::Server.
Feb 27 00:08:31 [amavis] sd_notify (no socket): STATUS=Preparing to bind sockets.
Feb 27 00:08:31 [amavis] Net::Server: 2020/02/27-00:08:31 Amavis (type Net::Server::PreForkSimple) starting! pid(1738)
Feb 27 00:08:31 [amavis] Net::Server: Binding to UNIX socket file "/var/amavis/amavisd.sock"
Feb 27 00:08:31 [amavis] (!)Net::Server: 2020/02/27-00:08:31 Can't connect to UNIX socket at file /var/amavis/amavisd.sock [No such file or directory]\n at line 66 in file /usr/lib64/perl5/vendor_perl/5.30.1/Net/Server/Proto/UNIX.pm
Feb 27 00:08:31 [amavis] sd_notify (no socket): STOPPING=1\nSTATUS=Server rundown, notifying child processes.
Feb 27 00:08:31 [amavis] Net::Server: 2020/02/27-00:08:31 Server closing!
Feb 27 00:08:31 [amavis] sd_notify (no socket): STATUS=Child processes have been stopped.In that error message, I noticed that there were still references to /var/amavis/ instead of the new /var/lib/amavishome/ directory, so I updated it using the $MYHOME variable in /etc/amavisd.conf:
# grep -e '^$MYHOME' /etc/amavisd.conf
$MYHOME = '/var/lib/amavishome'; # a convenient default for other settings, -HThereafter, the start-up logs indicated that it was binding to a UNIX socket in the correct home directory:
Feb 27 00:12:15 [amavis] socket module IO::Socket::IP, protocol families available: INET, INET6
Feb 27 00:12:15 [amavis] will bind to /var/lib/amavishome/amavisd.sock|unix, 127.0.0.1:10024/tcp, [::1]:10024/tcp
Feb 27 00:12:15 [amavis] sd_notify (no socket): STATUS=Transferring control to Net::Server.
Feb 27 00:12:15 [amavis] sd_notify (no socket): STATUS=Preparing to bind sockets.
Feb 27 00:12:15 [amavis] Net::Server: 2020/02/27-00:12:15 Amavis (type Net::Server::PreForkSimple) starting! pid(1952)
Feb 27 00:12:15 [amavis] Net::Server: Binding to UNIX socket file "/var/lib/amavishome/amavisd.sock"
Feb 27 00:12:15 [amavis] Net::Server: Binding to TCP port 10024 on host 127.0.0.1 with IPv4
Feb 27 00:12:15 [amavis] Net::Server: Binding to TCP port 10024 on host ::1 with IPv6ClamAV permissions within the amavis home directory:
Though this error wasn’t directly related to the upgrades (and had likely existed for quite some time beforehand), I only just now noticed it whilst combing through the logs (the first error is from my system’s mail log, and the second error is from the clamd log):
Feb 27 00:15:10 [amavis] (01980-01) run_av (ClamAV-clamd) result: /var/lib/amavishome/tmp/amavis-20200227T001510-01980-zrKbp28h/parts: lstat() failed: Permission denied. ERROR\n
Feb 27 00:15:10 [amavis] (01980-01) (!)run_av (ClamAV-clamd) FAILED - unexpected , output="/var/lib/amavishome/tmp/amavis-20200227T001510-01980-zrKbp28h/parts: lstat() failed: Permission denied. ERROR\n"
Feb 27 00:15:10 [amavis] (01980-01) (!)ClamAV-clamd av-scanner FAILED: CODE(0x5611198fa5d8) unexpected , output="/var/lib/amavishome/tmp/amavis-20200227T001510-01980-zrKbp28h/parts: lstat() failed: Permission denied. ERROR\n" at (eval 85) line 951.# grep 'lstat' /var/log/clamav/clamd.log
Wed Feb 26 23:26:53 2020 -> WARNING: lstat() failed on: /var/amavis/tmp/amavis-20200226T180007-00529-S1gbY8cd/parts
Wed Feb 26 23:28:32 2020 -> WARNING: lstat() failed on: /var/amavis/tmp/amavis-20200226T180038-00592-FK2_Uj2T/parts
Wed Feb 26 23:31:30 2020 -> WARNING: lstat() failed on: /var/amavis/tmp/amavis-20200226T165427-32346-V4WeP0YX/parts
Thu Feb 27 00:15:10 2020 -> WARNING: lstat() failed on: /var/lib/amavishome/tmp/amavis-20200227T001510-01980-zrKbp28h/parts
Thu Feb 27 00:26:21 2020 -> WARNING: lstat() failed on: /var/lib/amavishome/tmp/amavis-20200227T002621-01981-l36mWT4P/parts
Thu Feb 27 00:26:30 2020 -> WARNING: lstat() failed on: /var/lib/amavishome/tmp/amavis-20200227T002630-01982-k0qgJdjl/parts
Thu Feb 27 00:29:12 2020 -> WARNING: lstat() failed on: /var/lib/amavishome/tmp/amavis-20200227T002912-01983-G57aKCmK/parts
Thu Feb 27 00:31:55 2020 -> WARNING: lstat() failed on: /var/lib/amavishome/tmp/amavis-20200227T003155-01984-M9r9r1Gc/parts
Thu Feb 27 00:33:07 2020 -> WARNING: lstat() failed on: /var/lib/amavishome/tmp/amavis-20200227T003307-01985-8n_wS6pQ/parts
Thu Feb 27 00:40:20 2020 -> WARNING: lstat() failed on: /var/lib/amavishome/tmp/amavis-20200227T004020-01986-gH4PrFAk/parts
Thu Feb 27 00:45:45 2020 -> WARNING: lstat() failed on: /var/lib/amavishome/tmp/amavis-20200227T004545-01987-J4YGuNbw/partsThese errors were fixed by 1) adding the ‘clamav’ user to the ‘amavis’ group, 2) setting g+w permissions on the /var/lib/amavishome/tmp/ directory, and 3) restarting clamd and amavisd
# gpasswd -a clamav amavis
Adding user clamav to group amavis
# ls -alh /var/lib/amavishome/ | grep tmp
drwxr-xr-x 141 amavis amavis 12K Feb 27 00:46 tmp
# chmod 775 /var/lib/amavishome/tmp
# ls -alh /var/lib/amavishome/ | grep tmp
drwxrwxr-x 141 amavis amavis 12K Feb 27 00:46 tmp
# /etc/init.d/clamd restart && /etc/init.d/amavisd restartNow ClamAV is readily able to access files under /var/lib/amavishome/tmp/:
Feb 27 01:00:12 [amavis] (03346-01) ClamAV-clamd: Connecting to socket /var/run/clamav/clamd.sock
Feb 27 01:00:12 [amavis] (03346-01) new socket by IO::Socket::UNIX to /var/run/clamav/clamd.sock, timeout set to 10
Feb 27 01:00:12 [amavis] (03346-01) connected to /var/run/clamav/clamd.sock successfully
Feb 27 01:00:12 [amavis] (03346-01) ClamAV-clamd: Sending CONTSCAN /var/lib/amavishome/tmp/amavis-20200227T010012-03346-YjbUpYOk/parts\n to socket /var/run/clamav/clamd.sockHopefully, if you run into these errors, you will be able to take this information and apply it to your particular mail stack.
Cheers,
Zach
