Debugging spamassassin with postfix

Question

I am trying to setup spamassassin milter on my postfix mail server.

SpamAssassin Server version 3.4.1
  running on Perl 5.20.2
  with SSL support (IO::Socket::SSL 2.019)
  with zlib support (Compress::Zlib 2.064)

Postfix mail_version = 2.11.3

When i activate the milter by adding it to this line:

smtpd_milters = unix:/spamassassin/spamd.sock unix:/clamav/clamav-milter.ctl unix:/opendkim/opendkim.sock

strangely enough sending mail takes longer to complete (i thought spamassassin works only on received email) and i get the following logs :

Jan 28 15:39:38 mymailserver spamd[22388]: spamd: got connection over /var/spool/postfix/spamassassin/spamd.sock
Jan 28 15:40:08 mymailserver spamd[22388]: spamd: timeout: (30 second socket timeout reading input from client)
Jan 28 15:40:08 mymailserver postfix/smtpd[29865]: warning: milter unix:/spamassassin/spamd.sock: unreasonable packet length: 1397768525 > 1073741823
Jan 28 15:40:08 mymailserver postfix/smtpd[29865]: warning: milter unix:/spamassassin/spamd.sock: read error in initial handshake

The last error changes randomly, sometimes it complains about expecting something but receiving something else, which sounds reasonable because it's having problems reading from the socket.

I would like to learn how to debug this but I'm not even sure where to start. At least i'm certain that the socket exists and has the right owner, at least judging from the got connection over ... we can rule out socket existence and permissions.

There are also some other warnings that i'm not sure if they are related, but i was thinking of tackling those after

