On 06/01/16 14:41, Paolo Bonzini wrote: > > > On 01/06/2016 14:26, Laszlo Ersek wrote: >> On 06/01/16 13:30, Paolo Bonzini wrote: >>> >>> >>> On 01/06/2016 12:50, Laszlo Ersek wrote: >>>> In other words, the fault is raised and delivered (== the handler >>>> is entered) entirely within non-root operation, inside the VM. I >>>> find this amazing. (Amazingly annoying.) >>> >>> It is indeed. You can try using ept=0 to see the page faults. >> >> Given that it reproduces with TCG, I added the following option to >> the QEMU command line: >> >> -d int,pcall >> >> It absolutely spams the output, but the last two state dumps >> preceding the fault are: >> >> RIP (7feee48d) and CR2 (ffe00020) are consistent with the guest's own >> report: >> >>> ~SmiPFHandler: PFAddress=0xFFE00020 Rip=0x7FEEE48D >>> PageTable = 7FFA7000, PTIndex = 1FF, PageTable[PTIndex] = 7FFF31BD >>> New page table overlapped with old page table! >>> ASSERT .../UefiCpuPkg/PiSmmCpuDxeSmm/X64/PageTbl.c(618): ((BOOLEAN)(0==1)) >> >> Is this useful information? > > Yes, it is. If the PT address is constant, perhaps you can attach gdb > to QEMU and set a hardware watchpoint on the PTE?
Thank you. This tip allowed me to find the bug. :) It is a stack overflow in the SMM Core that tramples the top-most PTE in the SMM page table (the one that covers the last 2MB of the 4GB address space, that is, where the pflash chips are mapped). The haphazard behavior I've been seeing with my debug instrumentation must have been due to the unpredictable time and location of the stack overflow. The details: (1) I added some debug code to Gen4GPageTable() [UefiCpuPkg/PiSmmCpuDxeSmm/MpService.c] for dumping the initially generated page tables. They looked all good. (2) I appended the "-s" parameter (= start builtin GDB server on TCP port 1234) to the QEMU command line. It's important to use TCG acceleration for this; with KVM the watchpoints are not reliable. (3) Once I was standing at the UEFI shell with QEMU, I connected to QEMU with gdb (the client). I tried the symbolic debugging stuff we sometimes use otherwise <https://edk2.bluestop.org/w/tianocore/debugging-with-gdb/>, but it has no support for SMM drivers, so it wasn't helpful. Nonetheless, I calculated the address of the PTE that was always being corrupted. It was 0x7FFA7FF8 -- the very last entry in the page table area that Gen4GPageTable() allocates and pre-fills. Then, I set a (write-only) watchpoint on it, as you suggested: > (gdb) watch *(UINT64*)0x7FFA7FF8 > Hardware watchpoint 1: *(UINT64*)0x7FFA7FF8 > (gdb) cont > Continuing. (4) I ran EnrollDefaultKeys.efi from the UEFI shell, in the guest. The watchpoint fired in gdb: > Hardware watchpoint 1: *(UINT64*)0x7FFA7FF8 > > Old value = 18446744073709551615 > New value = 2147430300 > 0x000000007fff38fd in ?? () and I collected the following information: * stack dump: > (gdb) where > #0 0x000000007fff38fd in ?? () > #1 0x000000007fff2f9c in ?? () > #2 0x0000000000000000 in ?? () * registers: > (gdb) info registers > rax 0x7fff38fd 2147432701 > rbx 0x1fc4 8132 > rcx 0x7fe77010 2145873936 > rdx 0x7fe77010 2145873936 > rsi 0x7ffa8140 2147123520 > rdi 0x4 4 > rbp 0x7ffa8030 0x7ffa8030 > rsp 0x7ffa7ff8 0x7ffa7ff8 > r8 0x0 0 > r9 0x7ff69fa0 2146869152 > r10 0xffffffff 4294967295 > r11 0x0 0 > r12 0xc4d 3149 > r13 0x0 0 > r14 0x0 0 > r15 0x0 0 > rip 0x7fff38fd 0x7fff38fd > eflags 0x6 [ PF ] > cs 0x38 56 > ss 0x20 32 > ds 0x20 32 > es 0x20 32 > fs 0x20 32 > gs 0x20 32 * Some disassembly at RIP: > (gdb) disassemble /r 0x07fff38fd,+20 > Dump of assembler code from 0x7fff38fd to 0x7fff3911: > => 0x000000007fff38fd: 55 push %rbp > 0x000000007fff38fe: 48 89 e5 mov %rsp,%rbp > 0x000000007fff3901: 48 b8 88 9d ff 7f 00 00 00 00 movabs > $0x7fff9d88,%rax > 0x000000007fff390b: 0f b6 00 movzbl (%rax),%eax > 0x000000007fff390e: 0f b6 c0 movzbl %al,%eax > End of assembler dump. Now, on x86_64 the stack grows down. We can see that RSP is 7ffa7ff8, that is, the address of the PTE that gets corrupted. The value being pushed into it (as if onto the stack) is supposed to be RBP (0x7ffa8030). We're not seeing that in the watchpoint's "New value" -- I'm unsure why --, but what we *are* seeing as New value makes sense too: 2147430300 decimal is 0x7fff2f9c, which is exactly what the "where" command above listed for frame #1! So, it seems to me that we are just after a function call. Frame #1 has been pushed onto the "stack", corrupting the topmost PTE at 0x7FFA7FF8, and we are now in frame #0, at 0x7fff38fd. (5) Here I got stuck for quite some time, but after staring at the OVMF debug log, I found the following snippet (I was looking for base addresses slightly below the values visible on the "stack"): > Loading driver at 0x0007E5DC000 EntryPoint=0x0007E5DD04F PiSmmIpl.efi > InstallProtocolInterface: BC62157E-3E33-4FEC-9920-2D3B36D750DF 7EB64018 > SMM IPL opened SMRAM window > SMM IPL found SMRAM window 7F801000 - 7FFFFFFF > SMM IPL loading SMM Core at SMRAM address 7FFE7000 > SMM IPL calling SMM Core at SMRAM address 7FFE728F > PiSmmCoreImageBase - 0x000000007FFE7000 > PiSmmCoreImageSize - 0x0000000000018D60 > mSmmMemLibInternalMaximumSupportAddress = 0xFFFFFFFFF Aha! #0 0x000000007fff38fd - PiSmmCoreImageBase [0x7FFE7000] = 0xc8fd #1 0x000000007fff2f9c - PiSmmCoreImageBase [0x7FFE7000] = 0xbf9c Equipped with these offsets into the SMM Core, enter "objdump": > objdump -S --all-headers \ > > Build/Ovmf3264/DEBUG_GCC48/X64/MdeModulePkg/Core/PiSmmCore/PiSmmCore/DEBUG/PiSmmCore.debug First, let's verify: > start address 0x000000000000028f This matches 7FFE728F-7FFE7000 from the OVMF debug log (SMM Core entry point minus image base), okay. Second, lo and behold those offsets in the disassembly: * Frame #0, offset c8fd: > 000000000000c8fd <DebugAssertEnabled>: > BOOLEAN > EFIAPI > DebugAssertEnabled ( > VOID > ) > { > c8fd: 55 push %rbp > c8fe: 48 89 e5 mov %rsp,%rbp > return (BOOLEAN) ((PcdGet8(PcdDebugPropertyMask) & > DEBUG_PROPERTY_DEBUG_ASSERT_ENABLED) != 0); > c901: 48 b8 88 2d 01 00 00 movabs $0x12d88,%rax > c908: 00 00 00 > c903: R_X86_64_64 > _gPcd_FixedAtBuild_PcdDebugPropertyMask > c90b: 0f b6 00 movzbl (%rax),%eax > c90e: 0f b6 c0 movzbl %al,%eax This is identical to out disassembly in step (1), modulo a relocation! * Frame #1, offset bf9c: > 000000000000bf7a <InternalBaseLibIsNodeInList>: > InternalBaseLibIsNodeInList ( > IN CONST LIST_ENTRY *List, > IN CONST LIST_ENTRY *Node, > IN BOOLEAN VerifyNodeInList > ) > { > bf7a: 55 push %rbp > bf7b: 48 89 e5 mov %rsp,%rbp > bf7e: 48 83 ec 30 sub $0x30,%rsp > bf82: 48 89 4d 10 mov %rcx,0x10(%rbp) > bf86: 48 89 55 18 mov %rdx,0x18(%rbp) > bf8a: 44 89 c0 mov %r8d,%eax > bf8d: 88 45 20 mov %al,0x20(%rbp) > CONST LIST_ENTRY *Ptr; > > // > // Test the validity of List and Node > // > ASSERT (List != NULL); > bf90: 48 b8 fd c8 00 00 00 movabs $0xc8fd,%rax > bf97: 00 00 00 > bf92: R_X86_64_64 DebugAssertEnabled > bf9a: ff d0 callq *%rax > bf9c: 84 c0 test %al,%al So, some list-handling BaseLib code got executed as part of the SMM Core, and at some point an ASSERT() -> DebugAssertEnabled() function call caused the SMM stack to overflow. (6) Given that I had been staring at SmiPFHandler() for a day or more now [UefiCpuPkg/PiSmmCpuDxeSmm/X64/PageTbl.c]: > // > // If a page fault occurs in SMRAM range, it should be in a SMM stack guard > page. > // > if ((FeaturePcdGet (PcdCpuSmmStackGuard)) && > (PFAddress >= mCpuHotPlugData.SmrrBase) && > (PFAddress < (mCpuHotPlugData.SmrrBase + mCpuHotPlugData.SmrrSize))) { > DEBUG ((EFI_D_ERROR, "SMM stack overflow!\n")); > CpuDeadLoop (); > } I immediately checked the declaration and default value of "PcdCpuSmmStackGuard" in "UefiCpuPkg.dec": > ## Indicates if SMM Stack Guard will be enabled. > # If enabled, stack overflow in SMM can be caught which eases > debugging.<BR><BR> > # TRUE - SMM Stack Guard will be enabled.<BR> > # FALSE - SMM Stack Guard will be disabled.<BR> > # @Prompt Enable SMM Stack Guard. > gUefiCpuPkgTokenSpaceGuid.PcdCpuSmmStackGuard|FALSE|BOOLEAN|0x1000001C Are you *kidding* me? "Eases debugging"? Why on earth does this FeaturePCD not default to TRUE? Okay, okay, let's see the SMM stack size -- there must be such a tuneable, right? Certainly: > ## Specifies stack size in bytes for each processor in SMM. > # @Prompt Processor stack size in SMM. > gUefiCpuPkgTokenSpaceGuid.PcdCpuSmmStackSize|0x2000|UINT32|0x32132105 A measly 8KB. :( (7) At this point I changed PcdCpuSmmStackGuard to TRUE in the "OvmfPkg/OvmfPkgIa32X64.dsc" file, rebuilt OVMF, and re-ran the test. Sure enough, the SMM fault handler logged the following, under both TCG and KVM: > SMM stack overflow! Then I doubled "PcdCpuSmmStackSize" too, in "OvmfPkg/OvmfPkgIa32X64.dsc", and now everything works fine. :) I will submit a patch for UefiCpuPkg.dec, to change the default of PcdCpuSmmStackGuard to TRUE. Such critical safe-guards must be opt-out, not opt-in, for platforms! (Note that when it fires, it calls CpuDeadLoop(), which is never compiled out.) I will also submit a patch for the OVMF DSC files, setting PcdCpuSmmStackSize to 0x4000 (16KB). Thanks Laszlo _______________________________________________ edk2-devel mailing list [email protected] https://lists.01.org/mailman/listinfo/edk2-devel
