⌨ Labor omnia vincit ☮

Don’t Panic

Posted in Linux Kernel by anaumov on 22.07.2011

Порой бывает непросто разобраться в неполадках работы ядра Linux. Поиск причины, приводящей к kernel panic, требует воспроизведения ситуации, вызывающей некорректное поведение ядра, а также сбора информации, на основании которой можно сделать какие-то выводы. Проблема в том, что kernel panic иногда вешает систему полностью, и в этом случае даже не знаешь с какой стороны подступиться и что вообще делать с “заблокированной” машиной.

В этом посте я описал в общих чертах некоторые методы, которые помогут разобраться с причиной возникновения kernel panic.

Что такое kernel panic и из-за чего это происходит?

Как слудет из названия – это состояние ядра, при котором оно попадает в ситуацию когда не знает что делать дальше. У вас случался когда-нибудь сильный пожар в квартире? Если случался, то вы можете хорошо себе представить что такое kernel panic🙂

Привести к kernel panic могут ошибки в работе подгруженных модулей ядра. Они работают в одном адресном пространсве с ядром, поэтому ошибка может стать критичной для всей системы.
Чтобы просмотреть все подгруженные (динамические) модули, сделайте lsmod. Вывод будет содержать список модулей, как правило драйверов, например для SCSI или USB. В дополнение к этому так же можно отнести компоненты, с котороыми скомпилированно ядро (например это могут быть модули для работы с памятью).

О любой ошибке в ядре, даже не критичной для работы системы, создается oops-сообщение в /var/log/messages. Не всегда создание oops-сообщений говорит о kernel panic, но при kernel panic должны всегда создаваться oops-сообщения.

Выделяют два типа kernel panic: твердая паника (Hard panic), при появлении на экране сообщения ‘Aieee!’, и мягкая паника (Soft panic).

Hard panic

Признаки:

  • Машина полностью висит и ни на что не отвечает
  • Могут мигать NumLock/CapsLock/ScrollLock
  • На мониторе отладочная информация, а так же Aieee-фраза
  • Выглядит так же как виндовый “синий экран смерти”

Наиболее распространенной причиной Hard panic является ошибка драйвера, а именно когда он пытается получить доступ к нулевому указателю, и в это время запускается обработчик прерываний. Когда это происходит, драйвер не может обработать и завершить созданное им же прерывание, а ядро не может продолжать работу, потому что ждет пока драйвер обработает прерывание… а этого не происходит, и система просто виснет.

В зависимости от характера паники, ядро постарается зарегистрировать всю информацию непосредственно до блокировки/зависания. Однако никогда нельзя сказать наверняка, что информация будет собрана до самого последнего момента перед зависанием. Ниже перечисленны основные способы сбора информации о причине и характере зависания (все же не факт, что все они будут доступны).

  • /var/log/messages — иногда ядро успевает полностью записать в этой файл oops-сообщения
  • так же проверьте логи программ/библиотек. Иногда они могут рассказать показать что-то интересное перед kernel panic
  • Дамп, выводимый на консоль. Это самое главное. Так как операционная система висит, мы не можем скопировать ее куда-то в систему. Тут поможет только фотик, карандаш с листом бумаги или просто перепечатываем содержание дампа на другом компьютере

Например вот так выглядит kernel panic ядра 2.6.16.13-xen на x86_64-машине:

