EFA fails to spamcheck all incoming mail

[pdwalker]

This is a problem I've recently come across and I'm documenting how I diagnosed it in case anyone else has a similar problem.

---
This is something I've noticed recently, that not all incoming messages are scanned. For example, see the following screenshot:

EFA-spam-failure.png

You can see that all these are very spammy messages, but one has a score of 0. Searching through the maillog for that message id shows me the following:

Message 4WT4vZ0qJgzMy28n from 67.219.246.152 (www-data@kamtopiaero.shop) to XXX.com is not spam, SpamAssassin (not cached, timed out)

One of the message IDs that was properly marked shows the following:

Jul 24 03:43:34 efa4 MailScanner[2188]: Message 4WT6yR2CyYzMrG5V from 67.219.246.153 (www-data@kamtopiaero.shop) to XXX.com is spam, SpamAssassin (not cached, score=44.223, required 4, autolearn=spam, BAYES_80 2.00, XXX_EXTERNAL 0.01, XXX_SPOOF 12.00, C_RBL_GBUDB 5.00, C_RBL_UCE_1 1.01, DATE_IN_PAST_03_06 1.59, DCC_CHECK 1.10, DCC_REPUT_95_98 1.00, DIGEST_MULTIPLE 0.29, DKIM_ADSP_ALL 0.80, FROM_IN_TO_AND_SUBJ 1.80, HEADER_FROM_DIFFERENT_DOMAINS 0.00, HTML_FONT_LOW_CONTRAST 0.00, HTML_MESSAGE 0.00, HTML_OBFUSCATE_10_20 0.09, KHOP_HELO_FCRDNS 0.26, MIME_HTML_ONLY 0.10, ML_SPAMINFO_EXISTS 5.00, MXPF_TEST 0.00, PYZOR_CHECK 1.39, RCVD_IN_PBL 3.33, RCVD_IN_SBL_CSS 3.33, SPF_HELO_SOFTFAIL 0.73, SPF_SOFTFAIL 0.67, TO_EQ_FM_HTML_ONLY 0.00, TO_IN_SUBJ 0.00, TO_NO_BRKTS_HTML_ONLY 2.00, TXREP -2.25, URIBL_ABUSE_SURBL 1.25, URIBL_BLACK 1.70)

So, spamassassin is timing out somewhere (RBL checks maybe?) and then giving a default score of 0.

I also found that over the last couple of days, there were 30 messages that fell into this hole.

My Spamassassin timeout is set to 120 seconds, which is plenty of time to resolve things on an lightly loaded server.

Unfortunately, there is nothing in the logs that tells me why it is timing out.

In case it was unbound causing the issues, I searched for timeout in /var/log/messages and I found 30 messages like the following:

PHP Fatal error: Uncaught mysqli_sql_exception: Lock wait timeout exceeded; try restarting transaction in /var/www/html/mailscanner/functions.php:1066

so I think I've found the culprit.

Code: Select all

 3666 Jul 22 04:13:29 efa4 php: Stack trace:
 3667 Jul 22 04:13:29 efa4 php: Fatal error: Uncaught mysqli_sql_exception: Lock wait timeout exceeded; try restarting transaction in /var/www/html/mailscanner/functions.php:1066
 3668 Jul 22 04:13:29 efa4 php: Stack trace:
 3669 Jul 22 04:13:29 efa4 php: #0 /var/www/html/mailscanner/functions.php(1066): mysqli->query('REPLACE INTO `m...')
 3670 Jul 22 04:13:29 efa4 php: #1 /usr/bin/mailwatch/tools/Postfix_relay/mailwatch_milter_relay.php(168): dbquery('REPLACE INTO `m...')
 3671 Jul 22 04:13:29 efa4 php: #2 /usr/bin/mailwatch/tools/Postfix_relay/mailwatch_milter_relay.php(58): process_sql()
 3672 Jul 22 04:13:29 efa4 php: #3 /usr/bin/mailwatch/tools/Postfix_relay/mailwatch_milter_relay.php(210): doit('cat /var/log/ma...')
 3673 Jul 22 04:13:29 efa4 php: #4 {main}

Does this mean one of my database tables has now gotten too large?

Searching the /usr/bin/mailwatch/tools/Postfix_relay/mailwatch_milter_relay.php code at line 168 shows that the system is doing an update on the mtalog_ids table which has 2.2 million records on my system.

I vaguely recall someone else having an issue with this table growing too large, and a quick search found the following: viewtopic.php?p=19809#p19809

I am going to clean out this table and see if that resolves the issue. I suspect it will.

[pdwalker]

[I am leaving this post here to document how I am troubleshooting this problem and it's eventual resolution]

ok, it's a couple of days later and I am still getting spamassassin timeouts. This is one example from /var/log/maillog

Jul 21 17:16:20 efa4 MailScanner[11087]: New Batch: Scanning 1 messages, 49674 bytes
Jul 21 17:16:20 efa4 MailScanner[11087]: Virus and Content Scanning: Starting
Jul 21 17:16:20 efa4 MailScanner[11087]: <A> tag found in message 4WRd7g0k2CzMy28n from kfong@edgeconnex.com
Jul 21 17:16:20 efa4 MailScanner[11087]: Spam Checks: Starting
Jul 21 17:16:20 efa4 MailScanner[11087]: Expired 6 records from the SpamAssassin cache
Jul 21 17:16:20 efa4 MailScanner[11087]: MailWatch: Allowlist refresh time reached
Jul 21 17:16:20 efa4 MailScanner[11087]: MailWatch: Starting up MailWatch SQL Allowlist
Jul 21 17:16:20 efa4 MailScanner[11087]: MailWatch: Read 8 allowlist entries
Jul 21 17:16:20 efa4 MailScanner[11087]: MailWatch: Blocklist refresh time reached
Jul 21 17:16:20 efa4 MailScanner[11087]: MailWatch: Starting up MailWatch SQL Blocklist
Jul 21 17:16:20 efa4 MailScanner[11087]: MailWatch: Read 1 blocklist entries
Jul 21 17:18:21 efa4 MailScanner[11087]: SpamAssassin timed out and was killed, failure 1 of 10
Jul 21 17:18:22 efa4 MailScanner[11087]: Message 4WRd7g0k2CzMy28n from 67.219.246.154 (kfong@edgeconnex.com) to EXAMPLE.com is not spam, SpamAssassin (not cached, timed out)
Jul 21 17:18:22 efa4 MailScanner[11087]: Requeue: 4WRd7g0k2CzMy28n to 4WRd7g0k2CzMy28n
Jul 21 17:18:22 efa4 MailScanner[11087]: Uninfected: Delivered 1 messages
Jul 21 17:18:22 efa4 MailScanner[11087]: Deleted 1 messages from processing-database
Jul 21 17:18:22 efa4 MailScanner[11087]: MailWatch: Logging message 4WRd7g0k2CzMy28n to SQL

Unfortunately, I have no further clues as it seems to be an intermittent problem on my system. Perhaps it's an RBL lookup? Unless I enable debug mode for spamassassin, I am not going to have any further clues.

Since I am planning on upgrading to eFa v5 on a new linux installation, I am not going to worry further about this until after the migration.