Hi,
I am running Postfix 2.2.9 + Amavis 3.10 with DSPAM 3.6.2 on Fedora FC5
(Zimbra 4.0.4 installation)
A few days ago email delivery started being delayed after a long time
with no problems. Things started getting worse and worse and finally the
postfix "active" queue was growing faster than mail was being delivered
creating many hours of delay.
Turning off spam filtering using @bypass_spam_checks_maps = (1); got
mail flowing again and cleared the over 4000 awaiting emails within 30
minutes...
Looking at the Amavis log files shows problems:
Sample 1:
Feb 9 05:29:22[12436]: (12436-01) lookup (local_domains) => true,
"[EMAIL PROTECTED]" matches, result="1", matching_key="."
Feb 9 05:31:23[12436]: (12436-01) spam_scan: from DSPAM: Received: from
web30113.mail.mud.yahoo.com (web30113.mail.mud.yahoo.com [209.191.69.45])\n
Almost 2 minutes between entries...
DSPAM is taking way too long to process.
How can I find out what exactly is causing this slowness?
Sample 2 (20 minutes...):
Feb 9 05:35:31[12426]: (12426-01-3) lookup_ldap_attr(amavislocal), no
attribute, "[EMAIL PROTECTED]" result=1
Feb 9 05:35:31[12426]: (12426-01-3) lookup (local_domains) => true,
"[EMAIL PROTECTED]" matches, result="1", matching_key="/cached/"
Feb 9 05:55:03[12426]: (12426-01-3) TROUBLE in check_mail: spam_scan
FAILED: timed out
Feb 9 05:55:03[12426]: (12426-01-3) prolong_timer check done: remaining
time = 0 s
Feb 9 05:55:03[12426]: (12426-01-3) sending SMTP response: "451 4.5.0
Error in processing, id=12426-01-3, spam_scan FAILED: timed out"
Feb 9 05:55:03[12426]: (12426-01-3) PRESERVING EVIDENCE in
/opt/zimbra/amavisd/tmp/amavis-20070209T053134-12426
Feb 9 05:55:03[12426]: (12426-01-3) TIMING [total 1172691 ms] -
lookup_ldap: 517 (0%)0, SMTP pre-DATA-flush: 2 (0%)0, SMTP DATA: 42
(0%)0, body_digest: 1 (0%)0, gen_mail_id: 1 (0%)0, mime_decode: 15
(0%)0, get-file-type2: 17 (0%)0, parts_decode: 1 (0%)0, AV-scan-1: 24
(0%)0, spam-wb-list: 6 (0%)0, rundown: 1172065 (100%)100
Feb 9 05:55:03[12426]: (12426-01-3) ESMTP> 451 4.5.0 Error in
processing, id=12426-01-3, spam_scan FAILED: timed out
Feb 9 05:55:03[12426]: (12426-01-3) switch_to_client_time 480 s, smtp
response sent
Feb 9 05:55:03[12426]: (12426-01-3) idle_proc, 6: was busy, 1172173.8
ms, total idle 1.089 s, busy 1408.663 s
Feb 9 05:55:04[12426]: (12426-01-3) idle_proc, 5: was idle, 823.7 ms,
total idle 1.913 s, busy 1408.663 s
Feb 9 05:55:04[12426]: (12426-01-3) ESMTP< RSET\r\n
Feb 9 05:55:04[12426]: (12426-01-3) switch_to_my_time 480 s, SMTP RSET
received
Feb 9 05:55:04[12426]: (12426-01-3) ESMTP> 250 2.0.0 Ok RSET
Feb 9 05:55:04[12426]: (12426-01-3) switch_to_client_time 480 s, smtp
response sent
Feb 9 05:55:04[12426]: (12426-01-3) idle_proc, 6: was busy, 1.1 ms,
total idle 1.913 s, busy 1408.664 s
Feb 9 05:55:04[12426]: (12426-01-3) idle_proc, 5: was idle, 0.2 ms,
total idle 1.913 s, busy 1408.664 s
Feb 9 05:55:04[12426]: (12426-01-3) ESMTP< XFORWARD
NAME=out010.topica-platinum-y.com ADDR=66.227.60.30\r\n
Feb 9 05:55:04[12426]: (12426-01-3) switch_to_my_time 480 s, SMTP
XFORWARD received
Feb 9 05:55:04[12426]: (12426-01-3) ESMTP> 250 2.5.0 Ok XFORWARD
Feb 9 05:55:04[12426]: (12426-01-3) switch_to_client_time 480 s, smtp
response sent
Feb 9 05:55:04[12426]: (12426-01-3) idle_proc, 6: was busy, 0.8 ms,
total idle 1.913 s, busy 1408.664 s
Feb 9 05:55:04[12426]: (12426-01-3) idle_proc, 5: was idle, 0.1 ms,
total idle 1.913 s, busy 1408.664 s
Feb 9 05:55:04[12426]: (12426-01-3) ESMTP< XFORWARD PROTO=SMTP
HELO=out010.topica-platinum-y.com\r\n
Feb 9 05:55:04[12426]: (12426-01-3) switch_to_my_time 480 s, SMTP
XFORWARD received
Feb 9 05:55:04[12426]: (12426-01-3) ESMTP> 250 2.5.0 Ok XFORWARD
Feb 9 05:55:04[12426]: (12426-01-3) switch_to_client_time 480 s, smtp
response sent
Feb 9 05:55:04[12426]: (12426-01-3) idle_proc, 6: was busy, 11.3 ms,
total idle 1.913 s, busy 1408.676 s
Feb 9 05:55:04[12426]: (12426-01-3) idle_proc, 5: was idle, 0.2 ms,
total idle 1.913 s, busy 1408.676 s
Feb 9 05:55:04[12426]: (12426-01-3) ESMTP< MAIL
FROM:<[EMAIL PROTECTED]>
SIZE=17818\r\n
A few more log file lines show that DSPAM is actully the cause:
Feb 9 05:30:40[12418]: (12418-01) TIMING [total 81609 ms] -
ldap-prepare: 4 (0%)0, SMTP EHLO: 4 (0%)0, SMTP pre-MAIL: 4 (0%)0, mkdir
tempdir: 1 (0%)0, create email.txt: 0 (0%)0, ldap-connect: 9 (0%)0,
lookup_ldap: 37 (0%)0, SMTP pre-DATA-flush: 3 (0%)0, SMTP DATA: 44
(0%)0, body_digest: 2 (0%)0, gen_mail_id: 1 (0%)0, mkdir parts: 0 (0%)0,
mime_decode: 25 (0%)0, get-file-type3: 19 (0%)0, decompose_part: 2
(0%)0, parts_decode: 0 (0%)0, AV-scan-1: 37 (0%)0, spam-wb-list: 6
(0%)0, *DSPAM: 73202 (90%)*90, SA msg read: 1 (0%)90, SA parse: 3
(0%)90, SA check: 7861 (10%)100, SA finish: 4 (0%)100, DSPAM learn: 0
(0%)100, update_cache: 2 (0%)100, decide_mail_destiny: 3 (0%)100,
fwd-connect: 48 (0%)100, fwd-mail-from: 3 (0%)100, fwd-rcpt-to: 3
(0%)100, fwd-data-cmd: 1 (0%)100, write-header: 1 (0%)100,
fwd-data-contents: 2 (0%)100, fwd-data-end: 263 (0%)100, fwd-rundown: 2
(0%)100, prepare-dsn: 2 (0%)100, main_log_entry: 11 (0%)100,
update_snmp: 1 (0%)100, unlink-3-files: 2 (0%)100, rundown: 0 (0%)100
Feb 9 05:30:43[12427]: (12427-01) TIMING [total 77631 ms] -
ldap-prepare: 4 (0%)0, SMTP EHLO: 4 (0%)0, SMTP pre-MAIL: 10 (0%)0,
mkdir tempdir: 1 (0%)0, create email.txt: 1 (0%)0, ldap-connect: 12
(0%)0, lookup_ldap: 83 (0%)0, SMTP pre-DATA-flush: 3 (0%)0, SMTP DATA:
39 (0%)0, body_digest: 2 (0%)0, gen_mail_id: 1 (0%)0, mkdir parts: 0
(0%)0, mime_decode: 27 (0%)0, get-file-type3: 20 (0%)0, decompose_part:
1 (0%)0, parts_decode: 0 (0%)0, AV-scan-1: 24 (0%)0, spam-wb-list: 6
(0%)0, *DSPAM: 73336 (94%)*95, SA msg read: 123 (0%)95, SA parse: 3
(0%)95, SA check: 3903 (5%)100, SA finish: 3 (0%)100, DSPAM learn: 0
(0%)100, update_cache: 2 (0%)100, decide_mail_destiny: 4 (0%)100,
prepare-dsn: 7 (0%)100, main_log_entry: 9 (0%)100, update_snmp: 1
(0%)100, unlink-3-files: 2 (0%)100, rundown: 0 (0%)100
Feb 9 05:30:49[12435]: (12435-01) TIMING [total 83575 ms] -
ldap-prepare: 4 (0%)0, SMTP EHLO: 6 (0%)0, SMTP pre-MAIL: 6 (0%)0, mkdir
tempdir: 1 (0%)0, create email.txt: 1 (0%)0, ldap-connect: 11 (0%)0,
lookup_ldap: 118 (0%)0, SMTP pre-DATA-flush: 3 (0%)0, SMTP DATA: 1
(0%)0, body_digest: 2 (0%)0, gen_mail_id: 1 (0%)0, mkdir parts: 0 (0%)0,
mime_decode: 11 (0%)0, get-file-type1: 15 (0%)0, parts_decode: 1 (0%)0,
AV-scan-1: 12 (0%)0, spam-wb-list: 6 (0%)0, *DSPAM: 77584 (93%)93*, SA
msg read: 29 (0%)93, SA parse: 4 (0%)93, SA check: 5730 (7%)100, SA
finish: 3 (0%)100, DSPAM learn: 0 (0%)100, update_cache: 2 (0%)100,
decide_mail_destiny: 4 (0%)100, prepare-dsn: 7 (0%)100, main_log_entry:
9 (0%)100, update_snmp: 1 (0%)100, unlink-1-files: 1 (0%)100, rundown: 0
(0%)100
Any ideas?
Thanks, Eric
