Merge branch 'beta'

15 files changed, 134 insertions, 22 deletions

diff --git a/ChangeLog b/ChangeLog
index 8759c846..643c25e4 100644
--- a/ChangeLog
+++ b/ChangeLog
@@ -23,6 +23,12 @@ Version 5.3.0  [DEVEL] (rgerhards), 2009-09-14
 ---------------------------------------------------------------------------
 Version 5.1.6  [v5-beta] (rgerhards), 2009-09-??
 - feature imports from v4.5.6
+- bugfix: potential race condition when queue worker threads were
+  terminated
+- bugfix: solved potential (temporary) stall of messages when the queue was
+  almost empty and few new data added (caused testbench to sometimes hang!)
+- fixed some race condition in testbench
+- added more elaborate diagnostics to parts of the testbench
 - bugfixes imported from 4.5.4:
   * bugfix: potential segfault in stream writer on destruction
   * bugfix: potential race in object loader (obj.c) during use/release
@@ -177,6 +183,8 @@ Version 4.5.6  [v4-beta] (rgerhards), 2009-09-??
 Version 4.5.5  [v4-beta] (rgerhards), 2009-09-??
 - added $InputTCPServerNotifyOnConnectionClose config directive
   see doc for details
+- bugfix: debug string larger than 1K were improperly displayed. Max size
+  is now 32K
 - bugfix: invalid storage class selected for some size config parameters.
   This resulted in wrong values. The most prominent victim was the
   directory creation mode, which was set to zero in some cases. For 
diff --git a/plugins/imudp/imudp.c b/plugins/imudp/imudp.c
index 735042a4..5bfbdd4a 100644
--- a/plugins/imudp/imudp.c
+++ b/plugins/imudp/imudp.c
@@ -259,6 +259,7 @@ processSocket(int fd, struct sockaddr_storage *frominetPrev, int *pbIsPermitted,
 			pMsg->bParseHOSTNAME = 1;
 			MsgSetRcvFromStr(pMsg, fromHost, ustrlen(fromHost), &propFromHost);
 			CHKiRet(MsgSetRcvFromIPStr(pMsg, fromHostIP, ustrlen(fromHostIP), &propFromHostIP));
+dbgprintf("XXX: submitting msg to queue\n");
 			CHKiRet(submitMsg(pMsg));
 		}
 	}
diff --git a/runtime/debug.c b/runtime/debug.c
index fb751efb..959d56a3 100644
--- a/runtime/debug.c
+++ b/runtime/debug.c
@@ -840,7 +840,7 @@ do_dbgprint(uchar *pszObjName, char *pszMsg, size_t lenMsg)
 	static pthread_t ptLastThrdID = 0;
 	static int bWasNL = 0;
 	char pszThrdName[64]; /* 64 is to be on the safe side, anything over 20 is bad... */
-	char pszWriteBuf[1024];
+	char pszWriteBuf[32*1024];
 	size_t lenWriteBuf;
 	struct timespec t;
 
diff --git a/runtime/msg.c b/runtime/msg.c
index 5a33837f..d28ee350 100644
--- a/runtime/msg.c
+++ b/runtime/msg.c
@@ -1177,7 +1177,7 @@ uchar *getMSG(msg_t *pM)
 	if(pM == NULL)
 		ret = UCHAR_CONSTANT("");
 	else {
-		if(pM->offMSG == -1)
+		if(pM->iLenMSG == 0)
 			ret = UCHAR_CONSTANT("");
 		else
 			ret = pM->pszRawMsg + pM->offMSG;
@@ -1953,12 +1953,20 @@ void MsgSetHOSTNAME(msg_t *pThis, uchar* pszHOSTNAME, int lenHOSTNAME)
 
 
 /* set the offset of the MSG part into the raw msg buffer
+ * Note that the offset may be higher than the length of the raw message 
+ * (exactly by one). This can happen if we have a message that does not 
+ * contain any MSG part.
  */
 void MsgSetMSGoffs(msg_t *pMsg, short offs)
 {
 	ISOBJ_TYPE_assert(pMsg, msg);
-	pMsg->iLenMSG = pMsg->iLenRawMsg - offs;
 	pMsg->offMSG = offs;
+	if(offs > pMsg->iLenRawMsg) {
+		assert(offs - 1 == pMsg->iLenRawMsg);
+		pMsg->iLenMSG = 0;
+	} else {
+		pMsg->iLenMSG = pMsg->iLenRawMsg - offs;
+	}
 }
 
 
@@ -1992,7 +2000,8 @@ rsRetVal MsgReplaceMSG(msg_t *pThis, uchar* pszMSG, int lenMSG)
 		pThis->pszRawMsg = bufNew;
 	}
 
