New Queue Defaults in rsyslog 7.5

As regular readers of my blog know, we are moving towards preferring enterprise needs vs. low-end system needs in rsyslog. This is part of the changes in the logging world induced by systemd journal (the full story can be found here).

Many of the main queue and ruleset queue default parameters were a compromise, and much more in favor of low-end systems than enterprises. Most importantly, the queue sizes were very small, done so in an approach to save virtual memory space. With the 7.5.4 release, this will change. While the default size was 10,000 msgs so far, it has been increased 10-fold to 100,000. The main reason is that the inputs nowadays batch together quite some messages, which gives us very good performance on busy systems. It is not uncommon that e.g. the tcp input submits 2,000 messages as once. With the previous defaults, that meant the main queue could hold 5 such submission. Now we got much more head room.

Note that some other changes were made alongside. The dequeue batch size has been increased to 256 from the previous value of 32. The max number of worker threads has been increased to two, removing our previous conservative setting of one. At the same time, we now require at least 40,000 messages to be inside the queue before the second worker is activated. So this will only happen on very busy systems. Note that the previous value of 100 messages was really an artifact of long gone-away times and usually meant immediate activate of the maximum number of workers, what was quite contrary to the intention of that parameter.

Of course, these are just changed defaults. They can always be overridden by explicit settings. For those configs that already did this, nothing changes at all.

imfile multi-line messages

As most of you know, rsyslog permits to pull multiple lines from a text file and combine these into a single message. This is done with the imfile module. Up until version 7.5.3, this lead to a message which always had the LF characters embedded. That usually posed little problem when the same rsyslog instance wrote the message immediately to another file or database, but caused trouble with a number of other actions. The most important example of the latter is plain tcp syslog.

That industry standard protocol uses LF as a frame delimiter. This means a syslog message is considered finished when a LF is seen and everything after the LF is a new message. Unfortunately, the protocol does not provide a special escape mechanism for embedded LFs. This makes it simply impossible to correctly transmit messages with embedded LFs via plain tcp syslog (for more information, see RFC6587, section 3.4).

To solve this situation, rsyslog provides so-called “octet counted” framing, which permits transmission of any characters. While this is a great solution for rsyslog-to-rsyslog transmission, there are few other programs capable of working in that mode. So interoperability is limited.

Even worse, most log processing tools (primarily those working on files) do not expect multi-line messages. Usually they get very confused if LFs are included.

In short, embedded LFs are evil in the logging world. It was probably not a great idea to generate them when imfile processes multi-line messages.

Starting with rsyslog version 7.5.3, this problem has now been solved. Now, imfile escapes LF to the four-character sequence “#012”, which is rsyslog’s standard (octal) control character escape sequence. With this escaping in place, there will neither be problems at the protocol layer nor with other log processing applications. If for some reason embedded LF are needed, there is a new imfile input() parameter called “escapeLF”. If set to “off”, embedded LFs will generated. We assume that when a users does this, he also knows what he does and how to handled those embedded LFs.

This behaviour could obviously break existing configurations. So we have decided not to turn on LF escaping for file monitors defined via legacy statements. These are most probably those that do not want it and also probably long have dealt with the resulting problems.

As always, it is highly suggested that new configurations use the much easier to handle input() statement, which also has LF escaping turned on by default. Note that you cannot use LF escaping together with imfile legacy config statements. In that case, you must switch to the new style.

So this construct:

$InputFileName /tmp/imfile.in
$InputFileTag imfile.in
$InputFileStateFile imfile.in
$InputFileReadMode 1
$InputRunFileMonitor

Needs to become that one:

input(type=”imfile” file=”/tmp/imfile.in”
      statefile=”imfile.in” readMode=”2″ tag=”imfile.in”)

Again, keep in mind that in new style LF escaping is turned on by default, so the above config statement is equivalent to:

input(type=”imfile” file=”/tmp/imfile.in” escapelf=”on”
      statefile=”imfile.in” readMode=”2″ tag=”imfile.in”)

This later sample is obviously also correct.
To turn off LF escaping in new style, use:

input(type=”imfile” file=”/tmp/imfile.in” escapelf=”off”
      statefile=”imfile.in” readMode=”2″ tag=”imfile.in”)

I hope this clarifies reasons, usefulness and how to handle the new imfile LF escaping modes.

rsyslog: why disk-assisted queues keep a file open

From time to time, someone asks why rsyslog disk-assisted queues keep one file open until shutdown. So it probably is time to elaborate a bit about it.

