There is a race-condition when running rsyslog 1.20.0 or any previous release in multi-threaded mode. The probability for it to happen is very remote, but there definitely is a design flaw in it. Quick communication revealed, unfortunately, that this flaw can not be responsible for the hard to track segfault bug. The segfault occurs in a situation that does not match what I have found out. I discovered this problem when I worked on multi-threading re-design and focussed on input modules. Maybe my decision to hold off redesign until after the segfault bug has been found was wrong. Redesign forces me to look at more places from a very different angle and that may reveal even more (at lest I hope so).
Now here is the story on the “mark” race condition I discovered today:
fprintlog() duplicates the message object when we have a “last message repeated n times”. It does this by saving the pointer to the message object in a temporary buffer, carries out its work and then checks if it needs to restore the saved pointer. This works well in single threading as well as in almost all cases when running multi-threaded. However, if we reach a mark interval domark() calls fprintlog() potentially concurrently to a call that is already in place. What can happen is:
- domark() calls fprintlog() on an action
- fprintlog() begin execution and saves the previous message to the buffer
- fprintlog() is preempted
- the worker thread now calls into fprintlog() with the exact same message
- fprintlog() processes the message and finishes (deletes it)
- now processing of that thread ends and our first thread is resumed
- fprintlog() performs its actions and restores the already freed message object pointer
Now, the action holds an invalid pointer. Depending on what happens next, it either aborts (if the buffer has been overwritten) or continues to function but does a double-free.
The root cause is that access to the action object is not synchronized. This was deemed unnecessary, because there could be no concurrent write operations be in place. The domark() processing, however, had been overlooked.
This analysis is still preliminary, but points into a good direction. It needs to be said, though, that the probability for this failure scenario is remote. I have confirmed this is a race condition.
If you think about it, the mark() processing as a whole does not make much sense if we have a full queue. It is awfully flawed. I don’t like mark(): in the original sysklogd code, there was a similar issue: mark() was called by an alarm() timer and executed the full syslogd code during its processing. Given that lead to serious problems if some other message was being processed. I solved that issue by setting just a flag() in the alarm() handler. Then, actual mark() processing was started in the mainloop(). For single threading mode that works, because no other thread can be in the action processing at that time.
In multi-threaded mode, however, the mainloop() runs on a thread different from the work thread. So in fact, domark() can once again conflict with action processing. And if the queue is full, it does totally wrong things: because it uses whatever message is currently being processed as basis for emiting mark messages. This is seriously flawed! The root cause is that mark() processing does not go through the producer/consumer queue/gateway. This is what I now need to fix.
What mark() does is first to inject the “–mark–” message. That is no problem, because it is injected via the regular producer interface logmsgInternal(). But then, it calls domarkActions() on each action which in turn calls fprintlog(). It also accesses the messages then-current f_prevcount, which, with a full queue, has nothing to do with the last element being seen at that time.
The more I look at the code, the more I wonder what exact useful feature it is. I just checked the cuttren sysklogd source, and, yes, it still is there (even that domark() is being called in an alarm() handler is still there…). Interestingly, in both sysklogd and rsyslogd the “last message repeated n times” periodic display is turned off when mark messages are turned off. Is this intentional? I doubt so…
So what did the original sysklogd author think when he wrote that post? I guess he wanted to have an indication that messages had been dropped – and this not only when the next message with different text arrived, but after a set period (30 seconds with the current defines both in rsyslog and sysklogd). So message compression should indicate at least every 30 seconds that messages arrived, but were compressed. OK, that gives me something to think about.
Obviously, there is no point in emitting the “last message repeated n times” message if we have, let’s say, 100 identical message sitting in the queue followed from at least one non-identical message. In that case, the queue will be processed as fast as possible and upon arrival at the non-identical message, the “repeat message” will be issued. No need to say anything in between. If, however, there is no such non-identical message, rsyslogd is left in a somewhat open state. The queue is depleted but still no output is written (but “n” messages have not been displayed). Only in this scenario it is appropriate to start a timeout timer that will ultimately lead to the “repeated message” when no further non-identical message arrives in the allocated time window.
To be more precisely, it is not actually a question of messages being in the queue. As we have sophisticated filtering with rsyslog, the question actually is if a message was processed (e.g. written to file) by an action within the “repeated message” time window (RMTW). When the last message has been processed can be quite different from action to action.
One way to track this is to keep track when each action last successfully was called. If the queue is reasonable full and the action is supplied with reasonable, to be processed, data on a steady rate, that time should never fall outside of the RMTW. And if it does, isn’t that an indication that it is time to write a “repeated message” out, so that the operator is seeing at least one indication in every RMTW? Of course it is! So we can store this timer with each action and use it as a base check.
Now, we can periodically awake and check each action object; did it last process something outside of its RMTW AND does it have any repeated messages received? If so, it is time to emit the “repeated message” message. The fine difference to existing code is that we use the newly constructed timer here. Also, the action object must be locked, so that this background process and the worker thread(s) will not access the same vital data structures at the same time. The scenario from the top of this post would otherwise still apply. Finally, this processing should be de-coupled from the mark processing, because IMHO these are two totally separate things.
I will now go ahead and apply these changes and then we shall see where this bring us.
I have now done a first implementation. Actually, the code does not look that much different compared to before the change. The difference is that I have handled the timestamp thing a bit more transparently and, the biggie, I have used synchronization macros to guard the action object against the race condition. This code will become part of 1.20.1.