message classification with liblognorm sample code

I have just enhanced liblognorm‘s normalizer tool to support the -t option. If it is given, only messages with the specified tag will be output. Currently, only a single tag can be specified. The main purpose of this change is to provide some example code on how to use the message classification API, so that other developers can include it into their solutions more easily.

In essence, the whole logic is contained in normalizer.c, line 122 and 123. The application needs to keep the “wanted” tags inside an es_str_t type. Then, it needs to call the ee_getEventField() API to find out if the normalizer (better said: its rule) associated the tag with a given message. That’s it…

Please note that we may implement a more powerful API in the future — if this makes sense. If you think API additions would be useful, please suggest them together with a description of the benefits.

log classification with liblognorm

Today, I have added support for so-called “tags” to liblognorm (and it’s base library libee). This new capabilities permits very easy classification of syslog message and log records in general. So you can not only extract data from your various log source, you can also classify events, for example, as being a “login”, a “logout” or a firewall “denied access”. This makes it very easy to look at specific subsets of messages and process them in ways specific to the information being conveyed.

To see how it works, let’s first define what a tag is: A tag is a simple alphanumeric string that identifies a specific type of object, action, status, etc. For example, we can have object tags for firewalls and servers. For simplicity, let’s call them “firewall” and “server”. Then, we can have action tags like “login”, “logout” and “connectionOpen”. Status tags could include “success” or “fail”, among others. The idea of tags is based on early CEE concepts. I will try to keep consistent with whatever CEE heads to. Tags form a flat space, there is no inherent relationship between then (but this may be added later on top of the current implementation). Think of tags like the tag cloud in a blogging system. Tags can be defined for any reason and need (though obviously we must strive to get to a standard set, something I hope CEE will provide in the not too distant future). A single event can be associated with as many tags as required.

Assigning tags to messages is simple. A rule contains both the sample of the message (including the extracted fields) as well as -now- the tags. Have a look at this sample, taken from liblognorm 0.2.0:

rule=:sshd[%pid:number%]: Invalid user %user:word% from %src-ip:ipv4%

Here, we have a rule that shows an invalid ssh login request. The various field are used to extract information into a well-defined structure. Have you ever wondered why every rule starts with a colon? Now, here is the answer: the colon separates the tag part from the actual sample part. Starting with liblognorm 0.3.0, you can create a rule like this:

rule=ssh,user,login,fail:sshd[%pid:number%]: Invalid user %user:word% from %src-ip:ipv4%

Note the “ssh,user,login,fail” part in front of the colon. These are the four tags the user has decided to assign to this event. What now happens is that the normalizer does not only extract the information from the message if it finds a match, but it also adds the tags as metadata. Once normalization is done, one can not only query the individual fields, but also query if a specific tag is associated with this event. For example, to find all ssh-related events (provided the rules are built that way), you can normalize a large log and select only that subset of the normalized log that contains the tag “ssh”.

Note that versions of liblognorm 0.2.0 simply ignore the tag part, so old versions of the library are capable of working with new rule bases.

This is pretty cool and has ample potential. Just think about creating firewall reports: if you have different firewalls, you only need to have different rule bases to normalize these events all into the same format. Even more now, you can process the logs based on the classification assigned during the normalization process. For example, a “failed connection request” report may ignore everything that is not tagged as “connection, fail”.

That probably sounds pretty good to you, but how to actually use it? Right now, the core functionality is available inside the libraries (more precisely in the git version, I will do an official release very soon but wanted to spread word). That means developers have the necessary API to integrate with their programs. End user tools do not yet exist (what is not too surprisingly for a library). Integration of the new functionality is very easy. Classification is available without need to change anything in existing applications. A single new simple API ee_EventHasTag() has been added, which needs to be called to see if an event is associated with the given tag. [side-note: the current API is NOT guaranteed to be stable, even though I try not to break things without need]

In hope that developers will play with the new functionality, so that it will be available in end-user tools soon as well. I myself plan to enhance the normalizer tool very soon to support selecting subsets based on tags (this can also serve as an example for other developers). Also, I plan to add classification support to rsyslog very, very soon. So stay tuned to what’s coming up — it’s exciting ;)

