From dc44f5a475101aa18568a0eaceacc2a4eb718391 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Fri, 26 Sep 2008 13:40:41 +0200 Subject: cleaned up internal debug system code and made it behave better in regard to multi-threading --- ChangeLog | 2 + runtime/debug.c | 208 +++++++++++++++++++++----------------------------------- tools/syslogd.c | 10 ++- 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 #include #include +#include +#include +#include #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 } -- cgit