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

git-svn-id: https://origsvn.digium.com/svn/asterisk/branches/11@398649 65c4cc65-6c06-0410-ace0-fbb531ad65f3

diff --git a/include/asterisk/lock.h b/include/asterisk/lock.h
index 081f8a8588fed2642c60b09fdb482a53f4078e6b..dc1c3669492037e0a2707b7800e024b77c226a9e 100644 (file)
--- a/include/asterisk/lock.h
+++ b/include/asterisk/lock.h
@@ -281,12 +281,16 @@ void ast_remove_lock_info(void *lock_addr, struct ast_bt *bt);
 #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) */
 
 /*!

diff --git a/main/lock.c b/main/lock.c
index 3036e5bc4b3f0ad173dd59968bee784014c5d021..d66e01b27338e882cd92e22a8affb6367d29a5e9 100644 (file)
--- a/main/lock.c
+++ b/main/lock.c
@@ -208,12 +208,20 @@ int __ast_pthread_mutex_lock(const char *filename, int lineno, const char *func,
 
        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 @@ int __ast_pthread_mutex_trylock(const char *filename, int lineno, const char *fu
 
        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 @@ int __ast_cond_wait(const char *filename, int lineno, const char *func,
 
 #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 @@ int __ast_cond_wait(const char *filename, int lineno, const char *func,
                        __dump_backtrace(&lt->backtrace[ROFFSET], canlog);
 #endif
                        DO_THREAD_CRASH;
+               } 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;
                }
 
-               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
+               /* 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);
 
-#ifdef HAVE_BKTR
-               ast_remove_lock_info(t, bt);
-#else
-               ast_remove_lock_info(t);
-#endif
+               ast_suspend_lock_info(t);
        }
 #endif /* DEBUG_THREADS */
 
@@ -569,28 +570,16 @@ int __ast_cond_wait(const char *filename, int lineno, const char *func,
                                   filename, lineno, func, strerror(res));
                DO_THREAD_CRASH;
        } else if (t->tracking) {
+               pthread_mutex_t reentr_mutex_orig;
                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);
-               }
+               /* 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);
 
-#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
+               ast_restore_lock_info(t);
        }
 #endif /* DEBUG_THREADS */
 
@@ -605,10 +594,8 @@ int __ast_cond_timedwait(const char *filename, int lineno, const char *func,
 
 #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 @@ int __ast_cond_timedwait(const char *filename, int lineno, const char *func,
                        __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;
+                       DO_THREAD_CRASH;
                }
 
-               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
+               /* 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);
 
-#ifdef HAVE_BKTR
-               ast_remove_lock_info(t, bt);
-#else
-               ast_remove_lock_info(t);
-#endif
+               ast_suspend_lock_info(t);
        }
 #endif /* DEBUG_THREADS */
 
@@ -676,28 +651,16 @@ int __ast_cond_timedwait(const char *filename, int lineno, const char *func,
                                   filename, lineno, func, strerror(res));
                DO_THREAD_CRASH;
        } else if (t->tracking) {
+               pthread_mutex_t reentr_mutex_orig;
                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);
-               }
+               /* 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);
 
-#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
+               ast_suspend_lock_info(t);
        }
 #endif /* DEBUG_THREADS */
 
@@ -899,12 +862,20 @@ int __ast_rwlock_rdlock(const char *filename, int line, const char *func, ast_rw
 
        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 @@ int __ast_rwlock_wrlock(const char *filename, int line, const char *func, ast_rw
 
        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 @@ int __ast_rwlock_timedrdlock(const char *filename, int line, const char *func, a
 
        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 @@ int __ast_rwlock_timedwrlock(const char *filename, int line, const char *func, a
 
        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 @@ int __ast_rwlock_tryrdlock(const char *filename, int line, const char *func, ast
 
        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 @@ int __ast_rwlock_trywrlock(const char *filename, int line, const char *func, ast
 
        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);

diff --git a/main/utils.c b/main/utils.c
index 07669a9d4ba7c7845b1aa508302ea90eae87c0e7..083fb9433b4a75b3c152baa37598349afe73beb2 100644 (file)
--- a/main/utils.c
+++ b/main/utils.c
@@ -603,6 +603,8 @@ struct thr_lock_info {
                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
@@ -789,6 +791,60 @@ int ast_find_lock_info(void *lock_addr, char *filename, size_t filename_size, in
        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
@@ -882,7 +938,7 @@ static void append_lock_information(struct ast_str **str, struct thr_lock_info *
        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,
@@ -890,7 +946,8 @@ static void append_lock_information(struct ast_str **str, struct thr_lock_info *
                                   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
@@ -999,20 +1056,32 @@ static char *handle_show_locks(struct ast_cli_entry *e, int cmd, struct ast_cli_
        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);