From d97ad63e218112d7cd3a390854b2918407804976 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Mon, 8 Mar 2010 17:56:11 +0100 Subject: added new property replacer option "date-rfc3164-buggyday" primarily to ease migration from syslog-ng. See property replacer doc for details. [backport from 5.5.3 because urgently needed by some] --- ChangeLog | 5 +++++ doc/property_replacer.html | 13 +++++++++++++ runtime/datetime.c | 8 ++++++-- runtime/datetime.h | 6 ++++-- runtime/msg.c | 10 +++++++--- template.c | 2 ++ template.h | 2 +- tests/Makefile.am | 2 ++ tests/parsertest.sh | 4 ++++ tests/testsuites/diag-common2.conf | 16 ++++++++++++++++ tests/testsuites/parse-3164-buggyday.conf | 8 ++++++++ tests/testsuites/samples.parse-3164-buggyday | 6 ++++++ 12 files changed, 74 insertions(+), 8 deletions(-) create mode 100644 tests/testsuites/diag-common2.conf create mode 100644 tests/testsuites/parse-3164-buggyday.conf create mode 100644 tests/testsuites/samples.parse-3164-buggyday diff --git a/ChangeLog b/ChangeLog index 2cf5f024..e9ccd5c7 100644 --- a/ChangeLog +++ b/ChangeLog @@ -1,4 +1,9 @@ --------------------------------------------------------------------------- +Version 4.6.2 [v4-stable] (rgerhards), 2010-03-?? +- added new property replacer option "date-rfc3164-buggyday" primarily + to ease migration from syslog-ng. See property replacer doc for + details. [backport from 5.5.3 because urgently needed by some] +--------------------------------------------------------------------------- Version 4.6.1 [v4-stable] (rgerhards), 2010-03-04 - re-enabled old pipe output (using new module ompipe, built-in) after some problems with pipes (and especially in regard to xconsole) were diff --git a/doc/property_replacer.html b/doc/property_replacer.html index 7b604ea0..4d242a34 100644 --- a/doc/property_replacer.html +++ b/doc/property_replacer.html @@ -335,6 +335,19 @@ Especially useful for PIX. format as RFC 3164 date + +date-rfc3164-buggyday +similar to date-rfc3164, but emulates a common coding error: RFC 3164 demands +that a space is written for single-digit days. With this option, a zero is +written instead. This format seems to be used by syslog-ng and the +date-rfc3164-buggyday option can be used in migration scenarios where otherwise +lots of scripts would need to be adjusted. It is recommended not to use this +option when forwarding to remote hosts - they may treat the date as invalid +(especially when parsing strictly according to RFC 3164). +
This feature was introduced in rsyslog 4.6.2 and v4 versions above and +5.5.3 and all versions above. + + date-rfc3339 format as RFC 3339 date diff --git a/runtime/datetime.c b/runtime/datetime.c index 7b0d8d11..eff72f91 100644 --- a/runtime/datetime.c +++ b/runtime/datetime.c @@ -793,8 +793,12 @@ int formatTimestamp3339(struct syslogTime *ts, char* pBuf) * buffer that will receive the resulting string. The function * returns the size of the timestamp written in bytes (without * the string termnator). If 0 is returend, an error occured. + * rgerhards, 2010-03-05: Added support to for buggy 3164 dates, + * where a zero-digit is written instead of a space for the first + * day character if day < 10. syslog-ng seems to do that, and some + * parsing scripts (in migration cases) rely on that. */ -int formatTimestamp3164(struct syslogTime *ts, char* pBuf) +int formatTimestamp3164(struct syslogTime *ts, char* pBuf, int bBuggyDay) { static char* monthNames[12] = { "Jan", "Feb", "Mar", "Apr", "May", "Jun", "Jul", "Aug", "Sep", "Oct", "Nov", "Dec" }; @@ -807,7 +811,7 @@ int formatTimestamp3164(struct syslogTime *ts, char* pBuf) pBuf[2] = monthNames[(ts->month - 1) % 12][2]; pBuf[3] = ' '; iDay = (ts->day / 10) % 10; /* we need to write a space if the first digit is 0 */ - pBuf[4] = iDay ? iDay + '0' : ' '; + pBuf[4] = (bBuggyDay || iDay > 0) ? iDay + '0' : ' '; pBuf[5] = ts->day % 10 + '0'; pBuf[6] = ' '; pBuf[7] = (ts->hour / 10) % 10 + '0'; diff --git a/runtime/datetime.h b/runtime/datetime.h index 8140eb71..9dcce3c5 100644 --- a/runtime/datetime.h +++ b/runtime/datetime.h @@ -39,15 +39,17 @@ BEGINinterface(datetime) /* name must also be changed in ENDinterface macro! */ int (*formatTimestampToMySQL)(struct syslogTime *ts, char* pDst); int (*formatTimestampToPgSQL)(struct syslogTime *ts, char *pDst); int (*formatTimestamp3339)(struct syslogTime *ts, char* pBuf); - int (*formatTimestamp3164)(struct syslogTime *ts, char* pBuf); + int (*formatTimestamp3164)(struct syslogTime *ts, char* pBuf, int); int (*formatTimestampSecFrac)(struct syslogTime *ts, char* pBuf); ENDinterface(datetime) -#define datetimeCURR_IF_VERSION 2 /* increment whenever you change the interface structure! */ +#define datetimeCURR_IF_VERSION 4 /* increment whenever you change the interface structure! */ /* interface changes: * 1 - initial version * 2 - not compatible to 1 - bugfix required ParseTIMESTAMP3164 to accept char ** as * last parameter. Did not try to remain compatible as this is not something any * third-party module should call. -- rgerhards, 2008.-09-12 + * 3 - taken by v5 branch! + * 4 - formatTimestamp3164 takes a third int parameter */ /* prototypes */ diff --git a/runtime/msg.c b/runtime/msg.c index 70207075..3a2331f4 100644 --- a/runtime/msg.c +++ b/runtime/msg.c @@ -1213,10 +1213,12 @@ static inline char *getTimeReported(msg_t *pM, enum tplFormatTypes eFmt) switch(eFmt) { case tplFmtDefault: case tplFmtRFC3164Date: + case tplFmtRFC3164BuggyDate: MsgLock(pM); if(pM->pszTIMESTAMP3164 == NULL) { pM->pszTIMESTAMP3164 = pM->pszTimestamp3164; - datetime.formatTimestamp3164(&pM->tTIMESTAMP, pM->pszTIMESTAMP3164); + datetime.formatTimestamp3164(&pM->tTIMESTAMP, pM->pszTIMESTAMP3164, + (eFmt == tplFmtRFC3164BuggyDate)); } MsgUnlock(pM); return(pM->pszTIMESTAMP3164); @@ -1279,7 +1281,7 @@ static inline char *getTimeGenerated(msg_t *pM, enum tplFormatTypes eFmt) MsgUnlock(pM); return ""; } - datetime.formatTimestamp3164(&pM->tRcvdAt, pM->pszRcvdAt3164); + datetime.formatTimestamp3164(&pM->tRcvdAt, pM->pszRcvdAt3164, 0); } MsgUnlock(pM); return(pM->pszRcvdAt3164); @@ -1306,13 +1308,15 @@ static inline char *getTimeGenerated(msg_t *pM, enum tplFormatTypes eFmt) MsgUnlock(pM); return(pM->pszRcvdAt_PgSQL); case tplFmtRFC3164Date: + case tplFmtRFC3164BuggyDate: MsgLock(pM); if(pM->pszRcvdAt3164 == NULL) { if((pM->pszRcvdAt3164 = malloc(16)) == NULL) { MsgUnlock(pM); return ""; } - datetime.formatTimestamp3164(&pM->tRcvdAt, pM->pszRcvdAt3164); + datetime.formatTimestamp3164(&pM->tRcvdAt, pM->pszRcvdAt3164, + (eFmt == tplFmtRFC3164BuggyDate)); } MsgUnlock(pM); return(pM->pszRcvdAt3164); diff --git a/template.c b/template.c index 9c4a2a39..5a43cba3 100644 --- a/template.c +++ b/template.c @@ -487,6 +487,8 @@ static void doOptions(unsigned char **pp, struct templateEntry *pTpe) pTpe->data.field.eDateFormat = tplFmtPgSQLDate; } else if(!strcmp((char*)Buf, "date-rfc3164")) { pTpe->data.field.eDateFormat = tplFmtRFC3164Date; + } else if(!strcmp((char*)Buf, "date-rfc3164-buggyday")) { + pTpe->data.field.eDateFormat = tplFmtRFC3164BuggyDate; } else if(!strcmp((char*)Buf, "date-rfc3339")) { pTpe->data.field.eDateFormat = tplFmtRFC3339Date; } else if(!strcmp((char*)Buf, "date-subseconds")) { diff --git a/template.h b/template.h index 271e8271..71e8b428 100644 --- a/template.h +++ b/template.h @@ -48,7 +48,7 @@ struct template { enum EntryTypes { UNDEFINED = 0, CONSTANT = 1, FIELD = 2 }; enum tplFormatTypes { tplFmtDefault = 0, tplFmtMySQLDate = 1, tplFmtRFC3164Date = 2, tplFmtRFC3339Date = 3, tplFmtPgSQLDate = 4, - tplFmtSecFrac = 5}; + tplFmtSecFrac = 5, tplFmtRFC3164BuggyDate = 6}; enum tplFormatCaseConvTypes { tplCaseConvNo = 0, tplCaseConvUpper = 1, tplCaseConvLower = 2 }; #include "msg.h" diff --git a/tests/Makefile.am b/tests/Makefile.am index 7cc25e41..8849c3dc 100644 --- a/tests/Makefile.am +++ b/tests/Makefile.am @@ -94,6 +94,8 @@ EXTRA_DIST= 1.rstest 2.rstest 3.rstest err1.rstest \ testsuites/reallife.parse3 \ testsuites/parse_invld_regex.conf \ testsuites/samples.parse_invld_regex \ + testsuites/parse-3164-buggyday.conf \ + testsuites/samples.parse-3164-buggyday \ testsuites/omod-if-array.conf \ testsuites/1.omod-if-array \ testsuites/1.field1 \ diff --git a/tests/parsertest.sh b/tests/parsertest.sh index 5966a11b..83c5e614 100755 --- a/tests/parsertest.sh +++ b/tests/parsertest.sh @@ -6,6 +6,8 @@ source $srcdir/diag.sh nettester parse3 udp source $srcdir/diag.sh nettester parse3 tcp source $srcdir/diag.sh nettester parse_invld_regex udp source $srcdir/diag.sh nettester parse_invld_regex tcp +source $srcdir/diag.sh nettester parse-3164-buggyday udp +source $srcdir/diag.sh nettester parse-3164-buggyday tcp echo \[parsertest.sh]: redoing tests in IPv4-only mode source $srcdir/diag.sh nettester parse1 udp -4 @@ -14,4 +16,6 @@ source $srcdir/diag.sh nettester parse3 udp -4 source $srcdir/diag.sh nettester parse3 tcp -4 source $srcdir/diag.sh nettester parse_invld_regex udp -4 source $srcdir/diag.sh nettester parse_invld_regex tcp -4 +source $srcdir/diag.sh nettester parse-3164-buggyday udp -4 +source $srcdir/diag.sh nettester parse-3164-buggyday tcp -4 source $srcdir/diag.sh exit diff --git a/tests/testsuites/diag-common2.conf b/tests/testsuites/diag-common2.conf new file mode 100644 index 00000000..94f7e87f --- /dev/null +++ b/tests/testsuites/diag-common2.conf @@ -0,0 +1,16 @@ +# This is a config include file. It sets up rsyslog so that the +# diag system can successfully be used. Also, it generates a file +# "rsyslogd.started" after rsyslogd is initialized. This config file +# should be included in all tests that intend to use common code for +# controlling the daemon. +# NOTE: we assume that rsyslogd's current working directory is +# ./tests (or the distcheck equivalent), in particlular that this +# config file resides in the testsuites subdirectory. +# rgerhards, 2009-05-27 +$ModLoad ../plugins/imdiag/.libs/imdiag +$IMDiagServerRun 13501 + +$template startupfile,"rsyslogd2.started" # trick to use relative path names! +:syslogtag, contains, "rsyslogd" ?startupfile + +$ErrorMessagesToStderr off diff --git a/tests/testsuites/parse-3164-buggyday.conf b/tests/testsuites/parse-3164-buggyday.conf new file mode 100644 index 00000000..937f423a --- /dev/null +++ b/tests/testsuites/parse-3164-buggyday.conf @@ -0,0 +1,8 @@ +$ModLoad ../plugins/omstdout/.libs/omstdout +$IncludeConfig nettest.input.conf # This picks the to be tested input from the test driver! + +$ErrorMessagesToStderr off + +# use a special format that we can easily parse in expect +$template expect,"%PRI%,%syslogfacility-text%,%syslogseverity-text%,%timestamp:::date-rfc3164-buggyday%,%hostname%,%programname%,%syslogtag%,%msg%\n" +*.* :omstdout:;expect diff --git a/tests/testsuites/samples.parse-3164-buggyday b/tests/testsuites/samples.parse-3164-buggyday new file mode 100644 index 00000000..e21df980 --- /dev/null +++ b/tests/testsuites/samples.parse-3164-buggyday @@ -0,0 +1,6 @@ +# in 3164-buggyday mode, we need to have a leading zero in front of the day +<38> Mar 7 19:06:53 example tag: testmessage (only date actually tested) +38,auth,info,Mar 07 19:06:53,example,tag,tag:, testmessage (only date actually tested) +# and now one with a complete date: +<38> Mar 17 19:06:53 example tag: testmessage (only date actually tested) +38,auth,info,Mar 17 19:06:53,example,tag,tag:, testmessage (only date actually tested) -- cgit From 9e0426da5fae3f565e44411ed8b9796acc81040d Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Tue, 9 Mar 2010 17:52:01 +0100 Subject: bugfix: $omfileFlushOnTXEnd was turned on when set to off and vice versa --- ChangeLog | 2 ++ tools/omfile.c | 2 +- 2 files changed, 3 insertions(+), 1 deletion(-) diff --git a/ChangeLog b/ChangeLog index e9ccd5c7..321963dd 100644 --- a/ChangeLog +++ b/ChangeLog @@ -1,5 +1,7 @@ --------------------------------------------------------------------------- Version 4.6.2 [v4-stable] (rgerhards), 2010-03-?? +- bugfix: $omfileFlushOnTXEnd was turned on when set to off and vice + versa due to an invalid check - added new property replacer option "date-rfc3164-buggyday" primarily to ease migration from syslog-ng. See property replacer doc for details. [backport from 5.5.3 because urgently needed by some] diff --git a/tools/omfile.c b/tools/omfile.c index eb56201c..9b8f8e37 100644 --- a/tools/omfile.c +++ b/tools/omfile.c @@ -413,7 +413,7 @@ prepareFile(instanceData *pData, uchar *newFileName) * async processing, which is a real performance waste if we do not do buffered * writes! -- rgerhards, 2009-07-06 */ - if(!pData->bFlushOnTXEnd) + if(pData->bFlushOnTXEnd) CHKiRet(strm.SetiFlushInterval(pData->pStrm, pData->iFlushInterval)); if(pData->pszSizeLimitCmd != NULL) CHKiRet(strm.SetpszSizeLimitCmd(pData->pStrm, ustrdup(pData->pszSizeLimitCmd))); -- cgit From 7916735ba6890f67d49077975b0d635dc9931380 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Tue, 9 Mar 2010 17:57:46 +0100 Subject: retain old $OMFileFlushOnTXEnd semantics required because due to bug the default was actually different than specified (or better said: spec was inconsistent in doc as well). --- doc/rsyslog_conf_global.html | 4 ++-- tools/omfile.c | 4 ++-- 2 files changed, 4 insertions(+), 4 deletions(-) diff --git a/doc/rsyslog_conf_global.html b/doc/rsyslog_conf_global.html index 50d83a50..e7897f90 100644 --- a/doc/rsyslog_conf_global.html +++ b/doc/rsyslog_conf_global.html @@ -211,9 +211,9 @@ supported in order to be compliant to the upcoming new syslog RFC series. of the output file. The higher the number, the better the compression, but also the more CPU is required for zipping.
  • $OMFileIOBufferSize <size_nbr>, default 4k, size of the buffer used to writing output data. The larger the buffer, the potentially better performance is. The default of 4k is quite conservative, it is useful to go up to 64k, and 128K if you used gzip compression (then, even higher sizes may make sense)
    • -
  • $OMFileFlushOnTXEnd <[on/off]>, default on. Omfile has the +
  • $OMFileFlushOnTXEnd <[on/off]>, default ff. Omfile has the capability to -writes output using a buffered writer. Disk writes are only done when the buffer is +write output using a buffered writer. Disk writes are only done when the buffer is full. So if an error happens during that write, data is potentially lost. In cases where this is unacceptable, set $OMFileFlushOnTXEnd to on. Then, data is written at the end of each transaction (for pre-v5 this means after each log message) and the usual diff --git a/tools/omfile.c b/tools/omfile.c index 9b8f8e37..8fbf8fea 100644 --- a/tools/omfile.c +++ b/tools/omfile.c @@ -99,7 +99,7 @@ static uid_t dirGID; /* GID to be used for newly created directories */ static int bCreateDirs = 1;/* auto-create directories for dynaFiles: 0 - no, 1 - yes */ static int bEnableSync = 0;/* enable syncing of files (no dash in front of pathname in conf): 0 - no, 1 - yes */ static int iZipLevel = 0; /* zip compression mode (0..9 as usual) */ -static bool bFlushOnTXEnd = 1;/* flush write buffers when transaction has ended? */ +static bool bFlushOnTXEnd = 0;/* flush write buffers when transaction has ended? */ static int64 iIOBufSize = IOBUF_DFLT_SIZE; /* size of an io buffer */ static int iFlushInterval = FLUSH_INTRVL_DFLT; /* how often flush the output buffer on inactivity? */ uchar *pszFileDfltTplName = NULL; /* name of the default template to use */ @@ -749,7 +749,7 @@ static rsRetVal resetConfigVariables(uchar __attribute__((unused)) *pp, void __a bCreateDirs = 1; bEnableSync = 0; iZipLevel = 0; - bFlushOnTXEnd = 1; + bFlushOnTXEnd = 0; iIOBufSize = IOBUF_DFLT_SIZE; iFlushInterval = FLUSH_INTRVL_DFLT; if(pszFileDfltTplName != NULL) { -- cgit From 3d80d6ba301e4d26b646c84d621ebe880ebc513f Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Tue, 9 Mar 2010 18:07:31 +0100 Subject: bugfix: potential problem (loop, abort) when file write error occured When a write error occured in stream.c, variable iWritten had the error code but this was handled as if it were the actual number of bytes written. That was used in pointer arithmetic later on, and thus could lead to all sorts of problems. However, this could only happen if the error was EINTR or the file in question was a tty. All other cases were handled properly. Now, iWritten is reset to zero in such cases, resulting in proper retries. --- ChangeLog | 8 ++++++++ runtime/stream.c | 1 + tools/omfile.c | 4 ++-- 3 files changed, 11 insertions(+), 2 deletions(-) diff --git a/ChangeLog b/ChangeLog index 321963dd..5f495768 100644 --- a/ChangeLog +++ b/ChangeLog @@ -1,5 +1,13 @@ --------------------------------------------------------------------------- Version 4.6.2 [v4-stable] (rgerhards), 2010-03-?? +- bugfix: potential problem (loop, abort) when file write error occured + When a write error occured in stream.c, variable iWritten had the error + code but this was handled as if it were the actual number of bytes + written. That was used in pointer arithmetic later on, and thus could + lead to all sorts of problems. However, this could only happen if the + error was EINTR or the file in question was a tty. All other cases were + handled properly. Now, iWritten is reset to zero in such cases, resulting + in proper retries. - bugfix: $omfileFlushOnTXEnd was turned on when set to off and vice versa due to an invalid check - added new property replacer option "date-rfc3164-buggyday" primarily diff --git a/runtime/stream.c b/runtime/stream.c index 36f44003..82718099 100644 --- a/runtime/stream.c +++ b/runtime/stream.c @@ -790,6 +790,7 @@ doWriteCall(strm_t *pThis, uchar *pBuf, size_t *pLenBuf) if(iWritten < 0) { char errStr[1024]; int err = errno; + iWritten = 0; /* we have written NO bytes! */ rs_strerror_r(err, errStr, sizeof(errStr)); DBGPRINTF("log file (%d) write error %d: %s\n", pThis->fd, err, errStr); if(err == EINTR) { diff --git a/tools/omfile.c b/tools/omfile.c index 8fbf8fea..daefa680 100644 --- a/tools/omfile.c +++ b/tools/omfile.c @@ -79,7 +79,7 @@ DEFobjCurrIf(strm) struct s_dynaFileCacheEntry { uchar *pName; /* name currently open, if dynamic name */ strm_t *pStrm; /* our output stream */ - time_t lastUsed; /* for LRU - last access */ // TODO: perforamcne change to counter (see other comment!) + time_t lastUsed; /* for LRU - last access */ }; typedef struct s_dynaFileCacheEntry dynaFileCacheEntry; @@ -532,7 +532,7 @@ prepareDynFile(instanceData *pData, uchar *newFileName, unsigned iMsgOpts) ABORT_FINALIZE(RS_RET_OUT_OF_MEMORY); } pCache[iFirstFree]->pStrm = pData->pStrm; - pCache[iFirstFree]->lastUsed = time(NULL); // monotonically increasing value! TODO: performance + pCache[iFirstFree]->lastUsed = time(NULL); pData->iCurrElt = iFirstFree; DBGPRINTF("Added new entry %d for file cache, file '%s'.\n", iFirstFree, newFileName); -- cgit From 5996414f04118dec4f1dcc12c88ee8c68f6e89ad Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Wed, 10 Mar 2010 07:36:38 +0100 Subject: bugfixes and testbench improvement - improved testbench - bugfix: potential data loss during file stream shutdown - bugfix: potential problems during file stream shutdown The shutdown/close sequence was not clean, what potentially (but unlikely) could lead to some issues. We have not been able to describe any fatal cases, but there was some bug potential. Sequence has now been straighted out. --- ChangeLog | 13 ++++++++++--- runtime/stream.c | 17 +++++++++-------- tests/Makefile.am | 13 +++++++++++++ tests/asynwr_simple.sh | 16 ++++++++++++++++ tests/asynwr_small.sh | 24 ++++++++++++++++++++++++ tests/asynwr_timeout.sh | 19 +++++++++++++++++++ tests/asynwr_tinybuf.sh | 18 ++++++++++++++++++ tests/testsuites/asynwr_simple.conf | 14 ++++++++++++++ tests/testsuites/asynwr_small.conf | 13 +++++++++++++ tests/testsuites/asynwr_timeout.conf | 14 ++++++++++++++ tests/testsuites/asynwr_tinybuf.conf | 14 ++++++++++++++ 11 files changed, 164 insertions(+), 11 deletions(-) create mode 100755 tests/asynwr_simple.sh create mode 100755 tests/asynwr_small.sh create mode 100755 tests/asynwr_timeout.sh create mode 100755 tests/asynwr_tinybuf.sh create mode 100644 tests/testsuites/asynwr_simple.conf create mode 100644 tests/testsuites/asynwr_small.conf create mode 100644 tests/testsuites/asynwr_timeout.conf create mode 100644 tests/testsuites/asynwr_tinybuf.conf diff --git a/ChangeLog b/ChangeLog index 5f495768..7fe59dd9 100644 --- a/ChangeLog +++ b/ChangeLog @@ -1,5 +1,15 @@ --------------------------------------------------------------------------- Version 4.6.2 [v4-stable] (rgerhards), 2010-03-?? +- added new property replacer option "date-rfc3164-buggyday" primarily + to ease migration from syslog-ng. See property replacer doc for + details. [backport from 5.5.3 because urgently needed by some] +- improved testbench +- bugfix: potential data loss during file stream shutdown +- bugfix: potential problems during file stream shutdown + The shutdown/close sequence was not clean, what potentially (but + unlikely) could lead to some issues. We have not been able to describe + any fatal cases, but there was some bug potential. Sequence has now + been straighted out. - bugfix: potential problem (loop, abort) when file write error occured When a write error occured in stream.c, variable iWritten had the error code but this was handled as if it were the actual number of bytes @@ -10,9 +20,6 @@ Version 4.6.2 [v4-stable] (rgerhards), 2010-03-?? in proper retries. - bugfix: $omfileFlushOnTXEnd was turned on when set to off and vice versa due to an invalid check -- added new property replacer option "date-rfc3164-buggyday" primarily - to ease migration from syslog-ng. See property replacer doc for - details. [backport from 5.5.3 because urgently needed by some] --------------------------------------------------------------------------- Version 4.6.1 [v4-stable] (rgerhards), 2010-03-04 - re-enabled old pipe output (using new module ompipe, built-in) after diff --git a/runtime/stream.c b/runtime/stream.c index 82718099..5396bae0 100644 --- a/runtime/stream.c +++ b/runtime/stream.c @@ -306,20 +306,22 @@ strmWaitAsyncWriterDone(strm_t *pThis) /* close a strm file * Note that the bDeleteOnClose flag is honored. If it is set, the file will be * deleted after close. This is in support for the qRead thread. + * Note: it is valid to call this function when the physical file is closed. If so, + * strmCloseFile() will still check if there is any unwritten data inside buffers + * (this may be the case) and, if so, will open the file, write the data, and then + * close it again (this is done via strmFlush and friends). */ static rsRetVal strmCloseFile(strm_t *pThis) { DEFiRet; ASSERT(pThis != NULL); - ASSERT(pThis->fd != -1); dbgoprint((obj_t*) pThis, "file %d closing\n", pThis->fd); if(!pThis->bInClose && pThis->tOperationsMode != STREAMMODE_READ) { pThis->bInClose = 1; + strmFlush(pThis); if(pThis->bAsyncWrite) { - strmFlush(pThis); - } else { strmWaitAsyncWriterDone(pThis); } pThis->bInClose = 0; @@ -685,8 +687,10 @@ CODESTARTobjDestruct(strm) /* Note: mutex will be unlocked in stopWriter! */ d_pthread_mutex_lock(&pThis->mut); - if(pThis->tOperationsMode != STREAMMODE_READ) - strmFlush(pThis); + /* strmClose() will handle read-only files as well as need to open + * files that have unwritten buffers. -- rgerhards, 2010-03-09 + */ + strmCloseFile(pThis); if(pThis->bAsyncWrite) { stopWriter(pThis); @@ -705,9 +709,6 @@ CODESTARTobjDestruct(strm) * IMPORTANT: we MUST free this only AFTER the ansyncWriter has been stopped, else * we get random errors... */ - if(pThis->fd != -1) - strmCloseFile(pThis); - free(pThis->pszDir); free(pThis->pZipBuf); free(pThis->pszCurrFName); diff --git a/tests/Makefile.am b/tests/Makefile.am index 8849c3dc..92d3764b 100644 --- a/tests/Makefile.am +++ b/tests/Makefile.am @@ -9,6 +9,10 @@ TESTS = $(TESTRUNS) cfg.sh \ manytcp.sh \ sndrcv.sh \ sndrcv_gzip.sh \ + asynwr_simple.sh \ + asynwr_timeout.sh \ + asynwr_small.sh \ + asynwr_tinybuf.sh \ queue-persist.sh \ pipeaction.sh execonlyonce.sh \ @@ -135,6 +139,15 @@ EXTRA_DIST= 1.rstest 2.rstest 3.rstest err1.rstest \ testsuites/sndrcv_gzip_rcvr.conf \ pipeaction.sh \ testsuites/pipeaction.conf \ + asynwr_simple.sh \ + testsuites/asynwr_simple.conf \ + asynwr_timeout.sh \ + testsuites/asynwr_timeout.conf \ + asynwr_small.sh \ + testsuites/asynwr_small.conf \ + asynwr_tinybuf.sh \ + testsuites/asynwr_tinybuf.conf \ + testsuites/small.conf \ proprepltest.sh \ testsuites/rfctag.conf \ testsuites/master.rfctag \ diff --git a/tests/asynwr_simple.sh b/tests/asynwr_simple.sh new file mode 100755 index 00000000..693eca50 --- /dev/null +++ b/tests/asynwr_simple.sh @@ -0,0 +1,16 @@ +# This is test driver for testing asynchronous file output. +# +# added 2010-03-09 by Rgerhards +# This file is part of the rsyslog project, released under GPLv3 +echo TEST: \[asynwr_simple.sh\]: simple test for async file writing +source $srcdir/diag.sh init +# uncomment for debugging support: +#export RSYSLOG_DEBUG="debug nostdout noprintmutexaction" +#export RSYSLOG_DEBUGLOG="log" +source $srcdir/diag.sh startup asynwr_simple.conf +# send 35555 messages, make sure file size is not a multiple of +# 10K, the buffer size! +source $srcdir/diag.sh tcpflood 127.0.0.1 13514 1 35555 +source $srcdir/diag.sh shutdown-when-empty # shut down rsyslogd when done processing messages +source $srcdir/diag.sh seq-check 0 35554 +source $srcdir/diag.sh exit diff --git a/tests/asynwr_small.sh b/tests/asynwr_small.sh new file mode 100755 index 00000000..692d27fa --- /dev/null +++ b/tests/asynwr_small.sh @@ -0,0 +1,24 @@ +# This tests async writing with only a small set of data. That +# shall result in data staying in buffers until shutdown, what +# then will trigger some somewhat complex logic in the stream +# writer (open, write, close all during the stream close +# opertion). It is vital that only few messages be sent. +# +# The main effort of this test is not (only) to see if we +# receive the data, but rather to see if we get into an abort +# condition. +# +# added 2010-03-09 by Rgerhards +# +# This file is part of the rsyslog project, released under GPLv3 +echo TEST: \[asynwr_small.sh\]: test for async file writing for few messages +source $srcdir/diag.sh init +# uncomment for debugging support: +#export RSYSLOG_DEBUG="debug nostdout noprintmutexaction" +#export RSYSLOG_DEBUGLOG="log" +source $srcdir/diag.sh startup asynwr_small.conf +# send 4000 messages +source $srcdir/diag.sh tcpflood 127.0.0.1 13514 1 2 +source $srcdir/diag.sh shutdown-when-empty # shut down rsyslogd when done processing messages +source $srcdir/diag.sh seq-check 0 1 +source $srcdir/diag.sh exit diff --git a/tests/asynwr_timeout.sh b/tests/asynwr_timeout.sh new file mode 100755 index 00000000..84fbd481 --- /dev/null +++ b/tests/asynwr_timeout.sh @@ -0,0 +1,19 @@ +# This test writes to the output buffers, let's the output +# write timeout (and write data) and then continue. The conf file +# has a 2 second timeout, so we wait 4 seconds to be on the save side. +# +# added 2010-03-09 by Rgerhards +# This file is part of the rsyslog project, released under GPLv3 +echo TEST: \[asynwr_timeout.sh\]: test async file writing timeout writes +source $srcdir/diag.sh init +# uncomment for debugging support: +#export RSYSLOG_DEBUG="debug nostdout noprintmutexaction" +#export RSYSLOG_DEBUGLOG="log" +source $srcdir/diag.sh startup asynwr_timeout.conf +# send 35555 messages, make sure file size is not a multiple of +# 10K, the buffer size! +source $srcdir/diag.sh tcpflood 127.0.0.1 13514 1 35555 +sleep 4 # wait for output writer to write and empty buffer +source $srcdir/diag.sh shutdown-when-empty # shut down rsyslogd when done processing messages +source $srcdir/diag.sh seq-check 0 35554 +source $srcdir/diag.sh exit diff --git a/tests/asynwr_tinybuf.sh b/tests/asynwr_tinybuf.sh new file mode 100755 index 00000000..a7cc19ef --- /dev/null +++ b/tests/asynwr_tinybuf.sh @@ -0,0 +1,18 @@ +# This tests async writing with a very small output buffer (1 byte!), +# so it stresses output buffer handling. This also means operations will +# be somewhat slow, so we send only a small amounts of data. +# +# added 2010-03-09 by Rgerhards +# +# This file is part of the rsyslog project, released under GPLv3 +echo TEST: \[asynwr_tinybuf.sh\]: test async file writing with 1-byte buffer +source $srcdir/diag.sh init +# uncomment for debugging support: +#export RSYSLOG_DEBUG="debug nostdout noprintmutexaction" +#export RSYSLOG_DEBUGLOG="log" +source $srcdir/diag.sh startup asynwr_tinybuf.conf +# send 1000 messages, fairly enough to trigger problems +source $srcdir/diag.sh tcpflood 127.0.0.1 13514 1 1000 +source $srcdir/diag.sh shutdown-when-empty # shut down rsyslogd when done processing messages +source $srcdir/diag.sh seq-check 0 999 +source $srcdir/diag.sh exit diff --git a/tests/testsuites/asynwr_simple.conf b/tests/testsuites/asynwr_simple.conf new file mode 100644 index 00000000..68b85ff5 --- /dev/null +++ b/tests/testsuites/asynwr_simple.conf @@ -0,0 +1,14 @@ +# simple async writing test +# rgerhards, 2010-03-09 +$IncludeConfig diag-common.conf + +$ModLoad ../plugins/imtcp/.libs/imtcp +$MainMsgQueueTimeoutShutdown 10000 +$InputTCPServerRun 13514 + +$template outfmt,"%msg:F,58:2%\n" +$template dynfile,"rsyslog.out.log" # trick to use relative path names! +$OMFileFlushOnTXEnd off +$OMFileFlushInterval 2 +$OMFileFlushIOBufferSize 10k +:msg, contains, "msgnum:" ?dynfile;outfmt diff --git a/tests/testsuites/asynwr_small.conf b/tests/testsuites/asynwr_small.conf new file mode 100644 index 00000000..d9724cec --- /dev/null +++ b/tests/testsuites/asynwr_small.conf @@ -0,0 +1,13 @@ +# simple async writing test +# rgerhards, 2010-03-09 +$IncludeConfig diag-common.conf + +$ModLoad ../plugins/imtcp/.libs/imtcp +$MainMsgQueueTimeoutShutdown 10000 +$InputTCPServerRun 13514 + +$template outfmt,"%msg:F,58:2%\n" +$template dynfile,"rsyslog.out.log" # trick to use relative path names! +$OMFileFlushOnTXEnd off +$OMFileFlushInterval 2 +:msg, contains, "msgnum:" ?dynfile;outfmt diff --git a/tests/testsuites/asynwr_timeout.conf b/tests/testsuites/asynwr_timeout.conf new file mode 100644 index 00000000..68b85ff5 --- /dev/null +++ b/tests/testsuites/asynwr_timeout.conf @@ -0,0 +1,14 @@ +# simple async writing test +# rgerhards, 2010-03-09 +$IncludeConfig diag-common.conf + +$ModLoad ../plugins/imtcp/.libs/imtcp +$MainMsgQueueTimeoutShutdown 10000 +$InputTCPServerRun 13514 + +$template outfmt,"%msg:F,58:2%\n" +$template dynfile,"rsyslog.out.log" # trick to use relative path names! +$OMFileFlushOnTXEnd off +$OMFileFlushInterval 2 +$OMFileFlushIOBufferSize 10k +:msg, contains, "msgnum:" ?dynfile;outfmt diff --git a/tests/testsuites/asynwr_tinybuf.conf b/tests/testsuites/asynwr_tinybuf.conf new file mode 100644 index 00000000..9818b139 --- /dev/null +++ b/tests/testsuites/asynwr_tinybuf.conf @@ -0,0 +1,14 @@ +# simple async writing test +# rgerhards, 2010-03-09 +$IncludeConfig diag-common.conf + +$ModLoad ../plugins/imtcp/.libs/imtcp +$MainMsgQueueTimeoutShutdown 10000 +$InputTCPServerRun 13514 + +$template outfmt,"%msg:F,58:2%\n" +$template dynfile,"rsyslog.out.log" # trick to use relative path names! +$OMFileFlushOnTXEnd off +$OMFileFlushInterval 2 +$OMFileIOBufferSize 1 +:msg, contains, "msgnum:" ?dynfile;outfmt -- cgit From 8833612e7516694e89148eb3dc1c88f5ea954d16 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Wed, 10 Mar 2010 08:21:41 +0100 Subject: some cosmetic changes note that a buffer size calculation was done wrong, but this was cosmetic because our buffers currently all use byte size, so even though the formula was wrong, the result was correct. --- runtime/stream.c | 18 +++++++++--------- tests/asynwr_simple.sh | 1 + tests/asynwr_small.sh | 1 + tests/asynwr_timeout.sh | 1 + tests/asynwr_tinybuf.sh | 1 + 5 files changed, 13 insertions(+), 9 deletions(-) diff --git a/runtime/stream.c b/runtime/stream.c index 5396bae0..bb92eeb5 100644 --- a/runtime/stream.c +++ b/runtime/stream.c @@ -619,11 +619,11 @@ static rsRetVal strmConstructFinalize(strm_t *pThis) * to make sure we can write out everything with a SINGLE api call! * We add another 128 bytes to take care of the gzip header and "all eventualities". */ - CHKmalloc(pThis->pZipBuf = (Bytef*) malloc(sizeof(uchar) * pThis->sIOBufSize + 128)); + CHKmalloc(pThis->pZipBuf = (Bytef*) malloc(sizeof(uchar) * (pThis->sIOBufSize + 128))); } } - /* if we are aset to sync, we must obtain a file handle to the directory for fsync() purposes */ + /* if we are set to sync, we must obtain a file handle to the directory for fsync() purposes */ if(pThis->bSync && !pThis->bIsTTY) { pThis->fdDir = open((char*)pThis->pszDir, O_RDONLY | O_CLOEXEC | O_NOCTTY); if(pThis->fdDir == -1) { @@ -913,7 +913,7 @@ asyncWriterThread(void *pPtr) if(prctl(PR_SET_NAME, "rs:asyn strmwr", 0, 0, 0) != 0) { DBGPRINTF("prctl failed, not setting thread name for '%s'\n", "stream writer"); } -#endif +# endif while(1) { /* loop broken inside */ d_pthread_mutex_lock(&pThis->mut); @@ -1060,10 +1060,6 @@ finalize_it: * add a config switch so that the user can decide the risk he is ready * to take, but so far this is not yet implemented (not even requested ;)). * rgerhards, 2009-06-04 - * For the time being, we take a very conservative approach and do not run this - * method multithreaded. This is done in an effort to solve a segfault condition - * that seems to be related to the zip code. -- rgerhards, 2009-09-22 - * TODO: make multithreaded again! */ static rsRetVal doZipWrite(strm_t *pThis, uchar *pBuf, size_t lenBuf) @@ -1235,6 +1231,11 @@ finalize_it: * caller-provided buffer is larger than our one. So instead of optimizing a case * which normally does not exist, we expect some degradation in its case but make us * perform better in the regular cases. -- rgerhards, 2009-07-07 + * Note: the pThis->iBufPtr == pThis->sIOBufSize logic below looks a bit like an + * on-off error. In fact, it is not, because iBufPtr always points to the next + * *free* byte in the buffer. So if it is sIOBufSize - 1, there actually is one + * free byte left. This came up during a code walkthrough and was considered + * worth nothing. -- rgerhards, 2010-03-10 */ static rsRetVal strmWrite(strm_t *pThis, uchar *pBuf, size_t lenBuf) @@ -1359,8 +1360,7 @@ strmSetDir(strm_t *pThis, uchar *pszDir, size_t iLenDir) if(iLenDir < 1) ABORT_FINALIZE(RS_RET_FILE_PREFIX_MISSING); - if((pThis->pszDir = malloc(sizeof(uchar) * iLenDir + 1)) == NULL) - ABORT_FINALIZE(RS_RET_OUT_OF_MEMORY); + CHKmalloc(pThis->pszDir = malloc(sizeof(uchar) * iLenDir + 1)); memcpy(pThis->pszDir, pszDir, iLenDir + 1); /* always think about the \0! */ pThis->lenDir = iLenDir; diff --git a/tests/asynwr_simple.sh b/tests/asynwr_simple.sh index 693eca50..2e476b8f 100755 --- a/tests/asynwr_simple.sh +++ b/tests/asynwr_simple.sh @@ -2,6 +2,7 @@ # # added 2010-03-09 by Rgerhards # This file is part of the rsyslog project, released under GPLv3 +echo =============================================================================== echo TEST: \[asynwr_simple.sh\]: simple test for async file writing source $srcdir/diag.sh init # uncomment for debugging support: diff --git a/tests/asynwr_small.sh b/tests/asynwr_small.sh index 692d27fa..39dcd762 100755 --- a/tests/asynwr_small.sh +++ b/tests/asynwr_small.sh @@ -11,6 +11,7 @@ # added 2010-03-09 by Rgerhards # # This file is part of the rsyslog project, released under GPLv3 +echo =============================================================================== echo TEST: \[asynwr_small.sh\]: test for async file writing for few messages source $srcdir/diag.sh init # uncomment for debugging support: diff --git a/tests/asynwr_timeout.sh b/tests/asynwr_timeout.sh index 84fbd481..746ee3f1 100755 --- a/tests/asynwr_timeout.sh +++ b/tests/asynwr_timeout.sh @@ -4,6 +4,7 @@ # # added 2010-03-09 by Rgerhards # This file is part of the rsyslog project, released under GPLv3 +echo =============================================================================== echo TEST: \[asynwr_timeout.sh\]: test async file writing timeout writes source $srcdir/diag.sh init # uncomment for debugging support: diff --git a/tests/asynwr_tinybuf.sh b/tests/asynwr_tinybuf.sh index a7cc19ef..a0915394 100755 --- a/tests/asynwr_tinybuf.sh +++ b/tests/asynwr_tinybuf.sh @@ -5,6 +5,7 @@ # added 2010-03-09 by Rgerhards # # This file is part of the rsyslog project, released under GPLv3 +echo =============================================================================== echo TEST: \[asynwr_tinybuf.sh\]: test async file writing with 1-byte buffer source $srcdir/diag.sh init # uncomment for debugging support: -- cgit From 6c43f93022caa3feaa7b4fa3d88ca31746fd94cf Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Wed, 10 Mar 2010 09:52:49 +0100 Subject: fixed regression introduced with previous commit disk queue mode did no longer work correctly. A side-effect of this commit here is slightly cleaned-up (and more elegant) code for circular files. --- runtime/stream.c | 15 +++++++++++---- runtime/stream.h | 1 - tests/diskqueue.sh | 3 +++ 3 files changed, 14 insertions(+), 5 deletions(-) diff --git a/runtime/stream.c b/runtime/stream.c index 5396bae0..c6c8273e 100644 --- a/runtime/stream.c +++ b/runtime/stream.c @@ -318,13 +318,11 @@ static rsRetVal strmCloseFile(strm_t *pThis) ASSERT(pThis != NULL); dbgoprint((obj_t*) pThis, "file %d closing\n", pThis->fd); - if(!pThis->bInClose && pThis->tOperationsMode != STREAMMODE_READ) { - pThis->bInClose = 1; + if(pThis->tOperationsMode != STREAMMODE_READ) { strmFlush(pThis); if(pThis->bAsyncWrite) { strmWaitAsyncWriterDone(pThis); } - pThis->bInClose = 0; } close(pThis->fd); @@ -882,13 +880,22 @@ strmSchedWrite(strm_t *pThis, uchar *pBuf, size_t lenBuf) ASSERT(pThis != NULL); + /* we need to reset the buffer pointer BEFORE calling the actual write + * function. Otherwise, in circular mode, the write function will + * potentially close the file, then close will flush and as the + * buffer pointer is nonzero, will re-call into this code here. In + * the end result, we than have a problem (and things are screwed + * up). So we reset the buffer pointer first, and all this can + * not happen. It is safe to do so, because that pointer is NOT + * used inside the write functions. -- rgerhads, 2010-03-10 + */ + pThis->iBufPtr = 0; /* we are at the begin of a new buffer */ if(pThis->bAsyncWrite) { CHKiRet(doAsyncWriteInternal(pThis, lenBuf)); } else { CHKiRet(doWriteInternal(pThis, pBuf, lenBuf)); } - pThis->iBufPtr = 0; /* we are at the begin of a new buffer */ finalize_it: RETiRet; diff --git a/runtime/stream.h b/runtime/stream.h index 89175b0f..369d5a0f 100644 --- a/runtime/stream.h +++ b/runtime/stream.h @@ -119,7 +119,6 @@ typedef struct strm_s { size_t iBufPtr; /* pointer into current buffer */ int iUngetC; /* char set via UngetChar() call or -1 if none set */ bool bInRecord; /* if 1, indicates that we are currently writing a not-yet complete record */ - bool bInClose; /* used to break "deadly close loops", tells us we are already inside a close */ int iZipLevel; /* zip level (0..9). If 0, zip is completely disabled */ Bytef *pZipBuf; /* support for async flush procesing */ diff --git a/tests/diskqueue.sh b/tests/diskqueue.sh index 8233d569..ad512ee8 100755 --- a/tests/diskqueue.sh +++ b/tests/diskqueue.sh @@ -6,6 +6,9 @@ # This file is part of the rsyslog project, released under GPLv3 # uncomment for debugging support: echo diskqueue.sh: testing queue disk-only mode +# uncomment for debugging support: +#export RSYSLOG_DEBUG="debug nostdout noprintmutexaction" +#export RSYSLOG_DEBUGLOG="log" source $srcdir/diag.sh init source $srcdir/diag.sh startup diskqueue.conf # 20000 messages should be enough - the disk test is slow enough ;) -- cgit From 4408d4137acfacef57bd2e088a0da83d25e34918 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Wed, 10 Mar 2010 11:07:26 +0100 Subject: testbench: new calling interface for tcpflood this is a perquisite to support more flexible testing modes, which could not intelligently be implemented with the old interface --- tests/asynwr_simple.sh | 2 +- tests/asynwr_small.sh | 2 +- tests/asynwr_timeout.sh | 2 +- tests/asynwr_tinybuf.sh | 2 +- tests/diskqueue-fsync.sh | 2 +- tests/diskqueue.sh | 2 +- tests/execonlyonce.sh | 4 ++-- tests/imtcp-multiport.sh | 6 +++--- tests/manytcp.sh | 2 +- tests/pipeaction.sh | 2 +- tests/sndrcv_drvr.sh | 2 +- tests/tcpflood.c | 41 ++++++++++++++++++++++------------------- tests/threadingmqaq.sh | 2 +- tools/zpipe.c | 7 +++++++ 14 files changed, 44 insertions(+), 34 deletions(-) diff --git a/tests/asynwr_simple.sh b/tests/asynwr_simple.sh index 2e476b8f..c21f7893 100755 --- a/tests/asynwr_simple.sh +++ b/tests/asynwr_simple.sh @@ -11,7 +11,7 @@ source $srcdir/diag.sh init source $srcdir/diag.sh startup asynwr_simple.conf # send 35555 messages, make sure file size is not a multiple of # 10K, the buffer size! -source $srcdir/diag.sh tcpflood 127.0.0.1 13514 1 35555 +source $srcdir/diag.sh tcpflood -m35555 source $srcdir/diag.sh shutdown-when-empty # shut down rsyslogd when done processing messages source $srcdir/diag.sh seq-check 0 35554 source $srcdir/diag.sh exit diff --git a/tests/asynwr_small.sh b/tests/asynwr_small.sh index 39dcd762..ee091935 100755 --- a/tests/asynwr_small.sh +++ b/tests/asynwr_small.sh @@ -19,7 +19,7 @@ source $srcdir/diag.sh init #export RSYSLOG_DEBUGLOG="log" source $srcdir/diag.sh startup asynwr_small.conf # send 4000 messages -source $srcdir/diag.sh tcpflood 127.0.0.1 13514 1 2 +source $srcdir/diag.sh tcpflood -m2 source $srcdir/diag.sh shutdown-when-empty # shut down rsyslogd when done processing messages source $srcdir/diag.sh seq-check 0 1 source $srcdir/diag.sh exit diff --git a/tests/asynwr_timeout.sh b/tests/asynwr_timeout.sh index 746ee3f1..41b76ede 100755 --- a/tests/asynwr_timeout.sh +++ b/tests/asynwr_timeout.sh @@ -13,7 +13,7 @@ source $srcdir/diag.sh init source $srcdir/diag.sh startup asynwr_timeout.conf # send 35555 messages, make sure file size is not a multiple of # 10K, the buffer size! -source $srcdir/diag.sh tcpflood 127.0.0.1 13514 1 35555 +source $srcdir/diag.sh tcpflood -m 35555 sleep 4 # wait for output writer to write and empty buffer source $srcdir/diag.sh shutdown-when-empty # shut down rsyslogd when done processing messages source $srcdir/diag.sh seq-check 0 35554 diff --git a/tests/asynwr_tinybuf.sh b/tests/asynwr_tinybuf.sh index a0915394..8eae1e26 100755 --- a/tests/asynwr_tinybuf.sh +++ b/tests/asynwr_tinybuf.sh @@ -13,7 +13,7 @@ source $srcdir/diag.sh init #export RSYSLOG_DEBUGLOG="log" source $srcdir/diag.sh startup asynwr_tinybuf.conf # send 1000 messages, fairly enough to trigger problems -source $srcdir/diag.sh tcpflood 127.0.0.1 13514 1 1000 +source $srcdir/diag.sh tcpflood -m1000 source $srcdir/diag.sh shutdown-when-empty # shut down rsyslogd when done processing messages source $srcdir/diag.sh seq-check 0 999 source $srcdir/diag.sh exit diff --git a/tests/diskqueue-fsync.sh b/tests/diskqueue-fsync.sh index 0282202d..c7745930 100755 --- a/tests/diskqueue-fsync.sh +++ b/tests/diskqueue-fsync.sh @@ -9,7 +9,7 @@ echo testing queue disk-only mode, fsync case source $srcdir/diag.sh init source $srcdir/diag.sh startup diskqueue-fsync.conf # 1000 messages should be enough - the disk fsync test is very slow! -source $srcdir/diag.sh tcpflood 127.0.0.1 13514 1 1000 +source $srcdir/diag.sh tcpflood -m1000 source $srcdir/diag.sh shutdown-when-empty # shut down rsyslogd when done processing messages source $srcdir/diag.sh wait-shutdown source $srcdir/diag.sh seq-check 0 999 diff --git a/tests/diskqueue.sh b/tests/diskqueue.sh index ad512ee8..7a50d82e 100755 --- a/tests/diskqueue.sh +++ b/tests/diskqueue.sh @@ -13,7 +13,7 @@ source $srcdir/diag.sh init source $srcdir/diag.sh startup diskqueue.conf # 20000 messages should be enough - the disk test is slow enough ;) sleep 4 -source $srcdir/diag.sh tcpflood 127.0.0.1 13514 1 20000 +source $srcdir/diag.sh tcpflood -m20000 source $srcdir/diag.sh shutdown-when-empty # shut down rsyslogd when done processing messages source $srcdir/diag.sh wait-shutdown source $srcdir/diag.sh seq-check 0 19999 diff --git a/tests/execonlyonce.sh b/tests/execonlyonce.sh index a9b9d932..b7f60849 100755 --- a/tests/execonlyonce.sh +++ b/tests/execonlyonce.sh @@ -10,11 +10,11 @@ echo =========================================================================== echo \[execonlyonce.sh\]: test for the $ActionExecOnlyOnceEveryInterval directive source $srcdir/diag.sh init source $srcdir/diag.sh startup execonlyonce.conf -source $srcdir/diag.sh tcpflood 127.0.0.1 13514 1 10 1 +source $srcdir/diag.sh tcpflood -m10 -i1 # now wait until the interval definitely expires sleep 4 # one more than the once inerval! # and inject another couple of messages -source $srcdir/diag.sh tcpflood 127.0.0.1 13514 1 10 100 +source $srcdir/diag.sh tcpflood -m10 -i100 source $srcdir/diag.sh shutdown-when-empty # shut down rsyslogd when done processing messages # now we need your custom logic to see if the result is equal to the diff --git a/tests/imtcp-multiport.sh b/tests/imtcp-multiport.sh index 47a33cb9..ad2b44f8 100755 --- a/tests/imtcp-multiport.sh +++ b/tests/imtcp-multiport.sh @@ -11,7 +11,7 @@ echo =========================================================================== echo \[imtcp-multiport.sh\]: testing imtcp multiple listeners source $srcdir/diag.sh init source $srcdir/diag.sh startup imtcp-multiport.conf -source $srcdir/diag.sh tcpflood 127.0.0.1 13514 1 10000 +source $srcdir/diag.sh tcpflood -p13514 -m10000 source $srcdir/diag.sh shutdown-when-empty # shut down rsyslogd when done processing messages source $srcdir/diag.sh wait-shutdown source $srcdir/diag.sh seq-check 0 9999 @@ -23,7 +23,7 @@ source $srcdir/diag.sh exit # source $srcdir/diag.sh init source $srcdir/diag.sh startup imtcp-multiport.conf -source $srcdir/diag.sh tcpflood 127.0.0.1 13515 1 10000 +source $srcdir/diag.sh tcpflood -p13515 -m10000 source $srcdir/diag.sh shutdown-when-empty # shut down rsyslogd when done processing messages source $srcdir/diag.sh wait-shutdown source $srcdir/diag.sh seq-check 0 9999 @@ -35,7 +35,7 @@ source $srcdir/diag.sh exit # source $srcdir/diag.sh init source $srcdir/diag.sh startup imtcp-multiport.conf -source $srcdir/diag.sh tcpflood 127.0.0.1 13516 1 10000 +source $srcdir/diag.sh tcpflood -p13516 -m10000 source $srcdir/diag.sh shutdown-when-empty # shut down rsyslogd when done processing messages source $srcdir/diag.sh wait-shutdown source $srcdir/diag.sh seq-check 0 9999 diff --git a/tests/manytcp.sh b/tests/manytcp.sh index c55eb9c0..dbf1d961 100755 --- a/tests/manytcp.sh +++ b/tests/manytcp.sh @@ -2,7 +2,7 @@ source $srcdir/diag.sh init source $srcdir/diag.sh startup manytcp.conf # the config file specifies exactly 1100 connections -source $srcdir/diag.sh tcpflood 127.0.0.1 13514 1000 40000 +source $srcdir/diag.sh tcpflood -c1000 -m40000 source $srcdir/diag.sh shutdown-when-empty # shut down rsyslogd when done processing messages source $srcdir/diag.sh seq-check 0 39999 source $srcdir/diag.sh exit diff --git a/tests/pipeaction.sh b/tests/pipeaction.sh index 26a4c22a..c2201011 100755 --- a/tests/pipeaction.sh +++ b/tests/pipeaction.sh @@ -17,7 +17,7 @@ echo background cp process id is $CPPROCESS # now do the usual run source $srcdir/diag.sh startup pipeaction.conf # 20000 messages should be enough -#source $srcdir/diag.sh tcpflood 127.0.0.1 13514 1 20000 +#source $srcdir/diag.sh tcpflood -m20000 source $srcdir/diag.sh injectmsg 0 20000 source $srcdir/diag.sh shutdown-when-empty # shut down rsyslogd when done processing messages source $srcdir/diag.sh wait-shutdown diff --git a/tests/sndrcv_drvr.sh b/tests/sndrcv_drvr.sh index 63afd6b5..3d613069 100755 --- a/tests/sndrcv_drvr.sh +++ b/tests/sndrcv_drvr.sh @@ -34,7 +34,7 @@ source $srcdir/diag.sh wait-startup 2 # now inject the messages into instance 2. It will connect to instance 1, # and that instance will record the data. -source $srcdir/diag.sh tcpflood 127.0.0.1 13514 1 $2 1 +source $srcdir/diag.sh tcpflood -m$2 -i1 sleep 2 # make sure all data is received in input buffers # shut down sender when everything is sent, receiver continues to run concurrently # may be needed by TLS (once we do it): sleep 60 diff --git a/tests/tcpflood.c b/tests/tcpflood.c index 0439e33e..308495a5 100644 --- a/tests/tcpflood.c +++ b/tests/tcpflood.c @@ -2,11 +2,11 @@ * messages over them. This is used for stress-testing. * * Params - * argv[1] target address - * argv[2] target port - * argv[3] number of connections - * argv[4] number of messages to send (connection is random) - * argv[5] initial message number (optional) + * -t target address (default 127.0.0.1) + * -p target port (default 13514) + * -c number of connections (default 1) + * -m number of messages to send (connection is random) + * -i initial message number (optional) * * Part of the testbench for rsyslog. * @@ -47,10 +47,10 @@ /* Name of input file, must match $IncludeConfig in test suite .conf files */ #define NETTEST_INPUT_CONF_FILE "nettest.input.conf" /* name of input file, must match $IncludeConfig in .conf files */ -static char *targetIP; -static int targetPort; +static char *targetIP = "127.0.0.1"; +static int targetPort = 13514; static int numMsgsToSend; /* number of messages to send */ -static int numConnections; /* number of connections to create */ +static int numConnections = 1; /* number of connections to create */ static int *sockArray; /* array of sockets to use */ static int msgNum = 0; /* initial message number to start with */ @@ -259,6 +259,7 @@ tcpSend(char *buf, int lenBuf) int main(int argc, char *argv[]) { int ret = 0; + int opt; struct sigaction sigAct; static char buf[1024]; @@ -272,18 +273,20 @@ int main(int argc, char *argv[]) setvbuf(stdout, buf, _IONBF, 48); - if(argc != 5 && argc != 6) { - printf("Invalid call of tcpflood\n"); - printf("Usage: tcpflood target-host target-port num-connections num-messages [initial msgnum]\n"); - exit(1); + while((opt = getopt(argc, argv, "t:p:c:m:i:")) != -1) { + switch (opt) { + case 't': targetIP = optarg; + break; + case 'p': targetPort = atoi(optarg); + break; + case 'c': numConnections = atoi(optarg); + break; + case 'm': numMsgsToSend = atoi(optarg); + break; + case 'i': msgNum = atoi(optarg); + break; + } } - - targetIP = argv[1]; - targetPort = atoi(argv[2]); - numConnections = atoi(argv[3]); - numMsgsToSend = atoi(argv[4]); - if(argc == 6) - msgNum = atoi(argv[5]); if(openConnections() != 0) { printf("error opening connections\n"); diff --git a/tests/threadingmqaq.sh b/tests/threadingmqaq.sh index 9f2ea793..b7764821 100755 --- a/tests/threadingmqaq.sh +++ b/tests/threadingmqaq.sh @@ -9,7 +9,7 @@ echo TEST: threadingmqaq.sh - main/action queue concurrency source $srcdir/diag.sh init source $srcdir/diag.sh startup threadingmqaq.conf -#source $srcdir/diag.sh tcpflood 127.0.0.1 13514 2 100000 +#source $srcdir/diag.sh tcpflood -c2 -m100000 #source $srcdir/diag.sh shutdown-when-empty # shut down rsyslogd when done processing messages source $srcdir/diag.sh injectmsg 0 100000 source $srcdir/diag.sh shutdown-when-empty # shut down rsyslogd when done processing messages diff --git a/tools/zpipe.c b/tools/zpipe.c index d2278359..38069425 100644 --- a/tools/zpipe.c +++ b/tools/zpipe.c @@ -4,6 +4,13 @@ Version 2.0 03 June 2009 Rainer Gerhards */ /* RSYSLOG NOTE: + * This file is primarily been used as a testing aid for rsyslog. We do NOT + * properly maintain it and it has been brought to our attention that it may + * have some security issues. However, we prefer not to remove the file as it + * may turn out to be useful for further testing. All users are advised NOT + * to base any development on this version here, but rather look for the + * original zpipe.c by the authors mentioned above. + * * This file is beeing distributed as part of rsyslog, but is just an * add-on. Most importantly, rsyslog's copyright does not apply but * rather the (non-) copyright stated above. -- cgit From 5106cbe466781e824846742a036d36ba5f884ad6 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Wed, 10 Mar 2010 12:19:51 +0100 Subject: added ability to work with larger message sizes to testbench tools --- tests/chkseq.c | 26 ++++++++++++++++++++++---- tests/tcpflood.c | 48 +++++++++++++++++++++++++++++++++++++++++------- 2 files changed, 63 insertions(+), 11 deletions(-) diff --git a/tests/chkseq.c b/tests/chkseq.c index 6334d787..b8088cd5 100644 --- a/tests/chkseq.c +++ b/tests/chkseq.c @@ -32,6 +32,7 @@ #include "config.h" #include #include +#include #include int main(int argc, char *argv[]) @@ -40,14 +41,18 @@ int main(int argc, char *argv[]) int val; int i; int ret = 0; + int scanfOK; int verbose = 0; + int bHaveExtraData = 0; int dupsPermitted = 0; int start = 0, end = 0; int opt; int nDups = 0; + int edLen; /* length of extra data */ + static char edBuf[500*1024]; /* buffer for extra data (pretty large to be on the save side...) */ char *file = NULL; - while((opt = getopt(argc, argv, "e:f:ds:v")) != EOF) { + while((opt = getopt(argc, argv, "e:f:ds:vE")) != EOF) { switch((char)opt) { case 'f': file = optarg; @@ -64,8 +69,11 @@ int main(int argc, char *argv[]) case 'v': ++verbose; break; - default:printf("Invalid call of chkseq\n"); - printf("Usage: chkseq file -sstart -eend -d\n"); + case 'E': + bHaveExtraData = 1; + break; + default:printf("Invalid call of chkseq, optchar='%c'\n", opt); + printf("Usage: chkseq file -sstart -eend -d -E\n"); exit(1); } } @@ -93,7 +101,17 @@ int main(int argc, char *argv[]) } for(i = start ; i < end+1 ; ++i) { - if(fscanf(fp, "%d\n", &val) != 1) { + if(bHaveExtraData) { + scanfOK = fscanf(fp, "%d,%d,%s\n", &val, &edLen, edBuf) == 3 ? 1 : 0; + if(edLen != (int) strlen(edBuf)) { + printf("extra data length specified %d, but actually is %ld in record %d\n", + edLen, (long) strlen(edBuf), i); + exit(1); + } + } else { + scanfOK = fscanf(fp, "%d\n", &val) == 1 ? 1 : 0; + } + if(!scanfOK) { printf("scanf error in index i=%d\n", i); exit(1); } diff --git a/tests/tcpflood.c b/tests/tcpflood.c index 308495a5..fcfc30a7 100644 --- a/tests/tcpflood.c +++ b/tests/tcpflood.c @@ -7,6 +7,13 @@ * -c number of connections (default 1) * -m number of messages to send (connection is random) * -i initial message number (optional) + * -P PRI to be used for generated messages (default is 167). + * Specify the plain number without leading zeros + * -d amount of extra data to add to message. If present, the + * number itself will be added as third field, and the data + * bytes as forth. Add -r to randomize the amount of extra + * data included in the range 1..(value of -d). + * -r randomize amount of extra data added (-d must be > 0) * * Part of the testbench for rsyslog. * @@ -47,8 +54,13 @@ /* Name of input file, must match $IncludeConfig in test suite .conf files */ #define NETTEST_INPUT_CONF_FILE "nettest.input.conf" /* name of input file, must match $IncludeConfig in .conf files */ +#define MAX_EXTRADATA_LEN 100*1024 + static char *targetIP = "127.0.0.1"; +static char *msgPRI = "167"; static int targetPort = 13514; +static int extraDataLen = 0; /* amount of extra data to add to message */ +static int bRandomizeExtraData = 0; /* randomize amount of extra data added */ static int numMsgsToSend; /* number of messages to send */ static int numConnections = 1; /* number of connections to create */ static int *sockArray; /* array of sockets to use */ @@ -164,7 +176,9 @@ int sendMessages(void) int socknum; int lenBuf; int lenSend; - char buf[2048]; + int edLen; /* actual extra data length to use */ + char buf[MAX_EXTRADATA_LEN + 1024]; + char extraData[MAX_EXTRADATA_LEN + 1]; srand(time(NULL)); /* seed is good enough for our needs */ @@ -177,7 +191,19 @@ int sendMessages(void) socknum = i - (numMsgsToSend - numConnections); else socknum = rand() % numConnections; - lenBuf = sprintf(buf, "<167>Mar 1 01:00:00 172.20.245.8 tag msgnum:%8.8d:\n", msgNum); + if(extraDataLen == 0) { + lenBuf = sprintf(buf, "<%s>Mar 1 01:00:00 172.20.245.8 tag msgnum:%8.8d:\n", + msgPRI, msgNum); + } else { + if(bRandomizeExtraData) + edLen = ((long) rand() + extraDataLen) % extraDataLen + 1; + else + edLen = extraDataLen; + memset(extraData, 'X', edLen); + extraData[edLen] = '\0'; + lenBuf = sprintf(buf, "<%s>Mar 1 01:00:00 172.20.245.8 tag msgnum:%8.8d:%d:%s\n", + msgPRI, msgNum, edLen, extraData); + } lenSend = send(sockArray[socknum], buf, lenBuf, 0); if(lenSend != lenBuf) { printf("\r%5.5d\n", i); @@ -251,9 +277,7 @@ tcpSend(char *buf, int lenBuf) } -/* Run the test suite. This must be called with exactly one parameter, the - * name of the test suite. For details, see file header comment at the top - * of this file. +/* Run the test. * rgerhards, 2009-04-03 */ int main(int argc, char *argv[]) @@ -273,7 +297,7 @@ int main(int argc, char *argv[]) setvbuf(stdout, buf, _IONBF, 48); - while((opt = getopt(argc, argv, "t:p:c:m:i:")) != -1) { + while((opt = getopt(argc, argv, "t:p:c:m:i:P:d:r")) != -1) { switch (opt) { case 't': targetIP = optarg; break; @@ -285,6 +309,17 @@ int main(int argc, char *argv[]) break; case 'i': msgNum = atoi(optarg); break; + case 'P': msgPRI = optarg; + break; + case 'd': extraDataLen = atoi(optarg); + if(extraDataLen > MAX_EXTRADATA_LEN) { + fprintf(stderr, "-d max is %d!\n", + MAX_EXTRADATA_LEN); + exit(1); + } + break; + case 'r': bRandomizeExtraData = 1; + break; } } @@ -298,7 +333,6 @@ int main(int argc, char *argv[]) exit(1); } - //closeConnections(); printf("End of tcpflood Run\n"); exit(ret); -- cgit 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 +- tests/Makefile.am | 9 ++++++++ tests/asynwr_large.sh | 20 +++++++++++++++++ tests/asynwr_simple.sh | 1 + tests/asynwr_small.sh | 1 + tests/asynwr_timeout.sh | 1 + tests/chkseq.c | 5 +++++ tests/diag.sh | 21 +++++++++++++++-- tests/gzipwr_large.sh | 20 +++++++++++++++++ tests/gzipwr_large_dynfile.sh | 36 ++++++++++++++++++++++++++++++ tests/longrun.sh | 22 ++++++++++++++++++ tests/tcpflood.c | 23 ++++++++++++++----- tests/testsuites/asynwr_large.conf | 15 +++++++++++++ tests/testsuites/gzipwr_large.conf | 15 +++++++++++++ tests/testsuites/gzipwr_large_dynfile.conf | 17 ++++++++++++++ 15 files changed, 200 insertions(+), 8 deletions(-) create mode 100755 tests/asynwr_large.sh create mode 100755 tests/gzipwr_large.sh create mode 100755 tests/gzipwr_large_dynfile.sh create mode 100755 tests/longrun.sh create mode 100644 tests/testsuites/asynwr_large.conf create mode 100644 tests/testsuites/gzipwr_large.conf create mode 100644 tests/testsuites/gzipwr_large_dynfile.conf 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)) diff --git a/tests/Makefile.am b/tests/Makefile.am index 92d3764b..13443f63 100644 --- a/tests/Makefile.am +++ b/tests/Makefile.am @@ -13,6 +13,9 @@ TESTS = $(TESTRUNS) cfg.sh \ asynwr_timeout.sh \ asynwr_small.sh \ asynwr_tinybuf.sh \ + asynwr_large.sh \ + gzipwr_large.sh \ + gzipwr_large_dynfile.sh \ queue-persist.sh \ pipeaction.sh execonlyonce.sh \ @@ -147,6 +150,12 @@ EXTRA_DIST= 1.rstest 2.rstest 3.rstest err1.rstest \ testsuites/asynwr_small.conf \ asynwr_tinybuf.sh \ testsuites/asynwr_tinybuf.conf \ + asynwr_large.sh \ + testsuites/asynwr_large.conf \ + gzipwr_large.sh \ + testsuites/gzipwr_large.conf \ + gzipwr_large_dynfile.sh \ + testsuites/gzipwr_large_dynfile.conf \ testsuites/small.conf \ proprepltest.sh \ testsuites/rfctag.conf \ diff --git a/tests/asynwr_large.sh b/tests/asynwr_large.sh new file mode 100755 index 00000000..158fd80b --- /dev/null +++ b/tests/asynwr_large.sh @@ -0,0 +1,20 @@ +# This tests async writing large data records. We use up to 10K +# record size. + +# added 2010-03-10 by Rgerhards +# +# This file is part of the rsyslog project, released under GPLv3 +echo =============================================================================== +echo TEST: \[asynwr_large.sh\]: test for async file writing for large message sets +source $srcdir/diag.sh init +# uncomment for debugging support: +#export RSYSLOG_DEBUG="debug nostdout noprintmutexaction" +#export RSYSLOG_DEBUGLOG="log" +source $srcdir/diag.sh startup asynwr_large.conf +# send 4000 messages of 10.000bytes plus header max, randomized +source $srcdir/diag.sh tcpflood -m4000 -r -d10000 -P129 +sleep 1 # due to large messages, we need this time for the tcp receiver to settle... +source $srcdir/diag.sh shutdown-when-empty # shut down rsyslogd when done processing messages +source $srcdir/diag.sh wait-shutdown # and wait for it to terminate +source $srcdir/diag.sh seq-check 0 3999 -E +source $srcdir/diag.sh exit diff --git a/tests/asynwr_simple.sh b/tests/asynwr_simple.sh index c21f7893..eb87443c 100755 --- a/tests/asynwr_simple.sh +++ b/tests/asynwr_simple.sh @@ -13,5 +13,6 @@ source $srcdir/diag.sh startup asynwr_simple.conf # 10K, the buffer size! source $srcdir/diag.sh tcpflood -m35555 source $srcdir/diag.sh shutdown-when-empty # shut down rsyslogd when done processing messages +source $srcdir/diag.sh wait-shutdown # and wait for it to terminate source $srcdir/diag.sh seq-check 0 35554 source $srcdir/diag.sh exit diff --git a/tests/asynwr_small.sh b/tests/asynwr_small.sh index ee091935..97818f6e 100755 --- a/tests/asynwr_small.sh +++ b/tests/asynwr_small.sh @@ -21,5 +21,6 @@ source $srcdir/diag.sh startup asynwr_small.conf # send 4000 messages source $srcdir/diag.sh tcpflood -m2 source $srcdir/diag.sh shutdown-when-empty # shut down rsyslogd when done processing messages +source $srcdir/diag.sh wait-shutdown # and wait for it to terminate source $srcdir/diag.sh seq-check 0 1 source $srcdir/diag.sh exit diff --git a/tests/asynwr_timeout.sh b/tests/asynwr_timeout.sh index 41b76ede..b0bc5c28 100755 --- a/tests/asynwr_timeout.sh +++ b/tests/asynwr_timeout.sh @@ -16,5 +16,6 @@ source $srcdir/diag.sh startup asynwr_timeout.conf source $srcdir/diag.sh tcpflood -m 35555 sleep 4 # wait for output writer to write and empty buffer source $srcdir/diag.sh shutdown-when-empty # shut down rsyslogd when done processing messages +source $srcdir/diag.sh wait-shutdown # and wait for it to terminate source $srcdir/diag.sh seq-check 0 35554 source $srcdir/diag.sh exit diff --git a/tests/chkseq.c b/tests/chkseq.c index b8088cd5..b22c8992 100644 --- a/tests/chkseq.c +++ b/tests/chkseq.c @@ -134,5 +134,10 @@ int main(int argc, char *argv[]) exit(1); } + if(!feof(fp)) { + printf("end of processing, but NOT end of file!\n"); + exit(1); + } + exit(ret); } diff --git a/tests/diag.sh b/tests/diag.sh index f3d75a15..b3154c44 100755 --- a/tests/diag.sh +++ b/tests/diag.sh @@ -18,6 +18,7 @@ case $1 in rm -f rsyslogd.started work-*.conf rm -f rsyslogd2.started work-*.conf rm -f work rsyslog.out.log rsyslog.out.log.save # common work files + rm -f rsyslog.out.*.log rm -rf test-spool rm -f core.* vgcore.* mkdir test-spool @@ -25,6 +26,7 @@ case $1 in 'exit') rm -f rsyslogd.started work-*.conf diag-common.conf rm -f rsyslogd2.started diag-common2.conf rm -f work rsyslog.out.log rsyslog.out.log.save # common work files + rm -f rsyslog.out.*.log rm -rf test-spool ;; 'startup') # start rsyslogd with default params. $2 is the config file name to use @@ -34,14 +36,16 @@ case $1 in ;; 'wait-startup') # wait for rsyslogd startup ($2 is the instance) while test ! -f rsyslogd$2.started; do - true + #true + sleep 0.1 # if this is not supported by all platforms, use above! done echo "rsyslogd$2 started with pid " `cat rsyslog$2.pid` ;; 'wait-shutdown') # actually, we wait for rsyslog.pid to be deleted. $2 is the # instance while test -f rsyslog$2.pid; do - true + #true + sleep 0.1 # if this is not supported by all platforms, use above! done ;; 'wait-queueempty') # wait for main message queue to be empty. $2 is the instance. @@ -85,6 +89,7 @@ case $1 in ;; 'seq-check') # do the usual sequence check to see if everything was properly received. $2 is the instance. rm -f work + cp rsyslog.out.log work-presort sort < rsyslog.out.log > work # $4... are just to have the abilit to pass in more options... ./chkseq -fwork -v -s$2 -e$3 $4 $5 $6 $7 @@ -105,6 +110,18 @@ case $1 in exit 1 fi ;; + 'gzip-seq-check') # do the usual sequence check, but for gzip files + rm -f work + ls -l rsyslog.out.log + gunzip < rsyslog.out.log | sort > work + ls -l work + # $4... are just to have the abilit to pass in more options... + ./chkseq -fwork -v -s$2 -e$3 $4 $5 $6 $7 + if [ "$?" -ne "0" ]; then + echo "sequence error detected" + exit 1 + fi + ;; 'nettester') # perform nettester-based tests # use -v for verbose output! ./nettester -t$2 -i$3 diff --git a/tests/gzipwr_large.sh b/tests/gzipwr_large.sh new file mode 100755 index 00000000..ffce06f6 --- /dev/null +++ b/tests/gzipwr_large.sh @@ -0,0 +1,20 @@ +# This tests writing large data records in gzip mode. We use up to 10K +# record size. +# +# added 2010-03-10 by Rgerhards +# +# This file is part of the rsyslog project, released under GPLv3 +echo =============================================================================== +echo TEST: \[gzipwr_large.sh\]: test for gzip file writing for large message sets +source $srcdir/diag.sh init +# uncomment for debugging support: +#export RSYSLOG_DEBUG="debug nostdout noprintmutexaction" +#export RSYSLOG_DEBUGLOG="log" +source $srcdir/diag.sh startup gzipwr_large.conf +# send 4000 messages of 10.000bytes plus header max, randomized +source $srcdir/diag.sh tcpflood -m4000 -r -d10000 -P129 +sleep 1 # due to large messages, we need this time for the tcp receiver to settle... +source $srcdir/diag.sh shutdown-when-empty # shut down rsyslogd when done processing messages +source $srcdir/diag.sh wait-shutdown # and wait for it to terminate +source $srcdir/diag.sh gzip-seq-check 0 3999 -E +source $srcdir/diag.sh exit diff --git a/tests/gzipwr_large_dynfile.sh b/tests/gzipwr_large_dynfile.sh new file mode 100755 index 00000000..ebd4c558 --- /dev/null +++ b/tests/gzipwr_large_dynfile.sh @@ -0,0 +1,36 @@ +# This tests writing large data records in gzip mode. We also write it to +# 5 different dynafiles, with a dynafile cache size set to 4. So this stresses +# both the input side, as well as zip writing, async writing and the dynafile +# cache logic. +# +# This test is a bit timing-dependent on the tcp reception side, so if it fails +# one may look into the timing first. The main issue is that the testbench +# currently has no good way to know if the tcp receiver is finished. This is NOT +# a problem in rsyslogd, but only of the testbench. +# +# Note that we do not yet have sufficient support for dynafiles in diag.sh, +# so we mangle some files here manually. +# +# added 2010-03-10 by Rgerhards +# +# This file is part of the rsyslog project, released under GPLv3 +echo ==================================================================================== +echo TEST: \[gzipwr_large_dynfile.sh\]: test for gzip file writing for large message sets +source $srcdir/diag.sh init +# uncomment for debugging support: +export RSYSLOG_DEBUG="debug nostdout" +export RSYSLOG_DEBUGLOG="log" +source $srcdir/diag.sh startup gzipwr_large_dynfile.conf +# send 4000 messages of 10.000bytes plus header max, randomized +source $srcdir/diag.sh tcpflood -m4000 -r -d10000 -P129 -f5 +sleep 2 # due to large messages, we need this time for the tcp receiver to settle... +source $srcdir/diag.sh shutdown-when-empty # shut down rsyslogd when done processing messages +source $srcdir/diag.sh wait-shutdown # and wait for it to terminate +gunzip < rsyslog.out.0.log > rsyslog.out.log +gunzip < rsyslog.out.1.log >> rsyslog.out.log +gunzip < rsyslog.out.2.log >> rsyslog.out.log +gunzip < rsyslog.out.3.log >> rsyslog.out.log +gunzip < rsyslog.out.4.log >> rsyslog.out.log +#cat rsyslog.out.* > rsyslog.out.log +source $srcdir/diag.sh seq-check 0 3999 -E +source $srcdir/diag.sh exit diff --git a/tests/longrun.sh b/tests/longrun.sh new file mode 100755 index 00000000..09bddc58 --- /dev/null +++ b/tests/longrun.sh @@ -0,0 +1,22 @@ +# This is a test-aid script to try running some tests through many iterations. +# It is not yet used in the automated testbench, but I keep this file so that +# I can use it whenever there is need to. As such, it currently does not have +# parameters but is expected to be edited as needed. -- rgerhards, 2010-03-10 +MAXRUNS=10 +DISPLAYALIVE=100 +LOGFILE=runlog + +date > $LOGFILE + +for (( i=0; $i < 10000; i++ )) + do + if [ $(( i % DISPLAYALIVE )) -eq 0 ]; then + echo "$i iterations done" + fi + ./gzipwr_large_dynfile.sh >> $LOGFILE + if [ "$?" -ne "0" ]; then + echo "Test failed in iteration $i!" + exit 1 + fi + done +echo "No failure in $i iterations." diff --git a/tests/tcpflood.c b/tests/tcpflood.c index fcfc30a7..0f9f21f2 100644 --- a/tests/tcpflood.c +++ b/tests/tcpflood.c @@ -14,6 +14,9 @@ * bytes as forth. Add -r to randomize the amount of extra * data included in the range 1..(value of -d). * -r randomize amount of extra data added (-d must be > 0) + * -f support for testing dynafiles. If given, include a dynafile ID + * in the range 0..(f-1) as the SECOND field, shifting all field values + * one field to the right. Zero (default) disables this functionality. * * Part of the testbench for rsyslog. * @@ -59,6 +62,7 @@ static char *targetIP = "127.0.0.1"; static char *msgPRI = "167"; static int targetPort = 13514; +static int dynFileIDs = 0; static int extraDataLen = 0; /* amount of extra data to add to message */ static int bRandomizeExtraData = 0; /* randomize amount of extra data added */ static int numMsgsToSend; /* number of messages to send */ @@ -177,6 +181,7 @@ int sendMessages(void) int lenBuf; int lenSend; int edLen; /* actual extra data length to use */ + char dynFileIDBuf[128] = ""; char buf[MAX_EXTRADATA_LEN + 1024]; char extraData[MAX_EXTRADATA_LEN + 1]; @@ -191,9 +196,12 @@ int sendMessages(void) socknum = i - (numMsgsToSend - numConnections); else socknum = rand() % numConnections; + if(dynFileIDs > 0) { + sprintf(dynFileIDBuf, "%d:", rand() % dynFileIDs); + } if(extraDataLen == 0) { - lenBuf = sprintf(buf, "<%s>Mar 1 01:00:00 172.20.245.8 tag msgnum:%8.8d:\n", - msgPRI, msgNum); + lenBuf = sprintf(buf, "<%s>Mar 1 01:00:00 172.20.245.8 tag msgnum:%s%8.8d:\n", + msgPRI, dynFileIDBuf, msgNum); } else { if(bRandomizeExtraData) edLen = ((long) rand() + extraDataLen) % extraDataLen + 1; @@ -201,8 +209,8 @@ int sendMessages(void) edLen = extraDataLen; memset(extraData, 'X', edLen); extraData[edLen] = '\0'; - lenBuf = sprintf(buf, "<%s>Mar 1 01:00:00 172.20.245.8 tag msgnum:%8.8d:%d:%s\n", - msgPRI, msgNum, edLen, extraData); + lenBuf = sprintf(buf, "<%s>Mar 1 01:00:00 172.20.245.8 tag msgnum:%s%8.8d:%d:%s\n", + msgPRI, dynFileIDBuf, msgNum, edLen, extraData); } lenSend = send(sockArray[socknum], buf, lenBuf, 0); if(lenSend != lenBuf) { @@ -297,7 +305,7 @@ int main(int argc, char *argv[]) setvbuf(stdout, buf, _IONBF, 48); - while((opt = getopt(argc, argv, "t:p:c:m:i:P:d:r")) != -1) { + while((opt = getopt(argc, argv, "f:t:p:c:m:i:P:d:r")) != -1) { switch (opt) { case 't': targetIP = optarg; break; @@ -320,6 +328,11 @@ int main(int argc, char *argv[]) break; case 'r': bRandomizeExtraData = 1; break; + case 'f': dynFileIDs = atoi(optarg); + break; + default: printf("invalid option '%c' or value missing - terminating...\n", opt); + exit (1); + break; } } diff --git a/tests/testsuites/asynwr_large.conf b/tests/testsuites/asynwr_large.conf new file mode 100644 index 00000000..de41bc43 --- /dev/null +++ b/tests/testsuites/asynwr_large.conf @@ -0,0 +1,15 @@ +# simple async writing test +# rgerhards, 2010-03-09 +$MaxMessageSize 10k +$IncludeConfig diag-common.conf + +$ModLoad ../plugins/imtcp/.libs/imtcp +$MainMsgQueueTimeoutShutdown 10000 +$InputTCPServerRun 13514 + +$template outfmt,"%msg:F,58:2%,%msg:F,58:3%,%msg:F,58:4%\n" +$template dynfile,"rsyslog.out.log" # trick to use relative path names! +$OMFileFlushOnTXEnd off +$OMFileFlushInterval 2 +$OMFileIOBufferSize 256k +local0.* ?dynfile;outfmt diff --git a/tests/testsuites/gzipwr_large.conf b/tests/testsuites/gzipwr_large.conf new file mode 100644 index 00000000..54ad3bb3 --- /dev/null +++ b/tests/testsuites/gzipwr_large.conf @@ -0,0 +1,15 @@ +# simple async writing test +# rgerhards, 2010-03-09 +$MaxMessageSize 10k +$IncludeConfig diag-common.conf + +$ModLoad ../plugins/imtcp/.libs/imtcp +$MainMsgQueueTimeoutShutdown 10000 +$InputTCPServerRun 13514 + +$template outfmt,"%msg:F,58:2%,%msg:F,58:3%,%msg:F,58:4%\n" +$template dynfile,"rsyslog.out.log" # trick to use relative path names! +$OMFileFlushOnTXEnd off +$OMFileZipLevel 6 +$OMFileIOBufferSize 256k +local0.* ?dynfile;outfmt diff --git a/tests/testsuites/gzipwr_large_dynfile.conf b/tests/testsuites/gzipwr_large_dynfile.conf new file mode 100644 index 00000000..31bcb978 --- /dev/null +++ b/tests/testsuites/gzipwr_large_dynfile.conf @@ -0,0 +1,17 @@ +# simple async writing test +# rgerhards, 2010-03-09 +$MaxMessageSize 10k +$IncludeConfig diag-common.conf + +$ModLoad ../plugins/imtcp/.libs/imtcp +$MainMsgQueueTimeoutShutdown 10000 +$InputTCPServerRun 13514 + +$template outfmt,"%msg:F,58:3%,%msg:F,58:4%,%msg:F,58:5%\n" +$template dynfile,"rsyslog.out.%msg:F,58:2%.log" # trick to use relative path names! +$OMFileFlushOnTXEnd off +$OMFileZipLevel 6 +$OMFileIOBufferSize 256k +$DynaFileCacheSize 4 +$omfileFlushInterval 1 +local0.* ?dynfile;outfmt -- cgit From 4f97db43dfbf78f08509a71a0924347d900707b8 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Thu, 11 Mar 2010 14:48:44 +0100 Subject: added more parser test cases also improved testing tools to support new testcase structure --- tests/Makefile.am | 1 + tests/nettester.c | 65 +++++++++++++++++++++++++++++++-- tests/testsuites/snare.parse1 | 83 +++++++++++++++++++++++++++++++++++++++++++ 3 files changed, 147 insertions(+), 2 deletions(-) create mode 100644 tests/testsuites/snare.parse1 diff --git a/tests/Makefile.am b/tests/Makefile.am index 13443f63..392f0644 100644 --- a/tests/Makefile.am +++ b/tests/Makefile.am @@ -85,6 +85,7 @@ EXTRA_DIST= 1.rstest 2.rstest 3.rstest err1.rstest \ testsuites/1.parse1 \ testsuites/2.parse1 \ testsuites/3.parse1 \ + testsuites/snare.parse1 \ testsuites/oversizeTag-1.parse1 \ testsuites/weird.parse1 \ testsuites/date1.parse1 \ diff --git a/tests/nettester.c b/tests/nettester.c index 209c2a6f..22b5f16f 100644 --- a/tests/nettester.c +++ b/tests/nettester.c @@ -47,6 +47,7 @@ #include #include #include +#include #define EXIT_FAILURE 1 #define INVALID_SOCKET -1 @@ -254,6 +255,62 @@ int openPipe(char *configFile, pid_t *pid, int *pfd) } +/* This function unescapes a string of testdata. That it, escape sequences + * are converted into their one-character equivalent. While doing so, it applies + * C-like semantics. This was made necessary for easy integration of control + * characters inside test cases. -- rgerhards, 2009-03-11 + * Currently supported: + * \\ single backslash + * \n, \t, \r as in C + * \nnn where nnn is a 1 to 3 character octal sequence + * Note that when a problem occurs, the end result is undefined. After all, this + * is for a testsuite generatort, it must not be 100% bullet proof (so do not + * copy this code into something that must be!). Also note that we do in-memory + * unescaping and assume that the string gets shorter but NEVER longer! + */ +void unescapeTestdata(char *testdata) +{ + char *pDst; + char *pSrc; + int i; + int c; + + pDst = pSrc = testdata; + while(*pSrc) { + if(*pSrc == '\\') { + switch(*++pSrc) { + case '\\': *pDst++ = *pSrc++; + break; + case 'n': *pDst++ = '\n'; + ++pSrc; + break; + case 'r': *pDst++ = '\r'; + ++pSrc; + break; + case 't': *pDst++ = '\t'; + ++pSrc; + break; + case '0': + case '1': + case '2': + case '3': c = *pSrc++ - '0'; + i = 1; /* we already processed one digit! */ + while(i < 3 && isdigit(*pSrc)) { + c = c * 8 + *pSrc++ - '0'; + ++i; + } + *pDst++ = c; + break; + default: break; + } + } else { + *pDst++ = *pSrc++; + } + } + *pDst = '\0'; +} + + /* Process a specific test case. File name is provided. * Needs to return 0 if all is OK, something else otherwise. */ @@ -291,6 +348,7 @@ processTestFile(int fd, char *pszFileName) testdata[strlen(testdata)-1] = '\0'; /* remove \n */ /* now we have the test data to send (we could use function pointers here...) */ + unescapeTestdata(testdata); if(inputMode == inputUDP) { if(udpSend(testdata, strlen(testdata)) != 0) return(2); @@ -314,10 +372,13 @@ processTestFile(int fd, char *pszFileName) expected, buf); ret = 1; } - + /* we need to free buffers, as we have potentially modified them! */ + free(testdata); + testdata = NULL; + free(expected); + expected = NULL; } - free(testdata); free(expected); fclose(fp); return(ret); diff --git a/tests/testsuites/snare.parse1 b/tests/testsuites/snare.parse1 new file mode 100644 index 00000000..550b0703 --- /dev/null +++ b/tests/testsuites/snare.parse1 @@ -0,0 +1,83 @@ +# some parse test build around data in snare-format +<141>Mar 10 09:30:20 zuse.xysystems.local MSWinEventLog\0111\011Security\011563\011Wed Mar 10 09:30:15 2010\011538\011Security\011XYWS011$\011User\011Success Audit\011ZUSE\011Logon/Logoff\011\011User Logoff: User Name: XYWS011$ Domain: XYZSYSTEMS Logon ID: (0x0,0x5984789C) Logon Type: 3 \011552 +141,local1,notice,Mar 10 09:30:20,zuse.xysystems.local,MSWinEventLog#0111#011Security#011563#011Wed,MSWinEventLog#0111#011Security#011563#011Wed, Mar 10 09:30:15 2010#011538#011Security#011XYWS011$#011User#011Success Audit#011ZUSE#011Logon/Logoff#011#011User Logoff: User Name: XYWS011$ Domain: XYZSYSTEMS Logon ID: (0x0,0x5984789C) Logon Type: 3 #011552 +# +# NEXT MESSAGE +# +Mar 10 09:30:20 zuse.xysystems.local MSWinEventLog\0111\011Security\011564\011Wed Mar 10 09:30:19 2010\011540\011Security\011BACKUP1$\011User\011Success Audit\011ZUSE\011Logon/Logoff\011\011Successful Network Logon: User Name: BACKUP1$ Domain: XYZSYSTEMS Logon ID: (0x0,0x59848DB4) Logon Type: 3 Logon Process: Kerberos Authentication Package: Kerberos Workstation Name: Logon GUID: {f6f65903-1932-d229-4b75-64816121d569} Caller User Name: - Caller Domain: - Caller Logon ID: - Caller Process ID: - Transited Services: - Source Network Address: 172.16.0.31 Source Port: 0 \011553 +13,user,notice,Mar 10 09:30:20,zuse.xysystems.local,MSWinEventLog#0111#011Security#011564#011Wed,MSWinEventLog#0111#011Security#011564#011Wed, Mar 10 09:30:19 2010#011540#011Security#011BACKUP1$#011User#011Success Audit#011ZUSE#011Logon/Logoff#011#011Successful Network Logon: User Name: BACKUP1$ Domain: XYZSYSTEMS Logon ID: (0x0,0x59848DB4) Logon Type: 3 Logon Process: Kerberos Authentication Package: Kerberos Workstation Name: Logon GUID: {f6f65903-1932-d229-4b75-64816121d569} Caller User Name: - Caller Domain: - Caller Logon ID: - Caller Process ID: - Transited Services: - Source Network Address: 172.16.0.31 Source Port: 0 #011553 +# +# NEXT MESSAGE +# +<141>Mar 10 09:30:25 zuse.xysystems.local MSWinEventLog\0111\011Security\011566\011Wed Mar 10 09:30:21 2010\011540\011Security\011aadminps\011User\011Success Audit\011ZUSE\011Logon/Logoff\011\011Successful Network Logon: User Name: aadminps Domain: XYSYSTEMS Logon ID: (0x0,0x5984973C) Logon Type: 3 Logon Process: Authz Authentication Package: Kerberos Workstation Name: ZUSE Logon GUID: - Caller User Name: ZUSE$ Caller Domain: XYSYSTEMS Caller Logon ID: (0x0,0x3E7) Caller Process ID: 1004 Transited Services: - Source Network Address: - Source Port: - \011555 +141,local1,notice,Mar 10 09:30:25,zuse.xysystems.local,MSWinEventLog#0111#011Security#011566#011Wed,MSWinEventLog#0111#011Security#011566#011Wed, Mar 10 09:30:21 2010#011540#011Security#011aadminps#011User#011Success Audit#011ZUSE#011Logon/Logoff#011#011Successful Network Logon: User Name: aadminps Domain: XYSYSTEMS Logon ID: (0x0,0x5984973C) Logon Type: 3 Logon Process: Authz Authentication Package: Kerberos Workstation Name: ZUSE Logon GUID: - Caller User Name: ZUSE$ Caller Domain: XYSYSTEMS Caller Logon ID: (0x0,0x3E7) Caller Process ID: 1004 Transited Services: - Source Network Address: - Source Port: - #011555 +# +# NEXT MESSAGE +# +<141>Mar 10 09:30:25 zuse.xysystems.local MSWinEventLog\0111\011Security\011567\011Wed Mar 10 09:30:21 2010\011538\011Security\011aadminps\011User\011Success Audit\011ZUSE\011Logon/Logoff\011\011User Logoff: User Name: aadminps Domain: XYSYSTEMS Logon ID: (0x0,0x5984973C) Logon Type: 3 \011556 +141,local1,notice,Mar 10 09:30:25,zuse.xysystems.local,MSWinEventLog#0111#011Security#011567#011Wed,MSWinEventLog#0111#011Security#011567#011Wed, Mar 10 09:30:21 2010#011538#011Security#011aadminps#011User#011Success Audit#011ZUSE#011Logon/Logoff#011#011User Logoff: User Name: aadminps Domain: XYSYSTEMS Logon ID: (0x0,0x5984973C) Logon Type: 3 #011556 +# +# NEXT MESSAGE +# +<141>Mar 10 09:30:25 zuse.xysystems.local MSWinEventLog\0111\011Security\011568\011Wed Mar 10 09:30:25 2010\011540\011Security\011ANONYMOUS LOGON\011Well Known Group\011Success Audit\011ZUSE\011Logon/Logoff\011\011Successful Network Logon: User Name: Domain: Logon ID: (0x0,0x5984AB6F) Logon Type: 3 Logon Process: NtLmSsp Authentication Package: NTLM Workstation Name: XYWS083 Logon GUID: - Caller User Name: - Caller Domain: - Caller Logon ID: - Caller Process ID: - Transited Services: - Source Network Address: 172.16.3.91 Source Port: 0 \011557 +141,local1,notice,Mar 10 09:30:25,zuse.xysystems.local,MSWinEventLog#0111#011Security#011568#011Wed,MSWinEventLog#0111#011Security#011568#011Wed, Mar 10 09:30:25 2010#011540#011Security#011ANONYMOUS LOGON#011Well Known Group#011Success Audit#011ZUSE#011Logon/Logoff#011#011Successful Network Logon: User Name: Domain: Logon ID: (0x0,0x5984AB6F) Logon Type: 3 Logon Process: NtLmSsp Authentication Package: NTLM Workstation Name: XYWS083 Logon GUID: - Caller User Name: - Caller Domain: - Caller Logon ID: - Caller Process ID: - Transited Services: - Source Network Address: 172.16.3.91 Source Port: 0 #011557 +# +# NEXT MESSAGE +# +<141>Mar 10 09:30:25 zuse.xysystems.local MSWinEventLog\0111\011Security\011569\011Wed Mar 10 09:30:25 2010\011540\011Security\011SYSTEM\011User\011Success Audit\011ZUSE\011Logon/Logoff\011\011Successful Network Logon: User Name: ZUSE$ Domain: XYSYSTEMS Logon ID: (0x0,0x5984ACA7) Logon Type: 3 Logon Process: Kerberos Authentication Package: Kerberos Workstation Name: Logon GUID: {20014d9a-ce6c-6834-d1ed-607c08f0b6a7} Caller User Name: - Caller Domain: - Caller Logon ID: - Caller Process ID: - Transited Services: - Source Network Address: 172.16.0.15 Source Port: 2318 \011558 +141,local1,notice,Mar 10 09:30:25,zuse.xysystems.local,MSWinEventLog#0111#011Security#011569#011Wed,MSWinEventLog#0111#011Security#011569#011Wed, Mar 10 09:30:25 2010#011540#011Security#011SYSTEM#011User#011Success Audit#011ZUSE#011Logon/Logoff#011#011Successful Network Logon: User Name: ZUSE$ Domain: XYSYSTEMS Logon ID: (0x0,0x5984ACA7) Logon Type: 3 Logon Process: Kerberos Authentication Package: Kerberos Workstation Name: Logon GUID: {20014d9a-ce6c-6834-d1ed-607c08f0b6a7} Caller User Name: - Caller Domain: - Caller Logon ID: - Caller Process ID: - Transited Services: - Source Network Address: 172.16.0.15 Source Port: 2318 #011558 +# +# NEXT MESSAGE +# +<141>Mar 10 09:30:25 zuse.xysystems.local MSWinEventLog\0111\011Security\011570\011Wed Mar 10 09:30:25 2010\011538\011Security\011SYSTEM\011User\011Success Audit\011ZUSE\011Logon/Logoff\011\011User Logoff: User Name: ZUSE$ Domain: XYSYSTEMS Logon ID: (0x0,0x5984ACA7) Logon Type: 3 \011559 +141,local1,notice,Mar 10 09:30:25,zuse.xysystems.local,MSWinEventLog#0111#011Security#011570#011Wed,MSWinEventLog#0111#011Security#011570#011Wed, Mar 10 09:30:25 2010#011538#011Security#011SYSTEM#011User#011Success Audit#011ZUSE#011Logon/Logoff#011#011User Logoff: User Name: ZUSE$ Domain: XYSYSTEMS Logon ID: (0x0,0x5984ACA7) Logon Type: 3 #011559 +# +# NEXT MESSAGE +# +<141>Mar 10 09:30:25 zuse.xysystems.local MSWinEventLog\0111\011Security\011571\011Wed Mar 10 09:30:25 2010\011540\011Security\011SYSTEM\011User\011Success Audit\011ZUSE\011Logon/Logoff\011\011Successful Network Logon: User Name: ZUSE$ Domain: XYSYSTEMS Logon ID: (0x0,0x5984AD7C) Logon Type: 3 Logon Process: Kerberos Authentication Package: Kerberos Workstation Name: Logon GUID: {20014d9a-ce6c-6834-d1ed-607c08f0b6a7} Caller User Name: - Caller Domain: - Caller Logon ID: - Caller Process ID: - Transited Services: - Source Network Address: 172.16.0.15 Source Port: 2319 \011560\ +141,local1,notice,Mar 10 09:30:25,zuse.xysystems.local,MSWinEventLog#0111#011Security#011571#011Wed,MSWinEventLog#0111#011Security#011571#011Wed, Mar 10 09:30:25 2010#011540#011Security#011SYSTEM#011User#011Success Audit#011ZUSE#011Logon/Logoff#011#011Successful Network Logon: User Name: ZUSE$ Domain: XYSYSTEMS Logon ID: (0x0,0x5984AD7C) Logon Type: 3 Logon Process: Kerberos Authentication Package: Kerberos Workstation Name: Logon GUID: {20014d9a-ce6c-6834-d1ed-607c08f0b6a7} Caller User Name: - Caller Domain: - Caller Logon ID: - Caller Process ID: - Transited Services: - Source Network Address: 172.16.0.15 Source Port: 2319 #011560 +# +# NEXT MESSAGE +# +<141>Mar 10 09:30:25 zuse.xysystems.local MSWinEventLog\0111\011Security\011572\011Wed Mar 10 09:30:25 2010\011538\011Security\011SYSTEM\011User\011Success Audit\011ZUSE\011Logon/Logoff\011\011User Logoff: User Name: ZUSE$ Domain: XYSYSTEMS Logon ID: (0x0,0x5984AD7C) Logon Type: 3 \011561 +141,local1,notice,Mar 10 09:30:25,zuse.xysystems.local,MSWinEventLog#0111#011Security#011572#011Wed,MSWinEventLog#0111#011Security#011572#011Wed, Mar 10 09:30:25 2010#011538#011Security#011SYSTEM#011User#011Success Audit#011ZUSE#011Logon/Logoff#011#011User Logoff: User Name: ZUSE$ Domain: XYSYSTEMS Logon ID: (0x0,0x5984AD7C) Logon Type: 3 #011561 +# +# NEXT MESSAGE +# +<141>Mar 10 09:30:25 zuse.xysystems.local MSWinEventLog\0111\011Security\011573\011Wed Mar 10 09:30:25 2010\011680\011Security\011ettore.trezzani\011User\011Success Audit\011ZUSE\011Account Logon\011\011Logon attempt by: MICROSOFT_AUTHENTICATION_PACKAGE_V1_0 Logon account: ettore.trezzani Source Workstation: XYWS083 Error Code: 0x0 \011562 +141,local1,notice,Mar 10 09:30:25,zuse.xysystems.local,MSWinEventLog#0111#011Security#011573#011Wed,MSWinEventLog#0111#011Security#011573#011Wed, Mar 10 09:30:25 2010#011680#011Security#011ettore.trezzani#011User#011Success Audit#011ZUSE#011Account Logon#011#011Logon attempt by: MICROSOFT_AUTHENTICATION_PACKAGE_V1_0 Logon account: ettore.trezzani Source Workstation: XYWS083 Error Code: 0x0 #011562 +# +# NEXT MESSAGE +# +<141>Mar 10 09:30:25 zuse.xysystems.local MSWinEventLog\0111\011Security\011574\011Wed Mar 10 09:30:25 2010\011540\011Security\011ettore.trezzani\011User\011Success Audit\011ZUSE\011Logon/Logoff\011\011Successful Network Logon: User Name: ettore.trezzani Domain: XYSYSTEMS Logon ID: (0x0,0x5984ADD5) Logon Type: 3 Logon Process: NtLmSsp Authentication Package: NTLM Workstation Name: XYWS083 Logon GUID: - Caller User Name: - Caller Domain: - Caller Logon ID: - Caller Process ID: - Transited Services: - Source Network Address: 172.16.3.91 Source Port: 0 \011563 +141,local1,notice,Mar 10 09:30:25,zuse.xysystems.local,MSWinEventLog#0111#011Security#011574#011Wed,MSWinEventLog#0111#011Security#011574#011Wed, Mar 10 09:30:25 2010#011540#011Security#011ettore.trezzani#011User#011Success Audit#011ZUSE#011Logon/Logoff#011#011Successful Network Logon: User Name: ettore.trezzani Domain: XYSYSTEMS Logon ID: (0x0,0x5984ADD5) Logon Type: 3 Logon Process: NtLmSsp Authentication Package: NTLM Workstation Name: XYWS083 Logon GUID: - Caller User Name: - Caller Domain: - Caller Logon ID: - Caller Process ID: - Transited Services: - Source Network Address: 172.16.3.91 Source Port: 0 #011563 +# +# NEXT MESSAGE +# +<141>Mar 10 09:30:25 zuse.xysystems.local MSWinEventLog\0111\011Security\011575\011Wed Mar 10 09:30:25 2010\011540\011Security\011SYSTEM\011User\011Success Audit\011ZUSE\011Logon/Logoff\011\011Successful Network Logon: User Name: ZUSE$ Domain: XYSYSTEMS Logon ID: (0x0,0x5984AE49) Logon Type: 3 Logon Process: Kerberos Authentication Package: Kerberos Workstation Name: Logon GUID: {20014d9a-ce6c-6834-d1ed-607c08f0b6a7} Caller User Name: - Caller Domain: - Caller Logon ID: - Caller Process ID: - Transited Services: - Source Network Address: 172.16.0.15 Source Port: 2320 \011564 +141,local1,notice,Mar 10 09:30:25,zuse.xysystems.local,MSWinEventLog#0111#011Security#011575#011Wed,MSWinEventLog#0111#011Security#011575#011Wed, Mar 10 09:30:25 2010#011540#011Security#011SYSTEM#011User#011Success Audit#011ZUSE#011Logon/Logoff#011#011Successful Network Logon: User Name: ZUSE$ Domain: XYSYSTEMS Logon ID: (0x0,0x5984AE49) Logon Type: 3 Logon Process: Kerberos Authentication Package: Kerberos Workstation Name: Logon GUID: {20014d9a-ce6c-6834-d1ed-607c08f0b6a7} Caller User Name: - Caller Domain: - Caller Logon ID: - Caller Process ID: - Transited Services: - Source Network Address: 172.16.0.15 Source Port: 2320 #011564 +# +# NEXT MESSAGE +# +<141>Mar 10 09:30:25 zuse.xysystems.local MSWinEventLog\0111\011Security\011576\011Wed Mar 10 09:30:25 2010\011538\011Security\011SYSTEM\011User\011Success Audit\011ZUSE\011Logon/Logoff\011\011User Logoff: User Name: ZUSE$ Domain: XYSYSTEMS Logon ID: (0x0,0x5984AE49) Logon Type: 3 \011565 +141,local1,notice,Mar 10 09:30:25,zuse.xysystems.local,MSWinEventLog#0111#011Security#011576#011Wed,MSWinEventLog#0111#011Security#011576#011Wed, Mar 10 09:30:25 2010#011538#011Security#011SYSTEM#011User#011Success Audit#011ZUSE#011Logon/Logoff#011#011User Logoff: User Name: ZUSE$ Domain: XYSYSTEMS Logon ID: (0x0,0x5984AE49) Logon Type: 3 #011565 +# +# NEXT MESSAGE +# +<141>Mar 10 09:30:25 zuse.xysystems.local MSWinEventLog\0111\011Security\011577\011Wed Mar 10 09:30:25 2010\011540\011Security\011SYSTEM\011User\011Success Audit\011ZUSE\011Logon/Logoff\011\011Successful Network Logon: User Name: ZUSE$ Domain: XYSYSTEMS Logon ID: (0x0,0x5984AF00) Logon Type: 3 Logon Process: Kerberos Authentication Package: Kerberos Workstation Name: Logon GUID: {20014d9a-ce6c-6834-d1ed-607c08f0b6a7} Caller User Name: - Caller Domain: - Caller Logon ID: - Caller Process ID: - Transited Services: - Source Network Address: 172.16.0.15 Source Port: 2321 \011566 +141,local1,notice,Mar 10 09:30:25,zuse.xysystems.local,MSWinEventLog#0111#011Security#011577#011Wed,MSWinEventLog#0111#011Security#011577#011Wed, Mar 10 09:30:25 2010#011540#011Security#011SYSTEM#011User#011Success Audit#011ZUSE#011Logon/Logoff#011#011Successful Network Logon: User Name: ZUSE$ Domain: XYSYSTEMS Logon ID: (0x0,0x5984AF00) Logon Type: 3 Logon Process: Kerberos Authentication Package: Kerberos Workstation Name: Logon GUID: {20014d9a-ce6c-6834-d1ed-607c08f0b6a7} Caller User Name: - Caller Domain: - Caller Logon ID: - Caller Process ID: - Transited Services: - Source Network Address: 172.16.0.15 Source Port: 2321 #011566 +# +# NEXT MESSAGE +# +<141>Mar 10 09:30:25 zuse.xysystems.local MSWinEventLog\0111\011Security\011578\011Wed Mar 10 09:30:25 2010\011538\011Security\011SYSTEM\011User\011Success Audit\011ZUSE\011Logon/Logoff\011\011User Logoff: User Name: ZUSE$ Domain: XYSYSTEMS Logon ID: (0x0,0x5984AF00) Logon Type: 3 \011567 +141,local1,notice,Mar 10 09:30:25,zuse.xysystems.local,MSWinEventLog#0111#011Security#011578#011Wed,MSWinEventLog#0111#011Security#011578#011Wed, Mar 10 09:30:25 2010#011538#011Security#011SYSTEM#011User#011Success Audit#011ZUSE#011Logon/Logoff#011#011User Logoff: User Name: ZUSE$ Domain: XYSYSTEMS Logon ID: (0x0,0x5984AF00) Logon Type: 3 #011567 +# +# NEXT MESSAGE +# +<141>Mar 10 09:30:25 zuse.xysystems.local MSWinEventLog\0111\011Security\011579\011Wed Mar 10 09:30:25 2010\011538\011Security\011ANONYMOUS LOGON\011Well Known Group\011Success Audit\011ZUSE\011Logon/Logoff\011\011User Logoff: User Name: ANONYMOUS LOGON Domain: NT AUTHORITY Logon ID: (0x0,0x5984AB6F) Logon Type: 3 \011568 +141,local1,notice,Mar 10 09:30:25,zuse.xysystems.local,MSWinEventLog#0111#011Security#011579#011Wed,MSWinEventLog#0111#011Security#011579#011Wed, Mar 10 09:30:25 2010#011538#011Security#011ANONYMOUS LOGON#011Well Known Group#011Success Audit#011ZUSE#011Logon/Logoff#011#011User Logoff: User Name: ANONYMOUS LOGON Domain: NT AUTHORITY Logon ID: (0x0,0x5984AB6F) Logon Type: 3 #011568 +# +# NEXT MESSAGE +# +<141>Mar 10 09:30:30 zuse.xysystems.local MSWinEventLog\0111\011Security\011580\011Wed Mar 10 09:30:29 2010\011540\011Security\011XYWSBADGE$\011User\011Success Audit\011ZUSE\011Logon/Logoff\011\011Successful Network Logon: User Name: XYWSBADGE$ Domain: XYSYSTEMS Logon ID: (0x0,0x59852D73) Logon Type: 3 Logon Process: Kerberos Authentication Package: Kerberos Workstation Name: Logon GUID: {4bc3c075-5a77-4648-5822-bfdf88b4c211} Caller User Name: - Caller Domain: - Caller Logon ID: - Caller Process ID: - Transited Services: - Source Network Address: 172.16.3.18 Source Port: 0 \011569 +141,local1,notice,Mar 10 09:30:30,zuse.xysystems.local,MSWinEventLog#0111#011Security#011580#011Wed,MSWinEventLog#0111#011Security#011580#011Wed, Mar 10 09:30:29 2010#011540#011Security#011XYWSBADGE$#011User#011Success Audit#011ZUSE#011Logon/Logoff#011#011Successful Network Logon: User Name: XYWSBADGE$ Domain: XYSYSTEMS Logon ID: (0x0,0x59852D73) Logon Type: 3 Logon Process: Kerberos Authentication Package: Kerberos Workstation Name: Logon GUID: {4bc3c075-5a77-4648-5822-bfdf88b4c211} Caller User Name: - Caller Domain: - Caller Logon ID: - Caller Process ID: - Transited Services: - Source Network Address: 172.16.3.18 Source Port: 0 #011569 -- cgit 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. --- ChangeLog | 4 ++++ runtime/debug.c | 9 +++++++++ 2 files changed, 13 insertions(+) diff --git a/ChangeLog b/ChangeLog index 7fe59dd9..4a57639e 100644 --- a/ChangeLog +++ b/ChangeLog @@ -20,6 +20,10 @@ Version 4.6.2 [v4-stable] (rgerhards), 2010-03-?? in proper retries. - bugfix: $omfileFlushOnTXEnd was turned on when set to off and vice versa due to an invalid check +- 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. --------------------------------------------------------------------------- Version 4.6.1 [v4-stable] (rgerhards), 2010-03-04 - re-enabled old pipe output (using new module ompipe, built-in) after 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 From 46861a84f835a9579fa97b757be361d78b3d1c64 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Mon, 15 Mar 2010 09:36:02 +0100 Subject: fix recently introduced minor nit in Makefile for testbench --- tests/Makefile.am | 1 - 1 file changed, 1 deletion(-) diff --git a/tests/Makefile.am b/tests/Makefile.am index 392f0644..91152679 100644 --- a/tests/Makefile.am +++ b/tests/Makefile.am @@ -157,7 +157,6 @@ EXTRA_DIST= 1.rstest 2.rstest 3.rstest err1.rstest \ testsuites/gzipwr_large.conf \ gzipwr_large_dynfile.sh \ testsuites/gzipwr_large_dynfile.conf \ - testsuites/small.conf \ proprepltest.sh \ testsuites/rfctag.conf \ testsuites/master.rfctag \ -- cgit From 4cb3e80152ed4674ed370915f7c02889b5bfb6f3 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Tue, 16 Mar 2010 14:23:13 +0100 Subject: added new, complex testcase to testbench this is an excerpt from some of the more intensen manual tests I am doing, stripped down to be useful inside the testbench. --- tests/Makefile.am | 3 +++ tests/diag.sh | 2 +- tests/tcpflood.c | 27 ++++++++++++++++++++------- 3 files changed, 24 insertions(+), 8 deletions(-) diff --git a/tests/Makefile.am b/tests/Makefile.am index 91152679..bc7902b1 100644 --- a/tests/Makefile.am +++ b/tests/Makefile.am @@ -16,6 +16,7 @@ TESTS = $(TESTRUNS) cfg.sh \ asynwr_large.sh \ gzipwr_large.sh \ gzipwr_large_dynfile.sh \ + complex1.sh \ queue-persist.sh \ pipeaction.sh execonlyonce.sh \ @@ -157,6 +158,8 @@ EXTRA_DIST= 1.rstest 2.rstest 3.rstest err1.rstest \ testsuites/gzipwr_large.conf \ gzipwr_large_dynfile.sh \ testsuites/gzipwr_large_dynfile.conf \ + complex1.sh \ + testsuites/complex1.conf \ proprepltest.sh \ testsuites/rfctag.conf \ testsuites/master.rfctag \ diff --git a/tests/diag.sh b/tests/diag.sh index b3154c44..a4f13afd 100755 --- a/tests/diag.sh +++ b/tests/diag.sh @@ -66,7 +66,7 @@ case $1 in # note: we do not wait for the actual termination! ;; 'tcpflood') # do a tcpflood run and check if it worked params are passed to tcpflood - ./tcpflood $2 $3 $4 $5 $6 $7 $8 + ./tcpflood $2 $3 $4 $5 $6 $7 $8 $9 if [ "$?" -ne "0" ]; then echo "error during tcpflood! see rsyslog.out.log.save for what was written" cp rsyslog.out.log rsyslog.out.log.save diff --git a/tests/tcpflood.c b/tests/tcpflood.c index 0f9f21f2..0d819d1d 100644 --- a/tests/tcpflood.c +++ b/tests/tcpflood.c @@ -4,6 +4,7 @@ * Params * -t target address (default 127.0.0.1) * -p target port (default 13514) + * -n number of target ports (targets are in range -p..(-p+-n-1) * -c number of connections (default 1) * -m number of messages to send (connection is random) * -i initial message number (optional) @@ -62,6 +63,7 @@ static char *targetIP = "127.0.0.1"; static char *msgPRI = "167"; static int targetPort = 13514; +static int numTargetPorts = 1; static int dynFileIDs = 0; static int extraDataLen = 0; /* amount of extra data to add to message */ static int bRandomizeExtraData = 0; /* randomize amount of extra data added */ @@ -77,16 +79,25 @@ int openConn(int *fd) { int sock; struct sockaddr_in addr; + int port; int retries = 0; + int rnd; if((sock=socket(AF_INET, SOCK_STREAM, 0))==-1) { perror("socket()"); return(1); } + /* randomize port if required */ + if(numTargetPorts > 1) { + rnd = rand(); /* easier if we need value for debug messages ;) */ + port = targetPort + (rnd % numTargetPorts); + } else { + port = targetPort; + } memset((char *) &addr, 0, sizeof(addr)); addr.sin_family = AF_INET; - addr.sin_port = htons(targetPort); + addr.sin_port = htons(port); if(inet_aton(targetIP, &addr.sin_addr)==0) { fprintf(stderr, "inet_aton() failed\n"); return(1); @@ -185,10 +196,8 @@ int sendMessages(void) char buf[MAX_EXTRADATA_LEN + 1024]; char extraData[MAX_EXTRADATA_LEN + 1]; - srand(time(NULL)); /* seed is good enough for our needs */ - printf("Sending %d messages.\n", numMsgsToSend); - printf("\r%5.5d messages sent", 0); + printf("\r%8.8d messages sent", 0); for(i = 0 ; i < numMsgsToSend ; ++i) { if(i < numConnections) socknum = i; @@ -222,11 +231,11 @@ int sendMessages(void) return(1); } if(i % 100 == 0) { - printf("\r%5.5d", i); + printf("\r%8.8d", i); } ++msgNum; } - printf("\r%5.5d messages sent\n", i); + printf("\r%8.8d messages sent\n", i); return 0; } @@ -295,6 +304,8 @@ int main(int argc, char *argv[]) struct sigaction sigAct; static char buf[1024]; + srand(time(NULL)); /* seed is good enough for our needs */ + /* on Solaris, we do not HAVE MSG_NOSIGNAL, so for this reason * we block SIGPIPE (not an issue for this program) */ @@ -305,12 +316,14 @@ int main(int argc, char *argv[]) setvbuf(stdout, buf, _IONBF, 48); - while((opt = getopt(argc, argv, "f:t:p:c:m:i:P:d:r")) != -1) { + while((opt = getopt(argc, argv, "f:t:p:c:m:i:P:d:n:r")) != -1) { switch (opt) { case 't': targetIP = optarg; break; case 'p': targetPort = atoi(optarg); break; + case 'n': numTargetPorts = atoi(optarg); + break; case 'c': numConnections = atoi(optarg); break; case 'm': numMsgsToSend = atoi(optarg); -- cgit From 219336ec5a560a472f7b4e1d60a42e13685e9a5c Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Tue, 16 Mar 2010 17:02:49 +0100 Subject: bugfix: recent patch to fix small memory leak could cause invalid free. This could only happen during config file parsing. --- ChangeLog | 2 ++ plugins/omgssapi/omgssapi.c | 4 ++-- tools/omfwd.c | 4 ++-- 3 files changed, 6 insertions(+), 4 deletions(-) diff --git a/ChangeLog b/ChangeLog index 4a57639e..829e64b2 100644 --- a/ChangeLog +++ b/ChangeLog @@ -20,6 +20,8 @@ Version 4.6.2 [v4-stable] (rgerhards), 2010-03-?? in proper retries. - bugfix: $omfileFlushOnTXEnd was turned on when set to off and vice versa due to an invalid check +- bugfix: recent patch to fix small memory leak could cause invalid free. + This could only happen during config file parsing. - 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 diff --git a/plugins/omgssapi/omgssapi.c b/plugins/omgssapi/omgssapi.c index d9f80c14..782ac22f 100644 --- a/plugins/omgssapi/omgssapi.c +++ b/plugins/omgssapi/omgssapi.c @@ -377,7 +377,7 @@ CODESTARTtryResume ENDtryResume BEGINdoAction - char *psz; /* temporary buffering */ + char *psz = NULL; /* temporary buffering */ register unsigned l; int iMaxLine; CODESTARTdoAction @@ -454,7 +454,7 @@ CODESTARTdoAction } finalize_it: # ifdef USE_NETZIP - if(psz != (char*) ppString[0]) { + if((psz != NULL) && (psz != (char*) ppString[0])) { /* we need to free temporary buffer, alloced above - Naoya Nakazawa, 2010-01-11 */ free(psz); } diff --git a/tools/omfwd.c b/tools/omfwd.c index a6d83eb9..cbfc36a4 100644 --- a/tools/omfwd.c +++ b/tools/omfwd.c @@ -411,7 +411,7 @@ CODESTARTtryResume ENDtryResume BEGINdoAction - char *psz; /* temporary buffering */ + char *psz = NULL; /* temporary buffering */ register unsigned l; int iMaxLine; CODESTARTdoAction @@ -487,7 +487,7 @@ CODESTARTdoAction } finalize_it: # ifdef USE_NETZIP - if(psz != (char*) ppString[0]) { + if((psz != NULL) && (psz != (char*) ppString[0])) { /* we need to free temporary buffer, alloced above - Naoya Nakazawa, 2010-01-11 */ free(psz); } -- cgit 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(-) 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 From a577b09e58789c39b2f50e0bd89125fbad76672a Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Tue, 16 Mar 2010 19:01:22 +0100 Subject: reduced runtime requirements of inactive debug code a slight bit --- runtime/stream.c | 20 ++++++++++---------- 1 file changed, 10 insertions(+), 10 deletions(-) diff --git a/runtime/stream.c b/runtime/stream.c index d76f12e7..3373b795 100644 --- a/runtime/stream.c +++ b/runtime/stream.c @@ -220,7 +220,7 @@ doPhysOpen(strm_t *pThis) char errStr[1024]; int err = errno; rs_strerror_r(err, errStr, sizeof(errStr)); - dbgoprint((obj_t*) pThis, "open error %d, file '%s': %s\n", errno, pThis->pszCurrFName, errStr); + DBGOPRINT((obj_t*) pThis, "open error %d, file '%s': %s\n", errno, pThis->pszCurrFName, errStr); if(err == ENOENT) ABORT_FINALIZE(RS_RET_FILE_NOT_FOUND); else @@ -278,7 +278,7 @@ static rsRetVal strmOpenFile(strm_t *pThis) pThis->iCurrOffs = offset; } - dbgoprint((obj_t*) pThis, "opened file '%s' for %s as %d\n", pThis->pszCurrFName, + DBGOPRINT((obj_t*) pThis, "opened file '%s' for %s as %d\n", pThis->pszCurrFName, (pThis->tOperationsMode == STREAMMODE_READ) ? "READ" : "WRITE", pThis->fd); finalize_it: @@ -316,7 +316,7 @@ static rsRetVal strmCloseFile(strm_t *pThis) DEFiRet; ASSERT(pThis != NULL); - dbgoprint((obj_t*) pThis, "file %d closing\n", pThis->fd); + DBGOPRINT((obj_t*) pThis, "file %d closing\n", pThis->fd); if(pThis->tOperationsMode != STREAMMODE_READ) { strmFlush(pThis); @@ -441,7 +441,7 @@ strmHandleEOF(strm_t *pThis) case STREAMTYPE_FILE_CIRCULAR: /* we have multiple files and need to switch to the next one */ /* TODO: think about emulating EOF in this case (not yet needed) */ - dbgoprint((obj_t*) pThis, "file %d EOF\n", pThis->fd); + DBGOPRINT((obj_t*) pThis, "file %d EOF\n", pThis->fd); CHKiRet(strmNextFile(pThis)); break; case STREAMTYPE_FILE_MONITOR: @@ -473,7 +473,7 @@ strmReadBuf(strm_t *pThis) */ CHKiRet(strmOpenFile(pThis)); iLenRead = read(pThis->fd, pThis->pIOBuf, pThis->sIOBufSize); - dbgoprint((obj_t*) pThis, "file %d read %ld bytes\n", pThis->fd, iLenRead); + DBGOPRINT((obj_t*) pThis, "file %d read %ld bytes\n", pThis->fd, iLenRead); if(iLenRead == 0) { CHKiRet(strmHandleEOF(pThis)); } else if(iLenRead < 0) @@ -505,7 +505,7 @@ static rsRetVal strmReadChar(strm_t *pThis, uchar *pC) ASSERT(pThis != NULL); ASSERT(pC != NULL); - /* DEV debug only: dbgoprint((obj_t*) pThis, "strmRead index %d, max %d\n", pThis->iBufPtr, pThis->iBufPtrMax); */ + /* DEV debug only: DBGOPRINT((obj_t*) pThis, "strmRead index %d, max %d\n", pThis->iBufPtr, pThis->iBufPtrMax); */ if(pThis->iUngetC != -1) { /* do we have an "unread" char that we need to provide? */ *pC = pThis->iUngetC; ++pThis->iCurrOffs; /* one more octet read */ @@ -731,7 +731,7 @@ static rsRetVal strmCheckNextOutputFile(strm_t *pThis) strmWaitAsyncWriterDone(pThis); if(pThis->iCurrOffs >= pThis->iMaxFileSize) { - dbgoprint((obj_t*) pThis, "max file size %ld reached for %d, now %ld - starting new file\n", + DBGOPRINT((obj_t*) pThis, "max file size %ld reached for %d, now %ld - starting new file\n", (long) pThis->iMaxFileSize, pThis->fd, (long) pThis->iCurrOffs); CHKiRet(strmNextFile(pThis)); } @@ -811,7 +811,7 @@ doWriteCall(strm_t *pThis, uchar *pBuf, size_t *pLenBuf) pWriteBuf += iWritten; } while(lenBuf > 0); /* Warning: do..while()! */ - dbgoprint((obj_t*) pThis, "file %d write wrote %d bytes\n", pThis->fd, (int) iWritten); + DBGOPRINT((obj_t*) pThis, "file %d write wrote %d bytes\n", pThis->fd, (int) iWritten); finalize_it: *pLenBuf = iTotalWritten; @@ -1130,7 +1130,7 @@ strmFlush(strm_t *pThis) DEFiRet; ASSERT(pThis != NULL); - dbgoprint((obj_t*) pThis, "file %d flush, buflen %ld\n", pThis->fd, (long) pThis->iBufPtr); + DBGOPRINT((obj_t*) pThis, "file %d flush, buflen %ld\n", pThis->fd, (long) pThis->iBufPtr); if(pThis->tOperationsMode != STREAMMODE_READ && pThis->iBufPtr > 0) { iRet = strmSchedWrite(pThis, pThis->pIOBuf, pThis->iBufPtr); @@ -1155,7 +1155,7 @@ static rsRetVal strmSeek(strm_t *pThis, off_t offs) else strmFlush(pThis); int i; - dbgoprint((obj_t*) pThis, "file %d seek, pos %ld\n", pThis->fd, (long) offs); + DBGOPRINT((obj_t*) pThis, "file %d seek, pos %ld\n", pThis->fd, (long) offs); i = lseek(pThis->fd, offs, SEEK_SET); // TODO: check error! pThis->iCurrOffs = offs; /* we are now at *this* offset */ pThis->iBufPtr = 0; /* buffer invalidated */ -- cgit From d7faed130cb089343ea3d9875561582e6f1d469f Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Tue, 16 Mar 2010 19:06:01 +0100 Subject: bugfix(cosmetic): tried to close non-open fd, resulting in close(-1) --- runtime/stream.c | 9 +++++++-- 1 file changed, 7 insertions(+), 2 deletions(-) diff --git a/runtime/stream.c b/runtime/stream.c index 3373b795..87daedaf 100644 --- a/runtime/stream.c +++ b/runtime/stream.c @@ -325,8 +325,13 @@ static rsRetVal strmCloseFile(strm_t *pThis) } } - close(pThis->fd); - pThis->fd = -1; + /* the file may already be closed (or never have opened), so guard + * against this. -- rgerhards, 2010-03-19 + */ + if(pThis->fd != -1) { + close(pThis->fd); + pThis->fd = -1; + } if(pThis->fdDir != -1) { /* close associated directory handle, if it is open */ -- cgit From ba0f23182a55b26b2265d2138c707cbc7ddbb72e Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Wed, 17 Mar 2010 16:25:24 +0100 Subject: new feature: "." action type added to support writing files to relative pathes (this is primarily meant as a debug aid) --- ChangeLog | 2 ++ doc/rsyslog_conf_actions.html | 11 +++++++++-- tools/omfile.c | 3 ++- 3 files changed, 13 insertions(+), 3 deletions(-) diff --git a/ChangeLog b/ChangeLog index 829e64b2..1f74b252 100644 --- a/ChangeLog +++ b/ChangeLog @@ -1,5 +1,7 @@ --------------------------------------------------------------------------- Version 4.6.2 [v4-stable] (rgerhards), 2010-03-?? +- new feature: "." action type added to support writing files to relative + pathes (this is primarily meant as a debug aid) - added new property replacer option "date-rfc3164-buggyday" primarily to ease migration from syslog-ng. See property replacer doc for details. [backport from 5.5.3 because urgently needed by some] diff --git a/doc/rsyslog_conf_actions.html b/doc/rsyslog_conf_actions.html index 8c4b9cfc..6020dd88 100644 --- a/doc/rsyslog_conf_actions.html +++ b/doc/rsyslog_conf_actions.html @@ -37,8 +37,15 @@ compared to the otherwise-equal config directives below:

    *.=crit /var/log/critmsgs

     

    Regular File

    -

    Typically messages are logged to real files. The file has to -be specified with full pathname, beginning with a slash "/''.
    +

    Typically messages are logged to real files. The file usually is +specified by full pathname, beginning with a slash "/". +Starting with version 4.6.2 and 5.4.1 (previous v5 version do NOT support this) +relative file names can also be specified. To do so, these must begin with a +dot. For example, use "./file-in-current-dir.log" to specify a file in the +current directory. Please note that rsyslogd usually changes its working +directory to the root, so relative file names must be tested with care (they +were introduced primarily as a debugging vehicle, but may have useful other applications +as well).


    You may prefix each entry with the minus "-'' sign to omit syncing the diff --git a/tools/omfile.c b/tools/omfile.c index daefa680..438f8c4a 100644 --- a/tools/omfile.c +++ b/tools/omfile.c @@ -633,7 +633,7 @@ ENDdoAction BEGINparseSelectorAct CODESTARTparseSelectorAct - if(!(*p == '$' || *p == '?' || *p == '/' || *p == '-')) + if(!(*p == '$' || *p == '?' || *p == '/' || *p == '.' || *p == '-')) ABORT_FINALIZE(RS_RET_CONFLINE_UNPROCESSED); CHKiRet(createInstance(&pData)); @@ -683,6 +683,7 @@ CODESTARTparseSelectorAct * need high-performance pipes at a later stage (unlikely). -- rgerhards, 2010-02-28 */ case '/': + case '.': CODE_STD_STRING_REQUESTparseSelectorAct(1) /* we now have *almost* the same semantics for files and pipes, but we still need * to know we deal with a pipe, because we must do non-blocking opens in that case -- cgit From 679434312c20d9651faff26b8b3a5ab203be7ff3 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Wed, 17 Mar 2010 16:39:18 +0100 Subject: added test to check for deadlock condition in async-written files Note that this introduces a test case that breaks the current code. This commit does NOT yet provide the necessary code patch. Thus make check does currently hang. --- tests/Makefile.am | 3 +++ tests/asynwr_deadlock.sh | 23 +++++++++++++++++++++++ tests/testsuites/asynwr_deadlock.conf | 21 +++++++++++++++++++++ 3 files changed, 47 insertions(+) create mode 100755 tests/asynwr_deadlock.sh create mode 100644 tests/testsuites/asynwr_deadlock.conf diff --git a/tests/Makefile.am b/tests/Makefile.am index bc7902b1..3c2223d9 100644 --- a/tests/Makefile.am +++ b/tests/Makefile.am @@ -14,6 +14,7 @@ TESTS = $(TESTRUNS) cfg.sh \ asynwr_small.sh \ asynwr_tinybuf.sh \ asynwr_large.sh \ + asynwr_deadlock.sh \ gzipwr_large.sh \ gzipwr_large_dynfile.sh \ complex1.sh \ @@ -154,6 +155,8 @@ EXTRA_DIST= 1.rstest 2.rstest 3.rstest err1.rstest \ testsuites/asynwr_tinybuf.conf \ asynwr_large.sh \ testsuites/asynwr_large.conf \ + asynwr_deadlock.sh \ + testsuites/asynwr_deadlock.conf \ gzipwr_large.sh \ testsuites/gzipwr_large.conf \ gzipwr_large_dynfile.sh \ diff --git a/tests/asynwr_deadlock.sh b/tests/asynwr_deadlock.sh new file mode 100755 index 00000000..2d08419c --- /dev/null +++ b/tests/asynwr_deadlock.sh @@ -0,0 +1,23 @@ +# This is test case from practice, with the version we introduced it, it +# caused a deadlock on shutdown. I have added it to the test suite to automatically +# detect such things in the future. +# +# added 2010-03-17 by Rgerhards +# This file is part of the rsyslog project, released under GPLv3 +echo ================================================================================ +echo TEST: \[asynwr_deadlock.sh\]: a case known to have caused a deadlock in the past +source $srcdir/diag.sh init +# uncomment for debugging support: +export RSYSLOG_DEBUG="debug nostdout noprintmutexaction" +export RSYSLOG_DEBUGLOG="log" +source $srcdir/diag.sh startup asynwr_deadlock.conf +# just send one message +source $srcdir/diag.sh tcpflood -m1 +# sleep is important! need to make sure the instance is inactive +sleep 1 +# now try shutdown. The actual test is if the process does hang here! +echo "processing must continue soon" +source $srcdir/diag.sh shutdown-when-empty # shut down rsyslogd when done processing messages +source $srcdir/diag.sh wait-shutdown # and wait for it to terminate +source $srcdir/diag.sh seq-check 0 0 +source $srcdir/diag.sh exit diff --git a/tests/testsuites/asynwr_deadlock.conf b/tests/testsuites/asynwr_deadlock.conf new file mode 100644 index 00000000..b3a052df --- /dev/null +++ b/tests/testsuites/asynwr_deadlock.conf @@ -0,0 +1,21 @@ +# simple async writing test +# rgerhards, 2010-03-09 +$IncludeConfig diag-common.conf + +$ModLoad ../plugins/imtcp/.libs/imtcp +$MainMsgQueueTimeoutShutdown 10000 +$InputTCPServerRun 13514 + +$template outfmt,"%msg:F,58:2%\n" +$template dynfile,"rsyslog.out.log" # trick to use relative path names! + +$OMFileFlushOnTXEnd on +$OMFileFlushInterval 10 +$OMFileFlushIOBufferSize 10k +#:msg, contains, "msgnum:" ?dynfile;outfmt +:msg, contains, "msgnum:" ./rsyslog.out.log;outfmt + +$OMFileFlushOnTXEnd on +$OMFileFlushInterval 10 +$OMFileFlushIOBufferSize 10k +#:msg, contains, "msgnum:" ./rsyslog.out.2.log;outfmt -- cgit From 5c7225b77636b5f8231ccb0edc61fb7d68eb752b Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Wed, 17 Mar 2010 18:11:03 +0100 Subject: added test for deadlock with dynafile writing and cache exhaustion Note that this introduces a test case that breaks the current code. This commit does NOT yet provide the necessary code patch. Thus "make check" does currently hang. --- tests/Makefile.am | 3 ++ tests/asynwr_deadlock2.sh | 64 ++++++++++++++++++++++++++++++++++ tests/testsuites/asynwr_deadlock2.conf | 15 ++++++++ 3 files changed, 82 insertions(+) create mode 100755 tests/asynwr_deadlock2.sh create mode 100644 tests/testsuites/asynwr_deadlock2.conf diff --git a/tests/Makefile.am b/tests/Makefile.am index 3c2223d9..6f345b51 100644 --- a/tests/Makefile.am +++ b/tests/Makefile.am @@ -15,6 +15,7 @@ TESTS = $(TESTRUNS) cfg.sh \ asynwr_tinybuf.sh \ asynwr_large.sh \ asynwr_deadlock.sh \ + asynwr_deadlock2.sh \ gzipwr_large.sh \ gzipwr_large_dynfile.sh \ complex1.sh \ @@ -157,6 +158,8 @@ EXTRA_DIST= 1.rstest 2.rstest 3.rstest err1.rstest \ testsuites/asynwr_large.conf \ asynwr_deadlock.sh \ testsuites/asynwr_deadlock.conf \ + asynwr_deadlock2.sh \ + testsuites/asynwr_deadlock2.conf \ gzipwr_large.sh \ testsuites/gzipwr_large.conf \ gzipwr_large_dynfile.sh \ diff --git a/tests/asynwr_deadlock2.sh b/tests/asynwr_deadlock2.sh new file mode 100755 index 00000000..3b429b9a --- /dev/null +++ b/tests/asynwr_deadlock2.sh @@ -0,0 +1,64 @@ +# This is test case from practice, with the version we introduced it, it +# caused a deadlock during processing (when the a stream was purged from the +# dynafile cache). +# We added this as a standard test in the hopes that iw will help +# detect such things in the future. +# +# The problem that originally caused this test to fail was: +# We write to files asynchronously (with the async writer thread). There is +# no signaling done when the file stream is closed. That can lead to the writer +# process hanging in memory, that in turn leads to the main thread waiting on a +# condition that never occurs (because it would need to be signalled by the +# async writer). Even worse, in that case, the async writer was signalled invalid +# in such a way that when it received a wakeup, it thought it shall not terminate, +# but received a spurios wakeup due to timeout and no data to write. In that case +# it (correctly) concluded that it would not need to timeout until a new buffer write +# was done (in which case it would receive a wakeup). As such, it went into an eternal +# wait. However, the invalid signaling did not take into account that it did not +# signal the async writer to shut down. So the main thread went into a condition +# wait - and thus we had a deadlock. That situation occured only under very specific +# cirumstances. As far as the analysis goes, the following need to happen: +# 1. buffers on that file are being flushed +# 2. no new data arrives +# 3. the inactivity timeout has not yet happend +# 4. *then* (and only then) the stream is closed or destructed +# In that, 1 to 3 are prequisites for the deadlock which will happen in 4. In order +# to create this case reliably, I have used the "$OMFileFlushOnTXEnd on" directive +# inside my test case. It makes sure that #1 above happens. The test uses a dynafile +# cache size of 4, and the load generator generates data for 5 different dynafiles. +# So over time, we will hit a spot where 4 dynafiles are open and the 5th file name +# is generated. As such, one file needs to be discarded. Thanks to FlushOnTXEnd, we +# now likely have #2 in place and thanks to the load pattern generated, we most +# probably have #3 in place. During the dynafile cache displacement of the oldest +# entry, #4 is generated. At this point, we have the deadlock we are testing for. +# Note that this deadlock does not necessarily lead to a total lockup of rsyslogd. +# Parts of it continue to operate. But in our test setup, this means data is +# received and placed into the main queue. Once it's high water mark is hit, data +# is still being enqueued, but at a slow rate. So if one is patient enough, the load +# generator will be able to finish. However, rsyslogd will never process the data +# it received because it is locked in the deadlock caused by #4 above. +# Note that "$OMFileFlushOnTXEnd on" is not causing this behaviour. We just use it +# to (quite) reliably cause the failure condition. The failure described above +# (in version 4.6.1) was also present when the setting was set to "off", but its +# occurence was very much less probable - because the perquisites are then much +# harder to hit. without it, the test may need to run for several hours before +# we hit all failure conditions. +# +# added 2010-03-17 by Rgerhards +# This file is part of the rsyslog project, released under GPLv3 +echo ================================================================================= +echo TEST: \[asynwr_deadlock2.sh\]: a case known to have caused a deadlock in the past +source $srcdir/diag.sh init +# uncomment for debugging support: +export RSYSLOG_DEBUG="debug nostdout noprintmutexaction" +export RSYSLOG_DEBUGLOG="log" +source $srcdir/diag.sh startup asynwr_deadlock2.conf +# send 20000 messages, each close to 2K (non-randomized!), so that we can fill +# the buffers and hopefully run into the "deadlock". +source $srcdir/diag.sh tcpflood -m20000 -d1800 -P129 -i1 -f5 +# sleep is important! need to make sure the instance is inactive +source $srcdir/diag.sh shutdown-when-empty # shut down rsyslogd when done processing messages +source $srcdir/diag.sh wait-shutdown # and wait for it to terminate +zcat rsyslog.out.*.log > rsyslog.out.log +source $srcdir/diag.sh seq-check 1 20000 -E +source $srcdir/diag.sh exit diff --git a/tests/testsuites/asynwr_deadlock2.conf b/tests/testsuites/asynwr_deadlock2.conf new file mode 100644 index 00000000..c3eecae3 --- /dev/null +++ b/tests/testsuites/asynwr_deadlock2.conf @@ -0,0 +1,15 @@ +# rgerhards, 2010-03-17 +$IncludeConfig diag-common.conf + +$ModLoad ../plugins/imtcp/.libs/imtcp +$MainMsgQueueTimeoutShutdown 10000 +$InputTCPServerRun 13514 + +$template outfmt,"%msg:F,58:3%,%msg:F,58:4%,%msg:F,58:5%\n" +$template dynfile,"rsyslog.out.%msg:F,58:2%.log" # use multiple dynafiles + +$OMFileFlushOnTXEnd on +$OMFileFlushInterval 10 +$OMFileIOBufferSize 10k +$DynaFileCacheSize 4 +local0.* ?dynfile;outfmt -- cgit From 1fb45d3e993e44e1595fc54f1ad3b786c66fbb4c Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Thu, 18 Mar 2010 12:34:26 +0100 Subject: some cleanup, some additional comments and a bit more debug output --- runtime/stream.c | 13 +++++++++++-- tests/asynwr_deadlock.sh | 4 ++-- tests/asynwr_deadlock2.sh | 16 ++++++++++------ tests/testsuites/asynwr_deadlock.conf | 8 -------- tests/testsuites/gzipwr_large_dynfile.conf | 2 +- 5 files changed, 24 insertions(+), 19 deletions(-) diff --git a/runtime/stream.c b/runtime/stream.c index 87daedaf..9a0a8615 100644 --- a/runtime/stream.c +++ b/runtime/stream.c @@ -316,7 +316,8 @@ static rsRetVal strmCloseFile(strm_t *pThis) DEFiRet; ASSERT(pThis != NULL); - DBGOPRINT((obj_t*) pThis, "file %d closing\n", pThis->fd); + DBGOPRINT((obj_t*) pThis, "file %d(%s) closing\n", pThis->fd, + (pThis->pszFName == NULL) ? "N/A" : (char*)pThis->pszFName); if(pThis->tOperationsMode != STREAMMODE_READ) { strmFlush(pThis); @@ -929,6 +930,7 @@ asyncWriterThread(void *pPtr) while(1) { /* loop broken inside */ d_pthread_mutex_lock(&pThis->mut); +dbgprintf("XXX: asyncWriterThread iterating %s\n", pThis->pszFName); while(pThis->iCnt == 0) { if(pThis->bStopWriter) { pthread_cond_broadcast(&pThis->isEmpty); @@ -944,6 +946,7 @@ asyncWriterThread(void *pPtr) bTimedOut = 0; timeoutComp(&t, pThis->iFlushInterval * 2000); /* *1000 millisconds */ if(pThis->bDoTimedWait) { +dbgprintf("asyncWriter thread going to timeout sleep\n"); if(pthread_cond_timedwait(&pThis->notEmpty, &pThis->mut, &t) != 0) { int err = errno; if(err == ETIMEDOUT) { @@ -957,13 +960,16 @@ asyncWriterThread(void *pPtr) } } } else { +dbgprintf("asyncWriter thread going to eternal sleep\n"); d_pthread_cond_wait(&pThis->notEmpty, &pThis->mut); } +dbgprintf("asyncWriter woke up\n"); } bTimedOut = 0; /* we may have timed out, but there *is* work to do... */ iDeq = pThis->iDeq++ % STREAM_ASYNC_NUMBUFS; +dbgprintf("asyncWriter writes data\n"); doWriteInternal(pThis, pThis->asyncBuf[iDeq].pBuf, pThis->asyncBuf[iDeq].lenBuf); // TODO: error check????? 2009-07-06 @@ -1135,7 +1141,10 @@ strmFlush(strm_t *pThis) DEFiRet; ASSERT(pThis != NULL); - DBGOPRINT((obj_t*) pThis, "file %d flush, buflen %ld\n", pThis->fd, (long) pThis->iBufPtr); + DBGOPRINT((obj_t*) pThis, "file %d(%s) flush, buflen %ld\n", pThis->fd, pThis->pszFName, (long) pThis->iBufPtr); + DBGOPRINT((obj_t*) pThis, "file %d(%s) flush, buflen %ld%s\n", pThis->fd, + (pThis->pszFName == NULL) ? "N/A" : (char*)pThis->pszFName, + (long) pThis->iBufPtr, (pThis->iBufPtr == 0) ? " (no need to flush)" : ""); if(pThis->tOperationsMode != STREAMMODE_READ && pThis->iBufPtr > 0) { iRet = strmSchedWrite(pThis, pThis->pIOBuf, pThis->iBufPtr); diff --git a/tests/asynwr_deadlock.sh b/tests/asynwr_deadlock.sh index 2d08419c..dc08355e 100755 --- a/tests/asynwr_deadlock.sh +++ b/tests/asynwr_deadlock.sh @@ -8,8 +8,8 @@ echo =========================================================================== echo TEST: \[asynwr_deadlock.sh\]: a case known to have caused a deadlock in the past source $srcdir/diag.sh init # uncomment for debugging support: -export RSYSLOG_DEBUG="debug nostdout noprintmutexaction" -export RSYSLOG_DEBUGLOG="log" +#export RSYSLOG_DEBUG="debug nostdout noprintmutexaction" +#export RSYSLOG_DEBUGLOG="log" source $srcdir/diag.sh startup asynwr_deadlock.conf # just send one message source $srcdir/diag.sh tcpflood -m1 diff --git a/tests/asynwr_deadlock2.sh b/tests/asynwr_deadlock2.sh index 3b429b9a..34d37d48 100755 --- a/tests/asynwr_deadlock2.sh +++ b/tests/asynwr_deadlock2.sh @@ -20,10 +20,14 @@ # cirumstances. As far as the analysis goes, the following need to happen: # 1. buffers on that file are being flushed # 2. no new data arrives -# 3. the inactivity timeout has not yet happend +# 3. the inactivity timeout has not yet expired # 4. *then* (and only then) the stream is closed or destructed -# In that, 1 to 3 are prequisites for the deadlock which will happen in 4. In order -# to create this case reliably, I have used the "$OMFileFlushOnTXEnd on" directive +# In that, 1 to 4 are prequisites for the deadlock which will happen in 4. However, +# for it to happen, we also need the right "timing". There is a race between the +# main thread and the async writer thread. The deadlock will only happen under +# the "right" circumstances, which basically means it will not happen always. +# In order to create this case as reliable as possible, I have used +# the "$OMFileFlushOnTXEnd on" directive # inside my test case. It makes sure that #1 above happens. The test uses a dynafile # cache size of 4, and the load generator generates data for 5 different dynafiles. # So over time, we will hit a spot where 4 dynafiles are open and the 5th file name @@ -50,8 +54,8 @@ echo =========================================================================== echo TEST: \[asynwr_deadlock2.sh\]: a case known to have caused a deadlock in the past source $srcdir/diag.sh init # uncomment for debugging support: -export RSYSLOG_DEBUG="debug nostdout noprintmutexaction" -export RSYSLOG_DEBUGLOG="log" +#export RSYSLOG_DEBUG="debug nostdout noprintmutexaction" +#export RSYSLOG_DEBUGLOG="log" source $srcdir/diag.sh startup asynwr_deadlock2.conf # send 20000 messages, each close to 2K (non-randomized!), so that we can fill # the buffers and hopefully run into the "deadlock". @@ -59,6 +63,6 @@ source $srcdir/diag.sh tcpflood -m20000 -d1800 -P129 -i1 -f5 # sleep is important! need to make sure the instance is inactive source $srcdir/diag.sh shutdown-when-empty # shut down rsyslogd when done processing messages source $srcdir/diag.sh wait-shutdown # and wait for it to terminate -zcat rsyslog.out.*.log > rsyslog.out.log +cat rsyslog.out.*.log > rsyslog.out.log source $srcdir/diag.sh seq-check 1 20000 -E source $srcdir/diag.sh exit diff --git a/tests/testsuites/asynwr_deadlock.conf b/tests/testsuites/asynwr_deadlock.conf index b3a052df..d703791a 100644 --- a/tests/testsuites/asynwr_deadlock.conf +++ b/tests/testsuites/asynwr_deadlock.conf @@ -1,4 +1,3 @@ -# simple async writing test # rgerhards, 2010-03-09 $IncludeConfig diag-common.conf @@ -7,15 +6,8 @@ $MainMsgQueueTimeoutShutdown 10000 $InputTCPServerRun 13514 $template outfmt,"%msg:F,58:2%\n" -$template dynfile,"rsyslog.out.log" # trick to use relative path names! $OMFileFlushOnTXEnd on $OMFileFlushInterval 10 $OMFileFlushIOBufferSize 10k -#:msg, contains, "msgnum:" ?dynfile;outfmt :msg, contains, "msgnum:" ./rsyslog.out.log;outfmt - -$OMFileFlushOnTXEnd on -$OMFileFlushInterval 10 -$OMFileFlushIOBufferSize 10k -#:msg, contains, "msgnum:" ./rsyslog.out.2.log;outfmt diff --git a/tests/testsuites/gzipwr_large_dynfile.conf b/tests/testsuites/gzipwr_large_dynfile.conf index 31bcb978..3a1b255a 100644 --- a/tests/testsuites/gzipwr_large_dynfile.conf +++ b/tests/testsuites/gzipwr_large_dynfile.conf @@ -8,7 +8,7 @@ $MainMsgQueueTimeoutShutdown 10000 $InputTCPServerRun 13514 $template outfmt,"%msg:F,58:3%,%msg:F,58:4%,%msg:F,58:5%\n" -$template dynfile,"rsyslog.out.%msg:F,58:2%.log" # trick to use relative path names! +$template dynfile,"rsyslog.out.%msg:F,58:2%.log" # use multiple dynafiles $OMFileFlushOnTXEnd off $OMFileZipLevel 6 $OMFileIOBufferSize 256k -- cgit From adf3e203bd180c43e68bb0d87656e7ef470e269d Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Thu, 18 Mar 2010 12:39:19 +0100 Subject: enabled imudp to send complete text of large messages to debug log ... it turns out that this is sometimes extremely useful when debugging real-world problems at user sites. --- plugins/imudp/imudp.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/plugins/imudp/imudp.c b/plugins/imudp/imudp.c index 0970259d..f8555f00 100644 --- a/plugins/imudp/imudp.c +++ b/plugins/imudp/imudp.c @@ -241,7 +241,7 @@ processSocket(int fd, struct sockaddr_storage *frominetPrev, int *pbIsPermitted, } } - DBGPRINTF("recv(%d,%d)/%s,acl:%d,msg:%.80s\n", fd, (int) lenRcvBuf, fromHost, *pbIsPermitted, pRcvBuf); + DBGPRINTF("recv(%d,%d)/%s,acl:%d,msg:%s\n", fd, (int) lenRcvBuf, fromHost, *pbIsPermitted, pRcvBuf); if(*pbIsPermitted) { if((iTimeRequery == 0) || (iNbrTimeUsed++ % iTimeRequery) == 0) { -- cgit From e910078e41e2960f9afc55013cbd287532be478e Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Fri, 19 Mar 2010 07:19:28 +0100 Subject: bugfix: improper synchronization when "$OMFileFlushOnTXEnd on" was used Internal data structures were not properly protected due to missing mutex calls. --- ChangeLog | 3 +++ runtime/stream.c | 46 +++++++++++++++++++++++++++++++++++----------- 2 files changed, 38 insertions(+), 11 deletions(-) diff --git a/ChangeLog b/ChangeLog index 1f74b252..b00965c4 100644 --- a/ChangeLog +++ b/ChangeLog @@ -6,6 +6,9 @@ Version 4.6.2 [v4-stable] (rgerhards), 2010-03-?? to ease migration from syslog-ng. See property replacer doc for details. [backport from 5.5.3 because urgently needed by some] - improved testbench +- bugfix: improper synchronization when "$OMFileFlushOnTXEnd on" was used + Internal data structures were not properly protected due to missing + mutex calls. - bugfix: potential data loss during file stream shutdown - bugfix: potential problems during file stream shutdown The shutdown/close sequence was not clean, what potentially (but diff --git a/runtime/stream.c b/runtime/stream.c index 9a0a8615..93f7fd58 100644 --- a/runtime/stream.c +++ b/runtime/stream.c @@ -67,7 +67,7 @@ DEFobjStaticHelpers DEFobjCurrIf(zlibw) /* forward definitions */ -static rsRetVal strmFlush(strm_t *pThis); +static rsRetVal strmFlushInternal(strm_t *pThis); static rsRetVal strmWrite(strm_t *pThis, uchar *pBuf, size_t lenBuf); static rsRetVal strmCloseFile(strm_t *pThis); static void *asyncWriterThread(void *pPtr); @@ -309,7 +309,7 @@ strmWaitAsyncWriterDone(strm_t *pThis) * Note: it is valid to call this function when the physical file is closed. If so, * strmCloseFile() will still check if there is any unwritten data inside buffers * (this may be the case) and, if so, will open the file, write the data, and then - * close it again (this is done via strmFlush and friends). + * close it again (this is done via strmFlushInternal and friends). */ static rsRetVal strmCloseFile(strm_t *pThis) { @@ -320,7 +320,7 @@ static rsRetVal strmCloseFile(strm_t *pThis) (pThis->pszFName == NULL) ? "N/A" : (char*)pThis->pszFName); if(pThis->tOperationsMode != STREAMMODE_READ) { - strmFlush(pThis); + strmFlushInternal(pThis); if(pThis->bAsyncWrite) { strmWaitAsyncWriterDone(pThis); } @@ -939,7 +939,7 @@ dbgprintf("XXX: asyncWriterThread iterating %s\n", pThis->pszFName); } if(bTimedOut && pThis->iBufPtr > 0) { /* if we timed out, we need to flush pending data */ - strmFlush(pThis); + strmFlushInternal(pThis); bTimedOut = 0; continue; /* now we should have data */ } @@ -1136,12 +1136,11 @@ finalize_it: * rgerhards, 2008-01-10 */ static rsRetVal -strmFlush(strm_t *pThis) +strmFlushInternal(strm_t *pThis) { DEFiRet; ASSERT(pThis != NULL); - DBGOPRINT((obj_t*) pThis, "file %d(%s) flush, buflen %ld\n", pThis->fd, pThis->pszFName, (long) pThis->iBufPtr); DBGOPRINT((obj_t*) pThis, "file %d(%s) flush, buflen %ld%s\n", pThis->fd, (pThis->pszFName == NULL) ? "N/A" : (char*)pThis->pszFName, (long) pThis->iBufPtr, (pThis->iBufPtr == 0) ? " (no need to flush)" : ""); @@ -1154,6 +1153,31 @@ strmFlush(strm_t *pThis) } +/* flush stream output buffer to persistent storage. This can be called at any time + * and is automatically called when the output buffer is full. This function is for + * use by EXTERNAL callers. Do NOT use it internally. It locks the async writer + * mutex if ther is need to do so. + * rgerhards, 2010-03-18 + */ +static rsRetVal +strmFlush(strm_t *pThis) +{ + DEFiRet; + + ASSERT(pThis != NULL); + + if(pThis->bAsyncWrite) + d_pthread_mutex_lock(&pThis->mut); + CHKiRet(strmFlushInternal(pThis)); + +finalize_it: + if(pThis->bAsyncWrite) + d_pthread_mutex_unlock(&pThis->mut); + + RETiRet; +} + + /* seek a stream to a specific location. Pending writes are flushed, read data * is invalidated. * rgerhards, 2008-01-12 @@ -1167,7 +1191,7 @@ static rsRetVal strmSeek(strm_t *pThis, off_t offs) if(pThis->fd == -1) strmOpenFile(pThis); else - strmFlush(pThis); + strmFlushInternal(pThis); int i; DBGOPRINT((obj_t*) pThis, "file %d seek, pos %ld\n", pThis->fd, (long) offs); i = lseek(pThis->fd, offs, SEEK_SET); // TODO: check error! @@ -1208,7 +1232,7 @@ static rsRetVal strmWriteChar(strm_t *pThis, uchar c) /* if the buffer is full, we need to flush before we can write */ if(pThis->iBufPtr == pThis->sIOBufSize) { - CHKiRet(strmFlush(pThis)); + CHKiRet(strmFlushInternal(pThis)); } /* we now always have space for one character, so we simply copy it */ *(pThis->pIOBuf + pThis->iBufPtr) = c; @@ -1278,7 +1302,7 @@ strmWrite(strm_t *pThis, uchar *pBuf, size_t lenBuf) iOffset = 0; do { if(pThis->iBufPtr == pThis->sIOBufSize) { - CHKiRet(strmFlush(pThis)); /* get a new buffer for rest of data */ + CHKiRet(strmFlushInternal(pThis)); /* get a new buffer for rest of data */ } iWrite = pThis->sIOBufSize - pThis->iBufPtr; /* this fits in current buf */ if(iWrite > lenBuf) @@ -1293,7 +1317,7 @@ strmWrite(strm_t *pThis, uchar *pBuf, size_t lenBuf) * write it. This seems more natural than waiting (hours?) for the next message... */ if(pThis->iBufPtr == pThis->sIOBufSize) { - CHKiRet(strmFlush(pThis)); /* get a new buffer for rest of data */ + CHKiRet(strmFlushInternal(pThis)); /* get a new buffer for rest of data */ } finalize_it: @@ -1452,7 +1476,7 @@ static rsRetVal strmSerialize(strm_t *pThis, strm_t *pStrm) ISOBJ_TYPE_assert(pThis, strm); ISOBJ_TYPE_assert(pStrm, strm); - strmFlush(pThis); + strmFlushInternal(pThis); CHKiRet(obj.BeginSerialize(pStrm, (obj_t*) pThis)); objSerializeSCALAR(pStrm, iCurrFNum, INT); -- cgit From 44f670848a87fc59bffc0b8f433a2e2c798dc176 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Fri, 19 Mar 2010 07:22:59 +0100 Subject: added additional test case for async writer --- tests/Makefile.am | 3 +++ tests/asynwr_deadlock4.sh | 25 +++++++++++++++++++++++++ tests/testsuites/asynwr_deadlock4.conf | 15 +++++++++++++++ 3 files changed, 43 insertions(+) create mode 100755 tests/asynwr_deadlock4.sh create mode 100644 tests/testsuites/asynwr_deadlock4.conf diff --git a/tests/Makefile.am b/tests/Makefile.am index 6f345b51..47a68bd1 100644 --- a/tests/Makefile.am +++ b/tests/Makefile.am @@ -16,6 +16,7 @@ TESTS = $(TESTRUNS) cfg.sh \ asynwr_large.sh \ asynwr_deadlock.sh \ asynwr_deadlock2.sh \ + asynwr_deadlock4.sh \ gzipwr_large.sh \ gzipwr_large_dynfile.sh \ complex1.sh \ @@ -160,6 +161,8 @@ EXTRA_DIST= 1.rstest 2.rstest 3.rstest err1.rstest \ testsuites/asynwr_deadlock.conf \ asynwr_deadlock2.sh \ testsuites/asynwr_deadlock2.conf \ + asynwr_deadlock4.sh \ + testsuites/asynwr_deadlock4.conf \ gzipwr_large.sh \ testsuites/gzipwr_large.conf \ gzipwr_large_dynfile.sh \ diff --git a/tests/asynwr_deadlock4.sh b/tests/asynwr_deadlock4.sh new file mode 100755 index 00000000..cf1beddb --- /dev/null +++ b/tests/asynwr_deadlock4.sh @@ -0,0 +1,25 @@ +# This is test case from practice, with the version we introduced it, it +# caused a deadlock during processing. +# We added this as a standard test in the hopes that iw will help +# detect such things in the future. +# +# This is a test that is constructed similar to asynwr_deadlock2.sh, but +# can produce problems in a simpler way. +# +# added 2010-03-18 by Rgerhards +# This file is part of the rsyslog project, released under GPLv3 +echo ================================================================================= +echo TEST: \[asynwr_deadlock4.sh\]: a case known to have caused a deadlock in the past +source $srcdir/diag.sh init +# uncomment for debugging support: +export RSYSLOG_DEBUG="debug nostdout noprintmutexaction" +export RSYSLOG_DEBUGLOG="log" +source $srcdir/diag.sh startup asynwr_deadlock4.conf +# send 20000 messages, each close to 2K (non-randomized!), so that we can fill +# the buffers and hopefully run into the "deadlock". +source $srcdir/diag.sh tcpflood -m20000 -d18 -P129 -i1 -f5 +# sleep is important! need to make sure the instance is inactive +source $srcdir/diag.sh shutdown-when-empty # shut down rsyslogd when done processing messages +source $srcdir/diag.sh wait-shutdown # and wait for it to terminate +source $srcdir/diag.sh seq-check 1 20000 -E +source $srcdir/diag.sh exit diff --git a/tests/testsuites/asynwr_deadlock4.conf b/tests/testsuites/asynwr_deadlock4.conf new file mode 100644 index 00000000..23ce3cfc --- /dev/null +++ b/tests/testsuites/asynwr_deadlock4.conf @@ -0,0 +1,15 @@ +# rgerhards, 2010-03-17 +$IncludeConfig diag-common.conf + +$ModLoad ../plugins/imtcp/.libs/imtcp +$MainMsgQueueTimeoutShutdown 10000 +$InputTCPServerRun 13514 + +$template outfmt,"%msg:F,58:3%,%msg:F,58:4%,%msg:F,58:5%\n" +$template dynfile,"rsyslog.out.log" # use multiple dynafiles + +$OMFileFlushOnTXEnd on +$OMFileFlushInterval 10 +$OMFileIOBufferSize 10k +$DynaFileCacheSize 4 +local0.* ?dynfile;outfmt -- cgit From 3e0578605f7df8427aa5b70c2b4396504113fafc Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Fri, 19 Mar 2010 07:37:56 +0100 Subject: bugfix: potential hang condition during filestream close predicate was not properly checked when waiting for the background file writer --- ChangeLog | 3 +++ runtime/stream.c | 10 ++++++---- 2 files changed, 9 insertions(+), 4 deletions(-) diff --git a/ChangeLog b/ChangeLog index b00965c4..672c69ae 100644 --- a/ChangeLog +++ b/ChangeLog @@ -6,6 +6,9 @@ Version 4.6.2 [v4-stable] (rgerhards), 2010-03-?? to ease migration from syslog-ng. See property replacer doc for details. [backport from 5.5.3 because urgently needed by some] - improved testbench +- bugfix: potential hang condition during filestream close + predicate was not properly checked when waiting for the background file + writer - bugfix: improper synchronization when "$OMFileFlushOnTXEnd on" was used Internal data structures were not properly protected due to missing mutex calls. diff --git a/runtime/stream.c b/runtime/stream.c index 93f7fd58..88606db7 100644 --- a/runtime/stream.c +++ b/runtime/stream.c @@ -163,7 +163,7 @@ doSizeLimitProcessing(strm_t *pThis) ASSERT(pThis->fd != -1); if(pThis->iCurrOffs >= pThis->iSizeLimit) { - /* strmClosefile() destroys the current file name, so we + /* strmCloseFile() destroys the current file name, so we * need to preserve it. */ CHKmalloc(pszCurrFName = ustrdup(pThis->pszCurrFName)); @@ -296,8 +296,10 @@ strmWaitAsyncWriterDone(strm_t *pThis) BEGINfunc if(pThis->bAsyncWrite) { /* awake writer thread and make it write out everything */ - pthread_cond_signal(&pThis->notEmpty); - d_pthread_cond_wait(&pThis->isEmpty, &pThis->mut); + while(pThis->iCnt > 0) { + pthread_cond_signal(&pThis->notEmpty); + d_pthread_cond_wait(&pThis->isEmpty, &pThis->mut); + } } ENDfunc } @@ -944,7 +946,7 @@ dbgprintf("XXX: asyncWriterThread iterating %s\n", pThis->pszFName); continue; /* now we should have data */ } bTimedOut = 0; - timeoutComp(&t, pThis->iFlushInterval * 2000); /* *1000 millisconds */ + timeoutComp(&t, pThis->iFlushInterval * 2000); /* *1000 millisconds */ // TODO: check the 2000?!? if(pThis->bDoTimedWait) { dbgprintf("asyncWriter thread going to timeout sleep\n"); if(pthread_cond_timedwait(&pThis->notEmpty, &pThis->mut, &t) != 0) { -- cgit From 9cdcba0bdc8b8d2df8d06784f3c4f0066c90fd40 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Fri, 19 Mar 2010 07:41:04 +0100 Subject: bugfix: invalid buffer write in (file) stream class currently being accessed buffer could be overwritten with new data. While this probably did not cause access violations, it could case loss and/or duplication of some data (definitely a race with no deterministic outcome) --- ChangeLog | 5 +++++ runtime/stream.c | 3 ++- 2 files changed, 7 insertions(+), 1 deletion(-) diff --git a/ChangeLog b/ChangeLog index 672c69ae..85a9ecb6 100644 --- a/ChangeLog +++ b/ChangeLog @@ -6,6 +6,11 @@ Version 4.6.2 [v4-stable] (rgerhards), 2010-03-?? to ease migration from syslog-ng. See property replacer doc for details. [backport from 5.5.3 because urgently needed by some] - improved testbench +- bugfix: invalid buffer write in (file) stream class + currently being accessed buffer could be overwritten with new data. + While this probably did not cause access violations, it could case loss + and/or duplication of some data (definitely a race with no deterministic + outcome) - bugfix: potential hang condition during filestream close predicate was not properly checked when waiting for the background file writer diff --git a/runtime/stream.c b/runtime/stream.c index 88606db7..e2f6623e 100644 --- a/runtime/stream.c +++ b/runtime/stream.c @@ -863,7 +863,8 @@ doAsyncWriteInternal(strm_t *pThis, size_t lenBuf) DEFiRet; ISOBJ_TYPE_assert(pThis, strm); - while(pThis->iCnt >= STREAM_ASYNC_NUMBUFS) + /* the -1 below is important, because we need one buffer for the main thread! */ + while(pThis->iCnt >= STREAM_ASYNC_NUMBUFS - 1) d_pthread_cond_wait(&pThis->notFull, &pThis->mut); pThis->asyncBuf[pThis->iEnq % STREAM_ASYNC_NUMBUFS].lenBuf = lenBuf; -- cgit From 89216d6a96ea5f6d1fa9893d56fa877a2131d390 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Fri, 19 Mar 2010 09:42:46 +0100 Subject: fixed regression from previos (yet unrelease) $omfileFlushOnTXEnd fix The previous fix fixed an issue with on/off bying used in the exact wrong semantic. It corrected the situation, but failed to fix one spot where the wrong semantics were used. This is done with this commit. Note that this is NOT a bug seen in any released version. --- runtime/stream.c | 3 +++ tests/asynwr_deadlock4.sh | 4 ++-- tools/omfile.c | 2 +- 3 files changed, 6 insertions(+), 3 deletions(-) diff --git a/runtime/stream.c b/runtime/stream.c index e2f6623e..bfeecee5 100644 --- a/runtime/stream.c +++ b/runtime/stream.c @@ -641,6 +641,9 @@ static rsRetVal strmConstructFinalize(strm_t *pThis) } } + DBGPRINTF("file stream %s params: flush interval %d, async write %d\n", + (pThis->pszFName == NULL) ? "N/A" : (char*)pThis->pszFName, + pThis->iFlushInterval, pThis->bAsyncWrite); /* if we have a flush interval, we need to do async writes in any case */ if(pThis->iFlushInterval != 0) { pThis->bAsyncWrite = 1; diff --git a/tests/asynwr_deadlock4.sh b/tests/asynwr_deadlock4.sh index cf1beddb..a3452f5b 100755 --- a/tests/asynwr_deadlock4.sh +++ b/tests/asynwr_deadlock4.sh @@ -12,8 +12,8 @@ echo =========================================================================== echo TEST: \[asynwr_deadlock4.sh\]: a case known to have caused a deadlock in the past source $srcdir/diag.sh init # uncomment for debugging support: -export RSYSLOG_DEBUG="debug nostdout noprintmutexaction" -export RSYSLOG_DEBUGLOG="log" +#export RSYSLOG_DEBUG="debug nostdout noprintmutexaction" +#export RSYSLOG_DEBUGLOG="log" source $srcdir/diag.sh startup asynwr_deadlock4.conf # send 20000 messages, each close to 2K (non-randomized!), so that we can fill # the buffers and hopefully run into the "deadlock". diff --git a/tools/omfile.c b/tools/omfile.c index 438f8c4a..c4e834cc 100644 --- a/tools/omfile.c +++ b/tools/omfile.c @@ -413,7 +413,7 @@ prepareFile(instanceData *pData, uchar *newFileName) * async processing, which is a real performance waste if we do not do buffered * writes! -- rgerhards, 2009-07-06 */ - if(pData->bFlushOnTXEnd) + if(!pData->bFlushOnTXEnd) CHKiRet(strm.SetiFlushInterval(pData->pStrm, pData->iFlushInterval)); if(pData->pszSizeLimitCmd != NULL) CHKiRet(strm.SetpszSizeLimitCmd(pData->pStrm, ustrdup(pData->pszSizeLimitCmd))); -- cgit From 970383f2199e177453bc13a40c3ccf04aeb647e1 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Fri, 19 Mar 2010 12:20:58 +0100 Subject: slight improvement to testing tools --- tests/longrun.sh | 12 ++++++++++-- tests/manytcp.sh | 1 + tests/tcpflood.c | 25 ++++++++++++++++++------- 3 files changed, 29 insertions(+), 9 deletions(-) diff --git a/tests/longrun.sh b/tests/longrun.sh index 09bddc58..407e9fa9 100755 --- a/tests/longrun.sh +++ b/tests/longrun.sh @@ -2,10 +2,18 @@ # It is not yet used in the automated testbench, but I keep this file so that # I can use it whenever there is need to. As such, it currently does not have # parameters but is expected to be edited as needed. -- rgerhards, 2010-03-10 +# +# use: ./longrun.sh testname.sh +# +# where testname.sh is the test to be run +# to change other params, you need to edit the settings here below: MAXRUNS=10 DISPLAYALIVE=100 LOGFILE=runlog +echo "logfile is $LOGFILE" +echo "executing test $1" + date > $LOGFILE for (( i=0; $i < 10000; i++ )) @@ -13,9 +21,9 @@ for (( i=0; $i < 10000; i++ )) if [ $(( i % DISPLAYALIVE )) -eq 0 ]; then echo "$i iterations done" fi - ./gzipwr_large_dynfile.sh >> $LOGFILE + $1 >> $LOGFILE if [ "$?" -ne "0" ]; then - echo "Test failed in iteration $i!" + echo "Test failed in iteration $i, review $LOGFILE for details!" exit 1 fi done diff --git a/tests/manytcp.sh b/tests/manytcp.sh index dbf1d961..01f3e43b 100755 --- a/tests/manytcp.sh +++ b/tests/manytcp.sh @@ -4,5 +4,6 @@ source $srcdir/diag.sh startup manytcp.conf # the config file specifies exactly 1100 connections source $srcdir/diag.sh tcpflood -c1000 -m40000 source $srcdir/diag.sh shutdown-when-empty # shut down rsyslogd when done processing messages +source $srcdir/diag.sh wait-shutdown # we need to wait until rsyslogd is finished! source $srcdir/diag.sh seq-check 0 39999 source $srcdir/diag.sh exit diff --git a/tests/tcpflood.c b/tests/tcpflood.c index 0d819d1d..d4955447 100644 --- a/tests/tcpflood.c +++ b/tests/tcpflood.c @@ -71,6 +71,7 @@ static int numMsgsToSend; /* number of messages to send */ static int numConnections = 1; /* number of connections to create */ static int *sockArray; /* array of sockets to use */ static int msgNum = 0; /* initial message number to start with */ +static int bShowProgress = 1; /* show progress messages */ /* open a single tcp connection @@ -130,11 +131,13 @@ int openConnections(void) char msgBuf[128]; size_t lenMsg; - write(1, " open connections", sizeof(" open connections")-1); + if(bShowProgress) + write(1, " open connections", sizeof(" open connections")-1); sockArray = calloc(numConnections, sizeof(int)); for(i = 0 ; i < numConnections ; ++i) { if(i % 10 == 0) { - printf("\r%5.5d", i); + if(bShowProgress) + printf("\r%5.5d", i); //lenMsg = sprintf(msgBuf, "\r%5.5d", i); //write(1, msgBuf, lenMsg); } @@ -163,11 +166,14 @@ void closeConnections(void) char msgBuf[128]; size_t lenMsg; - write(1, " close connections", sizeof(" close connections")-1); + if(bShowProgress) + write(1, " close connections", sizeof(" close connections")-1); for(i = 0 ; i < numConnections ; ++i) { if(i % 10 == 0) { - lenMsg = sprintf(msgBuf, "\r%5.5d", i); - write(1, msgBuf, lenMsg); + if(bShowProgress) { + lenMsg = sprintf(msgBuf, "\r%5.5d", i); + write(1, msgBuf, lenMsg); + } } close(sockArray[i]); } @@ -197,7 +203,8 @@ int sendMessages(void) char extraData[MAX_EXTRADATA_LEN + 1]; printf("Sending %d messages.\n", numMsgsToSend); - printf("\r%8.8d messages sent", 0); + if(bShowProgress) + printf("\r%8.8d messages sent", 0); for(i = 0 ; i < numMsgsToSend ; ++i) { if(i < numConnections) socknum = i; @@ -231,7 +238,8 @@ int sendMessages(void) return(1); } if(i % 100 == 0) { - printf("\r%8.8d", i); + if(bShowProgress) + printf("\r%8.8d", i); } ++msgNum; } @@ -315,6 +323,9 @@ int main(int argc, char *argv[]) sigaction(SIGPIPE, &sigAct, NULL); setvbuf(stdout, buf, _IONBF, 48); + + if(!isatty(1)) + bShowProgress = 0; while((opt = getopt(argc, argv, "f:t:p:c:m:i:P:d:n:r")) != -1) { switch (opt) { -- cgit From ab8af1c38df75fc5757e83a04862bf548a1e98a3 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Fri, 19 Mar 2010 13:32:31 +0100 Subject: solved some race conditions in testbench the test cases actually have some races, not the code to be tested --- tests/asynwr_deadlock2.sh | 3 ++- tests/manytcp.sh | 2 ++ 2 files changed, 4 insertions(+), 1 deletion(-) diff --git a/tests/asynwr_deadlock2.sh b/tests/asynwr_deadlock2.sh index 34d37d48..1190f67a 100755 --- a/tests/asynwr_deadlock2.sh +++ b/tests/asynwr_deadlock2.sh @@ -60,7 +60,8 @@ source $srcdir/diag.sh startup asynwr_deadlock2.conf # send 20000 messages, each close to 2K (non-randomized!), so that we can fill # the buffers and hopefully run into the "deadlock". source $srcdir/diag.sh tcpflood -m20000 -d1800 -P129 -i1 -f5 -# sleep is important! need to make sure the instance is inactive +# the sleep below is needed to prevent too-early termination of the tcp listener +sleep 1 source $srcdir/diag.sh shutdown-when-empty # shut down rsyslogd when done processing messages source $srcdir/diag.sh wait-shutdown # and wait for it to terminate cat rsyslog.out.*.log > rsyslog.out.log diff --git a/tests/manytcp.sh b/tests/manytcp.sh index 01f3e43b..94a5c035 100755 --- a/tests/manytcp.sh +++ b/tests/manytcp.sh @@ -3,6 +3,8 @@ source $srcdir/diag.sh init source $srcdir/diag.sh startup manytcp.conf # the config file specifies exactly 1100 connections source $srcdir/diag.sh tcpflood -c1000 -m40000 +# the sleep below is needed to prevent too-early termination of the tcp listener +sleep 1 source $srcdir/diag.sh shutdown-when-empty # shut down rsyslogd when done processing messages source $srcdir/diag.sh wait-shutdown # we need to wait until rsyslogd is finished! source $srcdir/diag.sh seq-check 0 39999 -- cgit From 091e4dc1b92db7e516d30df659a46b969274d6bf Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Fri, 19 Mar 2010 15:14:09 +0100 Subject: added parser test cases to testbench --- tests/Makefile.am | 2 ++ tests/parsertest.sh | 4 ++++ tests/testsuites/parse-nodate.conf | 14 ++++++++++++++ tests/testsuites/samples.parse-nodate | 6 ++++++ 4 files changed, 26 insertions(+) create mode 100644 tests/testsuites/parse-nodate.conf create mode 100644 tests/testsuites/samples.parse-nodate diff --git a/tests/Makefile.am b/tests/Makefile.am index 47a68bd1..98b97d44 100644 --- a/tests/Makefile.am +++ b/tests/Makefile.am @@ -104,6 +104,8 @@ EXTRA_DIST= 1.rstest 2.rstest 3.rstest err1.rstest \ testsuites/rfc5424-4.parse1 \ testsuites/parse3.conf \ testsuites/reallife.parse3 \ + testsuites/parse-nodate.conf \ + testsuites/reallife.parse-nodate \ testsuites/parse_invld_regex.conf \ testsuites/samples.parse_invld_regex \ testsuites/parse-3164-buggyday.conf \ diff --git a/tests/parsertest.sh b/tests/parsertest.sh index 83c5e614..10a7f450 100755 --- a/tests/parsertest.sh +++ b/tests/parsertest.sh @@ -8,6 +8,8 @@ source $srcdir/diag.sh nettester parse_invld_regex udp source $srcdir/diag.sh nettester parse_invld_regex tcp source $srcdir/diag.sh nettester parse-3164-buggyday udp source $srcdir/diag.sh nettester parse-3164-buggyday tcp +source $srcdir/diag.sh nettester parse-nodate udp +source $srcdir/diag.sh nettester parse-nodate tcp echo \[parsertest.sh]: redoing tests in IPv4-only mode source $srcdir/diag.sh nettester parse1 udp -4 @@ -18,4 +20,6 @@ source $srcdir/diag.sh nettester parse_invld_regex udp -4 source $srcdir/diag.sh nettester parse_invld_regex tcp -4 source $srcdir/diag.sh nettester parse-3164-buggyday udp -4 source $srcdir/diag.sh nettester parse-3164-buggyday tcp -4 +source $srcdir/diag.sh nettester parse-nodate udp -4 +source $srcdir/diag.sh nettester parse-nodate tcp -4 source $srcdir/diag.sh exit diff --git a/tests/testsuites/parse-nodate.conf b/tests/testsuites/parse-nodate.conf new file mode 100644 index 00000000..570638d9 --- /dev/null +++ b/tests/testsuites/parse-nodate.conf @@ -0,0 +1,14 @@ +# test is a test config that does not include the timestamp. This is necessary to +# test some illformed messages that do not contain a date. In that case, the system's +# current timestamp is used, and that of course is a bit hard to compare against +# a fixed template. So the solution in this case is to use a format that does +# not contain any timestamp. Maybe not optimal, but it works ;) +# rgerhards, 2010-03-19 +$ModLoad ../plugins/omstdout/.libs/omstdout +$IncludeConfig nettest.input.conf # This picks the to be tested input from the test driver! + +$ErrorMessagesToStderr off + +# use a special format that we can easily parse +$template fmt,"%PRI%,%syslogfacility-text%,%syslogseverity-text%,%hostname%,%programname%,%syslogtag%,%msg%\n" +*.* :omstdout:;fmt diff --git a/tests/testsuites/samples.parse-nodate b/tests/testsuites/samples.parse-nodate new file mode 100644 index 00000000..7f16181c --- /dev/null +++ b/tests/testsuites/samples.parse-nodate @@ -0,0 +1,6 @@ +<27>xapi: [error|xen3|15|Guest liveness monitor D:bca30ab3f1c1|master_connection] Connection to master died. I will continue to retry indefinitely (supressing future logging of this message) +27,daemon,err,localhost,xapi,xapi:, [error|xen3|15|Guest liveness monitor D:bca30ab3f1c1|master_connection] Connection to master died. I will continue to retry indefinitely (supressing future logging of this message) +# a message with just text (as permitted by rfc 3164) +# it is questionable if the current sample result is really correct as of 3164! +This is a message! +13,user,notice,This,is,is, a message! -- cgit From 95cde529cc2d2aab2047f5ab2c52d9cd8ba23f31 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Sun, 21 Mar 2010 18:33:14 +0100 Subject: added some more tests for severely ill-formed snare messages also improved nettester testbench tool a bit --- tests/Makefile.am | 4 ++++ tests/nettester.c | 14 ++++++++------ tests/parsertest.sh | 8 ++++++++ tests/testsuites/samples.snare_ccoff_udp | 12 ++++++++++++ tests/testsuites/samples.snare_ccoff_udp2 | 20 ++++++++++++++++++++ tests/testsuites/snare_ccoff_udp.conf | 21 +++++++++++++++++++++ tests/testsuites/snare_ccoff_udp2.conf | 17 +++++++++++++++++ 7 files changed, 90 insertions(+), 6 deletions(-) create mode 100644 tests/testsuites/samples.snare_ccoff_udp create mode 100644 tests/testsuites/samples.snare_ccoff_udp2 create mode 100644 tests/testsuites/snare_ccoff_udp.conf create mode 100644 tests/testsuites/snare_ccoff_udp2.conf diff --git a/tests/Makefile.am b/tests/Makefile.am index 98b97d44..d2a90869 100644 --- a/tests/Makefile.am +++ b/tests/Makefile.am @@ -110,6 +110,10 @@ EXTRA_DIST= 1.rstest 2.rstest 3.rstest err1.rstest \ testsuites/samples.parse_invld_regex \ testsuites/parse-3164-buggyday.conf \ testsuites/samples.parse-3164-buggyday \ + testsuites/snare_ccoff_udp.conf \ + testsuites/samples.snare_ccoff_udp \ + testsuites/snare_ccoff_udp2.conf \ + testsuites/samples.snare_ccoff_udp2 \ testsuites/omod-if-array.conf \ testsuites/1.omod-if-array \ testsuites/1.field1 \ diff --git a/tests/nettester.c b/tests/nettester.c index 22b5f16f..e1ecbcb5 100644 --- a/tests/nettester.c +++ b/tests/nettester.c @@ -62,6 +62,7 @@ static char *testSuite = NULL; /* name of current test suite */ static int iPort = 12514; /* port which shall be used for sending data */ static char* pszCustomConf = NULL; /* custom config file, use -c conf to specify */ static int verbose = 0; /* verbose output? -v option */ +static int useDebugEnv = 0; /* activate debugging environment (for rsyslog debug log)? */ /* these two are quick hacks... */ int iFailed = 0; @@ -218,10 +219,8 @@ int openPipe(char *configFile, pid_t *pid, int *pfd) "-M../runtime/.libs:../.libs", NULL }; char confFile[1024]; char *newenviron[] = { NULL }; - /* debug aide... - char *newenviron[] = { "RSYSLOG_DEBUG=debug nostdout", + char *newenvironDeb[] = { "RSYSLOG_DEBUG=debug nostdout", "RSYSLOG_DEBUGLOG=log", NULL }; - */ sprintf(confFile, "-f%s/testsuites/%s.conf", srcdir, (pszCustomConf == NULL) ? configFile : pszCustomConf); @@ -244,7 +243,7 @@ int openPipe(char *configFile, pid_t *pid, int *pfd) close(pipefd[1]); close(pipefd[0]); fclose(stdin); - execve("../tools/rsyslogd", newargv, newenviron); + execve("../tools/rsyslogd", newargv, (useDebugEnv) ? newenvironDeb : newenviron); } else { close(pipefd[1]); *pid = cpid; @@ -460,11 +459,14 @@ int main(int argc, char *argv[]) char buf[4096]; char testcases[4096]; - while((opt = getopt(argc, argv, "c:i:p:t:v")) != EOF) { + while((opt = getopt(argc, argv, "dc:i:p:t:v")) != EOF) { switch((char)opt) { case 'c': pszCustomConf = optarg; break; + case 'd': + useDebugEnv = 1; + break; case 'i': if(!strcmp(optarg, "udp")) inputMode = inputUDP; @@ -485,7 +487,7 @@ int main(int argc, char *argv[]) verbose = 1; break; default:printf("Invalid call of nettester, invalid option '%c'.\n", opt); - printf("Usage: nettester -ttestsuite-name -iudp|tcp [-pport] [-ccustomConfFile] \n"); + printf("Usage: nettester -d -ttestsuite-name -iudp|tcp [-pport] [-ccustomConfFile] \n"); exit(1); } } diff --git a/tests/parsertest.sh b/tests/parsertest.sh index 10a7f450..fc68ab84 100755 --- a/tests/parsertest.sh +++ b/tests/parsertest.sh @@ -10,6 +10,10 @@ source $srcdir/diag.sh nettester parse-3164-buggyday udp source $srcdir/diag.sh nettester parse-3164-buggyday tcp source $srcdir/diag.sh nettester parse-nodate udp source $srcdir/diag.sh nettester parse-nodate tcp +# the following samples can only be run over UDP as they are so +# malformed they break traditional syslog/tcp framing... +source $srcdir/diag.sh nettester snare_ccoff_udp udp +source $srcdir/diag.sh nettester snare_ccoff_udp2 udp echo \[parsertest.sh]: redoing tests in IPv4-only mode source $srcdir/diag.sh nettester parse1 udp -4 @@ -22,4 +26,8 @@ source $srcdir/diag.sh nettester parse-3164-buggyday udp -4 source $srcdir/diag.sh nettester parse-3164-buggyday tcp -4 source $srcdir/diag.sh nettester parse-nodate udp -4 source $srcdir/diag.sh nettester parse-nodate tcp -4 +# UDP-only tests +source $srcdir/diag.sh nettester snare_ccoff_udp udp -4 +source $srcdir/diag.sh nettester snare_ccoff_udp2 udp -4 + source $srcdir/diag.sh exit diff --git a/tests/testsuites/samples.snare_ccoff_udp b/tests/testsuites/samples.snare_ccoff_udp new file mode 100644 index 00000000..334267f4 --- /dev/null +++ b/tests/testsuites/samples.snare_ccoff_udp @@ -0,0 +1,12 @@ +# see comments in snare_ccoff_udp.conf +# note that some of these samples look pretty wild, but they are +# *real* cases (just mangled to anonymize them...) +# Sample 1 - note the absence of PRI! +windowsserver MSWinEventLog 1 Security 1167 Fri Mar 19 15:33:30 2010 540 Security SYSTEM User Success Audit WINDOWSSERVER Logon/Logoff Successful Network Logon: User Name: WINDOWSSERVER$ Domain: DOMX Logon ID: (0x0,0xF88396) Logon Type: 3 Logon Process: Kerberos Authentication Package: Kerberos Workstation Name: Logon GUID: {79b6eb79-7bcc-8a2e-7dad-953c51dc00fd} Caller User Name: - Caller Domain: - Caller Logon ID: - Caller Process ID: - Transited Services: - Source Network Address: 10.11.11.3 Source Port: 3306 733\n +13,user,notice,localhost,windowsserver,windowsserver MSWinEventLog 1 Security 1167 Fri, Mar 19 15:33:30 2010 540 Security SYSTEM User Success Audit WINDOWSSERVER Logon/Logoff Successful Network Logon: User Name: WINDOWSSERVER$ Domain: DOMX Logon ID: (0x0,0xF88396) Logon Type: 3 Logon Process: Kerberos Authentication Package: Kerberos Workstation Name: Logon GUID: {79b6eb79-7bcc-8a2e-7dad-953c51dc00fd} Caller User Name: - Caller Domain: - Caller Logon ID: - Caller Process ID: - Transited Services: - Source Network Address: 10.11.11.3 Source Port: 3306 733 +# Sample 2 +windowsserver MSWinEventLog 1 Security 1166 Fri Mar 19 15:33:30 2010 576 Security SYSTEM User Success Audit WINDOWSSERVER Logon/Logoff Special privileges assigned to new logon: User Name: WINDOWSSERVER$ Domain: DOMX Logon ID: (0x0,0xF88396) Privileges: SeSecurityPrivilege SeBackupPrivilege SeRestorePrivilege SeTakeOwnershipPrivilege SeDebugPrivilege SeSystemEnvironmentPrivilege SeLoadDriverPrivilege SeImpersonatePrivilege SeEnableDelegationPrivilege 732\n +13,user,notice,localhost,windowsserver,windowsserver MSWinEventLog 1 Security 1166 Fri, Mar 19 15:33:30 2010 576 Security SYSTEM User Success Audit WINDOWSSERVER Logon/Logoff Special privileges assigned to new logon: User Name: WINDOWSSERVER$ Domain: DOMX Logon ID: (0x0,0xF88396) Privileges: SeSecurityPrivilege SeBackupPrivilege SeRestorePrivilege SeTakeOwnershipPrivilege SeDebugPrivilege SeSystemEnvironmentPrivilege SeLoadDriverPrivilege SeImpersonatePrivilege SeEnableDelegationPrivilege 732 +# Sample 3 +windowsserver MSWinEventLog 1 Security 1165 Fri Mar 19 15:33:30 2010 538 Security SYSTEM User Success Audit WINDOWSSERVER Logon/Logoff User Logoff: User Name: WINDOWSSERVER$ Domain: DOMX Logon ID: (0x0,0xF8830B) Logon Type: 3 731\n +13,user,notice,localhost,windowsserver,windowsserver MSWinEventLog 1 Security 1165 Fri, Mar 19 15:33:30 2010 538 Security SYSTEM User Success Audit WINDOWSSERVER Logon/Logoff User Logoff: User Name: WINDOWSSERVER$ Domain: DOMX Logon ID: (0x0,0xF8830B) Logon Type: 3 731 diff --git a/tests/testsuites/samples.snare_ccoff_udp2 b/tests/testsuites/samples.snare_ccoff_udp2 new file mode 100644 index 00000000..8c14f0bb --- /dev/null +++ b/tests/testsuites/samples.snare_ccoff_udp2 @@ -0,0 +1,20 @@ +# see comments in snare_ccoff_udp.conf +# note that some of these samples look pretty wild, but they are +# *real* cases (just mangled to anonymize them...) +# +# NOTE +# The current responses are probably not correct (handling of messages without PRI). +# However, we keep them inside the test to be consistent. We should look at how +# PRI-less messages are handled and once we have fixed that, the test cases may need +# to be adapted. We do NOT try to preserve misbehaviour on such seriously malformed +# messages. +# +# Sample 1 - note the absence of PRI! +windowsserver MSWinEventLog 1 Security 1167 Fri Mar 19 15:33:30 2010 540 Security SYSTEM User Success Audit WINDOWSSERVER Logon/Logoff Successful Network Logon: User Name: WINDOWSSERVER$ Domain: DOMX Logon ID: (0x0,0xF88396) Logon Type: 3 Logon Process: Kerberos Authentication Package: Kerberos Workstation Name: Logon GUID: {79b6eb79-7bcc-8a2e-7dad-953c51dc00fd} Caller User Name: - Caller Domain: - Caller Logon ID: - Caller Process ID: - Transited Services: - Source Network Address: 10.11.11.3 Source Port: 3306 733\n +insert into windows (Message, Facility,FromHost, Priority, DeviceReportedTime, ReceivedAt, InfoUnitID, SysLogTag) values (' Mar 19 15:33:30 2010 540 Security SYSTEM User Success Audit WINDOWSSERVER Logon/Logoff Successful Network Logon: User Name: WINDOWSSERVER$ Domain: DOMX Logon ID: (0x0,0xF88396) Logon Type: 3 Logon Process: Kerberos Authentication Package: Kerberos Workstation Name: Logon GUID: {79b6eb79-7bcc-8a2e-7dad-953c51dc00fd} Caller User Name: - Caller Domain: - Caller Logon ID: - Caller Process ID: - Transited Services: - Source Network Address: 10.11.11.3 Source Port: 3306 733', 1, 'localhost',5, '20100321185328', '20100321185328', 1, 'windowsserver MSWinEventLog 1 Security 1167 Fri') +# Sample 2 +windowsserver MSWinEventLog 1 Security 1166 Fri Mar 19 15:33:30 2010 576 Security SYSTEM User Success Audit WINDOWSSERVER Logon/Logoff Special privileges assigned to new logon: User Name: WINDOWSSERVER$ Domain: DOMX Logon ID: (0x0,0xF88396) Privileges: SeSecurityPrivilege SeBackupPrivilege SeRestorePrivilege SeTakeOwnershipPrivilege SeDebugPrivilege SeSystemEnvironmentPrivilege SeLoadDriverPrivilege SeImpersonatePrivilege SeEnableDelegationPrivilege 732\n +insert into windows (Message, Facility,FromHost, Priority, DeviceReportedTime, ReceivedAt, InfoUnitID, SysLogTag) values (' Mar 19 15:33:30 2010 576 Security SYSTEM User Success Audit WINDOWSSERVER Logon/Logoff Special privileges assigned to new logon: User Name: WINDOWSSERVER$ Domain: DOMX Logon ID: (0x0,0xF88396) Privileges: SeSecurityPrivilege SeBackupPrivilege SeRestorePrivilege SeTakeOwnershipPrivilege SeDebugPrivilege SeSystemEnvironmentPrivilege SeLoadDriverPrivilege SeImpersonatePrivilege SeEnableDelegationPrivilege 732', 1, 'localhost',5, '20100321185328', '20100321185328', 1, 'windowsserver MSWinEventLog 1 Security 1166 Fri') +# Sample 3 +windowsserver MSWinEventLog 1 Security 1165 Fri Mar 19 15:33:30 2010 538 Security SYSTEM User Success Audit WINDOWSSERVER Logon/Logoff User Logoff: User Name: WINDOWSSERVER$ Domain: DOMX Logon ID: (0x0,0xF8830B) Logon Type: 3 731\n +insert into windows (Message, Facility,FromHost, Priority, DeviceReportedTime, ReceivedAt, InfoUnitID, SysLogTag) values (' Mar 19 15:33:30 2010 538 Security SYSTEM User Success Audit WINDOWSSERVER Logon/Logoff User Logoff: User Name: WINDOWSSERVER$ Domain: DOMX Logon ID: (0x0,0xF8830B) Logon Type: 3 731', 1, 'localhost',5, '20100321185328', '20100321185328', 1, 'windowsserver MSWinEventLog 1 Security 1165 Fri') diff --git a/tests/testsuites/snare_ccoff_udp.conf b/tests/testsuites/snare_ccoff_udp.conf new file mode 100644 index 00000000..6abbedf4 --- /dev/null +++ b/tests/testsuites/snare_ccoff_udp.conf @@ -0,0 +1,21 @@ +# This test some real-world snare cases. I don't like snare (no wonder +# as I have written EventReporter, the ultimate Windows-to-Syslog tool), +# but besides that snare generates severely malformed messages that +# really stress-test the rsyslog engine. They deserve to be beaten by someone ;) +# This test needs to be run over UDP only, as snare puts LF INTO some of the messages, +# which makes it impossible to try these out via traditional syslog/tcp +# added 2010-03-21 rgerhards +$ModLoad ../plugins/omstdout/.libs/omstdout +$IncludeConfig nettest.input.conf # This picks the to be tested input from the test driver! + +$ErrorMessagesToStderr off + +# snare usses HT as field delimiter, so many users have turned off +# control character escaping to make any sense at all from these messages... +$EscapeControlCharactersOnReceive off + +# use a special format that we can easily check. We do NOT include a timestamp because +# the malformed snare messages usually do not contain one (and we can not check against +# the system time in our test cases). +$template fmt,"%PRI%,%syslogfacility-text%,%syslogseverity-text%,%hostname%,%programname%,%syslogtag%,%msg%\n" +*.* :omstdout:;fmt diff --git a/tests/testsuites/snare_ccoff_udp2.conf b/tests/testsuites/snare_ccoff_udp2.conf new file mode 100644 index 00000000..9115c14f --- /dev/null +++ b/tests/testsuites/snare_ccoff_udp2.conf @@ -0,0 +1,17 @@ +# Similar to snare_ccoff_udp_2, but with a different template. This template +# has triggered problems in the past, thus a test is granted. +# added 2010-03-21 rgerhards +$ModLoad ../plugins/omstdout/.libs/omstdout +$IncludeConfig nettest.input.conf # This picks the to be tested input from the test driver! + +$ErrorMessagesToStderr off + +# snare usses HT as field delimiter, so many users have turned off +# control character escaping to make any sense at all from these messages... +$EscapeControlCharactersOnReceive off + +# we need to use a fixed timestamp, as otherwise we can not compare :( +# This could be improved in later versions of the testing tools, but requires +# modification to the rsyslog core... +$template fmt,"insert into windows (Message, Facility,FromHost, Priority, DeviceReportedTime, ReceivedAt, InfoUnitID, SysLogTag) values ('%msg:::space-cc%', %syslogfacility%, '%HOSTNAME%',%syslogpriority%, '20100321185328', '20100321185328', %iut%, '%syslogtag:::space-cc%')\n",sql +*.* :omstdout:;fmt -- cgit From dccadb677c5a6b8379f631e4c1f14c8c4089d4a6 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Sun, 21 Mar 2010 18:52:51 +0100 Subject: exp: made omfile ensure that it is not called twice in parallel on the same file instance In theory, the rsyslog core should never call in parallel into an output module for the same instance. However, it looks like this seems to happen under (strange?) circumstances. I have now enhanced omfile so that it guards itself against being called in parallel on the same instance data. This is done to help troubleshooting and may stay as an interim solution if it proves to solve an anomaly we see in at least one installation (to trigger this problem, an extremely large traffic volume is needed). --- tools/omfile.c | 9 +++++++++ 1 file changed, 9 insertions(+) diff --git a/tools/omfile.c b/tools/omfile.c index c4e834cc..f4db7dab 100644 --- a/tools/omfile.c +++ b/tools/omfile.c @@ -48,6 +48,7 @@ #include #include #include +#include #ifdef OS_SOLARIS # include @@ -65,6 +66,7 @@ #include "stream.h" #include "unicode-helper.h" #include "atomic.h" +#include "debug.h" MODULE_TYPE_OUTPUT @@ -134,6 +136,7 @@ typedef struct _instanceData { int iIOBufSize; /* size of associated io buffer */ int iFlushInterval; /* how fast flush buffer on inactivity? */ bool bFlushOnTXEnd; /* flush write buffers when transaction has ended? */ + pthread_mutex_t mutEx; /* guard ourselves against being called multiple times with the same instance */ } instanceData; @@ -603,6 +606,7 @@ finalize_it: BEGINcreateInstance CODESTARTcreateInstance pData->pStrm = NULL; + pthread_mutex_init(&pData->mutEx, NULL); ENDcreateInstance @@ -612,6 +616,7 @@ CODESTARTfreeInstance dynaFileFreeCache(pData); } else if(pData->pStrm != NULL) strm.Destruct(&pData->pStrm); + pthread_mutex_destroy(&pData->mutEx); ENDfreeInstance @@ -621,12 +626,14 @@ ENDtryResume BEGINdoAction CODESTARTdoAction + d_pthread_mutex_lock(&pData->mutEx); DBGPRINTF("file to log to: %s\n", pData->f_fname); CHKiRet(writeFile(ppString, iMsgOpts, pData)); if(pData->bFlushOnTXEnd) { /* TODO v5: do this in endTransaction only! */ CHKiRet(strm.Flush(pData->pStrm)); } + d_pthread_mutex_unlock(&pData->mutEx); finalize_it: ENDdoAction @@ -764,6 +771,7 @@ static rsRetVal resetConfigVariables(uchar __attribute__((unused)) *pp, void __a BEGINdoHUP CODESTARTdoHUP + d_pthread_mutex_lock(&pData->mutEx); if(pData->bDynamicName) { dynaFileFreeCacheEntries(pData); } else { @@ -772,6 +780,7 @@ CODESTARTdoHUP pData->pStrm = NULL; } } + d_pthread_mutex_unlock(&pData->mutEx); ENDdoHUP -- cgit From 1ddb082cfa1ca6bb7b8c44ce760ccd4200e1f2f7 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Mon, 22 Mar 2010 14:06:05 +0100 Subject: added testcase showcasing problems when dynafile can not be opened note that so far no patch is provided. This has not yet been made part of "make check" --- tests/dynfile_invalid.sh | 34 +++++++++++++++++++++++++++ tests/tcpflood.c | 43 ++++++++++++++++++++++------------- tests/testsuites/dynfile_invalid.conf | 14 ++++++++++++ 3 files changed, 75 insertions(+), 16 deletions(-) create mode 100755 tests/dynfile_invalid.sh create mode 100644 tests/testsuites/dynfile_invalid.conf diff --git a/tests/dynfile_invalid.sh b/tests/dynfile_invalid.sh new file mode 100755 index 00000000..f61dc104 --- /dev/null +++ b/tests/dynfile_invalid.sh @@ -0,0 +1,34 @@ +# This test checks if omfile segfaults when a file open() in dynacache mode fails. +# The test is mimiced after a real-life scenario (which, of course, was much more +# complex). +# +# added 2010-03-09 by Rgerhards +# +# This file is part of the rsyslog project, released under GPLv3 +echo =============================================================================== +echo TEST: \[dynfile_invalid.sh\]: test open fail for dynafiles +source $srcdir/diag.sh init +# uncomment for debugging support: +export RSYSLOG_DEBUG="debug nostdout noprintmutexaction" +export RSYSLOG_DEBUGLOG="log" +source $srcdir/diag.sh startup dynfile_invalid.conf +# we send handcrafted message. We have a dynafile cache of 4, and now send one message +# each to fill up the cache. +./tcpflood -m1 -M "<129>Mar 10 01:00:00 172.20.245.8 tag msg:rsyslog.out.0.log:0" +./tcpflood -m1 -M "<129>Mar 10 01:00:00 172.20.245.8 tag msg:rsyslog.out.1.log:1" +./tcpflood -m1 -M "<129>Mar 10 01:00:00 172.20.245.8 tag msg:rsyslog.out.2.log:2" +./tcpflood -m1 -M "<129>Mar 10 01:00:00 172.20.245.8 tag msg:rsyslog.out.3.log:3" +# the next one has caused a segfault in practice +# note that /proc/rsyslog.error.file must not be creatable +./tcpflood -m1 -M "<129>Mar 10 01:00:00 172.20.245.8 tag msg:/proc/rsyslog.error.file:boom" +# some more writes +./tcpflood -m1 -M "<129>Mar 10 01:00:00 172.20.245.8 tag msg:rsyslog.out.0.log:4" +./tcpflood -m1 -M "<129>Mar 10 01:00:00 172.20.245.8 tag msg:rsyslog.out.1.log:5" +./tcpflood -m1 -M "<129>Mar 10 01:00:00 172.20.245.8 tag msg:rsyslog.out.2.log:6" +./tcpflood -m1 -M "<129>Mar 10 01:00:00 172.20.245.8 tag msg:rsyslog.out.3.log:7" +# done message generation +source $srcdir/diag.sh shutdown-when-empty # shut down rsyslogd when done processing messages +source $srcdir/diag.sh wait-shutdown # and wait for it to terminate +cat rsyslog.out.*.log > rsyslog.out.log +source $srcdir/diag.sh seq-check 0 7 +source $srcdir/diag.sh exit diff --git a/tests/tcpflood.c b/tests/tcpflood.c index d4955447..2bb7ba2c 100644 --- a/tests/tcpflood.c +++ b/tests/tcpflood.c @@ -18,10 +18,12 @@ * -f support for testing dynafiles. If given, include a dynafile ID * in the range 0..(f-1) as the SECOND field, shifting all field values * one field to the right. Zero (default) disables this functionality. + * -M the message to be sent. Disables all message format options, as + * only that exact same message is sent. * * Part of the testbench for rsyslog. * - * Copyright 2009 Rainer Gerhards and Adiscon GmbH. + * Copyright 2009, 2010 Rainer Gerhards and Adiscon GmbH. * * This file is part of rsyslog. * @@ -72,6 +74,7 @@ static int numConnections = 1; /* number of connections to create */ static int *sockArray; /* array of sockets to use */ static int msgNum = 0; /* initial message number to start with */ static int bShowProgress = 1; /* show progress messages */ +static char *MsgToSend = NULL; /* if non-null, this is the actual message to send */ /* open a single tcp connection @@ -212,21 +215,26 @@ int sendMessages(void) socknum = i - (numMsgsToSend - numConnections); else socknum = rand() % numConnections; - if(dynFileIDs > 0) { - sprintf(dynFileIDBuf, "%d:", rand() % dynFileIDs); - } - if(extraDataLen == 0) { - lenBuf = sprintf(buf, "<%s>Mar 1 01:00:00 172.20.245.8 tag msgnum:%s%8.8d:\n", - msgPRI, dynFileIDBuf, msgNum); + if(MsgToSend == NULL) { + if(dynFileIDs > 0) { + sprintf(dynFileIDBuf, "%d:", rand() % dynFileIDs); + } + if(extraDataLen == 0) { + lenBuf = sprintf(buf, "<%s>Mar 1 01:00:00 172.20.245.8 tag msgnum:%s%8.8d:\n", + msgPRI, dynFileIDBuf, msgNum); + } else { + if(bRandomizeExtraData) + edLen = ((long) rand() + extraDataLen) % extraDataLen + 1; + else + edLen = extraDataLen; + memset(extraData, 'X', edLen); + extraData[edLen] = '\0'; + lenBuf = sprintf(buf, "<%s>Mar 1 01:00:00 172.20.245.8 tag msgnum:%s%8.8d:%d:%s\n", + msgPRI, dynFileIDBuf, msgNum, edLen, extraData); + } } else { - if(bRandomizeExtraData) - edLen = ((long) rand() + extraDataLen) % extraDataLen + 1; - else - edLen = extraDataLen; - memset(extraData, 'X', edLen); - extraData[edLen] = '\0'; - lenBuf = sprintf(buf, "<%s>Mar 1 01:00:00 172.20.245.8 tag msgnum:%s%8.8d:%d:%s\n", - msgPRI, dynFileIDBuf, msgNum, edLen, extraData); + /* use fixed message format from command line */ + lenBuf = sprintf(buf, "%s\n", MsgToSend); } lenSend = send(sockArray[socknum], buf, lenBuf, 0); if(lenSend != lenBuf) { @@ -327,7 +335,7 @@ int main(int argc, char *argv[]) if(!isatty(1)) bShowProgress = 0; - while((opt = getopt(argc, argv, "f:t:p:c:m:i:P:d:n:r")) != -1) { + while((opt = getopt(argc, argv, "f:t:p:c:m:i:P:d:n:M:r")) != -1) { switch (opt) { case 't': targetIP = optarg; break; @@ -354,6 +362,9 @@ int main(int argc, char *argv[]) break; case 'f': dynFileIDs = atoi(optarg); break; + case 'M': MsgToSend = optarg; +fprintf(stderr, "msg to send: '%s'\n", MsgToSend); + break; default: printf("invalid option '%c' or value missing - terminating...\n", opt); exit (1); break; diff --git a/tests/testsuites/dynfile_invalid.conf b/tests/testsuites/dynfile_invalid.conf new file mode 100644 index 00000000..458f199b --- /dev/null +++ b/tests/testsuites/dynfile_invalid.conf @@ -0,0 +1,14 @@ +# simple async writing test +# rgerhards, 2010-03-09 +$IncludeConfig diag-common.conf + +$ModLoad ../plugins/imtcp/.libs/imtcp +$MainMsgQueueTimeoutShutdown 10000 +$InputTCPServerRun 13514 + +$template outfmt,"%msg:F,58:3%\n" +$template dynfile,"%msg:F,58:2%.log" # complete name is in message +$OMFileFlushOnTXEnd on +$DynaFileCacheSize 4 +$omfileFlushInterval 1 +local0.* ?dynfile;outfmt -- cgit From a28a31feeab1bec5f4c74e3b6121f866f68eac54 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Mon, 22 Mar 2010 14:22:22 +0100 Subject: previous (experimental) patch was somewhat incorrect, fixed This is what caused the new test to fail... --- tools/omfile.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tools/omfile.c b/tools/omfile.c index f4db7dab..0f27f1e9 100644 --- a/tools/omfile.c +++ b/tools/omfile.c @@ -633,8 +633,8 @@ CODESTARTdoAction /* TODO v5: do this in endTransaction only! */ CHKiRet(strm.Flush(pData->pStrm)); } - d_pthread_mutex_unlock(&pData->mutEx); finalize_it: + d_pthread_mutex_unlock(&pData->mutEx); ENDdoAction -- cgit From 42d2c13072734a41114b502cf77f378a51cf3431 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Mon, 22 Mar 2010 14:37:36 +0100 Subject: cleanup of debug message in testbench --- tests/tcpflood.c | 1 - 1 file changed, 1 deletion(-) diff --git a/tests/tcpflood.c b/tests/tcpflood.c index 2bb7ba2c..32bf959d 100644 --- a/tests/tcpflood.c +++ b/tests/tcpflood.c @@ -363,7 +363,6 @@ int main(int argc, char *argv[]) case 'f': dynFileIDs = atoi(optarg); break; case 'M': MsgToSend = optarg; -fprintf(stderr, "msg to send: '%s'\n", MsgToSend); break; default: printf("invalid option '%c' or value missing - terminating...\n", opt); exit (1); -- cgit From e6aaf1254404661c59504dab264a1140e9e7b2bc Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Mon, 22 Mar 2010 14:53:08 +0100 Subject: added one more test case for dynafile cache --- tests/Makefile.am | 8 +++++++- tests/dynfile_invalid2.sh | 34 ++++++++++++++++++++++++++++++++++ tests/testsuites/dynfile_invalid2.conf | 14 ++++++++++++++ 3 files changed, 55 insertions(+), 1 deletion(-) create mode 100755 tests/dynfile_invalid2.sh create mode 100644 tests/testsuites/dynfile_invalid2.conf diff --git a/tests/Makefile.am b/tests/Makefile.am index d2a90869..9e04ea1e 100644 --- a/tests/Makefile.am +++ b/tests/Makefile.am @@ -19,6 +19,8 @@ TESTS = $(TESTRUNS) cfg.sh \ asynwr_deadlock4.sh \ gzipwr_large.sh \ gzipwr_large_dynfile.sh \ + dynfile_invalid.sh \ + dynfile_invalid2.sh \ complex1.sh \ queue-persist.sh \ pipeaction.sh @@ -50,7 +52,7 @@ EXTRA_DIST= 1.rstest 2.rstest 3.rstest err1.rstest \ testsuites/valid.conf \ cfg.sh \ cfg1.cfgtest \ - cfg1.testin \ + fg1.testin \ cfg2.cfgtest \ cfg2.testin \ cfg3.cfgtest \ @@ -175,6 +177,10 @@ EXTRA_DIST= 1.rstest 2.rstest 3.rstest err1.rstest \ testsuites/gzipwr_large_dynfile.conf \ complex1.sh \ testsuites/complex1.conf \ + dynfile_invalid.sh \ + testsuites/dynfile_invalid.conf \ + dynfile_invalid2.sh \ + testsuites/dynfile_invalid2.conf \ proprepltest.sh \ testsuites/rfctag.conf \ testsuites/master.rfctag \ diff --git a/tests/dynfile_invalid2.sh b/tests/dynfile_invalid2.sh new file mode 100755 index 00000000..b6fb3945 --- /dev/null +++ b/tests/dynfile_invalid2.sh @@ -0,0 +1,34 @@ +# This test checks if omfile segfaults when a file open() in dynacache mode fails. +# The test is mimiced after a real-life scenario (which, of course, was much more +# complex). +# +# added 2010-03-22 by Rgerhards +# +# This file is part of the rsyslog project, released under GPLv3 +echo =============================================================================== +echo TEST: \[dynfile_invalid2.sh\]: test open fail for dynafiles +source $srcdir/diag.sh init +# uncomment for debugging support: +export RSYSLOG_DEBUG="debug nostdout noprintmutexaction" +export RSYSLOG_DEBUGLOG="log" +source $srcdir/diag.sh startup dynfile_invalid2.conf +# we send handcrafted message. We have a dynafile cache of 4, and now send one message +# each to fill up the cache. +./tcpflood -m1 -M "<129>Mar 10 01:00:00 172.20.245.8 tag msg:rsyslog.out.0.log:0" +./tcpflood -m1 -M "<129>Mar 10 01:00:00 172.20.245.8 tag msg:rsyslog.out.1.log:1" +./tcpflood -m1 -M "<129>Mar 10 01:00:00 172.20.245.8 tag msg:rsyslog.out.2.log:2" +./tcpflood -m1 -M "<129>Mar 10 01:00:00 172.20.245.8 tag msg:rsyslog.out.3.log:3" +# the next one has caused a segfault in practice +# note that /proc/rsyslog.error.file must not be creatable +./tcpflood -m1 -M "<129>Mar 10 01:00:00 172.20.245.8 tag msg:/proc/rsyslog.error.file:boom" +# some more writes +./tcpflood -m1 -M "<129>Mar 10 01:00:00 172.20.245.8 tag msg:rsyslog.out.0.log:4" +./tcpflood -m1 -M "<129>Mar 10 01:00:00 172.20.245.8 tag msg:rsyslog.out.1.log:5" +./tcpflood -m1 -M "<129>Mar 10 01:00:00 172.20.245.8 tag msg:rsyslog.out.2.log:6" +./tcpflood -m1 -M "<129>Mar 10 01:00:00 172.20.245.8 tag msg:rsyslog.out.3.log:7" +# done message generation +source $srcdir/diag.sh shutdown-when-empty # shut down rsyslogd when done processing messages +source $srcdir/diag.sh wait-shutdown # and wait for it to terminate +cat rsyslog.out.*.log > rsyslog.out.log +source $srcdir/diag.sh seq-check 0 7 +source $srcdir/diag.sh exit diff --git a/tests/testsuites/dynfile_invalid2.conf b/tests/testsuites/dynfile_invalid2.conf new file mode 100644 index 00000000..6d94c40d --- /dev/null +++ b/tests/testsuites/dynfile_invalid2.conf @@ -0,0 +1,14 @@ +# simple async writing test +# rgerhards, 2010-03-22 +$IncludeConfig diag-common.conf + +$ModLoad ../plugins/imtcp/.libs/imtcp +$MainMsgQueueTimeoutShutdown 10000 +$InputTCPServerRun 13514 + +$template outfmt,"%msg:F,58:3%\n" +$template dynfile,"%msg:F,58:2%.log" # complete name is in message +$OMFileFlushOnTXEnd off +$DynaFileCacheSize 4 +$omfileFlushInterval 1 +local0.* ?dynfile;outfmt -- cgit From 148910c285161097b44cd5df165c3bd19e21ae33 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Mon, 22 Mar 2010 15:47:07 +0100 Subject: bugfix(minor): BSD_SO_COMPAT query function had some global vars not properly initialized. However, in practice the loader initializes them with zero, the desired value, so there were no actual issue in almost all cases. --- ChangeLog | 4 ++++ runtime/net.c | 4 ++-- tests/diag.sh | 3 ++- tests/dynfile_invalid.sh | 4 ++-- 4 files changed, 10 insertions(+), 5 deletions(-) diff --git a/ChangeLog b/ChangeLog index 85a9ecb6..dc12e856 100644 --- a/ChangeLog +++ b/ChangeLog @@ -39,6 +39,10 @@ Version 4.6.2 [v4-stable] (rgerhards), 2010-03-?? 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. +- bugfix(minor): BSD_SO_COMPAT query function had some global vars not + properly initialized. However, in practice the loader initializes them + with zero, the desired value, so there were no actual issue in almost + all cases. --------------------------------------------------------------------------- Version 4.6.1 [v4-stable] (rgerhards), 2010-03-04 - re-enabled old pipe output (using new module ompipe, built-in) after diff --git a/runtime/net.c b/runtime/net.c index e91c8a7f..fe6eef5b 100644 --- a/runtime/net.c +++ b/runtime/net.c @@ -1010,8 +1010,8 @@ static int should_use_so_bsdcompat(void) { #ifndef OS_BSD - static int init_done; - static int so_bsdcompat_is_obsolete; + static int init_done = 0; + static int so_bsdcompat_is_obsolete = 0; if (!init_done) { struct utsname myutsname; diff --git a/tests/diag.sh b/tests/diag.sh index a4f13afd..a4100ac0 100755 --- a/tests/diag.sh +++ b/tests/diag.sh @@ -7,7 +7,8 @@ # This file is part of the rsyslog project, released under GPLv3 #valgrind="valgrind --log-fd=1" #valgrind="valgrind --tool=drd --log-fd=1" -#valgrind="valgrind --tool=helgrind --log-fd=1" +valgrind="valgrind --tool=helgrind --log-fd=1" +#valgrind="valgrind --tool=exp-ptrcheck --log-fd=1" #set -o xtrace #export RSYSLOG_DEBUG="debug nostdout printmutexaction" #export RSYSLOG_DEBUGLOG="log" diff --git a/tests/dynfile_invalid.sh b/tests/dynfile_invalid.sh index f61dc104..6c792db1 100755 --- a/tests/dynfile_invalid.sh +++ b/tests/dynfile_invalid.sh @@ -9,8 +9,8 @@ echo =========================================================================== echo TEST: \[dynfile_invalid.sh\]: test open fail for dynafiles source $srcdir/diag.sh init # uncomment for debugging support: -export RSYSLOG_DEBUG="debug nostdout noprintmutexaction" -export RSYSLOG_DEBUGLOG="log" +#export RSYSLOG_DEBUG="debug nostdout noprintmutexaction" +#export RSYSLOG_DEBUGLOG="log" source $srcdir/diag.sh startup dynfile_invalid.conf # we send handcrafted message. We have a dynafile cache of 4, and now send one message # each to fill up the cache. -- cgit From ea892d6cf041bd253d543570c1aac0ed171d2207 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Mon, 22 Mar 2010 15:53:45 +0100 Subject: cleanup: removed no longer needed variable Most importantly, this keeps the thread debugger output clean. --- tcps_sess.c | 3 --- 1 file changed, 3 deletions(-) diff --git a/tcps_sess.c b/tcps_sess.c index 8d307380..dec14b5a 100644 --- a/tcps_sess.c +++ b/tcps_sess.c @@ -59,8 +59,6 @@ DEFobjCurrIf(datetime) static int iMaxLine; /* maximum size of a single message */ -static int iNbrTimeUsed = 0; /* how often has previous time been used so far? */ - /* forward definitions */ static rsRetVal Close(tcps_sess_t *pThis); @@ -475,7 +473,6 @@ DataRcvd(tcps_sess_t *pThis, char *pData, size_t iLen) /* We now copy the message to the session buffer. */ pEnd = pData + iLen; /* this is one off, which is intensional */ - iNbrTimeUsed = 0; /* full time query */ while(pData < pEnd) { CHKiRet(processDataRcvd(pThis, *pData++, &stTime, ttGenTime, &multiSub)); } -- cgit From 2f1d5a12037453792eb1000c79daf737b41c5ba4 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Mon, 22 Mar 2010 15:59:33 +0100 Subject: valgrand accidently left enabled in diag.sh with the last commit --- tests/diag.sh | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/diag.sh b/tests/diag.sh index a4100ac0..27b60582 100755 --- a/tests/diag.sh +++ b/tests/diag.sh @@ -7,7 +7,7 @@ # This file is part of the rsyslog project, released under GPLv3 #valgrind="valgrind --log-fd=1" #valgrind="valgrind --tool=drd --log-fd=1" -valgrind="valgrind --tool=helgrind --log-fd=1" +#valgrind="valgrind --tool=helgrind --log-fd=1" #valgrind="valgrind --tool=exp-ptrcheck --log-fd=1" #set -o xtrace #export RSYSLOG_DEBUG="debug nostdout printmutexaction" -- cgit