cleaned up internal debug system code and made it behave better in regard to multi-threading

3 files changed, 89 insertions, 131 deletions

diff --git a/ChangeLog b/ChangeLog
index e2c7d5d4..7b35d660 100644
--- a/ChangeLog
+++ b/ChangeLog
@@ -18,6 +18,8 @@ Version 3.21.5  [DEVEL] (rgerhards), 2008-09-??
   believe that really caused problems, but in theory it could and with
   threading we often see that theory becomes practice if something is only
   used long enough on a fast enough machine with enough CPUs ;)
+- cleaned up internal debug system code and made it behave better
+  in regard to multi-threading
 ---------------------------------------------------------------------------
 Version 3.21.4  [DEVEL] (rgerhards), 2008-09-04
 - removed compile time fixed message size limit (was 2K), limit can now
diff --git a/runtime/debug.c b/runtime/debug.c
index 7ed1442b..15e9201b 100644
--- a/runtime/debug.c
+++ b/runtime/debug.c
@@ -43,6 +43,9 @@
 #include <pthread.h>
 #include <ctype.h>
 #include <assert.h>
+#include <unistd.h>
+#include <fcntl.h>
+#include <sys/stat.h>
 
 #include "rsyslog.h"
 #include "debug.h"
@@ -62,8 +65,8 @@ static int bPrintTime = 1;	/* print a timestamp together with debug message */
 static int bPrintAllDebugOnExit = 0;
 static int bAbortTrace = 1;	/* print a trace after SIGABRT or SIGSEGV */
 static char *pszAltDbgFileName = NULL; /* if set, debug output is *also* sent to here */
-static FILE *altdbg = NULL;	/* and the handle for alternate debug output */
-static FILE *stddbg;
+static int altdbg = -1;	/* and the handle for alternate debug output */
+static int stddbg;
 
 /* list of files/objects that should be printed */
 typedef struct dbgPrintName_s {
@@ -113,8 +116,7 @@ static dbgThrdInfo_t *dbgCallStackListRoot = NULL;
 static dbgThrdInfo_t *dbgCallStackListLast = NULL;
 static pthread_mutex_t mutCallStack;
 
-static pthread_mutex_t mutdbgprintf;
-static pthread_mutex_t mutdbgoprint;
+static pthread_mutex_t mutdbgprint;
 
 static pthread_key_t keyCallStack;
 
@@ -748,8 +750,6 @@ sigsegvHdlr(int signum)
 	}
 
 	dbgprintf("\n\nTo submit bug reports, visit http://www.rsyslog.com/bugs\n\n");
-	if(stddbg != NULL) fflush(stddbg);
-	if(altdbg != NULL) fflush(altdbg);
 
 	/* and finally abort... */
 	/* TODO: think about restarting rsyslog in this case: may be a good idea,
@@ -758,56 +758,36 @@ sigsegvHdlr(int signum)
 	abort();
 }
 
-
+#if 1
 #pragma GCC diagnostic ignored "-Wempty-body"
-/* print some debug output when an object is given
- * This is mostly a copy of dbgprintf, but I do not know how to combine it
- * into a single function as we have variable arguments and I don't know how to call
- * from one vararg function into another. I don't dig in this, it is OK for the
- * time being. -- rgerhards, 2008-01-29
+/* write the debug message. This is a helper to dbgprintf and dbgoprint which
+ * contains common code. added 2008-09-26 rgerhards
  */
-void
-dbgoprint(obj_t *pObj, char *fmt, ...)
+static void
+dbgprint(obj_t *pObj, char *pszMsg, size_t lenMsg)
 {
 	static pthread_t ptLastThrdID = 0;
 	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];
+	char pszThrdName[64]; /* 64 is to be on the safe side, anything over 20 is bad... */
+	char pszWriteBuf[1024];
 	size_t lenWriteBuf;
 	struct timespec t;
 
