Clamd issues: Messages Stuck in Virus Scan loop after upgrade to 3.0.2.1

[phideauxx]

After upgrading to 3.0.2.1 we found that although messages were showing up on the Recent Messages page, they were not being delivered. A reboot temporarily fixed the issue, but it came back after a while. I am seeing this in the maillog over and over. It seems there is something wrong with Clam and restarting only temporarily fixes the issue.

Code: Select all

Apr 21 07:32:26 mailfilter1 MailScanner[24723]: Virus and Content Scanning: Starting
Apr 21 07:32:26 mailfilter1 MailScanner[24723]: Clamd::ERROR:: COULD NOT CONNECT TO CLAMD, RECOMMEND RESTARTING DAEMON :: .
Apr 21 07:32:26 mailfilter1 MailScanner[24723]: Virus Scanning: Clamd found 1 infections
Apr 21 07:32:26 mailfilter1 MailScanner[24723]: Virus Scanning: No virus scanners worked, so message batch was abandoned and retried!
Apr 21 07:32:27 mailfilter1 MailScanner[24742]: Virus Scanning: Found 1 viruses
Apr 21 07:32:27 mailfilter1 MailScanner[24742]: Spam Checks: Starting
Apr 21 07:32:27 mailfilter1 MailScanner[24742]: Deleted 7 messages from processing-database
Apr 21 07:32:27 mailfilter1 MailScanner[24742]: MailWatch: Logging message 3909462247.A915D to SQL
Apr 21 07:32:27 mailfilter1 MailScanner[24742]: MailWatch: Logging message 8A81862246.A505E to SQL
Apr 21 07:32:27 mailfilter1 MailScanner[24787]: MailWatch: 3909462247.A915D: Logged to MailWatch SQL
Apr 21 07:32:27 mailfilter1 MailScanner[24742]: MailWatch: Logging message F09A662245.A2611 to SQL
Apr 21 07:32:27 mailfilter1 MailScanner[24742]: MailWatch: Logging message 994C362244.A0C8A to SQL
Apr 21 07:32:27 mailfilter1 MailScanner[24787]: MailWatch: 8A81862246.A505E: Logged to MailWatch SQL
Apr 21 07:32:27 mailfilter1 MailScanner[24742]: MailWatch: Logging message CF31462241.A1D5C to SQL
Apr 21 07:32:27 mailfilter1 MailScanner[24742]: MailWatch: Logging message BBD2F62249.AD3EF to SQL
Apr 21 07:32:27 mailfilter1 MailScanner[24742]: MailWatch: Logging message CD3F262248.ABA24 to SQL
Apr 21 07:32:27 mailfilter1 MailScanner[24787]: MailWatch: F09A662245.A2611: Logged to MailWatch SQL
Apr 21 07:32:27 mailfilter1 MailScanner[24787]: MailWatch: 994C362244.A0C8A: Logged to MailWatch SQL
Apr 21 07:32:27 mailfilter1 MailScanner[24742]: New Batch: Found 96 messages waiting
Apr 21 07:32:27 mailfilter1 MailScanner[24742]: New Batch: Scanning 7 messages, 168249 bytes
Apr 21 07:32:28 mailfilter1 MailScanner[24742]: Virus and Content Scanning: Starting
Apr 21 07:32:28 mailfilter1 MailScanner[24787]: MailWatch: CF31462241.A1D5C: Logged to MailWatch SQL
Apr 21 07:32:28 mailfilter1 MailScanner[24742]: Clamd::ERROR:: COULD NOT CONNECT TO CLAMD, RECOMMEND RESTARTING DAEMON :: .
Apr 21 07:32:28 mailfilter1 MailScanner[24787]: MailWatch: BBD2F62249.AD3EF: Logged to MailWatch SQL
Apr 21 07:32:28 mailfilter1 MailScanner[24787]: MailWatch: CD3F262248.ABA24: Logged to MailWatch SQL
Apr 21 07:32:28 mailfilter1 MailScanner[24742]: Virus Scanning: Clamd found 1 infections
Apr 21 07:32:28 mailfilter1 MailScanner[24742]: Virus Scanning: No virus scanners worked, so message batch was abandoned and retried!

[phideauxx]

