Friday, December 14, 2012

On backporting patches

Every now and then, I get (polite) requests to backport some patch to older versions. First of all, let me say that I usually patch things in the oldest affected (and supported) version and then "upport" these to the newer releases. So in those cases, everything is already covered (it pays to look into the ChangeLog file in the project root directory). However, "supported" is a keyword. I usually do not backport patches to older, unsupported versions (except if there exists good reasons and the version is in widespread use).

Let me elaborate a bit why I don't do that: backporting all patches to the many (unsupported) versions of rsyslog we have is a very time-consuming task (even though it may be rather simple, as probably in this case). So the more I backport, the less new stuff I get done. I went through this last year and it resulted in a *very considerable* productivity reduction. I am glad I got rid of all that in the later half of 2012, and so I am hesitant to go back to that business again. Just for the records: we of course support *all* versions for support contract customers, but then it is of benefit to the project because it provides funding.  Whereas it probably is even counter-productive in other cases: the more I backport, the less the interest in moving to new releases and so we stay with all that outdated stuff.   Also, if it is very simple for package maintainers to stick to outdated stuff, they probably have few incentive to move to new ones (to the disadvantage of many users). So if they want to stick with the old stuff, let them *they* pay the price for that and not *the project* ;) There are exceptions of course, and the maintainers I work with know that very well ;)

Wednesday, October 31, 2012

rsyslog disk queues: refactor or redesign? - part I

I am currently thinking about the design of rsyslog's disk queues. There are some things that I really like about them, but there are also lots of things I dislike. This blog post is meant to save as a basis for discussing whether the disk queue system should better be refactored or completely redesigned. The actual discussion should please be kept on the mailing list. I just blogged because this makes it easier to have a stable reference on where that whole thing started. This is the first in a series of ? blog posts. It describes the current state as of now (rsyslog 7.3.1 and below).

First of all, it must be noted that both serious refactoring as well as redesign are rathter costly. So I don't know when I can actually do that - it probably depends on the fact if there are some sponsors at least for parts of the work available. With that said, let's get down to technology:

The disk queue system is designed to be used primarily in exceptions (like remote destination being down for a longer period of time) or for high-reliability environments. A main design goal was that they should not take too much disk space, at least not more than necessary at any point in time. Also, human operators should be able to fix things (or at least understand them), when things go really wild.

To solve these needs, queue data is stored in pure US-ASCII text form, without any kind of compression or binary storage. The encoding used is rather simple it's basically name, type and value of any property, one per line (the details can be found in the relevant source files). The "not too much space" requirement is solved by using a set of rotating sequential files, where each file has a configured maximum size (10MB by default) [to be technically precise, the maximum is not totally enforced, a complete message is persisted to the file, even if that goes slightly above the maximum]. There is a kind of head and tail pointer into that rotating file set: the head is used by new messages coming in. They are always appended to the most recent file. The tail pointer is where messages are dequeued from, it alwass points to the oldest file inside the file set. Originally, there were just these two pointers, and a file was deleted as soon as the tail pointer moved past the end of the current file. However, this was modified to cover the ultra-reliable use case in v5: The problem with two pointers was that when messages were dequeued at the end of the tail file, that file was immediately deleted. When now something went wrong, the potentially unprocessed messages were lost. To prevent this, v5+ has actually three pointers: the head pointer (as before) a read pointer (former tail) and a delete pointer (kind of "real tail"). The read pointer is now used to dequeue the messages, and the delete pointer is used to re-read messages from the file after they have been processed and delete queue files, if they go out of the current file set while doing so (this actually is exactly the processin that the former tail pointer did). The bottom line is that each message is written once but read twice during queue processing.  The queue also maintains a state (or "queue info" - .qi) file, which among others contains these pointers. The user can configure how often data shall be synced to disk. The more often, the more robust the queue is, but it also gets slower as part of that process. To flush, both the current write needs to be flushed as well as the state file. For the state file, this currently means it is opened, written and closed again. At the extreme, this happens for each record being written (but keep in mind that the queue file itself is always kept open). It is also worth mentioning that all records are of variable size, so there is no random access possible to messages that reside inside the queue file.

