Bug hunting

Stack trace와 Oops 판독

Kernel bug report에는 다음과 같은 stack dump가 자주 포함됩니다. 첫 줄은 warning이 발생한 source path·line과 `module_put+0x57/0x70`처럼 function 안의 offset/전체 function 길이를 보여 주고, 이어서 loaded module, CPU·PID·taint, hardware, call trace가 나옵니다.

Kernel bug reports often come with a stack dump like the one below::

	------------[ cut here ]------------
	WARNING: CPU: 1 PID: 28102 at kernel/module.c:1108 module_put+0x57/0x70
	Modules linked in: dvb_usb_gp8psk(-) dvb_usb dvb_core nvidia_drm(PO) nvidia_modeset(PO) snd_hda_codec_hdmi snd_hda_intel snd_hda_codec snd_hwdep snd_hda_core snd_pcm snd_timer snd soundcore nvidia(PO) [last unloaded: rc_core]
	CPU: 1 PID: 28102 Comm: rmmod Tainted: P        WC O 4.8.4-build.1 #1
	Hardware name: MSI MS-7309/MS-7309, BIOS V1.12 02/23/2009
	 00000000 c12ba080 00000000 00000000 c103ed6a c1616014 00000001 00006dc6
	 c1615862 00000454 c109e8a7 c109e8a7 00000009 ffffffff 00000000 f13f6a10
	 f5f5a600 c103ee33 00000009 00000000 00000000 c109e8a7 f80ca4d0 c109f617
	Call Trace:
	 [<c12ba080>] ? dump_stack+0x44/0x64
	 [<c103ed6a>] ? __warn+0xfa/0x120
	 [<c109e8a7>] ? module_put+0x57/0x70
	 [<c109e8a7>] ? module_put+0x57/0x70
	 [<c103ee33>] ? warn_slowpath_null+0x23/0x30
	 [<c109e8a7>] ? module_put+0x57/0x70
	 [<f80ca4d0>] ? gp8psk_fe_set_frontend+0x460/0x460 [dvb_usb_gp8psk]
	 [<c109f617>] ? symbol_put_addr+0x27/0x50
	 [<f80bc9ca>] ? dvb_usb_adapter_frontend_exit+0x3a/0x70 [dvb_usb]
	 [<f80bb3bf>] ? dvb_usb_exit+0x2f/0xd0 [dvb_usb]
	 [<c13d03bc>] ? usb_disable_endpoint+0x7c/0xb0
	 [<f80bb48a>] ? dvb_usb_device_exit+0x2a/0x50 [dvb_usb]
	 [<c13d2882>] ? usb_unbind_interface+0x62/0x250
	 [<c136b514>] ? __pm_runtime_idle+0x44/0x70
	 [<c13620d8>] ? __device_release_driver+0x78/0x120
	 [<c1362907>] ? driver_detach+0x87/0x90
	 [<c1361c48>] ? bus_remove_driver+0x38/0x90
	 [<c13d1c18>] ? usb_deregister+0x58/0xb0
	 [<c109fbb0>] ? SyS_delete_module+0x130/0x1f0
	 [<c1055654>] ? task_work_run+0x64/0x80
	 [<c1000fa5>] ? exit_to_usermode_loop+0x85/0x90
	 [<c10013f0>] ? do_fast_syscall_32+0x80/0x130
	 [<c1549f43>] ? sysenter_past_esp+0x40/0x6a
	---[ end trace 6ebc60ef3981792f ]---

이 stack trace는 bug가 발생한 kernel source line을 찾기에 충분한 정보를 제공합니다. 문제 severity에 따라 다음처럼 `Oops`와 NULL pointer dereference, instruction pointer, page-table 정보가 포함될 수 있습니다.

