Merge branch 'v7-stable'

Conflicts:
	grammar/rainerscript.c
	runtime/ruleset.c

5 files changed, 185 insertions, 76 deletions

diff --git a/ChangeLog b/ChangeLog
index 97114227..fbb29d0c 100644
--- a/ChangeLog
+++ b/ChangeLog
@@ -1,6 +1,16 @@
 ---------------------------------------------------------------------------
 Version 7.3.10  [devel] 2013-04-??
 - added RainerScript re_extract() function
+- bugfix: failover/action suspend did not work correctly
+  This was experienced if the retry action took more than one second
+  to complete. For suspending, a cached timestamp was used, and if the
+  retry took longer, that timestamp was already in the past. As a 
+  result, the action never was kept in suspended state, and as such
+  no failover happened. The suspend functionalit now does no longer use
+  the cached timestamp (should not have any performance implication, as
+  action suspend occurs very infrequently).
+- bugfix: nested if/prifilt conditions did not work properly
+  closes: http://bugzilla.adiscon.com/show_bug.cgi?id=415
 - templates now permit substring extraction relative to end-of-string
 - bugfix: imuxsock aborted under some conditions
   regression from ratelimiting enhancements
@@ -221,6 +231,16 @@ Version 7.2.7  [v7-stable] 2013-03-??
   The rsyslog debug log file is now continued to be written across the
   fork.
 - updated systemd files to match current systemd source
+- bugfix: failover/action suspend did not work correctly
+  This was experienced if the retry action took more than one second
+  to complete. For suspending, a cached timestamp was used, and if the
+  retry took longer, that timestamp was already in the past. As a 
+  result, the action never was kept in suspended state, and as such
+  no failover happened. The suspend functionalit now does no longer use
+  the cached timestamp (should not have any performance implication, as
+  action suspend occurs very infrequently).
+- bugfix: nested if/prifilt conditions did not work properly
+  closes: http://bugzilla.adiscon.com/show_bug.cgi?id=415
 - bugfix: script == comparison did not work properly on JSON objects
   [backport from 7.3 branch]
 - bugfix: imudp scheduling parameters did affect main thread, not imudp
diff --git a/action.c b/action.c
index 89282389..7731c988 100644
--- a/action.c
+++ b/action.c
@@ -605,13 +605,17 @@ static void actionDisable(action_t *pThis)
  * CPU time. TODO: maybe a config option for that?
  * rgerhards, 2007-08-02
  */
-static inline void actionSuspend(action_t *pThis, time_t ttNow)
+static inline void actionSuspend(action_t *pThis)
 {
-	if(ttNow == NO_TIME_PROVIDED)
-		datetime.GetTime(&ttNow);
+	time_t ttNow;
+
+	/* note: we can NOT use a cached timestamp, as time may have evolved
+	 * since caching, and this would break logic (and it actually did so!)
+	 */
+	datetime.GetTime(&ttNow);
 	pThis->ttResumeRtry = ttNow + pThis->iResumeInterval * (pThis->iNbrResRtry / 10 + 1);
 	actionSetState(pThis, ACT_STATE_SUSP);
-	DBGPRINTF("earliest retry=%d\n", (int) pThis->ttResumeRtry);
+	DBGPRINTF("action suspended, earliest retry=%d\n", (int) pThis->ttResumeRtry);
 }
 
 
@@ -631,7 +635,7 @@ static inline void actionSuspend(action_t *pThis, time_t ttNow)
  * of its inability to recover. -- rgerhards, 2010-04-26.
  */
 static inline rsRetVal
