Search Results for: queue

How to use a parser module

A recent occurence initiated this small article. The question was about how to use a specific parser module.

First off, most parser modules, except those that are built-in, are only available in the git repository and the tarball releases. They cannot be used with RPMs and packages.

The specific parser module I want to use now is pmaixforwardedfrom and was contributed by David Lang. The module parses a message from AIX and strips the string “Message forwarded from ” from the message, because else the message cannot be parsed properly. So the original message that looks like this

Jan 25 23:09:48 Message forwarded from hostname: syslog: /usr/sbin/ifconfig -a

looks like this afterwards

Jan 25 23:09:48 hostname syslog: /usr/sbin/ifconfig -a

The problem is, that AIX adds this string by default, but ultimately this corrupts the hostname from the default format. A configuration to tackle the problem will look like this:

module(load=" imuxsock")
module(load="imtcp")
$modload pmaixforwardedfrom

$ruleset stripaix
$rulesetcreatemainqueue on
$rulesetparser rsyslog.aixforwardedfrom
$rulesetparser rsyslog.rfc5424
$rulesetparser rsyslog.rfc3164
*.* /var/log/aixlog

$ruleset RSYSLOG_DefaultRuleset

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

Please note, that we need to mix up config styles in this case. The new RainerScript config style cannot be applied for the entire configuration here.

Basically, we need a ruleset and bind a listener to the ruleset. The listener can be configured with RainerScript. The ruleset needs legacy parameters. In this ruleset, we first configure the additional parser, followed by the default parsers. As a final step, we write everything to a file.

It is strongly suggested to have a specific listener and ruleset for AIX log mesages.

More information about parser modules can be found here:
Doc – Rulesetparser
Doc – Messageparser

Error message when verifying signed logs

rsyslog provides the ability to sign logs through GuardTime. You can verify the logs with a provided tool called rsgtutil. We have identified two reasons why the signing process could fail and thus verifying the log signature is not possible.

Note on legacy API: The old API libgt would create files with the endings .gtsig and .gtstate. These are different from the current and recommended API libksi.

When signing logs with rsyslog and GuardTime, three files will be created.

logfile # holds the log messages
logfile.ksisig # holds the hash chain data
logfile.ksistate # holds GuardTime signature hash

When verifying the logs through rsgtutil, the .ksistate file is needed because it holds the signature hash from GuardTime. Without this file, verification is not possible. Now there are two reasons why this file might not be present and thus a verification fails with:

# ./rsgtutil --verify --show-verified /var/log/logfile
error 1 (i/o error) processing file /var/log/logfile

1. rsyslog is still running

The .ksistate file is created when shutting down rsyslog. At shutdown, a signature request will be sent to GuardTime and will then be returned with the signature hash, which will be stored into this file. If rsyslog is still running, the file will not be created, resulting in an unsuccesful verification.

Even if the .ksistate file is present, it might not be current. So please make sure to stop rsyslog before trying to verify the logs.

2. Timeout on shutdown

On Ubuntu we had the problem, that upstart automatically kills the process after 5 seconds if the SIGTERM signal wasn’t fully executed until then. We now realized, that requesting the signature through GuardTime can take some time, depending on the system, thus exceeding the 5 second timeout and rsyslog getting killed before writing the .ksistate file. Again this resulted in unverifyable logs. This is also a problem for other parts of rsyslog (e.g. DA queues not being completely written to disk).

Upon changing the timeout value in the upstart script for rsyslog, we could circumvent the default timeout and rsyslog could fully complete the signature request and write the .ksistate file. This is at least valid for Ubuntu and may also be valid for other distributions.

To change the timeout go to this file:

/etc/init/rsyslog.conf

Now add

kill timeout 30

right after

expect fork

This should result in the following:

description     “system logging daemon”

start on filesystem
stop on runlevel [06]

expect fork
kill timeout 30
respawn

pre-start script
/lib/init/apparmor-profile-load usr.sbin.rsyslogd
end script

script
. /etc/default/rsyslog
exec rsyslogd $RSYSLOGD_OPTIONS
end script

With the upstart script changed like this, rsyslog should not suffer from a too strict shutdown timeout and thus being able to complete the shutdown successfully. This change will also go in the startup and upstart scripts of the upcoming RPMs and Repo’s.

Side note

In the current versions, rsgtutil gives out a inappropriate error message. It currently states it is an I/O error. In reality it is an EOF error. In the upcoming versions (7.4.8, 7.5.8 and 8.1.4) this will be fixed.

Changelog for 7.4.7 (v7-stable)

