[rsyslog] rsyslog queues gets emptied on suspend?

Discussion:

Simon Lundström

2018-11-28 11:16:03 UTC

Hey all!

While trying to setup queueing like we want it to I wonder if we've
found a bug or most likely doing something wrong. We've set limits very
low just to make sure we fill the queue fast for testing. We're running
8.24.0-1 from Debian 9 Stretch and this is our config with comments
removed:

module(load="imuxsock"
SysSock.RateLimit.Interval="0"
)
module(load="imklog")
module(load="builtin:omfile"
dirCreateMode="0755"
fileCreateMode="0644"
fileGroup="adm"
fileOwner="root"
)

global(
workDirectory="/var/spool/rsyslog"
MaxMessageSize="64k"
preserveFQDN="on"
action.reportSuspensionContinuation="on"
)

if $fromhost-ip == "127.0.0.1" then {
action(
type="omfile"
name="omfile-/var/log/messages"
File="/var/log/messages"
)
}

module(load="imtcp")
module(load="imudp")
module(load="impstats"
format="json-elasticsearch"
interval="5"
)

module(load="omprog")
if $fromhost-ip == "127.0.0.1" and $programname == "rsyslogd-pstats" then {
action(
name="action-omprog-impstats"
type="omprog"
binary="/local/nrpe/libexec/check_rsyslogd.pl --write"
)
}

input(type="imtcp"
port="514"
)

action(type="omfwd"
name="om-logstash"
target="127.0.0.1"
port="2514"
protocol="tcp"
template="RSYSLOG_ForwardFormat"
action.resumeRetryCount="1"
action.resumeInterval="5"
resendlastmsgonreconnect="on"
queue.timeoutEnqueue="2000"
queue.spoolDirectory="/local/rsyslog/spool"
queue.saveonshutdown="on"
queue.type="LinkedList"
queue.filename="om_logstash"
queue.maxfilesize="10M"
queue.maxdiskspace="20M"
queue.checkpointinterval="4000"
queue.size="2048"
)

Nothing is listening on TCP/2514 so the queues fill up really quick:
# du -sch /local/rsyslog/spool/*
9.6M /local/rsyslog/spool/om_logstash.00000069
9.6M /local/rsyslog/spool/om_logstash.00000070
4.0K /local/rsyslog/spool/om_logstash.qi
20M total

