Re: kvm: WARNING in x86_emulate_insn

[Radim KrÄmÃÅ]

2017-01-12 14:55+0100, Dmitry Vyukov:
> Hello,
> 
> I've got the following WARNING in x86_emulate_insn while running
> syzkaller fuzzer:
> 
> WARNING: CPU: 2 PID: 18646 at arch/x86/kvm/emulate.c:5558
> x86_emulate_insn+0x16a5/0x4090 arch/x86/kvm/emulate.c:5572
> Modules linked in:
> CPU: 2 PID: 18646 Comm: syz-executor Not tainted 4.10.0-rc3+ #155
> Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
> Call Trace:
>  __dump_stack lib/dump_stack.c:15 [inline]
>  dump_stack+0x292/0x3a2 lib/dump_stack.c:51
>  __warn+0x19f/0x1e0 kernel/panic.c:547
>  warn_slowpath_null+0x2c/0x40 kernel/panic.c:582
>  x86_emulate_insn+0x16a5/0x4090 arch/x86/kvm/emulate.c:5572
>  x86_emulate_instruction+0x403/0x1cc0 arch/x86/kvm/x86.c:5618
>  emulate_instruction arch/x86/include/asm/kvm_host.h:1127 [inline]
>  handle_exception+0x594/0xfd0 arch/x86/kvm/vmx.c:5762
>  vmx_handle_exit+0x2b7/0x38b0 arch/x86/kvm/vmx.c:8625
>  vcpu_enter_guest arch/x86/kvm/x86.c:6888 [inline]
>  vcpu_run arch/x86/kvm/x86.c:6947 [inline]
>  kvm_arch_vcpu_ioctl_run+0xf3d/0x4660 arch/x86/kvm/x86.c:7105
>  kvm_vcpu_ioctl+0x673/0x1120 arch/x86/kvm/../../../virt/kvm/kvm_main.c:2569
>  vfs_ioctl fs/ioctl.c:43 [inline]
>  do_vfs_ioctl+0x1bf/0x1780 fs/ioctl.c:683
>  SYSC_ioctl fs/ioctl.c:698 [inline]
>  SyS_ioctl+0x8f/0xc0 fs/ioctl.c:689
>  entry_SYSCALL_64_fastpath+0x1f/0xc2
> RIP: 0033:0x445329
> RSP: 002b:00007f9e6e22fb58 EFLAGS: 00000286 ORIG_RAX: 0000000000000010
> RAX: ffffffffffffffda RBX: 0000000000000018 RCX: 0000000000445329
> RDX: 0000000000000000 RSI: 000000000000ae80 RDI: 0000000000000018
> RBP: 00000000006deb40 R08: 0000000000000000 R09: 0000000000000000
> R10: 0000000000000000 R11: 0000000000000286 R12: 0000000000700150
> R13: 0000000000000000 R14: 00007f9e6e2309c0 R15: 00007f9e6e230700
> ---[ end trace 6b54f749506b620c ]---
> ------------[ cut here ]------------
> WARNING: CPU: 2 PID: 18646 at arch/x86/kvm/x86.c:366
> exception_type+0x73/0x80 arch/x86/kvm/x86.c:366
> Modules linked in:
> CPU: 2 PID: 18646 Comm: syz-executor Tainted: G        W       4.10.0-rc3+ #155
> Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
> Call Trace:
>  __dump_stack lib/dump_stack.c:15 [inline]
>  dump_stack+0x292/0x3a2 lib/dump_stack.c:51
>  __warn+0x19f/0x1e0 kernel/panic.c:547
>  warn_slowpath_null+0x2c/0x40 kernel/panic.c:582
>  exception_type+0x73/0x80 arch/x86/kvm/x86.c:366
>  x86_emulate_instruction+0x1356/0x1cc0 arch/x86/kvm/x86.c:5664
>  emulate_instruction arch/x86/include/asm/kvm_host.h:1127 [inline]
>  handle_exception+0x594/0xfd0 arch/x86/kvm/vmx.c:5762
>  vmx_handle_exit+0x2b7/0x38b0 arch/x86/kvm/vmx.c:8625
>  vcpu_enter_guest arch/x86/kvm/x86.c:6888 [inline]
>  vcpu_run arch/x86/kvm/x86.c:6947 [inline]
>  kvm_arch_vcpu_ioctl_run+0xf3d/0x4660 arch/x86/kvm/x86.c:7105
>  kvm_vcpu_ioctl+0x673/0x1120 arch/x86/kvm/../../../virt/kvm/kvm_main.c:2569
>  vfs_ioctl fs/ioctl.c:43 [inline]
>  do_vfs_ioctl+0x1bf/0x1780 fs/ioctl.c:683
>  SYSC_ioctl fs/ioctl.c:698 [inline]
>  SyS_ioctl+0x8f/0xc0 fs/ioctl.c:689
>  entry_SYSCALL_64_fastpath+0x1f/0xc2
> RIP: 0033:0x445329
> RSP: 002b:00007f9e6e22fb58 EFLAGS: 00000286 ORIG_RAX: 0000000000000010
> RAX: ffffffffffffffda RBX: 0000000000000018 RCX: 0000000000445329
> RDX: 0000000000000000 RSI: 000000000000ae80 RDI: 0000000000000018
> RBP: 00000000006deb40 R08: 0000000000000000 R09: 0000000000000000
> R10: 0000000000000000 R11: 0000000000000286 R12: 0000000000700150
> R13: 0000000000000000 R14: 00007f9e6e2309c0 R15: 00007f9e6e230700
> ---[ end trace 6b54f749506b620d ]---
> 
> On commit ba836a6f5ab1243ff5e08a941a2d1de8b31244e1.
> 
> Unfortunately I can't reproduce it with a C program.
> It reproduces with the following syzkaller program within a minute, though:
> https://gist.githubusercontent.com/dvyukov/d09118fb9d986a9385487d80a1b50680/raw/884c68d22c3a80778ae596a6c5daf7467ea41b68/gistfile1.txt
> It can be executed following these instructions:
> https://github.com/google/syzkaller/wiki/How-to-execute-syzkaller-programs
> I run syz-execprog as:
> ./syz-execprog -repeat=0 -procs=8 -sandbox=none gistfile1.txt
> 
> Note that syz_kvm_setup_cpu is a pseudo syscall that setups vcpu into
> a complex state:
> https://github.com/google/syzkaller/blob/master/executor/common_kvm_amd64.h#L271
> 
> My bet would be on some race where VM memory is overwritten
> concurrently, and it affects either guest execution or
> emulate_instruction in a bad way...

