Lab 4: Debugging a Kernel (Milestone 4)

Background

You cannot attach a debugger to a production kernel, and single-stepping is useless for a bug that only appears under load on eight CPUs. So the kernel instruments itself, and the skill this lab teaches is reading what it already told you.

There is no new code to write here. Instead you will break the driver from Lab 3 in six specific ways, produce six specific diagnostics, and learn to read each one line by line — because in a year, one of these will arrive in your inbox from a stranger and you will have nothing else to go on.

Why This Lab Matters

• The first question in the debugging order is "what does the kernel already know?" — and most people skip it and start adding printk.
• A maintainer's first question about your patch is often "did you run this with KASAN and lockdep?"
• Every bug report you will receive is one of these six shapes.
• ftrace and bpftrace answer questions on a running machine, which is where the interesting bugs live.

Prerequisites

• Lab 3 complete — you have a char device to break.
• Context and Atomicity and Concurrency read.
• Both kernels built: lab-fast and lab-paranoid. This lab needs the difference.
• The Warm-Up exercises 9–11 done (ftrace, perf, bpftrace).

Predict First

1. A NULL dereference in your module. What is the very first line of the report, and which field tells you which function rather than which address?
2. A use-after-free, run 20 times on lab-fast (no KASAN). How many of the 20 produce any visible symptom?
3. A stack-trace line with a ? in front of it. Should you trust it? What does the ? mean?
4. You take two mutexes in opposite orders in two functions, and call each once, a second apart. Does lockdep report anything?
5. trace_printk() versus printk() in a hot path — which perturbs the timing of the bug you are chasing more, and by roughly how much?

The Six Diagnostics

   BUG YOU INJECT                   WHAT THE KERNEL PRINTS            WHAT FINDS IT
   ─────────────                    ──────────────────────            ─────────────
   1. NULL dereference          →   Oops + call trace                 always
   2. Use after free            →   KASAN: slab-use-after-free        CONFIG_KASAN
   3. Buffer overrun            →   KASAN: slab-out-of-bounds         CONFIG_KASAN
   4. Sleep in atomic context   →   BUG: sleeping function called…    DEBUG_ATOMIC_SLEEP
   5. ABBA lock inversion       →   possible circular locking dep.    PROVE_LOCKING
   6. Leak on the error path    →   kmemleak: unreferenced object     DEBUG_KMEMLEAK

Step-by-Step Tasks

Step 1: An oops, and how to decode it

Add an ioctl command to your Lab 3 driver that dereferences NULL, then trigger it.

case LAB_IOC_BUG_NULL: {
	int *p = NULL;
	*p = 1;                 /* deliberate */
	return 0;
}

insmod /mnt/host/chardev/lab_chardev.ko
/mnt/host/chardev/lab_test --bug null

Read the report in this order:

BUG: kernel NULL pointer dereference, address: 0000000000000000
     ^^^ WHAT and WHERE (the faulting address, not the faulting code)
#PF: supervisor write access in kernel mode
#PF: error_code(0x0002) - not-present page
     ^^^ a WRITE, from kernel mode, to an unmapped page
