[dspam-users] process_message returned error -5. dropping message.

From: Mikael Syska <mikael@syska.dk>
Date: Tue Nov 01 2005 - 16:18:25 EST

Hi,

I'm having problems using dspam on FreeBSD 5.4 and postfix with virtual
users.

its installed from source with the follow command:
# ./configure --enable-daemon \
--enable-virtual-users \
--enable-debug \
--enable-clamav \
--with-storage-driver=mysql_drv \
--with-mysql-includes=/usr/local/include/mysql \
--with-mysql-libraries=/usr/local/lib/mysql \
--enable-preferences-extension \
--enable-large-scale \
--enable-long-usernames \
--enable-verbose-debug \
--enable-alternative-bayesian
# make
# make install

dspam.conf

afterwards followed the guide in postfix.txt for adding it as a content
filter

I can recieve and send mail..... but I'm having problem sending spam to
"spam@domain.tld" and "notspam@domain.tld"...

I'm gettings this in the logs:
9238: [11/01/2005 21:27:28] Signature retrieval for
'3,4367beca6631309314037' failed
9238: [11/01/2005 21:27:28] Unable to find a valid signature. Aborting.
9238: [11/01/2005 21:27:28] process_message returned error -5. dropping
message.

When its builded with verbose logging i get this:
9238: [11/01/2005 20:39:53] attribute MySQLConnectionCache = 20
9238: [11/01/2005 20:39:53] attribute MySQLUIDInSignature = on
9238: [11/01/2005 20:39:53] _ds_pref_load: unable to
_mysql_drv_getpwnam(spam@xxx.dk) <--------------- What is does, it that
the errors that cursing it?
9238: [11/01/2005 20:39:53] attribute MySQLServer = 127.0.0.1
9238: [11/01/2005 20:39:53] attribute MySQLUser = root
9238: [11/01/2005 20:39:53] attribute MySQLPass = flyttekasse
9238: [11/01/2005 20:39:53] attribute MySQLDb = postfix
9238: [11/01/2005 20:39:53] attribute MySQLCompress = true
9238: [11/01/2005 20:39:53] attribute MySQLConnectionCache = 20
9238: [11/01/2005 20:39:53] attribute MySQLUIDInSignature = on
9238: [11/01/2005 20:39:53] Loading preferences for uid 0
9238: [11/01/2005 20:39:53] attribute MySQLServer = 127.0.0.1
9238: [11/01/2005 20:39:53] attribute MySQLUser = root
9238: [11/01/2005 20:39:53] attribute MySQLPass = flyttekasse
9238: [11/01/2005 20:39:53] attribute MySQLDb = postfix
9238: [11/01/2005 20:39:53] attribute MySQLCompress = true
9238: [11/01/2005 20:39:53] attribute MySQLConnectionCache = 20
9238: [11/01/2005 20:39:53] attribute MySQLUIDInSignature = on
9238: [11/01/2005 20:39:53] Loading preferences for uid 0
9238: [11/01/2005 20:39:53] loaded default preferences externally
9238: [11/01/2005 20:39:53] aggregated preference 'signatureLocation' =>
'message'
9238: [11/01/2005 20:39:53] using
/usr/local/var/dspam/opt-in/spam@syska.dk.dspam as path
9238: [11/01/2005 20:39:53] using
/usr/local/var/dspam/opt-out/spam@syska.dk.nodspam as path
9238: [11/01/2005 20:39:53] sedation level set to: 5
9238: [11/01/2005 20:39:53] attribute StorageDriver =
/usr/local/lib/libmysql_drv.so
9238: [11/01/2005 20:39:53] attribute MySQLServer = 127.0.0.1

 From sql.errors:
