make DEBUG_THREADS have more visible logging

make DEBUG_THREADS able to catch locks being unlocked by threads that did not own them
add proper wrappers for pthread_cond_wait() and pthread_cond_timedwait() for DEBUG_THREADS mode


git-svn-id: http://svn.digium.com/svn/asterisk/trunk@6464 f38db490-d61c-443f-a65b-d21fe96a405b

2 files changed, 203 insertions, 74 deletions

diff --git a/include/asterisk/lock.h b/include/asterisk/lock.h
index 7d1ff89ed..da261b83d 100755
--- a/include/asterisk/lock.h
+++ b/include/asterisk/lock.h
@@ -28,6 +28,8 @@
 #include <time.h>
 #include <sys/param.h>
 
+#include "asterisk/logger.h"
+
 #define AST_PTHREADT_NULL (pthread_t) -1
 #define AST_PTHREADT_STOP (pthread_t) -2
 
@@ -63,6 +65,8 @@
 
 #ifdef DEBUG_THREADS
 
+#define __ast_mutex_logger(...) { if (canlog) ast_log(LOG_ERROR, __VA_ARGS__); else fprintf(stderr, __VA_ARGS__); }
+
 #ifdef THREAD_CRASH
 #define DO_THREAD_CRASH do { *((int *)(0)) = 1; } while(0)
 #endif
@@ -72,7 +76,7 @@
 #include <stdio.h>
 #include <unistd.h>
 