Unable to handle kernel paging request at ffffc200001104ab
RIP: <ffffffff8801c732>{:ip_tables:ipt_do_table+197}
PGD 393067 PUD 392067 PMD 3fabb067 PTE 0
Oops: 0000 [1] SMP
CPU 0
Modules linked in: ipt_owner ipt_multiport xt_state ip_conntrack nfnetlink
xt_limit xt_tcpudp iptable_mangle ipt_REJECT ipt_LOG iptable_filter ip_tables
x_tables autofs4 loop dm_mod
Pid: 0, comm: swapper Not tainted 2.6.16.13-xenU #3
RIP: e030:[<ffffffff8801c732>] <ffffffff8801c732>{:ip_tables:ipt_do_table+197}
RSP: e02b:ffffffff803154c8  EFLAGS: 00010216
RAX: 0000000000001758 RBX: 0000000000000000 RCX: 0000000000000000
RDX: 0000000000000001 RSI: 0000000000000001 RDI: ffffffff88020814
RBP: ffffc20000110458 R08: ffffffff88020814 R09: 0000000000000000
R10: ffffffff880339be R11: ffffffff880339be R12: ffff88003fa00000
R13: ffffc20000110000 R14: ffff880031854030 R15: ffffc20000111758
FS:  00002b8dddb91ce0(0000) GS:ffffffff80357000(0000) knlGS:0000000000000000
CS:  e033 DS: 0000 ES: 0000
Process swapper (pid: 0, threadinfo ffffffff80364000, task ffffffff802bd6a0)
Stack: ffffffff8803b560 0000000000000000 0000000000000000 ffff88003fa00000
       000000010e01bed0 ffffffff80315620 ffffffff88020814 0000000000000000
       ffff88003fa00000 ffffffff8801ebc0
Call Trace:
<IRQ>
       <ffffffff8023ccd7>{nf_iterate+63}
       <ffffffff880339be>{:ip_conntrack:tcp_pkt_to_tuple+0}
       <ffffffff8024218b>{ip_local_deliver_finish+0}
       <ffffffff8023cdfd>{nf_hook_slow+90}
       <ffffffff8024218b>{ip_local_deliver_finish+0}
       <ffffffff802423ce>{ip_local_deliver+103}
       <ffffffff880339be>{:ip_conntrack:tcp_pkt_to_tuple+0}
       <ffffffff80242a6e>{ip_rcv+1206}
       <ffffffff8020e8f8>{netif_poll+1661}
       <ffffffff80229f4f>{net_rx_action+183}
       <ffffffff8012b68d>{__do_softirq+123}
       <ffffffff8010b992>{call_softirq+30}
       <ffffffff8010d02b>{do_softirq+75}
       <ffffffff8010d28e>{do_IRQ+67}
       <ffffffff8020472d>{evtchn_do_upcall+132}
       <ffffffff8010b4c2>{do_hypervisor_callback+30}
<EOI>
       <ffffffff801073aa>{hypercall_page+938}
       <ffffffff801073aa>{hypercall_page+938}
       <ffffffff801093bf>{xen_idle+134}
       <ffffffff8010943b>{cpu_idle+80}
       <ffffffff803676ab>{start_kernel+478}
       <ffffffff803670cc>{_sinittext+204}

Code: 40 8a 7d 53 8b 45 08 41 23 46 0c 3b 45 00 40 0f b6 cf 89 c8
RIP <ffffffff8801c732>{:ip_tables:ipt_do_table+197} RSP <ffffffff803154c8>
CR2: ffffc200001104ab
 <0>Kernel panic - not syncing: Aiee, killing interrupt handler!

Ниже представлен kernel panic, но уже на PowerPC:

