> On 25 Jul 2022, at 17:16, Jan Beulich <jbeul...@suse.com> wrote:
>
> On 25.07.2022 17:51, Bertrand Marquis wrote:
>> On our CI we have randomly a crash during guest boot on x86.
>
> Afaict of a PV guest.
>
>> We are running on qemu x86_64 using Xen staging.
>
> Which may introduce unusual timing. An issue never hit on actual hardware
> _may_ (but doesn't have to be) one in qemu itself.
>
>> The crash is happening randomly (something like 1 out of 20 times).
>>
>> This is always happening on the first guest we start, we never got it after
>> first guest was successfully started.
>>
>> Please tell me if you need any other info.
>>
>> Here is the guest kernel log:
>> [...]
>> [ 6.679020] general protection fault, maybe for address 0x8800: 0000 [#1]
>> PREEMPT SMP NOPTI
>> [ 6.679020] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 5.17.6 #1
>> [ 6.679020] RIP: e030:error_entry+0xaf/0xe0
>> [ 6.679020] Code: 29 89 c8 48 39 84 24 88 00 00 00 74 15 48 81 bc 24 88 00
>> 00 00 63 10 e0 81 75 03 0f 01 f8 90 90 90 c3 48 89 8c 24 88 00 00 00 <0f> 01
>> f8 90 90 90 eb 11 0f 20 d8 90 90 90 90 90 48 25 ff e7 ff ff
>
> This is SWAPGS, which supposedly a PV guest should never hit. Data further
> down suggests the kernel is still in the process of patching alternatives,
> which may be the reason for the insn to still be there (being at a point
> where exceptions are still unexpected).
So the exception path is using alternative code ? Sounds logic with the error
output.
But does explain the original error.
>
>> [ 6.679020] RSP: e02b:ffffffff82803a90 EFLAGS: 00000046
>> [ 6.679020] RAX: 0000000000008800 RBX: 0000000000000000 RCX: ffffffff81e00fa7
>> [ 6.679020] RDX: 0000000000000000 RSI: ffffffff81e009f8 RDI: 00000000000000eb
>> [ 6.679020] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
>> [ 6.679020] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000
>> [ 6.679020] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
>> [ 6.679020] FS: 0000000000000000(0000) GS:ffff88801f200000(0000)
>> knlGS:0000000000000000
>> [ 6.679020] CS: 10000e030 DS: 0000 ES: 0000 CR0: 0000000080050033
>> [ 6.679020] CR2: 0000000000000000 CR3: 000000000280c000 CR4: 0000000000050660
>> [ 6.679020] Call Trace:
>> [ 6.679020] <TASK>
>> [ 6.679020] RIP: e030:native_irq_return_iret+0x0/0x2
>> [ 6.679020] Code: 41 5d 41 5c 5d 5b 41 5b 41 5a 41 59 41 58 58 59 5a 5e 5f
>> 48 83 c4 08 eb 0a 0f 1f 00 90 66 0f 1f 44 00 00 f6 44 24 20 04 75 02 <48> cf
>> 57 0f 01 f8 eb 12 0f 20 df 90 90 90 90 90 48 81 e7 ff e7 ff
>> [ 6.679020] RSP: e02b:ffffffff82803b48 EFLAGS: 00000046 ORIG_RAX:
>> 000000000000e030
>> [ 6.679020] RAX: 0000000000008800 RBX: ffffffff82803be0 RCX: ffffffff81e00f95
>> [ 6.679020] RDX: ffffffff81e00f94 RSI: ffffffff81e00f95 RDI: 00000000000000eb
>> [ 6.679020] RBP: 00000000000000eb R08: 0000000090001f0f R09: 0000000000000007
>> [ 6.679020] R10: ffffffff81e00f94 R11: ffffffff8285a6c0 R12: 0000000000000000
>> [ 6.679020] R13: ffffffff81e00f94 R14: 0000000000000006 R15: 0000000000000006
>> [ 6.679020] ? asm_exc_general_protection+0x8/0x30
>> [ 6.679020] ? restore_regs_and_return_to_kernel+0x1b/0x27
>> [ 6.679020] ? restore_regs_and_return_to_kernel+0x1b/0x27
>> [ 6.679020] ? restore_regs_and_return_to_kernel+0x1c/0x27
>> [ 6.679020] ? restore_regs_and_return_to_kernel+0x1b/0x27
>> [ 6.679020] ? restore_regs_and_return_to_kernel+0x1c/0x27
>> [ 6.679020] RIP: e030:insn_get_opcode.part.0+0xab/0x180
>> [ 6.679020] Code: 00 00 8b 43 4c a9 c0 07 08 00 0f 84 bf 00 00 00 c6 43 1c
>> 01 31 c0 5b 5d c3 83 e2 03 be 01 00 00 00 eb b7 89 ef e8 65 e4 ff ff <89> 43
>> 4c a8 30 75 21 e9 8e 00 00 00 0f b6 7b 03 40 84 ff 75 73 8b
>> [ 6.679020] RSP: e02b:ffffffff82803b70 EFLAGS: 00000246
>> [ 6.679020] ? restore_regs_and_return_to_kernel+0x1b/0x27
>> [ 6.679020] insn_get_modrm+0x6c/0x120
>> [ 6.679020] ? restore_regs_and_return_to_kernel+0x1b/0x27
>> [ 6.679020] insn_get_sib+0x40/0x80
>> [ 6.679020] insn_get_displacement+0x82/0x100
>> [ 6.679020] insn_decode+0xf8/0x100
>> [ 6.679020] optimize_nops+0x60/0x1e0
>> [ 6.679020] ? rcu_nmi_exit+0x2b/0x140
>> [ 6.679020] ? restore_regs_and_return_to_kernel+0x1b/0x27
>> [ 6.679020] ? native_iret+0x3/0x7
>> [ 6.679020] ? restore_regs_and_return_to_kernel+0x1c/0x27
>> [ 6.679020] ? restore_regs_and_return_to_kernel+0x1b/0x27
>> [ 6.679020] apply_alternatives+0x165/0x2e0
>
> I have to admit that I'm a little lost with these "modern" stack traces,
> where contexts apparently switch without being clearly annotated. It is
> looking a little as if a #GP fault was happening somewhere here (hence
> the asm_exc_general_protection further up), but I cannot work out where
> (what insn) that would have come from.
>
> You may want to add some debugging code to the hypervisor to tell you
> where exactly that #GP (if there is one in the first place) originates
> from. With that it may then become a little more clear what's actually
> going on (and why the behavior is random).
I will check what I can do there but as the crash is very random and only
happening during our CI tests, this is not really easy to reproduce.
If you have any example of code to do the debugging, I could run some
tests with it.
>
> As a final remark - you've Cc-ed the x86 hypervisor maintainers, but at
> least from the data which is available so far this is more likely a
> kernel issue. So kernel folks might be of more help ...
I wanted to check if this could be a know issue first. The problem is
happening in the kernel, I agree, but only when it started as a Xen guest
so I assumed it could be related to Xen.
At the end I wanted to signal the problem, but I will not have much
resources to work on this.
Bertrand
>
> Jan
>
>> [ 6.679020] ? insn_get_opcode.part.0+0xab/0x180
>> [ 6.679020] ? insn_get_modrm+0x6c/0x120
>> [ 6.679020] ? rcu_nmi_enter+0x2b/0xf0
>> [ 6.679020] ? rcu_nmi_exit+0x2b/0x140
>> [ 6.679020] ? irqentry_exit+0x29/0x30
>> [ 6.679020] ? exc_xen_hypervisor_callback+0x8/0x10
>> [ 6.679020] ? relocate_restore_code+0x22a/0x240
>> [ 6.679020] alternative_instructions+0x8b/0x13a
>> [ 6.679020] check_bugs+0xa87/0xadf
>> [ 6.679020] ? __get_locked_pte+0xa8/0xf0
>> [ 6.679020] start_kernel+0x64c/0x680
>> [ 6.679020] xen_start_kernel+0x592/0x59f
>> [ 6.679020] startup_xen+0x3e/0x3e
>> [ 6.679020] </TASK>
>> [ 6.679020] Modules linked in:
>> [ 6.679020] ---[ end trace 0000000000000000 ]---
>> [ 6.679020] RIP: e030:error_entry+0xaf/0xe0
>> [ 6.679020] Code: 29 89 c8 48 39 84 24 88 00 00 00 74 15 48 81 bc 24 88 00
>> 00 00 63 10 e0 81 75 03 0f 01 f8 90 90 90 c3 48 89 8c 24 88 00 00 00 <0f> 01
>> f8 90 90 90 eb 11 0f 20 d8 90 90 90 90 90 48 25 ff e7 ff ff
>> [ 6.679020] RSP: e02b:ffffffff82803a90 EFLAGS: 00000046
>> [ 6.679020] RAX: 0000000000008800 RBX: 0000000000000000 RCX: ffffffff81e00fa7
>> [ 6.679020] RDX: 0000000000000000 RSI: ffffffff81e009f8 RDI: 00000000000000eb
>> [ 6.679020] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
>> [ 6.679020] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000
>> [ 6.679020] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
>> [ 6.679020] FS: 0000000000000000(0000) GS:ffff88801f200000(0000)
>> knlGS:0000000000000000
>> [ 6.679020] CS: 10000e030 DS: 0000 ES: 0000 CR0: 0000000080050033
>> [ 6.679020] CR2: 0000000000000000 CR3: 000000000280c000 CR4: 0000000000050660
>> [ 6.679020] Kernel panic - not syncing: Attempted to kill the idle task!
>>
>> Cheers
>> Bertrand