-actionDoRetry(action_t *pThis, time_t ttNow, int *pbShutdownImmediate)
+actionDoRetry(action_t *pThis, int *pbShutdownImmediate)
 {
 	int iRetries;
 	int iSleepPeriod;
@@ -642,7 +646,9 @@ actionDoRetry(action_t *pThis, time_t ttNow, int *pbShutdownImmediate)
 
 	iRetries = 0;
 	while((*pbShutdownImmediate == 0) && pThis->eState == ACT_STATE_RTRY) {
+		DBGPRINTF("actionDoRetry: enter loop, iRetries=%d\n", iRetries);
 		iRet = pThis->pMod->tryResume(pThis->pModData);
+		DBGPRINTF("actionDoRetry: action->tryResume returned %d\n", iRet);
 		if((pThis->iResumeOKinRow > 9) && (pThis->iResumeOKinRow % 10 == 0)) {
 			bTreatOKasSusp = 1;
 			pThis->iResumeOKinRow = 0;
@@ -650,16 +656,18 @@ actionDoRetry(action_t *pThis, time_t ttNow, int *pbShutdownImmediate)
 			bTreatOKasSusp = 0;
 		}
 		if((iRet == RS_RET_OK) && (!bTreatOKasSusp)) {
+			DBGPRINTF("actionDoRetry: had success RDY again (iRet=%d)\n", iRet);
 			actionSetState(pThis, ACT_STATE_RDY);
 		} else if(iRet == RS_RET_SUSPENDED || bTreatOKasSusp) {
 			/* max retries reached? */
+			DBGPRINTF("actionDoRetry: check for max retries, iResumeRetryCount %d, iRetries %d\n",
+				  pThis->iResumeRetryCount, iRetries);
 			if((pThis->iResumeRetryCount != -1 && iRetries >= pThis->iResumeRetryCount)) {
-				actionSuspend(pThis, ttNow);
+				actionSuspend(pThis);
 			} else {
 				++pThis->iNbrResRtry;
 				++iRetries;
 				iSleepPeriod = pThis->iResumeInterval;
-				ttNow += iSleepPeriod; /* not truly exact, but sufficiently... */
 				srSleep(iSleepPeriod, 0);
 				if(*pbShutdownImmediate) {
 					ABORT_FINALIZE(RS_RET_FORCE_TERM);
@@ -706,7 +714,7 @@ static rsRetVal actionTryResume(action_t *pThis, int *pbShutdownImmediate)
 	if(pThis->eState == ACT_STATE_RTRY) {
 		if(ttNow == NO_TIME_PROVIDED) /* use cached result if we have it */
 			datetime.GetTime(&ttNow);
-		CHKiRet(actionDoRetry(pThis, ttNow, pbShutdownImmediate));
+		CHKiRet(actionDoRetry(pThis, pbShutdownImmediate));
 	}
 
 	if(Debug && (pThis->eState == ACT_STATE_RTRY ||pThis->eState == ACT_STATE_SUSP)) {
@@ -1111,6 +1119,7 @@ submitBatch(action_t *pAction, batch_t *pBatch, int nElem)
 
 	assert(pBatch != NULL);
 
+	DBGPRINTF("submitBatch: enter, nElem %d\n", nElem);
 	wasDoneTo = pBatch->iDoneUpTo;
 	bDone = 0;
 	do {
@@ -1132,7 +1141,8 @@ submitBatch(action_t *pAction, batch_t *pBatch, int nElem)
 		   || localRet == RS_RET_DEFER_COMMIT) {
 			bDone = 1;
 		} else if(localRet == RS_RET_SUSPENDED) {
-			; /* do nothing, this will retry the full batch */
+			DBGPRINTF("action ret RS_RET_SUSPENDED - retry full batch\n");
+			/* do nothing, this will retry the full batch */
 		} else if(localRet == RS_RET_ACTION_FAILED) {
 			/* in this case, everything not yet committed is BAD */
 			for(i = pBatch->iDoneUpTo ; i < wasDoneTo + nElem ; ++i) {
@@ -1864,7 +1874,7 @@ addAction(action_t **ppAction, modInfo_t *pMod, void *pModData,
 	pAction->eState = ACT_STATE_RDY; /* action is enabled */
 
 	if(bSuspended)
-		actionSuspend(pAction, datetime.GetTime(NULL)); /* "good" time call, only during init and unavoidable */
+		actionSuspend(pAction);
 
 	CHKiRet(actionConstructFinalize(pAction, queueParams));
 	
diff --git a/grammar/rainerscript.c b/grammar/rainerscript.c
index 00e1e835..89cf946c 100644
--- a/grammar/rainerscript.c
+++ b/grammar/rainerscript.c
@@ -2,7 +2,7 @@
  *
  * Module begun 2011-07-01 by Rainer Gerhards
  *
- * Copyright 2011-2012 Rainer Gerhards and Adiscon GmbH.
+ * Copyright 2011-2013 Rainer Gerhards and Adiscon GmbH.
  *
  * This file is part of the rsyslog runtime library.
  *
@@ -2252,31 +2252,33 @@ cnfexprPrint(struct cnfexpr *expr, int indent)
 		break;
 	}
 }
+/* print only the given stmt 
+ * if "subtree" equals 1, the full statement subtree is printed, else
+ * really only the statement.
+ */
 void
-cnfstmtPrint(struct cnfstmt *root, int indent)
+cnfstmtPrintOnly(struct cnfstmt *stmt, int indent, sbool subtree)
 {
-	struct cnfstmt *stmt;
 	char *cstr;
-	//dbgprintf("stmt %p, indent %d, type '%c'\n", expr, indent, expr->nodetype);
-	for(stmt = root ; stmt != NULL ; stmt = stmt->next) {
-		switch(stmt->nodetype) {
-		case S_NOP:
-			doIndent(indent); dbgprintf("NOP\n");
-			break;
-		case S_STOP:
-			doIndent(indent); dbgprintf("STOP\n");
-			break;
-		case S_CALL:
-			cstr = es_str2cstr(stmt->d.s_call.name, NULL);
-			doIndent(indent); dbgprintf("CALL [%s]\n", cstr);
-			free(cstr);
-			break;
-		case S_ACT:
-			doIndent(indent); dbgprintf("ACTION %p [%s]\n", stmt->d.act, stmt->printable);
-			break;
-		case S_IF:
-			doIndent(indent); dbgprintf("IF\n");
-			cnfexprPrint(stmt->d.s_if.expr, indent+1);
+	switch(stmt->nodetype) {
+	case S_NOP:
+		doIndent(indent); dbgprintf("NOP\n");
+		break;
+	case S_STOP:
+		doIndent(indent); dbgprintf("STOP\n");
+		break;
+	case S_CALL:
+		cstr = es_str2cstr(stmt->d.s_call.name, NULL);
+		doIndent(indent); dbgprintf("CALL [%s]\n", cstr);
+		free(cstr);
+		break;
+	case S_ACT:
+		doIndent(indent); dbgprintf("ACTION %p [%s]\n", stmt->d.act, stmt->printable);
+		break;
+	case S_IF:
+		doIndent(indent); dbgprintf("IF\n");
+		cnfexprPrint(stmt->d.s_if.expr, indent+1);
+		if(subtree) {
 			doIndent(indent); dbgprintf("THEN\n");
 			cnfstmtPrint(stmt->d.s_if.t_then, indent+1);
 			if(stmt->d.s_if.t_else != NULL) {
@@ -2284,54 +2286,67 @@ cnfstmtPrint(struct cnfstmt *root, int indent)
 				cnfstmtPrint(stmt->d.s_if.t_else, indent+1);
 			}
 			doIndent(indent); dbgprintf("END IF\n");
-			break;
-		case S_SET:
-			doIndent(indent); dbgprintf("SET %s =\n",
-				          stmt->d.s_set.varname);
-			cnfexprPrint(stmt->d.s_set.expr, indent+1);
-			doIndent(indent); dbgprintf("END SET\n");
-			break;
-		case S_UNSET:
-			doIndent(indent); dbgprintf("UNSET %s\n",
-				          stmt->d.s_unset.varname);
-			break;
-		case S_PRIFILT:
-			doIndent(indent); dbgprintf("PRIFILT '%s'\n", stmt->printable);
-			pmaskPrint(stmt->d.s_prifilt.pmask, indent);
+		}
+		break;
+	case S_SET:
+		doIndent(indent); dbgprintf("SET %s =\n",
+				  stmt->d.s_set.varname);
+		cnfexprPrint(stmt->d.s_set.expr, indent+1);
+		doIndent(indent); dbgprintf("END SET\n");
+		break;
+	case S_UNSET:
+		doIndent(indent); dbgprintf("UNSET %s\n",
+				  stmt->d.s_unset.varname);
+		break;
+	case S_PRIFILT:
+		doIndent(indent); dbgprintf("PRIFILT '%s'\n", stmt->printable);
+		pmaskPrint(stmt->d.s_prifilt.pmask, indent);
+		if(subtree) {
 			cnfstmtPrint(stmt->d.s_prifilt.t_then, indent+1);
 			if(stmt->d.s_prifilt.t_else != NULL) {
 				doIndent(indent); dbgprintf("ELSE\n");
 				cnfstmtPrint(stmt->d.s_prifilt.t_else, indent+1);
 			}
 			doIndent(indent); dbgprintf("END PRIFILT\n");
-			break;
-		case S_PROPFILT:
-			doIndent(indent); dbgprintf("PROPFILT\n");
-			doIndent(indent); dbgprintf("\tProperty.: '%s'\n",
-				propIDToName(stmt->d.s_propfilt.propID));
-			if(stmt->d.s_propfilt.propName != NULL) {
-				cstr = es_str2cstr(stmt->d.s_propfilt.propName, NULL);
-				doIndent(indent);
-				dbgprintf("\tCEE-Prop.: '%s'\n", cstr);
-				free(cstr);
-			}
-			doIndent(indent); dbgprintf("\tOperation: ");
-			if(stmt->d.s_propfilt.isNegated)
-				dbgprintf("NOT ");
-			dbgprintf("'%s'\n", getFIOPName(stmt->d.s_propfilt.operation));
-			if(stmt->d.s_propfilt.pCSCompValue != NULL) {
-				doIndent(indent); dbgprintf("\tValue....: '%s'\n",
-				       rsCStrGetSzStrNoNULL(stmt->d.s_propfilt.pCSCompValue));
-			}
+		}
+		break;
+	case S_PROPFILT:
+		doIndent(indent); dbgprintf("PROPFILT\n");
+		doIndent(indent); dbgprintf("\tProperty.: '%s'\n",
+			propIDToName(stmt->d.s_propfilt.propID));
+		if(stmt->d.s_propfilt.propName != NULL) {
+			cstr = es_str2cstr(stmt->d.s_propfilt.propName, NULL);
+			doIndent(indent);
+			dbgprintf("\tCEE-Prop.: '%s'\n", cstr);
+			free(cstr);
+		}
+		doIndent(indent); dbgprintf("\tOperation: ");
+		if(stmt->d.s_propfilt.isNegated)
+			dbgprintf("NOT ");
+		dbgprintf("'%s'\n", getFIOPName(stmt->d.s_propfilt.operation));
+		if(stmt->d.s_propfilt.pCSCompValue != NULL) {
+			doIndent(indent); dbgprintf("\tValue....: '%s'\n",
+			       rsCStrGetSzStrNoNULL(stmt->d.s_propfilt.pCSCompValue));
+		}
+		if(subtree) {
 			doIndent(indent); dbgprintf("THEN\n");
 			cnfstmtPrint(stmt->d.s_propfilt.t_then, indent+1);
 			doIndent(indent); dbgprintf("END PROPFILT\n");
-			break;
-		default:
-			dbgprintf("error: unknown stmt type %u\n",
-				(unsigned) stmt->nodetype);
-			break;
 		}
+		break;
+	default:
+		dbgprintf("error: unknown stmt type %u\n",
+			(unsigned) stmt->nodetype);
+		break;
+	}
+}
+void
+cnfstmtPrint(struct cnfstmt *root, int indent)
+{
+	struct cnfstmt *stmt;
+	//dbgprintf("stmt %p, indent %d, type '%c'\n", expr, indent, expr->nodetype);
+	for(stmt = root ; stmt != NULL ; stmt = stmt->next) {
+		cnfstmtPrintOnly(stmt, indent, 1);
 	}
 }
 
@@ -3621,3 +3636,52 @@ unescapeStr(uchar *s, int len)
 		s[iDst] = '\0';
 	}
 }
+
+char *
+tokenval2str(int tok)
+{
+	if(tok < 256) return "";
+	switch(tok) {
+	case NAME: return "NAME";
+	case FUNC: return "FUNC";
+	case BEGINOBJ: return "BEGINOBJ";
+	case ENDOBJ: return "ENDOBJ";
+	case BEGIN_ACTION: return "BEGIN_ACTION";
+	case BEGIN_PROPERTY: return "BEGIN_PROPERTY";
+	case BEGIN_CONSTANT: return "BEGIN_CONSTANT";
+	case BEGIN_TPL: return "BEGIN_TPL";
+	case BEGIN_RULESET: return "BEGIN_RULESET";
+	case STOP: return "STOP";
+	case SET: return "SET";
+	case UNSET: return "UNSET";
+	case CONTINUE: return "CONTINUE";
+	case CALL: return "CALL";
+	case LEGACY_ACTION: return "LEGACY_ACTION";
+	case LEGACY_RULESET: return "LEGACY_RULESET";
+	case PRIFILT: return "PRIFILT";
+	case PROPFILT: return "PROPFILT";
+	case BSD_TAG_SELECTOR: return "BSD_TAG_SELECTOR";
+	case BSD_HOST_SELECTOR: return "BSD_HOST_SELECTOR";
+	case IF: return "IF";
+	case THEN: return "THEN";
+	case ELSE: return "ELSE";
+	case OR: return "OR";
+	case AND: return "AND";
+	case NOT: return "NOT";
+	case VAR: return "VAR";
+	case STRING: return "STRING";
+	case NUMBER: return "NUMBER";
+	case CMP_EQ: return "CMP_EQ";
+	case CMP_NE: return "CMP_NE";
+	case CMP_LE: return "CMP_LE";
+	case CMP_GE: return "CMP_GE";
+	case CMP_LT: return "CMP_LT";
+	case CMP_GT: return "CMP_GT";
+	case CMP_CONTAINS: return "CMP_CONTAINS";
+	case CMP_CONTAINSI: return "CMP_CONTAINSI";
+	case CMP_STARTSWITH: return "CMP_STARTSWITH";
+	case CMP_STARTSWITHI: return "CMP_STARTSWITHI";
+	case UMINUS: return "UMINUS";
+	default: return "UNKNOWN TOKEN";
+	}
+}
diff --git a/grammar/rainerscript.h b/grammar/rainerscript.h
index 4816951b..31b2eb93 100644
--- a/grammar/rainerscript.h
+++ b/grammar/rainerscript.h
@@ -318,6 +318,7 @@ int cnfparamvalsIsSet(struct cnfparamblk *params, struct cnfparamvals *vals);
 void varDelete(struct var *v);
 void cnfparamvalsDestruct(struct cnfparamvals *paramvals, struct cnfparamblk *blk);
 struct cnfstmt * cnfstmtNew(unsigned s_type);
+void cnfstmtPrintOnly(struct cnfstmt *stmt, int indent, sbool subtree);
 void cnfstmtPrint(struct cnfstmt *stmt, int indent);
 struct cnfstmt* scriptAddStmt(struct cnfstmt *root, struct cnfstmt *s);
 struct objlst* objlstAdd(struct objlst *root, struct cnfobj *o);
@@ -339,6 +340,7 @@ void cnfarrayContentDestruct(struct cnfarray *ar);
 char* getFIOPName(unsigned iFIOP);
 rsRetVal initRainerscript(void);
 void unescapeStr(uchar *s, int len);
+char * tokenval2str(int tok);
 
 /* debug helper */
 void cstrPrint(char *text, es_str_t *estr);
diff --git a/runtime/ruleset.c b/runtime/ruleset.c
index 66b38fc9..e3348938 100644
--- a/runtime/ruleset.c
+++ b/runtime/ruleset.c
@@ -11,7 +11,7 @@
  *
  * Module begun 2009-06-10 by Rainer Gerhards
  *
- * Copyright 2009-2012 Rainer Gerhards and Adiscon GmbH.
+ * Copyright 2009-2013 Rainer Gerhards and Adiscon GmbH.
  *
  * This file is part of the rsyslog runtime library.
  *
@@ -297,6 +297,7 @@ execIf(struct cnfstmt *stmt, batch_t *pBatch, sbool *active)
 	sbool *newAct;
 	int i;
 	sbool bRet;
+	sbool allInactive = 1;
 	DEFiRet;
 	newAct = newActive(pBatch);
 	for(i = 0 ; i < batchNumMsgs(pBatch) ; ++i) {
@@ -306,12 +307,19 @@ execIf(struct cnfstmt *stmt, batch_t *pBatch, sbool *active)
 			continue; /* will be ignored in any case */
 		if(active == NULL || active[i]) {
 			bRet = cnfexprEvalBool(stmt->d.s_if.expr, pBatch->pElem[i].pMsg);
+			allInactive = 0;
 		} else 
 			bRet = 0;
 		newAct[i] = bRet;
 		DBGPRINTF("batch: item %d: expr eval: %d\n", i, bRet);
 	}
 
+	if(allInactive) {
+		DBGPRINTF("execIf: all batch elements are inactive, holding execution\n");
+		freeActive(newAct);
+		FINALIZE;
+	}
+
 	if(stmt->d.s_if.t_then != NULL) {
 		scriptExec(stmt->d.s_if.t_then, pBatch, newAct);
 	}
@@ -319,7 +327,8 @@ execIf(struct cnfstmt *stmt, batch_t *pBatch, sbool *active)
 		for(i = 0 ; i < batchNumMsgs(pBatch) ; ++i) {
 			if(*(pBatch->pbShutdownImmediate))
 				FINALIZE;
-			if(pBatch->eltState[i] != BATCH_STATE_DISC)
+			if(pBatch->eltState[i] != BATCH_STATE_DISC
+			   && (active == NULL || active[i]))
 				newAct[i] = !newAct[i];
 			}
 		scriptExec(stmt->d.s_if.t_else, pBatch, newAct);
@@ -364,7 +373,8 @@ execPRIFILT(struct cnfstmt *stmt, batch_t *pBatch, sbool *active)
 		for(i = 0 ; i < batchNumMsgs(pBatch) ; ++i) {
 			if(*(pBatch->pbShutdownImmediate))
 				return;
-			if(pBatch->eltState[i] != BATCH_STATE_DISC)
+			if(pBatch->eltState[i] != BATCH_STATE_DISC
+			   && (active == NULL || active[i]))
 				newAct[i] = !newAct[i];
 			}
 		scriptExec(stmt->d.s_prifilt.t_else, pBatch, newAct);
@@ -504,7 +514,11 @@ scriptExec(struct cnfstmt *root, batch_t *pBatch, sbool *active)
 	struct cnfstmt *stmt;
 
 	for(stmt = root ; stmt != NULL ; stmt = stmt->next) {
-dbgprintf("RRRR: scriptExec: batch of %d elements, active %p, stmt %p, nodetype %u\n", batchNumMsgs(pBatch), active, stmt, stmt->nodetype);
+		if(Debug) {
+			dbgprintf("scriptExec: batch of %d elements, active %p, active[0]:%d\n",
+				  batchNumMsgs(pBatch), active, (active == NULL ? 1 : active[0]));
+			cnfstmtPrintOnly(stmt, 2, 0);
+		}
 		switch(stmt->nodetype) {
 		case S_NOP:
 			break;
@@ -521,7 +535,6 @@ dbgprintf("RRRR: scriptExec: batch of %d elements, active %p, stmt %p, nodetype
 			execUnset(stmt, pBatch, active);
 			break;
 		case S_CALL:
-			DBGPRINTF("calling ruleset\n"); // TODO: add Name
 			scriptExec(stmt->d.s_call.stmt, pBatch, active);
 			break;
 		case S_IF: