SA Bugzilla – Bug 6745
spamd crashes because of memory problems in Logger.pm
Last modified: 2013-01-17 01:54:08 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'
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?
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.
(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.
> 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.
(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?
> 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.
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.
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.
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.
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.
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
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).
(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?
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.
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.