dovecot - Dec 2009 - SASL plain authentication failed; unable to lookup user record

i'll guess the solution to my problem will be something simple and 
obvious, because i know i ain't the first person to do this and it ain't
all that complicated, but i've been staring at it for days and can't see
what's wrong.

new installation; os x snow leopard server; postfix 2.5.5; dovecot 
1.1.17apple0.5

i'm trying to get SMTP auth working via SASL.  using a plain password 
scheme and plain auth scheme over SSL.  client is apple mail. deliveries 
are working, and dovecot's pop3s and imaps are working just fine.  my 
configuration is the same simple config that is well documented on
both the postfix and dovecot sites.

when i attempt to use smtp auth from a mail client, postfix says

SASL plain authentication failed
unable to lookup user record

smtp authentication also fails if i use the usual command line method:

# telnet localhost 25
Escape character is '^]'.
220 osx-106.example.com ESMTP Postfix
EHLO foobie.example.com
250-osx-106.example.com
250-PIPELINING
250-SIZE 10485760
250-VRFY
250-ETRN
250-AUTH LOGIN PLAIN CRAM-MD5
250-STARTTLS
250-ENHANCEDSTATUSCODES
250-8BITMIME
250 DSN
AUTH PLAIN blah blah blah
535 Error: authentication failed

i've scoured months worth of postfix and dovecot list archives and 
although there are many sasl related issues i didn't see anything 
specific to this.

as expected, the socket is

srw-rw----  1 _postfix  _postfix  0 Dec  4 08:51
/var/spool/postfix/private/auth

lsof shows the socket is open by dovecot-auth (which is running as root):

dovecot-a 63614           root    5u     unix 0x0888b990       0t0
   /var/spool/postfix/private/auth

i have not seen the socket opened by postfix, but i'm assuming that is a 
transient event and would be difficult to capture (at least with lsof).

so both postfix and dovecot have read/write access to the socket.

the credentials sent are the same whether they're sent via a true pop3 
client or via the command line.  when sent via the command line, they're 
generated via perl -MMIME::Base64 -e 'print 
encode_base64("\0username\0password");'and i've verified
they're correct
  via decode_base64

config stuff:

# postconf -n
biff = no
command_directory = /usr/sbin
config_directory = /etc/postfix
content_filter = smtp-amavis:[127.0.0.1]:10024
daemon_directory = /usr/libexec/postfix
debug_peer_level = 2
enable_server_options = yes
header_checks = pcre:/etc/postfix/custom_header_checks
html_directory = /usr/share/doc/postfix/html
inet_interfaces = all
mail_owner = _postfix
mailbox_size_limit = 0
mailbox_transport = dovecot
mailq_path = /usr/bin/mailq
manpage_directory = /usr/share/man
message_size_limit = 10485760
mydomain = example.com
mydomain_fallback = localhost
mynetworks = 127.0.0.0/8,192.168.61.0/24
newaliases_path = /usr/bin/newaliases
queue_directory = /private/var/spool/postfix
readme_directory = /usr/share/doc/postfix
recipient_delimiter = +
relayhost sample_directory = /usr/share/doc/postfix/examples
sendmail_path = /usr/sbin/sendmail
setgid_group = _postdrop
smtpd_client_restrictions = permit_mynetworks permit_sasl_authenticated
reject
smtpd_enforce_tls = no
smtpd_helo_required = yes
smtpd_helo_restrictions = reject_invalid_helo_hostname
reject_non_fqdn_helo_hostname
smtpd_pw_server_security_options = plain, login cram-md5
smtpd_recipient_restrictions = permit_sasl_authenticated
permit_mynetworks reject_unauth_destination check_policy_service
unix:private/policy reject
smtpd_sasl_auth_enable = yes
smtpd_sasl_path = private/auth
smtpd_sasl_type = dovecot
smtpd_tls_CAfile
/etc/certificates/osx-106.example.com.E2FA6EFB8203E2E09C605D30A179669E4B4F69EB.chain.pem
smtpd_tls_cert_file
/etc/certificates/osx-106.example.com.E2FA6EFB8203E2E09C605D30A179669E4B4F69EB.cert.pem
smtpd_tls_exclude_ciphers = SSLv2, aNULL, ADH, eNULL
smtpd_tls_key_file
/etc/certificates/osx-106.example.com.E2FA6EFB8203E2E09C605D30A179669E4B4F69EB.key.pem
smtpd_use_pw_server = yes
smtpd_use_tls = yes
unknown_local_recipient_reject_code = 550
virtual_alias_maps virtual_gid_maps = static:5000
virtual_mailbox_base = /etc/postfix/datastore
virtual_mailbox_domains = osx.example.com
virtual_mailbox_maps = hash:/etc/postfix/datausers
virtual_minimum_uid = 100
virtual_uid_maps = static:5000

