[Date Prev][Date Next] [Chronological] [Thread] [Top]

Re: slapd deadlock bug ITS#7296

Richard Silverman wrote:


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.
It would probably be helpful for you to post your test code as well so other developers can use it to reproduce the issue. 


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.
The previously quoted code clearly sets conn->c_writing to 0 if a hard error occurs. What are the values in *conn when this hang happens? Which thread owns the write1 mutex at that point? 


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.
Yes, the code here is in need of a rewrite. In particular, blocked writer threads should just perform their own epoll/select instead of delegating this back to the main listener thread(s). That would eliminate at least one layer of complexity.
As for the rest - "reverse engineering" would be something like taking a compiled binary and trying to decompile it. Reading source code is simply that, it's not reverse engineering. The variables are documented with their purpose and usage, the comments show what a block of code aims to do. What more do you expect? 


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.


--
  -- Howard Chu
  CTO, Symas Corp.           http://www.symas.com
  Director, Highland Sun     http://highlandsun.com/hyc/
  Chief Architect, OpenLDAP  http://www.openldap.org/project/