[11/01/2005 21:44:48] 9238: VERBOSE DEBUG (INFO ONLY - NOT AN ERROR):
select uid, token, spam_hits, innocent_hits from dspam_token_d
ata where uid = 4 and token
in('5174632569486238062','9625057165174973815','1555451898066551904','16104613886016074596','84793959324
6534144','2403076604502008174','6128546630490786208','5578578887803288549','12117078172638540411','16391079132029963312','1784087306
2035665889','16338053912705154359','13343502029131713238','8238832432524265766','3214788094345337536','10122170691265312667','157426
37575607524723','3947380370050493742','3767524090364532967','13646266664744962224','15816493097487859084','5683620196431298136','866
7653582297399894','3215104753694137024','4671530707252146463','378804129159575741','16804621227417639898','17051583533530772407','13
900673616898285240','12485913189426762807','16100219874012200332','10801212046714182241','11927133412377179248','7867512904400844989
','1232207200902452564','5171625364718678992','5813005016478253056','9205274880554612174','2921702274845366976','4333295114525930484
','10658963851761267959','5854570099143864607','14157559045239583588','9878755385869960827','7693176545658771657','17926900928453995
433','13646266664744306864','14619317305582266837','1055930818711877088','17362489375534324698','6665353772883131365','6963488805557
398976','15766953501586783628','1148459355597043055','3735531722597264737','4405123497634172568','2008273048314448067','333638528428
4340928','18008498298190147855','1694610648703451279','3735531827521973601','15201038990766394680','6336409583094046718','3221610715
116450923','3355250156873296701','12328502069270722732','14262803978328626346','5810708846013956096','10018588523142920091','1509432
9407725356219','17837013875315749027','6993132128016348350','6946177522921710777','14721861600566682881','24251656603657441','178370
13874543997091','3014066209652920754','15758396926626709460','12640286223742571364','6229778482895276780','16905895114323513721','81
74558747310000206','3395782553519631165','15224283897550155352','16463662138550435127','7357415933694721070','13884833415944681423',
'2793463374009167360','18327011285923276810','7064682713829882926')

logs from "dspam --debug --daemon"
syska [/home/syska]# dspam --debug --daemon
9719: [11/01/2005 22:07:29] Daemon process starting
9719: [11/01/2005 22:07:29] initializing lock 0
9719: [11/01/2005 22:07:29] initializing lock 1
9719: [11/01/2005 22:07:29] initializing lock 2
9719: [11/01/2005 22:07:29] initializing lock 3
9719: [11/01/2005 22:07:29] initializing lock 4
9719: [11/01/2005 22:07:29] initializing lock 5
9719: [11/01/2005 22:07:29] initializing lock 6
9719: [11/01/2005 22:07:29] initializing lock 7
9719: [11/01/2005 22:07:29] initializing lock 8
9719: [11/01/2005 22:07:29] initializing lock 9
9719: [11/01/2005 22:07:29] initializing lock 10
9719: [11/01/2005 22:07:29] initializing lock 11
9719: [11/01/2005 22:07:29] initializing lock 12
9719: [11/01/2005 22:07:29] initializing lock 13
9719: [11/01/2005 22:07:29] initializing lock 14
9719: [11/01/2005 22:07:29] initializing lock 15
9719: [11/01/2005 22:07:29] initializing lock 16
9719: [11/01/2005 22:07:29] initializing lock 17
9719: [11/01/2005 22:07:29] initializing lock 18
9719: [11/01/2005 22:07:29] initializing lock 19
9719: [11/01/2005 22:07:29] spawning daemon listener
9719: [11/01/2005 22:07:29] Creating local domain socket /tmp/dspam.sock
9719: [11/01/2005 22:08:02] SEND: 220 DSPAM LMTP 3.6.0 Ready
9719: [11/01/2005 22:08:02] SRECV: LHLO thunder.syska.dk

9719: [11/01/2005 22:08:02] SEND: 250-localhost.localdomain
9719: [11/01/2005 22:08:02] SEND: 250-PIPELINING
9719: [11/01/2005 22:08:02] SEND: 250-ENHANCEDSTATUSCODES
9719: [11/01/2005 22:08:02] SEND: 250 SIZE
9719: [11/01/2005 22:08:02] SRECV: MAIL FROM:<mikael@syska.dk> SIZE=1968