-	memcpy(pThis->pszRawMsg + pThis->offMSG, pszMSG, lenMSG);
+	if(lenMSG > 0)
+		memcpy(pThis->pszRawMsg + pThis->offMSG, pszMSG, lenMSG);
 	pThis->pszRawMsg[lenNew] = '\0'; /* this also works with truncation! */
 	pThis->iLenRawMsg = lenNew;
 	pThis->iLenMSG = lenMSG;
diff --git a/runtime/queue.c b/runtime/queue.c
index cb14b58d..101052a1 100644
--- a/runtime/queue.c
+++ b/runtime/queue.c
@@ -1188,7 +1188,7 @@ tryShutdownWorkersWithinQueueTimeout(qqueue_t *pThis)
 		if(iRetLocal == RS_RET_TIMED_OUT) {
 			DBGOPRINT((obj_t*) pThis, "shutdown timed out on main queue DA worker pool (this is OK)\n");
 		} else {
-			DBGOPRINT((obj_t*) pThis, "main queue DA worker pool shut down.\n");
+			DBGOPRINT((obj_t*) pThis, "main queue DA worker pool shut down on first try.\n");
 		}
 	}
 
@@ -1247,13 +1247,31 @@ tryShutdownWorkersWithinActionTimeout(qqueue_t *pThis)
 			DBGOPRINT((obj_t*) pThis, "unexpected iRet state %d after trying immediate shutdown of the DA "
 				  "queue in disk save mode. Continuing, but results are unpredictable\n", iRetLocal);
 		}
+		/* and now we need to check the DA worker itself (the one that shuffles data to the disk). This
+		 * is necessary because we may be in a situation where the DA queue regular worker and the
+		 * main queue worker stopped rather quickly. In this case, there is almost no time (and
+		 * probably no thread switch!) between the point where we instructed the main queue DA
+		 * worker to shutdown and this code location. In consequence, it may not even have
+		 * noticed that it should should down, less acutally done this. So we provide it with a 
+		 * fixed 100ms timeout to try complete its work, what usually should be sufficient.
+		 * rgerhards, 2009-10-06
+		 */
+		timeoutComp(&tTimeout, 100);
+		DBGOPRINT((obj_t*) pThis, "last try for regular shutdown of main queue DA worker pool\n");
+		iRetLocal = wtpShutdownAll(pThis->pWtpDA, wtpState_SHUTDOWN_IMMEDIATE, &tTimeout);
+		if(iRetLocal == RS_RET_TIMED_OUT) {
+			DBGOPRINT((obj_t*) pThis, "shutdown timed out on main queue DA worker pool "
+					          "(this is not good, but probably OK)\n");
+		} else {
+			DBGOPRINT((obj_t*) pThis, "main queue DA worker pool shut down.\n");
+		}
 	}
 
 	RETiRet;
 }
 
 
-/* This function cancels all remenaing regular workers for both the main and the DA
+/* This function cancels all remaining regular workers for both the main and the DA
  * queue. The main queue's DA worker pool continues to run (if it exists and is active).
  * rgerhards, 2009-05-29
  */
@@ -1651,7 +1669,6 @@ DequeueConsumable(qqueue_t *pThis, wti_t *pWti)
 
 	// TODO: MULTI: check physical queue size?
 	pthread_cond_signal(&pThis->notFull);
