MonitorWare Knowledge Base

Hi,

First of all, excuse my poor english, hope this will be readable...

I've got rsyslog configured to log locally and send a copy to another (in fact 2, but the problem is the same with only one) log server via relp, the log input are imklog and imuxlog. All seems to work fine except in one condition.

here is a brief of my client configuration:

Code: Select all

$ModLoad immark.so # provides --MARK-- message capability
$ModLoad imuxsock.so # provides support for local system logging (e.g. via logger command)
$ModLoad imklog.so # kernel logging (formerly provided by rklogd)
$ModLoad omrelp # needs to be done just once
(...)template definition + local logging(...)
$WorkDirectory /var/log/rsys_spool
$ActionQueueType LinkedList
$ActionQueueFileName peer
$ActionResumeRetryCount -1
$ActionQueueSaveOnShutdown on
*.* :omrelp:10.X.X.X:2514;RSYSLOG_SyslogProtocol23Format

$WorkDirectory /var/log/rsys_spool
$ActionQueueType LinkedList
$ActionQueueFileName uranus
$ActionResumeRetryCount -1
$ActionQueueSaveOnShutdown on
*.* :omrelp:192.X.X.X:2514;RSYSLOG_SyslogProtocol23Format


If i run rsyslog with more than 300 message in /dev/log (the one that get imklog) and the remote server isn't running/accessible, as soon as this 300 msg are in the queue of the omrelp action, this one start lightDelaying message (as imklog message are lightdelayable). By doing this, the message are bloqued in the main queue, causing this one to just grow up as it will never more get a message out. At the end, the main queue is full and just drop msg, logging system is out.


Here is a brief of the debug (which will be better than my english explanation, i hope ...)

Code: Select all


(...)All starting stuff(...)

8082.335969000:main thread: Control character escape sequence prefix is '#'.
8082.335974000:main thread: Main queue size 10000 messages.
8082.335980000:main thread: Main queue worker threads: 1, Perists every 0 updates.
8082.335985000:main thread: Main queue timeouts: shutdown: 0, action completion shutdown: 1000, enq: 2000
8082.335991000:main thread: Main queue watermarks: high: 8000, low: 2000, discard: 9800, discard-severity: 8
8082.335997000:main thread: Main queue save on shutdown 1, max disk space allowed 0
8082.336002000:main thread: Work Directory: '/var/log/rsys_spool'.
8082.336009000:imklog.c: wtpAdviseMaxWorkers signals busy
8082.336015000:main thread: logmsg: flags 5, from 'demos', msg  [origin software="rsyslogd" swVersion="3.18.4" x-pid="2302" x-info="http://www.rsyslog.com"] restart
8082.336021000:imklog.c: main queue: entry added, size now 23 entries
8082.336027000:main thread: Message has legacy syslog format.
8082.336037000:imklog.c: main queue: EnqueueMsg signaled condition (0)
8082.336044000:imklog.c: 8082.336045000:main thread: main queue: wtpAdviseMaxWorkers signals busy
entry added, size now 24 entries
8082.336054000:main thread: main queue: EnqueueMsg signaled condition (0)
8082.336058000:main thread: wtpAdviseMaxWorkers signals busy
8082.336059000:imklog.c: main queue: entry added, size now 25 entries
8082.336066000:8082.336071000:main thread: imklog.c: main queue: EnqueueMsg signaled condition (0)
(re)started.
8082.336081000:main queue:Reg/w0: Called action, logging to builtin-file
8082.336089000:main thread: Debugging enabled, SIGUSR1 to turn off debugging.
8082.336095000:main thread: initialization completed, transitioning to regular run mode
8082.336113000:main queue:Reg/w0:  (DynMSG)
8082.336152000:imklog.c: wtpAdviseMaxWorkers signals busy
8082.336162000:imklog.c: main queue: entry added, size now 26 entries
8082.336167000:imklog.c: main queue: EnqueueMsg signaled condition (0)
8082.336171000:imklog.c: wtpAdviseMaxWorkers signals busy
8082.336178000:imklog.c: main queue: entry added, size now 27 entries
8082.336182000:imklog.c: main queue: EnqueueMsg signaled condition (0)
8082.336186000:imklog.c: wtpAdviseMaxWorkers signals busy
8082.336195000:imklog.c: main queue: entry added, size now 28 entries

(...)this 2 server were unavailable, stacking message on action queue(...)

8082.344734000:imklog.c: wtpAdviseMaxWorkers signals busy
8082.344741000:imklog.c: main queue: entry added, size now 520 entries
8082.344745000:imklog.c: main queue: EnqueueMsg signaled condition (0)
8082.344749000:imklog.c: wtpAdviseMaxWorkers signals busy
8082.344759000:imklog.c: main queue: entry added, size now 521 entries
8082.344763000:imklog.c: main queue: EnqueueMsg signaled condition (0)
8082.344767000:imklog.c: wtpAdviseMaxWorkers signals busy
8082.344774000:imklog.c: main queue: entry added, size now 522 entries
8082.344778000:imklog.c: main queue: EnqueueMsg signaled condition (0)
8082.344782000:imklog.c: wtpAdviseMaxWorkers signals busy
8082.345136000:main queue:Reg/w0: Added new entry 0 for file cache, file '/var/log/demos/2008-10-03/messages'.
8082.345465000:main queue:Reg/w0: Called action, logging to omrelp8082.345471000:main queue:Reg/w0: action 9 queue: entry added, size now 1 entries
8082.345481000:main queue:Reg/w0: action 9 queue: EnqueueMsg signaled condition (0)
wtpAdviseMaxWorkers signals busy
8082.345489000:main queue:Reg/w0: Called action, logging to omrelp8082.345494000:main queue:Reg/w0: action 10 queue: entry added, size now 1 entries
8082.345499000:main queue:Reg/w0: action 10 queue: EnqueueMsg signaled condition (0)
wtpAdviseMaxWorkers signals busy
8082.345508000:action 9 queue:Reg/w0: action 9 queue: entering rate limiter
8082.345513000:action 9 queue:Reg/w0: action 9 queue: entry deleted, state 0, size now 0 entries
8082.345525000:action 9 queue:Reg/w0:  10.X.X.X:2514/RELP
8082.345578000:main queue:Reg/w0: main queue: entering rate limiter
8082.345584000:main queue:Reg/w0: main queue: entry deleted, state 0, size now 521 entries
8082.345596000:main queue:Reg/w0: Called action, logging to builtin-file (DynMSG)
8082.345626000:main queue:Reg/w0: Called action, logging to omrelp8082.345631000:main queue:Reg/w0: action 9 queue: entry added, size now 1 entries
8082.345635000:main queue:Reg/w0: action 9 queue: EnqueueMsg signaled condition (0)
wtpAdviseMaxWorkers signals busy
8082.345642000:main queue:Reg/w0: Called action, logging to omrelp8082.345646000:main queue:Reg/w0: action 10 queue: entry added, size now 2 entries
8082.345650000:main queue:Reg/w0: action 10 queue: EnqueueMsg signaled condition (0)
wtpAdviseMaxWorkers signals busy
8082.345657000:action 10 queue:Reg/w0: action 10 queue: entering rate limiter
8082.345662000:action 10 queue:Reg/w0: action 10 queue: entry deleted, state 0, size now 1 entries
8082.345671000:action 10 queue:Reg/w0:  192.X.X.X:2514/RELP
8082.345689000:action 10 queue:Reg/w0: end relpSessConnect, iRet 10014
8082.345697000:action 10 queue:Reg/w0: Action requested to be suspended, done that.
8082.345703000:main queue:Reg/w0: main queue: entering rate limiter
8082.345708000:main queue:Reg/w0: main queue: entry deleted, state 0, size now 520 entries
8082.345713000:main queue:Reg/w0: Called action, logging to builtin-file (DynMSG)
8082.345737000:main queue:Reg/w0: Called action, logging to omrelp8082.345742000:main queue:Reg/w0: action 9 queue: entry added, size now 2 entries
8082.345746000:main queue:Reg/w0: action 9 queue: EnqueueMsg signaled condition (0)
wtpAdviseMaxWorkers signals busy

(...) main queue full, start dropping message (...)

