Enhanced printk() with Enterprise Event Logging

 

What is enhanced printk ?. 1

Why not just add information to the printk() message?. 2

How do I install this feature?. 2

Now that its installed, how can I best use it?. 3

Example of default event Formatting….. 3

Example of modifying event formating by editing the formatting template (plus, compact formatting)…   5

Example of custom event formatting using evlview command options….. 5

Example of providing a canned, user-defined event display format….. 6

Example of displaying event data in syslog format….. 6

 

 

What is enhanced printk ?

 

It is an optional feature of Enterprise Event Logging that records additional information with printk() messages that are forwarded to event logging:

    • printk() caller's  information:
      • Source file name
      • Function name
      • Line Number
    • A unique "reference code" computed as the checksum of source file name, function name, and original printk() format string.    

 

This features requires no changes to the existing printk() arg list, nor to any code that calls printk() (except code that assumes that printk isn’t a macro...).  In addition to the above information, all event records created from forwarded printk() messages also contain the following:

    • log_recid                  System-assigned ID of the event record
    • log_size                    Size of the event record variable data, which contains the formatted printk() message,  along with the printk() caller's information .
    • log_format                A BINARY event record is created which provides signifiicant flexibility in what gets displayed by how it is formatted
    • log_event_type          Set to the reference code described above.
    • log_facility               Always equal to LOG_KERN, since all printk() messages use this facility.
    • log_severity              Always equal to the severity passed to printk(), or the default severity that printk assigns (WARNING) if caller does not provide it.
    • log_uid                      Effective user ID associated with the event
    • log_gid                      Effective group ID associated with the event
    • log_pid                      Process ID associated with the event
    • log_pgrp                    Process group associated with the event
    • log_time                    Event Time stamp (time printk() was called)
    • log_flags                   The INTERRUPT flag is set if printk() was called from interrupt context.  The PRINTK flag is always set for these events.
    • log_thread                 Thread ID associated with event
    • log_processor            Processor ID associated with event

 

    • The original formatted printk() message.

 

 

Note that when the enhanced printk() event is displayed with the evlview command, the hostname can also be displayed.  By comparison, syslogd writes the following information to the destination(s) defined by syslog.conf:

 

    • Time of message
    • Hostname
    • The original formatted printk() message.

 

When enhanced printk is enabled, the original messages are still written unchanged to the printk() ring buffer and read and processed by klogd and syslogd exactly as before.

 

When enhanced printk and event logging are disabled, the impact of event logging on kernel resources is essentially zero.

 

Why not just add information to the printk() message?
 

The 2 main reasons:
 

    1. Additional information in /var/log/messages (and other output destinations) would require any existing parsing scripts to be modified to recognize the additional data.
    2. The printk() ring buffer size would need to be increased for handling the extra data and console messages from printk would be longer.

 

Some other considerations:

 

    1. The printk() function and klogd and syslogd daemons record everything as text strings, thus increasing the complexity and overhead associated with parsing the data.  For more details see the side-by-side comparison of printk/syslog and evlog.
    2. For cases where the additional information is not desirable, forwarding of printks (with the extra data) to event logging can be disabled, or event logging itself can be completely disabled.
    3. System admins may be accustomed to seeing information in /var/log/messages, etc. in a particular format, and modifying that information could be confusing or misleading.

 

 

How do I install this feature?

 

You will need to download the 2.4.18 or 2.4.19 version of the Linux Kernel from http://www.kernel.org/pub/linux/kernel/v2.4/ and install the following patches available from the event logging website.

 
evlog-1.4.2_kernel2.4.18.patch / evlog-1.4.2_kernel2.4.19 - implements event logging in the kernel and offers the
following options:
·               CONFIG_EVLOG -- Provides an API (i.e., an alternative to printk()) for writing events from the kernel to the enterprise event log.
·               CONFIG_EVLOG_FWPRINTK (requires CONFIG_EVLOG) -- Forwards a copy of each printk message to the enterprise event log.
·               CONFIG_EVLOG_PRINTKWLOC (requires CONFIG_EVLOG_FWPRINTK) -- Includes caller’s location along with each printk message logged to the enterprise event log.
 
 
Additionally, you will need to download and install the user-space library and utilities.   All of this is available from 
https://sourceforge.net/project/showfiles.php?group_id=34226, along with installation 
instructions for the kernel patches and user lib/utilities.
 
 

Now that its installed, how can I best use it?

 

The evlview command is used to read and display events from the event log.  There are numerous options available for displaying events created from printk() messages:

 

1.     Use default formatting

2.     Modify the formatting template

3.     Use compact formatting

4.     Specify custom formatting using evlview command options

5.     Specifying a canned, user-defined display format with the evlview -F option

6.     Displaying event data in "syslog message" format

 

 

To illustrate, take a couple of messages written to /var/log/messages by syslogd:

 

  Jun 12 12:18:49 elm3b99 kernel: hda: LTN485S, ATAPI CD/DVD-ROM drive

  Jun 12 12:18:49 elm3b99 kernel: ide0 at 0x1f0-0x1f7,0x3f6 on irq 14

  Jun 12 12:18:49 elm3b99 kernel: hda: ATAPI 48X CD-ROM drive, 120kB Cache, UDMA(33)

  Jun 12 12:18:49 elm3b99 kernel: Uniform CD-ROM driver Revision: 3.12

Example of default event Formatting…

 

If these had been forwarded to event logging, then this command:

 

  evlview -N 2 -f 'flags & PRINTK'

 

would display the following:

 

  recid=501, size=65, format=BINARY, event_type=0x9e7f906a, facility=KERN,

  severity=NOTICE, uid=root, gid=root, pid=1, pgrp=0,

  time=Wed 12 Jun 2002 12:17:52 PM PDT, flags=0x22 (KERNEL|PRINTK), thread=0x0,

  processor=1

  ide-probe.c:do_identify:152

  hda: LTN485S, ATAPI CD/DVD-ROM drive

 

  recid=503, size=61, format=BINARY, event_type=0xac7f7c84, facility=KERN,

  severity=NOTICE, uid=root, gid=root, pid=1, pgrp=0,

  time=Wed 12 Jun 2002 12:17:55 PM PDT, flags=0x22 (KERNEL|PRINTK), thread=0x0,

  processor=1

  ide-probe.c:init_irq:738

  ide0 at 0x1f0-0x1f7,0x3f6 on irq 14

 

  recid=505, size=93, format=BINARY, event_type=0xd175d27e, facility=KERN,

  severity=NOTICE, uid=root, gid=root, pid=1, pgrp=0,

  time=Wed 12 Jun 2002 12:17:55 PM PDT, flags=0x22 (KERNEL|PRINTK), thread=0x0,

  processor=1

  ide-cd.c:ide_cdrom_probe_capabilities:2707

  hda: ATAPI 48X CD-ROM drive, 120kB Cache, UDMA(33)

 

  recid=507, size=64, format=BINARY, event_type=0xfada1960, facility=KERN,

  severity=INFO, uid=root, gid=root, pid=1, pgrp=0,

  time=Wed 12 Jun 2002 12:17:55 PM PDT, flags=0x22 (KERNEL|PRINTK), thread=0x0,

  processor=1

  cdrom.c:register_cdrom:352

  Uniform CD-ROM driver Revision: 3.12

 

Note the use of -N (--newlines) to put spaces between each event, and -f (--filter) to indicate a filter expression, which in this case checks for the PRINTK flag.

 

Notice by comparing the first line in /var/log/messages with the first event record that the time from the printk() message is:

Jun 12 12:18:49

while the time from the associated event record is:

          Wed 12 Jun 2002 12:17:52 PM PDT

The difference of 57 seconds is due to the fact that the timestamp in the event record reflects when printk() was actually called; whereas, the timestamp in the printk() message is added by the syslogd daemon.  Also, note a 3-second difference between the first and last 3 event records.   This time difference is not reflected in the /var/log/messages entries.

 

The default display for event records is as follows:

 

  Header containing standard attributes:

recid=503, size=61, format=BINARY, event_type=0xac7f7c84, facility=KERN,

severity=NOTICE, uid=root, gid=root, pid=1, pgrp=0,

time=Wed 12 Jun 2002 12:17:55 PM PDT, flags=0x22 (KERNEL|PRINTK), thread=0x0,

processor=1

 

  Variable-length event data:

ide-probe.c:init_irq:738   ç location where printk() was called       

ide0 at 0x1f0-0x1f7,0x3f6 on irq 14  ç original printk() message 

 

By default, formatting of the variable-length portion is determined by the formatting template.  In this case,  /var/evlog/templates/kern/kern.t contains:

 

/*

 * If your kernel is built to forward printk messages to evlog, and to

 * include the caller's location information (file, function, line) with

 * each printk**, then you should compile this template (evltc kern.t).

 * This template enables evlview to display the printk message and location

 * information in a legible format.  (If you don't like the format, change

 * the last line of this file and recompile.)

 *

 * ** In menuconfig, it's configured thus:

 * General setup  --->

 * [*] Enterprise event logging support

 * (nnn) Eventlog buffer size (in K bytes)

 * [*] Forward printk messages to enterprise event log

 * [*] Include caller information with printk records

 */

facility "kern";

event_type default;

attributes {

        string msg;

        string file;

        string function;

        int line;

}

format

%file%:%function%:%line%

%msg%

 

Example of modifying event formating by editing the formatting template (plus, compact formatting)…

 

 

Alternative formatting can be accomplished by modifying the template, kern.t.  For example, changing the "format" specification to:

 

format

%file%/%function%()/%msg%

 

and issuing the commands:

         

evltc /var/evlog/templates/kern/kern.t  ç compiles template

evlview -N 2 -f 'flags & PRINTK' -c  -s :

 

displays the following:

         

501:65:BINARY:0x9e7f906a:KERN:NOTICE:root:root:1:0:Wed 12 Jun 2002 12:17:52 PM PDT:0x22 (KERNEL|PRINTK):0x0:1

ide-probe.c/do_identify()/hda: LTN485S, ATAPI CD/DVD-ROM drive

 

503:61:BINARY:0xac7f7c84:KERN:NOTICE:root:root:1:0:Wed 12 Jun 2002 12:17:55 PM PDT:0x22 (KERNEL|PRINTK):0x0:1

ide-probe.c/init_irq()/ide0 at 0x1f0-0x1f7,0x3f6 on irq 14

 

505:93:BINARY:0xd175d27e:KERN:NOTICE:root:root:1:0:Wed 12 Jun 2002 12:17:55 PM PDT:0x22 (KERNEL|PRINTK):0x0:1

ide-cd.c/ide_cdrom_probe_capabilities()/hda: ATAPI 48X CD-ROM drive, 120kB Cache, UDMA(33)

 

507:64:BINARY:0xfada1960:KERN:INFO:root:root:1:0:Wed 12 Jun 2002 12:17:55 PM PDT:0x22 (KERNEL|PRINTK):0x0:1

cdrom.c/register_cdrom()/Uniform CD-ROM driver Revision: 3.12

 

and also illustrates use of the -c (--compact) and -s (--separator) options.

 

Example of custom event formatting using evlview command options…

 

To illustrate use of custom formatting, the following command:

 

  evlview -N 2 -f 'flags & printk' -b -S '%time%:

  %host%,%facility%,%severity%,%event_type%,%function%() --\n%msg%'

  -d "%B %d %H:%M:%S"

[I recommend using a date format here that is (1) terser, and (2) more distinct from the default format.

 

would yield the following output:

 

  June 12 12:17:52: elm3b99,KERN,NOTICE,0x9e7f906a,do_identify() --

  hda: LTN485S, ATAPI CD/DVD-ROM drive

 

  Wed June 12 12:17:55 PM: elm3b99,KERN,NOTICE,0xac7f7c84,init_irq() --

  ide0 at 0x1f0-0x1f7,0x3f6 on irq 14

 

  Wed June 12 12:17:55PM:elm3b99,KERN,NOTICE,0xd175d27e,

  ide_cdrom_probe_capabilities() --

  hda: ATAPI 48X CD-ROM drive, 120kB Cache, UDMA(33)

 

  Wed June 12 12:17:55 PM: elm3b99,KERN,INFO,0xfada1960,register_cdrom() --

  Uniform CD-ROM driver Revision: 3.12

 

Note the use of -b (--templates) so that non-standard attributes ("function" in this case) are accepted, -S (--formatstr) to indicate alternative format string, and -d (--datefmt) so that date is displayed according to the provided dateformat string (which is passed to strftime() ).

 

 

Example of providing a canned, user-defined event display format…

 

 

If you wanted to use this custom formatting often, you could simply store this portion:

 

  '%time%: %host%,%facility%,%severity%,%event_type%,%function%() --\n%msg%'

 

in a file, say /var/evlog/cust_fmt, and then issue this command:

 

  evlview -N 2 -f 'flags & printk' -b -F /var/evlog/cust_fmt

  -d "%a %B %d %l:%M:%S %p"

 

which would display:

 

  Wed June 12 12:17:52 PM: elm3b99,KERN,NOTICE,0x9e7f906a,do_identify() --

  hda: LTN485S, ATAPI CD/DVD-ROM drive

 

as before.   The  -F (--formatfile) option specifies a file where the alternative format string is read from.

 

 

The following command:

 

  evlview -N 2 -f 'event_type=0x9e7f906a'

 

would yield the following output:

 

  recid=501, size=65, format=BINARY, event_type=0x9e7f906a, facility=KERN,

  severity=NOTICE, uid=root, gid=root, pid=1, pgrp=0,

  time=Wed 12 Jun 2002 12:17:52 PM PDT, flags=0x22 (KERNEL|PRINTK), thread=0x0,

  processor=1

  ide-probe.c/do_identify()/hda: LTN485S, ATAPI CD/DVD-ROM drive

 

and illustrates the use of event_type, which is calculated from source file name, function name, and printk() format string, as an attribute in a filter expression.  This could be useful for finding all instances of a specific call to printk().

 

Example of displaying event data in syslog format…

 

The following command:

 

  evlview --syslog

 

displays the event data in "syslog message" format:

 

  Jun 12 12:17:52 elm3b99 kernel: hda: LTN485S, ATAPI CD/DVD-ROM drive

  Jun 12 12:17:55 elm3b99 kernel: ide0 at 0x1f0-0x1f7,0x3f6 on irq 14

  Jun 12 12:17:55 elm3b99 kernel: hda: ATAPI 48X CD-ROM drive, 120kB Cache, UDMA(33)

  Jun 12 12:17:55 elm3b99 kernel: Uniform CD-ROM driver Revision: 3.12

 

And finally, the following script:

 

  lastrid=`cat /var/evlog/bootrecid`

  nextrid=`expr $lastrid + 1`

  evlview -n -R $nextrid -f 'flags & printk' --syslog >> /var/log/printks

 

would  run continuously,  appending to /var/log/printks all messages logged by the kernel's printk() function, starting with the first message after the current boot.  The message format is that of the syslogd daemon.   Note use of the -n (--new) and -R (--recid) options.