From 31fae7b93d7aa94b7b3fcbfdf101328230ea6302 Mon Sep 17 00:00:00 2001 From: Rainer Gerhards Date: Thu, 24 Jun 2010 12:13:48 +0200 Subject: bugfix: "$ActionExecOnlyWhenPreviousIsSuspended on" was broken Note that, as it looks, the directive was already broken in previous v5 versions. So while I solved what looked like a (intentional) regression from the performance tuning, I actually solved a previous regression as well ;) I have also added new test cases to the testbench in order to capture such problems in the future. This version does now look pretty good in shape. --- ChangeLog | 1 + action.c | 17 +++++++++----- runtime/batch.h | 19 ++++++++++++++++ runtime/rsyslog.h | 2 +- runtime/rule.c | 28 +++++------------------- runtime/ruleset.c | 1 + tests/Makefile.am | 12 ++++++++++ tests/diag.sh | 7 +++--- tests/execonlywhenprevsuspended.sh | 13 +++++++++++ tests/execonlywhenprevsuspended2.sh | 17 ++++++++++++++ tests/execonlywhenprevsuspended3.sh | 17 ++++++++++++++ tests/execonlywhenprevsuspended4.sh | 16 ++++++++++++++ tests/testsuites/execonlywhenprevsuspended.conf | 13 +++++++++++ tests/testsuites/execonlywhenprevsuspended2.conf | 19 ++++++++++++++++ tests/testsuites/execonlywhenprevsuspended3.conf | 18 +++++++++++++++ tests/testsuites/execonlywhenprevsuspended4.conf | 15 +++++++++++++ 16 files changed, 184 insertions(+), 31 deletions(-) create mode 100755 tests/execonlywhenprevsuspended.sh create mode 100755 tests/execonlywhenprevsuspended2.sh create mode 100755 tests/execonlywhenprevsuspended3.sh create mode 100755 tests/execonlywhenprevsuspended4.sh create mode 100644 tests/testsuites/execonlywhenprevsuspended.conf create mode 100644 tests/testsuites/execonlywhenprevsuspended2.conf create mode 100644 tests/testsuites/execonlywhenprevsuspended3.conf create mode 100644 tests/testsuites/execonlywhenprevsuspended4.conf diff --git a/ChangeLog b/ChangeLog index f62ac6ad..6513fe79 100644 --- a/ChangeLog +++ b/ChangeLog @@ -14,6 +14,7 @@ Version 5.5.6 [DEVEL] (rgerhards), 2010-06-?? * RSYSLOG_TraditionalForwardFormat - bugfix: mutexes used to similate atomic instructions were not destructed - bugfix: regression caused more locking action in msg.c than necessary +- bugfix: "$ActionExecOnlyWhenPreviousIsSuspended on" was broken --------------------------------------------------------------------------- Version 5.5.5 [DEVEL] (rgerhards), 2010-05-20 - added new cancel-reduced action thread termination method diff --git a/action.c b/action.c index 83929c2e..21a1ff01 100644 --- a/action.c +++ b/action.c @@ -832,6 +832,7 @@ finishBatch(action_t *pThis, batch_t *pBatch) /* flag messages as committed */ for(i = 0 ; i < pBatch->nElem ; ++i) { batchSetElemState(pBatch, i, BATCH_STATE_COMM); + pBatch->pElem[i].bPrevWasSuspended = 0; /* we had success! */ } break; case RS_RET_SUSPENDED: @@ -885,12 +886,14 @@ tryDoAction(action_t *pAction, batch_t *pBatch, int *pnElem) while(iElemProcessed <= *pnElem && i < pBatch->nElem) { if(*(pBatch->pbShutdownImmediate)) ABORT_FINALIZE(RS_RET_FORCE_TERM); - if(pBatch->pElem[i].bFilterOK && pBatch->pElem[i].state != BATCH_STATE_DISC) { + if( pBatch->pElem[i].bFilterOK + && pBatch->pElem[i].state != BATCH_STATE_DISC + && ((pAction->bExecWhenPrevSusp == 0) || pBatch->pElem[i].bPrevWasSuspended) ) { pMsg = (msg_t*) pBatch->pElem[i].pUsrp; localRet = actionProcessMessage(pAction, pMsg, pBatch->pElem[i].staticActParams); DBGPRINTF("action call returned %d\n", localRet); /* Note: we directly modify the batch object state, because we know that - * wo do not overwrite DISC indicators! + * wo do not overwrite BATCH_STATE_DISC indicators! */ if(localRet == RS_RET_OK) { /* mark messages as committed */ @@ -965,9 +968,13 @@ submitBatch(action_t *pAction, batch_t *pBatch, int nElem) } else if(localRet == RS_RET_SUSPENDED) { ; /* do nothing, this will retry the full batch */ } else if(localRet == RS_RET_ACTION_FAILED) { - /* in this case, the whole batch can not be processed */ - for(i = 0 ; i < nElem ; ++i) { - batchSetElemState(pBatch, i, BATCH_STATE_BAD); + /* in this case, everything not yet committed is BAD */ + for(i = pBatch->iDoneUpTo ; i < nElem ; ++i) { + if( pBatch->pElem[i].state != BATCH_STATE_DISC + && pBatch->pElem[i].state != BATCH_STATE_COMM ) { + pBatch->pElem[i].state = BATCH_STATE_BAD; + pBatch->pElem[i].bPrevWasSuspended = 1; + } } bDone = 1; } else { diff --git a/runtime/batch.h b/runtime/batch.h index 80621631..b555fc2a 100644 --- a/runtime/batch.h +++ b/runtime/batch.h @@ -174,4 +174,23 @@ batchInit(batch_t *pBatch, int maxElem) { finalize_it: RETiRet; } + + +/* primarily a helper for debug purposes, get human-readble name of state */ +static inline char * +batchState2String(batch_state_t state) { + switch(state) { + case BATCH_STATE_RDY: + return "BATCH_STATE_RDY"; + case BATCH_STATE_BAD: + return "BATCH_STATE_BAD"; + case BATCH_STATE_SUB: + return "BATCH_STATE_SUB"; + case BATCH_STATE_COMM: + return "BATCH_STATE_COMM"; + case BATCH_STATE_DISC: + return "BATCH_STATE_DISC"; + } + return "ERROR, batch state not known!"; +} #endif /* #ifndef BATCH_H_INCLUDED */ diff --git a/runtime/rsyslog.h b/runtime/rsyslog.h index ab9fb738..2279856e 100644 --- a/runtime/rsyslog.h +++ b/runtime/rsyslog.h @@ -412,7 +412,7 @@ enum rsRetVal_ /** return value. All methods return this if not specified oth RS_RET_RSCORE_TOO_OLD = -2120, /**< rsyslog core is too old for ... (eg this plugin) */ RS_RET_DEFER_COMMIT = -2121, /**< output plugin status: not yet committed (an OK state!) */ RS_RET_PREVIOUS_COMMITTED = -2122, /**< output plugin status: previous record was committed (an OK state!) */ - RS_RET_ACTION_FAILED = -2123, /**< action failed and is now suspended (consider this permanent for the time being) */ + RS_RET_ACTION_FAILED = -2123, /**< action failed and is now suspended */ RS_RET_NONFATAL_CONFIG_ERR = -2124, /**< non-fatal error during config processing */ RS_RET_NON_SIZELIMITCMD = -2125, /**< size limit for file defined, but no size limit command given */ RS_RET_SIZELIMITCMD_DIDNT_RESOLVE = -2126, /**< size limit command did not resolve situation */ diff --git a/runtime/rule.c b/runtime/rule.c index c3c974bf..42773768 100644 --- a/runtime/rule.c +++ b/runtime/rule.c @@ -99,29 +99,9 @@ DEFFUNC_llExecFunc(processBatchDoActions) action_t *pAction = (action_t*) pData; batch_t *pBatch = (batch_t*) pParam; - assert(pAction != NULL); - -#warning execonly when prev suspended functionality missing! -#if 0 // TODO: move this to the action object - if((pAction->bExecWhenPrevSusp == 1) && (pDoActData->bPrevWasSuspended == 0)) { - dbgprintf("not calling action because the previous one is not suspended\n"); - ABORT_FINALIZE(RS_RET_OK); - } -#endif - + DBGPRINTF("Processing next action\n"); iRetMod = pAction->submitToActQ(pAction, pBatch); -#if 0 // TODO: this must be done inside the action as well! - if(iRetMod == RS_RET_DISCARDMSG) { - ABORT_FINALIZE(RS_RET_DISCARDMSG); - } else if(iRetMod == RS_RET_SUSPENDED) { - /* indicate suspension for next module to be called */ - pDoActData->bPrevWasSuspended = 1; - } else { - pDoActData->bPrevWasSuspended = 0; - } -#endif - RETiRet; } @@ -291,11 +271,15 @@ processBatch(rule_t *pThis, batch_t *pBatch) ISOBJ_TYPE_assert(pThis, rule); assert(pBatch != NULL); - /* first check the filters... */ + /* first check the filters and reset status variables */ for(i = 0 ; i < batchNumMsgs(pBatch) && !*(pBatch->pbShutdownImmediate) ; ++i) { CHKiRet(shouldProcessThisMessage(pThis, (msg_t*)(pBatch->pElem[i].pUsrp), &(pBatch->pElem[i].bFilterOK))); // TODO: really abort on error? 2010-06-10 + if(pBatch->pElem[i].bFilterOK) { + /* re-init only when actually needed (cache write cost!) */ + pBatch->pElem[i].bPrevWasSuspended = 0; + } } CHKiRet(llExecFunc(&pThis->llActList, processBatchDoActions, pBatch)); diff --git a/runtime/ruleset.c b/runtime/ruleset.c index 8d6a1c2f..df7f8daa 100644 --- a/runtime/ruleset.c +++ b/runtime/ruleset.c @@ -146,6 +146,7 @@ DEFFUNC_llExecFunc(processBatchDoRules) { rsRetVal iRet; ISOBJ_TYPE_assert(pData, rule); + dbgprintf("Processing next rule\n"); iRet = rule.ProcessBatch((rule_t*) pData, (batch_t*) pParam); dbgprintf("ruleset: get iRet %d from rule.ProcessMsg()\n", iRet); return iRet; diff --git a/tests/Makefile.am b/tests/Makefile.am index ba0bb7ba..a0cc8c7d 100644 --- a/tests/Makefile.am +++ b/tests/Makefile.am @@ -35,6 +35,10 @@ TESTS = $(TESTRUNS) cfg.sh \ queue-persist.sh \ pipeaction.sh \ execonlyonce.sh \ + execonlywhenprevsuspended.sh \ + execonlywhenprevsuspended2.sh \ + execonlywhenprevsuspended3.sh \ + execonlywhenprevsuspended4.sh \ pipe_noreader.sh \ dircreate_dflt.sh \ dircreate_off.sh \ @@ -269,6 +273,14 @@ EXTRA_DIST= 1.rstest 2.rstest 3.rstest err1.rstest \ execonlyonce.sh \ testsuites/execonlyonce.conf \ testsuites/execonlyonce.data \ + execonlywhenprevsuspended.sh \ + testsuites/execonlywhenprevsuspended.sh \ + execonlywhenprevsuspended2.sh \ + testsuites/execonlywhenprevsuspended2.sh \ + execonlywhenprevsuspended3.sh \ + testsuites/execonlywhenprevsuspended3.sh \ + execonlywhenprevsuspended4.sh \ + testsuites/execonlywhenprevsuspended4.sh \ tabescape_dflt.sh \ testsuites/tabescape_dflt.conf \ testsuites/1.tabescape_dflt \ diff --git a/tests/diag.sh b/tests/diag.sh index 5b74a6dc..3d072880 100755 --- a/tests/diag.sh +++ b/tests/diag.sh @@ -19,7 +19,7 @@ case $1 in rm -f rsyslog.action.*.include rm -f rsyslogd.started work-*.conf rsyslog.random.data rm -f rsyslogd2.started work-*.conf - rm -f work rsyslog.out.log rsyslog.out.log.save # common work files + rm -f work rsyslog.out.log rsyslog2.out.log rsyslog.out.log.save # common work files rm -rf test-spool test-logdir rm -f rsyslog.out.*.log work-presort rsyslog.pipe rm -f core.* vgcore.* @@ -27,7 +27,7 @@ case $1 in ;; 'exit') rm -f rsyslogd.started work-*.conf diag-common.conf rm -f rsyslogd2.started diag-common2.conf rsyslog.action.*.include - rm -f work rsyslog.out.log rsyslog.out.log.save # common work files + rm -f work rsyslog.out.log rsyslog2.out.log rsyslog.out.log.save # common work files rm -rf test-spool test-logdir rm -f rsyslog.out.*.log rsyslog.random.data work-presort rsyslog.pipe echo ------------------------------------------------------------------------------- @@ -115,7 +115,8 @@ case $1 in rm -f work2 sort < rsyslog2.out.log > work2 # $4... are just to have the abilit to pass in more options... - ./chkseq -fwork2 -v -s$2 -e$3 $4 $5 $6 $7 + # add -v to chkseq if you need more verbose output + ./chkseq -fwork2 -s$2 -e$3 $4 $5 $6 $7 if [ "$?" -ne "0" ]; then echo "sequence error detected" exit 1 diff --git a/tests/execonlywhenprevsuspended.sh b/tests/execonlywhenprevsuspended.sh new file mode 100755 index 00000000..624f64af --- /dev/null +++ b/tests/execonlywhenprevsuspended.sh @@ -0,0 +1,13 @@ +# we test the execonly if previous is suspended directive. This is the +# most basic test which soley tests a singel case but no dependencies within +# the ruleset. +# rgerhards, 2010-06-23 +echo ===================================================================================== +echo \[execonlywhenprevsuspended.sh\]: test execonly...suspended functionality simple case +source $srcdir/diag.sh init +source $srcdir/diag.sh startup execonlywhenprevsuspended.conf +source $srcdir/diag.sh injectmsg 0 1000 +source $srcdir/diag.sh shutdown-when-empty # shut down rsyslogd when done processing messages +source $srcdir/diag.sh wait-shutdown +source $srcdir/diag.sh seq-check 1 999 +source $srcdir/diag.sh exit diff --git a/tests/execonlywhenprevsuspended2.sh b/tests/execonlywhenprevsuspended2.sh new file mode 100755 index 00000000..8af1b4d8 --- /dev/null +++ b/tests/execonlywhenprevsuspended2.sh @@ -0,0 +1,17 @@ +# we test the execonly if previous is suspended directive. For this, +# we have an action that is suspended for all messages but the second. +# we write two files: one only if the output is suspended and the other one +# in all cases. This should thouroughly check the logic involved. +# rgerhards, 2010-06-23 +echo =============================================================================== +echo \[execonlywhenprevsuspended2.sh\]: test execonly...suspended functionality +source $srcdir/diag.sh init +source $srcdir/diag.sh startup execonlywhenprevsuspended2.conf +source $srcdir/diag.sh injectmsg 0 1000 +source $srcdir/diag.sh shutdown-when-empty # shut down rsyslogd when done processing messages +source $srcdir/diag.sh wait-shutdown +echo check file 1 +source $srcdir/diag.sh seq-check 1 999 +echo check file 2 +source $srcdir/diag.sh seq-check2 0 999 +source $srcdir/diag.sh exit diff --git a/tests/execonlywhenprevsuspended3.sh b/tests/execonlywhenprevsuspended3.sh new file mode 100755 index 00000000..408aeba4 --- /dev/null +++ b/tests/execonlywhenprevsuspended3.sh @@ -0,0 +1,17 @@ +# we test the execonly if previous is suspended directive. +# This test checks if, within the same rule, one action can be set +# to emit only if the previous was suspended while the next action +# always sends data. +# rgerhards, 2010-06-24 +echo =============================================================================== +echo \[execonlywhenprevsuspended3.sh\]: test execonly...suspended functionality +source $srcdir/diag.sh init +source $srcdir/diag.sh startup execonlywhenprevsuspended3.conf +source $srcdir/diag.sh injectmsg 0 1000 +source $srcdir/diag.sh shutdown-when-empty # shut down rsyslogd when done processing messages +source $srcdir/diag.sh wait-shutdown +echo check file 1 +source $srcdir/diag.sh seq-check 1 999 +echo check file 2 +source $srcdir/diag.sh seq-check2 0 999 +source $srcdir/diag.sh exit diff --git a/tests/execonlywhenprevsuspended4.sh b/tests/execonlywhenprevsuspended4.sh new file mode 100755 index 00000000..87008b33 --- /dev/null +++ b/tests/execonlywhenprevsuspended4.sh @@ -0,0 +1,16 @@ +# we test the execonly if previous is suspended directive. +# This test checks if multiple backup actions can be defined. +# rgerhards, 2010-06-24 +echo =============================================================================== +echo \[execonlywhenprevsuspended4.sh\]: test execonly..suspended multi backup action +source $srcdir/diag.sh init +source $srcdir/diag.sh startup execonlywhenprevsuspended4.conf +source $srcdir/diag.sh injectmsg 0 1000 +source $srcdir/diag.sh shutdown-when-empty # shut down rsyslogd when done processing messages +source $srcdir/diag.sh wait-shutdown +source $srcdir/diag.sh seq-check 1 999 +if [[ -s rsyslog2.out.log ]] ; then + echo failure: second output file has data where it should be empty + exit 1 +fi ; +source $srcdir/diag.sh exit diff --git a/tests/testsuites/execonlywhenprevsuspended.conf b/tests/testsuites/execonlywhenprevsuspended.conf new file mode 100644 index 00000000..04dc6b59 --- /dev/null +++ b/tests/testsuites/execonlywhenprevsuspended.conf @@ -0,0 +1,13 @@ +# See main .sh file for info +# rgerhards, 2010-06-23 +$IncludeConfig diag-common.conf + +# omtesting provides the ability to cause "SUSPENDED" action state +$ModLoad ../plugins/omtesting/.libs/omtesting + +$MainMsgQueueTimeoutShutdown 100000 +$template outfmt,"%msg:F,58:2%\n" + +:msg, contains, "msgnum:" :omtesting:fail 2 0 +$ActionExecOnlyWhenPreviousIsSuspended on +& ./rsyslog.out.log;outfmt diff --git a/tests/testsuites/execonlywhenprevsuspended2.conf b/tests/testsuites/execonlywhenprevsuspended2.conf new file mode 100644 index 00000000..86aa8832 --- /dev/null +++ b/tests/testsuites/execonlywhenprevsuspended2.conf @@ -0,0 +1,19 @@ +# See main .sh file for info +# rgerhards, 2010-06-23 +$IncludeConfig diag-common.conf + +# omtesting provides the ability to cause "SUSPENDED" action state +$ModLoad ../plugins/omtesting/.libs/omtesting + +$MainMsgQueueTimeoutShutdown 100000 +$template outfmt,"%msg:F,58:2%\n" + +:msg, contains, "msgnum:" :omtesting:fail 2 0 +$ActionExecOnlyWhenPreviousIsSuspended on +& ./rsyslog.out.log;outfmt +# note that we MUST re-set PrevSusp, else it will remain active +# for all other actions as well (this tells us how bad the current +# config language is...). -- rgerhards, 2010-06-24 +$ActionExecOnlyWhenPreviousIsSuspended off + +:msg, contains, "msgnum:" ./rsyslog2.out.log;outfmt diff --git a/tests/testsuites/execonlywhenprevsuspended3.conf b/tests/testsuites/execonlywhenprevsuspended3.conf new file mode 100644 index 00000000..d2750e9a --- /dev/null +++ b/tests/testsuites/execonlywhenprevsuspended3.conf @@ -0,0 +1,18 @@ +# See main .sh file for info +# rgerhards, 2010-06-23 +$IncludeConfig diag-common.conf + +# omtesting provides the ability to cause "SUSPENDED" action state +$ModLoad ../plugins/omtesting/.libs/omtesting + +$MainMsgQueueTimeoutShutdown 100000 +$template outfmt,"%msg:F,58:2%\n" + +:msg, contains, "msgnum:" :omtesting:fail 2 0 +$ActionExecOnlyWhenPreviousIsSuspended on +& ./rsyslog.out.log;outfmt +# note that we MUST re-set PrevSusp, else it will remain active +# for all other actions as well (this tells us how bad the current +# config language is...). -- rgerhards, 2010-06-24 +$ActionExecOnlyWhenPreviousIsSuspended off +& ./rsyslog2.out.log;outfmt diff --git a/tests/testsuites/execonlywhenprevsuspended4.conf b/tests/testsuites/execonlywhenprevsuspended4.conf new file mode 100644 index 00000000..04bc3805 --- /dev/null +++ b/tests/testsuites/execonlywhenprevsuspended4.conf @@ -0,0 +1,15 @@ +# See main .sh file for info +# rgerhards, 2010-06-23 +$IncludeConfig diag-common.conf + +# omtesting provides the ability to cause "SUSPENDED" action state +$ModLoad ../plugins/omtesting/.libs/omtesting + +$MainMsgQueueTimeoutShutdown 100000 +$template outfmt,"%msg:F,58:2%\n" + +:msg, contains, "msgnum:" :omtesting:fail 2 0 +$ActionExecOnlyWhenPreviousIsSuspended on +& ./rsyslog.out.log;outfmt +# note that $ActionExecOnlyWhenPreviousIsSuspended on is still active! +& ./rsyslog2.out.log;outfmt -- cgit v1.2.3