fixed a potential race condition, see link for details:

    http://rgerhards.blogspot.com/2007/12/rsyslog-race-condition.html

4 files changed, 50 insertions, 24 deletions

diff --git a/Makefile.am b/Makefile.am
index bdc14486..1e6cf5a6 100644
--- a/Makefile.am
+++ b/Makefile.am
@@ -30,6 +30,8 @@ rsyslogd_SOURCES = \
 	template.h \
 	outchannel.h \
 	liblogging-stub.h \
+	sync.c \
+	sync.h \
 	net.c \
 	net.h \
 	msg.c \
diff --git a/action.c b/action.c
index 5759b2c2..621cda51 100644
--- a/action.c
+++ b/action.c
@@ -34,6 +34,7 @@
 #include "template.h"
 #include "action.h"
 #include "modules.h"
+#include "sync.h"
 
 
 /* object static data (once for all instances) */
@@ -52,6 +53,7 @@ rsRetVal actionDestruct(action_t *pThis)
 	if(pThis->f_pMsg != NULL)
 		MsgDestruct(pThis->f_pMsg);
 
+	SYNC_OBJ_TOOL_EXIT(pThis);
 	if(pThis->ppTpl != NULL)
 		free(pThis->ppTpl);
 	if(pThis->ppMsgs != NULL)
@@ -77,6 +79,7 @@ rsRetVal actionConstruct(action_t **ppThis)
 	}
 
 	pThis->iResumeInterval = glbliActionResumeInterval;
+	SYNC_OBJ_TOOL_INIT(pThis);
 
 finalize_it:
 	*ppThis = pThis;
diff --git a/action.h b/action.h
index c0cf19ad..9a24600a 100644
--- a/action.h
+++ b/action.h
@@ -25,6 +25,7 @@
 #define	ACTION_H_INCLUDED 1
 
 #include "syslogd-types.h"
+#include "sync.h"
 
 /* the following struct defines the action object data structure
  */
@@ -50,6 +51,7 @@ struct action_s {
 				 * content later). This is preserved after the message has been
 				 * processed - it is also used to detect duplicates.
 				 */
+	SYNC_OBJ_TOOL;		/* required for mutex support */
 };
 typedef struct action_s action_t;
 
diff --git a/syslogd.c b/syslogd.c
index d4c1b1f5..5a39801f 100644
--- a/syslogd.c
+++ b/syslogd.c
@@ -210,6 +210,7 @@
 #include "outchannel.h"
 #include "syslogd.h"
 #include "net.h" /* struct NetAddr */
+#include "sync.h" /* struct NetAddr */
 
 #include "parse.h"
 #include "msg.h"
@@ -2221,8 +2222,6 @@ void printline(char *hname, char *msg, int bParseHost)
 	return;
 }
 
-time_t	now;
-
 /* rgerhards 2004-11-09: the following is a function that can be used
  * to log a message orginating from the syslogd itself. In sysklogd code,
  * this is done by simply calling logmsg(). However, logmsg() is changed in
@@ -2232,7 +2231,8 @@ time_t	now;
  * function here probably is only an interim solution and that we need to
  * think on the best way to do this.
  */