Version 7.4.7  [v7.4-stable] 2013-12-10

  • bugfix: limiting queue disk space did not work properly
    •   queue.maxdiskspace actually initializes queue.maxfilesize
    •   total size of queue files was not checked against queue.maxdiskspace for disk assisted queues.

    Thanks to Karol Jurak for the patch.

  • bugfix: linux kernel-like ratelimiter did not work properly with all inputs (for example, it did not work with imdup). The reason was that the PRI value was used, but that needed parsing of the message, which was done too late.
  • bugfix: disk queues created files in wrong working directory if the $WorkDirectory was changed multiple times, all queues only used the last value set.
  • bugfix: legacy directive $ActionQueueWorkerThreads was not honored
  • bugfix: segfault on startup when certain script constructs are used
    e.g. “if not $msg …”
  • bugfix: imuxsock: UseSysTimeStamp config parameter did not work correctly
    Thanks to Tomas Heinrich for alerting us and provinding a solution suggestion.
  • bugfix: $SystemLogUseSysTimeStamp/$SystemLogUsePIDFromSystem did not work
    Thanks to Tomas Heinrich for the patch.
  • improved checking of queue config parameters on startup
  • bugfix: call to ruleset with async queue did not use the queue
    closes: http://bugzilla.adiscon.com/show_bug.cgi?id=443
  • bugfix: if imtcp is loaded and no listeners are configured (which is uncommon), rsyslog crashes during shutdown.

Changelog for 8.1.3 (v8-devel)

Version 8.1.3 [devel] 2013-12-06

THIS VERSION CAN BE CONSIDERED A “NORMAL” DEVEL RELEASE. It’s no longer
highly experimental. This assertion is based on real-world feedback.

  • changes to the strgen module interface
  • new output module interface for transactional modules
  • performance improvements
    • reduced number of malloc/frees due to further changes to the output module interface
    • reduced number of malloc/frees during string template processing
      We now re-use once allocated string template memory for as long as the worker thread exists. This saves us from doing new memory allocs (and their free counterpart) when the next message is processed. The drawback is that the cache always is the size of the so-far largest message processed. This is not considered a problem, as in any case a single messages’ memory footprint should be far lower than that of a whole set of messages (especially on busy servers).
    • used variable qualifiers (const, __restrict__) to hopefully help the compiler generate somewhat faster code
  • failed action detection more precisely for a number of actions
    If an action  uses string parameter passing but is non-transactional it can be executed immediately, giving a quicker indicatio of action failure.
  • bugfix: limiting queue disk space did not work properly
    • queue.maxdiskspace actually initializes queue.maxfilesize
    • total size of queue files was not checked against queue.maxdiskspace for disk assisted queues.

    Thanks to Karol Jurak for the patch.

rsyslog 8.1.2 (v8-devel) released

We have just released 8.1.2 of the v8-devel branch. This is primarily a maintenance release, but offers some improvements. Thanks to Pavel Levshin, mmnormalize now offers higher performance and we have added the ability to link directly to jemalloc. Also, usability of queue settings has been improved by using better (and dynamic) defaults for a range of settings.

ChangeLog:

http://www.rsyslog.com/changelog-for-8-1-2-v8-devel/

Download:

http://www.rsyslog.com/rsyslog-8-1-2-v8-devel/

Feedback is *very much* appreciated.

Best regards,
Florian Riedl

Changelog for 8.1.2 (v8-devel)

Version 8.1.2 [devel] 2013-11-28

  • support for liblognorm1 added – results in performance improvements
    Thanks to Pavel Levshin for his work in this regard.
  • support for jemalloc added via –enable-jemalloc
    Thanks to Pavel Levshin for suggesting jemalloc
  • queue defaults have changed
    •   high water mark is now dynamically 90% of queue size
    •   low water makr is now dynamically 70% of queue size
    •   queue.discardMark is now dynamically 98% of queue size
    •   queue.workerThreadMinimumMessage set to queue.size / num workers

    For queues with very low queue.maxSize (< 100), “emergency” defaults will be used.
    Note that build system is experimental at this stage.

  • bugfix: disk queues created files in wrong working directory
    if the $WorkDirectory was changed multiple times, all queues only used the last value set.
  • bugfix: legacy directive $ActionQueueWorkerThreads was not honored
  • bugfix: mmrfc5424addhmac: “key” parameter was not properly processed

rsyslog 7.5.7 (v7-devel) released

This is primarily a bug-fixing release, but offers some improvements in worker thread handling (thanks to Pavel Levshin!) as well as usability improvements when working changing queue sizes.

More detailed information is available in the changelog.

ChangeLog:

http://www.rsyslog.com/changelog-for-7-5-7-v7-devel/

Download:

http://www.rsyslog.com/rsyslog-7-5-7-v7-devel/

As always, feedback is appreciated.

Best regards,
Tim Eifler

How to use impstats

This summary was contributed by David Caplinger through the mailing list.

First, enable the module with something like:

module(load="impstats" interval="660" severity="7")

This will start generating logs tagged with “rsyslogd-pstats” every 600 seconds. If you like, you can use that tag to filter them into their own file:

if $syslogtag contains 'rsyslogd-pstats' then { 
     action(type="omfile" queue.type="linkedlist" queue.discardmark="980" 
            name="pstats" file="/var/log/pstats") 
     stop 
}

