Mailing List Archive: Re: Rsyslog 3.21.2 - $ActionExecOnlyEveryNthTime bug?

Hi Craig,

I don't see this in my lab, everything works correct. May it be that you
did not include some of the (automatic) initial messages in your
picture? In any case, a full debug log would be useful to track this
down. After my sig, you find the relevant part of my lab debug FYI.

Relevant part of rsyslog.conf:
$ActionExecOnlyEveryNthTime 3
:msg, contains, "test" -/rsyslog/logfile

Commands issued:
$ logger 1
$ logger 2
$ logger 3
$ logger 4
$ logger 5
$ logger 6

And the output file had:
2008-12-19T12:17:44.548207+01:00 rf10up rger: test 3
2008-12-19T12:17:53.522265+01:00 rf10up rger: test 6

Note that in this setup I made sure that no other messages than those
with the string "test" went into the log file. Otherwise, the counters
would have been affected by some startup messages.

Rainer

5455.946426832:main queue:Reg/w0: main queue:Reg/w0: worker IDLE,
waiting for work.
5460.051992823:imuxsock.c: Message from UNIX socket: #4
5460.066209819:imuxsock.c: logmsg: flags 4, pri 13, from 'rf10up', msg
Dec 19 12:17:40 rger: test 1
5460.066408445:imuxsock.c: Message has legacy syslog format.
5460.095581070:imuxsock.c: main queue: entry added, size now 1 entries
5460.096265506:imuxsock.c: wtpAdviseMaxWorkers signals busy
5460.096810820:imuxsock.c: main queue: EnqueueMsg advised worker start
5460.097417035:main queue:Reg/w0: main queue: entering rate limiter
5460.097797246:main queue:Reg/w0: main queue: entry deleted, state 0,
size now 0 entries
5460.098493974:main queue:Reg/w0: Filter: check for property
'msg' (value ' test 1') contains 'test': TRUE
5460.105295873:main queue:Reg/w0: action 0x4c64438 passed 1 times to
execution - less than neded - discarding
5460.109592735:main queue:Reg/w0: main queue: entering rate limiter
5460.110192245:main queue:Reg/w0: main queue:Reg/w0: worker IDLE,
waiting for work.
5460.115576662:imuxsock.c: --------imuxsock calling select, active file
descriptors (max 4): 4
5462.317878786:imuxsock.c: Message from UNIX socket: #4
5462.318410132:imuxsock.c: logmsg: flags 4, pri 13, from 'rf10up', msg
Dec 19 12:17:42 rger: test 2
5462.318585850:imuxsock.c: Message has legacy syslog format.
5462.319012436:imuxsock.c: main queue: entry added, size now 1 entries
5462.319271125:imuxsock.c: wtpAdviseMaxWorkers signals busy
5462.319537636:imuxsock.c: main queue: EnqueueMsg advised worker start
5462.319871473:main queue:Reg/w0: main queue: entering rate limiter
5462.320174580:main queue:Reg/w0: main queue: entry deleted, state 0,
size now 0 entries
5462.320470145:main queue:Reg/w0: Filter: check for property
'msg' (value ' test 2') contains 'test': TRUE
5462.321508812:main queue:Reg/w0: action 0x4c64438 passed 2 times to
execution - less than neded - discarding
5462.321825608:main queue:Reg/w0: main queue: entering rate limiter
5462.322078710:main queue:Reg/w0: main queue:Reg/w0: worker IDLE,
waiting for work.
5462.322350529:imuxsock.c: --------imuxsock calling select, active file
descriptors (max 4): 4
5464.547937451:imuxsock.c: Message from UNIX socket: #4
5464.548420747:imuxsock.c: logmsg: flags 4, pri 13, from 'rf10up', msg
Dec 19 12:17:44 rger: test 3
5464.548613227:imuxsock.c: Message has legacy syslog format.
5464.549042885:imuxsock.c: main queue: entry added, size now 1 entries
5464.549287885:imuxsock.c: wtpAdviseMaxWorkers signals busy
5464.549571158:imuxsock.c: main queue: EnqueueMsg advised worker start
5464.549888793:main queue:Reg/w0: main queue: entering rate limiter
5464.550211176:main queue:Reg/w0: main queue: entry deleted, state 0,
size now 0 entries
5464.550500036:main queue:Reg/w0: Filter: check for property
'msg' (value ' test 3') contains 'test': TRUE
5464.551797950:main queue:Reg/w0: Called action, logging to builtin-file
5464.605776776:main queue:Reg/w0: (/rsyslog/logfile)
5464.606371817:imuxsock.c: --------imuxsock calling select, active file
descriptors (max 4): 4
5464.627358305:main queue:Reg/w0: main queue: entering rate limiter
5464.628009218:main queue:Reg/w0: main queue:Reg/w0: worker IDLE,
waiting for work.
5469.671232071:imuxsock.c: Message from UNIX socket: #4
5469.671772915:imuxsock.c: logmsg: flags 4, pri 13, from 'rf10up', msg
Dec 19 12:17:49 rger: test 4
5469.671950031:imuxsock.c: Message has legacy syslog format.
5469.672340578:imuxsock.c: main queue: entry added, size now 1 entries
5469.672597591:imuxsock.c: wtpAdviseMaxWorkers signals busy
5469.672931428:imuxsock.c: main queue: EnqueueMsg advised worker start
5469.673234256:main queue:Reg/w0: main queue: entering rate limiter
5469.673563065:main queue:Reg/w0: main queue: entry deleted, state 0,
size now 0 entries
5469.673893829:main queue:Reg/w0: Filter: check for property
'msg' (value ' test 4') contains 'test': TRUE
5469.674471829:main queue:Reg/w0: action 0x4c64438 passed 1 times to
execution - less than neded - discarding
5469.674788066:main queue:Reg/w0: main queue: entering rate limiter
5469.675042006:main queue:Reg/w0: main queue:Reg/w0: worker IDLE,
waiting for work.
5469.675316618:imuxsock.c: --------imuxsock calling select, active file
descriptors (max 4): 4
5471.443424737:imuxsock.c: Message from UNIX socket: #4
5471.443973403:imuxsock.c: logmsg: flags 4, pri 13, from 'rf10up', msg
Dec 19 12:17:51 rger: test 5
5471.444148283:imuxsock.c: Message has legacy syslog format.
5471.444550564:imuxsock.c: main queue: entry added, size now 1 entries
5471.444845291:imuxsock.c: wtpAdviseMaxWorkers signals busy
5471.445187788:imuxsock.c: main queue: EnqueueMsg advised worker start
5471.445489499:main queue:Reg/w0: main queue: entering rate limiter
5471.445842612:main queue:Reg/w0: main queue: entry deleted, state 0,
size now 0 entries
5471.446121136:main queue:Reg/w0: Filter: check for property
'msg' (value ' test 5') contains 'test': TRUE
5471.446527886:main queue:Reg/w0: action 0x4c64438 passed 2 times to
execution - less than neded - discarding
5471.446837140:main queue:Reg/w0: main queue: entering rate limiter
5471.447091079:main queue:Reg/w0: main queue:Reg/w0: worker IDLE,
waiting for work.
5471.447366530:imuxsock.c: --------imuxsock calling select, active file
descriptors (max 4): 4
5473.522029412:imuxsock.c: Message from UNIX socket: #4
5473.522550422:imuxsock.c: logmsg: flags 4, pri 13, from 'rf10up', msg
Dec 19 12:17:53 rger: test 6
5473.522766368:imuxsock.c: Message has legacy syslog format.
5473.523162224:imuxsock.c: main queue: entry added, size now 1 entries
5473.523404989:imuxsock.c: wtpAdviseMaxWorkers signals busy
5473.523727931:imuxsock.c: main queue: EnqueueMsg advised worker start
5473.524011204:main queue:Reg/w0: main queue: entering rate limiter
5473.524328279:main queue:Reg/w0: main queue: entry deleted, state 0,
size now 0 entries
5473.524621330:main queue:Reg/w0: Filter: check for property
'msg' (value ' test 6') contains 'test': TRUE
5473.525016627:main queue:Reg/w0: Called action, logging to builtin-file
5473.525803589:main queue:Reg/w0: (/rsyslog/logfile)
5473.526170949:main queue:Reg/w0: main queue: entering rate limiter
5473.526423213:main queue:Reg/w0: main queue:Reg/w0: worker IDLE,
waiting for work.
5473.526753139:imuxsock.c: --------imuxsock calling select, active file
descriptors (max 4): 4

On Thu, 2008-12-18 at 12:51 -0500, Becker, Craig (DOB) wrote:
> The action $ActionExecOnlyEveryNthTime is not sending the Nth message
> but the first message, then the Nth + 1 message. For example, if I
> set the $ActionExecOnlyEveryNthTime 3 The 1st, 4th, 7th, etc. message
> are sent instead of the 3rd, 6th, 9th, etc. Has this bug (if it is a
> bug) been fixed in a later version?
>
>
>
> Iâ€™m enjoying learning this product and appreciate all the hard work
> that has gone into it.
>
>
>
> Thanks,
>
>
>
> Craig E. Becker
> IT Specialist II
> System Administrator
> Division of the Budget
> 518-473-1322
> craig.becker@budget.state.ny.us
>
>
>
>
>
>
>
> HTML:
> ______________________________________________________________________
> This e-mail, including any attachments, may be confidential,
> privileged or otherwise legally protected. If you have received this
> e-mail in error, or from someone who was not authorized to send it to
> you, do not disseminate, copy or otherwise use this e-mail or its
> attachments. Please notify the sender immediately if you have received
> this e-mail by mistake, and delete it from your system.

_______________________________________________
rsyslog mailing list
http://lists.adiscon.net/mailman/listinfo/rsyslog
http://www.rsyslog.com