-static void logmsgInternal(int pri, char *msg, int flags)
+static void
+logmsgInternal(int pri, char *msg, int flags)
 {
 	msg_t *pMsg;
 
@@ -2434,6 +2434,13 @@ static rsRetVal callAction(msg_t *pMsg, action_t *pAction)
 	assert(pMsg != NULL);
 	assert(pAction != NULL);
 
+	/* Make sure nodbody else modifies/uses this action object. Right now, this
+         * is important because of "message repeated n times" processing, later it will
+         * become important when we (possibly) have multiple worker threads.
+ 	 * rgerhards, 2007-12-11
+ 	 */
+	LockObj(pAction);
+
 	/* first, we need to check if this is a disabled
 	 * entry. If so, we must not further process it.
 	 * rgerhards 2005-09-26
@@ -2453,7 +2460,7 @@ static rsRetVal callAction(msg_t *pMsg, action_t *pAction)
 	}
 
 	/* don't output marks to recently written files */
-	if ((pMsg->msgFlags & MARK) && (now - pAction->f_time) < MarkInterval / 2) {
+	if ((pMsg->msgFlags & MARK) && (time(NULL) - pAction->f_time) < MarkInterval / 2) {
 		ABORT_FINALIZE(RS_RET_OK);
 	}
 
@@ -2467,14 +2474,14 @@ static rsRetVal callAction(msg_t *pMsg, action_t *pAction)
 	    !strcmp(getAPPNAME(pMsg), getAPPNAME(pAction->f_pMsg))) {
 		pAction->f_prevcount++;
 		dbgprintf("msg repeated %d times, %ld sec of %d.\n",
-		    pAction->f_prevcount, now - pAction->f_time,
+		    pAction->f_prevcount, time(NULL) - pAction->f_time,
 		    repeatinterval[pAction->f_repeatcount]);
 		MsgDestruct(pAction->f_pMsg);
 		pAction->f_pMsg = MsgAddRef(pMsg);
 		/* If domark would have logged this by now, flush it now (so we don't hold
 		 * isolated messages), but back off so we'll flush less often in the future.
 		 */
-		if (now > REPEATTIME(pAction)) {
+		if(time(NULL) > REPEATTIME(pAction)) {
 			iRet = fprintlog(pAction);
 			BACKOFF(pAction);
 		}
@@ -2497,6 +2504,7 @@ static rsRetVal callAction(msg_t *pMsg, action_t *pAction)
 	}
 
 finalize_it:
+	UnlockObj(pAction);
 	return iRet;
 }
 
@@ -2665,7 +2673,7 @@ static msgQueue *queueInit (void)
 static void queueDelete (msgQueue *q)
 {
 	pthread_mutex_destroy (q->mut);
-	free (q->mut);	
+	free (q->mut);
 	pthread_cond_destroy (q->notFull);
 	free (q->notFull);
 	pthread_cond_destroy (q->notEmpty);
@@ -3051,8 +3059,7 @@ static int parseLegacySyslogMsg(msg_t *pMsg, int flags)
 	 * MSG part of the message (as of RFC 3164).
 	 * rgerhards 2004-12-03
 	 */
-	(void) time(&now);
-	if (flags & ADDDATE) {
+	if(flags & ADDDATE) {
 		getCurrTime(&(pMsg->tTIMESTAMP)); /* use the current time! */
 	}
 
@@ -3209,7 +3216,8 @@ static int parseLegacySyslogMsg(msg_t *pMsg, int flags)
  * potential for misinterpretation, which we simply can not solve under the
  * circumstances given.
  */
-void logmsg(int pri, msg_t *pMsg, int flags)
+void
+logmsg(int pri, msg_t *pMsg, int flags)
 {
 	char *msg;
 	char PRItext[20];
@@ -3289,15 +3297,19 @@ void logmsg(int pri, msg_t *pMsg, int flags)
  * when a message was already repeated but also when a new message
  * arrived.
  * rgerhards 2007-08-01: interface changed to use action_t
+ * rgerhards, 2007-12-11: please note: THIS METHOD MUST ONLY BE
+ * CALLED AFTER THE CALLER HAS LOCKED THE pAction OBJECT! We do
+ * not do this here. Failing to do so results in all kinds of
+ * "interesting" problems!
  */
-rsRetVal fprintlog(action_t *pAction)
+rsRetVal
+fprintlog(action_t *pAction)
 {
 	msg_t *pMsgSave;	/* to save current message pointer, necessary to restore
 				   it in case it needs to be updated (e.g. repeated msgs) */
 	pMsgSave = NULL;	/* indicate message poiner not saved */
 	DEFiRet;
 	int i;
-
 	/* first check if this is a regular message or the repeation of
 	 * a previous message. If so, we need to change the message text
 	 * to "last message repeated n times" and then go ahead and write
@@ -3336,7 +3348,7 @@ rsRetVal fprintlog(action_t *pAction)
 
 	dbgprintf("Called fprintlog, logging to %s", modGetStateName(pAction->pMod));
 
-	pAction->f_time = now; /* we need this for message repeation processing TODO: why must "now" be global? */
+	time(&pAction->f_time); /* we need this for message repeation processing */
 
 	/* When we reach this point, we have a valid, non-disabled action.
 	 * So let's execute it. -- rgerhards, 2007-07-24
@@ -3360,7 +3372,7 @@ rsRetVal fprintlog(action_t *pAction)
 	}
 
 	if(iRet == RS_RET_OK)
-		pAction->f_prevcount = 0; /* message process, so we start a new cycle */
+		pAction->f_prevcount = 0; /* message processed, so we start a new cycle */
 
 finalize_it:
 	/* cleanup */
@@ -3374,12 +3386,12 @@ finalize_it:
 	if(pMsgSave != NULL) {
 		/* we had saved the original message pointer. That was
 		 * done because we needed to create a temporary one
-		 * (most often for "message repeated n time" handling. If so,
+		 * (most often for "message repeated n time" handling). If so,
 		 * we need to restore the original one now, so that procesing
 		 * can continue as normal. We also need to discard the temporary
 		 * one, as we do not like memory leaks ;) Please note that the original
 		 * message object will be discarded by our callers, so this is nothing
-		 * of our buisiness. rgerhards, 2007-07-10
+		 * of our business. rgerhards, 2007-07-10
 		 */
 		MsgDestruct(pAction->f_pMsg);
 		pAction->f_pMsg = pMsgSave;	/* restore it */
@@ -3389,7 +3401,8 @@ finalize_it:
 }
 
 
-static void reapchild()
+static void
+reapchild()
 {
 	int saved_errno = errno;
 	struct sigaction sigAct;
@@ -3412,14 +3425,16 @@ DEFFUNC_llExecFunc(domarkActions)
 	action_t *pAction = (action_t*) pData;
 
 	assert(pAction != NULL);
-
-	if (pAction->f_prevcount && now >= REPEATTIME(pAction)) {
+	
+	LockObj(pAction);
+	if (pAction->f_prevcount && time(NULL) >= REPEATTIME(pAction)) {
 		dbgprintf("flush %s: repeated %d times, %d sec.\n",
 		    modGetStateName(pAction->pMod), pAction->f_prevcount,
 		    repeatinterval[pAction->f_repeatcount]);
 		fprintlog(pAction);
 		BACKOFF(pAction);
 	}
+	UnlockObj(pAction);
 
 	return RS_RET_OK; /* we ignore errors, we can not do anything either way */
 }
@@ -3436,15 +3451,17 @@ DEFFUNC_llExecFunc(domarkActions)
  * main thread itself, which is the only thing to make sure rsyslogd will not do
  * strange things. The way it originally was seemed to work because mark occurs very
  * seldom. However, the code called was anything else but reentrant, so it was like
- * russian roulette.
- * rgerhards, 2005-10-20
+ * russian roulette. - rgerhards, 2005-10-20
+ * rgerhards, 2007-12-11: ... and it still is, if running multithreaded. Because in this
+ * case we run concurrently to the actions... I have now fixed that by using synchronization
+ * macros.
  */
-static void domark(void)
+static void
+domark(void)
 {
 	register selector_t *f;
 
 	if (MarkInterval > 0) {
-		now = time(NULL);
 		MarkSeq += TIMERINTVL;
 		if (MarkSeq >= MarkInterval) {
 			logmsgInternal(LOG_INFO, "-- MARK --", ADDDATE|MARK);
@@ -3463,7 +3480,8 @@ static void domark(void)
  * domark request. See domark() comments for further details.
  * rgerhards, 2005-10-20
  */
-static void domarkAlarmHdlr()
+static void
+domarkAlarmHdlr()
 {
 	struct sigaction sigAct;
 
@@ -4049,6 +4067,7 @@ DEFFUNC_llExecFunc(freeSelectorsActions)
 	assert(pAction != NULL);
 
 	/* flush any pending output */
+/* TODO: look at how this is done in the shutdown sequence (do we need to lock, wait?) */
 	if(pAction->f_prevcount) {
 		fprintlog(pAction);
 	}