[Dovecot] Possible bug in authentication cache in dovecot 1.1.alpha4

[arvids]

the problem disappeared when I added 'userdb sql'  to configuration(after the 
userdb prefetch).

Regards, Arvids


On Tuesday 11 September 2007 20:04:45 arvids wrote:
> Hello,
>
> it seems that there is some bug in authentication cache code in dovecot
> version 1.1.alpha4 - after login attempt with wrong password the correct
> password also will fail.
>
> I can reproduce it very easy:
> $telnet 10.10.10.30 110
> +OK Server. <861.2.46e6c679.jZ8QYpFmU8ZN6XIq7zPhkw==@server2>
> user testuser
> +OK
> pass pass
> +OK Logged in.
> quit
> +OK Logging out.
> Connection closed by foreign host.
> $telnet 10.10.10.30 110
> +OK Server. <861.4.46e6c68d.CBp+UUDmBlyfxy8yqnu4MQ==@server2>
> user testuser
> +OK
> pass wrongpass
> -ERR Authentication failed.
> quit
> +OK Logging out
> Connection closed by foreign host.
> $telnet 10.10.10.30 110
> +OK Server. <861.5.46e6c6aa.1SB5iDeA707TlaISooTumg==@server2>
> user testuser
> +OK
> pass pass
> -ERR [IN-USE] Internal login failure. Refer to server log for more
> information. Connection closed by foreign host.
>
> here is debug log:
> Sep 11 19:46:39 server2 dovecot: Dovecot v1.1.alpha4 starting up
> Sep 11 19:46:40 server2 dovecot: auth-worker(default): mysql: Connected to
> /tmp/mysql.sock (mail) Sep 11 19:47:03 server2 dovecot: auth(default):
> client in:
> AUTH^I1^IPLAIN^Iservice=pop3^Ilip=10.10.10.30^Irip=10.10.10.20^Iresp=AHRlc3
>R1c2VyAHBhc3M= Sep 11 19:47:03 server2 dovecot: auth(default):
> cache(testuser,10.10.10.20): miss Sep 11 19:47:03 server2 dovecot:
> auth-worker(default): sql(testuser,10.10.10.20): query: SELECT user,
> password, home as userdb_home, uid as userdb_uid, gid as userdb_gid FROM
> users WHERE user = 'testuser'
> Sep 11 19:47:03 server2 dovecot: auth(default): client out:
> OK^I1^Iuser=testuser Sep 11 19:47:03 server2 dovecot: auth(default): master
> in: REQUEST^I1^I2148^I1 Sep 11 19:47:03 server2 dovecot: auth(default):
> prefetch(testuser,10.10.10.20): success Sep 11 19:47:03 server2 dovecot:
> auth(default): master out:
> USER^I1^Itestuser^Itestuser=^Ihome=/vmail/00/testuser^Iuid=95^Igid=95 Sep
> 11 19:47:03 server2 dovecot: pop3-login: Login: user=<testuser>,
> method=PLAIN, rip=10.10.10.20, lip=10.10.10.30 Sep 11 19:47:08 server2
> dovecot: POP3(testuser): Disconnected: Logged out top=0/0, retr=0/0,
> del=0/0, size=0 Sep 11 19:47:34 server2 dovecot: auth(default): client in:
> AUTH^I2^IPLAIN^Iservice=pop3^Ilip=10.10.10.30^Irip=10.10.10.20^Iresp=AHRlc3
>R1c2VyAHdyb25ncGFzcw== Sep 11 19:47:34 server2 dovecot: auth(default):
> cache(testuser,10.10.10.20): hit Sep 11 19:47:34 server2 dovecot:
> auth(default): cache(testuser,10.10.10.20): Password mismatch Sep 11
> 19:47:34 server2 dovecot: auth(default): cache(testuser,10.10.10.20):
> PLAIN(wrongpass) != 'pass' Sep 11 19:47:34 server2 dovecot:
> auth-worker(default): sql(testuser,10.10.10.20): query: SELECT user,
> password, home as userdb_home, uid as userdb_uid, gid as userdb_gid FROM
> users WHERE user = 'testuser'
> Sep 11 19:47:34 server2 dovecot: auth-worker(default):
> sql(testuser,10.10.10.20): Password mismatch Sep 11 19:47:34 server2
> dovecot: auth-worker(default): sql(testuser,10.10.10.20): PLAIN(wrongpass)
> != 'pass' Sep 11 19:47:35 server2 dovecot: auth(default): client out:
> FAIL^I2^Iuser=testuser Sep 11 19:47:37 server2 dovecot: pop3-login: Aborted
> login: user=<testuser>, method=PLAIN, rip=10.10.10.20, lip=10.10.10.30 Sep
> 11 19:47:46 server2 dovecot: auth(default): client in:
> AUTH^I3^IPLAIN^Iservice=pop3^Ilip=10.10.10.30^Irip=10.10.10.20^Iresp=AHRlc3
>R1c2VyAHBhc3M= Sep 11 19:47:46 server2 dovecot: auth(default):
> cache(testuser,10.10.10.20): hit Sep 11 19:47:46 server2 dovecot:
> auth(default): client out: OK^I3^Iuser=testuser Sep 11 19:47:46 server2
> dovecot: auth(default): master in: REQUEST^I2^I2148^I3 Sep 11 19:47:46
> server2 dovecot: auth(default): prefetch(testuser,10.10.10.20): passdb
> didn't return userdb entries Sep 11 19:47:46 server2 dovecot:
> auth(default): userdb(testuser,10.10.10.20): user not found from userdb Sep
> 11 19:47:46 server2 dovecot: auth(default): master out: NOTFOUND^I2 Sep 11
> 19:47:46 server2 dovecot: pop3-login: Internal login failure:
> user=<testuser>, method=PLAIN, rip=10.10.10.20, lip=10.10.10.30
>
> dovecot -n output:
> # 1.1.alpha4: /usr/local/dovecot/etc/dovecot.conf
> base_dir: /var/run/dovecot/
> syslog_facility: local0
> protocols: pop3
> ssl_disable: yes
> disable_plaintext_auth: no
> login_dir: /var/run/dovecot/login
> login_executable: /usr/local/dovecot/libexec/dovecot/pop3-login
> login_greeting: Server.
> login_process_per_connection: no
> login_process_size: 64
> verbose_proctitle: yes
> first_valid_uid: 95
> first_valid_gid: 95
> mail_uid: 95
> mail_gid: 95
> mail_location: maildir:~/Maildir
> fsync_disable: yes
> mail_executable: /usr/local/dovecot/libexec/dovecot/pop3
> mail_plugin_dir: /usr/local/dovecot/lib/dovecot/pop3
> pop3_enable_last: yes
> pop3_client_workarounds: outlook-no-nuls oe-ns-eoh
> auth default:
>   mechanisms: plain login digest-md5 cram-md5 apop
>   cache_size: 2048
>   cache_ttl: 28800
>   cache_negative_ttl: 60
>   user: doveauth
>   verbose: yes
>   debug: yes
>   debug_passwords: yes
>   passdb:
>     driver: sql
>     args: /usr/local/dovecot/etc/dovecot-sql.conf
>   userdb:
>     driver: prefetch
>
>
> Regards, Arvids