kvm: WARNING in kvm_arch_vcpu_ioctl_run

[Dmitry Vyukov]

Hello,

The following program triggers WARNING in kvm_arch_vcpu_ioctl_run in
run in parallel loop:
https://gist.githubusercontent.com/dvyukov/08091eee6f38548ff9e6905c5e0eaaee/raw/8cae95f2e88eeb98c4ddc06d227670c1e248222f/gistfile1.txt

On commit e234832afb623fe5c7d1d5703d6619494d8d703f (Nov 13)

WARNING: CPU: 3 PID: 11141 at arch/x86/kvm/x86.c:6984
kvm_arch_vcpu_ioctl_run+0x1f0/0x4f50
CPU: 3 PID: 11141 Comm: syz-executor Not tainted 4.9.0-rc5+ #24
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
ffff880039cef698 ffffffff834c3959 ffffffff00000003 1ffff1000739de66
ffffed000739de5e 0000000041b58ab3 ffffffff89576450 ffffffff834c366b
0000000041b58ab3 ffffffff894d2830 ffffffff81590020 ffffffff810d90f0
Call Trace:
[< inline >] __dump_stack lib/dump_stack.c:15
[<ffffffff834c3959>] dump_stack+0x2ee/0x3f5 lib/dump_stack.c:51
[<ffffffff81849908>] panic+0x200/0x425 kernel/panic.c:179
[<ffffffff813fd919>] __warn+0x1c9/0x1e0 kernel/panic.c:542
[<ffffffff813fdb81>] warn_slowpath_null+0x31/0x40 kernel/panic.c:585
[<ffffffff810ee930>] kvm_arch_vcpu_ioctl_run+0x1f0/0x4f50
arch/x86/kvm/x86.c:6984
[<ffffffff8107b328>] kvm_vcpu_ioctl+0x678/0x11c0
arch/x86/kvm/../../../virt/kvm/kvm_main.c:2557
[< inline >] vfs_ioctl fs/ioctl.c:43
[<ffffffff81abdb44>] do_vfs_ioctl+0x1c4/0x1630 fs/ioctl.c:679
[< inline >] SYSC_ioctl fs/ioctl.c:694
[<ffffffff81abf044>] SyS_ioctl+0x94/0xc0 fs/ioctl.c:685
[<ffffffff88144885>] entry_SYSCALL_64_fastpath+0x23/0xc6

[Paolo Bonzini]

What I got for now is this dmesg splat:

[31705.171034] *** Guest State ***
[31705.171039] CR0: actual=0x0000000000000030, shadow=0x0000000060000010, gh_mask=fffffffffffffff7
[31705.171040] CR4: actual=0x0000000000002050, shadow=0x0000000000000000, gh_mask=fffffffffffff871
[31705.171040] CR3 = 0x00000000fffbc000
[31705.171041] RSP = 0x0000000000000007 RIP = 0x0000000000100000
[31705.171042] RFLAGS=0x00000ad0 DR7 = 0x0000000000000400
[31705.171043] Sysenter RSP=0000000000000000 CS:RIP=0000:0000000000000000
[31705.171044] CS: sel=0x0000, attr=0x0009b, limit=0x0000ffff, base=0x0000000000000000
[31705.171045] DS: sel=0x0000, attr=0x00093, limit=0x0000ffff, base=0x0000000000000000
[31705.171046] SS: sel=0x0000, attr=0x00093, limit=0x0000ffff, base=0x0000000000000000
[31705.171046] ES: sel=0x0000, attr=0x00093, limit=0x0000ffff, base=0x0000000000000000
[31705.171047] FS: sel=0x0000, attr=0x00093, limit=0x0000ffff, base=0x0000000000000000
[31705.171048] GS: sel=0x0000, attr=0x00093, limit=0x0000ffff, base=0x0000000000000000
[31705.171049] GDTR: limit=0x0000ffff, base=0x0000000000000000
[31705.171050] LDTR: sel=0x0000, attr=0x00082, limit=0x0000ffff, base=0x0000000000000000
[31705.171050] IDTR: limit=0x0000ffff, base=0x0000000000000000
[31705.171051] TR: sel=0x0000, attr=0x0008b, limit=0x0000ffff, base=0x0000000000000000
[31705.171052] EFER = 0x0000000000000000 PAT = 0x0007040600070406
[31705.171053] DebugCtl = 0x0000000000000000 DebugExceptions = 0x0000000000000000
[31705.171054] Interruptibility = 00000000 ActivityState = 00000000
[31705.171054] *** Host State ***
[31705.171055] RIP = 0xffffffffc0be5138 RSP = 0xffff8a4bc8967cd0
[31705.171056] CS=0010 SS=0018 DS=0000 ES=0000 FS=0000 GS=0000 TR=0040
[31705.171057] FSBase=00007fe434945700 GSBase=ffff8a4bde240000 TRBase=ffff8a4bde256c80
[31705.171058] GDTBase=ffff8a4bde249000 IDTBase=ffffffffff57b000
[31705.171058] CR0=0000000080050033 CR3=00000001934aa000 CR4=00000000001426e0
[31705.171059] Sysenter RSP=0000000000000000 CS:RIP=0010:ffffffff86803e10
[31705.171060] EFER = 0x0000000000000d01 PAT = 0x0407010600070106
[31705.171061] *** Control State ***
[31705.171061] PinBased=0000003f CPUBased=b6a1edfe SecondaryExec=000000eb
[31705.171062] EntryControls=0000d1ff ExitControls=002fefff
[31705.171063] ExceptionBitmap=00060042 PFECmask=00000000 PFECmatch=00000000
[31705.171064] VMEntry: intr_info=800000ff errcode=00000000 ilen=00000000
[31705.171065] VMExit: intr_info=00000000 errcode=00000000 ilen=00000002
[31705.171065] reason=80000021 qualification=0000000000000000
[31705.171066] IDTVectoring: info=00000000 errcode=00000000
[31705.171067] TSC Offset = 0xffffc75eb7825681
[31705.171067] TPR Threshold = 0x00
[31705.171068] EPT pointer = 0x000000019361301e
[31705.171069] Virtual processor ID = 0x0001

[Dmitry Vyukov]

I made dump_vmcs() no-op locally. You should see the warning
regardless, but probably it is difficult to notice. Or maybe tons of
output affect timings so that the warning does not happen.

> --
> You received this message because you are subscribed to the Google Groups "syzkaller" group.
> To unsubscribe from this group and stop receiving emails from it, send an email to syzkaller+...@googlegroups.com.
> For more options, visit https://groups.google.com/d/optout.

[Paolo Bonzini]

On 14/11/2016 15:09, Dmitry Vyukov wrote:
>
> I made dump_vmcs() no-op locally. You should see the warning
> regardless, but probably it is difficult to notice. Or maybe tons of
> output affect timings so that the warning does not happen.

I let it run for several minutes, and only got 50 splats out of several
thousand iterations. Reproducing is not going to help much anyway---if
we can get to the root cause, writing a reliable reproducer would be
easier anyway.

Paolo