-	if(!(Debug && debugging_on))
-		return;
-	
-	/* a quick and very dirty hack to enable us to display just from those objects
-	 * that we are interested in. So far, this must be changed at compile time (and
-	 * chances are great it is commented out while you read it. Later, this shall
-	 * be selectable via the environment. -- rgerhards, 2008-02-20
-	 */
-#if 0
-	if(objGetObjID(pObj) != OBJexpr)
-		return;
-#endif
-
-
-	pthread_mutex_lock(&mutdbgoprint);
-	pthread_cleanup_push(dbgMutexCancelCleanupHdlr, &mutdbgoprint);
+	pthread_mutex_lock(&mutdbgprint);
+	pthread_cleanup_push(dbgMutexCancelCleanupHdlr, &mutdbgprint);
 
 	/* The bWasNL handler does not really work. It works if no thread
 	 * switching occurs during non-NL messages. Else, things are messed
 	 * up. Anyhow, it works well enough to provide useful help during
 	 * getting this up and running. It is questionable if the extra effort
-	 * is worth fixing it, giving the limited appliability.
-	 * rgerhards, 2005-10-25
+	 * is worth fixing it, giving the limited appliability. -- rgerhards, 2005-10-25
 	 * I have decided that it is not worth fixing it - especially as it works
-	 * pretty well.
-	 * rgerhards, 2007-06-15
+	 * pretty well. -- rgerhards, 2007-06-15
 	 */
 	if(ptLastThrdID != pthread_self()) {
 		if(!bWasNL) {
-			if(stddbg != NULL) fprintf(stddbg, "\n");
-			if(altdbg != NULL) fprintf(altdbg, "\n");
+			if(stddbg != -1) write(stddbg, "\n", 1);
+			if(altdbg != -1) write(altdbg, "\n", 1);
 			bWasNL = 1;
 		}
 		ptLastThrdID = pthread_self();
@@ -821,113 +801,82 @@ dbgoprint(obj_t *pObj, char *fmt, ...)
 	if(bWasNL) {
 		if(bPrintTime) {
 			clock_gettime(CLOCK_REALTIME, &t);
-			if(stddbg != NULL) fprintf(stddbg, "%4.4ld.%9.9ld:", (long) (t.tv_sec % 10000), t.tv_nsec);
-			if(altdbg != NULL) fprintf(altdbg, "%4.4ld.%9.9ld:", (long) (t.tv_sec % 10000), t.tv_nsec);
+			lenWriteBuf = snprintf(pszWriteBuf, sizeof(pszWriteBuf),
+				 	"%4.4ld.%9.9ld:", (long) (t.tv_sec % 10000), t.tv_nsec);
+			if(stddbg != -1) write(stddbg, pszWriteBuf, lenWriteBuf);
+			if(altdbg != -1) write(altdbg, pszWriteBuf, lenWriteBuf);
 		}
-		if(stddbg != NULL) fprintf(stddbg, "%s: ", pszThrdName);
-		if(altdbg != NULL) fprintf(altdbg, "%s: ", pszThrdName);
+		lenWriteBuf = snprintf(pszWriteBuf, sizeof(pszWriteBuf), "%s: ", pszThrdName);
+		if(stddbg != -1) write(stddbg, pszWriteBuf, lenWriteBuf);
+		if(altdbg != -1) write(altdbg, pszWriteBuf, lenWriteBuf);
 		/* print object name header if we have an object */
 		if(pObj != NULL) {
-			if(stddbg != NULL) fprintf(stddbg, "%s: ", obj.GetName(pObj));
-			if(altdbg != NULL) fprintf(altdbg, "%s: ", obj.GetName(pObj));
+			lenWriteBuf = snprintf(pszWriteBuf, sizeof(pszWriteBuf), "%s: ", obj.GetName(pObj));
+			if(stddbg != -1) write(stddbg, pszWriteBuf, lenWriteBuf);
+			if(altdbg != -1) write(altdbg, pszWriteBuf, lenWriteBuf);
 		}
 	}
-	bWasNL = (*(fmt + strlen(fmt) - 1) == '\n') ? 1 : 0;
+	if(stddbg != -1) write(stddbg, pszMsg, lenMsg);
+	if(altdbg != -1) write(altdbg, pszMsg, lenMsg);
+
+	bWasNL = (pszMsg[lenMsg - 1] == '\n') ? 1 : 0;
+
+	pthread_cleanup_pop(1);
+}
+#pragma GCC diagnostic warning "-Wempty-body"
+#endif
+
+/* print some debug output when an object is given
+ * This is mostly a copy of dbgprintf, but I do not know how to combine it
+ * into a single function as we have variable arguments and I don't know how to call
+ * from one vararg function into another. I don't dig in this, it is OK for the
+ * time being. -- rgerhards, 2008-01-29
+ */
+void
+dbgoprint(obj_t *pObj, char *fmt, ...)
+{
+	va_list ap;
+	char pszWriteBuf[1024];
+	size_t lenWriteBuf;
+
+	if(!(Debug && debugging_on))
+		return;
+	
+	/* a quick and very dirty hack to enable us to display just from those objects
+	 * that we are interested in. So far, this must be changed at compile time (and
+	 * chances are great it is commented out while you read it. Later, this shall
+	 * be selectable via the environment. -- rgerhards, 2008-02-20
+	 */
+#if 0
+	if(objGetObjID(pObj) != OBJexpr)
+		return;
+#endif
+
 	va_start(ap, fmt);
 	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 = sizeof(pszWriteBuf) - 1;
-	}
 	va_end(ap);
