"Out of memory during request" error during OLE analysis

[Adam Bernstein]

I've got a particular email message causing a problem that looks like a 
SpamAssassin issue, except that it doesn't happen when we simply run SA 
directly on the message -- it only happens when MS is doing the scanning.

We're running the latest MS 4.70-1 (and SA 3.2.5) on FreeBSD 6.2 with Perl 
5.8.8, and we've got a message with an attachment that's causing MS to 
choke.  The attachment is an MS Word doc with base64 encoding, about 150KB, 
and the handoff to SA works fine but then something goes wrong:

Jul 28 13:31:29 smtp1 MailScanner[92705]: New Batch: Scanning 16
messages, 239966 bytes
Jul 28 13:31:58 smtp1 MailScanner[92705]: Spam Checks: Found 8 spam messages
Jul 28 13:31:58 smtp1 MailScanner[92705]: Spam Checks completed at 8417
bytes per second
Jul 28 13:32:27 smtp1 MailScanner[92705]: Skipping OLE document
unpacking due to OLE analysis failure

If we run MS with Debug Spamassassin = yes, we get this output (see error 
message at the bottom):

[80794] dbg: rules: running head tests; score so far=-2.6
[80794] dbg: locker: safe_lock: created
/var/spamassassin/auto-whitelist.mutex
[80794] dbg: locker: safe_lock: trying to get lock on
/var/spamassassin/auto-whitelist with 30 timeout
[80794] dbg: locker: safe_lock: link to
/var/spamassassin/auto-whitelist.mutex: link ok
[80794] dbg: auto-whitelist: tie-ing to DB file of type DB_File R/W in
/var/spamassassin/auto-whitelist
[80794] dbg: auto-whitelist: db-based vrasmussen at stny.rr.com|ip=74.65
scores 466/-1211.6
[80794] dbg: auto-whitelist: AWL active, pre-score: -2.6, autolearn
score: -2.6, mean: -2.6, IP: 74.65.68.5
[80794] dbg: auto-whitelist: add_score: new count: 467, new totscore:
-1214.2
[80794] dbg: auto-whitelist: DB addr list: untie-ing and unlocking
[80794] dbg: auto-whitelist: DB addr list: file locked, breaking lock
[80794] dbg: locker: safe_unlock: unlocked
/var/spamassassin/auto-whitelist.mutex
[80794] dbg: auto-whitelist: post auto-whitelist score: -2.6
[80794] dbg: rules: running body tests; score so far=-2.6
[80794] dbg: rules: running uri tests; score so far=-2.6
[80794] dbg: rules: running rawbody tests; score so far=-2.6
[80794] dbg: rules: running full tests; score so far=-2.6
[80794] dbg: rules: running meta tests; score so far=-2.6
[80794] dbg: plugin:
Mail::SpamAssassin::Plugin::AutoLearnThreshold=HASH(0x9e04d00)
implements 'autolearn_discriminator', priority 0
[80794] dbg: learn: auto-learn: currently using scoreset 3, recomputing
score based on scoreset 1
[80794] dbg: learn: auto-learn: message score: -2.6, computed score for
autolearn: 0
[80794] dbg: learn: auto-learn? ham=0.1, spam=10, body-points=0,
head-points=0, learned-points=-2.599
[80794] dbg: learn: auto-learn? yes, ham (0 < 0.1)
[80794] dbg: learn: initializing learner
[80794] dbg: learn: learning ham
[80794] dbg: eval: all '*From' addrs: vrasmussen at stny.rr.com
[80794] dbg: eval: all '*To' addrs: peter at rachel.org people at poclad.org
[80794] dbg: locker: safe_lock: created /var/spamassassin/bayes.mutex
[80794] dbg: locker: safe_lock: trying to get lock on
/var/spamassassin/bayes with 10 timeout
[80794] dbg: locker: safe_lock: link to /var/spamassassin/bayes.mutex:
link ok
[80794] dbg: bayes: tie-ing to DB file R/W /var/spamassassin/bayes_toks
[80794] dbg: bayes: tie-ing to DB file R/W /var/spamassassin/bayes_seen
[80794] dbg: bayes: found bayes db version 3
[80794] dbg: bayes:
432a63af2616531619871d341702255a9677ef97 at sa_generated already learnt
correctly, not learning twice
[80794] dbg: bayes: untie-ing
[80794] dbg: bayes: files locked, now unlocking lock
[80794] dbg: locker: safe_unlock: unlocked /var/spamassassin/bayes.mutex
[80794] dbg: learn: initializing learner
[80794] dbg: check: is spam? score=-2.6 required=5
[80794] dbg: check: tests=AWL,BAYES_00,SPF_PASS
[80794] dbg: check:
subtests=__CT,__CTYPE_HAS_BOUNDARY,__DOS_RCVD_SUN,__ENV_AND_HDR_FROM_MATCH,__HAS_MSGID,__HAS_RCVD,__HAS_SUBJECT,__LAST_UNTRUSTED_RELAY_NO_AUTH,__MIME_ATTACHMENT,__MIME_BASE64,__MIME_VERSION,__MISSING_REF,__MSOE_MID_WRONG_CASE,__NONEMPTY_BODY,__PART_STOCK_CD_F,__RCVD_IN_DNSWL,__RCVD_IN_SORBS,__RCVD_IN_ZEN,__SANE_MSGID,__TOCC_EXISTS
[80794] dbg: learn: auto-learn? ham=0.1, spam=10, body-points=0,
head-points=0, learned-points=-2.599
[80794] dbg: learn: auto-learn? yes, ham (0 < 0.1)
[80794] dbg: learn: initializing learner
[80794] dbg: learn: learning ham
[80794] dbg: eval: all '*From' addrs: vrasmussen at stny.rr.com
[80794] dbg: eval: all '*To' addrs: peter at rachel.org people at poclad.org
[80794] dbg: locker: safe_lock: created /var/spamassassin/bayes.mutex
[80794] dbg: locker: safe_lock: trying to get lock on
/var/spamassassin/bayes with 10 timeout
[80794] dbg: locker: safe_lock: link to /var/spamassassin/bayes.mutex:
link ok
[80794] dbg: bayes: tie-ing to DB file R/W /var/spamassassin/bayes_toks
[80794] dbg: bayes: tie-ing to DB file R/W /var/spamassassin/bayes_seen
[80794] dbg: bayes: found bayes db version 3
[80794] dbg: bayes:
432a63af2616531619871d341702255a9677ef97 at sa_generated already learnt
correctly, not learning twice
[80794] dbg: bayes: untie-ing
[80794] dbg: bayes: files locked, now unlocking lock
[80794] dbg: locker: safe_unlock: unlocked /var/spamassassin/bayes.mutex
[80794] dbg: learn: initializing learner

Out of memory during request for 268435464 bytes, total sbrk() is
313550848 bytes!
Failed.

So the problem seems to be happening during the learning phase in SA, 
except that we can run both spamassassin and sa-learn on this message from 
the command line, and scanning completes fine and gives the same scoring, 
and the learning happens fine and the command completes.  It's only when MS 
is calling SA that we see the crash.

I find various references to this error message on the net, mostly or 
always with BSD (not a Linux thing, or at least not commonly), and it seems 
to indicate that a memory allocation call is going a little crazy and 
continually grabbing bigger and bigger RAM until it hits the max for the 
process set by the operating system.  It's possible that raising that max 
would help us, but I think it would just delay the moment at which the 
process grabs all it can and fails.  So we need the call that allocates the 
memory to be fixed in some way.  Here's one instance of a similar problem, 
though maybe not precisely identical:

http://www.nntp.perl.org/group/perl.perl5.porters/2007/10/msg129981.html

Sorry this report is so long and nebulous, but this is a tricky one.  Any 
help out there?

Thanks!
        adam
        electric embers worker-owner, sysadmin