Kernel Logging — printk, Log Levels, and dmesg-Free Linux kernel development course

Previous Lecture
Next Lecture

Linux Kernel Programming
Chapter 4  |  Part 5 of 6
Kernel Logging — printk, Log Levels, and dmesg
📚 Essential
⏱ ~20 min
🔐 Kernel 6.x

🔍 Topics Covered
printk()
Log Level Macros
pr_info / pr_err / pr_debug
dev_info / dev_err
dmesg command
Kernel Ring Buffer
Console Log Level
Dynamic Debug

🎯 Why Logging Matters in Kernel Development

In user-space programming you can use a debugger like GDB to stop execution, inspect variables, and step through code. In kernel development, attaching a debugger is much more complicated. Your primary tool for understanding what the kernel is doing is logging — and printk() is how you log from kernel code. Mastering printk and its ecosystem is not optional; it is a daily survival skill for any kernel developer.

📥 printk() — The Kernel’s Logging Function

printk() is the kernel equivalent of printf(). The name stands for “print kernel.” It works similarly to printf but with one critical difference: every message has a log level prepended to it that controls where and whether the message appears.

/* Basic printk syntax */
printk(KERN_INFO "This is an informational message\n");
printk(KERN_ERR  "Something went wrong: error %d\n", err_code);
printk(KERN_DEBUG "Value of x = %d\n", x);

The log level prefix (KERN_INFO, KERN_ERR, etc.) is a string literal that gets concatenated with your format string by the C preprocessor. There is no comma between the log level and the format string — they are adjacent string literals that the compiler merges into one.

printk is safe to call from almost anywhere in the kernel — from interrupt handlers, from spinlock-held sections, during early boot — though it has limitations in atomic contexts (it may not always flush immediately). It is not async-signal-safe like printf, but it is designed to work even when the system is in trouble.

⚠ printk does not go to your terminal. It writes to the kernel ring buffer. You read it with dmesg. If a message’s log level is below the current console log level threshold, it also appears on the system console (tty1, serial console, etc.).

📌 Kernel Log Levels — All Eight Levels Explained

Linux defines eight log levels, numbered 0 (most urgent) through 7 (least urgent). Lower number = more important.

Linux Kernel Log Levels
Level Macro pr_* Shorthand Meaning & When to Use
0 — EMERG KERN_EMERG pr_emerg() System is unusable. Used before a kernel panic.
1 — ALERT KERN_ALERT pr_alert() Action must be taken immediately (e.g., data corruption detected).
2 — CRIT KERN_CRIT pr_crit() Critical conditions (hardware failure, severe software error).
3 — ERR KERN_ERR pr_err() Error conditions. Use when an operation has failed. Most common error level in drivers.
4 — WARNING KERN_WARNING pr_warn() Warning conditions. Something unexpected but not fatal. System continues.
5 — NOTICE KERN_NOTICE pr_notice() Normal but significant events (e.g., driver loaded successfully).
6 — INFO KERN_INFO pr_info() Informational messages. Most common level for normal module operation messages.
7 — DEBUG KERN_DEBUG pr_debug() Debug-level messages. Only printed when debug is enabled. Use generously for development.

Rule of thumb for kernel module development: Use pr_info() for normal status messages, pr_warn() for recoverable unexpected conditions, pr_err() when an operation fails, and pr_debug() for detailed tracing during development.

📄 pr_* Macros — The Modern Way to Log

Instead of typing printk(KERN_INFO "...") every time, modern kernel code uses the pr_* convenience macros. They are shorter, cleaner, and carry the same information.

#include <linux/kernel.h>

/* These are all equivalent forms - use pr_* in modern code */

/* Old style: */
printk(KERN_INFO "Module loaded, version %d\n", version);

/* Modern style — preferred: */
pr_info("Module loaded, version %d\n", version);

