[Dovecot] Weird series of errors with dovecot-stable

[Chris Wakelin]

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 at 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