[SOLVED] Kernel module unexpected exit when using insmod

abhinav007 · 03-07-2018, 02:37 AM

Hi,
I have written a simple kernel driver program. It has simple module entry and exit functions.

Code:

static int __init driver_entry(void){
 printk(KERN_INFO "module entry");
 return 0;
}
static void __exit driver_exit(void){
 printk(KERN_ALERT "module exited");
} 
module_init(driver_entry);
module_exit(driver_exit);

I created the standard makefile required for compiling module as follows:

Code:

CONFIG_MODULE_SIG=n
obj-m := testmod.o

KERNEL_DIR = /usr/src/linux-headers-$(shell uname -r)

all:
     $(MAKE) -C $(KERNEL_DIR) SUBDIRS=$(PWD) modules
clean:
     rm -rf *.o *.ko *.mod.* *.symvers *.order *~

The module compiles without error.I previously received a module verification error due to signature while insmod hence added the CONFIG_MODULE_SIG=n.
I am using the virtualbox environment running Ubuntu 16.04. However, when I insert the module using insmod, the "module exited" message appears highlighted with red background in dmesg log even before the "module entry" message. The function driver_exit gets executed automatically with the insmod call. Not able to understand this phenomenon?

Thank you.

smallpond · 03-07-2018, 11:39 AM

Is that the previous copy of your driver being removed when you insmod a new one? Did you check with lsmod?

abhinav007 · 03-08-2018, 12:06 AM

@smallpond, I have checked with lsmod and the module was not loaded before insmod was used. I changed the Makefile to compile with /lib/modules/$(shell uname -r)/build instead of /usr/src/linux-headers-$(shell uname -r).I am posting the full code below:

module1.c

Code:

#include <linux/module.h>
#include <linux/kernel.h>
#include <linux/fs.h>
#include <linux/cdev.h>
#include <linux/semaphore.h>
#include <asm/uaccess.h>
#include <linux/init.h>

static int __init driver_entry(void)
{
	printk(KERN_ALERT "module1: module entered");
	return 0;
}
static void __exit driver_exit(void)
{
	printk(KERN_ALERT "module1: module exit");
}
module_init(driver_entry);
module_exit(driver_exit);

MODULE_AUTHOR("Abhi");
MODULE_DESCRIPTION("Simple driver");
MODULE_LICENSE("GPL");

Makefile:

Code:

CONFIG_MODULE_SIG=n
obj-m := module1.o

KERNEL_DIR = /lib/modules/$(shell uname -r)/build

all:
	$(MAKE) -C $(KERNEL_DIR) M=$(PWD) modules

clean:
	$(MAKE) -C $(KERNEL_DIR) M=$(PWD) clean

The module throws compile error if I try to compile with "sudo make", but compiles successfully without the use of "sudo". I am attaching the log below:

Code:

abhinav@abhinav-VirtualBox:~/tuts/ch1$ ls
Makefile  module1.c

abhinav@abhinav-VirtualBox:~/tuts/ch1$ dmesg

abhinav@abhinav-VirtualBox:~/tuts/ch1$ make 
make -C /lib/modules/4.13.0-36-generic/build M=/home/abhinav/tuts/ch1 modules
make[1]: Entering directory '/usr/src/linux-headers-4.13.0-36-generic'
  CC [M]  /home/abhinav/tuts/ch1/module1.o
  Building modules, stage 2.
  MODPOST 1 modules
  CC      /home/abhinav/tuts/ch1/module1.mod.o
  LD [M]  /home/abhinav/tuts/ch1/module1.ko
make[1]: Leaving directory '/usr/src/linux-headers-4.13.0-36-generic'

abhinav@abhinav-VirtualBox:~/tuts/ch1$ sudo insmod module1.ko

abhinav@abhinav-VirtualBox:~/tuts/ch1$ dmesg
[ 1420.222942] module1: module exit

abhinav@abhinav-VirtualBox:~/tuts/ch1$ lsmod
Module                  Size  Used by
module1                16384  0
snd_intel8x0           40960  2
snd_ac97_codec        131072  1 snd_intel8x0
intel_powerclamp       16384  0
ac97_bus               16384  1 snd_ac97_codec
snd_pcm                98304  2 snd_ac97_codec,snd_intel8x0
crct10dif_pclmul       16384  0
crc32_pclmul           16384  0
ghash_clmulni_intel    16384  0
cryptd                 24576  1 ghash_clmulni_intel
joydev                 20480  0
intel_rapl_perf        16384  0
snd_seq_midi           16384  0
input_leds             16384  0
snd_seq_midi_event     16384  1 snd_seq_midi
snd_rawmidi            32768  1 snd_seq_midi
snd_seq                65536  2 snd_seq_midi_event,snd_seq_midi
serio_raw              16384  0
snd_seq_device         16384  3 snd_seq,snd_rawmidi,snd_seq_midi
vboxvideo              53248  2
ttm                    94208  1 vboxvideo
drm_kms_helper        167936  1 vboxvideo
snd_timer              32768  2 snd_seq,snd_pcm
drm                   360448  5 vboxvideo,ttm,drm_kms_helper
fb_sys_fops            16384  1 drm_kms_helper
syscopyarea            16384  2 vboxvideo,drm_kms_helper
snd                    81920  11 snd_seq,snd_ac97_codec,snd_timer,snd_rawmidi,snd_intel8x0,snd_seq_device,snd_pcm
vboxguest             294912  1 vboxvideo
mac_hid                16384  0
sysfillrect            16384  2 vboxvideo,drm_kms_helper
i2c_piix4              24576  0
sysimgblt              16384  2 vboxvideo,drm_kms_helper
soundcore              16384  1 snd
parport_pc             32768  0
ppdev                  20480  0
lp                     20480  0
parport                49152  3 lp,parport_pc,ppdev
autofs4                40960  2
hid_generic            16384  0
usbhid                 49152  0
hid                   118784  2 hid_generic,usbhid
ahci                   36864  2
e1000                 143360  0
psmouse               147456  0
libahci                32768  1 ahci
pata_acpi              16384  0
video                  40960  0

