Re: slapd deadlock bug ITS#7296

[Richard Silverman <res@qoxp.net>]

I was mistaken in my last message; my change did not actually fix the
problem. My harness for reproducing the bug (taken from the original bug
report) throws lots of cut connections at slapd and waits for the bug to
manifest; it just so happened that it took a much longer time than usual
for it to occur when I was testing that change.

Returning to the basic problem: when a connection is cut in mid-query as I
described, this code in send_ldap_ber() notices the problem:

		/*
		 * we got an error.  if it's ewouldblock, we need to
		 * wait on the socket being writable.  otherwise, figure
		 * it's a hard error and return.
		 */

		Debug( LDAP_DEBUG_CONNS, "ber_flush2 failed errno=%d reason=\"%s\"\n",
		    err, sock_errstr(err), 0 );

		if ( err != EWOULDBLOCK && err != EAGAIN ) {
			conn->c_writers--;
			conn->c_writing = 0;
			ldap_pvt_thread_mutex_unlock( &conn->c_write1_mutex );
			connection_closing( conn, "connection lost on write" );

			ldap_pvt_thread_mutex_unlock( &conn->c_mutex );
			return -1;
		}

However, this is somehow ineffective, because shortly thereafter all the
worker threads block with the following stack:

#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:162
#1  0x0000000000568f9a in ldap_int_thread_cond_wait (cond=0x7fe190fb9030, mutex=0x7fe190fb8fe0) at thr_posix.c:277
#2  0x000000000056aeee in ldap_pvt_thread_cond_wait (cond=0x7fe190fb9030, mutex=0x7fe190fb8fe0) at thr_debug.c:954
#3  0x000000000043e1b7 in send_ldap_ber (op=0x7fe160129fc0, ber=0x7fe16ae7b460) at result.c:303
#4  0x0000000000441338 in slap_send_search_entry (op=0x7fe160129fc0, rs=0x7fe16affc920) at result.c:1429
#5  0x00000000004c5953 in bdb_search (op=0x7fe160129fc0, rs=0x7fe16affc920) at search.c:1014
#6  0x000000000042daae in fe_op_search (op=0x7fe160129fc0, rs=0x7fe16affc920) at search.c:402
#7  0x000000000042d2f2 in do_search (op=0x7fe160129fc0, rs=0x7fe16affc920) at search.c:247
#8  0x000000000042a4b7 in connection_operation (ctx=0x7fe16affca00, arg_v=0x7fe160129fc0) at connection.c:1150
#9  0x00000000005679f3 in ldap_int_thread_pool_wrapper (xpool=0x1008e90) at tpool.c:688
#10 0x000000000056a493 in ldap_debug_thread_wrapper (arg=0x7fe1740015c0) at thr_debug.c:770
#11 0x00000039e3407851 in start_thread (arg=0x7fe16affd700) at pthread_create.c:301
#12 0x00000039e2ce811d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:115

(This is with thread debugging enabled.) They are blocked here, again in
send_ldap_ber():

	while ( conn->c_writers > 0 && conn->c_writing ) {
		ldap_pvt_thread_cond_wait( &conn->c_write1_cv, &conn->c_write1_mutex );
	}

The problem is that they are *all* here; there is no one left to signal
that condition variable, so slapd locks up forever.

Iâve tried various modifications, but the code is quite complex, sparsely
commented, and thereâs no overall design document explaining how the
various mutexes and condition variables are supposed to be used -- subtle
concurrency bugs like this are extremely difficult to debug dynamically or
reverse engineer, so Iâm really shooting in the dark. Any help would be
greatly appreciated.

Btw, this is not a theoretical problem: it caused us serious production
issues. We were accessing slapd through an F5 load balancer: it would
periodically max out its network link and drop some of the LDAP
connections going through it, and this triggers the bug.

Thanks,

--
  Richard