PGD 0 P4D 0
Oops: 0002 [#1] PREEMPT SMP NOPTI
             ^^^ [#1] = the FIRST oops. A [#2] means the machine is already
                 unreliable and everything after is suspect.
CPU: 2 PID: 231 Comm: lab_test Tainted: G           O       6.x.0-lab
                                        ^^^^^^^^^^^^^ TAINT FLAGS.
                 O = an out-of-tree module is loaded. A maintainer reads this
                 line first and decides whether to keep reading.
RIP: 0010:lab_ioctl+0x8e/0x140 [lab_chardev]
          ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ THE ANSWER: function + offset
                 into it / total size, and which module.
Call Trace:
 <TASK>
 __x64_sys_ioctl+0x94/0xd0
 do_syscall_64+0x5c/0x90
 entry_SYSCALL_64_after_hwframe+0x6e/0x76
 </TASK>

Now turn the offset into a line number:

# On the host:
cd ~/kernel/build
~/kernel/linux/scripts/faddr2line /mnt/host/chardev/lab_chardev.ko lab_ioctl+0x8e

# Or decode a whole pasted oops at once, including module symbols:
~/kernel/linux/scripts/decode_stacktrace.sh vmlinux ~/kernel/linux /mnt/host/chardev < /tmp/oops.txt

decode_stacktrace.sh is the one to remember: paste a bug report from a mailing list into a file, run it, and every func+0x2c/0x180 becomes a file and line.

The ? marker. On x86 with the ORC unwinder, a line prefixed with ? is the unwinder guessing — it found something on the stack that looks like a return address but could not prove it. Stale values from earlier calls appear this way. Do not chase a ? frame until the unprefixed ones are exhausted.

Step 2: Use after free, with and without KASAN

case LAB_IOC_BUG_UAF: {
	char *p = kmalloc(64, GFP_KERNEL);
	if (!p)
		return -ENOMEM;
	kfree(p);
	p[0] = 'x';             /* deliberate */
	return 0;
}

Run it 20 times on lab-fast (no KASAN):

for i in $(seq 20); do /mnt/host/chardev/lab_test --bug uaf; done
dmesg | tail -20

Predict first: how many of the 20 show anything?

Then reboot into lab-paranoid and run it once:

BUG: KASAN: slab-use-after-free in lab_ioctl+0xa2/0x140 [lab_chardev]
Write of size 1 at addr ffff888103a4f000 by task lab_test/244
     ^^^ WHAT kind of error, WHERE in the code, WHAT access, WHICH address

Call Trace:                       ← where the bad access happened
 kasan_report+0xae/0xe0
 lab_ioctl+0xa2/0x140 [lab_chardev]
 __x64_sys_ioctl+0x94/0xd0

Allocated by task 244:            ← where the object came from
 kmalloc_trace+0x4b/0xc0
 lab_ioctl+0x6e/0x140 [lab_chardev]

Freed by task 244:                ← where it was freed
 kfree+0x10a/0x2c0
 lab_ioctl+0x82/0x140 [lab_chardev]

The buggy address belongs to the object at ffff888103a4f000
 which belongs to the cache kmalloc-64 of size 64
Memory state around the buggy address:
 ffff888103a4ef00: fc fc fc fc fc fc fc fc fb fb fb fb fb fb fb fb
>ffff888103a4f000: fa fa fa fa fa fa fa fa fc fc fc fc fc fc fc fc
                   ^

Three stack traces: used here, allocated there, freed there. That is the entire investigation, done for you. The shadow bytes at the bottom show the state of the surrounding memory — the legend is printed with every report; fb is freed, fc is redzone.

Step 3: Out of bounds

case LAB_IOC_BUG_OOB: {
	char *p = kmalloc(64, GFP_KERNEL);
	if (!p)
		return -ENOMEM;
	p[64] = 'x';            /* one past the end */
	kfree(p);
	return 0;
}

Predict first: does this corrupt anything on lab-fast? Does anything notice? Then run it on lab-paranoid and compare the report's first line with the use-after-free one: slab-out-of-bounds versus slab-use-after-free, and note that the "Freed by" section is absent.

Step 4: Sleeping in atomic context

case LAB_IOC_BUG_ATOMIC: {
	void *p;
	spin_lock(&some_lock);
	p = kmalloc(128, GFP_KERNEL);       /* deliberate */
	spin_unlock(&some_lock);
	kfree(p);
	return 0;
}

Read every field, and identify which one is the bug:

BUG: sleeping function called from invalid context at mm/page_alloc.c:NNNN
in_atomic(): 1, irqs_disabled(): 0, non_block: 0, pid: 251, name: lab_test
preempt_count: 1, expected: 0
CPU: 1 PID: 251 Comm: lab_test Tainted: G           O
Call Trace:
 __might_resched.cold+0x...
 __kmalloc_noprof+0x...
 lab_ioctl+0xd4/0x140 [lab_chardev]
Preemption disabled at:
 lab_ioctl+0xc8/0x140 [lab_chardev]
 ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ THIS IS THE BUG — the spin_lock().
                                    The top line is the victim.

Step 5: An ABBA deadlock, caught before it deadlocks

static DEFINE_MUTEX(lock_a);
static DEFINE_MUTEX(lock_b);

case LAB_IOC_BUG_AB:
	mutex_lock(&lock_a); mutex_lock(&lock_b);
	mutex_unlock(&lock_b); mutex_unlock(&lock_a);
	return 0;

case LAB_IOC_BUG_BA:
	mutex_lock(&lock_b); mutex_lock(&lock_a);
	mutex_unlock(&lock_a); mutex_unlock(&lock_b);
	return 0;

/mnt/host/chardev/lab_test --bug ab
sleep 2
/mnt/host/chardev/lab_test --bug ba          # single-threaded, two seconds apart
dmesg | tail -60

Predict first: does the machine hang? Does anything appear in dmesg, and after which call?

lockdep prints a "possible unsafe locking scenario" diagram with both orders, and it did not need the two paths to ever race. It only had to see each half once. Read the two stack traces at the bottom — those are the two acquisition orders — then decide which one is wrong.

Step 6: A leak on the error path

Reintroduce the leak from Lab 2 — skip one kfree in an unwind — and use fault injection to reach it:

F=/sys/kernel/debug/failslab
echo 30 > $F/probability; echo -1 > $F/times; echo N > $F/ignore-gfp-wait
for i in $(seq 30); do insmod /mnt/host/chardev/lab_chardev.ko 2>/dev/null && rmmod lab_chardev; done
echo 0 > $F/probability

echo scan > /sys/kernel/debug/kmemleak; sleep 5
echo scan > /sys/kernel/debug/kmemleak
cat /sys/kernel/debug/kmemleak

unreferenced object 0xffff888104c1a800 (size 128):
  comm "insmod", pid 268, jiffies 4294899123
  backtrace:
    kmalloc_trace+0x4b/0xc0
    lab_init+0x5c/0x1000 [lab_chardev]
    do_one_initcall+0x...

The backtrace is the allocation site, not the leak site — which is what you need, because the leak site is "nowhere; nobody freed it".

Step 7: ftrace on your own module

T=/sys/kernel/tracing; [ -d "$T" ] || T=/sys/kernel/debug/tracing

echo 0 > $T/tracing_on
echo function_graph > $T/current_tracer
echo ':mod:lab_chardev' > $T/set_ftrace_filter    # every function in your module
echo 1 > $T/tracing_on

echo -n hello > /dev/mylab
cat /dev/mylab > /dev/null

echo 0 > $T/tracing_on
cat $T/trace | head -40

:mod:<name> is the filter syntax worth remembering. Then widen it to follow the path into your module:

echo 0 > $T/tracing_on; echo > $T/trace
echo function_graph > $T/current_tracer
echo lab_ioctl > $T/set_graph_function      # graph everything below this entry point
echo 1 > $T/tracing_on
/mnt/host/chardev/lab_test
echo 0 > $T/tracing_on
head -60 $T/trace

Useful options while you are there:

echo funcgraph-abstime > $T/trace_options   # absolute timestamps
echo funcgraph-proc    > $T/trace_options   # which task
echo 1 > $T/options/func_stack_trace        # a stack trace per traced function
cat $T/tracing_max_latency 2>/dev/null

Step 8: A kprobe on someone else's code

You do not need source access or a rebuild to instrument a function you did not write.

# The tracefs way:
echo 'p:mylab_probe vfs_read count=$arg3' > $T/kprobe_events
echo 1 > $T/events/kprobes/mylab_probe/enable
echo 1 > $T/tracing_on
cat /dev/mylab > /dev/null
head -20 $T/trace
echo 0 > $T/events/kprobes/mylab_probe/enable
echo > $T/kprobe_events

# The bpftrace way, which is one line and aggregates in-kernel:
bpftrace -e 'kprobe:lab_ioctl { @[arg1] = count(); }'      # by ioctl command
bpftrace -e 'kretprobe:lab_read { @ = hist(retval); }'     # return-value histogram

Step 9: trace_printk and dynamic debug

Two ways to add output without the cost of printk:

/* Goes to the FTRACE ring buffer, not the console. Far cheaper, and it
 * does not serialize on the console — so it perturbs timing much less.
 * It prints a loud banner in dmesg, on purpose: you must not ship it. */
trace_printk("read: pos=%lld count=%zu\n", *ppos, count);

cat $T/trace | grep read:
dmesg | grep -i "trace_printk"      # the banner reminding you to remove it

/* Compiled in but OFF by default; switched on at runtime, per file, per
 * line, per function. This is what you should ship.                   */
pr_debug("read: pos=%lld count=%zu\n", *ppos, count);

echo 'module lab_chardev +p' > /sys/kernel/debug/dynamic_debug/control
echo 'file lab_chardev.c line 120 +p' > /sys/kernel/debug/dynamic_debug/control
grep lab_chardev /sys/kernel/debug/dynamic_debug/control
echo 'module lab_chardev -p' > /sys/kernel/debug/dynamic_debug/control

Step 10: A wedged machine

Hang the driver on purpose (an infinite loop with preemption disabled), then get information out of a machine that is not answering:

# From inside, if it still responds:
echo t > /proc/sysrq-trigger      # every task's stack
echo l > /proc/sysrq-trigger      # a backtrace on every CPU
echo w > /proc/sysrq-trigger      # only blocked (D-state) tasks
echo m > /proc/sysrq-trigger      # memory info

# From QEMU, when it does not: Ctrl-A C for the monitor, then:
(qemu) sendkey alt-sysrq-l
(qemu) info registers
(qemu) info cpus

And GDB, which can always stop it:

(gdb) ^C
(gdb) info threads
(gdb) thread apply all bt
(gdb) lx-ps
(gdb) lx-dmesg

Also worth triggering deliberately once, so you recognize them later:

Implementation Requirements / Deliverables

• All six diagnostics produced, saved to files, and annotated line by line in your own words.
• For the oops: faddr2line and decode_stacktrace.sh both used successfully.
• A written explanation of the ? marker and what you do about it.
• The use-after-free run 20× on lab-fast and once on lab-paranoid, with the counts recorded.
• For the sleeping-in-atomic BUG: you identified the bug from the Preemption disabled at: line, not from the top line.
• The lockdep splat obtained without a hang, and both stack traces explained.
• kmemleak output with the allocation backtrace, and the leak fixed.
• function_graph output for your module, filtered with :mod:.
• A kprobe on a function you did not write, printing an argument.
• Dynamic debug switched on and off at runtime for one file.
• SysRq used from the QEMU monitor on a wedged guest.
• The taint flags on your reports decoded against Documentation/admin-guide/tainted-kernels.rst.

Expected Output

Beyond the reports above, the ftrace graph of your own driver:

# tracer: function_graph
#
# CPU  DURATION                  FUNCTION CALLS
# |     |   |                     |   |   |   |
 2)               |  lab_ioctl [lab_chardev]() {
 2)   0.412 us    |    mutex_lock();
 2)               |    _copy_to_user() {
 2)   0.298 us    |      __check_object_size();
 2)   1.104 us    |    }
 2)   0.221 us    |    mutex_unlock();
 2)   3.982 us    |  }

