[Dovecot] Login via IMAP with MySQL as user database not working

Wed Apr 13 20:33:30 EEST 2011

Hello all,

I am migrating from Postfix/Cyrus/MySQL mail server to a recently installed
dovecot 1.2.8 on a QNAP TS259 NAS via XDove.
I am unable to login via IMAP (the only method I've tried and the only
method I want).
I am using an almost identical database as the current existing
Postfix/Cyrus/MySQL setup (with the except of paths).
I have been attempting to get this working (off and on) for the past 5
months.  During that time I have researched and researched, but have not
found a solution.
The Maildir has been copied from the existing server to the Dovecot server
and have run the script 'courier-dovecot-migrate.pl', which was found at
http://www.dovecot.org/tools/courier-dovecot-migrate.pl

In a nutshell:
If I have the password_query string in the SQL config file (shown below) set
to return only 1 field, i.e. the password, then the Dovecot authtest app
succeeds.  But if more than 1 field is returned (i.e.: user and password)
the test fails.  And if testing with telnet I get the message of "* BYE
Internal login failure. Refer to server log for more information.".  The
logs indicate that the password check returned OK but the userdb read
appears to fail.  If I change the userdb_query to return only 1 field (such
as only the uid), then the logs show the correct value is returned, and yet
the telnet login fails.  So it seems that anytime there are multiple fields
returned from the SQL query, the result is failure at that step (password
check or userdb read).  Therefore userdb prefetch never works.
The NAS doesn't utilize a syslog so it's of no help in debugging.

Below are the config files and samples from log files (scrubbed):

dovecot.conf-   (NOTE: the 'home = /tmp' in the plugin section is an attempt
at rawlog from http://wiki2.dovecot.org/Debugging/Rawlog ... which doesn't
seem to work)
# 1.2.8: /etc/dovecot/dovecot.conf
# OS: Linux 2.6.33.2 i686
log_path: /var/log/dovecot/dovecot.log
info_log_path: /var/log/dovecot/dovecot-info.log
log_timestamp: "%Y-%m-%d %H:%M:%S"
protocols: imap
ssl: no
disable_plaintext_auth: no
login_dir: /var/run/dovecot/login
login_executable: /usr/libexec/dovecot/rawlog
/usr/libexec/dovecot/imap-login
login_user: _mailman
last_valid_uid: 65000
first_valid_gid: 70
last_valid_gid: 65000
mail_debug: yes
lda:
  postmaster_address: postmaster at example.com
auth default:
  user: dovecot
  verbose: yes
  debug: yes
  debug_passwords: yes
  worker_max_count: 10
  passdb:
    driver: sql
    args: /share/MD0_DATA/.qpkg/XDove/dovecot/etc/dovecot/dovecot-sql.conf
  userdb:
    driver: sql
    args: /share/MD0_DATA/.qpkg/XDove/dovecot/etc/dovecot/dovecot-sql.conf
  socket:
    type: listen
    client:
      path: /var/run/dovecot/auth-client
      mode: 432
    master:
      path: /var/run/dovecot/auth-master
      mode: 384
plugin:
  home: /tmp

dovecot-sql.conf-
driver = mysql
connect = host=127.0.0.1 user=<myuser> password=<mypass> dbname=users2
default_pass_scheme = CRYPT
password_query = SELECT user, crypt AS `password` FROM users WHERE user =
'%u' AND account_enabled = 'y' AND allow_email = 'y'
user_query = SELECT uid, gid, homedir AS home, maildir AS mail FROM users
WHERE user = '%u' AND account_enabled = 'y' AND allow_email = 'y'

Sample from log "dovecot-info.log"-
"2011-04-13 10:12:00" auth(default): Info: client in: AUTH      1
PLAIN   service=imap    secured lip=127.0.0.1   rip=127.0.0.1
lport=143       rport=36735
resp=AGNocmlzQNHhaWwuaG9tZWlwLm5ldABoYXBweTE=
"2011-04-13 10:12:00" auth-worker(default): Info:
sql(<user>@<domain>,127.0.0.1): query: SELECT user, crypt AS `password` FROM
users WHERE user = '<user>@<domain>' AND account_enabled = 'y' AND
allow_email = 'y'
"2011-04-13 10:12:00" auth-worker(default): Info:
auth(<user>@<domain>,127.0.0.1): username changed <user>@<domain> ->
<User>@<Domain>
"2011-04-13 10:12:00" auth-worker(default): Info: mysql: Connected to
127.0.0.1 (users2)
"2011-04-13 10:12:02" auth(default): Info: client out: FAIL     1
user=<user>@<domain>      temp