-	d_pthread_mutex_unlock(pThis->mut);
 	/* WE ARE NO LONGER PROTECTED BY THE MUTEX */
 
 	if(iRet != RS_RET_OK && iRet != RS_RET_DISCARDMSG) {
@@ -1758,9 +1775,7 @@ RateLimiter(qqueue_t *pThis)
 }
 
 
-/* This dequeues the next batch and checks if the queue is empty. If it is 
- * empty, return RS_RET_IDLE. That will trigger termination of the function
- * and tell the upper layer caller to initiate idle processing.
+/* This dequeues the next batch.
  * rgerhards, 2009-05-20
  */
 static inline rsRetVal
@@ -1771,11 +1786,13 @@ DequeueForConsumer(qqueue_t *pThis, wti_t *pWti)
 	ISOBJ_TYPE_assert(pThis, qqueue);
 	ISOBJ_TYPE_assert(pWti, wti);
 
+dbgprintf("YYY: deqeueu for consumer");
 	CHKiRet(DequeueConsumable(pThis, pWti));
 
 	if(pWti->batch.nElem == 0)
 		ABORT_FINALIZE(RS_RET_IDLE);
 
+
 finalize_it:
 	RETiRet;
 }
@@ -1814,6 +1831,10 @@ ConsumerReg(qqueue_t *pThis, wti_t *pWti)
 	ISOBJ_TYPE_assert(pWti, wti);
 
 	CHKiRet(DequeueForConsumer(pThis, pWti));
+
+	/* we now have a non-idle batch of work, so we can release the queue mutex and process it */
+	d_pthread_mutex_unlock(pThis->mut);
+
 	CHKiRet(pThis->pConsumer(pThis->pUsr, &pWti->batch));
 
 	/* we now need to check if we should deliberately delay processing a bit
@@ -1826,6 +1847,9 @@ ConsumerReg(qqueue_t *pThis, wti_t *pWti)
 		srSleep(pThis->iDeqSlowdown / 1000000, pThis->iDeqSlowdown % 1000000);
 	}
 
+	/* now we are done, but need to re-aquire the mutex */
+	d_pthread_mutex_lock(pThis->mut);
+
 finalize_it:
 dbgprintf("XXX: regular consumer finished, iret=%d, szlog %d sz phys %d\n", iRet, getLogicalQueueSize(pThis), getPhysicalQueueSize(pThis));
 	RETiRet;
@@ -1851,6 +1875,10 @@ ConsumerDA(qqueue_t *pThis, wti_t *pWti)
 	ISOBJ_TYPE_assert(pWti, wti);
 
 	CHKiRet(DequeueForConsumer(pThis, pWti));
