dspam no longer works after update

neal

neal

I just updated dspam on my system to the latest 3.10.1_2 port and it no longer works.

I have the following setup which worked perfectly before this last update:
opensmtpd -> dspam -> dovecot

All communication is using local domain sockets.

Unfortunately I get no error messages anywhere, even when running dspam with debug on and noforked. I have determined that dspam is failing to deliver mail to dovecot though, as if I reconfigure my pipeline without dspam it all works fine.

All I get in the maillog are entries such like:
Code: 
  Jun 16 13:36:19 mail smtpd[25086]: delivery: TempFail for 75749bf82a14ec18: from=<address removed>, to=<address removed>, user=removed, method=lmtp, delay=28m10s, stat=Error ("")

There is an entry in UPDATING:
Code: 
  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.

I have set the SETUID option, but I am running it as a daemon and it seems to be using the correct user and group, so if anyone has any ideas as to why this is suddenly not working, I'd be very grateful.
 
I don't have any ideas, but I'd start to try and eliminate possible causes. For starters: what happens if you start dspam manually as root? If it works normally after that then you can conclude that it's most likely a permission issue.
 
That was the first thing I tried, but with no luck unfortunately. This is what happens:

Code: 
root@mail:~ # dspam --daemon --nofork --debug
36822: [06/22/2016 10:01:29] Spawning daemon listener
36822: [06/22/2016 10:01:29] Creating local domain socket /var/run/dspam/dspam.sock
36822: [06/22/2016 10:01:35] checking trusted user list for root(0)
36822: [06/22/2016 10:01:37] checking trusted user list for root(0)

There seem to be no error messages that I can see as root is trusted. It at least shows that OpenSMTPd is contacting the dspam daemon on the local domain socket.
 
I've completely deleted dspam and reinstalled it again, but with no better results. I have turned on the BNR_DEBUG option, so I'm getting a lot more debug messages now.

Starting up dspam under root I get the following messages:
Code: 
61618: [06/27/2016 13:41:30] read attribute 'HashConcurrentUser'
61618: [06/27/2016 13:41:30] find attribute 'HashConcurrentUser'
61618: [06/27/2016 13:41:30]  -> read: not found attribute 'HashConcurrentUser'
61618: [06/27/2016 13:41:30] read attribute 'HashConnectionCache'
61618: [06/27/2016 13:41:30] find attribute 'HashConnectionCache'
61618: [06/27/2016 13:41:30]  -> found attribute 'HashConnectionCache' with value '10'
61618: [06/27/2016 13:41:30]  -> read attribute 'HashConnectionCache' with value '10'
61618: [06/27/2016 13:41:30] read attribute 'HashConnectionCache'
61618: [06/27/2016 13:41:30] find attribute 'HashConnectionCache'
61618: [06/27/2016 13:41:30]  -> found attribute 'HashConnectionCache' with value '10'
61618: [06/27/2016 13:41:30]  -> read attribute 'HashConnectionCache' with value '10'
61618: [06/27/2016 13:41:30] read attribute 'HashRecMax'
61618: [06/27/2016 13:41:30] find attribute 'HashRecMax'
61618: [06/27/2016 13:41:30]  -> found attribute 'HashRecMax' with value '98317'
61618: [06/27/2016 13:41:30]  -> read attribute 'HashRecMax' with value '98317'
61618: [06/27/2016 13:41:30] read attribute 'HashRecMax'
61618: [06/27/2016 13:41:30] find attribute 'HashRecMax'
61618: [06/27/2016 13:41:30]  -> found attribute 'HashRecMax' with value '98317'
61618: [06/27/2016 13:41:30]  -> read attribute 'HashRecMax' with value '98317'
61618: [06/27/2016 13:41:30] read attribute 'HashExtentSize'
61618: [06/27/2016 13:41:30] find attribute 'HashExtentSize'
61618: [06/27/2016 13:41:30]  -> found attribute 'HashExtentSize' with value '49157'
61618: [06/27/2016 13:41:30]  -> read attribute 'HashExtentSize' with value '49157'
61618: [06/27/2016 13:41:30] read attribute 'HashExtentSize'
61618: [06/27/2016 13:41:30] find attribute 'HashExtentSize'
61618: [06/27/2016 13:41:30]  -> found attribute 'HashExtentSize' with value '49157'
61618: [06/27/2016 13:41:30]  -> read attribute 'HashExtentSize' with value '49157'
61618: [06/27/2016 13:41:30] read attribute 'HashMaxExtents'
61618: [06/27/2016 13:41:30] find attribute 'HashMaxExtents'
61618: [06/27/2016 13:41:30]  -> found attribute 'HashMaxExtents' with value '0'
61618: [06/27/2016 13:41:30]  -> read attribute 'HashMaxExtents' with value '0'
61618: [06/27/2016 13:41:30] read attribute 'HashMaxExtents'
61618: [06/27/2016 13:41:30] find attribute 'HashMaxExtents'
61618: [06/27/2016 13:41:30]  -> found attribute 'HashMaxExtents' with value '0'
61618: [06/27/2016 13:41:30]  -> read attribute 'HashMaxExtents' with value '0'
61618: [06/27/2016 13:41:30] match attribute 'HashAutoExtend' with value 'on'
61618: [06/27/2016 13:41:30] find attribute 'HashAutoExtend'
61618: [06/27/2016 13:41:30]  -> found attribute 'HashAutoExtend' with value 'on'
61618: [06/27/2016 13:41:30]  -> matched attribute 'HashAutoExtend' with value 'on'
61618: [06/27/2016 13:41:30] read attribute 'HashPctIncrease'
61618: [06/27/2016 13:41:30] find attribute 'HashPctIncrease'
61618: [06/27/2016 13:41:30]  -> found attribute 'HashPctIncrease' with value '10'
61618: [06/27/2016 13:41:30]  -> read attribute 'HashPctIncrease' with value '10'
61618: [06/27/2016 13:41:30] read attribute 'HashPctIncrease'
61618: [06/27/2016 13:41:30] find attribute 'HashPctIncrease'
61618: [06/27/2016 13:41:30]  -> found attribute 'HashPctIncrease' with value '10'
61618: [06/27/2016 13:41:30]  -> read attribute 'HashPctIncrease' with value '10'
61618: [06/27/2016 13:41:30] read attribute 'HashMaxSeek'
61618: [06/27/2016 13:41:30] find attribute 'HashMaxSeek'
61618: [06/27/2016 13:41:30]  -> found attribute 'HashMaxSeek' with value '10'
61618: [06/27/2016 13:41:30]  -> read attribute 'HashMaxSeek' with value '10'
61618: [06/27/2016 13:41:30] read attribute 'HashMaxSeek'
61618: [06/27/2016 13:41:30] find attribute 'HashMaxSeek'
61618: [06/27/2016 13:41:30]  -> found attribute 'HashMaxSeek' with value '10'
61618: [06/27/2016 13:41:30]  -> read attribute 'HashMaxSeek' with value '10'
61618: [06/27/2016 13:41:30] read attribute 'ServerPID'
61618: [06/27/2016 13:41:30] find attribute 'ServerPID'
61618: [06/27/2016 13:41:30]  -> read: not found attribute 'ServerPID'
61618: [06/27/2016 13:41:30] Spawning daemon listener
61618: [06/27/2016 13:41:30] read attribute 'ServerPort'
61618: [06/27/2016 13:41:30] find attribute 'ServerPort'
61618: [06/27/2016 13:41:30]  -> read: not found attribute 'ServerPort'
61618: [06/27/2016 13:41:30] read attribute 'ServerQueueSize'
61618: [06/27/2016 13:41:30] find attribute 'ServerQueueSize'
61618: [06/27/2016 13:41:30]  -> read: not found attribute 'ServerQueueSize'
61618: [06/27/2016 13:41:30] read attribute 'ServerDomainSocketPath'
61618: [06/27/2016 13:41:30] find attribute 'ServerDomainSocketPath'
61618: [06/27/2016 13:41:30]  -> found attribute 'ServerDomainSocketPath' with value '/var/run/dspam/dspam.sock'
61618: [06/27/2016 13:41:30]  -> read attribute 'ServerDomainSocketPath' with value '/var/run/dspam/dspam.sock'
61618: [06/27/2016 13:41:30] read attribute 'ServerDomainSocketPath'
61618: [06/27/2016 13:41:30] find attribute 'ServerDomainSocketPath'
61618: [06/27/2016 13:41:30]  -> found attribute 'ServerDomainSocketPath' with value '/var/run/dspam/dspam.sock'
61618: [06/27/2016 13:41:30]  -> read attribute 'ServerDomainSocketPath' with value '/var/run/dspam/dspam.sock'
61618: [06/27/2016 13:41:30] Creating local domain socket /var/run/dspam/dspam.sock

From what I can see, this all looks as expected.

When a mail message is sent to it from smtpd I get the following:
Code: 
61618: [06/27/2016 13:42:18] read attribute 'ServerIdent'
61618: [06/27/2016 13:42:18] find attribute 'ServerIdent'
61618: [06/27/2016 13:42:18]  -> found attribute 'ServerIdent' with value 'nicandneal.net'
61618: [06/27/2016 13:42:18]  -> read attribute 'ServerIdent' with value 'nicandneal.net'
61618: [06/27/2016 13:42:18] read attribute 'ServerMode'
61618: [06/27/2016 13:42:18] find attribute 'ServerMode'
61618: [06/27/2016 13:42:18]  -> found attribute 'ServerMode' with value 'auto'
61618: [06/27/2016 13:42:18]  -> read attribute 'ServerMode' with value 'auto'
61618: [06/27/2016 13:42:18] read attribute 'ServerMode'
61618: [06/27/2016 13:42:18] find attribute 'ServerMode'
61618: [06/27/2016 13:42:18]  -> found attribute 'ServerMode' with value 'auto'
61618: [06/27/2016 13:42:18]  -> read attribute 'ServerMode' with value 'auto'
61618: [06/27/2016 13:42:18] read attribute 'ServerMode'
61618: [06/27/2016 13:42:18] find attribute 'ServerMode'
61618: [06/27/2016 13:42:18]  -> found attribute 'ServerMode' with value 'auto'
61618: [06/27/2016 13:42:18]  -> read attribute 'ServerMode' with value 'auto'
61618: [06/27/2016 13:42:18] read attribute 'ServerMode'
61618: [06/27/2016 13:42:18] find attribute 'ServerMode'
61618: [06/27/2016 13:42:18]  -> found attribute 'ServerMode' with value 'auto'
61618: [06/27/2016 13:42:18]  -> read attribute 'ServerMode' with value 'auto'
61618: [06/27/2016 13:42:18] SEND: 220 DSPAM LMTP 3.10.2 Ready
61618: [06/27/2016 13:42:18] SRECV: LHLO mail.home

61618: [06/27/2016 13:42:18] read attribute 'ServerPass.mail.home'
61618: [06/27/2016 13:42:18] find attribute 'ServerPass.mail.home'
61618: [06/27/2016 13:42:18]  -> read: not found attribute 'ServerPass.mail.home'
61618: [06/27/2016 13:42:18] SEND: 250-nicandneal.net
61618: [06/27/2016 13:42:18] SEND: 250-PIPELINING
61618: [06/27/2016 13:42:18] SEND: 250-ENHANCEDSTATUSCODES
61618: [06/27/2016 13:42:18] SEND: 250-8BITMIME
61618: [06/27/2016 13:42:18] SEND: 250 SIZE
61618: [06/27/2016 13:42:18] checking trusted user list for root(0)
61618: [06/27/2016 13:42:18] SRECV: MAIL FROM:<Important-News@5uixmsl.nufdiet.top>

61618: [06/27/2016 13:42:18] SEND: 250 2.1.0 OK
61618: [06/27/2016 13:42:18] read attribute 'ServerParameters'
61618: [06/27/2016 13:42:18] find attribute 'ServerParameters'
61618: [06/27/2016 13:42:18]  -> found attribute 'ServerParameters' with value '--deliver=innocent -d %u'
61618: [06/27/2016 13:42:18]  -> read attribute 'ServerParameters' with value '--deliver=innocent -d %u'
61618: [06/27/2016 13:42:18] SRECV: RCPT TO:<neal>

