Re: [AMaViS-user]

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 =
<foo@fa-lin.niedersachsen.de>/<foo@fa-lin.niedersachsen.de>//
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 =
<foo@fa-lin.niedersachsen.de>/<foo@fa-lin.niedersachsen.de>//
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] <Auto-Reply@sparkasse-emsland.de> ->
<foo@FA-LIN.NIEDERSACHSEN.DE>, Message-ID:
<OF00277F7F.C1257289-ON00277F7F.C1257289-00277F7F.C1257289@sparkasse-emsland.de>,
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 <foo@FA-LIN.NIEDERSACHSEN.DE>: "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=<foo@FA-LIN.NIEDERSACHSEN.DE>, 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=<foo@FA-LIN.NIEDERSACHSEN.DE>,
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=<1172041638.b5c5858a4804a195.7534ac68@persist.g oogle.com>
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=<googlealerts-noreply@google.com>, 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=<bar@FA-FUST-OL.NIEDERSACHSEN.DE>, 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=<H000027001ea5941.1172041642.merkur.igbce.de@MH S>
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=<bar@igbce.de>, 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=<bar@FA-CUX.NIEDERSACHSEN.DE>, 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?p...rge&CID=DEVDEV
_______________________________________________
AMaViS-user mailing list
AMaViS-user@lists.sourceforge.net
https://lists.sourceforge.net/lists/...fo/amavis-user
AMaViS-FAQ:http://www.amavis.org/amavis-faq.php3
AMaViS-HowTos:http://www.amavis.org/howto/