From the threading point of view, queue operations are naturally serial (as sequential files are involved). As such, a queue usues exactly one worker, no matter how many worker threads the user has configured. In case of a disk assisted (DA) queue, there are as many workers as configured for the in-memory part of the queue and one worker for the disk part of the queue. Note that all of these workers run in parallel. That also means that message sequence will change if disk and in-memory mode run at the same time But this comes at no surprise: for obvious reasons, this is always the case when multiple workers process queue messages in parallel (otherwise, the parallel workers would need to serialize the, effectively running a single worker thread...). To keep the code simple later versions of rsyslg (late v5+) keep the disk queue open once it has been started. First of all, this removes some complex synchronization issues inside the rsyslog core, which would otherwise not only complicate the code but slow things down, even when no disk queue is active. Secondly, there is a good chance that disk mode is needed again if it was initiated once, so it probably is even very smart to make this as painless as possible. Note that during rsyslog shutdown, the disk queue files are of course fully be deleted.

Tuesday, October 30, 2012

rate-limiting in rsyslog 7.3.2

In 7.3.2, to be released today, I  reworked ratelimiting and "last message repeated n times" handling -  all over rsyslog code. Each of the supported inputs now supports  linux-like ratelimiting (formerly only imuxsock did). Also, the "last message repeated n times" is now processed at the input side  and no longer at the output side of rsyslog processing. This  provides the basis for new future additons as well as usually more performance and a much simpler output part, which can be even further refactored. I kept away from refactoring that part of the code as I think the change was already large enough and I'd like to get some practical feedback on that version first.

Of course, the input side now has become a bit more complex, but this offers great new abilities. Most importantly, the "last message repeated n times" is finally a bit useful at all, because the repeat message detection now happens on a per-input basis. Previously, messages from different inputs were mixed and as such repeat messages from a single input could not reliably be detected and prevented. That was a design limitation stemming back from the original handling. It finally was time to remove that limitation.

Please note that we now also support linux-type ratelimiting, usually via the two parameters "ratelimit.burst" and "ratelimit.interval". The "ratelimit.burst" specifies how many messages can be emitted at most in the period specified by "ratelimit.interval" (in seconds). Any excess messages are discarded (the idea of just delaying them is floating around, but this is not yet implemented - but fairly easy to do...). At the end of the interval, the whole processing is restarted. This mode is MUCH faster than "last message repeated n times" but of course does not just reduce similiar messages.

A concrete example for imudp looks like this:

input(type="imudp" port="514"
      ratelimit.burst="5000" ratelimit.interval="2")

This allows at most 5,000 messages within 2 seconds.

Sunday, October 28, 2012

how to use rsyslog's ruleset and call statements

Rsyslog 7.2+ introduced a couple of cool config enhancements, among them a new way to specify rulesets and to call into a ruleset (a much better replacement for omruleset). Unfortunatley, the doc is currently extremely sparse. That will change soon, but in the mean time I thought I provide at least some clues here via the blog.

In essence, the ruleset statement permits to specify a ruleset. It's written as

ruleset(name="rulesetname") { statements here }

Rulesets can be bound to inputs, as usual, and any ruleset can call into another ruleset via the call statement:

call rulesetname

Note that in call, the rulesetname is just plainly specified. We created it that way as we thought this looks most intuitively to people used to any kind of scripting or programming language.

A somewhat larger sample (bascially taken from the rsyslog mailing list, thanks to Brian Knox) is:


module(load="imptcp" keepalive="on")
# use imptcp just as example for bind ruleset below
ruleset(name="rs1") {

        *.* /var/log/test1.log
}
ruleset(name="rs2") {
        *.* /var/log/test2.log
        call rs1
}
input(type="imptcp" port="13514" ruleset="rs2")

All statements NOT specified inside a ruleset become part of the default ruleset. Legacy-style $Ruleset statements are still supported, but cannot be used inside a ruleset() statement (that would create a big mess and is totally unnecessary).

Monday, October 22, 2012

new v7/v6 stable, v5 now legacy

Today is a very important day for me - and rsyslog. After a very intense work period, the first v7 version is finally ready for the "stable" label. It contains a lot of new and important functionality. IMHO v7 is the most important release since the introduction of v4, and the next 7.3+ versions will bring even more very important enhancements. We ironed out quite some bugs during the beta phase. Interestingly, some of the bug fixes stem back to as far as v5.10, which recently received quite some attention.

As v7-beta is based on v6-beta, we can also release a new v6-stable, because v6 is a proper subset and all relevant patches have been applied to v6 as well. So they receive kind of "transitive readiness" via v7. It is important to note that we developed concepts in v6, but usually published only the merged-up version in v7 (in order to save development effort). As such, the release count for v6 (6.5.1) doesn't look like it is a version ready for the "stable" label, but in fact the release count is artificially low due to the way we worked on the v6/v7 tandem.

Let me stress again that you usually want to go for v7 to see the latest and greatest in logging. Version 6 is basically a v5 engine, somewhat performance enhanced and with experimental support for structured logging/lumberjack logging. If you want to use structured logging in production, v7 is highly recommended. For example v6 does NOT support disk-queues in combination with structured logging, whereas v7 of course does.

With all these good news, v5 is now legacy and will no longer be officially supported by the project. Full support of course is still available as part of Adiscon's rsyslog support packages. In regard to its wide use in distributions, we will still collaborate with the distro maintainers to solve problematic bugs (as we always did in the past for officially non-supported versions). However, this still means we need to care much less about v5, and that in turn means we can free many development ressources tied to maintaining old stuff and merging all those changes to newer versions. This has been very time-consuming in the past and I am very relieved that we currently have a plain v6 stable, v7 stable and an active development branch taking place in v7, only. I hope this will remain the case (except for some occasional v7-betas) at least for the next couple of month. It would definitely boost my productivity.

Todays releases are the culmination of a group effort. I would like to express special thanks to Miloslav Trma─Ź, Milan Bartos, David Lang and Michael Biebl for their good suggestions, motivation and code contributions. I also thank the many other contributors (just have a look at the ChangeLog or git history!). The project would have been unable to reach this important milestone without all your contributions, including the well-done bug reports! Thanks a lot, folks!

With that said, I hope everyone enjoys the new stable versions. Also, look forward to an exciting future, which already has begun with the 7.3 series, which contains some good performance improvements. We continue to work on many cool new features!

Wednesday, October 17, 2012

new "stable" policy for rsyslog?

For many years, I have strongly opted for the devel-beta-release cycle for rsyslog, where a transition from beta to release only happens after two to three month in order to be sure that a stable version really was stable. This worked well, because early adopters of the beta branches helped to iron out any remaining bugs. Unfortunately, I see this the early adoption rate decline for around two years now (actually starting with v5). The reason is probably obvious: rsyslog has become so feature-rich that users usually do not see any need to work with the beta versions but rather wait for stable. The bottom line is that when everybody waits for stable, the beta won't stabilize at all ;-).

Unfortunately, I have seen this, too, happen in practice: even though we had very lengthy beta periods, problem reports just came in after the beta has been declared to be stable. At that time, many folks seem to start using the system, and as nobody did any testing before, things then begin to break. I guess there is noone to blame, that's just how things work. However, one needs to know that I invest quite some time into the devel-beta-stable cycle. Time, that is most probably better spent at other things, if looked at in the light of what I just described.

As such, I will most probably change our "stable" policy for rsyslog soon: the tag "stable" will no longer mean that the product has actually stabilized, but that we are ready to support it as a stable version (probably very important to those folks with support contracts). While this may sound harsh, it has a lot of good: first of all, this is what actually happens for 2+ years already, just with a 3-month delay. So we spare these months, what means new features will become more readily available, and bugs are probably quicker found AND fixed (because if a bug reports is closer to implementation, it is usually easier to figure out what is wrong). With that said, rsyslog 7.2 will probably the last stable that went through the usual cycle.

If you have a great idea how we can actually get more beta deployments, I'll reconsider that decision.

Note that we will still have devel-beta-stable branches, but beta will much quicker turn into stable than before.

Wednesday, October 10, 2012

Main Advantages of rsyslog v7 vs. v5

A lot of work has been done since the days of rsyslog v5. In this  post, I will provide the top 5 advantages of the v7 engine over the previous version. Please note that I do not talk about v6, as it is very close to the v5 engine, just with the improved config language. V6 also provides some experimental support for structured logging (project lumberjack), which has been fully matured in v7 (I strongly recommend to use v7 if you are serious about structured logging).

