Home | Projects | Notes > Linux Device Drivers > Debugging with printk & Kernel Log Levels

Debugging with `printk` & Kernel Log Levels

Debugging with `printk`

print is one of the best debugging tools we have in user-level applications.
When you work in kernel space, you will not have any access to the C standard library functions like printf or scanf.
As their counterpart, the kernel has its own printf-like API called printk, where the letter k signifies "Kernel space printing".

Examples;


xxxxxxxxxx
4
1
printf("User space.\n");
2
printk("Kernel space.\n");                      /* Kernel space */
3
printf("data1 = %d, data2 = %d\n, d1, d2");
4
printk("data1 = %d, data2 = %d\n, d1, d2");     /* Kernel space */

When using printk, the message will go into the kernel ring buffer (a.k.a. Kernel log) and we can print and control the kernel ring buffer using the command dmesg.
To check the latest 5 kernel messages:
```
xxxxxxxxxx
1
1
dmesg | tail -5
```
To check the first 20 kernel messages:
```
xxxxxxxxxx
1
1
dmesg | head -20
```

printk format specifiers


xxxxxxxxxx
14
1
Variable Type       printk Format Specifier
2
==================  =======================
3
int                 %d or %x
4
unsigned int        %u or %x
5
long                %ld or %lx
6
unsigned long       %lu or %lx
7
long long           %lld or %llx
8
unsigned long long  %llu or %llx
9
size_t              %zu or %zx
10
ssize_t             %zd or %zx
11
s32                 %d or %x
12
u32                 %u or %x
13
s64                 %lld or %llx
14
u64                 %llu or %llx

printk does not support floating-point formats (%e, %f, %g).

[!] Reference: https://www.kernel.org/doc/Documentation/printk-formats.txt

Kernel Log Levels

Based on the kernel log level you can control the priority of the printk messages.

There are 8 log levels

The lower the level number, the higher the priority
The default printk log level or priority is usually set to 4. (i.e., KERN_WARNING)


xxxxxxxxxx
15
1
/* include/linux/kern_levels.h */
2

3
#define KERN_SOH        "\001"          /* ASCII Start Of Header */
4
#define KERN_SOH_ASCII  '\001'
5

6
#define KERN_EMERG      KERN_SOH "0"    /* system is unstable */
7
#define KERN_ALERT      KERN_SOH "1"    /* action must be taken immediately */
8
#define KERN_CRIT       KERN_SOH "2"    /* critical conditions */
9
#define KERN_ERR        KERN_SOH "3"    /* error conditions */
10
#define KERN_WARNING    KERN_SOH "4"    /* warning conditions */
11
#define KERN_NOTICE     KERN_SOH "5"    /* normal but significant condition */
12
#define KERN_INFO       KERN_SOH "6"    /* informational */
13
#define KERN_DEBUG      KERN_SOH "7"    /* debug-level messages */
14

15
#define KERN_DEFAULT    ""              /* the default kernel loglevel */

The log level will be used by the kernel to understand the priority of the message. Based on the priority the kernel will decide whether the message should be presented to the user immediately by printing directly on to the console.
All kernel messages will have their own log level.

You may have to specify the log level while using printk. If not specified, the kernel will add the default log level set by the kernel config item CONFIG_MESSAGE_LOGLEVEL_DEFAULT whose value is 4.

So, the following statement


xxxxxxxxxx
1
1
prink("Kernel space\n");

is equivalent to


xxxxxxxxxx
3
1
prink(KERN_WARNING "Kernel space\n");
2
//    ------------  --------------
3
//      Log level      String arg

Notice that there's NO comma (,) between the log level and the string argument!

Default message log level can be configured via the kernel menuconfig (make ARCH=arm menuconfig)

Significance of the Kernel Log Level

There is another log level we need to consider; the current console log level.
The kernel message log level will be compared with the current console log level. If the kernel message log level is lower (i.e., higher priority) than the current console log level, the message will be directly printed on the current console.
By default, the console log level will have the value of config item CONFIG_CONSOLE_LOGLEVEL_DEFAULT whose default value is set to 7. This value can be changed via the kernel menuconfig or running commands.
To check the current console log level status, run
```
xxxxxxxxxx
2
1
cat /proc/sys/kernel/printk
2
7       4       1       7
```
The results shows the current, default, minimum and boot-time-default log levels.
pr_info (i.e., KERN_INFO level) used in the hello world LKM is of log level 6. This is why the message is getting printed when the LKM gets inserted into the kernel.
At run-time, you can change the current console log level (for example to 6) by running the following command:
```
xxxxxxxxxx
2
1
sudo -s
2
echo 6 > /proc/sys/kernel/prink
```
Now, if you check the current console log level:
```
xxxxxxxxxx
2
1
cat /proc/sys/kernel/printk
2
6       4       1       7
```
The current console log level has changed from 7 to 6.
Since the current console log level is now the same as pr_info (i.e., KERN_INFO level), the message will not get printed when the hello world LKM gets inserted into the kernel.

prink wrappers (Defined in include/linux/printk.h)

Name	Log Level	Alias Function
KERN_EMERG	"0"	pr_emerg
KERN_ALERT	"1"	pr_alert
KERN_CRIT	"2"	pr_crit
KERN_ERR	"3"	pr_err
KERN_WARNING	"4"	pr_warning
KERN_NOTICE	"5"	pr_notice
KERN_INFO	"6"	pr_info
KERN_DEBUG	"7"	pr_debug (works only if DEBUG is defined)
KERN_DEFAULT	""	-

pr_err - Useful for reporting errors
pr_info - Useful for printing general information
pr_warning - Useful for reporting warning
pr_alert, pr_crit - Useful for reporting critical situations

For example:


xxxxxxxxxx
1
1
printk(KERN_INFO "Kernel version 4.14\n");

Can be re-written as


xxxxxxxxxx
1
1
pr_info("Kernel version 4.14\n");

Debugging with printk & Kernel Log Levels

Debugging with printk

Kernel Log Levels

Significance of the Kernel Log Level

Debugging with `printk` & Kernel Log Levels

Debugging with `printk`