-	/*
-	if(stddbg != NULL) fprintf(stddbg, "%s", pszWriteBuf);
-	if(altdbg != NULL) fprintf(altdbg, "%s", pszWriteBuf);
-	*/
-	if(stddbg != NULL) fwrite(pszWriteBuf, lenWriteBuf, 1, stddbg);
-	if(altdbg != NULL) fwrite(pszWriteBuf, lenWriteBuf, 1, altdbg);
-
-	if(stddbg != NULL) fflush(stddbg);
-	if(altdbg != NULL) fflush(altdbg);
-	pthread_cleanup_pop(1);
+	dbgprint(pObj, pszWriteBuf, lenWriteBuf);
 }
-#pragma GCC diagnostic warning "-Wempty-body"
 
 
-#pragma GCC diagnostic ignored "-Wempty-body"
 /* print some debug output when no object is given
  * WARNING: duplicate code, see dbgoprin above!
  */
 void
 dbgprintf(char *fmt, ...)
 {
-	static pthread_t ptLastThrdID = 0;
-	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];
+	char pszWriteBuf[1024];
 	size_t lenWriteBuf;
-	struct timespec t;
 
 	if(!(Debug && debugging_on))
 		return;
 	
-	pthread_mutex_lock(&mutdbgprintf);
-	pthread_cleanup_push(dbgMutexCancelCleanupHdlr, &mutdbgprintf);
-
-	/* The bWasNL handler does not really work. It works if no thread
-	 * switching occurs during non-NL messages. Else, things are messed
-	 * up. Anyhow, it works well enough to provide useful help during
-	 * getting this up and running. It is questionable if the extra effort
-	 * is worth fixing it, giving the limited appliability.
-	 * rgerhards, 2005-10-25
-	 * I have decided that it is not worth fixing it - especially as it works
-	 * pretty well.
-	 * rgerhards, 2007-06-15
-	 */
-	if(ptLastThrdID != pthread_self()) {
-		if(!bWasNL) {
-			if(stddbg != NULL) fprintf(stddbg, "\n");
-			if(altdbg != NULL) fprintf(altdbg, "\n");
-			bWasNL = 1;
-		}
-		ptLastThrdID = pthread_self();
-	}
-
-	/* do not cache the thread name, as the caller might have changed it
-	 * TODO: optimized, invalidate cache when new name is set
-	 */
-	dbgGetThrdName(pszThrdName, sizeof(pszThrdName), ptLastThrdID, 0);
-
-	if(bWasNL) {
-		if(bPrintTime) {
-			clock_gettime(CLOCK_REALTIME, &t);
-			if(stddbg != NULL) fprintf(stddbg, "%4.4ld.%9.9ld:", (long) (t.tv_sec % 10000), t.tv_nsec);
-			if(altdbg != NULL) fprintf(altdbg, "%4.4ld.%9.9ld:", (long) (t.tv_sec % 10000), t.tv_nsec);
-		}
-		if(stddbg != NULL) fprintf(stddbg, "%s: ", pszThrdName);
-		if(altdbg != NULL) fprintf(altdbg, "%s: ", pszThrdName);
-	}
-	bWasNL = (*(fmt + strlen(fmt) - 1) == '\n') ? 1 : 0;
 	va_start(ap, fmt);
 	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 = sizeof(pszWriteBuf) - 1;
-	}
 	va_end(ap);
-	/*
-	if(stddbg != NULL) fprintf(stddbg, "%s", pszWriteBuf);
-	if(altdbg != NULL) fprintf(altdbg, "%s", pszWriteBuf);
-	*/
-	if(stddbg != NULL) fwrite(pszWriteBuf, lenWriteBuf, 1, stddbg);
-	if(altdbg != NULL) fwrite(pszWriteBuf, lenWriteBuf, 1, altdbg);
-
-	if(stddbg != NULL) fflush(stddbg);
-	if(altdbg != NULL) fflush(altdbg);
-	pthread_cleanup_pop(1);
+	dbgprint(NULL, pszWriteBuf, lenWriteBuf);
 }
