Bug 6745 - spamd crashes because of memory problems in Logger.pm
Summary: spamd crashes because of memory problems in Logger.pm
Status: RESOLVED FIXED
Alias: None
Product: Spamassassin
Classification: Unclassified
Component: spamc/spamd (show other bugs)
Version: 3.3.2
Hardware: PC FreeBSD
: P2 normal
Target Milestone: 3.4.0
Assignee: SpamAssassin Developer Mailing List
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2012-01-02 13:37 UTC by lehmann
Modified: 2013-01-17 01:54 UTC (History)
7 users (show)



Attachment Type Modified Status Actions Submitter/CLA Status
Avoid logging and any complex operations in a sigchld handler patch None Mark Martinec [HasCLA]

Note You need to log in before you can comment on or make changes to this bug.
Description lehmann 2012-01-02 13:37:34 UTC
Hi,

I'm getting the following syslog entries which leads to the fact, that spamd is no longer running. I've to restart it manually and it will stop working again later after some messages. The error is in Logger.pm line 224 in _log()

  if ($_[1] =~ /^([^:]+?):/) {




Dec 31 03:21:17 hostname spamd[161]: spamd: clean message (-97.7/5.0) for vpopmail:89 in 11.2 seconds, 7520 bytes.
Dec 31 03:21:17 hostname spamd[161]: spamd: result: . -97 - BAYES_00,RCVD_IN_PBL,RCVD_IN_SORBS_DUL,RDNS_NONE,TO_NO_BRKTS_NORDNS,USER_IN_WHITELIST scantime=11.2,size=7520,user=vpopmail,uid=89,required_score=5.0,rhost=localhost,raddr=127.0.0.1,rport=60330,mid=<201112310221.pBV2L5vK025460@host.domain.net>,bayes=0.000000,autolearn=no
Dec 31 03:21:17 hostname dovecot: lda(user@domain.de): sieve: msgid=<201112310221.pBV2L5vK025460@host.domain.net>: stored mail into mailbox 'admin'
Dec 31 03:21:18 hostname spamd[94442]: prefork: child states: III
Dec 31 03:21:18 hostname spamd[94442]: spamd: handled cleanup of child pid [39936] due to SIGCHLD: interrupted, signal 2 (0002)
Dec 31 03:21:18 hostname spamd[94442]: Out of memory during ridiculously large request at /usr/local/lib/perl5/site_perl/5.14.1/Mail/SpamAssassin/Logger.pm line 224.
Dec 31 03:24:13 hostname spamc[39973]: connect to spamd on 127.0.0.1 failed, retrying (#1 of 3): Operation timed out
Dec 31 03:25:29 hostname spamc[39973]: connect to spamd on 127.0.0.1 failed, retrying (#2 of 3): Operation timed out
Dec 31 03:26:45 hostname spamc[39973]: connect to spamd on 127.0.0.1 failed, retrying (#3 of 3): Operation timed out
Dec 31 03:26:46 hostname spamc[39973]: connection attempt to spamd aborted after 3 retries
Dec 31 03:26:46 hostname dovecot: lda(user@domain.de): sieve: msgid=<201112310222.pBV2MpoJ082589@repoman.freebsd.org>: stored mail into mailbox 'Mailinglists.ports-committers@FreeBSD'
Comment 1 Kevin A. McGrail 2012-01-03 14:50:26 UTC
The error: Out of memory during ridiculously large request is likely a perl bug as the regex is fairly simple.  There have been similar regex bugs before.

However, are you able to repeat by scanning the same email?  Can you include the email with the bug to see if others can reproduce?
Comment 2 lehmann 2012-01-03 15:52:34 UTC
I checked both mails from the logfile (the one before the error and the one after) with:

/usr/local/bin/spamc -f -s 2048000 < mailfile

And spamd did not crash. The parameters are the ones being used when checking incomming mail.
I'm not sure if this test is correct because "mailfile" already contains the X-Spam-* headers. I can filter those headers out and redo the test if you think this is necessary.

I upgraded my perl in the meantime to 5.14.2 and the error did not reoccur so far.
Comment 3 Kevin A. McGrail 2012-01-03 16:29:35 UTC
(In reply to comment #2)
> I checked both mails from the logfile (the one before the error and the one
> after) with:
> 
> /usr/local/bin/spamc -f -s 2048000 < mailfile
> 
> And spamd did not crash. The parameters are the ones being used when checking
> incomming mail.
> I'm not sure if this test is correct because "mailfile" already contains the
> X-Spam-* headers. I can filter those headers out and redo the test if you think
> this is necessary.
> 
> I upgraded my perl in the meantime to 5.14.2 and the error did not reoccur so
> far.

I'm going to close the error as invalid unless we can duplicate but the issue is LIKELY a perl issue so I think your upgrade to 5.14.2 may just resolve the issue.
Comment 4 Tim Gustafson 2012-02-16 02:30:44 UTC
> I'm going to close the error as invalid unless we can duplicate but the issue
> is LIKELY a perl issue so I think your upgrade to 5.14.2 may just resolve the
> issue.

I am seeing mostly the same error on my installation, except a slightly different line number (likely do to a slightly different version).  Specifically,

FreeBSD 9.0-RELEASE (i386)
Perl 5.14.2
SpamAssassin 3.3.2 (FreeBSD Port p5-Mail-SpamAssassin-3.3.2_6)

Out of memory during ridiculously large request at /usr/local/lib/perl5/site_perl/5.14.2/Mail/SpamAssassin/Logger.pm line 239.

I'm updating Perl now and will rebuild all my Perl ports, including SpamAssassin, shortly.
Comment 5 Kevin A. McGrail 2012-02-16 13:55:05 UTC
(In reply to comment #4)
> > I'm going to close the error as invalid unless we can duplicate but the issue
> > is LIKELY a perl issue so I think your upgrade to 5.14.2 may just resolve the
> > issue.
> 
> I am seeing mostly the same error on my installation, except a slightly
> different line number (likely do to a slightly different version). 
> Specifically,
> 
> FreeBSD 9.0-RELEASE (i386)
> Perl 5.14.2
> SpamAssassin 3.3.2 (FreeBSD Port p5-Mail-SpamAssassin-3.3.2_6)
> 
> Out of memory during ridiculously large request at
> /usr/local/lib/perl5/site_perl/5.14.2/Mail/SpamAssassin/Logger.pm line 239.
> 
> I'm updating Perl now and will rebuild all my Perl ports, including
> SpamAssassin, shortly.

Do you happen to have a copy of the message that caused the issue?
Comment 6 Tim Gustafson 2012-02-17 16:50:12 UTC
> Do you happen to have a copy of the message that caused the issue?

I'm sorry, but I don't.  It's hard for me to capture the messages that cause the crash because this is a very busy e-mail server and most messages are delivered off-server to end users where I can't peek into their mail file to examine the message that caused the problem (and there would be legal implications in doing so, of course).

Upgrading Perl and all the Perl modules did not help either; I'm still getting an occasional "Out of memory during ridiculously large request" messages.  (By the way, the spamass-milter is configured to only scan e-mails of 512kb or less, so I'm guessing that it's not complaining about the size of the message.  Or if it is, it must be getting confused about the message size somehow.)

So, for now I've got the spamass-milter configured to refuse e-mails when spamd is down, and I've got Nagios configured to re-start spamd when it crashes.  Obviously this is not a good long-term solution, but it's all I've got for the moment.
Comment 7 Stephen M 2012-03-20 13:07:15 UTC
Hello,

I've had the same problem last night, SA crashed with the following error:

Mar 19 23:53:06 shapai spamd[67540]: Out of memory during ridiculously large request at /usr/local/lib/perl5/site_perl/5.14.2/Mail/SpamAssassin/Logger.pm line 239.

My maillog contains the following:

Mar 19 23:53:06 shapai postfix/local[86791]: 390F211551: to=<sysmail@xxxxxxxxx.net>, orig_to=<root@xxxxxxxxx.net>, relay=local, delay=16, delays=0.36/0.01/0/15, dsn=2.0.0, status=sent (delivered to command: /usr/local/bin/procmail)
Mar 19 23:53:06 shapai postfix/qmgr[72002]: 390F211551: removed
Mar 19 23:53:06 shapai spamd[67540]: prefork: child states: III
Mar 19 23:53:06 shapai spamd[67540]: prefork: adjust: 3 idle children more than 2 maximum idle children. Decreasing spamd children: 86809 killed.
Mar 19 23:53:06 shapai spamd[67540]: spamd: handled cleanup of child pid [86809] due to SIGCHLD: interrupted, signal 2 (0002)
Mar 19 23:53:06 shapai spamd[67540]: Out of memory during ridiculously large request at /usr/local/lib/perl5/site_perl/5.14.2/Mail/SpamAssassin/Logger.pm line 239.

I'm using 6.4-RELEASE-p7 on a i386 CPU with perl-5.14.2_2. All ports are up to date.
Comment 8 Kevin A. McGrail 2012-03-20 13:18:47 UTC
Not discounting the issue but with a failure to reproduce and no email that appears to cause the issue, there is very little we can do.
Comment 9 Mark Martinec 2012-03-27 23:23:44 UTC
What is common between both submitted logs is that the error occurs in
a *parent* spamd process immediately after a child process termination
which terminated due to SIGINT:

spamd: handled cleanup of child pid [39936] due to SIGCHLD: interrupted, signal 2

The log message is produced by a sub child_handler, which is a signal
handling routine:
  $SIG{CHLD} = \&child_handler;

Perl docs warn against doing complex processing while handling a signal,
it is considered good practice to just set a flag in a pre-allocated
variable and leave the rest to the main program flow.

It does not surprise me that an error like "Out of memory" can occur
in such a scenario. What I don't know how to better handle the situation.
Perhaps just commenting out the call to info() in child_handler would
suffice.
Comment 10 Julian Yap 2012-04-05 21:10:12 UTC
This issue started occurring for me when I upgraded from to Perl 5.14.2 (running latest perl-5.14.2_2).

Issue does NOT occur on perl-5.10.1_6.

Exact same error message:
Out of memory during ridiculously large request at /usr/local/lib/perl5/site_perl/5.14.2/Mail/SpamAssassin/Logger.pm line 239.

I'm running FreeBSD 8.2-RELEASE.

I'm going to downgrade to Perl 5.10.1 now because this issue is killing me.
Comment 11 Kevin Fenzi 2012-04-16 03:34:11 UTC
We are seeing this in Fedora now as well... 

https://bugzilla.redhat.com/show_bug.cgi?id=812359

Fedora 16 also has perl-5.14.2
Comment 12 Mark Martinec 2012-04-24 00:40:25 UTC
Created attachment 5052 [details]
Avoid logging and any complex operations in a sigchld handler

Would something like the attached patch still do the job
while avoiding the problem?

(My brief testing under perl 5.14.2 looks alright even when prefork
is adjusting the number of child processes, but I'm not running spamd
in production, so more stress testing is appreciated).
Comment 13 Kevin A. McGrail 2012-05-14 15:55:55 UTC
(In reply to comment #12)
> Created attachment 5052 [details]
> Avoid logging and any complex operations in a sigchld handler
> 
> Would something like the attached patch still do the job
> while avoiding the problem?
> 
> (My brief testing under perl 5.14.2 looks alright even when prefork
> is adjusting the number of child processes, but I'm not running spamd
> in production, so more stress testing is appreciated).

It's been a few weeks so perhaps commit to trunk and let's get more production testing done?
Comment 14 Mark Martinec 2012-05-14 16:33:42 UTC
trunk (3.4.0):

Bug 6745: spamd crashes because of memory problems in Logger.pm
  Sending lib/Mail/SpamAssassin/Logger/Syslog.pm
  Sending spamd/spamd.raw
Committed revision 1338278.

Testing by sites that experienced the crashing would be most welcome.
Comment 15 Mark Martinec 2013-01-17 01:54:08 UTC
Tentatively closing, please re-open if reproducible with SpamAssassin 3.4.0
(or current trunk). The signal handler in spamd has been stripped of
logging calls, these are now handled outside of a signal handler.