gpdmz:/var/log # amavisd debug Feb 22 19:12:01 gpdmz amavisd[13338]: starting. amavisd at gpdmz amavisd-new-20030616-p5, Unicode aware Feb 22 19:12:01 gpdmz amavisd[13338]: Perl version 5.008001 Feb 22 19:12:01 gpdmz amavisd[13338]: Module Amavis::Conf 1.15 Feb 22 19:12:01 gpdmz amavisd[13338]: Module Archive::Tar 0.23 Feb 22 19:12:01 gpdmz amavisd[13338]: Module Archive::Zip 1.05 Feb 22 19:12:01 gpdmz amavisd[13338]: Module Compress::Zlib 1.16 Feb 22 19:12:01 gpdmz amavisd[13338]: Module Convert::TNEF 0.17 Feb 22 19:12:01 gpdmz amavisd[13338]: Module Convert::UUlib 0.31 Feb 22 19:12:01 gpdmz amavisd[13338]: Module MIME::Entity 5.404 Feb 22 19:12:01 gpdmz amavisd[13338]: Module MIME::Parser 5.406 Feb 22 19:12:01 gpdmz amavisd[13338]: Module MIME::Tools 5.411 Feb 22 19:12:01 gpdmz amavisd[13338]: Module Mail::Header 1.58 Feb 22 19:12:01 gpdmz amavisd[13338]: Module Mail::Internet 1.58 Feb 22 19:12:01 gpdmz amavisd[13338]: Module Mail::SpamAssassin 2.55 Feb 22 19:12:01 gpdmz amavisd[13338]: Module Net::Cmd 2.24 Feb 22 19:12:01 gpdmz amavisd[13338]: Module Net::DNS 0.38 Feb 22 19:12:01 gpdmz amavisd[13338]: Module Net::SMTP 2.26 Feb 22 19:12:01 gpdmz amavisd[13338]: Module Net::Server 0.85 Feb 22 19:12:01 gpdmz amavisd[13338]: Module Time::HiRes 1.51 Feb 22 19:12:01 gpdmz amavisd[13338]: Module Unix::Syslog 0.98 Feb 22 19:12:01 gpdmz amavisd[13338]: Found myself: /usr/sbin/amavisd -c /etc/amavisd.conf Feb 22 19:12:01 gpdmz amavisd[13338]: Lookup::SQL code NOT loaded Feb 22 19:12:01 gpdmz amavisd[13338]: Lookup::LDAP code NOT loaded Feb 22 19:12:01 gpdmz amavisd[13338]: AMCL-in protocol code loaded Feb 22 19:12:01 gpdmz amavisd[13338]: SMTP-in protocol code loaded Feb 22 19:12:01 gpdmz amavisd[13338]: ANTI-VIRUS code loaded Feb 22 19:12:01 gpdmz amavisd[13338]: ANTI-SPAM code loaded Feb 22 19:12:01 gpdmz amavisd[13338]: Net::Server: 2004/02/22-19:12:01 Amavis (type Net::Server::PreForkSimple) starting! pid(13338) Feb 22 19:12:01 gpdmz amavisd[13338]: Net::Server: Binding to UNIX socket file /var/spool/amavis/amavisd.sock using SOCK_STREAM Feb 22 19:12:01 gpdmz amavisd[13338]: Net::Server: Binding to TCP port 10024 on host 127.0.0.1 Feb 22 19:12:01 gpdmz amavisd[13338]: Net::Server: Setting gid to "101 101" Feb 22 19:12:01 gpdmz amavisd[13338]: Net::Server: Setting uid to "65" Feb 22 19:12:01 gpdmz amavisd[13338]: Net::Server: Couldn't POSIX::setuid to "65" [Illegal seek] Feb 22 19:12:01 gpdmz amavisd[13338]: Net::Server: Setting up serialization via flock Feb 22 19:12:01 gpdmz amavisd[13338]: Found $file at /usr/bin/file Feb 22 19:12:01 gpdmz amavisd[13338]: Found $arc at /usr/bin/arc Feb 22 19:12:01 gpdmz amavisd[13338]: Found $gzip at /usr/bin/gzip Feb 22 19:12:01 gpdmz amavisd[13338]: Found $bzip2 at /usr/bin/bzip2 Feb 22 19:12:01 gpdmz amavisd[13338]: No $lzop, not using it Feb 22 19:12:01 gpdmz amavisd[13338]: Found $lha at /usr/bin/lha Feb 22 19:12:01 gpdmz amavisd[13338]: Found $unarj at /usr/bin/unarj Feb 22 19:12:01 gpdmz amavisd[13338]: Found $uncompress at /usr/bin/uncompress Feb 22 19:12:01 gpdmz amavisd[13338]: No $unfreeze, not using it Feb 22 19:12:01 gpdmz amavisd[13338]: Found $unrar at /usr/bin/unrar Feb 22 19:12:01 gpdmz amavisd[13338]: Found $zoo at /usr/bin/zoo Feb 22 19:12:01 gpdmz amavisd[13338]: Found $cpio at /usr/bin/cpio Feb 22 19:12:01 gpdmz amavisd[13338]: No primary av scanner: KasperskyLab AntiViral Toolkit Pro (AVP) Feb 22 19:12:01 gpdmz amavisd[13338]: No primary av scanner: KasperskyLab AVPDaemonClient Feb 22 19:12:01 gpdmz amavisd[13338]: Found primary av scanner H+BEDV AntiVir or CentralCommand Vexira Antivirus at /usr/bin/antivir Feb 22 19:12:01 gpdmz amavisd[13338]: No primary av scanner: Command AntiVirus for Linux Feb 22 19:12:01 gpdmz amavisd[13338]: No primary av scanner: Symantec CarrierScan via Symantec CommandLineScanner Feb 22 19:12:01 gpdmz amavisd[13338]: No primary av scanner: DrWeb Antivirus for Linux/FreeBSD/Solaris Feb 22 19:12:01 gpdmz amavisd[13338]: No primary av scanner: F-Secure Antivirus Feb 22 19:12:01 gpdmz amavisd[13338]: No primary av scanner: CAI InoculateIT Feb 22 19:12:01 gpdmz amavisd[13338]: No primary av scanner: MkS_Vir for Linux (beta) Feb 22 19:12:01 gpdmz amavisd[13338]: No primary av scanner: MkS_Vir daemon Feb 22 19:12:01 gpdmz amavisd[13338]: No primary av scanner: ESET Software NOD32 Feb 22 19:12:01 gpdmz amavisd[13338]: No primary av scanner: ESET Software NOD32 - Client/Server Version Feb 22 19:12:01 gpdmz amavisd[13338]: No primary av scanner: Norman Virus Control v5 / Linux Feb 22 19:12:01 gpdmz amavisd[13338]: No primary av scanner: Panda Antivirus for Linux Feb 22 19:12:01 gpdmz amavisd[13338]: No primary av scanner: NAI McAfee AntiVirus (uvscan) Feb 22 19:12:01 gpdmz amavisd[13338]: No primary av scanner: VirusBuster Feb 22 19:12:01 gpdmz amavisd[13338]: No primary av scanner: CyberSoft VFind Feb 22 19:12:01 gpdmz amavisd[13338]: No primary av scanner: Ikarus AntiVirus for Linux Feb 22 19:12:01 gpdmz amavisd[13338]: No primary av scanner: BitDefender Feb 22 19:12:01 gpdmz amavisd[13338]: No secondary av scanner: Clam Antivirus - clamscan Feb 22 19:12:01 gpdmz amavisd[13338]: Found secondary av scanner FRISK F-Prot Antivirus at /usr/local/bin/f-prot Feb 22 19:12:01 gpdmz amavisd[13338]: No secondary av scanner: Trend Micro FileScanner Feb 22 19:12:01 gpdmz amavisd[13338]: SpamControl: initializing Mail::SpamAssassin Feb 22 19:12:03 gpdmz amavisd[13338]: SpamControl: done Feb 22 19:12:03 gpdmz amavisd[13338]: Net::Server: Beginning prefork (2 processes) Feb 22 19:12:03 gpdmz amavisd[13338]: Net::Server: Starting "2" children Feb 22 19:12:03 gpdmz amavisd[13358]: Net::Server: Child Preforked (13358) Feb 22 19:12:03 gpdmz amavisd[13359]: Net::Server: Child Preforked (13359) Feb 22 19:12:03 gpdmz amavisd[13338]: Net::Server: Parent ready for children. Feb 22 19:12:32 gpdmz amavisd[13358]: Net::Server: 2004/02/22-19:12:32 CONNECT TCP Peer: "127.0.0.1:35408" Local: "127.0.0.1:10024" Feb 22 19:12:32 gpdmz amavisd[13358]: lookup_ip_acl: key="127.0.0.1" matches "127.0.0.1", result=1 Feb 22 19:12:32 gpdmz amavisd[13358]: prolong_timer after new request - timer reset: remaining time = 300 s Feb 22 19:12:32 gpdmz amavisd[13358]: SMTP> 220 [127.0.0.1] ESMTP amavisd-new service ready Feb 22 19:12:32 gpdmz amavisd[13358]: prolong_timer after reading SMTP command: remaining time = 300 s Feb 22 19:12:32 gpdmz amavisd[13358]: SMTP< EHLO mail.foo.bar\r\n Feb 22 19:12:32 gpdmz amavisd[13358]: ESMTP> 250-[127.0.0.1] Feb 22 19:12:32 gpdmz amavisd[13358]: ESMTP> 250-PIPELINING Feb 22 19:12:32 gpdmz amavisd[13358]: ESMTP> 250-SIZE Feb 22 19:12:32 gpdmz amavisd[13358]: ESMTP> 250-8BITMIME Feb 22 19:12:32 gpdmz amavisd[13358]: ESMTP> 250 ENHANCEDSTATUSCODES Feb 22 19:12:32 gpdmz amavisd[13358]: prolong_timer after reading SMTP command: remaining time = 300 s Feb 22 19:12:32 gpdmz amavisd[13358]: ESMTP< MAIL FROM: SIZE=619\r\n Feb 22 19:12:32 gpdmz amavisd[13358]: prolong_timer after MAIL FROM received - timer reset: remaining time = 300 s Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) lookup_acl: key="user2@foo.bar", no match Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) ESMTP> 250 2.1.0 Sender user2@foo.bar OK Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) prolong_timer after reading SMTP command: remaining time = 300 s Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) ESMTP< RCPT TO:\r\n Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) ESMTP> 250 2.1.5 Recipient user1@foo.bar OK Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) prolong_timer after reading SMTP command: remaining time = 300 s Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) ESMTP< DATA\r\n Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) prolong_timer after DATA received - timer reset: remaining time = 300 s Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) ESMTP::10024 /var/spool/amavis/tmp/amavis-20040222T191232-13358: -> Received: SIZE=619 from mail.foo.bar ([127.0.0.1]) by localhost (gpdmz [127.0.0.1]) (amavisd-new, port 10024) with ESMTP id 13358-01 for ; Sun, 22 Feb 2004 19:12:32 +0100 (CET) Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) ESMTP> 354 End data with . Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) ESMTP< .\r\n Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) body hash: b6692098162ca9fae678433676aeb093 Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) Original mail size: 596; quota set to: 298000 bytes Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) Checking: -> Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) lookup_acl: key="user1@foo.bar", no match Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) lookup_acl: key="user1@foo.bar", no match Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) Extracting mime components Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) Issued a new file name: part-00001 Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) mime_decode: Content-type: text/plain, name: Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) Charging 23 bytes to remaining quota 298000 (out of 298000, (0%)) - by mime_decode Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) prolong_timer after mime_decode-1: remaining time = 300 s Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) Checking for banned MIME types and names Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) check_for_banned - mime-type: text/plain Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) lookup_RE: key="text/plain", no match Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) lookup_acl: key="user1@foo.bar", no match Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) decode_parts: level=1, #parts=1 : part-00001 Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) run_command: [13365] /usr/bin/file /var/spool/amavis/tmp/amavis-20040222T191232-13358/parts/part-00001 /dev/null Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) File-type of part-00001: ASCII text; (.asc) Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) lookup_acl: key="user1@foo.bar", no match Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) Checking for banned (contents-based) file types, 1 parts Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) check_for_banned (part-00001) - file type: .asc Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) lookup_RE: key=".asc", no match Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) check_for_banned (part-00001) - file type: ASCII text Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) lookup_RE: key="ASCII text", no match Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) do_ascii: Decoding part part-00001 (0 items) Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) decompose_part: part-00001 - atomic Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) prolong_timer after decoding: remaining time = 300 s Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) Using H+BEDV AntiVir or CentralCommand Vexira Antivirus: /usr/bin/antivir --allfiles -noboot -nombr -rs -s -z /var/spool/amavis/tmp/amavis-20040222T191232-13358/parts Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) run_command: [13366] /usr/bin/antivir --allfiles -noboot -nombr -rs -s -z /var/spool/amavis/tmp/amavis-20040222T191232-13358/parts &1 Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) run_av: /usr/bin/antivir status=0 (0 ),AntiVir / Linux Version 2.1.0-6\nCopyright (c) 1994-2004 by H+BEDV Datentechnik GmbH.\nAll rights reserved.\n\nLoading /usr/lib/AntiVir/antivir.vdf ...\n\nVDF version: 6.24.0.14 created 22 Feb 2004\n\nFor private, non-commercial use only.\nAntiVir license: 1001039369 for Potenza, Oberursel\n\nchecking drive/path (list): /var/spool/amavis/tmp/amavis-20040222T191232-13358/parts\n\n----- scan results -----\n directories: ...1\n...files: ...1\n...alerts: ...0\n scan time: 00:00:01\n------------------------\nThank you for using AntiVir. Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) run_av: clean Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) prolong_timer after virus_scan: remaining time = 300 s Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) white_black_list: checking sender Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) lookup_acl: key="user2@foo.bar", no match Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) lookup_RE: key="user2@foo.bar", no match Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) lookup_hash: key="user2@foo.bar", no match Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) lookup_hash: key="user2@", no match Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) lookup_hash: key="foo.bar", no match Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) lookup_hash: key=".foo.bar", no match Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) lookup_hash: key=".de", no match Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) lookup_hash: key=".", no match Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) lookup_acl: key="user2@foo.bar", no match Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) lookup_acl: key="user1@foo.bar", no match Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) CALLING NoMailAudit::check Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) RETURNED FROM NoMailAudit::check, time left: 20 s Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) prolong_timer after spam_scan_SA: remaining time = 300 s Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) spam_scan: hits=-0.5 tests=USER_AGENT_MOZILLA_UA Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) prolong_timer after spam_scan: remaining time = 300 s Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) lookup: (scalar) matches, result="5" Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) header: Received: from mail.foo.bar ([127.0.0.1])\n by localhost (gpdmz [127.0.0.1]) (amavisd-new, port 10024) with ESMTP\n id 13358-01 for ; Sun, 22 Feb 2004 19:12:32 +0100 (CET)\n Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) header: X-Virus-Scanned: by amavisd-new at foo.bar\n Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) lookup_acl: key="user1@foo.bar" matches ".foo.bar", result=1 Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) lookup: (scalar) matches, result="3" Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) lookup: (scalar) matches, result="5" Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) headers CLUSTERING: NEW CLUSTER : hits=-0.5, tag=0, tag2=0, subj=0, local=1, bl=0 Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) headers CLUSTERING: done all 1 recips in one go Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) FWD via SMTP: [127.0.0.1:10025] -> Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) Remote host introduces itself as: --= Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) prolong_timer after fwd-connect: remaining time = 300 s Feb 22 19:12:32 gpdmz amavisd[13358]: (13358-01) prolong_timer after fwd-mail-from: remaining time = 300 s Feb 22 19:12:33 gpdmz amavisd[13358]: (13358-01) prolong_timer after fwd-rcpt-to: remaining time = 300 s Feb 22 19:12:33 gpdmz amavisd[13358]: (13358-01) response to DATA: "354 End data with ." Feb 22 19:12:33 gpdmz amavisd[13358]: (13358-01) prolong_timer after fwd-data: remaining time = 300 s Feb 22 19:12:33 gpdmz amavisd[13358]: (13358-01) prolong_timer after fwd-data-end: remaining time = 300 s Feb 22 19:12:33 gpdmz amavisd[13358]: (13358-01) response to data end: "250 Ok: queued as F39961B39D" Feb 22 19:12:33 gpdmz amavisd[13358]: (13358-01) prolong_timer after fwd-rundown-1: remaining time = 300 s Feb 22 19:12:33 gpdmz amavisd[13358]: (13358-01) mail_via_smtp: 250 2.6.0 Ok, id=13358-01, from MTA: 250 Ok: queued as F39961B39D Feb 22 19:12:33 gpdmz amavisd[13358]: (13358-01) prolong_timer after forwarding: remaining time = 300 s Feb 22 19:12:33 gpdmz amavisd[13358]: (13358-01) one_response_for_all : success, dsn_needed=0, '250 2.6.0 Ok, id=13358-01, from MTA: 250 Ok: queued as F39961B39D' Feb 22 19:12:33 gpdmz amavisd[13358]: (13358-01) warnsender_with_pass=, dsn_needed=0, exit=0, 250 2.6.0 Ok, id=13358-01, from MTA: 250 Ok: queued as F39961B39D Feb 22 19:12:33 gpdmz amavisd[13358]: (13358-01) Passed, -> , Message-ID: <4038F105.9020109@foo.bar>, Hits: -0.5 Feb 22 19:12:33 gpdmz amavisd[13358]: (13358-01) sending SMTP response: "250 2.6.0 Ok, id=13358-01, from MTA: 250 Ok: queued as F39961B39D" Feb 22 19:12:33 gpdmz amavisd[13358]: (13358-01) timer stopped after DATA end Feb 22 19:12:33 gpdmz amavisd[13358]: (13358-01) rmdir_recursively: /var/spool/amavis/tmp/amavis-20040222T191232-13358/parts, excl=1 Feb 22 19:12:33 gpdmz amavisd[13358]: (13358-01) TIMING [total 1141 ms] - SMTP EHLO: 9 (1%), SMTP pre-MAIL: 3 (0%), mkdir tempdir: 1 (0%), create email.txt: 1 (0%), SMTP pre-DATA-flush: 12 (1%), SMTP DATA: 34 (3%), body hash: 2 (0%), mkdir parts: 3 (0%), mime_decode: 45 (4%), get-file-type: 22 (2%), decompose_part: 14 (1%), parts: 0 (0%), AV-scan-1: 629 (55%), SA msg read: 8 (1%), SA parse: 4 (0%), SA check: 118 (10%), fwd-connect: 46 (4%), fwd-mail-from: 4 (0%), fwd-rcpt-to: 7 (1%), write-header: 13 (1%), fwd-data: 1 (0%), fwd-data-end: 140 (12%), fwd-rundown: 7 (1%), unlink-1-files: 18 (2%), rundown: 1 (0%) Feb 22 19:12:33 gpdmz amavisd[13358]: (13358-01) ESMTP> 250 2.6.0 Ok, id=13358-01, from MTA: 250 Ok: queued as F39961B39D Feb 22 19:12:33 gpdmz amavisd[13358]: (13358-01) prolong_timer after reading SMTP command: remaining time = 0 s Feb 22 19:12:33 gpdmz amavisd[13358]: (13358-01) ESMTP< QUIT\r\n Feb 22 19:12:33 gpdmz amavisd[13358]: (13358-01) ESMTP> 221 2.0.0 [127.0.0.1] (amavisd) closing transmission channel Feb 22 19:12:45 gpdmz amavisd[13338]: Net::Server: 2004/02/22-19:12:45 Server closing! Feb 22 19:12:45 gpdmz amavisd[13358]: (13358-01) tempdir being removed: /var/spool/amavis/tmp/amavis-20040222T191232-13358 Feb 22 19:12:45 gpdmz amavisd[13358]: (13358-01) rmdir_recursively: /var/spool/amavis/tmp/amavis-20040222T191232-13358, excl= Feb 22 19:12:45 gpdmz amavisd[13358]: (13358-01) rmdir_recursively: /var/spool/amavis/tmp/amavis-20040222T191232-13358/parts, excl=0