This is with latest master On Mar 2, 2016 9:27 PM, "David Lang" <[email protected]> wrote:
> is this with 8.16 or with the git tree? (what will be 8.17 next week) > > David Lang > > On Wed, 2 Mar 2016, Kane Kim wrote: > > Date: Wed, 2 Mar 2016 15:08:39 -0800 >> 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 >> >> Hey David, here is the full log, it starts at idle state, then I send one >> line and shutdown rsyslog. commitTransaction never returns at this point, >> queue is deleted from disk and rsyslog starts with empty queue. >> commitTransaction has this: >> >> dbgprintf("omsgkafka: committransaction called\n"); >> for(;;) { >> srSleep(1500, 0); >> } >> >> iRet = RS_RET_SUSPENDED; >> >> dbgprintf("omsgkafka: committransaction end\n"); >> >> >> 9774.080804647:imuxsock.c : Message from UNIX socket: #6 >> 9774.080828380:imuxsock.c : main Q: qqueueAdd: entry added, size now >> log 1, phys 1 entries >> 9774.080835155:imuxsock.c : main Q: EnqueueMsg advised worker start >> 9774.080839004:imuxsock.c : --------imuxsock calling select, active >> file descriptors (max 6): 6 >> 9774.080850186:main Q:Reg/w0 : wti 0x1333800: worker awoke from idle >> processing >> 9774.080854144:main Q:Reg/w0 : DeleteProcessedBatch: we deleted 0 objects >> and enqueued 0 objects >> 9774.080857193:main Q:Reg/w0 : doDeleteBatch: delete batch from store, >> new >> sizes: log 1, phys 1 >> 9774.080860918:main Q:Reg/w0 : processBATCH: batch of 1 elements must be >> processed >> 9774.080863557:main Q:Reg/w0 : processBATCH: next msg 0: <190>Mar 2 >> 23:02:54 logger: test1 >> 9774.080866845:main Q:Reg/w0 : PRIFILT 'local7.*' >> 9774.080872187: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 >> 9774.080923618:main Q:Reg/w0 : PRIFILT condition result is 1 >> 9774.080926256:main Q:Reg/w0 : ACTION 0 >> [omsgkafka:action(type="omsgkafka" ...)] >> 9774.080932370:main Q:Reg/w0 : executing action 0 >> 9774.080935598:main Q:Reg/w0 : action 'kafka_action': called, logging to >> omsgkafka (susp 0/0, direct q 0) >> 9774.080955281:main Q:Reg/w0 : strm 0x13272d0: file -1(prism_kafka_queue) >> flush, buflen 405 >> 9774.080958942:main Q:Reg/w0 : strmPhysWrite, stream 0x13272d0, len 405 >> 9774.081005185:main Q:Reg/w0 : file >> '/var/spool/rsyslog/prism_kafka_queue.00000001' opened as #7 with mode 384 >> 9774.081014114:main Q:Reg/w0 : strm 0x13272d0: opened file >> '/var/spool/rsyslog/prism_kafka_queue.00000001' for WRITE as 7 >> 9774.081026793:main Q:Reg/w0 : strm 0x13272d0: file 7 write wrote 405 >> bytes >> 9774.081030432:main Q:Reg/w0 : kafka_action queue: write wrote 405 octets >> to disk, queue disk size now 405 octets, EnqOnly:0 >> 9774.081033284:main Q:Reg/w0 : kafka_action queue: qqueueAdd: entry >> added, >> size now log 1, phys 1 entries >> 9774.081036576:main Q:Reg/w0 : kafka_action queue:Reg: high activity - >> starting 1 additional worker thread(s). >> 9774.081057367:main Q:Reg/w0 : kafka_action queue:Reg: started with state >> 0, num workers now 1 >> 9774.081061235:main Q:Reg/w0 : kafka_action queue: EnqueueMsg advised >> worker start >> 9774.081119073:main Q:Reg/w0 : action 'kafka_action': set suspended state >> to 0 >> 9774.081124496:main Q:Reg/w0 : PRIFILT 'local0.*' >> 9774.081130002: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 >> 9774.081179409:main Q:Reg/w0 : PRIFILT condition result is 0 >> 9774.081183488:main Q:Reg/w0 : PRIFILT '*.emerg' >> 9774.081192108: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 >> 9774.081236853:main Q:Reg/w0 : PRIFILT condition result is 0 >> 9774.081239405:main Q:Reg/w0 : END batch execution phase, entering to >> commit phase [processed 1 of 1 messages] >> 9774.081242411:main Q:Reg/w0 : processBATCH: batch of 1 elements has been >> processed >> 9774.081245359:main Q:Reg/w0 : regular consumer finished, iret=0, szlog 0 >> sz phys 1 >> 9774.081249143:main Q:Reg/w0 : DeleteProcessedBatch: we deleted 1 objects >> and enqueued 0 objects >> 9774.081251772:main Q:Reg/w0 : doDeleteBatch: delete batch from store, >> new >> sizes: log 0, phys 0 >> 9774.081254445:main Q:Reg/w0 : regular consumer finished, iret=4, szlog 0 >> sz phys 0 >> 9774.081257074:main Q:Reg/w0 : main Q:Reg/w0: worker IDLE, waiting for >> work. >> 9774.082767917:7f08827fc700: thread created, tid 20310, name >> 'rs:kafka_action queue:R' >> 9774.083158670:kafka_action queue:Reg/w0: wti 0x1327ab0: worker starting >> 9774.083452008:kafka_action queue:Reg/w0: DeleteProcessedBatch: we deleted >> 0 objects and enqueued 0 objects >> 9774.083764135:kafka_action queue:Reg/w0: doDeleteBatch: delete batch from >> store, new sizes: log 1, phys 1 >> 9774.083928382:kafka_action queue:Reg/w0: file >> '/var/spool/rsyslog/prism_kafka_queue.00000001' opened as #8 with mode 384 >> 9774.084086546:kafka_action queue:Reg/w0: strm 0x1327570: opened file >> '/var/spool/rsyslog/prism_kafka_queue.00000001' for READ as 8 >> 9774.084098247:kafka_action queue:Reg/w0: strm 0x1327570: file 8 read 405 >> bytes >> 9774.084121083:kafka_action queue:Reg/w0: string to match for regex is: >> test1 >> 9774.084129965:kafka_action queue:Reg/w0: source file msg.c requested >> reference for module 'lmregexp', reference count now 2 >> 9774.084146981:kafka_action queue:Reg/w0: regexec return is 1 >> 9774.084151588:kafka_action queue:Reg/w0: regex: end search, found 0 >> 9774.084298127:kafka_action queue:Reg/w0: action 'kafka_action': is >> transactional - executing in commit phase >> 9774.084304450:kafka_action queue:Reg/w0: wti 0x1327ab0: we need to create >> a new action worker instance for action 0 >> 9774.084316690:kafka_action queue:Reg/w0: wti 0x1327ab0: created action >> worker instance 1 for action 0 >> 9774.084322447:kafka_action queue:Reg/w0: omsgkafka: beginTransaction >> called >> 9774.084327347:kafka_action queue:Reg/w0: Action 0 transitioned to state: >> itx >> 9774.084332329:kafka_action queue:Reg/w0: doTransaction: have >> commitTransaction IF, using that, pWrkrInfo 0x1327b60 >> 9774.084337162:kafka_action queue:Reg/w0: entering >> actionCallCommitTransaction(), state: itx, actionNbr 0, nMsgs 1 >> 9774.084341794:kafka_action queue:Reg/w0: omsgkafka: committransaction >> called >> ^C9777.756010044:main thread : DoDie called. >> DoDie called. >> 9777.757077361:main thread : exiting on signal 2 >> 9777.757445698:main thread : Terminating input threads... >> 9777.757936794:main thread : request term via SIGTTIN for input thread >> 'imuxsock' 0x837fe700 >> 9777.758371952:imuxsock.c : thrdStarter: usrThrdMain imuxsock - >> 0x7f08837fe700 returned with iRet 0, exiting now. >> 9777.758931583:imuxsock.c : destructor for debug call stack >> 0x7f08740008c0 called >> 9777.759216811:main thread : input thread term: thread imuxsock >> returned >> normally and is terminated >> 9777.759495668:main thread : non-cancel input thread termination >> succeeded for thread imuxsock 0x837fe700 >> 9777.759850405:main thread : imuxsock: unlinking unix socket file[0] >> /dev/log >> 9777.760098055:main thread : main Q: qqueueAdd: entry added, size now >> log 1, phys 1 entries >> 9777.760440595:main thread : main Q: EnqueueMsg advised worker start >> 9777.760618052:main Q:Reg/w0 : wti 0x1333800: worker awoke from idle >> processing >> 9777.760627213:main Q:Reg/w0 : DeleteProcessedBatch: we deleted 0 objects >> and enqueued 0 objects >> 9777.760633556:main Q:Reg/w0 : doDeleteBatch: delete batch from store, >> new >> sizes: log 1, phys 1 >> 9777.760640207:main Q:Reg/w0 : processBATCH: batch of 1 elements must be >> processed >> 9777.760646078:main Q:Reg/w0 : processBATCH: next msg 0: [origin >> software="rsyslogd" swVersion="8.17.0.master" x-pid="20303" x-info=" >> http://www.rsyslog.com";] exiting on signal 2. >> 9777.760652377:main Q:Reg/w0 : PRIFILT 'local7.*' >> 9777.760663339: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 >> 9777.760979712:main Q:Reg/w0 : PRIFILT condition result is 0 >> 9777.760985069:main Q:Reg/w0 : PRIFILT 'local0.*' >> 9777.760995436: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 >> 9777.761073220:main Q:Reg/w0 : PRIFILT condition result is 0 >> 9777.761077680:main Q:Reg/w0 : PRIFILT '*.emerg' >> 9777.761087341: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 >> 9777.761485735:main Q:Reg/w0 : PRIFILT condition result is 0 >> 9777.761494678:main Q:Reg/w0 : END batch execution phase, entering to >> commit phase [processed 1 of 1 messages] >> 9777.761504212:main Q:Reg/w0 : processBATCH: batch of 1 elements has been >> processed >> 9777.761513699:main Q:Reg/w0 : regular consumer finished, iret=0, szlog 0 >> sz phys 1 >> 9777.761532517:main Q:Reg/w0 : DeleteProcessedBatch: we deleted 1 objects >> and enqueued 0 objects >> 9777.761542961:main Q:Reg/w0 : doDeleteBatch: delete batch from store, >> new >> sizes: log 0, phys 0 >> 9777.761552408:main Q:Reg/w0 : regular consumer finished, iret=4, szlog 0 >> sz phys 0 >> 9777.761561267:main Q:Reg/w0 : main Q:Reg/w0: worker IDLE, waiting for >> work. >> 9777.761575630:main thread : Terminating main queue... >> 9777.761586414:main thread : main Q: initiating worker thread shutdown >> sequence >> 9777.761595699:main thread : main Q: trying shutdown of regular workers >> 9777.761612563:main thread : sent SIGTTIN to worker thread 0x82ffd700 >> 9777.762033112:main thread : main Q:Reg: waiting 1500ms on worker >> thread >> termination, 1 still running >> 9777.762471004:main Q:Reg/w0 : wti 0x1333800: worker awoke from idle >> processing >> 9777.762479524:main Q:Reg/w0 : DeleteProcessedBatch: we deleted 0 objects >> and enqueued 0 objects >> 9777.762485366:main Q:Reg/w0 : doDeleteBatch: delete batch from store, >> new >> sizes: log 0, phys 0 >> 9777.762490722:main Q:Reg/w0 : regular consumer finished, iret=4, szlog 0 >> sz phys 0 >> 9777.762495761:main Q:Reg/w0 : wti 0x1333800: terminating worker >> terminateRet=5, bInactivityTOOccured=0 >> 9777.762501491:main Q:Reg/w0 : DDDD: wti 0x1333800: worker cleanup action >> instances >> 9777.762507021:main Q:Reg/w0 : wti 0x1333800, action 0, ptr (nil) >> 9777.762511754:main Q:Reg/w0 : wti 0x1333800, action 1, ptr (nil) >> 9777.762516385:main Q:Reg/w0 : wti 0x1333800, action 2, ptr (nil) >> 9777.762521291:main Q:Reg/w0 : wti 0x1333800: worker exiting >> 9777.762526603:main Q:Reg/w0 : main Q:Reg: Worker thread 1333800, >> terminated, num workers now 0 >> 9777.762543503:main Q:Reg/w0 : destructor for debug call stack >> 0x7f087c0008c0 called >> 9777.762586045:main thread : main Q: regular queue workers shut down. >> 9777.762595242:main thread : main Q: checking to see if we need to >> cancel any worker threads of the primary queue >> 9777.762600740:main thread : main Q: worker threads terminated, >> remaining queue size log 0, phys 0. >> 9777.762612320:main thread : main Q: queue (type 0) will lose 0 >> messages, destroying... >> 9777.762626917:main thread : Terminating outputs... >> 9777.762635743:main thread : destructing ruleset 0x131b150, name >> 0x131b190 >> 9777.762642271:main thread : kafka_action queue: initiating worker >> thread shutdown sequence >> 9777.762647400:main thread : kafka_action queue: trying shutdown of >> regular workers >> 9777.762656067:main thread : sent SIGTTIN to worker thread 0x827fc700 >> 9777.762669071:main thread : kafka_action queue:Reg: waiting 0ms on >> worker thread termination, 1 still running >> 9777.762947979:main thread : kafka_action queue:Reg: timeout waiting on >> worker thread termination >> 9777.762972263:main thread : sent SIGTTIN to worker thread 0x827fc700 >> 9777.763088721:main thread : kafka_action queue: regular shutdown timed >> out on primary queue (this is OK) >> 9777.763185618:main thread : kafka_action queue: trying to shutdown >> workers within Action Timeoutsetting EnqOnly mode >> 9777.763196692:main thread : kafka_action queue: trying immediate >> shutdown of regular workers (if any) >> 9777.763214555:main thread : sent SIGTTIN to worker thread 0x827fc700 >> 9777.763226359:main thread : kafka_action queue:Reg: waiting 1000ms on >> worker thread termination, 1 still running >> 9778.763307260:main thread : kafka_action queue:Reg: timeout waiting on >> worker thread termination >> 9778.763833144:main thread : sent SIGTTIN to worker thread 0x827fc700 >> 9778.764176150:main thread : kafka_action queue: immediate shutdown >> timed out on primary queue (this is acceptable and triggers cancellation) >> 9778.764569596:main thread : kafka_action queue: checking to see if we >> need to cancel any worker threads of the primary queue >> 9778.765029132:main thread : sent SIGTTIN to worker thread 0x827fc700, >> giving it a chance to terminate >> 9778.775504248:main thread : cooperative worker termination failed, >> using cancellation... >> 9778.775932612:main thread : wti 0x1327ab0: canceling worker thread >> 9778.776268161:kafka_action queue:Reg/w0: kafka_action queue:Reg/w0: >> cancelation cleanup handler called. >> 9778.776647913:kafka_action queue:Reg/w0: DeleteProcessedBatch: we deleted >> 1 objects and enqueued 0 objects >> 9778.776910344:kafka_action queue:Reg/w0: doDeleteBatch: delete batch from >> store, new sizes: log 0, phys 0 >> 9778.777190970:kafka_action queue:Reg/w0: kafka_action queue:Reg/w0: done >> cancelation cleanup handler. >> 9778.777532500:kafka_action queue:Reg/w0: kafka_action queue:Reg: Worker >> thread 1327ab0 requested to be cancelled. >> 9778.777748314:kafka_action queue:Reg/w0: kafka_action queue:Reg: Worker >> thread 1327ab0, terminated, num workers now 0 >> 9778.777955651:kafka_action queue:Reg/w0: destructor for debug call stack >> 0x7f08780008c0 called >> 9778.778248027:main thread : kafka_action queue: worker threads >> terminated, remaining queue size log 0, phys 0. >> 9778.778262197:main thread : kafka_action queue: persisting queue to >> disk, 0 entries... >> 9778.778269955:main thread : strm 0x13272d0: file 7(prism_kafka_queue) >> closing >> 9778.778284655:main thread : strm 0x13272d0: file 7(prism_kafka_queue) >> flush, buflen 0 (no need to flush) >> 9778.778298933:main thread : strm 0x1327570: file 8(prism_kafka_queue) >> closing >> 9778.778435180:main thread : strm 0x1327810: file -1(prism_kafka_queue) >> closing >> 9778.778442428:main thread : strmCloseFile: deleting >> '/var/spool/rsyslog/prism_kafka_queue.00000001' >> 9778.778499467:main thread : omsgkafka: freeInstance called >> 9778.778513906:main thread : all primary multi-thread sources have been >> terminated - now doing aux cleanup... >> 9778.778519118:main thread : destructing current config... >> 9778.778524283:main thread : calling freeCnf(0x13191e0) for module >> 'builtin:omfile' >> 9778.778529272:main thread : calling freeCnf(0x13193a0) for module >> 'builtin:ompipe' >> 9778.778534707:main thread : calling freeCnf(0x131a3a0) for module >> 'builtin:omfwd' >> 9778.778540278:main thread : calling freeCnf(0x1329b00) for module >> 'imuxsock' >> 9778.778545633:main thread : calling freeCnf(0x132ac70) for module >> 'imklog' >> 9778.778729757:main thread : destructing parser 'rsyslog.rfc5424' >> 9778.778736340:main thread : destructing parser 'rsyslog.rfc3164' >> 9778.778741419:main thread : pmrfc3164: free parser instance 0x131a8b0 >> 9778.778810084:main thread : file rsyslogd.c released module 'lmnet', >> reference count now 2 >> 9778.778970064:main thread : module lmnet NOT unloaded because it still >> has a refcount of 2 >> 9778.778976042:main thread : Unloading module builtin:omfile >> 9778.778981773:main thread : module lmnet NOT unloaded because it still >> has a refcount of 2 >> 9778.778986410:main thread : Unloading module builtin:ompipe >> 9778.778991284:main thread : module lmnet NOT unloaded because it still >> has a refcount of 2 >> 9778.778996016:main thread : Unloading module builtin-shell >> 9778.779000666:main thread : module lmnet NOT unloaded because it still >> has a refcount of 2 >> 9778.779005245:main thread : Unloading module builtin:omdiscard >> 9778.779010169:main thread : module lmnet NOT unloaded because it still >> has a refcount of 2 >> 9778.779014765:main thread : Unloading module builtin:omfwd >> 9778.779020701:main thread : file omfwd.c released module 'lmnet', >> reference count now 1 >> 9778.779025970:main thread : module lmnet NOT unloaded because it still >> has a refcount of 1 >> 9778.779030535:main thread : Unloading module builtin:omusrmsg >> 9778.779035196:main thread : module lmnet NOT unloaded because it still >> has a refcount of 1 >> 9778.779039750:main thread : Unloading module builtin:pmrfc5424 >> 9778.779044623:main thread : module lmnet NOT unloaded because it still >> has a refcount of 1 >> 9778.779049166:main thread : Unloading module builtin:pmrfc3164 >> 9778.779053994:main thread : module lmnet NOT unloaded because it still >> has a refcount of 1 >> 9778.779058499:main thread : Unloading module builtin:smfile >> 9778.779063115:main thread : module lmnet NOT unloaded because it still >> has a refcount of 1 >> 9778.779067650:main thread : Unloading module builtin:smtradfile >> 9778.779072340:main thread : module lmnet NOT unloaded because it still >> has a refcount of 1 >> 9778.779080829:main thread : Unloading module builtin:smfwd >> 9778.779085950:main thread : module lmnet NOT unloaded because it still >> has a refcount of 1 >> 9778.779090579:main thread : Unloading module builtin:smtradfwd >> 9778.779095331:main thread : module lmnet NOT unloaded because it still >> has a refcount of 1 >> 9778.779099910:main thread : Unloading module imuxsock >> 9778.779127532:main thread : module lmnet NOT unloaded because it still >> has a refcount of 1 >> 9778.779134318:main thread : Unloading module imklog >> 9778.779149232:main thread : module lmnet NOT unloaded because it still >> has a refcount of 1 >> 9778.779452603:main thread : module lmregexp NOT unloaded because it >> still has a refcount of 2 >> 9778.779458039:main thread : Unloading module omsgkafka >> 9778.779853849:main thread : module lmnet NOT unloaded because it still >> has a refcount of 1 >> 9778.780141515:main thread : module lmregexp NOT unloaded because it >> still has a refcount of 2 >> 9778.780157201:main thread : file conf.c released module 'lmnet', >> reference count now 0 >> 9778.780297378:main thread : module 'lmnet' has zero reference count, >> unloading... >> 9778.780438764:main thread : Unloading module lmnet >> 9778.780664790:main thread : rsyslog runtime de-initialized, current >> users 0 >> 9778.780921611:main thread : Clean shutdown completed, bye >> >> >> >> On Thu, Feb 25, 2016 at 4:58 PM, David Lang <[email protected]> wrote: >> >> On Thu, 25 Feb 2016, Kane Kim wrote: >>> >>> Btw, I've tried it with latest master - I have following: >>> >>>> >>>> BEGINcommitTransaction >>>> CODESTARTcommitTransaction >>>> dbgprintf("omsgkafka: committransaction called\n"); >>>> srSleep(1500, 0); >>>> >>>> ..... >>>> >>>> Then I send 3 log lines and restart rsyslog 3 times in a row (while >>>> commitTransaction is still sleeping). After 3rd restart queue file >>>> disappears from disk. >>>> >>>> >>>> prior to this, what does the debug log say is happening to the log >>> message? it should show the message being read from the queue and then >>> ... >>> >>> >>> David Lang >>> _______________________________________________ >>> 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. >> >> _______________________________________________ > 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.
