[Dovecot] Weird series of errors with dovecot-stable
Chris Wakelin
c.d.wakelin at reading.ac.uk
Wed Sep 21 21:46:38 EEST 2005
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
More information about the dovecot
mailing list