You’ll wind up with several log lines at each interval, all showing current counters (since rsyslog restart). So to determine inter-interval deltas, you’d have to import these into a spreadsheet. (Newer rsyslog can emit just the deltas in the log lines, but that’s in v7.5.x I believe.)

For example, if you want to filter based on some property (such as source IP address) and send the matching logs to both a local file and on to a remote destination, you might use something like:

if $fromhost-ip ==
     [ "1.1.1.1", 
       "2.2.2.2" ] 
then {
     action (type="omfwd" queue.type="linkedlist" queue.discardmark="980" 
             action.resumeretrycount="-1" name="NET.forward" target="10.10.10.10" 
             port="514" protocol="tcp")
     action (type="omfile" queue.type="linkedlist" queue.discardmark="980" 
             name="NET.local" file="/var/log/messages")
     stop
}

Which is a log flow like:

source -> imudp -> main Q -> NET.local (to local files) & NET.forward (to remote)

Here’s an example of a batch of pstats output (re-ordered slightly) from the above config:

Nov 13 14:31:35 loghost rsyslogd-pstats: imudp(*:514): submitted=23035
Nov 13 14:31:35 loghost rsyslogd-pstats: main Q: size=15 enqueued=89624087 full=0 discarded.full=0 discarded.nf=0 maxqsize=444
Nov 13 14:31:35 loghost rsyslogd-pstats: NET.local: size=0 enqueued=11541 full=0 discarded.full=0 discarded.nf=0 maxqsize=7
Nov 13 14:31:35 loghost rsyslogd-pstats: NET.local: processed=11541 failed=0
Nov 13 14:31:35 loghost rsyslogd-pstats: NET.forward: size=0 enqueued=11541 full=0 discarded.full=0 discarded.nf=0 maxqsize=7
Nov 13 14:31:35 loghost rsyslogd-pstats: NET.forward: processed=11541 failed=0
Nov 13 14:31:35 loghost rsyslogd-pstats: pstats: size=0 enqueued=65508 full=0 discarded.full=0 discarded.nf=0 maxqsize=25
Nov 13 14:31:35 loghost rsyslogd-pstats: pstats: processed=65500 failed=0

In this case we have:

1) A UDP input (imudp)

This logs message counts “submitted” to rsyslog via UDP port 514.

2) A main queue (main Q)

This shows messages entering the queue (enqueued), as well as any dropped messages (discarded.full=0, discarded.nf=0). It also shows how many times the queue has become completely full (full=0) and it keeps a running total of the maximum size the queue has ever hit (maxqsize=444). (All these counters are since rsyslog startup.)

3) Two output/action queues (NET.local, NET.forward)

These logs queue stats like above, as well as successfully “processed” (via omfile and omfwd in this case), indicating successful delivery to their final destination (local file or remote TCP receiver, in this case).

4) Another queue to handle pstats output itself (as I described above)

This example doesn’t happen to include DA-mode, which adds another pstats log line for the DA portion of the associated action queue.

If you don’t give your action queues names, you’ll wind up with pstats logs referring to things like “action 2”, and have a hard time figuring out what is going on.

A well-behaved queue will have zero discarded.full and discarded.nf, and a low maxqsize, meaning that everything entering the queue is leaving promptly. In a backlog situation, you’ll see size and maxqsize for an action/output queue increase over time, until maxqsize hits your configured queue.size parameter. Then the main Q will start increasing in size (and maxqsize) until it approaches and exceeds full. Then the discarded.nf and discarded.full counters will start climbing.

action.execOnlyWhenPreviousIsSuspended preciseness

The “action.execOnlyWhenPreviousIsSuspended” parameter permits to conditionally execute an action only if the previous one is suspended. When an action actually gets suspended depends on the output module implementing the action, but the general rule is that an action suspends itself if there is a problem doing it’s job (e.g. a target server is down). This setting is generally used to implement failover destinations. So let’s call actions which have this attribute set “failover actions”.

Note that many action implement transactions to improve performance. If so, usually the success or error state of the action is only available after the transaction has been comitted. At this point, the messages have already been submitted to the action and the action could not set suspension state — simply because at that point everything looked fine. So when the failover action was about to be executed, the suspended flag was not set and the action not executed. Depending on system configuration, this can lead to loss of some messages during the failover process. If this seems totally unacceptable to you, you need to make sure that the transaction is committed after each message — this permits the output to obtain the actual success state (note that with some technologies, even this is not totally possible – a prime example is plain TCP syslog protocol).

To ensure commit of each message, the queue’s maximum batch size needs to be reduced to one. This can be done via the “queue.dequeuebatchsize” parameter. Note that reducing the batch size can have severe performance impact. Unfortunately, it is impossible to to have both high performance and precise failover actions. The simple reason is that for precise failover actions we need to know the result of the commit operation, which makes it necessary to do immediate commits.

Scroll to top