Let’s start with explaining what can be seen: if a disk-assisted queue is configured, rsyslog will normally use the in-memory queue. It will open a disk queue only if there is good reason to do so (because it severely hurts performance). The prime reason to go to disk is when the in memory queue’s configured size has been exhausted. Once this happens, rsyslog begins to create spool files, numbered consequtively. This should normally happen in cases where e.g. a remote target is temporarily not reachable or a database engine is responding extremely slow.  Once the situation has been cleared, rsyslog clears out the spool files. However, one spool file always is kept until you shut rsyslog down. Note well that when the disk queue is idle, all messages are processed even though the the physical spool file still contains some already-processed data (impstats will show you the exact details).

This is expected behaviour, and there is good reason for it. This is what happens technically:

A DA queue is actually “two queues in one”: It is a regular in-memory queue, which has a (second) helper disk queue in case it neeeds it. As long as operations run smoothly, the disk queue is never used. When the system starts up, only the in-memory queue is started. Startup of the disk queue is deferred until it is actually needed (as in most cases it will never be needed).

When the in-memory queue runs out of space, it starts that Disk queue, which than allocates its queue file. In order to reclaim space, not a single file is written but a series of files, where old files are deleted when they are processed and new files are created on an as-needed basis. Initially, there is only one file, which is read and written. And if the queue is empty, this single file still exists, because it is the representation of a disk queue (like the in-memory mapping tables for memory queues always exist, which just cannot be seen by the user).

So what happens in the above case is that the disk queue is created, put into action (the part where it writes and deletes files) and is then becoming idle and empty. At that stage, it will keep its single queue file, which holds the queue’s necessary mappings.

One may now ask “why not shut down the disk queue if no longer needed”? The short answer is that we anticpiate that it will be re-used and thus we do not make the effort to shut it down and restart when the need again arises. Let me elaborate: experience tells that when a system needs the disk queue once, it is highly likely to need it again in the future. The reason for disk queues to kick into action are often cyclic, like schedule restarts of remote systems or database engines (as part of a backup process, for example). So we assume if we used it once, we will most probably need it again and so keep it ready. This also helps reduce potential message loss during the switchover process to disk – in extreme cases this can happen if there is high traffic load and slim in-memory queues (remember that starting up a disk queue needs comparativley long).

The longer answer is that in the past rsyslog tried to shut down disk queues to “save” ressources. Experience told us that this “saving” often resulted in resource wasting. Also, the need to synchronize disk queue shutdown with the main queue was highly complex (just think about cases where we shut it down at the same time the in-memory queue actually begins to need it again!). This caused quite some overhead even when the disk queue was not used (again, this is the case most of the time – if properly sized). An indication of this effect probably is that we could remove roughly 20% of rsyslog’s queue code when we removed the “disk queue shutdown” feature!

Bottom line: keeping the disk queue active once it has been activated is highly desirable and as such seeing a queue file around until shutdown is absolutely correct. Many users will even never see this spool file, because there are no exceptional circumstances that force the queue to go to disk. So they may be surprised if it happens every now and then.

Side-Note: if disk queue files are created without a traget going offline, one should consider increasing the in-memory queue size, as disk queues are obviouly much less efficient than memory queues.

rsyslog on AIX: who wants to help porting?

Thanks to the recent IBM contribution of a partial rsyslog 5.8.6 port to AIX, we have come across that platform again. Unfortunately, some license issues prevent me from merging the IBM contribution to the current rsyslog release (7.4+). I tried to work with IBM resolving these issues, but it just occurred to me that actually doing the port ourselves is probably easier than wrangling with license issues. I could set some time aside to make changes (as a by-activity, aka “may be sluggish at times”), but I neither have time, machines nor know-how. David Lang has already said has has some machines to try compile on, but we still have know-how issues.

So question now: would there some more folks be interested in rsyslog on AIX? If so, could you join a porting effort and provide us with advise? The most pressing thing currently is setting up an environment where we can compile at all. Possibly, once this is done, we may run into issues that require some more in-depth programming know-how, but that’s to be seen (and must must not necessarily happen).

Anyone interested in helping with this please either comment to this blog posting or make yourself heard on the rsyslog mailing list or send me a private mail.

PS: all code derived from this work needs to be placed under ASL 2.0 – just so that you know.

rsyslog under ASL 2.0: why I can’t simply do that

