File 0002-bugfix-imfile-file-change-was-not-reliably... of Package rsyslog

Overview Repositories Revisions Requests Users Attributes Meta

File 0002-bugfix-imfile-file-change-was-not-reliably-detected.patch of Package rsyslog (Revision a17f9939821148b9fdcf940638ccbf64)

Currently displaying revision a17f9939821148b9fdcf940638ccbf64 , Show latest

From 158edac32e36e17625833a74e0c7746585a8c543 Mon Sep 17 00:00:00 2001
From: Rainer Gerhards <rgerhards@adiscon.com>
Date: Sun, 23 Sep 2018 13:19:31 +0200
Subject: [PATCH 2/7] bugfix imfile: file change was not reliably detected

A change in the inode was not detected under all circumstances,
most importantly not in some logrotate cases.

Includes new tests made by Andre Lorbach. They now use the
logrotate tool natively to reproduce the issue.

(cherry picked from commit f85ef7aabcec84497a5eaf9670616b3402c79d9c)
---
 plugins/imfile/imfile.c                       |  27 ++++--
 runtime/stream.c                              | 120 ++++++++++++++++++++++----
 runtime/stream.h                              |   9 ++
 tests/Makefile.am                             |  17 +++-
 tests/imfile-logrotate.sh                     |  78 +++++++++++++++++
 tests/imfile-wildcards-dirs-multi5-polling.sh |  28 +++---
 6 files changed, 238 insertions(+), 41 deletions(-)
 create mode 100755 tests/imfile-logrotate.sh

diff --git a/plugins/imfile/imfile.c b/plugins/imfile/imfile.c
index a5d20823f..a13687df8 100644
--- a/plugins/imfile/imfile.c
+++ b/plugins/imfile/imfile.c
@@ -621,13 +621,22 @@ detect_updates(fs_edge_t *const edge)
 		const int r = stat(act->name, &fileInfo);
 		if(r == -1) { /* object gone away? */
 			DBGPRINTF("object gone away, unlinking: '%s'\n", act->name);
-			act_obj_t *toDel = act;
-			act = act->next;
-			DBGPRINTF("new next act %p\n", act);
-			act_obj_unlink(toDel);
-			continue;
+			act_obj_unlink(act);
+			restart = 1;
+			break;
+		} else if(fileInfo.st_ino != act->ino) {
+			DBGPRINTF("file '%s' inode changed from %llu to %llu, unlinking from "
+				"internal lists\n", act->name, (long long unsigned) act->ino,
+				(long long unsigned) fileInfo.st_ino);
+			if(act->pStrm != NULL) {
+				/* we do no need to re-set later, as act_obj_unlink
+				 * will destroy the strm obj */
+				strmSet_checkRotation(act->pStrm, STRM_ROTATION_DO_NOT_CHECK);
+			}
+			act_obj_unlink(act);
+			restart = 1;
+			break;
 		}
-		// TODO: add inode check for change notification!
 
 		/* Note: active nodes may get deleted, so we need to do the
 		 * pointer advancement at the end of the for loop!
@@ -816,10 +825,10 @@ chk_active(const act_obj_t *act, const act_obj_t *const deleted)
 /* unlink act object from linked list and then
  * destruct it.
  */