+
+	/* we now have a non-idle batch of work, so we can release the queue mutex and process it */
+	d_pthread_mutex_unlock(pThis->mut);
+
 	/* iterate over returned results and enqueue them in DA queue */
 	for(i = 0 ; i < pWti->batch.nElem ; i++) {
 		/* TODO: we must add a generic "addRef" mechanism, because the disk queue enqueue destructs
@@ -1860,6 +1888,9 @@ ConsumerDA(qqueue_t *pThis, wti_t *pWti)
 		CHKiRet(qqueueEnqObj(pThis->pqDA, eFLOWCTL_NO_DELAY, (obj_t*)MsgAddRef((msg_t*)(pWti->batch.pElem[i].pUsrp))));
 	}
 
+	/* now we are done, but need to re-aquire the mutex */
+	d_pthread_mutex_lock(pThis->mut);
+
 finalize_it:
 	DBGOPRINT((obj_t*) pThis, "DAConsumer returns with iRet %d\n", iRet);
 	RETiRet;
@@ -2513,6 +2544,7 @@ finalize_it:
 	if(pThis->qType != QUEUETYPE_DIRECT) {
 		/* make sure at least one worker is running. */
 		qqueueAdviseMaxWorkers(pThis);
+dbgprintf("YYY: call advise with mutex %p locked \n", pThis->mut);
 		/* and release the mutex */
 		d_pthread_mutex_unlock(pThis->mut);
 		pthread_setcancelstate(iCancelStateSave, NULL);
diff --git a/runtime/wti.c b/runtime/wti.c
index 9d0560dd..53b695b0 100644
--- a/runtime/wti.c
+++ b/runtime/wti.c
@@ -114,7 +114,12 @@ wtiSetState(wti_t *pThis, bool bNewVal)
 
 
 /* Cancel the thread. If the thread is not running. But it is save and legal to
- * call wtiCancelThrd() in such situations.
+ * call wtiCancelThrd() in such situations. This function only returns when the
+ * thread has terminated. Else we may get race conditions all over the code...
+ * Note that when waiting for the thread to terminate, we do a busy wait, checking
+ * progress every 10ms. It is very unlikely that we will ever cancel a thread
+ * and, if so, it will only happen at the end of the rsyslog run. So doing this
+ * kind of not optimal wait is considered preferable over using condition variables.
  * rgerhards, 2008-02-26
  */
 rsRetVal
@@ -127,6 +132,11 @@ wtiCancelThrd(wti_t *pThis)
 	if(wtiGetState(pThis)) {
 		dbgoprint((obj_t*) pThis, "canceling worker thread\n");
 		pthread_cancel(pThis->thrdID);
+		/* now wait until the thread terminates... */
+		while(wtiGetState(pThis)) {
+//fprintf(stderr, "sleep loop for getState\n");
+			srSleep(0, 10000);
+		}
 	}
 
 	RETiRet;
@@ -214,9 +224,9 @@ doIdleProcessing(wti_t *pThis, wtp_t *pWtp, int *pbInactivityTOOccured)
 
 	pWtp->pfOnIdle(pWtp->pUsr, MUTEX_ALREADY_LOCKED);
 
-	d_pthread_mutex_lock(pWtp->pmutUsr);
 	if(pThis->bAlwaysRunning) {
 		/* never shut down any started worker */
+dbgprintf("YYY/ZZZ: wti Idle wait cond busy, mutex %p\n", pWtp->pmutUsr);
 		d_pthread_cond_wait(pWtp->pcondBusy, pWtp->pmutUsr);
 	} else {
 		timeoutComp(&t, pWtp->toWrkShutdown);/* get absolute timeout */
@@ -225,7 +235,6 @@ doIdleProcessing(wti_t *pThis, wtp_t *pWtp, int *pbInactivityTOOccured)
 			*pbInactivityTOOccured = 1; /* indicate we had a timeout */
 		}
 	}
-	d_pthread_mutex_unlock(pWtp->pmutUsr);
 	ENDfunc
 }
 
@@ -258,8 +267,10 @@ wtiWorker(wti_t *pThis)
 			pWtp->pfRateLimiter(pWtp->pUsr);
 		}
 		
+dbgprintf("YYY/ZZZ: pre lock mutex\n");
 		d_pthread_mutex_lock(pWtp->pmutUsr);
 
+dbgprintf("YYY/ZZZ: wti locks mutex %p\n", pWtp->pmutUsr);
 		/* first check if we are in shutdown process (but evaluate a bit later) */
 		terminateRet = wtpChkStopWrkr(pWtp, MUTEX_ALREADY_LOCKED);
 		if(terminateRet == RS_RET_TERMINATE_NOW) {
@@ -272,17 +283,24 @@ wtiWorker(wti_t *pThis)
 		}
 
 		/* try to execute and process whatever we have */
-		/* This function must and does RELEASE the MUTEX! */
+		/* Note that this function releases and re-aquires the mutex. The returned
+		 * information on idle state must be processed before releasing the mutex again.
+		 */
 		localRet = pWtp->pfDoWork(pWtp->pUsr, pThis);
 
