more improvements and bug fixes

2 files changed, 175 insertions, 43 deletions

diff --git a/debug.c b/debug.c
index f21320b1..1ccb3d60 100644
--- a/debug.c
+++ b/debug.c
@@ -52,9 +52,11 @@ int	Debug;		/* debug flag  - read-only after startup */
 int debugging_on = 0;	 /* read-only, except on sig USR1 */
 static int bLogFuncFlow = 0; /* shall the function entry and exit be logged to the debug log? */
 static int bPrintFuncDBOnExit = 0; /* shall the function entry and exit be logged to the debug log? */
-
+static char *pszAltDbgFileName = "/home/rger/proj/rsyslog/log"; /* if set, debug output is *also* sent to here */
+static FILE *altdbg;	/* and the handle for alternate debug output */
 static FILE *stddbg;
 
+
 /* list of all known FuncDBs. We use a special list, because it must only be single-linked. As
  * functions never disappear, we only need to add elements when we see a new one and never need
  * to remove anything. For this, we simply add at the top, which saves us a Last pointer. The goal
@@ -143,6 +145,8 @@ static void dbgMutexCancelCleanupHdlr(void *pmut)
 
 /* ------------------------- FuncDB utility functions ------------------------- */ 
 
+#define SIZE_FUNCDB_MUTEX_TABLE(pFuncDB) ((int) (sizeof(pFuncDB->mutInfo) / sizeof(dbgFuncDBmutInfoEntry_t)))
+
 /* print a FuncDB
  */
 static void dbgFuncDBPrint(dbgFuncDB_t *pFuncDB)
@@ -169,6 +173,96 @@ static void dbgFuncDBPrintAll(void)
 	dbgprintf("%d unique functions called\n", nFuncs);
 }
 
