Solved dspam fails after upgrade to repo version (VIRT_USERS in use)

J

jef

Edit: This was apparently caused by VIRT_USERS not being set in the FreeBSD-repo version of dspam

Consider using pkg lock mail/dspam to prevent locally compiled versions from the ports tree from being overridden during pkg upgrade

Edit: Note that there is a schema update between dspam 3.9 and dspam 3.10

After upgrading dspam using pkg and the FreeBSD package repository (9.3-STABLE), I no longer have dspam processing messages successfully.

The maillog messages are along the lines of
Code: 
Nov  4 11:37:42 mail dspam[83036]: bailing on error -2
Nov  4 11:37:42 mail dspam[83036]: received invalid result (!DSR_ISSPAM && !DSR_ISINNOCENT): -2
Nov  4 11:37:42 mail dspam[83036]: process_message returned error -5.  delivering.
and there is no dspam processing evident on the message.

I've read the UPDATING note
Code: 
20160501:
  AFFECTS: users of mail/dspam
  AUTHOR: junovitch@FreeBSD.org

  dspam has been modified to no longer run as root:mail by default.
  Existing configuration must be adjusted to reflect using a non-privileged
  port and the /var/run/dspam directory for PID and socket files.  If you
  need dspam to run as root for your mail setup, you can use the SETUID
  config option to enable the old insecure behavior.

and have checked that the appropriate files (as far as I know) are all writable (or at least readable) by the dspam user
Code: 
root@mail:/ # ls -l /usr/local/etc/dspam.conf
-rw-r--r--  1 root  mail  36278 Nov  4 06:53 /usr/local/etc/dspam.conf
root@mail:/ # ls -ld /var/run/dspam
drwxr-xr-x  2 dspam  dspam  2 Nov  4 11:19 /var/run/dspam
root@mail:/ # ls -ld /var/db/dspam/
drwxrwx---  3 dspam  dspam  8 Oct 31 22:34 /var/db/dspam/
root@mail:/ # ls -ld /var/spool/postfix/dspam/
drwxrwxr-x  2 postfix  dspam  2 Nov  4 11:19 /var/spool/postfix/dspam/
root@mail:/ # ls -ld /var/log/dspam/
drwxrwx---  2 dspam  dspam  9 Nov  4 11:01 /var/log/dspam/

I've also ensured that everything under /var/db/dspam/ is owned by dspam:dspam

I've manually checked that the mysql database can be accessed by the dspam login credentials using mysql from the command line.

Running # dspam --daemon --nofork --debug suggests that there is a problem accessing the mysql database

Code: 
root@mail:/ # dspam --version

DSPAM Anti-Spam Suite 3.10.2 (agent/library)

Copyright (C) 2002-2012 DSPAM Project
http://dspam.sourceforge.net.

DSPAM may be copied only under the terms of the GNU Affero General Public
License, a copy of which can be found with the DSPAM distribution kit.

Configuration parameters:  '--sysconfdir=/usr/local/etc' '--with-logdir=/var/log/dspam' '--with-dspam-home=/var/db/dspam' '--with-dspam-home-owner=dspam' '--with-dspam-home-group=dspam' '--with-dspam-home-mode=0770' '--with-dspam-owner=dspam' '--with-dspam-group=dspam' '--enable-syslog' '--enable-debug' '--enable-daemon' '--enable-clamav' '--with-pgsql-includes=/usr/local/include' '--with-pgsql-libraries=/usr/local/lib' '--with-sqlite-includes=/usr/local/include' '--with-sqlite-libraries=/usr/local/lib' '--with-mysql-includes=/usr/local/include/mysql' '--with-mysql-libraries=/usr/local/lib/mysql' '--enable-client-compression' '--with-storage-driver=pgsql_drv,sqlite3_drv,hash_drv,mysql_drv' '--with-dspam-mode=0555' '--prefix=/usr/local' '--localstatedir=/var' '--mandir=/usr/local/man' '--infodir=/usr/local/info/' '--build=amd64-portbld-freebsd9.3' 'build_alias=amd64-portbld-freebsd9.3' 'CC=cc' 'CFLAGS=-pipe -g -fstack-protector -fno-strict-aliasing' 'LDFLAGS= -L/usr/local/lib -L/usr/local/lib -fstack-protector' 'LIBS=' 'CPPFLAGS=-I/usr/local/include -I/usr/local/include' 'CPP=cpp'

