What is an Event? And what an Event Log?

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

Rsyslog will become Debian’s default syslogd

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:

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.

Writing syslog messages to a ram buffer

I just found an interesting article about ramlog, which enables to write syslog messages to a RAM disk. This sounds silly at first (after all, don’t we want to have the data secured in case of a failure?). But it makes an awful lot of sense in some scenarios, like laptops. But read yourself:

http://www.linux.com/feature/141231

Thinking about it, this is actually a buffer that performs a delayed write, but while the data is already accessible to the user. Delayed writing as such may be useful in its own right. Given that rsyslog already has queues, it may be worth to extend it to a mode where data is kept in the queue until either a configured amount of messages is queued or a configured period of time has elapsed. That could be used to generate more efficient, burst disk writes. For example, we could say that log messages be flushed only if there are at least 10 or at least one is older than one minute.

Note that this is a use case quite different from what ramlog addresses. Actually, they could even be combined. If you like this idea, please tell me, so that I can consider implementing it.

rsyslog work log / what’s going on / script engine…

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

rsyslog error message repository

Starting with 3.19.8, rsyslog finally offers specific error codes as part of the syslog tag. For example, rsyslogd-2040 means that a file could not be found. I have added these tags both to facilitate log parsing as well as easy troubleshooting.

But a tag is only as good as the information that it helps to find. Consequently, I have started to describe error cases inside the knowledge base’s event repository:

http://kb.monitorware.com/kbeventdb-list-1-Adiscon-rsyslog.html

So far, there is only a limited set of messages available (to phrase it politely ;)), but I plan to increase it over time. Note that there is an interactive feature where questions to the message can directly be posted to the forum. I hope this is useful.

If you run into an error message that is not-yet described, let us know and we’ll add an entry. In the long term, the new knowledge base part should be able to solve most problems.

rsyslog work log

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)

coding to save the environment…

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.

reliable plain tcp syslog – once again…

As said in my last blog post on plain tcp syslog reliability, I have now implemented Martin Schütte’s idea in rsyslog‘s plain tcp sender. I created an interface inside the netstream driver layer specifically for this method. It shall not be used by any other transport, and so it is clean enough to not affect any protocol other than the one that has the problem.

I have done some initial testing. It confirms the findings from my last post: the method works well in local, low-traffic environments, but fails in others. However, even in the fail cases, the message loss is somewhat less than without the work-around. So I think it is useful to have it inside rsyslog.

One thing that it affects is the current retry logic. Rsyslog used the work-around to resend the last message, which was most probably lost, after a successful reconnect. As connection loss is now much more reliable detected in some cases, the probabilty of message duplication greatly increases in them. In other cases, however, it may still be desirable to resend the last message. To (somewhat) solve this issue, I have now added a new config directive ($ActionSendResendLastMsgOnReconnect on/off) so that the user can specify his preferrence. The default now is to NOT send these messages on reconnect.

This functionality will be part of rsyslog 3.19.7.

rsyslog work

Past day’s rsyslog work log:
2008-06-06
– released 3.19.6
– added doc on suggested TLS deployment (rough picture, configuration
sample still missing).
– added new property replacer option “date-subseconds” that enables
to query just the subsecond part of a high-precision timestamp
2008-06-07
– fixed a bug with the new property replacer option in timereported
property – thanks to Elizabeth for reporting it

getting a bit more reliability from plain tcp syslog

As I have described in my recent post, plain TCP syslog is unreliable by its very nature. However, Martin Schütte had a good idea that helps improve the reliability, at least under some circumstances.

Martin showed that by doing a recv() call in front of the send(), reliability improves. This is because the local TCP stack is then forced to evaluate whatever the remote peer sent to it. Without that recv() call, the local stack may not evaluate the response until later. Of course, this is implementation specific, but seems to be common. From traces, I have seen that there seems to be good reason to do so: the number of packets sent is slightly lower when not doing the recv(), so it looks like the buffering is improved. On the other hand, this costs reliability as a remote shutdown is not immediately detected. I have not verified the buffering behaviour by looking at the tcp stack sources, but the traces are evidence enough. At least for practical purposes.

The recv() suggested by Martin forces the stack to evaluate packets received. If the remote end has closed the connection, that makes the local stack detect the condition. Consequently, loss of connection can be detected at this stage. Without the recv(), this needs at least one other send() call and thus causes the loss of one message. So we increase the reliability of plain tcp syslog by being able to detect the error state earlier.

However, this approach is racy. For example, if the remote peer initiated the shutdown after we did the recv() (but before the send()), this will not help. Also, it does not help if there is high traffic. In this case, the remote peer may be forced to shutdown the connection in the middle of a message. Keep in mind that a syslog server has no way of telling the client it intends to shut down. So if it must, it has no other chance than to terminate the connection forcefully (maybe after a short timeout, depending on the needs).

So, in short, the recv() trick often works if we have:

  • a network with likely no packet loss
  • a network with low latency
  • low network traffic

Fortunately, this is the situation we experience in many entry-level local networks. So for them, doing the recv() provides an improvement over not doing it. Most importantly, plain tcp syslog will deterministically lose one message in all environments without the recv(). With it, there is a chance the message will not be lost.

The larger the environment, the more slim this chance is. Unfortunately, I assume that in enterprise environments that really need reliability, the recv() trick does not contribute much to improving reliability (because they do not have the perquisites outlined above). So for enterprises, plain tcp syslog is still not an option when there is need for reliable logging (e.g. in an auditing environment). Protocols with app-level acknowledgement are required there (e.g. RFC 3195, RELP or SETP).

I have thought long how this affects rsyslog. I have now concluded I will give the recv() trick a try. I think it can improve the situation, at least in some practical scenarios. The problem is that it is kind of a hack. I need to find a well enough way to implement it into my netstream driver layer that doesn’t force the code to do something where it is illogical while at the same time keeping the driver clean to be used with more sophisticated protocols. So it is not a matter of adding a simple API call. I’ll probably introduce a driver call which may do the recv(), only if it makes sense for that type of driver, and does a dummy return for those drivers that do not (need) to support it.


For completeness, I reproduce some of my comments on Martin’s blog just so that I have a stable reference within a domain a manage (things too often disappear too quickly ;)).

  1. Rainer Gerhards says:
    20080530 11:55Martin, I have read your update. This use case isn’t fixed either, at least not reliably. It is racy. You get the same results be just doing the send() without the recv() – just give it a try. ;) — Rainer
  2. Rainer Gerhards says:
    20080530 14:34OK, I am not just ignorant ;) I’ve given it another try, while racy it looks like it indeed solves the problem in the majority of simple cases. I just wonder what happens under the hood. I’ll have a look :) — Rainer
  3. Rainer Gerhards says:
    20080530 15:02Interesting. I’ve now done a wireshark trace. As it looks, the IP stack does NOT process the incoming connection request until after it actually sends the message. If you do the recv(), this forces this evaluation. I have not verified this with the tcp sources and I don’t think it makes much sense to do so. It’s probably a bit platform-specific, depending on what the IP stack does. Anyhow, it seems to greatly reduce the problem in non-failure cases and does not cause much performance pain. So it is worth adding it. I’ll now apply it once again to the real rsyslog and see how it performs there. I keep you posted. Rainer
  4. Rainer Gerhards says:
    20080602 15:40OK, I have done some further stress testing. Unfortunately, the solution does not work as soon as the traffic gets higher. In client.c, you do a sleep. This sleep makes sure that the remote end has time to do its close and notify the client before the next message is sent. I modified you examples so that the sleep() is no longer used and 1000 messages are sent by the client. Then, the disconnect happens 1 byte into message 423 (stream was partly received). The next message I see is 701. The client also notices the problem at 701. So I have lost around 280 messages without anybody noticing it. Of course, on a non-busy server that does not happen, but it proves the point that even in a nice clean close scenario without packet loss you can lose data on a server restart. There is no reliable cure. I’ll now evaluate if it makes sense to add your suggested recv() logic for those cases where it helps. I am just unsure if these are a large enough sample to justify this code change. Anyhow… Please let me know any further findings you may have (did I overlook something)?

    Rainer