Category: rsyslog

You know this: the more you like something, the “faster” time elapses. So it turns out to be Thursday of my first week back at work from my summer vacation now ;) This time, I was really lazy and had extremely limited Internet connectivity while I was away. While a bit unusual for me (I was never disconnected for more than 2 days the past 10 years or so…), it turned out to be a good experience (well, some email via PDA flowed, though). As a side-note, it was good the see the rsyslog well alive while I was out of town! Many thanks to all contributors.

As you probably expect, there was a bunch of work waiting for me when I returned. I am still suffering a bit from it. However, I managed to do some work on rsyslog. So I finally managed to get rid of the hardcoded syslog message size limit. This, of course, caused a lot of code to be touched. I did a pre-release on the mailing list, but I do not have the feeling that many tried it. Well, now it is the official devel and we’ll see if we get into interesting parts of trouble.

The next thing on my agenda is the new documentation generation system. I got a lot of help from my friends at Red Hat Japan. Actually, I now need to fully understand the way docbook and the generation process at all works. I guess that will keep my occupied for a while. So please keep watching this blog, even though I may not have so many new posts for the time being.

Rsyslog obviously gains momentum. Not only is it becoming the default syslogd on Debian, a very important distribution, I am also seeing an increasing amount of questions inside the rsyslog forums and mailing list. The later, I think, is a good indication that people begin to care about rsyslog and also begin to explore rsyslog’s enhanced features.

I am very happy with this development. However, it also shows a downside. Rsyslog, for obvious reasons, “offers” much more chance for misconfiguration than its feature-bare ancestor sysklogd. While I tried hard to make configuration simple and intuitive, I managed to succeed only in the simple cases. If you configure rsyslog for complex needs, I have provided ample ways to screw up ;) That situation will hopefully get better with the new scripting engine, but even that will not be able to totally resolve the issue. To help people getting over this phase, rsyslog offers a myriad of diagnostics. Whenever something is wrong, it logs at least one message telling you (and often a couple of them, helping to identify the culprit).

With some frustration, however, I begin to see that many people never see these diagnostics. Many people try a configuration and just notice that it does not work. They never look at rsyslog’s own detailed error message (and some even do not write them anywhere, so they actually have nothing to look at ;)). So it has become quite common that for questions raised on the forum, we go lengths through the process of obtaining (large) debug logs, just to see that the debug log contains the otherwise-ignored error message that explains it all.

A (too) simple approach would be to blame users: why, the heck, don’t they pay attention to their system setup. Beside being lame to blame users, it doesn’t help solve the issue. The root cause seems to be that people tend not to know where to look for help. One approach is to improve documentation. I’ve gone some length on that, but what comes into our way is that people (including me ;)) tend to ignore documentation until there is no way around it (at this point, almost always too late, the foolishness of that approach is proven ;)).

An additional complexity is that people need to have at least some working configuration, including permissions, to make rsyslog record its error messages. A while ago, I thought about an internal message buffer, for error messages and maybe others, that can be viewed via a web browsers (this implies a simple http server inside rsyslogd). So folks with problems could simply point their web browser at rsyslogd and see which diagnostics exists. This solves at least the problem of recording and finding the messages. It does not solve the issue of people not knowing to do that, but it improves the situation: it is easier to tell “just point your web browser to” then to instruct people on how to review log files or create and send debug logs.

Up until now, I have stayed back from this approach because of security concerns I have. Such a http server, especially if it would also enable to view some of the live log data and live state information, could be an ideal tool for attackers. Of course, I can disable it by default and limit its features. But that is counter-productive in regard to the simple troubleshooting case. So I stayed back from it.