Sample from log "dovecot.log"-
"2011-04-13 10:12:00" auth(default): Error: worker-server(
chris at sail.homeip.net,127.0.0.1): Aborted: Worker process died unexpectedly
"2011-04-13 10:12:00" dovecot: Error: child 20136 (auth-worker) killed with
signal 11 (core dumps disabled)

If the password_query is changed to (only password returned):
password_query = SELECT crypt AS `password` FROM users WHERE user = '%u' AND
account_enabled = 'y' AND allow_email = 'y'
then the logs are as follows:

Sample from log "dovecot-info.log"-
"2011-04-13 10:18:03" auth(default): Info: client in: AUTH      1
PLAIN   service=imap    secured lip=127.
0.0.1   rip=127.0.0.1   lport=143       rport=33662
resp=AGNocmlzQNHhaWwuaG9tZWlwLm5ldABoYXBweTE=
"2011-04-13 10:18:03" auth-worker(default): Info:
sql(<user>@<domain>,127.0.0.1): query: SELECT crypt AS `password` FROM users
WHERE user = '<user>@<domain>' AND account_enabled = 'y' AND allow_email =
'y'
"2011-04-13 10:18:03" auth(default): Info: client out: OK       1
user=<user>@<domain>
"2011-04-13 10:18:03" auth(default): Info: master in: REQUEST   1
23395   1
"2011-04-13 10:18:03" auth-worker(default): Info:
sql(<user>@<domain>,127.0.0.1): SELECT uid, gid, homedir AS home, maildir AS
mail FROM users WHERE user = '<user>@<domain>' AND account_enabled = 'y' AND
allow_email = 'y'
"2011-04-13 10:18:03" auth(default): Info: master out: FAIL     1
"2011-04-13 10:18:03" imap-login: Info: Internal login failure (auth failed,
1 attempts): user=<<user>@<domain>>, method=PLAIN, rip=127.0.0.1,
lip=127.0.0.1, secured
"2011-04-13 10:18:03" auth-worker(default): Info: mysql: Connected to
127.0.0.1 (users2)

Sample from log "dovecot.log"-
"2011-04-13 10:18:03" auth(default): Error:
worker-server(<user>@<domain>,127.0.0.1): Aborted: Worker process died
unexpectedly
"2011-04-13 10:18:03" dovecot: Error: child 23383 (auth-worker) killed with
signal 11 (core dumps disabled)

And finally, if change the user_query (to return only homedir AS home):

then the logs are as follows:

Sample from log "dovecot-info.log"-
"2011-04-13 10:22:56" auth(default): Info: client in: AUTH      1
PLAIN   service=imap    secured lip=127.0.0.1   rip=127.0.0.1
lport=143       rport=35408
resp=AGNocmlzQNHhaWwuaG9tZWlwLm5ldABoYXBweTE=
"2011-04-13 10:22:56" auth-worker(default): Info:
sql(<user>@<domain>,127.0.0.1): query: SELECT crypt AS `password` FROM users
WHERE user = '<user>@<domain>' AND account_enabled = 'y' AND allow_email =
'y'
"2011-04-13 10:22:56" auth(default): Info: client out: OK       1
user=<user>@<domain>
"2011-04-13 10:22:56" auth(default): Info: master in: REQUEST   1
23787   1
"2011-04-13 10:22:56" auth-worker(default): Info:
sql(<user>@<domain>,127.0.0.1): SELECT homedir AS home FROM users WHERE user
= '<user>@<domain>' AND account_enabled = 'y' AND allow_email = 'y'
"2011-04-13 10:22:56" auth(default): Info: master out: USER     1
<user>@<domain>   home=/Users/<user>
"2011-04-13 10:22:56" imap-login: Info: Internal login failure (auth failed,
1 attempts): user=<<user>@<domain>>, method=PLAIN, rip=127.0.0.1,
lip=127.0.0.1, secured

Sample from log "dovecot.log"-
"2011-04-13 10:22:56" dovecot: Error: User <user>@<domain> is missing UID
(see mail_uid setting)

Greatly appreciate any help that anyone can give.
Chris