What is rsyslog auto-backgrounding?

Rsyslog, by default, auto-backgrounds itself after startup. That simply means that the instance that is started by the user (or script) more or less does nothing but fork a new instance detached from the current terminal session and execute it. The originally started instance exits after a short timeout. This behavior was carried over from sysklogd.

Note that auto-backgrounding is problematic (aka “makes things more complicated than the need to be”) in debug sessions, lab environments and so on. So command line switch “-n” can be used to turn off auto-backgrounding. In that case, the first instance started will actually carried out the work to be done (as most would expect in the first place).

It is strongly recommended to use “-n” option for lab testing.

log normalization: how to share rulebases?

Rulebases play a crucial role in log normalization. While the log normalizer itself needs to be of high quality and speed, it is the rulebase that really helps to detect which message the one in question is. I myself have so far concentrated on the code and not created any larger rulebase. Champ Clarck III has created many more for his use inside Sagan. But this means everything is in its infancy. What we really need is community involvement to create a large number of easy to access rulebases for almost all devices.

This brings up the question of how to manage and share such a repository. One method may be to place it on a web site, together with some submission tool. An alternate approach would be to put everything into a public git. This latter approach has some beauty, because git is universally available and well know. Even if a user does not know git, only a minimal set of commands is required to pull the rulebase. So maybe this is the way to go?

I would be very interested in suggestions on how we shall manage rulebases and spread the word. What do we need to support a great community? Whom can we talk to? If you have any ideas, concerns, questions or even an idle rant, be sure to let me know. At best, send mail to the lognorm mailing list, so we can broadcast this to other folks interested.

why does the rsyslog testbench sometimes fail?

Rsyslog contains a set of automatted tests, the so-called “testbench”. It is invoked via the standard method of “make check” and “make distcheck”. Since its introduction in version 3, the testbench has been continously enhanced and extended. It now contains around 150 individual tests, which sum up to around 80 tests from the autoconf point of view (some autoconf tests run a couple of subtests, thus the difference in number). The testbench has been proven to be very useful and caught numerous problems before new code was released.

But the testbench is not perfect, and it may sometimes fail without any actual problem. There are two reasons for this. One is that the test require a very specific environment. For example, some parser based tests assume that the system the test is run on is configured to be named “localhost.localdomain” (the default for many test deployments). This needs to be the case because there currently is no way in rsyslog to overwrite the local hostname. Some parser tests use malformed messages, in which case (as of the RFC), the local system name must be used. As such, we need to have a specific system name set in order to prove the results. In the long term, I’ll add the capability to overwrite system name inside rsyslog, but it does not make sense to create a dirty trick just for testbench use. So this needs to wait until we get to it as part of regular development. Note that a similar issues may exist at other places. An obvious one is the database tests, where we need pre-created users, databases, tables etc in order to run the tests.

The other issue is a bit more subtle. The syslog protocol is simply, without App-Layer acknowledgments. This makes it hard to know when rsyslog has received a while bunch of test data. That in turn makes it hard to definitely say when all test data has arrived and an instance can be shut down. So the whole process is a bit racy. To “solve” this, I use some wait periods in tests affected by this problem. However, longer wait periods mean longer test bench runtime and this reduces my development productivity. So I use wait time that usually does the job, but may fail under some circumstances (most notably when –enable-debug is set). This can affect a couple of TCP-based tests (like imtcp_conndrop.sh and similar ones). I have not yet a good idea what a clean solution to this problem is, where “clean” means that it a) always works and b) does no introduce unnecessary code complexity under non-testbench runs.

Given these problems, some care must be taken interpreting testbench results. Most importantly, a fail does not necessarily mean that things are actually broken. It merely means that one needs to look at the actual test and check a) why it fails and b) if it fails repeatedly. Especially the “racy” test tend to occasionally fail without any real problem. I’ve also seen them to fail consistenly on some platforms, simply because my timing assumptions are not valid there (Solaris was one example where I needed to adjust my overall wait periods).

So testbench results need to be taken with a grain of salt, and require interpretation. I know this is inconvenient for occasional users, but it is the best compromise I currently can offer.

using failover and asynchronous actions in rsyslog

I wanted to point out that failover actions and asynchronous processing does not work well in rsyslog — at least if a simple approach is used. The reason is that there is a conceptual problem with them working both together: async actions will – by design – always return an “everything went OK” status (because we don’t know otherwise, as things are async!). So this means failover processing will never see an error.

Now look the following config:

$modload imuxsock
$ActionQueueType LinkedList
$RepeatedMsgReduction on
*.* @@10.48.20.19:10514
$ActionExecOnlyWhenPreviousIsSuspended on
& @@10.48.20.18:10514
& -/home/logfile2
$ActionExecOnlyWhenPreviousIsSuspended off

If the Action Queue Type is set to linked list (and thus the action executed asynchronously), the other two actions will never be executed – because the async action always “succeeds”.

There are two ways to solve this situation:
1) do run the action synchronously — depending on your needs, this may be a solution or not
2) if you need to run it async, you need to define a new ruleset, which includes the config WITHOUT the async processing. Then, use omruleset to execute the newly defined ruleset as whole asynchronously. This is obviously a bit more complex, but will do what you need.

I hope this resolves some confusion about the failover functionality (and, yes, a better config language would make this less painful — hopefully we will finally be able to write one ;)).

new rsyslog/systemd work going on

This is just a quick note that systemd is doing really well in providing logging right from the system startup, even when no syslogd is running. The magic is that messages are put into the kernel log, where the (later started) syslogd can pull them from. Unfortunately, there are some downsides from this mode, and we are currently working to solve them. For more details, please follow this thread:

http://lists.freedesktop.org/archives/systemd-devel/2011-March/001558.html

I guess the remaining issues will be settled soon, as almost everything is in place and I just need to add some additional parsing logic to rsyslog. Due to the conference next week, I may need one extra week to complete that. All of this work will be part of the newly opened v5-devel (and above).

we are nearing a new rsyslog v5-stable

I have just released rsyslog v5.7.9. It will possibly be the last v5-beta versions of the 5.7. branch. I’ve ironed out a lot of bugs during the past two to three weeks. Right now, some patches are in 5.7.9 and not in the current stable, because I wait for some more feedback on the patches.There are still some bugs open in bugzilla, but all of this bugs are mostly concerned with rather exotic environments AND are present in the current v5-stable as well. So there is little argument to hold the new v5-stable branch just for that reason.

The plan is to release a last 5.6.6 version, ending that branch. Shortly after that, I’ll release 5.8.0. That way, conservative operators receive the latest round of bug fixes and can probably wait quite relaxed until 5.8.1 arrives ;)

It should be noted that 5.8.0 will be the first stable version with full support for systemd.

refactored imfile module now publically available

Hi all,

the refactoring and enhancement of imfile done by Nikolaidis Fotis has reached a first public-visible result. I have just created a new experimental git branch with his work:

http://git.adiscon.com/?p=rsyslog.git;a=shortlog;h=refs/heads/v5-stable-imfile-refactor

The code is probably not 100% finished, but it provides a preview plus the ability to suggest further improvements.

Please note that the code base has evolved since the refactoring begun. So in order to integrate into the main code line, we must see that we can adopt to the recent changes to imfile. Most importantly, you should try to merge this branch with v5-devel, which gives me a lot of issues when I try to do it. We will look at this once the new modules codebase has matured (and Nikolaidis gives me a “go” for that activity).
Feedback on the new module is appreciated (please direct it to the rsyslog mailing list).

rsyslog hit the one million message per second mark

Thanks to a user report, I just found out the the recent v5 versions of rsyslog have hit and exceeded the one million message per second (mps) mark! In my lab, with commodity hardware I reach around 500,000 mps. In practice this seems to be at least doubled :)

This strengthens even further that rsyslog is the syslogd of choice for demanding high-traffic environments :)

The full report is here:

http://kb.monitorware.com/000-000-character-messages-sec-with-rsyslog-t10740.html