8082.368148000:main queue:Reg/w0: main queue: entry deleted, state 0, size now 222 entries
8082.368152000:main queue:Reg/w0: Called action, logging to builtin-file (DynMSG)
8082.368177000:main queue:Reg/w0: Called action, logging to omrelp8082.368181000:main queue:Reg/w0: action 9 queue: entry added, size now 300 entries
8082.368185000:main queue:Reg/w0: action 9 queue: EnqueueMsg signaled condition (0)
wtpAdviseMaxWorkers signals busy
8082.368191000:main queue:Reg/w0: Called action, logging to omrelp8082.368195000:main queue:Reg/w0: action 10 queue: entry added, size now 300 entries
8082.368199000:main queue:Reg/w0: action 10 queue: EnqueueMsg signaled condition (0)
wtpAdviseMaxWorkers signals busy
8082.368206000:main queue:Reg/w0: main queue: entering rate limiter
8082.368210000:main queue:Reg/w0: main queue: entry deleted, state 0, size now 221 entries
8082.368214000:main queue:Reg/w0: Called action, logging to builtin-file (DynMSG)
8082.368238000:main queue:Reg/w0: Called action, logging to omrelp8082.368242000:main queue:Reg/w0: action 9 queue: enqueueMsg: LightDelay mark reached for light delayble message - blocking a bit.
8082.586621000:imklog.c: main queue: entry added, size now 222 entries
8082.586667000:imklog.c: main queue: EnqueueMsg signaled condition (0)

8082.586712000:imklog.c: wtpAdviseMaxWorkers signals busy
8082.586747000:imklog.c: main queue: entry added, size now 223 entries
8082.586751000:imklog.c: main queue: EnqueueMsg signaled condition (0)
8082.586756000:imklog.c: wtpAdviseMaxWorkers signals busy
8082.586861000:imklog.c: main queue: entry added, size now 224 entries
8082.586866000:imklog.c: main queue: EnqueueMsg signaled condition (0)
8082.586870000:imklog.c: wtpAdviseMaxWorkers signals busy
8082.589092000:imuxsock.c: Message from UNIX socket: #3
8082.589117000:imuxsock.c: logmsg: flags 6, from 'demos', msg Oct  3 14:48:02 sshd[2477]: Server listening on :: port 22.
8082.589124000:imuxsock.c: Message has legacy syslog format.
8082.589137000:imuxsock.c: main queue: entry added, size now 225 entries
8082.589142000:imuxsock.c: main queue: EnqueueMsg signaled condition (0)
8082.589146000:imuxsock.c: wtpAdviseMaxWorkers signals busy
8082.589151000:imuxsock.c: --------imuxsock calling select, active file descriptors (max 3): 3
8082.589165000:imuxsock.c: Message from UNIX socket: #3
8082.589174000:imuxsock.c: logmsg: flags 6, from 'demos', msg Oct  3 14:48:02 sshd[2477]: error: Bind to port 22 on 0.0.0.0 failed: Address already in use.
8082.589179000:imuxsock.c: Message has legacy syslog format.
8082.589187000:imuxsock.c: main queue: entry added, size now 226 entries
8082.589191000:imuxsock.c: main queue: EnqueueMsg signaled condition (0)
8082.589195000:imuxsock.c: wtpAdviseMaxWorkers signals busy
8082.589199000:imuxsock.c: --------imuxsock calling select, active file descriptors (max 3): 3

(...) action queue start lightdelaying, stacking message in main queue(...)

