POSIX Event Logging, kernel 2.5.6 & 2.4.18

I checked and there are nearly 41,000 calls to printk in the 2.5.6 kernel. Getting every maintainer to change to event logging's write functions
would be impossible. Instead we want to provide enhanced logging features
for new and updated device drivers and other kernel code--more of a "slow
migration over time" approach. We provided the feature that creates POSIX
event records from printks so that System Admins, field service, developers
testing and debugging their code (just to name a few) could still take advantage of the new tools provided with the user lib (too numerous to mention,
but see the spec on the website) for handling printk messages.

Of course, even with better tools there may still be those who only want to see
printks in /var/log/messages. It has even been suggested that events in the
event log which did not originate with printk should also be written to /var/log/messages, for this very reason.

Another way to "replace" printk is not to replace the function itself, but
instead combine printk's ring buffer with the event logging buffer, but still
the end-user would see events in the event log and/or messages in /var/log/messages. A proposal like that at this point in time would probably
be too radical, but is certainly a possibility.

I am sorry, I am not really familiar with netlink. Please explain why you
think netlink could be (or perhaps should be) replaced with event logging ?

I think the point you are making is that there are certain events that you
never under any circumstances want to miss or discard because of their importance. printk does not address this nor does it report the fact that
messages in the ring buffer have even been overwritten. Event logging is a little better, but it does not prevent the loss of events either.

One scheme we have thought of is to add dynamic event buffer allocation, so
that if the static event buffer overflows additional dynamic buffering will
activate until the logging daemon can read-out the events. Another possibility is the "selective" discarding of lower severity events when the
event buffer reaches a high-water mark.

into the
kernel buffer (or at least try) and apply policies, screening, filtering,
etc. only in user-space for both performance reasons and to reduce the complexity of the code in the kernel. Given the relatively low occurance
of events overruning the buffer; or, evlogd logging daemon not running and
draining them out, the "per-event type" policy you seem to be suggesting
*I think* would add more complexity than dynamically allocating more buffer
space when needed. Please elaborate if you disagree.

Regards,
Larry Kessler
http://evlog.sourceforge.net/

Yes, I think it is at least needed to share the ring buffer.

There are different uses for netlink, but one of the most common is event signalling (high performance) for routing and interface changes. Also denied/accounted/accepted packets need to be logged by something like ulogd because printk is not the right solution for that.

Posix and BSD Auditing events are an example for that. In secure mode the system must be halted on overflow. a printk replacement will want to keep the oldest entries and a enterprise event system may want to keep the oldest.

yes, but even larger dynamic kernel buffers will not stop you from running into full buffers. And I think a flexible policy will allow everybody to be happy with your framework. the only way to get it accepted, right?

I agree, it adds more complexity. Simple solutions are prefered, as long as they are solutions :)

Greetings
Bernd

Watching this whole event logging thing for a while, I wonder if a slightly different approach might not be better. Instead of adding extra kernel functionality, would it not be possible to define a text format to messages and some SIMPLE macros, to allow printk's to generate the desired information.

I understand about POSIX standards, but POSIX standards are not the infallible word of of the diety of computing and sometimes are completely bogos. While they do provide a thoughtful plan, they are not IMHO some holy grail. for silly standards, see the recent stuff about names for K = 10^6 vs. K= 2^10.

So if one drops strict POSIX compliamce and goes for providing the information, it maye be possible to provide some formating guidelines and support to printk and some log analysis tools to provide 99% solution.

One thing to remember, is that the really hard and important part of logging is not the part that can be legislated, or automated, it is making sure that the correct events are reported in a accurate manner, and this is not a one time job. This being the case, I would rather see effort expended in rationalizing the current printk's and improving their use, than adding some new infrastructure that may well be a perfromance drain and might even be more prone to loss of log messages, than the current method.

Brian,

I am responding to your comments in reverse order:

I could not agree more, and there has not really been any guidance for developers about what correct and accurate events are (nor is it clear that developers would follow the guidance, anyway). Our focus, obviously, has been on whether or not the existing logging capabilities facilitate the accurate recording of "correct" events. I will comment more on that below.

True, but in this case the POSIX standard is not a standard, but currently only a draft, and we (the Linux event logging team) have been (and are continuing to be) directly involved it its writing, editing, and (eventual, we hope) adoption as a standard. Even so, balloting could lead it into a direction that is contrary to what is best for Linux, in which case we would drop the "POSIX compliant" claims and do what's really needed. I do not expect that to happen, but you can never tell.

Ok, I am not conceding that your suggestion is "better" than event logging, but I do like the concept and we have, in fact, been discussing how to somehow get more information out of printk without asking kernel maintainers to use a different API. Specifically, we thought about renaming the printk() function and creating a printk macro. In the printk macro you would collect source file name, line number and function
name (and maybe some other useful info), and then call the renamed printk function with the original message plus the additional stuff (actually we were thinking call posix_log_write() with the orig. message+
addl. info and call the renamed printk with just the original message).

Is this the sort of thing you had in mind ?

The problem we found is some code like this...

printk("<1>" "And the answer is... %d\n",
#ifdef ONE
1
#else
2
#endif
);

which the compiler/preprocessor rejects.

Just casually looking I found at least 3 device drivers that log this way.
Do you think device driver maintainers would be willing to change their code to avoid this problem (and the Linux community be willing to abandon this style of coding with printks)?

I don't know if you've had a chance to look at the event filtering, event
notification, and log management utilities that we have in the user lib, but these work with text-based events, whether printks forwarded to event
logging, or messages logged with our new logging functions. So the user lib does have some log analysis/processing features like you've mentioned.

Another limitation that printk has is that everything has facility of LOG_KERN. Don't you think its useful to be able to define a facility of "XYZ Ethernet 10/100 Device Driver" (which in event logging generates a 32-bit CRC that gets stored in the event records, and gets converted back
to the facility name by the aforementioned utilities)?

I am absolutely open to suggestions for making printk messages better and more useful--we just haven't figured-out how yet.

Thanks,
Larry Kessler
http://evlog.sourceforge.net/