After rebooting again found the following message in the maillog

Code: Select all

Apr 21 08:02:07 mailfilter1 postfix/smtpd[7059]: warning: database /etc/postfix/virtual.db is older than source file /etc/postfix/virtual

So I ran

Code: Select all

sudo postmap /etc/postfix/virtual

from the "Common Issues Upgrading from 3.0.1.8 and below" thread and then restarted. Hoping that fixes the issue permanently.

[phideauxx]

OK, still not fixed. Messages continue to get stuck in inbound queue. Error messages in maillog as show below.

Code: Select all

Apr 21 08:36:23 mailfilter1 MailScanner[4913]: New Batch: Found 3 messages waiting
Apr 21 08:36:23 mailfilter1 MailScanner[4913]: New Batch: Scanning 1 messages, 87780 bytes
Apr 21 08:36:23 mailfilter1 MailScanner[4913]: File checker failed with real error: Can't fork at /usr/share/MailScanner/perl/MailScanner/SweepOther.pm line 443.
Apr 21 08:36:23 mailfilter1 MailScanner[6048]: MailScanner Email Processor version 5.0.3 starting...
Apr 21 08:36:23 mailfilter1 MailScanner[6048]: Reading configuration file /etc/MailScanner/MailScanner.conf
Apr 21 08:36:23 mailfilter1 MailScanner[6048]: Reading configuration file /etc/MailScanner/conf.d/README
Apr 21 08:36:23 mailfilter1 MailScanner[6048]: Read 2500 hostnames from the phishing whitelist
Apr 21 08:36:23 mailfilter1 MailScanner[6048]: Read 24648 hostnames from the phishing blacklists
Apr 21 08:36:23 mailfilter1 MailScanner[6048]: Config: calling custom init function SQLBlacklist
Apr 21 08:36:23 mailfilter1 MailScanner[6048]: MailWatch: Starting up MailWatch SQL Blacklist
Apr 21 08:36:24 mailfilter1 MailScanner[6048]: MailWatch: Read 67 blacklist entries
Apr 21 08:36:24 mailfilter1 MailScanner[6048]: Config: calling custom init function MailWatchLogging
Apr 21 08:36:24 mailfilter1 MailScanner[6048]: MailWatch: Started MailWatch SQL Logging child
Apr 21 08:36:24 mailfilter1 MailScanner[6048]: Config: calling custom init function SQLWhitelist
Apr 21 08:36:24 mailfilter1 MailScanner[6048]: MailWatch: Starting up MailWatch SQL Whitelist
Apr 21 08:36:24 mailfilter1 MailScanner[6048]: MailWatch: Read 147 whitelist entries
Apr 21 08:36:24 mailfilter1 MailScanner[6048]: Using SpamAssassin results cache
Apr 21 08:36:24 mailfilter1 MailScanner[6048]: Connected to SpamAssassin cache database
Apr 21 08:36:24 mailfilter1 MailScanner[6048]: Enabling SpamAssassin auto-whitelist functionality...
Apr 21 08:36:26 mailfilter1 MailScanner[6048]: Connected to Processing Attempts Database
Apr 21 08:36:26 mailfilter1 MailScanner[6048]: Found 3 messages in the Processing Attempts Database
Apr 21 08:36:26 mailfilter1 MailScanner[6048]: Using locktype = flock

which repeats over and over.
Also seeing

Code: Select all

Apr 21 08:42:14 mailfilter1 MailScanner[6048]: Warning: skipping message F0FFC62250.A63D4 as it has been attempted too many times
Apr 21 08:42:14 mailfilter1 MailScanner[6048]: Quarantined message F0FFC62250.A63D4 as it caused MailScanner to crash several times
Apr 21 08:42:14 mailfilter1 MailScanner[6048]: Saved entire message to /var/spool/MailScanner/quarantine/20170421/F0FFC62250.A63D4

Many times since the upgrade. Many messages are just being marked as "other" since it can't seem to finish scanning them.

[perforator]

Same problems here.
I see this when trying to start "clamd" after it has stopped due to memory issues.

Code: Select all

