Serious Problems With Amavis (Forking, Dying, Process Shutdown)

Hi guys,

We're having serious problems with Amavis at the moment.  I
have 3 machines on
round-robin DNS handling mail for a number of domains.

This afternoon one of the machines stopped processing email
and I noticed that
the amavisd processes weren't running.  I restarted them and
everything was
fine, the queues cleared and mail was flowing happily.  This
evening amavisd
has stopped on all three machines, with mail backing up all
over the place!
>From the logs it looks like it's having problems in the
mime decoding stages.
I have posted relevant sections of the logs below, though it
is weird that it
happened on all three machines within a few hours of each
other.

I'm running a dual exim4 system, each box processes around
3000 mails a day.
The system has been running for months without incident
until today.  My
initial thought was mailbomb messages, though the messages
preserved are
all plain text and legitimate PDF documents.  It's all very
weird.

The boxes in question are Pentium 4, 512mb Ram, 40GB hdd. 
Usually the load is
about 0.5 max, with tons of free memory, though most of the
time it is way below
this.  Something seems to be eating all available memory,
then either amavis is
killing itself or the kernel is running something called
oom-killer and knocking
out processes.

I'm using amavis-new-2.5.2, Perl 5.8.8.


Any suggestions / comments would be gratefully received!



----------------------------------------------

Sep  5 16:31:34 server1 amavis[29536]: (29536-01) Passed
CLEAN, <bbbccc.com>
-> <xxxyyy.com>, Hits: -2.383, tag=-9999,
tag2=6, kill=6, fwd: 250 OK
id=1ISwqp-0007gV-0w, L/Y/0/0
Sep  5 16:31:55 server1 amavis[29536]: (29536-02)
(!!)TROUBLE in check_mail:
parts_decode_ext FAILED: run_command (open pipe): Can't fork
at
/usr/lib/perl/5.8/IO/File.pm line 70, <GEN16> line
3930. at
/usr/local/sbin/amavisd line 2598, <GEN16> line 3930.
Sep  5 16:31:58 server1 amavis[29536]: (29536-02)
(!)PRESERVING EVIDENCE in
/var/lib/amavis/amavis-20070905T163055-29536
Sep  5 16:32:02 server1 amavis[29536]: (29536-03)
(!!)TROUBLE in check_mail:
parts_decode_ext FAILED: run_command (open pipe): Can't fork
at
/usr/lib/perl/5.8/IO/File.pm line 70, <GEN36> line
184. at
/usr/local/sbin/amavisd line 2598, <GEN36> line 184.
Sep  5 16:32:03 server1 amavis[29536]: (29536-03)
(!)PRESERVING EVIDENCE in
/var/lib/amavis/amavis-20070905T163159-29536
Sep  5 16:32:08 server1 amavis[29536]: (29536-04)
(!!)TROUBLE in check_mail:
parts_decode_ext FAILED: run_command (open pipe): Can't fork
at
/usr/lib/perl/5.8/IO/File.pm line 70, <GEN41> line 70.
at
/usr/local/sbin/amavisd line 2598, <GEN41> line 70.
Sep  5 16:32:09 server1 amavis[29536]: (29536-04)
(!)PRESERVING EVIDENCE in
/var/lib/amavis/amavis-20070905T163207-29536
Sep  5 16:32:15 server1 amavis[29536]: (29536-05)
(!!)TROUBLE in check_mail:
parts_decode_ext FAILED: run_command (open pipe): Can't fork
at
/usr/lib/perl/5.8/IO/File.pm line 70. at
/usr/local/sbin/amavisd line 2598.
Sep  5 16:32:15 server1 amavis[29536]: (29536-05)
(!)PRESERVING EVIDENCE in
/var/lib/amavis/amavis-20070905T163214-29536
Sep  5 16:32:19 server1 amavis[29536]: (29536-06)
(!!)TROUBLE in check_mail:
parts_decode_ext FAILED: run_command (open pipe): Can't fork
at
/usr/lib/perl/5.8/IO/File.pm line 70. at
/usr/local/sbin/amavisd line 2598.
Sep  5 16:32:19 server1 amavis[29536]: (29536-06)
(!)PRESERVING EVIDENCE in
/var/lib/amavis/amavis-20070905T163219-29536
Sep  5 16:32:21 server1 amavis[29536]: (29536-07)
(!!)TROUBLE in check_mail:
parts_decode_ext FAILED: run_command (open pipe): Can't fork
at
/usr/lib/perl/5.8/IO/File.pm line 70, <GEN53> line 87.
at
/usr/local/sbin/amavisd line 2598, <GEN53> line 87.
Sep  5 16:32:21 server1 amavis[29536]: (29536-07)
(!)PRESERVING EVIDENCE in
/var/lib/amavis/amavis-20070905T163221-29536
Sep  5 16:32:21 server1 amavis[29536]: (29536-08)
(!!)TROUBLE in
process_request: Can't create file
/var/lib/amavis/amavis-20070905T163221-29536/email.txt: File
exists at
/usr/local/sbin/amavisd line 4774, <GEN57> line 2.
Sep  5 16:32:22 server1 amavis[29536]: (29536-08)
(!)Requesting process rundown
after fatal error
Sep  5 16:32:31 server1 amavis[29535]: (29535-01) Passed
CLEAN,
[202.123.28.177] <jjjkkk.com> ->
<aaabbb.com>, Message-ID:
<OF4CEB55AB.4E688D07-ON4425734D.0054073C-4425734D.005549C
Fkkk.com>, mail_id:
cYbhnYH3LAtK, Hits: 1.054, size: 2007636, queued_as: 250 OK
id=1ISwrf-0007gv-JL, 62860 ms
Sep  5 16:32:31 server1 amavis[29535]: (29535-01) Passed
CLEAN, <yyywww.com>
-> <pppqqq.com>, Hits: 1.054, tag=-9999,
tag2=6, kill=6, fwd: 250 OK
id=1ISwrf-0007gv-JL, L/Y/0/0
Sep  5 16:32:53 server1 amavis[29535]: (29535-02)
(!!)TROUBLE in check_mail:
parts_decode_ext FAILED: run_command (open pipe): Can't fork
at
/usr/lib/perl/5.8/IO/File.pm line 70, <GEN16> line
51738. at
/usr/local/sbin/amavisd line 2598, <GEN16> line
51738.
Sep  5 16:32:57 server1 amavis[29535]: (29535-02)
(!)PRESERVING EVIDENCE in
/var/lib/amavis/amavis-20070905T163128-29535
Sep  5 16:33:13 server1 amavis[21401]: (!)Net::Server:
2007/09/05-16:33:11 Bad
fork [Cannot allocate memory]n  at line 168 in file
/usr/share/perl5/Net/Server/PreForkSimple.pm
Sep  5 16:33:32 server1 amavis[27526]: (27526-03) (!)TempDir
removal: tempdir
is to be PRESERVED:
/var/lib/amavis/amavis-20070905T143214-27526
Sep  5 16:34:11 server1 amavis[26269]: (26269-08) (!)TempDir
removal: tempdir
is to be PRESERVED:
/var/lib/amavis/amavis-20070905T133404-26269

