Category: rsyslog

Posted on

syslog data modeling capabilities

As part of the IETF discussions on a common logging format for sip, I explained some sylsog concepts to the sip-clf working group.

Traditionally, syslog messages contain free-form text, only – aimed at human observers. Of course, today most of the logging information is automatically being processed and the free-form text creates ample problems in that regard.

The recent syslog RFC series has gone great length to improve the situation. Most importantly, it introduced a concept called “Structured Data”, which permits to express information in a well-structured way. Actually, it provides a dual layer approach, with a corase designator at the upper layer and name/value pairs at the lower layer.

However, the syslog RFC do NOT provide any data/information modeling capabilities that come with these structured data elements. Their syntax and semantics is to be defined in separate RFCs. So far, only a few examples exist. One of them is the base RFC5424, which describes some common properties that can be contained in any syslog message. Other than that, RFC5674, which describes a mapping to the Alarm MIB and ITU perceived severities and RFC5675, which describes a mapping to SNMP traps. All of them are rather small. The IHE community, to the best of my knowledge, is currently considering using syslog structured data as an information container, but has not yet reached any conclusion.

Clearly, it would be of advantage to have more advanced data modeling capabilities inside the syslog base RFCs, at least some basic syntax definitions. So why is that not present?

One needs to remember that the syslog standardization effort was a very hard one. There were many different views, “thanks” to the broad variety of legacy syslog, and it was extremely hard to reach consensus (thus it took some years to complete the work…). Next, one needs to remember that there is such an immense variety in message content and objects, that it is a much larger effort to try define some generic syntaxes and semantics (I don’t say it can not be done, but it is far from being easy). In order to get the basics done, the syslog WG deciced to not dig down into these dirty details but rather lay out the foundation so that we can build on it in the future.

I still think this is a good compromise. It would be good if we could complement this foundation with some already existing technology. SNMP MIB encoding is not the right way to go, because it follows a different paradigm (syslog is still meant to be primarily clear text). One interesting alternative which I saw, and now evaluate, is the ipfix data modeling approach. Ideally, we could reuse it inside structured data, saving us the work to define some syslog-specific model of doing so.

The most important task, however, is to think about, and specify, some common “information building blocks”. With these, I mean standard properties, like source and destination ID, mail message id, bytes sent and received and so on. These, together with some standard syntaxes, can greatly relieve problems we face while consolidating and analyzing logs. Obviously, this is an area that I will be looking into in the near future as well.

It may be worth noting that I wrote a paper about syslog parsing back in 2004. It was, and has remained, work in progress. However, Adiscon did implement the concept in MonitorWare Console, which unfortunately never got wider exposure. Thinking about it, that work would benefit greatly from the availability of standardized syslog data models.

Posted on

new phplogcon site

Today, I received a first more or less complete link to what will become the new phplogcon site. The site is not yet live, but will provide some of the new features.

If you look at it, you’ll probably notice a couple of things. First of all, the name “phpLogCon” is no longer spelled out. The reason is that we considered a bit bulky and meaningless. “Loganalyzer” is exactly what the tools is about. But, of course, there are a myriad of (trademark) problems related to that name. So we try to avoid all confusion by calling it “Adiscon loganalyzer”, hoping that the company name as dominant part of the product name will rule out all problems. For that very reason, you’ll also see me to refer to Adiscon Loganalyzer in the future. If you wonder why I stress that “Adiscon” part, you now know why.

Secondly, you will notice the fresh design. While I am not a visual guy, I have to say that I like it very much. I think it removes much of the clutter and makes it easier to find the information you need quickly. We also have changed the content management system in the background. The new sites uses WordPress, which seems to be highly approprioate for what the site needs. Of course, the wiki and forum will remain as they are – they have proven to be quite well as they are.

If you look more closely, you will also note that Adiscon LogAnalyzer gets an important new component: a reporting module. I managed to convince my peers at Adiscon to move some of our MonitorWare Console closed source technology into Adiscon LogAnalyzer. My long-term vision is that reporting capabilities will much enhance the utility of this tool. In order for Adiscon to get something back, we will begin to develop some enhanced reports, which will be non-free for commercial users. However, the base product as well as some base reports, will always remain free!

I hope you consider this to be good news, just as I think! Thanks to everyone who made this possible.

Posted on

Some thoughts on reliability…

When talking syslog, we often talk about audit or other important data. A frequent question I get is if syslog (and rsyslog in specific) can provide a reliable transport.

When this happens, I need to first ask what level of reliability is needed? There are several flavors of reliability and usually loss of message is acceptable at some level.

For example, let’s assume the process writes out log messages to a text file. Under (allmost?) all modern operating systems and by default, this means the OS accepts the information to write, acks it, does NOT persist it to storage and lets the application continue. The actual data block is usually written a short while later. Obviously, this is not reliable: you can lose log data if an unrecoverable i/o error happens or something else goes fatally wrong.

This can be solved by instructing the operating system to actually persist the information to durable store before returning back from the API. You have to pay a big performance toll for that. This is also a frequent question for syslog data, and many operators do NOT sync and accept a small message loss risk to save themselves from requiring a factor of 10 servers of what they now need.

But even if writes are synchronous, how does the application react? For example: what shall the application do if log data cannot be written? If one really needs reliable logging, the only choice is to shutdown the application when it can no longer log. I know of very few systems that actually do that, even though “reliability” is highly demanded. Here, the cost of shutting down the application may be so high (or even fatal), that the limited risk of log data loss is accepted.

There are a myriad of things when thinking about reliability. So I think it is important to define the level of reliability that is required by the solution and do that in detail. To the best of my knowledge, this is also important for operators who are required by law to do “reliable” logging. If they have a risk matrix, they can define where it is “impossible” (for technical or financial reasons) to achieve full reliability and as of my understanding this is information auditors are looking for.

So for all cases, I strongly recommend to think about which level of reliability is needed. But to provide an answer for the rsyslog case: it can provide very high reliability and will most probably fulfil all needs you may have. But there is a toll in both performance and system uptime (as said above) to go to “full” reliability.

Posted on

The typical logging problem as viewed from syslog

I run into different syslog use cases from time to time. So I thought it is a good idea to express what I think the typical logging problem is. As I consider it the typical problem, syslog (and WinSyslog and rsyslog in specific) address most needs very well. What they spare is the analysis and correlation part, but other members of the family (like our log analyzer) and third parties care well for that.

So the typical logging problem, as seen from the syslog perspective, is:

  1. there exists events that need to be logged
  2. a single “higher-level” event E may consist of a
    number of fine-grained lower level events e_i
  3. each of the e_i’s may be on different
    systems / proxies
  4. each e_i consists of a subset of properties
    p_j from a set of all possible common properties P
  5. in order to gain higher-level knowledge, the
    high-level event E must be reconstructed from
    e_i’s obtained from *various* sources
  6. a transport mechanism must exist to move event
    e_i records from one system to another, e.g., to
    a central correlator
  7. systems from many different suppliers may be involved,
    resulting in different syntax and semantic of
    the higher-level objects
  8. there is potentially a massive amount of events
  9. events potentially need to be stored for
    an extended period of time
  10. quick review of at least the current event data
    (today, past week) is often desired
  11. there exists lots of noise data
  12. the data needs to be fed into backend processes,
    like billing systems
Posted on

on leap seconds and syslog

I was recently asked how syslog handles leap seconds. I thought it would be useful to reproduce my thoughts, initially expressed via private mail, here in the blog.

RFC5424 specifically forbids leap seconds, as during our discussions we found many cases where leap seconds caused grief. I also think the the TAI is considering aborting the use of leap seconds for this reason as well. To the best of my knowledge, GPS also does not use leap seconds. The ultimate reason to abandon UTC leap seconds in syslog was the we failed to identify an operating system that would expose leap seconds to a user process. So a syslogd or any other syslog sender would not even be able to see that one was introduced. From the syslog perspective, a leap second is just like any other second, but time flows “somewhat slower”. I guess we are in the same boat as many operating systems with this perspective.

In RFC5424 we didn’t explicitly state what time stamp should be written during a leap second – because we thought it could actually never happen (why? explained above!). But I would say that “Leap seconds MUST NOT be used” to me means that it should be expressed as the 59th second of said minute. But even if you bump the minute and use the 0 second, I cannot see how this should be problematic. On a single system, time should still evolve serially. For correlating events form multiple systems, the timestamp alone is insufficient in any case. You cannot closely enough synchronize the different real time clocks. So you need a different meachanism (like Lamport clocks) for this in any case.

Posted on

Helping to find major issues in rsyslog…

Rsyslog has a very rapid development process, complex capabilities and now gradually gets more and more exposure. While we are happy about this, it also has some bad effects: some deployment scenarios have probably never been tested and it may be impossible to test them for the development team because of resources needed. So while we try to avoid this, one may see a serious problem during deployments in demanding, non-standard, environments (hopefully not with a stable version, but chances are good you’ll run into troubles with the development versions).

Active support from the user base is very important to help us track down those things. Most often, serious problems are the result of some memory misadressing. During development, we routinely use valgrind, a very well and capable memory debugger. This helps us to create pretty clean code. But valgrind can not detect anything, most importantly not code pathes that are never executed. So of most use for us is information about aborts and abort locations.

Unforutnately, faults rooted in adressing errors typically show up only later, so the actual abort location is in an unrelated spot. To help track down the original spot, libc later than 5.4.23 offers support for finding, and possible temporary relief from it, by means of the MALLOC_CHECK_ environment variable. Setting it to 2 is a useful troubleshooting aid for us. It will make the program abort as soon as the check routines detect anything suspicious (unfortunately, this may still not be the root cause, but hopefully closer to it). Setting it to 0 may even make some problems disappear (but it will NOT fix them!). With functionality comes cost, and so exporting MALLOC_CHECK_ without need comes at a performance penalty. However, we strongly recommend adding this instrumentation to your test environment should you see any serious problems. Chances are good it will help us interpret a dump better, and thus be able to quicker craft a fix.

In order to get useful information, we need some backtrace of the abort. First, you need to make sure that a core file is created. Under Fedora, for example, that means you need to have an “ulimit -c unlimited” in place.

Now let’s assume you got a core file (e.g. in /core.1234). So what to do next? Sending a core file to us is most often pointless – we need to have the exact same system configuration in order to interpret it correctly. Obviously, chances are extremely slim for this to be. So we would appreciate if you could extract the most important information. This is done as follows:

  • $gdb /path/to/rsyslogd
  • $info thread
  • you’ll see a number of threads (in the range 0 to n with n being
    the highest number). For each of them, do the following (let’s assume
    that i is the thread number):

    • $ thread i (e.g. thread 0, thread 1, …)
    • $bt

  • then you can quit gdb with “$q”

Then please send all information that gdb spit out to the development team. It is best to first ask on the forum or mailing list on how to do that. The developers will keep in contact with you and, I fear, will probably ask for other things as well ;)

Note that we strive for highest reliability of the engine even in unusual deployment scenarios. Unfortunately, this is hard to achieve, especially with limited resources. So we are depending on cooperation from users. This is your chance to make a big contribution to the project without the need to program or do anything else except get a problem solved ;)

Posted on

Tools to detect stack adressing Problems?

Since I have begun to use the valgrind memory debugger routinely in rsyslog development (some two years ago), the quality of the source has much increased. Unfortunately, however, valgrind is not able to detect problems related to misaddressing variables on the stack. The 5.3.6 bug I was hunting for almost a week is a good example of this. Valgrind also provides only limited support for global data, as far as I know (and see from testing results).

This becomes an even more important restriction as I moved a lot of former heap memory use to the stack for performance reasons. I remember at least one more major bug hunting effort that was hard to find because it affected only stack space.

So I am currently looking for tools that could complement valgrind by providing good stack checking capabilities. As one tool, mudflap was suggested to me. It sounds interesting, but gives me a very hard time [very hard to read debug output (no symbolic names for dlloade’ed modules, (false?) reports for areas where I can not see anything wrong as well as frequent (threading-related?) crashes when running under instrumentation). Maybe I am just misinterpreting the output…

In short: I would highly appreciate suggestions for tools that can help with debugging stack memory access (global data would be a plus) – and/or instructions on how to interpret mudflap, if that is considered to be *the* tool for that use case.

Thanks,
Rainer

Posted on

rsyslog – feature “schedule”

Every know and then somebody asks what “release schedule” I have on my mind for future rsyslog releases. Today, it happened again, so I’ll do my usual blog post ;). Long time readers of this blog will know that this is a snapshot of what I have on my mind – open source development is quite dynamic and so what I actually implement can be quite different – and has been so in the past. It may be a good time to read my blog post describing how I assign priorities to rsyslog work.

For the foreseeable future, I have two primary things on my mind: one is a set of tools to gain insight knowledge of rsyslog’s inner workings while it is running. This includes statistics, but goes beyond (still, a recent forum post on rsyslog statistics may be an interesting read). This feature is of interest for the community at large, but it is also something that I need to do some in-depth performance analysis plus it is a real great debugging helper. As such, I intend not only to provide the glue inside rsyslog, but also create a full-blown GUI so that the power can actually be used. If nothing comes in the way, this is my top priority for new work (I intended to begin with it during summer time, but then more important things came into its way – but now it is becoming really pressing…).

The next feature I have on my mind is a change to the configuration language, which may also include some core changes. The community complains rightfully that rsyslog’s configuration is a real pain. It is extremely hard to configure some of the most enhanced features – even I need to think hard about how to create some desired results. This is a result of the growth of rsyslog. When the current config system was invented (some three years ago?), we had a handful of low-power commands. This has dramatically changed. For some time, I intended to replace the config language solely by a scripting language. This I no longer believe in. A full-blown scripting language would be a very desirable enhancement, but the base configuration must be done without it (this is also a performance issue). Redoing the config language includes untangling some of the inner workings, adding more flexibility. I am working towards that goal for roughly two and a half month now and that part went well. Now I need to do the next step. I expect that a new config format requires at least a month, more realistic two, to materialize. But adding more features with the current config system is of limited use, because only “expert experts” could configure them. But while the config is important, it is on the second spot on my todo list, right after the GUI and diagnostics tools.

GUI and diagnostics I expect another at least two month to get to something decent. Adding these numbers, I really do not think what the next larger features could be that I intend to implement. If all goes well, I can think about this in spring.

Also, I am currently quite busy with some other, paid, projects. So the time I can spent on rsyslog at the moment is limited. I devote much of this time to fixing bugs, with a primary goal being to get v5 finally ready for prime time (it looks good, but we are not yet fully there).

Also, I notice that adoption rate increases. I notice that by a large growth in support requests both on the mailing list as well as the forum. This is good new, but the bad news is that there are only few frequent contributors. So there is a lot of things that I need to take care of myself, and this needs increasingly more time – time that I obviously do not have for bug-fixing or developing new features. To get things a bit balanced, I have stopped responding to some questions, those that I think either a little google search can lead results to or those that obviously have a primarily commercial background. I’d like to respond to anything – but unfortunately, I simply do not have the time (if I did, rsyslog development would be totally stalled).

As I said, this is just a snapshot of how things look. Maybe tomorrow a sponsor shows up that changes my todo list considerably (we had only very few occurrences of such, but we thankfully had ;)). Even with a sponsor, I am tied with work for the rest of this year, then I have a little vacation, some more paid work, so that I think I can begin working on larger features mid-January, maybe a bit later. Bottom line: don’t take any “schedule” for granted, but I hope you get an overall idea of how things evolve. And: please continue to send in bug reports and feature request. Feature requests are very important – I use them (and their occurrence rate!) to judge how much demand for a feature there is in the community.

Happy syslogging!

Posted on

rsyslog multithreading

From time to time, I receive questions on how many cores rsyslog can run on a highly parallel system. Rsyslog is massivley multi-threaded, but that does not necessarily mean that each configuration, and even each use case, can actually benefit from it.

The most important thing to gain a speedup from parallelism is the ability to break down the workload (this is called “partitioning”) and distribute it to a set of threads, which than can work in parallel on each part.

For the partitioning to work well, the workload, and configuration, must be “partionable”. Let me give a counter-example. If you have a single sender and a single action (yes, this sometimes is the case!), there can not be much parallelism. Such a config looks like this (using imtcp as an example here):

$TCPServerRun 10514
*.* /path/to/file

This can not gain much, because we have on thread for the TCP receiver, one thread for the filtering and one for the output. With the queue engine, we can increase the number of threads that will work on filters in parallel, but these have almost nothing to do in any case. We can not, however, walk in parallel into the output action, because a) the output plugin interface guarantees that only one thread hits a plugin at one time and b) it wouldn’t make much sense here in any case: what would it help if we had hit the output twice and then need top synchronize the file access? No much…

So the bottom line is that a configuration like the one above is highly sequential in nature and consequently there is almost no gain by running some of the tasks concurrently. So, out of the box, rsyslog gains speedup from parallel processing in more complex cases, with more complex rule and many of them.

We are working the provide excellent speedup even for sequential configurations. But this is a long and complex road. For example, in v5 we have now de-coupled message parsing from the receiver thread, resulting in somewhat improved speedup for sequential configs like the one above. Also, we have added batching support in v5, which reduces some overhead involved with multiple threads (and thus reduces the gain we could potentially have). And in late v4 builds we introduced the ability to do double-buffered block i/o for output files, which can considerably reduce i/o overhead for high end systems and also runs in pipeline mode, sequzing a bit more parallelism out of the sequential job.

So with the newer engines, we have been able to apply a basic processing pipeline that looks like

input -> parse & filter -> generate file data -> write

which can be done in parallel. Of course, the file write is action-specific, but I guess you get the idea. What you need to do, however, is configure all that. And even then, you can not expect a 4-time speedup on a quad core system. I’d say you can be happy if the speedup is around 2, depending on a lot of factors.

To get to higher speedups, the job must be made more parallel. One idea is to spread the input, e.g. run it on four ports, then create four rulesets with ruleset queues for each of the inputs. Ideally, to solve the file bottleneck, these should write into four different files. While I did not have the opportunity to test this out in an actual deployment, that should gain a much larger speedup. Because now we have four of this pipelines running in parall, on partitioned data where there is no need to synchronize between them.

Well, almost… The bad news is that the current code base (5.5.0 as of this writing) does unfortunately not yet provide the ability to run the input on more than one thread. So if you have 1000 tcp connections, all of these need to be processed by a single thread (even though they may use different ports, that doesn’t matter…). It is not as bad as it sounds, because the input now is *very* quick (remember the parsing is done concurrently in a different thread [pool!]). But still it causes some loss of parallel processing where not strictly needed. My thinking is that we should either do a “one thread per connection” server (not any longer such a big problem on 64bit machines) or (better but even more effort) do a thread pool for pulling data from the connections. Unfortunately, I do not have time to tackle that beast, but maybe someone is interested in sponsoring that work (that would be *really* useful)?

As you can see, full speedup by using multiple cores is perfectly doable, but going the max requires a lot of careful thinking. And, of course, I have to admit that the best features are present in the newest releases (somewhat naturally…). Obviously, there is some stability risk involved with them, but on the other hand I had some very good success reports from some high-end sites, at least on of them has v5 already deployed in large-scale production.

I could only touch the issue here, but I hope the information is useful. For further reading, I recommend both the doc on queues, as well as my explanation on how messages are processed in rsyslog. These documents are somewhat older and do not cover all details of pipeline processing (which simply did not exist at that time), but I think they will be very useful to read. And, yes, updating them is another thing on my too-long todo list…

Posted on

rsyslog internal messages

I had an interesting conversation with someone who runs multiple instances of rsyslog on a machine for remote reception, only and for some reasons, another syslogd for local messages. The question arose where rsyslog error messages are emitted to.

It was expected that the showed up in the other syslogd. However, that is not the case, and for good reason. So I thought it is good to provide some general advise on how internal messages are emitted.

First of all, internal messages are messages generated by the rsyslog itself. The vast majority of them is error messages (like config error, resource error, unauthorized connect etc…), but there are also some status-like messages (like rsyslogd startup and shutdown, unexpectedly dropping tcp connection, …). Traditionally, rsyslog does not make a distinction between status and error messages (we could change that over time, but so far nobody asked what means this is not worth the hassle).

Rsyslogd is a syslogd, so all message it emits internally are syslog messages. For obvious reasons, they use the “syslog” facility. And as all are flagged as error message, to total priority is “syslog.err”. The internal message source is implicitly bound to the default ruleset.

It now depends on how that ruleset is defined where these messages show up. I strongly encourage everyone to include a rule that logs these message. If there are some e.g. config issues, they can be easily solved by looking at the emitted error message. But if you do not have them, it can take you ages to sort out what is wrong.

So you should always make sure that “syslog.err” (or probably better “syslog.*”) is logged somewhere.

If you now would like to use another syslogd to log these messages, but not rsyslog itself, you do what you usually do in this situation: first of all, make sure that no local rule logs syslog.* messages. Then, include a rule that forward syslog.* to the recipient that you want to receive it. You have the full flexibility of the rule engine at hand to limit or reformat those messages. Note that an elegant solution to do both is including the following 2 lines at the top of rsyslog.conf (I assume you use UDP-forwarding to another syslogd running on the same host machine):



syslog.* @127.0.0.1
& ~

Note that the tilde character is the discard action.