[Dovecot] Inactivity, Thunderbird -> bad password
Hi,
I'm running dovecot rc13 now on sparc64, freebsd 6.1-STABLE
When i'm connected with my 5 accounts to my dovecot imap over ssl/tls server i get the following message in my logs: Nov 18 15:25:47 Info: imap-login: Disconnected: Inactivity: rip=x.x.x.x, lip=x.x.x.x, TLS My client (thunderbird) then re-requests my password for only one of the 5 accounts.
In my dovecot.conf is the following variable set: imap_client_workarounds = delay-newmail outlook-idle netscape-eoh tb-extra-mailbox-sep
On Sat, 2006-11-18 at 16:02 +0100, Peter Veerman wrote:
Hi,
I'm running dovecot rc13 now on sparc64, freebsd 6.1-STABLE
When i'm connected with my 5 accounts to my dovecot imap over ssl/tls server i get the following message in my logs: Nov 18 15:25:47 Info: imap-login: Disconnected: Inactivity: rip=x.x.x.x, lip=x.x.x.x, TLS My client (thunderbird) then re-requests my password for only one of the 5 accounts.
Try if this patch helps:
http://dovecot.org/list/dovecot-cvs/2006-November/006895.html
Can't really think of anything else. It means that from Dovecot's point of view the client didn't send authentication command at all.
I'm running dovecot rc13 now on sparc64, freebsd 6.1-STABLE
When i'm connected with my 5 accounts to my dovecot imap over ssl/tls server i get the following message in my logs: Nov 18 15:25:47 Info: imap-login: Disconnected: Inactivity: rip=x.x.x.x, lip=x.x.x.x, TLS My client (thunderbird) then re-requests my password for only one of the 5 accounts.
Try if this patch helps:
http://dovecot.org/list/dovecot-cvs/2006-November/006895.html
Can't really think of anything else. It means that from Dovecot's point of view the client didn't send authentication command at all. It didn't help :( the only difference because of the patch is that i don't get the inactivity error anymor in the logs, instead of that I _only_ get the following message:
Nov 19 12:18:10 Info: IMAP(user@domain): Disconnected
For the sake of clarity; this and the previous error happens after being logged in for quite a while (about 25 minutes) on randomly one of my five imap mailboxes.
On Sun, 2006-11-19 at 12:29 +0100, Peter Veerman wrote:
I'm running dovecot rc13 now on sparc64, freebsd 6.1-STABLE
When i'm connected with my 5 accounts to my dovecot imap over ssl/tls server i get the following message in my logs: Nov 18 15:25:47 Info: imap-login: Disconnected: Inactivity: rip=x.x.x.x, lip=x.x.x.x, TLS My client (thunderbird) then re-requests my password for only one of the 5 accounts.
Try if this patch helps:
http://dovecot.org/list/dovecot-cvs/2006-November/006895.html
Can't really think of anything else. It means that from Dovecot's point of view the client didn't send authentication command at all. It didn't help :( the only difference because of the patch is that i don't get the inactivity error anymor in the logs, instead of that I _only_ get the following message:
Nov 19 12:18:10 Info: IMAP(user@domain): Disconnected
This means that the login succeeded, and the client just disconnected.
For the sake of clarity; this and the previous error happens after being logged in for quite a while (about 25 minutes) on randomly one of my five imap mailboxes.
Might as well be Thunderbird doing something broken..
I'm running dovecot rc13 now on sparc64, freebsd 6.1-STABLE
When i'm connected with my 5 accounts to my dovecot imap over ssl/tls server i get the following message in my logs: Nov 18 15:25:47 Info: imap-login: Disconnected: Inactivity: rip=x.x.x.x, lip=x.x.x.x, TLS My client (thunderbird) then re-requests my password for only one of the 5 accounts.
Try if this patch helps:
http://dovecot.org/list/dovecot-cvs/2006-November/006895.html
Can't really think of anything else. It means that from Dovecot's point of view the client didn't send authentication command at all.
It didn't help :( the only difference because of the patch is that i don't get the inactivity error anymor in the logs, instead of that I _only_ get the following message:
Nov 19 12:18:10 Info: IMAP(user@domain): Disconnected
This means that the login succeeded, and the client just disconnected.
For the sake of clarity; this and the previous error happens after being logged in for quite a while (about 25 minutes) on randomly one of my five imap mailboxes.
Might as well be Thunderbird doing something broken..
After restarting both Dovecot and Thunderbird the error already has not occurred anymore for 3 hours already, while the error popped up every 25 minutes or so... I think it is safe to say though that the patch solved the problem.
Timo: Thanx!
I'm running dovecot rc13 now on sparc64, freebsd 6.1-STABLE
When i'm connected with my 5 accounts to my dovecot imap over ssl/tls server i get the following message in my logs: Nov 18 15:25:47 Info: imap-login: Disconnected: Inactivity: rip=x.x.x.x, lip=x.x.x.x, TLS My client (thunderbird) then re-requests my password for only one of the 5 accounts.
Try if this patch helps:
http://dovecot.org/list/dovecot-cvs/2006-November/006895.html
Can't really think of anything else. It means that from Dovecot's point of view the client didn't send authentication command at all.
It didn't help :( the only difference because of the patch is that i don't get the inactivity error anymor in the logs, instead of that I _only_ get the following message:
Nov 19 12:18:10 Info: IMAP(user@domain): Disconnected
This means that the login succeeded, and the client just disconnected.
For the sake of clarity; this and the previous error happens after being logged in for quite a while (about 25 minutes) on randomly one of my five imap mailboxes.
Might as well be Thunderbird doing something broken..
After restarting both Dovecot and Thunderbird the error already has not occurred anymore for 3 hours already, while the error popped up every 25 minutes or so... I think it is safe to say though that the patch solved the problem.
Timo: Thanx!
Okay :(
The problem remained. I had to -not- use Thunderbird for a long time in order for dovecot to put the Inactivity and Disconnected in IDLE messages. And again one of my accounts randomly suddenly asks for its password. (It occurs happens with dovecot only and not with Courier-IMAP so although thunderbird might be the problem there is a way to solve it.)
In my logs I see: Nov 19 17:22:13 Info: IMAP(userA@domain): Disconnected Nov 19 17:22:13 Info: IMAP(userB@domain): Disconnected Nov 19 17:22:13 Info: IMAP(userC@domain): Disconnected Nov 19 17:32:10 Info: imap-login: Disconnected: Inactivity: rip=88.211.149.123, lip=62.45.54.4, TLS Nov 19 17:32:13 Info: IMAP(userA@domain): Disconnected in IDLE Nov 19 17:32:13 Info: IMAP(userC@domain): Disconnected in IDLE Nov 19 17:32:13 Info: IMAP(userB@domain): Disconnected in IDLE Nov 19 17:32:13 Info: IMAP(userD@domain): Disconnected in IDLE Nov 19 17:32:13 Info: IMAP(userE@domain): Disconnected Nov 19 17:32:13 Info: IMAP(userD@domain): Disconnected in IDLE Nov 19 17:32:13 Info: IMAP(userF@domain): Disconnected Nov 19 17:32:13 Info: IMAP(userF@domain): Disconnected in IDLE Nov 19 17:32:13 Info: IMAP(userA@domain): Disconnected in IDLE Nov 19 17:32:13 Info: IMAP(userB@domain): Disconnected in IDLE
But after these problems the next line is also in my logs when after these messages another user tries to authenticate: Nov 19 17:35:09 Info: auth-worker(default): mysql: Connected to localhost (postfix)
Could it be that the mysql username-password backend times out and takes it time to reconnect to mysql and in the meantime an account gets the "you have got a wrong password" response?
Peter
On Sun, 2006-11-19 at 19:30 +0100, Peter Veerman wrote:
Nov 19 17:32:10 Info: imap-login: Disconnected: Inactivity: rip=88.211.149.123, lip=62.45.54.4, TLS
So at least the TLS handshake gets finished.
Nov 19 17:32:13 Info: IMAP(userA@domain): Disconnected in IDLE Nov 19 17:32:13 Info: IMAP(userC@domain): Disconnected in IDLE Nov 19 17:32:13 Info: IMAP(userB@domain): Disconnected in IDLE Nov 19 17:32:13 Info: IMAP(userD@domain): Disconnected in IDLE Nov 19 17:32:13 Info: IMAP(userE@domain): Disconnected Nov 19 17:32:13 Info: IMAP(userD@domain): Disconnected in IDLE Nov 19 17:32:13 Info: IMAP(userF@domain): Disconnected Nov 19 17:32:13 Info: IMAP(userF@domain): Disconnected in IDLE Nov 19 17:32:13 Info: IMAP(userA@domain): Disconnected in IDLE Nov 19 17:32:13 Info: IMAP(userB@domain): Disconnected in IDLE
But after these problems the next line is also in my logs when after these messages another user tries to authenticate: Nov 19 17:35:09 Info: auth-worker(default): mysql: Connected to localhost (postfix)
Could it be that the mysql username-password backend times out and takes it time to reconnect to mysql and in the meantime an account gets the "you have got a wrong password" response?
Maybe.. Set auth_debug=yes and see what happens around the time it logs inactivity?
On Sun, 2006-11-19 at 19:30 +0100, Peter Veerman wrote:
Nov 19 17:32:10 Info: imap-login: Disconnected: Inactivity: rip=88.211.149.123, lip=62.45.54.4, TLS
So at least the TLS handshake gets finished.
Nov 19 17:32:13 Info: IMAP(userA@domain): Disconnected in IDLE Nov 19 17:32:13 Info: IMAP(userC@domain): Disconnected in IDLE Nov 19 17:32:13 Info: IMAP(userB@domain): Disconnected in IDLE Nov 19 17:32:13 Info: IMAP(userD@domain): Disconnected in IDLE Nov 19 17:32:13 Info: IMAP(userE@domain): Disconnected Nov 19 17:32:13 Info: IMAP(userD@domain): Disconnected in IDLE Nov 19 17:32:13 Info: IMAP(userF@domain): Disconnected Nov 19 17:32:13 Info: IMAP(userF@domain): Disconnected in IDLE Nov 19 17:32:13 Info: IMAP(userA@domain): Disconnected in IDLE Nov 19 17:32:13 Info: IMAP(userB@domain): Disconnected in IDLE
But after these problems the next line is also in my logs when after these messages another user tries to authenticate: Nov 19 17:35:09 Info: auth-worker(default): mysql: Connected to localhost (postfix)
Could it be that the mysql username-password backend times out and takes it time to reconnect to mysql and in the meantime an account gets the "you have got a wrong password" response?
Maybe.. Set auth_debug=yes and see what happens around the time it logs inactivity?
auth_debug=yes was already in my logfiles and i didn't see any suspicious other than the mysql: Connected to localhost (postfix) that related to the mysql database.. though
After a very long period of inactivity (me watching television) my /messages logfile reported the following errors:
Nov 21 22:41:03 bubbles kernel: pid 90306 (imap), uid 125: exited on signal 6 Nov 21 22:41:03 bubbles kernel: pid 90302 (imap), uid 125: exited on signal 6 Nov 21 22:41:03 bubbles kernel: pid 95719 (imap), uid 125: exited on signal 6 Nov 21 22:41:03 bubbles kernel: pid 90308 (imap), uid 125: exited on signal 6 Nov 21 22:41:03 bubbles kernel: pid 90299 (imap), uid 125: exited on signal 6 Nov 21 22:41:03 bubbles kernel: pid 90301 (imap), uid 125: exited on signal 6 Nov 21 22:41:04 bubbles kernel: pid 93803 (imap), uid 125: exited on signal 6 Nov 21 22:51:03 bubbles kernel: pid 95917 (imap), uid 125: exited on signal 6 Nov 21 22:51:06 bubbles kernel: pid 93685 (imap), uid 125: exited on signal 6
but and my dovecot reports:
Nov 21 22:41:00 Info: imap-login: Disconnected: Inactivity: rip=x.x.149.123, lip=x.x.54.4, TLS Nov 21 22:41:01 Info: imap-login: Disconnected: Inactivity: rip=x.x.149.123, lip=x.x.54.4, TLS Nov 21 22:41:03 Info: IMAP(user@domain): Disconnected in IDLE Nov 21 22:41:03 Info: IMAP(user@domain): Disconnected Nov 21 22:41:03 Info: IMAP(user@domain): Disconnected Nov 21 22:41:03 Info: IMAP(user@domain): Disconnected in IDLE Nov 21 22:41:03 Info: IMAP(user@domain): Disconnected in IDLE Nov 21 22:41:03 Info: IMAP(user@domain): Disconnected in IDLE Nov 21 22:41:03 Info: IMAP(user@domain): Disconnected in IDLE Nov 21 22:41:03 Info: IMAP(user@domain): Disconnected in IDLE Nov 21 22:41:04 Info: IMAP(user@domain): Disconnected in IDLE Nov 21 22:41:20 Info: auth-worker(default): mysql: Connected to localhost (postfix)
So something that is not shown in logs is not going that well.
grtz Peter
On Tue, 2006-11-21 at 23:40 +0100, Peter Veerman wrote:
After a very long period of inactivity (me watching television) my /messages logfile reported the following errors:
Nov 21 22:41:03 bubbles kernel: pid 90306 (imap), uid 125: exited on signal 6 Nov 21 22:41:03 bubbles kernel: pid 90302 (imap), uid 125: exited on signal 6 .. Nov 21 22:41:00 Info: imap-login: Disconnected: Inactivity: rip=x.x.149.123, lip=x.x.54.4, TLS Nov 21 22:41:01 Info: imap-login: Disconnected: Inactivity: rip=x.x.149.123, lip=x.x.54.4, TLS Nov 21 22:41:03 Info: IMAP(user@domain): Disconnected in IDLE Nov 21 22:41:03 Info: IMAP(user@domain): Disconnected Nov 21 22:41:03 Info: IMAP(user@domain): Disconnected Nov 21 22:41:03 Info: IMAP(user@domain): Disconnected in IDLE Nov 21 22:41:03 Info: IMAP(user@domain): Disconnected in IDLE Nov 21 22:41:03 Info: IMAP(user@domain): Disconnected in IDLE Nov 21 22:41:03 Info: IMAP(user@domain): Disconnected in IDLE Nov 21 22:41:03 Info: IMAP(user@domain): Disconnected in IDLE Nov 21 22:41:04 Info: IMAP(user@domain): Disconnected in IDLE Nov 21 22:41:20 Info: auth-worker(default): mysql: Connected to localhost (postfix)
I think you're looking only at Dovecot's "info" log. Errors are probably written to a different log file. If imap process dies with signal 6, Dovecot _always_ logs an error about it.
If you can't find anything, change log_path setting in dovecot.conf to point to some file.
participants (2)
-
Peter Veerman
-
Timo Sirainen