9719: [11/01/2005 22:08:02] SEND: 250 2.1.0 OK
9719: [11/01/2005 22:08:02] SRECV: RCPT TO:<spam@syska.dk>

9719: [11/01/2005 22:08:02] SEND: 250 2.1.5 OK
9719: [11/01/2005 22:08:02] SRECV: DATA

9719: [11/01/2005 22:08:02] No QuarantineAgent option found. Using
standard quarantine.
9719: [11/01/2005 22:08:02] SEND: 354 Enter mail, end with "." on a line
by itself
9719: [11/01/2005 22:08:02] SRECV: Received: from [192.168.199.100]
(unknown [192.168.199.100])

9719: [11/01/2005 22:08:02] SRECV: by thunder.syska.dk (Postfix)
with ESMTP id CD06E630F

9719: [11/01/2005 22:08:02] SRECV: for <spam@syska.dk>; Tue, 1 Nov
2005 22:08:02 +0100 (CET)

9719: [11/01/2005 22:08:02] SRECV: Message-ID: <4367D97D.8040103@syska.dk>

9719: [11/01/2005 22:08:02] SRECV: Date: Tue, 01 Nov 2005 22:09:17 +0100

9719: [11/01/2005 22:08:02] SRECV: From: Mikael Syska <mikael@syska.dk>

9719: [11/01/2005 22:08:02] SRECV: User-Agent: Mozilla Thunderbird 1.0.7
(Windows/20050923)

9719: [11/01/2005 22:08:02] SRECV: X-Accept-Language: en-us, en

9719: [11/01/2005 22:08:02] SRECV: MIME-Version: 1.0

9719: [11/01/2005 22:08:02] SRECV: To: spam@syska.dk

9719: [11/01/2005 22:08:02] SRECV: Subject: [Fwd: test]

9719: [11/01/2005 22:08:02] SRECV: Content-Type: multipart/mixed;

9719: [11/01/2005 22:08:02] SRECV:
boundary="------------040304040602010508030501"

9719: [11/01/2005 22:08:02] SRECV:

9719: [11/01/2005 22:08:02] SRECV: This is a multi-part message in MIME
format.

9719: [11/01/2005 22:08:02] SRECV: --------------040304040602010508030501

9719: [11/01/2005 22:08:02] SRECV: Content-Type: text/plain;
charset=ISO-8859-1; format=flowed

9719: [11/01/2005 22:08:02] SRECV: Content-Transfer-Encoding: 7bit

9719: [11/01/2005 22:08:02] SRECV:

9719: [11/01/2005 22:08:02] SRECV:

9719: [11/01/2005 22:08:02] SRECV:

9719: [11/01/2005 22:08:02] SRECV: --------------040304040602010508030501

9719: [11/01/2005 22:08:02] SRECV: Content-Type: message/rfc822;

9719: [11/01/2005 22:08:02] SRECV: name="test"

9719: [11/01/2005 22:08:02] SRECV: Content-Transfer-Encoding: 7bit

9719: [11/01/2005 22:08:02] SRECV: Content-Disposition: inline;

9719: [11/01/2005 22:08:02] SRECV: filename="test"

9719: [11/01/2005 22:08:02] SRECV:

9719: [11/01/2005 22:08:02] SRECV: Return-Path: <mikael@syska.dk>

9719: [11/01/2005 22:08:02] SRECV: X-Original-To: mikael@syska.dk

9719: [11/01/2005 22:08:02] SRECV: Delivered-To: mikael@syska.dk

9719: [11/01/2005 22:08:02] SRECV: Received: from localhost (localhost
[127.0.0.1])

9719: [11/01/2005 22:08:02] SRECV: by thunder.syska.dk (Postfix)
with SMTP id BBA9862FF

9719: [11/01/2005 22:08:02] SRECV: for <mikael@syska.dk>; Tue, 1
Nov 2005 20:39:40 +0100 (CET)

9719: [11/01/2005 22:08:02] SRECV: Received: from [192.168.199.100]
(unknown [192.168.199.100])

9719: [11/01/2005 22:08:02] SRECV: by thunder.syska.dk (Postfix)
with ESMTP id 2130F62FD