Now, seeing that the support problem (and pain people experience) is becoming worse, I have taken another look at this approach. I now think there is a compromise: I can create a separate plugin, one that can be loaded via a single “$ModLoad”, but is not by default. So the system is secure by default but it is easy to instruct people to activate advanced diagnostics capability. It is obviously also easy to disable them, but what if people forget (and we tend to, don’t we?). That would leave the attack vector intact once it was enabled. I think I now have a cure: What if the plugin automatically disables itself after a given period of time. Looking at the use case, it would be sufficient for most cases if diagnostics are available for 10 minutes after rsyslogd restart, but not any longer. I think I will now take this route. While it leaves the attack vector open, it mitigates the risk to a time frame, which usually is very short compared to overall runtime. And, after all, this is just a second safety measure. In the first instance, people should disable diagnostics once they no longer need it. Enabled diagnostics probably warrant a (startup) log message in themselves, so someone who cares to get an error-free startup should not forget about that (and those who don’t care, don’t deserve any better but still have a safety belt…).

I think I will try to implement a testing plugin in the current devel branch. This was unplanned work, and obviously pushes away other work. In the long term, however, I think it is very important to help folks getting up and running easily, so changing the schedule to solve that need is justified. For my testing purposes, though, I will not start with a http server but with something much more simplistic – just to grasp the essence of this approach.

There is an interesting discussion going on on the loganalysis mailing list. It tries to define what some entities we deal with on a daily basis really mean. While most people involved in logging have an intuitive – and sufficiently close – idea of what they mean, it is interesting to see how much difference there is in actual thoughts.

I will reproduce my posts/definitions here in this blog entry. To save me some time, I more or less copy and paste my text to this page. I think it should be sufficiently self-contained to grasp the idea. I reproduce my thoughts for two reasons: first of all, I would like to have a handy reference to my view of the logging world (so that I can refer anyone who asks to this page). Secondly, I think it is useful for all those of you who dig a bit deeper into rsyslog, phpLogCon and the rest of the MonitorWare line. All of these softwares are build around the definitions I am giving here.

Please note that I may update this page when I write new content. This helps to keep things tidy together. For you, unfortunately, this means you need to check this page from time to time…

As always, feedback is highly appreciated. You may either comment on this post or mail me.

So here now comes the “meat”:

I actually tend to agree that an event is *always* *associated* with a state change. The state change, however, may be subtle and not always obvious.

Let’s take this post excerpt as an example:

##
some logs which don’t indicate a state change such as login failures,
##

At first, a login failure seems to have not changed any state. After all, nobody was logged in before the event and nobody is logged in after it. HOWEVER, here our view is just not granular enough.

Let me take the position of the login machinery. That machine obviously has states for “awaiting login”, “authentication requested”, “auth success” and “auth failure” (among many others). What happens in the failed login case is that the machine transits between these states:

“awaiting login” –> “auth req” –> “auth failure” –> “awaiting login”

Obviously, state in this subsystem has changed three times. An upper level (e.g. a user process creator) may not have seen a state change, because the transitions did not request one. So at the upper level, we have no state change.

Depending on the granularity of logging we would like to have, we need to look at state changes at different levels. If I am interested in security logging, I most probably should look at the login machinery. And there, I see three transitions. As such, I may report three different events.

In a somewhat more abstract form, I even think an event is *always* bound to a state change. If we look closely enough at an entity, and this entity does not change state, so what can we then report? Is it noteworthy to report that entity x remains in the same state a it had a while ago? And even if so, couldn’t one say that the state of x has changed in a subtle way – time needs to be considered part of the entities “state set”.

With the “state set” I mean anything that makes up and influences the state of the entity. It includes all properties that differentiate between different states. The state set is obviously defined by the entity, but also by the needs of the observer (so the same entity may have different state sets if different observers look at it). For a given observer (use case) and a given entity, there is exactly one state set, consisting of mutually exclusive states and a set of properties that identify these states.

In this point of view, an event is actually another word for a state transition. If there is no state transition, there is no event. And why should there be one? Let’s assume the use case requires tracking of (identical) states over time. As such, elapsed time is part of the state set. Now let’s assume all other properties of the state set remain identical, but time elapses. Now we still have a state transition, because the state set changes between time “than” and time “now”. This justifies an event. If, however, the use case does not require tracking of continuity, elapsed time is not part of the state set. In the same example above, we do now not have a state change (all other properties remain identical) and consequently no event happens. This may sound like loss of information, but we defined that the observer is not interested in elapsed time. As such, from the POV of this observer, nothing happened. So we are correct in not raising an event.

From this I conclude:

a) there is no such thing like an “absolute event” – an event is always relative to the needs of the observer
b) thus different observers may have different perception of what justifies raising an event
c) what the observer is interested in is defined in the “state set”
d) an event is generated when a change in the “state set” is detected

Trying (and probably failing) to get a short grip on this, I would say “An event is a change in observer-relevant properties of an entity”. Which, of course leads to the need to define observer, observer-relevant, property and entity…

I haven’t looked at CEE enough to know if there are definitions of these (or similar) terms. Actually, when I looked at CEE some very long time ago I have to admit it didn’t look very appealing. But I now have subscribed to the mailing list and will see if I can contribute (or use ;)) to/from the work.

An interesting side-note of a) is that one may (try to) define a superset of state sets of all possible observers. Actually, I think this is what auditing people try to define when they design audit points. The knobs that trigger specific events provide the ability to limit the actual (running) state set to the subset that the configuring observer is interested in. And if you ever wanted to audit anything but did not find an audit point in the software for it, auditing designers made a wrong assumption on the required state superset ;)

> —–Original Message—–
> From: loganalysis-bounces@loganalysis.org [mailto:loganalysis-
> bounces@loganalysis.org] On Behalf Of Anton Chuvakin
> Sent: Friday, July 25, 2008 6:14 AM
> To: bschnzl@cotse.net
> Cc: loganalysis@loganalysis.org
> Subject: Re: [logs] How to define Log, Event, and Alert?
>
> Good point. So:
>
> Event = something that happened on a system.
> Log = a TIMED record of the above occurence.

If I may generalize things a bit…

I’d replace TIME by “sequence identifier”, with sequence identifier defined as being something that is monotonically increasing. A timestamp is an object that we think to be a natural example of a monotonically increasing function. HOWEVER, if we look at existing technology, this is not always the case. In fact, it is more often NOT the case than it is… If we have two systems a and b and these systems do not have time synchronized, and have a system c which is the event collector (and collects only events from a and b), then c may record time stamps inside its log that do not monotonically increase. For example, it may record:

02:00:00 event a1
01:00:00 event b1
02:01:00 event a2
01:01:00 event b2

Of course, this is still a TIMED record of occurrences. However, in this sense this is used, “TIMED” includes a sense of temporal order (at least to me). In the above log, we may not have the correct temporal order. We may be able to reconstruct it by sorting on the timestamp. That would be a valid approach if the timestamps are indeed correct (compared to universal time). But if a and/or b has incorrect time, we would create a wrong temporal order. Indeed, in this sense the monotonically increasing identity of the log in question would actually not be the timestamp but rather the *sequence of recording*, kind of a meta-property not directly contained in the property set of the individual event record (but rather obtained by its relationship to its predecessor in the log file).

Now let’s assume a log without a timestamp. These things happens, e.g. in debug logs (and all too often in others I have seen).

If we define

> Log = a TIMED record of the above occurence.

such a “log” would obviously not be a log, because it does not fulfill the requirement to be timed.

If a log instead is “a record of events with a sequence identifier”, that problem does not exist. The sequence identifier in that case would be the derived property I mentioned above.

The question remains if such a definition is actually useful. The sequence identifier is obviously something with very vague semantics. They depend on the observer as well as the correctness of the “sequence identifier generating function” on all systems in question.

