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 #757658とBug #1014877が非公開になっているのは、セキュリティのリスクを考慮してだと思う。CVEとして報告されているわけでもないので。ちなみにBug #757658が登録されたのは2011年11月28日。約2年越しのバグ修正だった*1。
追記2
RedHatの中の人より
Red Hat BugzillaはRHELクローンのバグ報告をする先ではない。RHELのサブスクリプション契約には契約期間内の回数無制限の問い合わせ権がついているのでカスタマーポータルから問い合わせて欲しい。>> http://t.co/K9FAlnkFN0
— Hajime Taira (@htaira) December 3, 2013ちなみに昔はご丁寧に拾ってくれていたそうです。いつからそのような方針に変わったかは不明。
*1:ちなみに私が報告したBug #1014877の登録日は2013年10月2日