-#define AST_MUTEX_INIT_VALUE      { PTHREAD_MUTEX_INIT_VALUE, NULL, 0, 0, NULL, 0 }
+#define AST_MUTEX_INIT_VALUE { PTHREAD_MUTEX_INIT_VALUE, NULL, 0, 0, NULL, 0 }
 
 struct ast_mutex_info {
 	pthread_mutex_t mutex;
@@ -90,67 +94,73 @@ static inline int __ast_pthread_mutex_init_attr(const char *filename, int lineno
 						pthread_mutexattr_t *attr) 
 {
 #ifdef AST_MUTEX_INIT_W_CONSTRUCTORS
-	if ((t->mutex) != ((pthread_mutex_t)PTHREAD_MUTEX_INITIALIZER)) {
-		fprintf(stderr, "%s line %d (%s): Error: mutex '%s' is already initialized.\n",
-			filename, lineno, func, mutex_name);
-		fprintf(stderr, "%s line %d (%s): Error: previously initialization of mutex '%s'.\n",
-			t->file, t->lineno, t->func, mutex_name);
+	int canlog = strcmp(filename, "logger.c");
+
+	if ((t->mutex) != ((pthread_mutex_t) PTHREAD_MUTEX_INITIALIZER)) {
+		__ast_mutex_logger("%s line %d (%s): Error: mutex '%s' is already initialized.\n",
+				   filename, lineno, func, mutex_name);
+		__ast_mutex_logger("%s line %d (%s): Error: previously initialization of mutex '%s'.\n",
+				   t->file, t->lineno, t->func, mutex_name);
 #ifdef THREAD_CRASH
 		DO_THREAD_CRASH;
 #endif
 		return 0;
 	}
 #endif
+
 	t->file = filename;
 	t->lineno = lineno;
 	t->func = func;
 	t->thread  = 0;
 	t->reentrancy = 0;
+
 	return pthread_mutex_init(&t->mutex, attr);
 }
 
 static inline int __ast_pthread_mutex_init(const char *filename, int lineno, const char *func,
-						const char *mutex_name, ast_mutex_t *t)
+					   const char *mutex_name, ast_mutex_t *t)
 {
 	static pthread_mutexattr_t  attr;
+
 	pthread_mutexattr_init(&attr);
 	pthread_mutexattr_settype(&attr, AST_MUTEX_KIND);
+
 	return __ast_pthread_mutex_init_attr(filename, lineno, func, mutex_name, t, &attr);
 }
 
-#define ast_mutex_init(pmutex) __ast_pthread_mutex_init(__FILE__, __LINE__, __PRETTY_FUNCTION__, #pmutex, pmutex)
-#define ast_pthread_mutex_init(pmutex,attr) __ast_pthread_mutex_init_attr(__FILE__, __LINE__, __PRETTY_FUNCTION__, #pmutex, pmutex, attr)
-
 static inline int __ast_pthread_mutex_destroy(const char *filename, int lineno, const char *func,
 						const char *mutex_name, ast_mutex_t *t)
 {
 	int res;
+	int canlog = strcmp(filename, "logger.c");
+
 #ifdef AST_MUTEX_INIT_W_CONSTRUCTORS
-	if ((t->mutex) == ((pthread_mutex_t)PTHREAD_MUTEX_INITIALIZER)) {
-		fprintf(stderr, "%s line %d (%s): Error: mutex '%s' is uninitialized.\n",
-			filename, lineno, func, mutex_name);
+	if ((t->mutex) == ((pthread_mutex_t) PTHREAD_MUTEX_INITIALIZER)) {
+		__ast_mutex_logger("%s line %d (%s): Error: mutex '%s' is uninitialized.\n",
+				   filename, lineno, func, mutex_name);
 	}
 #endif
+
 	res = pthread_mutex_trylock(&t->mutex);
 	switch (res) {
 	case 0:
 		pthread_mutex_unlock(&t->mutex);
 		break;
 	case EINVAL:
-		fprintf(stderr, "%s line %d (%s): Error: attempt to destroy invalid mutex '%s'.\n",
-			filename, lineno, func, mutex_name);
+		__ast_mutex_logger("%s line %d (%s): Error: attempt to destroy invalid mutex '%s'.\n",
+				  filename, lineno, func, mutex_name);
 		break;
 	case EBUSY:
-		fprintf(stderr, "%s line %d (%s): Error: attemp to destroy locked mutex '%s'.\n",
-			filename, lineno, func, mutex_name);
-		fprintf(stderr, "%s line %d (%s): Error: '%s' was locked here.\n",
-			t->file, t->lineno, t->func, mutex_name);
+		__ast_mutex_logger("%s line %d (%s): Error: attempt to destroy locked mutex '%s'.\n",
+				   filename, lineno, func, mutex_name);
+		__ast_mutex_logger("%s line %d (%s): Error: '%s' was locked here.\n",
+				   t->file, t->lineno, t->func, mutex_name);
 		break;
 	}
-	res = pthread_mutex_destroy(&t->mutex);
-	if (res) 
-		fprintf(stderr, "%s line %d (%s): Error destroying mutex: %s\n",
-				filename, lineno, func, strerror(res));
+
+	if ((res = pthread_mutex_destroy(&t->mutex)))
+		__ast_mutex_logger("%s line %d (%s): Error destroying mutex: %s\n",
+				   filename, lineno, func, strerror(res));
 #ifndef PTHREAD_RECURSIVE_MUTEX_INITIALIZER_NP
 	else
 		t->mutex = PTHREAD_MUTEX_INIT_VALUE;
@@ -158,11 +168,10 @@ static inline int __ast_pthread_mutex_destroy(const char *filename, int lineno,
 	t->file = filename;
 	t->lineno = lineno;
 	t->func = func;
+
 	return res;
 }
 
-#define ast_mutex_destroy(a) __ast_pthread_mutex_destroy(__FILE__, __LINE__, __PRETTY_FUNCTION__, #a, a)
-
 #if defined(AST_MUTEX_INIT_W_CONSTRUCTORS)
 /* if AST_MUTEX_INIT_W_CONSTRUCTORS is defined, use file scope
  constrictors/destructors to create/destroy mutexes.  */
@@ -190,21 +199,22 @@ static void  __attribute__ ((destructor)) fini_##mutex(void) \
 	scope ast_mutex_t mutex = AST_MUTEX_INIT_VALUE
 #endif /* AST_MUTEX_INIT_W_CONSTRUCTORS */
 
-
-
 static inline int __ast_pthread_mutex_lock(const char *filename, int lineno, const char *func,
                                            const char* mutex_name, ast_mutex_t *t)
 {
 	int res;
+	int canlog = strcmp(filename, "logger.c");
+
 #if defined(AST_MUTEX_INIT_W_CONSTRUCTORS) || defined(AST_MUTEX_INIT_ON_FIRST_USE)
-	if ((t->mutex) == ((pthread_mutex_t)PTHREAD_MUTEX_INITIALIZER)) {
+	if ((t->mutex) == ((pthread_mutex_t) PTHREAD_MUTEX_INITIALIZER)) {
 #ifdef AST_MUTEX_INIT_W_CONSTRUCTORS
-		fprintf(stderr, "%s line %d (%s): Error: mutex '%s' is uninitialized.\n",
-			filename, lineno, func, mutex_name);
+		ast_mutex_logger("%s line %d (%s): Error: mutex '%s' is uninitialized.\n",
+				 filename, lineno, func, mutex_name);
 #endif
 		ast_mutex_init(t);
 	}
-#endif /* definded(AST_MUTEX_INIT_W_CONSTRUCTORS) || defined(AST_MUTEX_INIT_ON_FIRST_USE) */
+#endif /* defined(AST_MUTEX_INIT_W_CONSTRUCTORS) || defined(AST_MUTEX_INIT_ON_FIRST_USE) */
+
 #ifdef DETECT_DEADLOCKS
 	{
 		time_t seconds = time(NULL);
@@ -214,10 +224,10 @@ static inline int __ast_pthread_mutex_lock(const char *filename, int lineno, con
 			if (res == EBUSY) {
 				current = time(NULL);
 				if ((current - seconds) && (!((current - seconds) % 5))) {
-					fprintf(stderr, "%s line %d (%s): Deadlock? waited %d sec for mutex '%s'?\n",
-						filename, lineno, func, (int)(current - seconds), mutex_name);
-					fprintf(stderr, "%s line %d (%s): '%s' was locked here.\n",
-						t->file, t->lineno, t->func, mutex_name);
+					__ast_mutex_logger("%s line %d (%s): Deadlock? waited %d sec for mutex '%s'?\n",
+							   filename, lineno, func, (int)(current - seconds), mutex_name);
+					__ast_mutex_logger("%s line %d (%s): '%s' was locked here.\n",
+							   t->file, t->lineno, t->func, mutex_name);
 				}
 				usleep(200);
 			}
@@ -225,7 +235,8 @@ static inline int __ast_pthread_mutex_lock(const char *filename, int lineno, con
 	}
 #else
 	res = pthread_mutex_lock(&t->mutex);
-#endif /*  DETECT_DEADLOCKS */
+#endif /* DETECT_DEADLOCKS */
+
 	if (!res) {
 		t->reentrancy++;
 		t->file = filename;
@@ -233,87 +244,206 @@ static inline int __ast_pthread_mutex_lock(const char *filename, int lineno, con
 		t->func = func;
 		t->thread = pthread_self();
 	} else {
-		fprintf(stderr, "%s line %d (%s): Error obtaining mutex: %s\n",
-			filename, lineno, func, strerror(errno));
+		__ast_mutex_logger("%s line %d (%s): Error obtaining mutex: %s\n",
+				   filename, lineno, func, strerror(errno));
 #ifdef THREAD_CRASH
 		DO_THREAD_CRASH;
 #endif
 	}
+
 	return res;
 }
 
-#define ast_mutex_lock(a) __ast_pthread_mutex_lock(__FILE__, __LINE__, __PRETTY_FUNCTION__, #a, a)
-
 static inline int __ast_pthread_mutex_trylock(const char *filename, int lineno, const char *func,
                                               const char* mutex_name, ast_mutex_t *t)
 {
 	int res;
+
 #if defined(AST_MUTEX_INIT_W_CONSTRUCTORS) || defined(AST_MUTEX_INIT_ON_FIRST_USE)
-	if ((t->mutex) == ((pthread_mutex_t)PTHREAD_MUTEX_INITIALIZER)) {
+	if ((t->mutex) == ((pthread_mutex_t) PTHREAD_MUTEX_INITIALIZER)) {
 #ifdef AST_MUTEX_INIT_W_CONSTRUCTORS
-		fprintf(stderr, "%s line %d (%s): Error: mutex '%s' is uninitialized.\n",
-			filename, lineno, func, mutex_name);
+		int canlog = strcmp(filename, "logger.c");
+
+		__ast_mutex_logger("%s line %d (%s): Error: mutex '%s' is uninitialized.\n",
+				   filename, lineno, func, mutex_name);
 #endif
 		ast_mutex_init(t);
 	}
-#endif /* definded(AST_MUTEX_INIT_W_CONSTRUCTORS) || defined(AST_MUTEX_INIT_ON_FIRST_USE) */
-	res = pthread_mutex_trylock(&t->mutex);
-	if (!res) {
+#endif /* defined(AST_MUTEX_INIT_W_CONSTRUCTORS) || defined(AST_MUTEX_INIT_ON_FIRST_USE) */
+
+	if (!(res = pthread_mutex_trylock(&t->mutex))) {
 		t->reentrancy++;
 		t->file = filename;
 		t->lineno = lineno;
 		t->func = func;
 		t->thread = pthread_self();
 	}
+
 	return res;
 }
 
-#define ast_mutex_trylock(a) __ast_pthread_mutex_trylock(__FILE__, __LINE__, __PRETTY_FUNCTION__, #a, a)
-
 static inline int __ast_pthread_mutex_unlock(const char *filename, int lineno, const char *func,
-			const char *mutex_name, ast_mutex_t *t) {
+					     const char *mutex_name, ast_mutex_t *t)
+{
 	int res;
+	int canlog = strcmp(filename, "logger.c");
+
 #ifdef AST_MUTEX_INIT_W_CONSTRUCTORS
-	if ((t->mutex) == ((pthread_mutex_t)PTHREAD_MUTEX_INITIALIZER)) {
-		fprintf(stderr, "%s line %d (%s): Error: mutex '%s' is uninitialized.\n",
-			filename, lineno, func, mutex_name);
+	if ((t->mutex) == ((pthread_mutex_t) PTHREAD_MUTEX_INITIALIZER)) {
+		__ast_mutex_logger("%s line %d (%s): Error: mutex '%s' is uninitialized.\n",
+				   filename, lineno, func, mutex_name);
 	}
 #endif
-	--t->reentrancy;
-	if (t->reentrancy < 0) {
-		fprintf(stderr, "%s line %d (%s): mutex '%s' freed more times than we've locked!\n",
-			filename, lineno, func, mutex_name);
+
+	if (t->thread != pthread_self()) {
+		__ast_mutex_logger("%s line %d (%s): attempted unlock mutex '%s' without owning it!\n",
+				   filename, lineno, func, mutex_name);
+		__ast_mutex_logger("%s line %d (%s): '%s' was locked here.\n",
+				   t->file, t->lineno, t->func, mutex_name);
+#ifdef THREAD_CRASH
+		DO_THREAD_CRASH;
+#endif
+	}
+
+	if (--t->reentrancy < 0) {
+		__ast_mutex_logger("%s line %d (%s): mutex '%s' freed more times than we've locked!\n",
+				   filename, lineno, func, mutex_name);
 		t->reentrancy = 0;
 	}
+
 	if (!t->reentrancy) {
 		t->file = NULL;
 		t->lineno = 0;
 		t->func = NULL;
 		t->thread = 0;
 	}
-	res = pthread_mutex_unlock(&t->mutex);
-	if (res) {
-		fprintf(stderr, "%s line %d (%s): Error releasing mutex: %s\n", 
-				filename, lineno, func, strerror(res));
+
+	if ((res = pthread_mutex_unlock(&t->mutex))) {
+		__ast_mutex_logger("%s line %d (%s): Error releasing mutex: %s\n", 
+				   filename, lineno, func, strerror(res));
 #ifdef THREAD_CRASH
 		DO_THREAD_CRASH;
 #endif
 	}
+
 	return res;
 }
 
-static inline int ast_pthread_cond_wait(pthread_cond_t *cond, ast_mutex_t *ast_mutex)
+static inline int __ast_pthread_cond_wait(const char *filename, int lineno, const char *func,
+					  pthread_cond_t *cond, const char *mutex_name, ast_mutex_t *t)
 {
-	return pthread_cond_wait(cond, &ast_mutex->mutex);
+	int res;
+	int canlog = strcmp(filename, "logger.c");
+
+#ifdef AST_MUTEX_INIT_W_CONSTRUCTORS
+	if ((t->mutex) == ((pthread_mutex_t) PTHREAD_MUTEX_INITIALIZER)) {
+		__ast_mutex_logger("%s line %d (%s): Error: mutex '%s' is uninitialized.\n",
+				   filename, lineno, func, mutex_name);
+	}
+#endif
+
+	if (t->thread != pthread_self()) {
+		__ast_mutex_logger("%s line %d (%s): attempted unlock mutex '%s' without owning it!\n",
+				   filename, lineno, func, mutex_name);
+		__ast_mutex_logger("%s line %d (%s): '%s' was locked here.\n",
+				   t->file, t->lineno, t->func, mutex_name);
+#ifdef THREAD_CRASH
+		DO_THREAD_CRASH;
+#endif
+	}
+
+	if (--t->reentrancy < 0) {
+		__ast_mutex_logger("%s line %d (%s): mutex '%s' freed more times than we've locked!\n",
+				   filename, lineno, func, mutex_name);
+		t->reentrancy = 0;
+	}
+
+	if (!t->reentrancy) {
+		t->file = NULL;
+		t->lineno = 0;
+		t->func = NULL;
+		t->thread = 0;
+	}
+
+	if ((res = pthread_cond_wait(cond, &t->mutex))) {
+		__ast_mutex_logger("%s line %d (%s): Error waiting on condition mutex '%s'\n", 
+				   filename, lineno, func, strerror(res));
+#ifdef THREAD_CRASH
+		DO_THREAD_CRASH;
+#endif
+	} else {
+		t->reentrancy++;
+		t->file = filename;
+		t->lineno = lineno;
+		t->func = func;
+		t->thread = pthread_self();
+	}
+
+	return res;
 }
 
-static inline int ast_pthread_cond_timedwait(pthread_cond_t *cond, ast_mutex_t *ast_mutex,
-					     const struct timespec *abstime)
+static inline int __ast_pthread_cond_timedwait(const char *filename, int lineno, const char *func,
+					       pthread_cond_t *cond, const struct timespec *abstime,
+					       const char *mutex_name, ast_mutex_t *t)
 {
-	return pthread_cond_timedwait(cond, &ast_mutex->mutex, abstime);
+	int res;
+	int canlog = strcmp(filename, "logger.c");
+
+#ifdef AST_MUTEX_INIT_W_CONSTRUCTORS
+	if ((t->mutex) == ((pthread_mutex_t) PTHREAD_MUTEX_INITIALIZER)) {
+		__ast_mutex_logger("%s line %d (%s): Error: mutex '%s' is uninitialized.\n",
+				   filename, lineno, func, mutex_name);
+	}
+#endif
+
+	if (t->thread != pthread_self()) {
+		__ast_mutex_logger("%s line %d (%s): attempted unlock mutex '%s' without owning it!\n",
+				   filename, lineno, func, mutex_name);
+		__ast_mutex_logger("%s line %d (%s): '%s' was locked here.\n",
+				   t->file, t->lineno, t->func, mutex_name);
+#ifdef THREAD_CRASH
+		DO_THREAD_CRASH;
+#endif
+	}
+
+	if (--t->reentrancy < 0) {
+		__ast_mutex_logger("%s line %d (%s): mutex '%s' freed more times than we've locked!\n",
+				   filename, lineno, func, mutex_name);
+		t->reentrancy = 0;
+	}
+
+	if (!t->reentrancy) {
+		t->file = NULL;
+		t->lineno = 0;
+		t->func = NULL;
+		t->thread = 0;
+	}
+
+	if ((res = pthread_cond_timedwait(cond, &t->mutex, abstime))) {
+		__ast_mutex_logger("%s line %d (%s): Error waiting on condition mutex '%s'\n", 
+				   filename, lineno, func, strerror(res));
+#ifdef THREAD_CRASH
+		DO_THREAD_CRASH;
+#endif
+	} else {
+		t->reentrancy++;
+		t->file = filename;
+		t->lineno = lineno;
+		t->func = func;
+		t->thread = pthread_self();
+	}
+
+	return res;
 }
 
+#define ast_mutex_init(pmutex) __ast_pthread_mutex_init(__FILE__, __LINE__, __PRETTY_FUNCTION__, #pmutex, pmutex)
+#define ast_pthread_mutex_init(pmutex,attr) __ast_pthread_mutex_init_attr(__FILE__, __LINE__, __PRETTY_FUNCTION__, #pmutex, pmutex, attr)
+#define ast_mutex_destroy(a) __ast_pthread_mutex_destroy(__FILE__, __LINE__, __PRETTY_FUNCTION__, #a, a)
+#define ast_mutex_lock(a) __ast_pthread_mutex_lock(__FILE__, __LINE__, __PRETTY_FUNCTION__, #a, a)
 #define ast_mutex_unlock(a) __ast_pthread_mutex_unlock(__FILE__, __LINE__, __PRETTY_FUNCTION__, #a, a)
+#define ast_mutex_trylock(a) __ast_pthread_mutex_trylock(__FILE__, __LINE__, __PRETTY_FUNCTION__, #a, a)
+#define ast_pthread_cond_wait(cond, a) __ast_pthread_cond_wait(__FILE__, __LINE__, __PRETTY_FUNCTION__, cond, #a, a)
+#define ast_pthread_cond_timedwait(cond, a, t) __ast_pthread_cond_timedwait(__FILE__, __LINE__, __PRETTY_FUNCTION__, cond, t, #a, a)
 
 #define pthread_mutex_t use_ast_mutex_t_instead_of_pthread_mutex_t
 #define pthread_mutex_lock use_ast_mutex_lock_instead_of_pthread_mutex_lock
diff --git a/logger.c b/logger.c
index be3b8c176..b06efb06b 100755
--- a/logger.c
+++ b/logger.c
@@ -29,15 +29,6 @@
 
 ASTERISK_FILE_VERSION(__FILE__, "$Revision$")
 
-#include "asterisk/lock.h"
-#include "asterisk/options.h"
-#include "asterisk/channel.h"
-#include "asterisk/config.h"
-#include "asterisk/term.h"
-#include "asterisk/cli.h"
-#include "asterisk/utils.h"
-#include "asterisk/manager.h"
-
 static int syslog_level_map[] = {
 	LOG_DEBUG,
 	LOG_INFO,    /* arbitrary equivalent of LOG_EVENT */
@@ -51,6 +42,14 @@ static int syslog_level_map[] = {
 #define SYSLOG_NLEVELS 6
 
 #include "asterisk/logger.h"
+#include "asterisk/lock.h"
+#include "asterisk/options.h"
+#include "asterisk/channel.h"
+#include "asterisk/config.h"
+#include "asterisk/term.h"
+#include "asterisk/cli.h"
+#include "asterisk/utils.h"
+#include "asterisk/manager.h"
 
 #define MAX_MSG_QUEUE 200