Re: [rsyslog] retry if output module returns RS_RET_SUSPENDED

David Lang Thu, 21 Apr 2016 00:01:33 -0700

If I am understanding Rainer's description of the current code correctly:

During the batch processing the output strings are created, but then the batchis finalized before any of the output modules try to deliver the strings. So ifthere is a problem, they can't recover.

If the batch does not get finalized until after all of the output modulesattempt to deliver the messages, then the error is detectable, but all themessages of actions that succeeded before the action that fails will end upgetting retransmitted when the batch is run again at some point in the future.(or a partial batch as I noted below)

The retry logic here can be interesting. How long should it retry within thebatch before it gives up and marks everything in the batch 'not yet delievered'.

I'd say that for the first pass, no retries within the batch context. If anoutput module can't deliver the full batch for any reason, abort the entirebatch and try again (either with a partial batch, or by grabbing messages freshfrom the queue if it's a type 1 failure)

Yes, this will duplicate messages to one output if a different one has problemsthat would be satisfied with a simple retry/reconnect, but I think we should getthings correct first, and then look to optimize it.


David Lang

On Wed, 20 Apr 2016, David Lang wrote:

Date: Wed, 20 Apr 2016 23:44:51 -0700 (PDT)
From: David Lang <[email protected]>
Reply-To: rsyslog-users <[email protected]>
To: rsyslog-users <[email protected]>
Subject: Re: [rsyslog] retry if output module returns RS_RET_SUSPENDED

The original discussion when we created the batch mode was that there weretwo possible ways for a batch commit to fail.


1. a temporary problem (can't reach the server, it doesn't respond, etc)

In this case, a delay and retry is the correct thing to do.

I believe this is what a suspended action is (I say this in case I ammisunderstanding terms)

The output module can usually detect this sort of problem, but if in doubt(or after enough retries), it may have to give up and decide that the problemis really the second type. A failure to establish a connection to thedestination should never be in doubt, it's always this first type of problem.

2. a data driven problem (no matter what, this particular data cannot bedelivered, even if we retried for 100 years)

This is problems like data elements having embedded quotes that aren'tescaped, a timestamp isn't valid by the definition of the database you areinserting data into, etc.

In this case, retries do no good. But what we can do is abort the batch andtry again with a batch half the size.

If any messages did get delivered as part of the batch processing, they willbe duplicated when the rest of the batch is processed.

If the problem was not in the half of the batch that was delivered, good,revert to normal processing for anything else in the queue (which probablymeans that the next batch will fail as well)

If the problem is in the half size batch, try again with a batch half thatsize.

If the batch that you are trying to process is a single message, assume it isfatally flawed and count it as an error.

In an ideal situation you can write such messages somewhere or otherwisedetect the error. But you end up only loosing one message that has somethingcorrupt in it, not an entire batch.


David Lang


On Wed, 20 Apr 2016, Kane Kim wrote:

What would happen if it will be retried forever at this point? Would it
affect any other queues or only current action queue. If it will not affect
anything else I'd really prefer it to block there until successfully
committed.

On Wed, Apr 20, 2016 at 11:16 PM, Rainer Gerhards<[email protected]>

wrote:

2016-04-21 3:22 GMT+02:00 David Lang <[email protected]>:

Thanks, I didn't know that you had been able to take any time to think

about

this issue yet.


Sorry for not being more explicit about it. But there was not yet
anything that could be posted. I did this as a side-activity all since
this opened. The plan acutally is:

1. get a testbench test to expose that problem -- this greatly eases
debugging
    line of thought is to update omfile, which is needed anyhow, so
that we can induce errors via it
2. add missing functionality to write error file
    this does not directly address the issue, but is useful and
ensures we are on the right path
3. check the end transaction endpoint. After review of old notes and
some thinking, I think that
     part of the "not yet implemented" comment is actually right. It's
not as easy as suggested by it,
    but we probably can do better.


It sounds like you are tenitively agreeing with my speculation that the

end

of the block processing is happening just a little sooner than it should,
preventing the chance to detect output errors.


No, I don't think so. I think it happens as it should, but we are not
handling the full situation. Originally, it was planned to write an
error file (point 2 above) when we cannot commit at end of
transaction. But we probably can give it some retries at that point as
well. In v8, we **need** to buffer transactional data until the end of
batch. If we wouldn't do that, we would always need to commit after
each and every transaction (because we need processing "completed"
when we advance to the next action). The, at end of batch, the
transaction commit processing happens. Right now, we have one try, and
then give up (unfortunately without any error indication). So we need
to go into that part of processing and enhance/fix it.

I hope this clarifies.
Rainer


David Lang


On Wed, 20 Apr 2016, Rainer Gerhards wrote:

I should also say that it had a release goal, so it is on my active

to-do

list.

Sent from phone, thus brief.
Am 20.04.2016 19:40 schrieb "Rainer Gerhards" <[email protected]

Yup... Look aty work Log - still no time... Was meant for last release
but
then came libfastjson work.

Sent from phone, thus brief.
Am 20.04.2016 19:39 schrieb "David Lang" <[email protected]>:

Rainer, ping on this issue.

David Lang

On Tue, 29 Mar 2016, Kane Kim wrote:

Date: Tue, 29 Mar 2016 10:46:49 -0700


From: Kane Kim <[email protected]>
Reply-To: rsyslog-users <[email protected]>
To: rsyslog-users <[email protected]>
Subject: Re: [rsyslog] retry if output module returns

RS_RET_SUSPENDED


Updated config to:
module(load="omrelp")
local0.* action(type="omrelp"
   target="10.0.0.1"
   port="2514"
   name="debug_relp"
   queue.filename="relp_queue"
   queue.maxdiskspace="1G"
   queue.saveonshutdown="on"
   queue.spoolDirectory="/var/spool/rsyslog"
   queue.type="Disk"
   action.resumeRetryCount="-1"
   action.resumeInterval="1"
)

Still message is lost:

3489.658349703:imuxsock.c     : Message from UNIX socket: #3
3489.658367582:imuxsock.c     : main Q: qqueueAdd: entry added, size
now
log 1, phys 1 entries
3489.658372561:imuxsock.c     : main Q: EnqueueMsg advised worker

start

3489.658374985:imuxsock.c     : --------imuxsock calling select,

active

file descriptors (max 3): 3
3489.658384201:main Q:Reg/w0  : wti 0x23c8ba0: worker awoke from idle
processing
3489.658386792:main Q:Reg/w0  : DeleteProcessedBatch: we deleted 0
objects
and enqueued 0 objects
3489.658388548:main Q:Reg/w0  : doDeleteBatch: delete batch from

store,

new
sizes: log 1, phys 1
3489.658391356:main Q:Reg/w0  : processBATCH: batch of 1 elements

must

be
processed
3489.658392786:main Q:Reg/w0  : processBATCH: next msg 0: <134>Mar 29
17:44:49 logger: test
3489.658395027:main Q:Reg/w0  :     PRIFILT 'local0.*'
3489.658397540:main Q:Reg/w0  :     pmask:  X  X  X  X  X  X  X  X  X
X  X
X  X  X  X  X FF  X  X  X  X  X  X  X  X  X
3489.658413235:main Q:Reg/w0  : PRIFILT condition result is 1
3489.658414686:main Q:Reg/w0  :     ACTION 0
[omrelp:action(type="omrelp"
...)]
3489.658417648:main Q:Reg/w0  : executing action 0
3489.658419520:main Q:Reg/w0  : action 'debug_relp': called, logging

to

omrelp (susp 0/0, direct q 0)
3489.658433462:main Q:Reg/w0  : strm 0x23b74c0: file -1(relp_queue)
flush,
buflen 410
3489.658435496:main Q:Reg/w0  : strmPhysWrite, stream 0x23b74c0, len
410
3489.658484243:main Q:Reg/w0  : file
'/var/spool/rsyslog/relp_queue.00000001' opened as #5 with mode 384
3489.658487347:main Q:Reg/w0  : strm 0x23b74c0: opened file
'/var/spool/rsyslog/relp_queue.00000001' for WRITE as 5
3489.658500498:main Q:Reg/w0  : strm 0x23b74c0: file 5 write wrote

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

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

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

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 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
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
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

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
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

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 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

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

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

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.

_______________________________________________
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 ofsites beyond our control. PLEASE UNSUBSCRIBE and DO NOT POST if you DON'TLIKE 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 ofsites beyond our control. PLEASE UNSUBSCRIBE and DO NOT POST if you DON'TLIKE 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.

Re: [rsyslog] retry if output module returns RS_RET_SUSPENDED

Reply via email to