From cf8b0717e12330695ce2e4b16966fda2a64b053e Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Thu, 18 Sep 2008 10:48:19 +0200 Subject: ignoring an (acceptable) race in debug system --- runtime/debug.c | 16 ++++++++++++++++ 1 file changed, 16 insertions(+) (limited to 'runtime/debug.c') diff --git a/runtime/debug.c b/runtime/debug.c index 1450d029..7ed1442b 100644 --- a/runtime/debug.c +++ b/runtime/debug.c @@ -480,7 +480,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. -- cgit v1.2.3 From 7b63cd6feda5087c43652bdcf8e694b544295d5b Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Thu, 18 Sep 2008 12:44:00 +0200 Subject: minor things, mostly improved debug info --- runtime/debug.c | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) (limited to 'runtime/debug.c') diff --git a/runtime/debug.c b/runtime/debug.c index 1450d029..958fb596 100644 --- a/runtime/debug.c +++ b/runtime/debug.c @@ -1,3 +1,4 @@ +#include /* debug.c * * This file proides debug and run time error analysis support. Some of the @@ -879,7 +880,7 @@ dbgprintf(char *fmt, ...) } /* do not cache the thread name, as the caller might have changed it - * TODO: optimized, invalidate cache when new name is set + * TODO: optimize, invalidate cache when new name is set */ dbgGetThrdName(pszThrdName, sizeof(pszThrdName), ptLastThrdID, 0); @@ -889,7 +890,8 @@ dbgprintf(char *fmt, ...) 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(stddbg != NULL) fprintf(stddbg, "{%ld}%s: ", (long) syscall(SYS_gettid), pszThrdName); + /*if(stddbg != NULL) fprintf(stddbg, "%s: ", pszThrdName);*/ if(altdbg != NULL) fprintf(altdbg, "%s: ", pszThrdName); } bWasNL = (*(fmt + strlen(fmt) - 1) == '\n') ? 1 : 0; -- cgit v1.2.3 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 --- runtime/debug.c | 208 +++++++++++++++++++++----------------------------------- 1 file changed, 79 insertions(+), 129 deletions(-) (limited to 'runtime/debug.c') 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; -- cgit v1.2.3 From 92c2e09d19bef9dd10d2e85a663925124d6e00e4 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Fri, 26 Sep 2008 18:40:28 +0200 Subject: some more threading cleanup - removed newly-introduced potential deadlock in debug system - removed unnecessary pthread_cond_signal - a bit general cleanup --- runtime/debug.c | 15 +++++++++++++-- 1 file changed, 13 insertions(+), 2 deletions(-) (limited to 'runtime/debug.c') diff --git a/runtime/debug.c b/runtime/debug.c index 15e9201b..b0bf76ea 100644 --- a/runtime/debug.c +++ b/runtime/debug.c @@ -772,6 +772,17 @@ dbgprint(obj_t *pObj, char *pszMsg, size_t lenMsg) char pszWriteBuf[1024]; size_t lenWriteBuf; struct timespec t; + uchar *pszObjName = NULL; + + /* 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(pObj != NULL) { + pszObjName = obj.GetName(pObj); + } pthread_mutex_lock(&mutdbgprint); pthread_cleanup_push(dbgMutexCancelCleanupHdlr, &mutdbgprint); @@ -810,8 +821,8 @@ dbgprint(obj_t *pObj, char *pszMsg, size_t lenMsg) 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) { - lenWriteBuf = snprintf(pszWriteBuf, sizeof(pszWriteBuf), "%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); } -- cgit v1.2.3 From a10bc421fffbeaa872ae0cdcb651f0a7e613ee7f Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Mon, 8 Dec 2008 19:55:27 +0100 Subject: resolved compile problem, e.g. on FreeBSD I commented out some debug code that is only useful in some testing scenarios and re-enabled the old code. This solved a FreeBSD compile issue. Also, I fixed some other syntax error, which somehow went into the tree (I am still puzzled about that, especially as some have already and successfully build from that tree... anyhow ;)). --- runtime/debug.c | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) (limited to 'runtime/debug.c') diff --git a/runtime/debug.c b/runtime/debug.c index 102d5d0f..53291fc2 100644 --- a/runtime/debug.c +++ b/runtime/debug.c @@ -819,8 +819,8 @@ dbgprint(obj_t *pObj, char *pszMsg, size_t lenMsg) if(altdbg != -1) write(altdbg, pszWriteBuf, lenWriteBuf); } - // old, reenable TODO lenWriteBuf = snprintf(pszWriteBuf, sizeof(pszWriteBuf), "%s: ", pszThrdName); - lenWriteBuf = snprintf(pszWriteBuf, sizeof(pszWriteBuf), "{%ld}%s: ", (long) syscall(SYS_gettid), 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 */ -- cgit v1.2.3 From 8f8f65abb66d1a7839c30c2d1b4b4d653a8990cc Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Wed, 16 Apr 2008 10:26:54 +0200 Subject: moved files to the runtime there are still some files left which could go into the runtime, but I think we will delete most of them once we are done with the full modularization. --- runtime/debug.c | 1332 +++++++++++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 1332 insertions(+) create mode 100644 runtime/debug.c (limited to 'runtime/debug.c') diff --git a/runtime/debug.c b/runtime/debug.c new file mode 100644 index 00000000..53624e38 --- /dev/null +++ b/runtime/debug.c @@ -0,0 +1,1332 @@ +/* debug.c + * + * This file proides debug and run time error analysis support. Some of the + * settings are very performance intense and my be turned off during a release + * build. + * + * File begun on 2008-01-22 by RGerhards + * + * Some functions are controlled by environment variables: + * + * RSYSLOG_DEBUGLOG if set, a debug log file is written to that location + * RSYSLOG_DEBUG specific debug options + * + * For details, visit doc/debug.html + * + * Copyright 2008 Rainer Gerhards and Adiscon GmbH. + * + * This file is part of the rsyslog runtime library. + * + * The rsyslog runtime library is free software: you can redistribute it and/or modify + * it under the terms of the GNU Lesser General Public License as published by + * the Free Software Foundation, either version 3 of the License, or + * (at your option) any later version. + * + * The rsyslog runtime library is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU Lesser General Public License for more details. + * + * You should have received a copy of the GNU Lesser General Public License + * along with the rsyslog runtime library. If not, see . + * + * A copy of the GPL can be found in the file "COPYING" in this distribution. + * A copy of the LGPL can be found in the file "COPYING.LESSER" in this distribution. + */ +#include "config.h" /* autotools! */ +#include +#include +#include +#include +#include +#include +#include +#include +#include + +#include "rsyslog.h" +#include "debug.h" +#include "atomic.h" +#include "obj.h" + + +/* static data (some time to be replaced) */ +DEFobjCurrIf(obj) +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 bLogAllocFree = 0; /* shall calls to (m/c)alloc and free be logged to the debug log? */ +static int bPrintFuncDBOnExit = 0; /* shall the function entry and exit be logged to the debug log? */ +static int bPrintMutexAction = 0; /* shall mutex calls be printed to the debug log? */ +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; + +/* list of files/objects that should be printed */ +typedef struct dbgPrintName_s { + uchar *pName; + struct dbgPrintName_s *pNext; +} dbgPrintName_t; + + +/* forward definitions */ +static void dbgGetThrdName(char *pszBuf, size_t lenBuf, pthread_t thrd, int bIncludeNumID); +static dbgThrdInfo_t *dbgGetThrdInfo(void); +static int dbgPrintNameIsInList(const uchar *pName, dbgPrintName_t *pRoot); + + +/* This lists are single-linked and members are added at the top */ +static dbgPrintName_t *printNameFileRoot = NULL; + + +/* 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 + * is to use as few memory as possible. + */ +typedef struct dbgFuncDBListEntry_s { + dbgFuncDB_t *pFuncDB; + struct dbgFuncDBListEntry_s *pNext; +} dbgFuncDBListEntry_t; +dbgFuncDBListEntry_t *pFuncDBListRoot; + +static pthread_mutex_t mutFuncDBList; + +typedef struct dbgMutLog_s { + struct dbgMutLog_s *pNext; + struct dbgMutLog_s *pPrev; + pthread_mutex_t *mut; + pthread_t thrd; + dbgFuncDB_t *pFuncDB; + int lockLn; /* the actual line where the mutex was locked */ + short mutexOp; +} dbgMutLog_t; +static dbgMutLog_t *dbgMutLogListRoot = NULL; +static dbgMutLog_t *dbgMutLogListLast = NULL; +static pthread_mutex_t mutMutLog; + + +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_key_t keyCallStack; + + +/* we do not have templates, so we use some macros to create linked list handlers + * for the several types + * DLL means "doubly linked list" + * rgerhards, 2008-01-23 + */ +#define DLL_Del(type, pThis) \ + if(pThis->pPrev != NULL) \ + pThis->pPrev->pNext = pThis->pNext; \ + if(pThis->pNext != NULL) \ + pThis->pNext->pPrev = pThis->pPrev; \ + if(pThis == dbg##type##ListRoot) \ + dbg##type##ListRoot = pThis->pNext; \ + if(pThis == dbg##type##ListLast) \ + dbg##type##ListLast = pThis->pPrev; \ + free(pThis); + +#define DLL_Add(type, pThis) \ + if(dbg##type##ListRoot == NULL) { \ + dbg##type##ListRoot = pThis; \ + dbg##type##ListLast = pThis; \ + } else { \ + pThis->pPrev = dbg##type##ListLast; \ + dbg##type##ListLast->pNext = pThis; \ + dbg##type##ListLast = pThis; \ + } + +/* we need to do our own mutex cancel cleanup handler as it shall not + * be subject to the debugging instrumentation (that would probably run us + * into an infinite loop + */ +static void dbgMutexCancelCleanupHdlr(void *pmut) +{ + pthread_mutex_unlock((pthread_mutex_t*) pmut); +} + + +/* handler to update the last execution location seen + * rgerhards, 2008-01-28 + */ +static inline void +dbgRecordExecLocation(int iStackPtr, int line) +{ + dbgThrdInfo_t *pThrd = dbgGetThrdInfo(); + pThrd->lastLine[iStackPtr] = line; +} + + +/* ------------------------- mutex tracking code ------------------------- */ + +/* ------------------------- 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) +{ + assert(pFuncDB != NULL); + assert(pFuncDB->magic == dbgFUNCDB_MAGIC); + /* make output suitable for sorting on invocation count */ + dbgprintf("%10.10ld times called: %s:%d:%s\n", pFuncDB->nTimesCalled, pFuncDB->file, pFuncDB->line, pFuncDB->func); +} + + +/* print all funcdb entries + */ +static void dbgFuncDBPrintAll(void) +{ + dbgFuncDBListEntry_t *pFuncDBList; + int nFuncs = 0; + + for(pFuncDBList = pFuncDBListRoot ; pFuncDBList != NULL ; pFuncDBList = pFuncDBList->pNext) { + dbgFuncDBPrint(pFuncDBList->pFuncDB); + nFuncs++; + } + + 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; + } +} + + +/* ------------------------- END FuncDB utility functions ------------------------- */ + +/* ########################################################################### + * IMPORTANT NOTE + * Mutex instrumentation reduces the code's concurrency and thus affects its + * order of execution. It is vital to test the code also with mutex + * instrumentation turned off! Some bugs may not show up while it on... + * ########################################################################### + */ + +/* constructor & add new entry to list + */ +dbgMutLog_t *dbgMutLogAddEntry(pthread_mutex_t *pmut, short mutexOp, dbgFuncDB_t *pFuncDB, int lockLn) +{ + dbgMutLog_t *pLog; + + pLog = calloc(1, sizeof(dbgMutLog_t)); + assert(pLog != NULL); + + /* fill data members */ + pLog->mut = pmut; + pLog->thrd = pthread_self(); + pLog->mutexOp = mutexOp; + pLog->lockLn = lockLn; + pLog->pFuncDB = pFuncDB; + + DLL_Add(MutLog, pLog); + + return pLog; +} + + +/* destruct log entry + */ +void dbgMutLogDelEntry(dbgMutLog_t *pLog) +{ + assert(pLog != NULL); + DLL_Del(MutLog, pLog); +} + + +/* print a single mutex log entry */ +static void dbgMutLogPrintOne(dbgMutLog_t *pLog) +{ + char *strmutop; + char buf[64]; + char pszThrdName[64]; + + assert(pLog != NULL); + switch(pLog->mutexOp) { + case MUTOP_LOCKWAIT: + strmutop = "waited on"; + break; + case MUTOP_LOCK: + strmutop = "owned"; + break; + default: + snprintf(buf, sizeof(buf)/sizeof(char), "unknown state %d - should not happen!", pLog->mutexOp); + strmutop = buf; + break; + } + + dbgGetThrdName(pszThrdName, sizeof(pszThrdName), pLog->thrd, 1); + dbgprintf("mutex 0x%lx is being %s by code at %s:%d, thread %s\n", (unsigned long) pLog->mut, + strmutop, pLog->pFuncDB->file, + (pLog->mutexOp == MUTOP_LOCK) ? pLog->lockLn : pLog->pFuncDB->line, + pszThrdName); +} + +/* print the complete mutex log */ +static void dbgMutLogPrintAll(void) +{ + dbgMutLog_t *pLog; + + dbgprintf("Mutex log for all known mutex operations:\n"); + for(pLog = dbgMutLogListRoot ; pLog != NULL ; pLog = pLog->pNext) + dbgMutLogPrintOne(pLog); + +} + + +/* find the last log entry for that specific mutex object. Is used to delete + * a thread's own requests. Searches occur from the back. + * The pFuncDB is optional and may be NULL to indicate no specific funciont is + * reqested (aka "it is ignored" ;)). This is important for the unlock case. + */ +dbgMutLog_t *dbgMutLogFindSpecific(pthread_mutex_t *pmut, short mutop, dbgFuncDB_t *pFuncDB) +{ + dbgMutLog_t *pLog; + pthread_t mythrd = pthread_self(); + + pLog = dbgMutLogListLast; + while(pLog != NULL) { + if( pLog->mut == pmut && pLog->thrd == mythrd && pLog->mutexOp == mutop + && (pFuncDB == NULL || pLog->pFuncDB == pFuncDB)) + break; + pLog = pLog->pPrev; + } + + return pLog; +} + + +/* find mutex object from the back of the list */ +dbgMutLog_t *dbgMutLogFindFromBack(pthread_mutex_t *pmut, dbgMutLog_t *pLast) +{ + dbgMutLog_t *pLog; + + if(pLast == NULL) + pLog = dbgMutLogListLast; + else + pLog = pLast->pPrev; /* if we get the last processed one, we need to go one before it, else its an endless loop */ + + while(pLog != NULL) { + if(pLog->mut == pmut) { + break; + } + pLog = pLog->pPrev; + } + + return pLog; +} + + +/* find lock aquire for mutex from back of list */ +dbgMutLog_t *dbgMutLogFindHolder(pthread_mutex_t *pmut) +{ + dbgMutLog_t *pLog; + + pLog = dbgMutLogFindFromBack(pmut, NULL); + while(pLog != NULL) { + if(pLog->mutexOp == MUTOP_LOCK) + break; + pLog = dbgMutLogFindFromBack(pmut, pLog); + } + + return pLog; +} + +/* report wait on a mutex and add it to the mutex log */ +static inline void dbgMutexPreLockLog(pthread_mutex_t *pmut, dbgFuncDB_t *pFuncDB, int ln) +{ + dbgMutLog_t *pHolder; + dbgMutLog_t *pLog; + char pszBuf[128]; + char pszHolderThrdName[64]; + char *pszHolder; + + pthread_mutex_lock(&mutMutLog); + pHolder = dbgMutLogFindHolder(pmut); + pLog = dbgMutLogAddEntry(pmut, MUTOP_LOCKWAIT, pFuncDB, ln); + + if(pHolder == NULL) + pszHolder = "[NONE]"; + else { + dbgGetThrdName(pszHolderThrdName, sizeof(pszHolderThrdName), pHolder->thrd, 1); + snprintf(pszBuf, sizeof(pszBuf)/sizeof(char), "%s:%d [%s]", pHolder->pFuncDB->file, pHolder->lockLn, pszHolderThrdName); + pszHolder = pszBuf; + } + + if(bPrintMutexAction) + 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, 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, lockLn); + dbgFuncDBAddMutexLock(pFuncDB, pmut, lockLn); + pthread_mutex_unlock(&mutMutLog); + if(bPrintMutexAction) + 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, 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); + if(bPrintMutexAction) + dbgprintf("%s:%d:%s: mutex %p UNlocked\n", pFuncDB->file, unlockLn, pFuncDB->func, (void*)pmut); +} + + +/* wrapper for pthread_mutex_lock() */ +int dbgMutexLock(pthread_mutex_t *pmut, dbgFuncDB_t *pFuncDB, int ln, int iStackPtr) +{ + int ret; + + dbgRecordExecLocation(iStackPtr, ln); + 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\n", + pFuncDB->file, ln, pFuncDB->func, (void*)pmut, ret); + } + + return ret; +} + + +/* wrapper for pthread_mutex_unlock() */ +int dbgMutexUnlock(pthread_mutex_t *pmut, dbgFuncDB_t *pFuncDB, int ln, int iStackPtr) +{ + int ret; + dbgRecordExecLocation(iStackPtr, ln); + dbgMutexUnlockLog(pmut, pFuncDB, ln); + ret = pthread_mutex_unlock(pmut); + return ret; +} + + +/* wrapper for pthread_cond_wait() */ +int dbgCondWait(pthread_cond_t *cond, pthread_mutex_t *pmut, dbgFuncDB_t *pFuncDB, int ln, int iStackPtr) +{ + int ret; + dbgRecordExecLocation(iStackPtr, ln); + dbgMutexUnlockLog(pmut, pFuncDB, ln); + if(bPrintMutexAction) { + dbgprintf("%s:%d:%s: mutex %p waiting on condition %p\n", pFuncDB->file, pFuncDB->line, + pFuncDB->func, (void*)pmut, (void*)cond); + } + dbgMutexPreLockLog(pmut, pFuncDB, ln); + ret = pthread_cond_wait(cond, pmut); + return ret; +} + + +/* 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 iStackPtr) +{ + int ret; + dbgRecordExecLocation(iStackPtr, ln); + dbgMutexUnlockLog(pmut, pFuncDB, ln); + dbgMutexPreLockLog(pmut, pFuncDB, ln); + if(bPrintMutexAction) { + 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); + dbgMutexLockLog(pmut, pFuncDB, ln); + return ret; +} + + +/* ------------------------- end mutex tracking code ------------------------- */ + + +/* ------------------------- malloc/free tracking code ------------------------- */ + +/* wrapper for free() */ +void dbgFree(void *pMem, dbgFuncDB_t *pFuncDB, int ln, int iStackPtr) +{ + dbgRecordExecLocation(iStackPtr, ln); + if(bLogAllocFree) { + dbgprintf("%s:%d:%s: free %p\n", pFuncDB->file, ln, pFuncDB->func, (void*) pMem); + } + free(pMem); +} + + +/* ------------------------- end malloc/free tracking code ------------------------- */ + +/* ------------------------- thread tracking code ------------------------- */ + +/* get ptr to call stack - if none exists, create a new stack + */ +static dbgThrdInfo_t *dbgGetThrdInfo(void) +{ + dbgThrdInfo_t *pThrd; + + pthread_mutex_lock(&mutCallStack); + if((pThrd = pthread_getspecific(keyCallStack)) == NULL) { + /* construct object */ + pThrd = calloc(1, sizeof(dbgThrdInfo_t)); + pThrd->thrd = pthread_self(); + (void) pthread_setspecific(keyCallStack, pThrd); + DLL_Add(CallStack, pThrd); + } + pthread_mutex_unlock(&mutCallStack); + return pThrd; +} + + + +/* find a specific thread ID. It must be present, else something is wrong + */ +static inline dbgThrdInfo_t *dbgFindThrd(pthread_t thrd) +{ + dbgThrdInfo_t *pThrd; + + for(pThrd = dbgCallStackListRoot ; pThrd != NULL ; pThrd = pThrd->pNext) { + if(pThrd->thrd == thrd) + break; + } + return pThrd; +} + + +/* build a string with the thread name. If none is set, the thread ID is + * used instead. Caller must provide buffer space. If bIncludeNumID is set + * to 1, the numerical ID is always included. + * rgerhards 2008-01-23 + */ +static void dbgGetThrdName(char *pszBuf, size_t lenBuf, pthread_t thrd, int bIncludeNumID) +{ + dbgThrdInfo_t *pThrd; + + assert(pszBuf != NULL); + + pThrd = dbgFindThrd(thrd); + + if(pThrd == 0 || pThrd->pszThrdName == NULL) { + /* no thread name, use numeric value */ + snprintf(pszBuf, lenBuf, "%lx", (long) thrd); + } else { + if(bIncludeNumID) { + snprintf(pszBuf, lenBuf, "%s (%lx)", pThrd->pszThrdName, (long) thrd); + } else { + snprintf(pszBuf, lenBuf, "%s", pThrd->pszThrdName); + } + } + +} + + +/* set a name for the current thread. The caller provided string is duplicated. + */ +void dbgSetThrdName(uchar *pszName) +{ + dbgThrdInfo_t *pThrd = dbgGetThrdInfo(); + if(pThrd->pszThrdName != NULL) + free(pThrd->pszThrdName); + pThrd->pszThrdName = strdup((char*)pszName); +} + + +/* destructor for a call stack object */ +static void dbgCallStackDestruct(void *arg) +{ + dbgThrdInfo_t *pThrd = (dbgThrdInfo_t*) arg; + + dbgprintf("destructor for debug call stack %p called\n", pThrd); + if(pThrd->pszThrdName != NULL) { + free(pThrd->pszThrdName); + } + + pthread_mutex_lock(&mutCallStack); + DLL_Del(CallStack, pThrd); + pthread_mutex_unlock(&mutCallStack); +} + + +/* print a thread's call stack + */ +static void dbgCallStackPrint(dbgThrdInfo_t *pThrd) +{ + int i; + char pszThrdName[64]; + + pthread_mutex_lock(&mutCallStack); + dbgGetThrdName(pszThrdName, sizeof(pszThrdName), pThrd->thrd, 1); + dbgprintf("\n"); + dbgprintf("Recorded Call Order for Thread '%s':\n", pszThrdName); + for(i = 0 ; i < pThrd->stackPtr ; i++) { + dbgprintf("%d: %s:%d:%s:\n", i, pThrd->callStack[i]->file, pThrd->lastLine[i], pThrd->callStack[i]->func); + } + dbgprintf("maximum number of nested calls for this thread: %d.\n", pThrd->stackPtrMax); + dbgprintf("NOTE: not all calls may have been recorded, code does not currently guarantee that!\n"); + pthread_mutex_unlock(&mutCallStack); +} + +/* print all threads call stacks + */ +static void dbgCallStackPrintAll(void) +{ + dbgThrdInfo_t *pThrd; + /* stack info */ + for(pThrd = dbgCallStackListRoot ; pThrd != NULL ; pThrd = pThrd->pNext) { + dbgCallStackPrint(pThrd); + } +} + + +/* handler for SIGSEGV - MUST terminiate the app, but does so in a somewhat + * more meaningful way. + * rgerhards, 2008-01-22 + */ +void +sigsegvHdlr(int signum) +{ + char *signame; + struct sigaction sigAct; + + /* first, restore the default abort handler */ + memset(&sigAct, 0, sizeof (sigAct)); + sigemptyset(&sigAct.sa_mask); + sigAct.sa_handler = SIG_DFL; + sigaction(SIGABRT, &sigAct, NULL); + + /* then do our actual processing */ + if(signum == SIGSEGV) { + signame = " (SIGSEGV)"; + } else if(signum == SIGABRT) { + signame = " (SIGABRT)"; + } else { + signame = ""; + } + + dbgprintf("\n\n\n\nSignal %d%s occured, execution must be terminated.\n\n\n\n", signum, signame); + + if(bAbortTrace) { + dbgPrintAllDebugInfo(); + dbgprintf("If the call trace is empty, you may want to ./configure --enable-rtinst\n"); + dbgprintf("\n\nTo submit bug reports, visit http://www.rsyslog.com/bugs\n\n"); + } + + 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, + * but may also be a very bad one (restart loops!) + */ + abort(); +} + + +/* 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, ...) +{ + 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]; + 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); + + /* 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); + /* 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)); + } + } + 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); +} + + +/* 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]; + 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); +} + +void tester(void) +{ +BEGINfunc +ENDfunc +} + +/* handler called when a function is entered. This function creates a new + * funcDB on the heap if the passed-in pointer is NULL. + */ +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(); + dbgFuncDBListEntry_t *pFuncDBListEntry; + unsigned int i; + dbgFuncDB_t *pFuncDB; + + assert(ppFuncDB != NULL); + assert(file != NULL); + assert(func != NULL); + pFuncDB = *ppFuncDB; + assert((pFuncDB == NULL) || (pFuncDB->magic == dbgFUNCDB_MAGIC)); + + 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 + * then reloaded again, we currently do not try to find its previous funcDB but + * instead create a duplicate. While finding the past one is straightforward, it + * opens up the question what to do with e.g. mutex data left in it. We do not + * yet see any need to handle these questions, so duplicaton seems to be the right + * thing to do. -- rgerhards, 2008-03-10 + */ + /* dbgprintf("%s:%d:%s: called first time, initializing FuncDB\n", pFuncDB->file, pFuncDB->line, pFuncDB->func); */ + /* get a new funcDB and add it to the list (all of this is protected by the mutex) */ + pthread_mutex_lock(&mutFuncDBList); + if((pFuncDBListEntry = calloc(1, sizeof(dbgFuncDBListEntry_t))) == NULL) { + dbgprintf("Error %d allocating memory for FuncDB List entry, not adding\n", errno); + pthread_mutex_unlock(&mutFuncDBList); + goto exit_it; + } else { + if((pFuncDB = calloc(1, sizeof(dbgFuncDB_t))) == NULL) { + dbgprintf("Error %d allocating memory for FuncDB, not adding\n", errno); + free(pFuncDBListEntry); + pthread_mutex_unlock(&mutFuncDBList); + goto exit_it; + } else { + pFuncDBListEntry->pFuncDB = pFuncDB; + pFuncDBListEntry->pNext = pFuncDBListRoot; + pFuncDBListRoot = pFuncDBListEntry; + } + } + /* now intialize the funcDB + * note that we duplicate the strings, because the address provided may go away + * if a loadable module is unloaded! + */ + pFuncDB->magic = dbgFUNCDB_MAGIC; + pFuncDB->file = strdup(file); + pFuncDB->func = strdup(func); + pFuncDB->line = line; + pFuncDB->nTimesCalled = 0; + for(i = 0 ; i < sizeof(pFuncDB->mutInfo)/sizeof(dbgFuncDBmutInfoEntry_t) ; ++i) { + pFuncDB->mutInfo[i].lockLn = -1; /* set to not Locked */ + } + + /* a round of safety checks... */ + if(pFuncDB->file == NULL || pFuncDB->func == NULL) { + dbgprintf("Error %d allocating memory for FuncDB, not adding\n", errno); + /* do a little bit of cleanup */ + if(pFuncDB->file != NULL) + free(pFuncDB->file); + if(pFuncDB->func != NULL) + free(pFuncDB->func); + free(pFuncDB); + free(pFuncDBListEntry); + pthread_mutex_unlock(&mutFuncDBList); + goto exit_it; + } + + /* done mutex-protected operations */ + pthread_mutex_unlock(&mutFuncDBList); + + *ppFuncDB = pFuncDB; /* all went well, so we can update the caller */ + } + + /* when we reach this point, we have a fully-initialized FuncDB! */ + ATOMIC_INC(pFuncDB->nTimesCalled); + if(bLogFuncFlow && dbgPrintNameIsInList((const uchar*)pFuncDB->file, printNameFileRoot)) + dbgprintf("%s:%d: %s: enter\n", pFuncDB->file, pFuncDB->line, pFuncDB->func); + 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; + } else { + iStackPtr = pThrd->stackPtr++; + if(pThrd->stackPtr > pThrd->stackPtrMax) + pThrd->stackPtrMax = pThrd->stackPtr; + pThrd->callStack[iStackPtr] = pFuncDB; + pThrd->lastLine[iStackPtr] = line; + } + +exit_it: + return iStackPtr; +} + + +/* handler called when a function is exited + */ +void dbgExitFunc(dbgFuncDB_t *pFuncDB, int iStackPtrRestore, int iRet) +{ + dbgThrdInfo_t *pThrd = dbgGetThrdInfo(); + + assert(iStackPtrRestore >= 0); + 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 && dbgPrintNameIsInList((const uchar*)pFuncDB->file, printNameFileRoot)) { + if(iRet == RS_RET_NO_IRET) + dbgprintf("%s:%d: %s: exit: (no iRet)\n", pFuncDB->file, pFuncDB->line, pFuncDB->func); + else + dbgprintf("%s:%d: %s: exit: %d\n", pFuncDB->file, pFuncDB->line, pFuncDB->func, iRet); + } + pThrd->stackPtr = iStackPtrRestore; + if(pThrd->stackPtr < 0) { + dbgprintf("Stack pointer for thread %lx below 0 - resetting (some RETiRet still wrong!)\n", (long) pthread_self()); + pThrd->stackPtr = 0; + } +} + + +/* externally-callable handler to record the last exec location. We use a different function + * so that the internal one can be inline. + */ +void +dbgSetExecLocation(int iStackPtr, int line) +{ + dbgRecordExecLocation(iStackPtr, line); +} + + +void dbgPrintAllDebugInfo(void) +{ + dbgCallStackPrintAll(); + dbgMutLogPrintAll(); + if(bPrintFuncDBOnExit) + dbgFuncDBPrintAll(); +} + + +/* Handler for SIGUSR2. Dumps all available debug output + */ +static void sigusr2Hdlr(int __attribute__((unused)) signum) +{ + dbgprintf("SIGUSR2 received, dumping debug information\n"); + dbgPrintAllDebugInfo(); +} + +/* support system to set debug options at runtime */ + + +/* parse a param/value pair from the current location of the + * option string. Returns 1 if an option was found, 0 + * otherwise. 0 means there are NO MORE options to be + * processed. -- rgerhards, 2008-02-28 + */ +static int +dbgGetRTOptNamVal(uchar **ppszOpt, uchar **ppOptName, uchar **ppOptVal) +{ + int bRet = 0; + uchar *p; + size_t i; + static uchar optname[128]; /* not thread- or reentrant-safe, but that */ + static uchar optval[1024]; /* doesn't matter (called only once at startup) */ + + assert(ppszOpt != NULL); + assert(*ppszOpt != NULL); + + /* make sure we have some initial values */ + optname[0] = '\0'; + optval[0] = '\0'; + + p = *ppszOpt; + /* skip whitespace */ + while(*p && isspace(*p)) + ++p; + + /* name - up until '=' or whitespace */ + i = 0; + while(i < (sizeof(optname)/sizeof(uchar) - 1) && *p && *p != '=' && !isspace(*p)) { + optname[i++] = *p++; + } + + if(i > 0) { + bRet = 1; + optname[i] = '\0'; + if(*p == '=') { + /* we have a value, get it */ + ++p; + i = 0; + while(i < (sizeof(optval)/sizeof(uchar) - 1) && *p && !isspace(*p)) { + optval[i++] = *p++; + } + optval[i] = '\0'; + } + } + + /* done */ + *ppszOpt = p; + *ppOptName = optname; + *ppOptVal = optval; + return bRet; +} + + +/* create new PrintName list entry and add it to list (they will never + * be removed. -- rgerhards, 2008-02-28 + */ +static void +dbgPrintNameAdd(uchar *pName, dbgPrintName_t **ppRoot) +{ + dbgPrintName_t *pEntry; + + if((pEntry = calloc(1, sizeof(dbgPrintName_t))) == NULL) { + fprintf(stderr, "ERROR: out of memory during debug setup\n"); + exit(1); + } + + if((pEntry->pName = (uchar*) strdup((char*) pName)) == NULL) { + fprintf(stderr, "ERROR: out of memory during debug setup\n"); + exit(1); + } + + if(*ppRoot != NULL) { + pEntry->pNext = *ppRoot; /* we enqueue at the front */ + } + *ppRoot = pEntry; + +printf("Name %s added to %p\n", pName, *ppRoot); +} + + +/* check if name is in a printName list - returns 1 if so, 0 otherwise. + * There is one special handling: if the root pointer is NULL, the function + * always returns 1. This is because when no name is set, output shall be + * unrestricted. + * rgerhards, 2008-02-28 + */ +static int +dbgPrintNameIsInList(const uchar *pName, dbgPrintName_t *pRoot) +{ + int bFound = 0; + dbgPrintName_t *pEntry = pRoot; + + if(pRoot == NULL) + bFound = 1; + + while(pEntry != NULL && !bFound) { + if(!strcasecmp((char*)pEntry->pName, (char*)pName)) { + bFound = 1; + } else { + pEntry = pEntry->pNext; + } + } + + return bFound; +} + + +/* read in the runtime options + * rgerhards, 2008-02-28 + */ +static void +dbgGetRuntimeOptions(void) +{ + uchar *pszOpts; + uchar *optval; + uchar *optname; + + /* set some defaults */ + stddbg = stdout; + + if((pszOpts = (uchar*) getenv("RSYSLOG_DEBUG")) != NULL) { + /* we have options set, so let's process them */ + while(dbgGetRTOptNamVal(&pszOpts, &optname, &optval)) { + if(!strcasecmp((char*)optname, "help")) { + fprintf(stderr, + "rsyslogd runtime debug support - help requested, rsyslog terminates\n\n" + "environment variables:\n" + "addional logfile: export RSYSLOG_DEBUGFILE=\"/path/to/file\"\n" + "to set: export RSYSLOG_DEBUG=\"cmd cmd cmd\"\n\n" + "Commands are (all case-insensitive):\n" + "help (this list, terminates rsyslogd\n" + "LogFuncFlow\n" + "LogAllocFree (very partly implemented)\n" + "PrintFuncDB\n" + "PrintMutexAction\n" + "PrintAllDebugInfoOnExit (not yet implemented)\n" + "NoLogTimestamp\n" + "Nostdoout\n" + "filetrace=file (may be provided multiple times)\n" + "\nSee debug.html in your doc set or http://www.rsyslog.com for details\n"); + exit(1); + } else if(!strcasecmp((char*)optname, "debug")) { + /* this is earlier in the process than the -d option, as such it + * allows us to spit out debug messages from the very beginning. + */ + Debug = 1; + debugging_on = 1; + } else if(!strcasecmp((char*)optname, "logfuncflow")) { + bLogFuncFlow = 1; + } else if(!strcasecmp((char*)optname, "logallocfree")) { + bLogAllocFree = 1; + } else if(!strcasecmp((char*)optname, "printfuncdb")) { + bPrintFuncDBOnExit = 1; + } else if(!strcasecmp((char*)optname, "printmutexaction")) { + bPrintMutexAction = 1; + } else if(!strcasecmp((char*)optname, "printalldebuginfoonexit")) { + bPrintAllDebugOnExit = 1; + } else if(!strcasecmp((char*)optname, "nologtimestamp")) { + bPrintTime = 0; + } else if(!strcasecmp((char*)optname, "nostdout")) { + stddbg = NULL; + } else if(!strcasecmp((char*)optname, "noaborttrace")) { + bAbortTrace = 0; + } else if(!strcasecmp((char*)optname, "filetrace")) { + if(*optval == '\0') { + fprintf(stderr, "Error: logfile debug option requires filename, " + "e.g. \"logfile=debug.c\"\n"); + exit(1); + } else { + /* create new entry and add it to list */ + dbgPrintNameAdd(optval, &printNameFileRoot); + } + } else { + fprintf(stderr, "Error: invalid debug option '%s', value '%s' - ignored\n", + optval, optname); + } + } + } +} + + +/* end support system to set debug options at runtime */ + +rsRetVal dbgClassInit(void) +{ + DEFiRet; + + struct sigaction sigAct; + sigset_t sigSet; + + (void) pthread_key_create(&keyCallStack, dbgCallStackDestruct); /* MUST be the first action done! */ + + /* we initialize all Mutexes with code, as some platforms seem to have + * bugs in the static initializer macros. So better be on the safe side... + * rgerhards, 2008-03-06 + */ + 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); + + /* 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 + * the object interface. -- rgerhards, 2008-02-29 + */ + CHKiRet(objGetObjInterface(&obj)); /* this provides the root pointer for all other queries */ + + memset(&sigAct, 0, sizeof (sigAct)); + sigemptyset(&sigAct.sa_mask); + sigAct.sa_handler = sigusr2Hdlr; + sigaction(SIGUSR2, &sigAct, NULL); + + sigemptyset(&sigSet); + sigaddset(&sigSet, SIGUSR2); + pthread_sigmask(SIG_UNBLOCK, &sigSet, NULL); + + dbgGetRuntimeOptions(); /* init debug system from environment */ + pszAltDbgFileName = getenv("RSYSLOG_DEBUGLOG"); + + 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"); + +finalize_it: + RETiRet; +} + + +rsRetVal dbgClassExit(void) +{ + dbgFuncDBListEntry_t *pFuncDBListEtry, *pToDel; + pthread_key_delete(keyCallStack); + + if(bPrintAllDebugOnExit) + dbgPrintAllDebugInfo(); + + if(altdbg != NULL) + fclose(altdbg); + + /* now free all of our memory to make the memory debugger happy... */ + pFuncDBListEtry = pFuncDBListRoot; + while(pFuncDBListEtry != NULL) { + pToDel = pFuncDBListEtry; + pFuncDBListEtry = pFuncDBListEtry->pNext; + free(pToDel->pFuncDB->file); + free(pToDel->pFuncDB->func); + free(pToDel->pFuncDB); + free(pToDel); + } + + return RS_RET_OK; +} +/* vi:set ai: + */ -- cgit v1.2.3 From 055d4ffc2afc77e03a3d31720d4a0998f8c3d92c Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Tue, 29 Apr 2008 15:36:22 +0200 Subject: fixed problem with module unload sequence --- runtime/debug.c | 2 -- 1 file changed, 2 deletions(-) (limited to 'runtime/debug.c') diff --git a/runtime/debug.c b/runtime/debug.c index 53624e38..f543efd8 100644 --- a/runtime/debug.c +++ b/runtime/debug.c @@ -1145,8 +1145,6 @@ dbgPrintNameAdd(uchar *pName, dbgPrintName_t **ppRoot) pEntry->pNext = *ppRoot; /* we enqueue at the front */ } *ppRoot = pEntry; - -printf("Name %s added to %p\n", pName, *ppRoot); } -- cgit v1.2.3 From b711a34a075cf3979f48937f8af8b05030644e82 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Mon, 23 Jun 2008 11:29:47 +0200 Subject: disabled compile warnings caused by third-party libraries --- runtime/debug.c | 4 ++++ 1 file changed, 4 insertions(+) (limited to 'runtime/debug.c') diff --git a/runtime/debug.c b/runtime/debug.c index f543efd8..1450d029 100644 --- a/runtime/debug.c +++ b/runtime/debug.c @@ -743,6 +743,7 @@ sigsegvHdlr(int signum) } +#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 @@ -834,8 +835,10 @@ dbgoprint(obj_t *pObj, char *fmt, ...) if(altdbg != NULL) fflush(altdbg); pthread_cleanup_pop(1); } +#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! */ @@ -908,6 +911,7 @@ dbgprintf(char *fmt, ...) if(altdbg != NULL) fflush(altdbg); pthread_cleanup_pop(1); } +#pragma GCC diagnostic warning "-Wempty-body" void tester(void) { -- cgit v1.2.3 From 6ffb9010811ee9bc0c3703716443c4dd00922f6f Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Wed, 25 Mar 2009 17:20:51 +0100 Subject: bugfix: potential abort with DA queue after high watermark is reached There exists a race condition that can lead to a segfault. Thanks go to vbernetr, who performed the analysis and provided patch, which I only tweaked a very little bit. --- runtime/debug.c | 69 +++++++++++++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 69 insertions(+) (limited to 'runtime/debug.c') diff --git a/runtime/debug.c b/runtime/debug.c index 1450d029..9d45c737 100644 --- a/runtime/debug.c +++ b/runtime/debug.c @@ -473,6 +473,55 @@ static inline void dbgMutexLockLog(pthread_mutex_t *pmut, dbgFuncDB_t *pFuncDB, dbgprintf("%s:%d:%s: mutex %p aquired\n", pFuncDB->file, lockLn, pFuncDB->func, (void*)pmut); } + +/* report trylock on a mutex and add it to the mutex log */ +static inline void dbgMutexPreTryLockLog(pthread_mutex_t *pmut, dbgFuncDB_t *pFuncDB, int ln) +{ + dbgMutLog_t *pHolder; + dbgMutLog_t *pLog; + char pszBuf[128]; + char pszHolderThrdName[64]; + char *pszHolder; + + pthread_mutex_lock(&mutMutLog); + pHolder = dbgMutLogFindHolder(pmut); + pLog = dbgMutLogAddEntry(pmut, MUTOP_TRYLOCK, pFuncDB, ln); + + if(pHolder == NULL) + pszHolder = "[NONE]"; + else { + dbgGetThrdName(pszHolderThrdName, sizeof(pszHolderThrdName), pHolder->thrd, 1); + snprintf(pszBuf, sizeof(pszBuf)/sizeof(char), "%s:%d [%s]", pHolder->pFuncDB->file, pHolder->lockLn, pszHolderThrdName); + pszHolder = pszBuf; + } + + if(bPrintMutexAction) + dbgprintf("%s:%d:%s: mutex %p trying to get lock, held by %s\n", pFuncDB->file, ln, pFuncDB->func, (void*)pmut, pszHolder); + pthread_mutex_unlock(&mutMutLog); +} + + +/* report attempted mutex lock */ +static inline void dbgMutexTryLockLog(pthread_mutex_t *pmut, dbgFuncDB_t *pFuncDB, int lockLn) +{ + dbgMutLog_t *pLog; + + pthread_mutex_lock(&mutMutLog); + + /* find and delete "trylock" entry */ + pLog = dbgMutLogFindSpecific(pmut, MUTOP_TRYLOCK, pFuncDB); + assert(pLog != NULL); + dbgMutLogDelEntry(pLog); + + /* add "lock" entry */ + pLog = dbgMutLogAddEntry(pmut, MUTOP_LOCK, pFuncDB, lockLn); + dbgFuncDBAddMutexLock(pFuncDB, pmut, lockLn); + pthread_mutex_unlock(&mutMutLog); + if(bPrintMutexAction) + 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, int unlockLn) { @@ -515,6 +564,26 @@ int dbgMutexLock(pthread_mutex_t *pmut, dbgFuncDB_t *pFuncDB, int ln, int iStack } +/* wrapper for pthread_mutex_trylock() */ +int dbgMutexTryLock(pthread_mutex_t *pmut, dbgFuncDB_t *pFuncDB, int ln, int iStackPtr) +{ + int ret; + + dbgRecordExecLocation(iStackPtr, ln); + dbgMutexPreLockLog(pmut, pFuncDB, ln); // TODO : update this + ret = pthread_mutex_trylock(pmut); + if(ret == 0 || ret == EBUSY) { + // TODO : update this + dbgMutexLockLog(pmut, pFuncDB, ln); + } else { + dbgprintf("%s:%d:%s: ERROR: pthread_mutex_trylock() for mutex %p failed with error %d\n", + pFuncDB->file, ln, pFuncDB->func, (void*)pmut, ret); + } + + return ret; +} + + /* wrapper for pthread_mutex_unlock() */ int dbgMutexUnlock(pthread_mutex_t *pmut, dbgFuncDB_t *pFuncDB, int ln, int iStackPtr) { -- cgit v1.2.3 From eb807027af9e126a212b0630c5873dddae48963b Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Thu, 2 Apr 2009 15:12:57 +0200 Subject: added O_CLOEXEC to open() calls to make sure only the minimum number of file handles is left open during a exec call. This is not a 100% solution, as there are also some fopen() calls and, more importantly, file descriptors opened by libraries. But it is better than nothing (and it was quick, at least until we run into platform hell, what we will for sure ;)). --- runtime/debug.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) (limited to 'runtime/debug.c') diff --git a/runtime/debug.c b/runtime/debug.c index 96004e47..4ee90226 100644 --- a/runtime/debug.c +++ b/runtime/debug.c @@ -1343,7 +1343,7 @@ rsRetVal dbgClassInit(void) if(pszAltDbgFileName != NULL) { /* we have a secondary file, so let's open it) */ - if((altdbg = open(pszAltDbgFileName, O_WRONLY|O_CREAT|O_TRUNC|O_NOCTTY, S_IRUSR|S_IWUSR)) == -1) { + if((altdbg = open(pszAltDbgFileName, O_WRONLY|O_CREAT|O_TRUNC|O_NOCTTY|O_CLOEXEC, S_IRUSR|S_IWUSR)) == -1) { fprintf(stderr, "alternate debug file could not be opened, ignoring. Error: %s\n", strerror(errno)); } } -- cgit v1.2.3 From bb79e96dc300fa5a2182e7c047afb3b15c5dc870 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Tue, 12 May 2009 15:27:40 +0200 Subject: moving to a cleaner implementation of batches ... now that we know what we need from a theoretical POV. --- runtime/debug.c | 14 +++++++++----- 1 file changed, 9 insertions(+), 5 deletions(-) (limited to 'runtime/debug.c') diff --git a/runtime/debug.c b/runtime/debug.c index 4ee90226..4f45a1e3 100644 --- a/runtime/debug.c +++ b/runtime/debug.c @@ -1050,7 +1050,9 @@ int dbgEntrFunc(dbgFuncDB_t **ppFuncDB, const char *file, const char *func, int /* when we reach this point, we have a fully-initialized FuncDB! */ ATOMIC_INC(pFuncDB->nTimesCalled); if(bLogFuncFlow && dbgPrintNameIsInList((const uchar*)pFuncDB->file, printNameFileRoot)) - dbgprintf("%s:%d: %s: enter\n", pFuncDB->file, pFuncDB->line, pFuncDB->func); + if(strcmp(pFuncDB->file, "stringbuf.c")) { /* TODO: make configurable */ + dbgprintf("%s:%d: %s: enter\n", pFuncDB->file, pFuncDB->line, pFuncDB->func); + } 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); @@ -1080,10 +1082,12 @@ void dbgExitFunc(dbgFuncDB_t *pFuncDB, int iStackPtrRestore, int iRet) dbgFuncDBPrintActiveMutexes(pFuncDB, "WARNING: mutex still owned by us as we exit function, mutex: ", pthread_self()); if(bLogFuncFlow && dbgPrintNameIsInList((const uchar*)pFuncDB->file, printNameFileRoot)) { - if(iRet == RS_RET_NO_IRET) - dbgprintf("%s:%d: %s: exit: (no iRet)\n", pFuncDB->file, pFuncDB->line, pFuncDB->func); - else - dbgprintf("%s:%d: %s: exit: %d\n", pFuncDB->file, pFuncDB->line, pFuncDB->func, iRet); + if(strcmp(pFuncDB->file, "stringbuf.c")) { /* TODO: make configurable */ + if(iRet == RS_RET_NO_IRET) + dbgprintf("%s:%d: %s: exit: (no iRet)\n", pFuncDB->file, pFuncDB->line, pFuncDB->func); + else + dbgprintf("%s:%d: %s: exit: %d\n", pFuncDB->file, pFuncDB->line, pFuncDB->func, iRet); + } } pThrd->stackPtr = iStackPtrRestore; if(pThrd->stackPtr < 0) { -- cgit v1.2.3 From 9f45b80ea9ea86d516c895d97fd8670df37e319e Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Wed, 20 May 2009 15:12:49 +0200 Subject: free last processed message in all cases so far, the last processed message was only freed when the next one was processed. This has been changed now. More precisely, a better algorithm has been selected for the queue worker process, which also involves less overhead than the previous one. The fix for "free last processed message" as then more or less a side-effect (easy to do) of the new algorithm. --- runtime/debug.c | 51 ++++++++++++++++++++++++++++++--------------------- 1 file changed, 30 insertions(+), 21 deletions(-) (limited to 'runtime/debug.c') diff --git a/runtime/debug.c b/runtime/debug.c index 4f45a1e3..248c5ea3 100644 --- a/runtime/debug.c +++ b/runtime/debug.c @@ -828,13 +828,12 @@ sigsegvHdlr(int signum) abort(); } -#if 1 -#pragma GCC diagnostic ignored "-Wempty-body" -/* write the debug message. This is a helper to dbgprintf and dbgoprint which - * contains common code. added 2008-09-26 rgerhards +/* actually write the debug message. This is a separate fuction because the cleanup_push/_pop + * interface otherwise is unsafe to use (generates compiler warnings at least). + * 2009-05-20 rgerhards */ -static void -dbgprint(obj_t *pObj, char *pszMsg, size_t lenMsg) +static inline void +do_dbgprint(uchar *pszObjName, char *pszMsg, size_t lenMsg) { static pthread_t ptLastThrdID = 0; static int bWasNL = 0; @@ -842,20 +841,6 @@ dbgprint(obj_t *pObj, char *pszMsg, size_t lenMsg) char pszWriteBuf[1024]; size_t lenWriteBuf; struct timespec t; - uchar *pszObjName = NULL; - - /* 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(pObj != NULL) { - pszObjName = obj.GetName(pObj); - } - - 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 @@ -903,11 +888,35 @@ dbgprint(obj_t *pObj, char *pszMsg, size_t lenMsg) if(altdbg != -1) write(altdbg, pszMsg, lenMsg); bWasNL = (pszMsg[lenMsg - 1] == '\n') ? 1 : 0; +} + +#pragma GCC diagnostic ignored "-Wempty-body" +/* write the debug message. This is a helper to dbgprintf and dbgoprint which + * contains common code. added 2008-09-26 rgerhards + */ +static void +dbgprint(obj_t *pObj, char *pszMsg, size_t lenMsg) +{ + uchar *pszObjName = NULL; + + /* 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(pObj != NULL) { + pszObjName = obj.GetName(pObj); + } + + pthread_mutex_lock(&mutdbgprint); + pthread_cleanup_push(dbgMutexCancelCleanupHdlr, &mutdbgprint); + + do_dbgprint(pszObjName, pszMsg, lenMsg); 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 -- cgit v1.2.3 From f53aa966e1fad03c478de342f5a878e57405de13 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Tue, 7 Jul 2009 12:09:41 +0200 Subject: solved a race condition --- runtime/debug.c | 2 ++ 1 file changed, 2 insertions(+) (limited to 'runtime/debug.c') diff --git a/runtime/debug.c b/runtime/debug.c index 4ee90226..ded1c218 100644 --- a/runtime/debug.c +++ b/runtime/debug.c @@ -732,6 +732,8 @@ static void dbgGetThrdName(char *pszBuf, size_t lenBuf, pthread_t thrd, int bInc */ void dbgSetThrdName(uchar *pszName) { +return; + dbgThrdInfo_t *pThrd = dbgGetThrdInfo(); if(pThrd->pszThrdName != NULL) free(pThrd->pszThrdName); -- cgit v1.2.3 From 26227091faac8c3cc9bc282eb4e4fc408635f8d2 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Tue, 7 Jul 2009 17:18:51 +0200 Subject: fixed a bug introduced today that lead to an abort in queue disk mode --- runtime/debug.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) (limited to 'runtime/debug.c') diff --git a/runtime/debug.c b/runtime/debug.c index ded1c218..807fd3f7 100644 --- a/runtime/debug.c +++ b/runtime/debug.c @@ -778,7 +778,7 @@ static void dbgCallStackPrint(dbgThrdInfo_t *pThrd) /* print all threads call stacks */ -static void dbgCallStackPrintAll(void) +void dbgCallStackPrintAll(void) { dbgThrdInfo_t *pThrd; /* stack info */ -- cgit v1.2.3 From 50d9939148055123015eeb7aca7e83de5ab0084b Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Thu, 8 Oct 2009 16:29:15 +0200 Subject: bugfix: debug string larger than 1K were improperly displayed. Max size is now 32K. --- runtime/debug.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) (limited to 'runtime/debug.c') diff --git a/runtime/debug.c b/runtime/debug.c index 807fd3f7..1b592ef3 100644 --- a/runtime/debug.c +++ b/runtime/debug.c @@ -841,7 +841,7 @@ dbgprint(obj_t *pObj, char *pszMsg, size_t lenMsg) static pthread_t ptLastThrdID = 0; static int bWasNL = 0; char pszThrdName[64]; /* 64 is to be on the safe side, anything over 20 is bad... */ - char pszWriteBuf[1024]; + char pszWriteBuf[32*1024]; size_t lenWriteBuf; struct timespec t; uchar *pszObjName = NULL; -- cgit v1.2.3 From ec56b763b83677d1e9cd02a7ae610caf62e902bb Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Thu, 8 Oct 2009 16:36:17 +0200 Subject: bugfix in debug system and more instrumentation to find an issue bugfix: debug string larger than 1K were improperly displayed. Max size is now 32K, and if a string is even longer it is meaningful truncated. --- runtime/debug.c | 12 +++++++++++- 1 file changed, 11 insertions(+), 1 deletion(-) (limited to 'runtime/debug.c') diff --git a/runtime/debug.c b/runtime/debug.c index fb751efb..7c938008 100644 --- a/runtime/debug.c +++ b/runtime/debug.c @@ -960,7 +960,7 @@ void dbgprintf(char *fmt, ...) { va_list ap; - char pszWriteBuf[1024]; + char pszWriteBuf[32*1024]; size_t lenWriteBuf; if(!(Debug && debugging_on)) @@ -969,6 +969,16 @@ dbgprintf(char *fmt, ...) va_start(ap, fmt); lenWriteBuf = vsnprintf(pszWriteBuf, sizeof(pszWriteBuf), fmt, ap); va_end(ap); + + if(lenWriteBuf >= sizeof(pszWriteBuf)) { + /* if we need to truncate, do it in a somewhat useful way... */ + pszWriteBuf[sizeof(pszWriteBuf) - 5] = '!'; + pszWriteBuf[sizeof(pszWriteBuf) - 4] = '.'; + pszWriteBuf[sizeof(pszWriteBuf) - 3] = '.'; + pszWriteBuf[sizeof(pszWriteBuf) - 2] = '.'; + pszWriteBuf[sizeof(pszWriteBuf) - 1] = '\n'; + lenWriteBuf = sizeof(pszWriteBuf); + } dbgprint(NULL, pszWriteBuf, lenWriteBuf); } -- cgit v1.2.3 From e04e1b50025f5fa9c26abd946190dce8f797d08f Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Thu, 22 Oct 2009 11:33:38 +0200 Subject: enhanced test environment (including testbench) support for enhancing probability of memory addressing failure by using non-NULL default value for malloced memory (optional, only if requested by configure option). This helps to track down some otherwise undetected issues within the testbench and is expected to be very useful in the future. --- runtime/debug.c | 14 ++++++++++++++ 1 file changed, 14 insertions(+) (limited to 'runtime/debug.c') diff --git a/runtime/debug.c b/runtime/debug.c index 476f8bf7..fa57a8d8 100644 --- a/runtime/debug.c +++ b/runtime/debug.c @@ -1254,6 +1254,20 @@ dbgPrintNameIsInList(const uchar *pName, dbgPrintName_t *pRoot) } +/* this is a special version of malloc that fills the alloced memory with + * HIGHVALUE, as this helps to identify bugs. -- rgerhards, 2009-10-22 + */ +void * +dbgmalloc(size_t size) +{ + void *pRet; + pRet = malloc(size); + if(pRet != NULL) + memset(pRet, 0xff, size); + return pRet; +} + + /* read in the runtime options * rgerhards, 2008-02-28 */ -- cgit v1.2.3 From 2b5e15d549940c7ace9017eaf40d523e3741c9a2 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Tue, 10 Nov 2009 12:50:48 +0100 Subject: added a so-called "On Demand Debug" mode in which debug output can be generated only after the process has started, but not right from the beginning. This is assumed to be useful for hard-to-find bugs. Also improved the doc on the debug system. --- runtime/debug.c | 9 +++++++++ 1 file changed, 9 insertions(+) (limited to 'runtime/debug.c') diff --git a/runtime/debug.c b/runtime/debug.c index 1b592ef3..9547eee6 100644 --- a/runtime/debug.c +++ b/runtime/debug.c @@ -51,6 +51,7 @@ #include "rsyslog.h" #include "debug.h" #include "atomic.h" +#include "cfsysline.h" #include "obj.h" @@ -1263,6 +1264,7 @@ dbgGetRuntimeOptions(void) "NoLogTimestamp\n" "Nostdoout\n" "filetrace=file (may be provided multiple times)\n" + "DebugOnDemand - enables debugging on USR1, but does not turn on output\n" "\nSee debug.html in your doc set or http://www.rsyslog.com for details\n"); exit(1); } else if(!strcasecmp((char*)optname, "debug")) { @@ -1271,6 +1273,13 @@ dbgGetRuntimeOptions(void) */ Debug = 1; debugging_on = 1; + } else if(!strcasecmp((char*)optname, "debugondemand")) { + /* Enables debugging, but turns off debug output */ + Debug = 1; + debugging_on = 1; + dbgprintf("Note: debug on demand turned on via configuraton file, " + "use USR1 signal to activate.\n"); + debugging_on = 0; } else if(!strcasecmp((char*)optname, "logfuncflow")) { bLogFuncFlow = 1; } else if(!strcasecmp((char*)optname, "logallocfree")) { -- cgit v1.2.3 From 5b55ab75e27861241981ae447ed3d1b8ad968deb Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Fri, 20 Nov 2009 18:41:04 +0100 Subject: debugondemand mode caused backgrounding to fail This is close to a bug, but I'd consider the ability to background in this mode a new feature... --- runtime/debug.c | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) (limited to 'runtime/debug.c') diff --git a/runtime/debug.c b/runtime/debug.c index 9547eee6..c23dec3b 100644 --- a/runtime/debug.c +++ b/runtime/debug.c @@ -1271,11 +1271,11 @@ dbgGetRuntimeOptions(void) /* this is earlier in the process than the -d option, as such it * allows us to spit out debug messages from the very beginning. */ - Debug = 1; + Debug = DEBUG_FULL; debugging_on = 1; } else if(!strcasecmp((char*)optname, "debugondemand")) { /* Enables debugging, but turns off debug output */ - Debug = 1; + Debug = DEBUG_ONDEMAND; debugging_on = 1; dbgprintf("Note: debug on demand turned on via configuraton file, " "use USR1 signal to activate.\n"); -- cgit v1.2.3 From 1fc8e4372bf0c7ccc7f54abe387933dc8a2de670 Mon Sep 17 00:00:00 2001 From: trey Date: Wed, 3 Feb 2010 14:55:35 +0100 Subject: patch to make rsyslog compile under Apple OS X Signed-off-by: Rainer Gerhards --- runtime/debug.c | 13 +++++++++++++ 1 file changed, 13 insertions(+) (limited to 'runtime/debug.c') diff --git a/runtime/debug.c b/runtime/debug.c index a517b1ba..6d82397f 100644 --- a/runtime/debug.c +++ b/runtime/debug.c @@ -47,6 +47,9 @@ #include #include #include +#if _POSIX_TIMERS <= 0 +#include +#endif #include "rsyslog.h" #include "debug.h" @@ -844,6 +847,9 @@ do_dbgprint(uchar *pszObjName, char *pszMsg, size_t lenMsg) char pszWriteBuf[32*1024]; size_t lenWriteBuf; struct timespec t; +# if _POSIX_TIMERS <= 0 + struct timeval tv; +# endif /* The bWasNL handler does not really work. It works if no thread * switching occurs during non-NL messages. Else, things are messed @@ -869,7 +875,14 @@ do_dbgprint(uchar *pszObjName, char *pszMsg, size_t lenMsg) if(bWasNL) { if(bPrintTime) { +# if _POSIX_TIMERS > 0 + /* this is the "regular" code */ clock_gettime(CLOCK_REALTIME, &t); +# else + gettimeofday(&tv, NULL); + t.tv_sec = tv.tv_sec; + t.tv_nsec = tv.tv_usec * 1000; +# endif lenWriteBuf = snprintf(pszWriteBuf, sizeof(pszWriteBuf), "%4.4ld.%9.9ld:", (long) (t.tv_sec % 10000), t.tv_nsec); if(stddbg != -1) write(stddbg, pszWriteBuf, lenWriteBuf); -- cgit v1.2.3 From cd8c6abcc8cea54924e55dffe820364ad98a40df Mon Sep 17 00:00:00 2001 From: Yann Droneaud Date: Thu, 4 Mar 2010 08:00:39 +0100 Subject: Includes "config.h" before any other header. For consistency, ./configure generated "config.h" must be the first header include through out the project. Signed-off-by: Rainer Gerhards --- runtime/debug.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) (limited to 'runtime/debug.c') diff --git a/runtime/debug.c b/runtime/debug.c index 9547eee6..20474a9a 100644 --- a/runtime/debug.c +++ b/runtime/debug.c @@ -1,4 +1,3 @@ -#include /* debug.c * * This file proides debug and run time error analysis support. Some of the @@ -550,6 +549,7 @@ if(pLog == NULL) { return; /* if we don't know it yet, we can not clean up... */ } #endif +#include /* 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. -- cgit v1.2.3 From 83c15bb0a004ee348228217861c0eab7c5573952 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Thu, 11 Mar 2010 12:36:21 +0100 Subject: added more tests to testbench and improved testing tools --- runtime/debug.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) (limited to 'runtime/debug.c') diff --git a/runtime/debug.c b/runtime/debug.c index 20474a9a..4504aaad 100644 --- a/runtime/debug.c +++ b/runtime/debug.c @@ -952,7 +952,7 @@ void dbgprintf(char *fmt, ...) { va_list ap; - char pszWriteBuf[1024]; + char pszWriteBuf[20480]; size_t lenWriteBuf; if(!(Debug && debugging_on)) -- cgit v1.2.3 From a1127abbae67ac3a9c154b1914b15f1e16deca56 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Mon, 15 Mar 2010 09:29:54 +0100 Subject: bugfix(minor): handling of extremely large strings in dbgprintf() fixed Previously, it could lead to garbagge output and, in extreme cases, also to segfaults. Note: this was a problem only when debug output was actually enabled, so it caused no problem in production use. --- runtime/debug.c | 9 +++++++++ 1 file changed, 9 insertions(+) (limited to 'runtime/debug.c') diff --git a/runtime/debug.c b/runtime/debug.c index 4504aaad..bc581a5d 100644 --- a/runtime/debug.c +++ b/runtime/debug.c @@ -961,6 +961,15 @@ dbgprintf(char *fmt, ...) va_start(ap, fmt); lenWriteBuf = vsnprintf(pszWriteBuf, sizeof(pszWriteBuf), fmt, ap); va_end(ap); + if(lenWriteBuf >= sizeof(pszWriteBuf)) { + /* prevent buffer overrruns and garbagge display */ + pszWriteBuf[sizeof(pszWriteBuf) - 5] = '.'; + pszWriteBuf[sizeof(pszWriteBuf) - 4] = '.'; + pszWriteBuf[sizeof(pszWriteBuf) - 3] = '.'; + pszWriteBuf[sizeof(pszWriteBuf) - 2] = '\n'; + pszWriteBuf[sizeof(pszWriteBuf) - 1] = '\0'; + lenWriteBuf = sizeof(pszWriteBuf); + } dbgprint(NULL, pszWriteBuf, lenWriteBuf); } -- cgit v1.2.3 From 16cb5ae53caba2a3cc9091026037c55d23cf3199 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Tue, 16 Mar 2010 17:06:21 +0100 Subject: enhanced dbgoprint() buffer size --- runtime/debug.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) (limited to 'runtime/debug.c') diff --git a/runtime/debug.c b/runtime/debug.c index bc581a5d..9b7c2952 100644 --- a/runtime/debug.c +++ b/runtime/debug.c @@ -922,7 +922,7 @@ void dbgoprint(obj_t *pObj, char *fmt, ...) { va_list ap; - char pszWriteBuf[1024]; + char pszWriteBuf[32*1024]; size_t lenWriteBuf; if(!(Debug && debugging_on)) -- cgit v1.2.3 From 54ae07e33cf28aead4d9318dfc28762cb7211a22 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Wed, 14 Apr 2010 08:30:15 +0200 Subject: slightly improved/cleaned up debugging system --- runtime/debug.c | 19 ++++++++++++++++--- 1 file changed, 16 insertions(+), 3 deletions(-) (limited to 'runtime/debug.c') diff --git a/runtime/debug.c b/runtime/debug.c index c82a411d..da471609 100644 --- a/runtime/debug.c +++ b/runtime/debug.c @@ -154,7 +154,9 @@ static pthread_key_t keyCallStack; */ static void dbgMutexCancelCleanupHdlr(void *pmut) { - pthread_mutex_unlock((pthread_mutex_t*) pmut); + int ret; + ret = pthread_mutex_unlock((pthread_mutex_t*) pmut); + assert(ret == 0); } @@ -846,6 +848,7 @@ dbgprint(obj_t *pObj, char *pszMsg, size_t lenMsg) size_t lenWriteBuf; struct timespec t; uchar *pszObjName = NULL; + int ret; /* 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 @@ -857,7 +860,8 @@ dbgprint(obj_t *pObj, char *pszMsg, size_t lenMsg) pszObjName = obj.GetName(pObj); } - pthread_mutex_lock(&mutdbgprint); + ret = pthread_mutex_lock(&mutdbgprint); + assert(ret == 0); /* make sure mutex operation does not fail */ pthread_cleanup_push(dbgMutexCancelCleanupHdlr, &mutdbgprint); /* The bWasNL handler does not really work. It works if no thread @@ -941,6 +945,15 @@ dbgoprint(obj_t *pObj, char *fmt, ...) va_start(ap, fmt); lenWriteBuf = vsnprintf(pszWriteBuf, sizeof(pszWriteBuf), fmt, ap); va_end(ap); + if(lenWriteBuf >= sizeof(pszWriteBuf)) { + /* prevent buffer overrruns and garbagge display */ + pszWriteBuf[sizeof(pszWriteBuf) - 5] = '.'; + pszWriteBuf[sizeof(pszWriteBuf) - 4] = '.'; + pszWriteBuf[sizeof(pszWriteBuf) - 3] = '.'; + pszWriteBuf[sizeof(pszWriteBuf) - 2] = '\n'; + pszWriteBuf[sizeof(pszWriteBuf) - 1] = '\0'; + lenWriteBuf = sizeof(pszWriteBuf); + } dbgprint(pObj, pszWriteBuf, lenWriteBuf); } @@ -952,7 +965,7 @@ void dbgprintf(char *fmt, ...) { va_list ap; - char pszWriteBuf[20480]; + char pszWriteBuf[32*1024]; size_t lenWriteBuf; if(!(Debug && debugging_on)) -- cgit v1.2.3 From cbe2e3d44496ec7c6418e7e74ce917f2086a2947 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Tue, 27 Apr 2010 17:31:28 +0200 Subject: bugfix: problems with atomic operations emulation replaced atomic operation emulation with new code. The previous code seemed to have some issue and also limited concurrency severely. The whole atomic operation emulation has been rewritten. --- runtime/debug.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) (limited to 'runtime/debug.c') diff --git a/runtime/debug.c b/runtime/debug.c index da471609..0ada909b 100644 --- a/runtime/debug.c +++ b/runtime/debug.c @@ -1073,7 +1073,7 @@ int dbgEntrFunc(dbgFuncDB_t **ppFuncDB, const char *file, const char *func, int } /* when we reach this point, we have a fully-initialized FuncDB! */ - ATOMIC_INC(pFuncDB->nTimesCalled); + PREFER_ATOMIC_INC(pFuncDB->nTimesCalled); if(bLogFuncFlow && dbgPrintNameIsInList((const uchar*)pFuncDB->file, printNameFileRoot)) dbgprintf("%s:%d: %s: enter\n", pFuncDB->file, pFuncDB->line, pFuncDB->func); if(pThrd->stackPtr >= (int) (sizeof(pThrd->callStack) / sizeof(dbgFuncDB_t*))) { -- cgit v1.2.3 From 2a2cc3d26d56b834dcc143f2f4e3abbb6bd206c6 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Fri, 17 Sep 2010 12:20:59 +0200 Subject: minor: added version number to some error messages --- runtime/debug.c | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) (limited to 'runtime/debug.c') diff --git a/runtime/debug.c b/runtime/debug.c index 64e251e5..5818dda9 100644 --- a/runtime/debug.c +++ b/runtime/debug.c @@ -1310,7 +1310,7 @@ dbgGetRuntimeOptions(void) while(dbgGetRTOptNamVal(&pszOpts, &optname, &optval)) { if(!strcasecmp((char*)optname, "help")) { fprintf(stderr, - "rsyslogd runtime debug support - help requested, rsyslog terminates\n\n" + "rsyslogd " VERSION " runtime debug support - help requested, rsyslog terminates\n\n" "environment variables:\n" "addional logfile: export RSYSLOG_DEBUGFILE=\"/path/to/file\"\n" "to set: export RSYSLOG_DEBUG=\"cmd cmd cmd\"\n\n" @@ -1358,7 +1358,7 @@ dbgGetRuntimeOptions(void) bAbortTrace = 0; } else if(!strcasecmp((char*)optname, "filetrace")) { if(*optval == '\0') { - fprintf(stderr, "Error: logfile debug option requires filename, " + fprintf(stderr, "rsyslogd " VERSION " error: logfile debug option requires filename, " "e.g. \"logfile=debug.c\"\n"); exit(1); } else { @@ -1366,7 +1366,7 @@ dbgGetRuntimeOptions(void) dbgPrintNameAdd(optval, &printNameFileRoot); } } else { - fprintf(stderr, "Error: invalid debug option '%s', value '%s' - ignored\n", + fprintf(stderr, "rsyslogd " VERSION " error: invalid debug option '%s', value '%s' - ignored\n", optval, optname); } } -- cgit v1.2.3 From 371a8eec29fa25bbf58f4b1f0d7e3bf4c3ad6329 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Thu, 16 Dec 2010 12:57:55 +0100 Subject: some cleanup based on clang static analyzer results --- runtime/debug.c | 6 ++---- 1 file changed, 2 insertions(+), 4 deletions(-) (limited to 'runtime/debug.c') diff --git a/runtime/debug.c b/runtime/debug.c index 9b7c2952..6bb8d743 100644 --- a/runtime/debug.c +++ b/runtime/debug.c @@ -433,14 +433,13 @@ dbgMutLog_t *dbgMutLogFindHolder(pthread_mutex_t *pmut) static inline void dbgMutexPreLockLog(pthread_mutex_t *pmut, dbgFuncDB_t *pFuncDB, int ln) { dbgMutLog_t *pHolder; - dbgMutLog_t *pLog; char pszBuf[128]; char pszHolderThrdName[64]; char *pszHolder; pthread_mutex_lock(&mutMutLog); pHolder = dbgMutLogFindHolder(pmut); - pLog = dbgMutLogAddEntry(pmut, MUTOP_LOCKWAIT, pFuncDB, ln); + dbgMutLogAddEntry(pmut, MUTOP_LOCKWAIT, pFuncDB, ln); if(pHolder == NULL) pszHolder = "[NONE]"; @@ -481,14 +480,13 @@ static inline void dbgMutexLockLog(pthread_mutex_t *pmut, dbgFuncDB_t *pFuncDB, static inline void dbgMutexPreTryLockLog(pthread_mutex_t *pmut, dbgFuncDB_t *pFuncDB, int ln) { dbgMutLog_t *pHolder; - dbgMutLog_t *pLog; char pszBuf[128]; char pszHolderThrdName[64]; char *pszHolder; pthread_mutex_lock(&mutMutLog); pHolder = dbgMutLogFindHolder(pmut); - pLog = dbgMutLogAddEntry(pmut, MUTOP_TRYLOCK, pFuncDB, ln); + dbgMutLogAddEntry(pmut, MUTOP_TRYLOCK, pFuncDB, ln); if(pHolder == NULL) pszHolder = "[NONE]"; -- cgit v1.2.3 From b9ba5013ad39dbf60a0a3bc06c38870a803451fd Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Thu, 16 Dec 2010 14:23:38 +0100 Subject: bugfix: batch processing flagged invalid message as "bad" under some circumstances also fixed some cosmetic nits --- runtime/debug.c | 8 +++----- 1 file changed, 3 insertions(+), 5 deletions(-) (limited to 'runtime/debug.c') diff --git a/runtime/debug.c b/runtime/debug.c index c69a0296..bfc57071 100644 --- a/runtime/debug.c +++ b/runtime/debug.c @@ -157,9 +157,7 @@ static pthread_key_t keyCallStack; */ static void dbgMutexCancelCleanupHdlr(void *pmut) { - int ret; - ret = pthread_mutex_unlock((pthread_mutex_t*) pmut); - assert(ret == 0); + pthread_mutex_unlock((pthread_mutex_t*) pmut); } @@ -473,7 +471,7 @@ static inline void dbgMutexLockLog(pthread_mutex_t *pmut, dbgFuncDB_t *pFuncDB, dbgMutLogDelEntry(pLog); /* add "lock" entry */ - pLog = dbgMutLogAddEntry(pmut, MUTOP_LOCK, pFuncDB, lockLn); + dbgMutLogAddEntry(pmut, MUTOP_LOCK, pFuncDB, lockLn); dbgFuncDBAddMutexLock(pFuncDB, pmut, lockLn); pthread_mutex_unlock(&mutMutLog); if(bPrintMutexAction) @@ -520,7 +518,7 @@ static inline void dbgMutexTryLockLog(pthread_mutex_t *pmut, dbgFuncDB_t *pFuncD dbgMutLogDelEntry(pLog); /* add "lock" entry */ - pLog = dbgMutLogAddEntry(pmut, MUTOP_LOCK, pFuncDB, lockLn); + dbgMutLogAddEntry(pmut, MUTOP_LOCK, pFuncDB, lockLn); dbgFuncDBAddMutexLock(pFuncDB, pmut, lockLn); pthread_mutex_unlock(&mutMutLog); if(bPrintMutexAction) -- cgit v1.2.3 From a4a94ddfc0dc2256d7a3bc79ed8f9489de9f0f9b Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Fri, 28 Jan 2011 11:00:21 +0100 Subject: interim commit: current debug state of new imptcp I need to verify the concept used in a simpler environment, and this means I probably need to freeze the (non-working) state here for a couple of days. --- runtime/debug.c | 40 +++++++++++++++++++++++----------------- 1 file changed, 23 insertions(+), 17 deletions(-) (limited to 'runtime/debug.c') diff --git a/runtime/debug.c b/runtime/debug.c index 3f1c23bd..a017fc30 100644 --- a/runtime/debug.c +++ b/runtime/debug.c @@ -843,12 +843,15 @@ do_dbgprint(uchar *pszObjName, char *pszMsg, size_t lenMsg) static int bWasNL = 0; char pszThrdName[64]; /* 64 is to be on the safe side, anything over 20 is bad... */ char pszWriteBuf[32*1024]; + size_t lenCopy; + size_t offsWriteBuf = 0; size_t lenWriteBuf; struct timespec t; # if _POSIX_TIMERS <= 0 struct timeval tv; # endif +#if 0 /* 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 @@ -859,8 +862,8 @@ do_dbgprint(uchar *pszObjName, char *pszMsg, size_t lenMsg) */ if(ptLastThrdID != pthread_self()) { if(!bWasNL) { - if(stddbg != -1) write(stddbg, "\n", 1); - if(altdbg != -1) write(altdbg, "\n", 1); + pszWriteBuf[0] = '\n'; + offsWriteBuf = 1; bWasNL = 1; } ptLastThrdID = pthread_self(); @@ -881,25 +884,28 @@ do_dbgprint(uchar *pszObjName, char *pszMsg, size_t lenMsg) t.tv_sec = tv.tv_sec; t.tv_nsec = tv.tv_usec * 1000; # endif - lenWriteBuf = snprintf(pszWriteBuf, sizeof(pszWriteBuf), + lenWriteBuf = snprintf(pszWriteBuf+offsWriteBuf, sizeof(pszWriteBuf) - offsWriteBuf, "%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); + offsWriteBuf += lenWriteBuf; } - 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); + lenWriteBuf = snprintf(pszWriteBuf + offsWriteBuf, sizeof(pszWriteBuf) - offsWriteBuf, "%s: ", pszThrdName); + offsWriteBuf += lenWriteBuf; /* print object name header if we have an object */ if(pszObjName != NULL) { - lenWriteBuf = snprintf(pszWriteBuf, sizeof(pszWriteBuf), "%s: ", pszObjName); - if(stddbg != -1) write(stddbg, pszWriteBuf, lenWriteBuf); - if(altdbg != -1) write(altdbg, pszWriteBuf, lenWriteBuf); + lenWriteBuf = snprintf(pszWriteBuf + offsWriteBuf, sizeof(pszWriteBuf) - offsWriteBuf, "%s: ", pszObjName); + offsWriteBuf += lenWriteBuf; } } - if(stddbg != -1) write(stddbg, pszMsg, lenMsg); - if(altdbg != -1) write(altdbg, pszMsg, lenMsg); +#endif + if(lenMsg > sizeof(pszWriteBuf) - offsWriteBuf) + lenCopy = sizeof(pszWriteBuf) - offsWriteBuf; + else + lenCopy = lenMsg; + memcpy(pszWriteBuf + offsWriteBuf, pszMsg, lenCopy); + offsWriteBuf += lenCopy; + if(stddbg != -1) write(stddbg, pszWriteBuf, offsWriteBuf); + if(altdbg != -1) write(altdbg, pszWriteBuf, offsWriteBuf); bWasNL = (pszMsg[lenMsg - 1] == '\n') ? 1 : 0; } @@ -923,12 +929,12 @@ dbgprint(obj_t *pObj, char *pszMsg, size_t lenMsg) pszObjName = obj.GetName(pObj); } - pthread_mutex_lock(&mutdbgprint); - pthread_cleanup_push(dbgMutexCancelCleanupHdlr, &mutdbgprint); +// pthread_mutex_lock(&mutdbgprint); +// pthread_cleanup_push(dbgMutexCancelCleanupHdlr, &mutdbgprint); do_dbgprint(pszObjName, pszMsg, lenMsg); - pthread_cleanup_pop(1); +// pthread_cleanup_pop(1); } #pragma GCC diagnostic warning "-Wempty-body" -- cgit v1.2.3 From fd256a09ffa109120304d293cf6faf808c5a1a21 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Mon, 31 Jan 2011 15:59:43 +0100 Subject: tcpsrv select-handler experimentally moved to multi-threading as well first tests done with plain tcp, TLS subsystems tests need to be carried out. No serious lab testing done so far. --- runtime/debug.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) (limited to 'runtime/debug.c') diff --git a/runtime/debug.c b/runtime/debug.c index a017fc30..283dae3a 100644 --- a/runtime/debug.c +++ b/runtime/debug.c @@ -851,7 +851,7 @@ do_dbgprint(uchar *pszObjName, char *pszMsg, size_t lenMsg) struct timeval tv; # endif -#if 0 +#if 1 /* 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 -- cgit v1.2.3 From f6dea36394ff969ac627c284ce9872899bc2eb9e Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Mon, 16 Jan 2012 12:39:01 +0100 Subject: runtime license change --- runtime/debug.c | 30 ++++++++++++++---------------- 1 file changed, 14 insertions(+), 16 deletions(-) (limited to 'runtime/debug.c') diff --git a/runtime/debug.c b/runtime/debug.c index 81b45d41..b4a4e3e7 100644 --- a/runtime/debug.c +++ b/runtime/debug.c @@ -13,25 +13,23 @@ * * For details, visit doc/debug.html * - * Copyright 2008 Rainer Gerhards and Adiscon GmbH. + * Copyright 2008-2012 Rainer Gerhards and Adiscon GmbH. * * This file is part of the rsyslog runtime library. * - * The rsyslog runtime library is free software: you can redistribute it and/or modify - * it under the terms of the GNU Lesser General Public License as published by - * the Free Software Foundation, either version 3 of the License, or - * (at your option) any later version. - * - * The rsyslog runtime library is distributed in the hope that it will be useful, - * but WITHOUT ANY WARRANTY; without even the implied warranty of - * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the - * GNU Lesser General Public License for more details. - * - * You should have received a copy of the GNU Lesser General Public License - * along with the rsyslog runtime library. If not, see . - * - * A copy of the GPL can be found in the file "COPYING" in this distribution. - * A copy of the LGPL can be found in the file "COPYING.LESSER" in this distribution. + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * -or- + * see COPYING.ASL20 in the source distribution + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. */ #include "config.h" /* autotools! */ #include -- cgit v1.2.3 From a4980cbde24b48c5540435d27d01651d5ca46d03 Mon Sep 17 00:00:00 2001 From: Tomas Heinrich Date: Tue, 29 May 2012 11:21:50 +0200 Subject: bugfix: if debug message could end up in log file when forking if rsyslog was set to auto-background (thus fork, the default) and debug mode to stdout was enabled, debug messages ended up in the first log file opened. Currently, stdout logging is completely disabled in forking mode (but writing to the debug log file is still possible). This is a change in behaviour, which is under review. If it causes problems to you, please let us know. Signed-off-by: Rainer Gerhards --- runtime/debug.c | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) (limited to 'runtime/debug.c') diff --git a/runtime/debug.c b/runtime/debug.c index d02bd516..fa33b99d 100644 --- a/runtime/debug.c +++ b/runtime/debug.c @@ -68,7 +68,7 @@ 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 int altdbg = -1; /* and the handle for alternate debug output */ -static int stddbg; +int stddbg = 1; /* the handle for regular debug output, set to stdout if not forking, -1 otherwise */ /* list of files/objects that should be printed */ typedef struct dbgPrintName_s { @@ -1297,8 +1297,6 @@ dbgGetRuntimeOptions(void) uchar *optname; /* set some defaults */ - stddbg = 1; - if((pszOpts = (uchar*) getenv("RSYSLOG_DEBUG")) != NULL) { /* we have options set, so let's process them */ while(dbgGetRTOptNamVal(&pszOpts, &optname, &optval)) { -- cgit v1.2.3 From d752786d4f5536828dc6d5cd1665f06d323e8844 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Thu, 11 Oct 2012 09:27:30 +0200 Subject: re-enabled commented-out serialization support in debug handler --- runtime/debug.c | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) (limited to 'runtime/debug.c') diff --git a/runtime/debug.c b/runtime/debug.c index edc4a255..307a8bb8 100644 --- a/runtime/debug.c +++ b/runtime/debug.c @@ -927,12 +927,12 @@ dbgprint(obj_t *pObj, char *pszMsg, size_t lenMsg) pszObjName = obj.GetName(pObj); } -// pthread_mutex_lock(&mutdbgprint); -// pthread_cleanup_push(dbgMutexCancelCleanupHdlr, &mutdbgprint); + pthread_mutex_lock(&mutdbgprint); + pthread_cleanup_push(dbgMutexCancelCleanupHdlr, &mutdbgprint); do_dbgprint(pszObjName, pszMsg, lenMsg); -// pthread_cleanup_pop(1); + pthread_cleanup_pop(1); } #pragma GCC diagnostic warning "-Wempty-body" -- cgit v1.2.3 From f161dfefd2455547847f0355b7a3a87063780a43 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Wed, 28 Nov 2012 10:11:14 +0100 Subject: silence some primarily cosmetic compiler warning messages --- runtime/debug.c | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-) (limited to 'runtime/debug.c') diff --git a/runtime/debug.c b/runtime/debug.c index 307a8bb8..1d306dbd 100644 --- a/runtime/debug.c +++ b/runtime/debug.c @@ -902,8 +902,12 @@ do_dbgprint(uchar *pszObjName, char *pszMsg, size_t lenMsg) lenCopy = lenMsg; memcpy(pszWriteBuf + offsWriteBuf, pszMsg, lenCopy); offsWriteBuf += lenCopy; - if(stddbg != -1) write(stddbg, pszWriteBuf, offsWriteBuf); - if(altdbg != -1) write(altdbg, pszWriteBuf, offsWriteBuf); + /* the write is included in an "if" just to silence compiler + * warnings. Here, we really don't care if the write fails, we + * have no good response to that in any case... -- rgerhards, 2012-11-28 + */ + if(stddbg != -1) if(write(stddbg, pszWriteBuf, offsWriteBuf)){}; + if(altdbg != -1) if(write(altdbg, pszWriteBuf, offsWriteBuf)){}; bWasNL = (pszMsg[lenMsg - 1] == '\n') ? 1 : 0; } -- cgit v1.2.3 From 17d48fc49986af1e8e1cc2150213fe4f6111d7c6 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Sun, 13 Jan 2013 12:14:58 +0100 Subject: added capability to output thread-id-to-function debug info This is a useful debug aid, but nothing of concern for regular users. --- runtime/debug.c | 22 ++++++++++++++++++++++ 1 file changed, 22 insertions(+) (limited to 'runtime/debug.c') diff --git a/runtime/debug.c b/runtime/debug.c index 1d306dbd..fa39e7fe 100644 --- a/runtime/debug.c +++ b/runtime/debug.c @@ -44,6 +44,9 @@ #include #include #include +#ifdef HAVE_SYS_SYSCALL_H +# include +#endif #if _POSIX_TIMERS <= 0 #include #endif @@ -66,6 +69,7 @@ static int bPrintMutexAction = 0; /* shall mutex calls be printed to the debug l 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 int bOutputTidToStderr = 0;/* output TID to stderr on thread creation */ static char *pszAltDbgFileName = NULL; /* if set, debug output is *also* sent to here */ static int altdbg = -1; /* and the handle for alternate debug output */ int stddbg = 1; /* the handle for regular debug output, set to stdout if not forking, -1 otherwise */ @@ -293,6 +297,21 @@ static inline void dbgFuncDBRemoveMutexLock(dbgFuncDB_t *pFuncDB, pthread_mutex_ /* ------------------------- END FuncDB utility functions ------------------------- */ +/* output the current thread ID to "relevant" places + * (what "relevant" means is determinded by various ways) + */ +void +dbgOutputTID(char* name) +{ +# ifdef HAVE_SYSCALL + if(bOutputTidToStderr) + fprintf(stderr, "thread tid %u, name '%s'\n", + (unsigned)syscall(SYS_gettid), name); + DBGPRINTF("thread created, tid %u, name '%s'\n", + (unsigned)syscall(SYS_gettid), name); +# endif +} + /* ########################################################################### * IMPORTANT NOTE * Mutex instrumentation reduces the code's concurrency and thus affects its @@ -1325,6 +1344,7 @@ dbgGetRuntimeOptions(void) "PrintAllDebugInfoOnExit (not yet implemented)\n" "NoLogTimestamp\n" "Nostdoout\n" + "OutputTidToStderr\n" "filetrace=file (may be provided multiple times)\n" "DebugOnDemand - enables debugging on USR1, but does not turn on output\n" "\nSee debug.html in your doc set or http://www.rsyslog.com for details\n"); @@ -1358,6 +1378,8 @@ dbgGetRuntimeOptions(void) stddbg = -1; } else if(!strcasecmp((char*)optname, "noaborttrace")) { bAbortTrace = 0; + } else if(!strcasecmp((char*)optname, "outputtidtostderr")) { + bOutputTidToStderr = 1; } else if(!strcasecmp((char*)optname, "filetrace")) { if(*optval == '\0') { fprintf(stderr, "rsyslogd " VERSION " error: logfile debug option requires filename, " -- cgit v1.2.3 From 8700672c769084dea7d85158f497e3b9a9942c12 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Wed, 27 Feb 2013 17:37:56 +0100 Subject: added ability to configure debug system via rsyslog.conf --- runtime/debug.c | 19 +++++++++++++++++++ 1 file changed, 19 insertions(+) (limited to 'runtime/debug.c') diff --git a/runtime/debug.c b/runtime/debug.c index fa39e7fe..1f22d34e 100644 --- a/runtime/debug.c +++ b/runtime/debug.c @@ -1398,6 +1398,25 @@ dbgGetRuntimeOptions(void) } +void +dbgSetDebugLevel(int level) +{ + Debug = level; + debugging_on = (level == DEBUG_FULL) ? 1 : 0; +} + +void +dbgSetDebugFile(uchar *fn) +{ + if(altdbg != -1) { + dbgprintf("switching to debug file %s\n", fn); + close(altdbg); + } + if((altdbg = open((char*)fn, O_WRONLY|O_CREAT|O_TRUNC|O_NOCTTY|O_CLOEXEC, S_IRUSR|S_IWUSR)) == -1) { + fprintf(stderr, "alternate debug file could not be opened, ignoring. Error: %s\n", strerror(errno)); + } +} + /* end support system to set debug options at runtime */ rsRetVal dbgClassInit(void) -- cgit v1.2.3 From 0114b531b38b16db98b04b680017d6c758987fd9 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Fri, 15 Mar 2013 14:33:23 +0100 Subject: debug system improvement & bug fix for init system status (see below) - rsyslogd startup information is now properly conveyed back to init when privileges are beging dropped Actually, we have moved termination of the parent in front of the priv drop. So it shall work now in all cases. See code comments in commit for more details. - If forking, the parent now waits for a maximum of 60 seconds for termination by the child - improved debugging support in forked (auto-backgrounding) mode The rsyslog debug log file is now continued to be written across the fork. --- runtime/debug.c | 9 +++++++++ 1 file changed, 9 insertions(+) (limited to 'runtime/debug.c') diff --git a/runtime/debug.c b/runtime/debug.c index 1d306dbd..26da31b4 100644 --- a/runtime/debug.c +++ b/runtime/debug.c @@ -1296,6 +1296,15 @@ dbgmalloc(size_t size) } +/* report fd used for debug log. This is needed in case of + * auto-backgrounding, where the debug log shall not be closed. + */ +int +dbgGetDbglogFd(void) +{ + return altdbg; +} + /* read in the runtime options * rgerhards, 2008-02-28 */ -- cgit v1.2.3 From aef0be0c1799fbb20955fc1dc014cb9c9772af88 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Tue, 19 Mar 2013 16:20:25 +0100 Subject: bugfix: solve compile problems on non-Linux platforms Thanks to Michael Biebl for alerting us on this issue. --- runtime/debug.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) (limited to 'runtime/debug.c') diff --git a/runtime/debug.c b/runtime/debug.c index 3cb22232..876f61d0 100644 --- a/runtime/debug.c +++ b/runtime/debug.c @@ -303,7 +303,7 @@ static inline void dbgFuncDBRemoveMutexLock(dbgFuncDB_t *pFuncDB, pthread_mutex_ void dbgOutputTID(char* name) { -# ifdef HAVE_SYSCALL +# if defined(HAVE_SYSCALL) && defined(HAVE_SYS_gettid) if(bOutputTidToStderr) fprintf(stderr, "thread tid %u, name '%s'\n", (unsigned)syscall(SYS_gettid), name); -- cgit v1.2.3 From 1f2b6f1a9b110fec5995582285f0fe9dcd628c99 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Wed, 15 May 2013 07:45:33 +0200 Subject: bugfix: potential hang *in debug mode* on rsyslogd termination --- runtime/debug.c | 17 ++++++++++------- 1 file changed, 10 insertions(+), 7 deletions(-) (limited to 'runtime/debug.c') diff --git a/runtime/debug.c b/runtime/debug.c index 876f61d0..68474989 100644 --- a/runtime/debug.c +++ b/runtime/debug.c @@ -1430,6 +1430,7 @@ dbgSetDebugFile(uchar *fn) rsRetVal dbgClassInit(void) { + pthread_mutexattr_t mutAttr; rsRetVal iRet; /* do not use DEFiRet, as this makes calls into the debug system! */ struct sigaction sigAct; @@ -1437,14 +1438,16 @@ rsRetVal dbgClassInit(void) (void) pthread_key_create(&keyCallStack, dbgCallStackDestruct); /* MUST be the first action done! */ - /* we initialize all Mutexes with code, as some platforms seem to have - * bugs in the static initializer macros. So better be on the safe side... - * rgerhards, 2008-03-06 + /* the mutexes must be recursive, because it may be called from within + * signal handlers, which can lead to a hang if the signal interrupted dbgprintf + * (yes, we have really seen that situation in practice!). -- rgerhards, 2013-05-17 */ - pthread_mutex_init(&mutFuncDBList, NULL); - pthread_mutex_init(&mutMutLog, NULL); - pthread_mutex_init(&mutCallStack, NULL); - pthread_mutex_init(&mutdbgprint, NULL); + pthread_mutexattr_init(&mutAttr); + pthread_mutexattr_settype(&mutAttr, PTHREAD_MUTEX_RECURSIVE); + pthread_mutex_init(&mutFuncDBList, &mutAttr); + pthread_mutex_init(&mutMutLog, &mutAttr); + pthread_mutex_init(&mutCallStack, &mutAttr); + pthread_mutex_init(&mutdbgprint, &mutAttr); /* 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 -- cgit v1.2.3