Skip to contentSkip to conversation

ptrace: gpf in syscall_trace_enter

DISCUSSION Sasha Levin 5 participants 12 messages May 7, 2014 Tracing

lore
Share & tools
lore
#0 lore raw

Hi all,

While fuzzing with trinity inside a KVM tools guest running the latest -next kernel I've stumbled on the following spew:

[ 3029.100936] general protection fault: 0000 [#1] PREEMPT SMP DEBUG_PAGEALLOC
[ 3029.102198] Dumping ftrace buffer:
[ 3029.102928]    (ftrace buffer empty)
[ 3029.103644] Modules linked in:
[ 3029.104732] CPU: 16 PID: 4959 Comm: sleep Tainted: G    B         3.15.0-rc4-next-20140506-sasha-00021-gc164334-dirty #447
[ 3029.108662] task: ffff8805472f8000 ti: ffff880547e3e000 task.ti: ffff880547e3e000
[ 3029.109900] RIP: syscall_trace_enter (include/trace/events/syscalls.h:16 arch/x86/kernel/ptrace.c:1488)
[ 3029.110064] RSP: 0018:ffff880547e3ff28  EFLAGS: 00010286
[ 3029.110064] RAX: 0000000000000000 RBX: ffff880547e3ff58 RCX: 0000000000000001
[ 3029.110064] RDX: 000000000000000c RSI: ffff880547e3ff58 RDI: 6b6b6b6b6b6b6b6b
[ 3029.110064] RBP: ffff880547e3ff48 R08: 0000000000000000 R09: 0000000000000001
[ 3029.110064] R10: 0000000000000000 R11: 0000000000000000 R12: 000000000000000c
[ 3029.110064] R13: 0000000000000000 R14: ffff880039583d50 R15: 0000000000001000
[ 3029.110064] FS:  0000000000000000(0000) GS:ffff8803d6e00000(0000) knlGS:0000000000000000
[ 3029.110064] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[ 3029.110064] CR2: 00007fe08b205130 CR3: 000000061d271000 CR4: 00000000000006a0
[ 3029.110064] DR0: 00000000006df000 DR1: 0000000000000000 DR2: 0000000000000000
[ 3029.110064] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000600
[ 3029.110064] Stack:
[ 3029.110064]  0000000000400040 0000000000000009 00007fffe95ab4b9 0000000000000000
[ 3029.110064]  00007fe08afe64e0 ffffffffaa585625 0000000000001000 0000000000000000
[ 3029.110064]  00007fffe95ab4b9 0000000000000009 00007fe08afe64e0 0000000000400040
[ 3029.110064] Call Trace:
[ 3029.110064] tracesys (arch/x86/kernel/entry_64.S:736)
[ 3029.110064] Code: c6 05 e0 9f f0 05 01 e8 3d 30 14 00 4d 85 f6 75 10 65 ff 0c 25 a0 da 00 00 0f 84 ca 00 00 00 eb 19 49 8b 7e 08 4c 89 e2 48 89 de <41> ff 16 49 83 c6 10 49 83 3e 00 75 e9 eb d7 4c 8b 63 78 0f 1f
[ 3029.110064] RIP syscall_trace_enter (include/trace/events/syscalls.h:16 arch/x86/kernel/ptrace.c:1488)
[ 3029.110064]  RSP <ffff880547e3ff28>

Thanks,
Sasha

#1 lore raw
Quoted 4 lines · Sasha Levin

Hi all,

While fuzzing with trinity inside a KVM tools guest running the latest -next kernel I've stumbled on the following spew:

And another similar trace:

[ 6897.628729] general protection fault: 0000 [#1] PREEMPT SMP DEBUG_PAGEALLOC
[ 6897.629654] Dumping ftrace buffer:
[ 6897.630034]    (ftrace buffer empty)
[ 6897.630034] Modules linked in:
[ 6897.630034] CPU: 24 PID: 23736 Comm: trinity-c148 Tainted: G    B         3.15.0-rc4-next-20140506-sasha-00021-gc164334-dirty #447
[ 6897.630034] task: ffff88002a870000 ti: ffff88000ef04000 task.ti: ffff88000ef04000
[ 6897.630034] RIP: syscall_trace_leave (include/trace/events/syscalls.h:42 arch/x86/kernel/ptrace.c:1517)
[ 6897.630034] RSP: 0000:ffff88000ef05f20  EFLAGS: 00010286
[ 6897.630034] RAX: 0000000000000000 RBX: ffff88000ef05f58 RCX: 0000000000000001
[ 6897.630034] RDX: fffffffffffffff2 RSI: ffff88000ef05f58 RDI: 6b6b6b6b6b6b6b6b
[ 6897.630034] RBP: ffff88000ef05f40 R08: ffff880218c3c498 R09: 0000000100290024
[ 6897.630034] R10: 0000000000000000 R11: 0000000000000000 R12: ffff8806c5d04630
[ 6897.630034] R13: fffffffffffffff2 R14: 00000000000032e0 R15: 00000000000000af
[ 6897.630034] FS:  00007f5541eec700(0000) GS:ffff880587000000(0000) knlGS:0000000000000000
[ 6897.630034] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[ 6897.630034] CR2: 00007fff1ac95d78 CR3: 00000000036a0000 CR4: 00000000000006a0
[ 6897.630034] DR0: 00000000006df000 DR1: 0000000000000000 DR2: 0000000000000000
[ 6897.630034] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 00000000000f0602
[ 6897.630034] Stack:
[ 6897.630034]  00007f5541f0e2e0 00000000006e2000 00007f5541f0e2e0 0000000000000094
[ 6897.630034]  0000000000000011 ffffffffb458577f 000000001008feff 00000000000000af
[ 6897.630034]  00000000000032e0 0000000000000094 00007f5541f0e2e0 0000000000000011
[ 6897.630034] Call Trace:
[ 6897.630034] int_check_syscall_exit_work (arch/x86/kernel/entry_64.S:795)
[ 6897.630034] Code: 05 d1 9d f0 05 01 e8 2d 2e 14 00 4d 85 e4 75 10 65 ff 0c 25 a0 da 00 00 0f 84 85 00 00 00 eb 1c 49 8b 7c 24 08 4c 89 ea 48 89 de <41> ff 14 24 49 83 c4 10 49 83 3c 24 00 75 e6 eb d4 0f 1f 40 00
[ 6897.630034] RIP syscall_trace_leave (include/trace/events/syscalls.h:42 arch/x86/kernel/ptrace.c:1517)
[ 6897.630034]  RSP <ffff88000ef05f20>

Thanks,
Sasha

#2 lore raw
Quoted 8 lines · Sasha Levin
Quoted 4 lines · Sasha Levin

Hi all,

While fuzzing with trinity inside a KVM tools guest running the latest -next kernel I've stumbled on the following spew:

And another similar trace:

Again, this looks like __DO_TRACE() trying to call it_func_ptr->func().

Quoted 32 lines
[ 6897.628729] general protection fault: 0000 [#1] PREEMPT SMP DEBUG_PAGEALLOC
[ 6897.629654] Dumping ftrace buffer:
[ 6897.630034]    (ftrace buffer empty)
[ 6897.630034] Modules linked in:
[ 6897.630034] CPU: 24 PID: 23736 Comm: trinity-c148 Tainted: G    B         3.15.0-rc4-next-20140506-sasha-00021-gc164334-dirty #447
[ 6897.630034] task: ffff88002a870000 ti: ffff88000ef04000 task.ti: ffff88000ef04000
[ 6897.630034] RIP: syscall_trace_leave (include/trace/events/syscalls.h:42 arch/x86/kernel/ptrace.c:1517)
[ 6897.630034] RSP: 0000:ffff88000ef05f20  EFLAGS: 00010286
[ 6897.630034] RAX: 0000000000000000 RBX: ffff88000ef05f58 RCX: 0000000000000001
[ 6897.630034] RDX: fffffffffffffff2 RSI: ffff88000ef05f58 RDI: 6b6b6b6b6b6b6b6b
[ 6897.630034] RBP: ffff88000ef05f40 R08: ffff880218c3c498 R09: 0000000100290024
[ 6897.630034] R10: 0000000000000000 R11: 0000000000000000 R12: ffff8806c5d04630
[ 6897.630034] R13: fffffffffffffff2 R14: 00000000000032e0 R15: 00000000000000af
[ 6897.630034] FS:  00007f5541eec700(0000) GS:ffff880587000000(0000) knlGS:0000000000000000
[ 6897.630034] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[ 6897.630034] CR2: 00007fff1ac95d78 CR3: 00000000036a0000 CR4: 00000000000006a0
[ 6897.630034] DR0: 00000000006df000 DR1: 0000000000000000 DR2: 0000000000000000
[ 6897.630034] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 00000000000f0602
[ 6897.630034] Stack:
[ 6897.630034]  00007f5541f0e2e0 00000000006e2000 00007f5541f0e2e0 0000000000000094
[ 6897.630034]  0000000000000011 ffffffffb458577f 000000001008feff 00000000000000af
[ 6897.630034]  00000000000032e0 0000000000000094 00007f5541f0e2e0 0000000000000011
[ 6897.630034] Call Trace:
[ 6897.630034] int_check_syscall_exit_work (arch/x86/kernel/entry_64.S:795)
[ 6897.630034] Code: 05 d1 9d f0 05 01 e8 2d 2e 14 00 4d 85 e4 75 10 65 ff 0c 25 a0 da 00 00 0f 84 85 00 00 00 eb 1c 49 8b 7c 24 08 4c 89 ea 48 89 de <41> ff 14 24 49 83 c4 10 49 83 3c 24 00 75 e6 eb d4 0f 1f 40 00
[ 6897.630034] RIP syscall_trace_leave (include/trace/events/syscalls.h:42 arch/x86/kernel/ptrace.c:1517)
[ 6897.630034]  RSP <ffff88000ef05f20>

Thanks,
Sasha

maintainer
#3 lore raw
Quoted 11 lines · On Wed, 7 May 2014 16:04:22 +0200 Oleg Nesterov <[email protected]> wrote:
Quoted 8 lines · Sasha Levin
Quoted 4 lines · Sasha Levin

Hi all,

While fuzzing with trinity inside a KVM tools guest running the latest -next kernel I've stumbled on the following spew:

And another similar trace:

Again, this looks like __DO_TRACE() trying to call it_func_ptr->func().

Really? Can I see an objdump of the location of the crash. Preferably the entire function.

Thanks!

-- Steve

Quoted 33 lines
Quoted 33 lines
[ 6897.628729] general protection fault: 0000 [#1] PREEMPT SMP DEBUG_PAGEALLOC
[ 6897.629654] Dumping ftrace buffer:
[ 6897.630034]    (ftrace buffer empty)
[ 6897.630034] Modules linked in:
[ 6897.630034] CPU: 24 PID: 23736 Comm: trinity-c148 Tainted: G    B         3.15.0-rc4-next-20140506-sasha-00021-gc164334-dirty #447
[ 6897.630034] task: ffff88002a870000 ti: ffff88000ef04000 task.ti: ffff88000ef04000
[ 6897.630034] RIP: syscall_trace_leave (include/trace/events/syscalls.h:42 arch/x86/kernel/ptrace.c:1517)
[ 6897.630034] RSP: 0000:ffff88000ef05f20  EFLAGS: 00010286
[ 6897.630034] RAX: 0000000000000000 RBX: ffff88000ef05f58 RCX: 0000000000000001
[ 6897.630034] RDX: fffffffffffffff2 RSI: ffff88000ef05f58 RDI: 6b6b6b6b6b6b6b6b
[ 6897.630034] RBP: ffff88000ef05f40 R08: ffff880218c3c498 R09: 0000000100290024
[ 6897.630034] R10: 0000000000000000 R11: 0000000000000000 R12: ffff8806c5d04630
[ 6897.630034] R13: fffffffffffffff2 R14: 00000000000032e0 R15: 00000000000000af
[ 6897.630034] FS:  00007f5541eec700(0000) GS:ffff880587000000(0000) knlGS:0000000000000000
[ 6897.630034] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[ 6897.630034] CR2: 00007fff1ac95d78 CR3: 00000000036a0000 CR4: 00000000000006a0
[ 6897.630034] DR0: 00000000006df000 DR1: 0000000000000000 DR2: 0000000000000000
[ 6897.630034] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 00000000000f0602
[ 6897.630034] Stack:
[ 6897.630034]  00007f5541f0e2e0 00000000006e2000 00007f5541f0e2e0 0000000000000094
[ 6897.630034]  0000000000000011 ffffffffb458577f 000000001008feff 00000000000000af
[ 6897.630034]  00000000000032e0 0000000000000094 00007f5541f0e2e0 0000000000000011
[ 6897.630034] Call Trace:
[ 6897.630034] int_check_syscall_exit_work (arch/x86/kernel/entry_64.S:795)
[ 6897.630034] Code: 05 d1 9d f0 05 01 e8 2d 2e 14 00 4d 85 e4 75 10 65 ff 0c 25 a0 da 00 00 0f 84 85 00 00 00 eb 1c 49 8b 7c 24 08 4c 89 ea 48 89 de <41> ff 14 24 49 83 c4 10 49 83 3c 24 00 75 e6 eb d4 0f 1f 40 00
[ 6897.630034] RIP syscall_trace_leave (include/trace/events/syscalls.h:42 arch/x86/kernel/ptrace.c:1517)
[ 6897.630034]  RSP <ffff88000ef05f20>

Thanks,
Sasha

#4 lore raw
Quoted 11 lines · Steven Rostedt
Quoted 8 lines · On Wed, 7 May 2014 16:04:22 +0200 Oleg Nesterov <[email protected]> wrote:
Quoted 7 lines · Sasha Levin
Quoted 4 lines · Sasha Levin

Hi all,

While fuzzing with trinity inside a KVM tools guest running the latest -next kernel I've stumbled on the following spew:

Quoted 6 lines
Quoted 3 lines
Quoted 1 line

And another similar trace:

Again, this looks like __DO_TRACE() trying to call it_func_ptr->func().

Really? Can I see an objdump of the location of the crash. Preferably the entire function.

0000000000002740 <syscall_trace_leave>:

    2740:	e8 00 00 00 00       	callq  2745 <syscall_trace_leave+0x5>
			2741: R_X86_64_PC32	__fentry__-0x4
    2745:	55                   	push   %rbp
    2746:	48 89 e5             	mov    %rsp,%rbp
    2749:	48 83 ec 20          	sub    $0x20,%rsp
    274d:	48 89 5d e8          	mov    %rbx,-0x18(%rbp)
    2751:	48 89 fb             	mov    %rdi,%rbx
    2754:	4c 89 65 f0          	mov    %r12,-0x10(%rbp)
    2758:	4c 89 6d f8          	mov    %r13,-0x8(%rbp)
    275c:	0f 1f 44 00 00       	nopl   0x0(%rax,%rax,1)
    2761:	65 48 8b 04 25 00 00 	mov    %gs:0x0,%rax
    2768:	00 00
			2766: R_X86_64_32S	current_task
    276a:	48 83 b8 b8 0b 00 00 	cmpq   $0x0,0xbb8(%rax)
    2771:	00
    2772:	74 1c                	je     2790 <syscall_trace_leave+0x50>
    2774:	48 8b 73 50          	mov    0x50(%rbx),%rsi
    2778:	31 ff                	xor    %edi,%edi
    277a:	48 81 fe 00 f0 ff ff 	cmp    $0xfffffffffffff000,%rsi
    2781:	40 0f 96 c7          	setbe  %dil
    2785:	e8 00 00 00 00       	callq  278a <syscall_trace_leave+0x4a>
			2786: R_X86_64_PC32	__audit_syscall_exit-0x4
    278a:	66 0f 1f 44 00 00    	nopw   0x0(%rax,%rax,1)
    2790:	65 48 8b 04 25 00 00 	mov    %gs:0x0,%rax
    2797:	00 00
			2795: R_X86_64_32S	kernel_stack
    2799:	48 8b 80 38 e0 ff ff 	mov    -0x1fc8(%rax),%rax
    27a0:	a9 00 00 00 10       	test   $0x10000000,%eax
    27a5:	74 71                	je     2818 <syscall_trace_leave+0xd8>
    27a7:	4c 8b 6b 50          	mov    0x50(%rbx),%r13
    27ab:	0f 1f 44 00 00       	nopl   0x0(%rax,%rax,1)
    27b0:	eb 62                	jmp    2814 <syscall_trace_leave+0xd4>
    27b2:	80 3d 00 00 00 00 00 	cmpb   $0x0,0x0(%rip)        # 27b9 <syscall_trace_leave+0x79>
			27b4: R_X86_64_PC32	.data.unlikely-0x4
    27b9:	75 28                	jne    27e3 <syscall_trace_leave+0xa3>
    27bb:	e8 00 00 00 00       	callq  27c0 <syscall_trace_leave+0x80>
			27bc: R_X86_64_PC32	.text.unlikely-0x4
    27c0:	85 c0                	test   %eax,%eax
    27c2:	75 1f                	jne    27e3 <syscall_trace_leave+0xa3>
    27c4:	48 c7 c2 00 00 00 00 	mov    $0x0,%rdx
			27c7: R_X86_64_32S	.rodata.str1.8+0x60
    27cb:	be 3e 00 00 00       	mov    $0x3e,%esi
    27d0:	48 c7 c7 00 00 00 00 	mov    $0x0,%rdi
			27d3: R_X86_64_32S	.rodata.str1.8+0x90
    27d7:	c6 05 00 00 00 00 01 	movb   $0x1,0x0(%rip)        # 27de <syscall_trace_leave+0x9e>
			27d9: R_X86_64_PC32	.data.unlikely-0x4
    27de:	e8 00 00 00 00       	callq  27e3 <syscall_trace_leave+0xa3>
			27df: R_X86_64_PC32	lockdep_rcu_suspicious-0x4
    27e3:	4d 85 e4             	test   %r12,%r12
    27e6:	75 10                	jne    27f8 <syscall_trace_leave+0xb8>
    27e8:	65 ff 0c 25 00 00 00 	decl   %gs:0x0
    27ef:	00
			27ec: R_X86_64_32S	__preempt_count
    27f0:	0f 84 85 00 00 00    	je     287b <syscall_trace_leave+0x13b>
    27f6:	eb 1c                	jmp    2814 <syscall_trace_leave+0xd4>
    27f8:	49 8b 7c 24 08       	mov    0x8(%r12),%rdi
    27fd:	4c 89 ea             	mov    %r13,%rdx
    2800:	48 89 de             	mov    %rbx,%rsi
    2803:	41 ff 14 24          	callq  *(%r12)
    2807:	49 83 c4 10          	add    $0x10,%r12
    280b:	49 83 3c 24 00       	cmpq   $0x0,(%r12)
    2810:	75 e6                	jne    27f8 <syscall_trace_leave+0xb8>
    2812:	eb d4                	jmp    27e8 <syscall_trace_leave+0xa8>
    2814:	0f 1f 40 00          	nopl   0x0(%rax)
    2818:	65 48 8b 04 25 00 00 	mov    %gs:0x0,%rax
    281f:	00 00
			281d: R_X86_64_32S	kernel_stack
    2821:	48 8b 90 38 e0 ff ff 	mov    -0x1fc8(%rax),%rdx
    2828:	83 e2 10             	and    $0x10,%edx
    282b:	74 5b                	je     2888 <syscall_trace_leave+0x148>
    282d:	48 8b 80 38 e0 ff ff 	mov    -0x1fc8(%rax),%rax
    2834:	a8 40                	test   $0x40,%al
    2836:	75 50                	jne    2888 <syscall_trace_leave+0x148>
    2838:	be 01 00 00 00       	mov    $0x1,%esi
    283d:	0f 1f 00             	nopl   (%rax)
    2840:	48 89 df             	mov    %rbx,%rdi
    2843:	e8 f8 fa ff ff       	callq  2340 <tracehook_report_syscall_exit>
    2848:	0f 1f 44 00 00       	nopl   0x0(%rax,%rax,1)
    284d:	eb 56                	jmp    28a5 <syscall_trace_leave+0x165>
    284f:	90                   	nop
    2850:	e8 00 00 00 00       	callq  2855 <syscall_trace_leave+0x115>
			2851: R_X86_64_PC32	context_tracking_user_exit-0x4
    2855:	e9 07 ff ff ff       	jmpq   2761 <syscall_trace_leave+0x21>
    285a:	65 ff 04 25 00 00 00 	incl   %gs:0x0
    2861:	00
			285e: R_X86_64_32S	__preempt_count
    2862:	4c 8b 25 00 00 00 00 	mov    0x0(%rip),%r12        # 2869 <syscall_trace_leave+0x129>
			2865: R_X86_64_PC32	__tracepoint_sys_exit+0x2c
    2869:	e8 00 00 00 00       	callq  286e <syscall_trace_leave+0x12e>
			286a: R_X86_64_PC32	debug_lockdep_rcu_enabled-0x4
    286e:	85 c0                	test   %eax,%eax
    2870:	0f 85 3c ff ff ff    	jne    27b2 <syscall_trace_leave+0x72>
    2876:	e9 68 ff ff ff       	jmpq   27e3 <syscall_trace_leave+0xa3>
    287b:	e8 00 00 00 00       	callq  2880 <syscall_trace_leave+0x140>
			287c: R_X86_64_PC32	___preempt_schedule_context-0x4
    2880:	eb 96                	jmp    2818 <syscall_trace_leave+0xd8>
    2882:	66 0f 1f 44 00 00    	nopw   0x0(%rax,%rax,1)
    2888:	65 48 8b 04 25 00 00 	mov    %gs:0x0,%rax
    288f:	00 00
			288d: R_X86_64_32S	kernel_stack
    2891:	48 8b 80 38 e0 ff ff 	mov    -0x1fc8(%rax),%rax
    2898:	31 f6                	xor    %esi,%esi
    289a:	a8 01                	test   $0x1,%al
    289c:	75 a2                	jne    2840 <syscall_trace_leave+0x100>
    289e:	eb a8                	jmp    2848 <syscall_trace_leave+0x108>
    28a0:	e8 00 00 00 00       	callq  28a5 <syscall_trace_leave+0x165>
			28a1: R_X86_64_PC32	context_tracking_user_enter-0x4
    28a5:	48 8b 5d e8          	mov    -0x18(%rbp),%rbx
    28a9:	4c 8b 65 f0          	mov    -0x10(%rbp),%r12
    28ad:	4c 8b 6d f8          	mov    -0x8(%rbp),%r13
    28b1:	c9                   	leaveq
    28b2:	c3                   	retq

Thanks,
Sasha

maintainer
#5 lore raw

[ adding Mathieu as well, as this is tracepoint code ]

Quoted 43 lines · On Wed, 07 May 2014 11:23:36 -0400 Sasha Levin <[email protected]> wrote:
Quoted 11 lines · Steven Rostedt
Quoted 8 lines · On Wed, 7 May 2014 16:04:22 +0200 Oleg Nesterov <[email protected]> wrote:
Quoted 7 lines · Sasha Levin
Quoted 4 lines · Sasha Levin

Hi all,

While fuzzing with trinity inside a KVM tools guest running the latest -next kernel I've stumbled on the following spew:

Quoted 6 lines
Quoted 3 lines
Quoted 1 line

And another similar trace:

Again, this looks like __DO_TRACE() trying to call it_func_ptr->func().

Really? Can I see an objdump of the location of the crash. Preferably the entire function.

0000000000002740 <syscall_trace_leave>:

    2740:	e8 00 00 00 00       	callq  2745 <syscall_trace_leave+0x5>
			2741: R_X86_64_PC32	__fentry__-0x4
    2745:	55                   	push   %rbp
    2746:	48 89 e5             	mov    %rsp,%rbp
    2749:	48 83 ec 20          	sub    $0x20,%rsp
    274d:	48 89 5d e8          	mov    %rbx,-0x18(%rbp)
    2751:	48 89 fb             	mov    %rdi,%rbx
    2754:	4c 89 65 f0          	mov    %r12,-0x10(%rbp)
    2758:	4c 89 6d f8          	mov    %r13,-0x8(%rbp)
    275c:	0f 1f 44 00 00       	nopl   0x0(%rax,%rax,1)
    2761:	65 48 8b 04 25 00 00 	mov    %gs:0x0,%rax
    2768:	00 00
			2766: R_X86_64_32S	current_task
    276a:	48 83 b8 b8 0b 00 00 	cmpq   $0x0,0xbb8(%rax)
    2771:	00
    2772:	74 1c                	je     2790 <syscall_trace_leave+0x50>
    2774:	48 8b 73 50          	mov    0x50(%rbx),%rsi
    2778:	31 ff                	xor    %edi,%edi
    277a:	48 81 fe 00 f0 ff ff 	cmp    $0xfffffffffffff000,%rsi
    2781:	40 0f 96 c7          	setbe  %dil
    2785:	e8 00 00 00 00       	callq  278a <syscall_trace_leave+0x4a>
			2786: R_X86_64_PC32	__audit_syscall_exit-0x4
    278a:	66 0f 1f 44 00 00    	nopw   0x0(%rax,%rax,1)
Quoted 8 lines
    2790:	65 48 8b 04 25 00 00 	mov    %gs:0x0,%rax
    2797:	00 00
			2795: R_X86_64_32S	kernel_stack
    2799:	48 8b 80 38 e0 ff ff 	mov    -0x1fc8(%rax),%rax
    27a0:	a9 00 00 00 10       	test   $0x10000000,%eax
    27a5:	74 71                	je     2818 <syscall_trace_leave+0xd8>
    27a7:	4c 8b 6b 50          	mov    0x50(%rbx),%r13
    27ab:	0f 1f 44 00 00       	nopl   0x0(%rax,%rax,1)

Here's the static_key branch

Quoted 6 lines
    27b0:	eb 62                	jmp    2814 <syscall_trace_leave+0xd4>
    27b2:	80 3d 00 00 00 00 00 	cmpb   $0x0,0x0(%rip)        # 27b9 <syscall_trace_leave+0x79>
			27b4: R_X86_64_PC32	.data.unlikely-0x4
    27b9:	75 28                	jne    27e3 <syscall_trace_leave+0xa3>
    27bb:	e8 00 00 00 00       	callq  27c0 <syscall_trace_leave+0x80>
			27bc: R_X86_64_PC32	.text.unlikely-0x4

Interesting that we have a "callq" to the next instruction.

Quoted 11 lines
    27c0:	85 c0                	test   %eax,%eax
    27c2:	75 1f                	jne    27e3 <syscall_trace_leave+0xa3>
    27c4:	48 c7 c2 00 00 00 00 	mov    $0x0,%rdx
			27c7: R_X86_64_32S	.rodata.str1.8+0x60
    27cb:	be 3e 00 00 00       	mov    $0x3e,%esi
    27d0:	48 c7 c7 00 00 00 00 	mov    $0x0,%rdi
			27d3: R_X86_64_32S	.rodata.str1.8+0x90
    27d7:	c6 05 00 00 00 00 01 	movb   $0x1,0x0(%rip)        # 27de <syscall_trace_leave+0x9e>
			27d9: R_X86_64_PC32	.data.unlikely-0x4
    27de:	e8 00 00 00 00       	callq  27e3 <syscall_trace_leave+0xa3>
			27df: R_X86_64_PC32	lockdep_rcu_suspicious-0x4

OK, rcu debugging is on. Not really a factor, just making notes.

Quoted 1 line
    27e3:	4d 85 e4             	test   %r12,%r12

%r12 is the it_func_ptr

Quoted 10 lines
    27e6:	75 10                	jne    27f8 <syscall_trace_leave+0xb8>
    27e8:	65 ff 0c 25 00 00 00 	decl   %gs:0x0
    27ef:	00
			27ec: R_X86_64_32S	__preempt_count
    27f0:	0f 84 85 00 00 00    	je     287b <syscall_trace_leave+0x13b>
    27f6:	eb 1c                	jmp    2814 <syscall_trace_leave+0xd4>
    27f8:	49 8b 7c 24 08       	mov    0x8(%r12),%rdi
    27fd:	4c 89 ea             	mov    %r13,%rdx
    2800:	48 89 de             	mov    %rbx,%rsi
    2803:	41 ff 14 24          	callq  *(%r12)

As I stated, I didn't need the offset that I asked for, but the machine code had the information I needed:

24 08 4c 89 ea 48 89 de <41> ff 14 24 49 83 c4 10 49

Which matches 2803.

Quoted 1 line

From your dump:

R10: 0000000000000000 R11: 0000000000000000 R12: 000000000000000c

Yeah, that's a bad pointer.

OK, for some reason, funcs got 0xc?

-- Steve

Quoted 57 lines
    2807:	49 83 c4 10          	add    $0x10,%r12
    280b:	49 83 3c 24 00       	cmpq   $0x0,(%r12)
    2810:	75 e6                	jne    27f8 <syscall_trace_leave+0xb8>
    2812:	eb d4                	jmp    27e8 <syscall_trace_leave+0xa8>
    2814:	0f 1f 40 00          	nopl   0x0(%rax)
    2818:	65 48 8b 04 25 00 00 	mov    %gs:0x0,%rax
    281f:	00 00
			281d: R_X86_64_32S	kernel_stack
    2821:	48 8b 90 38 e0 ff ff 	mov    -0x1fc8(%rax),%rdx
    2828:	83 e2 10             	and    $0x10,%edx
    282b:	74 5b                	je     2888 <syscall_trace_leave+0x148>
    282d:	48 8b 80 38 e0 ff ff 	mov    -0x1fc8(%rax),%rax
    2834:	a8 40                	test   $0x40,%al
    2836:	75 50                	jne    2888 <syscall_trace_leave+0x148>
    2838:	be 01 00 00 00       	mov    $0x1,%esi
    283d:	0f 1f 00             	nopl   (%rax)
    2840:	48 89 df             	mov    %rbx,%rdi
    2843:	e8 f8 fa ff ff       	callq  2340 <tracehook_report_syscall_exit>
    2848:	0f 1f 44 00 00       	nopl   0x0(%rax,%rax,1)
    284d:	eb 56                	jmp    28a5 <syscall_trace_leave+0x165>
    284f:	90                   	nop
    2850:	e8 00 00 00 00       	callq  2855 <syscall_trace_leave+0x115>
			2851: R_X86_64_PC32	context_tracking_user_exit-0x4
    2855:	e9 07 ff ff ff       	jmpq   2761 <syscall_trace_leave+0x21>
    285a:	65 ff 04 25 00 00 00 	incl   %gs:0x0
    2861:	00
			285e: R_X86_64_32S	__preempt_count
    2862:	4c 8b 25 00 00 00 00 	mov    0x0(%rip),%r12        # 2869 <syscall_trace_leave+0x129>
			2865: R_X86_64_PC32	__tracepoint_sys_exit+0x2c
    2869:	e8 00 00 00 00       	callq  286e <syscall_trace_leave+0x12e>
			286a: R_X86_64_PC32	debug_lockdep_rcu_enabled-0x4
    286e:	85 c0                	test   %eax,%eax
    2870:	0f 85 3c ff ff ff    	jne    27b2 <syscall_trace_leave+0x72>
    2876:	e9 68 ff ff ff       	jmpq   27e3 <syscall_trace_leave+0xa3>
    287b:	e8 00 00 00 00       	callq  2880 <syscall_trace_leave+0x140>
			287c: R_X86_64_PC32	___preempt_schedule_context-0x4
    2880:	eb 96                	jmp    2818 <syscall_trace_leave+0xd8>
    2882:	66 0f 1f 44 00 00    	nopw   0x0(%rax,%rax,1)
    2888:	65 48 8b 04 25 00 00 	mov    %gs:0x0,%rax
    288f:	00 00
			288d: R_X86_64_32S	kernel_stack
    2891:	48 8b 80 38 e0 ff ff 	mov    -0x1fc8(%rax),%rax
    2898:	31 f6                	xor    %esi,%esi
    289a:	a8 01                	test   $0x1,%al
    289c:	75 a2                	jne    2840 <syscall_trace_leave+0x100>
    289e:	eb a8                	jmp    2848 <syscall_trace_leave+0x108>
    28a0:	e8 00 00 00 00       	callq  28a5 <syscall_trace_leave+0x165>
			28a1: R_X86_64_PC32	context_tracking_user_enter-0x4
    28a5:	48 8b 5d e8          	mov    -0x18(%rbp),%rbx
    28a9:	4c 8b 65 f0          	mov    -0x10(%rbp),%r12
    28ad:	4c 8b 6d f8          	mov    -0x8(%rbp),%r13
    28b1:	c9                   	leaveq
    28b2:	c3                   	retq

Thanks,
Sasha

#6 lore raw
Quoted 59 lines · Steven Rostedt

[ adding Mathieu as well, as this is tracepoint code ]

Quoted 43 lines · On Wed, 07 May 2014 11:23:36 -0400 Sasha Levin <[email protected]> wrote:
Quoted 11 lines · Steven Rostedt
Quoted 8 lines · On Wed, 7 May 2014 16:04:22 +0200 Oleg Nesterov <[email protected]> wrote:
Quoted 7 lines · Sasha Levin
Quoted 4 lines · Sasha Levin

Hi all,

While fuzzing with trinity inside a KVM tools guest running the latest -next kernel I've stumbled on the following spew:

Quoted 6 lines
Quoted 3 lines
Quoted 1 line

And another similar trace:

Again, this looks like __DO_TRACE() trying to call it_func_ptr->func().

Really? Can I see an objdump of the location of the crash. Preferably the entire function.

0000000000002740 <syscall_trace_leave>:

    2740:	e8 00 00 00 00       	callq  2745 <syscall_trace_leave+0x5>
			2741: R_X86_64_PC32	__fentry__-0x4
    2745:	55                   	push   %rbp
    2746:	48 89 e5             	mov    %rsp,%rbp
    2749:	48 83 ec 20          	sub    $0x20,%rsp
    274d:	48 89 5d e8          	mov    %rbx,-0x18(%rbp)
    2751:	48 89 fb             	mov    %rdi,%rbx
    2754:	4c 89 65 f0          	mov    %r12,-0x10(%rbp)
    2758:	4c 89 6d f8          	mov    %r13,-0x8(%rbp)
    275c:	0f 1f 44 00 00       	nopl   0x0(%rax,%rax,1)
    2761:	65 48 8b 04 25 00 00 	mov    %gs:0x0,%rax
    2768:	00 00
			2766: R_X86_64_32S	current_task
    276a:	48 83 b8 b8 0b 00 00 	cmpq   $0x0,0xbb8(%rax)
    2771:	00
    2772:	74 1c                	je     2790 <syscall_trace_leave+0x50>
    2774:	48 8b 73 50          	mov    0x50(%rbx),%rsi
    2778:	31 ff                	xor    %edi,%edi
    277a:	48 81 fe 00 f0 ff ff 	cmp    $0xfffffffffffff000,%rsi
    2781:	40 0f 96 c7          	setbe  %dil
    2785:	e8 00 00 00 00       	callq  278a <syscall_trace_leave+0x4a>
			2786: R_X86_64_PC32	__audit_syscall_exit-0x4
    278a:	66 0f 1f 44 00 00    	nopw   0x0(%rax,%rax,1)
Quoted 8 lines
    2790:	65 48 8b 04 25 00 00 	mov    %gs:0x0,%rax
    2797:	00 00
			2795: R_X86_64_32S	kernel_stack
    2799:	48 8b 80 38 e0 ff ff 	mov    -0x1fc8(%rax),%rax
    27a0:	a9 00 00 00 10       	test   $0x10000000,%eax
    27a5:	74 71                	je     2818 <syscall_trace_leave+0xd8>
    27a7:	4c 8b 6b 50          	mov    0x50(%rbx),%r13
    27ab:	0f 1f 44 00 00       	nopl   0x0(%rax,%rax,1)

Here's the static_key branch

Quoted 8 lines
Quoted 6 lines
    27b0:	eb 62                	jmp    2814 <syscall_trace_leave+0xd4>
    27b2:	80 3d 00 00 00 00 00 	cmpb   $0x0,0x0(%rip)        # 27b9 <syscall_trace_leave+0x79>
			27b4: R_X86_64_PC32	.data.unlikely-0x4
    27b9:	75 28                	jne    27e3 <syscall_trace_leave+0xa3>
    27bb:	e8 00 00 00 00       	callq  27c0 <syscall_trace_leave+0x80>
			27bc: R_X86_64_PC32	.text.unlikely-0x4

Interesting that we have a "callq" to the next instruction.

I think this is just unrelocated output, presumably from objdump -dr something.o. objdump -d vmlinux will give better output.

--Andy, who got confused by exactly the same thing while debugging the vdso

#7 lore raw
In reply to Steven Rostedt

----- Original Message -----

Quoted 115 lines

From: "Steven Rostedt" <[email protected]>
To: "Sasha Levin" <[email protected]>
Cc: "Oleg Nesterov" <[email protected]>, [email protected], "LKML" <[email protected]>, "Dave Jones" <[email protected]>, "Mathieu Desnoyers" <[email protected]>
Sent: Wednesday, May 7, 2014 12:06:27 PM
Subject: Re: ptrace: gpf in syscall_trace_enter

[ adding Mathieu as well, as this is tracepoint code ]

Quoted 44 lines · On Wed, 07 May 2014 11:23:36 -0400 Sasha Levin <[email protected]> wrote:
Quoted 12 lines · Steven Rostedt
Quoted 9 lines · On Wed, 7 May 2014 16:04:22 +0200 Oleg Nesterov <[email protected]> wrote:
Quoted 8 lines · Sasha Levin
Quoted 5 lines · Sasha Levin

Hi all,

While fuzzing with trinity inside a KVM tools guest running the latest -next
kernel I've stumbled on the following spew:

Quoted 6 lines
Quoted 3 lines
Quoted 1 line

And another similar trace:

Again, this looks like __DO_TRACE() trying to call it_func_ptr->func().

Really? Can I see an objdump of the location of the crash. Preferably the entire function.

0000000000002740 <syscall_trace_leave>:

    2740:	e8 00 00 00 00       	callq  2745 <syscall_trace_leave+0x5>
			2741: R_X86_64_PC32	__fentry__-0x4
    2745:	55                   	push   %rbp
    2746:	48 89 e5             	mov    %rsp,%rbp
    2749:	48 83 ec 20          	sub    $0x20,%rsp
    274d:	48 89 5d e8          	mov    %rbx,-0x18(%rbp)
    2751:	48 89 fb             	mov    %rdi,%rbx
    2754:	4c 89 65 f0          	mov    %r12,-0x10(%rbp)
    2758:	4c 89 6d f8          	mov    %r13,-0x8(%rbp)
    275c:	0f 1f 44 00 00       	nopl   0x0(%rax,%rax,1)
    2761:	65 48 8b 04 25 00 00 	mov    %gs:0x0,%rax
    2768:	00 00
			2766: R_X86_64_32S	current_task
    276a:	48 83 b8 b8 0b 00 00 	cmpq   $0x0,0xbb8(%rax)
    2771:	00
    2772:	74 1c                	je     2790 <syscall_trace_leave+0x50>
    2774:	48 8b 73 50          	mov    0x50(%rbx),%rsi
    2778:	31 ff                	xor    %edi,%edi
    277a:	48 81 fe 00 f0 ff ff 	cmp    $0xfffffffffffff000,%rsi
    2781:	40 0f 96 c7          	setbe  %dil
    2785:	e8 00 00 00 00       	callq  278a <syscall_trace_leave+0x4a>
			2786: R_X86_64_PC32	__audit_syscall_exit-0x4
    278a:	66 0f 1f 44 00 00    	nopw   0x0(%rax,%rax,1)
Quoted 8 lines
    2790:	65 48 8b 04 25 00 00 	mov    %gs:0x0,%rax
    2797:	00 00
			2795: R_X86_64_32S	kernel_stack
    2799:	48 8b 80 38 e0 ff ff 	mov    -0x1fc8(%rax),%rax
    27a0:	a9 00 00 00 10       	test   $0x10000000,%eax
    27a5:	74 71                	je     2818 <syscall_trace_leave+0xd8>
    27a7:	4c 8b 6b 50          	mov    0x50(%rbx),%r13
    27ab:	0f 1f 44 00 00       	nopl   0x0(%rax,%rax,1)

Here's the static_key branch

Quoted 7 lines
    27b0:	eb 62                	jmp    2814 <syscall_trace_leave+0xd4>
    27b2:	80 3d 00 00 00 00 00 	cmpb   $0x0,0x0(%rip)        # 27b9
    <syscall_trace_leave+0x79>
			27b4: R_X86_64_PC32	.data.unlikely-0x4
    27b9:	75 28                	jne    27e3 <syscall_trace_leave+0xa3>
    27bb:	e8 00 00 00 00       	callq  27c0 <syscall_trace_leave+0x80>
			27bc: R_X86_64_PC32	.text.unlikely-0x4

Interesting that we have a "callq" to the next instruction.

Quoted 4 lines
    27c0:	85 c0                	test   %eax,%eax
    27c2:	75 1f                	jne    27e3 <syscall_trace_leave+0xa3>
    27c4:	48 c7 c2 00 00 00 00 	mov    $0x0,%rdx
			27c7: R_X86_64_32S	.rodata.str1.8+0x60
Quoted 8 lines
    27cb:	be 3e 00 00 00       	mov    $0x3e,%esi
    27d0:	48 c7 c7 00 00 00 00 	mov    $0x0,%rdi
			27d3: R_X86_64_32S	.rodata.str1.8+0x90
    27d7:	c6 05 00 00 00 00 01 	movb   $0x1,0x0(%rip)        # 27de
    <syscall_trace_leave+0x9e>
			27d9: R_X86_64_PC32	.data.unlikely-0x4
    27de:	e8 00 00 00 00       	callq  27e3 <syscall_trace_leave+0xa3>
			27df: R_X86_64_PC32	lockdep_rcu_suspicious-0x4

OK, rcu debugging is on. Not really a factor, just making notes.

Quoted 1 line
    27e3:	4d 85 e4             	test   %r12,%r12

%r12 is the it_func_ptr

Quoted 10 lines
    27e6:	75 10                	jne    27f8 <syscall_trace_leave+0xb8>
    27e8:	65 ff 0c 25 00 00 00 	decl   %gs:0x0
    27ef:	00
			27ec: R_X86_64_32S	__preempt_count
    27f0:	0f 84 85 00 00 00    	je     287b <syscall_trace_leave+0x13b>
    27f6:	eb 1c                	jmp    2814 <syscall_trace_leave+0xd4>
    27f8:	49 8b 7c 24 08       	mov    0x8(%r12),%rdi
    27fd:	4c 89 ea             	mov    %r13,%rdx
    2800:	48 89 de             	mov    %rbx,%rsi
    2803:	41 ff 14 24          	callq  *(%r12)

As I stated, I didn't need the offset that I asked for, but the machine code had the information I needed:

24 08 4c 89 ea 48 89 de <41> ff 14 24 49 83 c4 10 49

Which matches 2803.

Quoted 7 lines

From your dump:

R10: 0000000000000000 R11: 0000000000000000 R12: 000000000000000c

Yeah, that's a bad pointer.

OK, for some reason, funcs got 0xc?

Oh crap, I think I made a stupid mistake there. Calling call_rcu to free the old func before rcu_assign_pointer publishes the new func. Can you try the attached patch ? (sorry for no inlining, using a dumb mail client here)

Thanks,

Mathieu

Quoted 64 lines

-- Steve

Quoted 58 lines
    2807:	49 83 c4 10          	add    $0x10,%r12
    280b:	49 83 3c 24 00       	cmpq   $0x0,(%r12)
    2810:	75 e6                	jne    27f8 <syscall_trace_leave+0xb8>
    2812:	eb d4                	jmp    27e8 <syscall_trace_leave+0xa8>
    2814:	0f 1f 40 00          	nopl   0x0(%rax)
    2818:	65 48 8b 04 25 00 00 	mov    %gs:0x0,%rax
    281f:	00 00
			281d: R_X86_64_32S	kernel_stack
    2821:	48 8b 90 38 e0 ff ff 	mov    -0x1fc8(%rax),%rdx
    2828:	83 e2 10             	and    $0x10,%edx
    282b:	74 5b                	je     2888 <syscall_trace_leave+0x148>
    282d:	48 8b 80 38 e0 ff ff 	mov    -0x1fc8(%rax),%rax
    2834:	a8 40                	test   $0x40,%al
    2836:	75 50                	jne    2888 <syscall_trace_leave+0x148>
    2838:	be 01 00 00 00       	mov    $0x1,%esi
    283d:	0f 1f 00             	nopl   (%rax)
    2840:	48 89 df             	mov    %rbx,%rdi
    2843:	e8 f8 fa ff ff       	callq  2340 <tracehook_report_syscall_exit>
    2848:	0f 1f 44 00 00       	nopl   0x0(%rax,%rax,1)
    284d:	eb 56                	jmp    28a5 <syscall_trace_leave+0x165>
    284f:	90                   	nop
    2850:	e8 00 00 00 00       	callq  2855 <syscall_trace_leave+0x115>
			2851: R_X86_64_PC32	context_tracking_user_exit-0x4
    2855:	e9 07 ff ff ff       	jmpq   2761 <syscall_trace_leave+0x21>
    285a:	65 ff 04 25 00 00 00 	incl   %gs:0x0
    2861:	00
			285e: R_X86_64_32S	__preempt_count
    2862:	4c 8b 25 00 00 00 00 	mov    0x0(%rip),%r12        # 2869
    <syscall_trace_leave+0x129>
			2865: R_X86_64_PC32	__tracepoint_sys_exit+0x2c
    2869:	e8 00 00 00 00       	callq  286e <syscall_trace_leave+0x12e>
			286a: R_X86_64_PC32	debug_lockdep_rcu_enabled-0x4
    286e:	85 c0                	test   %eax,%eax
    2870:	0f 85 3c ff ff ff    	jne    27b2 <syscall_trace_leave+0x72>
    2876:	e9 68 ff ff ff       	jmpq   27e3 <syscall_trace_leave+0xa3>
    287b:	e8 00 00 00 00       	callq  2880 <syscall_trace_leave+0x140>
			287c: R_X86_64_PC32	___preempt_schedule_context-0x4
    2880:	eb 96                	jmp    2818 <syscall_trace_leave+0xd8>
    2882:	66 0f 1f 44 00 00    	nopw   0x0(%rax,%rax,1)
    2888:	65 48 8b 04 25 00 00 	mov    %gs:0x0,%rax
    288f:	00 00
			288d: R_X86_64_32S	kernel_stack
    2891:	48 8b 80 38 e0 ff ff 	mov    -0x1fc8(%rax),%rax
    2898:	31 f6                	xor    %esi,%esi
    289a:	a8 01                	test   $0x1,%al
    289c:	75 a2                	jne    2840 <syscall_trace_leave+0x100>
    289e:	eb a8                	jmp    2848 <syscall_trace_leave+0x108>
    28a0:	e8 00 00 00 00       	callq  28a5 <syscall_trace_leave+0x165>
			28a1: R_X86_64_PC32	context_tracking_user_enter-0x4
    28a5:	48 8b 5d e8          	mov    -0x18(%rbp),%rbx
    28a9:	4c 8b 65 f0          	mov    -0x10(%rbp),%r12
    28ad:	4c 8b 6d f8          	mov    -0x8(%rbp),%r13
    28b1:	c9                   	leaveq
    28b2:	c3                   	retq

Thanks,
Sasha

Signature · 3 lines
Mathieu Desnoyers
EfficiOS Inc.
http://www.efficios.com

commit 13c8bda5154665f4499b31030d74665207025d24

Author: Mathieu Desnoyers <[email protected]>
Date:   Wed May 7 18:48:53 2014 -0400

Fix: tracepoint: release old probe after rcu assign pointer

kernel/tracepoint.c +2 -2
index ac5b23c..6620e58 100644
@@ -188,7 +188,6 @@ static int tracepoint_add_func(struct tracepoint *tp,
 		WARN_ON_ONCE(1);
 		return PTR_ERR(old);
 	}
-	release_probes(old);
 
 	/*
 	 * rcu_assign_pointer has a smp_wmb() which makes sure that the new
@@ -200,6 +199,7 @@ static int tracepoint_add_func(struct tracepoint *tp,
 	rcu_assign_pointer(tp->funcs, tp_funcs);
 	if (!static_key_enabled(&tp->key))
 		static_key_slow_inc(&tp->key);
+	release_probes(old);
 	return 0;
 }
 
@@ -221,7 +221,6 @@ static int tracepoint_remove_func(struct tracepoint *tp,
 		WARN_ON_ONCE(1);
 		return PTR_ERR(old);
 	}
-	release_probes(old);
 
 	if (!tp_funcs) {
 		/* Removed last function */
@@ -232,6 +231,7 @@ static int tracepoint_remove_func(struct tracepoint *tp,
 			static_key_slow_dec(&tp->key);
 	}
 	rcu_assign_pointer(tp->funcs, tp_funcs);
+	release_probes(old);
 	return 0;
 }
 
maintainer
#8 lore raw
In reply to Oleg Nesterov
Quoted 19 lines · On Wed, 7 May 2014 16:04:22 +0200 Oleg Nesterov <[email protected]> wrote:
Quoted 8 lines · Sasha Levin
Quoted 4 lines · Sasha Levin

Hi all,

While fuzzing with trinity inside a KVM tools guest running the latest -next kernel I've stumbled on the following spew:

And another similar trace:

Again, this looks like __DO_TRACE() trying to call it_func_ptr->func().

Quoted 7 lines
[ 6897.628729] general protection fault: 0000 [#1] PREEMPT SMP DEBUG_PAGEALLOC
[ 6897.629654] Dumping ftrace buffer:
[ 6897.630034]    (ftrace buffer empty)
[ 6897.630034] Modules linked in:
[ 6897.630034] CPU: 24 PID: 23736 Comm: trinity-c148 Tainted: G    B         3.15.0-rc4-next-20140506-sasha-00021-gc164334-dirty #447
[ 6897.630034] task: ffff88002a870000 ti: ffff88000ef04000 task.ti: ffff88000ef04000
[ 6897.630034] RIP: syscall_trace_leave (include/trace/events/syscalls.h:42 arch/x86/kernel/ptrace.c:1517)

Thanks for sending the objdump, but then I just realized that this dump doesn't have the actual RIP. It just says syscall_trace_leave, without even giving me the offset.

As the objdump is just of the object files and not the vmlinux, I would need the offset from syscall_trace_leave of the RIP.

Thanks,

-- Steve

Quoted 25 lines
Quoted 25 lines
[ 6897.630034] RSP: 0000:ffff88000ef05f20  EFLAGS: 00010286
[ 6897.630034] RAX: 0000000000000000 RBX: ffff88000ef05f58 RCX: 0000000000000001
[ 6897.630034] RDX: fffffffffffffff2 RSI: ffff88000ef05f58 RDI: 6b6b6b6b6b6b6b6b
[ 6897.630034] RBP: ffff88000ef05f40 R08: ffff880218c3c498 R09: 0000000100290024
[ 6897.630034] R10: 0000000000000000 R11: 0000000000000000 R12: ffff8806c5d04630
[ 6897.630034] R13: fffffffffffffff2 R14: 00000000000032e0 R15: 00000000000000af
[ 6897.630034] FS:  00007f5541eec700(0000) GS:ffff880587000000(0000) knlGS:0000000000000000
[ 6897.630034] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[ 6897.630034] CR2: 00007fff1ac95d78 CR3: 00000000036a0000 CR4: 00000000000006a0
[ 6897.630034] DR0: 00000000006df000 DR1: 0000000000000000 DR2: 0000000000000000
[ 6897.630034] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 00000000000f0602
[ 6897.630034] Stack:
[ 6897.630034]  00007f5541f0e2e0 00000000006e2000 00007f5541f0e2e0 0000000000000094
[ 6897.630034]  0000000000000011 ffffffffb458577f 000000001008feff 00000000000000af
[ 6897.630034]  00000000000032e0 0000000000000094 00007f5541f0e2e0 0000000000000011
[ 6897.630034] Call Trace:
[ 6897.630034] int_check_syscall_exit_work (arch/x86/kernel/entry_64.S:795)
[ 6897.630034] Code: 05 d1 9d f0 05 01 e8 2d 2e 14 00 4d 85 e4 75 10 65 ff 0c 25 a0 da 00 00 0f 84 85 00 00 00 eb 1c 49 8b 7c 24 08 4c 89 ea 48 89 de <41> ff 14 24 49 83 c4 10 49 83 3c 24 00 75 e6 eb d4 0f 1f 40 00
[ 6897.630034] RIP syscall_trace_leave (include/trace/events/syscalls.h:42 arch/x86/kernel/ptrace.c:1517)
[ 6897.630034]  RSP <ffff88000ef05f20>

Thanks,
Sasha

#9 lore raw
Quoted 23 lines · Steven Rostedt
Quoted 19 lines · On Wed, 7 May 2014 16:04:22 +0200 Oleg Nesterov <[email protected]> wrote:
Quoted 8 lines · Sasha Levin
Quoted 4 lines · Sasha Levin

Hi all,

While fuzzing with trinity inside a KVM tools guest running the latest -next kernel I've stumbled on the following spew:

And another similar trace:

Again, this looks like __DO_TRACE() trying to call it_func_ptr->func().

Quoted 7 lines
[ 6897.628729] general protection fault: 0000 [#1] PREEMPT SMP DEBUG_PAGEALLOC
[ 6897.629654] Dumping ftrace buffer:
[ 6897.630034]    (ftrace buffer empty)
[ 6897.630034] Modules linked in:
[ 6897.630034] CPU: 24 PID: 23736 Comm: trinity-c148 Tainted: G    B         3.15.0-rc4-next-20140506-sasha-00021-gc164334-dirty #447
[ 6897.630034] task: ffff88002a870000 ti: ffff88000ef04000 task.ti: ffff88000ef04000
[ 6897.630034] RIP: syscall_trace_leave (include/trace/events/syscalls.h:42 arch/x86/kernel/ptrace.c:1517)
Quoted 6 lines

Thanks for sending the objdump, but then I just realized that this dump doesn't have the actual RIP. It just says syscall_trace_leave, without even giving me the offset.

As the objdump is just of the object files and not the vmlinux, I would need the offset from syscall_trace_leave of the RIP.

    2803:	41 ff 14 24          	callq  *(%r12)  <=== Here
    2807:	49 83 c4 10          	add    $0x10,%r12
    280b:	49 83 3c 24 00       	cmpq   $0x0,(%r12)

Thanks,
Sasha

maintainer
#10 lore raw
Quoted 6 lines · On Wed, 07 May 2014 11:52:35 -0400 Sasha Levin <[email protected]> wrote:
Quoted 2 lines

As the objdump is just of the object files and not the vmlinux, I would need the offset from syscall_trace_leave of the RIP.

    2803:	41 ff 14 24          	callq  *(%r12)  <=== Here
    2807:	49 83 c4 10          	add    $0x10,%r12
    280b:	49 83 3c 24 00       	cmpq   $0x0,(%r12)

Yeah, after I sent the email, I figured it out from the

24 08 4c 89 ea 48 89 de <41> ff 14 24 49 83 c4 10 49

Thanks,

-- Steve

#11 lore raw
In reply to Sasha Levin

Hi,

Quoted 5 lines · Sasha Levin

Hi all,

While fuzzing with trinity inside a KVM tools guest running the latest -next kernel I've stumbled on the following spew:

This is not ptrace ;)

At first glance, tracepoint->funcs corruption. Add Steven.

Quoted 31 lines
[ 3029.100936] general protection fault: 0000 [#1] PREEMPT SMP DEBUG_PAGEALLOC
[ 3029.102198] Dumping ftrace buffer:
[ 3029.102928]    (ftrace buffer empty)
[ 3029.103644] Modules linked in:
[ 3029.104732] CPU: 16 PID: 4959 Comm: sleep Tainted: G    B         3.15.0-rc4-next-20140506-sasha-00021-gc164334-dirty #447
[ 3029.108662] task: ffff8805472f8000 ti: ffff880547e3e000 task.ti: ffff880547e3e000
[ 3029.109900] RIP: syscall_trace_enter (include/trace/events/syscalls.h:16 arch/x86/kernel/ptrace.c:1488)
[ 3029.110064] RSP: 0018:ffff880547e3ff28  EFLAGS: 00010286
[ 3029.110064] RAX: 0000000000000000 RBX: ffff880547e3ff58 RCX: 0000000000000001
[ 3029.110064] RDX: 000000000000000c RSI: ffff880547e3ff58 RDI: 6b6b6b6b6b6b6b6b
[ 3029.110064] RBP: ffff880547e3ff48 R08: 0000000000000000 R09: 0000000000000001
[ 3029.110064] R10: 0000000000000000 R11: 0000000000000000 R12: 000000000000000c
[ 3029.110064] R13: 0000000000000000 R14: ffff880039583d50 R15: 0000000000001000
[ 3029.110064] FS:  0000000000000000(0000) GS:ffff8803d6e00000(0000) knlGS:0000000000000000
[ 3029.110064] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[ 3029.110064] CR2: 00007fe08b205130 CR3: 000000061d271000 CR4: 00000000000006a0
[ 3029.110064] DR0: 00000000006df000 DR1: 0000000000000000 DR2: 0000000000000000
[ 3029.110064] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000600
[ 3029.110064] Stack:
[ 3029.110064]  0000000000400040 0000000000000009 00007fffe95ab4b9 0000000000000000
[ 3029.110064]  00007fe08afe64e0 ffffffffaa585625 0000000000001000 0000000000000000
[ 3029.110064]  00007fffe95ab4b9 0000000000000009 00007fe08afe64e0 0000000000400040
[ 3029.110064] Call Trace:
[ 3029.110064] tracesys (arch/x86/kernel/entry_64.S:736)
[ 3029.110064] Code: c6 05 e0 9f f0 05 01 e8 3d 30 14 00 4d 85 f6 75 10 65 ff 0c 25 a0 da 00 00 0f 84 ca 00 00 00 eb 19 49 8b 7e 08 4c 89 e2 48 89 de <41> ff 16 49 83 c6 10 49 83 3e 00 75 e9 eb d7 4c 8b 63 78 0f 1f
[ 3029.110064] RIP syscall_trace_enter (include/trace/events/syscalls.h:16 arch/x86/kernel/ptrace.c:1488)
[ 3029.110064]  RSP <ffff880547e3ff28>

Thanks,
Sasha