So, here are the main points:
  • greatly improved configuration language - the new language is much more intuitive than the legacy format. It will also prevent some typical mistakes simply be not permitting these invalid constructs. Note that legacy format is still fully supported (and you can of course do the same mistakes as before if you use legacy format).
  • greatly improved execution engine - with nested if/then/else constructs as well as the capability to modify variables during processing.
  • full support for structured logging and project lumberjack / CEE - this includes everything from being able to create, interpret and handle JSON-based structured log messages, including the ability to normalize legacy text log messages.
  • more plugins - like support for MongoDB, HDFS, and ElasticSearch as well as for the kernel's new structured logging system.
  • higher performance - many optimizations all over the code, like 5 to 10 times faster execution time for script-based filters, enhanced multithreaded TCP input plugin, DNS cache and many more.
Of course, there are many more improvements. This list contains just the most important ones. For full details, check the file ChangeLog.

Friday, September 28, 2012

rsyslog string array comparisons

In order to aid some string comparisons, I have just introduced constant string arrays in rsyslog. Look at this construct:

if $msg contains ["event12", "event15","event19"] then
    /home/rgerhards/logfile

This will match if $msg contains any of the three strings given inside the array, so it works like an implicit "or". I have seen this in a couple of customer configs and I am confident that this will ease rsyslog configuration. In later releases, it will also provide room for performance optimizations.

This feature will be part of 7.1.7.

[edit] Starting with rsyslog 7.3.6, string array comparisons are notably faster, especially if the array is large. At most, there are log(n) comparisons required (where n is the array size).

rsyslog's new input() statement: a quick look

I have just completed the new input() config statement. This concludes the major part of the new config format for v6 (v7 will also support an enhanced ruleset() statement). I wanted to give you some quick ideas of how the new format looks in practice. So I have created a small test rsyslog.conf with the old-style directives commented out and followed by the new style ones. I guess it is pretty self-explanatory. Here it is:

#$ModLoad imfile
#$inputfilepollinterval 1
module(load="imfile" pollingInterval="1")

#input(type="imuxsock" )
module(load="imuxsock" syssock.use="off")
input(type="imuxsock" socket="/home/rgerhards/testsock")

$ModLoad imfile
module(load="imfile")
#$InputFileName /tmp/inputfile
#$InputFileTag tag1:
#$InputFileStateFile inputfile-state
#$InputRunFileMonitor
input(type="imfile" file="/tmp/inputfile" tag="tag1:" statefile="inputfile-state")

module(load="imptcp")
#$InputPTCPServerRun 13514
input(type="imptcp" port="13514")

module(load="imtcp" keepalive="on")
#$InputTCPServerSupportOctetCountedFraming off
#$InputTCPServerInputName tcpname
#$InputTCPServerRun 13515
input(type="imtcp" port="13515" name="tcpname" supportOctetCountedFraming="off")

#$UDPServerRun 13514
#$UDPServerRun 13515
input(type="imudp" port="13514")
input(type="imudp" port="13515")

Monday, September 24, 2012

rsyslog plugin for structured Linux kernel logs

Thanks to Milan Bartos, there now is imkmsg, which supports structured kernel logging. This module will become available as part of rsyslog 7.1.5 later this week. The module was created with the help of Red Hat as part of the lumberjack effort for a better and structured logging infrastructure.

Note that the rsyslog v7 engine supports numerous enhancements for simple processing of lumberjack strucutred logs. So imkmsg is a natural fit for that version. As Milan told me, there is still room for improvement inside the module and some nits may exist and be fixed within the next weeks. However, we would appreciate feedback from early adoptors.

Monday, September 17, 2012

setting variables in rsyslog v7

Starting with rsyslog 7.1.3, variables can be manipulated inside rsyslog.conf. Note that the native message properties (like $msg) cannot be modified, but the CEE/lumberjack-type properties (those $!name variables) can. As variable modification is primarily an aid for template generation and modification, we do not consider this a restriction, as native message properties can simply be copied to the CEE tree if this is needed.

Note that CEE/lumberjack properties, as implemented in rsyslog,  can be hierarchical and levels are delimited by the bang sign (based on lumberjack recommendations). So "!uid" is the uid field in the CEE root, whereas "!usr!uid" is the uid field inside the usr container. Nesting can be as deep as desired. Currently, all parts of the CEE tree can be accessed. In later versions, this may require the setting of a global option. If that will happen depends on the feedback we receive.

So: how does it work?

To set a variable, simply use
set varname = expression;
Where expression can be an arbitrary complex expression, just like in an "if" statement. Note the semicolon at the end: this is unfortunately necessary and a diversion from the other config statements. However, this is the price we need to pay to remain upward compatible with the old style config format.

Concrete examples:

set $!usr!level2!var1 = "test"; 
set $!usr!level2!var1 = $msg; # update variable with native MSG field
set $!usr!level2!var2 = 1+1; # set !usr!level2!var2 = 2
set $!usr!level2 = $fromhost; # invalid

The last example is invalid and will not be executed because it tries to replace a complete container (!usr!level2) with a single value. This is rejected and not executed. Note that this problem is not detected during config read time but rather during execution time (in less trivial samples, it can not be reliable detected without execution).

Note that string concatenation is currently NOT supported, but it will be soon in the next releases. Also, full JSON containers cannot yet be copied. If this is tried to, the resulting variable will receive a string representation, which most probably is not what you wanted (and you will get a different result in future versions).

There is also an accompanying "unset" statement to remove a variable that is no longer needed. This is primarily meant to restructure a CEE container. It's syntax simply is:

unset varname;

Again, note the semicolon at the end. A concrete example is

unset !usr!level2!var1;

which removes a single element. But full containers can also be removed:

unset !usr!level2;

Note that all variables are assigned to the message currently being processed. There currently is no way to set global variables (but this may become available based on feedback I see).

Tuesday, September 11, 2012

BSD-Style blocks will go away in rsyslog v7

Rsyslog supports BSD-style blocks since ages. They were a pretty handy tool to group actions together that should act only on remote hosts or log messages from specific programs. However, the v7 config system with its full nesting capabilities provides a much better - and easy to use - way to specify this. If both systems are mixed, the problem is that BSD-style blocks can be used to violate the nesting structure (examples below). Also, support for them adds a lot to rule engine code complexity. And finally, they are also very seldom used, few users even know they exist.

As a result, I have decided to drop support for BSD-style blocks in rsyslog v7 and above. A poll on the mailing list a week ago did not make anybody speak up against that change. So I assume none is hurt. This is especially the case as the conversion of BSD-style blocks to nested config is a very easy one.

Let's look at this example:


!prog1
*.* /var/log/prog1.log
*.* /var/log/prog1again.log
!prog2
*.* /var/log/prog2.log
*.* /var/log/prog2again.log

This code can very simply be replaced by:
 if $programname == 'prog1' then {
   /var/log/prog1.log
    /var/log/prog1again.log
}
if $programname == 'prog2' then {
   /var/log/prog2.log
   /var/log/prog2again.log
}

And if you prefer the more powerful action statments (probably not so much benefit for this use case...), you can write:
 if $programname == 'prog1' then {
   action(type="omfile" file="/var/log/prog1.log")
    action(type="omfile" file="/var/log/prog1again.log")
}
if $programname == 'prog2' then {
   action(type="omfile" file="/var/log/prog2.log")
   action(type="omfile" file="/var/log/prog2again.log")
}
I expect that usually these easy cases happen. HOWEVER, if I had kept support for BSD-style blocks, one could configure things like this:
!prog1
if $msg contains 'test' then  {
                action(type="omfile" file="/var/log/somefile")
                !prog2
                mail.* :mmjsonparse: 
                               & action(type="omfile" file="/var/log/somefile2") 
               !prog3

                               & ~
                !prog4 
                if $msg contains 'test2' then
                               /var/log/logfile
                else
                               /var/log/logfile2
}

Can you make out the actual nesting structure of this config? When, for example, programname needs to be "prog3" and what happens then? IMHO this combination can cause considerable user confusion and frustration. As such, I made a sharp cut and removed it.

My apologies for those that need to do the manual conversion. I am sure the time is well-invested in the long term.

Monday, July 30, 2012

creating an error log file for elasticsearch data errors