Yeah, all functions that return X86EMUL_PROPAGATE_FAULT seem to set
exception.vector to something sane.  The only easy way to get a bad value there
is when x86_emulate_instruction() clears it to -1U, but I don't see how a race
would play out.

Anyway, I can't reproduce on bare metal [got another warning, see below].
Will try after rebuilding a guest kernel.

Thanks.


The best result was this warning after 300k executions:

------------[ cut here ]------------
WARNING: CPU: 7 PID: 20187 at lib/debugobjects.c:263 debug_print_object+0x87/0xb0
ODEBUG: free active (active state 0) object type: hrtimer hint: hrtimer_wakeup+0x0/0x40
Modules linked in: vhost_net vhost macvtap macvlan xt_CHECKSUM ipt_MASQUERADE nf_nat_masquerade_ipv4 tun ip6t_rpfilter ip6t_REJECT nf_reject_ipv6 xt_conntrack ip_set nfnetlink ebtable_nat ebtable_broute bridge stp llc ip6table_nat nf_conntrack_ipv6 nf_defrag_ipv6 nf_nat_ipv6 ip6table_mangle ip6table_raw ip6table_security iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack iptable_mangle iptable_raw iptable_security ebtable_filter ebtables ip6table_filter ip6_tables intel_rapl sb_edac edac_core x86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel kvm irqbypass crct10dif_pclmul crc32_pclmul ghash_clmulni_intel intel_cstate xfs ipmi_ssif tg3 intel_uncore ipmi_si ptp iTCO_wdt iTCO_vendor_support dcdbas libcrc32c mei_me pps_core ipmi_devintf intel_rapl_perf pcspkr
 mei shpchp lpc_ich ipmi_msghandler fjes wmi acpi_power_meter tpm_tis tpm_tis_core tpm nfsd auth_rpcgss nfs_acl lockd grace sunrpc btrfs xor mgag200 i2c_algo_bit drm_kms_helper ttm drm raid6_pq crc32c_intel
CPU: 7 PID: 20187 Comm: syz-executor16 Not tainted 4.10.0-rc3+ #5
Hardware name: Dell Inc. PowerEdge R430/0HFG24, BIOS 1.6.2 01/08/2016
Call Trace:
 dump_stack+0xb3/0x10b
 ? debug_print_object+0x87/0xb0
 __warn+0x11a/0x140
 warn_slowpath_fmt+0x78/0xa0
 ? debug_lockdep_rcu_enabled+0x1d/0x20
 debug_print_object+0x87/0xb0
 ? enqueue_hrtimer+0x1c0/0x1c0
 debug_check_no_obj_freed+0x219/0x260
 __vunmap+0x9d/0x180
 vfree+0x59/0xb0
 kvfree+0x5b/0x70
 __kvm_set_memory_region.part.57+0xc0b/0xfb0 [kvm]
 __kvm_set_memory_region+0x41/0x50 [kvm]
 __x86_set_memory_region+0x12b/0x300 [kvm]
 vmx_create_vcpu+0x1229/0x1650 [kvm_intel]
 kvm_arch_vcpu_create+0x52/0x80 [kvm]
 kvm_vm_ioctl+0x3fa/0xbb0 [kvm]
 ? sched_clock_cpu+0xa7/0xc0
 ? __fget+0x13e/0x2b0
 ? kvm_set_memory_region+0x70/0x70 [kvm]
 do_vfs_ioctl+0xbf/0x8e0
 ? __schedule+0x2eb/0xae0
 SyS_ioctl+0x94/0xc0
 entry_SYSCALL_64_fastpath+0x1f/0xc2
