On Fri, 19 Sep 2014, Devin Christensen wrote:
Alright, I've got everything working, but I came across a very strang issue
in the process. As far as I can tell, the key to getting a disk assisted
queue to be re-loaded when rsyslog restarts is the *.qi file that gets stored
in the spool directory.
I can confirm that this is correct.
The follwing config prevented that file from getting
written when rsyslog shutdown.
module(load="imudp" threads="2")
When I changed the the threads setting in the imudp module from "2" to "1",
the *.qi files for my disk-assisted queues would correctly get written to the
spool directory when I shutdown rsyslog. I belive this is becasue rsyslog
would also take roughly 30 seconds to shutdown when threads was set to "2".
I'm thinking the shutdown process is timing out for some reason while trying
to cleanup the imudp input and never makes it to the disk-assisted queues to
write out the *.qi files.
All I know for sure is that setting threads in the imudp module to "2" causes
rsyslog to take 29.685s to shutdown and the *.qi files for my disk-assisted
queues never get written. When I set the threads for the imudp module to "1",
rsyslog shuts down in 0.121s, and the *.qi files for my disk-assisted queues
are written to the spool directory. I was seeing this behavior in 7.6.3 as
well as 8.4.0.
What distro are you using for this? Could you check the distro shutdown
script/config to see if it's enforcing the timeout?
I believe that rsyslog has a setting for how long it's allowed to spend trying
to flush it's queues when shutting down.
If you can duplicate this at will (especially if you can duplicate it starting
and stopping rsyslog manually), see if starting rsyslog with -dn has any
interesting output at shutdown time.
It's interesting that you are running into grief with an input module. that
would say that it's probably an issue with locking on the main queue.
The inudp module is rather efficient and you should not need more than one
thread with it unless you are dealing with more than a couple hundred thousand
messages per second. With most things in rsyslog, you have the option of
configuring additional threads, but usually shouldn't. Rsyslog has a lot of
internal queues that the message moves between. Normally this is done very
efficiently in batches of messages, but if you have too many threads for the
work you are doing, the batch size drops drastically and performance plummets
because the threads are spending too much time locking and unlocking the queues.
I would suggest dropping the workers count down to the default 1 everywhere,
unless benchmarking indicates that you have a bottleneck.
Also, as a side note, I've measured better performance with FixedArray queues
than LinkedList queues.
David Lang
Let me know if you need any other info to track this down.
On 09/18/2014 04:11 PM, Devin Christensen wrote:
I'm getting closer on this. Adding queue.timeoutenqueue="0" to the action
gave me what I was after in terms of discarding. It filled up the disk
queue to the configured max and then started discarding all messages after
that. I'm using impstats to track things. Here are the relative output
lines after filling up my disk-assisted queue:
action 1 queue[DA]: size=4101477 enqueued=5948040 full=1846563
discarded.full=1846563 discarded.nf=0 maxqsize=4101477
action 1 queue: size=51960 enqueued=6000000 full=0 discarded.full=0
discarded.nf=0 maxqsize=61776
main Q: size=17 enqueued=6000941 full=0 discarded.full=0 discarded.nf=0
maxqsize=5309
As you can see, the messages are only getting discarded at "action 1
queue[DA]" which is what I expected. So things are looking great there.
Back pressure is not piling up on the main Q (maxqsize=5309) either. Very
happy about the way that is working, but I'm now bumping into an issue
during restarts. When I restart rsyslog, the impstats output changes from
what's above to:
action 1 queue[DA]: size=0 enqueued=0 full=0 discarded.full=0
discarded.nf=0 maxqsize=0
rsyslogd-pstats: action 1 queue: size=0 enqueued=0 full=0 discarded.full=0
discarded.nf=0 maxqsize=0
main Q: size=17 enqueued=21 full=0 discarded.full=0 discarded.nf=0
maxqsize=17
As you can see, all the logs in "action 1 queue[DA]" are now gone (size=0),
even though the spool files still exist on disk. I expected the "action 1
queue[DA]" to remain at "size=4101477" after a restart. I confirmed the
logs were lost by starting the omfwd receiver again and waiting for 5
minutes. No logs were ever transmitted; howerver, it does receive new logs
just fine. When I shutdown the receiver and send more logs I get:
action 1 queue[DA]: size=101666 enqueued=101667 full=0 discarded.full=0
discarded.nf=0 maxqsize=101666
action 1 queue: size=77270 enqueued=500000 full=290102
discarded.full=290102 discarded.nf=0 maxqsize=100000
main Q: size=17 enqueued=501421 full=0 discarded.full=0 discarded.nf=0
maxqsize=475
Now the logs are getting discared at "action 1 queue" rather than "action 1
queue[DA]". It also looks like rsyslog reuses the spool files. Even though
"action 1 queue[DA]" filled to "size=101666", the actual on disk size never
increased beyond the size it was at when I restarted rsyslog. I'm going to
do some more experimenting, but do let me know if you see antyhing wrong
with my setup. I'm currently doing all testing on rsyslog 8.4.0. I'll try
7.6.3 if I can't get 8.4.0 working. Here's my test configuration:
################################################################################
# Global Config
################################################################################
$FileGroup adm
$FileOwner syslog
$PrivDropToGroup syslog
$PrivDropToUser syslog
$RepeatedMsgReduction off
$Umask 0022
$WorkDirectory /var/spool/rsyslog
################################################################################
# Input
################################################################################
module(load="imuxsock") # provides support for local system logging
module(load="imklog") # provides kernel logging support
module(load="imfile")
module(load="impstats" interval="5")
################################################################################
# Main Queue
################################################################################
main_queue(
queue.type="LinkedList"
queue.size="100000"
queue.dequeuebatchsize="1000"
queue.workerthreads="2"
queue.dequeueslowdown="0"
)
################################################################################
# Templates
################################################################################
template(name="preformatted" type="list") {
property(name="msg")
}
################################################################################
# Output
################################################################################
# Defaults for file output
module(
load="builtin:omfile"
template="RSYSLOG_TraditionalFileFormat"
dirCreateMode="0755"
fileCreateMode="0644"
)
# Test forward action
local1.* action(
type="omfwd"
Target="localhost"
Port="4414"
Protocol="tcp"
template="preformatted"
action.resumeRetryCount="-1"
action.resumeInterval="15"
queue.type="LinkedList"
queue.size="100000"
queue.highwatermark="60000"
queue.lowwatermark="50000"
queue.dequeuebatchsize="10"
queue.timeoutenqueue="0"
queue.workerthreads="2"
queue.filename="fwd_test"
queue.maxdiskspace="4g"
queue.maxfilesize="64m"
queue.saveonshutdown="on"
)
auth,authpriv.* /var/log/auth.log
*.*;auth,authpriv.none;\
local0,local1,local2,local3,local4,local5,local6,local7.none
/var/log/syslog
syslog.* /var/log/rsyslog.log #rsyslog error messages
kern.* /var/log/kern.log
mail.* /var/log/mail.log
mail.err /var/log/mail.err
news.crit /var/log/news/news.crit
news.err /var/log/news/news.err
news.notice /var/log/news/news.notice
*.emerg :omusrmsg:*
On 09/18/2014 02:50 AM, Rainer Gerhards wrote:
2014-09-18 9:03 GMT+02:00 Radu Gheorghe <[email protected]>:
Hi Devin,
My understanding is that a timeoutenqueue of 0 might have you lose
messages, as they're enqueued from the main queue to the action queue
when
rsyslog is busy, because it waits for... no time... for the action queue
to
enqueue that message. I was losing tons of messages during a performance
test with that setting. So I changed it to the default and had no more
problems.
It's used in cases where the queue in question is full or near-full, as
Devin quoted:
We can not hold processing infinitely, not even when throtteling.
For example, throtteling the local log socket too long would cause
the system at whole come to a standstill. To prevent this, rsyslogd
times out after a configured period ("$<object>QueueTimeoutEnqueue
",
specified in milliseconds) if no space becomes available. As a last
resort, it then discards the newly arrived message.
You probably lost messages because the queue was full and the output was
not able to free space. With defaults, the output could quickly enough
free
space and so the whole process continued without loss (remember, if there
is no timeout, even a nanosecond is "too long" a waittime).
Rainer
I'm still not 100% on what timeoutenqueue does, but I'd leave it to the
default for now on the action queue. Maybe Rainer or someone else who
understand this stuff better can clarify.
Best regards,
Radu
--
Performance Monitoring * Log Analytics * Search Analytics
Solr & Elasticsearch Support * http://sematext.com/
On Thu, Sep 18, 2014 at 9:52 AM, Devin Christensen <
[email protected]> wrote:
Thanks for the clarification. In that case, am I right in thinking that
the following action will discard all messages it receives when its disk
queue reaches 1 gigabyte, and avoid any throttling?
local1.* action(
type="omfwd"
Target="remote.example.com"
Port="4414"
Protocol="tcp"
template="preformatted"
action.resumeRetryCount="-1"
action.resumeInterval="15"
queue.type="LinkedList"
queue.size="100000"
queue.highwatermark="60000"
queue.lowwatermark="50000"
queue.dequeuebatchsize="1000"
queue.timeoutenqueue="0"
queue.workerthreads="2"
queue.filename="fwd_to_remote"
queue.maxdisksize="1g"
queue.maxfilesize="16m"
queue.saveonshutdown="on"
)
On 09/18/2014 12:43 AM, Rainer Gerhards wrote:
2014-09-18 8:28 GMT+02:00 Devin Christensen <
[email protected]>:
Actually, it looks like there may be some conflicting documentation
around
"queue.timeoutenqueue". From "Understanding Rsyslog Queues"
We can not hold processing infinitely, not even when throtteling.
For example, throtteling the local log socket too long would
cause
the system at whole come to a standstill. To prevent this,
rsyslogd
times out after a configured period
("$<object>QueueTimeoutEnqueue",
specified in milliseconds) if no space becomes available. As a
last
resort, it then discards the newly arrived message.
*If you do not like throtteling, set the timeout to 0 - the
message
will then immediately be discarded*. If you use a high timeout,
be
sure you know what you do. If a high main message queue enqueue
timeout is set, it can lead to something like a complete hang of
the
system. The same problem does not apply to action queues.
From "General Queue Parameters"
*queue.timeoutenqueue* number number is timeout in ms (1000ms is
1sec!), default 2000, *0 means indefinite*
This is wrong, just fixed the doc. 0 is "discard immediately".
Thx,
Rainer
Guess I won't tinker with that without a bit of clarification.
On 09/18/2014 12:15 AM, Devin Christensen wrote:
Thanks for the quick response. The other setting that I thought
might
help is "queue.timeoutenqueue" which I was considering setting to 0
on
the
action queue. The documentation leads me to believe this will discard
any
new messages arriving to the action when the disk queue reaches its
max
size. Does that sound right?
If I can isolate the discarded messages to those going to the omfwd
action that would be ideal. None of the other logs should cause back
pressure becuase they're not dependent on a remote host being up. Of
course, I think I should also add queue.discardmark and
queue.discardseverity to the main queue for additional reassurance.
On 09/17/2014 11:54 PM, Radu Gheorghe wrote:
Hi Devin,
I'm not 100% sure about this, but it sounds like what you should do
is
to
apply queue.discardmark and queue.discardseverity on the main queue.
This
should allow the action queue to fill up (to that 1GB), and put
pressure
on
the main queue. When main queue has more than $DISCARDMARK messages,
it
should begin discarding messages with a severity number higher than
$DISCARDSEVERITY.
You could go all-or-nothing with this, and discard everything
(severity=1
or maybe even 0 works?) when you hit 999999 messages, or you can
show a
bit
of mercy and, say, let only errors pass after you have 800K messages
in
the
queue. In the latter case you'd risk putting pressure back on the
socket,
though.
It sounds like you already know about all the queue parameters, but
just
in
case you missed the docs:
http://www.rsyslog.com/doc/master/rainerscript/queue_parameters.html
Best regards,
Radu
--
Performance Monitoring * Log Analytics * Search Analytics
Solr & Elasticsearch Support * http://sematext.com/
On Thu, Sep 18, 2014 at 8:41 AM, Devin Christensen <
[email protected]> wrote:
I'm trying to configure an action queue so that it will discard
all
messages immediately if it fills up it's allocated disk space. The
log
messages are coming in on the local socket. I just recovered from a
scenario where rsyslog was bringing systems to a halt, presumably
because
back pressure is ending up on the local log socket, filling it up,
and
letting nothing else write.
Here is my current configuration for my main queue and the action.
main_queue(
queue.type="LinkedList"
queue.size="1000000"
queue.dequeuebatchsize="1000"
queue.workerthreads="5"
queue.dequeueslowdown="0"
)
local1.* action(
type="omfwd"
Target="remote.example.com"
Port="4414"
Protocol="tcp"
template="preformatted"
action.resumeRetryCount="-1"
action.resumeInterval="15"
queue.type="LinkedList"
queue.size="100000"
queue.highwatermark="60000"
queue.lowwatermark="50000"
queue.dequeuebatchsize="1000"
queue.workerthreads="2"
queue.filename="fwd_preformatted_to_logflume"
queue.maxdisksize="1g"
queue.maxfilesize="16m"
queue.saveonshutdown="on"
)
In the event that the target (remote.example.com) is unavailable, I
would
like logs to spool to disk upto 1 gigabyte, and discard everything
immediately after that. I want to avoid any back pressure ending up
on
the
local log socket. It's much more valuable for our systems to
continue
running than to get all the log data.
My question is, what am I missing or completely messed up?
_______________________________________________
rsyslog mailing list
http://lists.adiscon.net/mailman/listinfo/rsyslog
http://www.rsyslog.com/professional-services/
What's up with rsyslog? Follow https://twitter.com/rgerhards
NOTE WELL: This is a PUBLIC mailing list, posts are ARCHIVED by a
myriad
of sites beyond our control. PLEASE UNSUBSCRIBE and DO NOT POST if
you
DON'T LIKE THAT.
_______________________________________________
rsyslog mailing list
http://lists.adiscon.net/mailman/listinfo/rsyslog
http://www.rsyslog.com/professional-services/
What's up with rsyslog? Follow https://twitter.com/rgerhards
NOTE WELL: This is a PUBLIC mailing list, posts are ARCHIVED by a
myriad
of sites beyond our control. PLEASE UNSUBSCRIBE and DO NOT POST if
you
DON'T LIKE THAT.
_______________________________________________
rsyslog mailing list
http://lists.adiscon.net/mailman/listinfo/rsyslog
http://www.rsyslog.com/professional-services/
What's up with rsyslog? Follow https://twitter.com/rgerhards
NOTE WELL: This is a PUBLIC mailing list, posts are ARCHIVED by a
myriad
of sites beyond our control. PLEASE UNSUBSCRIBE and DO NOT POST if
you
DON'T LIKE THAT.
_______________________________________________
rsyslog mailing list
http://lists.adiscon.net/mailman/listinfo/rsyslog
http://www.rsyslog.com/professional-services/
What's up with rsyslog? Follow https://twitter.com/rgerhards
NOTE WELL: This is a PUBLIC mailing list, posts are ARCHIVED by a
myriad
of sites beyond our control. PLEASE UNSUBSCRIBE and DO NOT POST if you
DON'T LIKE THAT.
_______________________________________________
rsyslog mailing list
http://lists.adiscon.net/mailman/listinfo/rsyslog
http://www.rsyslog.com/professional-services/
What's up with rsyslog? Follow https://twitter.com/rgerhards
NOTE WELL: This is a PUBLIC mailing list, posts are ARCHIVED by a
myriad
of sites beyond our control. PLEASE UNSUBSCRIBE and DO NOT POST if you
DON'T LIKE THAT.
_______________________________________________
rsyslog mailing list
http://lists.adiscon.net/mailman/listinfo/rsyslog
http://www.rsyslog.com/professional-services/
What's up with rsyslog? Follow https://twitter.com/rgerhards
NOTE WELL: This is a PUBLIC mailing list, posts are ARCHIVED by a myriad
of sites beyond our control. PLEASE UNSUBSCRIBE and DO NOT POST if you
DON'T LIKE THAT.
_______________________________________________
rsyslog mailing list
http://lists.adiscon.net/mailman/listinfo/rsyslog
http://www.rsyslog.com/professional-services/
What's up with rsyslog? Follow https://twitter.com/rgerhards
NOTE WELL: This is a PUBLIC mailing list, posts are ARCHIVED by a myriad
of sites beyond our control. PLEASE UNSUBSCRIBE and DO NOT POST if you
DON'T LIKE THAT.
_______________________________________________
rsyslog mailing list
http://lists.adiscon.net/mailman/listinfo/rsyslog
http://www.rsyslog.com/professional-services/
What's up with rsyslog? Follow https://twitter.com/rgerhards
NOTE WELL: This is a PUBLIC mailing list, posts are ARCHIVED by a myriad
of sites beyond our control. PLEASE UNSUBSCRIBE and DO NOT POST if you
DON'T LIKE THAT.
_______________________________________________
rsyslog mailing list
http://lists.adiscon.net/mailman/listinfo/rsyslog
http://www.rsyslog.com/professional-services/
What's up with rsyslog? Follow https://twitter.com/rgerhards
NOTE WELL: This is a PUBLIC mailing list, posts are ARCHIVED by a myriad of
sites beyond our control. PLEASE UNSUBSCRIBE and DO NOT POST if you DON'T
LIKE THAT.
_______________________________________________
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.
