Bug 4309 - Spamc/d should log memory and message-id after processing
Summary: Spamc/d should log memory and message-id after processing
Status: NEW
Alias: None
Product: Spamassassin
Classification: Unclassified
Component: spamc/spamd (show other bugs)
Version: unspecified
Hardware: Other other
: P3 enhancement
Target Milestone: Future
Assignee: SpamAssassin Developer Mailing List
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2005-05-06 04:36 UTC by Loren Wilton
Modified: 2006-09-05 07:48 UTC (History)
0 users



Attachment Type Modified Status Actions Submitter/CLA Status

Note You need to log in before you can comment on or make changes to this bug.
Description Loren Wilton 2005-05-06 04:36:09 UTC
There is great discussion at the moment about spamd children seemingly still 
growing out of control.  Certainly this has been a problem throught the 3.0x 
release cycle.  It never seems possible to obtain any informaiton to duplicate 
the problem, so not much can be done about it.

Spamd should log its memory size and the message-id of the message just 
processed at the completion of processing messages.  Obviously this shoudl 
include the spamd child id, so the message stream through a particulr errant 
child can be reconstructed accurately.

The child should ALSO log when it does anything unusual such as awl or bayes 
processing, logging the fact that it did it, and logging the memory size at the 
end of the action.  This would make it obvious if the growth were related to 
these actions rather than normal mail processing.

Even if my other suggestion (that the child die if it gets fat) is implemented, 
this should be implemented also, so that the reasons for obesity can be 
determined.
Comment 1 Justin Mason 2005-05-06 10:23:48 UTC
message-id: +1.  I really agree this is a good plan.

memory size: not so easy -- we can't actually get that info reliably on all
platforms :(

awl/bayes: it should already be doing that. hmm
Comment 2 Theo Van Dinter 2005-05-06 10:36:55 UTC
Subject: Re:  Spamc/d should log memory and message-id after processing

On Fri, May 06, 2005 at 10:23:48AM -0700, bugzilla-daemon@bugzilla.spamassassin.org wrote:
> message-id: +1.  I really agree this is a good plan.

Don't we do this already?

May  1 04:14:04 eclectic spamd[3094]: processing message
<200505010814.j418E3512935@franz.videotron.net> for timex:507. 

Comment 3 Justin Mason 2005-05-06 10:53:19 UTC
I think the idea is to log the Message-ID on errors and warns, too.
that way the log that now contains:

spamd [5304]: 30 second timeout while trying to CHECK

will be:

spamd [5304]: id=<20050430072654.GA24823@stripey.com>: 30 second timeout while
trying to CHECK

In other words, attach the message-id to every error message.

I think an admin could probably take the process-ID and work backwards to find
the corresponding Message-ID in the "processing message" line, but this makes
things a bit easier.
Comment 4 Loren Wilton 2005-05-06 19:25:38 UTC
Subject: Re:  Spamc/d should log memory and message-id after processing

> memory size: not so easy -- we can't actually get that info reliably on
all
> platforms :(

My impression of "unreliable" is that it may tend to over/under report,
depending on the platform.

However, that is immaterial.  It is the difference between two reports that
is interesting.  And no matter how badly the memory report is mangled, it is
highly improbable that it would show a decrease when top would show an
increase.

The idea is that when someone complains that spamd is taking 800 megs, being
able to track the reported number of "800" (whatever the "real" number might
be) back to some initial number that is probably in the 20-60 meg range.

Comment 5 Loren Wilton 2005-05-06 19:33:41 UTC
Subject: Re:  Spamc/d should log memory and message-id after processing

> I think the idea is to log the Message-ID on errors and warns, too.
> that way the log that now contains:
>
> In other words, attach the message-id to every error message.

That might be a good idea, but it wasn't what I had originally suggested.
My proginal suggestion was for a new log entry that said something like
(format it as you will):

    Spamd pid 1234: 14:32:51 Processed message <> ram <nn>.

If you want to add in a processing time for the message, that would be a
bonus.

If you want to combine the memory report with an existing "completed
processing" message, that would be fine, AS LONG as the report shows up in
the same format for all messages, no matter how the processing turned out.
And AS LONG as the memory report also appears on bayes/awl update
completions.

The idea is simply to track spamd memory usage per message, also showing the
message processing sequence, on the assumption that memory growth is related
more to the sequence than to an individual message.

Note: It now occurs to me that since spamd can get aborted, it might make
sense to report "started processing message <> ram nn", so that a log entry
will show up even if a message aborts.  In this case you obviously wouldn't
need a message at the end of processing, since the previous message
presumably ended with the amount of ram this one is starting at.

Comment 6 Justin Mason 2005-05-06 20:04:01 UTC
no, on some platforms you could only get it by parsing "ps" output -- which is
slow, heavyweight, and kludgy.
Comment 7 Justin Mason 2005-05-10 23:56:56 UTC
fwiw, it appears we can get the process size easily enough on linux:
/proc/self/status contains

VmSize:     1868 kB
VmLck:         0 kB
VmRSS:       648 kB
VmData:      160 kB
VmStk:        84 kB

etc. easily parseable.  the Apache::SizeLimit CAVEATS section lists a few more
platform-specific tricks.
Comment 8 Daniel Quinlan 2005-05-11 00:36:06 UTC
Logging memory usage is fine and all, but we should just start a new child
when memory usage goes over a certain point.
Comment 9 Loren Wilton 2005-05-11 01:14:43 UTC
Subject: Re:  Spamc/d should log memory and message-id after processing

> Logging memory usage is fine and all, but we should just start a new child
> when memory usage goes over a certain point.

I certainly won't object to that.  :-)  However, that still requires looking
at the momry usage, and deciding what that limit is.  Which might be a tad
hard to do with a single constant, as various systems seem to have different
ideas of memory usage values.

Still though I think logging it should also be done, so that it might be
possible to find out WHY memory usage goes Boom! (as one recent thread had
it) and then maybe fix the root cause, rather than just having a handy rifle
to shoot the offenders.

Comment 10 Justin Mason 2005-05-11 10:44:01 UTC
yeah, restarting if RAM usage goes over a certain size would be the #1 useful
feature that would fall out of this.  but as Loren says, being able to figure
out which message caused the RAM explosion -- or at least that message's
Message-Id -- allows us to receive bug reports ;) and would be very handy.

ok, I can add a plugin that'd do this pretty easily; a couple of hooks in spamd
is all it'd take.   Mail::SpamAssassin::Plugin::SpamdSizeLimit... sound useful?
Comment 11 Bob Menschel 2005-07-13 23:02:57 UTC
Triage: Based on the recorded discussion, at least some of these ideas should be
implemented.  Those that aren't yet in 3.1.0 probably should be targeted for 3.1.1.
Comment 12 Theo Van Dinter 2006-02-22 23:05:55 UTC
actually, I think this is major enough to be bumped to 3.2.
Comment 13 Justin Mason 2006-09-05 14:48:05 UTC
This is now eminently implementable in plugins; the 'set_spamd_result_item'
API on PerMsgStatus allows arbitrary name=value pairs to be added to the spamd
"result" line logged to syslog, and the 'spamd_child_post_connection_close'
plugin hook allows a plugin to run code after each message scanned by a child.  

Moving away from the 3.2.0 milestone, since it's now not limited by code in SVN,
just by someone stepping up to write it ;)