Oops: kernel access of bad area, sig: 11 [#1]
PREEMPT
NIP: C01A19A8 LR: C016D28C SP: C0237B70 REGS: c0237ac0 TRAP: 0300    Not
tainted
DAR: F9FFFE6B, DSISR: 00000000
TASK = c0206750[0] 'swapper' THREAD: c0236000
Last syscall: 120
GPR00: 0561D868 C0237B70 C0206750 C3C0A9E0 C0237BB0 C0237C58 C0237BF4 C0250000
NIP [c01a19a8] fn_hash_lookup+0x84/0x134
LR [c016d28c] ip_route_input+0x268/0xc6c
Call trace:
 [c016d28c] ip_route_input+0x268/0xc6c
 [c01952c8] arp_process+0x2e0/0x634
 [c0158498] netif_receive_skb+0x334/0x3d4
 [c013a9d8] emac_poll_rx+0x17c/0x7c8
 [c0138768] mal_poll+0xac/0x2b4
 [c015875c] net_rx_action+0x98/0x19c
 [c001db24] __do_softirq+0x7c/0xf4
 [c001dbf4] do_softirq+0x58/0x60
 [c001dcd8] irq_exit+0x5c/0x7c
 [c0003894] do_IRQ+0x84/0x98
 [c00023dc] ret_from_except+0x0/0x18
 [c0003928] cpu_idle+0x24/0x44
 [c00012fc] rest_init+0x3c/0x4c
 [c023868c] start_kernel+0x18c/0x1c4
 [c0000200] skpinv+0x1a8/0x1e4
Kernel panic - not syncing: Aiee, killing interrupt handler!
 Rebooting in 180 seconds..

Обратите внимание на сообщение “Kernel panic – not syncing: Aiee, killing interrupt handler!”. Все те же проблемы между CPU-memory при обработке прерывания модулем ядра. О смысле второй выделенной строки я расскажу ниже.

Soft panic

Признаки:

  • Менее серьезный чем hard panic
  • Связана в основном с ошибкой сегментации
  • Сообщения всегда попадают в /var/log/messages. Ищите там oops-сообщения
  • Машина реагирует на переключения консолей (но все же должна быть перезагружена после сбора информации)

Причиной soft panic может быть любая ошибка в модуле, но только когда дело не касается обработчика прерываний (в противном случае система замирает). В этом случае драйвер падает, но система может продолжать работать еще какое-то короткое время, т.к. она не ждет окончания обработки прерывания, созданного модулем. Естественно soft panic происходит только если это не “жизенно важный” для системы модуль.

Debug Information

Когда происходит kernel panic, ядро автоматически генерирует вывод, в который входит трассированный дамп, стек, информация о процессе, значения регистров а так же сам код инструкции, который и привел к kernel panic. Вывод перенаправляется в /var/log/messages, и в случае hard panic на экран.

Давайте рассмотрим каждую строчку попорядку. Для примера я приведу еще один дамп, но уже для i386.

Unable to handle kernel NULL pointer dereference at virtual address 00000094
 printing eip:
c02b47f6
*pde = 00000000
Oops: 0000 [#1]
CPU:    0
EIP:    0060:[<c02b47f6>]    Tainted: G  U
EFLAGS: 00010202   (2.6.5-7.97-default)
EIP is at udp_rcv+0xf6/0x5e0
eax: cfb53b80   ebx: df206844   ecx: 0e217d13   edx: 00000020
esi: 00002088   edi: 00882088   ebp: 00000000   esp: c0399e88
ds: 007b   es: 007b   ss: 0068
Process swapper (pid: 0, threadinfo=c0398000 task=c033b100)
Stack: e1047860 00000000 e10478a0 c0284f0e 00000000 4480b609 4180b609 df206844
       cfb53b80 cfb53b80 c035e0a0 00000000 00000000 c0294982 00000000 00000001
       00000002 c0285bca 00000000 cfb53b80 c03ffe88 cfb53b80 c856f030 d263f080
Call Trace:
 [<c0284f0e>] nf_iterate+0x5e/0xb0
 [<c0294982>] ip_local_deliver_finish+0x52/0x1c0
 [<c0285bca>] nf_hook_slow+0xea/0xf0
 [<c0294c5a>] ip_local_deliver+0x16a/0x220
 [<c0294930>] ip_local_deliver_finish+0x0/0x1c0
 [<c0294873>] ip_rcv+0x3c3/0x480
 [<c027cf40>] netif_receive_skb+0x210/0x220
 [<c02799f2>] alloc_skb+0x32/0xd0
 [<e104ce33>] e100_poll+0x2d3/0x650 [e100]
 [<c027bda2>] net_rx_action+0xa2/0xf0
 [<c01231e3>] __do_softirq+0x43/0x90
 [<c0123256>] do_softirq+0x26/0x30
 [<c010a8f5>] do_IRQ+0x125/0x1a0 [<c0108d48>] common_interrupt+0x18/0x20
 [<c0106290>] default_idle+0x0/0x30
 [<c01062b3>] default_idle+0x23/0x30
 [<c0106dac>] cpu_idle+0x1c/0x40
 [<c039a629>] start_kernel+0x299/0x300

Code: f7 85 94 00 00 00 00 00 00 30 0f 84 62 01 00 00 8b 4c 24 1c

Первая строка дает нам понять, почему произошло исключение: ядро пыталось получить доступ к несуществующему адресу (00000094). Такое, как мы знаем, происходит как правило при разыменовывании нулевого указателя.

Дальше идет hex-адрес EIP указателя инструкции (его еще называют указателем команд), который так же содержит оffset (величину смещения относительно начала программы) на инструкцию/команду, которая будет исполняться следующей. То есть полный адрес на следующую исполняемую команду будет CS:ЕIP – 0060:[<c02b47f6>] (название регистра зависит от платформы: на х86_32 это EIP, на х86_64 RIP, а PowerPC использует для этого регистр NIP).

Обратите внимание на выделенную строчку: исключение произошло при выполнении инструкции по адресу “udp_rcv+0xf6/0x5e0”. Здесь мы видим смещение 0xf6, считая от начала функции upd_rcv. Второе hex-число указывает на длину функции. Это расстояние до следующего глобального символа, где могут находится статические компоненты ядра (функции), которые не видны (не отображаются) в таблице символов… Все же эти два адреса говорят нам о том, где произошло зависание.

Далее идет дамп регистров. Ядро показывает их значения в момент выполнения инструкции, которая вызвала kernel panic. Их анализ также поможет при поиске функции, из которой эта инструкция была запущенна.

Несколькими строками ниже находится PID и имя процесса, который умер. В нашем примере, это swapper (PID 0).

После информации о процессе, oops включает hexdump вершину стека. Там могут быть адреса возврата, которые так же помогут при анализе ошибки. Помните, что стек может содержать так же и остатки от предыдущих вызовов функций. В этом случае сверяйте указатели функци в стеке с трассированным дампом. Напрмер в нашем дампе мы видим функции do_IRQ и следующая за ней common_interrupt по адресу c0108d48, которая подтверждает, что проблема так или иначе имеет отношение к обработчику прерыавний. До этого, к примеру, мы видим функцию ip_rcv, которая говорит нам о том, что передавался какой-то IP-пакет, а еще двумя строчками выше nf_hook_slow, которая вызывается только если настроенна фильтрация пакетов. Уже что-то. Таким образом следуя по этим вызовам, мы можем представить и воспроизвести картину случившегося.

Ну и наконец последняя строчка в oops показывает инструкцию, которая привела к kernel panic. Сразу же бросается в глаза “94 00 00 00”, что сответсвует смещению 0x94, как мы и предпологали выше. Для более понятного вывода, oops сообщения можно передать ksymoops – специально написанной для этого программе.

# cp /proc/modules /tmp/my_proc_modules
# ksymoops -l /tmp/my_proc_modules > /tmp/my_oops

(используем копию файла /proc/modules если работаем с динамически подгружаемым модулем, и /boot/System.map, если проблема непосредственно в ядре)

Вывод ksymoops покажет инструкцию “testl $ 0x30000000, 0x94 (% EBP)”.

Use debugger to get more information

Итак, теперь мы знаем, что oops вызвала инструкция “testl $ 0x30000000, 0x94 (% EBP)”. Самое время запустить отладчик.

Если наша функция находится в ядре, то нам естественно понадобится образ ядра. В openSUSE он находится в /boot/vmlinux-<kernelversions>.gz. В случае модуля будет достаточно просто передать отладчику бинарник модуля. Кстати, неплохой идеей будет использование так же objdump. С помощью этой утилиты мы можем получить полный дамп модуля. Весь дамп нам, правда, не нужен, так что будем использовать grep😉
Мы знаем какую инструкцию искать после использования ksymoops.

0xc02b47df <udp_rcv+226>:       push   %eax
0xc02b47e0 <udp_rcv+227>:       push   %edi
0xc02b47e1 <udp_rcv+228>:       push   %ebx
0xc02b47e2 <udp_rcv+229>: call 0xc02b467d <udp_checksum_init>
0xc02b47e7 <udp_rcv+234>:       add    $0x14,%esp
0xc02b47ea <udp_rcv+237>:       test   %eax,%eax
0xc02b47ec <udp_rcv+239>:       js     0xc02b4746 <udp_rcv+73>
0xc02b47f2 <udp_rcv+245>:       mov    0x8(%esp,1),%ebp
0xc02b47f6 <udp_rcv+249>: testl $0x30000000,0x94(%ebp)
0xc02b47fd <udp_rcv+256>:       je     0xc02601e8 <udp_rcv+296>
0xc02b47ff <udp_rcv+258>:       mov    (%esp,1),%eax
0xc02b4802 <udp_rcv+261>:       push   %eax

Что мы тут можем увидеть? Мы можем увидеть, что инструкция следует почти сразу же после вызова функции udp_checksum_init. Самое время теперь посмотреть исходники на “более человеческом” языке🙂

    struct rtable *rt = (struct rtable*) skb->dst;
    ...
        if (udp_checksum_init(skb, uh, ulen, saddr, daddr) < 0)
                goto csum_error;
        if (rt->rt_flags & (RTCF_BROADCAST|RTCF_MULTICAST))
                return udp_v4_mcast_deliver(skb, uh, saddr, daddr);

Ошибка во втором if-условии, потому что указатель “rt” был неправильно инициализирован. Никогда так не делайте…

Для особо любознательных: /usr/src/linux/drivers/scsi/cxgbi/libcxgbi.c

/proc/modules

Один из самых важных файлов в proc, который содержит полный список активных в настоящий момент модулей ядра. Ее содержание зависит от конфигурации системы. Формат следующий:

ip_tables         22270   2   iptable_raw, iptable_filter   Live 0xffffffffa0567000
ip6table_filter   1855    1                                 Live 0xffffffffa0538000

Сначала имя модуля. Затем размер, который он занимает в памяти (в байтах). Третья колонка это сколько копий этого модуля загруженно в данный момент (если 0, значит модуль выгружен). Затем зависимость этого модуля от других модулей. В нашем случае модуль ip_tables зависит от
iptable_raw и iptable_filter. Пятая колонка – состояние модуля; их может быть три: Live, Loading, или Unloading. Ну и наконец смещение(offset) в памяти для этого модуля. Именно это значение может быть полезным при отладке ядра, а так же анализе kernel panic.

/boot/System.map-$(uname -r)

Еще более полезным будет содержание файла /boot/System.map-$(uname -r). В нем находится символьная таблица адресов функций, используемых ядром. Именно эти адреса мы видем в “Call Trace” oops-сообщения.

cat /boot/System.map-$(uname -r) | grep nf_iterate
ffffffff8144fb70 T nf_iterate

cat /boot/System.map-$(uname -r) | grep ip_rcv
ffffffff81457270 t ip_rcv_finish
ffffffff81457a90 T ip_rcv

cat /boot/System.map-$(uname -r) | grep do_IRQ
ffffffff810054a0 T do_IRQ

cat /boot/System.map-$(uname -r) | grep common_interrupt
ffffffff81524580 t common_interrupt

Надеюсь, что теперь kernel panic не вызовет панику у вас, и вы сможете разобраться в проблеме, а возможно даже исправить ее. Удачи и happy hacking😉

5 Responses

Subscribe to comments with RSS.

  1. tuoma said, on 25.07.2011 at 07:59

    Очен6ь интересная и познавательная статья. Только маленькая поправочка: на фотке дамп регистров находится ДО информации о процессе🙂

    • Alex said, on 25.07.2011 at 11:00

      Да, спасибо🙂
      FIX: Поменял местами.

  2. […] знать какие пакеты/кодеки обновлять. Прочитал статью Don’t Panic , но не нашел , как получить стек рухнувшей программы. […]

  3. vladspbru said, on 03.08.2011 at 08:31

    Спасибо за статью.

    А как разобраться подобныйм образом с крахом пользовательской программы, включить трасировку стека, запись в лог?

    • Alex said, on 03.08.2011 at 13:48

      Спасибо за идею. Я сейчас начал статью о принципе работы отладчиков, и в следующей тогда опишу анализ отладочной информации из user space.
      Тут я хотел сосредоточится именно на ядре.


Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

%d bloggers like this: