このブログはURLが変更になりました

新しいブログはこちら→ https://matsuu.hatenablog.com/

RHEL(CentOS)6系でトラフィックをたくさん捌くサーバが死ぬ問題は6.5のkernel-2.6.32-431.el6以降で多分直る

タイトルで言いたいことはすべて言った。

経緯

うちの場合はLVS+keepalivedなロードバランサなんだけど、ちょくちょくkernel panicになる問題が発生してた。
そこでcrashコマンドで解析してみた。crashコマンドの使い方はこちらが参考になる。Linux crash dump 読み方入門

# crash /boot/System.map-2.6.32-279.14.1.el6.x86_64 /usr/lib/debug/lib/modules/2.6.32-279.14.1.el6.x86_64/vmlinux /var/crash/127.0.0.1-2013-09-27-16\:21\:01/vmcore 
(snip)
  SYSTEM MAP: /boot/System.map-2.6.32-279.14.1.el6.x86_64              
DEBUG KERNEL: /usr/lib/debug/lib/modules/2.6.32-279.14.1.el6.x86_64/vmlinux (2.6.32-279.14.1.el6.x86_64)
    DUMPFILE: /var/crash/127.0.0.1-2013-09-27-16:21:01/vmcore  [PARTIAL DUMP]
        CPUS: 8
        DATE: Fri Sep 27 16:19:55 2013
      UPTIME: 3 days, 15:03:51
LOAD AVERAGE: 0.01, 0.04, 0.00
       TASKS: 283
    NODENAME: XXXXXX(masked)
     RELEASE: 2.6.32-279.14.1.el6.x86_64
     VERSION: #1 SMP Tue Nov 6 23:43:09 UTC 2012
     MACHINE: x86_64  (2128 Mhz)
      MEMORY: 8 GB
       PANIC: "kernel BUG at net/ipv4/tcp_ipv4.c:417!"
         PID: 0
     COMMAND: "swapper"
        TASK: ffff88022a568aa0  (1 of 8)  [THREAD_INFO: ffff88022a56c000]
         CPU: 3
       STATE: TASK_RUNNING (PANIC)

ログ

crash> log
(snip)
kernel BUG at net/ipv4/tcp_ipv4.c:417!
invalid opcode: 0000 [#1] SMP 
last sysfs file: /sys/devices/system/cpu/cpu7/cache/index2/shared_cpu_map
CPU 3 
Modules linked in: ip_vs_rr ip_vs_wlc ip_vs_wrr ipmi_si mpt2sas scsi_transport_sas raid_class mptctl mptbase ipmi_devintf ipmi_msghandler dell_rbu ip_vs libcrc32c 8021q garp stp llc ipv6 nf_nat_ftp nf_conntrack_ftp nf_connt
rack_netbios_ns nf_conntrack_broadcast xt_limit ipt_REJECT xt_state xt_multiport iptable_filter ipt_LOG ipt_MASQUERADE xt_mark iptable_nat nf_nat nf_conntrack_ipv4 nf_conntrack nf_defrag_ipv4 xt_MARK iptable_mangle iptable_
raw ip_tables power_meter ses enclosure sg bnx2 dcdbas microcode serio_raw iTCO_wdt iTCO_vendor_support i7core_edac edac_core ext4 mbcache jbd2 sr_mod cdrom sd_mod crc_t10dif pata_acpi ata_generic ata_piix megaraid_sas dm_m
irror dm_region_hash dm_log dm_mod [last unloaded: ipmi_si]

Pid: 0, comm: swapper Not tainted 2.6.32-279.14.1.el6.x86_64 #1 Dell Inc. PowerEdge R410/01V648
RIP: 0010:[<ffffffff81494c71>]  [<ffffffff81494c71>] tcp_v4_err+0x5e1/0x5f0
RSP: 0018:ffff88002f863bd0  EFLAGS: 00010246
RAX: ffff8801bde90208 RBX: ffff880215d49c2c RCX: ffff8801bde90208
RDX: 00000000000007d0 RSI: 0000000000000002 RDI: ffff8801bde90188
RBP: ffff88002f863c50 R08: ffff8801bde90150 R09: ffff8801bde90188
R10: 0000000055d6096c R11: 0000000000000001 R12: ffff8801bde90140
R13: ffffffff8200cec0 R14: ffff880215d49c40 R15: 0000000000000071
FS:  0000000000000000(0000) GS:ffff88002f860000(0000) knlGS:0000000000000000
CS:  0010 DS: 0018 ES: 0018 CR0: 000000008005003b
CR2: 0000003da9613000 CR3: 0000000217c2f000 CR4: 00000000000006e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Process swapper (pid: 0, threadinfo ffff88022a56c000, task ffff88022a568aa0)
Stack:
 ffff880000000001 ffffffffa01b3557 ffff880100000014 000000000000b0c6
<d> ffff8801bde90188 fd02a8c0fd02a8c0 0000c6b000000001 01ffffff00000000
<d> 0000000080000000 000000002f863cd8 0000000080000000 0000000000000006
Call Trace:
 <IRQ> 
 [<ffffffffa01b3557>] ? ipv4_confirm+0x87/0x1d0 [nf_conntrack_ipv4]
 [<ffffffff8149f0d0>] icmp_unreach+0x140/0x2d0
 [<ffffffff8149ee40>] icmp_rcv+0x290/0x330
 [<ffffffff814718d0>] ? ip_local_deliver_finish+0x0/0x2d0
 [<ffffffff814719ad>] ip_local_deliver_finish+0xdd/0x2d0
 [<ffffffff81471c38>] ip_local_deliver+0x98/0xa0
 [<ffffffffa0126813>] ? bnx2_poll_work+0x633/0x1270 [bnx2]
 [<ffffffff814710fd>] ip_rcv_finish+0x12d/0x440
 [<ffffffff81471685>] ip_rcv+0x275/0x350
 [<ffffffff81447390>] ? neigh_timer_handler+0x0/0x340
 [<ffffffff8143adcb>] __netif_receive_skb+0x49b/0x6f0
 [<ffffffff8143b0ba>] process_backlog+0x9a/0x100
 [<ffffffff8143f7a3>] net_rx_action+0x103/0x2f0
 [<ffffffff81073f61>] __do_softirq+0xc1/0x1e0
 [<ffffffff81096d60>] ? hrtimer_interrupt+0x140/0x250
 [<ffffffff8100c24c>] call_softirq+0x1c/0x30
 [<ffffffff8100de85>] do_softirq+0x65/0xa0
 [<ffffffff81073d45>] irq_exit+0x85/0x90
 [<ffffffff81506450>] smp_apic_timer_interrupt+0x70/0x9b
 [<ffffffff8100bc13>] apic_timer_interrupt+0x13/0x20
 <EOI> 
 [<ffffffff81407a38>] ? poll_idle+0x38/0x80
 [<ffffffff81407a13>] ? poll_idle+0x13/0x80
 [<ffffffff81407c27>] cpuidle_idle_call+0xa7/0x140
 [<ffffffff81009e06>] cpu_idle+0xb6/0x110
 [<ffffffff814f754f>] start_secondary+0x22a/0x26d
Code: 4c 8b 4d a0 e9 71 fc ff ff 89 d2 eb 8d be ca 01 00 00 48 c7 c7 6e 46 80 81 e8 8c 6b bd ff 44 8b 55 98 4c 8b 4d a0 e9 1e fd ff ff <0f> 0b eb fe 90 90 90 90 90 90 90 90 90 90 90 55 48 89 e5 48 83 
RIP  [<ffffffff81494c71>] tcp_v4_err+0x5e1/0x5f0
 RSP <ffff88002f863bd0>

バックトレース

crash> bt
PID: 0      TASK: ffff88022a568aa0  CPU: 3   COMMAND: "swapper"
 #0 [ffff88002f863890] machine_kexec at ffffffff8103284b
 #1 [ffff88002f8638f0] crash_kexec at ffffffff810ba982
 #2 [ffff88002f8639c0] oops_end at ffffffff81501b00
 #3 [ffff88002f8639f0] die at ffffffff8100f26b
 #4 [ffff88002f863a20] do_trap at ffffffff815013f4
 #5 [ffff88002f863a80] do_invalid_op at ffffffff8100ce35
 #6 [ffff88002f863b20] invalid_op at ffffffff8100bedb
    [exception RIP: tcp_v4_err+1505]
    RIP: ffffffff81494c71  RSP: ffff88002f863bd0  RFLAGS: 00010246
    RAX: ffff8801bde90208  RBX: ffff880215d49c2c  RCX: ffff8801bde90208
    RDX: 00000000000007d0  RSI: 0000000000000002  RDI: ffff8801bde90188
    RBP: ffff88002f863c50   R8: ffff8801bde90150   R9: ffff8801bde90188
    R10: 0000000055d6096c  R11: 0000000000000001  R12: ffff8801bde90140
    R13: ffffffff8200cec0  R14: ffff880215d49c40  R15: 0000000000000071
    ORIG_RAX: ffffffffffffffff  CS: 0010  SS: 0018
 #7 [ffff88002f863c58] icmp_unreach at ffffffff8149f0d0
 #8 [ffff88002f863c98] icmp_rcv at ffffffff8149ee40
 #9 [ffff88002f863ce8] ip_local_deliver_finish at ffffffff814719ad
#10 [ffff88002f863d18] ip_local_deliver at ffffffff81471c38
#11 [ffff88002f863d48] ip_rcv_finish at ffffffff814710fd
#12 [ffff88002f863d88] ip_rcv at ffffffff81471685
#13 [ffff88002f863dc8] __netif_receive_skb at ffffffff8143adcb
#14 [ffff88002f863e28] process_backlog at ffffffff8143b0ba
#15 [ffff88002f863e78] net_rx_action at ffffffff8143f7a3
#16 [ffff88002f863ed8] __do_softirq at ffffffff81073f61
#17 [ffff88002f863f48] call_softirq at ffffffff8100c24c
#18 [ffff88002f863f60] do_softirq at ffffffff8100de85
#19 [ffff88002f863f80] irq_exit at ffffffff81073d45
#20 [ffff88002f863f90] smp_apic_timer_interrupt at ffffffff81506450
#21 [ffff88002f863fb0] apic_timer_interrupt at ffffffff8100bc13
--- <IRQ stack> ---
#22 [ffff88022a56ddf8] apic_timer_interrupt at ffffffff8100bc13
    [exception RIP: poll_idle+56]
    RIP: ffffffff81407a38  RSP: ffff88022a56dea8  RFLAGS: 00000246
    RAX: 0000000400000000  RBX: ffff88022a56ded8  RCX: 000000000000001f
    RDX: ffff88022a56dfd8  RSI: ffff88002f87dcd0  RDI: ffffffff81a8fc40
    RBP: ffffffff8100bc0e   R8: 0000000000000004   R9: 0000000000000010
    R10: 0000000000000000  R11: 0000000000000000  R12: 0000000000000000
    R13: 0000000000000000  R14: 0000000000000002  R15: 0000000000000050
    ORIG_RAX: ffffffffffffff10  CS: 0010  SS: 0018
#23 [ffff88022a56dee0] cpuidle_idle_call at ffffffff81407c27
#24 [ffff88022a56df00] cpu_idle at ffffffff81009e06

得られた情報からググってみたところ、これと全く同じ症状だった。

kernel panic in tcp_v4_err() on icmp unreachable

該当パッチは2011年1月にリリースされた2.6.37で取り込まれているのだが、2.6.32を採用したRHEL6にはバックポートされていなかった。ちなみにDebianには2012年9月にリリースされた2.6.32-46でバックポートされた模様。

Debian Bug report logs - #685087

そこでRedHatのbugzilla(一般非公開)に報告したものの待てど暮らせどと変化なし。
あとでRedHatの中の人に聞いたところによると、

RHELの開発者はどれだけ深刻な問題でもBugzillaから直接報告されたバグ報告は見てない。RHNのライセンスを介して報告しないと本家には伝わらない。

とのこと。あらーそうなのね。
でも運良くRedHatの人に拾ってもらえて、古いバグ報告(こちらも非公開)にmarked as duplicateされた後、RHEL6.5のリリースと共に修正が取り込まれた。

カーネルのリリースノートにはこのバグ修正に関する言及はないのだが、同じ問題で悩まれていた方は是非カーネルアップデートをご検討ください。

追記1

Bug #757658Bug #1014877が非公開になっているのは、セキュリティのリスクを考慮してだと思う。CVEとして報告されているわけでもないので。ちなみにBug #757658が登録されたのは2011年11月28日。約2年越しのバグ修正だった*1

追記2

RedHatの中の人より

実は俺もこの意見には賛成で、RedHatが直接Bugzillaに報告された報告を拾うことはあっても、必ず対応する必要なんてないと思ってる。それがどんなにひどいバグだとしても。

ちなみに昔はご丁寧に拾ってくれていたそうです。いつからそのような方針に変わったかは不明。

*1:ちなみに私が報告したBug #1014877の登録日は2013年10月2日