Andy: Does this happen with all messages, or only some?  If the latter, please
attach message(s) that will help reproduce the problem. Regardless, please
attach local.cf, user_prefs, and your *.pre files. These should help the
development team track it down.

Seems to be random messages. I'll try to to have SA scan one of my spamtrap 
addresses to see if I can find a message or two that triggers the errors. 

Spamd startup parms:

spamd_flags="-u spamd -x -d --max-conn-per-child=20 -r /var/run/spamd.pid"

local.cf:

# SpamAssassin config file

required_score          5.7
rewrite_header Subject  [SPAM _SCORE_]
report_safe             0
#add_header all DCC _DCCB_:_DCCR_
clear_headers
add_header all Report _REPORT_
use_bayes               1
bayes_auto_learn        1
bayes_auto_learn_threshold_nonspam -0.01
bayes_expiry_max_db_size 1000000

#use_auto_whitelist     0
skip_rbl_checks         1
#use_razor2                     1
#use_dcc                        1
#use_pyzor                      1
lock_method flock
#dcc_dccifd_path /usr/local/dcc
bayes_ignore_header X-Virus-Checked
bayes_ignore_header X-Virus-Scanned
bayes_ignore_header X-Virus-Status
bayes_ignore_header X-Greylist

#ok_languages            all
ok_locales              en
fold_headers            1

init.pre:


# RelayCountry - add metadata for Bayes learning, marking the countries
# a message was relayed through
#
# loadplugin Mail::SpamAssassin::Plugin::RelayCountry

# URIDNSBL - look up URLs found in the message against several DNS
# blocklists.
#
loadplugin Mail::SpamAssassin::Plugin::URIDNSBL

# Hashcash - perform hashcash verification.
#
loadplugin Mail::SpamAssassin::Plugin::Hashcash

# SPF - perform SPF verification.
#
loadplugin Mail::SpamAssassin::Plugin::SPF

v310.pre:


# DCC - perform DCC message checks.
#
# DCC is disabled here because it is not open source.  See the DCC
# license for more details.
#
loadplugin Mail::SpamAssassin::Plugin::DCC

# Pyzor - perform Pyzor message checks.
#
loadplugin Mail::SpamAssassin::Plugin::Pyzor

# Razor2 - perform Razor2 message checks.
#
# Razor2 is disabled here because it is not available for unlimited free
# use.  It is currently free for personal use, subject to capacity
# constraints.  See the Cloudmark SpamNet Service Policy for more details.
#
loadplugin Mail::SpamAssassin::Plugin::Razor2

# SpamCop - perform SpamCop message reporting
#
loadplugin Mail::SpamAssassin::Plugin::SpamCop

# AntiVirus - some simple anti-virus checks, this is not a replacement
# for an anti-virus filter like Clam AntiVirus
#
#loadplugin Mail::SpamAssassin::Plugin::AntiVirus

# AWL - do auto-whitelist checks
#
#loadplugin Mail::SpamAssassin::Plugin::AWL

# AutoLearnThreshold - threshold-based discriminator for Bayes auto-learning
#
loadplugin Mail::SpamAssassin::Plugin::AutoLearnThreshold

# TextCat - language guesser
#
loadplugin Mail::SpamAssassin::Plugin::TextCat

# AccessDB - lookup from-addresses in access database
#
#loadplugin Mail::SpamAssassin::Plugin::AccessDB

# WhitelistSubject - Whitelist/Blacklist certain subject regular expressions
#
loadplugin Mail::SpamAssassin::Plugin::WhiteListSubject

###########################################################################
# experimental plugins

# DomainKeys - perform DomainKeys verification
#
loadplugin Mail::SpamAssassin::Plugin::DomainKeys

# MIMEHeader - apply regexp rules against MIME headers in the message
#
loadplugin Mail::SpamAssassin::Plugin::MIMEHeader

# ReplaceTags
#
loadplugin Mail::SpamAssassin::Plugin::ReplaceTags

Created attachment 2982 [details]
Sample message

Ran the message through manually several times and could not re-create the
error. Tried both spamassassin & spamc.

btw it looks like this may be a side-effect of contention on your internet
connection, causing timeouts.  that's my guess...

