[Mimedefang] Potential SA Problem for load_scoreonly_sql

Fri Jun 1 18:13:31 EDT 2007

In one of my mimedefang filters, I have a rule that checks for a specific 
recipient domain and loads the domain-wide sql prefs for SpamAssassin.  I do 
not load user specific sql prefs.

The code looks like:

      if ($spamtest_enabled < 1 && $authorized_sender < 1 && $recip =~ 
m/\@domainname\.com>?$/i ) {
        $spamtest_enabled++;
        if (defined($sa_object)) {
          $sa_object->load_scoreonly_sql('masamail') || md_syslog('warning', 
"load_scoreonly_sql failed for $recip");
          #$sa_object->signal_user_changed({ username => 'domainname'}, 
user_dir => undef);
          md_syslog('warning', "Enabling SPAM Filter from MD because of 
$recip");
        }
        $rewrite_subject = 1;
        $report_safe = 1;
        $suspect_spammy_country_tlds = 0;
     }

Checking the database, you can see that the user has a preference of 6.5 for 
the spam threshold and that the fallback @global value is the same.

select username,value,preference from userpref where (username = 'masamail' 
or username='@global') and preference='required_hits' order by username 
desc;
+----------+-------+---------------+
| username | value | preference    |
+----------+-------+---------------+
| masamail | 6.5   | required_hits |
| @GLOBAL  | 6.5   | required_hits |
+----------+-------+---------------+
2 rows in set (0.01 sec)

However, occassionally, we are seeing 5.0 being used as the threshold.  This 
default of 5 ONLY exists in the /etc/mail/sa-mimedefang.cf.

The logging we are doing doesn't agree with this being used though and we 
don't have a single user with a threshold of 5.0.

>From the logs, you can see that the filter is activated on this user which 
makes the database call above without an error.  But we are seeing a 5.0 
threshold rather than the requires 6.5 threshold for SPAM
Jun 1 14:33:55 intel1 mimedefang.pl[16546]: Enabling SPAM Filter from MD 
because of <SDunlop at domain2.com>

Jun 1 14:34:01 intel1 mimedefang.pl[16546]: Yes, hits=5.5 required=5.0 
^Itests=AWL,DK_POLICY_SIGNSOME,HTML_MESSAGE,KAM_RPTR_SUSPECT, ^I 
KAM_RR_60_79,RM_rb_ANCHOR,RM_rb_BODY,RM_rb_BREAK, ^I 
RM_rb_FONT,RM_rb_HTML,RM_rb_PARA,RM_rb_TITLE ^Iversion=3.1.4

Jun 1 14:34:01 intel1 mimedefang.pl[16546]: 
MDLOG,l51IXqpg025576,spam,5.476,216.254.58.186,<fdechow at domain1.com>,<sdunlop at domain2.com>,Re: 
KIS update

Today, for example, of all the mail processed on this server, we saw 174 
emails tested against a 5.0 threshold.  This is a drop in the bucket 
compared to the overall number so I think we are seeing some race condition 
or bug.

I've changed the sa-mimedefang.cf file to 6.4 so I can see if that causes 
the race condition to occur at 6.4 rather than 5 which will pinpoint that 
it's using the sa-mimedefang.cf default somehow instead of the sql-based 
preferences.

>From these tests, it looks like 6.4 is being used which means that despite 
my load_scoreonly_sql call we are using the default preferences.  However, 
the issue is NOT consistent.  For example, here are 5 emails to one domain 
all within a second.  The first 4 get the default config and the 5th gets 
the correct sql based configuration:

Jun 1 17:43:23 intel1 mimedefang.pl[13576]: Enabling SPAM Filter from MD 
because of <amaloney at domain3.org>

Jun 1 17:43:30 intel1 mimedefang.pl[13576]: SA-DEBUG: 
<amaloney at domain3.org> - Yes, hits=50.2 required=6.4 
^Itests=DK_POLICY_SIGNSOME,FM_NO_STYLE,HTML_FONT_BIG,HTML_MESSAGE, ^I 
KAM_RPTR_MISSING,KAM_RR_80_99,KAM_TIME, ^I 
RAZOR2_CF_RANGE_51_100,RAZOR2_CF_RANGE_E4_51_100, ^I 
RAZOR2_CF_RANGE_E8_51_100,RAZOR2_CHECK,RCVD_IN_DSBL, ^I 
RCVD_IN_NJABL_DUL,RCVD_IN_SORBS_DUL,RCVD_IN_WHOIS_INVALID, ^I 
REPLICA_WATCH,RM_rb_ANCHOR,RM_rb_FONT,RM_rb_HTML, ^I 
SARE_SPEC_ROLEX,SARE_SPEC_ROLEX_REP,UNRESOLVED_TEMPLATE, ^I 
UOLCC_ROLEX_BODY1,UOLCC_ROLEX_BODY3,UOLCC_WATCH_REPL, ^I 
URIBL_BLACK,URIBL_JP_SURBL,URIBL_OB_SURBL,URIBL_SBL, ^I 
URIBL_SC_SURBL,URIBL_WS_SURBL ^Iversion=3.1.4

Jun 1 17:43:47 intel1 mimedefang.pl[13643]: Enabling SPAM Filter from MD 
because of <tzink at domain3.org>

Jun 1 17:43:48 intel1 mimedefang.pl[13672]: Enabling SPAM Filter from MD 
because of <apoole at domain3.org>