Apr 21 14:02:01 smtp kernel: [ 1465]   496  1465   219329   132839   1       0             0 clamd
Apr 21 14:02:01 smtp kernel: Out of memory: Kill process 1465 (clamd) score 277 or sacrifice child
Apr 21 14:02:01 smtp kernel: Killed process 1465, UID 496, (clamd) total-vm:877316kB, anon-rss:531352kB, file-rss:4kB
Apr 21 15:31:04 smtp clamd[17308]: Received 0 file descriptor(s) from systemd.
Apr 21 15:31:04 smtp clamd[17308]: clamd daemon 0.99.2 (OS: linux-gnu, ARCH: x86_64, CPU: x86_64)
Apr 21 15:31:04 smtp clamd[17308]: Running as user clam (UID 496, GID 497)
Apr 21 15:31:04 smtp clamd[17308]: Log file size limited to 4294967295 bytes.
Apr 21 15:31:04 smtp clamd[17308]: Reading databases from /var/lib/clamav
Apr 21 15:31:04 smtp clamd[17308]: Not loading PUA signatures.
Apr 21 15:31:04 smtp clamd[17308]: Bytecode: Security mode set to "TrustSigned".
Apr 21 15:31:18 smtp clamd[17308]: Loaded 6293795 signatures.
Apr 21 15:31:20 smtp clamd[17308]: TCP: Bound to [127.0.0.1]:3310
Apr 21 15:31:20 smtp clamd[17308]: TCP: Setting connection queue length to 30
Apr 21 15:31:20 smtp clamd[17308]: LOCAL: Removing stale socket file /var/run/clamav/clamd.sock
Apr 21 15:31:20 smtp clamd[17308]: LOCAL: Unix socket file /var/run/clamav/clamd.sock
Apr 21 15:31:20 smtp clamd[17308]: LOCAL: Setting connection queue length to 30
Apr 21 15:31:20 smtp clamd[17308]: daemonize() failed: Cannot allocate memory
Apr 21 15:31:20 smtp clamd[17308]: Socket file removed.

Code: Select all

Starting Clam AntiVirus Daemon: LibClamAV Error: yyerror(): /var/lib/clamav/antidebug_antivm.yar line 497 undefined identifier "pe"
LibClamAV Error: yyerror(): /var/lib/clamav/antidebug_antivm.yar line 512 undefined identifier "pe"
LibClamAV Error: yyerror(): /var/lib/clamav/antidebug_antivm.yar line 528 undefined identifier "pe"
LibClamAV Error: yyerror(): /var/lib/clamav/antidebug_antivm.yar line 544 undefined identifier "pe"
LibClamAV Error: yyerror(): /var/lib/clamav/antidebug_antivm.yar line 557 undefined identifier "pe"
LibClamAV Error: yyerror(): /var/lib/clamav/antidebug_antivm.yar line 603 undefined identifier "pe"
LibClamAV Error: yyerror(): /var/lib/clamav/antidebug_antivm.yar line 614 undefined identifier "pe"
LibClamAV Error: cli_loadyara: failed to parse rules file /var/lib/clamav/antidebug_antivm.yar, error count 7

I have now tried to double the amount of RAM to 4GB. Will return later with results.

[phideauxx]

Thanks perforator, I just increased my RAM from 2 to 4 GB also after seeing the following post which mirrored what I was seeing. Then I saw your reply.

viewtopic.php?f=13&t=2098

Looking at memory usage statistics in VMware it seems to be using that extra RAM. Maybe the update added some memory overhead?

Will also return and report, but so far so good.

[perforator]

Works just fine now when it has enough RAM.

[nsp653]

I am having the same issue but didn't start with 3.0.2.1. Been around a couple builds. And I have 4GB of vRAM on my host. In fact, this just happened again this morning. Mail queued up in POSTFIX due to CLAMD error.

[pdwalker]

I'd set your vm to 8GB as a minimum these days.

[nsp653]

Unfortunately....don't have that much to give on this ESXi host.

[shawniverson]

Unfortunately....don't have that much to give on this ESXi host.

Another option may be to turn off non essential items in eFa. For instance, munin, webmin, and so forth. It may also be useful to reduce the number of clamav-unofficial-rules that are in use to reduce the memory demand of clam.

[pdwalker]

It might be worth making a list of things that could be turned off (and how) in order of importance in order to conserve memory.