/* ---- All pr_* macros ---- */
pr_emerg("EMERGENCY: system cannot continue\n");
pr_alert("ALERT: immediate action required\n");
pr_crit("CRITICAL: hardware malfunction detected\n");
pr_err("ERROR: failed to allocate memory, ret=%d\n", ret);
pr_warn("WARNING: deprecated feature used\n");
pr_notice("NOTICE: device connected on port %d\n", port);
pr_info("INFO: driver initialized successfully\n");
pr_debug("DEBUG: entering function %s, x=%d\n", __func__, x);

One very useful macro is pr_fmt(). You can define it at the top of your source file to automatically prepend your module name to every pr_* message. This makes it easy to filter your module’s messages out of dmesg.

/* Define this BEFORE including linux/kernel.h */
#define pr_fmt(fmt) KBUILD_MODNAME ": " fmt

#include <linux/module.h>
#include <linux/kernel.h>

/* Now every pr_* call automatically gets your module name prepended */
pr_info("Hello!\n");
/* Outputs: "[ 1234.5678] hello: Hello!" in dmesg */

🔌 dev_* Macros — Logging for Device Drivers

When writing device drivers, you often want to include the device name and bus address in your log messages automatically. The dev_* macros do this for you by taking a pointer to a struct device as their first argument.

#include <linux/device.h>

/* struct device *dev comes from your driver's probe() function */

dev_err(dev,  "Failed to request IRQ %d\n", irq_num);
dev_warn(dev, "Timeout waiting for hardware\n");
dev_info(dev, "Device initialized at address 0x%08x\n", base_addr);
dev_dbg(dev,  "Register value: 0x%04x\n", reg_val);

The output from dev_info(dev, "Ready\n") looks like:

[  234.567890] i2c i2c-1: 0050: Ready
               ^^^^^^^^^^^^^^^^^^^
               Device name automatically added by the kernel

This is extremely helpful in systems with many devices — you immediately know which device generated the message without having to add the device name manually to every log line.

🔄 The Kernel Ring Buffer and dmesg

All printk output is stored in the kernel ring buffer — a fixed-size circular buffer in kernel memory. “Ring” means that when it fills up, the oldest messages are overwritten by new ones. The default size is typically 512KB to 1MB, configurable via CONFIG_LOG_BUF_SHIFT at kernel build time.

The Kernel Ring Buffer

Ring
Buffer
(fixed size)

New messages
written here ↓
Old messages
overwritten ↑
dmesg
reads
from
here

When the buffer fills up, oldest messages are silently discarded.

The dmesg command reads this ring buffer and prints it to your terminal.

# Show all kernel messages:
dmesg

# Show last N lines only:
dmesg | tail -20

# Follow in real time (like tail -f):
dmesg -w
dmesg --follow

# Show with human-readable timestamps:
dmesg -T
# [Mon Jan 15 10:23:45 2024] hello: Module loaded

# Show with relative timestamps (time since boot):
dmesg -r

# Filter by log level — show only errors and above:
dmesg --level=err,crit,alert,emerg

# Clear the ring buffer:
sudo dmesg -C

# On systemd systems — kernel messages with journalctl:
journalctl -k              # kernel messages this boot
journalctl -k -b -1        # kernel messages from previous boot
journalctl -k -f           # follow kernel messages live

💻 Console Log Level — What Gets Printed to the Terminal

Not all printk messages appear on your console (the physical screen or serial terminal). The kernel has a console log level threshold: only messages with a log level number lower than this threshold are printed to the console. Messages at or above the threshold go to the ring buffer only.

# Read the current log level settings:
cat /proc/sys/kernel/printk
# Output: 4  4  1  7
#         ^  ^  ^  ^
#         |  |  |  └── default_message_loglevel (for messages with no level specified)
#         |  |  └───── minimum_console_loglevel (can't set console level below this)
#         |  └──────── default_console_loglevel (new consoles start at this level)
#         └─────────── console_loglevel (CURRENT threshold — only < this prints to console)