+dbgprintf("YYY/ZZZ: wti loop locked mutex %p again\n", pWtp->pmutUsr);
 		if(localRet == RS_RET_IDLE) {
 			if(terminateRet == RS_RET_TERMINATE_WHEN_IDLE || bInactivityTOOccured) {
+				d_pthread_mutex_unlock(pWtp->pmutUsr);
 				break;	/* end of loop */
 			}
 			doIdleProcessing(pThis, pWtp, &bInactivityTOOccured);
+			d_pthread_mutex_unlock(pWtp->pmutUsr);
 			continue; /* request next iteration */
 		}
 
+		d_pthread_mutex_unlock(pWtp->pmutUsr);
+
 		bInactivityTOOccured = 0; /* reset for next run */
 	}
 
diff --git a/runtime/wtp.c b/runtime/wtp.c
index 4524e0c3..40d031dc 100644
--- a/runtime/wtp.c
+++ b/runtime/wtp.c
@@ -413,6 +413,7 @@ wtpAdviseMaxWorkers(wtp_t *pThis, int nMaxWrkr)
 
 	ISOBJ_TYPE_assert(pThis, wtp);
 
+int nMaxWrkrTmp = nMaxWrkr;
 	if(nMaxWrkr == 0)
 		FINALIZE;
 
@@ -420,6 +421,7 @@ wtpAdviseMaxWorkers(wtp_t *pThis, int nMaxWrkr)
 		nMaxWrkr = pThis->iNumWorkerThreads;
 
 	nMissing = nMaxWrkr - ATOMIC_FETCH_32BIT(pThis->iCurNumWrkThrd);
+dbgprintf("wtpAdviseMaxWorkers, nmax: %d, curr %d, missing %d\n", nMaxWrkrTmp, pThis->iNumWorkerThreads, nMissing);
 
 	if(nMissing > 0) {
 		DBGPRINTF("%s: high activity - starting %d additional worker thread(s).\n", wtpGetDbgHdr(pThis), nMissing);
@@ -428,6 +430,7 @@ wtpAdviseMaxWorkers(wtp_t *pThis, int nMaxWrkr)
 			CHKiRet(wtpStartWrkr(pThis));
 		}
 	} else {
+dbgprintf("YYY: adivse signal cond busy");
 		pthread_cond_signal(pThis->pcondBusy);
 	}
 
