SpamAssassin version 3.2.5 running on Perl version 5.8.8 Solaris 9 SPARC For the past few days I have noticed SpamAssassin takes much longer to process messages between about 10:00am and 1:00pm EDT. It doesn't appear to be a memory problem or a problem with our DNS server. To try to figure it out, I got a message which took 58 seconds to process and ran it through "spamassassin -D", taking note of where the output paused for a long time. The results are shown below. Can anybody tell me what SpamAssassin is doing at that point? It says "compiled body tests", but we are not running a compiled configuration.
... [13557] dbg: Botnet: RDNS is 'mail4.smartdeals-mail.com' [13557] dbg: Botnet: HELO is 'mail4.smartdeals-mail.com' [13557] dbg: Botnet: EnvelopeFrom is [EMAIL PROTECTED] [13557] dbg: Botnet: mail domain is smartdeals-mail.com [13557] dbg: Botnet: SOHO hit [13557] dbg: rules: ran eval rule BOTNET_SOHO ======> got hit (1) [13557] dbg: dkim: performing public key lookup and signature verification [13557] warn: Use of uninitialized value in sprintf at /usr/local/lib/perl5/site_perl/5.8.8/Mail/SpamAssassin/Logger.pm line 213. [13557] dbg: dkim: signing identity: , d=smartdeals-mail.com, a=rsa-sha1, c=nofws [13557] dbg: dkim: public key lookup or verification failed: cannot change identity on Mail::DKIM::DkSignature at /usr/local/lib/perl5/site_perl/5.8.8/Mail/SpamAssassin/Plugin/DKIM.pm line 366 [13557] dbg: dkim: policy: performing lookup [13557] dbg: dkim: policy result neutral: v=spf1 mx ip4:69.56.11.40/29 -all [13557] dbg: Botnet: checking NORDNS [13557] dbg: Botnet: no trusted relays [13557] dbg: Botnet: get_relay good RDNS [13557] dbg: Botnet: IP is '69.56.11.43' [13557] dbg: Botnet: RDNS is 'mail4.smartdeals-mail.com' [13557] dbg: Botnet: HELO is 'mail4.smartdeals-mail.com' [13557] dbg: Botnet: NORDNS miss [13557] dbg: spf: def_whitelist_from_spf: [EMAIL PROTECTED] is not in DEF_WHITELIST_FROM_SPF [13557] dbg: FreeMail: replyto: skipping, envelope sender looks bulk [13557] dbg: spf: whitelist_from_spf: [EMAIL PROTECTED] is not in user's WHITELIST_FROM_SPF [13557] dbg: async: select found no responses ready (t.o.=0.0) [13557] dbg: async: completed in 0.913 s: URI-DNSBL, DNSBL:sbl.spamhaus.org.:197.37.56.69 [13557] dbg: async: completed in 0.912 s: URI-DNSBL, DNSBL:sbl.spamhaus.org.:1.15.56.69 [13557] dbg: async: completed in 0.917 s: URI-DNSBL, DNSBL:sbl.spamhaus.org.:7.37.42.70 [13557] dbg: async: completed in 0.915 s: URI-DNSBL, DNSBL:sbl.spamhaus.org.:42.142.25.69 [13557] dbg: async: completed in 0.920 s: URI-DNSBL, DNSBL:sbl.spamhaus.org.:225.145.64.69 [13557] dbg: async: completed in 0.914 s: URI-DNSBL, DNSBL:sbl.spamhaus.org.:248.184.52.216 [13557] dbg: async: completed in 0.919 s: URI-DNSBL, DNSBL:sbl.spamhaus.org.:200.92.251.63 [13557] dbg: async: completed in 0.918 s: URI-DNSBL, DNSBL:sbl.spamhaus.org.:4.32.56.69 [13557] dbg: dns: harvested completed queries [13557] dbg: rules: running body tests; score so far=12.48 ------------->>>>>> Here is where output paused for a long time <<<<<<--------------- [13557] dbg: rules: compiled body tests [13557] dbg: rules: ran body rule __SARE_PHONE_NUM ======> got hit: "866-315-8447" [13557] dbg: rules: ran body rule FB_GET_MEDS ======> got hit: "get a Medic" [13557] dbg: rules: ran body rule __ORNL_LOTTO_BINGO_6 ======> got hit: "email address" [13557] dbg: rules: ran body rule __HAS_ANY_EMAIL ======> got hit: "[EMAIL PROTECTED]" [13557] dbg: rules: ran body rule __NONEMPTY_BODY ======> got hit: "G" [13557] dbg: rules: ran body rule __KAM_LOTTO3 ======> got hit: "claim" [13557] dbg: rules: ran body rule ACT_NOW_CAPS ======> got hit: "Act Now" [13557] dbg: rules: ran body rule __DOS_LINK ======> got hit: "link" [13557] dbg: rules: running uri tests; score so far=14.075 [13557] dbg: rules: compiled uri tests [13557] dbg: rules: ran uri rule __DOS_HAS_ANY_URI ======> got hit: "m" [13557] dbg: rules: ran uri rule __LOCAL_PP_NONPPURL ======> got hit: "http://www.onewaytoadventure.com"; [13557] dbg: pdfinfo: Identified 0 possible mime parts that need checked for PDF content [13557] dbg: pdfinfo: set_tag called for PDFCOUNT 0 [13557] dbg: pdfinfo: set_tag called for PDFIMGCOUNT 0 [13557] dbg: rules: ran eval rule __TAG_EXISTS_BODY ======> got hit (1) [13557] dbg: IXHASH: IxHash querying Server nospam.login-solutions.de [13557] dbg: IXHASH: Computed hash-value de2b33469f305b6e93687e3eb710db4d via method 1 [13557] dbg: IXHASH: Now checking de2b33469f305b6e93687e3eb710db4d.nospam.login-solutions.de ...