(Logs have been trimmed for space saving):
2018-11-28T11:48:13.570023+01:00 { "name": "omfile-\/var\/log\/messages", "origin": "core.action", "processed": 63, "failed": 0, "suspended": 0, "suspended!duration": 0, "resumed": 0 }
2018-11-28T11:48:13.570066+01:00 { "name": "om-logstash", "origin": "core.action", "processed": 494967, "failed": 0, "suspended": 2, "suspended!duration": 25, "resumed": 0 }
2018-11-28T11:48:13.570073+01:00 { "name": "imtcp(514)", "origin": "imtcp", "submitted": 513265 }
2018-11-28T11:48:13.570140+01:00 { "name": "om-logstash queue[DA]", "origin": "core.queue", "size": 6434, "enqueued": 12858, "full": 11, "discarded!full": 8, "discarded!nf": 0, "maxqsize": 6434 }
2018-11-28T11:48:13.570155+01:00 { "name": "om-logstash queue", "origin": "core.queue", "size": 2048, "enqueued": 494967, "full": 18, "discarded!full": 10, "discarded!nf": 0, "maxqsize": 2048 }
2018-11-28T11:48:13.570168+01:00 { "name": "main Q", "origin": "core.queue", "size": 18376, "enqueued": 513339, "full": 0, "discarded!full": 0, "discarded!nf": 0, "maxqsize": 70020 }
2018-11-28T11:48:18.575464+01:00 { "name": "omfile-\/var\/log\/messages", "origin": "core.action", "processed": 63, "failed": 0, "suspended": 0, "suspended!duration": 0, "resumed": 0 }
2018-11-28T11:48:18.575507+01:00 { "name": "om-logstash", "origin": "core.action", "processed": 494972, "failed": 0, "suspended": 2, "suspended!duration": 25, "resumed": 0 }
2018-11-28T11:48:18.575544+01:00 { "name": "imtcp(514)", "origin": "imtcp", "submitted": 564894 }
2018-11-28T11:48:18.575615+01:00 { "name": "om-logstash queue[DA]", "origin": "core.queue", "size": 6434, "enqueued": 12860, "full": 13, "discarded!full": 10, "discarded!nf": 0, "maxqsize": 6434 }
2018-11-28T11:48:18.575641+01:00 { "name": "om-logstash queue", "origin": "core.queue", "size": 2048, "enqueued": 494972, "full": 23, "discarded!full": 14, "discarded!nf": 0, "maxqsize": 2048 }
2018-11-28T11:48:18.575659+01:00 { "name": "main Q", "origin": "core.queue", "size": 70012, "enqueued": 564981, "full": 0, "discarded!full": 0, "discarded!nf": 0, "maxqsize": 70020 }
2018-11-28T11:48:20.028339+01:00 : action 'om-logstash' suspended, next retry is Wed Nov 28 11:48:25 2018 [v8.24.0 try http://www.rsyslog.com/e/2007 ]
2018-11-28T11:48:21.116309+01:00 : action 'om-logstash' suspended, next retry is Wed Nov 28 11:48:26 2018 [v8.24.0 try http://www.rsyslog.com/e/2007 ]

But here something happens
# du -sch /local/rsyslog/spool/*
9.6M /local/rsyslog/spool/om_logstash.00000070
104K /local/rsyslog/spool/om_logstash.00000071
4.0K /local/rsyslog/spool/om_logstash.qi
9.7M total

Looks like the queue is emptied because the size of "om-logstash
queue[DA]" is 0.

2018-11-28T11:48:23.580929+01:00 { "name": "omfile-\/var\/log\/messages", "origin": "core.action", "processed": 92, "failed": 0, "suspended": 0, "suspended!duration": 0, "resumed": 0 }
2018-11-28T11:48:23.580957+01:00 { "name": "om-logstash", "origin": "core.action", "processed": 671188, "failed": 0, "suspended": 2, "suspended!duration": 35, "resumed": 0 }
2018-11-28T11:48:23.580965+01:00 { "name": "imtcp(514)", "origin": "imtcp", "submitted": 671096 }
2018-11-28T11:48:23.581049+01:00 { "name": "om-logstash queue[DA]", "origin": "core.queue", "size": 0, "enqueued": 12928, "full": 14, "discarded!full": 11, "discarded!nf": 0, "maxqsize": 6477 }
2018-11-28T11:48:23.581080+01:00 { "name": "om-logstash queue", "origin": "core.queue", "size": 0, "enqueued": 671195, "full": 25, "discarded!full": 15, "discarded!nf": 0, "maxqsize": 2048 }
2018-11-28T11:48:23.581106+01:00 { "name": "main Q", "origin": "core.queue", "size": 18, "enqueued": 671213, "full": 0, "discarded!full": 0, "discarded!nf": 0, "maxqsize": 70020 }
2018-11-28T11:48:28.587074+01:00 { "name": "omfile-\/var\/log\/messages", "origin": "core.action", "processed": 104, "failed": 0, "suspended": 0, "suspended!duration": 0, "resumed": 0 }
2018-11-28T11:48:28.587108+01:00 { "name": "om-logstash", "origin": "core.action", "processed": 758684, "failed": 0, "suspended": 2, "suspended!duration": 35, "resumed": 0 }
2018-11-28T11:48:28.587116+01:00 { "name": "imtcp(514)", "origin": "imtcp", "submitted": 828582 }
2018-11-28T11:48:28.587167+01:00 { "name": "om-logstash queue[DA]", "origin": "core.queue", "size": 12103, "enqueued": 25033, "full": 16, "discarded!full": 12, "discarded!nf": 0, "maxqsize": 12103 }
2018-11-28T11:48:28.587182+01:00 { "name": "om-logstash queue", "origin": "core.queue", "size": 2048, "enqueued": 758684, "full": 28, "discarded!full": 16, "discarded!nf": 0, "maxqsize": 2048 }
2018-11-28T11:48:28.587195+01:00 { "name": "main Q", "origin": "core.queue", "size": 70011, "enqueued": 828694, "full": 0, "discarded!full": 0, "discarded!nf": 0, "maxqsize": 70020 }

I'm not sure what we've done wrong/missunderstood or if this really is a
bug. Why would rsyslog empty the queue?

We're trying to solve the problem of full queues, which will happen, and
what we want is for the rsyslog infront of logstash to start dropping
incoming messages not to push back to our central logserver.

This is our setup:

server 1 -> TCP -> central syslog server ( imtcp -> Action Queue ->
Action DA Queue -> omfwd TCP ) -> event server ( imtcp -> Action Queue
-> Action DA Queue -> omfwd TCP ) -> Logstash -> Elasticsearch.

On "central syslog server" and "event server" we want imtcp to just drop
the logs when one action queue is full. Is this possible at all or are
we trying to do something impossible?

BR,
- Simon

____________________________________

Simon Lundström
Section for Infrastructure

IT Services
Stockholm University
SE-106 91 Stockholm, Sweden

www.su.se/english/staff-info/it
https://www.su.se/english/about-this-website/privacy-policy
_______________________________________________
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

Rainer Gerhards

2018-11-28 11:24:24 UTC

Permalink

Post by Simon LundstrÃ¶m
Hey all!
While trying to setup queueing like we want it to I wonder if we've
found a bug or most likely doing something wrong. We've set limits very
low just to make sure we fill the queue fast for testing. We're running
8.24.0-1 from Debian 9 Stretch and this is our config with comments
module(load="imuxsock"
SysSock.RateLimit.Interval="0"
)
module(load="imklog")
module(load="builtin:omfile"
dirCreateMode="0755"
fileCreateMode="0644"
fileGroup="adm"
fileOwner="root"
)
global(
workDirectory="/var/spool/rsyslog"
MaxMessageSize="64k"
preserveFQDN="on"
action.reportSuspensionContinuation="on"
)
if $fromhost-ip == "127.0.0.1" then {
action(
type="omfile"
name="omfile-/var/log/messages"
File="/var/log/messages"
)
}
module(load="imtcp")
module(load="imudp")
module(load="impstats"
format="json-elasticsearch"
interval="5"
)
module(load="omprog")
if $fromhost-ip == "127.0.0.1" and $programname == "rsyslogd-pstats" then {
action(
name="action-omprog-impstats"
type="omprog"
binary="/local/nrpe/libexec/check_rsyslogd.pl --write"
)
}
input(type="imtcp"
port="514"
)
action(type="omfwd"
name="om-logstash"
target="127.0.0.1"
port="2514"
protocol="tcp"
template="RSYSLOG_ForwardFormat"
action.resumeRetryCount="1"

This tells rsyslog to do one retry, and if it fails suspend the
action. A suspended action will drop messages sent to it. Did you mean
"-1" (wait forever)?

Rainer

Post by Simon LundstrÃ¶m
action.resumeInterval="5"
resendlastmsgonreconnect="on"
queue.timeoutEnqueue="2000"
queue.spoolDirectory="/local/rsyslog/spool"
queue.saveonshutdown="on"
queue.type="LinkedList"
queue.filename="om_logstash"
queue.maxfilesize="10M"
queue.maxdiskspace="20M"
queue.checkpointinterval="4000"
queue.size="2048"
)
# du -sch /local/rsyslog/spool/*
9.6M /local/rsyslog/spool/om_logstash.00000069
9.6M /local/rsyslog/spool/om_logstash.00000070
4.0K /local/rsyslog/spool/om_logstash.qi
20M total
2018-11-28T11:48:13.570023+01:00 { "name": "omfile-\/var\/log\/messages", "origin": "core.action", "processed": 63, "failed": 0, "suspended": 0, "suspended!duration": 0, "resumed": 0 }
2018-11-28T11:48:13.570066+01:00 { "name": "om-logstash", "origin": "core.action", "processed": 494967, "failed": 0, "suspended": 2, "suspended!duration": 25, "resumed": 0 }
2018-11-28T11:48:13.570073+01:00 { "name": "imtcp(514)", "origin": "imtcp", "submitted": 513265 }
2018-11-28T11:48:13.570140+01:00 { "name": "om-logstash queue[DA]", "origin": "core.queue", "size": 6434, "enqueued": 12858, "full": 11, "discarded!full": 8, "discarded!nf": 0, "maxqsize": 6434 }
2018-11-28T11:48:13.570155+01:00 { "name": "om-logstash queue", "origin": "core.queue", "size": 2048, "enqueued": 494967, "full": 18, "discarded!full": 10, "discarded!nf": 0, "maxqsize": 2048 }
2018-11-28T11:48:13.570168+01:00 { "name": "main Q", "origin": "core.queue", "size": 18376, "enqueued": 513339, "full": 0, "discarded!full": 0, "discarded!nf": 0, "maxqsize": 70020 }
2018-11-28T11:48:18.575464+01:00 { "name": "omfile-\/var\/log\/messages", "origin": "core.action", "processed": 63, "failed": 0, "suspended": 0, "suspended!duration": 0, "resumed": 0 }
2018-11-28T11:48:18.575507+01:00 { "name": "om-logstash", "origin": "core.action", "processed": 494972, "failed": 0, "suspended": 2, "suspended!duration": 25, "resumed": 0 }
2018-11-28T11:48:18.575544+01:00 { "name": "imtcp(514)", "origin": "imtcp", "submitted": 564894 }
2018-11-28T11:48:18.575615+01:00 { "name": "om-logstash queue[DA]", "origin": "core.queue", "size": 6434, "enqueued": 12860, "full": 13, "discarded!full": 10, "discarded!nf": 0, "maxqsize": 6434 }
2018-11-28T11:48:18.575641+01:00 { "name": "om-logstash queue", "origin": "core.queue", "size": 2048, "enqueued": 494972, "full": 23, "discarded!full": 14, "discarded!nf": 0, "maxqsize": 2048 }
2018-11-28T11:48:18.575659+01:00 { "name": "main Q", "origin": "core.queue", "size": 70012, "enqueued": 564981, "full": 0, "discarded!full": 0, "discarded!nf": 0, "maxqsize": 70020 }
2018-11-28T11:48:20.028339+01:00 : action 'om-logstash' suspended, next retry is Wed Nov 28 11:48:25 2018 [v8.24.0 try http://www.rsyslog.com/e/2007 ]
2018-11-28T11:48:21.116309+01:00 : action 'om-logstash' suspended, next retry is Wed Nov 28 11:48:26 2018 [v8.24.0 try http://www.rsyslog.com/e/2007 ]
But here something happens
# du -sch /local/rsyslog/spool/*
9.6M /local/rsyslog/spool/om_logstash.00000070
104K /local/rsyslog/spool/om_logstash.00000071
4.0K /local/rsyslog/spool/om_logstash.qi
9.7M total
Looks like the queue is emptied because the size of "om-logstash
queue[DA]" is 0.
2018-11-28T11:48:23.580929+01:00 { "name": "omfile-\/var\/log\/messages", "origin": "core.action", "processed": 92, "failed": 0, "suspended": 0, "suspended!duration": 0, "resumed": 0 }
2018-11-28T11:48:23.580957+01:00 { "name": "om-logstash", "origin": "core.action", "processed": 671188, "failed": 0, "suspended": 2, "suspended!duration": 35, "resumed": 0 }
2018-11-28T11:48:23.580965+01:00 { "name": "imtcp(514)", "origin": "imtcp", "submitted": 671096 }
2018-11-28T11:48:23.581049+01:00 { "name": "om-logstash queue[DA]", "origin": "core.queue", "size": 0, "enqueued": 12928, "full": 14, "discarded!full": 11, "discarded!nf": 0, "maxqsize": 6477 }
2018-11-28T11:48:23.581080+01:00 { "name": "om-logstash queue", "origin": "core.queue", "size": 0, "enqueued": 671195, "full": 25, "discarded!full": 15, "discarded!nf": 0, "maxqsize": 2048 }
2018-11-28T11:48:23.581106+01:00 { "name": "main Q", "origin": "core.queue", "size": 18, "enqueued": 671213, "full": 0, "discarded!full": 0, "discarded!nf": 0, "maxqsize": 70020 }
2018-11-28T11:48:28.587074+01:00 { "name": "omfile-\/var\/log\/messages", "origin": "core.action", "processed": 104, "failed": 0, "suspended": 0, "suspended!duration": 0, "resumed": 0 }
2018-11-28T11:48:28.587108+01:00 { "name": "om-logstash", "origin": "core.action", "processed": 758684, "failed": 0, "suspended": 2, "suspended!duration": 35, "resumed": 0 }
2018-11-28T11:48:28.587116+01:00 { "name": "imtcp(514)", "origin": "imtcp", "submitted": 828582 }
2018-11-28T11:48:28.587167+01:00 { "name": "om-logstash queue[DA]", "origin": "core.queue", "size": 12103, "enqueued": 25033, "full": 16, "discarded!full": 12, "discarded!nf": 0, "maxqsize": 12103 }
2018-11-28T11:48:28.587182+01:00 { "name": "om-logstash queue", "origin": "core.queue", "size": 2048, "enqueued": 758684, "full": 28, "discarded!full": 16, "discarded!nf": 0, "maxqsize": 2048 }
2018-11-28T11:48:28.587195+01:00 { "name": "main Q", "origin": "core.queue", "size": 70011, "enqueued": 828694, "full": 0, "discarded!full": 0, "discarded!nf": 0, "maxqsize": 70020 }
I'm not sure what we've done wrong/missunderstood or if this really is a
bug. Why would rsyslog empty the queue?
We're trying to solve the problem of full queues, which will happen, and
what we want is for the rsyslog infront of logstash to start dropping
incoming messages not to push back to our central logserver.
server 1 -> TCP -> central syslog server ( imtcp -> Action Queue ->
Action DA Queue -> omfwd TCP ) -> event server ( imtcp -> Action Queue
-> Action DA Queue -> omfwd TCP ) -> Logstash -> Elasticsearch.
On "central syslog server" and "event server" we want imtcp to just drop
the logs when one action queue is full. Is this possible at all or are
we trying to do something impossible?
BR,
- Simon
____________________________________
Simon Lundström
Section for Infrastructure
IT Services
Stockholm University
SE-106 91 Stockholm, Sweden
www.su.se/english/staff-info/it
https://www.su.se/english/about-this-website/privacy-policy
_______________________________________________
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. PLEAS

Simon Lundström

2018-11-29 12:42:10 UTC

Permalink

Post by Rainer Gerhards

This tells rsyslog to do one retry, and if it fails suspend the
action. A suspended action will drop messages sent to it.

That's exactly what we want but that's not what we're seeing. I wrote in
my original mail what happens but if I was unclear let me know how I can
expand and explain!

Post by Rainer Gerhards
Did you mean "-1" (wait forever)?

No, as I wrote we want rsyslog to start dropping the incoming logs when
the queues are full and the action is suspended.

BR,
- Simon
_______________________________________________
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

Rainer Gerhards

2018-11-29 12:44:54 UTC

Permalink

Post by Simon LundstrÃ¶m

Post by Rainer Gerhards

then {

Post by Rainer Gerhards

Post by Simon LundstrÃ¶m
action(
name="action-omprog-impstats"
type="omprog"
binary="/local/nrpe/libexec/check_rsyslogd.pl --write"
)
}
input(type="imtcp"
port="514"
)
action(type="omfwd"
name="om-logstash"
target="127.0.0.1"
port="2514"
protocol="tcp"
template="RSYSLOG_ForwardFormat"
action.resumeRetryCount="1"

This tells rsyslog to do one retry, and if it fails suspend the
action. A suspended action will drop messages sent to it.

That's exactly what we want but that's not what we're seeing. I wrote in
my original mail what happens but if I was unclear let me know how I can
expand and explain!

Post by Rainer Gerhards
Did you mean "-1" (wait forever)?

No, as I wrote we want rsyslog to start dropping the incoming logs when
the queues are full and the action is suspended.

Out of my head, I don't think you can let an action go suspended but keep
the queue.

Actually, what you do is not let it go suspended, but discard messages that
do no longer fit into the queue. There is a queue setting for "drop
messages with prio x if queue fuller than...).

Rainer

BR,

Post by Simon LundstrÃ¶m
- Simon
_______________________________________________
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.