+
+/* find a mutex inside the FuncDB mutex table. Returns NULL if not found. Only mutexes from the same thread
+ * are found.
+ */
+static inline dbgFuncDBmutInfoEntry_t *dbgFuncDBGetMutexInfo(dbgFuncDB_t *pFuncDB, pthread_mutex_t *pmut)
+{
+	int i;
+	int iFound = -1;
+	pthread_t ourThrd = pthread_self();
+
+	for(i = 0 ; i < SIZE_FUNCDB_MUTEX_TABLE(pFuncDB) ; ++i) {
+		if(pFuncDB->mutInfo[i].pmut == pmut && pFuncDB->mutInfo[i].lockLn != -1 && pFuncDB->mutInfo[i].thrd == ourThrd) {
+			iFound = i;
+			break;
+		}
+	}
+	
+	return (iFound == -1) ?  NULL : &pFuncDB->mutInfo[i];
+}
+
+
+/* print any mutex that can be found in the FuncDB. Custom header is provided.
+ * "thrd" is the thread that is searched. If it is 0, mutexes for all threads
+ * shall be printed.
+ */
+static inline void
+dbgFuncDBPrintActiveMutexes(dbgFuncDB_t *pFuncDB, char *pszHdrText, pthread_t thrd)
+{
+	int i;
+	char pszThrdName[64];
+
+	for(i = 0 ; i < SIZE_FUNCDB_MUTEX_TABLE(pFuncDB) ; ++i) {
+		if(pFuncDB->mutInfo[i].lockLn != -1 && (thrd == 0 || thrd == pFuncDB->mutInfo[i].thrd)) {
+			dbgGetThrdName(pszThrdName, sizeof(pszThrdName), pFuncDB->mutInfo[i].thrd, 1);
+			dbgprintf("%s:%d:%s:invocation %ld: %s %p[%d/%s]\n", pFuncDB->file, pFuncDB->line, pFuncDB->func,
+				  pFuncDB->mutInfo[i].lInvocation, pszHdrText, (void*)pFuncDB->mutInfo[i].pmut, i,
+				  pszThrdName);
+		}
+	}
+}
+
+/* find a free mutex info spot in FuncDB. NULL is returned if table is full.
+ */
+static inline dbgFuncDBmutInfoEntry_t *dbgFuncDBFindFreeMutexInfo(dbgFuncDB_t *pFuncDB)
+{
+	int i;
+	int iFound = -1;
+
+	for(i = 0 ; i < SIZE_FUNCDB_MUTEX_TABLE(pFuncDB) ; ++i) {
+		if(pFuncDB->mutInfo[i].lockLn == -1) {
+			iFound = i;
+			break;
+		}
+	}
+
+	if(iFound == -1) {
+		dbgprintf("%s:%d:%s: INFO: out of space in FuncDB for mutex info (max %d entries) - ignoring\n",
+			  pFuncDB->file, pFuncDB->line, pFuncDB->func, SIZE_FUNCDB_MUTEX_TABLE(pFuncDB));
+	}
+	
+	return (iFound == -1) ?  NULL : &pFuncDB->mutInfo[i];
+}
+
+/* add a mutex lock to the FuncDB. If the size is exhausted, info is discarded.
+ */
+static inline void dbgFuncDBAddMutexLock(dbgFuncDB_t *pFuncDB, pthread_mutex_t *pmut, int lockLn)
+{
+	dbgFuncDBmutInfoEntry_t *pMutInfo;
+
+	if((pMutInfo = dbgFuncDBFindFreeMutexInfo(pFuncDB)) != NULL) {
+		pMutInfo->pmut = pmut;
+		pMutInfo->lockLn = lockLn;
+		pMutInfo->lInvocation = pFuncDB->nTimesCalled;
+		pMutInfo->thrd = pthread_self();
+	}
+}
+
+/* remove a locked mutex from the FuncDB (unlock case!).
+ */
+static inline void dbgFuncDBRemoveMutexLock(dbgFuncDB_t *pFuncDB, pthread_mutex_t *pmut)
+{
+	dbgFuncDBmutInfoEntry_t *pMutInfo;
+
+	if((pMutInfo = dbgFuncDBGetMutexInfo(pFuncDB, pmut)) != NULL) {
+		pMutInfo->lockLn = -1;
+	}
+//dbgprintf("dbgFuncDB mutex to be removed %p, ptr found %p, lockLn %d\n", pmut, pMutInfo, (pMutInfo == 0) ? 123456789 : pMutInfo->lockLn);
+}
+
+
 /* ------------------------- END FuncDB utility functions ------------------------- */ 
 
 /* ###########################################################################
@@ -264,7 +358,6 @@ dbgMutLog_t *dbgMutLogFindSpecific(pthread_mutex_t *pmut, short mutop, dbgFuncDB
 	
 	pLog = dbgMutLogListLast;
 	while(pLog != NULL) {
-
 		if(   pLog->mut == pmut && pLog->thrd == mythrd && pLog->mutexOp == mutop
 		   && (pFuncDB == NULL || pLog->pFuncDB == pFuncDB))
 			break;
@@ -289,8 +382,6 @@ dbgMutLog_t *dbgMutLogFindFromBack(pthread_mutex_t *pmut, dbgMutLog_t *pLast)
 		if(pLog->mut == pmut) {
 			break;
 		}
-//RUNLOG_VAR("%p", pLog);
-//RUNLOG_VAR("%p", pLog->pPrev);
 		pLog = pLog->pPrev;
 	}
 
@@ -307,8 +398,6 @@ dbgMutLog_t *dbgMutLogFindHolder(pthread_mutex_t *pmut)
 	while(pLog != NULL) {
 		if(pLog->mutexOp == MUTOP_LOCK)
 			break;
-//RUNLOG_VAR("%p", pLog);
-//RUNLOG_VAR("%p", pLog->pPrev);
 		pLog = dbgMutLogFindFromBack(pmut, pLog);
 	}
 
@@ -316,7 +405,7 @@ dbgMutLog_t *dbgMutLogFindHolder(pthread_mutex_t *pmut)
 }
 
 /* report wait on a mutex and add it to the mutex log */
