diff options
68 files changed, 1302 insertions, 141 deletions
@@ -1,4 +1,49 @@ --------------------------------------------------------------------------- +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] +- 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 +- 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 + 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 + 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 +- 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 + 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 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.</td> <td>format as RFC 3164 date</td> </tr> <tr> +<tr> +<td valign="top"><b>date-rfc3164-buggyday</b></td> +<td>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 <i>not</i> to use this +option when forwarding to remote hosts - they may treat the date as invalid +(especially when parsing strictly according to RFC 3164).</td> +<br><i>This feature was introduced in rsyslog 4.6.2 and v4 versions above and +5.5.3 and all versions above.</i> +</tr> +<tr> <td><b>date-rfc3339</b></td> <td>format as RFC 3339 date</td> </tr> 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:</p> *.=crit /var/log/critmsgs</b></code></p> <p> </p> <h3>Regular File</h3> -<p>Typically messages are logged to real files. The file has to -be specified with full pathname, beginning with a slash "/''.<br> +<p>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).<br> <br> <br> You may prefix each entry with the minus "-'' sign to omit syncing the 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.</li> <li><b>$OMFileIOBufferSize</b> <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)</li> -<li><b>$OMFileFlushOnTXEnd</b> <[<b>on</b>/off]>, default on. Omfile has the +<li><b>$OMFileFlushOnTXEnd</b> <[on/<b>off</b>]>, 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 <b>each</b> log message) and the usual 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) { 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/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/debug.c b/runtime/debug.c index 20474a9a..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)) @@ -952,7 +952,7 @@ void dbgprintf(char *fmt, ...) { va_list ap; - char pszWriteBuf[1024]; + char pszWriteBuf[20480]; size_t lenWriteBuf; if(!(Debug && debugging_on)) @@ -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); } 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/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/runtime/stream.c b/runtime/stream.c index 36f44003..bfeecee5 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); @@ -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)); @@ -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: @@ -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 } @@ -306,27 +308,33 @@ 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 strmFlushInternal 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); + DBGOPRINT((obj_t*) pThis, "file %d(%s) closing\n", pThis->fd, + (pThis->pszFName == NULL) ? "N/A" : (char*)pThis->pszFName); - if(!pThis->bInClose && pThis->tOperationsMode != STREAMMODE_READ) { - pThis->bInClose = 1; + if(pThis->tOperationsMode != STREAMMODE_READ) { + strmFlushInternal(pThis); if(pThis->bAsyncWrite) { - strmFlush(pThis); - } else { strmWaitAsyncWriterDone(pThis); } - pThis->bInClose = 0; } - 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 */ @@ -441,7 +449,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 +481,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 +513,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 */ @@ -617,11 +625,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) { @@ -633,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; @@ -685,8 +696,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 +718,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); @@ -732,7 +742,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)); } @@ -790,6 +800,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) { @@ -811,7 +822,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; @@ -855,7 +866,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; @@ -880,13 +892,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; @@ -911,10 +932,11 @@ 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); +dbgprintf("XXX: asyncWriterThread iterating %s\n", pThis->pszFName); while(pThis->iCnt == 0) { if(pThis->bStopWriter) { pthread_cond_broadcast(&pThis->isEmpty); @@ -923,13 +945,14 @@ asyncWriterThread(void *pPtr) } 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 */ } 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) { int err = errno; if(err == ETIMEDOUT) { @@ -943,13 +966,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 @@ -1058,10 +1084,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) @@ -1120,12 +1142,14 @@ 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 flush, buflen %ld\n", pThis->fd, (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); @@ -1135,6 +1159,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 @@ -1148,9 +1197,9 @@ 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); + 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 */ @@ -1189,7 +1238,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; @@ -1233,6 +1282,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) @@ -1254,7 +1308,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) @@ -1269,7 +1323,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: @@ -1357,8 +1411,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; @@ -1429,7 +1482,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); 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/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)); } @@ -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")) { @@ -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..9e04ea1e 100644 --- a/tests/Makefile.am +++ b/tests/Makefile.am @@ -9,6 +9,19 @@ TESTS = $(TESTRUNS) cfg.sh \ manytcp.sh \ sndrcv.sh \ sndrcv_gzip.sh \ + asynwr_simple.sh \ + asynwr_timeout.sh \ + asynwr_small.sh \ + asynwr_tinybuf.sh \ + asynwr_large.sh \ + asynwr_deadlock.sh \ + asynwr_deadlock2.sh \ + asynwr_deadlock4.sh \ + gzipwr_large.sh \ + gzipwr_large_dynfile.sh \ + dynfile_invalid.sh \ + dynfile_invalid2.sh \ + complex1.sh \ queue-persist.sh \ pipeaction.sh execonlyonce.sh \ @@ -39,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 \ @@ -78,6 +91,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 \ @@ -92,8 +106,16 @@ 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 \ + 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 \ @@ -133,6 +155,32 @@ 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 \ + asynwr_large.sh \ + testsuites/asynwr_large.conf \ + asynwr_deadlock.sh \ + 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 \ + 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/asynwr_deadlock.sh b/tests/asynwr_deadlock.sh new file mode 100755 index 00000000..dc08355e --- /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/asynwr_deadlock2.sh b/tests/asynwr_deadlock2.sh new file mode 100755 index 00000000..1190f67a --- /dev/null +++ b/tests/asynwr_deadlock2.sh @@ -0,0 +1,69 @@ +# 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 expired +# 4. *then* (and only then) the stream is closed or destructed +# 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 +# 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 +# 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 +source $srcdir/diag.sh seq-check 1 20000 -E +source $srcdir/diag.sh exit diff --git a/tests/asynwr_deadlock4.sh b/tests/asynwr_deadlock4.sh new file mode 100755 index 00000000..a3452f5b --- /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/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 new file mode 100755 index 00000000..eb87443c --- /dev/null +++ b/tests/asynwr_simple.sh @@ -0,0 +1,18 @@ +# 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 =============================================================================== +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 -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 new file mode 100755 index 00000000..97818f6e --- /dev/null +++ b/tests/asynwr_small.sh @@ -0,0 +1,26 @@ +# 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 =============================================================================== +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 -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 new file mode 100755 index 00000000..b0bc5c28 --- /dev/null +++ b/tests/asynwr_timeout.sh @@ -0,0 +1,21 @@ +# 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 =============================================================================== +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 -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/asynwr_tinybuf.sh b/tests/asynwr_tinybuf.sh new file mode 100755 index 00000000..8eae1e26 --- /dev/null +++ b/tests/asynwr_tinybuf.sh @@ -0,0 +1,19 @@ +# 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 =============================================================================== +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 -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/chkseq.c b/tests/chkseq.c index 6334d787..b22c8992 100644 --- a/tests/chkseq.c +++ b/tests/chkseq.c @@ -32,6 +32,7 @@ #include "config.h" #include <stdio.h> #include <stdlib.h> +#include <string.h> #include <getopt.h> 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); } @@ -116,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..27b60582 100755 --- a/tests/diag.sh +++ b/tests/diag.sh @@ -8,6 +8,7 @@ #valgrind="valgrind --log-fd=1" #valgrind="valgrind --tool=drd --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" @@ -18,6 +19,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 +27,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 +37,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. @@ -62,7 +67,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 @@ -85,6 +90,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 +111,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/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 8233d569..7a50d82e 100755 --- a/tests/diskqueue.sh +++ b/tests/diskqueue.sh @@ -6,11 +6,14 @@ # 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 ;) 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/dynfile_invalid.sh b/tests/dynfile_invalid.sh new file mode 100755 index 00000000..6c792db1 --- /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/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/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/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/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/longrun.sh b/tests/longrun.sh new file mode 100755 index 00000000..407e9fa9 --- /dev/null +++ b/tests/longrun.sh @@ -0,0 +1,30 @@ +# 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 +# +# 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++ )) + do + if [ $(( i % DISPLAYALIVE )) -eq 0 ]; then + echo "$i iterations done" + fi + $1 >> $LOGFILE + if [ "$?" -ne "0" ]; then + echo "Test failed in iteration $i, review $LOGFILE for details!" + exit 1 + fi + done +echo "No failure in $i iterations." diff --git a/tests/manytcp.sh b/tests/manytcp.sh index c55eb9c0..94a5c035 100755 --- a/tests/manytcp.sh +++ b/tests/manytcp.sh @@ -2,7 +2,10 @@ 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 +# 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 source $srcdir/diag.sh exit diff --git a/tests/nettester.c b/tests/nettester.c index 209c2a6f..e1ecbcb5 100644 --- a/tests/nettester.c +++ b/tests/nettester.c @@ -47,6 +47,7 @@ #include <signal.h> #include <netinet/in.h> #include <getopt.h> +#include <ctype.h> #define EXIT_FAILURE 1 #define INVALID_SOCKET -1 @@ -61,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; @@ -217,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); @@ -243,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; @@ -254,6 +254,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 +347,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 +371,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); @@ -399,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; @@ -424,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 5966a11b..fc68ab84 100755 --- a/tests/parsertest.sh +++ b/tests/parsertest.sh @@ -6,6 +6,14 @@ 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 +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 @@ -14,4 +22,12 @@ 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 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/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..32bf959d 100644 --- a/tests/tcpflood.c +++ b/tests/tcpflood.c @@ -2,15 +2,28 @@ * 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) + * -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) + * -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) + * -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. * @@ -47,12 +60,21 @@ /* 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; +#define MAX_EXTRADATA_LEN 100*1024 + +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 */ 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 */ +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 @@ -61,16 +83,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); @@ -103,11 +134,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); } @@ -136,11 +169,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]); } @@ -164,12 +200,14 @@ int sendMessages(void) int socknum; int lenBuf; int lenSend; - char buf[2048]; - - srand(time(NULL)); /* seed is good enough for our needs */ + int edLen; /* actual extra data length to use */ + char dynFileIDBuf[128] = ""; + char buf[MAX_EXTRADATA_LEN + 1024]; + char extraData[MAX_EXTRADATA_LEN + 1]; printf("Sending %d messages.\n", numMsgsToSend); - printf("\r%5.5d messages sent", 0); + if(bShowProgress) + printf("\r%8.8d messages sent", 0); for(i = 0 ; i < numMsgsToSend ; ++i) { if(i < numConnections) socknum = i; @@ -177,7 +215,27 @@ 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(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 { + /* use fixed message format from command line */ + lenBuf = sprintf(buf, "%s\n", MsgToSend); + } lenSend = send(sockArray[socknum], buf, lenBuf, 0); if(lenSend != lenBuf) { printf("\r%5.5d\n", i); @@ -188,11 +246,12 @@ int sendMessages(void) return(1); } if(i % 100 == 0) { - printf("\r%5.5d", i); + if(bShowProgress) + printf("\r%8.8d", i); } ++msgNum; } - printf("\r%5.5d messages sent\n", i); + printf("\r%8.8d messages sent\n", i); return 0; } @@ -251,17 +310,18 @@ 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[]) { int ret = 0; + int opt; 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) */ @@ -271,19 +331,44 @@ int main(int argc, char *argv[]) sigaction(SIGPIPE, &sigAct, NULL); 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); - } - targetIP = argv[1]; - targetPort = atoi(argv[2]); - numConnections = atoi(argv[3]); - numMsgsToSend = atoi(argv[4]); - if(argc == 6) - msgNum = atoi(argv[5]); + if(!isatty(1)) + bShowProgress = 0; + + while((opt = getopt(argc, argv, "f:t:p:c:m:i:P:d:n:M: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); + 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; + case 'f': dynFileIDs = atoi(optarg); + break; + case 'M': MsgToSend = optarg; + break; + default: printf("invalid option '%c' or value missing - terminating...\n", opt); + exit (1); + break; + } + } if(openConnections() != 0) { printf("error opening connections\n"); @@ -295,7 +380,6 @@ int main(int argc, char *argv[]) exit(1); } - //closeConnections(); printf("End of tcpflood Run\n"); exit(ret); diff --git a/tests/testsuites/asynwr_deadlock.conf b/tests/testsuites/asynwr_deadlock.conf new file mode 100644 index 00000000..d703791a --- /dev/null +++ b/tests/testsuites/asynwr_deadlock.conf @@ -0,0 +1,13 @@ +# rgerhards, 2010-03-09 +$IncludeConfig diag-common.conf + +$ModLoad ../plugins/imtcp/.libs/imtcp +$MainMsgQueueTimeoutShutdown 10000 +$InputTCPServerRun 13514 + +$template outfmt,"%msg:F,58:2%\n" + +$OMFileFlushOnTXEnd on +$OMFileFlushInterval 10 +$OMFileFlushIOBufferSize 10k +:msg, contains, "msgnum:" ./rsyslog.out.log;outfmt 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 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 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/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 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/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 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 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..3a1b255a --- /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" # use multiple dynafiles +$OMFileFlushOnTXEnd off +$OMFileZipLevel 6 +$OMFileIOBufferSize 256k +$DynaFileCacheSize 4 +$omfileFlushInterval 1 +local0.* ?dynfile;outfmt 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/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-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) 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! 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.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 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 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/omfile.c b/tools/omfile.c index eb56201c..0f27f1e9 100644 --- a/tools/omfile.c +++ b/tools/omfile.c @@ -48,6 +48,7 @@ #include <libgen.h> #include <unistd.h> #include <sys/file.h> +#include <pthread.h> #ifdef OS_SOLARIS # include <fcntl.h> @@ -65,6 +66,7 @@ #include "stream.h" #include "unicode-helper.h" #include "atomic.h" +#include "debug.h" MODULE_TYPE_OUTPUT @@ -79,7 +81,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; @@ -99,7 +101,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 */ @@ -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; @@ -532,7 +535,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); @@ -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,6 +626,7 @@ 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) { @@ -628,12 +634,13 @@ CODESTARTdoAction CHKiRet(strm.Flush(pData->pStrm)); } finalize_it: + d_pthread_mutex_unlock(&pData->mutEx); 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 +690,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 @@ -749,7 +757,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) { @@ -763,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 { @@ -771,6 +780,7 @@ CODESTARTdoHUP pData->pStrm = NULL; } } + d_pthread_mutex_unlock(&pData->mutEx); ENDdoHUP 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); } 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. |