From dd546f82a51bf2e71a97383fce88fffaa3b2a611 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Tue, 24 Mar 2015 11:35:20 +0100 Subject: [PATCH] imfile: proper handling of multiline messages after rsyslog restart handling of persisted info (and polling loops) was not correct. This needs some cleanup but I hope to find some folks for independent testing before I declare victory. see also https://github.com/rsyslog/rsyslog/issues/144 --- runtime/stream.c | 14 ++-- tests/Makefile.am | 11 +++- tests/imfile-readmode2-with-persists.sh | 65 +++++++++++++++++++ .../imfile-readmode2-with-persists.conf | 21 ++++++ 4 files changed, 105 insertions(+), 6 deletions(-) create mode 100755 tests/imfile-readmode2-with-persists.sh create mode 100644 tests/testsuites/imfile-readmode2-with-persists.conf diff --git a/runtime/stream.c b/runtime/stream.c index 162400fee..33bfd31d7 100644 --- a/runtime/stream.c +++ b/runtime/stream.c @@ -636,7 +636,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 %zd, max %zd\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 */ @@ -699,10 +699,11 @@ strmReadLine(strm_t *pThis, cstr_t **ppCStr, uint8_t mode, sbool bEscapeLF) ASSERT(pThis != NULL); ASSERT(ppCStr != NULL); +dbgprintf("DDDDD: readLine: enter, bPrevWasNL %d\n", pThis->bPrevWasNL); CHKiRet(cstrConstruct(ppCStr)); CHKiRet(strmReadChar(pThis, &c)); -dbgprintf("DDDDD: readLine: enter, bPrevWasNL %d\n", pThis->bPrevWasNL); +dbgprintf("DDDDD: readLine: pre-check, bPrevWasNL %d\n", pThis->bPrevWasNL); /* append previous message to current message if necessary */ if(pThis->prevLineSegment != NULL) { dbgprintf("DDDDD: readLine: have previous line segment: '%s'\n", rsCStrGetSzStr(pThis->prevLineSegment)); @@ -795,8 +796,10 @@ dbgprintf("DDDDD: readLine: enter, bPrevWasNL %d\n", pThis->bPrevWasNL); finalize_it: dbgprintf("DDDDD: readLine returns[%d]: '%s' [*ppCStr %p]\n", iRet, (char*)rsCStrGetSzStr(*ppCStr), *ppCStr); if(iRet != RS_RET_OK && *ppCStr != NULL) { - dbgprintf("DDDDD: readLine saves segment '%s'\n", rsCStrGetSzStr(*ppCStr)); - rsCStrConstructFromCStr(&pThis->prevLineSegment, *ppCStr); + if(cstrLen(*ppCStr) > 0) { /* we may have an empty string in an unsuccsfull poll or after restart! */ + dbgprintf("DDDDD: readLine saves segment '%s'\n", rsCStrGetSzStr(*ppCStr)); + rsCStrConstructFromCStr(&pThis->prevLineSegment, *ppCStr); + } cstrDestruct(ppCStr); } @@ -1859,7 +1862,8 @@ static rsRetVal strmSerialize(strm_t *pThis, strm_t *pStrm) l = pThis->inode; objSerializeSCALAR_VAR(pStrm, inode, INT64, l); - objSerializePTR(pStrm, prevLineSegment, PSZ); + cstrFinalize(pThis->prevLineSegment); + objSerializePTR(pStrm, prevLineSegment, CSTR); i = pThis->bPrevWasNL; objSerializeSCALAR_VAR(pStrm, bPrevWasNL, INT, i); diff --git a/tests/Makefile.am b/tests/Makefile.am index f480a7eef..98d19d9ba 100644 --- a/tests/Makefile.am +++ b/tests/Makefile.am @@ -261,7 +261,10 @@ if ENABLE_EXTENDED_TESTS endif if ENABLE_IMFILE -TESTS += imfile-basic.sh +TESTS += imfile-basic.sh \ + imfile-readmode2.sh \ + imfile-readmode2-with-persists-data-during-stop.sh \ + imfile-readmode2-with-persists.sh \ if HAVE_VALGRIND TESTS += imfile-basic-vg.sh endif @@ -634,6 +637,12 @@ EXTRA_DIST= 1.rstest 2.rstest 3.rstest err1.rstest \ testsuites/complex1.conf \ random.sh \ testsuites/random.conf \ + imfile-readmode2.sh \ + imfile-readmode2-with-persists-data-during-stop.sh \ + imfile-readmode2-with-persists.sh \ + testsuites/imfile-readmode2.conf \ + testsuites/imfile-readmode2-with-persists.conf \ + testsuites/imfile-readmode2-with-persists-data-during-stop.conf \ imfile-basic.sh \ imfile-basic-vg.sh \ testsuites/imfile-basic.conf \ diff --git a/tests/imfile-readmode2-with-persists.sh b/tests/imfile-readmode2-with-persists.sh new file mode 100755 index 000000000..306348489 --- /dev/null +++ b/tests/imfile-readmode2-with-persists.sh @@ -0,0 +1,65 @@ +# This is part of the rsyslog testbench, licensed under ASL 2.0 +echo ====================================================================== +echo [imfile-readmode2-with-persists.sh] +source $srcdir/diag.sh init +source $srcdir/diag.sh startup imfile-readmode2-with-persists.conf + +# write the beginning of the file +echo 'msgnum:0 + msgnum:1' > rsyslog.input +echo 'msgnum:2' >> rsyslog.input + +# sleep a little to give rsyslog a chance to begin processing +sleep 1 + +# now stop and restart rsyslog so that the file info must be +# persisted and read again on startup. Results should still be +# correct ;) +echo stopping rsyslog +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! +echo restarting rsyslog +source $srcdir/diag.sh startup imfile-readmode2-with-persists.conf +echo restarted rsyslog, continuing with test + +# write some more lines (see https://github.com/rsyslog/rsyslog/issues/144) +echo 'msgnum:3 + msgnum:4' >> rsyslog.input +echo 'msgnum:5' >> rsyslog.input # this one shouldn't be written to the output file because of ReadMode 2 + +# give it time to finish +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! + +# give it time to write the output file +sleep 1 + +## check if we have the correct number of messages + +NUMLINES=$(grep -c HEADER $srcdir/rsyslog.out.log 2>/dev/null) + +if [ -z $NUMLINES ]; then + echo "ERROR: expecting at least a match for HEADER, maybe rsyslog.out.log wasn't even written?" + exit 1 +else + if [ ! $NUMLINES -eq 3 ]; then + echo "ERROR: expecting 3 headers, got $NUMLINES" + exit 1 + fi +fi + +## check if all the data we expect to get in the file is there + +for i in {1..4}; do + grep msgnum:$i $srcdir/rsyslog.out.log > /dev/null 2>&1 + if [ ! $? -eq 0 ]; then + echo "ERROR: expecting the string 'msgnum:$i', it's not there" + exit 1 + fi +done + +## if we got here, all is good :) + +source $srcdir/diag.sh exit diff --git a/tests/testsuites/imfile-readmode2-with-persists.conf b/tests/testsuites/imfile-readmode2-with-persists.conf new file mode 100644 index 000000000..5d4464193 --- /dev/null +++ b/tests/testsuites/imfile-readmode2-with-persists.conf @@ -0,0 +1,21 @@ +$IncludeConfig diag-common.conf +global(workDirectory="test-spool") +module(load="../plugins/imfile/.libs/imfile") + +input(type="imfile" + File="./rsyslog.input" + Tag="file:" + ReadMode="2") + +template(name="outfmt" type="list") { + constant(value="HEADER ") + property(name="msg" format="json") + constant(value="\n") +} + +if $msg contains "msgnum:" then + action( + type="omfile" + file="rsyslog.out.log" + template="outfmt" + )