diff --git a/tcps_sess.c b/tcps_sess.c
index 8d307380..09861ab9 100644
--- a/tcps_sess.c
+++ b/tcps_sess.c
@@ -256,6 +256,7 @@ defaultDoSubmitMessage(tcps_sess_t *pThis, struct syslogTime *stTime, time_t ttG
 	CHKiRet(MsgSetRcvFromIP(pMsg, pThis->fromHostIP));
 	MsgSetRuleset(pMsg, pThis->pLstnInfo->pRuleset);
 
+dbgprintf("YYY: submitting msg to queue\n");
 	if(pMultiSub == NULL) {
 		CHKiRet(submitMsg(pMsg));
 	} else {
diff --git a/tests/arrayqueue.sh b/tests/arrayqueue.sh
index 01fc133b..58fd24ae 100755
--- a/tests/arrayqueue.sh
+++ b/tests/arrayqueue.sh
@@ -10,5 +10,8 @@ source $srcdir/diag.sh injectmsg  0 40000
 
 # terminate *now* (don't wait for queue to drain!)
 kill `cat rsyslog.pid`
+
+# now wait until rsyslog.pid is gone (and the process finished)
+source $srcdir/diag.sh wait-shutdown 
 source $srcdir/diag.sh seq-check 0 39999
 source $srcdir/diag.sh exit
diff --git a/tests/da-mainmsg-q.sh b/tests/da-mainmsg-q.sh
index 6ec2f3a9..d502fca3 100755
--- a/tests/da-mainmsg-q.sh
+++ b/tests/da-mainmsg-q.sh
@@ -7,7 +7,7 @@
 # check everything recovers from DA mode correctly.
 # added 2009-04-22 by Rgerhards
 # This file is part of the rsyslog project, released  under GPLv3
-echo "testing main message queue in DA mode (going to disk)"
+echo "[da-mainmsg-q.sh]: testing main message queue in DA mode (going to disk)"
 source $srcdir/diag.sh init
 source $srcdir/diag.sh startup da-mainmsg-q.conf
 
diff --git a/tests/daqueue-persist-drvr.sh b/tests/daqueue-persist-drvr.sh
index 7b6ec6dd..d95991fc 100755
--- a/tests/daqueue-persist-drvr.sh
+++ b/tests/daqueue-persist-drvr.sh
@@ -26,5 +26,6 @@ source $srcdir/diag.sh check-mainq-spool
 echo "#" > work-delay.conf
 source $srcdir/diag.sh startup queue-persist.conf
 source $srcdir/diag.sh shutdown-when-empty # shut down rsyslogd when done processing messages
+$srcdir/diag.sh wait-shutdown
 source $srcdir/diag.sh seq-check 0 4999
 source $srcdir/diag.sh exit
diff --git a/tests/diag.sh b/tests/diag.sh
index 13bb877d..d8ba43b8 100755
--- a/tests/diag.sh
+++ b/tests/diag.sh
@@ -9,7 +9,7 @@
 #valgrind="valgrind --tool=drd --log-fd=1"
 #valgrind="valgrind --tool=helgrind --log-fd=1"
 #set -o xtrace
-#export RSYSLOG_DEBUG="debug nostdout printmutexaction"
+#export RSYSLOG_DEBUG="debug nostdout noprintmutexaction"
 #export RSYSLOG_DEBUGLOG="log"
 case $1 in
    'init')	$srcdir/killrsyslog.sh # kill rsyslogd if it runs for some reason
@@ -39,6 +39,12 @@ case $1 in
 		while test -f rsyslog.pid; do
 			true
 		done
+		if [ -e core.* ]
+		then
+		   echo "ABORT! core file exists, starting interactive shell"
+		   bash
+		   exit 1
+		fi
 		;;
    'wait-queueempty') # wait for main message queue to be empty
 		echo WaitMainQueueEmpty | java -classpath $abs_top_builddir DiagTalker
diff --git a/tests/linkedlistqueue.sh b/tests/linkedlistqueue.sh
index 9570ed2b..72c2a403 100755
--- a/tests/linkedlistqueue.sh
+++ b/tests/linkedlistqueue.sh
@@ -10,5 +10,8 @@ source $srcdir/diag.sh injectmsg  0 40000
 
 # terminate *now* (don't wait for queue to drain)
 kill `cat rsyslog.pid`
+
+# now wait until rsyslog.pid is gone (and the process finished)
+source $srcdir/diag.sh wait-shutdown 
 source $srcdir/diag.sh seq-check 0 39999
 source $srcdir/diag.sh exit
diff --git a/tests/nettester.c b/tests/nettester.c
index 71641745..2838b919 100644
--- a/tests/nettester.c
+++ b/tests/nettester.c
@@ -47,6 +47,7 @@
 #include <signal.h>
 #include <netinet/in.h>
 #include <getopt.h>
+#include <errno.h>
 
 #define EXIT_FAILURE 1
 #define INVALID_SOCKET -1
@@ -90,6 +91,7 @@ void readLine(int fd, char *ln)
 	if(verbose)
 		fprintf(stderr, "begin readLine\n");
 	lenRead = read(fd, &c, 1);
+
 	while(lenRead == 1 && c != '\n') {
 		if(c == '\0') {
 			*ln = c;
@@ -102,6 +104,11 @@ void readLine(int fd, char *ln)
 	}
 	*ln = '\0';
 
+	if(lenRead < 0) {
+		printf("read from rsyslogd returned with error '%s' - aborting test\n", strerror(errno));
+		exit(1);
+	}
+
 	if(verbose)
 		fprintf(stderr, "end readLine, val read '%s'\n", orig);
 }
@@ -308,6 +315,10 @@ processTestFile(int fd, char *pszFileName)
 
 		/* pull response from server and then check if it meets our expectation */
 		readLine(fd, buf);
