1. Why Would You Write to the Kernel Log from User Space?

When you are debugging a Linux kernel module, you typically add printk() calls inside your kernel code. These appear in the kernel ring buffer and are visible via dmesg. So far so good.

But consider this scenario: you have a user space test script that exercises your kernel module. It opens a device file, sends commands, checks return values — a full automated test sequence. The kernel module emits its own log messages throughout. Now you are staring at dmesg output and trying to figure out which kernel messages correspond to which test step.

Without some form of synchronization in the log, the output looks like a tangled stream. You cannot tell whether a particular kernel warning happened before or after a specific test action.

The ideal solution is to have your test script write its own marker messages directly into the kernel log. That way, the dmesg timeline contains both user space events and kernel events in a single, coherent, timestamped stream that is easy to correlate.

2. The /dev/kmsg Interface

Linux exposes the kernel message buffer through a special character device: /dev/kmsg. Writing to this file injects a message into the kernel ring buffer, exactly as if a printk() inside the kernel had been called. Reading from it gives you a structured stream of kernel log entries.

Basic write syntax

# This injects a message into the kernel log
# Requires root privileges
echo "testscript: starting Phase 1 tests" > /dev/kmsg

After writing that line, dmesg will show your message alongside kernel messages, with a proper timestamp prefix.

The sudo redirect gotcha

A common mistake is trying to use sudo with shell redirection like this:

# This DOES NOT work — the redirect happens as the non-root user
sudo echo "testscript: marker" > /dev/kmsg

The shell opens /dev/kmsg for writing before sudo runs echo. Since the shell itself is not root, the redirect fails with a permission denied error. The correct approaches are:

# Option 1: Use bash -c with sudo (the entire command runs as root)
sudo bash -c 'echo "testscript: starting Phase 1 tests" > /dev/kmsg'

# Option 2: Get a root shell first, then use redirect freely
sudo -s
echo "testscript: starting Phase 1 tests" > /dev/kmsg
echo "testscript: Phase 1 complete" > /dev/kmsg
exit

# Option 3: Use tee with sudo (works because tee is the writer, not the shell)
echo "testscript: starting Phase 1 tests" | sudo tee /dev/kmsg > /dev/null

Verifying the message appeared in the kernel log

# Check the last few kernel log lines
dmesg | tail -n 5

# Or watch in real-time
dmesg -w

3. Specifying Log Levels When Writing to /dev/kmsg

When you write a plain string to /dev/kmsg without specifying a log level, the kernel assigns it the current default console log level, which is typically KERN_WARNING (level 4). This affects how tools like dmesg --decode display the message.

You can override the log level by prefixing your message with the level number enclosed in angle brackets:

# Log level 3 = KERN_ERR
sudo bash -c 'echo "testscript: critical failure detected" > /dev/kmsg'

# Log level 4 = KERN_WARNING (same as default)
sudo bash -c 'echo "testscript: resource not found, retrying" > /dev/kmsg'

# Log level 5 = KERN_NOTICE
sudo bash -c 'echo "testscript: Phase 1 complete" > /dev/kmsg'

# Log level 6 = KERN_INFO
sudo bash -c 'echo "testscript: starting Phase 2 tests" > /dev/kmsg'

# Log level 7 = KERN_DEBUG
sudo bash -c 'echo "testscript: debug checkpoint A" > /dev/kmsg'

4. Making dmesg Output More Readable

By default, dmesg shows raw kernel timestamps (seconds since boot) which are hard to correlate with wall clock time. The tool has several flags that transform this into something much more useful during debugging sessions.

# Human-readable timestamp, decoded log level, no pager, colors
dmesg --decode --nopager --color --ctime

# A convenient alias for your .bashrc or .zshrc
alias kdmesg='dmesg --decode --nopager --color --ctime'

With --ctime, timestamps appear as human-readable dates. With --decode, the log level prefix appears as a readable label like user:warn instead of the raw number. With --color, different severity levels get different colors in the terminal — errors appear in red, warnings in yellow, making it much faster to scan for problems.

