Postfix / Parallels Outbound Anti Spam - SASL Error

[euphbasio]

Hi,

I recently installed (and subscribed to) Parallels Outboound Anti Spam. Everything was fine for a couple of days, and then this morning I am seeing a lot of error in the maillog relating to SASL Auth and passwd.db.

Apr 1 22:35:24 pluto plesk_saslauthd[5329]: listen=6, status=5, dbpath='/var/spool/postfix/plesk/passwd.db', keypath='/var/spool/postfix/plesk/passwd_db_key', chroot=1, unprivileged=1
Apr 1 22:35:24 pluto plesk_saslauthd[5329]: privileges set to (89:89) (effective 89:89)
Apr 1 21:35:24 pluto plesk_saslauthd[5329]: Can't read encryption key from '/var/spool/postfix/plesk/passwd_db_key': No such file or directory (2)
Apr 1 21:35:24 pluto plesk_saslauthd[5329]: Failed to initialize encryption cipher 'AES-256-CBCKCS' with key '/var/spool/postfix/plesk/passwd_db_key'
Apr 1 21:35:24 pluto plesk_saslauthd[5329]: Failed to initialize password cipher context
Apr 1 21:35:24 pluto plesk_saslauthd[5329]: main cycle started
Apr 1 21:35:24 pluto plesk_saslauthd[5329]: main cycle iteration
Apr 1 21:35:24 pluto plesk_saslauthd[5329]: activity on 1 channel(s)
Apr 1 21:35:24 pluto plesk_saslauthd[5329]: new client (fd=10) registered
Apr 1 21:35:24 pluto plesk_saslauthd[5329]: main cycle iteration
Apr 1 21:35:24 pluto plesk_saslauthd[5329]: activity on 1 channel(s)
Apr 1 21:35:24 pluto plesk_saslauthd[5329]: some read activity on client 10
Apr 1 21:35:24 pluto plesk_saslauthd[5329]: read(10, &buf, 2)=2
Apr 1 21:35:24 pluto plesk_saslauthd[5329]: processing client data chunk [state=0]
Apr 1 21:35:24 pluto plesk_saslauthd[5329]: read(10, &buf, 6)=6
Apr 1 21:35:24 pluto plesk_saslauthd[5329]: processing client data chunk [state=1]
Apr 1 21:35:24 pluto plesk_saslauthd[5329]: read(10, &buf, 2)=2
Apr 1 21:35:24 pluto plesk_saslauthd[5329]: processing client data chunk [state=2]
Apr 1 21:35:24 pluto plesk_saslauthd[5329]: read(10, &buf, 10)=10
Apr 1 21:35:24 pluto plesk_saslauthd[5329]: processing client data chunk [state=3]
Apr 1 21:35:24 pluto plesk_saslauthd[5329]: read(10, &buf, 2)=2
Apr 1 21:35:24 pluto plesk_saslauthd[5329]: processing client data chunk [state=4]
Apr 1 21:35:24 pluto plesk_saslauthd[5329]: read(10, &buf, 4)=4
Apr 1 21:35:24 pluto plesk_saslauthd[5329]: processing client data chunk [state=5]
Apr 1 21:35:24 pluto plesk_saslauthd[5329]: read(10, &buf, 2)=2
Apr 1 21:35:24 pluto plesk_saslauthd[5329]: processing client data chunk [state=6]
Apr 1 21:35:24 pluto plesk_saslauthd[5329]: read(10, &buf, 12)=12
Apr 1 21:35:24 pluto plesk_saslauthd[5329]: processing client data chunk [state=7]
Apr 1 21:35:24 pluto plesk_saslauthd[5329]: Unable to open database(readonly) /var/spool/postfix/plesk/passwd.db: unable to open database file
Apr 1 21:35:24 pluto plesk_saslauthd[5329]: main cycle iteration
Apr 1 21:35:24 pluto plesk_saslauthd[5329]: activity on 1 channel(s)
Apr 1 21:35:24 pluto plesk_saslauthd[5329]: some write activity on client 10
Apr 1 21:35:24 pluto plesk_saslauthd[5329]: attempt to write(10, &buf, 4)
Apr 1 21:35:24 pluto plesk_saslauthd[5329]: client 10 processed
Apr 1 21:35:24 pluto plesk_saslauthd[5329]: main cycle iteration

Does anyone have any suggestions about this?

Many thanks,

euphbasio

 

[euphbasio]

Interestingly, this is always triggered when the same users attempts to log in with IMAP.

Any ideas?

Thanks.

 

[euphbasio]

Can anyone make any suggestions for this? Could use a hand to get our email back online.

Thanks.

 

[IgorG]

Do you have these files at least?

/var/spool/postfix/plesk/passwd.db
/var/spool/postfix/plesk/passwd_db_key

Have you tried mchck --with-spam ?

 

[euphbasio]

Hi Igor,

Yes, both exist and mchk runs with no errors (did this yesterday and errors still appearing since).

==> Checking for: mailsrv_conf_init... ok
==> Checking for: mail_handlers_init... ok
==> Checking for: mailsrv_entities_dump... ok
==> Checking for: mail_admin_aliases... ok
==> Checking for: mail_auth_dump... ok
==> Checking for: mailman_lists_dump... ok
==> Checking for: mail_kav8_restore... ok
==> Checking for: mail_responder_restore... ok
==> Checking for: mail_postfix_transport_restore... ok
==> Checking for: mail_spam_restore... ok
==> Checking for: mail_grey_restore... ok
==> Checking for: mail_mailbox_restore... ok
==> Checking for: mail_spf_restore... ok
==> Checking for: mail_dk_restore... ok
==> Checking for: mail_drweb_restore... not exists

Most mailboxes seem to be OK, just one user for whom the above is appearing on each auth attempt.

Thanks.

 

[euphbasio]

A bit more in this, looking at messages, I see the below:

Apr 2 13:59:41 pluto postfix/smtpd[21951]: SQL engine 'intentionally disabled' not supported
Apr 2 13:59:41 pluto postfix/smtpd[21951]: auxpropfunc error no mechanism available

Comparing sasl and sasl2 smtpd.conf reveals:

sasl - smtpd.conf:

pwcheck_method: auxprop saslauthd
auxprop_plugin: sql_sqlite3
saslauthd_path: /var/spool/postfix/private/plesk_saslauthd
mech_list: DIGEST-MD5 CRAM-MD5 PLAIN LOGIN
auto_transition: yes
sql_engine: sqlite3
sql_hostnames: localhost
sql_database: /var/spool/postfix/plesk/passwd.db
sql_select: SELECT `%p` FROM domains d, users u WHERE u.name='%u' and d.name='%r' and d.status=0 and u.status=0 and u.dom_id=d.id
sql_verbose: yes
log_level: 9

sasl2 - smtpd.conf

pwcheck_method: auxprop saslauthd
auxprop_plugin: plesk
saslauthd_path: /var/spool/postfix/private/plesk_saslauthd
mech_list: DIGEST-MD5 CRAM-MD5 PLAIN LOGIN
auto_transition: yes
sql_engine: intentionally disabled
log_level: 4

Can you comment on this for me?

Thanks.