Such stack traces provide enough information to identify the line inside the
Kernel's source code where the bug happened. Depending on the severity of
the issue, it may also contain the word **Oops**, as on this one::

	BUG: unable to handle kernel NULL pointer dereference at   (null)
	IP: [<c06969d4>] iret_exc+0x7d0/0xa59
	*pdpt = 000000002258a001 *pde = 0000000000000000
	Oops: 0002 [#1] PREEMPT SMP
	...

실제 형식이 Oops이든 다른 stack trace이든 bug를 식별하고 처리하려면 offending line이 보통 필요합니다. 이 문서에서는 분석이 필요한 모든 stack trace를 편의상 Oops라고 부릅니다.

Kernel을 `CONFIG_DEBUG_INFO`와 함께 compile했다면 `scripts/decode_stacktrace.sh`로 stack trace 품질을 높일 수 있습니다.

`Modules linked in`에서 tainted module 또는 현재 load/unload 중인 module은 괄호 안 annotation으로 표시합니다. Taint flag는 `Documentation/admin-guide/tainted-kernels.rst`에 설명되어 있고, `+`는 load 중, `-`는 unload 중임을 뜻합니다.

Oops message 위치와 crash log 확보

일반적으로 `klogd`가 kernel buffer에서 Oops text를 읽어 `syslogd`에 전달하고, `syslogd`가 `/etc/syslog.conf`에 따라 보통 `/var/log/messages`에 씁니다. Systemd system에서는 `journald`가 저장할 수 있으며 `journalctl`로 접근합니다.

`klogd`가 죽었다면 `dmesg > file`로 kernel buffer를 저장할 수 있습니다. `cat /proc/kmsg > file`도 가능하지만 `kmsg`는 끝나지 않는 file이므로 transfer를 중단하려면 interrupt해야 합니다.

Machine이 심하게 crash해 command를 입력할 수 없거나 disk를 사용할 수 없을 때는 세 방법이 있습니다. 첫째, screen text를 손으로 옮기거나 사진을 찍습니다. Message가 위로 사라지면 `vga=791` 같은 higher resolution이 더 많은 text를 보여 줄 수 있지만 `vesafb`가 필요하므로 early Oops에는 도움이 되지 않습니다.

둘째, `Documentation/admin-guide/serial-console.rst`에 따라 serial console로 boot하고 null-modem으로 두 번째 machine에 연결해 Minicom 같은 communication program으로 output을 capture합니다.

셋째, `Documentation/admin-guide/kdump/kdump.rst`의 Kdump를 사용하고 `Documentation/admin-guide/kdump/gdbmacros.txt`의 dmesg GDB macro로 old memory에서 kernel ring buffer를 추출합니다.

GDB로 source file·line 찾기

Bug report는 kernel source file의 정확한 위치를 제시할 때 가장 유용합니다. 방법은 두 가지이며 보통 GDB가 쉽지만 kernel을 debug information과 함께 미리 compile해야 합니다. GNU debugger `gdb`는 `vmlinux`에서 Oops의 정확한 file과 line number를 찾는 가장 좋은 방법입니다.

`CONFIG_DEBUG_INFO`를 enable하려면 다음 config command를 사용합니다.

The usage of gdb works best on a kernel compiled with ``CONFIG_DEBUG_INFO``.
This can be set by running::

  $ ./scripts/config -d COMPILE_TEST -e DEBUG_KERNEL -e DEBUG_INFO

Debug info가 있는 kernel에서는 Oops의 EIP address를 복사해 `gdb vmlinux`에서 `list *address`로 변환합니다.

On a kernel compiled with ``CONFIG_DEBUG_INFO``, you can simply copy the
EIP value from the OOPS::

 EIP:    0060:[<c021e50e>]    Not tainted VLI

And use GDB to translate that to human-readable form::

  $ gdb vmlinux
  (gdb) l *0xc021e50e

Oops를 만들 때 debug info가 없었다면 Oops의 function offset을 사용합니다. 같은 source를 `CONFIG_DEBUG_INFO`로 다시 compile하고 `list *function+offset`을 실행하면 예제의 `drivers/tty/vt/vt_ioctl.c:293`과 주변 C source를 얻습니다.

If you don't have ``CONFIG_DEBUG_INFO`` enabled, you use the function
offset from the OOPS::

 EIP is at vt_ioctl+0xda8/0x1482

And recompile the kernel with ``CONFIG_DEBUG_INFO`` enabled::

  $ ./scripts/config -d COMPILE_TEST -e DEBUG_KERNEL -e DEBUG_INFO
  $ make vmlinux
  $ gdb vmlinux
  (gdb) l *vt_ioctl+0xda8
  0x1888 is in vt_ioctl (drivers/tty/vt/vt_ioctl.c:293).
  288	{
  289		struct vc_data *vc = NULL;
  290		int ret = 0;
  291
  292		console_lock();
  293		if (VT_BUSY(vc_num))
  294			ret = -EBUSY;
  295		else if (vc_num)
  296			vc = vc_deallocate(vc_num);
  297		console_unlock();

더 자세히 보려면 `p vt_ioctl`로 function address를 확인하고 address+offset을 list할 수 있습니다. 전체 `vmlinux` 대신 해당 object file만 build해 GDB로 열 수도 있습니다.

or, if you want to be more verbose::

  (gdb) p vt_ioctl
  $1 = {int (struct tty_struct *, unsigned int, unsigned long)} 0xae0 <vt_ioctl>
  (gdb) l *0xae0+0xda8

You could, instead, use the object file::

  $ make drivers/tty/
  $ gdb drivers/tty/vt/vt_ioctl.o
  (gdb) l *vt_ioctl+0xda8

Call trace의 `:jbd:` annotation은 문제가 jbd module에 있을 가능성을 보여 줍니다. 해당 `.ko`를 GDB에 load하고 relevant function+offset을 list합니다.

If you have a call trace, such as::

     Call Trace:
      [<ffffffff8802c8e9>] :jbd:log_wait_commit+0xa3/0xf5
      [<ffffffff810482d9>] autoremove_wake_function+0x0/0x2e
      [<ffffffff8802770b>] :jbd:journal_stop+0x1be/0x1ee
      ...

this shows the problem likely is in the :jbd: module. You can load that module
in gdb and list the relevant code::

  $ gdb fs/jbd/jbd.ko
  (gdb) l *log_wait_commit+0xa3

같은 방식은 stack trace의 어느 function call에도 적용됩니다. 예제의 `dvb_usb_adapter_frontend_exit+0x3a/0x70 [dvb_usb]`는 해당 object file을 열어 offset을 조회합니다.

.. note::

     You can also do the same for any function call at the stack trace,
     like this one::

	 [<f80bc9ca>] ? dvb_usb_adapter_frontend_exit+0x3a/0x70 [dvb_usb]

     The position where the above call happened can be seen with::

	$ gdb drivers/media/usb/dvb-usb/dvb-usb.o
	(gdb) l *dvb_usb_adapter_frontend_exit+0x3a

objdump와 decodecode

Kernel debug에는 `objdump`를 사용해 crash output의 hexadecimal offset에 해당하는 code/assembler line을 찾을 수 있습니다. Debug symbol이 없으면 routine의 assembler만, 있으면 C code도 볼 수 있습니다. Debug symbol은 menu configuration의 kernel hacking menu에서 enable할 수 있습니다.

To debug a kernel, use objdump and look for the hex offset from the crash
output to find the valid line of code/assembler. Without debug symbols, you
will see the assembler code for the routine shown, but if your kernel has
debug symbols the C code will also be available. (Debug symbols can be enabled
in the kernel hacking menu of the menu configuration.) For example::

    $ objdump -r -S -l --disassemble net/ipv4/tcp.o

C file을 함께 찾으려면 kernel tree top level에서 command를 실행해야 합니다.

Source code에 접근할 수 없어도 Oops `Code:` byte를 `.byte` directive로 `foo.s`에 넣고 `gcc -c`로 object를 만든 다음 `objdump --disassemble`로 instruction을 복원할 수 있습니다. Oops의 angle bracket은 faulting instruction byte를 가리킵니다.

If you don't have access to the source code you can still debug some crash
dumps using the following method (example crash dump output as shown by
Dave Miller)::

     EIP is at 	+0x14/0x4c0
      ...
     Code: 44 24 04 e8 6f 05 00 00 e9 e8 fe ff ff 8d 76 00 8d bc 27 00 00
     00 00 55 57  56 53 81 ec bc 00 00 00 8b ac 24 d0 00 00 00 8b 5d 08
     <8b> 83 3c 01 00 00 89 44  24 14 8b 45 28 85 c0 89 44 24 18 0f 85

     Put the bytes into a "foo.s" file like this:

            .text
            .globl foo
     foo:
            .byte  .... /* bytes from Code: part of OOPS dump */

     Compile it with "gcc -c -o foo.o foo.s" then look at the output of
     "objdump --disassemble foo.o".

     Output:

     ip_queue_xmit:
         push       %ebp
         push       %edi
         push       %esi
         push       %ebx
         sub        $0xbc, %esp
         mov        0xd0(%esp), %ebp        ! %ebp = arg0 (skb)
         mov        0x8(%ebp), %ebx         ! %ebx = skb->sk
         mov        0x13c(%ebx), %eax       ! %eax = inet_sk(sk)->opt

CPU architecture에 따라 `scripts/decodecode`가 이 작업 대부분을 자동화할 수 있습니다.

Bug report 대상 찾기

Bug 위치를 찾은 뒤 직접 수정하거나 upstream에 report할 수 있습니다. Upstream report를 위해 해당 code 개발에 사용하는 bug tracker나 mailing list를 식별해야 하며 `get_maintainer.pl` script가 이를 도와줍니다.

예제는 gspca `sonixj.c`의 maintainer 정보를 조회합니다.

In order to report it upstream, you should identify the bug tracker, if any, or
mailing list used for the development of the affected code. This can be done by
using the ``get_maintainer.pl`` script.

For example, if you find a bug at the gspca's sonixj.c file, you can get
its maintainers with::

	$ ./scripts/get_maintainer.pl --bug -f drivers/media/usb/gspca/sonixj.c
	Hans Verkuil <[email protected]> (odd fixer:GSPCA USB WEBCAM DRIVER,commit_signer:1/1=100%)
	Mauro Carvalho Chehab <[email protected]> (maintainer:MEDIA INPUT INFRASTRUCTURE (V4L/DVB),commit_signer:1/1=100%)
	Tejun Heo <[email protected]> (commit_signer:1/1=100%)
	Bhaktipriya Shridhar <[email protected]> (commit_signer:1/1=100%,authored:1/1=100%,added_lines:4/4=100%,removed_lines:9/9=100%)
	[email protected] (open list:GSPCA USB WEBCAM DRIVER)
	[email protected] (open list)

결과에는 Git tree에서 최근 source를 건드린 developer, driver maintainer, subsystem maintainer, driver/subsystem mailing list, Linux Kernel mailing list, driver/subsystem bug-report URI가 포함될 수 있습니다. 최근 contributor가 실제 해당 file 개발에 관여한 사람은 아닐 수도 있습니다.

목록 끝에 bug-report URI가 있으면 email보다 우선합니다. 없으면 code 개발 mailing list에 report하고 driver maintainer를 copy합니다. 누구에게 보낼지 전혀 알 수 없고 `get_maintainer.pl`도 유용한 정보를 주지 못하면 `[email protected]`로 보냅니다.

이러한 report는 Linux를 가능한 한 안정적으로 만드는 데 도움을 줍니다.

Bug 수정과 patch 제출

Programming을 안다면 bug report뿐 아니라 해결책도 제공할 수 있습니다. Fix를 만들었다면 upstream에 제출합니다.

Code가 받아들여질 가능성을 높이려면 `Documentation/process/submitting-patches.rst`를 반드시 읽습니다.

klogd address resolution

Linus와 kernel developer의 protection-fault 분석을 돕기 위해 `klogd`에는 fault processing 지원이 포함되어 있습니다. Full address resolution을 위해 적어도 `sysklogd` 1.3-pl3을 사용해야 합니다.

Protection fault가 발생하면 `klogd` daemon은 kernel log의 중요한 address를 symbolic equivalent로 자동 변환하고, 현재 reporting mechanism으로 전달합니다. 따라서 변환된 fault message를 log file에서 잘라 kernel developer에게 보낼 수 있습니다.

`klogd`는 static과 dynamic 두 종류 address resolution을 수행합니다. Static translation은 `System.map`을 사용하므로 daemon initialization 때 system map file을 찾을 수 있어야 합니다. Search 방식은 klogd man page를 참고합니다.

Dynamic translation은 loadable kernel module에 중요합니다. Module memory는 kernel dynamic pool에서 할당되므로 module start와 내부 function·symbol 위치가 고정되지 않습니다.

Kernel system call로 loaded module과 memory 위치를 알아낼 수 있습니다. `klogd`는 이를 사용해 loadable module에서 생긴 protection fault를 debug할 symbol table을 만듭니다. 최소한 fault를 만든 module 이름을 제공하고, module이 symbol을 export했다면 추가 symbolic information도 제공합니다.

Module environment는 동적이므로 load/unload 때 `klogd`에 symbol refresh를 알려야 합니다. 실행 중 daemon에 refresh signal을 보내는 command-line option은 klogd manual에 설명되어 있습니다.

`sysklogd` distribution의 patch는 `modules-2.0.0` package가 module load/unload 때 자동으로 klogd에 signal하도록 수정합니다. 이를 적용하면 loadable-module protection fault debugging을 거의 seamless하게 지원합니다.

klogd가 변환한 module Oops 예제

마지막 예제는 loadable module에서 발생한 protection fault를 `klogd`가 처리한 결과입니다. Virtual address paging request, CR3와 PDE, Oops code, CPU, symbolic EIP `oops:_oops+16/3868`, register, process, stack, symbolic call trace, machine code를 포함합니다.

The following is an example of a protection fault in a loadable module
processed by ``klogd``::

	Aug 29 09:51:01 blizard kernel: Unable to handle kernel paging request at virtual address f15e97cc
	Aug 29 09:51:01 blizard kernel: current->tss.cr3 = 0062d000, %cr3 = 0062d000
	Aug 29 09:51:01 blizard kernel: *pde = 00000000
	Aug 29 09:51:01 blizard kernel: Oops: 0002
	Aug 29 09:51:01 blizard kernel: CPU:    0
	Aug 29 09:51:01 blizard kernel: EIP:    0010:[oops:_oops+16/3868]
	Aug 29 09:51:01 blizard kernel: EFLAGS: 00010212
	Aug 29 09:51:01 blizard kernel: eax: 315e97cc   ebx: 003a6f80   ecx: 001be77b   edx: 00237c0c
	Aug 29 09:51:01 blizard kernel: esi: 00000000   edi: bffffdb3   ebp: 00589f90   esp: 00589f8c
	Aug 29 09:51:01 blizard kernel: ds: 0018   es: 0018   fs: 002b   gs: 002b   ss: 0018
	Aug 29 09:51:01 blizard kernel: Process oops_test (pid: 3374, process nr: 21, stackpage=00589000)
	Aug 29 09:51:01 blizard kernel: Stack: 315e97cc 00589f98 0100b0b4 bffffed4 0012e38e 00240c64 003a6f80 00000001
	Aug 29 09:51:01 blizard kernel:        00000000 00237810 bfffff00 0010a7fa 00000003 00000001 00000000 bfffff00
	Aug 29 09:51:01 blizard kernel:        bffffdb3 bffffed4 ffffffda 0000002b 0007002b 0000002b 0000002b 00000036
	Aug 29 09:51:01 blizard kernel: Call Trace: [oops:_oops_ioctl+48/80] [_sys_ioctl+254/272] [_system_call+82/128]
	Aug 29 09:51:01 blizard kernel: Code: c7 00 05 00 00 00 eb 08 90 90 90 90 90 90 90 90 89 ec 5d c3