With the work I have just completed in the beta-jsonrt branch of rsyslog, omelasticsearch now supports logging records with data errors to a local log file. This, for example, handles cases where the data type does not match an expected case. These type of errors are not recoverable, so omelasticsearch does not busy the rsyslog core with handling them - especially as it knows precisely which records caused the error. Instead, as of now (will be "officially" available as part of  7.3.2) the user can configure a local error log file, where all requests with errors are written to. That file will receive information about the request and elasticsearch reply. Log records are formatted in JSON and as such are easy to handle. Note that the request will be reported as the post data, a string, NOT a full JSON representation. This is done for two reasons: first of all, the post data for a bulk mode request (as defined by ES) is NOT proper JSON, so we would need to mangle with that data - something we don't like, as it may hide the real request problem (better use "the real thing"). Secondly (and closely related), there may actually be errors in that string, so that we may not even be able to parse it. As such, it makes a lot more sense to supply the actual string. The reply part is JSON representation as we received it from ES (we assume that it could be parsed - else something would be awfully wrong). Note that in bulk mode, the error record may also contain records that have been processed correctly (ES status OK). Again, we include them so that the whole request/reply process can be evaluated. If data needs to be re-processed, users scripts must ignore such OK status records.

The core idea behind that representation is that it should be as simple as possible to create a custom cleanup script capable of processing the error information - while still providing full feedback on the error cause.

Once the error file is opened, it is never closed until rsyslog is terminated OR a HUP is sent. So proper processing of the error file in a custom script is to first rename the file and then send SIGHUP to rsyslog. This will cause it to release the file and re-open it *when needed*. Note that the file is only created if actually errors occurred. Among others, this is done so that the presence of this file can be used as simple trigger to decide if error handling must be started or not (should be easy to integrate with custom monitoring solutions).

The error file functionality is activated by specifying the "errorfile" action parameter. If it is not given, errors are simply ignored (as there is nothing we can do to handle them in any case).

A quick sample on how this can be done is here:

*.*     action(type="omelasticsearch"
           searchIndex="testindex"
           searchType="mytype" bulkmode="on"
           errorFile="/var/log/rsyslog/ES-error.log")

Error file contents will look like this:
{
    "request":    {
        "url":    "http://localhost:9200/_bulk?replication=async&timeout=1m&",
        "postdata":    "{\"index\":{\"_index\": \"testindex\",\"_type\":\"mytype\"}}\n{\"message\":\" test 1\",\"fromhost\":\"hostname\",\"facility\":\"kern\",\"priority\":\"notice\",\"timereported\":\"2012-07-30T12:38:38.737354+02:00\",\"timegenerated\":\"2012-07-30T12:38:38.737354+02:00\"}\n"
    },
    "reply":    {
        "took":    2,
        "items":    [{
                "create":    {
                    "_index":    "testindex",
                    "_type":    "mytype",
                    "_id":    "g8XJzt-TRd6WOu3pRyzrcg",
                    "error":    "MapperParsingException[Failed to parse [timegenerated]]; nested: NumberFormatException[For input string: \"2012-07-30T12:38:38.737354+02:00\"]; "
                }
            }]
    }
}

Thursday, July 05, 2012

rsyslog action queue

In pre-v6, action queues are quite hard to understand, because the syntax is very counter-intuitive. Based on a recent conversation, I thought I share a little bit of advise on how queues work.

Each action has a dedicated queue. This queue can be in-memory, it can be on disk and it can be a combination of both. There is also direct mode, which means by design there is a queue but the actual driver does forward messages to the action without action queueing.

When you define actions, the queue parameters belong to the next action (in v6 this is far easier to understand and see as the queue params are specified within the action). In the snippet below, we have two actions, and each of them is configured with different queue settings. This results with two different sets of queue files being written. It is important that the queue file names are different (as they are), but otherwise the queues are independent. There can be as many disk (or DA) queues as there are actions. Note that if there is only a single action queue and n actions, this means only one action uses the disk queue, whereas n-1 actions do not use it (if nothing else is set, they run in direct mode).

$ActionQueueType LinkedList # use asynchronous processing
$ActionQueueFileName nfsq    # set file name, also enables disk mode
*.* /var/log/log1