# dovecotd -n
# 1.1.17apple0.5: /private/etc/dovecot/dovecot.conf
Warning: fd limit 256 is lower than what Dovecot can use under full load
(more than 456). Either grow the limit or change
login_max_processes_count and max_mail_processes settings
# OS: Darwin 10.2.0 i386  hfs
base_dir: /var/run/dovecot
syslog_facility: local6
protocols: pop3s imaps
ssl_cert_file:
/etc/certificates/osx-106.example.com.E2FA6EFB8203E2E09C605D30A179669E4B4F69EB.cert.pem
ssl_key_file:
/etc/certificates/osx-106.example.com.E2FA6EFB8203E2E09C605D30A179669E4B4F69EB.key.pem
ssl_cipher_list: ALL:!LOW:!SSLv2:!aNULL:!ADH:!eNULL
disable_plaintext_auth: no
login_dir: /var/run/dovecot/login
login_executable(default): /usr/libexec/dovecot/imap-login
login_executable(imap): /usr/libexec/dovecot/imap-login
login_executable(pop3): /usr/libexec/dovecot/pop3-login
login_user: _dovecot
login_process_per_connection: no
max_mail_processes: 200
mail_max_userip_connections(default): 20
mail_max_userip_connections(imap): 20
mail_max_userip_connections(pop3): 10
verbose_proctitle: yes
first_valid_uid: 6
first_valid_gid: 6
mail_access_groups: mail
mail_location: maildir:/etc/postfix/datastore/%d/%n
mail_debug: yes
mail_executable(default): /usr/libexec/dovecot/imap
mail_executable(imap): /usr/libexec/dovecot/imap
mail_executable(pop3): /usr/libexec/dovecot/pop3
mail_process_sharing: full
mail_max_connections: 5
mail_plugins(default): quota imap_quota
mail_plugins(imap): quota imap_quota
mail_plugins(pop3): quota
mail_plugin_dir(default): /usr/lib/dovecot/imap
mail_plugin_dir(imap): /usr/lib/dovecot/imap
mail_plugin_dir(pop3): /usr/lib/dovecot/pop3
auth default:
   verbose: yes
   debug: yes
   debug_passwords: yes
   passdb:
     driver: passwd-file
     args: username_format=%n /etc/postfix/datastore/%d-passwd
   userdb:
     driver: passwd-file
     args: username_format=%n /etc/postfix/datastore/%d-passwd
   socket:
     type: listen
     client:
       path: /var/spool/postfix/private/auth
       mode: 432
       user: postfix
       group: postfix
plugin:
   quota_warning: storage=100%% /usr/libexec/dovecot/quota-exceeded.sh
   quota: maildir:User quota
   sieve: /var/spool/imap/dovecot/sieve-scripts/%u/dovecot.sieve


it would seem that something's not right between postfix and dovecot.

dovecot debug:yes and dovecot debug_passwords:yes and i do see debug 
info in the logs when i authenticate via pop3.  but i don't see any 
debug info in the logs when doing smtp auth.  i don't know if that's 
another symptom, or if dovecot just does not debug smtp auth connections 
to begin with.

so any other insight would be appreciated.  thanks.

jeff

On Wed, Dec 09, 2009 at 11:21:56AM -0800, JP wrote:
> i'll guess the solution to my problem will be something simple and
> obvious,
I think so.

