bugfixes and testbench improvement

- improved testbench
- bugfix: potential data loss during file stream shutdown
- bugfix: potential problems during file stream shutdown
  The shutdown/close sequence was not clean, what potentially (but
  unlikely) could lead to some issues. We have not been able to describe
  any fatal cases, but there was some bug potential. Sequence has now
  been straighted out.

11 files changed, 164 insertions, 11 deletions

diff --git a/ChangeLog b/ChangeLog
index 5f495768..7fe59dd9 100644
--- a/ChangeLog
+++ b/ChangeLog
@@ -1,5 +1,15 @@
 ---------------------------------------------------------------------------
 Version 4.6.2  [v4-stable] (rgerhards), 2010-03-??
+- added new property replacer option "date-rfc3164-buggyday" primarily
+  to ease migration from syslog-ng. See property replacer doc for
+  details. [backport from 5.5.3 because urgently needed by some]
+- improved testbench
+- bugfix: potential data loss during file stream shutdown
+- bugfix: potential problems during file stream shutdown
+  The shutdown/close sequence was not clean, what potentially (but
+  unlikely) could lead to some issues. We have not been able to describe
+  any fatal cases, but there was some bug potential. Sequence has now
+  been straighted out.
 - bugfix: potential problem (loop, abort) when file write error occured
   When a write error occured in stream.c, variable iWritten had the error
   code but this was handled as if it were the actual number of bytes
@@ -10,9 +20,6 @@ Version 4.6.2  [v4-stable] (rgerhards), 2010-03-??
   in proper retries.
 - bugfix: $omfileFlushOnTXEnd was turned on when set to off and vice
   versa due to an invalid check
-- added new property replacer option "date-rfc3164-buggyday" primarily
-  to ease migration from syslog-ng. See property replacer doc for
-  details. [backport from 5.5.3 because urgently needed by some]
 ---------------------------------------------------------------------------
 Version 4.6.1  [v4-stable] (rgerhards), 2010-03-04
 - re-enabled old pipe output (using new module ompipe, built-in) after