9866.464646000:imuxsock.c: wtpAdviseMaxWorkers signals busy
9866.464650000:imuxsock.c: --------imuxsock calling select, active file descriptors (max 3): 3
9866.465236000:imuxsock.c: Message from UNIX socket: #3
9866.465242000:imuxsock.c: logmsg: flags 6, from 'demos', msg Oct  3 15:17:46 root: 8756
9866.465247000:imuxsock.c: Message has legacy syslog format.
9866.465253000:imuxsock.c: main queue: queue nearly full (9998 entries), but could not drop msg (iRet: 0, severity 5)
9866.465258000:imuxsock.c: main queue: entry added, size now 9999 entries
9866.465262000:imuxsock.c: main queue: EnqueueMsg signaled condition (0)
9866.465266000:imuxsock.c: wtpAdviseMaxWorkers signals busy
9866.465270000:imuxsock.c: --------imuxsock calling select, active file descriptors (max 3): 3
9866.465833000:imuxsock.c: Message from UNIX socket: #3
9866.465841000:imuxsock.c: logmsg: flags 6, from 'demos', msg Oct  3 15:17:46 root: 8757
9866.465845000:imuxsock.c: Message has legacy syslog format.
9866.465852000:imuxsock.c: main queue: queue nearly full (9999 entries), but could not drop msg (iRet: 0, severity 5)
9866.465856000:imuxsock.c: main queue: entry added, size now 10000 entries
9866.465860000:imuxsock.c: main queue: EnqueueMsg signaled condition (0)
9866.465864000:imuxsock.c: wtpAdviseMaxWorkers signals busy
9866.465868000:imuxsock.c: --------imuxsock calling select, active file descriptors (max 3): 3
9866.466572000:imuxsock.c: Message from UNIX socket: #3
9866.466582000:imuxsock.c: logmsg: flags 6, from 'demos', msg Oct  3 15:17:46 root: 8758
9866.466587000:imuxsock.c: Message has legacy syslog format.
9866.466594000:imuxsock.c: main queue: queue nearly full (10000 entries), but could not drop msg (iRet: 0, severity 5)
9866.466599000:imuxsock.c: main queue: enqueueMsg: queue FULL - waiting to drain.
9866.973110000:main queue:Reg/w0: action 9 queue: enqueueMsg: LightDelay mark reached for light delayble message - blocking a bit.
9867.975278000:main queue:Reg/w0: action 9 queue: enqueueMsg: LightDelay mark reached for light delayble message - blocking a bit.
9868.468317000:imuxsock.c: main queue: enqueueMsg: cond timeout, dropping message!
9868.468350000:imuxsock.c: main queue: EnqueueMsg signaled condition (0)
9868.468358000:imuxsock.c: wtpAdviseMaxWorkers signals busy
9868.468364000:imuxsock.c: --------imuxsock calling select, active file descriptors (max 3): 3
9868.468383000:imuxsock.c: Message from UNIX socket: #3
9868.468394000:imuxsock.c: logmsg: flags 6, from 'demos', msg Oct  3 15:17:46 root: 8759
9868.468400000:imuxsock.c: Message has legacy syslog format.

(...) No log + rsyslog hang (...)

0652.554810000:main queue:Reg/w0: action 9 queue: enqueueMsg: LightDelay mark reached for light delayble message - blocking a bit.
0653.556970000:main queue:Reg/w0: action 9 queue: enqueueMsg: LightDelay mark reached for light delayble message - blocking a bit.
0654.558191000:main queue:Reg/w0: action 9 queue: enqueueMsg: LightDelay mark reached for light delayble message - blocking a bit.
0655.560351000:main queue:Reg/w0: action 9 queue: enqueueMsg: LightDelay mark reached for light delayble message - blocking a bit.
0656.562572000:main queue:Reg/w0: action 9 queue: enqueueMsg: LightDelay mark reached for light delayble message - blocking a bit.
DoDie called.
0657.564795000:main queue:Reg/w0: action 9 queue: enqueueMsg: LightDelay mark reached for light delayble message - blocking a bit.
DoDie called.
0658.566206000:main queue:Reg/w0: action 9 queue: enqueueMsg: LightDelay mark reached for light delayble message - blocking a bit.
DoDie called.
0659.568518000:main queue:Reg/w0: action 9 queue: enqueueMsg: LightDelay mark reached for light delayble message - blocking a bit.
DoDie called.
DoDie called.
DoDie called 5 times - unconditional exit
0659.935701000:main thread:



Signal 6 (SIGABRT) occured, execution must be terminated.



0659.935712000:main thread:
0659.935716000:main thread: Recorded Call Order for Thread 'main thread (2ad5c87b3a90)':
0659.935721000:main thread: maximum number of nested calls for this thread: 0.
0659.935725000:main thread: NOTE: not all calls may have been recorded, code does not currently guarantee that!
0659.935729000:main thread:
0659.935733000:main thread: Recorded Call Order for Thread 'action 9 queue:Reg/w0 (421a1940)':
0659.935737000:main thread: maximum number of nested calls for this thread: 0.
0659.935741000:main thread: NOTE: not all calls may have been recorded, code does not currently guarantee that!
0659.935745000:main thread:
0659.935749000:main thread: Recorded Call Order for Thread 'action 10 queue:Reg/w0 (42ba2940)':

(...)



I've noticed that only the first 300 message need to be from imklog to totally block the system (which i hope to be high reliable :p). If i disable sending kernel log via relp :

Code: Select all

*.*,kern.none :omrelp:192.X.X.X:2514;RSYSLOG_SyslogProtocol23Format

I haven't the problem.