$ActionQueueType LinkedList # use asynchronous processing
$ActionQueueFileName diskq    # set file name, also enables disk mode
*.* /var/log/log2

*.* /var/log/log3 # DIRECT mode here!!!!


In v6, queue parameters are set directly within the action:

*.* action(type="omfile" 
       queue.filename="nfsq" queue.type="linkedlist"
       file="/var/log/log1")
 
*.* action(type="omfile" 
       queue.filename="diskq" queue.type="linkedlist"
       file="/var/log/log2")

*.* action(type="omfile" file="/var/log/log3")
 

The v6 format hopefully make more clear what belongs together.

Wednesday, June 13, 2012

how to use mmjsonparse only for select messages

Rsyslog's mmjsonparse module permits to parse JSON base data (actually expecting CEE-format). This message modification module is implemented via the output plugin interface, which provides some nice flexibility in using it. Most importantly, you can trigger parsing only for a select set of messages.

Note that the module checks for the presence of the cee cookie. Only if it is present, json parsing will happen. Otherwise, the message is left alone. As the cee cookie was specifically designed to signify the presence of JSON data, this is a sufficient check to make sure only valid data is processed.

However, you may want to avoid the (small) checking overhead for non-json messages (note, however, that the check is *really fast*, so using a filter just to spare it does not gain you too much). Another reason for using only a select set might be that you have different types of cee-based messages but want to parse (and specifically process just some of them).

With mmjsonparse being implemented via the output module interface, it can be used like a regular action. So you could for example do this:


if ($programname == 'rsyslogd-pstats') then {
      action(type="mmjsonparse")
      action(type="omfwd" target="target.example.net" template="..." ...)
}

As with any regular action, mmjsonparse will only be called when the filter evaluates to true. Note, however, that the modification mmjsonparse makes (most importantly creating the structured data) will be kept after the closing if-block. So any other action below that if (in the config file) will also be able to see it.

Using ElasticSearch Bulk Mode with rsyslog

Rsyslog's omelasticsearch plugin now supports bulk mode. With bulk mode, message processing is much faster, especially if large loads are to be processed.

Bulk mode works with rsyslog's batching capabilities. So it probably is a good idea to refresh some of the batching concepts. The core idea is that while we would like to process many messages at once, we do NOT want to wait hold processing messages "just" because they are too few. So with batching, you set an upper limit on the batch size (number of messages inside a batch). Let's say the batch size is set to 32. When a new batch is to be processed, the queue worker tries to pull 32 messages off the queue. If there are 32 or more present, this is nice and all 32 are taken from the queue. But now let's assume there are only 10 messages at all present inside the queue. In that case, the queue worker does not try to guess when the next 22 messages will arrive and wait for that (if the time is short enough). Instead, it just pulls the 10 already-present messages off the queue and these form the batch. When new messages arrive, they will be part of the next batch.

Now let's look at the startup of a busy system. Lot's of messages come in. Let's assume they are submitted one-by-one (many sources submit multiple messages, but let's focus on those cases that do not). If so, the first message is submitted and the queue worker is activated. Assuming this happens immediately and before any other message is submitted (actually unlikely!), it will initially create a batch of exactly one message and process that. In the mean time, more messages arrive and the queue fills. So when the first batch is completed, there are ample messages inside the queue. As such, the queue worker will pull the next set of 32 messages off the queue and form a new batch out of them. This continues as long as there are sufficient messages. Note that in practice the first batch will usually be larger than one and often be the max batch size, thanks to various inner workings I would not like to elaborate on in detail in this article. Large batch sizes with more than 1024 messages are not bad at all and may even help improve performance. When looking at a system performing with such large batches, you will likely see that partial batches are being created, simply for the reason that the queue does not contain more messages. This is not an indicator for a problem but shows that everything works perfectly!


The max batch size can be configured via

$ActionQueueDequeueBatchSize
and
$MainMsgQueueDequeueBatchSize

Note that the default sizes are very conservative (read: low), so you probably want to adjust them to some higher value. The best value depends on your workload, but 256 is probably a good starting point. If the action queue runs asynchronously (e.g. linkedlist mode, everything non-direct), the action queue batch size specifies the upper limit for the elasticsearch bulk submission.