9719: [11/01/2005 22:08:02] SRECV: for <mikael@syska.dk>; Tue, 1
Nov 2005 20:39:40 +0100 (CET)

9719: [11/01/2005 22:08:02] SRECV: Message-ID: <4367C4C7.9080606@syska.dk>

9719: [11/01/2005 22:08:02] SRECV: Date: Tue, 01 Nov 2005 20:40:55 +0100

9719: [11/01/2005 22:08:02] SRECV: From: Mikael Syska <mikael@syska.dk>

9719: [11/01/2005 22:08:02] SRECV: User-Agent: Mozilla Thunderbird 1.0.7
(Windows/20050923)

9719: [11/01/2005 22:08:02] SRECV: X-Accept-Language: en-us, en

9719: [11/01/2005 22:08:02] SRECV: MIME-Version: 1.0

9719: [11/01/2005 22:08:02] SRECV: To: mikael@syska.dk

9719: [11/01/2005 22:08:02] SRECV: Subject: test

9719: [11/01/2005 22:08:02] SRECV: Content-Type: text/plain;
charset=ISO-8859-1; format=flowed

9719: [11/01/2005 22:08:02] SRECV: Content-Transfer-Encoding: 7bit

9719: [11/01/2005 22:08:02] SRECV: X-DSPAM-Result: Innocent

9719: [11/01/2005 22:08:02] SRECV: X-DSPAM-Processed: Tue Nov 1
20:39:40 2005

9719: [11/01/2005 22:08:02] SRECV: X-DSPAM-Confidence: 0.9996

9719: [11/01/2005 22:08:02] SRECV: X-DSPAM-Probability: 0.0000

9719: [11/01/2005 22:08:02] SRECV: X-DSPAM-Signature:
1,4367c47c92384697611496

9719: [11/01/2005 22:08:02] SRECV:

9719: [11/01/2005 22:08:02] SRECV: dfsdf fdsf fdsfsd fdsfsd

9719: [11/01/2005 22:08:02] SRECV:

9719: [11/01/2005 22:08:02] SRECV:

9719: [11/01/2005 22:08:02] SRECV:

9719: [11/01/2005 22:08:02] SRECV:

9719: [11/01/2005 22:08:02] SRECV:

9719: [11/01/2005 22:08:02] SRECV: --------------040304040602010508030501--

9719: [11/01/2005 22:08:02] SRECV: .

