Amavis - ClamAV - Exceeded allowed time

compsos1 · November 29, 2017, 3:10am

Hello,

On one of our Nethserver, we received a bounced back message:
“451 4.5.0 Error in processing, id=02585-11, virus_scan FAILED: AV: ALL VIRUS SCANNERS FAILED”

I checked the maillog and it had the following:

Nov 28 09:00:41 srv postfix/smtpd[23801]: connect from o19.sg.booking.com[167.89.96.8] Nov 28 09:00:50 srv postfix/policy-spf[23803]: Policy action=PREPEND Received-SPF: pass (sg.booking.com: 167.89.96.8 is authorized to use ‘bounces+4713178-dd3e-amanda=ourdomain.com.au@sg.booking.com’ in ‘mfrom’ identity (mechanism ‘ip4:167.89.0.0/17’ matched)) receiver=srv.ourdomain.com.au; identity=mailfrom; envelope-from="bounces+4713178-dd3e-amanda=ourdomian.com.au@sg.booking.com"; helo=o19.sg.booking.com; client-ip=167.89.96.8 Nov 28 09:00:50 srv postfix/smtpd[23801]: NOQUEUE: client=o19.sg.booking.com[167.89.96.8] Nov 28 09:00:58 srv amavis[23025]: (23025-11) (!)ClamAV-clamd av-scanner FAILED: run_av error: ask_daemon_internal: Exceeded allowed time at (eval 97) line 657.\n Nov 28 09:00:58 srv amavis[23025]: (23025-11) (!)WARN: all primary virus scanners failed, considering backups Nov 28 09:00:58 srv amavis[23025]: (23025-11) (!!)AV: ALL VIRUS SCANNERS FAILED Nov 28 09:00:58 srv amavis[23025]: (23025-11) (!!)TROUBLE in check_mail: virus_scan FAILED: AV: ALL VIRUS SCANNERS FAILED Nov 28 09:00:58 srv amavis[23025]: (23025-11) (!)PRESERVING EVIDENCE in /var/spool/amavisd/tmp/amavis-20171128T075625-23025-6b6rHoSQ Nov 28 09:00:58 srv postfix/smtpd[23784]: proxy-reject: END-OF-MESSAGE: 451 4.5.0 Error in processing, id=23025-11, virus_scan FAILED: AV: ALL VIRUS SCANNERS FAILED; from=bounces+4713178-3335-darryl=ourdomain.com.au@sg.booking.com to=darryl@ourdomain.com.au proto=ESMTP helo=<o20.sg.booking.com> Nov 28 09:00:58 srv amavis[23025]: (23025-11) size: 123247, TIMING [total 27217 ms] - SMTP greeting: 9 (0%)0, SMTP EHLO: 1.2 (0%)0, SMTP pre-MAIL: 0.8 (0%)0, SMTP MAIL: 3.7 (0%)0, SMTP pre-DATA-flush: 2.8 (0%)0, SMTP DATA: 60 (0%)0, check_init: 6 (0%)0, digest_hdr: 7 (0%)0, digest_body: 2.5 (0%)0, collect_info: 13 (0%)0, mime_decode: 45 (0%)1, get-file-type1: 47 (0%)1, decompose_part: 8 (0%)1, parts_decode: 0.1 (0%)1, check_header: 0.9 (0%)1, AV-scan-1: 27006 (99%)100, SMTP pre-response: 0.8 (0%)100, SMTP response: 0.8 (0%)100, rundown: 2.7 (0%)100 Nov 28 09:00:58 srv clamd[1437]: Database correctly reloaded (6532310 signatures) Nov 28 09:00:59 srv postfix/smtpd[23784]: disconnect from o20.sg.booking.com[167.89.96.75] Nov 28 09:01:02 srv amavis[22205]: (22205-17) ESMTP [127.0.0.1]:10024 /var/spool/amavisd/tmp/amavis-20171128T060024-22205-bbSE45Xz: bounces+4713178-dd3e-amanda=ourdomain.com.au@sg.booking.com → amanda@ourdomain.com.au Received: from srv.ourdomain.com.au ([127.0.0.1]) by localhost (srv.ourdomain.com.au [127.0.0.1]) (amavisd-new, port 10024) with ESMTP for amanda@ourdomain.com.au; Tue, 28 Nov 2017 09:01:02 +1000 (AEST) Nov 28 09:01:02 srv amavis[22205]: (22205-17) Checking: u55TmIxuWMs8 [167.89.96.8] bounces+4713178-dd3e-amanda=ourdomain.com.au@sg.booking.com → amanda@ourdomain.com.au Nov 28 09:01:02 srv amavis[22205]: (22205-17) p001 1 Content-Type: text/html, QP, size: 112709, SHA1 digest: a97ea89392b24f5220697c5f21380c14a0887d0a Nov 28 09:01:06 srv amavis[22205]: (22205-17) mangling NO: 0 (was: disclaimer), discl_allowed=0, bounces+4713178-dd3e-amanda=ourdomain.com.au@sg.booking.com → amanda@ourdomain.com.au Nov 28 09:01:06 srv amavis[22205]: (22205-17) spam-tag, bounces+4713178-dd3e-amanda=ourdomain.com.au@sg.booking.com → amanda@ourdomain.com.au, No, score=-4.543 tagged_above=-1000 required=3.8 tests=[BAYES_00=-1.9, DKIM_SIGNED=0.1, DKIM_VALID=-0.1, HTML_FONT_LOW_CONTRAST=0.001, HTML_IMAGE_RATIO_04=0.556, HTML_MESSAGE=0.001, LOCALPART_IN_SUBJECT=1.107, MIME_HTML_ONLY=0.723, RCVD_IN_MSPIKE_H3=-0.01, RCVD_IN_MSPIKE_WL=-0.01, RCVD_IN_RP_CERTIFIED=-3, RCVD_IN_RP_SAFE=-2, SPF_PASS=-0.001, T_RP_MATCHES_RCVD=-0.01] autolearn=ham autolearn_force=no Nov 28 09:01:06 srv postfix/smtpd[23794]: connect from localhost[127.0.0.1] Nov 28 09:01:06 srv postfix/smtpd[23794]: 6B5C92ABADF42: client=localhost[127.0.0.1], orig_client=o19.sg.booking.com[167.89.96.8] Nov 28 09:01:06 srv postfix/cleanup[23795]: 6B5C92ABADF42: message-id=8H1nEkcYRk6tZnEMQrbGoQ@ismtpd0006p1lon1.sendgrid.net Nov 28 09:01:06 srv postfix/smtpd[23794]: disconnect from localhost[127.0.0.1] Nov 28 09:01:06 srv postfix/qmgr[22562]: 6B5C92ABADF42: from=bounces+4713178-dd3e-amanda=ourdomain.com.au@sg.booking.com, size=123964, nrcpt=1 (queue active) Nov 28 09:01:06 srv amavis[22205]: (22205-17) u55TmIxuWMs8 FWD from bounces+4713178-dd3e-amanda=ourdomain.com.au@sg.booking.com → amanda@ourdomain.com.au, BODY=7BIT 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 6B5C92ABADF42 Nov 28 09:01:06 srv amavis[22205]: (22205-17) Passed CLEAN {RelayedInbound}, [167.89.96.8]:22911 [5.57.20.185] bounces+4713178-dd3e-amanda=ourdomain.com.au@sg.booking.com → amanda@ourdomain.com.au, Message-ID: 8H1nEkcYRk6tZnEMQrbGoQ@ismtpd0006p1lon1.sendgrid.net, mail_id: u55TmIxuWMs8, Hits: -4.543, size: 122998, queued_as: 6B5C92ABADF42, 3932 ms Nov 28 09:01:06 srv amavis[22205]: (22205-17) TIMING-SA total 3664 ms - parse: 11 (0.3%), extract_message_metadata: 108 (2.9%), get_uri_detail_list: 26 (0.7%), tests_pri_-1000: 10 (0.3%), tests_pri_-950: 1.54 (0.0%), tests_pri_-900: 3.7 (0.1%), tests_pri_-400: 83 (2.3%), check_bayes: 81 (2.2%), b_tokenize: 49 (1.3%), b_tok_get_all: 16 (0.5%), b_comp_prob: 11 (0.3%), b_tok_touch_all: 0.50 (0.0%), b_finish: 0.85 (0.0%), tests_pri_0: 3264 (89.1%), check_dkim_signature: 81 (2.2%), check_dkim_adsp: 122 (3.3%), check_spf: 379 (10.3%), poll_dns_idle: 316 (8.6%), check_razor2: 1181 (32.2%), check_pyzor: 0.34 (0.0%), tests_pri_500: 15 (0.4%), learn: 125 (3.4%), b_learn: 110 (3.0%), b_count_change: 43 (1.2%), get_report: 2.8 (0.1%) Nov 28 09:01:06 srv postfix/smtpd[23801]: proxy-accept: END-OF-MESSAGE: 250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 6B5C92ABADF42; from=bounces+4713178-dd3e-amanda=ourdomain.com.au@sg.booking.com to=amanda@ourdomain.com.au proto=ESMTP helo=<o19.sg.booking.com> Nov 28 09:01:06 srv amavis[22205]: (22205-17) size: 122998, TIMING [total 3934 ms] - SMTP greeting: 7 (0%)0, SMTP EHLO: 1.1 (0%)0, SMTP pre-MAIL: 0.7 (0%)0, SMTP MAIL: 3.1 (0%)0, SMTP pre-DATA-flush: 2.6 (0%)0, SMTP DATA: 3.2 (0%)0, check_init: 0.6 (0%)0, digest_hdr: 1.6 (0%)1, digest_body: 1.3 (0%)1, collect_info: 4.0 (0%)1, mime_decode: 26 (1%)1, get-file-type1: 44 (1%)2, decompose_part: 7 (0%)3, parts_decode: 0.1 (0%)3, check_header: 0.7 (0%)3, AV-scan-1: 122 (3%)6, spam-wb-list: 1.9 (0%)6, SA msg read: 1.2 (0%)6, SA parse: 13 (0%)6, SA check: 3647 (93%)99, decide_mail_destiny: 13 (0%)99, notif-quar: 1.0 (0%)99, fwd-connect: 7 (0%)99, fwd-xforward: 0.6 (0%)99, fwd-mail-pip: 1.9 (0%)99, fwd-rcpt-pip: 0.2 (0%)99, fwd-data-chkpnt: 0.0 (0%)99, write-header: 0.7 (0%)99, fwd-data-contents: 2.5 (0%)100, fwd-end-chkpnt: 8 (0%)100, prepare-dsn: 1.1 (0%)100, report: 2.2 (0%)100, main_log_entry: 6 (0%)100, SMTP pre-response: 0.3 (0%)100, SMTP response: 0.2 (0%)100, unlink-1-files: 0.4 (0%)100, rundown: 0… Nov 28 09:01:06 srv amavis[22205]: (22205-17) …6 (0%)100 Nov 28 09:01:06 srv postfix/lmtp[23820]: 6B5C92ABADF42: to=amanda@ourdomain.com.au, relay=mailx[192.168.60.3]:2003, delay=0.26, delays=0.01/0.02/0.02/0.21, dsn=2.1.5, status=sent (250 2.1.5 amanda@ourdomain.com.au Ok) Nov 28 09:01:06 srv postfix/qmgr[22562]: 6B5C92ABADF42: removed Nov 28 09:01:09 srv postfix/smtpd[23801]: disconnect from o19.sg.booking.com[167.89.96.8] Nov 28 09:01:18 srv postfix/smtpd[23788]: lost connection after CONNECT from o6.sg.booking.com[50.31.33.211] Nov 28 09:01:18 srv postfix/smtpd[23788]: disconnect from o6.sg.booking.com[50.31.33.211]

Those errors started showing up on Nov 28 09:00:58.
And I have few of those unsent emails on /var/spool/amavisd/tmp:

Some emails are still flowing in and out of the server, but some were not because of the error above

Is it an amavis timeout issue, is there a way I can increase the timeout?

Here’s the amavisd and clamav version we have installed.

Thank you

pagaille · December 4, 2017, 4:11pm

Hi,

I just noticed the same behaviour. This doesn’t happen all the time.

Following.

Matthieu

pagaille · December 4, 2017, 8:14pm

In my case it was related to the fact that clamd was reloading at that moment. It happened three time today : postfix tried to analyse a mail during the reload time. The mail traffic is very light. freshclam’s cron job is programmed to run every three hours.

Dec  4 17:51:02 cloud clamd: SelfCheck: Database modification detected. Forcing reload.                                                                                                                                                                                                 ┤
Dec  4 17:51:03 cloud clamd: Reading databases from /var/lib/clamav                                                                                                                                                                                                                     │
Dec  4 17:52:21 cloud clamd: Database correctly reloaded (6541471 signatures)

Could it be considered as a bug ?
Don’t know if it is something we could avoid (it’s seen from the outside !)
Disable postfix during the reload ?

Matthieu

filippo_carletti · December 4, 2017, 9:30pm

If the reload takes too much time, your system could be underpowered for clamav. Over the years, clamav recognizing millions of viruses has increased its needs for resources.
My NethServer takes 15 seconds to load 6541247 sigs.

Dec  4 08:55:18 nethservice clamd: Reading databases from /var/lib/clamav
Dec  4 08:55:33 nethservice clamd: Database correctly reloaded (6541247 signatures)

compsos1 · December 5, 2017, 12:16am

Hello Filippo/Matthieu,

The NethServer VM has 20GB of RAM and 700GB storage.

Below is the graph for the CPU and RAM.

May I please know your server specification. Should we increased the reserved RAM.
Thanks

pagaille · December 5, 2017, 10:23am

It is true than I run an old server (2007). I disabled clamd, I don’t really need it at this time.

How long does it take to reload clamd on your machine ? Your specs looks decent. Maybe that’s another issue.

compsos1 · December 6, 2017, 2:26am

Hi Matthieu,

May I please know how you disabled clamd.

I have clamd running but when I checked it as a service, it couldn’t find it.

Would it be ok to disable clamd for email filtering purposes?
It takes around 28 seconds to load 6542882 signatures.

You’re right, I received the “exceeded allowed time” on maillog when the clamd was reloading the database:

pagaille · December 7, 2017, 9:57am

I simply unchecked the “Antivirus” checkbox in Configuration > Email > Filter

Of course you’re not protected against the delivery of virus through email.

As a side note I believe that if clamd is likely to take 30 seconds to load even on robust server, that should be taken into account, @filippo_carletti. I would try to disable postfix during the time clamd is reloading, won’t you ?

Matthieu

compsos1 · December 8, 2017, 6:58am

How about changing the cron for clamav reading database to once a day?
I checked the cron jobs, but not sure if it’s the /etc/cron.d/clamav-update or the clamav-unofficial-sigs I should be modifying.

I was also reading this link https://www.howtoforge.com/tutorial/configure-clamav-to-scan-and-notify-virus-and-malware/ regarding the “Check for new database 24 times a day” but when I checked the /etc/clamav/freshclam.conf it doesn’t exists on NethServer.
Thanks

pagaille · December 10, 2017, 11:41am

Of course, but the problem stays the same : if a mail comes in at that moment it will be refused. It’ll only happen once a day

compsos1 · December 19, 2017, 6:59am

Hi Pagaille,

The exceeded allowed time issue seems to have stopped and last entry was on the 6th of December:

/var/log/maillog-20171210:Dec  6 12:53:01 srv amavis[29287]: (29287-01) (!)ClamAV-clamd av-scanner FAILED: run_av error: ask_daemon_internal: Exceeded allowed time at (eval 97) line 657.\n
/var/log/maillog-20171210:Dec  6 16:02:03 srv amavis[29142]: (29142-37) (!)ClamAV-clamd av-scanner FAILED: run_av error: ask_daemon_internal: Exceeded allowed time at (eval 97) line 657.\n
/var/log/maillog-20171210:Dec  6 17:01:46 srv amavis[30877]: (30877-04) (!)ClamAV-clamd av-scanner FAILED: run_av error: ask_daemon_internal: Exceeded allowed time at (eval 97) line 657.\n
/var/log/maillog-20171210:Dec  6 19:02:13 srv amavis[30877]: (30877-13) (!)ClamAV-clamd av-scanner FAILED: run_av error: ask_daemon_internal: Exceeded allowed time at (eval 97) line 657.\n

but I will keep observing.
Thank you very much for all of your help and time.

compsos1 · May 16, 2018, 7:06am

On /etc/cron.d/clamav-unofficial-sigs, I changed from every 45 minutes:

45 * * * * root /usr/bin/clamav-unofficial-sigs.sh &>/dev/null

to every 2am daily:
* 2 * * * root /usr/bin/clamav-unofficial-sigs.sh &>/dev/null

compsos1 · June 18, 2018, 4:45am

I also modified /etc/cron.d/clamav-update from running every 3 hours:

0 */3 * * * root /usr/share/clamav/freshclam-sleep

to run every 4am instead:

0 4 * * * root /usr/share/clamav/freshclam-sleep