I thought I had a github issue tracker, but didn't have one so far. So I created it:
https://github.com/rsyslog/rsyslog/issues/974 I would appreciate if all dev-releated issues were tracked there. I appreciate all help, but unfortunately now need to turn my attention to more urgent things for probably the rest of the day. After all, there is a reason I was not able to address this issue so far, albeit I would have loved to do so... Also, it doesn't really help if I have 10 half-done things open, I prefer to close some of them ;) Thanks, Rainer 2016-04-21 9:22 GMT+02:00 Kane Kim <[email protected]>: >> >> For example, a network based output that starts the batch thinking that it >> has a live connection, but then gets an error as it tries to write data may >> want to try once to re-establish a connection and deliver the message in >> case it's a simple stale NAT table or something like this > > > It's perfectly fine, but it's just special case of general rules that > already described in the docs and provide at-least-once semantics. As long > as rsyslog doesn't loose that batch if restarted in the middle of plugin > retrying it - plugin should be free to do whatever it wants to do. It can > choose to retry itself, always reply OK and save it's own error log, in all > cases rsyslog should just provide simple guarantees: message/batch that > wasn't committed with RS_RET_OK will be retried and not lost in any > circumstances. > > > On Thu, Apr 21, 2016 at 12:10 AM, David Lang <[email protected]> wrote: > >> On Wed, 20 Apr 2016, Kane Kim wrote: >> >> David, that is totally makes sense. If we can control those branches of >>> execution with different return codes (use case #1: RS_RET_SUSPENDED, case >>> #2 something else), that would solve it for all, I believe. >>> I think in #1 case rsyslog shouldn't try to be smart and just rely on >>> return code, if output module thinks it's temporary problem, it should >>> retry up to action.resumeRetryCount and drop batch after that. If output >>> module returns "abort batch" code, then retrying with half batch should >>> kick in. >>> >> >> Right, the rsyslog core cannot know what will and won't work for any >> particular output module. The issue may be that the output modules may need >> audits to make sure they figure out the difference. It may make sense for >> some output modules to do a retry themselves. For example, a network based >> output that starts the batch thinking that it has a live connection, but >> then gets an error as it tries to write data may want to try once to >> re-establish a connection and deliver the message in case it's a simple >> stale NAT table or something like this. But that should be up to the >> individual module, it would be perfectly legit for the module to just say >> "temp problem" and tear down the connection and leave the retry up to the >> core logic. >> >> David Lang >> >> On Wed, Apr 20, 2016 at 11:44 PM, David Lang <[email protected]> wrote: >>> >>> The original discussion when we created the batch mode was that there were >>>> two possible ways for a batch commit to fail. >>>> >>>> 1. a temporary problem (can't reach the server, it doesn't respond, etc) >>>> >>>> In this case, a delay and retry is the correct thing to do. >>>> >>>> I believe this is what a suspended action is (I say this in case I am >>>> misunderstanding terms) >>>> >>>> The output module can usually detect this sort of problem, but if in >>>> doubt >>>> (or after enough retries), it may have to give up and decide that the >>>> problem is really the second type. A failure to establish a connection to >>>> the destination should never be in doubt, it's always this first type of >>>> problem. >>>> >>>> 2. a data driven problem (no matter what, this particular data cannot be >>>> delivered, even if we retried for 100 years) >>>> >>>> This is problems like data elements having embedded quotes that aren't >>>> escaped, a timestamp isn't valid by the definition of the database you >>>> are >>>> inserting data into, etc. >>>> >>>> In this case, retries do no good. But what we can do is abort the batch >>>> and try again with a batch half the size. >>>> >>>> If any messages did get delivered as part of the batch processing, they >>>> will be duplicated when the rest of the batch is processed. >>>> >>>> If the problem was not in the half of the batch that was delivered, good, >>>> revert to normal processing for anything else in the queue (which >>>> probably >>>> means that the next batch will fail as well) >>>> >>>> If the problem is in the half size batch, try again with a batch half >>>> that >>>> size. >>>> >>>> If the batch that you are trying to process is a single message, assume >>>> it >>>> is fatally flawed and count it as an error. >>>> >>>> In an ideal situation you can write such messages somewhere or otherwise >>>> detect the error. But you end up only loosing one message that has >>>> something corrupt in it, not an entire batch. >>>> >>>> David Lang >>>> >>>> >>>> On Wed, 20 Apr 2016, Kane Kim wrote: >>>> >>>> What would happen if it will be retried forever at this point? Would it >>>> >>>>> affect any other queues or only current action queue. If it will not >>>>> affect >>>>> anything else I'd really prefer it to block there until successfully >>>>> committed. >>>>> >>>>> On Wed, Apr 20, 2016 at 11:16 PM, Rainer Gerhards < >>>>> [email protected]> >>>>> wrote: >>>>> >>>>> 2016-04-21 3:22 GMT+02:00 David Lang <[email protected]>: >>>>> >>>>>> >>>>>> Thanks, I didn't know that you had been able to take any time to think >>>>>>> >>>>>>> about >>>>>> >>>>>> this issue yet. >>>>>>> >>>>>>> >>>>>> Sorry for not being more explicit about it. But there was not yet >>>>>> anything that could be posted. I did this as a side-activity all since >>>>>> this opened. The plan acutally is: >>>>>> >>>>>> 1. get a testbench test to expose that problem -- this greatly eases >>>>>> debugging >>>>>> line of thought is to update omfile, which is needed anyhow, so >>>>>> that we can induce errors via it >>>>>> 2. add missing functionality to write error file >>>>>> this does not directly address the issue, but is useful and >>>>>> ensures we are on the right path >>>>>> 3. check the end transaction endpoint. After review of old notes and >>>>>> some thinking, I think that >>>>>> part of the "not yet implemented" comment is actually right. It's >>>>>> not as easy as suggested by it, >>>>>> but we probably can do better. >>>>>> >>>>>> >>>>>> It sounds like you are tenitively agreeing with my speculation that the >>>>>>> >>>>>>> end >>>>>> >>>>>> of the block processing is happening just a little sooner than it >>>>>>> should, >>>>>>> preventing the chance to detect output errors. >>>>>>> >>>>>>> >>>>>> No, I don't think so. I think it happens as it should, but we are not >>>>>> handling the full situation. Originally, it was planned to write an >>>>>> error file (point 2 above) when we cannot commit at end of >>>>>> transaction. But we probably can give it some retries at that point as >>>>>> well. In v8, we **need** to buffer transactional data until the end of >>>>>> batch. If we wouldn't do that, we would always need to commit after >>>>>> each and every transaction (because we need processing "completed" >>>>>> when we advance to the next action). The, at end of batch, the >>>>>> transaction commit processing happens. Right now, we have one try, and >>>>>> then give up (unfortunately without any error indication). So we need >>>>>> to go into that part of processing and enhance/fix it. >>>>>> >>>>>> I hope this clarifies. >>>>>> Rainer >>>>>> >>>>>> >>>>>> David Lang >>>>>>> >>>>>>> >>>>>>> On Wed, 20 Apr 2016, Rainer Gerhards wrote: >>>>>>> >>>>>>> I should also say that it had a release goal, so it is on my active >>>>>>> >>>>>>>> >>>>>>>> to-do >>>>>>> >>>>>> >>>>>> list. >>>>>>> >>>>>>>> >>>>>>>> Sent from phone, thus brief. >>>>>>>> Am 20.04.2016 19:40 schrieb "Rainer Gerhards" < >>>>>>>> [email protected] >>>>>>>> >>>>>>>> : >>>>>>> >>>>>>> >>>>>>>> Yup... Look aty work Log - still no time... Was meant for last >>>>>>>> release >>>>>>>> >>>>>>>>> but >>>>>>>>> then came libfastjson work. >>>>>>>>> >>>>>>>>> Sent from phone, thus brief. >>>>>>>>> Am 20.04.2016 19:39 schrieb "David Lang" <[email protected]>: >>>>>>>>> >>>>>>>>> Rainer, ping on this issue. >>>>>>>>> >>>>>>>>>> >>>>>>>>>> David Lang >>>>>>>>>> >>>>>>>>>> On Tue, 29 Mar 2016, Kane Kim wrote: >>>>>>>>>> >>>>>>>>>> Date: Tue, 29 Mar 2016 10:46:49 -0700 >>>>>>>>>> >>>>>>>>>> >>>>>>>>>>> From: Kane Kim <[email protected]> >>>>>>>>>>> Reply-To: rsyslog-users <[email protected]> >>>>>>>>>>> To: rsyslog-users <[email protected]> >>>>>>>>>>> Subject: Re: [rsyslog] retry if output module returns >>>>>>>>>>> >>>>>>>>>>> RS_RET_SUSPENDED >>>>>>>>>> >>>>>>>>> >>>>>> >>>>>>> Updated config to: >>>>>>>>>>> module(load="omrelp") >>>>>>>>>>> local0.* action(type="omrelp" >>>>>>>>>>> target="10.0.0.1" >>>>>>>>>>> port="2514" >>>>>>>>>>> name="debug_relp" >>>>>>>>>>> queue.filename="relp_queue" >>>>>>>>>>> queue.maxdiskspace="1G" >>>>>>>>>>> queue.saveonshutdown="on" >>>>>>>>>>> queue.spoolDirectory="/var/spool/rsyslog" >>>>>>>>>>> queue.type="Disk" >>>>>>>>>>> action.resumeRetryCount="-1" >>>>>>>>>>> action.resumeInterval="1" >>>>>>>>>>> ) >>>>>>>>>>> >>>>>>>>>>> Still message is lost: >>>>>>>>>>> >>>>>>>>>>> 3489.658349703:imuxsock.c : Message from UNIX socket: #3 >>>>>>>>>>> 3489.658367582:imuxsock.c : main Q: qqueueAdd: entry added, >>>>>>>>>>> size >>>>>>>>>>> now >>>>>>>>>>> log 1, phys 1 entries >>>>>>>>>>> 3489.658372561:imuxsock.c : main Q: EnqueueMsg advised worker >>>>>>>>>>> >>>>>>>>>>> start >>>>>>>>>> >>>>>>>>> >>>>>> 3489.658374985:imuxsock.c : --------imuxsock calling select, >>>>>>> >>>>>>>> >>>>>>>>>>> active >>>>>>>>>> >>>>>>>>> >>>>>> file descriptors (max 3): 3 >>>>>>> >>>>>>>> 3489.658384201:main Q:Reg/w0 : wti 0x23c8ba0: worker awoke from >>>>>>>>>>> idle >>>>>>>>>>> processing >>>>>>>>>>> 3489.658386792:main Q:Reg/w0 : DeleteProcessedBatch: we deleted 0 >>>>>>>>>>> objects >>>>>>>>>>> and enqueued 0 objects >>>>>>>>>>> 3489.658388548:main Q:Reg/w0 : doDeleteBatch: delete batch from >>>>>>>>>>> >>>>>>>>>>> store, >>>>>>>>>> >>>>>>>>> >>>>>> new >>>>>>> >>>>>>>> sizes: log 1, phys 1 >>>>>>>>>>> 3489.658391356:main Q:Reg/w0 : processBATCH: batch of 1 elements >>>>>>>>>>> >>>>>>>>>>> must >>>>>>>>>> >>>>>>>>> >>>>>> be >>>>>>> >>>>>>>> processed >>>>>>>>>>> 3489.658392786:main Q:Reg/w0 : processBATCH: next msg 0: <134>Mar >>>>>>>>>>> 29 >>>>>>>>>>> 17:44:49 logger: test >>>>>>>>>>> 3489.658395027:main Q:Reg/w0 : PRIFILT 'local0.*' >>>>>>>>>>> 3489.658397540:main Q:Reg/w0 : pmask: X X X X X X X X >>>>>>>>>>> X >>>>>>>>>>> X X >>>>>>>>>>> X X X X X FF X X X X X X X X X >>>>>>>>>>> 3489.658413235:main Q:Reg/w0 : PRIFILT condition result is 1 >>>>>>>>>>> 3489.658414686:main Q:Reg/w0 : ACTION 0 >>>>>>>>>>> [omrelp:action(type="omrelp" >>>>>>>>>>> ...)] >>>>>>>>>>> 3489.658417648:main Q:Reg/w0 : executing action 0 >>>>>>>>>>> 3489.658419520:main Q:Reg/w0 : action 'debug_relp': called, >>>>>>>>>>> logging >>>>>>>>>>> >>>>>>>>>>> to >>>>>>>>>> >>>>>>>>> >>>>>> omrelp (susp 0/0, direct q 0) >>>>>>> >>>>>>>> 3489.658433462:main Q:Reg/w0 : strm 0x23b74c0: file -1(relp_queue) >>>>>>>>>>> flush, >>>>>>>>>>> buflen 410 >>>>>>>>>>> 3489.658435496:main Q:Reg/w0 : strmPhysWrite, stream 0x23b74c0, >>>>>>>>>>> len >>>>>>>>>>> 410 >>>>>>>>>>> 3489.658484243:main Q:Reg/w0 : file >>>>>>>>>>> '/var/spool/rsyslog/relp_queue.00000001' opened as #5 with mode >>>>>>>>>>> 384 >>>>>>>>>>> 3489.658487347:main Q:Reg/w0 : strm 0x23b74c0: opened file >>>>>>>>>>> '/var/spool/rsyslog/relp_queue.00000001' for WRITE as 5 >>>>>>>>>>> 3489.658500498:main Q:Reg/w0 : strm 0x23b74c0: file 5 write wrote >>>>>>>>>>> >>>>>>>>>>> 410 >>>>>>>>>> >>>>>>>>> >>>>>> bytes >>>>>>> >>>>>>>> 3489.658502751:main Q:Reg/w0 : debug_relp queue: write wrote 410 >>>>>>>>>>> octets >>>>>>>>>>> to >>>>>>>>>>> disk, queue disk size now 410 octets, EnqOnly:0 >>>>>>>>>>> 3489.658504568:main Q:Reg/w0 : debug_relp queue: qqueueAdd: entry >>>>>>>>>>> added, >>>>>>>>>>> size now log 1, phys 1 entries >>>>>>>>>>> 3489.658506705:main Q:Reg/w0 : debug_relp queue:Reg: high >>>>>>>>>>> activity >>>>>>>>>>> - >>>>>>>>>>> starting 1 additional worker thread(s). >>>>>>>>>>> 3489.658528951:main Q:Reg/w0 : debug_relp queue:Reg: started with >>>>>>>>>>> state >>>>>>>>>>> 0, >>>>>>>>>>> num workers now 1 >>>>>>>>>>> 3489.658530689:main Q:Reg/w0 : debug_relp queue: EnqueueMsg >>>>>>>>>>> advised >>>>>>>>>>> worker >>>>>>>>>>> start >>>>>>>>>>> 3489.658532183:main Q:Reg/w0 : action 'debug_relp': set suspended >>>>>>>>>>> state >>>>>>>>>>> to >>>>>>>>>>> 0 >>>>>>>>>>> 3489.658533672:main Q:Reg/w0 : PRIFILT >>>>>>>>>>> '*.info;mail.none;authpriv.none;cron.none' >>>>>>>>>>> 3489.658536164:main Q:Reg/w0 : pmask: 7F 7F X 7F 7F 7F 7F 7F >>>>>>>>>>> 7F >>>>>>>>>>> X X >>>>>>>>>>> 7F 7F 7F 7F 7F 7F 7F 7F 7F 7F 7F 7F 7F 7F 7F >>>>>>>>>>> 3489.658552240:main Q:Reg/w0 : PRIFILT condition result is 1 >>>>>>>>>>> 3489.658553393:main Q:Reg/w0 : ACTION 1 >>>>>>>>>>> [builtin:omfile:/var/log/messages] >>>>>>>>>>> 3489.658556301:main Q:Reg/w0 : executing action 1 >>>>>>>>>>> 3489.658557878:main Q:Reg/w0 : action 'action 1': called, logging >>>>>>>>>>> to >>>>>>>>>>> builtin:omfile (susp 0/0, direct q 1) >>>>>>>>>>> 3489.658561265:main Q:Reg/w0 : action 'action 1': is >>>>>>>>>>> transactional >>>>>>>>>>> - >>>>>>>>>>> executing in commit phase >>>>>>>>>>> 3489.658563696:main Q:Reg/w0 : Action 1 transitioned to state: >>>>>>>>>>> itx >>>>>>>>>>> 3489.658564902:main Q:Reg/w0 : action 'action 1': set suspended >>>>>>>>>>> >>>>>>>>>>> state >>>>>>>>>> >>>>>>>>> >>>>>> to 0 >>>>>>> >>>>>>>> 3489.658566053:main Q:Reg/w0 : PRIFILT 'authpriv.*' >>>>>>>>>>> 3489.658568233:main Q:Reg/w0 : pmask: X X X X X X X X >>>>>>>>>>> X >>>>>>>>>>> X >>>>>>>>>>> FF >>>>>>>>>>> X X X X X X X X X X X X X X X >>>>>>>>>>> 3489.658582888:main Q:Reg/w0 : PRIFILT condition result is 0 >>>>>>>>>>> 3489.658584058:main Q:Reg/w0 : PRIFILT 'mail.*' >>>>>>>>>>> 3489.658586243:main Q:Reg/w0 : pmask: X X FF X X X X X >>>>>>>>>>> X >>>>>>>>>>> X X >>>>>>>>>>> X X X X X X X X X X X X X X X >>>>>>>>>>> 3489.658600961:main Q:Reg/w0 : PRIFILT condition result is 0 >>>>>>>>>>> 3489.658602136:main Q:Reg/w0 : PRIFILT 'cron.*' >>>>>>>>>>> 3489.658604562:main Q:Reg/w0 : pmask: X X X X X X X X >>>>>>>>>>> X >>>>>>>>>>> FF X >>>>>>>>>>> X X X X X X X X X X X X X X X >>>>>>>>>>> 3489.658619159:main Q:Reg/w0 : PRIFILT condition result is 0 >>>>>>>>>>> 3489.658620352:main Q:Reg/w0 : PRIFILT '*.emerg' >>>>>>>>>>> 3489.658622551:main Q:Reg/w0 : pmask: 1 1 1 1 1 1 1 1 >>>>>>>>>>> 1 >>>>>>>>>>> 1 1 >>>>>>>>>>> 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 >>>>>>>>>>> 3489.658638435:main Q:Reg/w0 : PRIFILT condition result is 0 >>>>>>>>>>> 3489.658639529:main Q:Reg/w0 : PRIFILT 'uucp,news.crit' >>>>>>>>>>> 3489.658641711:main Q:Reg/w0 : pmask: X X X X X X X 7 >>>>>>>>>>> 7 >>>>>>>>>>> X X >>>>>>>>>>> X X X X X X X X X X X X X X X >>>>>>>>>>> 3489.658656380:main Q:Reg/w0 : PRIFILT condition result is 0 >>>>>>>>>>> 3489.658657532:main Q:Reg/w0 : PRIFILT 'local7.*' >>>>>>>>>>> 3489.658659794:main Q:Reg/w0 : pmask: X X X X X X X X >>>>>>>>>>> X >>>>>>>>>>> X X >>>>>>>>>>> X X X X X X X X X X X X FF X X >>>>>>>>>>> 3489.658674346:main Q:Reg/w0 : PRIFILT condition result is 0 >>>>>>>>>>> 3489.658675686:main Q:Reg/w0 : END batch execution phase, >>>>>>>>>>> entering >>>>>>>>>>> >>>>>>>>>>> to >>>>>>>>>> >>>>>>>>> >>>>>> commit phase [processed 1 of 1 messages] >>>>>>> >>>>>>>> 3489.658677400:main Q:Reg/w0 : actionCommitAll: action 1, state 1, >>>>>>>>>>> >>>>>>>>>>> nbr >>>>>>>>>> >>>>>>>>> >>>>>> to >>>>>>> >>>>>>>> commit 0 isTransactional 1 >>>>>>>>>>> 3489.658679044:main Q:Reg/w0 : doTransaction: have >>>>>>>>>>> commitTransaction >>>>>>>>>>> IF, >>>>>>>>>>> using that, pWrkrInfo 0x23c8ce0 >>>>>>>>>>> 3489.658680668:main Q:Reg/w0 : entering >>>>>>>>>>> >>>>>>>>>>> actionCallCommitTransaction(), >>>>>>>>>> >>>>>>>>> >>>>>> state: itx, actionNbr 1, nMsgs 1 >>>>>>> >>>>>>>> 3489.658682704:main Q:Reg/w0 : omfile: write to stream, >>>>>>>>>>> pData->pStrm >>>>>>>>>>> 0x7f1ef4002480, lenBuf 42, strt data Mar 29 17:44:49 314959ac8cb0 >>>>>>>>>>> logger: >>>>>>>>>>> test >>>>>>>>>>> >>>>>>>>>>> 3489.658685296:main Q:Reg/w0 : strm 0x7f1ef4002480: file >>>>>>>>>>> 4(messages) >>>>>>>>>>> flush, buflen 42 >>>>>>>>>>> 3489.658686866:main Q:Reg/w0 : strmPhysWrite, stream >>>>>>>>>>> 0x7f1ef4002480, >>>>>>>>>>> len 42 >>>>>>>>>>> 3489.658696046:main Q:Reg/w0 : strm 0x7f1ef4002480: file 4 write >>>>>>>>>>> >>>>>>>>>>> wrote >>>>>>>>>> >>>>>>>>> >>>>>> 42 >>>>>>> >>>>>>>> bytes >>>>>>>>>>> 3489.658697884:main Q:Reg/w0 : Action 1 transitioned to state: >>>>>>>>>>> rdy >>>>>>>>>>> 3489.658699301:main Q:Reg/w0 : Action 1 transitioned to state: >>>>>>>>>>> itx >>>>>>>>>>> 3489.658700575:main Q:Reg/w0 : Action 1 transitioned to state: >>>>>>>>>>> rdy >>>>>>>>>>> 3489.658701773:main Q:Reg/w0 : actionCommit, in retry loop, iRet >>>>>>>>>>> 0 >>>>>>>>>>> 3489.658703176:main Q:Reg/w0 : processBATCH: batch of 1 elements >>>>>>>>>>> has >>>>>>>>>>> been >>>>>>>>>>> processed >>>>>>>>>>> 3489.658704989:main Q:Reg/w0 : regular consumer finished, iret=0, >>>>>>>>>>> szlog >>>>>>>>>>> 0 >>>>>>>>>>> sz phys 1 >>>>>>>>>>> 3489.658707214:main Q:Reg/w0 : DeleteProcessedBatch: we deleted 1 >>>>>>>>>>> objects >>>>>>>>>>> and enqueued 0 objects >>>>>>>>>>> 3489.658708626:main Q:Reg/w0 : doDeleteBatch: delete batch from >>>>>>>>>>> >>>>>>>>>>> store, >>>>>>>>>> >>>>>>>>> >>>>>> new >>>>>>> >>>>>>>> sizes: log 0, phys 0 >>>>>>>>>>> 3489.658710186:main Q:Reg/w0 : regular consumer finished, iret=4, >>>>>>>>>>> szlog >>>>>>>>>>> 0 >>>>>>>>>>> sz phys 0 >>>>>>>>>>> 3489.658711550:main Q:Reg/w0 : main Q:Reg/w0: worker IDLE, >>>>>>>>>>> waiting >>>>>>>>>>> >>>>>>>>>>> for >>>>>>>>>> >>>>>>>>> >>>>>> work. >>>>>>> >>>>>>>> 3489.660013052:7f1efbb14700: thread created, tid 30310, name >>>>>>>>>>> 'rs:debug_relp >>>>>>>>>>> queue:Reg' >>>>>>>>>>> 3489.660298870:debug_relp queue:Reg/w0: wti 0x23c78b0: worker >>>>>>>>>>> >>>>>>>>>>> starting >>>>>>>>>> >>>>>>>>> >>>>>> 3489.660645336:debug_relp queue:Reg/w0: DeleteProcessedBatch: we >>>>>>> >>>>>>>> deleted >>>>>>>>>>> 0 >>>>>>>>>>> objects and enqueued 0 objects >>>>>>>>>>> 3489.660922752:debug_relp queue:Reg/w0: doDeleteBatch: delete >>>>>>>>>>> batch >>>>>>>>>>> from >>>>>>>>>>> store, new sizes: log 1, phys 1 >>>>>>>>>>> 3489.660947418:debug_relp queue:Reg/w0: file >>>>>>>>>>> '/var/spool/rsyslog/relp_queue.00000001' opened as #6 with mode >>>>>>>>>>> 384 >>>>>>>>>>> 3489.660959920:debug_relp queue:Reg/w0: strm 0x23b7760: opened >>>>>>>>>>> file >>>>>>>>>>> '/var/spool/rsyslog/relp_queue.00000001' for READ as 6 >>>>>>>>>>> 3489.660967370:debug_relp queue:Reg/w0: strm 0x23b7760: file 6 >>>>>>>>>>> read >>>>>>>>>>> >>>>>>>>>>> 410 >>>>>>>>>> >>>>>>>>> >>>>>> bytes >>>>>>> >>>>>>>> 3489.661768120:debug_relp queue:Reg/w0: action 'debug_relp': is >>>>>>>>>>> transactional - executing in commit phase >>>>>>>>>>> 3489.661782408:debug_relp queue:Reg/w0: wti 0x23c78b0: we need to >>>>>>>>>>> create >>>>>>>>>>> a >>>>>>>>>>> new action worker instance for action 0 >>>>>>>>>>> 3489.661789583:debug_relp queue:Reg/w0: relp engine created new >>>>>>>>>>> >>>>>>>>>>> client >>>>>>>>>> >>>>>>>>> >>>>>> 0x7f1ef00027e0 >>>>>>> >>>>>>>> 3489.661794073:debug_relp queue:Reg/w0: wti 0x23c78b0: created >>>>>>>>>>> action >>>>>>>>>>> worker instance 1 for action 0 >>>>>>>>>>> 3489.661798129:debug_relp queue:Reg/w0: omrelp: beginTransaction >>>>>>>>>>> ^C3497.710058579:main thread : DoDie called. >>>>>>>>>>> 3497.710272055:main thread : exiting on signal 2 >>>>>>>>>>> 3497.710576430:main thread : Terminating input threads... >>>>>>>>>>> 3497.710765753:main thread : request term via SIGTTIN for input >>>>>>>>>>> thread >>>>>>>>>>> 'imuxsock' 0xfcb16700 >>>>>>>>>>> 3497.711033925:imuxsock.c : thrdStarter: usrThrdMain imuxsock >>>>>>>>>>> - >>>>>>>>>>> 0x7f1efcb16700 returned with iRet 0, exiting now. >>>>>>>>>>> 3497.711447372:main thread : non-cancel input thread >>>>>>>>>>> termination >>>>>>>>>>> succeeded for thread imuxsock 0xfcb16700 >>>>>>>>>>> 3497.713028584:imuxsock.c : destructor for debug call stack >>>>>>>>>>> 0x7f1eec0008c0 called >>>>>>>>>>> 3497.713390963:main thread : imuxsock: unlinking unix socket >>>>>>>>>>> >>>>>>>>>>> file[0] >>>>>>>>>> >>>>>>>>> >>>>>> /dev/log >>>>>>> >>>>>>>> 3497.713734513:main thread : main Q: qqueueAdd: entry added, size >>>>>>>>>>> now >>>>>>>>>>> log 1, phys 1 entries >>>>>>>>>>> 3497.713906635:main thread : main Q: EnqueueMsg advised worker >>>>>>>>>>> >>>>>>>>>>> start >>>>>>>>>> >>>>>>>>> >>>>>> 3497.714257550:main Q:Reg/w0 : wti 0x23c8ba0: worker awoke from idle >>>>>>> >>>>>>>> processing >>>>>>>>>>> 3497.714544345:main Q:Reg/w0 : DeleteProcessedBatch: we deleted 0 >>>>>>>>>>> objects >>>>>>>>>>> and enqueued 0 objects >>>>>>>>>>> 3497.715372923:main Q:Reg/w0 : doDeleteBatch: delete batch from >>>>>>>>>>> >>>>>>>>>>> store, >>>>>>>>>> >>>>>>>>> >>>>>> new >>>>>>> >>>>>>>> sizes: log 1, phys 1 >>>>>>>>>>> 3497.715611163:main Q:Reg/w0 : processBATCH: batch of 1 elements >>>>>>>>>>> >>>>>>>>>>> must >>>>>>>>>> >>>>>>>>> >>>>>> be >>>>>>> >>>>>>>> processed >>>>>>>>>>> 3497.715762447:main Q:Reg/w0 : processBATCH: next msg 0: [origin >>>>>>>>>>> software="rsyslogd" swVersion="8.18.0.master" x-pid="30306" >>>>>>>>>>> x-info=" >>>>>>>>>>> http://www.rsyslog.com";] exiting on signal 2. >>>>>>>>>>> 3497.715965911:main Q:Reg/w0 : PRIFILT 'local0.*' >>>>>>>>>>> 3497.715976154:main Q:Reg/w0 : pmask: X X X X X X X X >>>>>>>>>>> X >>>>>>>>>>> X X >>>>>>>>>>> X X X X X FF X X X X X X X X X >>>>>>>>>>> 3497.716332698:main Q:Reg/w0 : PRIFILT condition result is 0 >>>>>>>>>>> 3497.716337713:main Q:Reg/w0 : PRIFILT >>>>>>>>>>> '*.info;mail.none;authpriv.none;cron.none' >>>>>>>>>>> 3497.716347729:main Q:Reg/w0 : pmask: 7F 7F X 7F 7F 7F 7F 7F >>>>>>>>>>> 7F >>>>>>>>>>> X X >>>>>>>>>>> 7F 7F 7F 7F 7F 7F 7F 7F 7F 7F 7F 7F 7F 7F 7F >>>>>>>>>>> 3497.716424684:main Q:Reg/w0 : PRIFILT condition result is 1 >>>>>>>>>>> 3497.716429241:main Q:Reg/w0 : ACTION 1 >>>>>>>>>>> [builtin:omfile:/var/log/messages] >>>>>>>>>>> 3497.716439928:main Q:Reg/w0 : executing action 1 >>>>>>>>>>> 3497.716445132:main Q:Reg/w0 : action 'action 1': called, logging >>>>>>>>>>> to >>>>>>>>>>> builtin:omfile (susp 0/0, direct q 1) >>>>>>>>>>> 3497.716452142:main Q:Reg/w0 : action 'action 1': is >>>>>>>>>>> transactional >>>>>>>>>>> - >>>>>>>>>>> executing in commit phase >>>>>>>>>>> 3497.716457817:main Q:Reg/w0 : Action 1 transitioned to state: >>>>>>>>>>> itx >>>>>>>>>>> 3497.716462371:main Q:Reg/w0 : action 'action 1': set suspended >>>>>>>>>>> >>>>>>>>>>> state >>>>>>>>>> >>>>>>>>> >>>>>> to 0 >>>>>>> >>>>>>>> 3497.716466771:main Q:Reg/w0 : PRIFILT 'authpriv.*' >>>>>>>>>>> 3497.716476330:main Q:Reg/w0 : pmask: X X X X X X X X >>>>>>>>>>> X >>>>>>>>>>> X >>>>>>>>>>> FF >>>>>>>>>>> X X X X X X X X X X X X X X X >>>>>>>>>>> 3497.716796250:main Q:Reg/w0 : PRIFILT condition result is 0 >>>>>>>>>>> 3497.716802372:main Q:Reg/w0 : PRIFILT 'mail.*' >>>>>>>>>>> 3497.716811926:main Q:Reg/w0 : pmask: X X FF X X X X X >>>>>>>>>>> X >>>>>>>>>>> X X >>>>>>>>>>> X X X X X X X X X X X X X X X >>>>>>>>>>> 3497.717436983:main Q:Reg/w0 : PRIFILT condition result is 0 >>>>>>>>>>> 3497.717444114:main Q:Reg/w0 : PRIFILT 'cron.*' >>>>>>>>>>> 3497.717454023:main Q:Reg/w0 : pmask: X X X X X X X X >>>>>>>>>>> X >>>>>>>>>>> FF X >>>>>>>>>>> X X X X X X X X X X X X X X X >>>>>>>>>>> 3497.717823841:main Q:Reg/w0 : PRIFILT condition result is 0 >>>>>>>>>>> 3497.717829094:main Q:Reg/w0 : PRIFILT '*.emerg' >>>>>>>>>>> 3497.717838767:main Q:Reg/w0 : pmask: 1 1 1 1 1 1 1 1 >>>>>>>>>>> 1 >>>>>>>>>>> 1 1 >>>>>>>>>>> 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 >>>>>>>>>>> 3497.717916499:main Q:Reg/w0 : PRIFILT condition result is 0 >>>>>>>>>>> 3497.717920817:main Q:Reg/w0 : PRIFILT 'uucp,news.crit' >>>>>>>>>>> 3497.717930304:main Q:Reg/w0 : pmask: X X X X X X X 7 >>>>>>>>>>> 7 >>>>>>>>>>> X X >>>>>>>>>>> X X X X X X X X X X X X X X X >>>>>>>>>>> 3497.718043828:main Q:Reg/w0 : PRIFILT condition result is 0 >>>>>>>>>>> 3497.718044097:main Q:Reg/w0 : PRIFILT 'local7.*' >>>>>>>>>>> 3497.718055458:main Q:Reg/w0 : pmask: X X X X X X X X >>>>>>>>>>> X >>>>>>>>>>> X X >>>>>>>>>>> X X X X X X X X X X X X FF X X >>>>>>>>>>> 3497.718838257:main Q:Reg/w0 : PRIFILT condition result is 0 >>>>>>>>>>> 3497.718842803:main Q:Reg/w0 : END batch execution phase, >>>>>>>>>>> entering >>>>>>>>>>> >>>>>>>>>>> to >>>>>>>>>> >>>>>>>>> >>>>>> commit phase [processed 1 of 1 messages] >>>>>>> >>>>>>>> 3497.718847686:main Q:Reg/w0 : actionCommitAll: action 1, state 1, >>>>>>>>>>> >>>>>>>>>>> nbr >>>>>>>>>> >>>>>>>>> >>>>>> to >>>>>>> >>>>>>>> commit 0 isTransactional 1 >>>>>>>>>>> 3497.718852750:main Q:Reg/w0 : doTransaction: have >>>>>>>>>>> commitTransaction >>>>>>>>>>> IF, >>>>>>>>>>> using that, pWrkrInfo 0x23c8ce0 >>>>>>>>>>> 3497.718857172:main Q:Reg/w0 : entering >>>>>>>>>>> >>>>>>>>>>> actionCallCommitTransaction(), >>>>>>>>>> >>>>>>>>> >>>>>> state: itx, actionNbr 1, nMsgs 1 >>>>>>> >>>>>>>> 3497.718862516:main Q:Reg/w0 : omfile: write to stream, >>>>>>>>>>> pData->pStrm >>>>>>>>>>> 0x7f1ef4002480, lenBuf 161, strt data Mar 29 17:44:57 314959ac8cb0 >>>>>>>>>>> rsyslogd: [origin software="rsyslogd" swVersion="8.18.0.master" >>>>>>>>>>> x-pid="30306" x-info="http://www.rs >>>>>>>>>>> 3497.718868427:main Q:Reg/w0 : strm 0x7f1ef4002480: file >>>>>>>>>>> 4(messages) >>>>>>>>>>> flush, buflen 161 >>>>>>>>>>> 3497.718873173:main Q:Reg/w0 : strmPhysWrite, stream >>>>>>>>>>> 0x7f1ef4002480, >>>>>>>>>>> len >>>>>>>>>>> 161 >>>>>>>>>>> 3497.718890732:main Q:Reg/w0 : strm 0x7f1ef4002480: file 4 write >>>>>>>>>>> >>>>>>>>>>> wrote >>>>>>>>>> >>>>>>>>> >>>>>> 161 >>>>>>> >>>>>>>> bytes >>>>>>>>>>> 3497.718896519:main Q:Reg/w0 : Action 1 transitioned to state: >>>>>>>>>>> rdy >>>>>>>>>>> 3497.718901151:main Q:Reg/w0 : Action 1 transitioned to state: >>>>>>>>>>> itx >>>>>>>>>>> 3497.718905316:main Q:Reg/w0 : Action 1 transitioned to state: >>>>>>>>>>> rdy >>>>>>>>>>> 3497.718909316:main Q:Reg/w0 : actionCommit, in retry loop, iRet >>>>>>>>>>> 0 >>>>>>>>>>> 3497.718913541:main Q:Reg/w0 : processBATCH: batch of 1 elements >>>>>>>>>>> has >>>>>>>>>>> been >>>>>>>>>>> processed >>>>>>>>>>> 3497.718918158:main Q:Reg/w0 : regular consumer finished, iret=0, >>>>>>>>>>> szlog >>>>>>>>>>> 0 >>>>>>>>>>> sz phys 1 >>>>>>>>>>> 3497.718923739:main Q:Reg/w0 : DeleteProcessedBatch: we deleted 1 >>>>>>>>>>> objects >>>>>>>>>>> and enqueued 0 objects >>>>>>>>>>> 3497.718928090:main Q:Reg/w0 : doDeleteBatch: delete batch from >>>>>>>>>>> >>>>>>>>>>> store, >>>>>>>>>> >>>>>>>>> >>>>>> new >>>>>>> >>>>>>>> sizes: log 0, phys 0 >>>>>>>>>>> 3497.718932606:main Q:Reg/w0 : regular consumer finished, iret=4, >>>>>>>>>>> szlog >>>>>>>>>>> 0 >>>>>>>>>>> sz phys 0 >>>>>>>>>>> 3497.718936888:main Q:Reg/w0 : main Q:Reg/w0: worker IDLE, >>>>>>>>>>> waiting >>>>>>>>>>> >>>>>>>>>>> for >>>>>>>>>> >>>>>>>>> >>>>>> work. >>>>>>> >>>>>>>> 3497.718942403:main thread : Terminating main queue... >>>>>>>>>>> 3497.718946280:main thread : main Q: initiating worker thread >>>>>>>>>>> shutdown >>>>>>>>>>> sequence >>>>>>>>>>> 3497.718950170:main thread : main Q: trying shutdown of regular >>>>>>>>>>> workers >>>>>>>>>>> 3497.718957067:main thread : sent SIGTTIN to worker thread >>>>>>>>>>> 0xfc315700 >>>>>>>>>>> 3497.718961130:main thread : main Q:Reg: waiting 1500ms on >>>>>>>>>>> worker >>>>>>>>>>> thread >>>>>>>>>>> termination, 1 still running >>>>>>>>>>> 3497.718968288:main Q:Reg/w0 : wti 0x23c8ba0: worker awoke from >>>>>>>>>>> idle >>>>>>>>>>> processing >>>>>>>>>>> 3497.718972108:main Q:Reg/w0 : DeleteProcessedBatch: we deleted 0 >>>>>>>>>>> objects >>>>>>>>>>> and enqueued 0 objects >>>>>>>>>>> 3497.718975498:main Q:Reg/w0 : doDeleteBatch: delete batch from >>>>>>>>>>> >>>>>>>>>>> store, >>>>>>>>>> >>>>>>>>> >>>>>> new >>>>>>> >>>>>>>> sizes: log 0, phys 0 >>>>>>>>>>> 3497.718979083:main Q:Reg/w0 : regular consumer finished, iret=4, >>>>>>>>>>> szlog >>>>>>>>>>> 0 >>>>>>>>>>> sz phys 0 >>>>>>>>>>> 3497.718982620:main Q:Reg/w0 : wti 0x23c8ba0: terminating worker >>>>>>>>>>> terminateRet=5, bInactivityTOOccured=0 >>>>>>>>>>> 3497.718986378:main Q:Reg/w0 : DDDD: wti 0x23c8ba0: worker >>>>>>>>>>> cleanup >>>>>>>>>>> action >>>>>>>>>>> instances >>>>>>>>>>> 3497.718990027:main Q:Reg/w0 : wti 0x23c8ba0, action 0, ptr (nil) >>>>>>>>>>> 3497.718993327:main Q:Reg/w0 : wti 0x23c8ba0, action 1, ptr >>>>>>>>>>> 0x7f1ef40022a0 >>>>>>>>>>> 3497.718997548:main Q:Reg/w0 : wti 0x23c8ba0, action 2, ptr (nil) >>>>>>>>>>> 3497.719000789:main Q:Reg/w0 : wti 0x23c8ba0, action 3, ptr (nil) >>>>>>>>>>> 3497.719003996:main Q:Reg/w0 : wti 0x23c8ba0, action 4, ptr (nil) >>>>>>>>>>> 3497.719007201:main Q:Reg/w0 : wti 0x23c8ba0, action 5, ptr (nil) >>>>>>>>>>> 3497.719010409:main Q:Reg/w0 : wti 0x23c8ba0, action 6, ptr (nil) >>>>>>>>>>> 3497.719013604:main Q:Reg/w0 : wti 0x23c8ba0, action 7, ptr (nil) >>>>>>>>>>> 3497.719016916:main Q:Reg/w0 : wti 0x23c8ba0: worker exiting >>>>>>>>>>> 3497.719020757:main Q:Reg/w0 : main Q:Reg: Worker thread 23c8ba0, >>>>>>>>>>> terminated, num workers now 0 >>>>>>>>>>> 3497.719090631:main thread : main Q: regular queue workers shut >>>>>>>>>>> down. >>>>>>>>>>> 3497.719097597:main thread : main Q: checking to see if we need >>>>>>>>>>> to >>>>>>>>>>> cancel any worker threads of the primary queue >>>>>>>>>>> 3497.719101335:main thread : main Q: worker threads terminated, >>>>>>>>>>> remaining queue size log 0, phys 0. >>>>>>>>>>> 3497.719111115:main thread : main Q: queue (type 0) will lose 0 >>>>>>>>>>> messages, destroying... >>>>>>>>>>> 3497.719501847:main Q:Reg/w0 : destructor for debug call stack >>>>>>>>>>> 0x7f1ef40008c0 called >>>>>>>>>>> 3497.719547524:main thread : Terminating outputs... >>>>>>>>>>> 3497.719553777:main thread : destructing ruleset 0x23ab150, >>>>>>>>>>> name >>>>>>>>>>> 0x23ab190 >>>>>>>>>>> 3497.719558276:main thread : debug_relp queue: initiating >>>>>>>>>>> worker >>>>>>>>>>> thread >>>>>>>>>>> shutdown sequence >>>>>>>>>>> 3497.719561940:main thread : debug_relp queue: trying shutdown >>>>>>>>>>> of >>>>>>>>>>> regular workers >>>>>>>>>>> 3497.719568068:main thread : sent SIGTTIN to worker thread >>>>>>>>>>> 0xfbb14700 >>>>>>>>>>> 3497.719587478:main thread : debug_relp queue:Reg: waiting 0ms >>>>>>>>>>> on >>>>>>>>>>> worker >>>>>>>>>>> thread termination, 1 still running >>>>>>>>>>> 3497.719593945:debug_relp queue:Reg/w0: end relpSessConnect, iRet >>>>>>>>>>> >>>>>>>>>>> 10014 >>>>>>>>>> >>>>>>>>> >>>>>> 3497.719599684:debug_relp queue:Reg/w0: Action 0 transitioned to >>>>>>> >>>>>>>> >>>>>>>>>>> state: >>>>>>>>>> >>>>>>>>> >>>>>> rtry >>>>>>> >>>>>>>> 3497.719603211:debug_relp queue:Reg/w0: doTransaction: action 0, >>>>>>>>>>> currIParam >>>>>>>>>>> 1 >>>>>>>>>>> 3497.719607186:debug_relp queue:Reg/w0: actionDoRetry: debug_relp >>>>>>>>>>> >>>>>>>>>>> enter >>>>>>>>>> >>>>>>>>> >>>>>> loop, iRetries=0 >>>>>>> >>>>>>>> 3497.719677407:main thread : debug_relp queue:Reg: timeout >>>>>>>>>>> waiting >>>>>>>>>>> on >>>>>>>>>>> worker thread termination >>>>>>>>>>> 3497.719677554:main thread : sent SIGTTIN to worker thread >>>>>>>>>>> 0xfbb14700 >>>>>>>>>>> 3497.719677725:main thread : debug_relp queue: regular shutdown >>>>>>>>>>> timed >>>>>>>>>>> out on primary queue (this is OK) >>>>>>>>>>> 3497.719677897:main thread : debug_relp queue: trying to >>>>>>>>>>> shutdown >>>>>>>>>>> workers within Action Timeoutsetting EnqOnly mode >>>>>>>>>>> 3497.719678191:main thread : debug_relp queue: trying immediate >>>>>>>>>>> shutdown >>>>>>>>>>> of regular workers (if any) >>>>>>>>>>> 3497.719678362:main thread : sent SIGTTIN to worker thread >>>>>>>>>>> 0xfbb14700 >>>>>>>>>>> 3497.719678558:main thread : debug_relp queue:Reg: waiting >>>>>>>>>>> 1000ms >>>>>>>>>>> >>>>>>>>>>> on >>>>>>>>>> >>>>>>>>> >>>>>> worker thread termination, 1 still running >>>>>>> >>>>>>>> 3497.719678754:debug_relp queue:Reg/w0: end relpSessConnect, iRet >>>>>>>>>>> >>>>>>>>>>> 10014 >>>>>>>>>> >>>>>>>>> >>>>>> 3497.719678877:debug_relp queue:Reg/w0: actionDoRetry: debug_relp >>>>>>> >>>>>>>> action->tryResume returned -2007 >>>>>>>>>>> 3497.719678999:debug_relp queue:Reg/w0: actionDoRetry: debug_relp >>>>>>>>>>> >>>>>>>>>>> check >>>>>>>>>> >>>>>>>>> >>>>>> for >>>>>>> >>>>>>>> max retries, iResumeRetryCount -1, iRetries 0 >>>>>>>>>>> 3498.720321005:debug_relp queue:Reg/w0: actionTryResume: action >>>>>>>>>>> 0x23bebf0 >>>>>>>>>>> state: rtry, next retry (if applicable): 0 [now 1459273498] >>>>>>>>>>> 3498.720769277:debug_relp queue:Reg/w0: actionCommit, in retry >>>>>>>>>>> loop, >>>>>>>>>>> iRet >>>>>>>>>>> -2007 >>>>>>>>>>> 3498.721034552:debug_relp queue:Reg/w0: regular consumer finished, >>>>>>>>>>> iret=-2007, szlog 0 sz phys 1 >>>>>>>>>>> 3498.721240322:debug_relp queue:Reg/w0: DeleteProcessedBatch: we >>>>>>>>>>> deleted >>>>>>>>>>> 1 >>>>>>>>>>> objects and enqueued 0 objects >>>>>>>>>>> 3498.721396664:debug_relp queue:Reg/w0: doDeleteBatch: delete >>>>>>>>>>> batch >>>>>>>>>>> from >>>>>>>>>>> store, new sizes: log 0, phys 0 >>>>>>>>>>> 3498.721831840:debug_relp queue:Reg/w0: wti 0x23c78b0: terminating >>>>>>>>>>> worker >>>>>>>>>>> because of TERMINATE_NOW mode, del iRet 0 >>>>>>>>>>> 3498.721991265:debug_relp queue:Reg/w0: DDDD: wti 0x23c78b0: >>>>>>>>>>> worker >>>>>>>>>>> cleanup >>>>>>>>>>> action instances >>>>>>>>>>> 3498.722274489:debug_relp queue:Reg/w0: wti 0x23c78b0, action 0, >>>>>>>>>>> ptr >>>>>>>>>>> 0x7f1ef00020d0 >>>>>>>>>>> 3498.722431811:debug_relp queue:Reg/w0: relp engine destructing >>>>>>>>>>> >>>>>>>>>>> client >>>>>>>>>> >>>>>>>>> >>>>>> 0x7f1ef00027e0 >>>>>>> >>>>>>>> 3498.723389457:debug_relp queue:Reg/w0: wti 0x23c78b0, action 1, ptr >>>>>>>>>>> (nil) >>>>>>>>>>> 3498.723559462:debug_relp queue:Reg/w0: wti 0x23c78b0, action 2, >>>>>>>>>>> ptr >>>>>>>>>>> (nil) >>>>>>>>>>> 3498.723794716:debug_relp queue:Reg/w0: wti 0x23c78b0, action 3, >>>>>>>>>>> ptr >>>>>>>>>>> (nil) >>>>>>>>>>> 3498.723972736:debug_relp queue:Reg/w0: wti 0x23c78b0, action 4, >>>>>>>>>>> ptr >>>>>>>>>>> (nil) >>>>>>>>>>> 3498.724207978:debug_relp queue:Reg/w0: wti 0x23c78b0, action 5, >>>>>>>>>>> ptr >>>>>>>>>>> (nil) >>>>>>>>>>> 3498.724215660:debug_relp queue:Reg/w0: wti 0x23c78b0, action 6, >>>>>>>>>>> ptr >>>>>>>>>>> (nil) >>>>>>>>>>> 3498.724219766:debug_relp queue:Reg/w0: wti 0x23c78b0, action 7, >>>>>>>>>>> ptr >>>>>>>>>>> (nil) >>>>>>>>>>> 3498.724223775:debug_relp queue:Reg/w0: wti 0x23c78b0: worker >>>>>>>>>>> exiting >>>>>>>>>>> 3498.724228430:debug_relp queue:Reg/w0: debug_relp queue:Reg: >>>>>>>>>>> Worker >>>>>>>>>>> thread >>>>>>>>>>> 23c78b0, terminated, num workers now 0 >>>>>>>>>>> 3498.724243673:debug_relp queue:Reg/w0: destructor for debug call >>>>>>>>>>> >>>>>>>>>>> stack >>>>>>>>>> >>>>>>>>> >>>>>> 0x7f1ef00008c0 called >>>>>>> >>>>>>>> 3498.724371931:main thread : debug_relp queue: checking to see if >>>>>>>>>>> >>>>>>>>>>> we >>>>>>>>>> >>>>>>>>> >>>>>> need to cancel any worker threads of the primary queue >>>>>>> >>>>>>>> 3498.724379712:main thread : debug_relp queue: worker threads >>>>>>>>>>> terminated, remaining queue size log 0, phys 0. >>>>>>>>>>> 3498.724386288:main thread : debug_relp queue: persisting queue >>>>>>>>>>> to >>>>>>>>>>> disk, >>>>>>>>>>> 0 entries... >>>>>>>>>>> 3498.724391611:main thread : strm 0x23b74c0: file 5(relp_queue) >>>>>>>>>>> closing >>>>>>>>>>> 3498.724396110:main thread : strm 0x23b74c0: file 5(relp_queue) >>>>>>>>>>> flush, >>>>>>>>>>> buflen 0 (no need to flush) >>>>>>>>>>> 3498.724411574:main thread : strm 0x23b7760: file 6(relp_queue) >>>>>>>>>>> closing >>>>>>>>>>> 3498.724418797:main thread : strm 0x23b7a00: file >>>>>>>>>>> -1(relp_queue) >>>>>>>>>>> closing >>>>>>>>>>> 3498.724423956:main thread : strmCloseFile: deleting >>>>>>>>>>> '/var/spool/rsyslog/relp_queue.00000001' >>>>>>>>>>> 3498.724490018:main thread : strm 0x7f1ef4002480: file >>>>>>>>>>> 4(messages) >>>>>>>>>>> closing >>>>>>>>>>> 3498.724607874:main thread : strm 0x7f1ef4002480: file >>>>>>>>>>> 4(messages) >>>>>>>>>>> flush, buflen 0 (no need to flush) >>>>>>>>>>> 3498.724731690:main thread : all primary multi-thread sources >>>>>>>>>>> have >>>>>>>>>>> been >>>>>>>>>>> terminated - now doing aux cleanup... >>>>>>>>>>> 3498.724737248:main thread : destructing current config... >>>>>>>>>>> 3498.724741760:main thread : calling freeCnf(0x23a91e0) for >>>>>>>>>>> module >>>>>>>>>>> 'builtin:omfile' >>>>>>>>>>> 3498.724745773:main thread : calling freeCnf(0x23a93a0) for >>>>>>>>>>> module >>>>>>>>>>> 'builtin:ompipe' >>>>>>>>>>> 3498.724749977:main thread : calling freeCnf(0x23aa3a0) for >>>>>>>>>>> module >>>>>>>>>>> 'builtin:omfwd' >>>>>>>>>>> 3498.724754588:main thread : calling freeCnf(0x23b9b00) for >>>>>>>>>>> module >>>>>>>>>>> 'imuxsock' >>>>>>>>>>> 3498.724758956:main thread : calling freeCnf(0x23bac70) for >>>>>>>>>>> module >>>>>>>>>>> 'imklog' >>>>>>>>>>> 3498.724807014:main thread : destructing parser >>>>>>>>>>> 'rsyslog.rfc5424' >>>>>>>>>>> 3498.724871141:main thread : destructing parser >>>>>>>>>>> 'rsyslog.rfc3164' >>>>>>>>>>> 3498.724876440:main thread : pmrfc3164: free parser instance >>>>>>>>>>> 0x23aa8b0 >>>>>>>>>>> 3498.724887558:main thread : file rsyslogd.c released module >>>>>>>>>>> 'lmnet', >>>>>>>>>>> reference count now 2 >>>>>>>>>>> 3498.724892004:main thread : module lmnet NOT unloaded because >>>>>>>>>>> it >>>>>>>>>>> still >>>>>>>>>>> has a refcount of 2 >>>>>>>>>>> 3498.724895745:main thread : Unloading module builtin:omfile >>>>>>>>>>> 3498.724900191:main thread : module lmnet NOT unloaded because >>>>>>>>>>> it >>>>>>>>>>> still >>>>>>>>>>> has a refcount of 2 >>>>>>>>>>> 3498.724904194:main thread : Unloading module builtin:ompipe >>>>>>>>>>> 3498.724908035:main thread : module lmnet NOT unloaded because >>>>>>>>>>> it >>>>>>>>>>> still >>>>>>>>>>> has a refcount of 2 >>>>>>>>>>> 3498.724911707:main thread : Unloading module builtin-shell >>>>>>>>>>> 3498.725044125:main thread : module lmnet NOT unloaded because >>>>>>>>>>> it >>>>>>>>>>> still >>>>>>>>>>> has a refcount of 2 >>>>>>>>>>> 3498.725050401:main thread : Unloading module builtin:omdiscard >>>>>>>>>>> 3498.725054843:main thread : module lmnet NOT unloaded because >>>>>>>>>>> it >>>>>>>>>>> still >>>>>>>>>>> has a refcount of 2 >>>>>>>>>>> 3498.725058772:main thread : Unloading module builtin:omfwd >>>>>>>>>>> 3498.725064464:main thread : file omfwd.c released module >>>>>>>>>>> 'lmnet', >>>>>>>>>>> reference count now 1 >>>>>>>>>>> 3498.725068747:main thread : module lmnet NOT unloaded because >>>>>>>>>>> it >>>>>>>>>>> still >>>>>>>>>>> has a refcount of 1 >>>>>>>>>>> 3498.725072460:main thread : Unloading module builtin:omusrmsg >>>>>>>>>>> 3498.725076324:main thread : module lmnet NOT unloaded because >>>>>>>>>>> it >>>>>>>>>>> still >>>>>>>>>>> has a refcount of 1 >>>>>>>>>>> 3498.725080023:main thread : Unloading module builtin:pmrfc5424 >>>>>>>>>>> 3498.725084039:main thread : module lmnet NOT unloaded because >>>>>>>>>>> it >>>>>>>>>>> still >>>>>>>>>>> has a refcount of 1 >>>>>>>>>>> 3498.725087646:main thread : Unloading module builtin:pmrfc3164 >>>>>>>>>>> 3498.725091651:main thread : module lmnet NOT unloaded because >>>>>>>>>>> it >>>>>>>>>>> still >>>>>>>>>>> has a refcount of 1 >>>>>>>>>>> 3498.725095255:main thread : Unloading module builtin:smfile >>>>>>>>>>> 3498.725099010:main thread : module lmnet NOT unloaded because >>>>>>>>>>> it >>>>>>>>>>> still >>>>>>>>>>> has a refcount of 1 >>>>>>>>>>> 3498.725102601:main thread : Unloading module >>>>>>>>>>> builtin:smtradfile >>>>>>>>>>> 3498.725106419:main thread : module lmnet NOT unloaded because >>>>>>>>>>> it >>>>>>>>>>> still >>>>>>>>>>> has a refcount of 1 >>>>>>>>>>> 3498.725110003:main thread : Unloading module builtin:smfwd >>>>>>>>>>> 3498.725113689:main thread : module lmnet NOT unloaded because >>>>>>>>>>> it >>>>>>>>>>> still >>>>>>>>>>> has a refcount of 1 >>>>>>>>>>> 3498.725117357:main thread : Unloading module builtin:smtradfwd >>>>>>>>>>> 3498.725121132:main thread : module lmnet NOT unloaded because >>>>>>>>>>> it >>>>>>>>>>> still >>>>>>>>>>> has a refcount of 1 >>>>>>>>>>> 3498.725124782:main thread : Unloading module imuxsock >>>>>>>>>>> 3498.725157459:main thread : module lmnet NOT unloaded because >>>>>>>>>>> it >>>>>>>>>>> still >>>>>>>>>>> has a refcount of 1 >>>>>>>>>>> 3498.725162797:main thread : Unloading module imklog >>>>>>>>>>> 3498.725179208:main thread : module lmnet NOT unloaded because >>>>>>>>>>> it >>>>>>>>>>> still >>>>>>>>>>> has a refcount of 1 >>>>>>>>>>> 3498.726112994:main thread : Unloading module omrelp >>>>>>>>>>> 3498.726184405:main thread : module lmnet NOT unloaded because >>>>>>>>>>> it >>>>>>>>>>> still >>>>>>>>>>> has a refcount of 1 >>>>>>>>>>> 3498.726189821:main thread : module lmregexp NOT unloaded >>>>>>>>>>> because >>>>>>>>>>> >>>>>>>>>>> it >>>>>>>>>> >>>>>>>>> >>>>>> still has a refcount of 1 >>>>>>> >>>>>>>> 3498.726195161:main thread : file conf.c released module 'lmnet', >>>>>>>>>>> reference count now 0 >>>>>>>>>>> 3498.726198620:main thread : module 'lmnet' has zero reference >>>>>>>>>>> count, >>>>>>>>>>> unloading... >>>>>>>>>>> 3498.726201936:main thread : Unloading module lmnet >>>>>>>>>>> 3498.726218655:main thread : rsyslog runtime de-initialized, >>>>>>>>>>> >>>>>>>>>>> current >>>>>>>>>> >>>>>>>>> >>>>>> users 0 >>>>>>> >>>>>>>> 3498.726222660:main thread : Clean shutdown completed, bye >>>>>>>>>>> >>>>>>>>>>> >>>>>>>>>>> On Mon, Mar 28, 2016 at 4:41 PM, Kane Kim <[email protected]> >>>>>>>>>>> wrote: >>>>>>>>>>> >>>>>>>>>>> Hello Reiner, >>>>>>>>>>> >>>>>>>>>>> >>>>>>>>>>>> >>>>>>>>>>>> I'm seeing the same behavior with omrelp module. I've configured >>>>>>>>>>>> omrelp >>>>>>>>>>>> to >>>>>>>>>>>> non-routable ip address: >>>>>>>>>>>> module(load="omrelp") >>>>>>>>>>>> local0.* action(type="omrelp" >>>>>>>>>>>> target="10.0.0.1" >>>>>>>>>>>> port="2514" >>>>>>>>>>>> name="debug_relp" >>>>>>>>>>>> queue.filename="relp_queue" >>>>>>>>>>>> queue.maxdiskspace="1G" >>>>>>>>>>>> queue.saveonshutdown="on" >>>>>>>>>>>> queue.spoolDirectory="/var/spool/rsyslog" >>>>>>>>>>>> queue.type="Disk" >>>>>>>>>>>> ) >>>>>>>>>>>> Then I try to log a line: >>>>>>>>>>>> [root@314959ac8cb0 prism]# logger -p local0.info test >>>>>>>>>>>> [root@314959ac8cb0 prism]# ls /var/spool/rsyslog/ >>>>>>>>>>>> relp_queue.00000001 >>>>>>>>>>>> # I shutdown rsyslog at this point >>>>>>>>>>>> [root@314959ac8cb0 prism]# ls /var/spool/rsyslog/ >>>>>>>>>>>> # after shutdown queue is deleted and message is lost >>>>>>>>>>>> [root@314959ac8cb0 prism]# >>>>>>>>>>>> >>>>>>>>>>>> Here is rsyslog log, so omrelp starts transaction and then I >>>>>>>>>>>> >>>>>>>>>>>> shutdown >>>>>>>>>>> >>>>>>>>>> >>>>>> rsyslog, it seems at some point queue is deleted: >>>>>>> >>>>>>>> >>>>>>>>>>>> 8184.798028612:debug_relp queue:Reg/w0: omrelp: beginTransaction >>>>>>>>>>>> ^C8194.245122305:main thread : DoDie called. >>>>>>>>>>>> 8194.245301525:main thread : exiting on signal 2 >>>>>>>>>>>> 8194.245532709:main thread : Terminating input threads... >>>>>>>>>>>> 8194.245873683:main thread : request term via SIGTTIN for >>>>>>>>>>>> input >>>>>>>>>>>> thread >>>>>>>>>>>> 'imuxsock' 0xcb767700 >>>>>>>>>>>> 8194.246079748:imuxsock.c : thrdStarter: usrThrdMain >>>>>>>>>>>> imuxsock - >>>>>>>>>>>> 0x7f9bcb767700 returned with iRet 0, exiting now. >>>>>>>>>>>> 8194.247556671:main thread : non-cancel input thread >>>>>>>>>>>> termination >>>>>>>>>>>> succeeded for thread imuxsock 0xcb767700 >>>>>>>>>>>> 8194.249357547:imuxsock.c : destructor for debug call stack >>>>>>>>>>>> 0x7f9bbc0008c0 called >>>>>>>>>>>> 8194.249784271:main thread : imuxsock: unlinking unix socket >>>>>>>>>>>> file[0] >>>>>>>>>>>> /dev/log >>>>>>>>>>>> 8194.250043368:main thread : main Q: qqueueAdd: entry added, >>>>>>>>>>>> size >>>>>>>>>>>> now >>>>>>>>>>>> log 1, phys 1 entries >>>>>>>>>>>> 8194.250321193:main thread : main Q: EnqueueMsg advised worker >>>>>>>>>>>> start >>>>>>>>>>>> 8194.250493505:main Q:Reg/w0 : wti 0x1c13bb0: worker awoke from >>>>>>>>>>>> >>>>>>>>>>>> idle >>>>>>>>>>> >>>>>>>>>> >>>>>> processing >>>>>>> >>>>>>>> 8194.250735988:main Q:Reg/w0 : DeleteProcessedBatch: we deleted 0 >>>>>>>>>>>> objects >>>>>>>>>>>> and enqueued 0 objects >>>>>>>>>>>> 8194.250959294:main Q:Reg/w0 : doDeleteBatch: delete batch from >>>>>>>>>>>> store, >>>>>>>>>>>> new sizes: log 1, phys 1 >>>>>>>>>>>> 8194.251913535:main Q:Reg/w0 : processBATCH: batch of 1 elements >>>>>>>>>>>> >>>>>>>>>>>> must >>>>>>>>>>> >>>>>>>>>> >>>>>> be >>>>>>> >>>>>>>> processed >>>>>>>>>>>> 8194.252193683:main Q:Reg/w0 : processBATCH: next msg 0: >>>>>>>>>>>> [origin >>>>>>>>>>>> software="rsyslogd" swVersion="8.18.0.master" x-pid="30298" >>>>>>>>>>>> x-info=" >>>>>>>>>>>> http://www.rsyslog.com";] exiting on signal 2. >>>>>>>>>>>> 8194.252377044:main Q:Reg/w0 : PRIFILT 'local0.*' >>>>>>>>>>>> 8194.252669683:main Q:Reg/w0 : pmask: X X X X X X X >>>>>>>>>>>> X >>>>>>>>>>>> >>>>>>>>>>>> X >>>>>>>>>>> >>>>>>>>>> >>>>>> X >>>>>>> >>>>>>>> X X X X X X FF X X X X X X X X X >>>>>>>>>>>> 8194.252898063:main Q:Reg/w0 : PRIFILT condition result is 0 >>>>>>>>>>>> 8194.252902083:main Q:Reg/w0 : PRIFILT >>>>>>>>>>>> '*.info;mail.none;authpriv.none;cron.none' >>>>>>>>>>>> 8194.252908847:main Q:Reg/w0 : pmask: 7F 7F X 7F 7F 7F 7F >>>>>>>>>>>> 7F >>>>>>>>>>>> >>>>>>>>>>>> 7F >>>>>>>>>>> >>>>>>>>>> >>>>>> X >>>>>>> >>>>>>>> X 7F 7F 7F 7F 7F 7F 7F 7F 7F 7F 7F 7F 7F 7F 7F >>>>>>>>>>>> 8194.252956209:main Q:Reg/w0 : PRIFILT condition result is 1 >>>>>>>>>>>> 8194.252959849:main Q:Reg/w0 : ACTION 1 >>>>>>>>>>>> [builtin:omfile:/var/log/messages] >>>>>>>>>>>> 8194.252967510:main Q:Reg/w0 : executing action 1 >>>>>>>>>>>> 8194.252971541:main Q:Reg/w0 : action 'action 1': called, >>>>>>>>>>>> logging >>>>>>>>>>>> >>>>>>>>>>>> to >>>>>>>>>>> >>>>>>>>>> >>>>>> builtin:omfile (susp 0/0, direct q 1) >>>>>>> >>>>>>>> 8194.252977583:main Q:Reg/w0 : action 'action 1': is transactional >>>>>>>>>>>> >>>>>>>>>>>> - >>>>>>>>>>> >>>>>>>>>> >>>>>> executing in commit phase >>>>>>> >>>>>>>> 8194.252982638:main Q:Reg/w0 : Action 1 transitioned to state: itx >>>>>>>>>>>> 8194.252986300:main Q:Reg/w0 : action 'action 1': set suspended >>>>>>>>>>>> >>>>>>>>>>>> state >>>>>>>>>>> >>>>>>>>>> >>>>>> to 0 >>>>>>> >>>>>>>> 8194.252989729:main Q:Reg/w0 : PRIFILT 'authpriv.*' >>>>>>>>>>>> 8194.252996951:main Q:Reg/w0 : pmask: X X X X X X X >>>>>>>>>>>> X >>>>>>>>>>>> >>>>>>>>>>>> X >>>>>>>>>>> >>>>>>>>>> >>>>>> X >>>>>>> >>>>>>>> FF X X X X X X X X X X X X X X X >>>>>>>>>>>> 8194.253051858:main Q:Reg/w0 : PRIFILT condition result is 0 >>>>>>>>>>>> 8194.253056228:main Q:Reg/w0 : PRIFILT 'mail.*' >>>>>>>>>>>> 8194.253065299:main Q:Reg/w0 : pmask: X X FF X X X X >>>>>>>>>>>> X >>>>>>>>>>>> >>>>>>>>>>>> X >>>>>>>>>>> >>>>>>>>>> >>>>>> X >>>>>>> >>>>>>>> X X X X X X X X X X X X X X X X >>>>>>>>>>>> 8194.253407472:main Q:Reg/w0 : PRIFILT condition result is 0 >>>>>>>>>>>> 8194.253412679:main Q:Reg/w0 : PRIFILT 'cron.*' >>>>>>>>>>>> 8194.253422055:main Q:Reg/w0 : pmask: X X X X X X X >>>>>>>>>>>> X >>>>>>>>>>>> >>>>>>>>>>>> X >>>>>>>>>>> >>>>>>>>>> >>>>>> FF >>>>>>> >>>>>>>> X X X X X X X X X X X X X X X X >>>>>>>>>>>> 8194.253493551:main Q:Reg/w0 : PRIFILT condition result is 0 >>>>>>>>>>>> 8194.253498038:main Q:Reg/w0 : PRIFILT '*.emerg' >>>>>>>>>>>> 8194.253507065:main Q:Reg/w0 : pmask: 1 1 1 1 1 1 1 >>>>>>>>>>>> 1 >>>>>>>>>>>> >>>>>>>>>>>> 1 >>>>>>>>>>> >>>>>>>>>> >>>>>> 1 >>>>>>> >>>>>>>> 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 1 >>>>>>>>>>>> 8194.253580307:main Q:Reg/w0 : PRIFILT condition result is 0 >>>>>>>>>>>> 8194.253584400:main Q:Reg/w0 : PRIFILT 'uucp,news.crit' >>>>>>>>>>>> 8194.253593442:main Q:Reg/w0 : pmask: X X X X X X X >>>>>>>>>>>> 7 >>>>>>>>>>>> >>>>>>>>>>>> 7 >>>>>>>>>>> >>>>>>>>>> >>>>>> X >>>>>>> >>>>>>>> X X X X X X X X X X X X X X X X >>>>>>>>>>>> 8194.253664984:main Q:Reg/w0 : PRIFILT condition result is 0 >>>>>>>>>>>> 8194.253669184:main Q:Reg/w0 : PRIFILT 'local7.*' >>>>>>>>>>>> 8194.253678130:main Q:Reg/w0 : pmask: X X X X X X X >>>>>>>>>>>> X >>>>>>>>>>>> >>>>>>>>>>>> X >>>>>>>>>>> >>>>>>>>>> >>>>>> X >>>>>>> >>>>>>>> X X X X X X X X X X X X X FF X X >>>>>>>>>>>> 8194.254445021:main Q:Reg/w0 : PRIFILT condition result is 0 >>>>>>>>>>>> 8194.254450651:main Q:Reg/w0 : END batch execution phase, >>>>>>>>>>>> entering >>>>>>>>>>>> >>>>>>>>>>>> to >>>>>>>>>>> >>>>>>>>>> >>>>>> commit phase [processed 1 of 1 messages] >>>>>>> >>>>>>>> 8194.254456257:main Q:Reg/w0 : actionCommitAll: action 1, state 1, >>>>>>>>>>>> nbr >>>>>>>>>>>> to >>>>>>>>>>>> commit 0 isTransactional 1 >>>>>>>>>>>> 8194.254461646:main Q:Reg/w0 : doTransaction: have >>>>>>>>>>>> >>>>>>>>>>>> commitTransaction >>>>>>>>>>> >>>>>>>>>> >>>>>> IF, >>>>>>> >>>>>>>> using that, pWrkrInfo 0x1c13cf0 >>>>>>>>>>>> 8194.254466238:main Q:Reg/w0 : entering >>>>>>>>>>>> actionCallCommitTransaction(), >>>>>>>>>>>> state: itx, actionNbr 1, nMsgs 1 >>>>>>>>>>>> 8194.254471876:main Q:Reg/w0 : omfile: write to stream, >>>>>>>>>>>> >>>>>>>>>>>> pData->pStrm >>>>>>>>>>> >>>>>>>>>> >>>>>> 0x7f9bc4002480, lenBuf 161, strt data Mar 28 23:36:34 314959ac8cb0 >>>>>>> >>>>>>>> rsyslogd: [origin software="rsyslogd" swVersion="8.18.0.master" >>>>>>>>>>>> x-pid="30298" x-info="http://www.rs >>>>>>>>>>>> 8194.254478237:main Q:Reg/w0 : strm 0x7f9bc4002480: file >>>>>>>>>>>> >>>>>>>>>>>> 4(messages) >>>>>>>>>>> >>>>>>>>>> >>>>>> flush, buflen 161 >>>>>>> >>>>>>>> 8194.254483210:main Q:Reg/w0 : strmPhysWrite, stream >>>>>>>>>>>> >>>>>>>>>>>> 0x7f9bc4002480, >>>>>>>>>>> >>>>>>>>>> >>>>>> len >>>>>>> >>>>>>>> 161 >>>>>>>>>>>> 8194.254500329:main Q:Reg/w0 : strm 0x7f9bc4002480: file 4 write >>>>>>>>>>>> wrote >>>>>>>>>>>> 161 bytes >>>>>>>>>>>> 8194.254506254:main Q:Reg/w0 : Action 1 transitioned to state: >>>>>>>>>>>> rdy >>>>>>>>>>>> 8194.254511506:main Q:Reg/w0 : Action 1 transitioned to state: >>>>>>>>>>>> itx >>>>>>>>>>>> 8194.254515961:main Q:Reg/w0 : Action 1 transitioned to state: >>>>>>>>>>>> rdy >>>>>>>>>>>> 8194.254520243:main Q:Reg/w0 : actionCommit, in retry loop, >>>>>>>>>>>> iRet 0 >>>>>>>>>>>> 8194.254524679:main Q:Reg/w0 : processBATCH: batch of 1 elements >>>>>>>>>>>> >>>>>>>>>>>> has >>>>>>>>>>> >>>>>>>>>> >>>>>> been >>>>>>> >>>>>>>> processed >>>>>>>>>>>> 8194.254529731:main Q:Reg/w0 : regular consumer finished, >>>>>>>>>>>> iret=0, >>>>>>>>>>>> szlog 0 >>>>>>>>>>>> sz phys 1 >>>>>>>>>>>> 8194.254536104:main Q:Reg/w0 : DeleteProcessedBatch: we deleted >>>>>>>>>>>> 1 >>>>>>>>>>>> objects >>>>>>>>>>>> and enqueued 0 objects >>>>>>>>>>>> 8194.254540861:main Q:Reg/w0 : doDeleteBatch: delete batch from >>>>>>>>>>>> store, >>>>>>>>>>>> new sizes: log 0, phys 0 >>>>>>>>>>>> 8194.254545792:main Q:Reg/w0 : regular consumer finished, >>>>>>>>>>>> iret=4, >>>>>>>>>>>> szlog 0 >>>>>>>>>>>> sz phys 0 >>>>>>>>>>>> 8194.254550314:main Q:Reg/w0 : main Q:Reg/w0: worker IDLE, >>>>>>>>>>>> waiting >>>>>>>>>>>> for >>>>>>>>>>>> work. >>>>>>>>>>>> 8194.254556418:main thread : Terminating main queue... >>>>>>>>>>>> 8194.254560776:main thread : main Q: initiating worker thread >>>>>>>>>>>> shutdown >>>>>>>>>>>> sequence >>>>>>>>>>>> 8194.254564653:main thread : main Q: trying shutdown of >>>>>>>>>>>> regular >>>>>>>>>>>> workers >>>>>>>>>>>> 8194.254572961:main thread : sent SIGTTIN to worker thread >>>>>>>>>>>> 0xcaf66700 >>>>>>>>>>>> 8194.254577260:main thread : main Q:Reg: waiting 1499ms on >>>>>>>>>>>> worker >>>>>>>>>>>> thread termination, 1 still running >>>>>>>>>>>> 8194.254585507:main Q:Reg/w0 : wti 0x1c13bb0: worker awoke from >>>>>>>>>>>> >>>>>>>>>>>> idle >>>>>>>>>>> >>>>>>>>>> >>>>>> processing >>>>>>> >>>>>>>> 8194.254589465:main Q:Reg/w0 : DeleteProcessedBatch: we deleted 0 >>>>>>>>>>>> objects >>>>>>>>>>>> and enqueued 0 objects >>>>>>>>>>>> 8194.254593070:main Q:Reg/w0 : doDeleteBatch: delete batch from >>>>>>>>>>>> store, >>>>>>>>>>>> new sizes: log 0, phys 0 >>>>>>>>>>>> 8194.254596813:main Q:Reg/w0 : regular consumer finished, >>>>>>>>>>>> iret=4, >>>>>>>>>>>> szlog 0 >>>>>>>>>>>> sz phys 0 >>>>>>>>>>>> 8194.254600412:main Q:Reg/w0 : wti 0x1c13bb0: terminating worker >>>>>>>>>>>> terminateRet=5, bInactivityTOOccured=0 >>>>>>>>>>>> 8194.254604469:main Q:Reg/w0 : DDDD: wti 0x1c13bb0: worker >>>>>>>>>>>> cleanup >>>>>>>>>>>> action >>>>>>>>>>>> instances >>>>>>>>>>>> 8194.254608268:main Q:Reg/w0 : wti 0x1c13bb0, action 0, ptr >>>>>>>>>>>> (nil) >>>>>>>>>>>> 8194.254611752:main Q:Reg/w0 : wti 0x1c13bb0, action 1, ptr >>>>>>>>>>>> 0x7f9bc40022a0 >>>>>>>>>>>> 8194.254616114:main Q:Reg/w0 : wti 0x1c13bb0, action 2, ptr >>>>>>>>>>>> (nil) >>>>>>>>>>>> 8194.254619450:main Q:Reg/w0 : wti 0x1c13bb0, action 3, ptr >>>>>>>>>>>> (nil) >>>>>>>>>>>> 8194.254622767:main Q:Reg/w0 : wti 0x1c13bb0, action 4, ptr >>>>>>>>>>>> (nil) >>>>>>>>>>>> 8194.254626075:main Q:Reg/w0 : wti 0x1c13bb0, action 5, ptr >>>>>>>>>>>> (nil) >>>>>>>>>>>> 8194.254629392:main Q:Reg/w0 : wti 0x1c13bb0, action 6, ptr >>>>>>>>>>>> (nil) >>>>>>>>>>>> 8194.254632707:main Q:Reg/w0 : wti 0x1c13bb0, action 7, ptr >>>>>>>>>>>> (nil) >>>>>>>>>>>> 8194.254636124:main Q:Reg/w0 : wti 0x1c13bb0: worker exiting >>>>>>>>>>>> 8194.254639920:main Q:Reg/w0 : main Q:Reg: Worker thread >>>>>>>>>>>> 1c13bb0, >>>>>>>>>>>> terminated, num workers now 0 >>>>>>>>>>>> 8194.254656279:main thread : main Q: regular queue workers >>>>>>>>>>>> shut >>>>>>>>>>>> down. >>>>>>>>>>>> 8194.254656402:main thread : main Q: checking to see if we >>>>>>>>>>>> need >>>>>>>>>>>> >>>>>>>>>>>> to >>>>>>>>>>> >>>>>>>>>> >>>>>> cancel any worker threads of the primary queue >>>>>>> >>>>>>>> 8194.254656524:main thread : main Q: worker threads terminated, >>>>>>>>>>>> remaining queue size log 0, phys 0. >>>>>>>>>>>> 8194.254656647:main thread : main Q: queue (type 0) will lose >>>>>>>>>>>> 0 >>>>>>>>>>>> messages, destroying... >>>>>>>>>>>> 8194.255021761:main Q:Reg/w0 : destructor for debug call stack >>>>>>>>>>>> 0x7f9bc40008c0 called >>>>>>>>>>>> 8194.255069521:main thread : Terminating outputs... >>>>>>>>>>>> 8194.255084818:main thread : destructing ruleset 0x1bf6150, >>>>>>>>>>>> name >>>>>>>>>>>> 0x1bf6190 >>>>>>>>>>>> 8194.255089525:main thread : debug_relp queue: initiating >>>>>>>>>>>> worker >>>>>>>>>>>> thread >>>>>>>>>>>> shutdown sequence >>>>>>>>>>>> 8194.255093230:main thread : debug_relp queue: trying shutdown >>>>>>>>>>>> of >>>>>>>>>>>> regular workers >>>>>>>>>>>> 8194.255099210:main thread : sent SIGTTIN to worker thread >>>>>>>>>>>> 0xca765700 >>>>>>>>>>>> 8194.255119598:main thread : debug_relp queue:Reg: waiting 0ms >>>>>>>>>>>> on >>>>>>>>>>>> worker thread termination, 1 still running >>>>>>>>>>>> 8194.255126357:debug_relp queue:Reg/w0: end relpSessConnect, iRet >>>>>>>>>>>> 10014 >>>>>>>>>>>> 8194.255132022:debug_relp queue:Reg/w0: Action 0 transitioned to >>>>>>>>>>>> state: >>>>>>>>>>>> rtry >>>>>>>>>>>> 8194.255135551:debug_relp queue:Reg/w0: doTransaction: action 0, >>>>>>>>>>>> currIParam 1 >>>>>>>>>>>> 8194.255139603:debug_relp queue:Reg/w0: actionDoRetry: debug_relp >>>>>>>>>>>> enter >>>>>>>>>>>> loop, iRetries=0 >>>>>>>>>>>> 8194.255210939:main thread : debug_relp queue:Reg: timeout >>>>>>>>>>>> >>>>>>>>>>>> waiting >>>>>>>>>>> >>>>>>>>>> >>>>>> on >>>>>>> >>>>>>>> worker thread termination >>>>>>>>>>>> 8194.255211086:main thread : sent SIGTTIN to worker thread >>>>>>>>>>>> 0xca765700 >>>>>>>>>>>> 8194.255211257:main thread : debug_relp queue: regular >>>>>>>>>>>> shutdown >>>>>>>>>>>> timed >>>>>>>>>>>> out on primary queue (this is OK) >>>>>>>>>>>> 8194.255211429:main thread : debug_relp queue: trying to >>>>>>>>>>>> shutdown >>>>>>>>>>>> workers within Action Timeoutsetting EnqOnly mode >>>>>>>>>>>> 8194.255215492:main thread : debug_relp queue: trying >>>>>>>>>>>> immediate >>>>>>>>>>>> shutdown of regular workers (if any) >>>>>>>>>>>> 8194.255221059:main thread : sent SIGTTIN to worker thread >>>>>>>>>>>> 0xca765700 >>>>>>>>>>>> 8194.255226792:main thread : debug_relp queue:Reg: waiting >>>>>>>>>>>> 1000ms >>>>>>>>>>>> on >>>>>>>>>>>> worker thread termination, 1 still running >>>>>>>>>>>> 8194.255232713:debug_relp queue:Reg/w0: end relpSessConnect, iRet >>>>>>>>>>>> 10014 >>>>>>>>>>>> 8194.255237080:debug_relp queue:Reg/w0: actionDoRetry: debug_relp >>>>>>>>>>>> action->tryResume returned -2007 >>>>>>>>>>>> 8194.255240684:debug_relp queue:Reg/w0: actionDoRetry: debug_relp >>>>>>>>>>>> check >>>>>>>>>>>> for max retries, iResumeRetryCount 0, iRetries 0 >>>>>>>>>>>> 8194.255244459:debug_relp queue:Reg/w0: Action 0 transitioned to >>>>>>>>>>>> state: >>>>>>>>>>>> susp >>>>>>>>>>>> 8194.255257975:debug_relp queue:Reg/w0: Called LogMsg, msg: >>>>>>>>>>>> action >>>>>>>>>>>> 'debug_relp' suspended, next retry is Mon Mar 28 23:37:04 2016 >>>>>>>>>>>> 8194.255266857:debug_relp queue:Reg/w0: submitMsg2() could not >>>>>>>>>>>> >>>>>>>>>>>> submit >>>>>>>>>>> >>>>>>>>>> >>>>>> message - queue does (no longer?) exist - ignored >>>>>>> >>>>>>>> 8194.255271065:debug_relp queue:Reg/w0: action 'debug_relp' >>>>>>>>>>>> >>>>>>>>>>>> suspended, >>>>>>>>>>> >>>>>>>>>> >>>>>> earliest retry=1459208224 (now 1459208194), iNbrResRtry 0, duration >>>>>>> >>>>>>>> >>>>>>>>>>>> 30 >>>>>>>>>>> >>>>>>>>>> >>>>>> 8194.255275244:debug_relp queue:Reg/w0: actionTryResume: action >>>>>>> >>>>>>>> 0x1c09af0 >>>>>>>>>>>> state: susp, next retry (if applicable): 1459208224 [now >>>>>>>>>>>> 1459208194] >>>>>>>>>>>> 8194.255278825:debug_relp queue:Reg/w0: actionCommit, in retry >>>>>>>>>>>> loop, >>>>>>>>>>>> iRet >>>>>>>>>>>> -2123 >>>>>>>>>>>> 8194.255282409:debug_relp queue:Reg/w0: regular consumer >>>>>>>>>>>> finished, >>>>>>>>>>>> iret=-2123, szlog 0 sz phys 1 >>>>>>>>>>>> 8194.255287286:debug_relp queue:Reg/w0: DeleteProcessedBatch: we >>>>>>>>>>>> deleted 1 >>>>>>>>>>>> objects and enqueued 0 objects >>>>>>>>>>>> 8194.255290952:debug_relp queue:Reg/w0: doDeleteBatch: delete >>>>>>>>>>>> batch >>>>>>>>>>>> from >>>>>>>>>>>> store, new sizes: log 0, phys 0 >>>>>>>>>>>> 8194.255295204:debug_relp queue:Reg/w0: wti 0x1c12880: >>>>>>>>>>>> terminating >>>>>>>>>>>> worker >>>>>>>>>>>> because of TERMINATE_NOW mode, del iRet 0 >>>>>>>>>>>> 8194.255298822:debug_relp queue:Reg/w0: DDDD: wti 0x1c12880: >>>>>>>>>>>> worker >>>>>>>>>>>> cleanup action instances >>>>>>>>>>>> 8194.255302306:debug_relp queue:Reg/w0: wti 0x1c12880, action 0, >>>>>>>>>>>> ptr >>>>>>>>>>>> 0x7f9bc00020d0 >>>>>>>>>>>> 8194.255305929:debug_relp queue:Reg/w0: relp engine destructing >>>>>>>>>>>> >>>>>>>>>>>> client >>>>>>>>>>> >>>>>>>>>> >>>>>> 0x7f9bc00027e0 >>>>>>> >>>>>>>> 8194.255309843:debug_relp queue:Reg/w0: wti 0x1c12880, action 1, >>>>>>>>>>>> ptr >>>>>>>>>>>> (nil) >>>>>>>>>>>> 8194.255313226:debug_relp queue:Reg/w0: wti 0x1c12880, action 2, >>>>>>>>>>>> ptr >>>>>>>>>>>> (nil) >>>>>>>>>>>> 8194.255316479:debug_relp queue:Reg/w0: wti 0x1c12880, action 3, >>>>>>>>>>>> ptr >>>>>>>>>>>> (nil) >>>>>>>>>>>> 8194.255319704:debug_relp queue:Reg/w0: wti 0x1c12880, action 4, >>>>>>>>>>>> ptr >>>>>>>>>>>> (nil) >>>>>>>>>>>> 8194.255322934:debug_relp queue:Reg/w0: wti 0x1c12880, action 5, >>>>>>>>>>>> ptr >>>>>>>>>>>> (nil) >>>>>>>>>>>> 8194.255326175:debug_relp queue:Reg/w0: wti 0x1c12880, action 6, >>>>>>>>>>>> ptr >>>>>>>>>>>> (nil) >>>>>>>>>>>> 8194.255329409:debug_relp queue:Reg/w0: wti 0x1c12880, action 7, >>>>>>>>>>>> ptr >>>>>>>>>>>> (nil) >>>>>>>>>>>> 8194.255332655:debug_relp queue:Reg/w0: wti 0x1c12880: worker >>>>>>>>>>>> >>>>>>>>>>>> exiting >>>>>>>>>>> >>>>>>>>>> >>>>>> 8194.255336231:debug_relp queue:Reg/w0: debug_relp queue:Reg: Worker >>>>>>> >>>>>>>> thread 1c12880, terminated, num workers now 0 >>>>>>>>>>>> 8194.255344540:debug_relp queue:Reg/w0: destructor for debug call >>>>>>>>>>>> stack >>>>>>>>>>>> 0x7f9bc00008c0 called >>>>>>>>>>>> 8194.255371534:main thread : debug_relp queue: checking to see >>>>>>>>>>>> if >>>>>>>>>>>> we >>>>>>>>>>>> need to cancel any worker threads of the primary queue >>>>>>>>>>>> 8194.255376798:main thread : debug_relp queue: worker threads >>>>>>>>>>>> terminated, remaining queue size log 0, phys 0. >>>>>>>>>>>> 8194.255381256:main thread : debug_relp queue: persisting >>>>>>>>>>>> queue >>>>>>>>>>>> >>>>>>>>>>>> to >>>>>>>>>>> >>>>>>>>>> >>>>>> disk, 0 entries... >>>>>>> >>>>>>>> 8194.255385525:main thread : strm 0x1c024c0: file 5(relp_queue) >>>>>>>>>>>> closing >>>>>>>>>>>> 8194.255389222:main thread : strm 0x1c024c0: file >>>>>>>>>>>> 5(relp_queue) >>>>>>>>>>>> flush, >>>>>>>>>>>> buflen 0 (no need to flush) >>>>>>>>>>>> 8194.255398716:main thread : strm 0x1c02760: file >>>>>>>>>>>> 6(relp_queue) >>>>>>>>>>>> closing >>>>>>>>>>>> 8194.255404785:main thread : strm 0x1c02a00: file >>>>>>>>>>>> -1(relp_queue) >>>>>>>>>>>> closing >>>>>>>>>>>> 8194.255409145:main thread : strmCloseFile: deleting >>>>>>>>>>>> '/var/spool/rsyslog/relp_queue.00000001' >>>>>>>>>>>> 8194.255460812:main thread : strm 0x7f9bc4002480: file >>>>>>>>>>>> >>>>>>>>>>>> 4(messages) >>>>>>>>>>> >>>>>>>>>> >>>>>> closing >>>>>> >>>>>> > _______________________________________________ > rsyslog mailing list > http://lists.adiscon.net/mailman/listinfo/rsyslog > http://www.rsyslog.com/professional-services/ > What's up with rsyslog? Follow https://twitter.com/rgerhards > NOTE WELL: This is a PUBLIC mailing list, posts are ARCHIVED by a myriad of > sites beyond our control. PLEASE UNSUBSCRIBE and DO NOT POST if you DON'T > LIKE THAT. _______________________________________________ rsyslog mailing list http://lists.adiscon.net/mailman/listinfo/rsyslog http://www.rsyslog.com/professional-services/ What's up with rsyslog? Follow https://twitter.com/rgerhards NOTE WELL: This is a PUBLIC mailing list, posts are ARCHIVED by a myriad of sites beyond our control. PLEASE UNSUBSCRIBE and DO NOT POST if you DON'T LIKE THAT.