9719: [11/01/2005 22:08:02] using database handle id 4
9719: [11/01/2005 22:08:02] handle locked
9719: [11/01/2005 22:08:02] DSPAM Instance Startup
9719: [11/01/2005 22:08:02] input args: dspam --deliver=innocent
9719: [11/01/2005 22:08:02] pass-thru args: /usr/libexec/mail.local
9719: [11/01/2005 22:08:02] processing user spam@syska.dk
9719: [11/01/2005 22:08:02] uid = 0, euid = 0, gid = 0, egid = 0
9719: [11/01/2005 22:08:02] loading preferences for user spam@syska.dk
9719: [11/01/2005 22:08:02] attribute MySQLServer = 127.0.0.1
9719: [11/01/2005 22:08:02] attribute MySQLUser = root
9719: [11/01/2005 22:08:02] attribute MySQLPass = flyttekasse
9719: [11/01/2005 22:08:02] attribute MySQLDb = postfix
9719: [11/01/2005 22:08:02] attribute MySQLCompress = true
9719: [11/01/2005 22:08:02] attribute MySQLConnectionCache = 20
9719: [11/01/2005 22:08:02] attribute MySQLUIDInSignature = on
9719: [11/01/2005 22:08:02] _ds_pref_load: unable to
_mysql_drv_getpwnam(spam@syska.dk)
9719: [11/01/2005 22:08:02] attribute MySQLServer = 127.0.0.1
9719: [11/01/2005 22:08:02] attribute MySQLUser = root
9719: [11/01/2005 22:08:02] attribute MySQLPass = flyttekasse
9719: [11/01/2005 22:08:02] attribute MySQLDb = postfix
9719: [11/01/2005 22:08:02] attribute MySQLCompress = true
9719: [11/01/2005 22:08:02] attribute MySQLConnectionCache = 20
9719: [11/01/2005 22:08:02] attribute MySQLUIDInSignature = on
9719: [11/01/2005 22:08:02] Loading preferences for uid 0
9719: [11/01/2005 22:08:02] attribute MySQLServer = 127.0.0.1
9719: [11/01/2005 22:08:02] attribute MySQLUser = root
9719: [11/01/2005 22:08:02] attribute MySQLPass = password
9719: [11/01/2005 22:08:02] attribute MySQLDb = postfix
9719: [11/01/2005 22:08:02] attribute MySQLCompress = true
9719: [11/01/2005 22:08:02] attribute MySQLConnectionCache = 20
9719: [11/01/2005 22:08:02] attribute MySQLUIDInSignature = on
9719: [11/01/2005 22:08:02] Loading preferences for uid 0
9719: [11/01/2005 22:08:02] loaded default preferences externally
9719: [11/01/2005 22:08:02] aggregated preference 'signatureLocation' =>
'message'
9719: [11/01/2005 22:08:02] using
/usr/local/var/dspam/opt-in/spam@domain.tld.dspam as path
9719: [11/01/2005 22:08:02] using
/usr/local/var/dspam/opt-out/spam@domain.tld.nodspam as path
9719: [11/01/2005 22:08:02] sedation level set to: 5
9719: [11/01/2005 22:08:02] attribute StorageDriver =
/usr/local/lib/libmysql_drv.so
9719: [11/01/2005 22:08:02] attribute MySQLServer = 127.0.0.1
9719: [11/01/2005 22:08:02] attribute MySQLUser = root
9719: [11/01/2005 22:08:02] attribute MySQLPass = password
9719: [11/01/2005 22:08:02] attribute MySQLDb = postfix
9719: [11/01/2005 22:08:02] attribute MySQLCompress = true
9719: [11/01/2005 22:08:02] attribute MySQLConnectionCache = 20
9719: [11/01/2005 22:08:02] attribute MySQLUIDInSignature = on
9719: [11/01/2005 22:08:02] attribute HashRecMax = 100000
9719: [11/01/2005 22:08:02] attribute HashAutoExtend = on
9719: [11/01/2005 22:08:02] attribute HashMaxExtents = 0
9719: [11/01/2005 22:08:02] attribute HashExtentSize = 50000
9719: [11/01/2005 22:08:02] attribute HashMaxSeek = 100
9719: [11/01/2005 22:08:02] attribute LocalMX = 127.0.0.1
9719: [11/01/2005 22:08:02] attribute ProcessorBias = on
9719: [11/01/2005 22:08:02] _mysql_drv_get_spamtotals: unable to
_mysql_drv_getpwnam(spam@domain.tld)
9719: [11/01/2005 22:08:02] unable to load totals. using zero values.
9719: [11/01/2005 22:08:02] scanning component 0 for a DSPAM signature
9719: [11/01/2005 22:08:02] : Boundary :
------------040304040602010508030501
9719: [11/01/2005 22:08:02] : Term Boundary:
------------040304040602010508030501
9719: [11/01/2005 22:08:02] : Encoding : 254
9719: [11/01/2005 22:08:02] : Media Type : 1
9719: [11/01/2005 22:08:02] : Media Subtype: 2
9719: [11/01/2005 22:08:02] : Headers:
9719: [11/01/2005 22:08:02] Received from
[192.168.199.100] (unknown [192.168.199.100])
        by thunder.domain.tld (Postfix) with ESMTP id CD06E630F
        for <spam@domain.tld>; Tue, 1 Nov 2005 22:08:02 +0100 (CET)