+		if(strlen(buf) == 0) {
+			printf("something went wrong - read a zero-length string from rsyslogd");
+			exit(1);
+		}
 		if(strcmp(expected, buf)) {
 			++iFailed;
 			printf("\nExpected Response:\n'%s'\nActual Response:\n'%s'\n",
@@ -372,11 +383,24 @@ doTests(int fd, char *files)
 	return(iFailed);
 }
 
+
+/* indicate that our child has died (where it is not permitted to!).
+ */
+void childDied(__attribute__((unused)) int sig)
+{
+	printf("ERROR: child died unexpectedly (maybe a segfault?)!\n");
+	exit(1);
+}
+
+
 /* cleanup */
 void doAtExit(void)
 {
 	int status;
 
+	/* disarm died-child handler */
+	signal(SIGCHLD, SIG_IGN);
+
 	if(rsyslogdPid != 0) {
 		kill(rsyslogdPid, SIGTERM);
 		waitpid(rsyslogdPid, &status, 0);	/* wait until instance terminates */
@@ -457,6 +481,9 @@ int main(int argc, char *argv[])
 	}
 	fclose(fp);
 
+	/* arm died-child handler */
+	signal(SIGCHLD, childDied);
+
 	/* start to be tested rsyslogd */
 	openPipe(testSuite, &rsyslogdPid, &fd);
 	readLine(fd, buf);
@@ -467,5 +494,6 @@ int main(int argc, char *argv[])
 		ret = 1;
 
 	if(verbose) printf("End of nettester run (%d).\n", ret);
+
 	exit(ret);
 }
diff --git a/tools/syslogd.c b/tools/syslogd.c
index 0f4f8a23..8c4c8e94 100644
--- a/tools/syslogd.c
+++ b/tools/syslogd.c
@@ -1205,8 +1205,6 @@ int parseLegacySyslogMsg(msg_t *pMsg, int flags)
 	assert(pMsg != NULL);
 	assert(pMsg->pszRawMsg != NULL);
 	lenMsg = pMsg->iLenRawMsg - (pMsg->offAfterPRI + 1);
-RUNLOG_VAR("%d", pMsg->offAfterPRI);
-RUNLOG_VAR("%d", lenMsg);
 	p2parse = pMsg->pszRawMsg + pMsg->offAfterPRI; /* point to start of text, after PRI */
 
 	/* Check to see if msg contains a timestamp. We start by assuming
@@ -1262,16 +1260,16 @@ RUNLOG_VAR("%d", lenMsg);
 		bTAGCharDetected = 0;
 		if(lenMsg > 0 && flags & PARSE_HOSTNAME) {
 			i = 0;
-			while(lenMsg > 0 && (isalnum(p2parse[i]) || p2parse[i] == '.' || p2parse[i] == '.'
+			while(i < lenMsg && (isalnum(p2parse[i]) || p2parse[i] == '.' || p2parse[i] == '.'
 				|| p2parse[i] == '_' || p2parse[i] == '-') && i < CONF_TAG_MAXSIZE) {
 				bufParseHOSTNAME[i] = p2parse[i];
 				++i;
-				--lenMsg;
 			}
 
 			if(i > 0 && p2parse[i] == ' ' && isalnum(p2parse[i-1])) {
 				/* we got a hostname! */
 				p2parse += i + 1; /* "eat" it (including SP delimiter) */
+				lenMsg -= i + 1;
 				bufParseHOSTNAME[i] = '\0';
 				MsgSetHOSTNAME(pMsg, bufParseHOSTNAME, i);
 			}
@@ -1738,8 +1736,6 @@ die(int sig)
 	 */
 	tplDeleteAll();
 
-	remove_pid(PidFile);
-
 	/* de-init some modules */
 	modExitIminternal();
 
@@ -1773,6 +1769,9 @@ die(int sig)
 	 */
 	freeAllDynMemForTermination();
 	/* NO CODE HERE - feeelAllDynMemForTermination() must be the last thing before exit()! */
+
+	remove_pid(PidFile);
+
 	exit(0); /* "good" exit, this is the terminator function for rsyslog [die()] */
 }