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: B::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=17
2.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 = 7D891807Ft/7D891807Ft//
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 = 9345C4C6E4t/9345C4C6E4t//
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.C125728
9 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<
QUITrn
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: ESTROY
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: B::SNMPD
ESTROY 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.google.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.deMHS>
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?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.amav
is.org/amavis-faq.php3
AMaViS-HowTos:http://www.amavis.org/ho
wto/
|
Hans,
> 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)
> Amavis::In::SMTPDESTROY called, [...]
Looks like a clean shutdown of a child process...
> Feb 21 08:05:50 rzhs098 mail:debug amavis[540686]:
(540686-02)
> Net::Server: Child leaving (20)
At this point the amavisd parent process is about to
execute
the SAVI routine load_data(), which seems to crash the
(master) process
> 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)
and you end up with no amavisd.
So the problem lies either in the load_data() routine, or in
the
underlying SAVI library. Running the master process through
strace
(or truss) could show the true reason for a crash:
su vscan
strace amavisd foreground >1.log 2>&1
Just in case the failure is non-fatal and could be caught,
would you
please replace the entire (small) subroutine sub
sophos_savi_reload
with the following replacement, which provides a little bit
more
logging and is a bit more tolerant to SAVI problems. At
least you
will see an additional log entry (at log level 2 or above):
sophos_savi_reload: about to reload SAVI data
sub sophos_savi_reload {
if (defined $savi_obj) {
do_log(2,"sophos_savi_reload: about to reload SAVI
data");
my($status); eval { $status = $savi_obj->load_data
};
if ($ ne '') {
chomp($ ); do_log(-1,"sophos_savi_reload
failed: %s",$ );
} elsif (defined $status) {
do_log(-1,"sophos_savi_reload: failed to load
SAVI virus data %s (%s)",
$savi_obj->error_string($status),
$status);
}
my($version) = $savi_obj->version;
if (!ref($version)) {
do_log(-1,"sophos_savi_reload: Can't get SAVI
version: %s", $version);
} else {
do_log(2,"Updated SAVI data: Version %s (engine
%d.%d) ".
"recognizing %d viruses",
$version->string,
$version->major, $version->minor,
$version->count);
}
}
}
Mark
------------------------------------------------------------
-------------
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.amav
is.org/amavis-faq.php3
AMaViS-HowTos:http://www.amavis.org/ho
wto/
|