The ASL 2.0 topic boiled up again due to a much-appreciated IBM contribution to make rsyslog 5.8.6 work on AIX. Unfortunately, this contribution was done under GPLv3+. I tried to work with IBM to have it released under ASL 2.0, but their legal department is of the opinion that this is not possible. This resulted in some restrictions, which can be found in the git branches’ README file. Most importantly, it’s a dead-end branch branch which cannot be merged up to new versions.

As an option, IBM said if I would release rsyslog 5.8.6 under ASL 2.0, they could release their patch under ASL 2.0 as well. Unfortunately, I cannot do this by just declaring so.

You need to keep in mind that I do not own the complete copyright! Actually, there are a couple of hundreds contributors that I can find in git history … and there are even more in the original sysklogd, which I can’t even identify all. As such, it is simple impossible for me to change the license “on my own”.
To reach the current state, I did quite intense research on who contributed what some time (two years maybe?) ago. I concentrated on “easy” files (new ones without sysklogd code) and contacted all contributors if they agree on ASL 2.0. Those files that I got agreement on are now under ASL 2.0. For the “hard” files, I even did some research which of them were still from the original syslogd, which was released under BSD. I replaced these files /code sequences with the BSD version (which is identical), and so could put that under ASL 2.0. But still there is a notable body of code left that needs to be under GPLv3+. Some can probably be changed with more author contacting (especially Red Hat contributions, where I have a general “go” for most things), but some code definitely needs to be rewritten. I guess the additional research takes at least some weeks, with the rewrite taking maybe another month or so.

Bottom line: it’s far from being easy and there is no pressing need. But I don’t want to fallback on the effort just because of the IBM contribution. I would need to rewrite it in any case, so there is no point in merging mainstream.

Joining the Guardtime Technical Advisory Board

I just wanted to let everyone know that I will be joining the Guardtime technical advisory board. The board’s prime mission is to make sure that Guardtime implements technology that users need.

While implementing the rsyslog log signature interface and it’s first signature provider, I worked very closely and productive with the Guardtime folks. Over time, we exchanged more and more ideas and the whole thing culminated when I visited their office in Tallinn, Estonia where we had even better discussions and hacking sessions.

Guardtime seems to have enjoyed this work as well, and so I was recently asked if I would like to join their to-be-formed technical advisory board (TAB). At first, I was a bit hesitant because I wondered if there is any collision of interest between being on the Guardtime  TAB and driving rsyslog forward. So I talked a bit with the Guardtime folks clarifying my position. As it turns out, the whole point of the TAB is to assemble experts from different fields and let them discuss and provide information on what end-users really need. The rationale is very obvious: Guardtime as a company can only succeed if they provide what the market really needs. There is no point in trying the market to pick up some product or technology that has no real value. Too many companies tried that in the past and failed miserably. So, in that sense, I can act as the logging user’s agent inside the TAB and help push Guardtime in a direction that really is of value for logging. As I already think their current technology is a really good fit for what we need in logging, this is an exciting opportunity.

I also admit that it is very appealing that I will get ready access to Guardtime’s team of qualified cryptographers (including chief scientist Atho Buldas, who helped building the Estonian national PKI), which is a really big win in regard to secure cryptography in rsyslog. I never before had the chance to work with such top-notch crypto people. In fact, they already provided feedback on the non-Guardtime encryption bits in rsyslog and I am sure that working closer with them will help us getting very solid cryptography into rsyslog. If in doubt, just look at the rsyslog git tree and commit history about when all this new crypto stuff got in :-)

As a side-note, I am also talking with some other party about a custom module using a HMAC based tamper proof system for log records. While this is not as strong as the Gurdtime signature provider, there are obviously some use cases for it as well. If that project materializes, it will of course be merged into the main rsyslog git tree. So, for the concerned, rsyslog will definitely not get a Guardtime bias. After all, my main interest is driving rsyslog forward and, again, you can do that against what “the market” demands.

One of the things I discussed with the Guardtime cryptographers while I was in Tallinn was about how we could extend log integrity proof to a full network relay case, where relays even drop messages. This is a very hard and yet unsolved problem (for details see my paper on log signing in the relay case). While we got no ready solution from the initial discussion, we had some very promising ideas. This for sure is nothing we’ll see within the next quarter or so, but I am happy I now have the opportunity to discuss this and other hard problems with the knowledgeable (and very friendly, btw ;)) folks from Guardtime.

