Отладка Kernel Panic

• ставим kdump и kernel-debuginfo (нужен vmlinux Не linuz)
• ловим панику
• Запускаем утилиту crash /usr/lib/debug/lib/modules/2.6.32-642.el6.x86_64/vmlinux /var/crash/vmcore
• http://people.redhat.com/anderson/crash_whitepaper/#HELP
• https://www.kernel.org/doc/Documentation/kdump/kdump.txt
• https://www.dedoimedo.com/computers/crash-book.html
• http://people.redhat.com/anderson/crash_whitepaper/
• Удобный листинг dis -rl 0xffffffffb1fe2fe5
• Если это обычная паника по памяти и тп, то она обычно на то ядре где и поймали.
• Помним что локап мог быть на 4ом ядре, а виновато могло быть 1 ядро. Локап надо сверять по всем ядрам и смотреть те которые значительно по стеку отличаются от других.
• Помним что стек может быть лоскутным из-за прерываний и случайного попадания переменных колбек функций в стек.
• Видим

 KERNEL: /usr/lib/debug/lib/modules/2.6.32-642.el6.x86_64/vmlinux
    DUMPFILE: /var/crash/127.0.0.1-2018-09-24-15:07:40/vmcore  [PARTIAL DUMP]
        CPUS: 8
        DATE: Mon Sep 24 15:21:45 2018
      UPTIME: 76 days, 03:30:21
LOAD AVERAGE: 40.84, 23.29, 11.60
       TASKS: 298
    NODENAME: host22
     RELEASE: 2.6.32-642.el6.x86_64
     VERSION: #1 SMP Tue May 10 17:27:01 UTC 2016
     MACHINE: x86_64  (3702 Mhz)
      MEMORY: 32 GB
       PANIC: "Kernel panic - not syncing: softlockup: hung tasks"
         PID: 5487
     COMMAND: "sshd"
        TASK: ffff880834017520  [THREAD_INFO: ffff8807708e4000]
         CPU: 6
       STATE: TASK_RUNNING (PANIC)

• Причина паники PANIC: «Kernel panic - not syncing: softlockup: hung tasks»
• LOAD AVERAGE: 40.84 - довольно большой, возможно паника была не мгновенной, а вначале подвисло, значит в стеке мусора может быть много.
• COMMAND: «sshd» - Обычно это просто текущее приложение которое было активно во время паники и если от него нет прямых сисколов в паникующу функцию, то оно не причем.
• Команды crash
• начнем с crash>log лог здесь может быть полней чем в messages тк messages
• список процессов crash>ps

• Делаем bt -c 0 далее bt -c 1 и тд по всем процессорам
• Находим стеки отличающиеся от других и просто подозрительные
• Завариваем кофе, выливаем, гадаем
• Обычно локап бывает при повторном попадании на свой же спинлок или свой врайтлок поверх ридлок при сменах контекста в широком смысле, часто из-за незапрещеных/случайноразрешенных BH или CLI. То есть висит себе ядро в блокироке, его прерывали и послали обрабатывать по другому стеку и пришло оно к той же блокировке и вот вам локап.
• Часто если функция и локеры написаны для ядра, а вызываются из юспейс и наоборот
• Часто конфликты юспейс и ядра
• Часто перекрестная блокировка deadlock 2×2 две блокировки два ядра крест накрет

crash>bt -c 0