# Example output with --decode --ctime
user :info  : [Thu Jun 12 09:31:05 2025] mymodule: probe successful
user :warn  : [Thu Jun 12 09:31:06 2025] testscript: starting Phase 1 tests
kern :warn  : [Thu Jun 12 09:31:06 2025] mymodule: unexpected register value 0x1f
user :info  : [Thu Jun 12 09:31:07 2025] testscript: Phase 1 complete

With this output you can immediately see that the kernel warning from your module happened while Phase 1 was running — exactly the kind of correlation you need during debugging.

5. Using /dev/kmsg in Automated Test Scripts

Here is a practical shell script pattern that uses /dev/kmsg to create a structured, correlated test log for a kernel module under test:

#!/bin/bash
# test_mymodule.sh — Automated test script with kernel log markers
# Must be run as root: sudo bash test_mymodule.sh

LOGDEV="/dev/kmsg"
MODULE="mymodule"
DEVICE="/dev/mydevice"

# Helper: write a timestamped marker to the kernel log at KERN_INFO level
klog() {
    echo "test_mymodule: $1" > "${LOGDEV}"
}

# ── Phase 0: Setup ──────────────────────────────────────────────
klog "=== TEST RUN START ==="
klog "Loading kernel module: ${MODULE}"
modprobe "${MODULE}"
sleep 0.2

klog "Module loaded — checking /proc/modules"
grep -q "${MODULE}" /proc/modules && klog "OK: module found in /proc/modules" \
                                  || klog "FAIL: module not found"

# ── Phase 1: Basic open/close ───────────────────────────────────
klog "--- Phase 1: open/close test ---"
if [ -c "${DEVICE}" ]; then
    klog "Device node exists: ${DEVICE}"
    # Open the device and immediately close it
    cat "${DEVICE}" > /dev/null 2>&1 &
    sleep 0.1
    klog "Phase 1 complete"
else
    klog "FAIL: device node missing: ${DEVICE}"
    exit 1
fi

# ── Phase 2: ioctl stress ───────────────────────────────────────
klog "--- Phase 2: ioctl stress test ---"
for i in $(seq 1 10); do
    klog "ioctl iteration ${i}"
    # Your actual ioctl command here
    sleep 0.05
done
klog "Phase 2 complete"

# ── Teardown ────────────────────────────────────────────────────
klog "Removing module"
modprobe -r "${MODULE}"
klog "=== TEST RUN END ==="

echo "Done. Check dmesg --decode --ctime --nopager for the full correlated log."

6. Security Considerations for /dev/kmsg

The /dev/kmsg interface requires root-level access by default. This is intentional: allowing arbitrary user space processes to inject messages into the kernel log would create an opportunity for confusion and log spoofing attacks.

There is one additional consideration worth knowing: a message written to the kernel log via /dev/kmsg is indistinguishable from a message emitted by printk() inside kernel code — they look identical in dmesg output. This is why adding a recognizable prefix like testscript: or a signature like [USER] to your injected messages is important for keeping your log readable.

7. The pr_fmt Macro — Standardizing printk Output

Here is a frustrating but common problem in kernel driver development: you have a module with twenty or thirty printk calls spread across multiple source files and several developers. Everyone writes their printk slightly differently:

/* Developer A's style */
pr_warn("mymodule: %s(): allocation failed\n", __func__);

/* Developer B's style */
pr_warn("%s: allocation failed\n", KBUILD_MODNAME);

/* Developer C's style */
pr_warn("allocation failed at line %d\n", __LINE__);

/* Developer D's style (no prefix at all!) */
pr_warn("allocation failed\n");

When you read dmesg, you cannot quickly tell which message came from which module or which function, especially when multiple modules are loaded simultaneously. Consistent formatting is critical for efficient debugging.

The pr_fmt macro solves this elegantly. It is a single macro definition placed at the very top of your source file that automatically prefixes every single subsequent pr_*() call in that file with whatever format string you specify. You define it once, and every developer’s pr_info(), pr_warn(), pr_err() automatically gets the same consistent prefix — with zero extra work per call site.

8. How pr_fmt Works Under the Hood

The pr_fmt macro must be defined before the very first #include directive in your source file. This is not just a convention — it is a hard requirement. The reason is that linux/printk.h (included transitively by almost every kernel header) defines a default pr_fmt if one has not been defined already. If your definition comes after any #include, the default wins and your definition is ignored.

The internal mechanism

The pr_info() macro (and all pr_* macros) are defined roughly as:

/* Inside linux/printk.h — simplified for clarity */
#ifndef pr_fmt
#define pr_fmt(fmt) fmt   /* default: no prefix, just pass fmt through */
#endif

#define pr_info(fmt, ...) \
    printk(KERN_INFO pr_fmt(fmt), ##__VA_ARGS__)

When you define your own pr_fmt before the includes, it replaces the default no-op definition. Every pr_info(fmt, ...) call then expands to printk(KERN_INFO pr_fmt(fmt), ...) which inserts your prefix automatically.

Standard pr_fmt pattern used in the Linux kernel itself

/*
 * pr_fmt MUST be defined before ANY #include
 * This is not optional — it must be first.
 *
 * Format: "modulename:functionname(): original_message"
 * KBUILD_MODNAME expands to the module name as a string literal
 * __func__ expands to the current function name at each call site
 */
#define pr_fmt(fmt)  KBUILD_MODNAME ": " __func__ "(): " fmt

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

MODULE_LICENSE("GPL");
MODULE_AUTHOR("EmbeddedPathashala");

static int __init mymodule_init(void)
{
    /*
     * This single pr_info call produces:
     * "mymodule: mymodule_init(): module loaded successfully"
     *
     * No need to manually add the module name or function name!
     */
    pr_info("module loaded successfully\n");

    pr_warn("this is a warning\n");
    /* Expands to: "mymodule: mymodule_init(): this is a warning" */

    return 0;
}

static void __exit mymodule_exit(void)
{
    pr_info("module removed\n");
    /* Expands to: "mymodule: mymodule_exit(): module removed" */
}

module_init(mymodule_init);
module_exit(mymodule_exit);

9. Practical pr_fmt Patterns for Real Drivers

Different situations call for different levels of detail in the log prefix. Here are patterns used in real kernel driver development:

Pattern 1 — Module name only (minimal, for production drivers)

#define pr_fmt(fmt)  KBUILD_MODNAME ": " fmt

/* Output: "myusbdriver: USB device enumerated on port 3" */

Pattern 2 — Module name + function name (best for debugging)

#define pr_fmt(fmt)  KBUILD_MODNAME ": " __func__ "(): " fmt

/* Output: "myusbdriver: usb_probe(): USB device enumerated on port 3" */

Pattern 3 — Module name + function name + line number (for deep debugging)

/*
 * Note: __LINE__ is an integer, not a string, so we cannot
 * use simple string concatenation. Use a format specifier instead.
 * This requires a slight change in how pr_fmt is defined.
 */
#define pr_fmt(fmt)  KBUILD_MODNAME ":%s:%d: " fmt, __func__, __LINE__

/*
 * Important: when using this form, your pr_* calls must NOT have
 * additional leading commas in their argument lists.
 * This form is less commonly used due to complexity.
 * Patterns 1 and 2 are preferred.
 */

Pattern 4 — Per-device prefix using a device pointer (for multi-instance drivers)

/*
 * For drivers managing multiple device instances, using pr_fmt alone
 * is insufficient because you also need to identify WHICH instance.
 * In this case, use dev_info(), dev_warn(), dev_err() from
 * linux/device.h instead, which automatically include the device name.
 */
#include <linux/device.h>

static int mydriver_probe(struct platform_device *pdev)
{
    struct device *dev = &pdev->dev;

    /* dev_info automatically includes device name — better than pr_fmt
       for multi-instance drivers */
    dev_info(dev, "probe successful\n");
    /* Output: "mydriver mydevice0: probe successful" */

    dev_warn(dev, "resource not optimal\n");
    /* Output: "mydriver mydevice0: resource not optimal" */

    return 0;
}

10. Architecture Diagram: Kernel Logging Paths

The diagram below shows how kernel messages reach the ring buffer from both kernel space and user space, and how they flow to the various consumer interfaces: