For approximately the past six weeks or so, I’ve noticed an uptick in the amount of spam getting through (and delivered) on my primary mail server. At first the increase in false negatives (meaning spam not getting flagged as such) wasn’t all that bad, so I didn’t think much of it. However, starting last week and especially this week, the increase was so dramatic that it prompted me to look further into the problem.

I started by looking through my SpamAssassin and amavis settings to make sure that nothing was blatantly wrong, but nothing stood out as having recently changed. I made sure that I had the required Perl modules for all of SpamAssassin’s filtering, and again, nothing had recently changed. Coming up empty-handed, I decided to take a look at some headers for an email that came through even though it was spam:

X-Spam-Status: No, score=1.502 required=3.2 tests=[
	DKIM_SIGNED=0.1, DKIM_VALID=-0.1, FREEMAIL_FORGED_FROMDOMAIN=0.25,
	FREEMAIL_FROM=0.001, HEADER_FROM_DIFFERENT_DOMAINS=0.25,
	HTML_MESSAGE=0.001]

I thought that possibly something had changed with how SpamAssassin assigned points for various tests, and temporarily dropped the score required for spam flagging to 1.4. Delving more deeply, though, I found that the point assignments had not changed, so I reverted to 3.2 and kept investigating. After looking again, I noticed that one key test wasn’t showing in the ‘X-Spam-Status’ header for this email: Bayesian filtering. Normally, there would be some type of reference to ‘BAYES_%=#’ (where % represents the chance that the Bayesian filter thought that the message could be spam and # represents the score assigned to the email based on that chance) in the spam header. However, it was no longer showing up, which indicated to me that the Bayes filters weren’t running.

I then started with some basic Bayes troubleshooting steps, and found some clues. By analysing the output of spamassassin -D --lint, I saw that there could be problem with the Bayes database:

Apr 14 22:10:41.875 [20701] dbg: plugin: loading Mail::SpamAssassin::Plugin::Bayes from @INC
Apr 14 22:10:42.061 [20701] dbg: config: fixed relative path: /var/lib/spamassassin/3.004004/updates_spamassassin_org/23_bayes.cf
Apr 14 22:10:42.061 [20701] dbg: config: using "/var/lib/spamassassin/3.004004/updates_spamassassin_org/23_bayes.cf" for included file
Apr 14 22:10:42.061 [20701] dbg: config: read file /var/lib/spamassassin/3.004004/updates_spamassassin_org/23_bayes.cf
Apr 14 22:10:42.748 [20701] dbg: plugin: Mail::SpamAssassin::Plugin::Bayes=HASH(0x55f1700749b8) implements 'learner_new', priority 0
Apr 14 22:10:42.748 [20701] dbg: bayes: learner_new self=Mail::SpamAssassin::Plugin::Bayes=HASH(0x55f1700749b8), bayes_store_module=Mail::SpamAssassin::BayesStore::DBM
Apr 14 22:10:42.759 [20701] dbg: bayes: learner_new: got store=Mail::SpamAssassin::BayesStore::DBM=HASH(0x55f170db5ba8)
Apr 14 22:10:42.759 [20701] dbg: plugin: Mail::SpamAssassin::Plugin::Bayes=HASH(0x55f1700749b8) implements 'learner_is_scan_available', priority 0
Apr 14 22:10:42.759 [20701] dbg: bayes: tie-ing to DB file R/O /var/amavis/.spamassassin/bayes_toks
Apr 14 22:10:42.760 [20701] dbg: bayes: tie-ing to DB file R/O /var/amavis/.spamassassin/bayes_seen
Apr 14 22:10:42.760 [20701] dbg: bayes: found bayes db version 3
Apr 14 22:10:42.760 [20701] dbg: bayes: DB journal sync: last sync: 1586894330
Apr 14 22:10:42.760 [20701] dbg: bayes: not available for scanning, only 0 ham(s) in bayes DB < 200
Apr 14 22:10:42.760 [20701] dbg: bayes: untie-ing
Apr 14 22:10:42.764 [20701] dbg: bayes: tie-ing to DB file R/O /var/amavis/.spamassassin/bayes_toks
Apr 14 22:10:42.764 [20701] dbg: bayes: tie-ing to DB file R/O /var/amavis/.spamassassin/bayes_seen
Apr 14 22:10:42.765 [20701] dbg: bayes: found bayes db version 3
Apr 14 22:10:42.765 [20701] dbg: bayes: DB journal sync: last sync: 1586894330
Apr 14 22:10:42.765 [20701] dbg: bayes: not available for scanning, only 0 ham(s) in bayes DB < 200
Apr 14 22:10:42.765 [20701] dbg: bayes: untie-ing

In particular, the following lines indicated a problem to me:

Apr 14 22:10:42.760 [20701] dbg: bayes: not available for scanning, only 0 ham(s) in bayes DB < 200
<snip>
Apr 14 22:10:42.765 [20701] dbg: bayes: not available for scanning, only 0 ham(s) in bayes DB < 200

Thinking back, I remembered that there were some changes to the amavis implementation in Gentoo that caused me problems in late February of 2020. One of those changes was relocating the amavis user’s home/runtime directory from /var/amavis/ to /var/lib/amavishome/. That’s when I saw it in the debugging output:

Apr 14 22:10:42.759 [20701] dbg: bayes: tie-ing to DB file R/O /var/amavis/.spamassassin/bayes_toks
Apr 14 22:10:42.760 [20701] dbg: bayes: tie-ing to DB file R/O /var/amavis/.spamassassin/bayes_seen

The directory for the Bayes database shouldn’t be /var/amavis/.spamassassin/bayes* any longer, but instead should be /var/lib/amavishome/.spamassassin/bayes*. I made that change:

# grep bayes_path /etc/mail/spamassassin/local.cf 
bayes_path /var/lib/amavishome/.spamassassin/bayes

and restarted both amavis and spamd, and now I could see the Bayes filter in the ‘X-Spam-Status’ header:

X-Spam-Status: Yes, score=18.483 required=3.2 tests=[BAYES_99=5.75,
	BAYES_999=8, FROM_SUSPICIOUS_NTLD=0.499,
	FROM_SUSPICIOUS_NTLD_FP=0.514, HTML_MESSAGE=0.001,
	HTML_OFF_PAGE=0.927, PDS_OTHER_BAD_TLD=1.999, RDNS_NONE=0.793]

After implementing the change for the Bayes database location in amavis, I have seen the false negative level drop back to where it used to be. 🙂

Cheers,
Zach

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

However, 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-Zip

Fortunately, 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, -H

Thereafter, 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 IPv6

ClamAV 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/parts

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

Now 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.sock

Hopefully, if you run into these errors, you will be able to take this information and apply it to your particular mail stack.

Cheers,

Zach