Pages

Sunday, July 19, 2015

Linux Kernel: memory corruption - debug tricks

Note: This post is meant to help you debug a memory corruption if you are building your own kernel from source.

The symptoms:


If you see one of the following errors in your in your dmesg log:

* BUG: unable to handle kernel paging request at 7f45402d
* invalid opcode: 0000 [#1] SMP
* general protection fault: 0000 [#1] SMP
* BUG: unable to handle kernel NULL pointer dereference at 0000000000000258

Then you probably have a memory corruption somewhere.

In my case, I didn't get these errors at first. I was adding objects to a list by calling list_add_tail(my_list, my_obj) and verifying that list_empty(my_list) was returning false as expected (and it was). But latter in the code when I called list_empty(my_list) again, it was returning true, and in nowhere in my code I was removing objects from the list.

Weird behaviors that doesn't make sense probably are due to memory corruption. When I started simplifying the code to isolate the problem, I start getting the errors above in the dmesg log.

Where it is happening:


When you have an error, you get a log message in dmesg like:

We will be looking at 2 infos there:
1) The IP (instruction pointer) address in the 2nd line
2) The call trace at line 23rd

The IP

In the 2nd line of this log, we have the instruction pointer address, it is the address the computer was executing that generated the error.

In this example, the IP is ffffffff817c69f0, then we can find where in the code this address corresponds to using the addr2line tool:

Where the path_to_your_kernel_tree is the path to the kernel code where you downloaded it (where you do make && make install)
The vmlinux file is the uncompressed version of the Linux image (it is created when you do make)

Note: if it doesn't work, check if your make menuconfig if your kernel is compiled with DEBUG flag

But this technique won't work if the corresponding address is not part of the kernel core code (if it was an error caused by some module, as we will see in the call trace section).

The call trace

In the log above, line 23rd, it means that the function devres_remove was called by devres_destroy, which was called by devm_kfree, which was called by vmc_cap_destroy and so on.

Now suppose that the vmc_cap_destroy function call devm_kfree in many places and you want to know exactly which one has triggered the bug. Lets do this in 2 steps:

1) Get the offset in the code section of the function using nm:
nm is a tool to get the offset of a symbol in a section:

In this example, the offset of the vmc_cap_destroy function is 0x680

2) Get the file and the line using addr2line:
In line 27th we have: vmc_cap_destroy+0x40, where the 0x40 is the offset inside the vmc_cap_destroy function where the code execution would return if the call to devm_kfree hadn't triggered the bug.

So lets add the function offset we found in the previous step with the offset inside the function: 0x680 + 0x40 = 0x6c0

And now we use the addr2line with the compile module.ko to find out where is it:

Then the buggy devm_kfree call is the first one just before the line 396 in file vmc-capture.c

Enable debug prints:


Besides the techniques above, you can enable the debug level prints in the dmesg log:

sudo sh -c "echo 8 > /proc/sys/kernel/printk"

If this doesn't work, check if the DYNAMIC_DEBUG flag is enabled in your menuconfig, if so, then check the next section about Dynamic debug.

In the case of a module that I was testing (the vivid module), I needed to change the vivid_debug parameter:

We can do this when we start the module:

sudo modprobe vivid vivid_debug=8

Or changing the parameter while its already running:

sudo sh -c "echo -n 0 > sys/module/vivid/parameters/vivid_debug"


Dynamic debug:

If your kernel is compiled with DYNAMIC_DEBUG flag, then changing the printk level probably won't enable the debug prints in the dmesg log.

Lets say the module we are working is called media, lets add it into the kernel:

sudo modprobe media

And now we will enable all the debug prints in the media module by sending 'module media +p' to the dynamic_debug/control file:

If you look at the dynamic_debug/control file content (as we did above) you can see the "=p" which means that the prints in those lines are enabled.

To disable the prints, we send 'module media -p' to the dynamic_debug/control file:

If you look at the dynamic_debug/control file content again you can see the "=_" which means that the prints in those lines are disabled.

Enabling a specific print

Instead of enabling all the debug prints of the entire module, we can enable all the prints on a specific file, or we can specify a file and a line:

$ sudo sh -c "echo -n 'file media-entity.c +p' > /sys/kernel/debug/dynamic_debug/control"

$ sudo sh -c "echo -n 'file media-entity.c line 301 +p' > /sys/kernel/debug/dynamic_debug/control"

Read dmesg log continuously


Instead of calling dmesg every time to check the log, you can do:

$ tail -f /var/log/kern.log

and the log will be printed continuously.

3 comments:

  1. Thanks Helen for a very informative article! I've used a couple of the tools named but I'm really happy that I got to know new debugging techniques and tools too! I have two questions though:

    Why did you decide that the problem is memory corruption?
    You introduced a problem a problem that occurred to you and then provided the techniques that you followed to handle the issue. What happened to your problem at the end? I know that you solved it but I would like to know details. =D

    ReplyDelete
    Replies
    1. Thanks for asking :)

      I decided that my problem was about memory corruption because I had a list with elements, and this list was empty in some point in the code, but I never removed the elements from it.

      I was working with a complex topology (described in this post http://helenfornazier.blogspot.com.br/2015/06/outreachy-status-log-third-week-basic.html), then I tried to simplify it a bit, using only the "Sensor A" to generate the image and the "Capture A" to export this image to user space (without the other nodes as debayers, sensor B or capture B).

      When I simplified it, I got a kernel message error (kernel Oops) saying I was accessing some region of the code that I shouldn't.
      I wasn't getting this error with the complex topology because of a coincidence (explained below). Then I find out the line of the code which was generating the error and I realize I was accessing an array like pipe[ent_num] instead of pipe[ent_num-1].

      The coincidence:
      In the complex topology, when the "Capture A" (/dev/video0) is opened to read a frame, it activates the "Sensor A" to generate the frames periodically.
      The order of the entities in the pipe array was something like: Sensor A, Sensor B, Debayer A, Debayer B, Capture A, Capture B, Scaler.
      When the "Sensor A" generates a frame, it is sent to the "Capture A" through the pipe array and using the index ent_num, but as the minus 1 was missing, the frame was being sent to the "Capture B" instead of "Capture A", and I wasn't getting the error because the "Capture B" has the same code of "Capture A".

      Delete
  2. CONFIG_SLUB_DEBUG_ON=y can help in some instances of memory corruption.

    ReplyDelete