general protection fault: 0000 [#1] PREEMPT SMP
Modules linked in: vmw_vsock_vmci_transport vmw_vmci vsock bnep fuse rfcomm hidp l2tp_ppp l2tp_core 8021q garp mrp dlci pppoe pppox ppp_generic slhc scsi_transport_iscsi rose caif_socket caif can_raw bridge af_key can_bcm llc2 stp can netrom phonet af_rxrpc nfnetlink ipt_ULOG x25 rds irda crc_ccitt ax25 ipx p8023 p8022 decnet atm appletalk psnap llc nfc lockd sunrpc ip6t_REJECT nf_conntrack_ipv6 nf_defrag_ipv6 xt_conntrack nf_conntrack ip6table_filter ip6_tables snd_hda_codec_realtek snd_hda_intel snd_hda_codec snd_pcm btusb snd_page_alloc bluetooth snd_timer snd microcode rfkill usb_debug serio_raw pcspkr edac_core soundcore vhost_net tun r8169 macvtap macvlan mii kvm_amd kvm
CPU 0
Pid: 23476, comm: trinity-child1 Not tainted 3.9.0-rc1+ #69 Gigabyte Technology Co., Ltd. GA-MA78GM-S2H/GA-MA78GM-S2H
RIP: 0010:[<ffffffff812356b7>] [<ffffffff812356b7>] sysfs_find_dirent+0x47/0xf0
RSP: 0018:ffff88000585bd68 EFLAGS: 00010202
RAX: 0000000094be55f6 RBX: 6b6b6b6b6b6b6b6b RCX: 000000006b6b6b6b
RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000000
RBP: ffff88000585bd88 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000000 R12: 000000000029c161
R13: ffff8800a8918288 R14: 0000000000000000 R15: 0000000000000009
FS: 00007fa12651e740(0000) GS:ffff88012ae00000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 0000000000000010 CR3: 000000001a128000 CR4: 00000000000007f0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Process trinity-child1 (pid: 23476, threadinfo ffff88000585a000, task ffff8800cd454920)
Stack:
ffff880128edc1e8 ffff8800a8918250 fffffffffffffffe ffff88012265f430
ffff88000585bdb8 ffffffff812357cd ffff8800a8918250 ffff8801226514d0
ffff88000585bf38 0000000000000000 ffff88000585bde8 ffffffff811bb30d
Call Trace:
[<ffffffff812357cd>] sysfs_lookup+0x6d/0xe0
[<ffffffff811bb30d>] lookup_real+0x1d/0x60
[<ffffffff811bb528>] __lookup_hash+0x38/0x50
[<ffffffff811bb559>] lookup_hash+0x19/0x20
[<ffffffff811be993>] kern_path_create+0x93/0x170
[<ffffffff811bce46>] ? getname_flags.part.32+0x86/0x150
[<ffffffff811beaba>] user_path_create+0x4a/0x70
[<ffffffff811c1a09>] sys_mkdirat+0x39/0xe0
[<ffffffff816cd942>] system_call_fastpath+0x16/0x1b
Code: 00 48 8b 9f 88 00 00 00 f6 c4 0f 0f 95 c0 48 85 f6 0f 95 c2 38 d0 75 79 4c 89 ee 4c 89 f7 e8 91 ef ff ff 41 89 c4 48 85 db 74 1d <8b> 4b 28 41 39 cc 74 21 44 89 e0 29 c8 83 f8 00 7c 2c 74 45 48
RIP [<ffffffff812356b7>] sysfs_find_dirent+0x47/0xf0
RSP <ffff88000585bd68>
---[ end trace 4ba97703eaafbb8b ]---
And even more sysfs fallout (From a clean boot)..
=============================================================================
BUG sysfs_dir_cache (Not tainted): Poison overwritten
-----------------------------------------------------------------------------
Disabling lock debugging due to kernel taint
INFO: 0xffff8801239a85b8-0xffff8801239a85b8. First byte 0x69 instead of 0x6b
INFO: Allocated in sysfs_new_dirent+0x59/0x130 age=493166 cpu=3 pid=301
__slab_alloc+0x4ed/0x584
kmem_cache_alloc+0x2c0/0x330
sysfs_new_dirent+0x59/0x130
sysfs_add_file_mode+0x6b/0x110
sysfs_add_file+0x12/0x20
sysfs_create_file+0x26/0x30
load_module+0x1360/0x28d0
sys_init_module+0xd7/0x120
system_call_fastpath+0x16/0x1b
INFO: Freed in release_sysfs_dirent+0x81/0x100 age=10736 cpu=3 pid=8692
__slab_free+0x3c/0x3de
kmem_cache_free+0x362/0x380
release_sysfs_dirent+0x81/0x100
sysfs_dir_pos+0x46/0xf0
sysfs_readdir+0x9a/0x2b0
vfs_readdir+0xb8/0xf0
sys_getdents64+0x8f/0x110
system_call_fastpath+0x16/0x1b
INFO: Slab 0xffffea00048e6a00 objects=16 used=16 fp=0x (null) flags=0x5000000000004080
INFO: Object 0xffff8801239a85b8 @offset=1464 fp=0x (null)
Bytes b4 ffff8801239a85a8: 00 00 00 00 00 00 00 00 5a 5a 5a 5a 5a 5a 5a 5a ........ZZZZZZZZ
Object ffff8801239a85b8: 69 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b ikkkkkkkkkkkkkkk
Object ffff8801239a85c8: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
Object ffff8801239a85d8: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
Object ffff8801239a85e8: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
Object ffff8801239a85f8: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
Object ffff8801239a8608: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
Object ffff8801239a8618: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
Object ffff8801239a8628: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
Object ffff8801239a8638: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
Object ffff8801239a8648: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b a5 kkkkkkkkkkkkkkk.
Redzone ffff8801239a8658: bb bb bb bb bb bb bb bb ........
Padding ffff8801239a8798: 5a 5a 5a 5a 5a 5a 5a 5a ZZZZZZZZ
Pid: 15728, comm: modprobe Tainted: G B 3.9.0-rc1+ #69
Call Trace:
[<ffffffff8118e81d>] ? print_section+0x3d/0x40
[<ffffffff8118f98e>] print_trailer+0xfe/0x160
[<ffffffff8118fb2f>] check_bytes_and_report+0xef/0x130
[<ffffffff81190126>] check_object+0x1c6/0x240
[<ffffffff81190989>] ? check_slab+0x89/0x130
[<ffffffff81235159>] ? sysfs_new_dirent+0x59/0x130
[<ffffffff816bb755>] alloc_debug_processing+0x67/0x109
[<ffffffff816bc2ee>] __slab_alloc+0x4ed/0x584
[<ffffffff81235159>] ? sysfs_new_dirent+0x59/0x130
[<ffffffff811926f0>] kmem_cache_alloc+0x2c0/0x330
[<ffffffff81235159>] ? sysfs_new_dirent+0x59/0x130
[<ffffffff81235159>] sysfs_new_dirent+0x59/0x130
[<ffffffff812343eb>] sysfs_add_file_mode+0x6b/0x110
[<ffffffff81237620>] internal_create_group+0xd0/0x210
[<ffffffff81237793>] sysfs_create_group+0x13/0x20
[<ffffffff810c71f1>] load_module+0x22d1/0x28d0
[<ffffffff81355570>] ? ddebug_proc_open+0xc0/0xc0
[<ffffffff810b24ae>] ? put_lock_stats.isra.23+0xe/0x40
[<ffffffff810c78c7>] sys_init_module+0xd7/0x120
[<ffffffff816cd942>] system_call_fastpath+0x16/0x1b
FIX sysfs_dir_cache: Restoring 0xffff8801239a85b8-0xffff8801239a85b8=0x6b
On Thu, Mar 07, 2013 at 12:28:54AM -0500, Dave Jones wrote:
> general protection fault: 0000 [#1] PREEMPT SMP
> Modules linked in: vmw_vsock_vmci_transport vmw_vmci vsock bnep fuse rfcomm hidp l2tp_ppp l2tp_core 8021q garp mrp dlci pppoe pppox ppp_generic slhc scsi_transport_iscsi rose caif_socket caif can_raw bridge af_key can_bcm llc2 stp can netrom phonet af_rxrpc nfnetlink ipt_ULOG x25 rds irda crc_ccitt ax25 ipx p8023 p8022 decnet atm appletalk psnap llc nfc lockd sunrpc ip6t_REJECT nf_conntrack_ipv6 nf_defrag_ipv6 xt_conntrack nf_conntrack ip6table_filter ip6_tables snd_hda_codec_realtek snd_hda_intel snd_hda_codec snd_pcm btusb snd_page_alloc bluetooth snd_timer snd microcode rfkill usb_debug serio_raw pcspkr edac_core soundcore vhost_net tun r8169 macvtap macvlan mii kvm_amd kvm
> CPU 0
> Pid: 23476, comm: trinity-child1 Not tainted 3.9.0-rc1+ #69 Gigabyte Technology Co., Ltd. GA-MA78GM-S2H/GA-MA78GM-S2H
> RIP: 0010:[<ffffffff812356b7>] [<ffffffff812356b7>] sysfs_find_dirent+0x47/0xf0
> RSP: 0018:ffff88000585bd68 EFLAGS: 00010202
> RAX: 0000000094be55f6 RBX: 6b6b6b6b6b6b6b6b RCX: 000000006b6b6b6b
> RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000000
> RBP: ffff88000585bd88 R08: 0000000000000000 R09: 0000000000000000
> R10: 0000000000000000 R11: 0000000000000000 R12: 000000000029c161
> R13: ffff8800a8918288 R14: 0000000000000000 R15: 0000000000000009
> FS: 00007fa12651e740(0000) GS:ffff88012ae00000(0000) knlGS:0000000000000000
> CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> CR2: 0000000000000010 CR3: 000000001a128000 CR4: 00000000000007f0
> DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
> Process trinity-child1 (pid: 23476, threadinfo ffff88000585a000, task ffff8800cd454920)
> Stack:
> ffff880128edc1e8 ffff8800a8918250 fffffffffffffffe ffff88012265f430
> ffff88000585bdb8 ffffffff812357cd ffff8800a8918250 ffff8801226514d0
> ffff88000585bf38 0000000000000000 ffff88000585bde8 ffffffff811bb30d
> Call Trace:
> [<ffffffff812357cd>] sysfs_lookup+0x6d/0xe0
> [<ffffffff811bb30d>] lookup_real+0x1d/0x60
> [<ffffffff811bb528>] __lookup_hash+0x38/0x50
> [<ffffffff811bb559>] lookup_hash+0x19/0x20
> [<ffffffff811be993>] kern_path_create+0x93/0x170
> [<ffffffff811bce46>] ? getname_flags.part.32+0x86/0x150
> [<ffffffff811beaba>] user_path_create+0x4a/0x70
> [<ffffffff811c1a09>] sys_mkdirat+0x39/0xe0
> [<ffffffff816cd942>] system_call_fastpath+0x16/0x1b
> Code: 00 48 8b 9f 88 00 00 00 f6 c4 0f 0f 95 c0 48 85 f6 0f 95 c2 38 d0 75 79 4c 89 ee 4c 89 f7 e8 91 ef ff ff 41 89 c4 48 85 db 74 1d <8b> 4b 28 41 39 cc 74 21 44 89 e0 29 c8 83 f8 00 7c 2c 74 45 48
> RIP [<ffffffff812356b7>] sysfs_find_dirent+0x47/0xf0
> RSP <ffff88000585bd68>
> ---[ end trace 4ba97703eaafbb8b ]---
Any hint as to what was happening here when this crashed?
thanks,
greg k-h
On Thu, Mar 07, 2013 at 12:33:53AM -0500, Dave Jones wrote:
> And even more sysfs fallout (From a clean boot)..
>
> =============================================================================
> BUG sysfs_dir_cache (Not tainted): Poison overwritten
> -----------------------------------------------------------------------------
>
> Disabling lock debugging due to kernel taint
> INFO: 0xffff8801239a85b8-0xffff8801239a85b8. First byte 0x69 instead of 0x6b
> INFO: Allocated in sysfs_new_dirent+0x59/0x130 age=493166 cpu=3 pid=301
> __slab_alloc+0x4ed/0x584
> kmem_cache_alloc+0x2c0/0x330
> sysfs_new_dirent+0x59/0x130
> sysfs_add_file_mode+0x6b/0x110
> sysfs_add_file+0x12/0x20
> sysfs_create_file+0x26/0x30
> load_module+0x1360/0x28d0
> sys_init_module+0xd7/0x120
> system_call_fastpath+0x16/0x1b
> INFO: Freed in release_sysfs_dirent+0x81/0x100 age=10736 cpu=3 pid=8692
> __slab_free+0x3c/0x3de
> kmem_cache_free+0x362/0x380
> release_sysfs_dirent+0x81/0x100
> sysfs_dir_pos+0x46/0xf0
> sysfs_readdir+0x9a/0x2b0
> vfs_readdir+0xb8/0xf0
> sys_getdents64+0x8f/0x110
> system_call_fastpath+0x16/0x1b
> INFO: Slab 0xffffea00048e6a00 objects=16 used=16 fp=0x (null) flags=0x5000000000004080
> INFO: Object 0xffff8801239a85b8 @offset=1464 fp=0x (null)
>
> Bytes b4 ffff8801239a85a8: 00 00 00 00 00 00 00 00 5a 5a 5a 5a 5a 5a 5a 5a ........ZZZZZZZZ
> Object ffff8801239a85b8: 69 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b ikkkkkkkkkkkkkkk
> Object ffff8801239a85c8: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
> Object ffff8801239a85d8: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
> Object ffff8801239a85e8: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
> Object ffff8801239a85f8: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
> Object ffff8801239a8608: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
> Object ffff8801239a8618: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
> Object ffff8801239a8628: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
> Object ffff8801239a8638: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b kkkkkkkkkkkkkkkk
> Object ffff8801239a8648: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b a5 kkkkkkkkkkkkkkk.
> Redzone ffff8801239a8658: bb bb bb bb bb bb bb bb ........
> Padding ffff8801239a8798: 5a 5a 5a 5a 5a 5a 5a 5a ZZZZZZZZ
> Pid: 15728, comm: modprobe Tainted: G B 3.9.0-rc1+ #69
> Call Trace:
> [<ffffffff8118e81d>] ? print_section+0x3d/0x40
> [<ffffffff8118f98e>] print_trailer+0xfe/0x160
> [<ffffffff8118fb2f>] check_bytes_and_report+0xef/0x130
> [<ffffffff81190126>] check_object+0x1c6/0x240
> [<ffffffff81190989>] ? check_slab+0x89/0x130
> [<ffffffff81235159>] ? sysfs_new_dirent+0x59/0x130
> [<ffffffff816bb755>] alloc_debug_processing+0x67/0x109
> [<ffffffff816bc2ee>] __slab_alloc+0x4ed/0x584
> [<ffffffff81235159>] ? sysfs_new_dirent+0x59/0x130
> [<ffffffff811926f0>] kmem_cache_alloc+0x2c0/0x330
> [<ffffffff81235159>] ? sysfs_new_dirent+0x59/0x130
> [<ffffffff81235159>] sysfs_new_dirent+0x59/0x130
> [<ffffffff812343eb>] sysfs_add_file_mode+0x6b/0x110
> [<ffffffff81237620>] internal_create_group+0xd0/0x210
> [<ffffffff81237793>] sysfs_create_group+0x13/0x20
> [<ffffffff810c71f1>] load_module+0x22d1/0x28d0
> [<ffffffff81355570>] ? ddebug_proc_open+0xc0/0xc0
> [<ffffffff810b24ae>] ? put_lock_stats.isra.23+0xe/0x40
> [<ffffffff810c78c7>] sys_init_module+0xd7/0x120
> [<ffffffff816cd942>] system_call_fastpath+0x16/0x1b
> FIX sysfs_dir_cache: Restoring 0xffff8801239a85b8-0xffff8801239a85b8=0x6b
>
Hm, a module was being loaded. Odd, I haven't seen this before, I'm
guessing that 3.8 doesn't show this, right?
greg k-h
On Thu, Mar 07, 2013 at 02:02:30PM +0800, Greg Kroah-Hartman wrote:
> On Thu, Mar 07, 2013 at 12:28:54AM -0500, Dave Jones wrote:
> > general protection fault: 0000 [#1] PREEMPT SMP
> > Modules linked in: vmw_vsock_vmci_transport vmw_vmci vsock bnep fuse rfcomm hidp l2tp_ppp l2tp_core 8021q garp mrp dlci pppoe pppox ppp_generic slhc scsi_transport_iscsi rose caif_socket caif can_raw bridge af_key can_bcm llc2 stp can netrom phonet af_rxrpc nfnetlink ipt_ULOG x25 rds irda crc_ccitt ax25 ipx p8023 p8022 decnet atm appletalk psnap llc nfc lockd sunrpc ip6t_REJECT nf_conntrack_ipv6 nf_defrag_ipv6 xt_conntrack nf_conntrack ip6table_filter ip6_tables snd_hda_codec_realtek snd_hda_intel snd_hda_codec snd_pcm btusb snd_page_alloc bluetooth snd_timer snd microcode rfkill usb_debug serio_raw pcspkr edac_core soundcore vhost_net tun r8169 macvtap macvlan mii kvm_amd kvm
> > CPU 0
> > Pid: 23476, comm: trinity-child1 Not tainted 3.9.0-rc1+ #69 Gigabyte Technology Co., Ltd. GA-MA78GM-S2H/GA-MA78GM-S2H
> > RIP: 0010:[<ffffffff812356b7>] [<ffffffff812356b7>] sysfs_find_dirent+0x47/0xf0
> > RSP: 0018:ffff88000585bd68 EFLAGS: 00010202
> > RAX: 0000000094be55f6 RBX: 6b6b6b6b6b6b6b6b RCX: 000000006b6b6b6b
> > RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000000
> > RBP: ffff88000585bd88 R08: 0000000000000000 R09: 0000000000000000
> > R10: 0000000000000000 R11: 0000000000000000 R12: 000000000029c161
> > R13: ffff8800a8918288 R14: 0000000000000000 R15: 0000000000000009
> > FS: 00007fa12651e740(0000) GS:ffff88012ae00000(0000) knlGS:0000000000000000
> > CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> > CR2: 0000000000000010 CR3: 000000001a128000 CR4: 00000000000007f0
> > DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> > DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
> > Process trinity-child1 (pid: 23476, threadinfo ffff88000585a000, task ffff8800cd454920)
> > Stack:
> > ffff880128edc1e8 ffff8800a8918250 fffffffffffffffe ffff88012265f430
> > ffff88000585bdb8 ffffffff812357cd ffff8800a8918250 ffff8801226514d0
> > ffff88000585bf38 0000000000000000 ffff88000585bde8 ffffffff811bb30d
> > Call Trace:
> > [<ffffffff812357cd>] sysfs_lookup+0x6d/0xe0
> > [<ffffffff811bb30d>] lookup_real+0x1d/0x60
> > [<ffffffff811bb528>] __lookup_hash+0x38/0x50
> > [<ffffffff811bb559>] lookup_hash+0x19/0x20
> > [<ffffffff811be993>] kern_path_create+0x93/0x170
> > [<ffffffff811bce46>] ? getname_flags.part.32+0x86/0x150
> > [<ffffffff811beaba>] user_path_create+0x4a/0x70
> > [<ffffffff811c1a09>] sys_mkdirat+0x39/0xe0
> > [<ffffffff816cd942>] system_call_fastpath+0x16/0x1b
> > Code: 00 48 8b 9f 88 00 00 00 f6 c4 0f 0f 95 c0 48 85 f6 0f 95 c2 38 d0 75 79 4c 89 ee 4c 89 f7 e8 91 ef ff ff 41 89 c4 48 85 db 74 1d <8b> 4b 28 41 39 cc 74 21 44 89 e0 29 c8 83 f8 00 7c 2c 74 45 48
> > RIP [<ffffffff812356b7>] sysfs_find_dirent+0x47/0xf0
> > RSP <ffff88000585bd68>
> > ---[ end trace 4ba97703eaafbb8b ]---
>
> Any hint as to what was happening here when this crashed?
Given I haven't seen this (or the other sysfs bug) before today, I'm going
to assume it's due to one of the features I added to trinity today.
1. Instead of just relying on filenames it gathers from sysfs on startup,
it now also generates mangled variants of them.
(Appending a / followed by garbage for eg)
2. When a syscall wants a page of memory, it now sometimes hands it one
filled with malformed UTF-8 characters.
3. A combo of the above, that garbage appended to a pathname may be unicode junk.
Could be some of those that caused these bugs.
I just retried rerunning the test a few times. Every time I run for a while
I end up with different crashes. It's raining bugs over here.
(Here's another sysfs one below)
Running 'trinity -c mkdirat -V /sys' doesn't seem to trigger it, so it's an
interaction with something else maybe.
The one common thing here is that 6b6b6b6b6b6b6b6b showing up in every trace,
suggesting a use-after-free bugs. They may all be different manifestations
of the same underlying bug if there's some kind of refcounting bug perhaps.
(This may also be why telling it to do just mkdirat isn't triggering it,
if it's racing with some other operation)
Getting this stuff easily reproducable is pretty hard. The best I can offer
right now is that it seems to trigger *something* bad quickly, even if it's
not necessarily the exact same trace.
Dave
general protection fault: 0000 [#1] PREEMPT SMP
Modules linked in: vmw_vsock_vmci_transport vmw_vmci vsock fuse bnep hidp dlci 8021q garp mrp bridge stp l2tp_ppp l2tp_core scsi_transport_iscsi rfcomm ipt_ULOG nfnetlink nfc rose af_key appletalk can_raw can_bcm netrom x25 ipx caif_socket af_rxrpc rds p8023 psnap p8022 ax25 irda pppoe decnet can pppox llc2 caif crc_ccitt ppp_generic slhc atm phonet llc lockd sunrpc ip6t_REJECT nf_conntrack_ipv6 nf_defrag_ipv6 xt_conntrack nf_conntrack ip6table_filter ip6_tables snd_hda_codec_realtek snd_hda_intel snd_hda_codec snd_pcm btusb bluetooth snd_page_alloc snd_timer microcode snd serio_raw pcspkr usb_debug rfkill edac_core soundcore r8169 mii vhost_net tun macvtap macvlan kvm_amd kvm
CPU 2
Pid: 30261, comm: trinity-main Not tainted 3.9.0-rc1+ #69 Gigabyte Technology Co., Ltd. GA-MA78GM-S2H/GA-MA78GM-S2H
RIP: 0010:[<ffffffff8133a44b>] [<ffffffff8133a44b>] rb_next+0x1b/0x50
RSP: 0018:ffff880104dc7e58 EFLAGS: 00010202
RAX: 6b6b6b6b6b6b6b6b RBX: 0000000000000000 RCX: ffff880124018000
RDX: 6b6b6b6b6b6b6b6b RSI: ffff880124011c98 RDI: ffff880124018048
RBP: ffff880104dc7e58 R08: 2222222222222222 R09: 2222222222222222
R10: 0000000000000000 R11: 0000000000000000 R12: ffff8800b0599600
R13: 0000000000000000 R14: 0000000000000018 R15: ffff880124018000
FS: 00007f6f46f21740(0000) GS:ffff88012b200000(0000) knlGS:0000000000000000
CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 0000003e29ebb750 CR3: 0000000112440000 CR4: 00000000000007e0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Process trinity-main (pid: 30261, threadinfo ffff880104dc6000, task ffff88011b362490)
Stack:
ffff880104dc7ed8 ffffffff81234fb9 ffffffff00000008 0000000000003222
ffff880104dc0001 ffff88010777fa68 2222222222222222 ffffffff811c4640
ffff880104dc7f40 ffff880124011c98 ffff880104dc7ed8 ffff8800b0599600
Call Trace:
[<ffffffff81234fb9>] sysfs_readdir+0x169/0x2b0
[<ffffffff811c4640>] ? sys_ioctl+0xb0/0xb0
[<ffffffff811c4640>] ? sys_ioctl+0xb0/0xb0
[<ffffffff811c49f8>] vfs_readdir+0xb8/0xf0
[<ffffffff811d026c>] ? fget_light+0x3cc/0x500
[<ffffffff811c4b4f>] sys_getdents+0x8f/0x120
[<ffffffff816cd942>] system_call_fastpath+0x16/0x1b
Code: 48 89 32 eb b2 0f 1f 00 48 89 70 10 eb a9 66 90 55 48 8b 17 48 89 e5 48 39 d7 74 33 48 8b 47 08 48 85 c0 75 06 eb 17 90 48 89 d0 <48> 8b 50 10 48 85 d2 75 f4 5d c3 66 90 48 8b 10 48 89 c7 48 89
RIP [<ffffffff8133a44b>] rb_next+0x1b/0x50
RSP <ffff880104dc7e58>
---[ end trace 761f3bbe53bd909e ]---
On Thu, Mar 7, 2013 at 2:26 PM, Dave Jones <[email protected]> wrote:
> Could be some of those that caused these bugs.
>
> I just retried rerunning the test a few times. Every time I run for a while
> I end up with different crashes. It's raining bugs over here.
> (Here's another sysfs one below)
>
> Running 'trinity -c mkdirat -V /sys' doesn't seem to trigger it, so it's an
> interaction with something else maybe.
Maybe it is helpful for trinity to output some previous recorded operations
on /sysfs when the crash is triggered.
Thanks,
--
Ming Lei
On 03/07/2013 01:26 AM, Dave Jones wrote:
> On Thu, Mar 07, 2013 at 02:02:30PM +0800, Greg Kroah-Hartman wrote:
> > On Thu, Mar 07, 2013 at 12:28:54AM -0500, Dave Jones wrote:
> > > general protection fault: 0000 [#1] PREEMPT SMP
> > > Modules linked in: vmw_vsock_vmci_transport vmw_vmci vsock bnep fuse rfcomm hidp l2tp_ppp l2tp_core 8021q garp mrp dlci pppoe pppox ppp_generic slhc scsi_transport_iscsi rose caif_socket caif can_raw bridge af_key can_bcm llc2 stp can netrom phonet af_rxrpc nfnetlink ipt_ULOG x25 rds irda crc_ccitt ax25 ipx p8023 p8022 decnet atm appletalk psnap llc nfc lockd sunrpc ip6t_REJECT nf_conntrack_ipv6 nf_defrag_ipv6 xt_conntrack nf_conntrack ip6table_filter ip6_tables snd_hda_codec_realtek snd_hda_intel snd_hda_codec snd_pcm btusb snd_page_alloc bluetooth snd_timer snd microcode rfkill usb_debug serio_raw pcspkr edac_core soundcore vhost_net tun r8169 macvtap macvlan mii kvm_amd kvm
> > > CPU 0
> > > Pid: 23476, comm: trinity-child1 Not tainted 3.9.0-rc1+ #69 Gigabyte Technology Co., Ltd. GA-MA78GM-S2H/GA-MA78GM-S2H
> > > RIP: 0010:[<ffffffff812356b7>] [<ffffffff812356b7>] sysfs_find_dirent+0x47/0xf0
> > > RSP: 0018:ffff88000585bd68 EFLAGS: 00010202
> > > RAX: 0000000094be55f6 RBX: 6b6b6b6b6b6b6b6b RCX: 000000006b6b6b6b
> > > RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000000
> > > RBP: ffff88000585bd88 R08: 0000000000000000 R09: 0000000000000000
> > > R10: 0000000000000000 R11: 0000000000000000 R12: 000000000029c161
> > > R13: ffff8800a8918288 R14: 0000000000000000 R15: 0000000000000009
> > > FS: 00007fa12651e740(0000) GS:ffff88012ae00000(0000) knlGS:0000000000000000
> > > CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> > > CR2: 0000000000000010 CR3: 000000001a128000 CR4: 00000000000007f0
> > > DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> > > DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
> > > Process trinity-child1 (pid: 23476, threadinfo ffff88000585a000, task ffff8800cd454920)
> > > Stack:
> > > ffff880128edc1e8 ffff8800a8918250 fffffffffffffffe ffff88012265f430
> > > ffff88000585bdb8 ffffffff812357cd ffff8800a8918250 ffff8801226514d0
> > > ffff88000585bf38 0000000000000000 ffff88000585bde8 ffffffff811bb30d
> > > Call Trace:
> > > [<ffffffff812357cd>] sysfs_lookup+0x6d/0xe0
> > > [<ffffffff811bb30d>] lookup_real+0x1d/0x60
> > > [<ffffffff811bb528>] __lookup_hash+0x38/0x50
> > > [<ffffffff811bb559>] lookup_hash+0x19/0x20
> > > [<ffffffff811be993>] kern_path_create+0x93/0x170
> > > [<ffffffff811bce46>] ? getname_flags.part.32+0x86/0x150
> > > [<ffffffff811beaba>] user_path_create+0x4a/0x70
> > > [<ffffffff811c1a09>] sys_mkdirat+0x39/0xe0
> > > [<ffffffff816cd942>] system_call_fastpath+0x16/0x1b
> > > Code: 00 48 8b 9f 88 00 00 00 f6 c4 0f 0f 95 c0 48 85 f6 0f 95 c2 38 d0 75 79 4c 89 ee 4c 89 f7 e8 91 ef ff ff 41 89 c4 48 85 db 74 1d <8b> 4b 28 41 39 cc 74 21 44 89 e0 29 c8 83 f8 00 7c 2c 74 45 48
> > > RIP [<ffffffff812356b7>] sysfs_find_dirent+0x47/0xf0
> > > RSP <ffff88000585bd68>
> > > ---[ end trace 4ba97703eaafbb8b ]---
> >
> > Any hint as to what was happening here when this crashed?
>
> Given I haven't seen this (or the other sysfs bug) before today, I'm going
> to assume it's due to one of the features I added to trinity today.
>
> 1. Instead of just relying on filenames it gathers from sysfs on startup,
> it now also generates mangled variants of them.
> (Appending a / followed by garbage for eg)
>
> 2. When a syscall wants a page of memory, it now sometimes hands it one
> filled with malformed UTF-8 characters.
>
> 3. A combo of the above, that garbage appended to a pathname may be unicode junk.
>
> Could be some of those that caused these bugs.
>
> I just retried rerunning the test a few times. Every time I run for a while
> I end up with different crashes. It's raining bugs over here.
> (Here's another sysfs one below)
>
> Running 'trinity -c mkdirat -V /sys' doesn't seem to trigger it, so it's an
> interaction with something else maybe.
>
> The one common thing here is that 6b6b6b6b6b6b6b6b showing up in every trace,
> suggesting a use-after-free bugs. They may all be different manifestations
> of the same underlying bug if there's some kind of refcounting bug perhaps.
> (This may also be why telling it to do just mkdirat isn't triggering it,
> if it's racing with some other operation)
>
> Getting this stuff easily reproducable is pretty hard. The best I can offer
> right now is that it seems to trigger *something* bad quickly, even if it's
> not necessarily the exact same trace.
I've hit something similar, but I suspect it's the same issue:
[ 350.140100] general protection fault: 0000 [#1] PREEMPT SMP DEBUG_PAGEALLOC
[ 350.141468] Dumping ftrace buffer:
[ 350.142048] (ftrace buffer empty)
[ 350.142619] Modules linked in:
[ 350.143128] CPU 0
[ 350.143434] Pid: 25064, comm: trinity-child14 Tainted: G W 3.9.0-rc2-next-20130314-sasha-00046-g3897511 #295
[ 350.145415] RIP: 0010:[<ffffffff819ebfb3>] [<ffffffff819ebfb3>] rb_next+0x23/0x60
[ 350.146680] RSP: 0018:ffff88007b9dde48 EFLAGS: 00010202
[ 350.147528] RAX: 6b6b6b6b6b6b6b6b RBX: ffff8800b8524b70 RCX: ffff8800b8524b70
[ 350.148738] RDX: 6b6b6b6b6b6b6b6b RSI: ffff8800b63b96e0 RDI: ffff8800b8524bb8
[ 350.149939] RBP: ffff88007b9dde48 R08: 2222222222222222 R09: 2222222222222222
[ 350.150035] R10: 2222222222222222 R11: 0000000000000000 R12: ffff88008c5cb180
[ 350.150035] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000010
[ 350.150035] FS: 00007fec4eae2700(0000) GS:ffff8800bb800000(0000) knlGS:0000000000000000
[ 350.150035] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 350.150035] CR2: 0000000000000001 CR3: 000000007c32d000 CR4: 00000000000406f0
[ 350.150035] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 350.150035] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[ 350.150035] Process trinity-child14 (pid: 25064, threadinfo ffff88007b9dc000, task ffff880096413000)
[ 350.150035] Stack:
[ 350.150035] ffff88007b9ddeb8 ffffffff812fa959 2222222222222222 2222222200000008
[ 350.150035] 000000000000293e ffffffff8128cca0 ffff88007b9ddf28 ffff8800b63b96e0
[ 350.150035] ffff8800a14e9b78 ffff88008c5cb180 ffff88007b9ddf28 ffffffff8128cca0
[ 350.150035] Call Trace:
[ 350.150035] [<ffffffff812fa959>] sysfs_readdir+0x219/0x280
[ 350.150035] [<ffffffff8128cca0>] ? filldir+0x100/0x100
[ 350.150035] [<ffffffff8128cca0>] ? filldir+0x100/0x100
[ 350.150035] [<ffffffff8128cf18>] vfs_readdir+0x78/0xc0
[ 350.150035] [<ffffffff8117ad3d>] ? trace_hardirqs_on+0xd/0x10
[ 350.150035] [<ffffffff8128d190>] SyS_getdents64+0x90/0x120
[ 350.150035] [<ffffffff83d946d8>] tracesys+0xe1/0xe6
[ 350.150035] Code: 85 d2 75 f4 5d c3 66 90 55 31 c0 48 8b 17 48 89 e5 48 39 d7 74 4a 48 8b 47 08 48 85 c0 75 0c eb 17 0f 1f 80
00 00 00 00 48 89 d0 <48> 8b 50 10 48 85 d2 75 f4 eb 2a 66 90 48 89 d1 48 83 e1 fc 74
[ 350.150035] RIP [<ffffffff819ebfb3>] rb_next+0x23/0x60
[ 350.150035] RSP <ffff88007b9dde48>
[ 350.179705] ---[ end trace a39f58a515b594d5 ]---
Thanks,
Sasha
On 03/15/2013 12:03 AM, Sasha Levin wrote:
> On 03/07/2013 01:26 AM, Dave Jones wrote:
>> On Thu, Mar 07, 2013 at 02:02:30PM +0800, Greg Kroah-Hartman wrote:
>> > On Thu, Mar 07, 2013 at 12:28:54AM -0500, Dave Jones wrote:
>> > > general protection fault: 0000 [#1] PREEMPT SMP
>> > > Modules linked in: vmw_vsock_vmci_transport vmw_vmci vsock bnep fuse rfcomm hidp l2tp_ppp l2tp_core 8021q garp mrp dlci pppoe pppox ppp_generic slhc scsi_transport_iscsi rose caif_socket caif can_raw bridge af_key can_bcm llc2 stp can netrom phonet af_rxrpc nfnetlink ipt_ULOG x25 rds irda crc_ccitt ax25 ipx p8023 p8022 decnet atm appletalk psnap llc nfc lockd sunrpc ip6t_REJECT nf_conntrack_ipv6 nf_defrag_ipv6 xt_conntrack nf_conntrack ip6table_filter ip6_tables snd_hda_codec_realtek snd_hda_intel snd_hda_codec snd_pcm btusb snd_page_alloc bluetooth snd_timer snd microcode rfkill usb_debug serio_raw pcspkr edac_core soundcore vhost_net tun r8169 macvtap macvlan mii kvm_amd kvm
>> > > CPU 0
>> > > Pid: 23476, comm: trinity-child1 Not tainted 3.9.0-rc1+ #69 Gigabyte Technology Co., Ltd. GA-MA78GM-S2H/GA-MA78GM-S2H
>> > > RIP: 0010:[<ffffffff812356b7>] [<ffffffff812356b7>] sysfs_find_dirent+0x47/0xf0
>> > > RSP: 0018:ffff88000585bd68 EFLAGS: 00010202
>> > > RAX: 0000000094be55f6 RBX: 6b6b6b6b6b6b6b6b RCX: 000000006b6b6b6b
>> > > RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000000
>> > > RBP: ffff88000585bd88 R08: 0000000000000000 R09: 0000000000000000
>> > > R10: 0000000000000000 R11: 0000000000000000 R12: 000000000029c161
>> > > R13: ffff8800a8918288 R14: 0000000000000000 R15: 0000000000000009
>> > > FS: 00007fa12651e740(0000) GS:ffff88012ae00000(0000) knlGS:0000000000000000
>> > > CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
>> > > CR2: 0000000000000010 CR3: 000000001a128000 CR4: 00000000000007f0
>> > > DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
>> > > DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
>> > > Process trinity-child1 (pid: 23476, threadinfo ffff88000585a000, task ffff8800cd454920)
>> > > Stack:
>> > > ffff880128edc1e8 ffff8800a8918250 fffffffffffffffe ffff88012265f430
>> > > ffff88000585bdb8 ffffffff812357cd ffff8800a8918250 ffff8801226514d0
>> > > ffff88000585bf38 0000000000000000 ffff88000585bde8 ffffffff811bb30d
>> > > Call Trace:
>> > > [<ffffffff812357cd>] sysfs_lookup+0x6d/0xe0
>> > > [<ffffffff811bb30d>] lookup_real+0x1d/0x60
>> > > [<ffffffff811bb528>] __lookup_hash+0x38/0x50
>> > > [<ffffffff811bb559>] lookup_hash+0x19/0x20
>> > > [<ffffffff811be993>] kern_path_create+0x93/0x170
>> > > [<ffffffff811bce46>] ? getname_flags.part.32+0x86/0x150
>> > > [<ffffffff811beaba>] user_path_create+0x4a/0x70
>> > > [<ffffffff811c1a09>] sys_mkdirat+0x39/0xe0
>> > > [<ffffffff816cd942>] system_call_fastpath+0x16/0x1b
>> > > Code: 00 48 8b 9f 88 00 00 00 f6 c4 0f 0f 95 c0 48 85 f6 0f 95 c2 38 d0 75 79 4c 89 ee 4c 89 f7 e8 91 ef ff ff 41 89 c4 48 85 db 74 1d <8b> 4b 28 41 39 cc 74 21 44 89 e0 29 c8 83 f8 00 7c 2c 74 45 48
>> > > RIP [<ffffffff812356b7>] sysfs_find_dirent+0x47/0xf0
>> > > RSP <ffff88000585bd68>
>> > > ---[ end trace 4ba97703eaafbb8b ]---
>> >
>> > Any hint as to what was happening here when this crashed?
>>
>> Given I haven't seen this (or the other sysfs bug) before today, I'm going
>> to assume it's due to one of the features I added to trinity today.
>>
>> 1. Instead of just relying on filenames it gathers from sysfs on startup,
>> it now also generates mangled variants of them.
>> (Appending a / followed by garbage for eg)
>>
>> 2. When a syscall wants a page of memory, it now sometimes hands it one
>> filled with malformed UTF-8 characters.
>>
>> 3. A combo of the above, that garbage appended to a pathname may be unicode junk.
>>
>> Could be some of those that caused these bugs.
>>
>> I just retried rerunning the test a few times. Every time I run for a while
>> I end up with different crashes. It's raining bugs over here.
>> (Here's another sysfs one below)
>>
>> Running 'trinity -c mkdirat -V /sys' doesn't seem to trigger it, so it's an
>> interaction with something else maybe.
>>
>> The one common thing here is that 6b6b6b6b6b6b6b6b showing up in every trace,
>> suggesting a use-after-free bugs. They may all be different manifestations
>> of the same underlying bug if there's some kind of refcounting bug perhaps.
>> (This may also be why telling it to do just mkdirat isn't triggering it,
>> if it's racing with some other operation)
>>
>> Getting this stuff easily reproducable is pretty hard. The best I can offer
>> right now is that it seems to trigger *something* bad quickly, even if it's
>> not necessarily the exact same trace.
>
> I've hit something similar, but I suspect it's the same issue:
>
> [ 350.140100] general protection fault: 0000 [#1] PREEMPT SMP DEBUG_PAGEALLOC
> [ 350.141468] Dumping ftrace buffer:
> [ 350.142048] (ftrace buffer empty)
> [ 350.142619] Modules linked in:
> [ 350.143128] CPU 0
> [ 350.143434] Pid: 25064, comm: trinity-child14 Tainted: G W 3.9.0-rc2-next-20130314-sasha-00046-g3897511 #295
> [ 350.145415] RIP: 0010:[<ffffffff819ebfb3>] [<ffffffff819ebfb3>] rb_next+0x23/0x60
> [ 350.146680] RSP: 0018:ffff88007b9dde48 EFLAGS: 00010202
> [ 350.147528] RAX: 6b6b6b6b6b6b6b6b RBX: ffff8800b8524b70 RCX: ffff8800b8524b70
> [ 350.148738] RDX: 6b6b6b6b6b6b6b6b RSI: ffff8800b63b96e0 RDI: ffff8800b8524bb8
> [ 350.149939] RBP: ffff88007b9dde48 R08: 2222222222222222 R09: 2222222222222222
> [ 350.150035] R10: 2222222222222222 R11: 0000000000000000 R12: ffff88008c5cb180
> [ 350.150035] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000010
> [ 350.150035] FS: 00007fec4eae2700(0000) GS:ffff8800bb800000(0000) knlGS:0000000000000000
> [ 350.150035] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 350.150035] CR2: 0000000000000001 CR3: 000000007c32d000 CR4: 00000000000406f0
> [ 350.150035] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> [ 350.150035] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
> [ 350.150035] Process trinity-child14 (pid: 25064, threadinfo ffff88007b9dc000, task ffff880096413000)
> [ 350.150035] Stack:
> [ 350.150035] ffff88007b9ddeb8 ffffffff812fa959 2222222222222222 2222222200000008
> [ 350.150035] 000000000000293e ffffffff8128cca0 ffff88007b9ddf28 ffff8800b63b96e0
> [ 350.150035] ffff8800a14e9b78 ffff88008c5cb180 ffff88007b9ddf28 ffffffff8128cca0
> [ 350.150035] Call Trace:
> [ 350.150035] [<ffffffff812fa959>] sysfs_readdir+0x219/0x280
> [ 350.150035] [<ffffffff8128cca0>] ? filldir+0x100/0x100
> [ 350.150035] [<ffffffff8128cca0>] ? filldir+0x100/0x100
> [ 350.150035] [<ffffffff8128cf18>] vfs_readdir+0x78/0xc0
> [ 350.150035] [<ffffffff8117ad3d>] ? trace_hardirqs_on+0xd/0x10
> [ 350.150035] [<ffffffff8128d190>] SyS_getdents64+0x90/0x120
> [ 350.150035] [<ffffffff83d946d8>] tracesys+0xe1/0xe6
> [ 350.150035] Code: 85 d2 75 f4 5d c3 66 90 55 31 c0 48 8b 17 48 89 e5 48 39 d7 74 4a 48 8b 47 08 48 85 c0 75 0c eb 17 0f 1f 80
> 00 00 00 00 48 89 d0 <48> 8b 50 10 48 85 d2 75 f4 eb 2a 66 90 48 89 d1 48 83 e1 fc 74
> [ 350.150035] RIP [<ffffffff819ebfb3>] rb_next+0x23/0x60
> [ 350.150035] RSP <ffff88007b9dde48>
> [ 350.179705] ---[ end trace a39f58a515b594d5 ]---
And on the bright side, unlike in Dave's case, similar issues reproduce rather easily
over here:
[ 117.001400] general protection fault: 0000 [#1] PREEMPT SMP DEBUG_PAGEALLOC
[ 117.007659] Dumping ftrace buffer:
[ 117.008300] (ftrace buffer empty)
[ 117.008885] Modules linked in:
[ 117.009397] CPU 0
[ 117.009700] Pid: 9168, comm: trinity-child11 Tainted: G W 3.9.0-rc2-next-20130314-sasha-00046-g3897511 #295
[ 117.010041] RIP: 0010:[<ffffffff812fa6e0>] [<ffffffff812fa6e0>] sysfs_dir_pos+0xa0/0x100
[ 117.010041] RSP: 0018:ffff8800796dde18 EFLAGS: 00010202
[ 117.010041] RAX: 6b6b6b6b6b6b6b6b RBX: 0000000000000000 RCX: ffff8800b853d8c8
[ 117.010041] RDX: 0000000051932d51 RSI: 000000006b6b6b6b RDI: 0000000000000000
[ 117.010041] RBP: ffff8800796dde48 R08: 2222222222222222 R09: 2222222222222222
[ 117.010041] R10: 2222222222222222 R11: 0000000000000000 R12: 0000000000000000
[ 117.010041] R13: 0000000000000000 R14: ffff8800a4a4b0b8 R15: ffff8800a4a4afd0
[ 117.010041] FS: 00007f943990a700(0000) GS:ffff8800bb800000(0000) knlGS:0000000000000000
[ 117.010041] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 117.010041] CR2: 0000000000000000 CR3: 000000007bea7000 CR4: 00000000000406f0
[ 117.010041] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 117.010041] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[ 117.010041] Process trinity-child11 (pid: 9168, threadinfo ffff8800796dc000, task ffff88008120b000)
[ 117.010041] Stack:
[ 117.010041] ffff8800a4a4b0b8 ffff8800a4a4afd0 ffff8800796dde48 ffffffff83d87edf
[ 117.010041] ffff8800b853d6e0 ffff8800aa27d340 ffff8800796ddeb8 ffffffff812fa85d
[ 117.010041] 2222222222222222 2222222222222222 ffff8800796dde98 ffffffff8128cca0
[ 117.010041] Call Trace:
[ 117.010041] [<ffffffff83d87edf>] ? mutex_lock_nested+0x3f/0x50
[ 117.010041] [<ffffffff812fa85d>] sysfs_readdir+0x11d/0x280
[ 117.010041] [<ffffffff8128cca0>] ? filldir+0x100/0x100
[ 117.010041] [<ffffffff8128cca0>] ? filldir+0x100/0x100
[ 117.010041] [<ffffffff8128cf18>] vfs_readdir+0x78/0xc0
[ 117.010041] [<ffffffff8117ad3d>] ? trace_hardirqs_on+0xd/0x10
[ 117.010041] [<ffffffff8128d190>] SyS_getdents64+0x90/0x120
[ 117.010041] [<ffffffff83d946d8>] tracesys+0xe1/0xe6
[ 117.010041] Code: 00 00 00 48 85 c9 74 6d 48 39 59 68 75 45 eb 65 0f 1f 00 48 81 fa fe ff ff 7f 7f 59 48 8b 86 88 00 00 00 48
85 c0 74 4d 0f 1f 00 <8b> 70 28 48 8d 48 b8 48 39 f2 7d 0c 48 8b 40 10 eb 0c 66 0f 1f
[ 117.010041] RIP [<ffffffff812fa6e0>] sysfs_dir_pos+0xa0/0x100
[ 117.010041] RSP <ffff8800796dde18>
[ 117.058487] ---[ end trace 1a817146a00445c0 ]---
Thanks,
Sasha
Hi,
On Fri, Mar 15, 2013 at 1:04 PM, Sasha Levin <[email protected]> wrote:
> On 03/15/2013 12:03 AM, Sasha Levin wrote:
>>
>> [ 350.140100] general protection fault: 0000 [#1] PREEMPT SMP DEBUG_PAGEALLOC
>> [ 350.141468] Dumping ftrace buffer:
>> [ 350.142048] (ftrace buffer empty)
>> [ 350.142619] Modules linked in:
>> [ 350.143128] CPU 0
>> [ 350.143434] Pid: 25064, comm: trinity-child14 Tainted: G W 3.9.0-rc2-next-20130314-sasha-00046-g3897511 #295
>> [ 350.145415] RIP: 0010:[<ffffffff819ebfb3>] [<ffffffff819ebfb3>] rb_next+0x23/0x60
>> [ 350.146680] RSP: 0018:ffff88007b9dde48 EFLAGS: 00010202
>> [ 350.147528] RAX: 6b6b6b6b6b6b6b6b RBX: ffff8800b8524b70 RCX: ffff8800b8524b70
>> [ 350.148738] RDX: 6b6b6b6b6b6b6b6b RSI: ffff8800b63b96e0 RDI: ffff8800b8524bb8
>> [ 350.149939] RBP: ffff88007b9dde48 R08: 2222222222222222 R09: 2222222222222222
>> [ 350.150035] R10: 2222222222222222 R11: 0000000000000000 R12: ffff88008c5cb180
>> [ 350.150035] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000010
>> [ 350.150035] FS: 00007fec4eae2700(0000) GS:ffff8800bb800000(0000) knlGS:0000000000000000
>> [ 350.150035] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
>> [ 350.150035] CR2: 0000000000000001 CR3: 000000007c32d000 CR4: 00000000000406f0
>> [ 350.150035] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
>> [ 350.150035] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
>> [ 350.150035] Process trinity-child14 (pid: 25064, threadinfo ffff88007b9dc000, task ffff880096413000)
>> [ 350.150035] Stack:
>> [ 350.150035] ffff88007b9ddeb8 ffffffff812fa959 2222222222222222 2222222200000008
>> [ 350.150035] 000000000000293e ffffffff8128cca0 ffff88007b9ddf28 ffff8800b63b96e0
>> [ 350.150035] ffff8800a14e9b78 ffff88008c5cb180 ffff88007b9ddf28 ffffffff8128cca0
>> [ 350.150035] Call Trace:
>> [ 350.150035] [<ffffffff812fa959>] sysfs_readdir+0x219/0x280
>> [ 350.150035] [<ffffffff8128cca0>] ? filldir+0x100/0x100
>> [ 350.150035] [<ffffffff8128cca0>] ? filldir+0x100/0x100
>> [ 350.150035] [<ffffffff8128cf18>] vfs_readdir+0x78/0xc0
>> [ 350.150035] [<ffffffff8117ad3d>] ? trace_hardirqs_on+0xd/0x10
>> [ 350.150035] [<ffffffff8128d190>] SyS_getdents64+0x90/0x120
>> [ 350.150035] [<ffffffff83d946d8>] tracesys+0xe1/0xe6
>> [ 350.150035] Code: 85 d2 75 f4 5d c3 66 90 55 31 c0 48 8b 17 48 89 e5 48 39 d7 74 4a 48 8b 47 08 48 85 c0 75 0c eb 17 0f 1f 80
>> 00 00 00 00 48 89 d0 <48> 8b 50 10 48 85 d2 75 f4 eb 2a 66 90 48 89 d1 48 83 e1 fc 74
>> [ 350.150035] RIP [<ffffffff819ebfb3>] rb_next+0x23/0x60
>> [ 350.150035] RSP <ffff88007b9dde48>
>> [ 350.179705] ---[ end trace a39f58a515b594d5 ]---
>
> And on the bright side, unlike in Dave's case, similar issues reproduce rather easily
> over here:
Could you share how to reproduce that easily?
Thanks,
--
Ming Lei
On 03/15/2013 03:38 AM, Ming Lei wrote:
> Hi,
>
> On Fri, Mar 15, 2013 at 1:04 PM, Sasha Levin <[email protected]> wrote:
>> On 03/15/2013 12:03 AM, Sasha Levin wrote:
>>>
>>> [ 350.140100] general protection fault: 0000 [#1] PREEMPT SMP DEBUG_PAGEALLOC
>>> [ 350.141468] Dumping ftrace buffer:
>>> [ 350.142048] (ftrace buffer empty)
>>> [ 350.142619] Modules linked in:
>>> [ 350.143128] CPU 0
>>> [ 350.143434] Pid: 25064, comm: trinity-child14 Tainted: G W 3.9.0-rc2-next-20130314-sasha-00046-g3897511 #295
>>> [ 350.145415] RIP: 0010:[<ffffffff819ebfb3>] [<ffffffff819ebfb3>] rb_next+0x23/0x60
>>> [ 350.146680] RSP: 0018:ffff88007b9dde48 EFLAGS: 00010202
>>> [ 350.147528] RAX: 6b6b6b6b6b6b6b6b RBX: ffff8800b8524b70 RCX: ffff8800b8524b70
>>> [ 350.148738] RDX: 6b6b6b6b6b6b6b6b RSI: ffff8800b63b96e0 RDI: ffff8800b8524bb8
>>> [ 350.149939] RBP: ffff88007b9dde48 R08: 2222222222222222 R09: 2222222222222222
>>> [ 350.150035] R10: 2222222222222222 R11: 0000000000000000 R12: ffff88008c5cb180
>>> [ 350.150035] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000010
>>> [ 350.150035] FS: 00007fec4eae2700(0000) GS:ffff8800bb800000(0000) knlGS:0000000000000000
>>> [ 350.150035] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
>>> [ 350.150035] CR2: 0000000000000001 CR3: 000000007c32d000 CR4: 00000000000406f0
>>> [ 350.150035] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
>>> [ 350.150035] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
>>> [ 350.150035] Process trinity-child14 (pid: 25064, threadinfo ffff88007b9dc000, task ffff880096413000)
>>> [ 350.150035] Stack:
>>> [ 350.150035] ffff88007b9ddeb8 ffffffff812fa959 2222222222222222 2222222200000008
>>> [ 350.150035] 000000000000293e ffffffff8128cca0 ffff88007b9ddf28 ffff8800b63b96e0
>>> [ 350.150035] ffff8800a14e9b78 ffff88008c5cb180 ffff88007b9ddf28 ffffffff8128cca0
>>> [ 350.150035] Call Trace:
>>> [ 350.150035] [<ffffffff812fa959>] sysfs_readdir+0x219/0x280
>>> [ 350.150035] [<ffffffff8128cca0>] ? filldir+0x100/0x100
>>> [ 350.150035] [<ffffffff8128cca0>] ? filldir+0x100/0x100
>>> [ 350.150035] [<ffffffff8128cf18>] vfs_readdir+0x78/0xc0
>>> [ 350.150035] [<ffffffff8117ad3d>] ? trace_hardirqs_on+0xd/0x10
>>> [ 350.150035] [<ffffffff8128d190>] SyS_getdents64+0x90/0x120
>>> [ 350.150035] [<ffffffff83d946d8>] tracesys+0xe1/0xe6
>>> [ 350.150035] Code: 85 d2 75 f4 5d c3 66 90 55 31 c0 48 8b 17 48 89 e5 48 39 d7 74 4a 48 8b 47 08 48 85 c0 75 0c eb 17 0f 1f 80
>>> 00 00 00 00 48 89 d0 <48> 8b 50 10 48 85 d2 75 f4 eb 2a 66 90 48 89 d1 48 83 e1 fc 74
>>> [ 350.150035] RIP [<ffffffff819ebfb3>] rb_next+0x23/0x60
>>> [ 350.150035] RSP <ffff88007b9dde48>
>>> [ 350.179705] ---[ end trace a39f58a515b594d5 ]---
>>
>> And on the bright side, unlike in Dave's case, similar issues reproduce rather easily
>> over here:
>
> Could you share how to reproduce that easily?
Reproduces easily with trinity, didn't look into manually doing it yet.
Thought it looks like the dir is going away while we're listing the directory,
so I assume it would be easy to reproduce if we put a short delay into sysfs_dir_next_pos
and remove the directory underneath? I can try that later today/tomorrow.
Thanks,
Sasha
On Fri, Mar 15, 2013 at 1:04 PM, Sasha Levin <[email protected]> wrote:
> On 03/15/2013 12:03 AM, Sasha Levin wrote:
>> On 03/07/2013 01:26 AM, Dave Jones wrote:
>>> On Thu, Mar 07, 2013 at 02:02:30PM +0800, Greg Kroah-Hartman wrote:
>>> > On Thu, Mar 07, 2013 at 12:28:54AM -0500, Dave Jones wrote:
>>> > > general protection fault: 0000 [#1] PREEMPT SMP
>>> > > Modules linked in: vmw_vsock_vmci_transport vmw_vmci vsock bnep fuse rfcomm hidp l2tp_ppp l2tp_core 8021q garp mrp dlci pppoe pppox ppp_generic slhc scsi_transport_iscsi rose caif_socket caif can_raw bridge af_key can_bcm llc2 stp can netrom phonet af_rxrpc nfnetlink ipt_ULOG x25 rds irda crc_ccitt ax25 ipx p8023 p8022 decnet atm appletalk psnap llc nfc lockd sunrpc ip6t_REJECT nf_conntrack_ipv6 nf_defrag_ipv6 xt_conntrack nf_conntrack ip6table_filter ip6_tables snd_hda_codec_realtek snd_hda_intel snd_hda_codec snd_pcm btusb snd_page_alloc bluetooth snd_timer snd microcode rfkill usb_debug serio_raw pcspkr edac_core soundcore vhost_net tun r8169 macvtap macvlan mii kvm_amd kvm
>>> > > CPU 0
>>> > > Pid: 23476, comm: trinity-child1 Not tainted 3.9.0-rc1+ #69 Gigabyte Technology Co., Ltd. GA-MA78GM-S2H/GA-MA78GM-S2H
>>> > > RIP: 0010:[<ffffffff812356b7>] [<ffffffff812356b7>] sysfs_find_dirent+0x47/0xf0
>>> > > RSP: 0018:ffff88000585bd68 EFLAGS: 00010202
>>> > > RAX: 0000000094be55f6 RBX: 6b6b6b6b6b6b6b6b RCX: 000000006b6b6b6b
>>> > > RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000000000000
>>> > > RBP: ffff88000585bd88 R08: 0000000000000000 R09: 0000000000000000
>>> > > R10: 0000000000000000 R11: 0000000000000000 R12: 000000000029c161
>>> > > R13: ffff8800a8918288 R14: 0000000000000000 R15: 0000000000000009
>>> > > FS: 00007fa12651e740(0000) GS:ffff88012ae00000(0000) knlGS:0000000000000000
>>> > > CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
>>> > > CR2: 0000000000000010 CR3: 000000001a128000 CR4: 00000000000007f0
>>> > > DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
>>> > > DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
>>> > > Process trinity-child1 (pid: 23476, threadinfo ffff88000585a000, task ffff8800cd454920)
>>> > > Stack:
>>> > > ffff880128edc1e8 ffff8800a8918250 fffffffffffffffe ffff88012265f430
>>> > > ffff88000585bdb8 ffffffff812357cd ffff8800a8918250 ffff8801226514d0
>>> > > ffff88000585bf38 0000000000000000 ffff88000585bde8 ffffffff811bb30d
>>> > > Call Trace:
>>> > > [<ffffffff812357cd>] sysfs_lookup+0x6d/0xe0
>>> > > [<ffffffff811bb30d>] lookup_real+0x1d/0x60
>>> > > [<ffffffff811bb528>] __lookup_hash+0x38/0x50
>>> > > [<ffffffff811bb559>] lookup_hash+0x19/0x20
>>> > > [<ffffffff811be993>] kern_path_create+0x93/0x170
>>> > > [<ffffffff811bce46>] ? getname_flags.part.32+0x86/0x150
>>> > > [<ffffffff811beaba>] user_path_create+0x4a/0x70
>>> > > [<ffffffff811c1a09>] sys_mkdirat+0x39/0xe0
>>> > > [<ffffffff816cd942>] system_call_fastpath+0x16/0x1b
>>> > > Code: 00 48 8b 9f 88 00 00 00 f6 c4 0f 0f 95 c0 48 85 f6 0f 95 c2 38 d0 75 79 4c 89 ee 4c 89 f7 e8 91 ef ff ff 41 89 c4 48 85 db 74 1d <8b> 4b 28 41 39 cc 74 21 44 89 e0 29 c8 83 f8 00 7c 2c 74 45 48
>>> > > RIP [<ffffffff812356b7>] sysfs_find_dirent+0x47/0xf0
>>> > > RSP <ffff88000585bd68>
>>> > > ---[ end trace 4ba97703eaafbb8b ]---
>>> >
>>> > Any hint as to what was happening here when this crashed?
>>>
>>> Given I haven't seen this (or the other sysfs bug) before today, I'm going
>>> to assume it's due to one of the features I added to trinity today.
>>>
>>> 1. Instead of just relying on filenames it gathers from sysfs on startup,
>>> it now also generates mangled variants of them.
>>> (Appending a / followed by garbage for eg)
>>>
>>> 2. When a syscall wants a page of memory, it now sometimes hands it one
>>> filled with malformed UTF-8 characters.
>>>
>>> 3. A combo of the above, that garbage appended to a pathname may be unicode junk.
>>>
>>> Could be some of those that caused these bugs.
>>>
>>> I just retried rerunning the test a few times. Every time I run for a while
>>> I end up with different crashes. It's raining bugs over here.
>>> (Here's another sysfs one below)
>>>
>>> Running 'trinity -c mkdirat -V /sys' doesn't seem to trigger it, so it's an
>>> interaction with something else maybe.
>>>
>>> The one common thing here is that 6b6b6b6b6b6b6b6b showing up in every trace,
>>> suggesting a use-after-free bugs. They may all be different manifestations
>>> of the same underlying bug if there's some kind of refcounting bug perhaps.
>>> (This may also be why telling it to do just mkdirat isn't triggering it,
>>> if it's racing with some other operation)
>>>
>>> Getting this stuff easily reproducable is pretty hard. The best I can offer
>>> right now is that it seems to trigger *something* bad quickly, even if it's
>>> not necessarily the exact same trace.
>>
>> I've hit something similar, but I suspect it's the same issue:
>>
>> [ 350.140100] general protection fault: 0000 [#1] PREEMPT SMP DEBUG_PAGEALLOC
>> [ 350.141468] Dumping ftrace buffer:
>> [ 350.142048] (ftrace buffer empty)
>> [ 350.142619] Modules linked in:
>> [ 350.143128] CPU 0
>> [ 350.143434] Pid: 25064, comm: trinity-child14 Tainted: G W 3.9.0-rc2-next-20130314-sasha-00046-g3897511 #295
>> [ 350.145415] RIP: 0010:[<ffffffff819ebfb3>] [<ffffffff819ebfb3>] rb_next+0x23/0x60
>> [ 350.146680] RSP: 0018:ffff88007b9dde48 EFLAGS: 00010202
>> [ 350.147528] RAX: 6b6b6b6b6b6b6b6b RBX: ffff8800b8524b70 RCX: ffff8800b8524b70
>> [ 350.148738] RDX: 6b6b6b6b6b6b6b6b RSI: ffff8800b63b96e0 RDI: ffff8800b8524bb8
>> [ 350.149939] RBP: ffff88007b9dde48 R08: 2222222222222222 R09: 2222222222222222
>> [ 350.150035] R10: 2222222222222222 R11: 0000000000000000 R12: ffff88008c5cb180
>> [ 350.150035] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000010
>> [ 350.150035] FS: 00007fec4eae2700(0000) GS:ffff8800bb800000(0000) knlGS:0000000000000000
>> [ 350.150035] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
>> [ 350.150035] CR2: 0000000000000001 CR3: 000000007c32d000 CR4: 00000000000406f0
>> [ 350.150035] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
>> [ 350.150035] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
>> [ 350.150035] Process trinity-child14 (pid: 25064, threadinfo ffff88007b9dc000, task ffff880096413000)
>> [ 350.150035] Stack:
>> [ 350.150035] ffff88007b9ddeb8 ffffffff812fa959 2222222222222222 2222222200000008
>> [ 350.150035] 000000000000293e ffffffff8128cca0 ffff88007b9ddf28 ffff8800b63b96e0
>> [ 350.150035] ffff8800a14e9b78 ffff88008c5cb180 ffff88007b9ddf28 ffffffff8128cca0
>> [ 350.150035] Call Trace:
>> [ 350.150035] [<ffffffff812fa959>] sysfs_readdir+0x219/0x280
>> [ 350.150035] [<ffffffff8128cca0>] ? filldir+0x100/0x100
>> [ 350.150035] [<ffffffff8128cca0>] ? filldir+0x100/0x100
>> [ 350.150035] [<ffffffff8128cf18>] vfs_readdir+0x78/0xc0
>> [ 350.150035] [<ffffffff8117ad3d>] ? trace_hardirqs_on+0xd/0x10
>> [ 350.150035] [<ffffffff8128d190>] SyS_getdents64+0x90/0x120
>> [ 350.150035] [<ffffffff83d946d8>] tracesys+0xe1/0xe6
>> [ 350.150035] Code: 85 d2 75 f4 5d c3 66 90 55 31 c0 48 8b 17 48 89 e5 48 39 d7 74 4a 48 8b 47 08 48 85 c0 75 0c eb 17 0f 1f 80
>> 00 00 00 00 48 89 d0 <48> 8b 50 10 48 85 d2 75 f4 eb 2a 66 90 48 89 d1 48 83 e1 fc 74
>> [ 350.150035] RIP [<ffffffff819ebfb3>] rb_next+0x23/0x60
>> [ 350.150035] RSP <ffff88007b9dde48>
>> [ 350.179705] ---[ end trace a39f58a515b594d5 ]---
>
> And on the bright side, unlike in Dave's case, similar issues reproduce rather easily
> over here:
>
> [ 117.001400] general protection fault: 0000 [#1] PREEMPT SMP DEBUG_PAGEALLOC
> [ 117.007659] Dumping ftrace buffer:
> [ 117.008300] (ftrace buffer empty)
> [ 117.008885] Modules linked in:
> [ 117.009397] CPU 0
> [ 117.009700] Pid: 9168, comm: trinity-child11 Tainted: G W 3.9.0-rc2-next-20130314-sasha-00046-g3897511 #295
> [ 117.010041] RIP: 0010:[<ffffffff812fa6e0>] [<ffffffff812fa6e0>] sysfs_dir_pos+0xa0/0x100
> [ 117.010041] RSP: 0018:ffff8800796dde18 EFLAGS: 00010202
> [ 117.010041] RAX: 6b6b6b6b6b6b6b6b RBX: 0000000000000000 RCX: ffff8800b853d8c8
> [ 117.010041] RDX: 0000000051932d51 RSI: 000000006b6b6b6b RDI: 0000000000000000
> [ 117.010041] RBP: ffff8800796dde48 R08: 2222222222222222 R09: 2222222222222222
> [ 117.010041] R10: 2222222222222222 R11: 0000000000000000 R12: 0000000000000000
> [ 117.010041] R13: 0000000000000000 R14: ffff8800a4a4b0b8 R15: ffff8800a4a4afd0
> [ 117.010041] FS: 00007f943990a700(0000) GS:ffff8800bb800000(0000) knlGS:0000000000000000
> [ 117.010041] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 117.010041] CR2: 0000000000000000 CR3: 000000007bea7000 CR4: 00000000000406f0
> [ 117.010041] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> [ 117.010041] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
> [ 117.010041] Process trinity-child11 (pid: 9168, threadinfo ffff8800796dc000, task ffff88008120b000)
> [ 117.010041] Stack:
> [ 117.010041] ffff8800a4a4b0b8 ffff8800a4a4afd0 ffff8800796dde48 ffffffff83d87edf
> [ 117.010041] ffff8800b853d6e0 ffff8800aa27d340 ffff8800796ddeb8 ffffffff812fa85d
> [ 117.010041] 2222222222222222 2222222222222222 ffff8800796dde98 ffffffff8128cca0
> [ 117.010041] Call Trace:
> [ 117.010041] [<ffffffff83d87edf>] ? mutex_lock_nested+0x3f/0x50
> [ 117.010041] [<ffffffff812fa85d>] sysfs_readdir+0x11d/0x280
> [ 117.010041] [<ffffffff8128cca0>] ? filldir+0x100/0x100
> [ 117.010041] [<ffffffff8128cca0>] ? filldir+0x100/0x100
> [ 117.010041] [<ffffffff8128cf18>] vfs_readdir+0x78/0xc0
> [ 117.010041] [<ffffffff8117ad3d>] ? trace_hardirqs_on+0xd/0x10
> [ 117.010041] [<ffffffff8128d190>] SyS_getdents64+0x90/0x120
> [ 117.010041] [<ffffffff83d946d8>] tracesys+0xe1/0xe6
> [ 117.010041] Code: 00 00 00 48 85 c9 74 6d 48 39 59 68 75 45 eb 65 0f 1f 00 48 81 fa fe ff ff 7f 7f 59 48 8b 86 88 00 00 00 48
> 85 c0 74 4d 0f 1f 00 <8b> 70 28 48 8d 48 b8 48 39 f2 7d 0c 48 8b 40 10 eb 0c 66 0f 1f
> [ 117.010041] RIP [<ffffffff812fa6e0>] sysfs_dir_pos+0xa0/0x100
> [ 117.010041] RSP <ffff8800796dde18>
> [ 117.058487] ---[ end trace 1a817146a00445c0 ]---
>
init rb node before use due to empty node checked by rb_next().
--- a/fs/sysfs/dir.c Sat Mar 16 20:12:16 2013
+++ b/fs/sysfs/dir.c Sat Mar 16 20:37:10 2013
@@ -396,6 +396,7 @@ struct sysfs_dirent *sysfs_new_dirent(co
atomic_set(&sd->s_count, 1);
atomic_set(&sd->s_active, 0);
+ rb_init_node(&sd->s_rb);
sd->s_name = name;
sd->s_mode = mode;
--
On Sat, Mar 16, 2013 at 8:39 PM, Hillf Danton <[email protected]> wrote:
> init rb node before use due to empty node checked by rb_next().
>
> --- a/fs/sysfs/dir.c Sat Mar 16 20:12:16 2013
> +++ b/fs/sysfs/dir.c Sat Mar 16 20:37:10 2013
> @@ -396,6 +396,7 @@ struct sysfs_dirent *sysfs_new_dirent(co
>
> atomic_set(&sd->s_count, 1);
> atomic_set(&sd->s_active, 0);
> + rb_init_node(&sd->s_rb);
Looks there is no the symbol in linus tree, and not necessary since
rb_link_node() may initialize the node correctly.
Also I can't reproduce the problem on my Pandaboard with trinity, maybe
the below debug code can find the name of the affected node if anyone
would like to test it.
--
diff --git a/fs/sysfs/dir.c b/fs/sysfs/dir.c
index 2fbdff6..9aa11c7 100644
--- a/fs/sysfs/dir.c
+++ b/fs/sysfs/dir.c
@@ -281,6 +281,10 @@ void release_sysfs_dirent(struct sysfs_dirent * sd)
*/
parent_sd = sd->s_parent;
+ if(!(sd->s_flags & SYSFS_FLAG_REMOVED))
+ printk("%s sysfs_dirent use after free: %s-%s\n",
+ __func__, parent_sd->s_name, sd->s_name);
+
if (sysfs_type(sd) == SYSFS_KOBJ_LINK)
sysfs_put(sd->s_symlink.target_sd);
if (sysfs_type(sd) & SYSFS_COPY_NAME)
@@ -962,6 +966,9 @@ static struct sysfs_dirent *sysfs_dir_pos(const void *ns,
int valid = !(pos->s_flags & SYSFS_FLAG_REMOVED) &&
pos->s_parent == parent_sd &&
hash == pos->s_hash;
+ if (valid && (atomic_read(&pos->s_count) <= 1))
+ printk("%s sysfs_dirent use after free: %s-%s\n",
+ __func__, parent_sd->s_name, pos->s_name);
sysfs_put(pos);
if (!valid)
pos = NULL;
Thanks,
--
Ming Lei
On 03/16/2013 09:30 AM, Ming Lei wrote:
> On Sat, Mar 16, 2013 at 8:39 PM, Hillf Danton <[email protected]> wrote:
>> init rb node before use due to empty node checked by rb_next().
>>
>> --- a/fs/sysfs/dir.c Sat Mar 16 20:12:16 2013
>> +++ b/fs/sysfs/dir.c Sat Mar 16 20:37:10 2013
>> @@ -396,6 +396,7 @@ struct sysfs_dirent *sysfs_new_dirent(co
>>
>> atomic_set(&sd->s_count, 1);
>> atomic_set(&sd->s_active, 0);
>> + rb_init_node(&sd->s_rb);
>
> Looks there is no the symbol in linus tree, and not necessary since
> rb_link_node() may initialize the node correctly.
>
> Also I can't reproduce the problem on my Pandaboard with trinity, maybe
> the below debug code can find the name of the affected node if anyone
> would like to test it.
Hi Ming,
With your patch:
[ 1525.874312] release_sysfs_dirent sysfs_dirent use after free: ptysb-uevent
[ 1529.025850] general protection fault: 0000 [#1] PREEMPT SMP DEBUG_PAGEALLOC
[ 1529.027158] Dumping ftrace buffer:
[ 1529.028070] (ftrace buffer empty)
[ 1529.028964] Modules linked in:
[ 1529.029524] CPU 1
[ 1529.029870] Pid: 3945, comm: trinity-child55 Tainted: G W 3.9.0-rc2-next-20130315-sasha-00046-gecde602-dirty #300
[ 1529.030039] RIP: 0010:[<ffffffff812f9300>] [<ffffffff812f9300>] sysfs_find_dirent+0xa0/0x120
[ 1529.030039] RSP: 0018:ffff88009693dbf8 EFLAGS: 00010202
[ 1529.030039] RAX: 00000000144bc5af RBX: 0000000000000000 RCX: 0000000000000000
[ 1529.030039] RDX: 00000000144bc5af RSI: 0000000000000000 RDI: 00000000ffb7311a
[ 1529.030039] RBP: ffff88009693dc28 R08: 0000000000000000 R09: 0000000000000000
[ 1529.030039] R10: 2222222222222222 R11: 0000000000000000 R12: 6b6b6b6b6b6b6b6b
[ 1529.030039] R13: 000000007fb7311a R14: ffff8800b4a443d0 R15: ffff88006db60978
[ 1529.030039] FS: 00007ff6ccfd1700(0000) GS:ffff8800bba00000(0000) knlGS:0000000000000000
[ 1529.030039] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 1529.030039] CR2: 0000000000000000 CR3: 000000006dcef000 CR4: 00000000000406e0
[ 1529.030039] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 1529.030039] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[ 1529.030039] Process trinity-child55 (pid: 3945, threadinfo ffff88009693c000, task ffff880085683000)
[ 1529.030039] Stack:
[ 1529.030039] fffffffffffffffe ffff88006db60940 ffff8800a39f3fc0 ffff8800b4a45ab0
[ 1529.030039] fffffffffffffffe 0000000000000078 ffff88009693dc58 ffffffff812f93e9
[ 1529.030039] ffff88006db60940 ffff8800a39fa9a0 ffff8800a39fa9a0 0000000000000000
[ 1529.030039] Call Trace:
[ 1529.030039] [<ffffffff812f93e9>] sysfs_lookup+0x69/0xf0
[ 1529.030039] [<ffffffff8128232e>] lookup_real+0x2e/0x60
[ 1529.030039] [<ffffffff81282713>] __lookup_hash+0x33/0x40
[ 1529.030039] [<ffffffff83cff60d>] lookup_slow+0x42/0xa8
[ 1529.030039] [<ffffffff812839e5>] ? getname_flags+0x55/0x1a0
[ 1529.030039] [<ffffffff81284d22>] path_lookupat+0xf2/0x770
[ 1529.030039] [<ffffffff83cfe1bc>] ? __slab_alloc.isra.34+0x2ed/0x31f
[ 1529.030039] [<ffffffff81179958>] ? trace_hardirqs_on_caller+0x168/0x1a0
[ 1529.030039] [<ffffffff812853cf>] filename_lookup+0x2f/0xc0
[ 1529.030039] [<ffffffff812839e5>] ? getname_flags+0x55/0x1a0
[ 1529.030039] [<ffffffff8128550d>] do_path_lookup+0x2d/0x30
[ 1529.030039] [<ffffffff81285775>] kern_path+0x25/0x50
[ 1529.030039] [<ffffffff81283a13>] ? getname_flags+0x83/0x1a0
[ 1529.030039] [<ffffffff812b4af7>] lookup_bdev+0x27/0x90
[ 1529.030039] [<ffffffff81283b3d>] ? getname+0xd/0x10
[ 1529.030039] [<ffffffff812e14c3>] quotactl_block+0x33/0xf0
[ 1529.030039] [<ffffffff812e1f03>] SyS_quotactl+0xe3/0x150
[ 1529.030039] [<ffffffff83d919d8>] tracesys+0xe1/0xe6
[ 1529.030039] Code: 8e 00 00 00 0f 1f 80 00 00 00 00 4c 89 fe 48 89 df 45 31 f6 e8 d2 ee ff ff 4d 85 e4 41 89 c5 74 71 66 2e 0f
1f 84 00 00 00 00 00 <41> 8b 44 24 28 4d 8d 74 24 b8 41 39 c5 74 11 44 89 ea 29 c2 89
[ 1529.030039] RIP [<ffffffff812f9300>] sysfs_find_dirent+0xa0/0x120
[ 1529.030039] RSP <ffff88009693dbf8>
Thanks,
Sasha
On Sat, Mar 16, 2013 at 11:07 PM, Sasha Levin <[email protected]> wrote:
>
> Hi Ming,
>
> With your patch:
>
>
> [ 1525.874312] release_sysfs_dirent sysfs_dirent use after free: ptysb-uevent
Sasha, thanks for your test.
So is the oops always triggered on this node of 'ptysb-uevent' or the node name
is changed every time?
Thanks,
--
Ming Lei
On Sat, Mar 16, 2013 at 11:22 PM, Ming Lei <[email protected]> wrote:
> On Sat, Mar 16, 2013 at 11:07 PM, Sasha Levin <[email protected]> wrote:
>>
>> Hi Ming,
>>
>> With your patch:
>>
>>
>> [ 1525.874312] release_sysfs_dirent sysfs_dirent use after free: ptysb-uevent
>
> Sasha, thanks for your test.
>
> So is the oops always triggered on this node of 'ptysb-uevent' or the node name
> is changed every time?
Also, we may dump stack on the release path with the below patch to see who
did the ugly free.
--
diff --git a/fs/sysfs/dir.c b/fs/sysfs/dir.c
index 2fbdff6..993671d 100644
--- a/fs/sysfs/dir.c
+++ b/fs/sysfs/dir.c
@@ -281,6 +281,12 @@ void release_sysfs_dirent(struct sysfs_dirent * sd)
*/
parent_sd = sd->s_parent;
+ if(!(sd->s_flags & SYSFS_FLAG_REMOVED)) {
+ printk("%s sysfs_dirent use after free: %s-%s\n",
+ __func__, parent_sd->s_name, sd->s_name);
+ dump_stack();
+ }
+
if (sysfs_type(sd) == SYSFS_KOBJ_LINK)
sysfs_put(sd->s_symlink.target_sd);
if (sysfs_type(sd) & SYSFS_COPY_NAME)
@@ -962,6 +968,9 @@ static struct sysfs_dirent *sysfs_dir_pos(const void *ns,
int valid = !(pos->s_flags & SYSFS_FLAG_REMOVED) &&
pos->s_parent == parent_sd &&
hash == pos->s_hash;
+ if (valid && (atomic_read(&pos->s_count) <= 1))
+ printk("%s sysfs_dirent use after free: %s-%s\n",
+ __func__, parent_sd->s_name, pos->s_name);
sysfs_put(pos);
if (!valid)
pos = NULL;
Thanks,
--
Ming Lei
On 03/16/2013 11:22 AM, Ming Lei wrote:
> On Sat, Mar 16, 2013 at 11:07 PM, Sasha Levin <[email protected]> wrote:
>>
>> Hi Ming,
>>
>> With your patch:
>>
>>
>> [ 1525.874312] release_sysfs_dirent sysfs_dirent use after free: ptysb-uevent
>
> Sasha, thanks for your test.
>
> So is the oops always triggered on this node of 'ptysb-uevent' or the node name
> is changed every time?
Hi Ming,
Looks like it's a different one every time. Just got one on ad7266-unbind.
Thanks,
Sasha
On 03/16/2013 11:58 AM, Ming Lei wrote:
> On Sat, Mar 16, 2013 at 11:22 PM, Ming Lei <[email protected]> wrote:
>> On Sat, Mar 16, 2013 at 11:07 PM, Sasha Levin <[email protected]> wrote:
>>>
>>> Hi Ming,
>>>
>>> With your patch:
>>>
>>>
>>> [ 1525.874312] release_sysfs_dirent sysfs_dirent use after free: ptysb-uevent
>>
>> Sasha, thanks for your test.
>>
>> So is the oops always triggered on this node of 'ptysb-uevent' or the node name
>> is changed every time?
>
> Also, we may dump stack on the release path with the below patch to see who
> did the ugly free.
>
> --
> diff --git a/fs/sysfs/dir.c b/fs/sysfs/dir.c
> index 2fbdff6..993671d 100644
> --- a/fs/sysfs/dir.c
> +++ b/fs/sysfs/dir.c
> @@ -281,6 +281,12 @@ void release_sysfs_dirent(struct sysfs_dirent * sd)
> */
> parent_sd = sd->s_parent;
>
> + if(!(sd->s_flags & SYSFS_FLAG_REMOVED)) {
> + printk("%s sysfs_dirent use after free: %s-%s\n",
> + __func__, parent_sd->s_name, sd->s_name);
> + dump_stack();
> + }
> +
> if (sysfs_type(sd) == SYSFS_KOBJ_LINK)
> sysfs_put(sd->s_symlink.target_sd);
> if (sysfs_type(sd) & SYSFS_COPY_NAME)
> @@ -962,6 +968,9 @@ static struct sysfs_dirent *sysfs_dir_pos(const void *ns,
> int valid = !(pos->s_flags & SYSFS_FLAG_REMOVED) &&
> pos->s_parent == parent_sd &&
> hash == pos->s_hash;
> + if (valid && (atomic_read(&pos->s_count) <= 1))
> + printk("%s sysfs_dirent use after free: %s-%s\n",
> + __func__, parent_sd->s_name, pos->s_name);
> sysfs_put(pos);
> if (!valid)
> pos = NULL;
>
I don't think it shows what we want it to show thought:
[ 327.416905] Pid: 10504, comm: trinity-child98 Tainted: G W 3.9.0-rc2-next-20130315-sasha-00046-gecde602-dirty #301
[ 327.418815] Call Trace:
[ 327.419255] [<ffffffff812f880e>] release_sysfs_dirent+0x4e/0x120
[ 327.420595] [<ffffffff812f89d2>] sysfs_dir_pos+0x92/0x130
[ 327.421608] [<ffffffff812f8b8d>] sysfs_readdir+0x11d/0x280
[ 327.422562] [<ffffffff8128b070>] ? SyS_ioctl+0xa0/0xa0
[ 327.423441] [<ffffffff8128b070>] ? SyS_ioctl+0xa0/0xa0
[ 327.424314] [<ffffffff8128b3e8>] vfs_readdir+0x78/0xc0
[ 327.425263] [<ffffffff8128b54c>] SyS_getdents+0x8c/0x110
[ 327.426173] [<ffffffff83d919d8>] tracesys+0xe1/0xe6
On Sun, Mar 17, 2013 at 2:33 AM, Sasha Levin <[email protected]> wrote:
>
> I don't think it shows what we want it to show thought:
>
> [ 327.416905] Pid: 10504, comm: trinity-child98 Tainted: G W 3.9.0-rc2-next-20130315-sasha-00046-gecde602-dirty #301
> [ 327.418815] Call Trace:
> [ 327.419255] [<ffffffff812f880e>] release_sysfs_dirent+0x4e/0x120
> [ 327.420595] [<ffffffff812f89d2>] sysfs_dir_pos+0x92/0x130
> [ 327.421608] [<ffffffff812f8b8d>] sysfs_readdir+0x11d/0x280
> [ 327.422562] [<ffffffff8128b070>] ? SyS_ioctl+0xa0/0xa0
> [ 327.423441] [<ffffffff8128b070>] ? SyS_ioctl+0xa0/0xa0
> [ 327.424314] [<ffffffff8128b3e8>] vfs_readdir+0x78/0xc0
> [ 327.425263] [<ffffffff8128b54c>] SyS_getdents+0x8c/0x110
> [ 327.426173] [<ffffffff83d919d8>] tracesys+0xe1/0xe6
>
Sasha, looks there is a race when sys_readdir() is run concurrently
on same directory, and the below patch may fix the race, could you test the
attachment patch to see if the use after free can be fixed?
Thanks,
--
Ming Lei
On 03/16/2013 09:02 PM, Ming Lei wrote:
> On Sun, Mar 17, 2013 at 2:33 AM, Sasha Levin <[email protected]> wrote:
>>
>> I don't think it shows what we want it to show thought:
>>
>> [ 327.416905] Pid: 10504, comm: trinity-child98 Tainted: G W 3.9.0-rc2-next-20130315-sasha-00046-gecde602-dirty #301
>> [ 327.418815] Call Trace:
>> [ 327.419255] [<ffffffff812f880e>] release_sysfs_dirent+0x4e/0x120
>> [ 327.420595] [<ffffffff812f89d2>] sysfs_dir_pos+0x92/0x130
>> [ 327.421608] [<ffffffff812f8b8d>] sysfs_readdir+0x11d/0x280
>> [ 327.422562] [<ffffffff8128b070>] ? SyS_ioctl+0xa0/0xa0
>> [ 327.423441] [<ffffffff8128b070>] ? SyS_ioctl+0xa0/0xa0
>> [ 327.424314] [<ffffffff8128b3e8>] vfs_readdir+0x78/0xc0
>> [ 327.425263] [<ffffffff8128b54c>] SyS_getdents+0x8c/0x110
>> [ 327.426173] [<ffffffff83d919d8>] tracesys+0xe1/0xe6
>>
>
> Sasha, looks there is a race when sys_readdir() is run concurrently
> on same directory, and the below patch may fix the race, could you test the
> attachment patch to see if the use after free can be fixed?
I still see it going on with the patch applied:
[ 521.881968] release_sysfs_dirent sysfs_dirent use after free: altera_jtaguart-bind
[ 521.883202] Pid: 29624, comm: trinity-child51 Tainted: G W 3.9.0-rc2-next-20130315-sasha-00046-gecde602-dirty #302
[ 521.885030] Call Trace:
[ 521.885503] [<ffffffff812f880e>] release_sysfs_dirent+0x4e/0x120
[ 521.886559] [<ffffffff812f89d2>] sysfs_dir_pos+0x92/0x130
[ 521.887514] [<ffffffff812f8bd4>] sysfs_readdir+0x164/0x2c0
[ 521.888403] [<ffffffff8128b170>] ? filldir+0x100/0x100
[ 521.889241] [<ffffffff8128b170>] ? filldir+0x100/0x100
[ 521.890222] [<ffffffff8128b3e8>] vfs_readdir+0x78/0xc0
[ 521.891028] [<ffffffff8117999d>] ? trace_hardirqs_on+0xd/0x10
[ 521.891976] [<ffffffff8128b660>] SyS_getdents64+0x90/0x120
[ 521.892831] [<ffffffff83d91a18>] tracesys+0xe1/0xe6
[ 526.910352] general protection fault: 0000 [#1] PREEMPT SMP DEBUG_PAGEALLOC
[ 526.911625] Dumping ftrace buffer:
[ 526.912158] (ftrace buffer empty)
[ 526.912715] Modules linked in:
[ 526.913213] CPU 3
[ 526.913521] Pid: 374, comm: trinity-child86 Tainted: G W 3.9.0-rc2-next-20130315-sasha-00046-gecde602-dirty #302
[ 526.915342] RIP: 0010:[<ffffffff812f8a10>] [<ffffffff812f8a10>] sysfs_dir_pos+0xd0/0x130
[ 526.916622] RSP: 0018:ffff88008caa9e18 EFLAGS: 00010202
[ 526.917453] RAX: 6b6b6b6b6b6b6b6b RBX: ffff8800b417d128 RCX: ffff8800b417cb70
[ 526.918525] RDX: 000000006b6b6b6b RSI: ffff8800b417c988 RDI: 0000000000000000
[ 526.919579] RBP: ffff88008caa9e48 R08: 2222222222222222 R09: 2222222222222222
[ 526.920058] R10: 2222222222222222 R11: 0000000000000000 R12: 0000000000000000
[ 526.920058] R13: 0000000049619f4a R14: ffff8800b417c988 R15: 0000000000000000
[ 526.920058] FS: 00007fd9e349b700(0000) GS:ffff8800bbe00000(0000) knlGS:0000000000000000
[ 526.920058] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 526.920058] CR2: 0000000100000000 CR3: 0000000084c61000 CR4: 00000000000406e0
[ 526.920058] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 526.920058] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[ 526.920058] Process trinity-child86 (pid: 374, threadinfo ffff88008caa8000, task ffff880082a63000)
[ 526.920058] Stack:
[ 526.920058] ffff8800a4d26088 ffff88008dc7f180 ffff88008dc7f180 0000000000000000
[ 526.920058] ffff8800a4d26088 ffff8800a4d25fa0 ffff88008caa9eb8 ffffffff812f8bd4
[ 526.920058] 2222222222222222 2222222222222222 ffff88008caa9e98 ffffffff8128b170
[ 526.920058] Call Trace:
[ 526.920058] [<ffffffff812f8bd4>] sysfs_readdir+0x164/0x2c0
[ 526.920058] [<ffffffff8128b170>] ? filldir+0x100/0x100
[ 526.920058] [<ffffffff8128b170>] ? filldir+0x100/0x100
[ 526.920058] [<ffffffff8128b3e8>] vfs_readdir+0x78/0xc0
[ 526.920058] [<ffffffff8117999d>] ? trace_hardirqs_on+0xd/0x10
[ 526.920058] [<ffffffff8128b660>] SyS_getdents64+0x90/0x120
[ 526.920058] [<ffffffff83d91a18>] tracesys+0xe1/0xe6
[ 526.920058] Code: 44 00 00 48 85 db 74 6d 4c 39 63 68 75 45 eb 65 0f 1f 00 49 81 fd fe ff ff 7f 7f 59 49 8b 86 88 00 00 00 48
85 c0 74 4d 0f 1f 00 <8b> 50 28 48 8d 58 b8 49 39 d5 7d 0c 48 8b 40 10 eb 0c 66 0f 1f
[ 526.920058] RIP [<ffffffff812f8a10>] sysfs_dir_pos+0xd0/0x130
[ 526.920058] RSP <ffff88008caa9e18>
[ 526.946105] ---[ end trace ec3353999032c934 ]---
On Sun, Mar 17, 2013 at 10:24 PM, Sasha Levin <[email protected]> wrote:
>
> I still see it going on with the patch applied:
Looks the previous patch still has the race problem, so could you just
apply the attachment patch and cancel all previous patches for the
test? If there is still the problem, please post out the log.
BTW, the attachment patch is only for verifying if the current problem
is caused by 'filp->private_data' race, and not for merge.
Thanks,
--
Ming Lei
On 03/17/2013 12:23 PM, Ming Lei wrote:
> On Sun, Mar 17, 2013 at 10:24 PM, Sasha Levin <[email protected]> wrote:
>>
>> I still see it going on with the patch applied:
>
> Looks the previous patch still has the race problem, so could you just
> apply the attachment patch and cancel all previous patches for the
> test? If there is still the problem, please post out the log.
>
> BTW, the attachment patch is only for verifying if the current problem
> is caused by 'filp->private_data' race, and not for merge.
[ 232.822703] sysfs_dir_pos-973 sysfs_dirent use after free: vx855(vx855)-bind, 0-25520352
[ 232.824100] release_sysfs_dirent-285 sysfs_dirent use after free: vx855-bind
[ 232.825297] Pid: 22751, comm: trinity-child99 Tainted: G W 3.9.0-rc2-next-20130318-sasha-00041-g7b66226-dirty #304
[ 232.827141] Call Trace:
[ 232.827566] [<ffffffff812fa0a3>] release_sysfs_dirent+0x53/0x120
[ 232.828545] [<ffffffff812fa26a>] sysfs_dir_pos+0x9a/0x140
[ 232.829498] [<ffffffff812fa41b>] sysfs_readdir+0x10b/0x230
[ 232.830765] [<ffffffff8128c900>] ? filldir+0x100/0x100
[ 232.831644] [<ffffffff8128c900>] ? filldir+0x100/0x100
[ 232.832490] [<ffffffff8128cb78>] vfs_readdir+0x78/0xc0
[ 232.833327] [<ffffffff8117ac7d>] ? trace_hardirqs_on+0xd/0x10
[ 232.834313] [<ffffffff8128cdf0>] SyS_getdents64+0x90/0x120
[ 232.835242] [<ffffffff83d94d98>] tracesys+0xe1/0xe6
[ 233.906761] general protection fault: 0000 [#1] PREEMPT SMP DEBUG_PAGEALLOC
[ 233.907976] Dumping ftrace buffer:
[ 233.908522] (ftrace buffer empty)
[ 233.909186] Modules linked in:
[ 233.909741] CPU 2
[ 233.910037] Pid: 17193, comm: trinity-child57 Tainted: G W 3.9.0-rc2-next-20130318-sasha-00041-g7b66226-dirty #304
[ 233.910037] RIP: 0010:[<ffffffff812fab70>] [<ffffffff812fab70>] sysfs_find_dirent+0xa0/0x120
[ 233.910037] RSP: 0018:ffff880099211bf8 EFLAGS: 00010202
[ 233.910037] RAX: 000000009651d576 RBX: 0000000000000000 RCX: 0000000000000000
[ 233.910037] RDX: 000000009651d576 RSI: 0000000000000000 RDI: 0000000001bd40e1
[ 233.910037] RBP: ffff880099211c28 R08: 0000000000000000 R09: 0000000000000000
[ 233.910037] R10: 2222222222222222 R11: 0000000000000000 R12: 6b6b6b6b6b6b6b6b
[ 233.910037] R13: 0000000001bd40e1 R14: ffff8800b12eb4f8 R15: ffff8800817bfc58
[ 233.910037] FS: 00007f7dd41f8700(0000) GS:ffff8800bbc00000(0000) knlGS:0000000000000000
[ 233.910037] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 233.910037] CR2: 0000000000000008 CR3: 000000009ceb4000 CR4: 00000000000406e0
[ 233.910037] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 233.910037] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[ 233.910037] Process trinity-child57 (pid: 17193, threadinfo ffff880099210000, task ffff88009c1eb000)
[ 233.910037] Stack:
[ 233.910037] fffffffffffffffe ffff8800817bfc20 ffff8800a5d79540 ffff8800b12ea3d0
[ 233.910037] fffffffffffffffe 0000000000000000 ffff880099211c58 ffffffff812fac59
[ 233.910037] ffff8800817bfc20 ffff8800a5d6f530 ffff8800a5d6f530 0000000000000000
[ 233.910037] Call Trace:
[ 233.910037] [<ffffffff812fac59>] sysfs_lookup+0x69/0xf0
[ 233.910037] [<ffffffff81283abe>] lookup_real+0x2e/0x60
[ 233.910037] [<ffffffff81283ea3>] __lookup_hash+0x33/0x40
[ 233.910037] [<ffffffff83d02bcd>] lookup_slow+0x42/0xa8
[ 233.910037] [<ffffffff81285175>] ? getname_flags+0x55/0x1a0
[ 233.910037] [<ffffffff812864b2>] path_lookupat+0xf2/0x770
[ 233.910037] [<ffffffff83d0177c>] ? __slab_alloc.isra.34+0x2ed/0x31f
[ 233.910037] [<ffffffff8117ac38>] ? trace_hardirqs_on_caller+0x168/0x1a0
[ 233.910037] [<ffffffff81286b5f>] filename_lookup+0x2f/0xc0
[ 233.910037] [<ffffffff81285175>] ? getname_flags+0x55/0x1a0
[ 233.910037] [<ffffffff81286c9d>] do_path_lookup+0x2d/0x30
[ 233.910037] [<ffffffff81286f05>] kern_path+0x25/0x50
[ 233.910037] [<ffffffff812851a3>] ? getname_flags+0x83/0x1a0
[ 233.910037] [<ffffffff812b6387>] lookup_bdev+0x27/0x90
[ 233.910037] [<ffffffff812852cd>] ? getname+0xd/0x10
[ 233.910037] [<ffffffff812e2d53>] quotactl_block+0x33/0xf0
[ 233.910037] [<ffffffff812e3793>] SyS_quotactl+0xe3/0x150
[ 233.910037] [<ffffffff83d94d98>] tracesys+0xe1/0xe6
[ 233.910037] Code: 8e 00 00 00 0f 1f 80 00 00 00 00 4c 89 fe 48 89 df 45 31 f6 e8 f2 ee ff ff 4d 85 e4 41 89 c5 74 71 66 2e 0f
1f 84 00 00 00 00 00 <41> 8b 44 24 28 4d 8d 74 24 b8 41 39 c5 74 11 44 89 ea 29 c2 89
[ 233.910037] RIP [<ffffffff812fab70>] sysfs_find_dirent+0xa0/0x120
[ 233.910037] RSP <ffff880099211bf8>
[ 233.973905] ---[ end trace a80e42d248abaa1f ]---
Thanks,
Sasha
Hi Sasha,
On Tue, Mar 19, 2013 at 10:06 AM, Sasha Levin <[email protected]> wrote:
> [ 232.822703] sysfs_dir_pos-973 sysfs_dirent use after free: vx855(vx855)-bind, 0-25520352
Looks filp->f_pos is changed as zero by llseek(), so may leave
filp->private_data
point to one refcount-balanced sysfs_dirent object, which will be put
again afterwards.
Hope we are luck this time, please try the attachment patch.
Thanks,
--
Ming Lei
Hi Sasha,
On Tue, Mar 19, 2013 at 11:40 AM, Ming Lei <[email protected]> wrote:
> Hi Sasha,
>
> On Tue, Mar 19, 2013 at 10:06 AM, Sasha Levin <[email protected]> wrote:
>> [ 232.822703] sysfs_dir_pos-973 sysfs_dirent use after free: vx855(vx855)-bind, 0-25520352
>
> Looks filp->f_pos is changed as zero by llseek(), so may leave
> filp->private_data
> point to one refcount-balanced sysfs_dirent object, which will be put
> again afterwards.
>
> Hope we are luck this time, please try the attachment patch.
Looks the better and simpler way is to hold the i_mutex for llseek.
If you haven't test the v2, please ignore it and just test the attachment
v3 patch.
Thanks,
--
Ming Lei
On 03/19/2013 07:54 AM, Ming Lei wrote:
> Hi Sasha,
>
> On Tue, Mar 19, 2013 at 11:40 AM, Ming Lei <[email protected]> wrote:
>> Hi Sasha,
>>
>> On Tue, Mar 19, 2013 at 10:06 AM, Sasha Levin <[email protected]> wrote:
>>> [ 232.822703] sysfs_dir_pos-973 sysfs_dirent use after free: vx855(vx855)-bind, 0-25520352
>>
>> Looks filp->f_pos is changed as zero by llseek(), so may leave
>> filp->private_data
>> point to one refcount-balanced sysfs_dirent object, which will be put
>> again afterwards.
>>
>> Hope we are luck this time, please try the attachment patch.
>
> Looks the better and simpler way is to hold the i_mutex for llseek.
> If you haven't test the v2, please ignore it and just test the attachment
> v3 patch.
With v3 of the patch:
[ 1275.665758] sysfs_dir_pos-973 sysfs_dirent use after free: tun(tun)-uevent, 2-1472641949
[ 1275.667234] release_sysfs_dirent-285 sysfs_dirent use after free: tun-uevent
[ 1275.668347] Pid: 13795, comm: trinity-child62 Tainted: G W 3.9.0-rc3-next-20130319-sasha-00041-g22d0dce-dirty #305
[ 1275.696032] Call Trace:
[ 1275.696529] [<ffffffff812fa373>] release_sysfs_dirent+0x53/0x120
[ 1275.697593] [<ffffffff812fa53a>] sysfs_dir_pos+0x9a/0x140
[ 1275.698551] [<ffffffff812fa6fd>] sysfs_readdir+0x11d/0x280
[ 1275.699512] [<ffffffff8128ca00>] ? SyS_ioctl+0xa0/0xa0
[ 1275.700586] [<ffffffff8128ca00>] ? SyS_ioctl+0xa0/0xa0
[ 1275.701482] [<ffffffff8128cd78>] vfs_readdir+0x78/0xc0
[ 1275.702333] [<ffffffff8128cedc>] SyS_getdents+0x8c/0x110
[ 1275.703242] [<ffffffff83da13d8>] tracesys+0xe1/0xe6
[ 1275.710567] general protection fault: 0000 [#1] PREEMPT SMP DEBUG_PAGEALLOC
[ 1275.711796] Dumping ftrace buffer:
[ 1275.712423] (ftrace buffer empty)
[ 1275.712993] Modules linked in:
[ 1275.713518] CPU 0
[ 1275.713830] Pid: 13795, comm: trinity-child62 Tainted: G W 3.9.0-rc3-next-20130319-sasha-00041-g22d0dce-dirty #305
[ 1275.717622] RIP: 0010:[<ffffffff819eccf3>] [<ffffffff819eccf3>] rb_next+0x23/0x60
[ 1275.718775] RSP: 0018:ffff880065349e58 EFLAGS: 00010202
[ 1275.719618] RAX: 6b6b6b6b6b6b6b6b RBX: ffff8800af811ab0 RCX: ffff8800af811ab0
[ 1275.720046] RDX: 6b6b6b6b6b6b6b6b RSI: ffff8800afff8f40 RDI: ffff8800af811af8
[ 1275.720046] RBP: ffff880065349e58 R08: 2222222222222222 R09: 2222222222222222
[ 1275.720046] R10: 2222222222222222 R11: 0000000000000000 R12: ffff88009c642100
[ 1275.720046] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000009
[ 1275.720046] FS: 00007faf86d64700(0000) GS:ffff8800bb800000(0000) knlGS:0000000000000000
[ 1275.720046] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 1275.720046] CR2: 0000000001e3b228 CR3: 000000007207e000 CR4: 00000000000406f0
[ 1275.720046] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 1275.720046] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[ 1275.720046] Process trinity-child62 (pid: 13795, threadinfo ffff880065348000, task ffff880065240000)
[ 1275.720046] Stack:
[ 1275.720046] ffff880065349ec8 ffffffff812fa7f9 2222222222222222 222222220000000a
[ 1275.720046] 000000000000c3e5 ffffffff8128ca00 ffff880065349f28 ffff8800afff8f40
[ 1275.720046] ffff8800a31c65d8 ffff88009c642100 ffff880065349f28 ffffffff8128ca00
[ 1275.720046] Call Trace:
[ 1275.720046] [<ffffffff812fa7f9>] sysfs_readdir+0x219/0x280
[ 1275.720046] [<ffffffff8128ca00>] ? SyS_ioctl+0xa0/0xa0
[ 1275.720046] [<ffffffff8128ca00>] ? SyS_ioctl+0xa0/0xa0
[ 1275.720046] [<ffffffff8128cd78>] vfs_readdir+0x78/0xc0
[ 1275.720046] [<ffffffff8128cedc>] SyS_getdents+0x8c/0x110
[ 1275.720046] [<ffffffff83da13d8>] tracesys+0xe1/0xe6
[ 1275.720046] Code: 85 d2 75 f4 5d c3 66 90 55 31 c0 48 8b 17 48 89 e5 48 39 d7 74 4a 48 8b 47 08 48 85 c0 75 0c eb 17 0f 1f 80 00
00 00 00 48 89 d0 <48> 8b 50 10 48 85 d2 75 f4 eb 2a 66 90 48 89 d1 48 83 e1 fc 74
[ 1275.720046] RIP [<ffffffff819eccf3>] rb_next+0x23/0x60
[ 1275.720046] RSP <ffff880065349e58>
Thanks,
Sasha
Hi Sasha,
On Wed, Mar 20, 2013 at 12:28 AM, Sasha Levin <[email protected]> wrote:
> On 03/19/2013 07:54 AM, Ming Lei wrote:
>
> With v3 of the patch:
>
> [ 1275.665758] sysfs_dir_pos-973 sysfs_dirent use after free: tun(tun)-uevent, 2-1472641949
Thanks again for your test.
Looks it is caused by another bug in sysfs_readdir: if filldir() returns
failure(such as small buffer length passed from userspace, very probably
for trinity) in case of 'if (filp->f_pos == 0 or 1)',
filp->private_data still will
point to one refcount-balanced sysfs_dirent object.
V4 adds fix for this situation, please test attachment v4 patch.
Thanks,
--
Ming Lei
On 03/19/2013 09:02 PM, Ming Lei wrote:
> Hi Sasha,
>
> On Wed, Mar 20, 2013 at 12:28 AM, Sasha Levin <[email protected]> wrote:
>> On 03/19/2013 07:54 AM, Ming Lei wrote:
>>
>> With v3 of the patch:
>>
>> [ 1275.665758] sysfs_dir_pos-973 sysfs_dirent use after free: tun(tun)-uevent, 2-1472641949
>
> Thanks again for your test.
>
> Looks it is caused by another bug in sysfs_readdir: if filldir() returns
> failure(such as small buffer length passed from userspace, very probably
> for trinity) in case of 'if (filp->f_pos == 0 or 1)',
> filp->private_data still will
> point to one refcount-balanced sysfs_dirent object.
>
> V4 adds fix for this situation, please test attachment v4 patch.
With this one it didn't happen at all during overnight tests so looks like it did
the job.
Thanks!
On Wed, Mar 20, 2013 at 10:34:40AM -0400, Sasha Levin wrote:
> On 03/19/2013 09:02 PM, Ming Lei wrote:
> > Hi Sasha,
> >
> > On Wed, Mar 20, 2013 at 12:28 AM, Sasha Levin <[email protected]> wrote:
> >> On 03/19/2013 07:54 AM, Ming Lei wrote:
> >>
> >> With v3 of the patch:
> >>
> >> [ 1275.665758] sysfs_dir_pos-973 sysfs_dirent use after free: tun(tun)-uevent, 2-1472641949
> >
> > Thanks again for your test.
> >
> > Looks it is caused by another bug in sysfs_readdir: if filldir() returns
> > failure(such as small buffer length passed from userspace, very probably
> > for trinity) in case of 'if (filp->f_pos == 0 or 1)',
> > filp->private_data still will
> > point to one refcount-balanced sysfs_dirent object.
> >
> > V4 adds fix for this situation, please test attachment v4 patch.
>
> With this one it didn't happen at all during overnight tests so looks like it did
> the job.
Thanks for testing, and thanks Ming, for finding and fixing this.
greg k-h