[asterisk-commits] dlee: branch 12 r398651 - in /branches/12: ./ include/asterisk/ main/

SVN commits to the Asterisk project asterisk-commits at lists.digium.com
Mon Sep 9 15:12:49 CDT 2013


Author: dlee
Date: Mon Sep  9 15:12:46 2013
New Revision: 398651

URL: http://svnview.digium.com/svn/asterisk?view=rev&rev=398651
Log:
Fix DEBUG_THREADS when lock is acquired in __constructor__

This patch fixes some long-standing bugs in debug threads that were
exacerbated with recent Optional API work in Asterisk 12.

With debug threads enabled, on some systems, there's a lock ordering
problem between our mutex and glibc's mutex protecting its module list
(Ubuntu Lucid, glibc 2.11.1 in this instance). In one thread, the module
list will be locked before acquiring our mutex. In another thread, our
mutex will be locked before locking the module list (which happens in
the depths of calling backtrace()).

This patch fixes this issue by moving backtrace() calls outside of
critical sections that have the mutex acquired. The bigger change was to
reentrancy tracking for ast_cond_{timed,}wait, which wrongly assumed
that waiting on the mutex was equivalent to a single unlock (it actually
suspends all recursive locks on the mutex).

(closes issue ASTERISK-22455)
Review: https://reviewboard.asterisk.org/r/2824/
........

Merged revisions 398648 from http://svn.asterisk.org/svn/asterisk/branches/1.8
........

Merged revisions 398649 from http://svn.asterisk.org/svn/asterisk/branches/11

Modified:
    branches/12/   (props changed)
    branches/12/include/asterisk/lock.h
    branches/12/main/lock.c
    branches/12/main/utils.c

Propchange: branches/12/
------------------------------------------------------------------------------
Binary property 'branch-11-merged' - no diff available.

Modified: branches/12/include/asterisk/lock.h
URL: http://svnview.digium.com/svn/asterisk/branches/12/include/asterisk/lock.h?view=diff&rev=398651&r1=398650&r2=398651
==============================================================================
--- branches/12/include/asterisk/lock.h (original)
+++ branches/12/include/asterisk/lock.h Mon Sep  9 15:12:46 2013
@@ -282,12 +282,16 @@
 #else
 void ast_remove_lock_info(void *lock_addr);
 #endif /* HAVE_BKTR */
+void ast_suspend_lock_info(void *lock_addr);
+void ast_restore_lock_info(void *lock_addr);
 #else
 #ifdef HAVE_BKTR
 #define ast_remove_lock_info(ignore,me)
 #else
 #define ast_remove_lock_info(ignore)
 #endif /* HAVE_BKTR */
+#define ast_suspend_lock_info(ignore);
+#define ast_restore_lock_info(ignore);
 #endif /* !defined(LOW_MEMORY) */
 
 /*!

Modified: branches/12/main/lock.c
URL: http://svnview.digium.com/svn/asterisk/branches/12/main/lock.c?view=diff&rev=398651&r1=398650&r2=398651
==============================================================================
--- branches/12/main/lock.c (original)
+++ branches/12/main/lock.c Mon Sep  9 15:12:46 2013
@@ -208,12 +208,20 @@
 
 	if (t->tracking) {
 #ifdef HAVE_BKTR
+		struct ast_bt tmp;
+
+		/* The implementation of backtrace() may have its own locks.
+		 * Capture the backtrace outside of the reentrancy lock to
+		 * avoid deadlocks. See ASTERISK-22455. */
+		ast_bt_get_addresses(&tmp);
+
 		ast_reentrancy_lock(lt);
 		if (lt->reentrancy != AST_MAX_REENTRANCY) {
-			ast_bt_get_addresses(&lt->backtrace[lt->reentrancy]);
+			lt->backtrace[lt->reentrancy] = tmp;
 			bt = &lt->backtrace[lt->reentrancy];
 		}
 		ast_reentrancy_unlock(lt);
+
 		ast_store_lock_info(AST_MUTEX, filename, lineno, func, mutex_name, t, bt);
 #else
 		ast_store_lock_info(AST_MUTEX, filename, lineno, func, mutex_name, t);
@@ -340,12 +348,20 @@
 
 	if (t->tracking) {
 #ifdef HAVE_BKTR
+		struct ast_bt tmp;
+
+		/* The implementation of backtrace() may have its own locks.
+		 * Capture the backtrace outside of the reentrancy lock to
+		 * avoid deadlocks. See ASTERISK-22455. */
+		ast_bt_get_addresses(&tmp);
+
 		ast_reentrancy_lock(lt);
 		if (lt->reentrancy != AST_MAX_REENTRANCY) {
-			ast_bt_get_addresses(&lt->backtrace[lt->reentrancy]);
+			lt->backtrace[lt->reentrancy] = tmp;
 			bt = &lt->backtrace[lt->reentrancy];
 		}
 		ast_reentrancy_unlock(lt);
+
 		ast_store_lock_info(AST_MUTEX, filename, lineno, func, mutex_name, t, bt);
 #else
 		ast_store_lock_info(AST_MUTEX, filename, lineno, func, mutex_name, t);
@@ -497,10 +513,8 @@
 
 #ifdef DEBUG_THREADS
 	struct ast_lock_track *lt;
+	struct ast_lock_track lt_orig;
 	int canlog = strcmp(filename, "logger.c") & t->tracking;
-#ifdef HAVE_BKTR
-	struct ast_bt *bt = NULL;
-#endif
 
 #if defined(AST_MUTEX_INIT_W_CONSTRUCTORS) && defined(CAN_COMPARE_MUTEX_TO_INIT_VALUE)
 	if ((t->mutex) == ((pthread_mutex_t) PTHREAD_MUTEX_INITIALIZER)) {
@@ -531,33 +545,20 @@
 			__dump_backtrace(&lt->backtrace[ROFFSET], canlog);
 #endif
 			DO_THREAD_CRASH;
-		}
-
-		if (--lt->reentrancy < 0) {
-			__ast_mutex_logger("%s line %d (%s): mutex '%s' freed more times than we've locked!\n",
-				   filename, lineno, func, mutex_name);
-			lt->reentrancy = 0;
-		}
-
-		if (lt->reentrancy < AST_MAX_REENTRANCY) {
-			lt->file[lt->reentrancy] = NULL;
-			lt->lineno[lt->reentrancy] = 0;
-			lt->func[lt->reentrancy] = NULL;
-			lt->thread[lt->reentrancy] = 0;
-		}
-
-#ifdef HAVE_BKTR
-		if (lt->reentrancy) {
-			bt = &lt->backtrace[lt->reentrancy - 1];
-		}
-#endif
-		ast_reentrancy_unlock(lt);
-
-#ifdef HAVE_BKTR
-		ast_remove_lock_info(t, bt);
-#else
-		ast_remove_lock_info(t);
-#endif
+		} else if (lt->reentrancy <= 0) {
+			__ast_mutex_logger("%s line %d (%s): attempted to wait on an unlocked mutex '%s'\n",
+					   filename, lineno, func, mutex_name);
+			DO_THREAD_CRASH;
+		}
+
+		/* Waiting on a condition completely suspends a recursive mutex,
+		 * even if it's been recursively locked multiple times. Make a
+		 * copy of the lock tracking, and reset reentrancy to zero */
+		lt_orig = *lt;
+		lt->reentrancy = 0;
+		ast_reentrancy_unlock(lt);
+
+		ast_suspend_lock_info(t);
 	}
 #endif /* DEBUG_THREADS */
 
