arvids
2007-Sep-11 17:04 UTC
[Dovecot] Possible bug in authentication cache in dovecot 1.1.alpha4
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=AHRlc3R1c2VyAHBhc3MSep 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=AHRlc3R1c2VyAHdyb25ncGFzcw=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=AHRlc3R1c2VyAHBhc3MSep 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
arvids
2007-Sep-13 19:31 UTC
[Dovecot] Possible bug in authentication cache in dovecot 1.1.alpha4
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
Timo Sirainen
2007-Sep-17 08:17 UTC
[Dovecot] Possible bug in authentication cache in dovecot 1.1.alpha4
On Tue, 2007-09-11 at 20:04 +0300, arvids wrote:> 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.Thanks, fixed: http://hg.dovecot.org/dovecot/rev/fd7ffed49763 -------------- next part -------------- A non-text attachment was scrubbed... Name: signature.asc Type: application/pgp-signature Size: 189 bytes Desc: This is a digitally signed message part URL: <http://dovecot.org/pipermail/dovecot/attachments/20070917/fe6da86d/attachment-0002.bin>
Possibly Parallel Threads
- dovecot update ?
- problem with IMAP authentication with Thunderbird in local network
- SSL-read error in logfile
- dovecot-1.0_rc7 crashes (Login process died too early) with repeated deletes from thunderbird
- Problems with the IMAP proxy after upgrading from dovecot 1.1.16 to 1.211