Why is pr_debug of the Linux kernel not giving any output?

Question

I have a loadable kernel module and its init is as given below

static int __init id_init(void)
{
    struct identity *temp;

    /* some code which is not relevant to the question */

    temp = identity_find(3);
    pr_debug("id 3 = %s\n", temp->name);

    temp = identity_find(42);
    if (temp == NULL)
        pr_debug("id 42 not found\n");

    /* some code which is not relevant to the question */

    return 0;
}

Also I have enabled dynamic debugging enabled on the kernel version I am using - i.e CONFIG_DYNAMIC_DEBUG=y.

And in the Makefile of the module I have added a line CFLAGS_[id].o := -DDEBUG where id.c is the file name.

Now I checked in the /sys/kernel/debug/dynamic_debug/control after doing insmod of this module, in which I found the below lines

/home/pauldc/Programming/Kernel/id/id.c:69 [id]id_init =_ "id 42 not found\012"
/home/pauldc/Programming/Kernel/id/id.c:65 [id]id_init =_ "id 3 = %s\012"

Even after doing all this, to my disappointment I could not find the above two pr_debug statements in the output of dmesg. So what am I missing or doing wrong?

Solution 1

Add following to Makefile, assuming filename.c is the module source file.

CFLAGS_filename.o := -DDEBUG

not

CFLAGS_[filename].o := -DDEBUG

Refer https://www.kernel.org/doc/local/pr_debug.txt

Solution 2

CONFIG_DYNAMIC_DEBUG=y

https://www.kernel.org/doc/html/v4.11/admin-guide/dynamic-debug-howto.html

If you compile the kernel with this option, then you can do amazing things like:

echo 8 > /proc/sys/kernel/printk
echo 'file kernel/module.c +p' > /sys/kernel/debug/dynamic_debug/control

and this will selectively enable the pr_debug() you want.

We can then test this out with:

insmod mymodule.ko

which prints a lot of extra debug info as in:

[   84.875592] init_module: umod=0000000073518b66, len=185416, uargs=000000009c6e375a                    
[   84.876099] Core section allocation order:       
[   84.876257]  .text                               
[   84.876332]  .note.gnu.build-id                  
[   84.876418]  .rodata.str1.1                      
[   84.876492]  .orc_unwind_ip                      
[   84.876568]  .orc_unwind                         
[   84.876636]  __mcount_loc                        
[   84.876705]  .data                               
[   84.876760]  .gnu.linkonce.this_module           
[   84.876856]  .bss                                
[   84.876919] Init section allocation order:       
[   84.877041]  .symtab                             
[   84.877121]  .strtab                             
[   84.877235] final section addresses:             
[   84.877352]  0xffffffffc0006000 .note.gnu.build-id                                                    
[   84.877482]  0xffffffffc0005000 .text            
[   84.877580]  0xffffffffc0006024 .rodata.str1.1   
[   84.877695]  0xffffffffc0006040 .orc_unwind_ip   
[   84.877805]  0xffffffffc0006050 .orc_unwind      
[   84.877905]  0xffffffffc0006068 __mcount_loc     
[   84.878012]  0xffffffffc0007000 .data            
[   84.878107]  0xffffffffc0007000 .gnu.linkonce.this_module                                             
[   84.878238]  0xffffffffc0007340 .bss             
[   84.878331]  0xffffffffc000a000 .symtab          
[   84.878430]  0xffffffffc000a348 .strtab          
[   84.878657] Absolute symbol: 0x00000000          
[   84.878951] Absolute symbol: 0x00000000          
[   84.879713] hello init 

And in particular, it contains the module load address:

[   84.877482]  0xffffffffc0005000 .text            

which is useful to convert addresses to lines.

For modules, we can do:

echo 8 > /proc/sys/kernel/printk
echo 'module myprintk +p' > /sys/kernel/debug/dynamic_debug/control
insmod /myprintk.ko

which allows us to easily test pr_debug by adding that to our own module.

Tested on kernel 4.16 with this setup.

printk(KERN_DEBUG != pr_debug when CONFIG_DYNAMIC_DEBUG=y

This is very inconsistent, but printk(KERN_DEBUG does show up when loglevel=8 even if we don't enable /sys/kernel/debug/dynamic_debug/control, this can be seen from: https://stackoverflow.com/a/37283021/895245

Comments

[Milind Dumbare]

Check your system's log level. May be its not supposed to print debug logs.

[0andriy]

Have you not seem in dmesg or on screen or both? Try to add dyndbg parameter to the module when you load it. If you have compiled in use <NAME>.dyndbg, where <NAME> is a name of your module accordingly to Makefile.

[PaulDaviesC]

@Miline Did you mean CONFIG_MESSAGE_LOGLEVEL_DEFAULT ? That is 4, as reported by the config file. But does that make any difference?

[Milind Dumbare]

Any specific reason why you can not use printk?

[PaulDaviesC]

@AndyShevchenko I did not get it. Can you please elaborate?

[PaulDaviesC]

@Miline I cannot use printk. This requirement comes from the assignment question.

[0andriy]

First of all, remove -DDEBUG from your Makefile. It's often wrong approach. Enable DYNAMIC_DEBUG (like you did already). Compile everything, then if you have module you load and it's called id, do modprobe id dyndbg. Also, if you would like to see on screen, set loglevel to 8.

[Ciro Santilli OurBigBook.com]

Maybe you forgot the echo 8 > /proc/sys/kernel/printk: stackoverflow.com/a/49835405/895245

[clearlight]

Or, to enable debug for the whole module, you can modify the Makefile in that directory and add flags to ccflags-y, if I understand section 4.2 of this document properly: kernel.org/doc/Documentation/kbuild/modules.txt