Things appear to start up OK
Code: 
Nov  4 11:45:05 mail dspam[83910]: Daemon process starting
84682: [11/04/2016 12:07:20] dspam_init_driver: initializing lock 0
Nov  4 12:07:20 mail dspam[84682]: Daemon process starting
84682: [11/04/2016 12:07:20] dspam_init_driver: initializing lock 1
84682: [11/04/2016 12:07:20] dspam_init_driver: initializing lock 2
84682: [11/04/2016 12:07:20] dspam_init_driver: initializing lock 3
84682: [11/04/2016 12:07:20] dspam_init_driver: initializing lock 4
84682: [11/04/2016 12:07:20] dspam_init_driver: initializing lock 5
84682: [11/04/2016 12:07:20] dspam_init_driver: initializing lock 6
84682: [11/04/2016 12:07:20] dspam_init_driver: initializing lock 7
84682: [11/04/2016 12:07:20] dspam_init_driver: initializing lock 8
84682: [11/04/2016 12:07:20] dspam_init_driver: initializing lock 9
84682: [11/04/2016 12:07:20] Spawning daemon listener
84682: [11/04/2016 12:07:20] Creating local domain socket /var/spool/postfix/dspam/dspam.sock

As soon as a message gets sent to dspam from postfix
(don't worry, the email address shown is already heavily spammed from being on the open Internet for years),
Code: 
84682: [11/04/2016 12:07:47] DSPAM Instance Startup
84682: [11/04/2016 12:07:47] input args: dspam --deliver=innocent,spam
84682: [11/04/2016 12:07:47] pass-thru args:
84682: [11/04/2016 12:07:47] processing user freebsd@wagsky.com
84682: [11/04/2016 12:07:47] uid = 0, euid = 0, gid = 0, egid = 0
84682: [11/04/2016 12:07:47] loading preferences for user freebsd@wagsky.com
84682: [11/04/2016 12:07:47] default preferences empty. reverting to dspam.conf preferences.
84682: [11/04/2016 12:07:47] Loading preferences from dspam.conf
84682: [11/04/2016 12:07:47] using /var/db/dspam/opt-in/freebsd@wagsky.com.dspam as path
84682: [11/04/2016 12:07:47] using /var/db/dspam/opt-out/freebsd@wagsky.com.nodspam as path
84682: [11/04/2016 12:07:47] assigning user freebsd@wagsky.com to shared group heavily-spammed
84682: [11/04/2016 12:07:47] sedation level set to: 5
84682: [11/04/2016 12:07:47] _mysql_drv_get_spamtotals: unable to _mysql_drv_getpwnam(heavily-spammed)
84682: [11/04/2016 12:07:47] _ds_init_storage: unable to load totals. Using zero values.
84682: [11/04/2016 12:07:47] Connecting to 127.0.0.1:3310 for virus check
84682: [11/04/2016 12:07:47] Connecting to 127.0.0.1:1328 for virus stream transmission
84682: [11/04/2016 12:07:47] _ds_getall_spamrecords: unable to _mysql_drv_getpwnam(heavily-spammed)
84682: [11/04/2016 12:07:47] _ds_getall_spamrecords() failed
Nov  4 12:07:47 mail dspam[84682]: bailing on error -2
84682: [11/04/2016 12:07:47] total processing time: 0.01134s
Nov  4 12:07:47 mail dspam[84682]: received invalid result (!DSR_ISSPAM && !DSR_ISINNOCENT): -2
84682: [11/04/2016 12:07:47] _mysql_drv_set_spamtotals: unable to _mysql_drv_getpwnam(heavily-spammed)
84682: [11/04/2016 12:07:47] delivering message
84682: [11/04/2016 12:07:47] Establishing connection to 127.0.0.1:24
Nov  4 12:07:47 mail dspam[84682]: process_message returned error -5.  delivering.
84682: [11/04/2016 12:07:47] Connection established
84682: [11/04/2016 12:07:48] DSPAM Instance Shutdown.  Exit Code: 0
84682: [11/04/2016 12:07:48] checking trusted user list for root(0)
Nov  4 12:07:48 mail postfix/lmtp[84685]: D178640F: to=<freebsd@wagsky.com>, relay=mail.pn.wagsky.com[dspam/dspam.sock], delay=0.69, delays=0.05/0/0/0.64, dsn=2.6.0, status=sent (250 2.6.0 <freebsd@wagsky.com> Message accepted for delivery)

I can confirm that the (virtual) address exists by logging in with the dspam credentials and executing mysql> select * from dspam_virtual_uids ;

It appears that the first failure is
Code: 
_mysql_drv_get_spamtotals: unable to _mysql_drv_getpwnam(freebsd@wagsky.com)

Running mysql56-server-5.6.34

I have the same behavior with all email addresses, not just the ones in the heavily-spammed group.



Any suggestions as what to look at next?

TIA,

Jeff
 
Last edited:
One "secret" appears to be hidden in /usr/local/share/doc/upgrading
Be warned that the schema upgrade may not be quick!

Edit: This does not solve the problems, though should be done for compatibility with 3.10

Code: 
/usr/local/share/doc/dspam # less UPGRADING
Follow the steps sequentially from the base version you are running up to
the top.

UPGRADING FROM 3.9.0
--------------------

1. Ensure MySQL is using latin1 character set. This should reduce the needed
   database space. The following clauses should be executed for upgrading 3.9.0
   DSPAM MySQL schema:
     ALTER TABLE `dspam_signature_data`
       CHANGE `signature` `signature` VARCHAR(32) CHARACTER SET latin1 COLLATE latin1_general_ci NOT NULL;
     ALTER TABLE `dspam_signature_data`
       DEFAULT CHARACTER SET latin1 COLLATE latin1_general_ci;
     ALTER TABLE `dspam_stats`
       DEFAULT CHARACTER SET latin1 COLLATE latin1_general_ci;
     ALTER TABLE `dspam_token_data`
       DEFAULT CHARACTER SET latin1 COLLATE latin1_general_ci;

   If you are using preference extension with DSPAM, then you should execute
   the following clause for upgrading DSPAM preference MySQL schema to use
   latin1 character set:
     ALTER TABLE `dspam_preferences`
       CHANGE `preference` `preference` VARCHAR(32) CHARACTER SET latin1 COLLATE latin1_general_ci NOT NULL;
     ALTER TABLE `dspam_preferences`
       CHANGE `value` `value` VARCHAR(64) CHARACTER SET latin1 COLLATE latin1_general_ci NOT NULL;
     ALTER TABLE `dspam_preferences`
       DEFAULT CHARACTER SET latin1 COLLATE latin1_general_ci;

   If you are using the DSPAM virtual user feature then execute the following
   clauses to update the DSPAM virtual user table to use latin1 character set:
     ALTER TABLE `dspam_virtual_uids`
       CHANGE `username` `username` VARCHAR(128) CHARACTER SET latin1 COLLATE latin1_general_ci NOT NULL;
     ALTER TABLE `dspam_virtual_uids`
       DEFAULT CHARACTER SET latin1 COLLATE latin1_general_ci;
 
Last edited:
Destroying the dspam database and recreating it, using
Code: 
root@mail:/ # mysql -u root -p dspam < /usr/local/share/examples/dspam/mysql/mysql_objects-4.1.sql 
Enter password: 
root@mail:/ # mysql -u root -p dspam < /usr/local/share/examples/dspam/mysql/virtual_users.sql 
Enter password:
and granting all to 'dspam'@'localhost' did not resolve the problem.
 
I wish it was getting better, but it's getting stranger now.

I've turned on logging in mysql and when I service dspam restart I see the connections being accepted in hte log:
Code: 
 161109 13:36:14      10 Quit 
          11 Quit 
          12 Quit 
          13 Connect    dspam@localhost on dspam
          14 Connect    dspam@localhost on dspam
          15 Connect    dspam@localhost on dspam

(See http://dev.mysql.com/doc/refman/5.6/en/query-log.html)

However, I don't see any transactions when dspam tries to process a message.

I do see "manual" queries showing up in the log, including invalid ones ( tail of mysql log running in background of interactive session):
Code: 
# jexec mail mysql -u dspam -p dspam
Enter password:
161109 13:40:46      16 Connect    dspam@localhost on dspam
          16 Query    show databases
          16 Query    show tables
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

          16 Field List    dspam_preferences
          16 Field List    dspam_signature_data
          16 Field List    dspam_stats
          16 Field List    dspam_token_data
          16 Field List    dspam_virtual_uids
Welcome to the MySQL monitor.  Commands end with ; or \g.
          16 Query    select @@version_comment limit 1
Your MySQL connection id is 16
Server version: 5.6.34 Source distribution

Copyright (c) 2000, 2016, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> SELECT * FROM dspam_virtual_users ;
161109 13:41:06      16 Query    SELECT * FROM dspam_virtual_users
ERROR 1146 (42S02): Table 'dspam.dspam_virtual_users' doesn't exist
mysql> SELECT * FROM dspam_virtual_uids ;
161109 13:41:18      16 Query    SELECT * FROM dspam_virtual_uids
Empty set (0.00 sec)

This and previous posts left as they may help another locate this thread, or a solution.
 
You must log in or register to reply here.
Back
Top