To activate bulk mode, use

*.*     action(type="omelasticsearch"
           ... other params ...
           bulkmode="on")

The default is the more conservative "off". Note that the action can of course be used with any type of filter, not just the catch-all "*.*". This is only used as a sample.

Monday, May 14, 2012

omudpspoof, threads, and libnet..

I today ran into a problem with omudpspoof (rsyslog's UDP spoofing output module) that only occured when multiple output threads were used. If that perquisite was given and a larger traffic volume was generated, rsyslog relatively quickly aborted - often even during startup, otherwise very quickly thereafter. Diging down to the potential troublespot, it turned out that libnet is not threadsafe (and I have to admit they do not explicitely claim that). That was a very quick hint, and I now protect libnet calls via a mutex, ensuring that only one thread at a time will ever call into libnet. Of course, this somewhat limits concurrency, but for obvious reasons stability is far more important. There was also recently some discussion on different-kind problems with omudpspoof. While I do not think that this was releated to multithreading (data was malformed, what I could not reproduce), I can not totally outrule that. Will try to follow up with that on the mailing list as well.

The problem probably took quite some while to surface, as people usually have a single UDP spoofing action AND do not run it on multiple threads (given the i/o-boundness of this action, you probably can not gain much be using more than the standard single instance thread).

If you are interested in patching older versions, the patch is available via git (use the raw link to obtain a file usuable with patch). New releases are due soon.

Friday, April 20, 2012

RFC5424 or cee-enhanced syslog?

I  recently got a question if it would be better to implement RFC5424 or cee-enhanced syslog in a new project. This sounds like a though question, but looking at the details helps to ease it a bit.

First of all, RFC5424 has a far broader scope than cee-enhanced syslog. RFC5424 is the base RFC of a new series of syslog RFCs that solve many problems, among them (this list for sure will not be complete):

  • finally a standardized syslog format (no standard exists before, just a weak understanding)
  • supports multiple transports, e.g. UDP and TLS (all in their own RFCs)
  • solves some long-standing nits, like the date format (RFC5424 supports high precision and demands a year as part of the timestamp)
  • increases the syslog message size and permits operators to set an (almost) arbitrary upper limit for message sizes
  • supports structured logging via so-called "structured data"
In contrast, cee-enhanced syslog only cares about the structured logging feature - none of the others is addressed with it. This is the case because its intent is different: the goal here is to have a format that can work with existing technology and still provide the best possible structured logging solution. Depending on circumstances, "best possible" can be quite different. For example, in a scenario where it needs to work with crufty old syslogds, it can mean that message content can not be longer than 1k, a serious restriction. Even more, it is envisioned that cee-enhanced syslog will also work over non-syslog transport, and may even be transported by simply copying (and merging) files.

CEE has long thought about using RFC5424 structured data format for its structured logging needs. However, that would have limited its ability to work with all these older (and deployed) syslog implementations. Thus, the decision was made to use text that purely resides inside the message part and, without transformation, can be used in legacy systems (with given restrictions, of course).

So now back to the question: what to implement? With this facts, I think it boils down to "both". To use the benefits of modern-day syslog (as described above), you definitely need to implement RFC5424 and its helper RFCs (like 5425 for TLS). HOWEVER, the question remains if one should use structured data or cee-enhanced syslog. This, I have to admit, is indeed a though question.

My personal opinion, which can be totally wrong and is solely based on my experience (aka "gut feeling" ;)), cee-enhanced syslog sounds more promising for structured data. The main reason for this is that the format has received very good responses from major players and a lot of work is currently being done by a lot of folks driving important projects in the logging environment. There is also a lot of supporting libraries upcoming AND some of them already available. Most importantly, this effort is thightly integrated with Mitre and  it probably is not to far-fetched to assume that cee-enhanced syslog will appear on some purchasing checklists in the not so distant future. RFC5424 structured data does not have this broad backing. So while cee-enhanced syslog is a very fresh project, my personal assumption is that it will take off.

But again, that does not mean that RFC5424 shall not be implemented. I think RFC5424 technology is vital for a number of reasons. Of course, things like TLS can also be obtained without RFC5424, but not in a standards-compliant way. So to ensure interoperability, going the 5424 way is a good idea.