Re: [rsyslog] retry if output module returns RS_RET_SUSPENDED

Thu, 21 Apr 2016 00:26:47 -0700 

On Thu, 21 Apr 2016, Kane Kim wrote:


Are actions in the queue executed in parallel or sequentially? If batch
can't be finalized until all output modules succeeded I don't see reason
not to block current batch until they all succeed.


"yes" :-)


as a batch is processed, rsyslog takes an individual message and goes 
sequentially through every action, doing the filtering and letting each action 
create the chunk of data to be delivered, but nothing is delivered at this 
point, just accumulated.



Then after all log messages in this batch have been processed, rsyslog loops 
through the actions saying "deliver all the messages you have prepared"





so (approximately)  if you have 2 messages in a batch (m1, m2) with two actions 
(@@server1, @@server2)



At the start of the batch, the worker thread locks the queue and markes two 
messages as being processed (so that another worker thread won't try to deliver 
them). It will then unlock the queue so that other things can add/remove 
messages from the queue.



rsyslog will take message m1, tell action 1 (@@server1) to prepare it, action 1 
will create a string "m1\n"
rsyslog will then tell action2 (@@server2) to prepare it, action2 will create a 
string "m1\n"


rsyslog will then take message m2 and tell action1 to prepare it
action1 will modify it's string to now contain "m1\nm2\n"
rsyslog will then take message m2 and tell action2 to prepare it
action2 will modify it's string to now contain "m1\nm2\n"

(I think this is when the batch is currently ending)


now that all messages have been processed, rsyslog will tell action2 to deliver 
the messages and the module will send the string "m1\nm2\n" over the network to 
server1



rsyslog will then tell action2 to deliver the messages, and the module wil try 
to send the string, in this case let's say that it gets a error from the TCP 
stack that the connection is gone and can't deliver the messages.


At this point the messages were already delivered to server1, but not to server2


since this is a temporary error, rsyslog will lock the queue, and remove the 
marks from the two messages, making them look like they have never been 
processed, and then unlock the queue.



the worker thread will then look at the queue again with fresh eyes and grab the 
two messages again and go through the entire process again. Each time it tries 
to deliver messages and fails going to server2, server1 will get another copy.



These retries have backoffs so that a failure doesn't end of DOSing the network 
with it's retries.




see what I mean by "yes", depending on how you look at it, it's serialized or 
parallel :-)



in v7, the worker thread processed all messages for each action before moving 
to the next action. But that caused problems with things like global variables 
where you want to process all actions with one value (and one log message) and 
then all actions with the next value (and the next log message), so in v8 it was 
changed.


David Lang




On Thu, Apr 21, 2016 at 12:00 AM, David Lang <[email protected]> wrote:


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

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

If the batch does not get finalized until after all of the output modules
attempt to deliver the messages, then the error is detectable, but all the
messages of actions that succeeded before the action that fails will end up
getting 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
the batch 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
an output module can't deliver the full batch for any reason, abort the
entire batch and try again (either with a partial batch, or by grabbing
messages fresh from the queue if it's a type 1 failure)

Yes, this will duplicate messages to one output if a different one has
problems that would be satisfied with a simple retry/reconnect, but I think
we should get things 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
were two 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 am
misunderstanding 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
problem is really the second type. A failure to establish a connection to
the destination 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 be
delivered, even if we retried for 100 years)

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

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

If any messages did get delivered as part of the batch processing, they
will be 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 probably
means that the next batch will fail as well)

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

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

In an ideal situation you can write such messages somewhere or otherwise
detect the error. But you end up only loosing one message that has
something corrupt 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


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)




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





























					Reply via email to