-#pragma GCC diagnostic warning "-Wempty-body"
 
 void tester(void)
 {
@@ -941,7 +890,7 @@ ENDfunc
 int dbgEntrFunc(dbgFuncDB_t **ppFuncDB, const char *file, const char *func, int line)
 {
 	int iStackPtr = 0; /* TODO: find some better default, this one hurts the least, but it is not clean */
-	dbgThrdInfo_t *pThrd = dbgGetThrdInfo();
+	dbgThrdInfo_t *pThrd;
 	dbgFuncDBListEntry_t *pFuncDBListEntry;
 	unsigned int i;
 	dbgFuncDB_t *pFuncDB;
@@ -952,6 +901,8 @@ int dbgEntrFunc(dbgFuncDB_t **ppFuncDB, const char *file, const char *func, int
 	pFuncDB = *ppFuncDB;
 	assert((pFuncDB == NULL) || (pFuncDB->magic == dbgFUNCDB_MAGIC));
 
+	pThrd = dbgGetThrdInfo(); /* we must do this AFTER the mutexes are initialized! */
+
 	if(pFuncDB == NULL) {
 		/* we do not yet have a funcDB and need to create a new one. We also add it
 		 * to the linked list of funcDBs. Please note that when a module is unloaded and
@@ -1206,7 +1157,7 @@ dbgGetRuntimeOptions(void)
 	uchar *optname;
 
 	/* set some defaults */
-	stddbg = stdout;
+	stddbg = 1;
 
 	if((pszOpts = (uchar*) getenv("RSYSLOG_DEBUG")) != NULL) {
 		/* we have options set, so let's process them */
@@ -1248,7 +1199,7 @@ dbgGetRuntimeOptions(void)
 			} else if(!strcasecmp((char*)optname, "nologtimestamp")) {
 				bPrintTime = 0;
 			} else if(!strcasecmp((char*)optname, "nostdout")) {
-				stddbg = NULL;
+				stddbg = -1;
 			} else if(!strcasecmp((char*)optname, "noaborttrace")) {
 				bAbortTrace = 0;
 			} else if(!strcasecmp((char*)optname, "filetrace")) {
@@ -1273,7 +1224,7 @@ dbgGetRuntimeOptions(void)
 
 rsRetVal dbgClassInit(void)
 {
-	DEFiRet;
+	rsRetVal iRet;	/* do not use DEFiRet, as this makes calls into the debug system! */
 
 	struct sigaction sigAct;
 	sigset_t sigSet;
@@ -1287,8 +1238,7 @@ rsRetVal dbgClassInit(void)
 	pthread_mutex_init(&mutFuncDBList, NULL);
 	pthread_mutex_init(&mutMutLog, NULL);
 	pthread_mutex_init(&mutCallStack, NULL);
-	pthread_mutex_init(&mutdbgprintf, NULL);
-	pthread_mutex_init(&mutdbgoprint, NULL);
+	pthread_mutex_init(&mutdbgprint, NULL);
 
 	/* while we try not to use any of the real rsyslog code (to avoid infinite loops), we
 	 * need to have the ability to query object names. Thus, we need to obtain a pointer to
@@ -1310,7 +1260,7 @@ rsRetVal dbgClassInit(void)
 
 	if(pszAltDbgFileName != NULL) {
 		/* we have a secondary file, so let's open it) */
-		if((altdbg = fopen(pszAltDbgFileName, "w")) == NULL) {
+		if((altdbg = open(pszAltDbgFileName, O_WRONLY|O_CREAT|O_TRUNC|O_NOCTTY, S_IRUSR|S_IWUSR)) == -1) {
 			fprintf(stderr, "alternate debug file could not be opened, ignoring. Error: %s\n", strerror(errno));
 		}
 	}
@@ -1318,7 +1268,7 @@ rsRetVal dbgClassInit(void)
 	dbgSetThrdName((uchar*)"main thread");
 
 finalize_it:
-	RETiRet;
+	return(iRet);
 }
 
 
@@ -1330,8 +1280,8 @@ rsRetVal dbgClassExit(void)
 	if(bPrintAllDebugOnExit)
 		dbgPrintAllDebugInfo();
 
-	if(altdbg != NULL)
-		fclose(altdbg);
+	if(altdbg != -1)
+		close(altdbg);
 
 	/* now free all of our memory to make the memory debugger happy... */
 	pFuncDBListEtry = pFuncDBListRoot;
diff --git a/tools/syslogd.c b/tools/syslogd.c
index 3a637dd8..a39f5a5c 100644
--- a/tools/syslogd.c
+++ b/tools/syslogd.c
@@ -1871,16 +1871,22 @@ void legacyOptsParseTCP(char ch, char *arg)
  * a minimal delay, but it is much cleaner than the approach of doing everything
  * inside the signal handler.
  * rgerhards, 2005-10-26
+ * Note: we do not call dbgprintf() as this may cause us to block in case something
+ * with the threading is wrong.
  */
 static void doDie(int sig)
 {
+#	define MSG1 "DoDie called.\n"
+#	define MSG2 "DoDie called 5 times - unconditional exit\n"
 	static int iRetries = 0; /* debug aid */
-	printf("DoDie called.\n");
+	write(1, MSG1, sizeof(MSG1));
 	if(iRetries++ == 4) {
-		printf("DoDie called 5 times - unconditional exit\n");
+		write(1, MSG2, sizeof(MSG2));
 		abort();
 	}
 	bFinished = sig;
+#	undef MSG1
+#	undef MSG2
 }