From 131e581845678a30e3dea0e499e78acc429cd5fa Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Mon, 14 May 2012 09:05:38 +0200 Subject: bugfix/omudpspoof: problems, including abort, happend when run on multiple threads. Root cause is that libnet is not thread-safe. Omudpspoof now guards libnet calls with their own mutex. --- ChangeLog | 3 +++ plugins/omudpspoof/omudpspoof.c | 11 +++++++++++ 2 files changed, 14 insertions(+) diff --git a/ChangeLog b/ChangeLog index ea21b3ea..c2290bac 100644 --- a/ChangeLog +++ b/ChangeLog @@ -6,6 +6,9 @@ Version 5.8.12 [V5-stable] 2012-05-?? full delayable sources somewhat smarter and permits, assuming sufficient timouts, to persist message up to the max queue capacity. Also some nits in debug instrumentation have been fixed. +- bugfix/omudpspoof: problems, including abort, happend when run on + multiple threads. Root cause is that libnet is not thread-safe. + omudpspoof now guards libnet calls with their own mutex. - bugfix/tcpflood: sending small test files did not work correctly --------------------------------------------------------------------------- Version 5.8.11 [V5-stable] 2012-05-03 diff --git a/plugins/omudpspoof/omudpspoof.c b/plugins/omudpspoof/omudpspoof.c index 48d7a68e..11be59d6 100644 --- a/plugins/omudpspoof/omudpspoof.c +++ b/plugins/omudpspoof/omudpspoof.c @@ -118,6 +118,7 @@ static int iSourcePortEnd = DFLT_SOURCE_PORT_END; /* add some variables needed for libnet */ libnet_t *libnet_handle; char errbuf[LIBNET_ERRBUF_SIZE]; +pthread_mutex_t mutLibnet; /* forward definitions */ static rsRetVal doTryResume(instanceData *pData); @@ -180,6 +181,8 @@ ENDdbgPrintInstInfo /* Send a message via UDP + * Note: libnet is not thread-safe, so we need to ensure that only one + * instance ever is calling libnet code. * rgehards, 2007-12-20 */ static inline rsRetVal @@ -193,6 +196,7 @@ UDPSend(instanceData *pData, uchar *pszSourcename, char *msg, size_t len) struct sockaddr_in *tempaddr,source_ip; libnet_ptag_t ip, ipo; libnet_ptag_t udp; + sbool bNeedUnlock = 0; DEFiRet; if(pData->pSockArray == NULL) { @@ -207,6 +211,8 @@ UDPSend(instanceData *pData, uchar *pszSourcename, char *msg, size_t len) inet_pton(AF_INET, (char*)pszSourcename, &(source_ip.sin_addr)); bSendSuccess = FALSE; + d_pthread_mutex_lock(&mutLibnet); + bNeedUnlock = 1; for (r = pData->f_addr; r; r = r->ai_next) { tempaddr = (struct sockaddr_in *)r->ai_addr; libnet_clear_packet(libnet_handle); @@ -267,6 +273,9 @@ UDPSend(instanceData *pData, uchar *pszSourcename, char *msg, size_t len) } finalize_it: + if(bNeedUnlock) { + d_pthread_mutex_unlock(&mutLibnet); + } RETiRet; } @@ -440,6 +449,7 @@ BEGINmodExit CODESTARTmodExit /* destroy the libnet state needed for forged UDP sources */ libnet_destroy(libnet_handle); + pthread_mutex_destroy(&mutLibnet); /* release what we no longer need */ objRelease(errmsg, CORE_COMPONENT); objRelease(glbl, CORE_COMPONENT); @@ -488,6 +498,7 @@ CODEmodInit_QueryRegCFSLineHdlr errmsg.LogError(0, NO_ERRCODE, "Error initializing libnet, can not continue "); ABORT_FINALIZE(RS_RET_ERR_LIBNET_INIT); } + pthread_mutex_init(&mutLibnet, NULL); CHKiRet(regCfSysLineHdlr((uchar *)"actionomudpspoofdefaulttemplate", 0, eCmdHdlrGetWord, NULL, &pszTplName, NULL)); CHKiRet(regCfSysLineHdlr((uchar *)"actionomudpspoofsourcenametemplate", 0, eCmdHdlrGetWord, NULL, &pszSourceNameTemplate, NULL)); -- cgit 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 --- ChangeLog | 8 ++++++++ runtime/debug.c | 4 +--- runtime/debug.h | 1 + tools/syslogd.c | 3 +++ 4 files changed, 13 insertions(+), 3 deletions(-) diff --git a/ChangeLog b/ChangeLog index c2290bac..0a3cda9d 100644 --- a/ChangeLog +++ b/ChangeLog @@ -9,6 +9,14 @@ Version 5.8.12 [V5-stable] 2012-05-?? - bugfix/omudpspoof: problems, including abort, happend when run on multiple threads. Root cause is that libnet is not thread-safe. omudpspoof now guards libnet calls with their own mutex. +- 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. + Thanks to Tomas Heinrich for the patch. - bugfix/tcpflood: sending small test files did not work correctly --------------------------------------------------------------------------- Version 5.8.11 [V5-stable] 2012-05-03 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)) { diff --git a/runtime/debug.h b/runtime/debug.h index 717c0fef..26672c3e 100644 --- a/runtime/debug.h +++ b/runtime/debug.h @@ -35,6 +35,7 @@ /* external static data elements (some time to be replaced) */ extern int Debug; /* debug flag - read-only after startup */ extern int debugging_on; /* read-only, except on sig USR1 */ +extern int stddbg; /* the handle for regular debug output, set to stdout if not forking, -1 otherwise */ /* data types */ diff --git a/tools/syslogd.c b/tools/syslogd.c index 98f06627..f3f27598 100644 --- a/tools/syslogd.c +++ b/tools/syslogd.c @@ -2514,6 +2514,9 @@ doGlblProcessInit(void) sigAct.sa_handler = doexit; sigaction(SIGTERM, &sigAct, NULL); + /* stop writing debug messages to stdout (if debugging is on) */ + stddbg = -1; + if (fork()) { /* Parent process */ -- cgit From 21fc2ac97775bf223f9b4882cb4b35898bce8984 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Thu, 31 May 2012 13:01:07 +0200 Subject: cosmetic: slightly improved debug output --- tools/syslogd.c | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/tools/syslogd.c b/tools/syslogd.c index f3f27598..7872cb5f 100644 --- a/tools/syslogd.c +++ b/tools/syslogd.c @@ -2506,7 +2506,7 @@ doGlblProcessInit(void) if( !(Debug == DEBUG_FULL || NoFork) ) { - DBGPRINTF("Checking pidfile.\n"); + DBGPRINTF("Checking pidfile '%s'.\n", PidFile); if (!check_pid(PidFile)) { memset(&sigAct, 0, sizeof (sigAct)); @@ -2579,7 +2579,7 @@ doGlblProcessInit(void) } /* tuck my process id away */ - DBGPRINTF("Writing pidfile %s.\n", PidFile); + DBGPRINTF("Writing pidfile '%s'.\n", PidFile); if (!check_pid(PidFile)) { if (!write_pid(PidFile)) -- cgit From fd46d10a4f49da35758ab9201f6f863d69d5d4f5 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Fri, 1 Jun 2012 15:19:54 +0200 Subject: bugfix: delayble source could block action queue, ... even if there was a disk queue associated with it. The root cause of this problem was that it makes no sense to delay messages once they arrive in the action queue - the "input" that is being held in that case is the main queue worker, what makes no sense. Thanks to Marcin for alerting us on this problem and providing instructions to reproduce it. --- ChangeLog | 7 +++++++ action.c | 2 +- 2 files changed, 8 insertions(+), 1 deletion(-) diff --git a/ChangeLog b/ChangeLog index 0a3cda9d..25a67cfa 100644 --- a/ChangeLog +++ b/ChangeLog @@ -1,5 +1,12 @@ --------------------------------------------------------------------------- Version 5.8.12 [V5-stable] 2012-05-?? +- bugfix: delayble source could block action queue, even if there was + a disk queue associated with it. The root cause of this problem was + that it makes no sense to delay messages once they arrive in the + action queue - the "input" that is being held in that case is the main + queue worker, what makes no sense. + Thanks to Marcin for alerting us on this problem and providing + instructions to reproduce it. - bugfix: disk queue was not persisted on shutdown, regression of fix to http://bugzilla.adiscon.com/show_bug.cgi?id=299 The new code also handles the case of shutdown of blocking light and diff --git a/action.c b/action.c index e859cce4..459ab0d6 100644 --- a/action.c +++ b/action.c @@ -1265,7 +1265,7 @@ doSubmitToActionQ(action_t *pAction, msg_t *pMsg) if(pAction->pQueue->qType == QUEUETYPE_DIRECT) iRet = qqueueEnqObjDirect(pAction->pQueue, (void*) MsgAddRef(pMsg)); else - iRet = qqueueEnqObj(pAction->pQueue, pMsg->flowCtlType, (void*) MsgAddRef(pMsg)); + iRet = qqueueEnqObj(pAction->pQueue, eFLOWCTL_NO_DELAY, (void*) MsgAddRef(pMsg)); RETiRet; } -- cgit From 9020647cdcdb0ef132491838e36c870f4e4e90ea Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Fri, 1 Jun 2012 15:51:57 +0200 Subject: some better code to handle queue congestion This is a minor optimization to spare some cycles if the timeout is set to immediate discard --- runtime/queue.c | 25 +++++++++++++++---------- 1 file changed, 15 insertions(+), 10 deletions(-) diff --git a/runtime/queue.c b/runtime/queue.c index 9d92af36..d78ab2e3 100644 --- a/runtime/queue.c +++ b/runtime/queue.c @@ -2323,20 +2323,25 @@ doEnqSingleObj(qqueue_t *pThis, flowControl_t flowCtlType, void *pUsr) while( (pThis->iMaxQueueSize > 0 && pThis->iQueueSize >= pThis->iMaxQueueSize) || (pThis->qType == QUEUETYPE_DISK && pThis->sizeOnDiskMax != 0 && pThis->tVars.disk.sizeOnDisk > pThis->sizeOnDiskMax)) { - DBGOPRINT((obj_t*) pThis, "enqueueMsg: queue FULL - waiting to drain.\n"); - if(glbl.GetGlobalInputTermState()) { - DBGOPRINT((obj_t*) pThis, "enqueueMsg: queue FULL, discard due to FORCE_TERM.\n"); - ABORT_FINALIZE(RS_RET_FORCE_TERM); - } - timeoutComp(&t, pThis->toEnq); STATSCOUNTER_INC(pThis->ctrFull, pThis->mutCtrFull); -// TODO : handle enqOnly => discard! - if(pthread_cond_timedwait(&pThis->notFull, pThis->mut, &t) != 0) { - DBGOPRINT((obj_t*) pThis, "enqueueMsg: cond timeout, dropping message!\n"); + if(pThis->toEnq == 0 || pThis->bEnqOnly) { + DBGOPRINT((obj_t*) pThis, "enqueueMsg: queue FULL - configured for immediate discarding.\n"); objDestruct(pUsr); ABORT_FINALIZE(RS_RET_QUEUE_FULL); - } + } else { + DBGOPRINT((obj_t*) pThis, "enqueueMsg: queue FULL - waiting %dms to drain.\n", pThis->toEnq); + if(glbl.GetGlobalInputTermState()) { + DBGOPRINT((obj_t*) pThis, "enqueueMsg: queue FULL, discard due to FORCE_TERM.\n"); + ABORT_FINALIZE(RS_RET_FORCE_TERM); + } + timeoutComp(&t, pThis->toEnq); + if(pthread_cond_timedwait(&pThis->notFull, pThis->mut, &t) != 0) { + DBGOPRINT((obj_t*) pThis, "enqueueMsg: cond timeout, dropping message!\n"); + objDestruct(pUsr); + ABORT_FINALIZE(RS_RET_QUEUE_FULL); + } dbgoprint((obj_t*) pThis, "enqueueMsg: wait solved queue full condition, enqueing\n"); + } } /* and finally enqueue the message */ -- cgit