Jan 28 15:40:09 mymailserver dovecot: lda(me@mydomain.com): Debug: sieve: Pigeonhole version 0.4.8 (0c4ae064f307+) initializing
Jan 28 15:40:09 mymailserver dovecot: lda(me@mydomain.com): Debug: sieve: include: sieve_global is not set; it is currently not possible to include `:global' scripts.
Jan 28 15:40:09 mymailserver dovecot: lda(me@mydomain.com): Debug: sieve: file storage: Storage path `/var/mail/vmail/mydomain.com/me/sieve' not found
Jan 28 15:40:09 mymailserver dovecot: lda(me@mydomain.com): Debug: sieve: file storage: Using Sieve script path: /var/mail/vmail/mydomain.com/me/.dovecot.sieve
Jan 28 15:40:09 mymailserver dovecot: lda(me@mydomain.com): Debug: sieve: file storage: Storage path `/var/mail/vmail/mydomain.com/me/.dovecot.sieve' not found
Jan 28 15:40:09 mymailserver dovecot: lda(me@mydomain.com): Debug: sieve: storage: No default script location configured
Jan 28 15:40:09 mymailserver dovecot: lda(me@mydomain.com): Debug: sieve: User has no personal script
Jan 28 15:40:09 mymailserver dovecot: lda(me@mydomain.com): Debug: sieve: file storage: Storage path `/var/mail/vmail/sieve-before' not found
Jan 28 15:40:09 mymailserver dovecot: lda(me@mydomain.com): Debug: sieve: Location for sieve_before not found: /var/mail/vmail/sieve-before
Jan 28 15:40:09 mymailserver dovecot: lda(me@mydomain.com): Debug: sieve: file storage: Storage path `/var/mail/vmail/sieve-after' not found
Jan 28 15:40:09 mymailserver dovecot: lda(me@mydomain.com): Debug: sieve: Location for sieve_after not found: /var/mail/vmail/sieve-after
Jan 28 15:40:09 mymailserver dovecot: lda(me@mydomain.com): Debug: sieve: No scripts to execute: reverting to default delivery.

** Update 1 **

Here is the content of my main.cf

alias_maps = hash:/etc/aliases
append_dot_mydomain = no
biff = no
broken_sasl_auth_clients = yes
command_directory = /usr/sbin
config_directory = /etc/postfix
daemon_directory = /usr/lib/postfix
data_directory = /var/lib/postfix
debugger_command = PATH=/bin:/usr/bin:/usr/local/bin:/usr/X11R6/bin ddd $daemon_directory/$process_name $process_id & sleep 5
default_destination_concurrency_limit = 5
disable_vrfy_command = yes
inet_interfaces = all
inet_protocols = all
local_recipient_maps = unix:passwd.byname $alias_maps
mailbox_size_limit = 0
message_size_limit = 104857600
milter_connect_macros = j {daemon_name} v {if_name} _
milter_default_action = accept
mydestination = localhost.$mydomain, localhost, $mydomain
mydomain = example.com
myhostname = mail.example.com
mynetworks = 127.0.0.0/8 10.0.0.0/8 [::ffff:127.0.0.0]/104 [::1]/128
myorigin = /etc/mailname
non_smtpd_milters = $smtpd_milters
readme_directory = no
recipient_delimiter = +
relay_destination_concurrency_limit = 1
smtp_tls_note_starttls_offer = yes
smtp_tls_security_level = may
smtp_tls_session_cache_database = btree:${data_directory}/smtp_scache
smtpd_banner = $myhostname ESMTP
smtpd_helo_required = yes
smtpd_helo_restrictions = permit_mynetworks, reject_invalid_helo_hostname, permit
smtpd_milters = unix:/clamav/clamav-milter.ctl unix:/opendkim/opendkim.sock
smtpd_recipient_restrictions = reject_unknown_sender_domain, reject_unknown_recipient_domain, reject_unauth_pipelining, permit_mynetworks, permit_sasl_authenticated, reject_unauth_destination, reject_invalid_hostname, reject_non_fqdn_sender
smtpd_relay_restrictions = permit_mynetworks permit_sasl_authenticated defer_unauth_destination
smtpd_sasl_auth_enable = yes
smtpd_sasl_authenticated_header = yes
smtpd_sasl_local_domain = $myhostname
smtpd_sasl_path = private/auth
smtpd_sasl_security_options = noanonymous
smtpd_sasl_type = dovecot
smtpd_sender_login_maps = $virtual_mailbox_maps
smtpd_sender_restrictions = check_sender_access hash:/etc/postfix/sender_checks, reject_unknown_sender_domain, reject_sender_login_mismatch
smtpd_tls_CAfile = /etc/ssl/certs/ca-certificates.crt
smtpd_tls_ask_ccert = yes
smtpd_tls_auth_only = yes
smtpd_tls_cert_file = /etc/ssl/private/mail_example_com.pem
smtpd_tls_ciphers = high
smtpd_tls_key_file = /etc/ssl/private/mail_example_com.key
smtpd_tls_loglevel = 0
smtpd_tls_mandatory_ciphers = medium
smtpd_tls_mandatory_protocols = SSLv3, TLSv1
smtpd_tls_received_header = yes
smtpd_tls_security_level = may
smtpd_tls_session_cache_database = btree:${data_directory}/smtpd_scache
smtpd_tls_session_cache_timeout = 3600s
smtpd_use_tls = yes
tls_random_source = dev:/dev/urandom
unknown_address_reject_code = 550
unknown_client_reject_code = 550
unknown_hostname_reject_code = 550
unknown_local_recipient_reject_code = 550
virtual_alias_maps = hash:/etc/postfix/virtual
virtual_mailbox_base = /var/mail/vmail
virtual_mailbox_domains = hash:/etc/postfix/virtual-mailbox-domains
virtual_mailbox_maps = hash:/etc/postfix/virtual-mailbox-users
virtual_transport = dovecot

Answer 1

If I understand things correctly then spamassassin (or spamd, as you are using here) can not directly be used as a milter.

You need spamass-milter in addition to spamassassin.

See here: http://www.stefan-seelmann.de/wiki/mailserver-postfix-dovecot or here: https://www.nesono.com/node/220 for reference.

Answer 2

As pointed out by the accepted answer, there are a couple of conmponents to get this to work. I have had both spamassassin and spamass-milter installed.

However, during the setup, i misunderstood how to setup the sockets so here are the relevant files/lines

First /etc/default/spamassassin :

OPTIONS="-x --max-children 5 --nouser-config --helper-home-dir /var/lib/spamassassin -u debian-spamd -g debian-spamd --siteconfigpath /etc/spamassassin --socketpath=/var/run/spamassassin/spamd.sock --socketowner=debian-spamd --socketgro$

Second /etc/default/spamass-milter :

OPTIONS="-u spamass-milter -i 127.0.0.1 -m -I -- --socket=/var/run/spamassassin/spamd.sock"

And last, /etc/postfix/main.cf

smtpd_milters = unix:/spamass/spamass.sock

So in conclusion, from what i understood, there are a couple of sockets used. One is for communication between the milter and spamassassin (spamd.sock) and one between Postfix and the milter (spamass.sock). Previously i had forced them all to use the same socket, which explained why sometimes it would work (by chance) and sometimes errors would point out that something unexpected...

So upon setting these correctly, the errors about spamassassin were gone and the performance was restore. I also didn't see any more sieve related messages, but i'm not completely sure if they were related. I haven't done any other configuration changes besides the one above.