Every nesting level is a call, and the right-hand column is the duration. That is a profiler and a call tracer in one, built in, with no rebuild.

Debugging Steps

dmesg shows nothing after a crash

The machine died before flushing. That is what the serial console is for — console=ttyS0 means the output left the machine as it was produced. Scroll back in the QEMU terminal.

The stack trace has no module symbols

decode_stacktrace.sh needs the module directory:

scripts/decode_stacktrace.sh vmlinux <kernel-source-dir> <dir-containing-.ko> < oops.txt

In GDB, lx-symbols <dir> does the equivalent.

faddr2line says "no match"

You are using a different .ko than the one that produced the trace. Rebuild traceability: keep the exact .ko and vmlinux that produced a report.

KASAN reports nothing for an obvious bug

Confirm you booted the right kernel: grep -i kasan /proc/cmdline; dmesg | grep -i kasan. Also note KASAN does not catch every class — it will not see a race (that is KCSAN) or an uninitialized read (that is CONFIG_KMSAN).

kmemleak reports objects that are not leaks

Scan twice, several seconds apart; the first scan reports transients. echo clear > resets it between experiments. Some false positives are inherent (objects referenced only from registers or percpu areas).

ftrace produces gigabytes and the machine crawls

You enabled the function tracer without a filter. Reset with the escape hatch from the warm-up, and always set set_ftrace_filter before tracing_on.

The lockdep splat appears once and never again

By design: lockdep disables itself after the first report (debug_locks = 0) because subsequent state is untrustworthy. Look for Disabling lock debugging due to kernel taint too. Reboot between lock experiments.

bpftrace says "BTF not found"

CONFIG_DEBUG_INFO_BTF is off, usually because pahole was missing at build time. Check ls -l /sys/kernel/btf/vmlinux and rebuild.

Experiment

CLAIM. The debug options are not "nice to have". Without them, most of these bugs produce no symptom at all — so an idle development machine with the options off actively hides them.

METHOD. Build one module containing all six bugs behind ioctl commands. Then, for each of the two kernels, run each bug 20 times and fill in this table:

PREDICTION. Fill in all twelve cells before running anything.

RESULT. Then compute what the table costs: measure boot time and the runtime of your Lab 3 test program on both kernels, and write down the slowdown factor.

Finally, answer the question the experiment exists for: given that cost, when should you run lab-paranoid? The honest answer is not "always" and not "never", and being able to state your policy is the deliverable.

Test

Debugging skill is tested by reading, not by running. Build a corpus:

mkdir -p ~/kernel-labs/reports
# Save every diagnostic you produced:
dmesg > ~/kernel-labs/reports/$(date +%s)-<bugname>.txt

