Ok even more details.
The below statements are only true if I change the main message queue
to a disk backed LinkedList queue.
The following config gives me a working setup. I get log entries
spooled to disk and if the destination becomes available everything is
dequeued nicely. BUT the mainqueue is bound to disk now... What
gives?
Here's the config.
$MaxMessageSize 8k
$RepeatedMsgReduction off
# Use traditional timestamp format
$ActionFileDefaultTemplate RSYSLOG_TraditionalFileFormat
# Provides kernel logging support (previously done by rklogd)
$ModLoad imklog
# Provides support for local system logging (e.g. via logger command)
$ModLoad imuxsock
$ModLoad imtcp.so
$InputTCPFlowControl off
#$OMFileAsyncWriting on
$MainMsgQueueFileName mainqueue
$MainMsgQueueType LinkedList
$MainMsgQueueSaveOnShutdown on
$MainMsgQueueSize 100000
$InputTCPMaxSessions 1024
$InputTCPFlowControl off
$InputTCPServerRun 5142
$WorkDirectory /var/spool/rsyslog # where to place spool files
$ActionQueueType LinkedList # run asynchronously
$ActionQueueFileName remotqeque # unique name prefix for spool files
$ActionResumeRetryCount -1 # infinite retries if host is down
$ActionQueueSaveOnShutdown on # save messages to disk on shutdown
$ActionQueueMaxFileSize 100m
$ActionQueueMaxDiskSpace 19g # 1gb space limit (use as much as possible)
$ActionQueueDequeueSlowdown 0
$ActionQueueWorkerThreads 4
*.* @@127.0.0.1:51422
If I watch the debug with something like: tail -f
/tmp/rsyslog-debug.log | awk '/main queue: entry added, size now/ {
print $8 }'
I see that the queue has right around 8000 messages in it. Then if I
look on disk I am getting 100M remotequeue.00000000 files but my
mainqueue.0000000 files fluctuate between 0 and 700K on average I
would say.
Regards,
-Alan
On Thu, Jul 28, 2011 at 6:35 PM, Alan Evans <[email protected]> wrote:
> I've made some progress.
>
> It seems it has to do with the main queue and the action queue and
> their interaction.
>
> If I set the mainqueue to something large, say 20,000 or 100,000
> everything seems to be spooling to disk and the main queue floats at
> about 8000 entries (the default high water mark IIRC). If I set the
> main queue to 10,000 it floats at about 7,000 entries but messages
> seem to be getting dropped.
>
> Does this make any sense to anyone?
>
> -Alan
>
> On Thu, Jul 28, 2011 at 3:28 PM, <[email protected]> wrote:
>> If you are sticking with rsyslog 3.x because that's the only thing supported
>> by redhat, I think that you will need to ask redhat for support. (or buy a
>> support agreement). v3 isn't supported anymore due to it's age and how much
>> ahs changed (they are up to version 6 now)
>>
>> there have been problems in the queuing, even in far more recent versions,
>> so I suspect that that version is just buggy in that area.
>>
>> note that this isn't an official answer (I don't work for adiscon), but
>> supporting such an old version is not easy.
>>
>> David Lang
>>
>>
>>
>> On Thu, 28 Jul 2011, Alan Evans wrote:
>>
>>> Date: Thu, 28 Jul 2011 15:21:10 -0400
>>> From: Alan Evans <[email protected]>
>>> To: [email protected]
>>> Subject: [rsyslog] Rsyslog as intermediate syslog not queueing messages
>>>
>>> I am attempting to configure rsyslog to queue messages while the
>>> destination server is down but I am finding it is only queuing approx
>>> 1 message per second and we receive a whole lot more than that.
>>>
>>> We have many hosts that send messages to a 'proxy' if you will at a
>>> location which then in turn forwards it to our central log server for
>>> archival. We are going to have an outage on the central log server
>>> soon so I am trying to replace syslog-ng with rsyslog so the
>>> intermediates can queue messages while the central server is down.
>>>
>>> I am using 3.22.1 packaged with RHEL 5 which I understand is old but I
>>> will not be able to use a newer version. I have followed the setup at
>>> http://www.rsyslog.com/doc/rsyslog_reliable_forwarding.html but am not
>>> getting the expected results.
>>>
>>> Here's my config.
>>>
>>> # Globals
>>> $MaxMessageSize 8k
>>> $MainMsgQueueType LinkedList
>>>
>>> # Use traditional timestamp format
>>> $ActionFileDefaultTemplate RSYSLOG_TraditionalFileFormat
>>>
>>> # Provides kernel logging support (previously done by rklogd)
>>> $ModLoad imklog
>>> # Provides support for local system logging (e.g. via logger command)
>>> $ModLoad imuxsock
>>> $ModLoad imtcp.so
>>>
>>> $InputTCPMaxSessions 1024
>>> $InputTCPServerRun 5142
>>>
>>> $WorkDirectory /var/spool/rsyslog # where to place spool files
>>> $ActionQueueType LinkedList # run asynchronously
>>> $ActionQueueFileName remotqeque # unique name prefix for spool files
>>> $ActionResumeRetryCount -1 # infinite retries if host is down
>>> $ActionQueueSaveOnShutdown on # save messages to disk on shutdown
>>> $ActionQueueMaxDiskSpace 2g # 1gb space limit (use as much as possible)
>>> $ActionQueueDequeueSlowdown 0
>>> *.* @@redacted:51422
>>>
>>> To get logs to rsyslog I have configured syslog-ng to deliver to both
>>> the central syslog server and to rsyslog on the intermediate. Rsyslog
>>> is sending to redacted:51422 which is not actually listening (since I
>>> don't really want to double my messages to the central server) which
>>> simulates the central server being offline.
>>>
>>> In practice I am seeing in the debug rsyslog process about one log
>>> entry per second which it is sending to my disk assisted queue.
>>> Syslog-ng however is receiving thousands of messages per minute.
>>>
>>> If I get rid of the action queue and just log to a file rsyslog keeps
>>> up with syslog-ng no problem.
>>>
>>> Here's a snippet from the debug log.
>>>
>>> 2402.830836385:main queue:Reg/w0: action 1 queue: enqueueMsg: cond
>>> timeout, dropping message!
>>> 2402.830862669:main queue:Reg/w0: wtpAdviseMaxWorkers signals busy
>>> 2402.830868074:main queue:Reg/w0: action 1 queue: EnqueueMsg advised
>>> worker start
>>> 2402.830879658:main queue:Reg/w0: main queue: entering rate limiter
>>> 2402.830887901:main queue:Reg/w0: main queue: entry deleted, state 0,
>>> size now 7385 entries
>>> 2402.830897655:main queue:Reg/w0: Called action, logging to builtin-fwd
>>> 2402.830903570:main queue:Reg/w0: action 1 queue: enqueueMsg:
>>> LightDelay mark reached for light delayable message - blocking a bit.
>>> 2403.059393630:imuxsock.c: Message from UNIX socket: #6
>>> 2403.059418695:imuxsock.c: logmsg: flags 4, from 'hostnameredacted',
>>> message content redacted
>>> 2403.059424142:imuxsock.c: Message has legacy syslog format.
>>> 2403.059434733:imuxsock.c: main queue: entry added, size now 7386 entries
>>> 2403.059441696:imuxsock.c: wtpAdviseMaxWorkers signals busy
>>> 2403.059446737:imuxsock.c: main queue: EnqueueMsg advised worker start
>>> 2403.059453751:imuxsock.c: --------imuxsock calling select, active
>>> file descriptors (max 6): 6
>>> 2403.087373110:imuxsock.c: Message from UNIX socket: #6
>>> 2403.087416859:imuxsock.c: logmsg: flags 4, from 'hostnameredacted',
>>> message content redacted
>>> 2403.087422226:imuxsock.c: Message has legacy syslog format.
>>> 2403.087432941:imuxsock.c: main queue: entry added, size now 7387 entries
>>> 2403.087439847:imuxsock.c: wtpAdviseMaxWorkers signals busy
>>> 2403.087444749:imuxsock.c: main queue: EnqueueMsg advised worker start
>>> 2403.087451626:imuxsock.c: --------imuxsock calling select, active
>>> file descriptors (max 6): 6
>>> 2403.088771548:imuxsock.c: Message from UNIX socket: #6
>>> 2403.088785375:imuxsock.c: logmsg: flags 4, from 'hostnameredacted',
>>> message content redacted
>>> 2403.088790500:imuxsock.c: Message has legacy syslog format.
>>> 2403.088797998:imuxsock.c: main queue: entry added, size now 7388 entries
>>> 2403.088804299:imuxsock.c: wtpAdviseMaxWorkers signals busy
>>> 2403.088809079:imuxsock.c: main queue: EnqueueMsg advised worker start
>>> 2403.088826047:imuxsock.c: --------imuxsock calling select, active
>>> file descriptors (max 6): 6
>>> 2403.113614170:imuxsock.c: Message from UNIX socket: #6
>>> 2403.113659621:imuxsock.c: logmsg: flags 4, from 'hostnameredacted',
>>> message content redacted
>>> 2403.113675071:imuxsock.c: main queue: entry added, size now 7389 entries
>>> 2403.113681913:imuxsock.c: wtpAdviseMaxWorkers signals busy
>>> 2403.113687091:imuxsock.c: main queue: EnqueueMsg advised worker start
>>> 2403.113693974:imuxsock.c: --------imuxsock calling select, active
>>> file descriptors (max 6): 6
>>> 2403.709635421:imtcp.c: main queue: entry added, size now 7390 entries
>>> 2403.709660157:imtcp.c: wtpAdviseMaxWorkers signals busy
>>> 2403.709665565:imtcp.c: main queue: EnqueueMsg advised worker start
>>> 2403.709683772:imtcp.c: logmsg: flags 0, from 'hostnameredacted',
>>> message content redacted
>>> 2403.709688841:imtcp.c: Message has legacy syslog format.
>>> 2403.709697186:imtcp.c: main queue: enqueueMsg: LightDelay mark
>>> reached for light delayable message - blocking a bit.
>>> 2403.832590271:main queue:Reg/w0: action 1 queue: enqueueMsg: queue
>>> FULL - waiting to drain.
>>> 2404.712385305:imtcp.c: main queue: entry added, size now 7391 entries
>>> 2404.712414709:imtcp.c: wtpAdviseMaxWorkers signals busy
>>>
>>> Lines containing "cond timeout, dropping message!" and "queue FULL -
>>> waiting to drain." have me concerned. But it doesn't look like all of
>>> my logs are making it to the main queue anyway. Is imtcp dropping
>>> messages and the debug level is not high enough to see it maybe?
>>>
>>> Please help! How do I get rsyslog to queue all the messages bound for
>>> the simulated down central log host?
>>>
>>> Regards,
>>> -Alan
>>> _______________________________________________
>>> rsyslog mailing list
>>> http://lists.adiscon.net/mailman/listinfo/rsyslog
>>> http://www.rsyslog.com
>>>
>>
>
_______________________________________________
rsyslog mailing list
http://lists.adiscon.net/mailman/listinfo/rsyslog
http://www.rsyslog.com