diff --git a/runtime/stream.c b/runtime/stream.c
index 82718099..5396bae0 100644
--- a/runtime/stream.c
+++ b/runtime/stream.c
@@ -306,20 +306,22 @@ strmWaitAsyncWriterDone(strm_t *pThis)
 /* close a strm file
  * Note that the bDeleteOnClose flag is honored. If it is set, the file will be
  * deleted after close. This is in support for the qRead thread.
+ * Note: it is valid to call this function when the physical file is closed. If so,
+ * strmCloseFile() will still check if there is any unwritten data inside buffers
+ * (this may be the case) and, if so, will open the file, write the data, and then
+ * close it again (this is done via strmFlush and friends).
  */
 static rsRetVal strmCloseFile(strm_t *pThis)
 {
 	DEFiRet;
 
 	ASSERT(pThis != NULL);
-	ASSERT(pThis->fd != -1);
 	dbgoprint((obj_t*) pThis, "file %d closing\n", pThis->fd);
 
 	if(!pThis->bInClose && pThis->tOperationsMode != STREAMMODE_READ) {
 		pThis->bInClose = 1;
+		strmFlush(pThis);
 		if(pThis->bAsyncWrite) {
-			strmFlush(pThis);
-		} else {
 			strmWaitAsyncWriterDone(pThis);
 		}
 		pThis->bInClose = 0;
@@ -685,8 +687,10 @@ CODESTARTobjDestruct(strm)
 		/* Note: mutex will be unlocked in stopWriter! */
 		d_pthread_mutex_lock(&pThis->mut);
 
-	if(pThis->tOperationsMode != STREAMMODE_READ)
-		strmFlush(pThis);
+	/* strmClose() will handle read-only files as well as need to open
+	 * files that have unwritten buffers. -- rgerhards, 2010-03-09
+	 */
+	strmCloseFile(pThis);
 
 	if(pThis->bAsyncWrite) {
 		stopWriter(pThis);
@@ -705,9 +709,6 @@ CODESTARTobjDestruct(strm)
 	 * IMPORTANT: we MUST free this only AFTER the ansyncWriter has been stopped, else
 	 * we get random errors...
 	 */
-	if(pThis->fd != -1)
-		strmCloseFile(pThis);
-
 	free(pThis->pszDir);
 	free(pThis->pZipBuf);
 	free(pThis->pszCurrFName);
diff --git a/tests/Makefile.am b/tests/Makefile.am
index 8849c3dc..92d3764b 100644
--- a/tests/Makefile.am
+++ b/tests/Makefile.am
@@ -9,6 +9,10 @@ TESTS = $(TESTRUNS) cfg.sh \
 	manytcp.sh \
 	sndrcv.sh \
 	sndrcv_gzip.sh \
+	asynwr_simple.sh \
+	asynwr_timeout.sh \
+	asynwr_small.sh \
+	asynwr_tinybuf.sh \
 	queue-persist.sh \
 	pipeaction.sh
 	execonlyonce.sh \
@@ -135,6 +139,15 @@ EXTRA_DIST= 1.rstest 2.rstest 3.rstest err1.rstest \
 	   testsuites/sndrcv_gzip_rcvr.conf \
 	   pipeaction.sh \
 	   testsuites/pipeaction.conf \
+	   asynwr_simple.sh \
+	   testsuites/asynwr_simple.conf \
+	   asynwr_timeout.sh \
+	   testsuites/asynwr_timeout.conf \
+	   asynwr_small.sh \
+	   testsuites/asynwr_small.conf \
+	   asynwr_tinybuf.sh \
+	   testsuites/asynwr_tinybuf.conf \
+	   testsuites/small.conf \
 	   proprepltest.sh \
 	   testsuites/rfctag.conf \
 	   testsuites/master.rfctag \
diff --git a/tests/asynwr_simple.sh b/tests/asynwr_simple.sh
new file mode 100755
index 00000000..693eca50
--- /dev/null
+++ b/tests/asynwr_simple.sh
@@ -0,0 +1,16 @@
+# This is test driver for testing asynchronous file output.
+#
+# added 2010-03-09 by Rgerhards
+# This file is part of the rsyslog project, released  under GPLv3
+echo TEST: \[asynwr_simple.sh\]: simple test for async file writing
+source $srcdir/diag.sh init
+# uncomment for debugging support:
+#export RSYSLOG_DEBUG="debug nostdout noprintmutexaction"
+#export RSYSLOG_DEBUGLOG="log"
+source $srcdir/diag.sh startup asynwr_simple.conf
+# send 35555 messages, make sure file size is not a multiple of
+# 10K, the buffer size!
+source $srcdir/diag.sh tcpflood 127.0.0.1 13514 1 35555
+source $srcdir/diag.sh shutdown-when-empty # shut down rsyslogd when done processing messages
+source $srcdir/diag.sh seq-check 0 35554
+source $srcdir/diag.sh exit
diff --git a/tests/asynwr_small.sh b/tests/asynwr_small.sh
new file mode 100755
index 00000000..692d27fa
--- /dev/null
+++ b/tests/asynwr_small.sh
@@ -0,0 +1,24 @@
+# This tests async writing with only a small set of data. That
+# shall result in data staying in buffers until shutdown, what
+# then will trigger some somewhat complex logic in the stream
+# writer (open, write, close all during the stream close
+# opertion). It is vital that only few messages be sent.
+#
+# The main effort of this test is not (only) to see if we
+# receive the data, but rather to see if we get into an abort
+# condition.
+#
+# added 2010-03-09 by Rgerhards
+#
+# This file is part of the rsyslog project, released  under GPLv3
+echo TEST: \[asynwr_small.sh\]: test for async file writing for few messages
+source $srcdir/diag.sh init
+# uncomment for debugging support:
+#export RSYSLOG_DEBUG="debug nostdout noprintmutexaction"
+#export RSYSLOG_DEBUGLOG="log"
+source $srcdir/diag.sh startup asynwr_small.conf
+# send 4000 messages
+source $srcdir/diag.sh tcpflood 127.0.0.1 13514 1 2
+source $srcdir/diag.sh shutdown-when-empty # shut down rsyslogd when done processing messages
+source $srcdir/diag.sh seq-check 0 1
+source $srcdir/diag.sh exit
diff --git a/tests/asynwr_timeout.sh b/tests/asynwr_timeout.sh
new file mode 100755
index 00000000..84fbd481
--- /dev/null
+++ b/tests/asynwr_timeout.sh
@@ -0,0 +1,19 @@
+# This test writes to the output buffers, let's the output
+# write timeout (and write data) and then continue. The conf file
+# has a 2 second timeout, so we wait 4 seconds to be on the save side.
+#
+# added 2010-03-09 by Rgerhards
+# This file is part of the rsyslog project, released  under GPLv3
+echo TEST: \[asynwr_timeout.sh\]: test async file writing timeout writes
+source $srcdir/diag.sh init
+# uncomment for debugging support:
+#export RSYSLOG_DEBUG="debug nostdout noprintmutexaction"
+#export RSYSLOG_DEBUGLOG="log"
+source $srcdir/diag.sh startup asynwr_timeout.conf
+# send 35555 messages, make sure file size is not a multiple of
+# 10K, the buffer size!
+source $srcdir/diag.sh tcpflood 127.0.0.1 13514 1 35555
+sleep 4 # wait for output writer to write and empty buffer
+source $srcdir/diag.sh shutdown-when-empty # shut down rsyslogd when done processing messages
+source $srcdir/diag.sh seq-check 0 35554
+source $srcdir/diag.sh exit
diff --git a/tests/asynwr_tinybuf.sh b/tests/asynwr_tinybuf.sh
new file mode 100755
index 00000000..a7cc19ef
--- /dev/null
+++ b/tests/asynwr_tinybuf.sh
@@ -0,0 +1,18 @@
+# This tests async writing with a very small output buffer (1 byte!),
+# so it stresses output buffer handling. This also means operations will
+# be somewhat slow, so we send only a small amounts of data.
+#
+# added 2010-03-09 by Rgerhards
+#
+# This file is part of the rsyslog project, released  under GPLv3
+echo TEST: \[asynwr_tinybuf.sh\]: test async file writing with 1-byte buffer
+source $srcdir/diag.sh init
+# uncomment for debugging support:
+#export RSYSLOG_DEBUG="debug nostdout noprintmutexaction"
+#export RSYSLOG_DEBUGLOG="log"
+source $srcdir/diag.sh startup asynwr_tinybuf.conf
+# send 1000 messages, fairly enough to trigger problems
+source $srcdir/diag.sh tcpflood 127.0.0.1 13514 1 1000
+source $srcdir/diag.sh shutdown-when-empty # shut down rsyslogd when done processing messages
+source $srcdir/diag.sh seq-check 0 999
+source $srcdir/diag.sh exit
diff --git a/tests/testsuites/asynwr_simple.conf b/tests/testsuites/asynwr_simple.conf
new file mode 100644
index 00000000..68b85ff5
--- /dev/null
+++ b/tests/testsuites/asynwr_simple.conf
@@ -0,0 +1,14 @@
+# simple async writing test
+# rgerhards, 2010-03-09
+$IncludeConfig diag-common.conf
+
+$ModLoad ../plugins/imtcp/.libs/imtcp
+$MainMsgQueueTimeoutShutdown 10000
+$InputTCPServerRun 13514
+
+$template outfmt,"%msg:F,58:2%\n"
+$template dynfile,"rsyslog.out.log" # trick to use relative path names!
+$OMFileFlushOnTXEnd off
+$OMFileFlushInterval 2
+$OMFileFlushIOBufferSize 10k
+:msg, contains, "msgnum:" ?dynfile;outfmt
diff --git a/tests/testsuites/asynwr_small.conf b/tests/testsuites/asynwr_small.conf
new file mode 100644
index 00000000..d9724cec
--- /dev/null
+++ b/tests/testsuites/asynwr_small.conf
@@ -0,0 +1,13 @@
+# simple async writing test
+# rgerhards, 2010-03-09
+$IncludeConfig diag-common.conf
+
+$ModLoad ../plugins/imtcp/.libs/imtcp
+$MainMsgQueueTimeoutShutdown 10000
+$InputTCPServerRun 13514
+
+$template outfmt,"%msg:F,58:2%\n"
+$template dynfile,"rsyslog.out.log" # trick to use relative path names!
+$OMFileFlushOnTXEnd off
+$OMFileFlushInterval 2
+:msg, contains, "msgnum:" ?dynfile;outfmt
diff --git a/tests/testsuites/asynwr_timeout.conf b/tests/testsuites/asynwr_timeout.conf
new file mode 100644
index 00000000..68b85ff5
--- /dev/null
+++ b/tests/testsuites/asynwr_timeout.conf
@@ -0,0 +1,14 @@
+# simple async writing test
+# rgerhards, 2010-03-09
+$IncludeConfig diag-common.conf
+
+$ModLoad ../plugins/imtcp/.libs/imtcp
+$MainMsgQueueTimeoutShutdown 10000
+$InputTCPServerRun 13514
+
+$template outfmt,"%msg:F,58:2%\n"
+$template dynfile,"rsyslog.out.log" # trick to use relative path names!
+$OMFileFlushOnTXEnd off
+$OMFileFlushInterval 2
+$OMFileFlushIOBufferSize 10k
+:msg, contains, "msgnum:" ?dynfile;outfmt
diff --git a/tests/testsuites/asynwr_tinybuf.conf b/tests/testsuites/asynwr_tinybuf.conf
new file mode 100644
index 00000000..9818b139
--- /dev/null
+++ b/tests/testsuites/asynwr_tinybuf.conf
@@ -0,0 +1,14 @@
+# simple async writing test
+# rgerhards, 2010-03-09
+$IncludeConfig diag-common.conf
+
+$ModLoad ../plugins/imtcp/.libs/imtcp
+$MainMsgQueueTimeoutShutdown 10000
+$InputTCPServerRun 13514
+
+$template outfmt,"%msg:F,58:2%\n"
+$template dynfile,"rsyslog.out.log" # trick to use relative path names!
+$OMFileFlushOnTXEnd off
+$OMFileFlushInterval 2
+$OMFileIOBufferSize 1
+:msg, contains, "msgnum:" ?dynfile;outfmt