Let’s get back to the simple case of timestamps: as outlined above, the semantics of timestamps depend on time sync. Even if there is ntp timesync, timestamps (with reasonable precision) are always questionable. They are approximate, even on the same system. With standard syslog timestamps (second precision!) the problem is easy to see: one may receive hundreds of events within the same second. So even if time is correct, an observer is unable to detect any order of events. If looking just at the timestamps, one must conclude that all events happened at once. If looking at the semantics of the messages, one most often also can conclude this is impossible (e.g. how to delete a file before it is created?). Obviously, the timestamp alone is never sufficient to detect order of events, even on a single system. Granted, for practical purposes a high resolution timestamp (with good time synchronization) is most often a sufficiently well approximation of the time an event happened. But do you really trust it? …always? Have a look at your own correlation engines: do they work on pure timestamps – or do they include some other properties, like the order of event log records inside the log?

Now let me try to define what I think a log actually is:

An EVENT is a set of properties that describe a state change (in the sense I have described state change yesterday). The contents of this set is depending on the entity who’s state changes as well as on the observer. [so it may actually be a set of two sets: entity-related properties and observer-related properties]

An event is generated when a state changes.

An EVENT RECORD is the physical representation of an event inside an event log. It is a set of (at least) two sets: the event’s set itself as well as a set of meta-properties which describe the event record (e.g. it’s size, it’s order inside an event log record, it’s format, …). I think this has a tendency to contain observer-related properties, too. Some Meta-properties are obviously event log related (like sequence of recording).

Finally, an (EVENT) LOG is a set of event records. Please note that according to this definition, the stream of syslog messages flowing from system a to system b is also an event log – not just log files or database tables. So an event log does not necessarily need to be persistend.

There is no inherent order inside event logs. In practice we experience a “natural order” (one record begins before another), but that actually is a meta-property of the event record. So we can order event records based on their meta-properties. It just happens that a text log is physically ordered by the sequence meta property.

[side-note: if we look at a UDP based transmission of an event log, we notice that the sender’s perception of the event log is different from the receiver’s: the physical order of event log records may be different, as well as their absolute number (if UDP discards messages)]

Finally, different log files, database tables, log stores in general are just partitions of the event log set. This also explains why we need to merge different log files if we would like to have a broader view of events that happened inside our system: We need to re-unit the partitions that contain things of interest for our needs so that we build a sufficiently large set for our analysis algorithm (that set being a complete partition of the log set in regard to what we are interested in).

[side-note: if we need to unite such sets, we often experience the problem that we do not have a truly identifying function for event log records, which makes it often really hard to create real supersets, where no two elements are the same]

Again, I see that my definitions are not really one-liners, but I think if we try to use too-simple definitions, we end up incorrectly describing the objects we are talking about. That will most probably lead us to wrong conclusions, and, in a very practical sense, to a) wrong implementations and b) wrong actions taken on the conclusions we think we have drawn (but were invalid).

Rainer

I have some great news. It has come to my attention that the Debian project has selected rsyslog as the default syslogd for Debian lenny. So after Fedora, this is the second time rsyslog is becoming the standard syslogd for a big platform. This leads room for the hope that it will be able to capture even more momentum in the future.

Special thanks go to Michael Biebl. He maintains the rsyslog package on Debian. Without his hard work and very solid understanding of the Debian platform, rsyslog would never have been able to be ready for prime time on that platform.

For those who enjoy the good news as much as I do, here are two relevant links:

• http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=490440
  
• http://lists.debian.org/debian-release/2008/07/msg00259.html

While it is joy to read about these developments, it is also a chore of the rsyslog project to live up to the trust that is put into it. We are well aware of this and will keep rsyslog in good shape for all who depend on it.

Hi folks,

I have not posted any work log for long. Even worse, I have not fully kept up with the log. So what’s going on? Is rsyslog development pace going down?

No, definitely not! I am just currently concerned with helping users, doing some labs myself, working a bit on phpLogCon and thinking about how to best do the scripting engine.

