Thu Nguyen
2009-Oct-11 14:57 UTC
[Dovecot] Dovecot inactive after an intermittent connection with LDAP
Hello all,
I'm facing the problem below:
1. Firstly, the connection between dovecot and ldap was down.
dovecot: Oct 10 09:11:12 Info: auth(default): ldap(user1,x.x.x.x): Aborting
(timeout), we're not connected to LDAP server
dovecot: Oct 10 09:11:12 Info: auth(default): master out: USER 265490
user1
2. There is many new connection from user created....
dovecot: Oct 10 09:11:12 Info: auth(default): new auth connection: pid=21114
dovecot: Oct 10 09:11:12 Info: auth(default): new auth connection: pid=21113
3. ....but it obviously failed.
dovecot: Oct 10 09:11:12 Info: pop3-login: Internal login failure (auth
failed,1 attempts): user=<user1>, method=PLAIN, rip=x.x.x.x, lip= x.x.x.x
dovecot: Oct 10 09:11:12 Info: pop3-login: Internal login failure (auth
failed,1 attempts): user=<user2>, method=PLAIN, rip= x.x.x.x,lip= x.x.x.x
.................
dovecot: Oct 10 09:11:15 Info: auth(default): new auth connection: pid=21125
dovecot: Oct 10 09:11:15 Info: auth(default): new auth connection: pid=21126
dovecot: Oct 10 09:11:22 Info: auth(default): client in: AUTH 1 PLAIN
service=pop3 lip= x.x.x.x rip= x.x.x.x lport=110 rport=4504
resp=<hidden>
dovecot: Oct 10 09:11:22 Info: auth(default): client in: AUTH 1 PLAIN
service=pop3 lip= x.x.x.x rip= x.x.x.x lport=110 rport=6316
resp=<hidden>
dovecot: Oct 10 09:11:22 Info: auth(default): new auth connection: pid=21132
dovecot: Oct 10 09:11:24 Info: auth(default): client in: AUTH 1
PLAIN service=pop3 lip= x.x.x.x rip= x.x.x.x lport=110
4. LDAP connection is back to normal, however, it still failed.
dovecot: Oct 10 09:14:14 Info: auth(default): new auth connection: pid=21250
dovecot: Oct 10 09:14:14 Info: auth(default): new auth connection: pid=21251
dovecot: Oct 10 09:14:14 Info: auth(default): client in: AUTH 1 PLAIN
service=pop3 lip= x.x.x.x rip= x.x.x.x lport=110 rport=2959 resp=<hidden>
dovecot: Oct 10 09:14:14 Info: pop3-login: Disconnected: Inactivity (auth
failed, 1 attempts): method=PLAIN, lip= x.x.x.x rip= x.x.x.x
dovecot: Oct 10 09:14:15 Info: pop3-login: Disconnected: Inactivity (auth
failed, 1 attempts): method=PLAIN, lip= x.x.x.x rip= x.x.x.x
dovecot: Oct 10 09:14:15 Info: pop3-login: Disconnected: Inactivity (auth
failed, 1 attempts): method=PLAIN, lip= x.x.x.x rip= x.x.x.x
dovecot: Oct 10 09:14:15 Info: auth(default): client in: AUTH 1
PLAIN service=pop3 lip= x.x.x.x rip= x.x.x.x lport=110 rport=3765
resp=<hidden>
dovecot: Oct 10 09:14:15 Info: auth(default): client in: AUTH 1
PLAIN service=pop3 lip= x.x.x.x rip= x.x.x.x lport=110 rport=48
08 resp=<hidden>
dovecot: Oct 10 09:14:15 Info: pop3-login: Disconnected: Inactivity (auth
failed, 1 attempts): method=PLAIN, rip=199.30.31.48, lip=199.30.26.18
5. Then the request queue is full ... Dovecot is completely inactive. Of
course it try to fail back to pam but as the password is not the same so
it's failed also.
dovecot: Oct 10 09:38:53 Error: auth(default): ldap(user1,10.0.0.7): Request
queue is full (oldest added 1660 secs ago)
dovecot: Oct 10 09:38:53 Info: auth-worker(default): pam(user1,10.0.0.7):
lookup service=dovecot
dovecot: Oct 10 09:38:53 Info: auth-worker(default): pam(user1.vn,10.0.0.7):
#1/1 style=1 msg=Password:
dovecot: Oct 10 09:38:53 Info: auth(default): new auth connection: pid=22405
dovecot: Oct 10 09:38:54 Info: auth(default): client in: AUTH 1
PLAIN service=pop3 lip= x.x.x.x rip= x.x.x.x lport=110 rport=2789
resp=<hidden>
dovecot: Oct 10 09:38:56 Info: auth-worker(default): pam(user1,x.x.x.x):
pam_authenticate() failed: Authentication failure (password mismatch?)
----------------------------------------------------------------
Bref, I suggest that when the connection between LDAP and dovecot is
dropped, the connection from user is still there and as they don't receive a
result from dovecot [Fail or Success]... And it still "pending"
somehow to
wait a response from dovecot. But when ldap is connected to the system,
these pending connection (from user) is still pending .... so it makes the
"request queue is full". Isn't it?
Should I do something to work-through or work-around this problem? May I did
something wrong in my configuration. Below is usual information may it helps
us analyze the problem!
Thanks many much for your help!
-----------------------------------------------------------------
[root ~]# dovecot -n
# 1.1.14: /etc/dovecot.conf
# OS: Linux 2.6.18-92.el5PAE i686 CentOS release 5.2 (Final) ext3
log_path: /var/log/dovecot.log
protocols: imap pop3
ssl_disable: yes
login_dir: /var/run/dovecot/login
login_executable(default): /usr/libexec/dovecot/imap-login
login_executable(imap): /usr/libexec/dovecot/imap-login
login_executable(pop3): /usr/libexec/dovecot/pop3-login
verbose_proctitle: yes
mail_gid: 100
mail_location: maildir:/home/%u/Maildir
mail_debug: yes
mail_executable(default): /usr/libexec/dovecot/imap
mail_executable(imap): /usr/libexec/dovecot/imap
mail_executable(pop3): /usr/libexec/dovecot/pop3
mail_plugin_dir(default): /usr/lib/dovecot/imap
mail_plugin_dir(imap): /usr/lib/dovecot/imap
mail_plugin_dir(pop3): /usr/lib/dovecot/pop3
auth default:
verbose: yes
debug: yes
passdb:
driver: ldap
args: /etc/dovecot-ldap.conf
passdb:
driver: pam
userdb:
driver: ldap
args: /etc/dovecot-ldap.conf
userdb:
driver: static
socket:
type: listen
master:
path: /var/run/dovecot/auth-master
mode: 384
user: dovecot
group: dovecot
plugin:
sieve: /home/%u/.dovecot.sieve
--------------------------------------------------------------------
[root ~]# grep -v '^ *\(#.*\)\?$' /etc/dovecot-ldap.conf
hosts = ldap.tma.com.vn
dn = #####
dnpass = ######
auth_bind = yes
auth_bind_userdn = uid=%u,ou=Users,dc=tma,dc=com,dc=vn
ldap_version = 3
base = ou=Users,dc=,dc=com,dc=vn
scope = subtree
user_attrs = uid=uid,mailQuota=quota_rule=*:storage=%$M
user_filter = (&(objectClass=posixAccount)(uid=%u))
pass_attrs = uid=user,userPassword=password
pass_filter = (&(objectClass=posixAccount)(uid=%u))
default_pass_scheme = CRYPT
--------------------------------------------------------------------
Regards,
Thu NGUYEN.
Timo Sirainen
2009-Oct-16 00:01 UTC
[Dovecot] Dovecot inactive after an intermittent connection with LDAP
On Sun, 2009-10-11 at 21:57 +0700, Thu Nguyen wrote:> [root ~]# dovecot -n > # 1.1.14: /etc/dovecot.confI'd suggest first upgrading. There are at least two related LDAP bugs fixed since 1.1.4: * src/auth/db-ldap.c: ldap: If first request is over 60 seconds old while a new request comes, reconnect. [f28d0ec6ec09] * src/auth/db-ldap.c: ldap: Fixed hang when >128 requests were sent at once. Based on patch by Marek Miska. [9954461eda42] -------------- next part -------------- A non-text attachment was scrubbed... Name: signature.asc Type: application/pgp-signature Size: 197 bytes Desc: This is a digitally signed message part URL: <http://dovecot.org/pipermail/dovecot/attachments/20091015/e7424caf/attachment-0002.bin>
Thu Nguyen
2009-Oct-16 07:23 UTC
[Dovecot] Dovecot inactive after an intermittent connection with LDAP
Thanks. We plan to upgrade it now. Regards, Thu NGUYEN. -----Original Message----- From: dovecot-bounces+ntathu=tma.com.vn at dovecot.org [mailto:dovecot-bounces+ntathu=tma.com.vn at dovecot.org] On Behalf Of Timo Sirainen Sent: Friday, October 16, 2009 7:02 AM To: Thu Nguyen Cc: dovecot at dovecot.org Subject: Re: [Dovecot] Dovecot inactive after an intermittent connection with LDAP On Sun, 2009-10-11 at 21:57 +0700, Thu Nguyen wrote:> [root ~]# dovecot -n > # 1.1.14: /etc/dovecot.confI'd suggest first upgrading. There are at least two related LDAP bugs fixed since 1.1.4: * src/auth/db-ldap.c: ldap: If first request is over 60 seconds old while a new request comes, reconnect. [f28d0ec6ec09] * src/auth/db-ldap.c: ldap: Fixed hang when >128 requests were sent at once. Based on patch by Marek Miska. [9954461eda42]