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
> 8194.255466309:main thread : strm 0x7f9bc4002480: file 4(messages)
> flush, buflen 0 (no need to flush)
> 8194.255479325:main thread : all primary multi-thread sources have been
> terminated - now doing aux cleanup...
> 8194.255482809:main thread : destructing current config...
> 8194.255486662:main thread : calling freeCnf(0x1bf41e0) for module
> 'builtin:omfile'
> 8194.255490098:main thread : calling freeCnf(0x1bf43a0) for module
> 'builtin:ompipe'
> 8194.255493809:main thread : calling freeCnf(0x1bf53a0) for module
> 'builtin:omfwd'
> 8194.255497793:main thread : calling freeCnf(0x1c04b00) for module
> 'imuxsock'
> 8194.255501565:main thread : calling freeCnf(0x1c05c70) for module
> 'imklog'
> 8194.255543579:main thread : destructing parser 'rsyslog.rfc5424'
> 8194.255547468:main thread : destructing parser 'rsyslog.rfc3164'
> 8194.255550784:main thread : pmrfc3164: free parser instance 0x1bf58b0
> 8194.255559659:main thread : file rsyslogd.c released module 'lmnet',
> reference count now 2
> 8194.255563470:main thread : module lmnet NOT unloaded because it still
> has a refcount of 2
> 8194.255566676:main thread : Unloading module builtin:omfile
> 8194.255570420:main thread : module lmnet NOT unloaded because it still
> has a refcount of 2
> 8194.255573674:main thread : Unloading module builtin:ompipe
> 8194.255576857:main thread : module lmnet NOT unloaded because it still
> has a refcount of 2
> 8194.255579938:main thread : Unloading module builtin-shell
> 8194.255583060:main thread : module lmnet NOT unloaded because it still
> has a refcount of 2
> 8194.255586144:main thread : Unloading module builtin:omdiscard
> 8194.255589509:main thread : module lmnet NOT unloaded because it still
> has a refcount of 2
> 8194.255592658:main thread : Unloading module builtin:omfwd
> 8194.255596441:main thread : file omfwd.c released module 'lmnet',
> reference count now 1
> 8194.255599981:main thread : module lmnet NOT unloaded because it still
> has a refcount of 1
> 8194.255603068:main thread : Unloading module builtin:omusrmsg
> 8194.255606240:main thread : module lmnet NOT unloaded because it still
> has a refcount of 1
> 8194.255609287:main thread : Unloading module builtin:pmrfc5424
> 8194.255612755:main thread : module lmnet NOT unloaded because it still
> has a refcount of 1
> 8194.255615826:main thread : Unloading module builtin:pmrfc3164
> 8194.255619252:main thread : module lmnet NOT unloaded because it still
> has a refcount of 1
> 8194.255622315:main thread : Unloading module builtin:smfile
> 8194.255625406:main thread : module lmnet NOT unloaded because it still
> has a refcount of 1
> 8194.255628486:main thread : Unloading module builtin:smtradfile
> 8194.255631753:main thread : module lmnet NOT unloaded because it still
> has a refcount of 1
> 8194.255634819:main thread : Unloading module builtin:smfwd
> 8194.255637916:main thread : module lmnet NOT unloaded because it still
> has a refcount of 1
> 8194.255640987:main thread : Unloading module builtin:smtradfwd
> 8194.255644187:main thread : module lmnet NOT unloaded because it still
> has a refcount of 1
> 8194.255647267:main thread : Unloading module imuxsock
> 8194.255676232:main thread : module lmnet NOT unloaded because it still
> has a refcount of 1
> 8194.255680751:main thread : Unloading module imklog
> 8194.255694428:main thread : module lmnet NOT unloaded because it still
> has a refcount of 1
> 8194.255698085:main thread : Unloading module omrelp
> 8194.255750953:main thread : module lmnet NOT unloaded because it still
> has a refcount of 1
> 8194.255755236:main thread : module lmregexp NOT unloaded because it
> still has a refcount of 1
> 8194.255759705:main thread : file conf.c released module 'lmnet',
> reference count now 0
> 8194.255762875:main thread : module 'lmnet' has zero reference count,
> unloading...
> 8194.255765901:main thread : Unloading module lmnet
> 8194.255780970:main thread : rsyslog runtime de-initialized, current
> users 0
> 8194.255784704:main thread : Clean shutdown completed, bye
>
>
>
> On Sun, Mar 13, 2016 at 9:30 PM, David Lang <[email protected]> wrote:
>
>> On Sun, 13 Mar 2016, Kane Kim wrote:
>>
>> +1to David, having module handle the errors is not 100% reliable, what if
>>> module dies before having a chance to save error log, those messages will
>>> be lost.
>>>
>>
>> well, the module is a thread of rsyslog, so if it dies, rsyslog has died.
>>
>> But if you are doing large batches (hundreds or thousands), putting all
>> of them in a 'bad messages' file because one has a problem seems like the
>> wrong thing to do.
>>
>> given that the error is not detected until the batch is being flushed for
>> the output, any outputs that have already flushed their batches can't be
>> changed, so the question is if it's worse to have messages resent to those
>> outputs as the batch gets re-processed, or having to have the output go to
>> a "couldn't deliver" file.
>>
>> It's bad enough if the problem is a corrupt message that can never be
>> delivered and the error is a permanent one, but if the problem is instead a
>> temporary error (server is down), you will have a LOT of messages going
>> into this 'couldn't deliver' bucket, when what should really be happening
>> is that rsyslog should be pausing in the processing of messages, retrying
>> after the suspended timeout.
>>
>> David Lang
>>
>>
>> On Mar 13, 2016 9:07 PM, "David Lang" <[email protected]> wrote:
>>>
>>> On Sun, 13 Mar 2016, Rainer Gerhards wrote:
>>>>
>>>> Rainer, can you explain what happens when a batch fails on an action?
>>>>
>>>>>
>>>>>>
>>>>> It depends on when what happens and if we have batches of one or
>>>>> batches of many. For batches of one, the failure is immediately
>>>>> detected and acted upon. For batches of many,all action strings or
>>>>> stored temporarily. During that time, it is assume that the messages
>>>>> could be processed. There is no way around this assumption, because we
>>>>> now run each action completely through the rule engine before the next
>>>>> one is begun to process, which means that other parts of the config
>>>>> have actually acted on a message, which means we cannot undo that
>>>>> state. If is needed to act on the "real" state, we need to process
>>>>> batches of one. There simply is no other solution possible. So let's
>>>>> stay with batches of many. Once the batch is completed, the temporary
>>>>> strings are passed to the output's commitTransaction entry point. It
>>>>> is currently assumed that the output does inteligently handle the
>>>>> case, and as it looks most do this well (no regression tests failed,
>>>>> no bad reports since we introduced this with the initial v8 version
>>>>> (15+ month ago). If the action fails, status is reflected accordingly.
>>>>> Also, the core engine *should* (but obviously does not support this
>>>>> right now) write an error file with the messages in error (just like
>>>>> omelasticsearch does, which has proven to be quite good).
>>>>>
>>>>>
>>>> well, it's not in the specs that modules should have local error files
>>>> the
>>>> way omelasticsearch does.
>>>>
>>>> What I would expect if there is a problem when commiting the batch is
>>>> that
>>>> the entire batch would be marked as not delivered and try again with
>>>> half
>>>> of it.
>>>>
>>>> This will cause messages to other outputs working from the same queue to
>>>> get duplciate messages, but it's better than loosing an entire batch of
>>>> messages because one is corrupt in some way. or there is a temporary
>>>> problem with the output.
>>>>
>>>> David Lang
>>>>
>>>> I have managed to look at least briefly at the commitTransaction core
>>>>
>>>>> engine code. I think we can even improve it and may get some ability
>>>>> to do retries if the action itself does not handle that. At the
>>>>> minimum, it should have the ability (which was intended originally,
>>>>> but pushed away by more urgent work) to write that error file.
>>>>>
>>>>> I am very grateful that Kane is working on a repro with the standard
>>>>> modules. Once we have that, I can go deeper into the code and check
>>>>> what I am thinking about. It might be possible that we cannot manage
>>>>> to repro this with the standard modules. Then we need to think about a
>>>>> way via the testing module to do the same thing.
>>>>>
>>>>> I will try to address this within the 8.18 timeframe, but cannot
>>>>> totally commit to it. There has a lot of work been going on, and
>>>>> especially all that CI testing has taken up lots of works.
>>>>> Nevertheless, I've been able to iron out quite some nits, so it's
>>>>> probably worth it. I would still like to continue to get the CI
>>>>> environment into better shape, because now I know what I am doing. If
>>>>> I stop again and let it go for a couple of weeks, I would lose a lot
>>>>> of momentum. I have also do to some work for support customers, which
>>>>> keeps me able to work on rsyslog in general, so this, too, has
>>>>> priority (and validly has so because without support customers I would
>>>>> be totally unable to work on rsyslog other than as a hobby)
>>>>>
>>>>> I hope this explains the current state.
>>>>> Rainer
>>>>>
>>>>>
>>>>> Kane, can you try and duplicate your problem using standard modules?
>>>>>> I'm
>>>>>> thinking that if you define a omrelp action that doesn't go anywhere,
>>>>>> it
>>>>>> should return errors similar to what you are trying to do, so you
>>>>>> should
>>>>>> be
>>>>>> able to duplicate the problem that way.
>>>>>>
>>>>>> David Lang
>>>>>>
>>>>>>
>>>>>>
>>>>>>
>>>>>> On Tue, 23 Feb 2016, Kane Kim wrote:
>>>>>>
>>>>>> Looking at omkafka module source code it seems that it relies on
>>>>>> rsyslog
>>>>>>
>>>>>>> retries in DoAction, returning RS_RET_SUSPENDED:
>>>>>>>
>>>>>>> DBGPRINTF("omkafka: writeKafka returned %d\n", iRet);
>>>>>>> if(iRet != RS_RET_OK) {
>>>>>>> iRet = RS_RET_SUSPENDED;
>>>>>>> }
>>>>>>>
>>>>>>> I've tried similar code in DoAction, it seems that action processing
>>>>>>> is suspended at that point and messages are not retried to module.
>>>>>>>
>>>>>>>
>>>>>>> On Tue, Feb 23, 2016 at 9:06 AM, Kane Kim <[email protected]>
>>>>>>> wrote:
>>>>>>>
>>>>>>> Thanks for your help Rainer, I'll try to debug what's going on, so
>>>>>>> far
>>>>>>>
>>>>>>>> it
>>>>>>>> seems rsyslog doesn't retry even with batch size 1. It doesn't retry
>>>>>>>> if I
>>>>>>>> return RS_RET_SUSPENDED from DoAction as well.
>>>>>>>>
>>>>>>>> On Tue, Feb 23, 2016 at 9:05 AM, Rainer Gerhards
>>>>>>>> <[email protected]
>>>>>>>>
>>>>>>>>
>>>>>>>>> wrote:
>>>>>>>>>
>>>>>>>>>
>>>>>>>>
>>>>>>>> 2016-02-23 18:03 GMT+01:00 David Lang <[email protected]>:
>>>>>>>>
>>>>>>>>>
>>>>>>>>>
>>>>>>>>>> On Tue, 23 Feb 2016, Rainer Gerhards wrote:
>>>>>>>>>>
>>>>>>>>>> 2016-02-23 17:38 GMT+01:00 Kane Kim <[email protected]>:
>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>> Hello Rainer, thanks for the prompt reply! To give you some
>>>>>>>>>>>> context:
>>>>>>>>>>>> I
>>>>>>>>>>>> want
>>>>>>>>>>>> to write module that both using batching and also can't loose
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>> messages in
>>>>>>>>>
>>>>>>>>>
>>>>>>>>>> any circumstances. Are you saying it is by design that rsyslog
>>>>>>>>>>>> can't
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>> do
>>>>>>>>>
>>>>>>>>>
>>>>>>>>>> that together? According to documentation rsyslog will retry if
>>>>>>>>>>>> module
>>>>>>>>>>>> returns any error. Do you plan to fix this in rsyslog or update
>>>>>>>>>>>> documentation to say batching and retries don't work?
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>> It depends on many things. In almost all cases, the retry should
>>>>>>>>>>> work
>>>>>>>>>>> well (and does so in practice). Unfortunately, I am pretty
>>>>>>>>>>> swamped.
>>>>>>>>>>> I
>>>>>>>>>>> need to go to a conference tomorrow and have had quite some
>>>>>>>>>>> unexpected
>>>>>>>>>>> work today. It would probably be good if you could ping me next
>>>>>>>>>>> week
>>>>>>>>>>> to see if we can look into more details what is causing you pain.
>>>>>>>>>>> But
>>>>>>>>>>> I can't guarantee that I will be available early next week.
>>>>>>>>>>>
>>>>>>>>>>> In general, we cannot handle a fatal error here from an engine
>>>>>>>>>>> PoV,
>>>>>>>>>>> because everything is already processed and we do no longer have
>>>>>>>>>>> the
>>>>>>>>>>> original messages. This is simply needed if you want to process
>>>>>>>>>>> messages one after another through the full config (a goal for v8
>>>>>>>>>>> that
>>>>>>>>>>> was muuuuch requested). As I said, the solution is to use
>>>>>>>>>>> batches of
>>>>>>>>>>> one, because otherwise we would really need to turn back time and
>>>>>>>>>>> undo
>>>>>>>>>>> everything that was already done on the messages in question by
>>>>>>>>>>> other
>>>>>>>>>>> modules (including state advances).
>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>> I thought that if a batch failed, it pushed all the messages back
>>>>>>>>>> on
>>>>>>>>>> the
>>>>>>>>>> queue and retried with a half size batch until it got to the one
>>>>>>>>>> message
>>>>>>>>>> that could not be processed and only did a fatal fail on that
>>>>>>>>>> message.
>>>>>>>>>>
>>>>>>>>>> Now, there is a big difference between a module giving a hard
>>>>>>>>>> error
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>> "this
>>>>>>>>>
>>>>>>>>>
>>>>>>>>>> message is never going to be able to be processed no matter how
>>>>>>>>>> many
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>> times
>>>>>>>>>
>>>>>>>>>
>>>>>>>>>> it's retried" vs a soft error "there is a problem delivering
>>>>>>>>>> things
>>>>>>>>>> to
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>> this
>>>>>>>>>
>>>>>>>>>
>>>>>>>>>> destination right now, retry later". I thought the batch
>>>>>>>>>> processing
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>> handled
>>>>>>>>>
>>>>>>>>>
>>>>>>>>>> these differently.
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>
>>>>>>>>> That's no longer possible with v8, at least generically. As I said
>>>>>>>>> above, we would need to turn back time.
>>>>>>>>>
>>>>>>>>> But I really run out of time now...
>>>>>>>>>
>>>>>>>>> Rainer
>>>>>>>>>
>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>> 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.
>>>>>>
>>>>>> _______________________________________________
>>>>> 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.
>>
>
>
_______________________________________________
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.