With a console_loglevel of 4, messages at KERN_ERR (3), KERN_CRIT (2), KERN_ALERT (1), and KERN_EMERG (0) are printed to the console. KERN_WARNING (4) and lower-priority messages (higher numbers) only go to the ring buffer.

# Temporarily set console log level (shows everything including DEBUG):
sudo sh -c 'echo 8 > /proc/sys/kernel/printk'

# Or use the dmesg command:
sudo dmesg -n 8   # set console level to 8 (show all)
sudo dmesg -n 4   # restore default (errors and above only)

# Permanently via sysctl:
sudo sysctl -w kernel.printk="4 4 1 7"

🛠 Dynamic Debug — Enabling pr_debug at Runtime

pr_debug() and dev_dbg() are compiled out by default — they produce no code unless CONFIG_DYNAMIC_DEBUG is enabled in the kernel configuration (which most distribution kernels enable). When dynamic debug is available, you can enable specific debug messages at runtime without recompiling.

# Enable all debug messages from a specific module:
echo "module hello +p" | sudo tee /sys/kernel/debug/dynamic_debug/control

# Enable debug for a specific source file:
echo "file hello.c +p" | sudo tee /sys/kernel/debug/dynamic_debug/control

# Enable debug for a specific function:
echo "func hello_init +p" | sudo tee /sys/kernel/debug/dynamic_debug/control

# Disable (remove +p flag):
echo "module hello -p" | sudo tee /sys/kernel/debug/dynamic_debug/control

# See what is currently enabled:
cat /sys/kernel/debug/dynamic_debug/control | grep hello

Dynamic debug is extremely powerful for production systems — you can get detailed debug output from a specific driver without rebooting or recompiling, then turn it off again when done.

🏆 Interview Questions — Kernel Logging
Q1. Why can’t kernel code use printf()? What is the equivalent?
printf() is part of the C standard library (glibc), which is a user-space library. Kernel code does not link against glibc. The kernel equivalent is printk(), which writes to the kernel ring buffer instead of stdout. Modern kernel code uses the pr_* convenience wrappers (pr_info, pr_err, etc.).
Q2. What is the kernel ring buffer?
It is a fixed-size circular buffer in kernel memory where all printk output is stored. It is “ring” shaped because when it fills up, new messages overwrite the oldest ones. The dmesg command reads from this buffer. The size is configured at kernel build time via CONFIG_LOG_BUF_SHIFT (default typically 512KB to 1MB).
Q3. What are the 8 kernel log levels in order from most to least urgent?
EMERG (0), ALERT (1), CRIT (2), ERR (3), WARNING (4), NOTICE (5), INFO (6), DEBUG (7). Lower number = higher priority = more urgent.
Q4. What is the difference between pr_debug() and pr_info()?
pr_info() always generates log output (at KERN_INFO level). pr_debug() is compiled out to a no-op unless CONFIG_DYNAMIC_DEBUG is enabled, or CONFIG_DEBUG_KERNEL is set. Even when compiled in, pr_debug() messages only appear when the console log level is 8 or they are specifically enabled via the dynamic debug control file.
Q5. What is the advantage of dev_err() over pr_err()?
dev_err() takes a struct device pointer and automatically prepends the device name, bus type, and address to the log message. This is extremely useful in systems with multiple devices because you can immediately identify which device generated the error without manually adding device information to every log statement.
Q6. How do you view kernel messages from the previous boot?
On systemd-based systems, use: journalctl -k -b -1 (kernel messages, previous boot). The ring buffer itself is lost on reboot, but systemd-journald persists kernel messages to disk. On older systems without journald, kernel crash logs may be captured by tools like kdump.

Up Next: Part 6 — The Kbuild System and Module Makefile
Understand the Kbuild system deeply, multi-file modules, conditional compilation, and cross-compilation.

← Part 4
Part 6: Kbuild & Makefile →

Previous Lecture
Next Lecture

Leave a Reply

Your email address will not be published. Required fields are marked *