Amavis-new on the fritz... not sure what to do next

Hi all,

I hope one of you can help me, because this is driving me crazy! I have a SLES 10 SP2 box that uses a fairly standard Postfix + Cyrus IMAP + Amavis-new + SpamAssassin + ClamAV setup.

Yes, I’ve posted on the Novell forums, but no replies yet. My bet is that SLES and openSUSE are similar enough that the fix is similar enough.

The other day my mail server lost it’s marbles when I added a whitelisting in my /etc/mail/spamassassin/local.cf. Mail would gather in the Postfix queue, but would hang up when they passed through Amavis. As such, users were not receiving mail.

I had to take Amavis out of the picture (commenting lines in Postfix main.cf, master.cf) temporarily so that my co-workers could get email. I flushed the postfix queue and things were working fine - without anti-virus and anti-spam of course.

But checking Postfix queue while Amavis is in place, the undeliverable messages look like this:

1F6D8158B12 860 Mon Jan 12 21:26:41 user@domain.com
(host 127.0.0.1[127.0.0.1] said: 451 4.5.0 Error in processing, id=05537-02-4, parts_decode_ext FAILED: parsing file(1) results - missing last 1 results at (eval 64) line 154. (in reply to end of DATA command))
postmaster@domain.com

One problem I realized I had is that my perl Net::Server module had been updated somehow. I know versions newer than what came with SLES 10 don’t jive with Amavis. I had to reinstall the module from the rpm on the SLES CD. Unfortunately, while it fixed a separate problem, that didn’t fix the main problem.

I ran Amavis in debug mode and from what I gathered, SpamAssassin was loading correctly. I saw no errors until Amavis actually received email from Postfix. That’s when it would trip up.

I actually don’t think the problem is actually spamassassin. I think my changes were simply coincidental. Amavis had been running for months without a restart. When I updated my SA local.cf, I restarted amavis… so if I had a bad perl module or config problem, that restart would have activated it.

Any help would be appreciated. Any thoughts?

Well SLES lags OpenSUSE by a bit so SLES 10 is closest to SUSE 9.something, enterprise-fied. But the Net::Server problem you mentioned is not confined to SUSE. If you do a search on some of the terms, you will find bug reports like these:

https://bugzilla.redhat.com/show_bug.cgi?id=189888

It seems the solution is either to downgrade Net::Server or upgrade amavis-new. So you say you restored Net::Server so that should be fixed, but you say you haven’t fixed the main problem (I take it this is the mail not going through amavis, but I didn’t see it labelled as “main problem” in your story), but you haven’t posted any symptoms of the main problem. You need to gather some more evidence. Where is the mail getting stuck? Is postfix trying to contact amavisd? Are there any error messages in /var/log/mail? Is the queue getting longer? Is amavisd providing a Unix socket or a port for postfix to talk to? Is amavisd indeed running. And so forth.

Break it down and solve the problem by testing each part of the pipeline. Use tools like netstat, lsof, ps, and so forth.

Well I’m not quite sure how to go about this. I will tell you what I know.


I start amavisd-new in debug mode and this is what I get:


Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: starting.  /usr/sbin/amavisd at mail.domain.com amavisd-new-2.3.3 (20050822), Unicode aware, LANG=en_US.UTF-8
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: user=, EUID: 0 (0);  group=, EGID: 0 1006 3 0 (0 1006 3 0)
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Perl version               5.008008
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: INFO: no optional modules: Sys::Hostname::Long Mail::SPF::Query Razor2::Client::Agent Net::CIDR::Lite Mail::SpamAssassin::Plugin::DomainKeys Mail::DomainKeys::Header Mail::DomainKeys::Message Mail::DomainKeys::Policy Mail::DomainKeys::Signature Mail::DomainKeys::Key Mail::DomainKeys::Key::Public Crypt::OpenSSL::RSA auto::Crypt::OpenSSL::RSA::_new auto::Crypt::OpenSSL::RSA::DESTROY auto::Crypt::OpenSSL::RSA::load_public_key auto::Crypt::OpenSSL::RSA::new_public_key IP::Country::Fast
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Net::Server: 2009/01/14-10:06:06 Amavis (type Net::Server::PreForkSimple) starting! pid(6317)
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Net::Server: Binding to UNIX socket file /var/spool/amavis/amavisd.sock using SOCK_STREAM
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Net::Server: Binding to TCP port 10024 on host 127.0.0.1
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Net::Server: Setting gid to "106 106"
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Net::Server: Setting uid to "65"
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Net::Server: Setting up serialization via flock
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Module Amavis::Conf        2.043
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Module Archive::Tar        1.24
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Module Archive::Zip        1.16
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Module BerkeleyDB          0.26
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Module Compress::Zlib      1.35
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Module Convert::TNEF       0.17
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Module Convert::UUlib      1.051
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Module DBD::mysql          3.0002
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Module DBI                 1.50
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Module DB_File             1.814
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Module MIME::Entity        5.427
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Module MIME::Parser        5.427
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Module MIME::Tools         5.427
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Module Mail::Header        1.67
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Module Mail::Internet      1.67
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Module Mail::SpamAssassin  3.002004
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Module Net::Cmd            2.26
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Module Net::DNS            0.55
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Module Net::SMTP           2.29
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Module Net::Server         0.97
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Module Time::HiRes         1.9715
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Module Unix::Syslog        0.100
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Amavis::DB code    loaded
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Amavis::Cache code loaded
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: SQL base code      NOT loaded
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: SQL::Log code      NOT loaded
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: SQL::Quarantine    NOT loaded
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Lookup::SQL  code  NOT loaded
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Lookup::LDAP code  NOT loaded
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: AM.PDP prot  code  loaded
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: SMTP-in prot code  loaded
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: ANTI-VIRUS code    loaded
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: ANTI-SPAM  code    loaded
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Unpackers  code    loaded
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Found $file            at /usr/bin/file
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: No $dspam,             not using it
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Internal decoder for .mail
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Internal decoder for .asc
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Internal decoder for .uue
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Internal decoder for .hqx
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Internal decoder for .ync
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: No decoder for       .F    tried: unfreeze, freeze -d, melt, fcat
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Found decoder for    .Z    at /usr/bin/uncompress
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Internal decoder for .gz
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Found decoder for    .gz   at /usr/bin/gzip -d (backup, not used)
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Found decoder for    .bz2  at /usr/bin/bzip2 -d
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: No decoder for       .lzo  tried: lzop -d
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Found decoder for    .rpm  at /usr/bin/rpm2cpio
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Found decoder for    .cpio at /usr/bin/pax
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Found decoder for    .tar  at /usr/bin/pax
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Internal decoder for .tar  (backup, not used)
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Found decoder for    .deb  at /usr/bin/ar
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Internal decoder for .zip
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Found decoder for    .rar  at /usr/bin/unrar
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Found decoder for    .arj  at /usr/bin/unarj
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: No decoder for       .arc  tried: nomarch, arc
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Found decoder for    .zoo  at /usr/bin/zoo
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Found decoder for    .lha  at /usr/bin/lha
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Found decoder for    .cab  at /usr/bin/cabextract
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: No decoder for       .tnef tried: tnef
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Internal decoder for .tnef
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd: Found decoder for    .exe  at /usr/bin/unrar; /usr/bin/lha; /usr/bin/unarj

(I have to break up my replies… too large)

… and this (again, all during amavisd initialization)


Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd[6317]: Using internal av scanner code for (primary) ClamAV-clamd
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd[6317]: No primary av scanner: KasperskyLab AVP - aveclient
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd[6317]: No primary av scanner: KasperskyLab AntiViral Toolkit Pro (AVP)
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd[6317]: No primary av scanner: KasperskyLab AVPDaemonClient
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd[6317]: No primary av scanner: CentralCommand Vexira (new) vascan
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd[6317]: No primary av scanner: H+BEDV AntiVir or the (old) CentralCommand Vexira Antivirus
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd[6317]: No primary av scanner: Command AntiVirus for Linux
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd[6317]: No primary av scanner: Symantec CarrierScan via Symantec CommandLineScanner
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd[6317]: No primary av scanner: Symantec AntiVirus Scan Engine
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd[6317]: No primary av scanner: F-Secure Antivirus
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd[6317]: No primary av scanner: CAI InoculateIT
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd[6317]: No primary av scanner: CAI eTrust Antivirus
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd[6317]: No primary av scanner: MkS_Vir for Linux (beta)
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd[6317]: No primary av scanner: MkS_Vir daemon
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd[6317]: No primary av scanner: ESET Software NOD32
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd[6317]: No primary av scanner: ESET Software NOD32 - Client/Server Version
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd[6317]: No primary av scanner: Norman Virus Control v5 / Linux
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd[6317]: No primary av scanner: Panda Antivirus for Linux
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd[6317]: No primary av scanner: NAI McAfee AntiVirus (uvscan)
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd[6317]: No primary av scanner: VirusBuster
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd[6317]: No primary av scanner: CyberSoft VFind
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd[6317]: No primary av scanner: Ikarus AntiVirus for Linux
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd[6317]: No primary av scanner: BitDefender
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd[6317]: Found secondary av scanner ClamAV-clamscan at /usr/bin/clamscan
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd[6317]: No secondary av scanner: FRISK F-Prot Antivirus
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd[6317]: No secondary av scanner: Trend Micro FileScanner
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd[6317]: No secondary av scanner: drweb - DrWeb Antivirus
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd[6317]: No secondary av scanner: KasperskyLab kavscanner
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd[6317]: Creating db in /var/spool/amavis/db/; BerkeleyDB 0.26, libdb 4.3
Jan 14 10:06:06 mail.domain.com /usr/sbin/amavisd[6317]: SpamControl: initializing Mail::SpamAssassin
Jan 14 10:06:07 mail.domain.com /usr/sbin/amavisd[6317]: SpamControl: done
Jan 14 10:06:07 mail.domain.com /usr/sbin/amavisd[6317]: Net::Server: Beginning prefork (2 processes)
Jan 14 10:06:07 mail.domain.com /usr/sbin/amavisd[6317]: Net::Server: Starting "2" children
Jan 14 10:06:07 mail.domain.com /usr/sbin/amavisd[6319]: Net::Server: Child Preforked (6319)
Jan 14 10:06:07 mail.domain.com /usr/sbin/amavisd[6319]: TIMING [total 8 ms] - bdb-open: 8 (100%)100, rundown: 0 (0%)100
Jan 14 10:06:07 mail.domain.com /usr/sbin/amavisd[6317]: Net::Server: Parent ready for children.
Jan 14 10:06:07 mail.domain.com /usr/sbin/amavisd[6320]: Net::Server: Child Preforked (6320)
Jan 14 10:06:07 mail.domain.com /usr/sbin/amavisd[6320]: TIMING [total 6 ms] - bdb-open: 6 (100%)100, rundown: 0 (0%)100

And…


Then, once my system starts to receive email, they begin to collect in Postfix’s queue, as they are “undeliverable” so long as Amavis is enabled.


The command postqueue -p shows:
E0D36158B2C     5595 Wed Jan 14 14:08:59  somedude@email.com
(host 127.0.0.1[127.0.0.1] said: 451 4.5.0 Error in processing, id=06320-01, parts_decode_ext FAILED: parsing file(1) results - missing last 1 results at (eval 64) line 154. (in reply to end of DATA command))
                                         user@domain.com


I checked /var/log/mail.info for the same message (same id) and it shows:


Jan 14 14:09:00 fs2 postfix/smtp[12480]: DEEAF158B2A: to=<user@domain.com>, relay=127.0.0.1[127.0.0.1], delay=1, status=deferred (host 127.0.0.1[127.0.0.1] said: 451 4.5.0 Error in processing, id=06319-01, parts_decode_ext FAILED: parsing file(1) results - missing last 1 results at (eval 64) line 154. (in reply to end of DATA command))


I then get a bunch of stuff (on the amavis debug screen) like this:


Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-01) Net::Server: 2009/01/14-14:35:55 CONNECT TCP Peer: "127.0.0.1:58840" Local: "127.0.0.1:10024"
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-01) idle_proc, hi : was idle, 21537.0 ms, total idle 21.538 s, busy 0.081 s
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-01) loaded base policy bank
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-01) lookup_ip_acl (inet_acl): key="127.0.0.1" matches "127.0.0.1", result=1
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-01) prolong_timer after new request - timer reset: remaining time = 480 s
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-01) process_request: suggested_protocol="" on TCP
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) SMTP> 220 [127.0.0.1] ESMTP amavisd-new service ready
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) idle_proc, 4: was busy, 2.2 ms, total idle 21.538 s, busy 0.083 s
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) idle_proc, 5: was idle, 0.2 ms, total idle 21.539 s, busy 0.083 s
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) prolong_timer after reading SMTP command: remaining time = 480 s
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) SMTP< EHLO domain.com

Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) ESMTP> 250-[127.0.0.1]
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) ESMTP> 250-PIPELINING
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) ESMTP> 250-SIZE
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) ESMTP> 250-8BITMIME
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) ESMTP> 250-ENHANCEDSTATUSCODES
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) ESMTP> 250 XFORWARD NAME ADDR PROTO HELO
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) idle_proc, 6: was busy, 1.2 ms, total idle 21.539 s, busy 0.084 s
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) idle_proc, 5: was idle, 0.2 ms, total idle 21.539 s, busy 0.084 s
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) prolong_timer after reading SMTP command: remaining time = 480 s
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) ESMTP< XFORWARD NAME=spgate01.vocus.com ADDR=66.77.65.139

Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) ESMTP> 250 2.5.0 Ok XFORWARD
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) idle_proc, 6: was busy, 0.7 ms, total idle 21.539 s, busy 0.085 s
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) idle_proc, 5: was idle, 0.1 ms, total idle 21.539 s, busy 0.085 s
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) prolong_timer after reading SMTP command: remaining time = 480 s
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) ESMTP< XFORWARD PROTO=ESMTP HELO=spgate01.vocus.com

Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) ESMTP> 250 2.5.0 Ok XFORWARD
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) idle_proc, 6: was busy, 0.6 ms, total idle 21.539 s, busy 0.086 s
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) idle_proc, 5: was idle, 0.1 ms, total idle 21.539 s, busy 0.086 s
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) prolong_timer after reading SMTP command: remaining time = 480 s
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) ESMTP< MAIL FROM:<PR.519537.1376545@prnews2.com> SIZE=3220 BODY=8BITMIME

Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) prolong_timer after MAIL FROM received - timer reset: remaining time = 480 s
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) check_mail_begin_task: task_count=2
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) prepare_tempdir: creating directory /var/spool/amavis/tmp/amavis-20090114T143555-16756
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) prepare_tempdir: creating file /var/spool/amavis/tmp/amavis-20090114T143555-16756/email.txt
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) lookup (debug_sender) => undef, "PR.519537.1376545@prnews2.com" does not match
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) ESMTP> 250 2.1.0 Sender PR.519537.1376545@prnews2.com OK
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) idle_proc, 6: was busy, 2.3 ms, total idle 21.539 s, busy 0.088 s
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) idle_proc, 5: was idle, 0.1 ms, total idle 21.539 s, busy 0.088 s
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) prolong_timer after reading SMTP command: remaining time = 480 s
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) ESMTP< RCPT TO:<user@domain2.com>

Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) ESMTP> 250 2.1.5 Recipient user@domain2.com OK
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) idle_proc, 6: was busy, 0.7 ms, total idle 21.539 s, busy 0.089 s
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) idle_proc, 5: was idle, 0.1 ms, total idle 21.539 s, busy 0.089 s
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) prolong_timer after reading SMTP command: remaining time = 480 s
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) ESMTP< RCPT TO:<archives@domain.com>

Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) ESMTP> 250 2.1.5 Recipient archives@domain.com OK
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) idle_proc, 6: was busy, 0.6 ms, total idle 21.539 s, busy 0.089 s
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) idle_proc, 5: was idle, 0.1 ms, total idle 21.539 s, busy 0.089 s
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) prolong_timer after reading SMTP command: remaining time = 480 s
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) ESMTP< DATA

Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) prolong_timer after DATA received - timer reset: remaining time = 480 s
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) ESMTP::10024 /var/spool/amavis/tmp/amavis-20090114T143555-16756: <PR.519537.1376545@prnews2.com> -> <user@domain2.com>,<archives@domain.com> Received: SIZE=3220 BODY=8BITMIME from domain.com ([127.0.0.1]) by localhost (mail.domain.com [127.0.0.1]) (amavisd-new, port 10024) with ESMTP id 16756-02; Wed, 14 Jan 2009 14:35:55 -0700 (MST)
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) ESMTP> 354 End data with <CR><LF>.<CR><LF>
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) ESMTP< .

Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) Actual message size 3219 B, declared 3220 B
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) body hash: 5931e14633c689b78fa81b0787df4549
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) Original mail size: 3219; quota set to: 1609500 bytes
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) Checking: f+4PktxeMm+L [66.77.65.139] <PR.519537.1376545@prnews2.com> -> <user@domain2.com>,<archives@domain.com>

And…


Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) query_keys: user@domain2.com, user@, domain2.com, .domain2.com, .com, .
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) lookup_hash(user@domain2.com), no matches
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) lookup (bypass_virus_checks) => undef, "user@domain2.com" does not match
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) query_keys: archives@domain.com, archives@, domain.com, .domain.com, .com, .
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) lookup_hash(archives@domain.com), no matches
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) lookup (bypass_virus_checks) => undef, "archives@domain.com" does not match
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) Extracting mime components
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) Issued a new file name: p001
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) Charging 2070 bytes to remaining quota 1609500 (out of 1609500, (0%)) - by mime_decode
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) p001 1 Content-Type: text/plain, size: 2070 B, name:
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) prolong_timer after mime_decode-1: remaining time = 480 s
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) decode_parts: level=1, #parts=1 : p001
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) run_command: [17145] /usr/bin/file p001 </dev/null 2>&1
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[17145]: (16756-02) run_command: child process [17145]: Error closing main::stdin: Bad file descriptor at /usr/sbin/amavisd line 1872.

Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) TROUBLE in check_mail: parts_decode_ext FAILED: parsing file(1) results - missing last 1 results at (eval 64) line 154.
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) sending SMTP response: "451 4.5.0 Error in processing, id=16756-02, parts_decode_ext FAILED: parsing file(1) results - missing last 1 results at (eval 64) line 154."
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) timer stopped after DATA end
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) PRESERVING EVIDENCE in /var/spool/amavis/tmp/amavis-20090114T143555-16756
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) TIMING [total 70 ms] - SMTP EHLO: 3 (4%)4, SMTP pre-MAIL: 3 (4%)8, mkdir tempdir: 1 (1%)9, create email.txt: 0 (1%)10, SMTP pre-DATA-flush: 4 (5%)15, SMTP DATA: 36 (52%)67, body_digest: 1 (1%)68, gen_mail_id: 0 (1%)69, mkdir parts: 0 (0%)70, mime_decode: 8 (12%)81, rundown: 13 (19%)100
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) ESMTP> 451 4.5.0 Error in processing, id=16756-02, parts_decode_ext FAILED: parsing file(1) results - missing last 1 results at (eval 64) line 154.
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) idle_proc, 6: was busy, 61.3 ms, total idle 21.539 s, busy 0.150 s
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) idle_proc, 5: was idle, 0.2 ms, total idle 21.540 s, busy 0.150 s
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) prolong_timer after reading SMTP command: remaining time = 0 s
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) ESMTP< QUIT

Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) ESMTP> 221 2.0.0 [127.0.0.1] amavisd-new closing transmission channel
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) extra modules loaded: Mail/SpamAssassin/Locales.pm, Mail/SpamAssassin/Plugin/Bayes.pm, Mail/SpamAssassin/Plugin/BodyEval.pm, Mail/SpamAssassin/Plugin/Check.pm, Mail/SpamAssassin/Plugin/DNSEval.pm, Mail/SpamAssassin/Plugin/HTMLEval.pm, Mail/SpamAssassin/Plugin/HTTPSMismatch.pm, Mail/SpamAssassin/Plugin/HeaderEval.pm, Mail/SpamAssassin/Plugin/ImageInfo.pm, Mail/SpamAssassin/Plugin/MIMEEval.pm, Mail/SpamAssassin/Plugin/RelayEval.pm, Mail/SpamAssassin/Plugin/URIDetail.pm, Mail/SpamAssassin/Plugin/URIEval.pm, Mail/SpamAssassin/Plugin/VBounce.pm, Mail/SpamAssassin/Plugin/WLBLEval.pm
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) post_process_request_hook: timer stopped
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) idle_proc, bye: was busy, 2.2 ms, total idle 21.540 s, busy 0.153 s
Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) load: 1 %, total idle 21.540 s, busy 0.153 s


I see a lot of this:


Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[17145]: (16756-02) run_command: child process [17145]: Error closing main::stdin: Bad file descriptor at /usr/sbin/amavisd line 1872.


And I see a lot of this:


Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) TROUBLE in check_mail: parts_decode_ext FAILED: parsing file(1) results - missing last 1 results at (eval 64) line 154.

Jan 14 14:35:55 mail.domain.com /usr/sbin/amavisd[16756]: (16756-02) sending SMTP response: "451 4.5.0 Error in processing, id=16756-02, parts_decode_ext FAILED: parsing file(1) results - missing last 1 results at (eval 64) line 154."


I’ve also run a chkdsk which found nothing wrong with the filesystem (ext3).

Amavis runs under the vscan user and vscan group, both of which have ownership on /var/spool/amavis.

I’m just not sure where to go from here…

That sounds like what other people have described about the Net::Server update breaking amavisd. So it looks like you haven’t really fixed that problem.

Okay, I finally got it fixed. What a mess!

Anyway, I wanted to note what had happened, in case anyone else has this problem in the future.

The perl module Net::Server was in fact version 0.97, which doesn’t jive with my version of amavisd-new. The version that comes with SLES is 0.90. I think CPAN did some automatic updates when I was using it a few weeks before.

Anyhow, I realized that there are two copies of the perl modules on the filesystem.

/usr/lib/perl5/site_perl/5.8.8/Net

  • and -
    /usr/lib/perl5/site_perl/5.8.8/Net

The RPM simply installs to the vender_perl location.

So, after reinstalling the rpm from the SLES CDs, I removed the Server module in site_perl (i.e. ‘rm -rf /usr/lib/perl5/site_perl/5.8.8/Net/Server*’) and then copied the ones from vender_perl over (i.e. ‘cp -av /usr/lib/perl5/site_perl/5.8.8/Net/Server* /usr/lib/perl5/site_perl/5.8.8/Net’).

Things appear to be working now that the right module is in place.

Woohoo!