diff options
Diffstat (limited to 'runtime/debug.c')
-rw-r--r-- | runtime/debug.c | 236 |
1 files changed, 108 insertions, 128 deletions
diff --git a/runtime/debug.c b/runtime/debug.c index 9d45c737..96004e47 100644 --- a/runtime/debug.c +++ b/runtime/debug.c @@ -1,3 +1,4 @@ +#include <sys/syscall.h> /* debug.c * * This file proides debug and run time error analysis support. Some of the @@ -43,6 +44,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 +66,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 +117,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; @@ -529,7 +532,23 @@ static inline void dbgMutexUnlockLog(pthread_mutex_t *pmut, dbgFuncDB_t *pFuncDB pthread_mutex_lock(&mutMutLog); pLog = dbgMutLogFindSpecific(pmut, MUTOP_LOCK, NULL); +#if 0 /* toggle for testing */ assert(pLog != NULL); +#else +/* the change below seems not to work - the problem seems to be a real race... I keep this code in just in case + * I need to re-use it. It should be removed once we are finished analyzing this problem. -- rgerhards, 2008-09-17 + */ +if(pLog == NULL) { + /* this may happen due to some races. We do not try to avoid + * this, as it would complicate the "real" code. This is not justified + * just to keep the debug info system up. -- rgerhards, 2008-09-17 + */ + pthread_mutex_unlock(&mutMutLog); + dbgprintf("%s:%d:%s: mutex %p UNlocked [but we did not yet know this mutex!]\n", + pFuncDB->file, unlockLn, pFuncDB->func, (void*)pmut); + return; /* if we don't know it yet, we can not clean up... */ +} +#endif /* 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. @@ -801,8 +820,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, @@ -811,56 +828,47 @@ 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; + uchar *pszObjName = NULL; - 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 + /* we must get the object name before we lock the mutex, because the object + * potentially calls back into us. If we locked the mutex, we would deadlock + * ourselfs. On the other hand, the GetName call needs not to be protected, as + * this thread has a valid reference. If such an object is deleted by another + * thread, we are in much more trouble than just for dbgprint(). -- rgerhards, 2008-09-26 */ -#if 0 - if(objGetObjID(pObj) != OBJexpr) - return; -#endif - + if(pObj != NULL) { + pszObjName = obj.GetName(pObj); + } - 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(); @@ -874,113 +882,84 @@ 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); + // use for testing: lenWriteBuf = snprintf(pszWriteBuf, sizeof(pszWriteBuf), "{%ld}%s: ", (long) syscall(SYS_gettid), 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)); + if(pszObjName != NULL) { + lenWriteBuf = snprintf(pszWriteBuf, sizeof(pszWriteBuf), "%s: ", pszObjName); + 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) { @@ -994,7 +973,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; @@ -1005,6 +984,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 @@ -1259,7 +1240,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 */ @@ -1301,7 +1282,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")) { @@ -1326,7 +1307,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; @@ -1340,8 +1321,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 @@ -1363,7 +1343,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)); } } @@ -1371,7 +1351,7 @@ rsRetVal dbgClassInit(void) dbgSetThrdName((uchar*)"main thread"); finalize_it: - RETiRet; + return(iRet); } @@ -1383,8 +1363,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; |