----------------------------------------------

Sep  5 15:34:42 server2 amavis[3708]: (03708-01) Blocked
SPAM, <xxxyyy.com> ->
<aaabbb.com>, Hits: 25.409, tag=-9999, tag2=6, kill=6,
L/Y/Y/Y
Sep  5 15:34:55 server2 amavis[3709]: (03709-02) (!!)TROUBLE
in check_mail:
parts_decode_ext FAILED: run_command (open pipe): Can't fork
at
/usr/lib/perl/5.8/IO/File.pm line 70. at
/usr/local/sbin/amavisd line 2598.
Sep  5 15:34:56 server2 amavis[3708]: (03708-02) (!!)TROUBLE
in check_mail:
parts_decode_ext FAILED: run_command (open pipe): Can't fork
at
/usr/lib/perl/5.8/IO/File.pm line 70, <GEN17> line
1867. at
/usr/local/sbin/amavisd line 2598, <GEN17> line 1867.
Sep  5 15:34:57 server2 amavis[3709]: (03709-02)
(!)PRESERVING EVIDENCE in
/var/lib/amavis/amavis-20070905T153336-03709
Sep  5 15:34:57 server2 amavis[3708]: (03708-02)
(!)PRESERVING EVIDENCE in
/var/lib/amavis/amavis-20070905T153336-03708
Sep  5 15:34:59 server2 amavis[3709]: (03709-03) (!!)TROUBLE
in check_mail:
parts_decode_ext FAILED: run_command (open pipe): Can't fork
at
/usr/lib/perl/5.8/IO/File.pm line 70. at
/usr/local/sbin/amavisd line 2598.
Sep  5 15:34:59 server2 amavis[3709]: (03709-03)
(!)PRESERVING EVIDENCE in
/var/lib/amavis/amavis-20070905T153459-03709
Sep  5 15:35:07 server2 amavis[3708]: (03708-03) (!!)TROUBLE
in check_mail:
parts_decode_ext FAILED: run_command (open pipe): Can't fork
at
/usr/lib/perl/5.8/IO/File.pm line 70, <GEN37> line
211. at
/usr/local/sbin/amavisd line 2598, <GEN37> line 211.
Sep  5 15:35:08 server2 amavis[3708]: (03708-03)
(!)PRESERVING EVIDENCE in
/var/lib/amavis/amavis-20070905T153505-03708
Sep  5 15:35:55 server2 amavis[3709]: (03709-04) (!!)TROUBLE
in check_mail:
parts_decode_ext FAILED: run_command (open pipe): Can't fork
at
/usr/lib/perl/5.8/IO/File.pm line 70, <GEN39> line
175118. at
/usr/local/sbin/amavisd line 2598, <GEN39> line
175118.
Sep  5 15:35:56 server2 amavis[3709]: (03709-04)
(!)PRESERVING EVIDENCE in
/var/lib/amavis/amavis-20070905T153515-03709
Sep  5 15:36:29 server2 amavis[3708]: (03708-04) (!!)TROUBLE
in check_mail:
parts_decode_ext FAILED: run_command (open pipe): Can't fork
at
/usr/lib/perl/5.8/IO/File.pm line 70. at
/usr/local/sbin/amavisd line 2598.
Sep  5 15:36:31 server2 amavis[3708]: (03708-04)
(!)PRESERVING EVIDENCE in
/var/lib/amavis/amavis-20070905T153620-03708
Sep  5 15:36:56 server2 amavis[3709]: (03709-05) (!!)TROUBLE
in check_mail:
parts_decode_ext FAILED: run_command (open pipe): Can't fork
at
/usr/lib/perl/5.8/IO/File.pm line 70. at
/usr/local/sbin/amavisd line 2598.
Sep  5 15:36:56 server2 amavis[3709]: (03709-05)
(!)PRESERVING EVIDENCE in
/var/lib/amavis/amavis-20070905T153649-03709
Sep  5 15:37:16 server2 amavis[3708]: (03708-05) (!!)TROUBLE
in check_mail:
parts_decode_ext FAILED: run_command (open pipe): Can't fork
at
/usr/lib/perl/5.8/IO/File.pm line 70. at
/usr/local/sbin/amavisd line 2598.
Sep  5 15:37:18 server2 amavis[3708]: (03708-05)
(!)PRESERVING EVIDENCE in
/var/lib/amavis/amavis-20070905T153711-03708
Sep  5 15:39:09 server2 amavis[3709]: (03709-06) (!!)TROUBLE
in check_mail:
parts_decode_ext FAILED: run_command (open pipe): Can't fork
at
/usr/lib/perl/5.8/IO/File.pm line 70, <GEN48> line
121. at
/usr/local/sbin/amavisd line 2598, <GEN48> line 121.
Sep  5 15:39:10 server2 amavis[3709]: (03709-06)
(!)PRESERVING EVIDENCE in
/var/lib/amavis/amavis-20070905T153907-03709
Sep  5 15:39:39 server2 amavis[3708]: (03708-06) (!!)TROUBLE
in check_mail:
parts_decode_ext FAILED: run_command (open pipe): Can't fork
at
/usr/lib/perl/5.8/IO/File.pm line 70. at
/usr/local/sbin/amavisd line 2598.
Sep  5 15:39:39 server2 amavis[3708]: (03708-06)
(!)PRESERVING EVIDENCE in
/var/lib/amavis/amavis-20070905T153938-03708
Sep  5 15:42:56 server2 amavis[3709]: (03709-07) (!!)TROUBLE
in check_mail:
parts_decode_ext FAILED: run_command (open pipe): Can't fork
at
/usr/lib/perl/5.8/IO/File.pm line 70. at
/usr/local/sbin/amavisd line 2598.
Sep  5 15:42:57 server2 amavis[3709]: (03709-07)
(!)PRESERVING EVIDENCE in
/var/lib/amavis/amavis-20070905T154256-03709
Sep  5 15:43:43 server2 amavis[3708]: (03708-07) (!!)TROUBLE
in check_mail:
parts_decode_ext FAILED: run_command (open pipe): Can't fork
at
/usr/lib/perl/5.8/IO/File.pm line 70, <GEN54> line
264. at
/usr/local/sbin/amavisd line 2598, <GEN54> line 264.
Sep  5 15:43:43 server2 amavis[3708]: (03708-07)
(!)PRESERVING EVIDENCE in
/var/lib/amavis/amavis-20070905T154343-03708
Sep  5 15:44:17 server2 amavis[3709]: (03709-08) (!!)TROUBLE
in check_mail:
parts_decode_ext FAILED: run_command (open pipe): Can't fork
at
/usr/lib/perl/5.8/IO/File.pm line 70, <GEN57> line
386. at
/usr/local/sbin/amavisd line 2598, <GEN57> line 386.
Sep  5 15:44:17 server2 amavis[3709]: (03709-08)
(!)PRESERVING EVIDENCE in
/var/lib/amavis/amavis-20070905T154417-03709
Sep  5 15:45:16 server2 amavis[3708]: (03708-08) (!!)TROUBLE
in check_mail:
parts_decode_ext FAILED: run_command (open pipe): Can't fork
at
/usr/lib/perl/5.8/IO/File.pm line 70, <GEN59> line
693. at
/usr/local/sbin/amavisd line 2598, <GEN59> line 693.
Sep  5 15:45:16 server2 amavis[3708]: (03708-08)
(!)PRESERVING EVIDENCE in
/var/lib/amavis/amavis-20070905T154516-03708
Sep  5 15:48:08 server2 amavis[3709]: (03709-09) (!!)TROUBLE
in check_mail:
parts_decode_ext FAILED: run_command (open pipe): Can't fork
at
/usr/lib/perl/5.8/IO/File.pm line 70. at
/usr/local/sbin/amavisd line 2598.
Sep  5 15:48:09 server2 amavis[3709]: (03709-09)
(!)PRESERVING EVIDENCE in
/var/lib/amavis/amavis-20070905T154805-03709
Sep  5 15:50:18 server2 amavis[3708]: (03708-09) (!!)TROUBLE
in check_mail:
parts_decode_ext FAILED: run_command (open pipe): Can't fork
at
/usr/lib/perl/5.8/IO/File.pm line 70, <GEN64> line 77.
at
/usr/local/sbin/amavisd line 2598, <GEN64> line 77.
Sep  5 15:50:19 server2 amavis[3708]: (03708-09)
(!)PRESERVING EVIDENCE in
/var/lib/amavis/amavis-20070905T155016-03708
Sep  5 15:51:54 server2 amavis[3709]: (03709-10) (!!)TROUBLE
in check_mail:
parts_decode_ext FAILED: run_command (open pipe): Can't fork
at
/usr/lib/perl/5.8/IO/File.pm line 70, <GEN66> line
228. at
/usr/local/sbin/amavisd line 2598, <GEN66> line 228.
Sep  5 15:51:54 server2 amavis[3709]: (03709-10)
(!)PRESERVING EVIDENCE in
/var/lib/amavis/amavis-20070905T155153-03709
Sep  5 15:52:23 server2 amavis[12149]: (!)Net::Server:
2007/09/05-15:52:19 Bad
fork [Cannot allocate memory]n  at line 168 in file
/usr/share/perl5/Net/Server/PreForkSimple.pm

