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.
My initial thought was mailbomb messages, though the messages preserved are
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, though most of the time it is way below this. I'm running a
dual exim4 system, each box processes around 3000 mails a day. The system has
been running for months without incident.
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, <[EMAIL
PROTECTED]> -> <[EMAIL PROTECTED]>, 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] <[EMAIL PROTECTED]> -> <[EMAIL PROTECTED]>, Message-ID:
<[EMAIL PROTECTED]>, 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, <[EMAIL
PROTECTED]> -> <[EMAIL PROTECTED]>, 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, <[EMAIL
PROTECTED]> -> <[EMAIL PROTECTED]>, 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 203\n\teval {...}
called at /usr/share/perl5/Mail/SpamAssassin/Plugin/PDFInfo.pm line
203\n\tMail::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
417\n\tMail::SpamAssassin::Plugin::PDFInfo::_find_pdf_mime_parts('Mail::SpamAssassin::Plugin::PDFInfo=HASH(0xa45cc9c)',
'Mail::SpamAssassin::PerMsgStatus=HASH(0xb962d48)') called at
/usr/share/perl5/Mail/SpamAssassin/Plugin/PDFInfo.pm line
681\n\tMail::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-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/