-static void //ATTR_NONNULL()
-act_obj_unlink(act_obj_t *const act)
+static void ATTR_NONNULL()
+act_obj_unlink(act_obj_t *act)
 {
-	DBGPRINTF("act_obj_unlink %p: %s\n", act, act->name);
+	DBGPRINTF("act_obj_unlink %p: %s, pStrm %p\n", act, act->name, act->pStrm);
 	if(act->prev == NULL) {
 		act->edge->active = act->next;
 	} else {
diff --git a/runtime/stream.c b/runtime/stream.c
index 7286e819e..028a4652c 100644
--- a/runtime/stream.c
+++ b/runtime/stream.c
@@ -325,8 +325,8 @@ CheckFileChange(strm_t *pThis)
 	CHKiRet(strmSetCurrFName(pThis));
 	if(stat((char*) pThis->pszCurrFName, &statName) == -1)
 		ABORT_FINALIZE(RS_RET_IO_ERROR);
-	DBGPRINTF("stream/after deserialize checking for file change on '%s', "
-		"inode %u/%u, size/currOffs %llu/%llu\n",
+	DBGPRINTF("CheckFileChange: stream/after deserialize checking for file change "
+		"on '%s', inode %u/%u, size/currOffs %llu/%llu\n",
 		pThis->pszCurrFName, (unsigned) pThis->inode,
 		(unsigned) statName.st_ino,
 		(long long unsigned) statName.st_size,
@@ -536,8 +536,8 @@ finalize_it:
  * circumstances). So starting as of now, we only check the inode number and
  * a file change is detected only if the inode changes. -- rgerhards, 2011-01-10
  */
-static rsRetVal
-strmHandleEOFMonitor(strm_t *pThis)
+static rsRetVal ATTR_NONNULL()
+strmHandleEOFMonitor(strm_t *const pThis)
 {
 	DEFiRet;
 	struct stat statName;
@@ -545,9 +545,9 @@ strmHandleEOFMonitor(strm_t *pThis)
 	ISOBJ_TYPE_assert(pThis, strm);
 	if(stat((char*) pThis->pszCurrFName, &statName) == -1)
 		ABORT_FINALIZE(RS_RET_IO_ERROR);
-	DBGPRINTF("stream checking for file change on '%s', inode %u/%u\n",
-	  pThis->pszCurrFName, (unsigned) pThis->inode,
-	  (unsigned) statName.st_ino);
+	DBGPRINTF("strmHandleEOFMonitor: stream checking for file change on '%s', inode %u/%u size %llu/%llu\n",
+		pThis->pszCurrFName, (unsigned) pThis->inode, (unsigned) statName.st_ino,
+		(long long unsigned) pThis->iCurrOffs, (long long unsigned) statName.st_size);
 
 	/* Inode unchanged but file size on disk is less than current offset
 	 * means file was truncated, we also reopen if 'reopenOnTruncate' is on
@@ -573,8 +573,8 @@ finalize_it:
  * try to open the next one.
  * rgerhards, 2008-02-13
  */
-static rsRetVal
-strmHandleEOF(strm_t *pThis)
+static rsRetVal ATTR_NONNULL()
+strmHandleEOF(strm_t *const pThis)
 {
 	DEFiRet;
 
@@ -591,7 +591,13 @@ strmHandleEOF(strm_t *pThis)
 			CHKiRet(strmNextFile(pThis));
 			break;
 		case STREAMTYPE_FILE_MONITOR:
-			CHKiRet(strmHandleEOFMonitor(pThis));
+			DBGOPRINT((obj_t*) pThis, "file '%s' (%d) EOF, rotationCheck %d\n",
+				pThis->pszCurrFName, pThis->fd, pThis->rotationCheck);
+			if(pThis->rotationCheck == STRM_ROTATION_DO_CHECK) {
+				CHKiRet(strmHandleEOFMonitor(pThis));
+			} else {
+				ABORT_FINALIZE(RS_RET_EOF);
+			}
 			break;
 	}
 
@@ -599,6 +605,75 @@ finalize_it:
 	RETiRet;
 }
 
+
+/* helper to checkTruncation */
+static rsRetVal ATTR_NONNULL()
+rereadTruncated(strm_t *const pThis, const char *const reason)
+{
+	DEFiRet;
+
+	LogMsg(errno, RS_RET_FILE_TRUNCATED, LOG_WARNING, "file '%s': truncation detected, "
+		"(%s) - re-start reading from beginning",
+		pThis->pszCurrFName, reason);
+	DBGPRINTF("checkTruncation, file %s last buffer CHANGED\n", pThis->pszCurrFName);
+	CHKiRet(strmCloseFile(pThis));
+	CHKiRet(strmOpenFile(pThis));
+	iRet = RS_RET_FILE_TRUNCATED;
+
+finalize_it:
+	RETiRet;
+}
+/* helper to read:
+ * Check if file has been truncated since last read and, if so, re-set reading
+ * to begin of file. To detect truncation, we try to re-read the last block.
+ * If that does not succeed or different data than from the original read is
+ * returned, truncation is assumed.
+ * NOTE: this function must be called only if truncation is enabled AND
+ * when the previous read buffer still is valid (aka "before the next read").
+ * It is ok to call with a 0-size buffer, which we than assume as begin of
+ * reading. In that case, no truncation will be detected.
+ * rgerhards, 2018-09-20
+ */
+static rsRetVal ATTR_NONNULL()
+checkTruncation(strm_t *const pThis)
+{
+	DEFiRet;
+	int ret;
+	off64_t backseek;
+	assert(pThis->bReopenOnTruncate);
+
+	DBGPRINTF("checkTruncation, file %s, iBufPtrMax %zd\n", pThis->pszCurrFName, pThis->iBufPtrMax);
+	if(pThis->iBufPtrMax == 0) {
+		FINALIZE;
+	}
+
+	int currpos = lseek64(pThis->fd, 0, SEEK_CUR);
+	backseek = -1 * (off64_t) pThis->iBufPtrMax;
+	dbgprintf("checkTruncation in actual processing, currpos %d, backseek is %d\n", (int)currpos, (int) backseek);
+	ret = lseek64(pThis->fd, backseek, SEEK_CUR);
+	if(ret < 0) {
+		iRet = rereadTruncated(pThis, "cannot seek backward to begin of last block");
+		FINALIZE;
+	}
+
+	const ssize_t lenRead = read(pThis->fd, pThis->pIOBuf_truncation, pThis->iBufPtrMax);
+	dbgprintf("checkTruncation proof-read: %d bytes\n", (int) lenRead);
+	if(lenRead < 0) {
+		iRet = rereadTruncated(pThis, "last block could not be re-read");
+		FINALIZE;
+	}
+
+	if(!memcmp(pThis->pIOBuf_truncation, pThis->pIOBuf, pThis->iBufPtrMax)) {
+		DBGPRINTF("checkTruncation, file %s last buffer unchanged\n", pThis->pszCurrFName);
+	} else {
+		iRet = rereadTruncated(pThis, "last block data different");
+	}
+
+finalize_it:
+	RETiRet;
+}
+
+
 /* read the next buffer from disk
  * rgerhards, 2008-02-13
  */
@@ -744,7 +819,7 @@ static rsRetVal strmUnreadChar(strm_t *pThis, uchar c)
  * a line, but following lines that are indented are part of the same log entry
  */
 static rsRetVal
-strmReadLine(strm_t *pThis, cstr_t **ppCStr, uint8_t mode, sbool bEscapeLF,
+strmReadLine(strm_t *const pThis, cstr_t **ppCStr, uint8_t mode, sbool bEscapeLF,
 	uint32_t trimLineOverBytes, int64 *const strtOffs)
 {
         uchar c;
@@ -2018,14 +2093,25 @@ DEFpropSetMeth(strm, cryprov, cryprov_if_t*)
 DEFpropSetMeth(strm, cryprovData, void*)
 
 /* sets timeout in seconds */
-void
+void ATTR_NONNULL()
 strmSetReadTimeout(strm_t *const __restrict__ pThis, const int val)
 {
+	ISOBJ_TYPE_assert(pThis, strm);
 	pThis->readTimeout = val;
 }
 
-static rsRetVal strmSetbDeleteOnClose(strm_t *pThis, int val)
+void ATTR_NONNULL()
+strmSet_checkRotation(strm_t *const pThis, const int val) {
+	ISOBJ_TYPE_assert(pThis, strm);
+	assert(val == STRM_ROTATION_DO_CHECK || val == STRM_ROTATION_DO_NOT_CHECK);
+	pThis->rotationCheck = val;
+}
+
+
+static rsRetVal ATTR_NONNULL()
+strmSetbDeleteOnClose(strm_t *const pThis, const int val)
 {
+	ISOBJ_TYPE_assert(pThis, strm);
 	pThis->bDeleteOnClose = val;
 	if(pThis->cryprov != NULL) {
 		pThis->cryprov->SetDeleteOnClose(pThis->cryprovFileData, pThis->bDeleteOnClose);
@@ -2033,15 +2119,19 @@ static rsRetVal strmSetbDeleteOnClose(strm_t *pThis, int val)
 	return RS_RET_OK;
 }
 
-static rsRetVal strmSetiMaxFiles(strm_t *pThis, int iNewVal)
+static rsRetVal ATTR_NONNULL()
+strmSetiMaxFiles(strm_t *const pThis, const int iNewVal)
 {
+	ISOBJ_TYPE_assert(pThis, strm);
 	pThis->iMaxFiles = iNewVal;
 	pThis->iFileNumDigits = getNumberDigits(iNewVal);
 	return RS_RET_OK;
 }
 
-static rsRetVal strmSetFileNotFoundError(strm_t *pThis, int pFileNotFoundError)
+static rsRetVal ATTR_NONNULL()
+strmSetFileNotFoundError(strm_t *const pThis, const int pFileNotFoundError)
 {
+	ISOBJ_TYPE_assert(pThis, strm);
 	pThis->fileNotFoundError = pFileNotFoundError;
 	return RS_RET_OK;
 }
diff --git a/runtime/stream.h b/runtime/stream.h
index bafa5fbd3..57d8c68b0 100644
--- a/runtime/stream.h
+++ b/runtime/stream.h
@@ -91,6 +91,10 @@ typedef enum {				/* when extending, do NOT change existing modes! */
 	STREAMMODE_WRITE_APPEND = 4
 } strmMode_t;
 
+/* settings for stream rotation (applies not to all processing modes!) */
+#define	STRM_ROTATION_DO_CHECK		0
+#define	STRM_ROTATION_DO_NOT_CHECK	1
+
 #define STREAM_ASYNC_NUMBUFS 2 /* must be a power of 2 -- TODO: make configurable */
 /* The strm_t data structure */
 typedef struct strm_s {
@@ -114,6 +118,7 @@ typedef struct strm_s {
 	sbool bDisabled; /* should file no longer be written to? (currently set only if omfile file size limit fails) */
 	sbool bSync;	/* sync this file after every write? */
 	sbool bReopenOnTruncate;
+	int rotationCheck; /* rotation check mode */
 	size_t sIOBufSize;/* size of IO buffer */
 	uchar *pszDir; /* Directory */
 	int lenDir;
@@ -230,5 +235,9 @@ rsRetVal strmReadMultiLine(strm_t *pThis, cstr_t **ppCStr, regex_t *preg,
 int strmReadMultiLine_isTimedOut(const strm_t *const __restrict__ pThis);
 void strmDebugOutBuf(const strm_t *const pThis);
 void strmSetReadTimeout(strm_t *const __restrict__ pThis, const int val);
+const uchar * ATTR_NONNULL() strmGetPrevLineSegment(strm_t *const pThis);
+const uchar * ATTR_NONNULL() strmGetPrevMsgSegment(strm_t *const pThis);
+int ATTR_NONNULL() strmGetPrevWasNL(const strm_t *const pThis);
+void ATTR_NONNULL() strmSet_checkRotation(strm_t *const pThis, const int val);
 
 #endif /* #ifndef STREAM_H_INCLUDED */
diff --git a/tests/Makefile.am b/tests/Makefile.am
index 2283066ac..4386c626d 100644
--- a/tests/Makefile.am
+++ b/tests/Makefile.am
@@ -784,7 +784,17 @@ TESTS += \
 	imfile-wildcards-dirs-multi5.sh \
 	imfile-wildcards-dirs-multi5-polling.sh \
 	imfile-rename-while-stopped.sh \
-	imfile-rename.sh
+	imfile-rename.sh \
+	imfile-symlink.sh \
+	imfile-symlink-multi.sh \
+	imfile-logrotate.sh \
+	imfile-growing-file-id.sh \
+	glbl-oversizeMsg-truncate-imfile.sh
+
+if ENABLE_MMNORMALIZE
+TESTS += \
+	imfile-endmsg.regex-with-example.sh
+endif
 
 if HAVE_VALGRIND
 TESTS += \
@@ -1485,6 +1495,11 @@ EXTRA_DIST= \
 	testsuites/imfile-wildcards-dirs-multi2.conf \
 	testsuites/imfile-wildcards-dirs-multi3.conf \
 	testsuites/imfile-wildcards-dirs-multi4.conf \
+	imfile-symlink.sh \
+	imfile-symlink-multi.sh \
+	imfile-logrotate.sh \
+	imfile-growing-file-id.sh \
+	glbl-oversizeMsg-truncate-imfile.sh \
 	dynfile_invld_async.sh \
 	dynfile_invld_sync.sh \
 	dynfile_cachemiss.sh \
diff --git a/tests/imfile-logrotate.sh b/tests/imfile-logrotate.sh
new file mode 100755
index 000000000..9e5476105
--- /dev/null
+++ b/tests/imfile-logrotate.sh
@@ -0,0 +1,78 @@
+#!/bin/bash
+# This is part of the rsyslog testbench, licensed under ASL 2.0
+. $srcdir/diag.sh check-inotify-only
+. $srcdir/diag.sh init
+check_command_available logrotate
+
+export TESTMESSAGES=10000
+export RETRIES=50
+export TESTMESSAGESFULL=19999
+
+generate_conf
+add_conf '
+$WorkDirectory '$RSYSLOG_DYNNAME'.spool
+
+/* Filter out busy debug output */
+global(
+	debug.whitelist="off"
+	debug.files=["rainerscript.c", "ratelimit.c", "ruleset.c", "main Q", "msg.c", "../action.c"]
+	)
+
+module(	load="../plugins/imfile/.libs/imfile"
+	mode="inotify"
+	PollingInterval="1")
+
+input(type="imfile"
+	File="./'$RSYSLOG_DYNNAME'.input.*.log"
+	Tag="file:"
+	Severity="error"
+	Facility="local7"
+	addMetadata="on"
+)
+
+$template outfmt,"%msg:F,58:2%\n"
+if $msg contains "msgnum:" then
+ action(
+   type="omfile"
+   file=`echo $RSYSLOG_OUT_LOG`
+   template="outfmt"
+ )
+'
+
+# Write logrotate config file
+echo '"./'$RSYSLOG_DYNNAME'.input.*.log"
+{
+	rotate 7
+	create
+	daily
+	missingok
+	notifempty
+	compress
+}' > $RSYSLOG_DYNNAME.logrotate
+
+# generate input file first.
+./inputfilegen -m $TESTMESSAGES > $RSYSLOG_DYNNAME.input.1.log
+ls -l $RSYSLOG_DYNNAME.input*
+
+startup
+
+# Wait until testmessages are processed by imfile!
+. $srcdir/diag.sh wait-file-lines  $RSYSLOG_OUT_LOG $TESTMESSAGES $RETRIES
+
+# Logrotate on logfile
+logrotate -f $RSYSLOG_DYNNAME.logrotate
+./msleep 1000
+
+# generate more input after logrotate into new logfile
+./inputfilegen -m $TESTMESSAGES -i $TESTMESSAGES >> $RSYSLOG_DYNNAME.input.1.log
+ls -l $RSYSLOG_DYNNAME.input*
+echo ls ${RSYSLOG_DYNNAME}.spool:
+ls -l ${RSYSLOG_DYNNAME}.spool
+
+let msgcount="2* $TESTMESSAGES"
+. $srcdir/diag.sh wait-file-lines  $RSYSLOG_OUT_LOG $msgcount $RETRIES
+
+shutdown_when_empty # shut down rsyslogd when done processing messages
+wait_shutdown	# we need to wait until rsyslogd is finished!
+seq_check 0 $TESTMESSAGESFULL
+exit_test
diff --git a/tests/imfile-wildcards-dirs-multi5-polling.sh b/tests/imfile-wildcards-dirs-multi5-polling.sh
index 0689bd087..7d8fda5a9 100755
--- a/tests/imfile-wildcards-dirs-multi5-polling.sh
+++ b/tests/imfile-wildcards-dirs-multi5-polling.sh
@@ -1,11 +1,9 @@
 #!/bin/bash
-# This is part of the rsyslog testbench, licensed under GPLv3
-export IMFILEINPUTFILES="8" #"8"
-export IMFILEINPUTFILESSTEPS="5" #"5"
-#export IMFILEINPUTFILESALL=$(($IMFILEINPUTFILES * $IMFILEINPUTFILESSTEPS))
-export IMFILECHECKTIMEOUT="5"
+# This is part of the rsyslog testbench, licensed under ASL 2.0
 . $srcdir/diag.sh init
-#. $srcdir/diag.sh check-inotify-only
+export IMFILEINPUTFILES="8"
+export IMFILEINPUTFILESSTEPS="5"
+export IMFILECHECKTIMEOUT="5"
 # generate input files first. Note that rsyslog processes it as
 # soon as it start up (so the file should exist at that point).
 
@@ -13,7 +11,7 @@ export IMFILECHECKTIMEOUT="5"
 . $srcdir/diag.sh generate-conf
 . $srcdir/diag.sh add-conf '
 global( debug.whitelist="on"
-	debug.files=["imfile.c"])
+	debug.files=["imfile.c", "stream.c"])
 #	debug.files=["rainerscript.c", "ratelimit.c", "ruleset.c", "main Q",
 #	"msg.c", "../action.c", "imdiag.c"])
 
@@ -46,30 +44,28 @@ if $msg contains "msgnum:" then
 
 . $srcdir/diag.sh startup 
 
-for j in `seq 1 $IMFILEINPUTFILESSTEPS`;
-do
+for j in $(seq 1 $IMFILEINPUTFILESSTEPS); do
+	cp log log.$j
 	echo "Loop Num $j"
 
 	for i in `seq 1 $IMFILEINPUTFILES`;
 	do
-		mkdir rsyslog.input.dir$i
-		mkdir rsyslog.input.dir$i/dir$i
-		./inputfilegen -m 1 > rsyslog.input.dir$i/dir$i/file.logfile
+		mkdir $RSYSLOG_DYNNAME.input.dir$i
+		mkdir $RSYSLOG_DYNNAME.input.dir$i/dir$i
+		./inputfilegen -i $j -m 1 > $RSYSLOG_DYNNAME.input.dir$i/dir$i/file.logfile
 	done
 
 	ls -d rsyslog.input.*
 	
 	# Check correct amount of input files each time
-	let IMFILEINPUTFILESALL=$(($IMFILEINPUTFILES * $j))
-	. $srcdir/diag.sh content-check-with-count "HEADER msgnum:00000000:" $IMFILEINPUTFILESALL $IMFILECHECKTIMEOUT
-
+	let IMFILEINPUTFILESALL=$((IMFILEINPUTFILES * j))
+	content_check_with_count "HEADER msgnum:000000" $IMFILEINPUTFILESALL $IMFILECHECKTIMEOUT
 	# Delete all but first!
 	for i in `seq 1 $IMFILEINPUTFILES`;
 	do
 		rm -rf rsyslog.input.dir$i/dir$i/file.logfile
 		rm -rf rsyslog.input.dir$i
 	done
-
 done
 
 . $srcdir/diag.sh shutdown-when-empty # shut down rsyslogd when done processing messages
-- 
2.16.4

Places

File 0002-bugfix-imfile-file-change-was-not-reliably-detected.patch of Package rsyslog (Revision a17f9939821148b9fdcf940638ccbf64)

Places