----------------------------------------------

Sep  5 21:37:42 server3 amavis[5001]: (05001-01) (!!)TROUBLE
in check_mail:
parts_decode_ext FAILED: run_command (open pipe): Can't fork
at
/usr/lib/perl/5.8/IO/File.pm line 70, <GEN17> line
128951. at
/usr/local/sbin/amavisd line 2598, <GEN17> line
128951.
Sep  5 21:37:43 server3 amavis[5001]: (05001-01)
(!)PRESERVING EVIDENCE in
/var/lib/amavis/amavis-20070905T213709-05001
Sep  5 22:07:20 server3 amavis[4709]: (04709-02) (!!)TROUBLE
in check_mail:
parts_decode_ext FAILED: run_command (open pipe): Can't fork
at
/usr/lib/perl/5.8/IO/File.pm line 70, <GEN17> line
386853. at
/usr/local/sbin/amavisd line 2598, <GEN17> line
386853.
Sep  5 22:07:21 server3 amavis[4709]: (04709-02)
(!)PRESERVING EVIDENCE in
/var/lib/amavis/amavis-20070905T191718-04709
Sep  5 22:08:40 server3 amavis[5062]: (05062-01) (!!)TROUBLE
in check_mail:
parts_decode_ext FAILED: run_command (open pipe): Can't fork
at
/usr/lib/perl/5.8/IO/File.pm line 70, <GEN17> line
144642. at
/usr/local/sbin/amavisd line 2598, <GEN17> line
144642.
Sep  5 22:08:42 server3 amavis[5062]: (05062-01)
(!)PRESERVING EVIDENCE in
/var/lib/amavis/amavis-20070905T220755-05062
Sep  5 22:09:45 server3 amavis[4709]: (04709-03) (!!)TROUBLE
in check_mail:
parts_decode_ext FAILED: run_command (open pipe): Can't fork
at
/usr/lib/perl/5.8/IO/File.pm line 70, <GEN33> line
174953. at
/usr/local/sbin/amavisd line 2598, <GEN33> line
174953.
Sep  5 22:09:46 server3 amavis[4709]: (04709-03)
(!)PRESERVING EVIDENCE in
/var/lib/amavis/amavis-20070905T220918-04709
Sep  5 22:35:35 server3 amavis[4706]: (04706-01) (!)TempDir
removal: tempdir is
to be PRESERVED:
/var/lib/amavis/amavis-20070905T193927-04706
Sep  6 01:13:21 server3 amavis[5001]: (05001-02) (!)SA TIMED
OUT, backtrace: at
/usr/share/perl5/Mail/SpamAssassin/Plugin/PDFInfo.pm line
203nteval {...}
called at
/usr/share/perl5/Mail/SpamAssassin/Plugin/PDFInfo.pm line
203ntMail::SpamAssassin::Plugin::PDFInfo::__ANON__('Mail::
SpamAssassin::Plugin::PDFInfo=HASH(0xa45cc9c)',
'Mail::SpamAssassin::PerMsgStatus=HASH(0xb962d48)',
'Mail::SpamAssassin::Message::Node=HASH(0xbacd728)') called
at
/usr/share/perl5/Mail/SpamAssassin/Plugin/PDFInfo.pm line
417ntMail::SpamAssassin::Plugin::PDFInfo::_find_pdf_mime_p
arts('Mail::SpamAssassin::Plugin::PDFInfo=HASH(0xa45cc9c)',
'Mail::SpamAssassin::PerMsgStatus=HASH(0xb962d48)') called
at
/usr/share/perl5/Mail/SpamAssassin/Plugin/PDFInfo.pm line
681ntMail::SpamAssassin::Plugin::PDFInfo::pdf_match_fuzzy_
md5('Mail::SpamAssassin::Plugin::PDFInfo=HASH(0xa45cc9c)',
'Mail::SpamAssassin::PerMsgStatus=HASH(0xb962d48)',
'ARRAY(0xab6eb08)',
'653C8AA9FDFD03D38252[...]
Sep  6 01:39:07 server3 amavis[4709]: (04709-04) (!!)TROUBLE
in check_mail:
parts_decode_ext FAILED: run_command (open pipe): Can't fork
at
/usr/lib/perl/5.8/IO/File.pm line 70, <GEN39> line
128951. at
/usr/local/sbin/amavisd line 2598, <GEN39> line
128951.
Sep  6 01:39:07 server3 amavis[4709]: (04709-04)
(!)PRESERVING EVIDENCE in
/var/lib/amavis/amavis-20070906T013740-04709
Sep  6 01:45:19 server3 amavis[5062]: (05062-02) (!)TempDir
removal: tempdir is
to be PRESERVED:
/var/lib/amavis/amavis-20070906T013944-05062

----------------------------------------------




Also I found this in the syslog for one box

Sep  5 14:54:04 server3 kernel: Out of Memory: Kill process
2175 (amavisd)
score 117203 and children.
Sep  5 14:54:04 server3 kernel: Out of memory: Killed
process 2590 (amavisd).
Sep  5 15:21:06 server3 kernel: Out of Memory: Kill process
2175 (amavisd)
score 114150 and children.
Sep  5 15:21:06 server3 kernel: Out of memory: Killed
process 3525 (amavisd).
Sep  5 15:38:37 server3 kernel: Out of Memory: Kill process
2175 (amavisd)
score 114072 and children.
Sep  5 15:38:37 server3 kernel: Out of memory: Killed
process 4132 (amavisd).
Sep  5 16:37:26 server3 kernel: Out of Memory: Kill process
2175 (amavisd)
score 117964 and children.
Sep  5 16:37:26 server3 kernel: Out of memory: Killed
process 4161 (amavisd).
Sep  5 17:47:52 server3 kernel: Out of Memory: Kill process
2175 (amavisd)
score 115795 and children.
Sep  5 17:47:52 server3 kernel: Out of memory: Killed
process 4302 (amavisd).
Sep  5 19:31:51 server3 kernel: Out of Memory: Kill process
2175 (amavisd)
score 59285 and children.
Sep  5 19:31:51 server3 kernel: Out of memory: Killed
process 4478 (amavisd).
Sep  5 19:42:25 server3 kernel: Out of Memory: Kill process
2175 (amavisd)
score 58714 and children.
Sep  5 19:42:25 server3 kernel: Out of memory: Killed
process 4537 (amavisd).
Sep  6 01:41:05 server3 kernel: Out of Memory: Kill process
2175 (amavisd)
score 59513 and children.
Sep  6 01:41:05 server3 kernel: Out of memory: Killed
process 4709 (amavisd).




Many thanks in advance





Richard
------------------------------------------------------------
-------------
This SF.net email is sponsored by: Splunk Inc.
Still grepping through log files to find problems?  Stop.
Now Search log events and configuration files using AJAX and
a browser.
Download your FREE copy of Splunk now >>  http://get.splunk.com/
_______________________________________________
AMaViS-user mailing list
AMaViS-userlists.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/

Richard,

> This afternoon one of the machines stopped processing
email and I noticed
> that the amavisd processes weren't running.  I
restarted them and
> everything was fine, the queues cleared and mail was
flowing happily.  This
> evening amavisd has stopped on all three machines, with
mail backing up all
> over the place! I'm using amavis-new-2.5.2, Perl
5.8.8.

> Sep  5 16:31:55 server1 amavis[29536]: (29536-02)
> (!!)TROUBLE in check_mail: parts_decode_ext FAILED:
> run_command (open pipe): Can't fork
> at /usr/lib/perl/5.8/IO/File.pm line 70,<GEN16>
line 3930.
> at /usr/local/sbin/amavisd line 2598, <GEN16>
line 3930.

> Sep  5 16:33:13 server1 amavis[21401]:
> (!)Net::Server: 2007/09/05-16:33:11 Bad fork [Cannot
allocate memory]
> at line 168 in file
/usr/share/perl5/Net/Server/PreForkSimple.pm

> Sep  5 14:54:04 server3 kernel: Out of Memory: Kill
process 2175 (amavisd)
> score 117203 and children.

Three symptoms of the same problem: fork fails, apparently
because
system is low on memory. To find a cause you'll need to
find
what is consuming memory - use system tools (ps, vmstat,
...).
Btw, how many amavisd child processes are you running?

  Mark

------------------------------------------------------------
-------------
This SF.net email is sponsored by: Splunk Inc.
Still grepping through log files to find problems?  Stop.
Now Search log events and configuration files using AJAX and
a browser.
Download your FREE copy of Splunk now >>  http://get.splunk.com/
_______________________________________________
AMaViS-user mailing list
AMaViS-userlists.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/

Hi Mark,
Firstly thanks for your very prompt reply.

    > Three symptoms of the same problem: fork fails,
apparently because
    > system is low on memory. To find a cause you'll
need to find
    > what is consuming memory - use system tools (ps,
vmstat, ...).
    > Btw, how many amavisd child processes are you
running?

I could see that the machines were running out of memory,
though I wasn't
sure what was causing it.  I've been monitoring them for the
past couple of
hours, having rebooted everything previously.  It seems that
there are
problems when SA is called, with amavis eating memory and
CPU.  Looking
through the logs I think I've narrowed it down to the
PDFInfo.pm plugin for
SA, this seems to be not far away when errors are thrown:


Sep  6 01:28:54 server2 amavis[22301]: (22301-07-29) (!)SA
TIMED OUT,
backtrace: at
/usr/share/perl5/Mail/SpamAssassin/Plugin/PDFInfo.pm line
203nteval {...} called at
/usr/share/perl5/Mail/SpamAssassin/Plugin/PDFInfo.pm line
203ntMail::SpamAssassin::Plugin::PDFInfo::__ANON__('Mail::
SpamAssassin::Plugin::PDFInfo=HASH(0xa466b10)',
'Mail::SpamAssassin::PerMsgStatus=HASH(0xbde6f98)',
'Mail::SpamAssassin::Message::Node=HASH(0xbe0a48c)') called
at
/usr/share/perl5/Mail/SpamAssassin/Plugin/PDFInfo.pm line
417ntMail::SpamAssassin::Plugin::PDFInfo::_find_pdf_mime_p
arts('Mail::SpamAssassin::Plugin::PDFInfo=HASH(0xa466b10)',
'Mail::SpamAssassin::PerMsgStatus=HASH(0xbde6f98)') called
at
/usr/share/perl5/Mail/SpamAssassin/Plugin/PDFInfo.pm line
681ntMail::SpamAssassin::Plugin::PDFInfo::pdf_match_fuzzy_
md5('Mail::SpamAssassin::Plugin::PDFInfo=HASH(0xa466b10)',
'Mail::SpamAssassin::PerMsgStatus=HASH(0xbde6f98)',
'ARRAY(0xbddeb80)',
'653C8AA9FDFD03D38252[...]
Sep  6 01:30:39 server2 amavis[23888]: (23888-02-2)
(!!)TROUBLE in
check_mail: parts_decode_ext FAILED: run_command (open
pipe): Can't fork at
/usr/lib/perl/5.8/IO/File.pm line 70, <GEN18> line
207. at
/usr/local/sbin/amavisd line 2598, <GEN18> line 207.
Sep  6 01:30:40 server2 amavis[23888]: (23888-02-2)
(!)PRESERVING EVIDENCE
in /var/lib/amavis/amavis-20070906T013021-23888
Sep  6 01:33:55 server2 amavis[23889]: (23889-02-8) (!)SA
TIMED OUT,
backtrace: at
/usr/share/perl5/Mail/SpamAssassin/Plugin/PDFInfo.pm line
203nteval {...} called at
/usr/share/perl5/Mail/SpamAssassin/Plugin/PDFInfo.pm line
203ntMail::SpamAssassin::Plugin::PDFInfo::__ANON__('Mail::
SpamAssassin::Plugin::PDFInfo=HASH(0xa466b10)',
'Mail::SpamAssassin::PerMsgStatus=HASH(0xbeeaa90)',
'Mail::SpamAssassin::Message::Node=HASH(0xbe0ced0)') called
at
/usr/share/perl5/Mail/SpamAssassin/Plugin/PDFInfo.pm line
417ntMail::SpamAssassin::Plugin::PDFInfo::_find_pdf_mime_p
arts('Mail::SpamAssassin::Plugin::PDFInfo=HASH(0xa466b10)',
'Mail::SpamAssassin::PerMsgStatus=HASH(0xbeeaa90)') called
at
/usr/share/perl5/Mail/SpamAssassin/Plugin/PDFInfo.pm line
681ntMail::SpamAssassin::Plugin::PDFInfo::pdf_match_fuzzy_
md5('Mail::SpamAssassin::Plugin::PDFInfo=HASH(0xa466b10)',
'Mail::SpamAssassin::PerMsgStatus=HASH(0xbeeaa90)',
'ARRAY(0xbd7cb90)',
'653C8AA9FDFD03D38252[...]


I've disabled this module in SA and restarted amavis and
everything seems to
have been ok for the past hour or so, the load is normal
(0.1 - 0.2), with
300mb of memory free.  There's obviously something in this
module at fault
somewhere.  I'm running PDFInfo.pm version 0.7 though it
doesn't appear from
the changelog that anything has been fixed in the latest
release (0.8),
other than adding FDF support.

Has anybody else had problems with this Plugin?

In response to your question, I've got the following in
amavisd.conf:

$max_servers = 4;
$max_requests = 10;
$child_timeout = 8*60;


Thanks again


Richard
------------------------------------------------------------
-------------
This SF.net email is sponsored by: Splunk Inc.
Still grepping through log files to find problems?  Stop.
Now Search log events and configuration files using AJAX and
a browser.
Download your FREE copy of Splunk now >>  http://get.splunk.com/
_______________________________________________
AMaViS-user mailing list
AMaViS-userlists.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/