Re: [PATCH-RFC] POSIX Event Logging, kernel 2.5.6 & 2.4.18

Re: [PATCH-RFC] POSIX Event Logging, kernel 2.5.6 & 2.4.18

[Larry Kessler]

Brian,

I am responding to your comments in reverse order:

> 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

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.

> I understand about POSIX standards, but POSIX standards are not the
> infallible word of of the diety of computing and sometimes are
> completely bogos.

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.

> 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...
> ...it maye be possible to provide some formating guidelines
> and support to printk and some log analysis tools to provide 99%
> solution.

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/

Re: [PATCH-RFC] POSIX Event Logging, kernel 2.5.6 & 2.4.18y

[Alan Cox]

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

What you don't want to do is break printk. In AberMUD I used macros for
something similar

#define Module  static char *Mod_Name=
#define Version static char *Ver_Name=
#define Author  static char *Aut_Name=

#define Error(x)        ErrFunc((x),Mod_Name,Ver_Name,__LINE__,__FILE__)

And drivers started

Module  "System";
Version "1.28";
Author  "----*(A)";


However that doesn't work for varargs. Nevertheless something of a similar
approach might let you avoid breaking printk in most old code. If you can
avoid a grand replacement of printk you win lots of friends. If you can
do it in a way that people can do automated parsing of kernel messages
for translation tables in klogd/initlog/dmesg you also win lots of friends.

Re: [PATCH-RFC] POSIX Event Logging, kernel 2.5.6 & 2.4.18

[Larry Kessler]

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

Ideally, you are right.  But messing around with the printk
functionality is risky and could be unpopular in the community,
especially if you are only conserving what really amounts to
a small amount of memory (16,32 or 64K, for printk ring buffer).

> 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.

So I think what you want is to set a "watch" for certain events and
when those event(s) are written to the buffer (1) trigger some action, 
like halting the machine, and (2) save the last n events leading-up to 
the trigger-action.  You might also want to initiate a crash-dump and 
be able to retrieve the pinned events from the dump.

Am I on the right track ?  Can you give me some idea which information
you would watch for in the events (facility, severity, event_type,
etc.)?  

> And I think a flexible policy will allow everybody to
> be
> happy with your framework. the only way to get it accepted, right?

Its not clear that the sort of requirement you are describing...
...In secure mode the system must be halted on overflow...
is needed by the majority of potential event logging users, so could
what you are asking for be implemented as a kernel module ?

Re: [PATCH-RFC] POSIX Event Logging, kernel 2.5.6 & 2.4.18

[Larry Kessler]

> Bernd wrote...
> Of course it is only useful if it is not another framework because this will
> lead to kernel clutter. So do we want to replace netlink and printk?

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 ?      

> Well, depending on the type of events one can even think about a "halt" like
> it is required for audit trail overflow.

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.

> What would be nice is a policy for each type of event:
>
> - overwrite old/new/halt
> - rate limit
> - buffer size

>From the beginning our design appoach has been to "write everything"
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/

Re: [PATCH-RFC] POSIX Event Logging, kernel 2.5.6 & 2.4.18

[Bernd Eckenfels]

In article <3C8FF7C7.5CA133B0@us.ibm.com> you wrote:
> 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.

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

> 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 ?      

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.

> 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.

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.

> 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.

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?

> 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.    

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

Greetings
Bernd

Re: [PATCH-RFC] POSIX Event Logging, kernel 2.5.6 & 2.4.18

[Brian Beattie]

On Wed, 2002-03-13 at 17:07, Larry Kessler wrote:
> > Bernd wrote...
> > Of course it is only useful if it is not another framework because this will
> > lead to kernel clutter. So do we want to replace netlink and printk?
> 
> 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. 
> 

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.

Re: [PATCH-RFC] POSIX Event Logging, kernel 2.5.6 & 2.4.18

[Larry Kessler]

Brian,

I am responding to your comments in reverse order:

> 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

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.

> I understand about POSIX standards, but POSIX standards are not the
> infallible word of of the diety of computing and sometimes are
> completely bogos.

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.

> 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...
> ...it maye be possible to provide some formating guidelines
> and support to printk and some log analysis tools to provide 99%
> solution.

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/

[PATCH-RFC] POSIX Event Logging, kernel 2.5.6 & 2.4.18

[Larry Kessler]

Please cc: kessler@us.ibm.com with your comments.

Patch for kernel version 2.5.6:
http://prdownloads.sourceforge.net/evlog/evlog-1.3.0_kernel2.5.6.patch
Patch for kernel version 2.4.17, 2.4.18:
http://prdownloads.sourceforge.net/evlog/evlog-1.3.0_kernel2.4.17.patch

This patch, in combination with the event logging and event
notification user library, provides a comprehensive event 
logging package based on the draft POSIX standard 1003.25.
See http://evlog.sourceforge.net/ for details and downloads.

A summary of the kernel patch:
1) A static kernel buffer is implemented for POSIX events logged
   in the kernel.  Size is configurable during kernel build.
2) If the buffer overruns the oldest events are kept, newest
   discarded, and a count of discarded events is reported.
3) Optionally, POSIX events can be created from printk messages
   (printk messages still go to /var/log/messages, as before)
4) Functions are provided for: 
   - logging directly to kernel event buffer (text string or
     binary data which gets formatted outside of the kernel)
   - registering facilities beyond the standard ones in syslog.h
     (device drivers can have facility other than KERN)
5) Events are displayed on the system console as single-line
   summary messages (based on printk's default console logging level).

Please be clear that this is NOT intended to replace printk and
syslog, but to coexist with them and provide additional 
capabilities not available with printk/syslog that are highly 
desirable in large servers and Telecom environments (to name a few).

Larry Kessler

Re: [PATCH-RFC] POSIX Event Logging, kernel 2.5.6 & 2.4.18

[Dominik Kubla]

On Tue, Mar 12, 2002 at 02:15:36PM -0800, Larry Kessler wrote:
> 2) If the buffer overruns the oldest events are kept, newest
>    discarded, and a count of discarded events is reported.

Hmm. That sounds like a possible security problem to me: simply generate a
bunch of harmless messages to fill the buffer and then one can do the nasty
stuff...

Dominik Kubla
-- 
ScioByte GmbH    Zum Schiersteiner Grund 2     55127 Mainz (Germany)
Phone: +49 700 724 629 83                    Fax: +49 700 724 629 84
1024D/717F16BB    A384 F5F1 F566 5716 5485  27EF 3B00 C007 717F 16BB

Re: [PATCH-RFC] POSIX Event Logging, kernel 2.5.6 & 2.4.18

[Larry Kessler]

Dominik Kubla wrote:
> 
> On Tue, Mar 12, 2002 at 02:15:36PM -0800, Larry Kessler wrote:
> > 2) If the buffer overruns the oldest events are kept, newest
> >    discarded, and a count of discarded events is reported.
> 
> Hmm. That sounds like a possible security problem to me: simply generate a
> bunch of harmless messages to fill the buffer and then one can do the nasty
> stuff...

I assume that you mean do the nasty stuff but never have anything in
your
event log indicating that it happened.  Good point, but if the buffer is
sized appropriately for the incoming volume of events and the logging
daemon 
is reading the events out of the kernel buffer (as should normally be
the case), 
then you would see the events.  

The reasoning behind this approach is to increase the liklihood that
events
indicating "root cause" would be logged and not over-written by a flood
of 
secondary events.  Keep in mind that only events originating in the
kernel (or
kernel module) are stored in this buffer.

Re: [PATCH-RFC] POSIX Event Logging, kernel 2.5.6 & 2.4.18

[Bernd Eckenfels]

In article <3C8E8912.64435C1E@us.ibm.com> you wrote:
> I assume that you mean do the nasty stuff but never have anything in
> your
> event log indicating that it happened.  Good point, but if the buffer is
> sized appropriately for the incoming volume of events and the logging
> daemon 
> is reading the events out of the kernel buffer (as should normally be
> the case), 
> then you would see the events.  

Well, depending on the type of events one can even think about a "halt" like
it is required for audit trail overflow.

What would be nice is a policy for each type of event:

- overwrite old/new/halt
- rate limit
- buffer size

Re: [PATCH-RFC] POSIX Event Logging, kernel 2.5.6 & 2.4.18

[Bernd Eckenfels]

In article <3C8E7E08.C3CF4227@us.ibm.com> you wrote:
> Please be clear that this is NOT intended to replace printk and
> syslog, but to coexist with them and provide additional 
> capabilities not available with printk/syslog that are highly 
> desirable in large servers and Telecom environments (to name a few).

Thinks I could think of, which produce a large amount are iptables logs, audit
messages and network debug logs like rejected packets, discarded packages due
to checksum failures, route changes, interface changes, etc.

Of course it is only useful if it is not another framework because this will
lead to kernel clutter. So do we want to replace netlink and printk?

Greetings
Bernd