PID: 6836   TASK: ffff88082d8e3520  CPU: 2   COMMAND: "sshd"
 #0 [ffff880028286e90] crash_nmi_callback at ffffffff810366e6
 #1 [ffff880028286ea0] notifier_call_chain at ffffffff8154dc85
 #2 [ffff880028286ee0] atomic_notifier_call_chain at ffffffff8154dcea
 #3 [ffff880028286ef0] notify_die at ffffffff810aceae
 #4 [ffff880028286f20] do_nmi at ffffffff8154b903
 #5 [ffff880028286f50] nmi at ffffffff8154b1c3
    [exception RIP: __write_lock_failed+9]
    RIP: ffffffff812a6f29  RSP: ffff880028283950  RFLAGS: 00000287
    RAX: ffff88078b0fbfd8  RBX: ffff88075efe27e0  RCX: 0000000000000002
    RDX: 0000000000000036  RSI: ffff8807905a35c0  RDI: ffff88075efe27e0
    RBP: ffff880028283968   R8: 0000000000000006   R9: ffff880028283937
    R10: ffffc90019613300  R11: 0000000000000000  R12: 0000000000000002
    R13: 0000000000000002  R14: ffff8807905a35c0  R15: ffff88075efe27e0
    ORIG_RAX: ffffffffffffffff  CS: 0010  SS: 0018
--- <NMI exception stack> ---
 #6 [ffff880028283950] __write_lock_failed at ffffffff812a6f29
 #7 [ffff880028283950] _write_lock_bh at ffffffff8154aa87
 #8 [ffff880028283970] ip_set_add at ffffffffa0726841 [ip_set]
 #9 [ffff8800282839c0] set_target at ffffffffa074d464 [xt_set]
#10 [ffff8800282839f0] ipt_do_table at ffffffffa06d920b [ip_tables]
#11 [ffff880028283b80] ipt_hook at ffffffffa071d0f3 [iptable_filter]
#12 [ffff880028283b90] nf_iterate at ffffffff814a8c89
#13 [ffff880028283be0] nf_hook_slow at ffffffff814a8e46
#14 [ffff880028283c60] ip_forward at ffffffff814b5523
#15 [ffff880028283ca0] ip_rcv_finish at ffffffff814b34ad
#16 [ffff880028283ce0] ip_rcv at ffffffff814b3a35
#17 [ffff880028283d20] __netif_receive_skb at ffffffff81478401

Далее crash> bt -c 1

PID: 5752   TASK: ffff88077fa8aab0  CPU: 1   COMMAND: "modules_ctl"
 #0 [ffff880028246e90] crash_nmi_callback at ffffffff810366e6
 #1 [ffff880028246ea0] notifier_call_chain at ffffffff8154dc85
 #2 [ffff880028246ee0] atomic_notifier_call_chain at ffffffff8154dcea
 #3 [ffff880028246ef0] notify_die at ffffffff810aceae
 #4 [ffff880028246f20] do_nmi at ffffffff8154b903
 #5 [ffff880028246f50] nmi at ffffffff8154b1c3
    [exception RIP: __write_lock_failed+15]
    RIP: ffffffff812a6f2f  RSP: ffff8800282438e8  RFLAGS: 00000287
    RAX: ffff880769db3fd8  RBX: ffff88075efe27e0  RCX: 0000000000000002
    RDX: 0000000000000036  RSI: ffff8807ceee3880  RDI: ffff88075efe27e0
    RBP: ffff880028243900   R8: 0000000000000006   R9: ffff8800282438cf
    R10: ffffc9001960b300  R11: 0000000000000001  R12: 0000000000000002
    R13: 0000000000000002  R14: ffff8807ceee3880  R15: ffff88075efe27e0
    ORIG_RAX: ffffffffffffffff  CS: 0010  SS: 0000
--- <NMI exception stack> ---
 #6 [ffff8800282438e8] __write_lock_failed at ffffffff812a6f2f
 #7 [ffff8800282438e8] _write_lock_bh at ffffffff8154aa87
 #8 [ffff880028243908] ip_set_add at ffffffffa0726841 [ip_set]
 #9 [ffff880028243958] set_target at ffffffffa074d464 [xt_set]
#10 [ffff880028243988] ipt_do_table at ffffffffa06d920b [ip_tables]
#11 [ffff880028243b18] ipt_hook at ffffffffa071d0f3 [iptable_filter]
#12 [ffff880028243b28] nf_iterate at ffffffff814a8c89
#13 [ffff880028243b78] nf_hook_slow at ffffffff814a8e46
#14 [ffff880028243bf8] ip_forward at ffffffff814b5523
#15 [ffff880028243c38] ip_rcv_finish at ffffffff814b34ad
#16 [ffff880028243c78] ip_rcv at ffffffff814b3a35
#17 [ffff880028243cb8] __netif_receive_skb at ffffffff81478401

Далее crash> bt -c 0 1 2 3 4 5 6 - имеют примерно одинаковый вывод с залочиванием на функции ip_set_add на _write_lock_bh
А вот далее уже интересней на 8 ом ядре
crash> bt -c 7

crash> bt -c 7
PID: 33     TASK: ffff8808340da040  CPU: 7   COMMAND: "ksoftirqd/7"
 #0 [ffff8800283c6e90] crash_nmi_callback at ffffffff810366e6
PID: 33     TASK: ffff8808340da040  CPU: 7   COMMAND: "ksoftirqd/7"
 #0 [ffff8800283c6e90] crash_nmi_callback at ffffffff810366e6
 #1 [ffff8800283c6ea0] notifier_call_chain at ffffffff8154dc85
 #2 [ffff8800283c6ee0] atomic_notifier_call_chain at ffffffff8154dcea
 #3 [ffff8800283c6ef0] notify_die at ffffffff810aceae
 #4 [ffff8800283c6f20] do_nmi at ffffffff8154b903
 #5 [ffff8800283c6f50] nmi at ffffffff8154b1c3
    [exception RIP: hash_netport4_expire+91]
    RIP: ffffffffa00c608b  RSP: ffff8800283c3878  RFLAGS: 00000246
    RAX: 0000000000000000  RBX: 00000000000e08c0  RCX: 0000000000000010
    RDX: 00000002881f522f  RSI: ffff8800283c3928  RDI: 0000000000000004
    RBP: ffff8800283c38b8   R8: ffff8800283c392c   R9: ffff8800283c392e
    R10: 0000000000000001  R11: 0000000000000001  R12: 0000000000000000
    R13: ffff88080f400000  R14: 00000000000e08d0  R15: ffff88082e4cd400
    ORIG_RAX: ffffffffffffffff  CS: 0010  SS: 0018
--- <NMI exception stack> ---
 #6 [ffff8800283c3878] hash_netport4_expire at ffffffffa00c608b [ip_set_hash_netport]
 #7 [ffff8800283c38c0] hash_netport4_tadd at ffffffffa00ca2a0 [ip_set_hash_netport]
 #8 [ffff8800283c3910] hash_netport4_kadt at ffffffffa00c5b2a [ip_set_hash_netport]
 #9 [ffff8800283c3970] ip_set_add at ffffffffa0726860 [ip_set]
#10 [ffff8800283c39c0] set_target at ffffffffa074d464 [xt_set]
#11 [ffff8800283c39f0] ipt_do_table at ffffffffa06d920b [ip_tables]
#12 [ffff8800283c3b80] ipt_hook at ffffffffa071d0f3 [iptable_filter]
#13 [ffff8800283c3b90] nf_iterate at ffffffff814a8c89
#14 [ffff8800283c3be0] nf_hook_slow at ffffffff814a8e46
#15 [ffff8800283c3c60] ip_forward at ffffffff814b5523
#16 [ffff8800283c3ca0] ip_rcv_finish at ffffffff814b34ad
#17 [ffff8800283c3ce0] ip_rcv at ffffffff814b3a35
#18 [ffff8800283c3d20] __netif_receive_skb at ffffffff81478401

• На 8 ом процессоре явно ситуация отличная от других, здесь ip_set_add прошел через _write_lock и застрял где-то в #6 [ffff8800283c3878] hash_netport4_expire at ffffffffa00c608b [ip_set_hash_netport].
  
• at 0xffffffffa00c608b - это нужный нам абсолютный адрес для дебага
  • [ip_set_hash_netport] - это имя модуля
• Делаем dis -l hash_netport4_expiredis и смотрим 0xffffffffa00c608b

            0xffffffffa00c607f <hash_netport4_expire+79>:   shl    $0x4,%r14
            0xffffffffa00c6083 <hash_netport4_expire+83>:   cmpb   $0x0,0x11(%r14,%r13,1)
            0xffffffffa00c6089 <hash_netport4_expire+89>:   jne    0xffffffffa00c60a3
НАША АДРЕС: 0xffffffffa00c608b <hash_netport4_expire+91>:   jmpq   0xffffffffa00c614d
            0xffffffffa00c6090 <hash_netport4_expire+96>:   movzbl 0x11(%r14,%r13,1),%eax
            0xffffffffa00c6096 <hash_netport4_expire+102>:  add    $0x1,%r12d
            0xffffffffa00c609a <hash_netport4_expire+106>:  cmp    %r12d,%eax

• Наш адрес = hash_netport4_expire+91
• Далее выходим из crash и запускаем gdb на на модуль
  • gdb /lib/modules/2.6.32-642.el6.x86_64/kernel/net/netfilter/ipset/ip_set_hash_netport.ko
  • Ура подгрузилось с дебагом: Reading symbols from /usr/lib/debug/lib/modules/2.6.32-642.el6.x86_64/kernel/net/netfilter/ipset/ip_set_hash_netport.ko.debug…done.
  • disass hash_netport4_expire

                0x00000000000010b3 <+83>:    cmpb   $0x0,0x11(%r14,%r13,1)
                0x00000000000010b9 <+89>:    jne    0x10d3 <hash_netport4_expire+115>
НАШ АДРЕС +91   0x00000000000010bb <+91>:    jmpq   0x117d <hash_netport4_expire+285>
                0x00000000000010c0 <+96>:    movzbl 0x11(%r14,%r13,1),%eax
                0x00000000000010c6 <+102>:   add    $0x1,%r12d

• Видим нашу строку 0x00000000000010bb <+91>: jmpq 0x117d <hash_netport4_expire+285>
• Делаем листинг
• (gdb) list *hash_netport4_expire+91
• 0x10bb is in hash_netport4_expire (include/linux/netfilter/ipset/ip_set_ahash.h:701).

0x10bb is in hash_netport4_expire (include/linux/netfilter/ipset/ip_set_ahash.h:701).
696             u32 i;
697             int j;
698
699             for (i = 0; i < jhash_size(t->htable_bits); i++) {
700                     n = hbucket(t, i);
Наша строка 701                     for (j = 0; j < n->pos; j++) {
702                             data = ahash_tdata(n, j);
703                             if (type_pf_data_expired(data)) {
704                                     pr_debug("expired %u/%u\n", i, j);
705     #ifdef IP_SET_HASH_WITH_NETS 

• Итого мы нашли подозрительную функцию и конкретную строчку

• grep hash_netport4_expire - ничего не находим, такое часто если функции сделаны через макросы и надо искать префикс или постфикс
• grep -r _expire /usr/src/linux/include/linux/netfilter/ipset - а вот и нашли #define type_pf_expire TOKEN(TYPE, PF, _expire
• Имя функции генерируется макросом через макропеременную TYPE который объявлен в ip_set_hash_netport.c
  • #define TYPE hash_netport
• Далее смотрим откуда она вызывается grep type_pf_expire
• Находим аналогично через предыдущую функцию hash_netport4_tadd ее макроопределение type_pf_tadd и там

if (h->elements >= h->maxelem)
       /* FIXME: when set is full, we slow down here */
       type_pf_expire(h);

• В функции type_pf_expire мы видим два вложенных цикла, но в теории они не очень большие, а локап срабатывает при 60 сек.
• Возможно что то приводит к частому вызову type_pf_expire либо она сильно тормозит.
• В любом случае проблема при переполнении ip_set h→elements >= h→maxelem
• Что делаем далее, далее пауза и пробуем повторить синтетик тестом, если не вышло то ждем повтора на продакшене
• Если удалось повторить, начинаем разбираться подробней с дебагами и тд

~~OWNERAPPROVE~~