So for me getting on the TAB I think is a win-win-win situation for rsyslog, it’s user base and of course also Guardtime. Hope a lot of good stuff will come out of it.

systemd journal endlessly sends data to imjournal

When Fedora updated to rsyslog 7.4.0 in Fedora 19, they changed the default way how they obtain local log messages. In all previous releases, imuxsock, the traditional Unix/Linux input was used. That also works in conjunction with journal, at least as far as traditional syslog is involved. This is because journal provides these messages via the log socket it passes to rsyslog. Unfortunately, journal hides information if structured content is available. In order to obtain that, Red Hat has contributed a new module, imjournal, which reads the journal database via native journal APIs and as such gets hold of all data. With 7.4.0, the Fedora maintainers switched the default input in the desire to get full logging information into the system.

Unfortunately, rapidly many users begun to report serious problems with duplicate messages exhausting their system resources. As can be seen in this systemd journal database corruption Red Hat bug tracker, the root cause of this problem is that the journal database is corrupted and the native journal API thus endlessly returns the same messages ever and ever again.

The authors of imjournal did not use rsyslog’s ratelimiting capability in this module. Actually, there was good reason not to do it, as journal itself provides some rate-limiting, so doing it twice doesn’t sound like a good idea.

If you dig deeper into the journal bug, you’ll notice that this is not a new problem. It occurs with journal tools as well, and does so obviously for quite a while. In my opinion, it now surfaced as a big issue simply because imjournal was the first application ever to make serious use of the journal database.

After I received reports on this problem, I acted immediately. First and foremost, I put a warning message into imjournal telling about the risk on relying on the journal database. I can obviously not solve that problem, but then I mitigated it by adding rate-limiting to the module. The current git version by default does not permit more than 20,000 messages within a 10 minute interval, so even with a broken journal, no more than 120,000 messages per hour should be emitted. That’s as far as I can go handling this situation. Note that there is already a fix for the current problem in journal, it is also included in the bug tracker I mentioned above. However, in the past couple of weeks I talked to quite some folks on rsyslog/journal integration, and journal database corruption was frequently mentioned. Nobody told me about loops, but as I guard against future problems, I will keep the ratelimiting default active in imjournal.

Note that the rsyslog project “officially” always suggested to use imjournal only in cases where there is hard need for it (this was a result of talking to the end users). Thankfully I published a presentation on rsyslog and systemd journal integration including this fact just last week, so I can even proof that recommendation ;)

How will we go forward? If you need a quick patch, you should rebuild rsyslog from the git v7-stable branch. For a single patch that addresses the ratelimiting, you can use this one. The full patch set will be included in 7.4.1. We are working with Red Hat to release it ASAP, hopefully tomorrow.

Another viable solution is to simply disable imjournal in rsyslog.conf and replace it with the former imuxsock configuration. Please note that this problem does not affect any version of rsyslog installed from Adiscon’s repositories. This is because we never use imjournal by default.

I hope this clarifies the root cause of this problem, how to mitigate it and how the rsyslog team intends to prevent further harm from potential systemd journal database corruption.

rsyslog performance: main and action queue workers

Rsyslog has both “main” message queues and action queues. [Actually, “main message queues” are queues created for a ruleset, “main message” is an old-time term that was preserved even though it is no longer accurate.]

By default, both queues are set to one worker maximum. The reason is that this is sufficient for many systems and it can not lead to message reordering. If multiple workers are concurrently active, messages will obviously be reordered, as the order now, among others, depends on thread scheduling order.

So for now let’s assume that you want to utilize a multi-core machine. Then you most probably want to increase the maximum number of main message queue workers. The reason is that main queue workers process all filters for all rules inside the rule set, as well as full action processing for all actions that are not run on an asynchronous (action) queue. In typical setups, this offers ample of opportunity for concurrency. Intense tests on the v5 engine have shown near linear scalability to up to 8 cores, with still good improvements for higher number of cores (but increasing overhead). Later engines do most probably even better, but have not been rigorously performance tested (doing it right is a big effort in itself).

Action queues have a much limited concurrency potential because they do only a subset of the work (no filtering, for example, just generating the strings and executing the actual plugin action). The output module interface traditionally permits only one thread at a time to be present within the actual doAction() call of the plugin. This is to simply writing output plugins, but would be needed in any case as most can not properly handle real concurrent operations (think for example about writing to sequential files or a TCP stream…). For most plugins, the doAction() part is what takes most processing time. HOWEVER, multiple threads on action queues can build string concurrently, which can be a time consuming operation (especially when regexpes are involved). But even then it is hard to envision that more than two action queue worker threads can make much sense.

