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@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@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