9719: [11/01/2005 22:08:02] Message-ID
<4367D97D.8040103@domain.tld>
9719: [11/01/2005 22:08:02] Date Tue,
01 Nov 2005 22:09:17 +0100
9719: [11/01/2005 22:08:02] From Mikael
Syska <mikael@domain.tld>
9719: [11/01/2005 22:08:02] User-Agent
Mozilla Thunderbird 1.0.7 (Windows/20050923)
9719: [11/01/2005 22:08:02] X-Accept-Language en-us, en
9719: [11/01/2005 22:08:02] MIME-Version 1.0
9719: [11/01/2005 22:08:02] To
spam@domain.tld
9719: [11/01/2005 22:08:02] Subject [Fwd:
test]
9719: [11/01/2005 22:08:02] Content-Type
multipart/mixed;
 boundary="------------040304040602010508030501"
9719: [11/01/2005 22:08:02] scanning component 1 for a DSPAM signature
9719: [11/01/2005 22:08:02] : Term Boundary:
------------040304040602010508030501
9719: [11/01/2005 22:08:02] : Encoding : 0
9719: [11/01/2005 22:08:02] : Media Type : 0
9719: [11/01/2005 22:08:02] : Media Subtype: 0
9719: [11/01/2005 22:08:02] : Headers:
9719: [11/01/2005 22:08:02] Content-Type
text/plain; charset=ISO-8859-1; format=flowed
9719: [11/01/2005 22:08:02] Content-Transfer-Encoding 7bit
9719: [11/01/2005 22:08:02] scanning component 2 for a DSPAM signature
9719: [11/01/2005 22:08:02] : Term Boundary:
------------040304040602010508030501--
9719: [11/01/2005 22:08:02] : Encoding : 0
9719: [11/01/2005 22:08:02] : Media Type : 2
9719: [11/01/2005 22:08:02] : Media Subtype: 4
9719: [11/01/2005 22:08:02] : Headers:
9719: [11/01/2005 22:08:02] Content-Type
message/rfc822;
 name="test"
9719: [11/01/2005 22:08:02] Content-Transfer-Encoding 7bit
9719: [11/01/2005 22:08:02] Content-Disposition inline;
 filename="test"
9719: [11/01/2005 22:08:02] found signature '1,4367c47c92384697611496'
9719: [11/01/2005 22:08:02] scanning component 3 for a DSPAM signature
9719: [11/01/2005 22:08:02] : Encoding : 254
9719: [11/01/2005 22:08:02] : Media Type : 0
9719: [11/01/2005 22:08:02] : Media Subtype: 0
9719: [11/01/2005 22:08:02] : Headers:
9719: [11/01/2005 22:08:02] _ds_get_signature: unable to
_mysql_drv_getpwnam(spam@domain.tld)
9719: [11/01/2005 22:08:02] Signature retrieval for
'1,4367c47c92384697611496' failed
9719: [11/01/2005 22:08:02] Unable to find a valid signature. Aborting.
9719: [11/01/2005 22:08:03] _mysql_drv_get_spamtotals: unable to
_mysql_drv_getpwnam(spam@domain.tld)
9719: [11/01/2005 22:08:03] process_message returned error -5. dropping
message.
9719: [11/01/2005 22:08:03] DSPAM Instance Shutdown. Exit Code: 0
9719: [11/01/2005 22:08:03] SEND: 250 2.6.0 <spam@domain.tld> Message
accepted for delivery

The only preference I have in the sql database are
"signatureLocation=message".... does all my settings need to be there
since i'm using mysql or is it enough its in the "dspam.conf" file...?

9719: [11/01/2005 22:08:02] using
/usr/local/var/dspam/opt-in/spam@domain.tld.dspam as path
9719: [11/01/2005 22:08:02] using
/usr/local/var/dspam/opt-out/spam@domain.tld.nodspam as path

These 2 dirs dont exists, what are that used for?

Is it possible to disable the writing to /usr/local/var/dspam/data/ what
are it used for?

That all for now, really hope that there are a person out there that
have had the same program and ofcause a solution for it...

best regards
Mikael Sysks

!DSPAM:5,4367db5797199395215187!
Received on Tue Nov 1 16:18:46 2005

This archive was generated by hypermail 2.1.8 : Wed Nov 02 2005 - 00:00:01 EST