MonitorWare Knowledge Base

HI Everybody,

I am setting up a rsyslog server that will receive logs from about 15 different servers. They will include apache logs and jboss logs. It will be a massive amount of data.

I am running rsyslog-3.21.0, compiled with:
FEATURE_REGEXP: Yes
FEATURE_LARGEFILE: Yes
FEATURE_NETZIP (message compression): Yes
GSSAPI Kerberos 5 support: No
FEATURE_DEBUG (debug build, slow code): No
Runtime Instrumentation (slow code): No


I have correct setup jboss and apache logging to syslog and it is all working, but I am having trouble understanding the queues in depth, especially on the forwarder.

I have 1 forwarder running apache and jboss sending all the logs to it's local rsyslog, which then forwards everything to the central logging server.

It seems that the MainMsgQueue doesn't always behave the same way on the forwarder.

From my understanding, on the forwarder, all the messages are received by the MainMsgQueue and then sent to the ActionQueues for delivery.
I am generating about 200/400 syslog messages per second and it seems that the MainMsgQueue waits for random number of messages on its queue before sending it to the action queues. This random number is varying from 10000 to 150000 on my tests..

Is there a configuration parameter that tells the MainMsgQueue to send the msgs to the ActionQueues ?

What is the function of the WaterMarks when used on a queue that it not Disk Assisted? I was assuming that this is what tells the Main Queue to send the msgs to the Action, but it's not working like that.

Using the configuration pasted below, the MainQueue started forwarding the messages after there were 67170 messages in the queue. this is the debug log if that part.

Code: Select all

7156.729907000:imudp.c: main queue: entry added, size now 67170 entries
7156.729915000:imudp.c: main queue: EnqueueMsg signaled condition (0)
7156.729923000:imudp.c: wtpAdviseMaxWorkers signals busy
7156.729933000:imudp.c: Listening on UDP syslogd socket 6 (IPv6/port 514).
7156.729942000:imudp.c: Listening on UDP syslogd socket 7 (IPv4/port 514).
7156.729950000:imudp.c: --------imUDP calling select, active file descriptors (max 7): 6 7
7156.730023000:imudp.c: Message from inetd socket: #7, host: twofacev03
7156.730032000:imudp.c: dropped LF at very end of message (DropTrailingLF is set)
7156.730046000:imudp.c: logmsg: flags 0, pri 139, from 'twofacev03', msg ERROR [uk.co.fresca.struts.subcontroller.pws.ProductDetailsAction] Error while getti
ng searchable product with id:35271 RuntimeException; CausedByException is:#012#011null
7156.730055000:imudp.c: Message has legacy syslog format.
7156.730069000:imudp.c: main queue: entry added, size now 67171 entries
7156.730077000:imudp.c: main queue: EnqueueMsg signaled condition (0)
7156.730085000:imudp.c: wtpAdviseMaxWorkers signals busy
7156.730094000:imudp.c: Listening on UDP syslogd socket 6 (IPv6/port 514).
7156.730104000:imudp.c: Listening on UDP syslogd socket 7 (IPv4/port 514).
7156.730112000:imudp.c: --------imUDP calling select, active file descriptors (max 7): 6 7
7157.128861000:imuxsock.c: main queue: enqueueMsg: LightDelay mark reached for light delayble message - blocking a bit.
7157.277744000:action 3 queue:Reg/w0: action 3 queue: entering rate limiter
7157.277779000:action 3 queue:Reg/w0: action 3 queue:Reg/w0: worker IDLE, waiting for work.
7157.277800000:action 4 queue:Reg/w0: action 4 queue: entering rate limiter
7157.277825000:action 4 queue:Reg/w0: action 4 queue: entry deleted, state 0, size now 0 entries
7157.277854000:action 4 queue:Reg/w0:  10.3.2.111
7157.277863000:action 4 queue:Reg/w0:  10.3.2.111:514/tcp
7157.277892000:action 4 queue:Reg/w0: TCP sent 211 bytes, requested 211
7157.277911000:main queue:Reg/w0: main queue: entering rate limiter
7157.277922000:main queue:Reg/w0: main queue: entry deleted, state 0, size now 67170 entries
7157.277936000:main queue:Reg/w0: Called action, logging to builtin-fwd
7157.277947000:main queue:Reg/w0: action 4 queue: entry added, size now 1 entries
7157.277980000:main queue:Reg/w0: action 4 queue: EnqueueMsg signaled condition (0)
7157.277990000:main queue:Reg/w0: wtpAdviseMaxWorkers signals busy
7157.278002000:action 4 queue:Reg/w0: action 4 queue: entering rate limiter
7157.278011000:action 4 queue:Reg/w0: action 4 queue: entry deleted, state 0, size now 0 entries
7157.278025000:action 4 queue:Reg/w0:  10.3.2.111
7157.278034000:action 4 queue:Reg/w0:  10.3.2.111:514/tcp
7157.278048000:action 4 queue:Reg/w0: TCP sent 228 bytes, requested 228
7157.278073000:main queue:Reg/w0: main queue: entering rate limiter
7157.278083000:main queue:Reg/w0: main queue: entry deleted, state 0, size now 67169 entries
7157.278093000:main queue:Reg/w0: Called action, logging to builtin-fwd
7157.278103000:main queue:Reg/w0: action 4 queue: entry added, size now 1 entries
7157.278111000:main queue:Reg/w0: action 4 queue: EnqueueMsg signaled condition (0)
7157.278119000:main queue:Reg/w0: wtpAdviseMaxWorkers signals busy


Below is a copy of my configuration:

Code: Select all

$ModLoad imtcp
$InputTCPServerRun 514

$ModLoad imudp
$UDPServerRun 514

$ModLoad imuxsock.so
$ModLoad imklog.so

$MainMsgQueueType LinkedList
$MainMsgQueueSize 200000
$MainMsgQueueLowWaterMark 10000 # Tried different values here
$MainMsgQueueHighWatermark 20000 # Tried different values here
$MainMsgQueueDiscardMark 180000
#$MainMsgQueueWorkerThreadMinimumMessages 200
#$MainMsgQueueWorkerThreads 4

$WorkDirectory /var/rsyslog/spool # where to place spool files


$ActionQueueFileName jbossqueue
$ActionQueueMaxDiskSpace 1g   
$ActionQueueSaveOnShutdown on
$ActionQueueType LinkedList   
$ActionQueueLowWaterMark  2000 # tried different values here
$ActionQueueHighWaterMark 5000 # tried different values here
#$ActionQueueWorkerThreadMinimumMessages 200
#$ActionQueueWorkerThreads 4
local1.*       @@(o)10.3.2.111


$ActionQueueFileName apacheerrorqueue
$ActionQueueMaxDiskSpace 1g
$ActionQueueSaveOnShutdown on
$ActionQueueType LinkedList
$ActionQueueLowWaterMark 2000
$ActionQueueHighWaterMark 5000
#$ActionQueueWorkerThreadMinimumMessages 200
#$ActionQueueWorkerThreads 4
local2.*       @@(o)10.3.2.111


$ActionQueueFileName apacheaccessqueue
$ActionQueueMaxDiskSpace 1g
$ActionQueueSaveOnShutdown on
$ActionQueueType LinkedList
$ActionQueueLowWaterMark 2000
$ActionQueueHighWaterMark 5000
#$ActionQueueWorkerThreadMinimumMessages 200
#$ActionQueueWorkerThreads 4
local3.*       @@(o)10.3.2.111


$ActionQueueFileName apacherewritequeue
$ActionQueueMaxDiskSpace 1g
$ActionQueueSaveOnShutdown on
$ActionQueueType LinkedList
$ActionQueueLowWaterMark 2000
$ActionQueueHighWaterMark 5000
#$ActionQueueWorkerThreadMinimumMessages 200
#$ActionQueueWorkerThreads 4
local4.*       @@(o)10.3.2.111



And the configuration on the Rsyslog central server. (No problems with it so far)

Code: Select all


# Remote logging
$ModLoad imrelp
$InputRELPServerRun 20514
$ModLoad imtcp
#$TCPServerAddress 0.0.0.0
$InputTCPServerRun 514

#$ModLoad imudp
#$UDPServerAddress 0.0.0.0
#$UDPServerRun 514







$WorkDirectory /var/rsyslog/spool # where to place spool files
$ActionQueueFileName receiving # unique name prefix for spool files
$ActionQueueMaxDiskSpace 1g   # 1gb space limit (use as much as possible)
$ActionQueueSaveOnShutdown on # save messages to disk on shutdown
$ActionQueueType LinkedList   # run asynchronously
$ActionQueueMaxFileSize 2mb
$ActionResumeRetryCount -1    # infinite retries if host is down


#$MainMsgQueueWorkerThreadMinimumMessages 200
#$MainMsgQueueWorkerThreads 5
#$MainMsgQueueType LinkedList
#$MainMsgQueueSize 200000
#$MainMsgQueueLowWaterMark 200
#$MainMsgQueueHighWatermark 400
#$MainMsgQueueDiscardMark 180000
#$MainMsgQueueWorkerThreadMinimumMessages 200
#$MainMsgQueueWorkerThreads 5

$template format, "%msg:2:$%\n"
$template DYNmessages, "/var/log/hosts/%FROMHOST%/%$YEAR%/%$MONTH%/%$DAY%/messages"
$template DYNsecure, "/var/log/hosts/%FROMHOST%/%$YEAR%/%$MONTH%/%$DAY%/secure"
$template DYNmaillog, "/var/log/hosts/%FROMHOST%/%$YEAR%/%$MONTH%/%$DAY%/maillog"
$template DYNcron, "/var/log/hosts/%FROMHOST%/%$YEAR%/%$MONTH%/%$DAY%/cron"
$template DYNspooler, "/var/log/hosts/%FROMHOST%/%$YEAR%/%$MONTH%/%$DAY%/spooler"
$template DYNboot, "/var/log/hosts/%FROMHOST%/%$YEAR%/%$MONTH%/%$DAY%/boot.log"
$template DYNall, "/var/log/hosts/%FROMHOST%/%$YEAR%/%$MONTH%/%$DAY%/all.log"
$template DYNjboss, "/var/log/hosts/%FROMHOST%/%$YEAR%/%$MONTH%/%$DAY%/jboss-server.log"
$template DYNapacheerror, "/var/log/hosts/%FROMHOST%/%$YEAR%/%$MONTH%/%$DAY%/apache/error.log"
$template DYNapacheaccess, "/var/log/hosts/%FROMHOST%/%$YEAR%/%$MONTH%/%$DAY%/apache/access.log"
$template DYNapacheaccessWWW, "/var/log/hosts/%FROMHOST%/%$YEAR%/%$MONTH%/%$DAY%/apache/www-access.log"
$template DYNapacheaccessWWWS, "/var/log/hosts/%FROMHOST%/%$YEAR%/%$MONTH%/%$DAY%/apache/wwws-access.log"
$template DYNapacherewrite, "/var/log/hosts/%FROMHOST%/%$YEAR%/%$MONTH%/%$DAY%/apache/rewrite.log"
$template DYNapacherewriteWWW, "/var/log/hosts/%FROMHOST%/%$YEAR%/%$MONTH%/%$DAY%/apache/www-rewrite.log"
$template DYNapacherewriteWWWS, "/var/log/hosts/%FROMHOST%/%$YEAR%/%$MONTH%/%$DAY%/apache/wwws-rewrite.log"


if \
        $source != 'magneto' \
                and \
        $syslogfacility-text == 'local1' \
then ?DYNjboss

if \
        $source != 'magneto' \
                and \
        $syslogfacility-text == 'local2' \
then ?DYNapacheerror;format

if \
        $source != 'magneto' \
                and \
        $syslogfacility-text == 'local3' \
                and \
        $syslogseverity-text == 'info' \
then ?DYNapacheaccessWWW;format


if \
        $source != 'magneto' \
                and \
        $syslogfacility-text == 'local3' \
                and \
        $syslogseverity-text == 'notice' \
then ?DYNapacheaccessWWWS;format



if \
        $source != 'magneto' \
                and \
        $syslogfacility-text == 'local4' \
                and \
        $syslogseverity-text == 'info' \
then ?DYNapacherewriteWWW;format

if \
        $source != 'magneto' \
                and \
        $syslogfacility-text == 'local4' \
                and \
        $syslogseverity-text == 'notice' \
then ?DYNapacherewriteWWWS;format



Apologies for the long post, I hope someone can point what I am doing wrong and maybe explain what I didn't understand anbout the Main Queue.


Many Thanks.


Bruno

• Custom written rsyslog.conf?
• Maintenance Contract?
• Installation support?

bsda wrote:From my understanding, on the forwarder, all the messages are received by the MainMsgQueue and then sent to the ActionQueues for delivery.
I am generating about 200/400 syslog messages per second and it seems that the MainMsgQueue waits for random number of messages on its queue before sending it to the action queues. This random number is varying from 10000 to 150000 on my tests..

The main message queue does never wait (except you instruct it with rate limiting, e.g. via a time frame). So I think there are three reasons why you see what you see:

a) the client syslogd is swamped with new traffic, so that the sender thread does not receive any CPU quota and is stuck. I think this is unlikely.

b) the observation may not be correct, which leads us to

c) there is a problem related in creating the connection to the destination, like a DNS timeout or such

bsda wrote:What is the function of the WaterMarks when used on a queue that it not Disk Assisted? I was assuming that this is what tells the Main Queue to send the msgs to the Action, but it's not working like that.

WaterMarks are used with disk-assisted queues, only. Otherwise, they are ignored.

bsda wrote:Using the configuration pasted below, the MainQueue started forwarding the messages after there were 67170 messages in the queue. this is the debug log if that part.

Thanks for including the debug log in the initial post - much appreciated . However, as it looks, the problems happens earlier. So what I actually need is probably the first 2000 or so lines after startup plus 1000 or so lines before the first TCP send happens (plus a couple of lines when it is sending, just as you provided above. There is still a chance I need more, but that should get me started.

Thanks,
Rainer

Hi Rainer,

Thanks for the quick reply.

After you mentioned that it could be the CPU was too busy, I decided to make a few more tests.

The machine generating all the syslog messages is a Virtual Machine on XEN and it had 1GB MEM and 1 VCPU.
The load average during the tests was going up to 6/8 and it is indeed a very busy machine, running mysql, apache and jboss( it's a dev environment).

I just added an extra VCPU to it and rsyslog now performs much more likely what I was expecting, it starts forwarding the messages just after 137 messages are in the queue, and that is probably generated in about half a second. I tested it with 3.21.0 and 3.21.1.

So, it looks like I was abusing my system....I want to test it thoroughly before putting it on our production servers

Apologies for my mistake and please let me know if you wish me to make any more tests.


Thanks

Bruno

Hi Bruno,

glad it works out now, but I have to admit I am a bit surprised the (OS) scheduler lets starve the sending thread for sooo long. Rsyslog does nothing special in regard to thread priorities (it would open up platform incompatibility hell), but all reports I had so far tell that it is working reasonably well. Interesting to see the situation you experienced.

As a side-note, a run with debug output requires much more CPU than one without. Similarly, the --enable-debug runtime options adds considerable overhead. So if you have enabled it (it needs to), I'd make a test without it.

Rainer