Category: rsyslog

Posted on

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.

Posted on

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).

Posted on

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.
Posted on

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″]; ”
}
}]
}
}

Posted on

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.

Posted on

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.

Posted on

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.

Posted on

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.

Posted on

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.

Posted on

MongoDB, BSON and templates…

After I have improved the template system yesterday, I have begun to think again about the integration of custom templates (actually field lists) with ommongodb (rsyslog’s mongodb output plugin). A “problem” with the mongo interface is that it does not support native JSON but rather BSON, its binary equivalent. So what needs to be done is convert the textual JSON representation to BSON before it can be stored in MongoDB. Given the fact that the JSON representation must be build with the property replacer, this looks like a was of coding/enconding. Assuming that I would take JSON and tansfrom it to BSON (all this in ommongodb), the workflow would be as follows:

text properties -> encode JSON -> decode JSON -> generate BSON

The “encode JSON” step would happen inside the template processr, the “decode JSON” part in ommongodb. In essence, this looks like a quite flexible, but rather slow approach. After all, it would serialize to JSON just for interim needs. What I am actually looking for is this workflow:

text properties -> generate BSON

In that we would replace the JSON format with some internal format. That internal format in a kind already exists, in array passing mode. In this mode, the property text is passed in via an array. As a side-note, some transformations are necessary and desired even in internal format, as the property replacer permits to use not only the raw properties themselves but substrings, case conversions, regexes and the like. The problem with array passing mode is that it provides just the plain values. However, for BSON (and MongoDB) we also need to know the field name – and type information. The latter is probably easy, as rsyslog usually deals with text, only, and so we could stick to strings except maybe for dates. The field name is available since yesterday inside the template structure. However, there currently is no way for a plugin to access this information.

So it looks like the decent thing is to create a new interface that passes in a (description,value) pair to the plugin. The description most probably could be the template structure (or some abstraction if we feel bad about tying things too deeply together). That will prevent the detour via JSON, but still provide otherwise full capabilities. The bad thing, however, is that some complex interface gets yet another option (maybe it is time for a general cleanup?).

Feedback on this issue is appreciated.