Logging in linux kernel

Содержание

Chapter 13. Getting started with kernel logging
13.1. What is the kernel ring buffer
13.2. Role of printk on log-levels and kernel logging
Message logging with printk¶
Function reference¶

Chapter 13. Getting started with kernel logging

Log files are files that contain messages about the system, including the kernel, services, and applications running on it. The logging system in Red Hat Enterprise Linux is based on the built-in syslog protocol. Various utilities use this system to record events and organize them into log files. These files are useful when auditing the operating system or troubleshooting problems.

13.1. What is the kernel ring buffer

During the boot process, the console provides a lot of important information about the initial phase of the system startup. To avoid loss of the early messages the kernel utilizes what is called a ring buffer. This buffer stores all messages, including boot messages, generated by the printk() function within the kernel code. The messages from the kernel ring buffer are then read and stored in log files on permanent storage, for example, by the syslog service.

The buffer mentioned above is a cyclic data structure which has a fixed size, and is hard-coded into the kernel. Users can display data stored in the kernel ring buffer through the dmesg command or the /var/log/boot.log file. When the ring buffer is full, the new data overwrites the old.

Additional resources

13.2. Role of printk on log-levels and kernel logging

Each message the kernel reports has a log-level associated with it that defines the importance of the message. The kernel ring buffer, as described in What is the kernel ring buffer, collects kernel messages of all log-levels. It is the kernel.printk parameter that defines what messages from the buffer are printed to the console.

The log-level values break down in this order:

0 — Kernel emergency. The system is unusable.
1 — Kernel alert. Action must be taken immediately.
2 — Condition of the kernel is considered critical.
3 — General kernel error condition.
4 — General kernel warning condition.
5 — Kernel notice of a normal but significant condition.
6 — Kernel informational message.
7 — Kernel debug-level messages.

By default, kernel.printk in RHEL 8 contains the following four values:

# sysctl kernel.printk kernel.printk = 7 4 1 7

The four values define the following:

value. Console log-level, defines the lowest priority of messages printed to the console.
value. Default log-level for messages without an explicit log-level attached to them.
value. Sets the lowest possible log-level configuration for the console log-level.
value. Sets default value for the console log-level at boot time. Each of these values above defines a different rule for handling error messages.

Читайте также: What computers use linux

The default 7 4 1 7 printk value allows for better debugging of kernel activity. However, when coupled with a serial console, this printk setting is able to cause intense I/O bursts that could lead to a RHEL system becoming temporarily unresponsive. To avoid these situations, setting a printk value of 4 4 1 7 typically works, but at the expense of losing the extra debugging information.

Also note that certain kernel command line parameters, such as quiet or debug , change the default kernel.printk values.

Additional resources

Источник

Message logging with printk¶

printk() is one of the most widely known functions in the Linux kernel. It’s the standard tool we have for printing messages and usually the most basic way of tracing and debugging. If you’re familiar with printf(3) you can tell printk() is based on it, although it has some functional differences:

printk() messages can specify a log level.
the format string, while largely compatible with C99, doesn’t follow the exact same specification. It has some extensions and a few limitations (no %n or floating point conversion specifiers). See How to get printk format specifiers right .

All printk() messages are printed to the kernel log buffer, which is a ring buffer exported to userspace through /dev/kmsg. The usual way to read it is using dmesg .

printk() is typically used like this:

printk(KERN_INFO "Message: %s\n", arg);

where KERN_INFO is the log level (note that it’s concatenated to the format string, the log level is not a separate argument). The available log levels are:

The log level specifies the importance of a message. The kernel decides whether to show the message immediately (printing it to the current console) depending on its log level and the current console_loglevel (a kernel variable). If the message priority is higher (lower log level value) than the console_loglevel the message will be printed to the console.

If the log level is omitted, the message is printed with KERN_DEFAULT level.

You can check the current console_loglevel with:

$ cat /proc/sys/kernel/printk 4 4 1 7

The result shows the current, default, minimum and boot-time-default log levels.

To change the current console_loglevel simply write the desired level to /proc/sys/kernel/printk . For example, to print all messages to the console:

# echo 8 > /proc/sys/kernel/printk

sets the console_loglevel to print KERN_WARNING (4) or more severe messages to console. See dmesg(1) for more information.

As an alternative to printk() you can use the pr_*() aliases for logging. This family of macros embed the log level in the macro names. For example:

pr_info("Info message no. %d\n", msg_num);

prints a KERN_INFO message.

Besides being more concise than the equivalent printk() calls, they can use a common definition for the format string through the pr_fmt() macro. For instance, defining this at the top of a source file (before any #include directive):

#define pr_fmt(fmt) "%s:%s: " fmt, KBUILD_MODNAME, __func__

would prefix every pr_*() message in that file with the module and function name that originated the message.

For debugging purposes there are also two conditionally-compiled macros: pr_debug() and pr_devel() , which are compiled-out unless DEBUG (or also CONFIG_DYNAMIC_DEBUG in the case of pr_debug() ) is defined.

Function reference¶

used by the pr_*() macros to generate the printk format string

format string passed from a pr_*() macro

Description

This macro can be used to generate a unified format string for pr_*() macros. A common use is to prefix all pr_*() messages in a file with a common string. For example, defining this at the top of a source file:

#define pr_fmt(fmt) KBUILD_MODNAME «: » fmt

would prefix all pr_info, pr_emerg. messages in the file with the module name.

Description

This is printk() . It can be called from any context. We want it to work.

If printk indexing is enabled, _printk() is called from printk_index_wrap. Otherwise, printk is simply #defined to _printk.

We try to grab the console_lock. If we succeed, it’s easy — we log the output and call the console drivers. If we fail to get the semaphore, we place the output into the log buffer and return. The current holder of the console_sem will notice the new output in console_unlock() ; and will send it to the consoles before releasing the lock.

One effect of this deferred printing is that code which calls printk() and then changes console_loglevel may break. This is because console_loglevel is inspected when the actual printing occurs.

See the vsnprintf() documentation for format string extensions over C99.

Print an emergency-level message