[Dovecot] Authorization client connect failing
Hello, and thank you in advance for your valuable time.
I am running Dovecot v1.0.rc15 on an OpenBSD 3.9 i386 machine (no time to upgrade yet). I downloaded the source from the dovecot site, compiled and installed without any problem. The server starts up find and runs for a while. After a few hours to a few days, the server stops sending the CAPABILITY statement when a client tries to login. I found a few descriptions of this problem on the web, but no satisfactory resolution.
I added some debugging code to the functions in auth-client.c and got the following traces. Included in this email are a successful login attempt, a failed attempt, and a startup trace. I am not a UNIX sockets guru and don't know the dovecot internals well enough to figure out what's wrong. I am happy to add/remove debugging code as requested to help track down the problem, although it may take a few days for the server to hang again. I hope someone can help me figure out the problem so my mail server works reliably!
Here is a successful login attempt.
Dec 9 10:34:45 myhost dovecot: imap-login: DEBUG:: auth_client_is_connected? Dec 9 10:34:45 myhost dovecot: imap-login: DEBUG:: auth_client_get_available_mechs Dec 9 10:34:45 myhost dovecot: imap-login: DEBUG:: auth_client_new Dec 9 10:34:45 myhost dovecot: imap-login: DEBUG:: auth_client_new_external Dec 9 10:34:45 myhost dovecot: imap-login: DEBUG:: auth_client_connect_missing_servers Dec 9 10:34:45 myhost dovecot: imap-login: DEBUG:: creating file descriptor for path... Dec 9 10:34:45 myhost dovecot: imap-login: default Dec 9 10:34:45 myhost dovecot: imap-login: DEBUG:: auth_client_set_connect_notify Dec 9 10:34:45 myhost dovecot: imap-login: DEBUG:: auth_client_find_mech Dec 9 10:34:45 myhost dovecot: imap-login: DEBUG:: auth_client_is_connected? Dec 9 10:34:47 myhost dovecot: imap-login: DEBUG:: auth_client_is_connected? Dec 9 10:34:47 myhost dovecot: imap-login: DEBUG:: auth_client_find_mech Dec 9 10:34:47 myhost dovecot: imap-login: Login: user=<myuser>, method=plain, rip=1.2.3.client, lip=1.2.3.server, TLS Dec 9 11:02:13 myhost dovecot: IMAP(myuser): Disconnected: Logged out Dec 9 11:02:13 myhost dovecot: imap-login: DEBUG:: auth_client_free Dec 9 11:02:13 myhost dovecot: imap-login: DEBUG:: auth_client_is_connected?
The "creating file" output is from auth_server_connection_new(...) and dumps the requested path on the next line. Following is a failed attempt. The failure messages continue about every 5 seconds thereafter until I kill dovecot and restart.
Dec 9 16:26:53 myhost dovecot: imap-login: DEBUG:: auth_client_is_connected? Dec 9 16:26:53 myhost dovecot: imap-login: DEBUG:: auth_client_get_available_mechs Dec 9 16:26:53 myhost dovecot: imap-login: DEBUG:: auth_client_new Dec 9 16:26:53 myhost dovecot: imap-login: DEBUG:: auth_client_new_external Dec 9 16:26:53 myhost dovecot: imap-login: DEBUG:: auth_client_connect_missing_servers Dec 9 16:26:53 myhost dovecot: imap-login: DEBUG:: auth_client_set_connect_notify Dec 9 16:26:58 myhost dovecot: imap-login: DEBUG:: reconnect_timeout Dec 9 16:26:58 myhost dovecot: imap-login: DEBUG:: auth_client_connect_missing_servers Dec 9 16:26:58 myhost dovecot: imap-login: DEBUG:: auth_client_is_connected? Dec 9 16:27:03 myhost dovecot: imap-login: DEBUG:: reconnect_timeout Dec 9 16:27:03 myhost dovecot: imap-login: DEBUG:: auth_client_connect_missing_servers Dec 9 16:27:03 myhost dovecot: imap-login: DEBUG:: auth_client_is_connected? Dec 9 16:27:04 myhost dovecot: imap-login: DEBUG:: auth_client_is_connected? Dec 9 16:27:04 myhost dovecot: imap-login: DEBUG:: auth_client_find_mech Dec 9 16:27:04 myhost dovecot: imap-login: Login: user=<myuser>, method=plain, rip=1.2.3.client, lip=1.2.3.server, TLS Dec 9 16:27:08 myhost dovecot: imap-login: DEBUG:: reconnect_timeout Dec 9 16:27:08 myhost dovecot: imap-login: DEBUG:: auth_client_connect_missing_servers Dec 9 16:27:08 myhost dovecot: imap-login: DEBUG:: auth_client_is_connected? Dec 9 16:27:13 myhost dovecot: imap-login: DEBUG:: reconnect_timeout Dec 9 16:27:13 myhost dovecot: imap-login: DEBUG:: auth_client_connect_missing_servers Dec 9 16:27:13 myhost dovecot: imap-login: DEBUG:: auth_client_is_connected? Dec 9 16:27:18 myhost dovecot: imap-login: DEBUG:: reconnect_timeout Dec 9 16:27:18 myhost dovecot: imap-login: DEBUG:: auth_client_connect_missing_servers Dec 9 16:27:18 myhost dovecot: imap-login: DEBUG:: auth_client_is_connected? Dec 9 16:27:23 myhost dovecot: imap-login: DEBUG:: reconnect_timeout
Here is the startup trace. After this I see 3 imap-login processes.
Dec 9 15:32:33 myhost dovecot: Dovecot v1.0.rc15 starting up Dec 9 15:32:33 myhost dovecot: Generating Diffie-Hellman parameters for the first time. This may take a while.. Dec 9 15:32:35 myhost dovecot: imap-login: DEBUG:: auth_client_new Dec 9 15:32:35 myhost dovecot: imap-login: DEBUG:: auth_client_new Dec 9 15:32:35 myhost dovecot: imap-login: DEBUG:: auth_client_new_external Dec 9 15:32:35 myhost dovecot: imap-login: DEBUG:: auth_client_new_external Dec 9 15:32:35 myhost dovecot: imap-login: DEBUG:: auth_client_connect_missing_servers Dec 9 15:32:35 myhost dovecot: imap-login: DEBUG:: auth_client_connect_missing_servers Dec 9 15:32:35 myhost dovecot: imap-login: DEBUG:: auth_client_new Dec 9 15:32:35 myhost dovecot: imap-login: DEBUG:: creating file descriptor for path... Dec 9 15:32:35 myhost dovecot: imap-login: DEBUG:: creating file descriptor for path... Dec 9 15:32:35 myhost dovecot: imap-login: DEBUG:: auth_client_new_external Dec 9 15:32:35 myhost dovecot: imap-login: default Dec 9 15:32:35 myhost dovecot: imap-login: default Dec 9 15:32:35 myhost dovecot: imap-login: DEBUG:: auth_client_connect_missing_servers Dec 9 15:32:35 myhost dovecot: imap-login: DEBUG:: creating file descriptor for path... Dec 9 15:32:35 myhost dovecot: imap-login: default Dec 9 15:32:35 myhost dovecot: imap-login: DEBUG:: auth_client_set_connect_notify Dec 9 15:32:35 myhost dovecot: imap-login: DEBUG:: auth_client_set_connect_notify Dec 9 15:32:35 myhost dovecot: imap-login: DEBUG:: auth_client_find_mech Dec 9 15:32:35 myhost dovecot: imap-login: DEBUG:: auth_client_find_mech Dec 9 15:32:35 myhost dovecot: imap-login: DEBUG:: auth_client_set_connect_notify Dec 9 15:32:35 myhost dovecot: imap-login: DEBUG:: auth_client_is_connected? Dec 9 15:32:35 myhost dovecot: imap-login: DEBUG:: auth_client_is_connected? Dec 9 15:32:35 myhost dovecot: imap-login: DEBUG:: auth_client_find_mech Dec 9 15:32:35 myhost dovecot: imap-login: DEBUG:: auth_client_is_connected?
Thank you!
Ryan Hinton iobass@email.com
On 13.10.2006, at 8.49, Ryan Hinton wrote:
I am running Dovecot v1.0.rc15 on an OpenBSD 3.9 i386 machine (no
time to upgrade yet). I downloaded the source from the dovecot
site, compiled and installed without any problem. The server
starts up find and runs for a while. After a few hours to a few
days, the server stops sending the CAPABILITY statement when a
client tries to login. I found a few descriptions of this problem
on the web, but no satisfactory resolution.
I think it's usually because dovecot-auth gets stuck, so you should
rather look at what it's doing at the time. Maybe ktrace it (http://
wiki.dovecot.org/Debugging/ProcessTracing). What passdb and userdb
are you using?
On Fri 13 Oct 2006 08:49, Ryan Hinton wrote:
Hello, and thank you in advance for your valuable time.
I am running Dovecot v1.0.rc15 on an OpenBSD 3.9 i386 machine (no time to upgrade yet). I downloaded the source from the dovecot site, compiled and installed without any problem. The server starts up find and runs for a while. After a few hours to a few days, the server stops sending the CAPABILITY statement when a client tries to login. I found a few descriptions of this problem on the web, but no satisfactory resolution.
I believe I am seeing the same problem with Dovecot 1.0.rc15, Postfix and OpenLDAP on SUSE 10.1
Prior to the problem occurring I see the following in the logs:
"dovecot: child 24628 (auth) killed with signal 6"
It is happening every 1-2 weeks...
--
Peter Nixon http://www.peternixon.net/ PGP Key: http://www.peternixon.net/public.asc
On 4.1.2007, at 15.29, Peter Nixon wrote:
Prior to the problem occurring I see the following in the logs:
"dovecot: child 24628 (auth) killed with signal 6"
This means it died with abort(). Which means that it really should
have logged an error message before this line. Do you see it?
On Fri 05 Jan 2007 20:35, Timo Sirainen wrote:
On 4.1.2007, at 15.29, Peter Nixon wrote:
Prior to the problem occurring I see the following in the logs:
"dovecot: child 24628 (auth) killed with signal 6"
This means it died with abort(). Which means that it really should have logged an error message before this line. Do you see it?
Oops. Sorry for the lack of detail.
I have the following in /var/log/mail:
Jan 4 11:12:25 server postfix/smtpd[6197]: connect from unknown[81.214.254.126] Jan 4 11:12:33 server postfix/smtpd[6024]: warning: unknown[x.x.x.x]: SASL LOGIN authentication failed: Connection lost to authentication server Jan 4 11:12:33 server postfix/smtpd[6024]: lost connection after AUTH from unknown[x.x.x.x] Jan 4 11:12:33 server postfix/smtpd[6024]: disconnect from unknown[x.x.x.x] Jan 4 11:12:36 server postfix/smtpd[6197]: warning: unknown[x.x.x.x]: SASL LOGIN authentication failed: Connection lost to authentication server Jan 4 11:12:36 server postfix/smtpd[6197]: lost connection after AUTH from unknown[x.x.x.x] Jan 4 11:12:36 server postfix/smtpd[6197]: disconnect from unknown[x.x.x.x] Jan 4 11:12:47 server postfix/smtpd[6455]: connect from unknown[x.x.x.x] Jan 4 11:12:48 server dovecot: auth(default): LDAP: ldap_result() failed: Can't contact LDAP server Jan 4 11:12:48 server dovecot: pop3-login: Disconnected: Inactivity: method=PLAIN, rip=x.x.x.x, lip=y.y.y.y Jan 4 11:12:48 server dovecot: auth(default): ldap(user): ldap_bind() failed: Invalid DN syntax Jan 4 11:12:48 server dovecot: auth(default): ldap(user): ldap_bind() failed: Invalid DN syntax Jan 4 11:12:48 server dovecot: auth(default): ldap(info): ldap_bind() failed: Invalid DN syntax Jan 4 11:12:48 server dovecot: auth(default): ldap(smtp): ldap_bind() failed: Invalid DN syntax Jan 4 11:12:48 server dovecot: auth(default): ldap(smtp): ldap_bind() failed: Invalid DN syntax Jan 4 11:12:48 server dovecot: auth(default): ldap(smtp): ldap_bind() failed: Invalid DN syntax Jan 4 11:12:48 server dovecot: auth(default): ldap(smtp): ldap_bind() failed: Invalid DN syntax Jan 4 11:12:48 server dovecot: auth(default): ldap(smtp): ldap_bind() failed: Invalid DN syntax Jan 4 11:12:48 server dovecot: auth(default): ldap(smtp): ldap_bind() failed: Invalid DN syntax Jan 4 11:12:48 server dovecot: auth(default): ldap(smtp): ldap_bind() failed: Invalid DN syntax Jan 4 11:12:48 server dovecot: auth(default): ldap(web): ldap_bind() failed: Invalid DN syntax Jan 4 11:12:48 server dovecot: auth(default): key not found from hash Jan 4 11:12:48 server postfix/smtpd[6455]: warning: unknown[x.x.x.x]: SASL LOGIN authentication failed: Jan 4 11:12:48 server dovecot: pop3-login: Internal login failure: user=user1@domain.com, method=PLAIN, rip=x.x.x.x, lip=y.y.y.y Jan 4 11:12:48 server dovecot: pop3-login: Internal login failure: user=user2@domain.com, method=PLAIN, rip=x.x.x.x, lip=y.y.y.y Jan 4 11:12:48 server dovecot: pop3-login: Internal login failure: user=user1@domain.com, method=PLAIN, rip=x.x.x.x, lip=y.y.y.y Jan 4 11:12:48 server dovecot: child 24628 (auth) killed with signal 6
I have checked /var/log/messages and there is nothing logged by ldap just before or after this error.
The problem was solved with a dovecot restart. slapd was NOT restarted.
Any ideas?
--
Peter Nixon http://www.peternixon.net/ PGP Key: http://www.peternixon.net/public.asc
participants (3)
-
Peter Nixon
-
Ryan Hinton
-
Timo Sirainen