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.
