Mark Martinec schrieb: > Let me know if the problem reappears with 2.4.4 (or 2.4.5). It took a few day, but today amavis (2.4.5) stopped working again. Here is the log (level 5) output.
Feb 21 08:05:50 rzhs098 mail:notice amavis[540686]: (540686-02) Requesting process rundown due to stale Sophos virus data [...] Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) Net::Server: Child leaving (20) [...] Feb 21 08:05:55 rzhs098 mail:info postfix/lmtp[262266]: connect to 127.0.0.1[127.0.0.1]: Connection refused (port 10024) If you need some further information, please let me know. An sophos update at night ran successfully (and at 9:00 am too). Feb 21 02:05:44 rzhs098 mail:notice amavis[356508]: (356508-04-2) Requesting process rundown due to stale Sophos virus data [...] Feb 21 02:05:44 rzhs098 mail:debug amavis[319696]: Net::Server: Starting "6" children Feb 21 02:05:44 rzhs098 mail:debug amavis[356508]: (356508-04-2) Amavis::DB::SNMP DESTROY called Feb 21 02:05:44 rzhs098 mail:debug amavis[688286]: (688286-01) run_command: [692318] /usr/bin/file p001 </dev/null 2>&1 Feb 21 02:05:44 rzhs098 mail:debug amavis[692318]: (688286-01) open_on_specific_fd: target fd0 closing, to become < /dev/null Feb 21 02:05:44 rzhs098 mail:debug amavis[692318]: (688286-01) open_on_specific_fd: target fd2 closing, to become > &1 Feb 21 02:05:44 rzhs098 mail:debug amavis[692318]: (688286-01) open_on_specific_fd: target fd2 dup2 from fd1 > &1 Feb 21 02:05:44 rzhs098 mail:debug amavis[540926]: Net::Server: Child Preforked(540926) Feb 21 02:05:44 rzhs098 mail:debug amavis[532584]: Net::Server: Child Preforked(532584) Feb 21 02:05:44 rzhs098 mail:debug amavis[536742]: Net::Server: Child Preforked(536742) Feb 21 02:05:44 rzhs098 mail:info amavis[540926]: TIMING [total 27 ms] - bdb-ope Feb 21 02:05:45 rzhs098 mail:debug amavis[319696]: Net::Server: Starting "1" children Feb 21 02:05:45 rzhs098 mail:debug amavis[356510]: Net::Server: Child Preforked(356510) Feb 21 02:05:45 rzhs098 mail:info amavis[356510]: TIMING [total 20 ms] - bdb-open: 20 (100%)100, rundown: 0 (0%)100 Hans Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) fish_out_ip_from_received: , S067DP00.i067.finanzit.sko.de Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) parse_received: from = po-tp1-01.e.sn.finanzit.sko.de ([IP=172.22.198.162.../po-tp1-01.e.sn.finanzit.sko.de//IP=172.22.198.162 Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) parse_received: by = eSafe SMTP Relay 1172012421/eSafe// Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) parse_received: ; = Wed Feb 21 08:06:41 2007/Wed Feb 21 08:06:41 2007// Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) fish_out_ip_from_received: 172.22.198.162, po-tp1-01.e.sn.finanzit.sko.de ([IP=172.22.198.162]) Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) lookup_ip_acl (publicnetworks): key="172.22.198.162" matches "!172.16.0.0/12", result=0 Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) parse_received: from = eo-tp1-01.e.is.finanzit.sko.de (eo-tp1-01.e.sn.fin.../eo-tp1-01.e.is.finanzit.sko.de/eo-tp1-01.e.sn.finanzit.sko.de/172.22.198.21 Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) parse_received: by = pd-tp2-01.as.finanzit.net /pd-tp2-01.as.finanzit.net// Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) parse_received: with = SMTP /SMTP // Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) parse_received: id = 7D891807F\t/7D891807F\t// Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) parse_received: for = <[EMAIL PROTECTED]>/<[EMAIL PROTECTED]>// Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) parse_received: ; = Wed, 21 Feb 2007 08:06:41 +0100 (CET)/Wed, 21 Feb 2007 08:06:41 +0100 (CET)// Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) fish_out_ip_from_received: 172.22.198.21, eo-tp1-01.e.is.finanzit.sko.de (eo-tp1-01.e.sn.finanzit.sko.de [172.22.198.21])\t Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) lookup_ip_acl (publicnetworks): key="172.22.198.21" matches "!172.16.0.0/12", result=0 Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) parse_received: from = pd-tp2-01.as.finanzit.net (ww-vir-h1.e.sn.finanzit.../pd-tp2-01.as.finanzit.net/ww-vir-h1.e.sn.finanzit.sko.de/172.22.198.58 Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) parse_received: by = pd-tp1-02.as.finanzit.net /pd-tp1-02.as.finanzit.net// Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) parse_received: with = ESMTP /ESMTP // Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) parse_received: id = 9345C4C6E4\t/9345C4C6E4\t// Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) parse_received: for = <[EMAIL PROTECTED]>/<[EMAIL PROTECTED]>// Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) parse_received: ; = Wed, 21 Feb 2007 08:06:41 +0100 (CET)/Wed, 21 Feb 2007 08:06:41 +0100 (CET)// Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) fish_out_ip_from_received: 172.22.198.58, pd-tp2-01.as.finanzit.net (ww-vir-h1.e.sn.finanzit.sko.de [172.22.198.58])\t Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) lookup_ip_acl (publicnetworks): key="172.22.198.58" matches "!172.16.0.0/12", result=0 Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) parse_received: from = pd-tp1-02.as.finanzit.net ([62.181.134.165]) /pd-tp1-02.as.finanzit.net//62.181.134.165 Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) parse_received: by = INETMAIL02.NIEDERSACHSEN.DE /INETMAIL02.NIEDERSACHSEN.DE// Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) parse_received: with = SMTP /SMTP // Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) parse_received: id = 10XQWWSW/10XQWWSW// Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) parse_received: ; = Wed, 21 Feb 2007 08:07:14 +0100/Wed, 21 Feb 2007 08:07:14 +0100// Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) fish_out_ip_from_received: 62.181.134.165, pd-tp1-02.as.finanzit.net ([62.181.134.165]) Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) lookup_ip_acl (publicnetworks): key="62.181.134.165" matches "::FFFF:0:0/96", result=1 Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) best_try_originator_ip: 62.181.134.165 Feb 21 08:05:50 rzhs098 mail:notice amavis[540686]: (540686-02) Passed CLEAN, [62.181.134.165] <[EMAIL PROTECTED]> -> <[EMAIL PROTECTED]>, Message-ID: <[EMAIL PROTECTED]>, mail_id: PwKTmAFFj3LE, Hits: -, queued_as: 153DB104D, 858 ms Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) prolong_timer main_log_entry: remaining time = 480 s Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) updating snmp variables Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) prolong_timer check done: remaining time = 480 s Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) LMTP response for <[EMAIL PROTECTED]>: "250 2.6.0 Ok, id=540686-02, fromMTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 153DB104D" Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) LMTP> 250 2.6.0 Ok, id=540686-02, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 153DB104D Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) switch_to_client_time 480 s, smtp response sent Feb 21 08:05:50 rzhs098 mail:info postfix/lmtp[520392]: 64A7A1037: to=<[EMAIL PROTECTED]>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.92, delays=0.05/0/0.02/0.86, dsn=2.6.0, status=sent (250 2.6.0 Ok, id=540686-02, from MTA([127.0.0.1]:10025): 250 2.0.0 Ok: queued as 153DB104D) Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) TempDir::strip: /opt/mail/var/amavis/tmp/amavis-20070221T080506-540686 Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) rmdir_recursively: /opt/mail/var/amavis/tmp/amavis-20070221T080506-540686/parts, excl=1 Feb 21 08:05:50 rzhs098 mail:info amavis[540686]: (540686-02) TIMING [total 873ms] - SMTP greeting: 9 (1%)1, SMTP LHLO: 3 (0%)1, SMTP pre-MAIL: 5 (1%)2, SMTP pre-DATA-flush: 13 (1%)3, SMTP DATA: 340 (39%)42, check_init: 2 (0%)42, digest_hdr: 3 (0%)43, digest_body: 1 (0%)43, gen_mail_id: 1 (0%)43, mime_decode: 45 (5%)48, get-file-type1: 157 (18%)66, decompose_part: 7 (1%)67, parts_decode: 0 (0%)67, update_cache: 11 (1%)68, decide_mail_destiny: 5 (1%)69, fwd-connect: 30 (3%)72, fwd-mail-from: 2 (0%)72, fwd-rcpt-to: 20 (2%)75, fwd-data-cmd: 1 (0%)75, write-header: 5 (1%)76, fwd-data-contents: 2 (0%)76, fwd-data-end: 141 (16%)92, fwd-rundown: 3 (0%)92, prepare-dsn: 5 (1%)93, main_log_entry: 54 (6%)99, update_snmp: 4 (0%)99, SMTP pre-response: 2 (0%)99, SMTP response: 2 (0%)100, unlink-1-files: 2 (0%)100, rundown: 1 (0%)100 Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) idle_proc, 6: was busy, 850.3 ms, total idle 42.538 s, busy 1.525 s Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) idle_proc, 5: was idle, 0.5 ms, total idle 42.538 s, busy 1.525 s Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) LMTP< QUIT\r\n Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) switch_to_my_time 480 s, SMTP QUIT received Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) LMTP> 221 2.0.0 [127.0.0.1] amavisd-new closing transmission channel Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) switch_to_client_time 480 s, smtp response sent Feb 21 08:05:50 rzhs098 mail:info postfix/qmgr[430332]: 64A7A1037: removed Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) SMTP session over, timer stopped Feb 21 08:05:50 rzhs098 mail:notice amavis[540686]: (540686-02) Requesting process rundown due to stale Sophos virus data Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) Amavis::In::SMTPDESTROY called, sock=Net::Server::Proto::TCP=GLOB(0x307c1578), normal=1 Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) Amavis::TempDir::DESTROY called Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) TempDir removal:empty tempdir is being removed: /opt/mail/var/amavis/tmp/amavis-20070221T080506-540686 Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) rmdir_recursively: /opt/mail/var/amavis/tmp/amavis-20070221T080506-540686, excl= Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) rmdir_recursively: /opt/mail/var/amavis/tmp/amavis-20070221T080506-540686/parts, excl=0 Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) exiting process_request Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) post_process_request_hook: timer was not running Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) idle_proc, bye: was busy, 9.8 ms, total idle 42.538 s, busy 1.535 s Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) load: 3 %, total idle 42.538 s, busy 1.535 s Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) child_finish_hook: invoking DESTROY methods Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) Amavis::Cache DESTROY called Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) Amavis::DB::SNMPDESTROY called Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]: (540686-02) Net::Server: Child leaving (20) Feb 21 08:05:50 rzhs098 mail:info postfix/smtp[737454]: 153DB104D: to=<[EMAIL PROTECTED]>, relay=lins099.ofd-h.de[10.48.120.5]:25, delay=0.38, delays=0.17/0/0.09/0.11, dsn=2.0.0, status=sent (250 Message accepted for delivery) Feb 21 08:05:50 rzhs098 mail:info postfix/qmgr[430332]: 153DB104D: removed Feb 21 08:05:55 rzhs098 mail:info postfix/smtpd[360578]: connect from unknown[10.49.2.112] Feb 21 08:05:55 rzhs098 mail:info postfix/smtpd[360578]: 160881037: client=unknown[10.49.2.112] Feb 21 08:05:55 rzhs098 mail:info postfix/cleanup[663770]: 160881037: message-id=<[EMAIL PROTECTED]> Feb 21 08:05:55 rzhs098 mail:info postfix/smtpd[360578]: disconnect from unknown [10.49.2.112] Feb 21 08:05:55 rzhs098 mail:info postfix/qmgr[430332]: 160881037: from=<[EMAIL PROTECTED]>, size=3116, nrcpt=1 (queue active) Feb 21 08:05:55 rzhs098 mail:info postfix/lmtp[262266]: connect to 127.0.0.1[127.0.0.1]: Connection refused (port 10024) Feb 21 08:05:55 rzhs098 mail:info postfix/lmtp[262266]: 160881037: to=<[EMAIL PROTECTED]>, relay=none, delay=0.05, delays=0.05/0/0/0, dsn=4.4.1, status=deferred (connect to 127.0.0.1[127.0.0.1]: Connection refused) Feb 21 08:05:59 rzhs098 mail:info postfix/smtpd[671780]: connect from unknown[10.49.2.112] Feb 21 08:05:59 rzhs098 mail:info postfix/smtpd[671780]: 764F71056: client=unknown[10.49.2.112] Feb 21 08:05:59 rzhs098 mail:info postfix/cleanup[385142]: 764F71056: message-id=<[EMAIL PROTECTED]> Feb 21 08:05:59 rzhs098 mail:info postfix/smtpd[671780]: disconnect from unknown[10.49.2.112] Feb 21 08:05:59 rzhs098 mail:info postfix/qmgr[430332]: 764F71056: from=<[EMAIL PROTECTED]>, size=7511, nrcpt=1 (queue active) Feb 21 08:05:59 rzhs098 mail:info postfix/lmtp[614570]: connect to 127.0.0.1[127.0.0.1]: Connection refused (port 10024) Feb 21 08:05:59 rzhs098 mail:info postfix/lmtp[614570]: 764F71056: to=<[EMAIL PROTECTED]>, relay=none, delay=0.05, delays=0.05/0/0/0, dsn=4.4.1, status=deferred (connect to 127.0.0.1[127.0.0.1]: Connection refused) ------------------------------------------------------------------------- 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/
