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.