-static inline void dbgMutexPreLockLog(pthread_mutex_t *pmut, dbgFuncDB_t *pFuncDB)
+static inline void dbgMutexPreLockLog(pthread_mutex_t *pmut, dbgFuncDB_t *pFuncDB, int ln)
 {
 	dbgMutLog_t *pHolder;
 	dbgMutLog_t *pLog;
@@ -324,15 +413,10 @@ static inline void dbgMutexPreLockLog(pthread_mutex_t *pmut, dbgFuncDB_t *pFuncD
 	char pszHolderThrdName[64];
 	char *pszHolder;
 
-//RUNLOG;
 	pthread_mutex_lock(&mutMutLog);
-//dbgprintf("dbgMutexPreLockLog mutMutLog aquired\n");
-//RUNLOG;
 	pHolder = dbgMutLogFindHolder(pmut);
-//RUNLOG;
 	pLog = dbgMutLogAddEntry(pmut, MUTOP_LOCKWAIT, pFuncDB);
 
-//RUNLOG;
 	if(pHolder == NULL)
 		pszHolder = "[NONE]";
 	else {
@@ -341,82 +425,103 @@ static inline void dbgMutexPreLockLog(pthread_mutex_t *pmut, dbgFuncDB_t *pFuncD
 		pszHolder = pszBuf;
 	}
 
-	dbgprintf("%s:%d:%s: mutex %p waiting on lock, held by %s\n", pFuncDB->file, pFuncDB->line, pFuncDB->func, (void*)pmut, pszHolder);
+	dbgprintf("%s:%d:%s: mutex %p waiting on lock, held by %s\n", pFuncDB->file, ln, pFuncDB->func, (void*)pmut, pszHolder);
 	pthread_mutex_unlock(&mutMutLog);
 }
 
 
 /* report aquired mutex */
-static inline void dbgMutexLockLog(pthread_mutex_t *pmut, dbgFuncDB_t *pFuncDB)
+static inline void dbgMutexLockLog(pthread_mutex_t *pmut, dbgFuncDB_t *pFuncDB, int lockLn)
 {
 	dbgMutLog_t *pLog;
 
 	pthread_mutex_lock(&mutMutLog);
+
+	/* find and delete "waiting" entry */
 	pLog = dbgMutLogFindSpecific(pmut, MUTOP_LOCKWAIT, pFuncDB);
 	assert(pLog != NULL);
 	dbgMutLogDelEntry(pLog);
+
+	/* add "lock" entry */
 	pLog = dbgMutLogAddEntry(pmut, MUTOP_LOCK, pFuncDB);
+	dbgFuncDBAddMutexLock(pFuncDB, pmut, lockLn);
 	pthread_mutex_unlock(&mutMutLog);
-	dbgprintf("%s:%d:%s: mutex %p aquired\n", pFuncDB->file, pFuncDB->line, pFuncDB->func, (void*)pmut); 
+	dbgprintf("%s:%d:%s: mutex %p aquired\n", pFuncDB->file, lockLn, pFuncDB->func, (void*)pmut); 
 }
 
 /* if we unlock, we just remove the lock aquired entry from the log list */
-static inline void dbgMutexUnlockLog(pthread_mutex_t *pmut, dbgFuncDB_t *pFuncDB)
+static inline void dbgMutexUnlockLog(pthread_mutex_t *pmut, dbgFuncDB_t *pFuncDB, int unlockLn)
 {
 	dbgMutLog_t *pLog;
 
 	pthread_mutex_lock(&mutMutLog);
 	pLog = dbgMutLogFindSpecific(pmut, MUTOP_LOCK, NULL);
 	assert(pLog != NULL);
+
+	/* we found the last lock entry. We now need to see from which FuncDB we need to
+	 * remove it. This is recorded inside the mutex log entry.
+	 */
+	dbgFuncDBRemoveMutexLock(pLog->pFuncDB, pmut);
+
+	/* donw with the log entry, get rid of it... */
 	dbgMutLogDelEntry(pLog);
+
 	pthread_mutex_unlock(&mutMutLog);
-	dbgprintf("%s:%d:%s: mutex %p UNlocked\n", pFuncDB->file, pFuncDB->line, pFuncDB->func, (void*)pmut);
+	dbgprintf("%s:%d:%s: mutex %p UNlocked\n", pFuncDB->file, unlockLn, pFuncDB->func, (void*)pmut);
 }
 
 
-int dbgMutexLock(pthread_mutex_t *pmut, dbgFuncDB_t *pFuncDB)
+/* wrapper for pthread_mutex_lock() */
+int dbgMutexLock(pthread_mutex_t *pmut, dbgFuncDB_t *pFuncDB, int ln)
 {
 	int ret;
 
-	dbgMutexPreLockLog(pmut, pFuncDB);
+	dbgMutexPreLockLog(pmut, pFuncDB, ln);
 	ret = pthread_mutex_lock(pmut);
+	if(ret == 0) {
+		dbgMutexLockLog(pmut, pFuncDB, ln);
+	} else {
+		dbgprintf("%s:%d:%s: ERROR: pthread_mutex_lock() for mutex %p failed with error %d (%s)\n",
+			  pFuncDB->file, ln, pFuncDB->func, (void*)pmut, ret, strerror(errno)); // TODO: remove strerror!"!!
+	}
 
-	dbgMutexLockLog(pmut, pFuncDB);
 	return ret;
 }
 
 
-int dbgMutexUnlock(pthread_mutex_t *pmut, dbgFuncDB_t *pFuncDB)
+/* wrapper for pthread_mutex_unlock() */
+int dbgMutexUnlock(pthread_mutex_t *pmut, dbgFuncDB_t *pFuncDB, int ln)
 {
 	int ret;
-	dbgMutexUnlockLog(pmut, pFuncDB);
+	dbgMutexUnlockLog(pmut, pFuncDB, ln);
 	ret = pthread_mutex_unlock(pmut);
 	return ret;
 }
 
 
-int dbgCondWait(pthread_cond_t *cond, pthread_mutex_t *pmut, dbgFuncDB_t *pFuncDB)
+/* wrapper for pthread_cond_wait() */
+int dbgCondWait(pthread_cond_t *cond, pthread_mutex_t *pmut, dbgFuncDB_t *pFuncDB, int ln)
 {
 	int ret;
-	dbgMutexUnlockLog(pmut, pFuncDB);
+	dbgMutexUnlockLog(pmut, pFuncDB, ln);
 	dbgprintf("%s:%d:%s: mutex %p waiting on condition %p\n", pFuncDB->file, pFuncDB->line, pFuncDB->func, (void*)pmut, (void*)cond);
-	dbgMutexPreLockLog(pmut, pFuncDB);
+	dbgMutexPreLockLog(pmut, pFuncDB, ln);
 	ret = pthread_cond_wait(cond, pmut);
-	dbgMutexLockLog(pmut, pFuncDB);
 	return ret;
 }
 
 
-int dbgCondTimedWait(pthread_cond_t *cond, pthread_mutex_t *pmut, const struct timespec *abstime, dbgFuncDB_t *pFuncDB)
+/* wrapper for pthread_cond_timedwait() */
+int dbgCondTimedWait(pthread_cond_t *cond, pthread_mutex_t *pmut, const struct timespec *abstime, dbgFuncDB_t *pFuncDB, int ln)
 {
 	int ret;
-	dbgMutexUnlockLog(pmut, pFuncDB);
-	dbgMutexPreLockLog(pmut, pFuncDB);
+	dbgMutexUnlockLog(pmut, pFuncDB, ln);
+	dbgMutexPreLockLog(pmut, pFuncDB, ln);
 	dbgprintf("%s:%d:%s: mutex %p waiting on condition %p (with timeout)\n", pFuncDB->file, pFuncDB->line, pFuncDB->func,
 		  (void*)pmut, (void*)cond);
 	ret = pthread_cond_timedwait(cond, pmut, abstime);
 RUNLOG;
-	dbgMutexLockLog(pmut, pFuncDB);
+	dbgMutexLockLog(pmut, pFuncDB, ln);
 	return ret;
 }
 
@@ -583,6 +688,8 @@ dbgprintf(char *fmt, ...)
 	static int bWasNL = 0;
 	va_list ap;
 	static char pszThrdName[64]; /* 64 is to be on the safe side, anything over 20 is bad... */
+	static char pszWriteBuf[1024];
+	size_t lenWriteBuf;
 
 	if(!(Debug && debugging_on))
 		return;
@@ -603,6 +710,7 @@ dbgprintf(char *fmt, ...)
 	if(ptLastThrdID != pthread_self()) {
 		if(!bWasNL) {
 			fprintf(stddbg, "\n");
+			if(altdbg != NULL) fprintf(altdbg, "\n");
 			bWasNL = 1;
 		}
 		ptLastThrdID = pthread_self();
@@ -615,13 +723,25 @@ dbgprintf(char *fmt, ...)
 
 	if(bWasNL) {
 		fprintf(stddbg, "%s: ", pszThrdName);
+		if(altdbg != NULL) fprintf(altdbg, "%s: ", pszThrdName);
 	}
 	bWasNL = (*(fmt + strlen(fmt) - 1) == '\n') ? 1 : 0;
 	va_start(ap, fmt);
-	vfprintf(stddbg, fmt, ap);
+	lenWriteBuf = vsnprintf(pszWriteBuf, sizeof(pszWriteBuf), fmt, ap);
+	if(lenWriteBuf >= sizeof(pszWriteBuf)) {
+		/* if our buffer was too small, we simply truncate. TODO: maybe something better? */
+		lenWriteBuf--;
+	}
 	va_end(ap);
+	/*
+	fprintf(stddbg, "%s", pszWriteBuf);
+	if(altdbg != NULL) fprintf(altdbg, "%s", pszWriteBuf);
+	*/
+	fwrite(pszWriteBuf, lenWriteBuf, 1, stddbg);
+	fwrite(pszWriteBuf, lenWriteBuf, 1, altdbg);
 
 	fflush(stddbg);
+	fflush(altdbg);
 	pthread_cleanup_pop(1);
 }
 
@@ -644,11 +764,12 @@ int dbgEntrFunc(dbgFuncDB_t *pFuncDB)
 	assert(pFuncDB->magic == dbgFUNCDB_MAGIC);
 
 	if(pFuncDB->nTimesCalled++ == 0) {
+		/* dbgprintf("%s:%d:%s: called first time, initializing FuncDB\n", pFuncDB->file, pFuncDB->line, pFuncDB->func); */
 		/* this is the first time we see this function, so let's fully initialize the FuncDB. Note
 		 * that partial initialization already occured via the initializer, as far as this could be
 		 * done (all static values have been set).
 		 */
-		for(i = 1 ; i < sizeof(pFuncDB->mutInfo)/sizeof(dbgFuncDBmutInfoEntry_t) ; ++i) {
+		for(i = 0 ; i < sizeof(pFuncDB->mutInfo)/sizeof(dbgFuncDBmutInfoEntry_t) ; ++i) {
 			pFuncDB->mutInfo[i].lockLn = -1; /* set to not Locked */
 		}
 		/* finally add element to list of FuncDBs */
@@ -668,7 +789,7 @@ int dbgEntrFunc(dbgFuncDB_t *pFuncDB)
 
 	if(bLogFuncFlow)
 		dbgprintf("%s:%d: %s: enter\n", pFuncDB->file, pFuncDB->line, pFuncDB->func);
-	if(pThrd->stackPtr >= (int) (sizeof(pThrd->callStack) / sizeof(dbgFuncDB_t))) {
+	if(pThrd->stackPtr >= (int) (sizeof(pThrd->callStack) / sizeof(dbgFuncDB_t*))) {
 		dbgprintf("%s:%d: %s: debug module: call stack for this thread full, suspending call tracking\n",
 			  pFuncDB->file, pFuncDB->line, pFuncDB->func);
 		iStackPtr = pThrd->stackPtr;
@@ -693,6 +814,7 @@ void dbgExitFunc(dbgFuncDB_t *pFuncDB, int iStackPtrRestore)
 	assert(pFuncDB != NULL);
 	assert(pFuncDB->magic == dbgFUNCDB_MAGIC);
 
+	dbgFuncDBPrintActiveMutexes(pFuncDB, "WARNING: mutex still owned by us as we exit function, mutex: ", pthread_self());
 	if(bLogFuncFlow)
 		dbgprintf("%s:%d: %s: exit\n", pFuncDB->file, pFuncDB->line, pFuncDB->func);
 	pThrd->stackPtr = iStackPtrRestore;
@@ -733,6 +855,13 @@ rsRetVal dbgClassInit(void)
 	sigaction(SIGUSR1, &sigAct, NULL);
 
 	stddbg = stdout;
+	if(pszAltDbgFileName != NULL) {
+		/* we have a secondary file, so let's open it) */
+		if((altdbg = fopen(pszAltDbgFileName, "w")) == NULL) {
+			fprintf(stderr, "alternate debug file could not be opened, ignoring. Error: %s\n", strerror(errno));
+		}
+	}
+
 	dbgSetThrdName((uchar*)"main thread");
 	return RS_RET_OK;
 }
@@ -741,6 +870,8 @@ rsRetVal dbgClassInit(void)
 rsRetVal dbgClassExit(void)
 {
 	pthread_key_delete(keyCallStack);
+	if(altdbg != NULL)
+		fclose(altdbg);
 	return RS_RET_OK;
 }
 /*
diff --git a/debug.h b/debug.h
index 08960a14..c25fd6f9 100644
--- a/debug.h
+++ b/debug.h
@@ -40,9 +40,10 @@ extern int debugging_on;	 /* read-only, except on sig USR1 */
  * rgerhards, 2008-01-24
  */
 typedef struct dbgFuncDBmutInfoEntry_s {
-	pthread_mutex_t mut;
+	pthread_mutex_t *pmut;
 	int lockLn; /* line where it was locked (inside our func): -1 means mutex is not locked */
-	unsigned long lIteration; /* iteration of this function that locked the mutex */
+	pthread_t thrd; /* thrd where the mutex was locked */
+	unsigned long lInvocation; /* invocation (unique during program run!) of this function that locked the mutex */
 } dbgFuncDBmutInfoEntry_t;
 typedef struct dbgFuncDB_s {
 	unsigned magic;
@@ -69,10 +70,10 @@ rsRetVal dbgClassInit(void);
 rsRetVal dbgClassExit(void);
 void sigsegvHdlr(int signum);
 void dbgprintf(char *fmt, ...) __attribute__((format(printf,1, 2)));
-int dbgMutexLock(pthread_mutex_t *pmut, dbgFuncDB_t *pFuncDB);
-int dbgMutexUnlock(pthread_mutex_t *pmut, dbgFuncDB_t *pFuncDB);
-int dbgCondWait(pthread_cond_t *cond, pthread_mutex_t *pmut, dbgFuncDB_t *pFuncDB);
-int dbgCondTimedWait(pthread_cond_t *cond, pthread_mutex_t *pmut, const struct timespec *abstime, dbgFuncDB_t *pFuncDB);
+int dbgMutexLock(pthread_mutex_t *pmut, dbgFuncDB_t *pFuncD, int lnB);
+int dbgMutexUnlock(pthread_mutex_t *pmut, dbgFuncDB_t *pFuncD, int lnB);
+int dbgCondWait(pthread_cond_t *cond, pthread_mutex_t *pmut, dbgFuncDB_t *pFuncD, int lnB);
+int dbgCondTimedWait(pthread_cond_t *cond, pthread_mutex_t *pmut, const struct timespec *abstime, dbgFuncDB_t *pFuncD, int lnB);
 int dbgEntrFunc(dbgFuncDB_t *pFuncDB);
 void dbgExitFunc(dbgFuncDB_t *pFuncDB, int iStackPtrRestore);
 void dbgSetThrdName(uchar *pszName);
@@ -102,10 +103,10 @@ void dbgPrintAllDebugInfo(void);
 
 /* debug aides */
 #if 1
-#define d_pthread_mutex_lock(x)     dbgMutexLock(x, &dbgFuncDB)
-#define d_pthread_mutex_unlock(x)   dbgMutexUnlock(x, &dbgFuncDB)
-#define d_pthread_cond_wait(cond, mut)   dbgCondWait(cond, mut, &dbgFuncDB)
-#define d_pthread_cond_timedwait(cond, mut, to)   dbgCondTimedWait(cond, mut, to, &dbgFuncDB)
+#define d_pthread_mutex_lock(x)     dbgMutexLock(x, &dbgFuncDB, __LINE__)
+#define d_pthread_mutex_unlock(x)   dbgMutexUnlock(x, &dbgFuncDB, __LINE__)
+#define d_pthread_cond_wait(cond, mut)   dbgCondWait(cond, mut, &dbgFuncDB, __LINE__)
+#define d_pthread_cond_timedwait(cond, mut, to)   dbgCondTimedWait(cond, mut, to, &dbgFuncDB, __LINE__)
 #else
 #define d_pthread_mutex_lock(x)     pthread_mutex_lock(x)
 #define d_pthread_mutex_unlock(x)   pthread_mutex_unlock(x)