dovecot - Oct 2011 - newbie: can't login as virtual user

dovecot -n
# 2.0.15: /etc/dovecot/dovecot.conf
# OS: Linux 2.6.38.8-32.fc15.i686.PAE i686 Fedora release 15 (Lovelock)
auth_debug_passwords = yes
disable_plaintext_auth = no
info_log_path = /var/log/dovecot-info.log
log_path = /var/log/dovecot.log
mail_access_groups = mail
mail_location = mbox:~/mail:INBOX=/var/spool/mail/%u
mail_privileged_group = mail
mbox_write_locks = fcntl
passdb {
   args = username_format=%u /etc/dovecot/users
   driver = passwd-file
}
service lmtp {
   unix_listener /var/spool/postfix/private/dovecot-lmtp {
     group = postfix
     mode = 0666
     user = postfix
   }
}
ssl_cert = </etc/pki/dovecot/certs/dovecot.pem
ssl_key = </etc/pki/dovecot/private/dovecot.pem
userdb {
   driver = passwd
}
userdb {
   args = username_format=%u /etc/dovecot/users
   driver = passwd-file
}
protocol lmtp {
   mail_plugins = quota sieve
}

cat /etc/dovecot/users
..........
test1 at example.com:{PLAIN}test1pass

BUT,
. OK Pre-login capabilities listed, post-login capabilities have more.
a login test1 at example.com test1pass
* BYE Internal error occurred. Refer to server log for more information.
closed

 From the server:
Oct 22 21:45:53 auth-worker: Debug: passwd-file /etc/dovecot/users: Read 
5 users
Oct 22 21:45:53 auth-worker: Debug: pam(test1 at example.com,www.xx.yy.zz): 
lookup service=dovecot
Oct 22 21:45:53 auth-worker: Debug: pam(test1 at example.com,  ): #1/1 
style=1 msg=Password:
Oct 22 21:45:55 auth-worker: Info: pam(test1 at example.com,   ): unknown user
Oct 22 21:45:55 auth: Debug: passwd-file(test1 at example.com,    ): 
lookup: user=test1 at example.com file=/etc/dovecot/users
Oct 22 21:45:55 auth: Debug: client out: OK	1	user=test1 at example.com
Oct 22 21:45:55 auth: Debug: master in: REQUEST	2303328257	27060	1 
964b20421c19356f1cbdefbf976467e0
Oct 22 21:45:55 auth: Debug: passwd(test1 at example.com,    ): lookup
Oct 22 21:45:55 auth: Info: passwd(test1 at example.com,   ): unknown user
Oct 22 21:45:55 auth: Debug: passwd-file(test1 at example.com,    ): 
lookup: user=test1 at example.com file=/etc/dovecot/users
Oct 22 21:45:55 auth: Debug: master out: USER	2303328257	test1 at example.com
Oct 22 21:45:55 imap-login: Info: Login: user=<test1 at example.com>, 
method=PLAIN, rip=   , lip=    , mpid=27062, TLS


What's wrong with my configuration?

Thanks,

sean

sean darcy writes:
> Oct 22 21:45:55 auth: Debug: passwd(test1 at example.com,    ): lookup
> Oct 22 21:45:55 auth: Info: passwd(test1 at example.com,   ): unknown user
> Oct 22 21:45:55 auth: Debug: passwd-file(test1 at example.com,    ):
> lookup: user=test1 at example.com file=/etc/dovecot/users
> Oct 22 21:45:55 auth: Debug: master out: USER	2303328257	test1 at
example.com
> Oct 22 21:45:55 imap-login: Info: Login: user=<test1 at example.com>,
> method=PLAIN, rip=   , lip=    , mpid=27062, TLS
I think up to now it's OK (not quite sure about "master out" log
entry
but it looks innocuous enough).  Dovecot reports to have looked in the
system password file, failed, then looked in /etc/dovecot/users and
found the user and logged them in.

I think the problem happens later and you will have to show the subsequent
log entries.

Joseph Tam <jtam.home at gmail.com>