RIP: 0033:0x468069
RSP: 002b:00007fa6e2da5b58 EFLAGS: 00000212 ORIG_RAX: 0000000000000010
RAX: ffffffffffffffda RBX: 000000000000abb5 RCX: 0000000000468069
RDX: 0000000000000000 RSI: 000000000000ae41 RDI: 0000000000000017
RBP: 00007fa6e34ca000 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000212 R12: 00007fa6e34ca008
R13: 00007fa6e3511c58 R14: 00007fa6e351fdb0 R15: 0000000000000000
---[ end trace 65d04d71aa6654bf ]---
general protection fault: 0000 [#1] SMP
Modules linked in: vhost_net vhost macvtap macvlan xt_CHECKSUM ipt_MASQUERADE nf_nat_masquerade_ipv4 tun ip6t_rpfilter ip6t_REJECT nf_reject_ipv6 xt_conntrack ip_set nfnetlink ebtable_nat ebtable_broute bridge stp llc ip6table_nat nf_conntrack_ipv6 nf_defrag_ipv6 nf_nat_ipv6 ip6table_mangle ip6table_raw ip6table_security iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack iptable_mangle iptable_raw iptable_security ebtable_filter ebtables ip6table_filter ip6_tables intel_rapl sb_edac edac_core x86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel kvm irqbypass crct10dif_pclmul crc32_pclmul ghash_clmulni_intel intel_cstate xfs ipmi_ssif tg3 intel_uncore ipmi_si ptp iTCO_wdt iTCO_vendor_support dcdbas libcrc32c mei_me pps_core ipmi_devintf intel_rapl_perf pcspkr
 mei shpchp lpc_ich ipmi_msghandler fjes wmi acpi_power_meter tpm_tis tpm_tis_core tpm nfsd auth_rpcgss nfs_acl lockd grace sunrpc btrfs xor mgag200 i2c_algo_bit drm_kms_helper ttm drm raid6_pq crc32c_intel
CPU: 7 PID: 20187 Comm: syz-executor16 Tainted: G        W       4.10.0-rc3+ #5
Hardware name: Dell Inc. PowerEdge R430/0HFG24, BIOS 1.6.2 01/08/2016
task: ffff8b93c7063280 task.stack: ffff9ee18ff04000
RIP: 0010:hrtimer_active+0x5c/0xb0
RSP: 0018:ffff9ee18ff079a8 EFLAGS: 00010246
RAX: 0000000000010000 RBX: 000158838b48c789 RCX: 0000000000010000
RDX: ffffffff81179548 RSI: ffff9ee1a63c6000 RDI: ffff9ee1ae2fbd38
RBP: ffff9ee18ff079c0 R08: ffff9ee1ae2fbd38 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000000 R12: ffffffffbb1221fa
R13: ffff9ee1ae2fbd38 R14: ffffffffbc0b6b40 R15: ffffffffbd6620e8
FS:  00007fa6e2da6700(0000) GS:ffff8b982e400000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
CR2: 00007f611cd4e118 CR3: 0000000409189000 CR4: 00000000001426e0
Call Trace:
 hrtimer_try_to_cancel+0x36/0x270
 hrtimer_fixup_free+0x33/0x70
 debug_object_fixup+0x13/0x30
 debug_check_no_obj_freed+0x249/0x260
 __vunmap+0x9d/0x180
 vfree+0x59/0xb0
 kvfree+0x5b/0x70
 __kvm_set_memory_region.part.57+0xc0b/0xfb0 [kvm]
 __kvm_set_memory_region+0x41/0x50 [kvm]
 __x86_set_memory_region+0x12b/0x300 [kvm]
 vmx_create_vcpu+0x1229/0x1650 [kvm_intel]
 kvm_arch_vcpu_create+0x52/0x80 [kvm]
 kvm_vm_ioctl+0x3fa/0xbb0 [kvm]
 ? sched_clock_cpu+0xa7/0xc0
 ? __fget+0x13e/0x2b0
 ? kvm_set_memory_region+0x70/0x70 [kvm]
 do_vfs_ioctl+0xbf/0x8e0
 ? __schedule+0x2eb/0xae0
 SyS_ioctl+0x94/0xc0
 entry_SYSCALL_64_fastpath+0x1f/0xc2
RIP: 0033:0x468069
RSP: 002b:00007fa6e2da5b58 EFLAGS: 00000212 ORIG_RAX: 0000000000000010
RAX: ffffffffffffffda RBX: 000000000000abb5 RCX: 0000000000468069
RDX: 0000000000000000 RSI: 000000000000ae41 RDI: 0000000000000017
RBP: 00007fa6e34ca000 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000212 R12: 00007fa6e34ca008
R13: 00007fa6e3511c58 R14: 00007fa6e351fdb0 R15: 0000000000000000
Code: 00 00 00 74 4d e8 e5 33 06 00 44 39 63 48 75 d0 e8 da 33 06 00 4d 8b 65 30 49 8b 04 24 48 39 c3 74 43 e8 c8 33 06 00 49 8b 1c 24 <44> 8b 63 48 41 f6 c4 01 74 b6 e8 b5 33 06 00 f3 90 44 8b 63 48 
RIP: hrtimer_active+0x5c/0xb0 RSP: ffff9ee18ff079a8
---[ end trace 65d04d71aa6654c0 ]---