Hi,
I have a little problem with my amavisd-new installation. I "inherited"
a linux system with postfix, amavis and spamassassin installed. However,
SA stopped working for some reason. Unfortunately, the server is a mess,
any meddling with it could cause it's entire collapse. I did make an
upgrade from SA 2.x to 3.1.7, and it is working when tested with
sa-learn -D, or called from procmail. However, when i want to use
amavisd-new to call it (the original setup), it just hangs there. Did
some debugging, and got this in the logs:
dec 14 14:41:22 zeusz amavisd-new[32190]: lookup_ip_acl: key="127.0.0.1"
matches "127.0.0.1", result=1
dec 14 14:41:22 zeusz amavisd-new[32190]: prolong_timer after new
request - timer reset: remaining time = 300 s
dec 14 14:41:22 zeusz amavisd-new[32190]: SMTP> 220 [127.0.0.1] ESMTP
amavisd-new service ready
dec 14 14:41:22 zeusz amavisd-new[32190]: prolong_timer after reading
SMTP command: remaining time = 300 s
dec 14 14:41:22 zeusz amavisd-new[32190]: SMTP< EHLO
zeusz.pannonvolan.hu\r\n
dec 14 14:41:22 zeusz amavisd-new[32190]: ESMTP> 250-[127.0.0.1]
dec 14 14:41:22 zeusz amavisd-new[32190]: ESMTP> 250-PIPELINING
dec 14 14:41:22 zeusz amavisd-new[32190]: ESMTP> 250-SIZE
dec 14 14:41:22 zeusz amavisd-new[32190]: ESMTP> 250-8BITMIME
dec 14 14:41:22 zeusz amavisd-new[32190]: ESMTP> 250 ENHANCEDSTATUSCODES
dec 14 14:41:22 zeusz amavisd-new[32190]: prolong_timer after reading
SMTP command: remaining time = 300 s
dec 14 14:41:22 zeusz amavisd-new[32190]: ESMTP< MAIL
FROM:<[EMAIL PROTECTED]> SIZE=1304\r\n
dec 14 14:41:22 zeusz amavisd-new[32190]: prolong_timer after MAIL FROM
received - timer reset: remaining time = 300 s
dec 14 14:41:22 zeusz amavisd-new[32190]: (32190-01) lookup_acl:
key="[EMAIL PROTECTED]", no match
dec 14 14:41:22 zeusz amavisd-new[32190]: (32190-01) ESMTP> 250 2.1.0
Sender [EMAIL PROTECTED] OK
dec 14 14:41:22 zeusz amavisd-new[32190]: (32190-01) prolong_timer after
reading SMTP command: remaining time = 300 s
dec 14 14:41:22 zeusz amavisd-new[32190]: (32190-01) ESMTP< RCPT
TO:<[EMAIL PROTECTED]>\r\n
dec 14 14:41:22 zeusz amavisd-new[32190]: (32190-01) ESMTP> 250 2.1.5
Recipient [EMAIL PROTECTED] OK
dec 14 14:41:22 zeusz amavisd-new[32190]: (32190-01) prolong_timer after
reading SMTP command: remaining time = 300 s
dec 14 14:41:22 zeusz amavisd-new[32190]: (32190-01) ESMTP< DATA\r\n
dec 14 14:41:22 zeusz amavisd-new[32190]: (32190-01) prolong_timer after
DATA received - timer reset: remaining time = 300 s
Dec 14 14:41:22 zeusz amavisd-new[32190]: (32190-01) ESMTP::10024
/var/lib/amavis/amavis-20061214T144122-32190:
<[EMAIL PROTECTED]> -> <[EMAIL PROTECTED]> Received:
SIZE=1304 from zeusz.pannonvolan.hu ([127.0.0.1]) by localhost (zeusz
[127.0.0.1]) (amavisd-new, port 10024) with ESMTP id 32190-01 for
<[EMAIL PROTECTED]>; Thu, 14 Dec 2006 14:41:22 +0100 (CET)
Dec 14 14:41:22 zeusz amavisd-new[32190]: (32190-01) ESMTP> 354 End data
with <CR><LF>.<CR><LF>
Dec 14 14:41:22 zeusz amavisd-new[32190]: (32190-01) ESMTP< .\r\n
Dec 14 14:41:22 zeusz amavisd-new[32190]: (32190-01) body hash:
668e4e0be6707b67e472409e3239c87c
Dec 14 14:41:22 zeusz amavisd-new[32190]: (32190-01) Original mail size:
1267; quota set to: 633500 bytes
Dec 14 14:41:22 zeusz amavisd-new[32190]: (32190-01) Checking:
<[EMAIL PROTECTED]> -> <[EMAIL PROTECTED]>
Dec 14 14:41:22 zeusz amavisd-new[32190]: (32190-01) lookup_acl:
key="[EMAIL PROTECTED]", no match
Dec 14 14:41:22 zeusz amavisd-new[32190]: (32190-01) lookup_acl:
key="[EMAIL PROTECTED]", no match
Dec 14 14:41:22 zeusz amavisd-new[32190]: (32190-01) Extracting mime
components
Dec 14 14:41:22 zeusz amavisd-new[32190]: (32190-01) Issued a new file
name: part-00001
Dec 14 14:41:22 zeusz amavisd-new[32190]: (32190-01) mime_decode:
Content-type: text/plain, name:
Dec 14 14:41:22 zeusz amavisd-new[32190]: (32190-01) Charging 239 bytes
to remaining quota 633500 (out of 633500, (0%)) - by mime_decode
Dec 14 14:41:22 zeusz amavisd-new[32190]: (32190-01) prolong_timer after
mime_decode-1: remaining time = 300 s
Dec 14 14:41:22 zeusz amavisd-new[32190]: (32190-01) Checking for banned
MIME types and names
Dec 14 14:41:22 zeusz amavisd-new[32190]: (32190-01) check_for_banned -
mime-type: text/plain
Dec 14 14:41:22 zeusz amavisd-new[32190]: (32190-01) lookup_RE:
key="text/plain", no match
Dec 14 14:41:22 zeusz amavisd-new[32190]: (32190-01) No anti-virus code
loaded, skipping this section
Dec 14 14:41:22 zeusz amavisd-new[32190]: (32190-01) white_black_list:
checking sender <[EMAIL PROTECTED]>
Dec 14 14:41:22 zeusz amavisd-new[32190]: (32190-01) lookup_hash:
key="[EMAIL PROTECTED]", no match
Dec 14 14:41:22 zeusz amavisd-new[32190]: (32190-01) lookup_hash:
key="tamas.gregorics@", no match
Dec 14 14:41:22 zeusz amavisd-new[32190]: (32190-01) lookup_hash:
key="mmcomputer.hu", no match
Dec 14 14:41:22 zeusz amavisd-new[32190]: (32190-01) lookup_hash:
key=".mmcomputer.hu", no match
Dec 14 14:41:22 zeusz amavisd-new[32190]: (32190-01) lookup_hash:
key=".hu", no match
Dec 14 14:41:22 zeusz amavisd-new[32190]: (32190-01) lookup_hash:
key=".", no match
Dec 14 14:41:22 zeusz amavisd-new[32190]: (32190-01) lookup_acl:
key="[EMAIL PROTECTED]", no match
Dec 14 14:41:22 zeusz amavisd-new[32190]: (32190-01) lookup_RE:
key="[EMAIL PROTECTED]", no match
Dec 14 14:41:22 zeusz amavisd-new[32190]: (32190-01) lookup_hash:
key="[EMAIL PROTECTED]", no match
Dec 14 14:41:22 zeusz amavisd-new[32190]: (32190-01) lookup_hash:
key="tamas.gregorics@", no match
Dec 14 14:41:22 zeusz amavisd-new[32190]: (32190-01) lookup_hash:
key="mmcomputer.hu", no match
Dec 14 14:41:22 zeusz amavisd-new[32190]: (32190-01) lookup_hash:
key=".mmcomputer.hu", no match
Dec 14 14:41:22 zeusz amavisd-new[32190]: (32190-01) lookup_hash:
key=".hu", no match
Dec 14 14:41:22 zeusz amavisd-new[32190]: (32190-01) lookup_hash:
key=".", no match
Dec 14 14:41:22 zeusz amavisd-new[32190]: (32190-01) lookup_acl:
key="[EMAIL PROTECTED]", no match
Dec 14 14:41:22 zeusz amavisd-new[32190]: (32190-01) lookup_acl:
key="[EMAIL PROTECTED]", no match
Dec 14 14:46:02 zeusz amavisd-new[32189]: (32189-01) SA TIMED OUT,
backtrace: at /usr/local/share/perl/5.8.4/Mail/SpamAssassin/Message.pm
line 130\n\teval {...} called at
/usr/local/share/perl/5.8.4/Mail/SpamAssassin/Message.pm line
130\n\tMail::SpamAssassin::Message::new('Mail::SpamAssassin::NoMailAudit')
called at /usr/share/perl5/Mail/SpamAssassin/NoMailAudit.pm line
34\n\tMail::SpamAssassin::NoMailAudit::new('Mail::SpamAssassin::NoMailAudit',
'data', 'ARRAY(0x93d4238)', 'add_From_line', 0) called at (eval 38) line
161\n\teval {...} called at (eval 38) line
149\n\tAmavis::SpamControl::spam_scan('Amavis::In::Connection=HASH(0x98479fc)',
'Amavis::In::Message=HASH(0x9d2bcbc)') called at /usr/sbin/amavisd-new
line 5369\n\teval {...} called at /usr/sbin/amavisd-new line
5151\n\tAmavis::check_mail('Amavis::In::Connection=HASH(0x98479fc)',
'Amavis::In::Message=HASH(0x9d2bcbc)', 0,
'/var/lib/amavis/amavis-20061214T144102-32189') called at (eval 37) line
3...
Dec 14 14:46:22 zeusz amavisd-new[32190]: (32190-01) SA TIMED OUT,
backtrace: at /usr/local/share/perl/5.8.4/Mail/SpamAssassin/Message.pm
line 130\n\teval {...} called at
/usr/local/share/perl/5.8.4/Mail/SpamAssassin/Message.pm line
130\n\tMail::SpamAssassin::Message::new('Mail::SpamAssassin::NoMailAudit')
called at /usr/share/perl5/Mail/SpamAssassin/NoMailAudit.pm line
34\n\tMail::SpamAssassin::NoMailAudit::new('Mail::SpamAssassin::NoMailAudit',
'data', 'ARRAY(0x93d4238)', 'add_From_line', 0) called at (eval 38) line
161\n\teval {...} called at (eval 38) line
149\n\tAmavis::SpamControl::spam_scan('Amavis::In::Connection=HASH(0x9847a20)',
'Amavis::In::Message=HASH(0x9d2bce0)') called at /usr/sbin/amavisd-new
line 5369\n\teval {...} called at /usr/sbin/amavisd-new line
5151\n\tAmavis::check_mail('Amavis::In::Connection=HASH(0x9847a20)',
'Amavis::In::Message=HASH(0x9d2bce0)', 0,
'/var/lib/amavis/amavis-20061214T144122-32190') called at (eval 37) line
3...
And thats all, it just hangs there after it, keeping the mails in
postfix queue. If i disable spam checking in amavisd.conf the mail gets
delivered to the mailboxes, but then of course, spam checking does not
occur.
Here is the content of mail.log (different message, but same setup)
Dec 14 10:22:12 zeusz postfix/smtpd[18654]: 268B5888661:
client=mmcomp.adsl.datanet.hu[195.56.52.140]
Dec 14 10:22:12 zeusz postfix/cleanup[18634]: 268B5888661:
message-id=<[EMAIL PROTECTED]>
Dec 14 10:22:12 zeusz postfix/qmgr[18602]: 268B5888661:
from=<[EMAIL PROTECTED]>, size=1309, nrcpt=1 (queue active)
Dec 14 10:29:55 zeusz postfix/qmgr[18602]: 268B5888661:
to=<[EMAIL PROTECTED]>, relay=none, delay=463, status=deferred
(connect to localhost[127.0.0.1]: Connection refused)
At this point, after hanging for a while i disabled spam checking in
amavisd:
Dec 14 10:46:43 zeusz postfix/qmgr[19376]: 268B5888661:
from=<[EMAIL PROTECTED]>, size=1309, nrcpt=1 (queue active)
Dec 14 10:46:49 zeusz postfix/smtp[19396]: 268B5888661:
to=<[EMAIL PROTECTED]>, relay=localhost[127.0.0.1], delay=1477,
status=sent (250 2.6.0 Ok, id=22142-08, from MTA: 250 Ok: queued as
63035888672)
My amavis installation is kind of old (amavisd-new-20030616-p7), but i'd
like to consider updating it as a last resort. Any ideas what could
possibly cause this error?
-------------------------------------------------------------------------
Take Surveys. Earn Cash. Influence the Future of IT
Join SourceForge.net's Techsay panel and you'll get the chance to share your
opinions on IT & business topics through brief surveys - and earn cash
http://www.techsay.com/default.php?page=join.php&p=sourceforge&CID=DEVDEV
_______________________________________________
AMaViS-user mailing list
AMaViS-user@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/amavis-user
AMaViS-FAQ:http://www.amavis.org/amavis-faq.php3
AMaViS-HowTos:http://www.amavis.org/howto/