Jun 1 17:43:48 intel1 mimedefang.pl[13685]: Enabling SPAM Filter from MD 
because of <cviladesau at domain3.org>

Jun 1 17:43:58 intel1 mimedefang.pl[13643]: SA-DEBUG: <tzink at domain3.org> - 
Yes, hits=37.4 required=6.4 
^Itests=DK_POLICY_SIGNSOME,FB_GET_MEDS,HELO_DYNAMIC_IPADDR, ^I 
HTML_MESSAGE,KAM_6C822ECF,KAM_RPTR_SUSPECT,KAM_RR_100, ^I 
LOCAL_OBFU_GENERIC,ONLINE_PHARMACY,RAZOR2_CF_RANGE_51_100, ^I 
RAZOR2_CF_RANGE_E4_51_100,RAZOR2_CF_RANGE_E8_51_100, ^I 
RAZOR2_CHECK,RM_rb_ANCHOR,RM_rb_BODY,RM_rb_HTML,RM_rb_PARA, ^I 
SUBJ_ILLEGAL_CHARS,URIBL_BLACK,URIBL_JP_SURBL ^Iversion=3.1.4

Jun 1 17:43:58 intel1 mimedefang.pl[13685]: SA-DEBUG: 
<cviladesau at domain3.org> - Yes, hits=29.8 required=6.4 
^Itests=DC_IMG_HTML_RATIO,DC_IMG_TEXT_RATIO,DK_POLICY_SIGNSOME, ^I 
FM_NO_STYLE,HTML_IMAGE_ONLY_16,HTML_MESSAGE, ^I 
HTML_SHORT_LINK_IMG_2,KAM_RPTR_SUSPECT,KAM_RR_40_59, ^I 
LOCAL_OBFU_CIALIS,LOCAL_OBFU_CIALIS_SUBJ,MIME_HTML_MOSTLY, ^I 
MPART_ALT_DIFF,RAZOR2_CF_RANGE_51_100, ^I 
RAZOR2_CF_RANGE_E4_51_100,RAZOR2_CF_RANGE_E8_51_100, ^I 
RAZOR2_CHECK,RCVD_IN_BL_SPAMCOP_NET,RCVD_IN_NJABL_DUL, ^I 
RCVD_IN_SORBS_DUL,RM_rb_ANCHOR,RM_rb_BREAK,RM_rb_DIV, ^I 
RM_rb_FONT,RM_rb_HTML,URIBL_BLACK,URIBL_JP_SURBL ^Iversion=3.1.4

Jun 1 17:43:58 intel1 mimedefang.pl[13672]: SA-DEBUG: <apoole at domain3.org> - 
Yes, hits=26.8 required=6.4 
^Itests=DK_POLICY_SIGNSOME,HELO_DYNAMIC_DHCP,HELO_DYNAMIC_IPADDR, ^I 
HTML_MESSAGE,KAM_RPTR_SUSPECT,KAM_RR_100, ^I 
RAZOR2_CF_RANGE_51_100,RAZOR2_CF_RANGE_E4_51_100, ^I 
RAZOR2_CF_RANGE_E8_51_100,RAZOR2_CHECK,RCVD_IN_NJABL_DUL, ^I 
RCVD_IN_SORBS_DUL,RM_rb_ANCHOR,RM_rb_BODY,RM_rb_BREAK, ^I 
RM_rb_FONT,RM_rb_HTML,RM_rb_PARA,RM_rb_TITLE,URIBL_BLACK, ^I URIBL_JP_SURBL 
^Iversion=3.1.4

Jun 1 17:44:10 intel1 mimedefang.pl[13616]: Enabling SPAM Filter from MD 
because of <cviladesau at domain3.org>

Jun 1 17:44:14 intel1 mimedefang.pl[13616]: SA-DEBUG: 
<cviladesau at domain3.org> - Yes, hits=32.0 required=6.5 
^Itests=DC_IMG_HTML_RATIO,DC_IMG_TEXT_RATIO,DK_POLICY_SIGNSOME, ^I 
FB_BUY_NOW,FM_NO_STYLE,HTML_IMAGE_ONLY_16,HTML_MESSAGE, ^I 
HTML_SHORT_LINK_IMG_2,KAM_RPTR_SUSPECT,KAM_RR_80_99, ^I 
MIME_HTML_MOSTLY,MPART_ALT_DIFF,RAZOR2_CF_RANGE_51_100, ^I 
RAZOR2_CF_RANGE_E4_51_100,RAZOR2_CF_RANGE_E8_51_100, ^I 
RAZOR2_CHECK,RCVD_IN_NJABL_DUL,RCVD_IN_SORBS_DUL, ^I 
RM_rb_ANCHOR,RM_rb_BREAK,RM_rb_DIV,RM_rb_FONT,RM_rb_HTML, ^I 
SUBJECT_FUZZY_MEDS,URIBL_BLACK,URIBL_JP_SURBL, ^I URIBL_SC_SURBL 
^Iversion=3.1.4

Right now, I've added logging for the actual SQL queries by modifying SA's 
SQL.pm and I'll report back more on that.

Anyone ever seen this before?  These are older versions of the software but 
I do have logs showing it working exactly perfectly in between a few of the 
race conditions where it is not working.  I'd rather not upgrade everything 
on a goose chase.

Regards,
KAM 