61618: [06/27/2016 13:42:18] match attribute 'Broken' with value 'case'
61618: [06/27/2016 13:42:18] find attribute 'Broken'
61618: [06/27/2016 13:42:18]  -> match: not found attribute 'Broken'
61618: [06/27/2016 13:42:18] match attribute 'StripRcptDomain' with value 'on'
61618: [06/27/2016 13:42:18] find attribute 'StripRcptDomain'
61618: [06/27/2016 13:42:18]  -> found attribute 'StripRcptDomain' with value 'off'
61618: [06/27/2016 13:42:18]  -> match: not found attribute 'StripRcptDomain' with value 'on'
61618: [06/27/2016 13:42:18] SEND: 250 2.1.5 OK
61618: [06/27/2016 13:42:18] SRECV: DATA
61618: [06/27/2016 13:42:18] read attribute 'ClientHost'
61618: [06/27/2016 13:42:18] find attribute 'ClientHost'
61618: [06/27/2016 13:42:18]  -> found attribute 'ClientHost' with value '/var/run/dspam/dspam.sock'
61618: [06/27/2016 13:42:18]  -> read attribute 'ClientHost' with value '/var/run/dspam/dspam.sock'
61618: [06/27/2016 13:42:18] read attribute 'TrainingMode'
61618: [06/27/2016 13:42:18] find attribute 'TrainingMode'
61618: [06/27/2016 13:42:18]  -> found attribute 'TrainingMode' with value 'tum'
61618: [06/27/2016 13:42:18]  -> read attribute 'TrainingMode' with value 'tum'
61618: [06/27/2016 13:42:18] read attribute 'TrustedDeliveryAgent'
61618: [06/27/2016 13:42:18] find attribute 'TrustedDeliveryAgent'
61618: [06/27/2016 13:42:18]  -> found attribute 'TrustedDeliveryAgent' with value '/usr/local/libexec/dovecot/dovecot-lda'
61618: [06/27/2016 13:42:18]  -> read attribute 'TrustedDeliveryAgent' with value '/usr/local/libexec/dovecot/dovecot-lda'
61618: [06/27/2016 13:42:18] read attribute 'QuarantineAgent'
61618: [06/27/2016 13:42:18] find attribute 'QuarantineAgent'
61618: [06/27/2016 13:42:18]  -> found attribute 'QuarantineAgent' with value '/usr/local/libexec/dovecot/dovecot-lda'
61618: [06/27/2016 13:42:18]  -> read attribute 'QuarantineAgent' with value '/usr/local/libexec/dovecot/dovecot-lda'
61618: [06/27/2016 13:42:18] read attribute 'QuarantineAgent'
61618: [06/27/2016 13:42:18] find attribute 'QuarantineAgent'
61618: [06/27/2016 13:42:18]  -> found attribute 'QuarantineAgent' with value '/usr/local/libexec/dovecot/dovecot-lda'
61618: [06/27/2016 13:42:18]  -> read attribute 'QuarantineAgent' with value '/usr/local/libexec/dovecot/dovecot-lda'
61618: [06/27/2016 13:42:18] find attribute 'Feature'
61618: [06/27/2016 13:42:18]  -> found attribute 'Feature' with value 'whitelist'
61618: [06/27/2016 13:42:18] find attribute 'Feature'
61618: [06/27/2016 13:42:18]  -> found attribute 'Feature' with value 'whitelist'
61618: [06/27/2016 13:42:18] match attribute 'ParseToHeaders' with value 'on'
61618: [06/27/2016 13:42:18] find attribute 'ParseToHeaders'
61618: [06/27/2016 13:42:18]  -> match: not found attribute 'ParseToHeaders'
61618: [06/27/2016 13:42:18] SEND: 354 Enter mail, end with "." on a line by itself

At this point smtpd reports a failure and no mail is sent to dovecot. Also nothing is written to /var/db/dspam/data.
 
You must log in or register to reply here.
Back
Top