@@ -569,28 +570,16 @@
 				   filename, lineno, func, strerror(res));
 		DO_THREAD_CRASH;
 	} else if (t->tracking) {
-		ast_reentrancy_lock(lt);
-		if (lt->reentrancy < AST_MAX_REENTRANCY) {
-			lt->file[lt->reentrancy] = filename;
-			lt->lineno[lt->reentrancy] = lineno;
-			lt->func[lt->reentrancy] = func;
-			lt->thread[lt->reentrancy] = pthread_self();
-#ifdef HAVE_BKTR
-			ast_bt_get_addresses(&lt->backtrace[lt->reentrancy]);
-			bt = &lt->backtrace[lt->reentrancy];
-#endif
-			lt->reentrancy++;
-		} else {
-			__ast_mutex_logger("%s line %d (%s): '%s' really deep reentrancy!\n",
-							   filename, lineno, func, mutex_name);
-		}
-		ast_reentrancy_unlock(lt);
-
-#ifdef HAVE_BKTR
-		ast_store_lock_info(AST_MUTEX, filename, lineno, func, mutex_name, t, bt);
-#else
-		ast_store_lock_info(AST_MUTEX, filename, lineno, func, mutex_name, t);
-#endif
+		pthread_mutex_t reentr_mutex_orig;
+		ast_reentrancy_lock(lt);
+		/* Restore lock tracking to what it was prior to the wait */
+		reentr_mutex_orig = lt->reentr_mutex;
+		*lt = lt_orig;
+		/* un-trash the mutex we just copied over */
+		lt->reentr_mutex = reentr_mutex_orig;
+		ast_reentrancy_unlock(lt);
+
+		ast_restore_lock_info(t);
 	}
 #endif /* DEBUG_THREADS */
 
@@ -605,10 +594,8 @@
 
 #ifdef DEBUG_THREADS
 	struct ast_lock_track *lt;
+	struct ast_lock_track lt_orig;
 	int canlog = strcmp(filename, "logger.c") & t->tracking;
-#ifdef HAVE_BKTR
-	struct ast_bt *bt = NULL;
-#endif
 
 #if defined(AST_MUTEX_INIT_W_CONSTRUCTORS) && defined(CAN_COMPARE_MUTEX_TO_INIT_VALUE)
 	if ((t->mutex) == ((pthread_mutex_t) PTHREAD_MUTEX_INITIALIZER)) {
@@ -639,32 +626,20 @@
 			__dump_backtrace(&lt->backtrace[ROFFSET], canlog);
 #endif
 			DO_THREAD_CRASH;
-		}
-
-		if (--lt->reentrancy < 0) {
-			__ast_mutex_logger("%s line %d (%s): mutex '%s' freed more times than we've locked!\n",
+		} else if (lt->reentrancy <= 0) {
+			__ast_mutex_logger("%s line %d (%s): attempted to wait on an unlocked mutex '%s'\n",
 					   filename, lineno, func, mutex_name);
-			lt->reentrancy = 0;
-		}
-
-		if (lt->reentrancy < AST_MAX_REENTRANCY) {
-			lt->file[lt->reentrancy] = NULL;
-			lt->lineno[lt->reentrancy] = 0;
-			lt->func[lt->reentrancy] = NULL;
-			lt->thread[lt->reentrancy] = 0;
-		}
-#ifdef HAVE_BKTR
-		if (lt->reentrancy) {
-			bt = &lt->backtrace[lt->reentrancy - 1];
-		}
-#endif
-		ast_reentrancy_unlock(lt);
-
-#ifdef HAVE_BKTR
-		ast_remove_lock_info(t, bt);
-#else
-		ast_remove_lock_info(t);
-#endif
+			DO_THREAD_CRASH;
+		}
+
+		/* Waiting on a condition completely suspends a recursive mutex,
+		 * even if it's been recursively locked multiple times. Make a
+		 * copy of the lock tracking, and reset reentrancy to zero */
+		lt_orig = *lt;
+		lt->reentrancy = 0;
+		ast_reentrancy_unlock(lt);
+
+		ast_suspend_lock_info(t);
 	}
 #endif /* DEBUG_THREADS */
 
@@ -676,28 +651,16 @@
 				   filename, lineno, func, strerror(res));
 		DO_THREAD_CRASH;
 	} else if (t->tracking) {
-		ast_reentrancy_lock(lt);
-		if (lt->reentrancy < AST_MAX_REENTRANCY) {
-			lt->file[lt->reentrancy] = filename;
-			lt->lineno[lt->reentrancy] = lineno;
-			lt->func[lt->reentrancy] = func;
-			lt->thread[lt->reentrancy] = pthread_self();
-#ifdef HAVE_BKTR
-			ast_bt_get_addresses(&lt->backtrace[lt->reentrancy]);
-			bt = &lt->backtrace[lt->reentrancy];
-#endif
-			lt->reentrancy++;
-		} else {
-			__ast_mutex_logger("%s line %d (%s): '%s' really deep reentrancy!\n",
-							   filename, lineno, func, mutex_name);
-		}
-		ast_reentrancy_unlock(lt);
-
-#ifdef HAVE_BKTR
-		ast_store_lock_info(AST_MUTEX, filename, lineno, func, mutex_name, t, bt);
-#else
-		ast_store_lock_info(AST_MUTEX, filename, lineno, func, mutex_name, t);
-#endif
+		pthread_mutex_t reentr_mutex_orig;
+		ast_reentrancy_lock(lt);
+		/* Restore lock tracking to what it was prior to the wait */
+		reentr_mutex_orig = lt->reentr_mutex;
+		*lt = lt_orig;
+		/* un-trash the mutex we just copied over */
+		lt->reentr_mutex = reentr_mutex_orig;
+		ast_reentrancy_unlock(lt);
+
+		ast_suspend_lock_info(t);
 	}
 #endif /* DEBUG_THREADS */
 
@@ -899,12 +862,20 @@
 
 	if (t->tracking) {
 #ifdef HAVE_BKTR
+		struct ast_bt tmp;
+
+		/* The implementation of backtrace() may have its own locks.
+		 * Capture the backtrace outside of the reentrancy lock to
+		 * avoid deadlocks. See ASTERISK-22455. */
+		ast_bt_get_addresses(&tmp);
+
 		ast_reentrancy_lock(lt);
 		if (lt->reentrancy != AST_MAX_REENTRANCY) {
-			ast_bt_get_addresses(&lt->backtrace[lt->reentrancy]);
+			lt->backtrace[lt->reentrancy] = tmp;
 			bt = &lt->backtrace[lt->reentrancy];
 		}
 		ast_reentrancy_unlock(lt);
+
 		ast_store_lock_info(AST_RDLOCK, filename, line, func, name, t, bt);
 #else
 		ast_store_lock_info(AST_RDLOCK, filename, line, func, name, t);
@@ -1018,12 +989,20 @@
 
 	if (t->tracking) {
 #ifdef HAVE_BKTR
+		struct ast_bt tmp;
+
+		/* The implementation of backtrace() may have its own locks.
+		 * Capture the backtrace outside of the reentrancy lock to
+		 * avoid deadlocks. See ASTERISK-22455. */
+		ast_bt_get_addresses(&tmp);
+
 		ast_reentrancy_lock(lt);
 		if (lt->reentrancy != AST_MAX_REENTRANCY) {
-			ast_bt_get_addresses(&lt->backtrace[lt->reentrancy]);
+			lt->backtrace[lt->reentrancy] = tmp;
 			bt = &lt->backtrace[lt->reentrancy];
 		}
 		ast_reentrancy_unlock(lt);
+
 		ast_store_lock_info(AST_WRLOCK, filename, line, func, name, t, bt);
 #else
 		ast_store_lock_info(AST_WRLOCK, filename, line, func, name, t);
@@ -1141,12 +1120,20 @@
 
 	if (t->tracking) {
 #ifdef HAVE_BKTR
+		struct ast_bt tmp;
+
+		/* The implementation of backtrace() may have its own locks.
+		 * Capture the backtrace outside of the reentrancy lock to
+		 * avoid deadlocks. See ASTERISK-22455. */
+		ast_bt_get_addresses(&tmp);
+
 		ast_reentrancy_lock(lt);
 		if (lt->reentrancy != AST_MAX_REENTRANCY) {
-			ast_bt_get_addresses(&lt->backtrace[lt->reentrancy]);
+			lt->backtrace[lt->reentrancy] = tmp;
 			bt = &lt->backtrace[lt->reentrancy];
 		}
 		ast_reentrancy_unlock(lt);
+
 		ast_store_lock_info(AST_WRLOCK, filename, line, func, name, t, bt);
 #else
 		ast_store_lock_info(AST_WRLOCK, filename, line, func, name, t);
@@ -1244,12 +1231,20 @@
 
 	if (t->tracking) {
 #ifdef HAVE_BKTR
+		struct ast_bt tmp;
+
+		/* The implementation of backtrace() may have its own locks.
+		 * Capture the backtrace outside of the reentrancy lock to
+		 * avoid deadlocks. See ASTERISK-22455. */
+		ast_bt_get_addresses(&tmp);
+
 		ast_reentrancy_lock(lt);
 		if (lt->reentrancy != AST_MAX_REENTRANCY) {
-			ast_bt_get_addresses(&lt->backtrace[lt->reentrancy]);
+			lt->backtrace[lt->reentrancy] = tmp;
 			bt = &lt->backtrace[lt->reentrancy];
 		}
 		ast_reentrancy_unlock(lt);
+
 		ast_store_lock_info(AST_WRLOCK, filename, line, func, name, t, bt);
 #else
 		ast_store_lock_info(AST_WRLOCK, filename, line, func, name, t);
@@ -1350,12 +1345,20 @@
 
 	if (t->tracking) {
 #ifdef HAVE_BKTR
+		struct ast_bt tmp;
+
+		/* The implementation of backtrace() may have its own locks.
+		 * Capture the backtrace outside of the reentrancy lock to
+		 * avoid deadlocks. See ASTERISK-22455. */
+		ast_bt_get_addresses(&tmp);
+
 		ast_reentrancy_lock(lt);
 		if (lt->reentrancy != AST_MAX_REENTRANCY) {
-			ast_bt_get_addresses(&lt->backtrace[lt->reentrancy]);
+			lt->backtrace[lt->reentrancy] = tmp;
 			bt = &lt->backtrace[lt->reentrancy];
 		}
 		ast_reentrancy_unlock(lt);
+
 		ast_store_lock_info(AST_RDLOCK, filename, line, func, name, t, bt);
 #else
 		ast_store_lock_info(AST_RDLOCK, filename, line, func, name, t);
@@ -1420,12 +1423,20 @@
 
 	if (t->tracking) {
 #ifdef HAVE_BKTR
+		struct ast_bt tmp;
+
+		/* The implementation of backtrace() may have its own locks.
+		 * Capture the backtrace outside of the reentrancy lock to
+		 * avoid deadlocks. See ASTERISK-22455. */
+		ast_bt_get_addresses(&tmp);
+
 		ast_reentrancy_lock(lt);
 		if (lt->reentrancy != AST_MAX_REENTRANCY) {
-			ast_bt_get_addresses(&lt->backtrace[lt->reentrancy]);
+			lt->backtrace[lt->reentrancy] = tmp;
 			bt = &lt->backtrace[lt->reentrancy];
 		}
 		ast_reentrancy_unlock(lt);
+
 		ast_store_lock_info(AST_WRLOCK, filename, line, func, name, t, bt);
 #else
 		ast_store_lock_info(AST_WRLOCK, filename, line, func, name, t);

Modified: branches/12/main/utils.c
URL: http://svnview.digium.com/svn/asterisk/branches/12/main/utils.c?view=diff&rev=398651&r1=398650&r2=398651
==============================================================================
--- branches/12/main/utils.c (original)
+++ branches/12/main/utils.c Mon Sep  9 15:12:46 2013
@@ -597,6 +597,8 @@
 		enum ast_lock_type type;
 		/*! This thread is waiting on this lock */
 		int pending:2;
+		/*! A condition has suspended this lock */
+		int suspended:1;
 #ifdef HAVE_BKTR
 		struct ast_bt *backtrace;
 #endif
@@ -783,6 +785,60 @@
 	return 0;
 }
 
+void ast_suspend_lock_info(void *lock_addr)
+{
+	struct thr_lock_info *lock_info;
+	int i = 0;
+
+	if (!(lock_info = ast_threadstorage_get(&thread_lock_info, sizeof(*lock_info)))) {
+		return;
+	}
+
+	pthread_mutex_lock(&lock_info->lock);
+
+	for (i = lock_info->num_locks - 1; i >= 0; i--) {
+		if (lock_info->locks[i].lock_addr == lock_addr)
+			break;
+	}
+
+	if (i == -1) {
+		/* Lock not found :( */
+		pthread_mutex_unlock(&lock_info->lock);
+		return;
+	}
+
+	lock_info->locks[i].suspended = 1;
+
+	pthread_mutex_unlock(&lock_info->lock);
+}
+
+void ast_restore_lock_info(void *lock_addr)
+{
+	struct thr_lock_info *lock_info;
+	int i = 0;
+
+	if (!(lock_info = ast_threadstorage_get(&thread_lock_info, sizeof(*lock_info))))
+		return;
+
+	pthread_mutex_lock(&lock_info->lock);
+
+	for (i = lock_info->num_locks - 1; i >= 0; i--) {
+		if (lock_info->locks[i].lock_addr == lock_addr)
+			break;
+	}
+
+	if (i == -1) {
+		/* Lock not found :( */
+		pthread_mutex_unlock(&lock_info->lock);
+		return;
+	}
+
+	lock_info->locks[i].suspended = 0;
+
+	pthread_mutex_unlock(&lock_info->lock);
+}
+
+
 #ifdef HAVE_BKTR
 void ast_remove_lock_info(void *lock_addr, struct ast_bt *bt)
 #else
@@ -876,7 +932,7 @@
 	ast_mutex_t *lock;
 	struct ast_lock_track *lt;
 
-	ast_str_append(str, 0, "=== ---> %sLock #%d (%s): %s %d %s %s %p (%d)\n",
+	ast_str_append(str, 0, "=== ---> %sLock #%d (%s): %s %d %s %s %p (%d%s)\n",
 				   lock_info->locks[i].pending > 0 ? "Waiting for " :
 				   lock_info->locks[i].pending < 0 ? "Tried and failed to get " : "", i,
 				   lock_info->locks[i].file,
@@ -884,7 +940,8 @@
 				   lock_info->locks[i].line_num,
 				   lock_info->locks[i].func, lock_info->locks[i].lock_name,
 				   lock_info->locks[i].lock_addr,
-				   lock_info->locks[i].times_locked);
+				   lock_info->locks[i].times_locked,
+				   lock_info->locks[i].suspended ? " - suspended" : "");
 #ifdef HAVE_BKTR
 	append_backtrace_information(str, lock_info->locks[i].backtrace);
 #endif
@@ -982,20 +1039,32 @@
 	pthread_mutex_lock(&lock_infos_lock.mutex);
 	AST_LIST_TRAVERSE(&lock_infos, lock_info, entry) {
 		int i;
-		if (lock_info->num_locks) {
-			ast_str_append(&str, 0, "=== Thread ID: 0x%lx (%s)\n", (long) lock_info->thread_id,
-				lock_info->thread_name);
-			pthread_mutex_lock(&lock_info->lock);
-			for (i = 0; str && i < lock_info->num_locks; i++) {
-				append_lock_information(&str, lock_info, i);
+		int header_printed = 0;
+		pthread_mutex_lock(&lock_info->lock);
+		for (i = 0; str && i < lock_info->num_locks; i++) {
+			/* Don't show suspended locks */
+			if (lock_info->locks[i].suspended) {
+				continue;
 			}
-			pthread_mutex_unlock(&lock_info->lock);
-			if (!str)
-				break;
+
+			if (!header_printed) {
+				ast_str_append(&str, 0, "=== Thread ID: 0x%lx (%s)\n", (long) lock_info->thread_id,
+					lock_info->thread_name);
+				header_printed = 1;
+			}
+
+			append_lock_information(&str, lock_info, i);
+		}
+		pthread_mutex_unlock(&lock_info->lock);
+		if (!str) {
+			break;
+		}
+		if (header_printed) {
 			ast_str_append(&str, 0, "=== -------------------------------------------------------------------\n"
-			               "===\n");
-			if (!str)
-				break;
+				"===\n");
+		}
+		if (!str) {
+			break;
 		}
 	}
 	pthread_mutex_unlock(&lock_infos_lock.mutex);




More information about the asterisk-commits mailing list