I've been seeing this too. We're using dovecot-stable on Solaris 8 using passdb=pam (pam_ldap to Active Directory) userdb=passwd (NIS) and login_process_per_user = no. It sorts itself out after a second or so for us. We also often get "Can't connect to auth server at default: Connection refused" shortly afterwards.

We had big problems (lots of "Can't connect") yesterday before changing login_process_per_user from "yes", but didn't get quite these errors. (We did get an assertion failure in auth-client-connection.c: line 38 (auth_client_send): assertion failed: (conn->refcount > 1) on one of the occasions)

Did you ever sort out the cause?

The auth_request_destroy assertion failures generate core files, I managed to extract a backtrace but it's not very illuminating:

#0 0xff19fc14 in __tbl_2_huge_digits () from /usr/lib/libc.so.1 (gdb) bt #0 0xff19fc14 in __tbl_2_huge_digits () from /usr/lib/libc.so.1 #1 0xff13598c in abort () from /usr/lib/libc.so.1 #2 0x21c08 in i_internal_fatal_handler (status=187936, fmt=0xffbef808 "", args=0x21bec) at failures.c:374

Best Wishes, Chris

Ben Beuchler wrote:

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

-- --+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+---+- Christopher Wakelin, c.d.wakelin@reading.ac.uk IT Services Centre, The University of Reading, Tel: +44 (0)118 378 8439 Whiteknights, Reading, RG6 2AF, UK Fax: +44 (0)118 975 3094