[snip]
> config stuff:
> 
> # postconf -n
> mail_owner = _postfix
That strange non-default setting might be one of the problems.
> queue_directory = /private/var/spool/postfix
That's equally strange and also a likely part of the problem.
> smtpd_client_restrictions = permit_mynetworks permit_sasl_authenticated
> reject
This is not suitable for mail exchange, and not needed anyway. This
says you reject anything which has not authenticated or is not in
mynetworrks.
> smtpd_helo_restrictions = reject_invalid_helo_hostname
> reject_non_fqdn_helo_hostname
These are good restrictions to use, but they will block some MUA
submission. They belong __
                          | below
                          v
> smtpd_recipient_restrictions = permit_sasl_authenticated
> permit_mynetworks reject_unauth_destination check_policy_service
> unix:private/policy reject
in here after the two permit_* restrictions.
> smtpd_pw_server_security_options = plain, login cram-md5
> smtpd_use_pw_server = yes
postconf: warning: smtpd_pw_server_security_options: unknown parameter
postconf: warning: smtpd_use_pw_server: unknown parameter

This is patched. Talk to Apple for support. The patching could be a
part of the problem as well.
> smtpd_sasl_path = private/auth
This pathname, as documented, is relative to $queue_directory. See
above for your strange non-default setting.
> virtual_mailbox_base = /etc/postfix/datastore
This is really bizarre. Sure, files can go anywhere you want, but is
there anything wrong with traditional Unix standards? I'm reminded of
the famous quote: "Those who don't understand Unix are doomed to
reinvent it, poorly."
> # dovecotd -n
> # 1.1.17apple0.5: /private/etc/dovecot/dovecot.conf
> Warning: fd limit 256 is lower than what Dovecot can use under full load
> (more than 456). Either grow the limit or change
> login_max_processes_count and max_mail_processes settings
Hmmm, that sounds like something you might want to consider.
> auth default:
>   verbose: yes
>   debug: yes
>   debug_passwords: yes
>   passdb:
>     driver: passwd-file
>     args: username_format=%n /etc/postfix/datastore/%d-passwd
>   userdb:
>     driver: passwd-file
>     args: username_format=%n /etc/postfix/datastore/%d-passwd
>   socket:
>     type: listen
>     client:
>       path: /var/spool/postfix/private/auth
I see a problem in that path!
>       mode: 432
>       user: postfix
>       group: postfix
I see a problem in that user (and maybe group)!
> it would seem that something's not right between postfix and dovecot.
Perhaps Dovecot should create a socket in the place Postfix needs it,
with ownership such that Postfix can use it.
-- 
    Offlist mail to this address is discarded unless
    "/dev/rob0" or "not-spam" is in Subject: header

On Wed, 2009-12-09 at 11:21 -0800, JP wrote:
> dovecot debug:yes and dovecot debug_passwords:yes and i do see debug 
> info in the logs when i authenticate via pop3.  but i don't see any 
> debug info in the logs when doing smtp auth.  i don't know if
that's
> another symptom, or if dovecot just does not debug smtp auth connections 
> to begin with.
If Dovecot logs nothing, it means nothing tried to authenticate to
Dovecot. Do you also mean Postfix doesn't log anything? I don't really
know what things it logs or doesn't. I'd guess it would log errors about
not being able to connect to auth socket, so maybe the problem is some
setting that makes Postfix not even attempt an actual authentication.

-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 197 bytes
Desc: This is a digitally signed message part
URL:
<http://dovecot.org/pipermail/dovecot/attachments/20091209/2dce68ea/attachment-0002.bin>

Hi

On Wed, 09.12.2009 @ 11:21:56AM, JP wrote:
> when i attempt to use smtp auth from a mail client, postfix says
> 
> SASL plain authentication failed
> unable to lookup user record
You did not send your master.cf from postfix, am I right? AFAIK
smtpd is running in a chroot. For this, your config seems to be
correct.
Have you already tried to set a chmod 777 on the socket? Another
point is to check whether dovecot could even open the location ->
check the permissions of the topfolders (/var/, /var/spool, ...).

Another try would be to check whether it work without a chroot?

I dunno whether this helps that much... but often the mistakes are
small.

Regards
 raf
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 835 bytes
Desc: Digital signature
URL:
<http://dovecot.org/pipermail/dovecot/attachments/20091210/1c638272/attachment-0002.bin>