abhinav@abhinav-VirtualBox:~/tuts/ch1$ sudo rmmod module1.ko

abhinav@abhinav-VirtualBox:~/tuts/ch1$ dmesg
[ 1420.222942] module1: module exit
[ 2283.046381] module1: module entered

abhinav@abhinav-VirtualBox:~/tuts/ch1$ lsmod
Module                  Size  Used by
snd_intel8x0           40960  2
snd_ac97_codec        131072  1 snd_intel8x0
intel_powerclamp       16384  0
ac97_bus               16384  1 snd_ac97_codec
snd_pcm                98304  2 snd_ac97_codec,snd_intel8x0
crct10dif_pclmul       16384  0
crc32_pclmul           16384  0
ghash_clmulni_intel    16384  0
cryptd                 24576  1 ghash_clmulni_intel
joydev                 20480  0
intel_rapl_perf        16384  0
snd_seq_midi           16384  0
input_leds             16384  0
snd_seq_midi_event     16384  1 snd_seq_midi
snd_rawmidi            32768  1 snd_seq_midi
snd_seq                65536  2 snd_seq_midi_event,snd_seq_midi
serio_raw              16384  0
snd_seq_device         16384  3 snd_seq,snd_rawmidi,snd_seq_midi
vboxvideo              53248  2
ttm                    94208  1 vboxvideo
drm_kms_helper        167936  1 vboxvideo
snd_timer              32768  2 snd_seq,snd_pcm
drm                   360448  5 vboxvideo,ttm,drm_kms_helper
fb_sys_fops            16384  1 drm_kms_helper
syscopyarea            16384  2 vboxvideo,drm_kms_helper
snd                    81920  11 snd_seq,snd_ac97_codec,snd_timer,snd_rawmidi,snd_intel8x0,snd_seq_device,snd_pcm
vboxguest             294912  1 vboxvideo
mac_hid                16384  0
sysfillrect            16384  2 vboxvideo,drm_kms_helper
i2c_piix4              24576  0
sysimgblt              16384  2 vboxvideo,drm_kms_helper
soundcore              16384  1 snd
parport_pc             32768  0
ppdev                  20480  0
lp                     20480  0
parport                49152  3 lp,parport_pc,ppdev
autofs4                40960  2
hid_generic            16384  0
usbhid                 49152  0
hid                   118784  2 hid_generic,usbhid
ahci                   36864  2
e1000                 143360  0
psmouse               147456  0
libahci                32768  1 ahci
pata_acpi              16384  0
video                  40960  0

Can clearly verify that module is loaded and unloaded by using lsmod, but not sure what is actually going behind the execution. It seems driver_exit function is triggered as soon as the module is instatiated by insmod. Could it be still the module verification error due to missing signature?

AwesomeMachine · 03-08-2018, 11:13 PM

Is there some compelling reason you are using insmod instead of modprobe?

abhinav007 · 03-09-2018, 12:46 AM

Quote:

Originally Posted by AwesomeMachine

Is there some compelling reason you are using insmod instead of modprobe?

Seems there a lot of work needs to be done with modprobe. It demands the module to be present in /lib/usr/$(shell uname -r) directory. Also I tried modules_install but it throws error that

Code:

cp: cannot stat './modules.order':No such file or directory

Also I found many methods to compile and load LKM, it has become slightly confusing

AwesomeMachine · 03-09-2018, 01:27 AM

Modprobe is more trouble, but it also makes more checks, and it doesn't mysteriously fail like insmod.

abhinav007 · 03-09-2018, 03:45 AM

Quote:

Originally Posted by AwesomeMachine

Modprobe is more trouble, but it also makes more checks, and it doesn't mysteriously fail like insmod.

I used modprobe this time by making a symbolic link and depmod. No change in the output though.
It seems that the driver_entry and driver_exit are behaving exactly opposite than intended. driver_exit is executed when the module is instantiated and driver_entry is executed when rmmod is used. The message indicating module is out-of-tree build and module verification failure appears initially every time I restart the system and load the module for the first time (even though CONFIG_MODULE_SIG=n in makefile). I also checked that CONFIG_MODULE_SIG_FORCE is not enabled.

Could it be that dmesg log is lagging behind or something similar?

AwesomeMachine · 03-12-2018, 08:46 AM

Try tailing /var/log/messages and watch it as you try to load the module. It should give some clue. You could also enable kernel debugging.

abhinav007 · 03-21-2018, 11:38 AM

Found the solution. It was the most stupid thing I could imagine, just added "\n" at the end of printk message. Guess the module was working properly but dmesg didn't show correct log until I added a newline at the end of the KERN_INFO & KERN_ALERT message.
But still wonder how this issue prompted "module exited" before "module entry" ?