On 29-Oct-04, at 11:13 AM, Michael Parker wrote:
On Fri, Oct 29, 2004 at 05:04:03AM -0400, Jason Lixfeld wrote:-Spamd's logfile below shows the from plixfeld-at-andromedas.com to
jason-at-lixfeld.ca. The system things the username is "nobody". I've
tried with both the -q and -Q spamd switches to no avail.
-anyone know what's going on here?
=== 8< ===
logmsg: connection from localhost [127.0.0.1] at port 57943
debug: Conf::SQL: executing SQL: SELECT preference, value FROM userpref
WHERE username = 'nobody' OR username = '$GLOBAL' OR username =
CONCAT('%',NULL) ORDER BY username ASC
debug: retrieving prefs for nobody from SQL server
debug: user has changed
You need to configure sa-exim to pass the Username header to spamd. Most likely what is happening is with no Username header spamd is falling back to user nobody.
Google turned up this link on a seach for sa-exim Username Header:
http://www.linuxpowered.com/LDP/HOWTO/Spam-Filtering-for-MX/exim- sa.html
Hope that helps.
Indeed. I added the appropriate stuff and it now expands the recipient, however it doesn't recognize seem to recognize any of the preferences I have set for myself. The SA debug below appears to get the correct info now to get the correct preferences, but they don't seem to be getting applied:
mysql> select * from spamassassin.userpref where username = 'jason-at-lixfeld.ca';
+---------------------+------------------------- +-------------------------------+--------+
| username | preference | value | prefid |
+---------------------+------------------------- +-------------------------------+--------+
| jason-at-lixfeld.ca | whitelist_from | plixfeld-at-andromedas.com | 3 |
| jason-at-lixfeld.ca | score USER_IN_WHITELIST | -10 | 5 |
+--===----------------+------------------------- +-------------------------------+--------+
2 rows in set (0.00 sec)
mysql>
Exim log:
2004-10-29 14:05:58 1CNb8P-00003A-8i SA: Debug: SAEximRunCond expand returned: '1'
2004-10-29 14:05:58 1CNb8P-00003A-8i SA: Debug: check succeeded, running spamc
2004-10-29 14:06:00 1CNb8P-00003A-8i SA: Debug: SARewriteBody == 1, rewriting message body
2004-10-29 14:06:00 1CNb8P-00003A-8i SA: Debug: SAEximRejCond expand returned: '1'
2004-10-29 14:06:00 1CNb8P-00003A-8i SA: Debug: Writing message to /var/spool/exim/SAtempreject/new/1CNb8P-00003A-8i
2004-10-29 14:06:00 1CNb8P-00003A-8i SA: Action: temporarily rejected message: score=10.9 required=5.0 trigger=9.0 (scanned
in 2/2 secs | Message-Id: 1CNb8P-00003A-8i). From <plixfeld-at-andromedas.com> (host=cpe000625c4faac-cm014160000219.cpe.net.c
able.rogers.com [65.50.84.33]) for jason-at-lixfeld.ca
2004-10-29 14:06:00 1CNb8P-00003A-8i F=plixfeld-at-andromedas.com H=cpe000625c4faac-cm014160000219.cpe.net.cable.rogers.com (f
oo.com) [65.50.84.33] P=smtp temporarily rejected by local_scan(): Please try again later
Spamd Debug:
logmsg: connection from localhost [127.0.0.1] at port 54837
debug: Conf::SQL: executing SQL: SELECT preference, value FROM userpref WHERE username = 'jason-at-lixfeld.ca' OR username = '$GLOBAL' OR username = CONCAT('%','lixfeld.ca') ORDER BY username ASC
debug: retrieving prefs for jason-at-lixfeld.ca from SQL server
debug: user has changed
debug: bayes: 223 tie-ing to DB file R/O /root/.spamassassin/bayes_toks
debug: bayes: 223 tie-ing to DB file R/O /root/.spamassassin/bayes_seen
debug: bayes: found bayes db version 3
debug: bayes: Not available for scanning, only 100 spam(s) in Bayes DB < 200
debug: bayes: 223 untie-ing
debug: bayes: 223 untie-ing db_toks
debug: bayes: 223 untie-ing db_seen
debug: Score set 1 chosen.
logmsg: checking message (unknown) for jason-at-lixfeld.ca:0.
debug: bayes: 223 tie-ing to DB file R/O /root/.spamassassin/bayes_toks
debug: bayes: 223 tie-ing to DB file R/O /root/.spamassassin/bayes_seen
debug: bayes: found bayes db version 3
debug: bayes: Not available for scanning, only 100 spam(s) in Bayes DB < 200
debug: bayes: 223 untie-ing
debug: bayes: 223 untie-ing db_toks
debug: bayes: 223 untie-ing db_seen
debug: received-header: parsed as [ ip=65.50.84.33 rdns=cpe000625c4faac-cm014160000219.cpe.net.cable.rogers.com helo=foo.com by=eshara.ebit.ca ident= envfrom= intl=0 id=1CNb8P-00003A-8i ]
debug: is Net::DNS::Resolver available? yes
debug: Net::DNS version: 0.48
debug: looking up A records for 'eshara.ebit.ca'
debug: A records for 'eshara.ebit.ca': 69.90.17.218
debug: looking up A records for 'eshara.ebit.ca'
debug: A records for 'eshara.ebit.ca': 69.90.17.218
debug: received-header: 'by' eshara.ebit.ca has public IP 69.90.17.218
debug: received-header: relay 65.50.84.33 trusted? no internal? no
debug: metadata: X-Spam-Relays-Trusted:
debug: metadata: X-Spam-Relays-Untrusted: [ ip=65.50.84.33 rdns=cpe000625c4faac-cm014160000219.cpe.net.cable.rogers.com helo=foo.com by=eshara.ebit.ca ident= envfrom= intl=0 id=1CNb8P-00003A-8i ]
debug: ---- MIME PARSER START ----
debug: main message type: text/plain
debug: parsing normal part
debug: added part, type: text/plain
debug: ---- MIME PARSER END ----
debug: decoding: no encoding detected
debug: Message too short for language analysis
debug: is Net::DNS::Resolver available? yes
debug: Net::DNS version: 0.48
debug: all '*From' addrs:
debug: Running tests for priority: 0
debug: running header regexp tests; score so far=0
debug: all '*To' addrs: jason-at-lixfeld.ca
debug: forged-HELO: from=rogers.com helo=foo.com by=eshara.ebit.ca
debug: forged-HELO: mismatch on HELO: 'foo.com' != 'rogers.com'
debug: running body-text per-line regexp tests; score so far=0.069
debug: running uri tests; score so far=0.069
debug: Razor2 is available
debug: entering helper-app run mode
Razor-Log: Computed razorhome from env: /root/.razor
Razor-Log: No razorhome found, using all defaults
Razor-Log: No razor-agent.conf found, using defaults.
Oct 29 14:05:57.391408 check[223]: [ 2] [bootup] Logging initiated LogDebugLevel=9 to stdout
Oct 29 14:05:57.391787 check[223]: [ 5] computed razorhome=, conf=, ident=identity
Oct 29 14:05:57.392056 check[223]: [ 8] Client supported_engines: 4 8
Oct 29 14:05:57.392681 check[223]: [ 8] prep_mail done: mail 1 headers=227, mime0=40
Oct 29 14:05:57.392957 check[223]: [ 7] Can't read file servers.discovery.lst, looking relatve to
Oct 29 14:05:57.393085 check[223]: [ 5] Can't read file /servers.discovery.lst: No such file or directory
Oct 29 14:05:57.393208 check[223]: [ 7] Can't read file servers.nomination.lst, looking relatve to
Oct 29 14:05:57.393296 check[223]: [ 5] Can't read file /servers.nomination.lst: No such file or directory
Oct 29 14:05:57.393350 check[223]: [ 7] Can't read file servers.catalogue.lst, looking relatve to
Oct 29 14:05:57.393398 check[223]: [ 5] Can't read file /servers.catalogue.lst: No such file or directory
Oct 29 14:05:57.393568 check[223]: [ 5] no listfile: servers.catalogue.lst
Oct 29 14:05:57.393653 check[223]: [ 6] no discovery listfile: servers.discovery.lst
Oct 29 14:05:57.393696 check[223]: [ 5] Finding Discovery Servers via DNS in the razor2.cloudmark.com zone
Oct 29 14:05:57.475436 check[223]: [ 6] Found 1 Discovery Servers via DNS in the razor2.cloudmark.com zone
Oct 29 14:05:57.475694 check[223]: [ 8] Checking with Razor Discovery Server 66.151.150.12
Oct 29 14:05:57.475856 check[223]: [ 6] No port specified, using 2703
Oct 29 14:05:57.475944 check[223]: [ 5] Connecting to 66.151.150.12 ...
Oct 29 14:05:57.592398 check[223]: [ 8] Connection established
Oct 29 14:05:57.592542 check[223]: [ 4] 66.151.150.12 >> 35 server greeting: sn=D&srl=460&a=l&a=cg&ep4=7542-10
Oct 29 14:05:57.592830 check[223]: [ 4] 66.151.150.12 << 12
Oct 29 14:05:57.592891 check[223]: [ 6] a=g&pm=csl
Oct 29 14:05:57.652104 check[223]: [ 4] 66.151.150.12 >> 76
Oct 29 14:05:57.652205 check[223]: [ 6] response to sent.1
-csl=?
wonder.cloudmark.com
thrill.cloudmark.com
pride.cloudmark.com
.
Oct 29 14:05:57.652496 check[223]: [ 8] Discovery Server 66.151.150.12 replying with csl=wonder.cloudmark.com
Oct 29 14:05:57.652545 check[223]: [ 8] Discovery Server 66.151.150.12 replying with csl=thrill.cloudmark.com
Oct 29 14:05:57.652588 check[223]: [ 8] Discovery Server 66.151.150.12 replying with csl=pride.cloudmark.com
Oct 29 14:05:57.652740 check[223]: [ 4] 66.151.150.12 << 12
Oct 29 14:05:57.652780 check[223]: [ 6] a=g&pm=nsl
Oct 29 14:05:57.712652 check[223]: [ 4] 66.151.150.12 >> 51
Oct 29 14:05:57.712752 check[223]: [ 6] response to sent.2
-nsl=?
folly.cloudmark.com
joy.cloudmark.com
.
Oct 29 14:05:57.712932 check[223]: [ 8] Discovery Server 66.151.150.12 replying with nsl=folly.cloudmark.com
Oct 29 14:05:57.712979 check[223]: [ 8] Discovery Server 66.151.150.12 replying with nsl=joy.cloudmark.com
Oct 29 14:05:57.713122 check[223]: [ 5] no razorhome, not caching server info to disk
Oct 29 14:05:57.713214 check[223]: [ 6] losing old server connection, 66.151.150.12, for new server, thrill.cloudmark.com
Oct 29 14:05:57.713261 check[223]: [ 5] disconnecting from server 66.151.150.12
Oct 29 14:05:57.713404 check[223]: [ 4] 66.151.150.12 << 5
Oct 29 14:05:57.713444 check[223]: [ 6] a=q
Oct 29 14:05:57.713511 check[223]: [ 5] Connecting to thrill.cloudmark.com ...
Oct 29 14:05:57.830516 check[223]: [ 8] Connection established
Oct 29 14:05:57.830662 check[223]: [ 4] thrill.cloudmark.com >> 36 server greeting: sn=C&srl=5047&a=l&a=cg&ep4=7542-10
Oct 29 14:05:57.831071 check[223]: [ 4] thrill.cloudmark.com << 25
Oct 29 14:05:57.831167 check[223]: [ 6] cn=razor-agents&cv=2.61
Oct 29 14:05:57.831439 check[223]: [ 4] thrill.cloudmark.com << 14
Oct 29 14:05:57.831534 check[223]: [ 6] a=g&pm=state
Oct 29 14:05:57.976083 check[223]: [ 4] thrill.cloudmark.com >> 141
Oct 29 14:05:57.976183 check[223]: [ 6] response to sent.5
-sv=3.44
sn=C
zone=razor2.cloudmark.com
ac=6
srl=5047
lm=4
bql=50
bqs=129
dre=4
se=C8
srf=FF
ep4=7542-10
ep8=5
pp=1
crt=90
.
Oct 29 14:05:57.976771 check[223]: [ 5] Updated to new server state srl 5047 for server thrill.cloudmark.com
Oct 29 14:05:57.976893 check[223]: [ 6] thrill.cloudmark.com is a Catalogue Server srl 5047; computed min_cf=6, Server se: C8
Oct 29 14:05:57.977036 check[223]: [ 8] Computed supported_engines: 4 8
Oct 29 14:05:57.977088 check[223]: [ 5] no razorhome, not caching server info to disk
Oct 29 14:05:57.977127 check[223]: [ 5] srl was updated, forcing discovery ...
Oct 29 14:05:57.977204 check[223]: [ 5] no listfile: servers.catalogue.lst
Oct 29 14:05:57.977263 check[223]: [ 8] already have 1 discovery servers
Oct 29 14:05:57.977312 check[223]: [ 8] Checking with Razor Discovery Server 66.151.150.12
Oct 29 14:05:57.977387 check[223]: [ 6] losing old server connection, thrill.cloudmark.com, for new server, 66.151.150.12
Oct 29 14:05:57.977433 check[223]: [ 5] disconnecting from server thrill.cloudmark.com
Oct 29 14:05:57.977580 check[223]: [ 4] thrill.cloudmark.com << 5
Oct 29 14:05:57.977619 check[223]: [ 6] a=q
Oct 29 14:05:57.977687 check[223]: [ 5] Connecting to 66.151.150.12 ...
Oct 29 14:05:58.094961 check[223]: [ 8] Connection established
Oct 29 14:05:58.095080 check[223]: [ 4] 66.151.150.12 >> 35 server greeting: sn=D&srl=460&a=l&a=cg&ep4=7542-10
Oct 29 14:05:58.095302 check[223]: [ 4] 66.151.150.12 << 12
Oct 29 14:05:58.095395 check[223]: [ 6] a=g&pm=csl
Oct 29 14:05:58.156267 check[223]: [ 4] 66.151.150.12 >> 76
Oct 29 14:05:58.156366 check[223]: [ 6] response to sent.7
-csl=?
pride.cloudmark.com
thrill.cloudmark.com
wonder.cloudmark.com
.
Oct 29 14:05:58.156569 check[223]: [ 8] Discovery Server 66.151.150.12 replying with csl=pride.cloudmark.com
Oct 29 14:05:58.156616 check[223]: [ 8] Discovery Server 66.151.150.12 replying with csl=thrill.cloudmark.com
Oct 29 14:05:58.156658 check[223]: [ 8] Discovery Server 66.151.150.12 replying with csl=wonder.cloudmark.com
Oct 29 14:05:58.156808 check[223]: [ 4] 66.151.150.12 << 12
Oct 29 14:05:58.156849 check[223]: [ 6] a=g&pm=nsl
Oct 29 14:05:58.217262 check[223]: [ 4] 66.151.150.12 >> 51
Oct 29 14:05:58.217361 check[223]: [ 6] response to sent.8
-nsl=?
joy.cloudmark.com
folly.cloudmark.com
.
Oct 29 14:05:58.217545 check[223]: [ 8] Discovery Server 66.151.150.12 replying with nsl=joy.cloudmark.com
Oct 29 14:05:58.217592 check[223]: [ 8] Discovery Server 66.151.150.12 replying with nsl=folly.cloudmark.com
Oct 29 14:05:58.217705 check[223]: [ 5] no razorhome, not caching server info to disk
Oct 29 14:05:58.217793 check[223]: [ 5] no razorhome, not caching server info to disk
Oct 29 14:05:58.217844 check[223]: [ 8] Using next closest server thrill.cloudmark.com:2703, cached info srl 5047
Oct 29 14:05:58.217943 check[223]: [ 8] mail 1 has no subject
Oct 29 14:05:58.218163 check[223]: [ 6] preproc: mail 1.0 went from 40 bytes to 3
Oct 29 14:05:58.218248 check[223]: [ 6] computing sigs for mail 1.0, len 3
Oct 29 14:05:58.219447 check[223]: [ 6] Engine (8) didn't produce a signature for mail 1.0
Oct 29 14:05:58.219603 check[223]: [ 6] skipping whitelist file (empty?): razor-whitelist
Oct 29 14:05:58.219666 check[223]: [ 6] losing old server connection, 66.151.150.12, for new server, thrill.cloudmark.com
Oct 29 14:05:58.219710 check[223]: [ 5] disconnecting from server 66.151.150.12
Oct 29 14:05:58.219863 check[223]: [ 4] 66.151.150.12 << 5
Oct 29 14:05:58.219904 check[223]: [ 6] a=q
Oct 29 14:05:58.219980 check[223]: [ 5] Connecting to thrill.cloudmark.com ...
Oct 29 14:05:58.336741 check[223]: [ 8] Connection established
Oct 29 14:05:58.336912 check[223]: [ 4] thrill.cloudmark.com >> 36 server greeting: sn=C&srl=5047&a=l&a=cg&ep4=7542-10
Oct 29 14:05:58.337207 check[223]: [ 4] thrill.cloudmark.com << 25
Oct 29 14:05:58.337251 check[223]: [ 6] cn=razor-agents&cv=2.61
Oct 29 14:05:58.337374 check[223]: [ 6] thrill.cloudmark.com is a Catalogue Server srl 5047; computed min_cf=6, Server se: C8
Oct 29 14:05:58.337629 check[223]: [ 8] Computed supported_engines: 4 8
Oct 29 14:05:58.337842 check[223]: [ 8] mail 1.0 e4 sig: DXc-2nXPD705qwuy78OtNOq1FcwA
Oct 29 14:05:58.337959 check[223]: [ 5] mail 1.0 e8 got no sig
Oct 29 14:05:58.338025 check[223]: [ 8] preparing 1 queries
Oct 29 14:05:58.338132 check[223]: [ 8] sending 1 batches
Oct 29 14:05:58.338280 check[223]: [ 4] thrill.cloudmark.com << 52
Oct 29 14:05:58.338325 check[223]: [ 6] a=c&e=4&ep4=7542-10&s=DXc-2nXPD705qwuy78OtNOq1FcwA
Oct 29 14:05:58.501072 check[223]: [ 4] thrill.cloudmark.com >> 10
Oct 29 14:05:58.501242 check[223]: [ 6] response to sent.11
p=0&ct=1
Oct 29 14:05:58.501711 check[223]: [ 6] mail 1.0 e=4 sig=DXc-2nXPD705qwuy78OtNOq1FcwA: sig not found.
Oct 29 14:05:58.501835 check[223]: [ 7] method 4: mail 1.0: contention part, skipping
Oct 29 14:05:58.501932 check[223]: [ 7] method 4: mail 1: all non-contention parts not spam, mail not spam
Oct 29 14:05:58.502044 check[223]: [ 3] mail 1 is not known spam.
Oct 29 14:05:58.502133 check[223]: [ 5] disconnecting from server thrill.cloudmark.com
Oct 29 14:05:58.502291 check[223]: [ 4] thrill.cloudmark.com << 5
Oct 29 14:05:58.502332 check[223]: [ 6] a=q
debug: Using results from Razor v2.61
debug: Found Razor2 part: part=0 engine=4 ct=1 cf=0
debug: leaving helper-app run mode
debug: Razor2 results: spam? 0 highest cf score: 0
debug: running raw-body-text per-line regexp tests; score so far=0.069
debug: running full-text regexp tests; score so far=0.069
debug: Razor2 is available
debug: DCCifd is not available: no r/w dccifd socket found.
debug: DCC is not available: no executable dccproc found.
debug: Pyzor is not available: pyzor not found
debug: Running tests for priority: 500
debug: RBL: success for 36 of 36 queries
debug: running meta tests; score so far=9.361
debug: running header regexp tests; score so far=10.931
debug: running body-text per-line regexp tests; score so far=10.931
debug: running uri tests; score so far=10.931
debug: running raw-body-text per-line regexp tests; score so far=10.931
debug: running full-text regexp tests; score so far=10.931
debug: Running tests for priority: 1000
debug: running meta tests; score so far=10.931
debug: running header regexp tests; score so far=10.931
debug: running body-text per-line regexp tests; score so far=10.931
debug: running uri tests; score so far=10.931
debug: running raw-body-text per-line regexp tests; score so far=10.931
debug: running full-text regexp tests; score so far=10.931
debug: auto-learn: currently using scoreset 1.
debug: auto-learn: message score: 10.931, computed score for autolearn: 10.931
debug: auto-learn? ham=0.1, spam=12, body-points=9.292, head-points=9.361, learned-points=0
debug: auto-learn? no: inside auto-learn thresholds, not considered ham or spam
debug: is spam? score=10.931 required=5
debug: tests=FORGED_RCVD_HELO,MISSING_DATE,MISSING_SUBJECT,RCVD_IN_NJABL_DUL,RC VD_IN_ROGERS,RCVD_IN_SORBS,RCVD_IN_SORBS_DUL
debug: subtests=__RCVD_IN_NJABL,__RCVD_IN_SORBS
logmsg: identified spam (10.9/5.0) for jason-at-lixfeld.ca:0 in 1.2 seconds, 232 bytes.
logmsg: result: Y 10 - FORGED_RCVD_HELO,MISSING_DATE,MISSING_SUBJECT,RCVD_IN_NJABL_DUL,RCVD_IN_ ROGERS,RCVD_IN_SORBS,RCVD_IN_SORBS_DUL scantime=1.2,size=232,mid=(unknown),autolearn=no
logmsg: connection from localhost [127.0.0.1] at port 54842
debug: Conf::SQL: executing SQL: SELECT preference, value FROM userpref WHERE username = 'mailnull' OR username = '$GLOBAL' OR username = CONCAT('%',NULL) ORDER BY username ASC
debug: retrieving prefs for mailnull from SQL server
debug: user has changed
debug: bayes: 224 tie-ing to DB file R/O /root/.spamassassin/bayes_toks
debug: bayes: 224 tie-ing to DB file R/O /root/.spamassassin/bayes_seen
debug: bayes: found bayes db version 3
debug: bayes: Not available for scanning, only 100 spam(s) in Bayes DB < 200
debug: bayes: 224 untie-ing
debug: bayes: 224 untie-ing db_toks
debug: bayes: 224 untie-ing db_seen
debug: Score set 1 chosen.
logmsg: processing message (unknown) for mailnull:0.
debug: bayes: 224 tie-ing to DB file R/O /root/.spamassassin/bayes_toks
debug: bayes: 224 tie-ing to DB file R/O /root/.spamassassin/bayes_seen
debug: bayes: found bayes db version 3
debug: bayes: Not available for scanning, only 100 spam(s) in Bayes DB < 200
debug: bayes: 224 untie-ing
debug: bayes: 224 untie-ing db_toks
debug: bayes: 224 untie-ing db_seen
debug: received-header: parsed as [ ip=65.50.84.33 rdns=cpe000625c4faac-cm014160000219.cpe.net.cable.rogers.com helo=foo.com by=eshara.ebit.ca ident= envfrom= intl=0 id=1CNb8P-00003A-8i ]
debug: is Net::DNS::Resolver available? yes
debug: Net::DNS version: 0.48
debug: looking up A records for 'eshara.ebit.ca'
debug: A records for 'eshara.ebit.ca': 69.90.17.218
debug: looking up A records for 'eshara.ebit.ca'
debug: A records for 'eshara.ebit.ca': 69.90.17.218
debug: received-header: 'by' eshara.ebit.ca has public IP 69.90.17.218
debug: received-header: relay 65.50.84.33 trusted? no internal? no
debug: metadata: X-Spam-Relays-Trusted:
debug: metadata: X-Spam-Relays-Untrusted: [ ip=65.50.84.33 rdns=cpe000625c4faac-cm014160000219.cpe.net.cable.rogers.com helo=foo.com by=eshara.ebit.ca ident= envfrom= intl=0 id=1CNb8P-00003A-8i ]
debug: ---- MIME PARSER START ----
debug: main message type: text/plain
debug: parsing normal part
debug: added part, type: text/plain
debug: ---- MIME PARSER END ----
debug: decoding: no encoding detected
debug: Message too short for language analysis
debug: is Net::DNS::Resolver available? yes
debug: Net::DNS version: 0.48
debug: all '*From' addrs:
debug: Running tests for priority: 0
debug: running header regexp tests; score so far=0
debug: all '*To' addrs: jason-at-lixfeld.ca
debug: forged-HELO: from=rogers.com helo=foo.com by=eshara.ebit.ca
debug: forged-HELO: mismatch on HELO: 'foo.com' != 'rogers.com'
debug: running body-text per-line regexp tests; score so far=0.069
debug: running uri tests; score so far=0.069
debug: Razor2 is available
debug: entering helper-app run mode
Razor-Log: Computed razorhome from env: /root/.razor
Razor-Log: No razorhome found, using all defaults
Razor-Log: No razor-agent.conf found, using defaults.
Oct 29 14:05:58.654078 check[224]: [ 2] [bootup] Logging initiated LogDebugLevel=9 to stdout
Oct 29 14:05:58.654388 check[224]: [ 5] computed razorhome=, conf=, ident=identity
Oct 29 14:05:58.654595 check[224]: [ 8] Client supported_engines: 4 8
Oct 29 14:05:58.655182 check[224]: [ 8] prep_mail done: mail 1 headers=306, mime0=40
Oct 29 14:05:58.655393 check[224]: [ 7] Can't read file servers.discovery.lst, looking relatve to
Oct 29 14:05:58.655465 check[224]: [ 5] Can't read file /servers.discovery.lst: No such file or directory
Oct 29 14:05:58.655518 check[224]: [ 7] Can't read file servers.nomination.lst, looking relatve to
Oct 29 14:05:58.655567 check[224]: [ 5] Can't read file /servers.nomination.lst: No such file or directory
Oct 29 14:05:58.655618 check[224]: [ 7] Can't read file servers.catalogue.lst, looking relatve to
Oct 29 14:05:58.655667 check[224]: [ 5] Can't read file /servers.catalogue.lst: No such file or directory
Oct 29 14:05:58.655852 check[224]: [ 5] no listfile: servers.catalogue.lst
Oct 29 14:05:58.655935 check[224]: [ 6] no discovery listfile: servers.discovery.lst
Oct 29 14:05:58.655979 check[224]: [ 5] Finding Discovery Servers via DNS in the razor2.cloudmark.com zone
Oct 29 14:05:58.660390 check[224]: [ 6] Found 1 Discovery Servers via DNS in the razor2.cloudmark.com zone
Oct 29 14:05:58.660645 check[224]: [ 8] Checking with Razor Discovery Server 66.151.150.12
Oct 29 14:05:58.660777 check[224]: [ 6] No port specified, using 2703
Oct 29 14:05:58.660841 check[224]: [ 5] Connecting to 66.151.150.12 ...
Oct 29 14:05:58.778069 check[224]: [ 8] Connection established
Oct 29 14:05:58.778219 check[224]: [ 4] 66.151.150.12 >> 35 server greeting: sn=D&srl=460&a=l&a=cg&ep4=7542-10
Oct 29 14:05:58.778501 check[224]: [ 4] 66.151.150.12 << 12
Oct 29 14:05:58.778564 check[224]: [ 6] a=g&pm=csl
Oct 29 14:05:58.838940 check[224]: [ 4] 66.151.150.12 >> 76
Oct 29 14:05:58.839042 check[224]: [ 6] response to sent.1
-csl=?
pride.cloudmark.com
wonder.cloudmark.com
thrill.cloudmark.com
.
Oct 29 14:05:58.839339 check[224]: [ 8] Discovery Server 66.151.150.12 replying with csl=pride.cloudmark.com
Oct 29 14:05:58.839387 check[224]: [ 8] Discovery Server 66.151.150.12 replying with csl=wonder.cloudmark.com
Oct 29 14:05:58.839430 check[224]: [ 8] Discovery Server 66.151.150.12 replying with csl=thrill.cloudmark.com
Oct 29 14:05:58.839584 check[224]: [ 4] 66.151.150.12 << 12
Oct 29 14:05:58.839624 check[224]: [ 6] a=g&pm=nsl
Oct 29 14:05:58.900804 check[224]: [ 4] 66.151.150.12 >> 51
Oct 29 14:05:58.900903 check[224]: [ 6] response to sent.2
-nsl=?
folly.cloudmark.com
joy.cloudmark.com
.
Oct 29 14:05:58.901086 check[224]: [ 8] Discovery Server 66.151.150.12 replying with nsl=folly.cloudmark.com
Oct 29 14:05:58.901133 check[224]: [ 8] Discovery Server 66.151.150.12 replying with nsl=joy.cloudmark.com
Oct 29 14:05:58.901276 check[224]: [ 5] no razorhome, not caching server info to disk
Oct 29 14:05:58.901367 check[224]: [ 6] losing old server connection, 66.151.150.12, for new server, thrill.cloudmark.com
Oct 29 14:05:58.901414 check[224]: [ 5] disconnecting from server 66.151.150.12
Oct 29 14:05:58.901558 check[224]: [ 4] 66.151.150.12 << 5
Oct 29 14:05:58.901598 check[224]: [ 6] a=q
Oct 29 14:05:58.901665 check[224]: [ 5] Connecting to thrill.cloudmark.com ...
Oct 29 14:05:59.018814 check[224]: [ 8] Connection established
Oct 29 14:05:59.018960 check[224]: [ 4] thrill.cloudmark.com >> 36 server greeting: sn=C&srl=5047&a=l&a=cg&ep4=7542-10
Oct 29 14:05:59.019374 check[224]: [ 4] thrill.cloudmark.com << 25
Oct 29 14:05:59.019472 check[224]: [ 6] cn=razor-agents&cv=2.61
Oct 29 14:05:59.019744 check[224]: [ 4] thrill.cloudmark.com << 14
Oct 29 14:05:59.019839 check[224]: [ 6] a=g&pm=state
Oct 29 14:05:59.136729 check[224]: [ 4] thrill.cloudmark.com >> 141
Oct 29 14:05:59.136829 check[224]: [ 6] response to sent.5
-sv=3.44
sn=C
zone=razor2.cloudmark.com
ac=6
srl=5047
lm=4
bql=50
bqs=129
dre=4
se=C8
srf=FF
ep4=7542-10
ep8=5
pp=1
crt=90
.
Oct 29 14:05:59.137412 check[224]: [ 5] Updated to new server state srl 5047 for server thrill.cloudmark.com
Oct 29 14:05:59.137534 check[224]: [ 6] thrill.cloudmark.com is a Catalogue Server srl 5047; computed min_cf=6, Server se: C8
Oct 29 14:05:59.137679 check[224]: [ 8] Computed supported_engines: 4 8
Oct 29 14:05:59.137732 check[224]: [ 5] no razorhome, not caching server info to disk
Oct 29 14:05:59.137771 check[224]: [ 5] srl was updated, forcing discovery ...
Oct 29 14:05:59.137846 check[224]: [ 5] no listfile: servers.catalogue.lst
Oct 29 14:05:59.137905 check[224]: [ 8] already have 1 discovery servers
Oct 29 14:05:59.137954 check[224]: [ 8] Checking with Razor Discovery Server 66.151.150.12
Oct 29 14:05:59.138030 check[224]: [ 6] losing old server connection, thrill.cloudmark.com, for new server, 66.151.150.12
Oct 29 14:05:59.138074 check[224]: [ 5] disconnecting from server thrill.cloudmark.com
Oct 29 14:05:59.138219 check[224]: [ 4] thrill.cloudmark.com << 5
Oct 29 14:05:59.138258 check[224]: [ 6] a=q
Oct 29 14:05:59.138325 check[224]: [ 5] Connecting to 66.151.150.12 ...
Oct 29 14:05:59.255186 check[224]: [ 8] Connection established
Oct 29 14:05:59.255304 check[224]: [ 4] 66.151.150.12 >> 35 server greeting: sn=D&srl=460&a=l&a=cg&ep4=7542-10
Oct 29 14:05:59.255529 check[224]: [ 4] 66.151.150.12 << 12
Oct 29 14:05:59.255622 check[224]: [ 6] a=g&pm=csl
Oct 29 14:05:59.317222 check[224]: [ 4] 66.151.150.12 >> 76
Oct 29 14:05:59.317321 check[224]: [ 6] response to sent.7
-csl=?
wonder.cloudmark.com
pride.cloudmark.com
thrill.cloudmark.com
.
Oct 29 14:05:59.317522 check[224]: [ 8] Discovery Server 66.151.150.12 replying with csl=wonder.cloudmark.com
Oct 29 14:05:59.317569 check[224]: [ 8] Discovery Server 66.151.150.12 replying with csl=pride.cloudmark.com
Oct 29 14:05:59.317612 check[224]: [ 8] Discovery Server 66.151.150.12 replying with csl=thrill.cloudmark.com
Oct 29 14:05:59.317764 check[224]: [ 4] 66.151.150.12 << 12
Oct 29 14:05:59.317804 check[224]: [ 6] a=g&pm=nsl
Oct 29 14:05:59.750011 check[224]: [ 4] 66.151.150.12 >> 51
Oct 29 14:05:59.750122 check[224]: [ 6] response to sent.8
-nsl=?
joy.cloudmark.com
folly.cloudmark.com
.
Oct 29 14:05:59.750293 check[224]: [ 8] Discovery Server 66.151.150.12 replying with nsl=joy.cloudmark.com
Oct 29 14:05:59.750403 check[224]: [ 8] Discovery Server 66.151.150.12 replying with nsl=folly.cloudmark.com
Oct 29 14:05:59.750596 check[224]: [ 5] no razorhome, not caching server info to disk
Oct 29 14:05:59.750753 check[224]: [ 5] no razorhome, not caching server info to disk
Oct 29 14:05:59.750870 check[224]: [ 8] Using next closest server thrill.cloudmark.com:2703, cached info srl 5047
Oct 29 14:05:59.751032 check[224]: [ 8] mail 1 has no subject
Oct 29 14:05:59.751258 check[224]: [ 6] preproc: mail 1.0 went from 40 bytes to 3
Oct 29 14:05:59.751345 check[224]: [ 6] computing sigs for mail 1.0, len 3
Oct 29 14:05:59.752542 check[224]: [ 6] Engine (8) didn't produce a signature for mail 1.0
Oct 29 14:05:59.752702 check[224]: [ 6] skipping whitelist file (empty?): razor-whitelist
Oct 29 14:05:59.752767 check[224]: [ 6] losing old server connection, 66.151.150.12, for new server, thrill.cloudmark.com
Oct 29 14:05:59.752811 check[224]: [ 5] disconnecting from server 66.151.150.12
Oct 29 14:05:59.752965 check[224]: [ 4] 66.151.150.12 << 5
Oct 29 14:05:59.753006 check[224]: [ 6] a=q
Oct 29 14:05:59.753082 check[224]: [ 5] Connecting to thrill.cloudmark.com ...
Oct 29 14:05:59.869918 check[224]: [ 8] Connection established
Oct 29 14:05:59.870097 check[224]: [ 4] thrill.cloudmark.com >> 36 server greeting: sn=C&srl=5047&a=l&a=cg&ep4=7542-10
Oct 29 14:05:59.870448 check[224]: [ 4] thrill.cloudmark.com << 25
Oct 29 14:05:59.870544 check[224]: [ 6] cn=razor-agents&cv=2.61
Oct 29 14:05:59.870744 check[224]: [ 6] thrill.cloudmark.com is a Catalogue Server srl 5047; computed min_cf=6, Server se: C8
Oct 29 14:05:59.870918 check[224]: [ 8] Computed supported_engines: 4 8
Oct 29 14:05:59.871141 check[224]: [ 8] mail 1.0 e4 sig: DXc-2nXPD705qwuy78OtNOq1FcwA
Oct 29 14:05:59.871321 check[224]: [ 5] mail 1.0 e8 got no sig
Oct 29 14:05:59.871442 check[224]: [ 8] preparing 1 queries
Oct 29 14:05:59.871628 check[224]: [ 8] sending 1 batches
Oct 29 14:05:59.871842 check[224]: [ 4] thrill.cloudmark.com << 52
Oct 29 14:05:59.871940 check[224]: [ 6] a=c&e=4&ep4=7542-10&s=DXc-2nXPD705qwuy78OtNOq1FcwA
Oct 29 14:06:00.182218 check[224]: [ 4] thrill.cloudmark.com >> 10
Oct 29 14:06:00.182321 check[224]: [ 6] response to sent.11
p=0&ct=1
Oct 29 14:06:00.182674 check[224]: [ 6] mail 1.0 e=4 sig=DXc-2nXPD705qwuy78OtNOq1FcwA: sig not found.
Oct 29 14:06:00.182738 check[224]: [ 7] method 4: mail 1.0: contention part, skipping
Oct 29 14:06:00.182781 check[224]: [ 7] method 4: mail 1: all non-contention parts not spam, mail not spam
Oct 29 14:06:00.182822 check[224]: [ 3] mail 1 is not known spam.
Oct 29 14:06:00.182869 check[224]: [ 5] disconnecting from server thrill.cloudmark.com
Oct 29 14:06:00.183013 check[224]: [ 4] thrill.cloudmark.com << 5
Oct 29 14:06:00.183053 check[224]: [ 6] a=q
debug: Using results from Razor v2.61
debug: Found Razor2 part: part=0 engine=4 ct=1 cf=0
debug: leaving helper-app run mode
debug: Razor2 results: spam? 0 highest cf score: 0
debug: running raw-body-text per-line regexp tests; score so far=0.069
debug: running full-text regexp tests; score so far=0.069
debug: Razor2 is available
debug: DCCifd is not available: no r/w dccifd socket found.
debug: DCC is not available: no executable dccproc found.
debug: Pyzor is not available: pyzor not found
debug: Running tests for priority: 500
debug: RBL: success for 36 of 36 queries
debug: running meta tests; score so far=9.361
debug: running header regexp tests; score so far=10.931
debug: running body-text per-line regexp tests; score so far=10.931
debug: running uri tests; score so far=10.931
debug: running raw-body-text per-line regexp tests; score so far=10.931
debug: running full-text regexp tests; score so far=10.931
debug: Running tests for priority: 1000
debug: running meta tests; score so far=10.931
debug: running header regexp tests; score so far=10.931
debug: running body-text per-line regexp tests; score so far=10.931
debug: running uri tests; score so far=10.931
debug: running raw-body-text per-line regexp tests; score so far=10.931
debug: running full-text regexp tests; score so far=10.931
debug: auto-learn: currently using scoreset 1.
debug: auto-learn: message score: 10.931, computed score for autolearn: 10.931
debug: auto-learn? ham=0.1, spam=12, body-points=9.292, head-points=9.361, learned-points=0
debug: auto-learn? no: inside auto-learn thresholds, not considered ham or spam
debug: is spam? score=10.931 required=5
debug: tests=FORGED_RCVD_HELO,MISSING_DATE,MISSING_SUBJECT,RCVD_IN_NJABL_DUL,RC VD_IN_ROGERS,RCVD_IN_SORBS,RCVD_IN_SORBS_DUL
debug: subtests=__RCVD_IN_NJABL,__RCVD_IN_SORBS
logmsg: identified spam (10.9/5.0) for mailnull:0 in 1.7 seconds, 311 bytes.
logmsg: result: Y 10 - FORGED_RCVD_HELO,MISSING_DATE,MISSING_SUBJECT,RCVD_IN_NJABL_DUL,RCVD_IN_ ROGERS,RCVD_IN_SORBS,RCVD_IN_SORBS_DUL scantime=1.7,size=311,mid=(unknown),autolearn=no
Michael