Another think i've done is to patch imklog.c to send is message has eFLOWCTL_NO_DELAY and the problem disapear (maybe like the imuxlog flow control bug ?). But i don't know if this is a configuration mistake i've done, if imklog should not sent is message has lightdelayable, or if the mistake is that omrelp should never lightdelayed message has it is an output (disk assisted) plugin.

I vote for first or third proposition, but i debug has i write english so ....

Thanks for your work.


Nicolas

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

Oups, forgot to say client and server are RHEL5 with rsyslog 3.18.4

just a quick note: I am pretty sure that the most recent stable build has removed the ligh delayble flag from imuxsock. However, if you hit the max queue size, there still is a delay. The proper cure is to run RELP off its own queue (and thus asyncrhonously). A sample should be in the default config file.

No problems with imuxlog, the lightdelayed message came from imklog. As far as i understand, omlrep is on his own queue (actionqueue 9 and 10) but "lightdelayed" message coming from main queue (originaly coming from imklog).

I have past the last few day searching for a configuration mistake, but what i do is quite classical (copy/paste of reliable transfert) and work well, except in this "race condition" : more than 300 message coming from imklog + relp server unreachable. But in this condition, all stop working (no local log of the next 1000 messages and then message dropping)

Complete configuration :

Code: Select all

$ModLoad immark.so # provides --MARK-- message capability
$ModLoad imuxsock.so # provides support for local system logging (e.g. via logger command)
$ModLoad imklog.so # kernel logging (formerly provided by rklogd)
$ModLoad omrelp # needs to be done just once

# The authpriv file has restricted access.
$template DynAuth, "/var/log/%HOSTNAME%/%$YEAR%-%$MONTH%-%$DAY%/secure.log"

# Log anything (except mail and cron) of level info or higher.
$template DynMSG, "/var/log/%HOSTNAME%/%$YEAR%-%$MONTH%-%$DAY%/messages"

# Log all the mail messages in one place.
$template Dynmail, "/var/log/%HOSTNAME%/%$YEAR%-%$MONTH%-%$DAY%/maillog"

# Log cron stuff
$template Dyncron,"/var/log/%HOSTNAME%/%$YEAR%-%$MONTH%-%$DAY%/cron"

# Save news errors of level crit and higher in a special file.
$template Dynspool, "/var/log/%HOSTNAME%/%$YEAR%-%$MONTH%-%$DAY%/spooler"

# Save boot messages also to boot.log
$template Dynboot, "/var/log/%HOSTNAME%/%$YEAR%-%$MONTH%-%$DAY%/boot.log"

# Save squid messages
$template SquidAccess, "/var/log/%HOSTNAME%/%$YEAR%-%$MONTH%-%$DAY%/squid_access.log"

# Save dansguardian messages
$template DansAccess, "/var/log/%HOSTNAME%/%$YEAR%-%$MONTH%-%$DAY%/dansguardian.log"

authpriv.* ?DynAuth;RSYSLOG_SyslogProtocol23Format
*.info,mail.none,authpriv.none,cron.none,local2.none,user.none ?DynMSG;RSYSLOG_SyslogProtocol23Format
mail.* -?Dynmail;RSYSLOG_SyslogProtocol23Format
cron.* ?Dyncron;RSYSLOG_SyslogProtocol23Format
uucp,news.crit ?Dynspool;RSYSLOG_SyslogProtocol23Format
local7.* ?Dynboot;RSYSLOG_SyslogProtocol23Format
local2.* ?SquidAccess;RSYSLOG_SyslogProtocol23Format
user.* ?DansAccess;RSYSLOG_SyslogProtocol23Format

## Only log from this host (demos)
+demos

# send to server 1
$WorkDirectory /var/log/rsys_spool
$ActionQueueType LinkedList
$ActionQueueFileName peer
$ActionResumeRetryCount -1
$ActionQueueSaveOnShutdown on
*.* :omrelp:10.X.X.X:2514;RSYSLOG_SyslogProtocol23Format

# Send to server 2
$WorkDirectory /var/log/rsys_spool
$ActionQueueType LinkedList
$ActionQueueFileName uranus
$ActionResumeRetryCount -1
$ActionQueueSaveOnShutdown on
*.* :omrelp:192.X.X.X:2514;RSYSLOG_SyslogProtocol23Format


Hope it's more clear, sorry for my english.


Nicolas