[Dovecot] Authorization client connect failing

[Ryan Hinton]

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 at email.com