Then the real test — reports you did not produce:

1. Go to lore.kernel.org and search for BUG: KASAN: slab-use-after-free.
2. Pick three reports from the last year, in subsystems you have never read.
3. For each, before reading the replies, write down: what kind of bug, which function, what was freed and where, and what you would investigate first.
4. Then read the thread and compare.

You are done with this milestone when your three answers are mostly right and you can say why you were wrong where you were.

Challenge Extensions

1. Add a tracepoint to your driver. Define one with TRACE_EVENT() in a header under include/trace/events/, emit it from lab_read, and consume it with both echo 1 > $T/events/lab/lab_read/enable and bpftrace -e 'tracepoint:lab:lab_read { ... }'. Then explain what a tracepoint gives you that a kprobe does not, and what it costs when disabled.

2. Decode an oops by hand. Take the Code: bytes from an oops report and disassemble them (scripts/decodecode < oops.txt). Find the faulting instruction, marked with <...>.

3. Catch a race with KCSAN. Build with CONFIG_KCSAN=y, reintroduce the unlocked counter from Lab 3, and read the report. Note that it names both sides of the race — something no other tool here does.

4. Use perf on your driver. perf record -e 'probe:lab_read' -aR (after perf probe --add lab_read), then perf report. Compare the workflow with ftrace's and decide when you would use each.

5. Reproduce a hung task. Make an ioctl sleep forever on a mutex nobody releases, and wait 120 seconds for INFO: task blocked for more than 120 seconds. Then reduce /proc/sys/kernel/hung_task_timeout_secs and confirm the mechanism.

6. Enable panic_on_warn. Set /proc/sys/kernel/panic_on_warn, trigger a WARN_ON, and watch the machine panic. Then read why syzbot runs with this on, and what it implies about adding a WARN_ON to a path user space can reach.

Validation / Self-check

1. In an oops, which field names the function, and what do the two numbers after + mean?
2. What does [#1] mean, and why should you distrust a [#2]?
3. What does a ? prefix on a stack-trace line mean, and what should you do with that frame?
4. Decode these taint letters: G, P, O, W, D. Which one makes a maintainer stop reading?
5. A KASAN report has three stack traces. What is each one, and which is usually the least useful?
6. What is the difference between slab-use-after-free and slab-out-of-bounds in the report, and what is missing from one of them?
7. In a sleeping-in-atomic BUG, which line is the bug and which is the victim?
8. How can lockdep report a deadlock that never happened? Why does it stop reporting after the first one?
9. What does the backtrace in a kmemleak report point to, and why is that the useful one?
10. Give the ftrace filter syntax for "every function in module X". Why must you set it before enabling tracing?
11. When would you use trace_printk over printk, and why must you never ship it?
12. What does dynamic debug (pr_debug) give you that a #ifdef DEBUG does not?
13. Name three things KASAN does not catch, and the tool for each.
14. Your guest is wedged and not responding to the console. Name three ways to get information out.
15. What is your policy for when to run lab-paranoid, and what does it cost?

Next: Lab 5 — A Syscall and Its ABI, where you add a permanent interface to the kernel and then argue that you should not have.