How to debug a Linux Kernel Module

April 26, 2020 5-minute read

linux • kernel • debugging

Build an example module

Let’s start by write a simple test module. We can try the Hello World example from cyberciti.biz You first have to install the kernel header files with apt-get install kernel-headers-$(uname -r).

Content of hello.c:

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

int init_module(void)
{
    printk(KERN_INFO "init_module() called\n");
    return 0;
}

void cleanup_module(void)
{
    printk(KERN_INFO "cleanup_module() called\n");
}

MODULE_LICENSE("GPL");

Content of Makefile:

obj-m := hello.o
KDIR := /lib/modules/$(shell uname -r)/build
PWD := $(shell pwd)
default:
    $(MAKE) -C $(KDIR) SUBDIRS=$(PWD) modules
clean:
    rm -rf *.ko
    rm -rf *.mod.c
    rm -rf *mod.o
    rm -rf *.o

Build and load, and unload the module:

kmille@linbox: make  
kmille@linbox: insmod hello.ko  
kmille@linbox: rmmod hello.ko

You will find the proper messages in the dmesg output:

kmille@linbox: dmesg:  
...
kmille@linbox: [  512.003876] init_module() called  
kmille@linbox: [  512.009321] cleanup_module() called

Debugging a real module

For example nf_log_ipv4 which gets called if iptables -j TRACE is executed.

Get the source code of the module
- download it from Github: git clone https://github.com/torvalds/linux
- checkout the kernel version you are currently running: git checkout ...
Add multiple print statements
- printk(KERN_INFO "nf_log_ipv4: Passed %s %d \n",__FUNCTION__,__LINE__);
In the Makefile above replace hello.o with nf_log_ipv4.o
- that’s it. just use make to build it
Load the module into the kernel with insmod nf_log_ipv4
- insmod does not load dependencies => symbol not found error
- modprobe automatically loads dependencies
- but modprobe loads modules from /lib/modules/$(uname -r)/, insmod from the current dir.

My actual problem

I was debugging why iptables -j TRACE didn’t log something to dmesg. After some time I found out why: Debian buster moved from netfilter to nf_tables per default and you get the logs via nft monitor trace. If you use the old iptables (/usr/sbin/iptables-legacy) the messages are logged to dmesg.

Automate the process

Adding prints to debug code is a very old school approach. A more modern way would be function tracing (for example with bpftrace). If we do the classic print way, we should automate the build and debug process. Content of rebuild.sh:

root@buster:~/mod/hello-example# cat rebuild.sh 
#/bin/bash
#iptables=/usr/sbin/iptables-legacy
iptables=iptables

make clean
make
rmmod nf_log_ipv4
modprobe nf_log_common
insmod nf_log_ipv4.ko
echo nf_log_ipv4 > /proc/sys/net/netfilter/nf_log/2
cat /proc/net/netfilter/nf_log
$iptables -t raw -F
$iptables -t raw -I OUTPUT -p icmp -j TRACE
$iptables -t raw -I PREROUTING -p icmp -j TRACE
lsmod | grep nf_log
ping -c 1 1.1.1.1
$iptables -t raw -vnL

Where to look in the code?

It’s very easy to grep the kernel code as everything is in a single namespace and all functions have a unique name. You can use strace to get the called syscalls which is a good starting point:

root@linbox ~ strace -e network iptables -vnL
socket(AF_INET, SOCK_RAW, IPPROTO_RAW)  = 4
getsockopt(4, SOL_IP, IPT_SO_GET_INFO, "filter\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., [84]) = 0
getsockopt(4, SOL_IP, IPT_SO_GET_ENTRIES, "filter\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., [2984]) = 0
Chain INPUT (policy DROP 0 packets, 0 bytes)
 pkts bytes target     prot opt in     out     source               destination
socket(AF_INET, SOCK_RAW, IPPROTO_RAW)  = 5
getsockopt(5, SOL_IP, IPT_SO_GET_REVISION_MATCH, 0x7fff31ce9a90, [30]) = -1 EPROTONOSUPPORT (Protocol not supported)
socket(AF_INET, SOCK_RAW, IPPROTO_RAW)  = 5
getsockopt(5, SOL_IP, IPT_SO_GET_REVISION_MATCH, "conntrack\0\202\365d\177\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\1", [30]) = 0
socket(AF_INET, SOCK_RAW, IPPROTO_RAW)  = 5
getsockopt(5, SOL_IP, IPT_SO_GET_REVISION_MATCH, 0x7fff31ce9a40, [30]) = -1 EPROTONOSUPPORT (Protocol not supported)
socket(AF_INET, SOCK_RAW, IPPROTO_RAW)  = 5
getsockopt(5, SOL_IP, IPT_SO_GET_REVISION_MATCH, "conntrack\0\214\365d\177\0\0\1\0\0\0\0\0\0\0\3111\200\365d\2", [30]) = 0
socket(AF_INET, SOCK_RAW, IPPROTO_RAW)  = 5
getsockopt(5, SOL_IP, IPT_SO_GET_REVISION_MATCH, 0x7fff31ce99f0, [30]) = -1 EPROTONOSUPPORT (Protocol not supported)
socket(AF_INET, SOCK_RAW, IPPROTO_RAW)  = 5
getsockopt(5, SOL_IP, IPT_SO_GET_REVISION_MATCH, "conntrack\0\227\342\332y\347X\1\0\0\0\0\0\0\0\3111\200\365d\3", [30]) = 0
socket(AF_INET, SOCK_RAW, IPPROTO_RAW)  = 5
getsockopt(5, SOL_IP, IPT_SO_GET_REVISION_MATCH, 0x7fff31ce99a0, [30]) = -1 EPROTONOSUPPORT (Protocol not supported)
socket(AF_INET, SOCK_RAW, IPPROTO_RAW)  = 5
getsockopt(5, SOL_IP, IPT_SO_GET_REVISION_MATCH, "conntrack\0\214\365d\177\0\0\0\0\0\0\0\0\0\0\3111\200\365\1\3", [30]) = 0
socket(AF_INET, SOCK_RAW, IPPROTO_RAW)  = 5
getsockopt(5, SOL_IP, IPT_SO_GET_REVISION_MATCH, "conntrack\0\214\365d\177\0\0\0\0\0\0\0\0\0\0\0\0\0\0\1\3", [30]) = 0
socket(AF_INET, SOCK_RAW, IPPROTO_RAW)  = 5
getsockopt(5, SOL_IP, IPT_SO_GET_REVISION_MATCH, "conntrack\0\214\365d\177\0\0\0\0\0\0\0\0\0\0\0\0\0\0\1\2", [30]) = 0
    0     0 DROP       all  --  *      *       0.0.0.0/0            0.0.0.0/0            state INVALID
socket(AF_INET, SOCK_RAW, IPPROTO_RAW)  = 5
getsockopt(5, SOL_IP, IPT_SO_GET_REVISION_MATCH, 0x7fff31ce9d00, [30]) = -1 EPROTONOSUPPORT (Protocol not supported)
1472K 1056M ACCEPT     all  --  *      *       0.0.0.0/0            0.0.0.0/0            state RELATED,ESTABLISHED
 1619 97140 ACCEPT     all  --  lo     *       0.0.0.0/0            0.0.0.0/0
    0     0 ACCEPT     icmp --  *      *       0.0.0.0/0            0.0.0.0/0
socket(AF_INET, SOCK_RAW, IPPROTO_RAW)  = 5
getsockopt(5, SOL_IP, IPT_SO_GET_REVISION_TARGET, "REJECT\0\0s\371\202\365d\177\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0", [30]) = 0
    0     0 REJECT     all  --  cdark.net *       0.0.0.0/0            0.0.0.0/0            reject-with icmp-port-unreachable
socket(AF_INET, SOCK_RAW, IPPROTO_RAW)  = 5
getsockopt(5, SOL_IP, IPT_SO_GET_REVISION_MATCH, "tcp\0d\177\0\0s\371\202\365d\177\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0", [30]) = 0
    0     0 ACCEPT     tcp  --  *      *       0.0.0.0/0            0.0.0.0/0            tcp dpt:22
    0     0 ACCEPT     tcp  --  *      *       0.0.0.0/0            0.0.0.0/0            tcp dpt:22000
socket(AF_INET, SOCK_RAW, IPPROTO_RAW)  = 5
getsockopt(5, SOL_IP, IPT_SO_GET_REVISION_MATCH, "udp\0d\177\0\0s\371\202\365d\177\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0", [30]) = 0
    0     0 ACCEPT     udp  --  *      *       0.0.0.0/0            0.0.0.0/0            udp dpt:21027
    0     0 ACCEPT     tcp  --  *      *       0.0.0.0/0            0.0.0.0/0            tcp dpt:5001
    0     0 ACCEPT     tcp  --  *      *       0.0.0.0/0            0.0.0.0/0            tcp dpt:8080
   63 17777 REJECT     all  --  *      *       0.0.0.0/0            0.0.0.0/0            reject-with icmp-port-unreachable

Chain FORWARD (policy ACCEPT 0 packets, 0 bytes)
 pkts bytes target     prot opt in     out     source               destination

Chain OUTPUT (policy ACCEPT 398K packets, 4393M bytes)
 pkts bytes target     prot opt in     out     source               destination
+++ exited with 0 +++
root@linbox ~ #

If you are looking for the IPT_SO_GET_INFO function,

you can just Google torvald/linux IPT_SO_GET_INFO and you will directly find the proper .c file: https://github.com/torvalds/linux/blob/master/net/ipv4/netfilter/ip_tables.c
bootlin is also nice because it can show you all references and definitions: https://elixir.bootlin.com/linux/latest/ident/IPT_SO_GET_INFO as search engine

Update: I also wrote about tracing kernel functions with bpftrace.