--sorry, my mailer didn't reply to the list for some reason--

Sounds like a too-old version. Jepp, you mention 3.21.2 in the subject, I think the directives were introduced some time later.

Rainer

> -----Original Message-----
> From: Becker, Craig (DOB) [mailto:Craig.Becker@budget.state.ny.us]
> Sent: Friday, December 19, 2008 5:34 PM
> To: rsyslog@lists.adiscon.com
> Cc: Rainer Gerhards
> Subject: RE: Rsyslog 3.21.2 - $ActionExecOnlyEveryNthTime bug?
>
> Thanks for the help. When I start Rsyslog in Debug mode, I get the
> following errors:
>
>
> rsyslogd: invalid or yet-unknown config file command - have you
> forgotten to load a module? [try http://www.rsyslog.com/e/3003 ]
> rsyslogd: the last error occured in /etc/rsyslog.conf, line 404
> rsyslogd: invalid or yet-unknown config file command - have you
> forgotten to load a module? [try http://www.rsyslog.com/e/3003 ]
> rsyslogd: the last error occured in /etc/rsyslog.conf, line 405
> rsyslogd: invalid or yet-unknown config file command - have you
> forgotten to load a module? [try http://www.rsyslog.com/e/3003 ]
> rsyslogd: the last error occured in /etc/rsyslog.conf, line 698
> rsyslogd: invalid or yet-unknown config file command - have you
> forgotten to load a module? [try http://www.rsyslog.com/e/3003 ]
> rsyslogd: the last error occured in /etc/rsyslog.conf, line 699
>
> These errors correspond to the actions:
>
> $ActionExecOnlyEveryNthTime 50 #Lines 404 & 698
> $ActionExecOnlyEveryNthTimeTimeout 1800 #Lines 405 & 699
>
> These are the Modules loaded:
>
> #______All Modules loaded here__________
> $ModLoad immark.so # provides --MARK-- message capability
> $ModLoad imuxsock.so # provides support for local system logging
> (e.g. via logger command)
> $ModLoad imklog.so # kernel logging (formerly provided by
> rklogd)
> $ModLoad ommail # This mod enables sending E-mail on alerts
> $ModLoad imudp.so # provides UDP syslog reception
> $ModLoad imtcp.so # provides TCP syslog reception
>
> I tried to add all the modules I have access to without fixing the
> issue. Is there a module missing or should I look to another version?
> The strange thing is that the command actually works after the first
> email is sent (i.e. The 1st, 51st, 101st messages are sent).
>
> Any help would be appreciated.
>
> Thanks again,
> Craig
>
>
>
> -----Original Message-----
> From: Rainer Gerhards [mailto:rgerhards@hq.adiscon.com]
> Sent: Friday, December 19, 2008 6:24 AM
> To: rsyslog@lists.adiscon.com
> Cc: Becker, Craig (DOB)
> Subject: Re: Rsyslog 3.21.2 - $ActionExecOnlyEveryNthTime bug?
>
> Hi Craig,
>
> I don't see this in my lab, everything works correct. May it be that
> you
> did not include some of the (automatic) initial messages in your
> picture? In any case, a full debug log would be useful to track this
> down. After my sig, you find the relevant part of my lab debug FYI.
>
> Relevant part of rsyslog.conf:
> $ActionExecOnlyEveryNthTime 3
> :msg, contains, "test" -/rsyslog/logfile
>
> Commands issued:
> $ logger 1
> $ logger 2
> $ logger 3
> $ logger 4
> $ logger 5
> $ logger 6
>
> And the output file had:
> 2008-12-19T12:17:44.548207+01:00 rf10up rger: test 3
> 2008-12-19T12:17:53.522265+01:00 rf10up rger: test 6
>
> Note that in this setup I made sure that no other messages than those
> with the string "test" went into the log file. Otherwise, the counters
> would have been affected by some startup messages.
>
> Rainer
>
> 5455.946426832:main queue:Reg/w0: main queue:Reg/w0: worker IDLE,
> waiting for work.
> 5460.051992823:imuxsock.c: Message from UNIX socket: #4
> 5460.066209819:imuxsock.c: logmsg: flags 4, pri 13, from 'rf10up', msg
> Dec 19 12:17:40 rger: test 1
> 5460.066408445:imuxsock.c: Message has legacy syslog format.
> 5460.095581070:imuxsock.c: main queue: entry added, size now 1 entries
> 5460.096265506:imuxsock.c: wtpAdviseMaxWorkers signals busy
> 5460.096810820:imuxsock.c: main queue: EnqueueMsg advised worker start
> 5460.097417035:main queue:Reg/w0: main queue: entering rate limiter
> 5460.097797246:main queue:Reg/w0: main queue: entry deleted, state 0,
> size now 0 entries
> 5460.098493974:main queue:Reg/w0: Filter: check for property
> 'msg' (value ' test 1') contains 'test': TRUE
> 5460.105295873:main queue:Reg/w0: action 0x4c64438 passed 1 times to
> execution - less than neded - discarding
> 5460.109592735:main queue:Reg/w0: main queue: entering rate limiter
> 5460.110192245:main queue:Reg/w0: main queue:Reg/w0: worker IDLE,
> waiting for work.
> 5460.115576662:imuxsock.c: --------imuxsock calling select, active file
> descriptors (max 4): 4
> 5462.317878786:imuxsock.c: Message from UNIX socket: #4
> 5462.318410132:imuxsock.c: logmsg: flags 4, pri 13, from 'rf10up', msg
> Dec 19 12:17:42 rger: test 2
> 5462.318585850:imuxsock.c: Message has legacy syslog format.
> 5462.319012436:imuxsock.c: main queue: entry added, size now 1 entries
> 5462.319271125:imuxsock.c: wtpAdviseMaxWorkers signals busy
> 5462.319537636:imuxsock.c: main queue: EnqueueMsg advised worker start
> 5462.319871473:main queue:Reg/w0: main queue: entering rate limiter
> 5462.320174580:main queue:Reg/w0: main queue: entry deleted, state 0,
> size now 0 entries
> 5462.320470145:main queue:Reg/w0: Filter: check for property
> 'msg' (value ' test 2') contains 'test': TRUE
> 5462.321508812:main queue:Reg/w0: action 0x4c64438 passed 2 times to
> execution - less than neded - discarding
> 5462.321825608:main queue:Reg/w0: main queue: entering rate limiter
> 5462.322078710:main queue:Reg/w0: main queue:Reg/w0: worker IDLE,
> waiting for work.
> 5462.322350529:imuxsock.c: --------imuxsock calling select, active file
> descriptors (max 4): 4
> 5464.547937451:imuxsock.c: Message from UNIX socket: #4
> 5464.548420747:imuxsock.c: logmsg: flags 4, pri 13, from 'rf10up', msg
> Dec 19 12:17:44 rger: test 3
> 5464.548613227:imuxsock.c: Message has legacy syslog format.
> 5464.549042885:imuxsock.c: main queue: entry added, size now 1 entries
> 5464.549287885:imuxsock.c: wtpAdviseMaxWorkers signals busy
> 5464.549571158:imuxsock.c: main queue: EnqueueMsg advised worker start
> 5464.549888793:main queue:Reg/w0: main queue: entering rate limiter
> 5464.550211176:main queue:Reg/w0: main queue: entry deleted, state 0,
> size now 0 entries
> 5464.550500036:main queue:Reg/w0: Filter: check for property
> 'msg' (value ' test 3') contains 'test': TRUE
> 5464.551797950:main queue:Reg/w0: Called action, logging to builtin-
> file
> 5464.605776776:main queue:Reg/w0: (/rsyslog/logfile)
> 5464.606371817:imuxsock.c: --------imuxsock calling select, active file
> descriptors (max 4): 4
> 5464.627358305:main queue:Reg/w0: main queue: entering rate limiter
> 5464.628009218:main queue:Reg/w0: main queue:Reg/w0: worker IDLE,
> waiting for work.
> 5469.671232071:imuxsock.c: Message from UNIX socket: #4
> 5469.671772915:imuxsock.c: logmsg: flags 4, pri 13, from 'rf10up', msg
> Dec 19 12:17:49 rger: test 4
> 5469.671950031:imuxsock.c: Message has legacy syslog format.
> 5469.672340578:imuxsock.c: main queue: entry added, size now 1 entries
> 5469.672597591:imuxsock.c: wtpAdviseMaxWorkers signals busy
> 5469.672931428:imuxsock.c: main queue: EnqueueMsg advised worker start
> 5469.673234256:main queue:Reg/w0: main queue: entering rate limiter
> 5469.673563065:main queue:Reg/w0: main queue: entry deleted, state 0,
> size now 0 entries
> 5469.673893829:main queue:Reg/w0: Filter: check for property
> 'msg' (value ' test 4') contains 'test': TRUE
> 5469.674471829:main queue:Reg/w0: action 0x4c64438 passed 1 times to
> execution - less than neded - discarding
> 5469.674788066:main queue:Reg/w0: main queue: entering rate limiter
> 5469.675042006:main queue:Reg/w0: main queue:Reg/w0: worker IDLE,
> waiting for work.
> 5469.675316618:imuxsock.c: --------imuxsock calling select, active file
> descriptors (max 4): 4
> 5471.443424737:imuxsock.c: Message from UNIX socket: #4
> 5471.443973403:imuxsock.c: logmsg: flags 4, pri 13, from 'rf10up', msg
> Dec 19 12:17:51 rger: test 5
> 5471.444148283:imuxsock.c: Message has legacy syslog format.
> 5471.444550564:imuxsock.c: main queue: entry added, size now 1 entries
> 5471.444845291:imuxsock.c: wtpAdviseMaxWorkers signals busy
> 5471.445187788:imuxsock.c: main queue: EnqueueMsg advised worker start
> 5471.445489499:main queue:Reg/w0: main queue: entering rate limiter
> 5471.445842612:main queue:Reg/w0: main queue: entry deleted, state 0,
> size now 0 entries
> 5471.446121136:main queue:Reg/w0: Filter: check for property
> 'msg' (value ' test 5') contains 'test': TRUE
> 5471.446527886:main queue:Reg/w0: action 0x4c64438 passed 2 times to
> execution - less than neded - discarding
> 5471.446837140:main queue:Reg/w0: main queue: entering rate limiter
> 5471.447091079:main queue:Reg/w0: main queue:Reg/w0: worker IDLE,
> waiting for work.
> 5471.447366530:imuxsock.c: --------imuxsock calling select, active file
> descriptors (max 4): 4
> 5473.522029412:imuxsock.c: Message from UNIX socket: #4
> 5473.522550422:imuxsock.c: logmsg: flags 4, pri 13, from 'rf10up', msg
> Dec 19 12:17:53 rger: test 6
> 5473.522766368:imuxsock.c: Message has legacy syslog format.
> 5473.523162224:imuxsock.c: main queue: entry added, size now 1 entries
> 5473.523404989:imuxsock.c: wtpAdviseMaxWorkers signals busy
> 5473.523727931:imuxsock.c: main queue: EnqueueMsg advised worker start
> 5473.524011204:main queue:Reg/w0: main queue: entering rate limiter
> 5473.524328279:main queue:Reg/w0: main queue: entry deleted, state 0,
> size now 0 entries
> 5473.524621330:main queue:Reg/w0: Filter: check for property
> 'msg' (value ' test 6') contains 'test': TRUE
> 5473.525016627:main queue:Reg/w0: Called action, logging to builtin-
> file
> 5473.525803589:main queue:Reg/w0: (/rsyslog/logfile)
> 5473.526170949:main queue:Reg/w0: main queue: entering rate limiter
> 5473.526423213:main queue:Reg/w0: main queue:Reg/w0: worker IDLE,
> waiting for work.
> 5473.526753139:imuxsock.c: --------imuxsock calling select, active file
> descriptors (max 4): 4
>
>
>
> On Thu, 2008-12-18 at 12:51 -0500, Becker, Craig (DOB) wrote:
> > The action $ActionExecOnlyEveryNthTime is not sending the Nth message
> > but the first message, then the Nth + 1 message. For example, if I
> > set the $ActionExecOnlyEveryNthTime 3 The 1st, 4th, 7th, etc. message
> > are sent instead of the 3rd, 6th, 9th, etc. Has this bug (if it is a
> > bug) been fixed in a later version?
> >
> >
> >
> > Iâ€™m enjoying learning this product and appreciate all the hard work
> > that has gone into it.
> >
> >
> >
> > Thanks,
> >
> >
> >
> > Craig E. Becker
> > IT Specialist II
> > System Administrator
> > Division of the Budget
> > 518-473-1322
> > craig.becker@budget.state.ny.us
> >
> >
> >
> >
> >
> >
> >
> > HTML:
> >
> ______________________________________________________________________
> > This e-mail, including any attachments, may be confidential,
> > privileged or otherwise legally protected. If you have received this
> > e-mail in error, or from someone who was not authorized to send it to
> > you, do not disseminate, copy or otherwise use this e-mail or its
> > attachments. Please notify the sender immediately if you have
> received
> > this e-mail by mistake, and delete it from your system.
>
>
>
> -----------------------------------------------------------------------
> ---------
> This e-mail, including any attachments, may be confidential, privileged
> or otherwise legally protected. If you have received this e-mail in
> error, or from someone who was not authorized to send it to you, do not
> disseminate, copy or otherwise use this e-mail or its attachments.
> Please notify the sender immediately if you have received this e-mail
> by mistake, and delete it from your system.

_______________________________________________
rsyslog mailing list
http://lists.adiscon.net/mailman/listinfo/rsyslog
http://www.rsyslog.com