diff options
Diffstat (limited to 'runtime/debug.c')
| -rw-r--r-- | runtime/debug.c | 478 |
1 files changed, 478 insertions, 0 deletions
diff --git a/runtime/debug.c b/runtime/debug.c new file mode 100644 index 0000000..6e6c9fd --- /dev/null +++ b/runtime/debug.c @@ -0,0 +1,478 @@ +/* debug.c + * + * This file proides debug support. + * + * 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-2018 Rainer Gerhards and Adiscon GmbH. + * + * This file is part of the rsyslog runtime library. + * + * 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 <stdio.h> +#include <stdlib.h> +#include <stdarg.h> +#include <string.h> +#include <signal.h> +#include <errno.h> +#include <pthread.h> +#include <ctype.h> +#include <assert.h> +#include <unistd.h> +#include <fcntl.h> +#include <sys/stat.h> +#ifdef HAVE_SYS_SYSCALL_H +# include <sys/syscall.h> +#endif +#if _POSIX_TIMERS <= 0 +#include <sys/time.h> +#endif + +#include "rsyslog.h" +#include "debug.h" +#include "cfsysline.h" +#include "obj.h" + + +/* static data (some time to be replaced) */ +DEFobjCurrIf(obj) +int Debug = DEBUG_OFF; /* debug flag - read-only after startup */ +int debugging_on = 0; /* read-only, except on sig USR1 */ +int dbgTimeoutToStderr = 0; +static int bPrintTime = 1; /* print a timestamp together with debug message */ +static int bOutputTidToStderr = 0;/* output TID to stderr on thread creation */ +char *pszAltDbgFileName = NULL; /* if set, debug output is *also* sent to here */ +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 */ +static uint64_t dummy_errcount = 0; /* just to avoid some static analyzer complaints */ +static pthread_key_t keyThrdName; + + +/* output the current thread ID to "relevant" places + * (what "relevant" means is determinded by various ways) + */ +void +dbgOutputTID(char* name __attribute__((unused))) +{ +# if defined(HAVE_SYSCALL) && defined(HAVE_SYS_gettid) + 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 +} + + +/* build a string with the thread name. If none is set, the thread ID is + * used instead. Caller must provide buffer space. + */ +static void ATTR_NONNULL() +dbgGetThrdName(char *const pszBuf, const size_t lenBuf, const pthread_t thrdID) +{ + assert(pszBuf != NULL); + + const char *const thrdName = pthread_getspecific(keyThrdName); + if(thrdName == NULL) { + snprintf(pszBuf, lenBuf, "%lx", (long) thrdID); + } else { + snprintf(pszBuf, lenBuf, "%-15s", thrdName); + } +} + + +/* set a name for the current thread */ +void ATTR_NONNULL() +dbgSetThrdName(const uchar *const pszName) +{ + (void) pthread_setspecific(keyThrdName, strdup((char*) pszName)); +} + + +/* destructor for thread name (called by pthreads!) */ +static void dbgThrdNameDestruct(void *arg) +{ + free(arg); +} + + +/* write the debug message. This is a helper to dbgprintf and dbgoprint which + * contains common code. added 2008-09-26 rgerhards + * Note: We need to split the function due to the bad nature of POSIX + * cancel cleanup handlers. + */ +static void DBGL_UNUSED +dbgprint(obj_t *pObj, char *pszMsg, const char *pszFileName, const size_t lenMsg) +{ + uchar *pszObjName = NULL; + 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[32*1024]; + size_t lenCopy; + size_t offsWriteBuf = 0; + size_t lenWriteBuf; + struct timespec t; +# if _POSIX_TIMERS <= 0 + struct timeval tv; +# endif + + if(pObj != NULL) { + pszObjName = obj.GetName(pObj); + } + + /* 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) { + pszWriteBuf[0] = '\n'; + offsWriteBuf = 1; + bWasNL = 1; + } + ptLastThrdID = pthread_self(); + } + + dbgGetThrdName(pszThrdName, sizeof(pszThrdName), ptLastThrdID); + + 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+offsWriteBuf, sizeof(pszWriteBuf) - offsWriteBuf, + "%4.4ld.%9.9ld:", (long) (t.tv_sec % 10000), t.tv_nsec); + offsWriteBuf += 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 + offsWriteBuf, sizeof(pszWriteBuf) - offsWriteBuf, + "%s: ", pszObjName); + offsWriteBuf += lenWriteBuf; + } + lenWriteBuf = snprintf(pszWriteBuf + offsWriteBuf, sizeof(pszWriteBuf) - offsWriteBuf, + "%s: ", pszFileName); + offsWriteBuf += lenWriteBuf; + } + if(lenMsg > sizeof(pszWriteBuf) - offsWriteBuf) + lenCopy = sizeof(pszWriteBuf) - offsWriteBuf; + else + lenCopy = lenMsg; + memcpy(pszWriteBuf + offsWriteBuf, pszMsg, lenCopy); + offsWriteBuf += lenCopy; + /* 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)) { + ++dummy_errcount; + } + } + if(altdbg != -1) { + if(write(altdbg, pszWriteBuf, offsWriteBuf)) { + ++dummy_errcount; + } + } + + bWasNL = (pszMsg[lenMsg - 1] == '\n') ? 1 : 0; +} + + +static int DBGL_UNUSED +checkDbgFile(const char *srcname) +{ + if(glblDbgFilesNum == 0) { + return 1; + } + if(glblDbgWhitelist) { + if(bsearch(srcname, glblDbgFiles, glblDbgFilesNum, sizeof(char*), bs_arrcmp_glblDbgFiles) == NULL) { + return 0; + } else { + return 1; + } + } else { + if(bsearch(srcname, glblDbgFiles, glblDbgFilesNum, sizeof(char*), bs_arrcmp_glblDbgFiles) != NULL) { + return 0; + } else { + return 1; + } + } +} +/* 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 + */ +#ifndef DEBUGLESS +void +r_dbgoprint( const char *srcname, obj_t *pObj, const char *fmt, ...) +{ + va_list ap; + char pszWriteBuf[32*1024]; + size_t lenWriteBuf; + + if(!(Debug && debugging_on)) + return; + + if(!checkDbgFile(srcname)) { + return; + } + + 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, srcname, lenWriteBuf); +} +#endif + +/* print some debug output when no object is given + * WARNING: duplicate code, see dbgoprint above! + */ +#ifndef DEBUGLESS +void +r_dbgprintf(const char *srcname, const char *fmt, ...) +{ + va_list ap; + char pszWriteBuf[32*1024]; + size_t lenWriteBuf; + + if(!(Debug && debugging_on)) { + return; + } + + if(!checkDbgFile(srcname)) { + return; + } + + 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, srcname, lenWriteBuf); +} +#endif + +/* 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 ATTR_NONNULL() +dbgGetRTOptNamVal(const uchar **const ppszOpt, uchar **const ppOptName) +{ + assert(ppszOpt != NULL); + assert(*ppszOpt != NULL); + int bRet = 0; + const uchar *p = *ppszOpt; + size_t i; + static uchar optname[128] = ""; + + /* skip whitespace */ + while(*p && isspace(*p)) + ++p; + + /* name: up until whitespace */ + i = 0; + while(i < (sizeof(optname) - 1) && *p && !isspace(*p)) { + optname[i++] = *p++; + } + + if(i > 0) { + bRet = 1; + optname[i] = '\0'; + } + + /* done */ + *ppszOpt = p; + *ppOptName = optname; + return bRet; +} + + +/* 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 + */ +static void +dbgGetRuntimeOptions(void) +{ + const uchar *pszOpts; + uchar *optname; + + /* set some defaults */ + if((pszOpts = (uchar*) getenv("RSYSLOG_DEBUG")) != NULL) { + /* we have options set, so let's process them */ + while(dbgGetRTOptNamVal(&pszOpts, &optname)) { + if(!strcasecmp((char*)optname, "help")) { + fprintf(stderr, + "rsyslogd " VERSION " runtime debug support - help requested, " + "rsyslog terminates\n\nenvironment variables:\n" + "additional 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" + "NoLogTimestamp\n" + "Nostdout\n" + "OutputTidToStderr\n" + "DebugOnDemand - enables debugging on USR1, but does not turn on output\n" + "\nSee debug.html in your doc set or https://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 = DEBUG_FULL; + debugging_on = 1; + } else if(!strcasecmp((char*)optname, "debugondemand")) { + /* Enables debugging, but turns off debug output */ + Debug = DEBUG_ONDEMAND; + debugging_on = 1; + dbgprintf("Note: debug on demand turned on via configuration file, " + "use USR1 signal to activate.\n"); + debugging_on = 0; + } else if(!strcasecmp((char*)optname, "nologtimestamp")) { + bPrintTime = 0; + } else if(!strcasecmp((char*)optname, "nostdout")) { + stddbg = -1; + } else if(!strcasecmp((char*)optname, "outputtidtostderr")) { + bOutputTidToStderr = 1; + } else { + fprintf(stderr, "rsyslogd " VERSION " error: invalid debug option '%s' " + "- ignored\n", optname); + } + } + } +} + + +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) +{ + rsRetVal iRet; /* do not use DEFiRet, as this makes calls into the debug system! */ + + + (void) pthread_key_create(&keyThrdName, dbgThrdNameDestruct); + + /* 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 */ + + const char *dbgto2stderr; + dbgto2stderr = getenv("RSYSLOG_DEBUG_TIMEOUTS_TO_STDERR"); + dbgTimeoutToStderr = (dbgto2stderr != NULL && !strcmp(dbgto2stderr, "on")) ? 1 : 0; + if(dbgTimeoutToStderr) { + fprintf(stderr, "rsyslogd: NOTE: RSYSLOG_DEBUG_TIMEOUTS_TO_STDERR activated\n"); + } + 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 = 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)); + } + } + + dbgSetThrdName((uchar*)"main thread"); + +finalize_it: + return(iRet); +} + + +rsRetVal dbgClassExit(void) +{ + pthread_key_delete(keyThrdName); + if(altdbg != -1) + close(altdbg); + return RS_RET_OK; +} |