(In reply to comment #4)
I am experiencing the same errors intermittently using Pyzor.pm:

Aug 26 08:40:12 yoda2 spamd[14005]: __alarm__ 
Aug 26 08:40:12 yoda2 spamd[14005]: __alarm__ 
Aug 26 08:40:12 yoda2 spamd[14005]: Use of uninitialized value in pattern match
(m//) at /usr/lib/perl5/site_perl/5.8.1/Mail/SpamAssassin/Plugin/Pyzor.pm line 287. 
Aug 26 08:40:12 yoda2 spamd[14005]: Use of uninitialized value in concatenation
(.) or string at
/usr/lib/perl5/site_perl/5.8.1/Mail/SpamAssassin/Plugin/Pyzor.pm line 295. 

I have tried to reproduce the errors parsing a message through spamassassin and
spamc but the behavior appears to be random and can not be reproduced as of yet. 

These errors started with the move to 3.1.0-rc1.

I just installed 3.1.0-RC2 from Duncan's .deb and can reproduce these Pyzor errors with any 
message sent through spamd.  Passing the same email through spamassassin does not print any 
error messages.

My server is Debian Sarge, with SA 3.1.0-rc2 from experimental running Linux 2.6.8 on x86.


Aug 31 15:16:30 ns1 spamd[6500]: spamd: connection from localhost [127.0.0.1] at port 51413 
Aug 31 15:16:30 ns1 spamd[6500]: spamd: setuid to sone succeeded 
Aug 31 15:16:30 ns1 spamd[6500]: spamd: processing message <q9.92,511$9.
9owKYI9wjej57s9K7box@br18.traintree.com> for sone:1003 
Aug 31 15:16:40 ns1 spamd[6500]: __alarm__ 
Aug 31 15:16:40 ns1 spamd[6500]: __alarm__ 
Aug 31 15:16:40 ns1 spamd[6500]: Use of uninitialized value in pattern match (m//) at /usr/share/
perl5/Mail/SpamAssassin/Plugin/Pyzor.pm line 297. 
Aug 31 15:16:40 ns1 spamd[6500]: Use of uninitialized value in concatenation (.) or string at /usr/
share/perl5/Mail/SpamAssassin/Plugin/Pyzor.pm line 305. 
Aug 31 15:16:41 ns1 spamd[6500]: spamd: identified spam (36.8/5.0) for sone:1003 in 10.9 
seconds, 1970 bytes. 
Aug 31 15:16:41 ns1 spamd[6500]: spamd: result: Y 36 - AWL,BAYES_99,BigEvilList_118,
DCC_CHECK,DIGEST_MULTIPLE,HTML_90_100,HTML_IMAGE_ONLY_16,HTML_IMAGE_RATIO_02,
HTML_MESSAGE,HTML_SHORT_LINK_IMG_2,MIME_HTML_ONLY,RATWARE_EFROM,
RAZOR2_CF_RANGE_51_100,RAZOR2_CF_RANGE_E4_51_100,RAZOR2_CF_RANGE_E8_51_100,
RAZOR2_CHECK,RCVD_IN_BL_SPAMCOP_NET,RCVD_IN_SBL,URIBL_BLACK,URIBL_JP_SURBL,URIBL_SBL,
URIBL_SC_SURBL,URIBL_WS_SURBL scantime=10.9,size=1970,user=sone,uid=1003,
required_score=5.0,rhost=localhost,raddr=127.0.0.1,rport=51413,mid=<q9.92_511$9.
9owKYI9wjej57s9K7box@br18.traintree.com>,bayes=0.999999999999999,autolearn=disabled 
Aug 31 15:16:41 ns1 spamd[6494]: prefork: child states: II 

reaiming

looking into it: these are *definitely* timeouts.  I think I see how there's a
window where there could be a problem btw.

Do the __alarm__ messages appear in other modules, or is it just Pyzor.pm?

Finally, is everyone reporting this on 3.1.0rc2?

Created attachment 3122 [details]
possible fix

ok, here's a possible fix...

Basically, there are a number of spots where the alarm isn't cleared up
*immediately* after the eval {...}; blocks.

Instead in a few of these cases, there's a few lines of code between the end of

eval {...} and the "alarm $oldalarm;" line.   This leaves a race condition,
where the code in eval {...}; could have failed for some reason, and in the
intervening code before the alarm cleanup, the alarm fires. The result of that
would be "__alarm__" in the logs, and the mail getting passed through
unscanned.

This patch fixes that, by resetting "alarm $oldalarm" immediately after every
eval {...} block and failure point, instead of at later points; it also sets
$oldalarm = undef; after doing this to avoid double-resetting.

it relies on alarm always returning a defined value, but that appears to be the
case.

Still getting the error on Pyzor.pm. Line numbers changed, but error is still 
there. Pulled down the latest SVN tarball (spamassassin_20050909103552.tar.gz) 
and applied the patch.  

Sep  9 09:27:25 python spamd[85869]: __alarm__
Sep  9 09:27:25 python spamd[85869]: __alarm__
Sep  9 09:27:25 python spamd[85869]: Use of uninitialized value in pattern 
match (m//) 
at /usr/local/lib/perl5/site_perl/5.8.6/Mail/SpamAssassin/Plugin/Pyzor.pm line 
304.
Sep  9 09:27:25 python spamd[85869]: Use of uninitialized value in 
concatenation (.) or string 
at /usr/local/lib/perl5/site_perl/5.8.6/Mail/SpamAssassin/Plugin/Pyzor.pm line 
312.


Errors I was getting from the other plugins seem to be gone except for an 
occasional one, but I'm not sure where it's from. Not Pyzor, since it hit on 
this message.

Sep  9 09:29:04 python spamd[85947]: alarm
Sep  9 09:29:04 python spamd[85947]: alarm
Sep  9 09:29:05 python spamd[85947]: spamd: identified spam (30.7/5.7) for 
spamd:1002 in 6.2 seconds, 5064 bytes.
Sep  9 09:29:05 python spamd[85947]: spamd: result: Y 30 - 
BAYES_99,DCC_CHECK,DIGEST_MULTIPLE,HTML_IMAGE_RATIO_02,HTML_MESSAGE,MIME_HTML_O
NLY,PYZOR_CHECK,SARE_FREE_WEBM_MailD,SARE_HEAD_HDR_XCLIHST,SARE_RD_TO_BAD_TLD,U
RIBL_BLACK,URIBL_JP_SURBL,URIBL_OB_SURBL 
scantime=6.2,size=5064,user=spamd,uid=1002,required_score=5.7,rhost=localhost.s
tepan.com,raddr=127.0.0.1,rport=61782,mid=(unknown),bayes=1,autolearn=spam

is there a possibility that the alarm is occurring as it's supposed to, and is
being handled correctly -- but when the die("__alarm__") is being called, some
logging code somewhere is getting hold of that message and outputting it,
instead of it being quietly handled in the error-handling blocks after the
eval{...} blocks?

because those log snippets you're posting seem to indicate that the message goes
on to complete its checks successfully afterwards.

Razor2.pm is the only plugin that uses "alarm" and not "__alarm__".  Flock.pm
also uses "alarm".  I'm pretty sure its just a case of us not trapping the die
message.

Created attachment 3127 [details]
patch to silence alarm timeout logging

Silences die messages for both alarm timeouts and broken pipes in the plugins,
both of which are logged anyway in debug mode.

Justin's patch can be applied in addition to this one.

looks sensible -- could someone try that in combination with my patch?

(I'm still wondering how the die messages "leak" to Logger, though.)

Still not quite right. Using the latest SVN tarball 
spamassassin_20050912104142.tar.gz and both patches.

Sep 12 09:24:56 python spamd[61995]: __alarm__ignore__
Sep 12 09:24:56 python spamd[61995]: __alarm__ignore__
Sep 12 09:24:56 python spamd[61995]: Use of uninitialized value in pattern 
match
 (m//) 
at /usr/local/lib/perl5/site_perl/5.8.6/Mail/SpamAssassin/Plugin/Pyzor.pm
 line 304.
Sep 12 09:24:56 python spamd[61995]: Use of uninitialized value in 
concatenation
 (.) or string 
at /usr/local/lib/perl5/site_perl/5.8.6/Mail/SpamAssassin/Plugin/
Pyzor.pm line 312.
Sep 12 09:24:57 python spamd[61995]: spamd: clean message (-0.2/5.7) for 
spamd:1
002 in 6.9 seconds, 6197 bytes.

That's weird, the alarm suppression worked fine when I forced a Razor timeout. 
The patch hunk against Logger.pm didn't fail, right?

I have no idea how $response[0] is becoming undefined after Pyzor.pm line 258
(after the Trackback match).

My bad... looks like Logger.pm wasn't even touched, no .rej or .orig files. 
Patched it again and it now looks like that error has been eliminated. Sorry 
about that!!!

I now seem to be getting quite a few of the following errors, not sure if it's 
related or not. Pyzor does work, I do get some messages being tagged by Pyzor 
and the error doesn't occur on every message that doesn't get tagged either, 
just the occasional message.

Sep 13 09:10:43 python spamd[11339]: internal error
Sep 13 09:10:43 python spamd[11339]: pyzor: check failed: internal error
Sep 13 09:10:43 python spamd[11339]: spamd: clean message (-0.0/5.7) for 
spamd:1002 in 4.5 seconds, 197493 bytes.
Sep 13 09:10:43 python spamd[11339]: spamd: result: .  0 - 
BAYES_00,MIME_BASE64_NO_NAME  
scantime=4.5,size=197493,user=spamd,uid=1002,required_score=5.7,rhost=localhost
.stepan.com,raddr=127.0.0.1,rport=58788,mid=<ISSMTP.2002_3_.20050912144646.2824
O@unilever.com>,bayes=0,autolearn=no

good to hear!  sounds like the fix works, then.

Sep 13 09:10:43 python spamd[11339]: pyzor: check failed: internal error

this is simply indicative of a pyzor timeout, I think.

Created attachment 3134 [details]
merge of both patches

OK, here's a single-patch merge of the two patches; there was a conflict on a
couple of files, so a little hand-editing was required.  Please review.

Consolidated patch seems to be working fine with the latest tarball. 
(spamassassin_20050913162404.tar.gz) Will keep an eye on it.

Patch applies cleanly to both trunk and 3.1

+1

+1

Sep 13 09:10:43 python spamd[11339]: pyzor: check failed: internal error

...is actually a Pyzor error, but as far as I know, it's not something caused by
SA.  I do think it's something we DO want to log though so that people can
attempt to fix their Pyzor installation, if that's possible (I don't know I
don't use Pyzor).

[dos@silver trunk]$ svn commit
Committed revision 280717.

[dos@silver 3.1]$ svn commit
Committed revision 280718.