I'm using the dovecot-stable from 7/30, authenticating against an OpenLDAP server. From time to time, dovecot stops responding to new queries. It seems to be a self-correcting problem, lasting about 20 minutes.
Here's how it starts:
Aug 18 19:38:23 cliff dovecot: imap-login: Disconnected: Inactivity [150.253.42.12] Aug 18 19:38:36 cliff dovecot: pop3-login: Disconnected: Inactivity [68.46.174.217] Aug 18 19:39:35 cliff dovecot: imap-login: Disconnected: Inactivity [150.253.42.12]
Normally I see almost no "Disconnected: Inactivity" messages, but when this problem shows up I get an almost non-stop barrage of them. In fact, over the 20 minutes or so, there's about 150 of those entries, so I filtered them out of the log snippets. I also filtered out any "normal" activity during the time period. Here's what's left:
Aug 18 19:40:29 cliff dovecot: auth(ldap): file mech.c: line 117 (auth_request_destroy): assertion failed: (request->refcount > 0) Aug 18 19:40:29 cliff dovecot: child 22347 (auth) killed with signal 6 Aug 18 19:42:04 cliff dovecot: auth(ldap): ldap(vmail,150.253.80.31): unknown user Aug 18 19:42:41 cliff dovecot: imap-login: SSL_read() syscall failed: EOF [24.26.184.219] Aug 18 19:43:25 cliff dovecot: auth(ldap): Login process has too old (126s) requests, killing it. Aug 18 19:43:25 cliff dovecot: auth(ldap): Login process has too old (126s) requests, killing it. Aug 18 19:43:25 cliff dovecot: auth(ldap): Login process has too old (126s) requests, killing it. Aug 18 19:43:25 cliff dovecot: auth(ldap): Login process has too old (126s) requests, killing it. Aug 18 19:43:25 cliff dovecot: auth(ldap): Login process has too old (126s) requests, killing it. Aug 18 19:43:31 cliff dovecot: auth(ldap): Login process has too old (121s) requests, killing it. Aug 18 19:43:43 cliff dovecot: auth(ldap): Login process has too old (121s) requests, killing it. Aug 18 19:43:43 cliff dovecot: auth(ldap): Login process has too old (122s) requests, killing it. Aug 18 19:43:49 cliff dovecot: imap-login: Master sent reply with unknown tag 1 Aug 18 19:43:49 cliff dovecot: auth(ldap): file mech.c: line 117 (auth_request_destroy): assertion failed: (request->refcount > 0) Aug 18 19:43:49 cliff dovecot: child 22557 (auth) killed with signal 6 Aug 18 19:43:49 cliff dovecot: child 22562 (login) returned error 89 Aug 18 19:45:31 cliff dovecot: imap-login: Master sent reply with unknown tag 1 Aug 18 19:45:31 cliff dovecot: imap-login: Master sent reply with unknown tag 1 Aug 18 19:45:31 cliff dovecot: imap-login: Master sent reply with unknown tag 1 Aug 18 19:45:31 cliff dovecot: imap-login: Master sent reply with unknown tag 1 Aug 18 19:45:31 cliff dovecot: imap-login: Master sent reply with unknown tag 1 Aug 18 19:45:32 cliff dovecot: child 22522 (login) returned error 89 Aug 18 19:45:32 cliff dovecot: child 22561 (login) returned error 89 Aug 18 19:45:32 cliff dovecot: child 22563 (login) returned error 89 Aug 18 19:45:32 cliff dovecot: child 22564 (login) returned error 89 Aug 18 19:45:32 cliff dovecot: child 22566 (login) returned error 89 Aug 18 19:47:54 cliff dovecot: auth(ldap): file mech.c: line 117 (auth_request_destroy): assertion failed: (request->refcount > 0) Aug 18 19:47:54 cliff dovecot: child 22599 (auth) killed with signal 6 Aug 18 19:48:18 cliff dovecot: imap-login: SSL_read() syscall failed: EOF [69.81.39.120] Aug 18 19:48:18 cliff dovecot: imap-login: SSL_read() syscall failed: EOF [69.81.39.120] Aug 18 19:51:32 cliff dovecot: auth(ldap): file mech.c: line 117 (auth_request_destroy): assertion failed: (request->refcount > 0) Aug 18 19:51:32 cliff dovecot: child 22628 (auth) killed with signal 6 Aug 18 19:54:14 cliff dovecot: auth(ldap): file mech.c: line 117 (auth_request_destroy): assertion failed: (request->refcount > 0) Aug 18 19:54:14 cliff dovecot: child 22655 (login) returned error 89 Aug 18 19:54:14 cliff dovecot: child 22683 (login) returned error 89 Aug 18 19:54:14 cliff dovecot: child 22686 (auth) killed with signal 6 Aug 18 19:54:14 cliff dovecot: child 22689 (login) returned error 89 Aug 18 19:54:14 cliff dovecot: child 22690 (login) returned error 89 Aug 18 19:54:14 cliff dovecot: child 22699 (login) returned error 89
Then, magickally, it begins working again.
Any thoughts?
-Ben