Oh yes, the scripting engine… I am promising and promising it. The reason it takes so long is that I want to have a perfect solution on the first shot (well, as close to perfect as possible…). And I want to keep it backwards-compatible to what we currently have. This involves a lot of things under the hood, and it requires very careful planning to do it right. In fact, I am even re-evaluating some theoretical concepts for the scripting language, maybe it makes sense to adopt a few more thoughts. But, even though you do not see it, I am still very focussed on it. It is the next big thing to happen.

Just to get you an example of the subtle problems: how to *best* handle the “*.*” PRI selectors that are in the current config at the rule of almost all filters. If that is not mapped properly, it can have an enourmous performance hit. To support it, I may need to do a constant folding phase in my interpretative language, something that I so far did not consider as needed. And I am still trying to avoid this (it offers little benefit for almost all other cases).

Whith that said, on to the (partial) work log:

Past day’s rsyslog work log:
2008-06-13
– created autconf support for a rsyslog testbench
– created the first very rough beginnings of a RainerScript testbench
2008-06-23
– disabled warnings caused by third-party libraries
2008-06-24
– enhanced gtls driver to support fully async operation (there was
a bug before if gtls did issue EGAIN without getting any data)
2008-06-25
– bugfix: comments after actions were not properly treated. For some
actions (e.g. forwarding), this could also lead to invalid configuration
applied to beta branch

… something missing, see git log ;) …

2008-07-01
– released 3.19.8

Past day’s rsyslog work log:
2008-06-09
– somewhat improved plain tcp syslog reliability by doing a connection
check before sending. Credits to Martin Schuette for providing the
idea.
– made rsyslog tickless in the (usual and default) case that repeated
message reduction is turned off. More info:
http://blog.gerhards.net/2008/06/coding-to-save-environment.html
2008-06-11
– applied some patches from Michael Biebl – thanks!
– released 3.19.7
2008-06-12
– changed default for $KlogSymbolLookup to “off” (in beta)

Each one of us has ways to help save the environment. Interestingly, there are even some options exclusively available to coders ;)

I was made aware by Michael Biebl some time ago that the Linux community is trying to save power by disabling unnecessary wakeups inside the softwares. For example, the Linux kernel has become mostly tickless, that is does not necessarily wake up frequently. This is important, because modern CPUs have power save modes: simply said, the less is computed, the less power is needed. An idle CPU uses least power. However, when an application wakes up, the CPU resumes into modes that need more power. Of course, the CPU does not know if what it needs to be executed is actually useful or could be done more smartly. You can find more details at the site http://www.lesswatts.org/.

But why am I telling you this? The reason is that rsyslog, too, had (and unfrotunately has) some wakeups which are not strictly necessary. For example, the current imfile implementation needs to poll input files. This is the most portable way to do things, but it is not power-effcient. An update to a more power-efficient solution (on the platforms that support it) is scheduled. Next, the –MARK– message generator runs periodically. This one can probably never be avoided, because the actual functionality is the periodic activity. Any user should think if the functionality is neeed and, if not, not enable this plugin.

Finally, and the core rsyslog awoke every 30 seconds to check if repeated messages need to be flushed. However, repeated message reduction is no longer the default and I assume that most people do not use it. The default is to have it turned off. But even when it was turned off, rsyslog still awoke to do the (unnecessary) check. I have changed this, rsyslog now only initiates the wakeups when they are actually needed. To many (if not most) environments this means rsyslog will never again wakeup the system if there is no need to. It’s a small saving, but every little bit counts toward the ultimate goal. And given the potentially large number of systems running rsyslog, the saving may actually be larger than one initially assumes.

In the future, repeated message reduction will probably be implemented based on a different paradigm, which enables us to not run on a tick even when it is turned on.

In any case, I hope the new feature will contribute to – you name it – slightly longer notebook battery life and less environent pollution. And, ultimately, it’s a interesting fact to see how a software developer can affect environment health these days ;)

The new functionality will be available starting with rsyslog 3.19.7.