読者です 読者をやめる 読者になる 読者になる

デバッグ: CentOS7 BUG: unable to handle kernel NULL pointer dereference at (null)

CentOS7 で BUG: unable to handle kernel NULL pointer dereference at (null) で kernel panic したのを深追いで調べていた

バックトレース

[705327.823158] BUG: unable to handle kernel NULL pointer dereference at           (null)
[705327.824009] IP: [<ffffffff81573762>] skb_entail+0x52/0xd0
[705327.828140] PGD 18fe72067 PUD 18fe73067 PMD 0 
[705327.828140] Oops: 0002 [#1] SMP 
[705327.828140] Modules linked in: dccp_diag dccp tcp_diag udp_diag inet_diag unix_diag af_packet_diag netlink_diag nls_utf8 isofs ppdev i2c_piix4 sg parport_pc virtio_balloon parport pcspkr nfsd auth_rpcgss nfs_acl lockd grace sunrpc ip_tables xfs libcrc32c sr_mod cdrom ata_generic pata_acpi cirrus virtio_blk virtio_net syscopyarea sysfillrect sysimgblt drm_kms_helper ttm ata_piix crc32c_intel drm virtio_pci virtio_ring serio_raw libata virtio i2c_core floppy dm_mirror dm_region_hash dm_log dm_mod
[705327.837099] CPU: 0 PID: 2790 Comm: nginx Not tainted 3.10.0-327.36.1.el7.x86_64 #1
[705327.837099] Hardware name: Red Hat Inc. OpenStack Nova, BIOS 0.5.1 01/01/2007
[705327.837099] task: ffff880036a1dc00 ti: ffff88018fcbc000 task.ti: ffff88018fcbc000
[705327.837099] RIP: 0010:[<ffffffff81573762>]  [<ffffffff81573762>] skb_entail+0x52/0xd0
[705327.837099] RSP: 0018:ffff88018fcbfb88  EFLAGS: 00010202
[705327.837099] RAX: 0000000000000000 RBX: 0000000000003890 RCX: 00000000ffffffff
[705327.837099] RDX: ffff8801089c9038 RSI: ffff8801089c9038 RDI: ffff8801089c8f00
[705327.837099] RBP: ffff88018fcbfb88 R08: 00000000000006c0 R09: 0000000000000900
[705327.837099] R10: ffff880217001400 R11: 8883e3b982e39d83 R12: 0000000000000000
[705327.837099] R13: ffff8801089c8f00 R14: ffff8801089c9038 R15: 0000000000000fb0
[705327.837099] FS:  00007fca72598840(0000) GS:ffff88021fc00000(0000) knlGS:0000000000000000
[705327.837099] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[705327.837099] CR2: 0000000000000000 CR3: 000000018fe71000 CR4: 00000000000007f0
[705327.837099] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[705327.837099] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[705327.837099] Stack:
[705327.837099]  ffff88018fcbfc50 ffffffff81577bf2 ffff880036a1e688 ffff880000000001
[705327.837099]  0000000000000050 ffff88018fcbffd8 0000000000000000 ffff880036a1dc00
[705327.837099]  ffff88018fcbffd8 ffff88018fcbfe70 00000000011b4df9 0000000000000501
[705327.837099] Call Trace:
[705327.837099]  [<ffffffff81577bf2>] tcp_sendmsg+0x6f2/0xc20
[705327.837099]  [<ffffffff815a1c04>] inet_sendmsg+0x64/0xb0
[705327.837099]  [<ffffffff815103d7>] sock_aio_write+0x157/0x180
[705327.837099]  [<ffffffff811de5d9>] do_sync_readv_writev+0x79/0xd0
[705327.837099]  [<ffffffff811dfbae>] do_readv_writev+0xce/0x260
[705327.837099]  [<ffffffff81058aaf>] ? kvm_clock_get_cycles+0x1f/0x30
[705327.837099]  [<ffffffff810d896a>] ? __getnstimeofday64+0x3a/0xd0
[705327.837099]  [<ffffffff811dfdd5>] vfs_writev+0x35/0x60
[705327.837099]  [<ffffffff811dff8f>] SyS_writev+0x7f/0x110
[705327.837099]  [<ffffffff81646a09>] system_call_fastpath+0x16/0x1b
[705327.837099] Code: 4d 00 89 46 44 89 46 40 8b 86 dc 00 00 00 c7 44 02 24 01 00 01 00 48 8b 87 40 01 00 00 48 8d 97 38 01 00 00 48 89 16 48 89 46 08 <48> 89 30 83 87 48 01 00 00 01 48 83 bf 68 02 00 00 00 48 89 b7 
[705327.837099] RIP  [<ffffffff81573762>] skb_entail+0x52/0xd0
[705327.837099]  RSP <ffff88018fcbfb88>
[705327.837099] CR2: 0000000000000000

以下、調べてみてのわかったことと推測

  • sk_stream_alloc_skb で新規に割り当てた struct sk_buffer skb と、 sk->write_queue のアドレスが なぜか同一 になっている
    • sk_stream_alloc_skb が返す skb は memset でゼロクリアされているので、skb->next, skb->prev 共に NULL となっている
    • skb と sk->write_queue が同じアドレスを指しいるので、つまり、sk->write_queue->next, sk->write_queue->prev も NULL となっている
  • 以上の状況で __skb_insert でリスト操作をする際に NULL pointer dereference が起きた

NULL pointer dereference が起きた状況は整理できたが、なぜこうなったのか、根本的な原因はよくわからない。ググってみても「これ」といったものは発見できず

調べていったログを記しておく (全体を整頓しきれていないので、情報が飛散しているのはご了承を)

dmesg

該当のインスタンスには kdump が仕込まれていたので、vmcore と dmesg が採取できている

$ cat /var/crash/127.0.0.1-2016-10-27-01\:11\:15/vmcore-dmesg.txt | grep -A100 BUG
[705327.823158] BUG: unable to handle kernel NULL pointer dereference at           (null)
[705327.824009] IP: [<ffffffff81573762>] skb_entail+0x52/0xd0
[705327.828140] PGD 18fe72067 PUD 18fe73067 PMD 0 
[705327.828140] Oops: 0002 [#1] SMP 
[705327.828140] Modules linked in: dccp_diag dccp tcp_diag udp_diag inet_diag unix_diag af_packet_diag netlink_diag nls_utf8 isofs ppdev i2c_piix4 sg parport_pc virtio_balloon parport pcspkr nfsd auth_rpcgss nfs_acl lockd grace sunrpc ip_tables xfs libcrc32c sr_mod cdrom ata_generic pata_acpi cirrus virtio_blk virtio_net syscopyarea sysfillrect sysimgblt drm_kms_helper ttm ata_piix crc32c_intel drm virtio_pci virtio_ring serio_raw libata virtio i2c_core floppy dm_mirror dm_region_hash dm_log dm_mod
[705327.837099] CPU: 0 PID: 2790 Comm: nginx Not tainted 3.10.0-327.36.1.el7.x86_64 #1
[705327.837099] Hardware name: Red Hat Inc. OpenStack Nova, BIOS 0.5.1 01/01/2007
[705327.837099] task: ffff880036a1dc00 ti: ffff88018fcbc000 task.ti: ffff88018fcbc000
[705327.837099] RIP: 0010:[<ffffffff81573762>]  [<ffffffff81573762>] skb_entail+0x52/0xd0
[705327.837099] RSP: 0018:ffff88018fcbfb88  EFLAGS: 00010202
[705327.837099] RAX: 0000000000000000 RBX: 0000000000003890 RCX: 00000000ffffffff
[705327.837099] RDX: ffff8801089c9038 RSI: ffff8801089c9038 RDI: ffff8801089c8f00
[705327.837099] RBP: ffff88018fcbfb88 R08: 00000000000006c0 R09: 0000000000000900
[705327.837099] R10: ffff880217001400 R11: 8883e3b982e39d83 R12: 0000000000000000
[705327.837099] R13: ffff8801089c8f00 R14: ffff8801089c9038 R15: 0000000000000fb0
[705327.837099] FS:  00007fca72598840(0000) GS:ffff88021fc00000(0000) knlGS:0000000000000000
[705327.837099] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[705327.837099] CR2: 0000000000000000 CR3: 000000018fe71000 CR4: 00000000000007f0
[705327.837099] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[705327.837099] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[705327.837099] Stack:
[705327.837099]  ffff88018fcbfc50 ffffffff81577bf2 ffff880036a1e688 ffff880000000001
[705327.837099]  0000000000000050 ffff88018fcbffd8 0000000000000000 ffff880036a1dc00
[705327.837099]  ffff88018fcbffd8 ffff88018fcbfe70 00000000011b4df9 0000000000000501
[705327.837099] Call Trace:
[705327.837099]  [<ffffffff81577bf2>] tcp_sendmsg+0x6f2/0xc20
[705327.837099]  [<ffffffff815a1c04>] inet_sendmsg+0x64/0xb0
[705327.837099]  [<ffffffff815103d7>] sock_aio_write+0x157/0x180
[705327.837099]  [<ffffffff811de5d9>] do_sync_readv_writev+0x79/0xd0
[705327.837099]  [<ffffffff811dfbae>] do_readv_writev+0xce/0x260
[705327.837099]  [<ffffffff81058aaf>] ? kvm_clock_get_cycles+0x1f/0x30
[705327.837099]  [<ffffffff810d896a>] ? __getnstimeofday64+0x3a/0xd0
[705327.837099]  [<ffffffff811dfdd5>] vfs_writev+0x35/0x60
[705327.837099]  [<ffffffff811dff8f>] SyS_writev+0x7f/0x110
[705327.837099]  [<ffffffff81646a09>] system_call_fastpath+0x16/0x1b
[705327.837099] Code: 4d 00 89 46 44 89 46 40 8b 86 dc 00 00 00 c7 44 02 24 01 00 01 00 48 8b 87 40 01 00 00 48 8d 97 38 01 00 00 48 89 16 48 89 46 08 <48> 89 30 83 87 48 01 00 00 01 48 83 bf 68 02 00 00 00 48 89 b7 
[705327.837099] RIP  [<ffffffff81573762>] skb_entail+0x52/0xd0
[705327.837099]  RSP <ffff88018fcbfb88>
[705327.837099] CR2: 0000000000000000

crash

debug-info と crash を用意した後に vmcore を解析する

crash> sys
      KERNEL: /usr/lib/debug/usr/lib/modules/3.10.0-327.36.1.el7.x86_64/vmlinux
    DUMPFILE: /var/crash/127.0.0.1-2016-10-27-01:11:15/vmcore  [PARTIAL DUMP]
        CPUS: 4
        DATE: Wed Oct 26 16:11:13 2016
      UPTIME: 8 days, 03:55:27
LOAD AVERAGE: 0.13, 0.14, 0.14
       TASKS: 285
    NODENAME: ********************
     RELEASE: 3.10.0-327.36.1.el7.x86_64
     VERSION: #1 SMP Sun Sep 18 13:04:29 UTC 2016
     MACHINE: x86_64  (2399 Mhz)
      MEMORY: 8 GB
       PANIC: "BUG: unable to handle kernel NULL pointer dereference at           (null)"

詳細な backtrace を取る

crash> bt -FF
PID: 2790   TASK: ffff880036a1dc00  CPU: 0   COMMAND: "nginx"
 #0 [ffff88018fcbf830] machine_kexec at ffffffff81051e9b
    ffff88018fcbf838: 000088018fcbf898 ffff880000000000 
    ffff88018fcbf848: 000000002d001000 ffff88002d001000 
    ffff88018fcbf858: 000000002d000000 ffff88018fcbf878 
    ffff88018fcbf868: 000000001e1b4df9 ffff88018fcbfad8 
    ffff88018fcbf878: ffff88018fcbf898 0000000000000246 
    ffff88018fcbf888: ffff88018fcbf958 crash_kexec+114  
 #1 [ffff88018fcbf890] crash_kexec at ffffffff810f27e2
    ffff88018fcbf898: 0000000000000fb0 [ffff8801089c9038:TCP] 
    ffff88018fcbf8a8: [ffff8801089c8f00:TCP] 0000000000000000 
    ffff88018fcbf8b8: ffff88018fcbfb88 0000000000003890 
    ffff88018fcbf8c8: 8883e3b982e39d83 [ffff880217001400:kmem_cache] 
    ffff88018fcbf8d8: 0000000000000900 00000000000006c0 
    ffff88018fcbf8e8: 0000000000000000 00000000ffffffff 
    ffff88018fcbf8f8: [ffff8801089c9038:TCP] [ffff8801089c9038:TCP] 
    ffff88018fcbf908: [ffff8801089c8f00:TCP] ffffffffffffffff 
    ffff88018fcbf918: skb_entail+82    0000000000000010 
    ffff88018fcbf928: 0000000000010202 ffff88018fcbfb88 
    ffff88018fcbf938: 0000000000000018 000000001e1b4df9 
    ffff88018fcbf948: 0000000000000009 ffff88018fcbfad8 
    ffff88018fcbf958: ffff88018fcbf980 oops_end+280     
 #2 [ffff88018fcbf960] oops_end at ffffffff8163f308
    ffff88018fcbf968: ffff88018fcbfad8 0000000000000246 
    ffff88018fcbf978: 0000000000000009 ffff88018fcbf9d0 
    ffff88018fcbf988: no_context+640   
 #3 [ffff88018fcbf988] no_context at ffffffff8162f431
    ffff88018fcbf990: 0003000100000003 0000000000000246 
    ffff88018fcbf9a0: 000000001e1b4df9 0000000000000002 
    ffff88018fcbf9b0: ffff88018fcbfad8 0000000000000000 
    ffff88018fcbf9c0: [ffff880036a1dc00:task_struct] 0000000000030001 
    ffff88018fcbf9d0: ffff88018fcbfa18 __bad_area_nosemaphore+115 
 #4 [ffff88018fcbf9d8] __bad_area_nosemaphore at ffffffff8162f4c7
    ffff88018fcbf9e0: __alloc_pages_nodemask+407 ffff88021ffd8000 
    ffff88018fcbf9f0: ffff88018fcbfad8 0000000000000002 
    ffff88018fcbfa00: 0000000000000000 ffff88018fcbfad8 
    ffff88018fcbfa10: 0000000000000029 ffff88018fcbfa40 
    ffff88018fcbfa20: bad_area+67      
 #5 [ffff88018fcbfa20] bad_area at ffffffff8162f7eb
    ffff88018fcbfa28: 0000000000000002 0000000000000000 
    ffff88018fcbfa38: [ffff8802108eb840:mm_struct] ffff88018fcbfaa0 
    ffff88018fcbfa48: __do_page_fault+837 
 #6 [ffff88018fcbfa48] __do_page_fault at ffffffff816420f5
    ffff88018fcbfa50: kmem_cache_free+437 0000000000000002 
    ffff88018fcbfa60: [ffff880036a1dc00:task_struct] 0000000036a1dc00 
    ffff88018fcbfa70: [ffff8802108eb8b8:mm_struct] ffff88018fcbfad8 
    ffff88018fcbfa80: 0000000000000000 [ffff8801089c8f00:TCP] 
    ffff88018fcbfa90: [ffff8801089c9038:TCP] 0000000000000fb0 
    ffff88018fcbfaa0: ffff88018fcbfac8 do_page_fault+35 
 #7 [ffff88018fcbfaa8] do_page_fault at ffffffff81642223
    ffff88018fcbfab0: ffff88018fcbfb2f 0000000000000001 
    ffff88018fcbfac0: 0000000000000000 ffff88018fcbfb88 
    ffff88018fcbfad0: page_fault+40    
 #8 [ffff88018fcbfad0] page_fault at ffffffff8163e508
    [exception RIP: skb_entail+82] 🔥
    RIP: ffffffff81573762  RSP: ffff88018fcbfb88  RFLAGS: 00010202
    RAX: 0000000000000000  RBX: 0000000000003890  RCX: 00000000ffffffff
    RDX: ffff8801089c9038  RSI: ffff8801089c9038  RDI: ffff8801089c8f00
    RBP: ffff88018fcbfb88   R8: 00000000000006c0   R9: 0000000000000900
    R10: ffff880217001400  R11: 8883e3b982e39d83  R12: 0000000000000000
    R13: ffff8801089c8f00  R14: ffff8801089c9038  R15: 0000000000000fb0
    ORIG_RAX: ffffffffffffffff  CS: 0010  SS: 0018
    ffff88018fcbfad8: 0000000000000fb0 [ffff8801089c9038:TCP] 
    ffff88018fcbfae8: [ffff8801089c8f00:TCP] 0000000000000000 
    ffff88018fcbfaf8: ffff88018fcbfb88 0000000000003890 
    ffff88018fcbfb08: 8883e3b982e39d83 [ffff880217001400:kmem_cache] 
    ffff88018fcbfb18: 0000000000000900 00000000000006c0 
    ffff88018fcbfb28: 0000000000000000 00000000ffffffff 
    ffff88018fcbfb38: [ffff8801089c9038:TCP] [ffff8801089c9038:TCP] 
    ffff88018fcbfb48: [ffff8801089c8f00:TCP] ffffffffffffffff 
    ffff88018fcbfb58: skb_entail+82    0000000000000010 
    ffff88018fcbfb68: 0000000000010202 ffff88018fcbfb88 
    ffff88018fcbfb78: 0000000000000018 [ffff8801089c8f00:TCP] 
    ffff88018fcbfb88: ffff88018fcbfc50 tcp_sendmsg+1778 
 #9 [ffff88018fcbfb90] tcp_sendmsg at ffffffff81577bf2
    ffff88018fcbfb98: [ffff880036a1e688:task_struct] ffff880000000001 
    ffff88018fcbfba8: 0000000000000050 ffff88018fcbffd8 
    ffff88018fcbfbb8: 0000000000000000 [ffff880036a1dc00:task_struct] 
    ffff88018fcbfbc8: ffff88018fcbffd8 ffff88018fcbfe70 
    ffff88018fcbfbd8: 00000000011b4df9 0000000000000501 
    ffff88018fcbfbe8: [ffff880036a1e601:task_struct] [ffff8801089c9038:TCP] 
    ffff88018fcbfbf8: 0000000001fef010 000005a800000000 
    ffff88018fcbfc08: 0000004000001050 ffff880100003890 
    ffff88018fcbfc18: 0000000000000000 000000001e1b4df9 
    ffff88018fcbfc28: ffff88018fcbfd60 ffff88018fcbfd60 
    ffff88018fcbfc38: 0000000000000002 ffff88018fcbfe60 
    ffff88018fcbfc48: [ffff88013ab76580:sock_inode_cache] ffff88018fcbfc80 
    ffff88018fcbfc58: inet_sendmsg+100 
#10 [ffff88018fcbfc58] inet_sendmsg at ffffffff815a1c04
    ffff88018fcbfc60: 0000000000000040 000000001e1b4df9 
    ffff88018fcbfc70: ffff88018fcbfc80 0000000000002000 
    ffff88018fcbfc80: ffff88018fcbfd50 sock_aio_write+343 
#11 [ffff88018fcbfc88] sock_aio_write at ffffffff815103d7
    ffff88018fcbfc90: 00002000815d3d04 ffff88018fcbfcd8 
    ffff88018fcbfca0: 0000900000000040 [ffff88013ab75180:sock_inode_cache] 
    ffff88018fcbfcb0: 000020008fcbfd70 [ffff88013ab76580:sock_inode_cache] 
    ffff88018fcbfcc0: ffff88018fcbfcc8 0000000000000000 
    ffff88018fcbfcd0: ffff88018fcbfcd8 0000000000000000 
    ffff88018fcbfce0: 0000000000000000 ffff88018fcbfe60 
    ffff88018fcbfcf0: 0000000000000002 0000000000000000 
    ffff88018fcbfd00: 0000000000000000 0000000000000040 
    ffff88018fcbfd10: ffff88018fcbfd60 000000001e1b4df9 
    ffff88018fcbfd20: 0000000000009000 ffff88018fcbff48 
    ffff88018fcbfd30: 0000000000002000 [ffff88007c3d5400:kmalloc-256] 
    ffff88018fcbfd40: 0000000000000002 [ffff88007c3d5400:kmalloc-256] 
    ffff88018fcbfd50: ffff88018fcbfe28 do_sync_readv_writev+121 
#12 [ffff88018fcbfd58] do_sync_readv_writev at ffffffff811de5d9
    ffff88018fcbfd60: 0000000000000001 [ffff88007c3d5400:kmalloc-256] 
    ffff88018fcbfd70: 0000000000000000 0000000000000000 
    ffff88018fcbfd80: 0000000000000000 [ffff880036a1dc00:task_struct] 
    ffff88018fcbfd90: 0000000000000000 0000000000000000 
    ffff88018fcbfda0: ffff88018fcbfca0 0000000000000000 
    ffff88018fcbfdb0: 0000000000002000 0000000000000000 
    ffff88018fcbfdc0: 0000000000002000 0000000000000000 
    ffff88018fcbfdd0: 0000000000000000 0000000000000000 
    ffff88018fcbfde0: 0000000000000000 0000000000000000 
    ffff88018fcbfdf0: 0000000000000000 0000000000000000 
    ffff88018fcbfe00: 0000000000000000 000000001e1b4df9 
    ffff88018fcbfe10: 0000000000002000 0000000000000001 
    ffff88018fcbfe20: ffff88018fcbfe60 ffff88018fcbff20 
    ffff88018fcbfe30: do_readv_writev+206 
#13 [ffff88018fcbfe30] do_readv_writev at ffffffff811dfbae
#13 [ffff88018fcbfe30] do_readv_writev at ffffffff811dfbae
    ffff88018fcbfe38: 0000000000000040 0000000000001000 
    ffff88018fcbfe48: 0000000000002000 ffff88018fcbff48 
    ffff88018fcbfe58: ffff88018fcbfe60 0000000001ff1ff0 
    ffff88018fcbfe68: 0000000000001000 0000000001feefc0 
    ffff88018fcbfe78: 0000000000001000 0000000001fedfb0 
    ffff88018fcbfe88: 0000000000001000 ffff88018fcbfe70 
    ffff88018fcbfe98: 0000000000000001 0000000000000000 
    ffff88018fcbfea8: 0000000000000000 0000000000000000 
    ffff88018fcbfeb8: ffff88018fcbff20 kvm_clock        
    ffff88018fcbfec8: ffff88018fcbfed8 kvm_clock_get_cycles+31 
    ffff88018fcbfed8: ffff88018fcbff00 __getnstimeofday64+58 
    ffff88018fcbfee8: 000000001e1b4df9 0000000000000000 
    ffff88018fcbfef8: [ffff88007c3d5400:kmalloc-256] 0000000000000001 
    ffff88018fcbff08: 00007ffcc8b17100 0000000000000002 
    ffff88018fcbff18: 0000000001f702e0 ffff88018fcbff30 
    ffff88018fcbff28: vfs_writev+53    
#14 [ffff88018fcbff28] vfs_writev at ffffffff811dfdd5
    ffff88018fcbff30: ffff88018fcbff78 sys_writev+127   
#15 [ffff88018fcbff38] sys_writev at ffffffff811dff8f
    ffff88018fcbff40: ffff88018fcbff78 0000000000000000 
    ffff88018fcbff50: 000000001e1b4df9 00007ffcc8b170e0 
    ffff88018fcbff60: 0000000001f702e0 0000000001fc3cd0 
    ffff88018fcbff70: 0000000000002000 0000000001ff6050 
    ffff88018fcbff80: system_call_fastpath+22 
#16 [ffff88018fcbff80] system_call_fastpath at ffffffff81646a09
    RIP: 00007fca70a8aea0  RSP: 00007ffcc8b179f0  RFLAGS: 00000246
    RAX: 0000000000000014  RBX: ffffffff81646a09  RCX: 0000000000000000
    RDX: 0000000000000002  RSI: 00007ffcc8b17100  RDI: 0000000000000009
    RBP: 0000000001ff6050   R8: 0000000000000000   R9: 0000000000002000
    R10: 000000007fffdfff  R11: 0000000000000293  R12: 0000000000002000
    R13: 0000000001fc3cd0  R14: 0000000001f702e0  R15: 00007ffcc8b170e0
    ORIG_RAX: 0000000000000014  CS: 0033  SS: 002b

🔥 [exception RIP: skb_entail+82] を手がかりに skb_entail を disassemble する

crash> dis skb_entail 
0xffffffff81573710 <skb_entail>:        data32 data32 data32 xchg %ax,%ax [FTRACE NOP]
0xffffffff81573715 <skb_entail+5>:      push   %rbp
0xffffffff81573716 <skb_entail+6>:      movl   $0x0,0x74(%rsi)
0xffffffff8157371d <skb_entail+13>:     mov    0x658(%rdi),%eax
0xffffffff81573723 <skb_entail+19>:     mov    0xe0(%rsi),%rdx
0xffffffff8157372a <skb_entail+26>:     orb    $0x10,0x7c(%rsi)
0xffffffff8157372e <skb_entail+30>:     movb   $0x10,0x4c(%rsi)
0xffffffff81573732 <skb_entail+34>:     mov    %rsp,%rbp
0xffffffff81573735 <skb_entail+37>:     movb   $0x0,0x4d(%rsi)
0xffffffff81573739 <skb_entail+41>:     mov    %eax,0x44(%rsi)
0xffffffff8157373c <skb_entail+44>:     mov    %eax,0x40(%rsi)
0xffffffff8157373f <skb_entail+47>:     mov    0xdc(%rsi),%eax
0xffffffff81573745 <skb_entail+53>:     movl   $0x10001,0x24(%rdx,%rax,1)
0xffffffff8157374d <skb_entail+61>:     mov    0x140(%rdi),%rax ?null?
0xffffffff81573754 <skb_entail+68>:     lea    0x138(%rdi),%rdx
0xffffffff8157375b <skb_entail+75>:     mov    %rdx,(%rsi)
0xffffffff8157375e <skb_entail+78>:     mov    %rax,0x8(%rsi)
0xffffffff81573762 <skb_entail+82>:     mov    %rsi,(%rax) 🔥
0xffffffff81573765 <skb_entail+85>:     addl   $0x1,0x148(%rdi)
0xffffffff8157376c <skb_entail+92>:     cmpq   $0x0,0x268(%rdi)
0xffffffff81573774 <skb_entail+100>:    mov    %rsi,0x140(%rdi)
0xffffffff8157377b <skb_entail+107>:    je     0xffffffff815737c0 <skb_entail+176>

🔥 で NULL pointer dereference により exception を起こしている

ここまでの状況を整理

  • Nginx が TCPソケットに writev(2) したプロセスコンテキストである
  • exception を起こした RIP は 0xffffffff81573762 skb_entail+82 mov %rsi,(%rax) が例外を起こした命令
  • %rax0000000000000000 なので、(%rax) で NULL pointer dereference となり例外を起こしている

その他の情報として、このインスタンスの運用で把握していることは

  • kernel panic を起こした KVMインスタンスは、 Nginx + Unicorn が動作している典型的な Rails 構成の role である
  • この role は、水平にスケールする構成をとっており、同様に動く KVM インスタンスが他に数十ほどいる
  • 全て合計すると Nginx プロセス数百ほどいる

という環境で発生した kernel panic なので、かなり稀にしか発生しないバグ、という推測をたてている

disassemble して解析

objdump でソースのアノテーション付きで disassemble する

 objdump -D -S /usr/lib/debug/usr/lib/modules/3.10.0-327.36.1.el7.x86_64/vmlinux > disassemble.txt

RIP 0xffffffff81573762 の付近のソースは下記の通り

static inline void __tcp_add_write_queue_tail(struct sock *sk, struct sk_buff *skb)
{
ffffffff81573754:       48 8d 97 38 01 00 00    lea    0x138(%rdi),%rdx
        __skb_queue_tail(&sk->sk_write_queue, skb);

static inline void __skb_insert(struct sk_buff *newsk,
                                struct sk_buff *prev, struct sk_buff *next,
                                struct sk_buff_head *list)
{
ffffffff8157375b:       48 89 16                mov    %rdx,(%rsi)
        newsk->next = next;
ffffffff8157375e:       48 89 46 08             mov    %rax,0x8(%rsi)
        newsk->prev = prev;
ffffffff81573762:       48 89 30                mov    %rsi,(%rax) 🔥
        next->prev  = prev->next = newsk;
ffffffff81573765:       83 87 48 01 00 00 01    addl   $0x1,0x148(%rdi)
        list->qlen++;

🔥 exception を起こした時点でのレジスタを確認する

  • %rsi struct sk_buff *next 0xffff8801089c9038
  • 0x08(%rsi) struct sk_buff *next 0xffff8801089c9038
  • %rdx struct sk_buff *next 0xffff8801089c9038
  • %rax struct sk_buff *prev NULL

prev が NULL であることで例外をおこしている。newsk, next が同一アドレスなのはおかしい気がする。

crash で構造体を見る

crash> p *(struct sk_buff *) 0xffff8801089c9038
$12 = {
  next = 0xffff8801089c9038, 
  prev = 0x0
  {
    tstamp = {
      tv64 = 0
    }, 
    skb_mstamp = {
      {
        v64 = 0, 
        {
          stamp_us = 0, 
          stamp_jiffies = 0
        }
      }
    }
  }, 
  sk = 0x0, 
  dev = 0x0, 

... 略
crash> p ((struct sock *) 0xffff8801089c8f00)->sk_write_queue
$19 = {
  next = 0xffff8801089c9038,  /* ❓ */
  prev = 0x0, 
  qlen = 0, 
  lock = {
    {
      rlock = {
        raw_lock = {
          {
            head_tail = 0, 
            tickets = {
              head = 0, 
              tail = 0
            }
          }
        }
      }
    }
  }
}

struct sk_buff は struct sk_buff_head と合わせて下記のような circular doubly linked list の構造を取る。

f:id:hiboma:20161029164403j:plain

sk->sk_write_queue は 図の struct sk_buff_head に相当する

systemtap で確認

別の検証として systemtapsk_stream_alloc_skbskb_entail を呼び出した際の変数のアドレスを見てみたが、 $skb と $sk->sk_write_queue のアドレスは別になっている

[11185] sshd
sk_stream_alloc_skb
$skb:                      0xffff880038bf7600
$skb->prev:                0x0
$skb->next:                0x0
skb_entail
$skb:                      0xffff880038bf7600
$skb->prev:                0x0
$skb->next:                0x0
$sk->sk_write_queue:       0xffff8800360f2e38
$sk->sk_write_queue->prev: 0xffff8800360f2e38
$sk->sk_write_queue->next: 0xffff8800360f2e38

本来はこのように別のアドレスを指すべきなのだと思われる

検証に使った systemtap
$ cat test.stap
probe kernel.function("sk_stream_alloc_skb").return
{
  printf ("---------------------------------------------------------\n")
  printf ("[%d] %s\n", pid(), execname())
  printf ("sk_stream_alloc_skb\n") 
  printf ("$skb:                      %p\n", $return)
  printf ("$skb->prev:                %p\n", $return->prev)
  printf ("$skb->next:                %p\n", $return->next) 
}

probe kernel.function("skb_entail").call
{
  printf ("skb_entail\n")
  printf ("$skb:                      %p\n", $skb)
  printf ("$skb->prev:                %p\n", $skb->prev)
  printf ("$skb->next:                %p\n", $skb->next); 
  printf ("$sk->sk_write_queue:       %p\n", &$sk->sk_write_queue)
  printf ("$sk->sk_write_queue->prev: %p\n", $sk->sk_write_queue->prev)
  printf ("$sk->sk_write_queue->next: %p\n", $sk->sk_write_queue->next)
}

更にソースを追う

struct sk_buffer * skb がどこからやってくるかをソースを遡ってみる

static inline void __skb_insert(struct sk_buff *newsk,
                struct sk_buff *prev 💀, struct sk_buff *next,
                struct sk_buff_head *list)
{
        // newsk 0xffff8801089c9038
        // prev  NULL
        // next  0xffff8801089c9038
        // list  0xffff8801089c9038

    newsk->next = next;
    newsk->prev = prev; 💀               /* prev is NULL */
    next->prev  = prev->next = newsk; 🔥 /* oops NULL pointer derefernce */
    list->qlen++;
}
static inline void __skb_queue_before(struct sk_buff_head *list,
                      struct sk_buff *next 🍣,
                      struct sk_buff *newsk)
{
        // newsk 0xffff8801089c9038
        // next->prev NULL
        // next 0xffff8801089c9038
        // list 0xffff8801089c9038 ???
    __skb_insert(newsk, next->prev 💀, next, list);
}
static inline void __skb_queue_tail(struct sk_buff_head *list,
                   struct sk_buff *newsk)
{
        // list  0xffff8801089c9038
        //   * list->prev NULL
        // newsk 0xffff8801089c9038
    __skb_queue_before(list, (struct sk_buff *)list 🍣, newsk);
}
static inline void __tcp_add_write_queue_tail(struct sock *sk, struct sk_buff *skb)
{
    // sk  0xffff8801089c8f00 
    //     * sk->sk_write_queue->next 0xffff8801089c9038
    //     * sk->sk_write_queue->prev NULL 💀
    // skb 0xffff8801089c9038
        __skb_queue_tail(&sk->sk_write_queue 🍣, skb );
}
static inline void tcp_add_write_queue_tail(struct sock *sk, struct sk_buff *skb)
{
    // sk  0xffff8801089c8f00
    // skb 0xffff8801089c9038
    __tcp_add_write_queue_tail(sk 🍣, skb );

    /* Queue it, remembering where we must start sending. */
    if (sk->sk_send_head == NULL) {
        sk->sk_send_head = skb;

        if (tcp_sk(sk)->highest_sack == NULL)
            tcp_sk(sk)->highest_sack = skb;
    }
}
static void skb_entail(struct sock *sk, struct sk_buff *skb)
{
    struct tcp_sock *tp = tcp_sk(sk);
    struct tcp_skb_cb *tcb = TCP_SKB_CB(skb);

    skb->csum    = 0;
    tcb->seq     = tcb->end_seq = tp->write_seq;
    tcb->tcp_flags = TCPHDR_ACK;
    tcb->sacked  = 0;
    __skb_header_release(skb);
    
    // sk  0xffff8801089c8f00
    // skb 0xffff8801089c9038
    tcp_add_write_queue_tail(sk 🍣, skb ); 
    sk->sk_wmem_queued += skb->truesize;
    sk_mem_charge(sk, skb->truesize);
    if (tp->nonagle & TCP_NAGLE_PUSH)
        tp->nonagle &= ~TCP_NAGLE_PUSH;
}
int tcp_sendmsg(struct kiocb *iocb, struct sock *sk, struct msghdr *msg,
        size_t size)
{
    struct iovec *iov;
    struct tcp_sock *tp = tcp_sk(sk);
    struct sk_buff *skb;
    int iovlen, flags, err, copied = 0;
    int mss_now = 0, size_goal, copied_syn = 0, offset = 0;
    bool sg;
    long timeo;

//...

new_segment:
                /* Allocate new segment. If the interface is SG,
                * allocate skb fitting to single page.
                */
                if (!sk_stream_memory_free(sk))
                    goto wait_for_sndbuf;

                skb = sk_stream_alloc_skb(sk,
                              select_size(sk, sg),
                              sk->sk_allocation);
                if (!skb)
                    goto wait_for_memory;

                /*
                * Check whether we can use HW checksum.
                */
                if (sk->sk_route_caps & NETIF_F_ALL_CSUM)
                    skb->ip_summed = CHECKSUM_PARTIAL;

                                // sk  0xffff8801089c8f00 %rdi
                                // skb 0xffff8801089c9038 %rsi 
                skb_entail(sk, skb); 🔥

sk_stream_alloc_skb で割り当てた skb は __alloc_skb の memset で 0 クリアされている

struct sk_buff *__alloc_skb(unsigned int size, gfp_t gfp_mask,
                int flags, int node)
{
    struct kmem_cache *cache;
    struct skb_shared_info *shinfo;
    struct sk_buff *skb;
    u8 *data;
    bool pfmemalloc;

... 略

    /*
    * Only clear those fields we need to clear, not those that we will
    * actually initialise below. Hence, don't put any more fields after
    * the tail pointer in struct sk_buff!
    */
    memset(skb, 0, offsetof(struct sk_buff, tail));

よって skb->prev と skb->next は 0 = NULL