So the bottom line is that you need to increase the main queue worker threads to get much better performance. If you need to go further, you can fine-tune action queue worker threads, but that’s just that: fine-tuning.

Note that putting “fast” actions (like omfile) on an async action queue just to be able to specify action threads is the wrong thing to do in almost all situations: there is some inherent overhead with scheduling the action queue, and that overhead will most probably eat up any additional performance gain you get from the action queue (even more so, I’d expect that usually it will slow things down).

Action queues are meant to be used with slow (database, network) and/or unreliable outputs.

For all other types of actions, even long-running, increasing the main queue worker thread makes much more sense, because this is where most concurrency is possible. So for “fast” action, use direct action queues (aka “no queue”) and increase the main thread workers.

Finally a special note on low-concurrency rulesets. Such rulesets have limited inherent concurrency. A typical example is a ruleset that consists of a single action. For obvious reasons, the number of things that can be done concurrently is very limited. If it is a fast action, and there is little effort involved in producing the strings (most importantly no regex), it is very hard to gain extra concurreny, especially as a high overhead is involved with such fine-grained concurrency. In some cases, the output plugin may come to help. For example, omfile can do background writes, which will definitely help in such situations.

You are in a somewhat better shape if the string builder is CPU intense, e.g. because it contains many and complex regexes. Remember that strings can be build in parallel to executing an action (if run on multiple threads). So in this case, it makes sense to increase the max number of threads. It makes even more sense to increase the default batch size. That is because strings for the whole batch are build, and then the action plugin is called. So the larger the batch, the large these two partitions of work are. For a busy system, a batch size of 10,000 messages does not sound unreasonable in such cases. When it comes to which worker threads to increase, again increase the main queue workers, not the action ones. It must be iterated that this gives the rsyslog core more concurrency to work with (larger chunks of CPU bound activity) and avoids the extra overhead (though relatively small) of an async action queue.

I hope this clarifies worker thread settings a bit more.

recent librelp development

I thought I share some news on what I have been busy with and intend to be in the future. In the past days, I have added more config options to librelp, which now supports GnuTLS compression methods as well as provides the ability to set the Diffie-Hellman key strength (number of bits) and – for experts – to set the GnuTLS priorities, which select the cipher methods and other important aspects of TLS handling.

This is done now and I also added rsyslog facilities to use these new features. Some of this stuff is not yet released, but will soon be.

The next big step is preventing man-in-the-middle attacks. I will most probably use SSH-type fingerprint authentication, so that no full PKI is necessary to make this work. I guess implementing this feature set will probably take a couple of days and will keep you posted on how things progress.

What is a rsyslog signature provider?

Some folks asked what a (rsyslog) signature provider is. In essence, it is just a piece of software written to a specific interface.

There are little functional requirements for signature providers. Most obviously, we expect that it will provide some useful way to sign logs, what means it should be able to provide an integrity proof of either a complete log file or even some log records some time after the logs are recorded.

There is no “official signature provider spec” available. As usual in open source, the provider interface is well defined inside its actual source header file. Take a look for example at rsyslog’s git to see the definition.

If you look at that code, the interface is fairly simple. The primary entry points a programmer needs to define are

  • OnFileOpen
  • OnRecordWrite
  • OnFileClose

As the names imply, they are called whenever a log file is opened, written to, and closed. Again, what the provider does at these events is up to the provider.

The initial provider that ships directly with rsyslog is using a secure remote signing service provided by Guardtime.  There are various reasons why I selected this provider, and I elaborated at length on them in my blog posting on why I selected Guardtime as first rsyslog signature provider. In a nutshell, it is a method that does not rely on local secrets and as such can not be circumvented (again: details in my other posting). Obviously, Guardtime offers paid services, but they also operate free services for everyone to use (a key point when I evaluated that technology).

If you have privacy concerns about the Guardtime provider, you may want to read my blog posting on just that question.

Note that signature provider implementations can use the above entry points in any way they like. For example, the may ignore file open and close and do all work in record write. So this small interface is highly flexible. If you look at the full interface description, you’ll also see some more events which primarily provide housekeeping functionality. If you intend to write your own signature provider, I suggest to start with a copy of the guardtime provider and change it according to your needs. That way, you have a great example of how the housekeeping calls are handled.