UEFI Runtime Services Bug

[GMN2020]

Fusion Pro 11.5.1 on MAC Host

UEFI provides a number of "Boot Services" and "Runtime Services".   Boot Services are used in the pre-boot environment via physical addressing, while Runtime Services are available in both the pre-boot and post-boot environments.   The transition between these phases of operation occurs with a call to the Boot Service "ExitBootServices" followed by a call to another Boot Service "SetVirtualAddressMap".    Once these two procedures have been called, the "Boot Services" dispatch table is to be zeroed out, along with the UEFI System Table's pointer to the Boot Services table.   No further Boot Services should be called.

After calling SetVirtualAddressMap, the UEFI Runtime Services can be called from the virtual addresses supplied in the memory map argument passed to SetVirtualAddressMap.

UEFI updates its Runtime Service dispatch table to include these virtual addresses and notifications are issued to any UEFI components and drivers that need to know that we have switched to a runtime environment.

That's how it *should* work...

However, what is happening is that Fusion's UEFI implementation is incorrectly handling Runtime Service calls.   To illustrate these, I am calling a Runtime Service "GetTime" using its physical address BEFORE ExitBootServices.   This works fine, however, I have noticed by stepping through the code that Fusion has set up the "Boot" Services table (identified by it's ASCII signature) to contain the Runtime Service vectors.   How do I know?   Like I said, each table has an ASCII signature, in this case "BOOT_SERV", yet stepping through the code shows that it is correctly pulling the procedure pointer for GetTime from the expected position in a Runtime Services table.   Strange.

Now AFTER calling ExitBootServices and SetVirtualAddressMap, the Runtime Service call to GetTime is made again using its Virtual Address.   It fails.

Stepping through the code again, the code again tries to get the GetTime procedure from the "Boot" Service table but it has now been zeroed out! 

When I examine the EFI_SYSTEM_TABLE's pointer to the Boot Services table, it is correctly zero.

When I examine the EFI_SYSTEM_TABLE's pointer to the Runtime Services table, it is correct and each of the entries in the table is correct.  But the actual Runtime call to GetTime is still trying to access the Boot Services table.    This is clearly a bug in Fusions implementation of UEFI.   I will try this on both Workstation and ESXi shortly.   BTW, I have decades of experience with EFI/UEFI and OS Loaders and my code is running on hundreds of systems and other VM Hosts, so this is not a post from a confused newbie....  Just sayin'   ;^)

Has anyone else actually used UEFI Runtime Services in the post-boot, virtual environment?

[GMN2020]

I tried the same code on VMware Workstation and on ESXi and it fails in the same way.

The code works fine on every "hardware" platform produced by HP since 2007 and as a guest on

VirtualBox and KVM.   Only VMware products exhibit this inability to call UEFI Runtime Services.

I have noticed that all three VMware products report the same UEFI 1.0 version and I find very

little reference to actual use of UEFI services.   Am I to conclude that no other OS'es depend on

UEFI Runtime Services?  

BTW, I am with OpenVMS engineering and we are trying to add VMware as one of our supported

X86-64 VM Hosts.   Any insight into this problem would be helpful.

[wila]

Hi,

Not an expert on this field, but perhaps dariusd​ can help.

edit: You might also want to check out the partner program, as either OEM or TAP.

More info here: Become a Partner

--

Wil

[dariusd]

Thanks for the heads-up, wila​!  I've been a bit too busy lately to keep a proper eye on the Communities.

GMN2020​, while I start digging into the problem here, it'd be great if I could get some more information on this:

Now AFTER calling ExitBootServices and SetVirtualAddressMap, the Runtime Service call to GetTime is made again using its Virtual Address.   It fails.

Stepping through the code again, the code again tries to get the GetTime procedure from the "Boot" Service table but it has now been zeroed out!

There is no field for a GetTime procedure in the Boot Services table.  Can you provide a sample of the machine code which is performing this reference?

We use the standard EDK2 PcAtChipsetPkg implementation of GetTime, and I can not yet see any modifications we might have made to it which could cause it to attempt to reference the Boot Services table at runtime.  It's possible that one of our libraries is performing such a reference, but again I cannot yet see where/how/why..

We have an automated test which verifies that a call to GetTime works at runtime... but of course it is always possible that our test is succeeding due to some quirk of the test environment...

Anyhow, a snippet of disassembly of the problematic routine would be very helpful in understanding the problem.

Thanks,

--

Darius

[GMN2020]

This is rather long, but is should contain what you need.  

Thanks for looking into this.  Our company (VMS Software Inc.) are new members of your partners program, so if this should be directed somewhere else, let me know. 

PROBLEM:  Cannot call UEFI “Runtime” Services after ExitBootServices and SetVirtualAddressMap is called.

TESTED ON: VMware Fusion, Workstation and ESXi latest versions.

WORKS ON:  Hardware platforms, VirtualBox and KVM guests

THEORY: Although I don’t have VMware listings, stepping through a failing and a successful call to the GetTime runtime service code, it appears that both are attempting to access the “Boot” Services dispatch table in the internal implementation of this service. The “Boot” service table contains (correctly) zeros after ExitBootServices has been called. 

“GetTime” is a runtime service and so it’s implementation must not access the “Boot” services table once we are in a runtime state.  It is possible that the VMware code is trying to call “RaiseTPL” (a boot service) *18(%rax) or that a subtle error in the memory map may be involved, but I have found no evidence of this.

PSEUDO-CODE EXAMPLE:

// IN BOOT ENVIRONMENT

// CALL TIME SERVICE PHYSICALLY BEFORE EXITBOOTSERVICES

  Status = pRuntimeService->GetTime(&Time, NULL);

   if (Status == EFI_SUCCESS)

   {

         Print("Physical GetTime: %04hu-%02hhu-%02hhu\n",

           Time.Year, Time.Month, Time.Day);

   } 

    // GET THE LATEST MEMORY MAP KEY

    Status = pBootService->GetMemoryMap(

    &uqMM_Size,pMemMap,&uqMM_Key,&uqMM_DescSize,&ulMM_DescVer);

    // EXIT BOOT SERVICES

    Status = pBootService->ExitBootServices(uqHandle,uqMM_Key);

    if (Status != EFI_SUCCESS) return (SS$_BADPARAM); // FATAL

   // SET VIRTUAL ADDRESS MAP

   // The map Virtual Addresses have been assigned previously.

       Status = pRuntimeService->SetVirtualAddressMap(

        uqMM_MapSize,uqMM_DescSize,ulMM_DescVer, iqMM_PA);  

       if (Status != EFI_SUCCESS) return (SS$_PARTMAPPED); // FATAL

   // Flush the TB and cache one last time.

   uqCr0Value = __getReg(_X86_REG_CR0);

   __setReg(_X86_REG_CR0,uqCr0Value);   

   // Switch to the new VA's   

   exe$gpq_efi_system_table     = (int64) uqST_VA;

   exe$gpq_efi_runtime_services = (int64) uqRT_VA;  

// NOW IN RUNTIME ENVIRONMENT WITH VIRTUAL ADDRESSES

// CALL TIME SERVICE VIRTUALLY AFTER EXITBOOTSERVICES

   Status = exe$gpq_efi_runtime_services->GetTime(

        &EfiTime, NULL);

   if (Status == EFI_SUCCESS)

   {

         Print("Virtual GetTime: %04hu-%02hhu-%02hhu\n",

           EfiTime.Year,EfiTime.Month,EfiTime.Day);

   }

// END EXAMPLE  

BELOW IS THE UEFI MEMORY MAP INVOLVED IN THESE EXAMPLES

Final UEFI Memory Map, KEY: 0X152D

ACPI_NVS    0x00000000.00000000, 0x00000000.00000FFF

PrimaryOS   0x00000000.00001000, 0x00000000.0009EFFF

RT_data     0x00000000.0009F000, 0x00000000.0009FFFF

PrimaryOS   0x00000000.00100000, 0x00000000.001FFFFF

LoaderData  0x00000000.00200000, 0x00000000.002FFFFF

PrimaryOS   0x00000000.00300000, 0x00000000.003FFFFF

LoaderCode  0x00000000.00400000, 0x00000000.005FFFFF

LoaderData  0x00000000.00600000, 0x00000000.006FFFFF

PrimaryOS   0x00000000.00700000, 0x00000000.007FFFFF

LoaderData  0x00000000.00800000, 0x00000000.04DFFFFF

PrimaryOS   0x00000000.04E00000, 0x00000000.080E9FFF

RT_data     0x00000000.080EA000, 0x00000000.088D3FFF

PrimaryOS   0x00000000.088D4000, 0x00000000.08EC2FFF

BS_data     0x00000000.08EC3000, 0x00000000.0DA83FFF

PrimaryOS   0x00000000.0DA84000, 0x00000000.0DE4DFFF

LoaderCode  0x00000000.0DE4E000, 0x00000000.0E021FFF

BS_data     0x00000000.0E022000, 0x00000000.0E1F6FFF

LoaderCode  0X00000000.0E1F7000, 0x00000000.0E385FFF

PrimaryOS   0x00000000.0E386000, 0x00000000.0E46FFFF

LoaderCode  0x00000000.0E470000, 0x00000000.0E51EFFF

PrimaryOS   0x00000000.0E51F000, 0x00000000.0E547FFF

LoaderData  0x00000000.0E548000, 0x00000000.0E548FFF

PrimaryOS   0x00000000.0E549000, 0x00000000.0E54CFFF

LoaderData  0x00000000.0E54D000, 0x00000000.0E54EFFF

PrimaryOS   0x00000000.0E54F000, 0x00000000.0E553FFF

RT_data     0x00000000.0E554000, 0x00000000.0E582FFF

BS_data     0x00000000.0E583000, 0x00000000.0E5A8FFF

PrimaryOS   0x00000000.0E5A9000, 0x00000000.0E5B5FFF

LoaderData  0x00000000.0E5B6000, 0x00000000.0E5CEFFF

BS_data     0x00000000.0E5CF000, 0x00000000.0EA4FFFF

BS_code     0x00000000.0EA50000, 0x00000000.0EBE5FFF

BS_data     0x00000000.0EBE6000, 0x00000000.0EEE6FFF

BS_code     0x00000000.0EEE7000, 0x00000000.0EF27FFF

RT_code     0x00000000.0EF28000, 0x00000000.0EF30FFF

BS_code     0x00000000.0EF31000, 0x00000000.0EF43FFF

RT_code     0x00000000.0EF44000, 0x00000000.0EF49FFF

BS_code     0x00000000.0EF4A000, 0x00000000.0EF60FFF

RT_code     0x00000000.0EF61000, 0x00000000.0EF65FFF

BS_code     0x00000000.0EF66000, 0x00000000.0EF8AFFF

BS_data     0x00000000.0EF8B000, 0x00000000.0F3F6FFF

PrimaryOS   0x00000000.0F3F7000, 0x00000000.0F409FFF

BS_data     0x00000000.0F40A000, 0x00000000.0F441FFF

PrimaryOS   0x00000000.0F442000, 0x00000000.0F442FFF

BS_data     0x00000000.0F443000, 0x00000000.0F445FFF

PrimaryOS   0x00000000.0F446000, 0x00000000.0F447FFF

BS_data     0x00000000.0F448000, 0x00000000.0F448FFF

PrimaryOS   0x00000000.0F449000, 0x00000000.0F449FFF

BS_data     0x00000000.0F44A000, 0x00000000.0F44AFFF

PrimaryOS   0x00000000.0F44B000, 0x00000000.0F44BFFF

BS_data     0x00000000.0F44C000, 0x00000000.0F44CFFF

PrimaryOS   0x00000000.0F44D000, 0x00000000.0F44DFFF

BS_data     0x00000000.0F44E000, 0x00000000.0F44EFFF

PrimaryOS   0x00000000.0F44F000, 0x00000000.0F451FFF

BS_data     0x00000000.0F452000, 0x00000000.0F455FFF

PrimaryOS   0x00000000.0F456000, 0x00000000.0F45DFFF

BS_data     0x00000000.0F45E000, 0x00000000.0F45FFFF

PrimaryOS   0x00000000.0F460000, 0x00000000.0F463FFF

BS_data     0x00000000.0F464000, 0x00000000.0F465FFF

PrimaryOS   0x00000000.0F466000, 0x00000000.0F467FFF

BS_data     0x00000000.0F468000, 0x00000000.0F468FFF

PrimaryOS   0x00000000.0F469000, 0x00000000.0F46AFFF

BS_data     0x00000000.0F46B000, 0x00000000.0F46BFFF

PrimaryOS   0x00000000.0F46C000, 0x00000000.0F46CFFF

BS_data     0x00000000.0F46D000, 0x00000000.0F46EFFF

PrimaryOS   0x00000000.0F46F000, 0x00000000.0F46FFFF

BS_data     0x00000000.0F470000, 0x00000000.0F472FFF

PrimaryOS   0x00000000.0F473000, 0x00000000.0F492FFF

BS_data     0x00000000.0F493000, 0x00000000.0FC00FFF

PrimaryOS   0x00000000.0FC01000, 0x00000000.0FCACFFF

BS_data     0x00000000.0FCAD000, 0x00000000.0FCADFFF

PrimaryOS   0x00000000.0FCAE000, 0x00000000.0FCAFFFF

BS_data     0x00000000.0FCB0000, 0x00000000.0FDF6FFF

BS_code     0x00000000.0FDF7000, 0x00000000.0FEE6FFF

RT_code     0x00000000.0FEE7000, 0x00000000.0FF06FFF

RT_data     0x00000000.0FF07000, 0x00000000.0FF56FFF

ACPI_recl   0x00000000.0FF57000, 0x00000000.0FF72FFF

ACPI_NVS    0x00000000.0FF73000, 0x00000000.0FF76FFF

BS_data     0x00000000.0FF77000, 0x00000000.0FFBEFFF

BS_code     0x00000000.0FFBF000, 0x00000000.0FFFFFFF

PrimaryOS   0x00000000.10000000, 0x00000000.BFFFFFFF

PrimaryOS   0x00000001.00000000, 0x00000002.3FFFFFFF    

Reserved    0x00000000.000C0000, 0x00000000.000FFFFF

MemMapIO    0x00000000.FFC00000, 0x00000000.FFC29FFF

g_pSYSTEM_TABLE_PA:         0x0FF56018 in RT_data

g_pRUNTIME_SERVICES_PA:     0x0FF56B98 in RT_data

g_pBOOT_SERVICES_PA:        0x0FFD6440 in BS_code

ExitBootServices:           0x0FFC064B in BS_code

Handle:     0x0FCE0E18 in BS_data

Map Key:    0x152D

BELOW ARE THE VIRTUAL ADDRESSES MAPPED TO THE RUNTIME DESCRIPTORS

Map PA: 0x0009F000 as VA: 0xFFFF8300.0C589000, Len: 0x1000,

Map PA: 0x080EA000 as VA: 0xFFFF8300.0C58A000, Len: 0x7EA000,

Map PA: 0x0E554000 as VA: 0xFFFF8300.0CD74000, Len: 0x2F000,

Map PA: 0x0EF28000 as VA: 0xFFFF8300.0CDA4000, Len: 0x9000,

Map PA: 0x0EF44000 as VA: 0xFFFF8300.0CDAE000, Len: 0x6000,

Map PA: 0x0EF61000 as VA: 0xFFFF8300.0CDB5000, Len: 0x5000,

Map PA: 0x0FEE7000 as VA: 0xFFFF8300.0CDBB000, Len: 0x20000,

Map PA: 0x0FF07000 as VA: 0xFFFF8300.0CDDD000, Len: 0x50000,

Map PA: 0xFFC00000 as VA: 0xFFFF8300.0CE2E000, Len: 0x2A000, MMIO

+ UEFI SYSTEM_TABLE_VA:    0xFFFF8300.0CE2C018

+ UEFI RUNTIME_TABLE_VA:   0xFFFF8300.0CE2CB98

BELOW IS A SUCCESSFUL CALL TO RUNTIME SERVICE “GetTime” PRIOR TO CALLING

EXITBOOTSERVICES AND USING PHYSICAL ADDRESSES.

RS: 0x00000000.0FF56B98,    BS: 0x00000000.0FFD6440

GetTime at: 0x00000000.0EF2D1C9

RDI/00000000.0EF2D1C9,  // GetTime

RCX/00000000.00422450,  // Time struct

RDX/00000000.00000000   // NULL

// CALL TO GetTime PA

00000000.004B86DB!callq   *%rdi RDI/00000000.0EF2D1C9 S

00000000.0EF2D1C9!pushq   %rbp S

00000000.0EF2D1CA!leaq    00001EDF(%rip),%r8 S

00000000.0EF2D1D1!movq    %rsp,%rbp R8/00000000.0EF2F0B0 S

00000000.0EF2D1D4!subq    $20,%rsp RBP/00000000.0FF286A0 S

00000000.0EF2D1D8!callq   000005D1 S

00000000.0EF2D7AE!pushq   %rbp S

00000000.0EF2D7AF!movq    %rsp,%rbp S

00000000.0EF2D7B2!pushq   %r12 RBP/00000000.0FF28670 S

00000000.0EF2D7B4!movq    %r8,%r12 R8/00000000.0EF2F0B0 S

00000000.0EF2D7B7!pushq   %rdi RDI/00000000.0EF2D1C9 S

00000000.0EF2D7B8!movq    $80000000.00000002,%rdi S

00000000.0EF2D7C2!pushq   %rsi RDI/80000000.00000002 S

00000000.0EF2D7C3!movq    %rdx,%rsi S

00000000.0EF2D7C6!pushq   %rbx RSI/00000000.00000000 S

00000000.0EF2D7C7!movq    %rcx,%rbx RCX/00000000.0FF28948 S

00000000.0EF2D7CA!subq    $20,%rsp S

00000000.0EF2D7CE!testq   %rcx,%rcx S

00000000.0EF2D7D1!je      000000FB S

00000000.0EF2D7D7!callq   00000E42 S

00000000.0EF2E61E!pushq   %rbp RBP/00000000.0FF28670 S

00000000.0EF2E61F!movb    00000B64(%rip),%al S

00000000.0EF2E625!movq    %rsp,%rbp %AL/00 S

00000000.0EF2E628!leaveq S

00000000.0EF2E629!retq S

00000000.0EF2D7DC!testb   %al,%al S

00000000.0EF2D7DE!jne     08 S

00000000.0EF2D7E0!movq    %r12,%rcx R12/00000000.0EF2F0B0 S

00000000.0EF2D7E3!callq   00001031 S

00000000.0EF2E819!pushq   %rbp RBP/00000000.0FF28670 S

00000000.0EF2E81A!movq    %rsp,%rbp S

00000000.0EF2E81D!pushq   %rbx RBX/00000000.0FF28948 S

00000000.0EF2E81E!movq    %rcx,%rbx RCX/00000000.0EF2F0B0 S

00000000.0EF2E821!subq    $28,%rsp S

00000000.0EF2E825!movq    0000093C(%rip),%rax S

00000000.0EF2E82C!movq    (%rcx),%rcx RAX/00000000.0FFD6440 S

// 0FFD6440 is the PA of the EFI_BOOT_SERVICES Table

00000000.0EF2E82F!callq   *18(%rax) RAX/00000000.0FFD6440 S

00000000.0FFC8999!pushq   %rbp

// Examining the BOOT Services table.

FFD6440/56524553.544F4F42           // ASCII Sig: BOOTSERV

00000000.0FFD6448/00000178.0002001F 

00000000.0FFD6450/00000000.D81FB251 

00000000.0FFD6458/00000000.0FFC8999  <- *18(%rax)  “RaiseTPL”

00000000.0FFD6460/00000000.0FFC89D2 

00000000.0FFD6468/00000000.0FFD1E0F 

00000000.0FFD6470/00000000.0FFD1AB4 

00000000.0FFD6478/00000000.0FFD1113 

00000000.0FFD6480/00000000.0FFD0ACF 

00000000.0FFD6488/00000000.0FFD0DCD 

00000000.0FFD6490/00000000.0FFC90BC 

00000000.0FFD6498/00000000.0FFC8C1E 

00000000.0FFD64A0/00000000.0FFC9242 S

// End of examines

00000000.0FFC899A!movq    %rsp,%rbp S

00000000.0FFC899D!pushq   %rsi RSI/00000000.00000000 S

00000000.0FFC899E!movq    %rcx,%rsi RCX/00000000.00000008 S

00000000.0FFC89A1!pushq   %rbx S

00000000.0FFC89A2!subq    $20,%rsp S

00000000.0FFC89A6!cmpq    $1E,%rcx S

00000000.0FFC89AA!movq    0000E7DF(%rip),%rbx S

00000000.0FFC89B1!jbe     0D S

00000000.0FFC89C0!movq    %rsi,0000E7C9(%rip) S

00000000.0FFC89C7!movq    %rbx,%rax S

00000000.0FFC89CA!addq    $20,%rsp S

00000000.0FFC89CE!popq    %rbx S

00000000.0FFC89CF!popq    %rsi S

00000000.0FFC89D0!leaveq S

00000000.0FFC89D1!retq S

00000000.0EF2E832!movl    $00000002,10(%rbx) S

00000000.0EF2E839!movq    %rax,08(%rbx) RAX/00000000.00000004 S

00000000.0EF2E83D!addq    $28,%rsp S

00000000.0EF2E841!popq    %rbx S

00000000.0EF2E842!leaveq S

00000000.0EF2E843!retq S

00000000.0EF2D7E8!movl    $000186A0,%ecx S

00000000.0EF2D7ED!callq   -0000039A O

00000000.0EF2D7F2!testq   %rax,%rax S

00000000.0EF2D7F5!movq    %rax,%rdi S

00000000.0EF2D7F8!jns     1A S

00000000.0EF2D814!movl    $0000000B,%ecx S

00000000.0EF2D819!callq   -0000054B O

00000000.0EF2D81E!xorl    %ecx,%ecx S

00000000.0EF2D820!movb    %al,%dil S

00000000.0EF2D823!callq   -00000555 O

00000000.0EF2D828!movl    $00000002,%ecx S

00000000.0EF2D82D!movb    %al,06(%rbx) S

00000000.0EF2D830!callq   -00000562 O

00000000.0EF2D835!movl    $00000004,%ecx S

00000000.0EF2D83A!movb    %al,05(%rbx) S

00000000.0EF2D83D!callq   -0000056F O

00000000.0EF2D842!movl    $00000007,%ecx S

00000000.0EF2D847!movb    %al,04(%rbx) S

00000000.0EF2D84A!callq   -0000057C O

00000000.0EF2D84F!movl    $00000008,%ecx S

00000000.0EF2D854!movb    %al,03(%rbx) S

00000000.0EF2D857!callq   -00000589 O

00000000.0EF2D85C!movl    $00000009,%ecx S

00000000.0EF2D861!movb    %al,02(%rbx) S

00000000.0EF2D864!callq   -00000596 O

00000000.0EF2D869!movzbl  %al,%eax S

00000000.0EF2D86C!movw    %ax,(%rbx) S

00000000.0EF2D86F!callq   00000DAA O

00000000.0EF2D874!testb   %al,%al S

00000000.0EF2D876!jne     08 S

00000000.0EF2D878!movq    %r12,%rcx O

00000000.0EF2D87B!callq   00000FC4 S

00000000.0EF2E844!pushq   %rbp S

00000000.0EF2E845!movq    %rsp,%rbp O

00000000.0EF2E848!subq    $20,%rsp O

00000000.0EF2E84C!movq    08(%rcx),%rax O

00000000.0EF2E850!movl    $00000001,10(%rcx) O

00000000.0EF2E857!movq    %rax,%rcx O

00000000.0EF2E85A!movq    00000907(%rip),%rax O

00000000.0EF2E861!callq   *20(%rax) O

00000000.0EF2E864!leaveq O

00000000.0EF2E865!retq O

00000000.0EF2D880!movl    18(%r12),%eax O

00000000.0EF2D885!movb    %dil,%dl O

00000000.0EF2D888!movq    %rbx,%rcx O

00000000.0EF2D88B!movw    %ax,0C(%rbx) O

00000000.0EF2D88F!movb    1A(%r12),%al O

00000000.0EF2D894!movb    %al,0E(%rbx) O

00000000.0EF2D897!callq   -0000052E O

00000000.0EF2D89C!testq   %rax,%rax O

00000000.0EF2D89F!js      27 O

00000000.0EF2D8A1!movq    %rbx,%rcx O

00000000.0EF2D8A4!callq   -00000330 O

00000000.0EF2D8A9!testq   %rax,%rax O

00000000.0EF2D8AC!js      1A O

00000000.0EF2D8AE!xorl    %edi,%edi O

00000000.0EF2D8B0!testq   %rsi,%rsi O

00000000.0EF2D8B3!je      1D O

00000000.0EF2D8D2!addq    $20,%rsp O

00000000.0EF2D8D6!movq    %rdi,%rax O

00000000.0EF2D8D9!popq    %rbx O

00000000.0EF2D8DA!popq    %rsi O

00000000.0EF2D8DB!popq    %rdi O

00000000.0EF2D8DC!popq    %r12 O

00000000.0EF2D8DE!leaveq O

00000000.0EF2D8DF!retq O

00000000.0EF2D1DD!leaveq O

00000000.0EF2D1DE!retq O

00000000.004B86DD!addq    $58,%rsp O

00000000.004B86E1!retq O

00000000.00439A8A!movq    %rax,-00000090(%rbp) O

00000000.00439A91!cmpq    $00000000,-00000090(%rbp) O

00000000.00439A9C!sete    %r11l O

00000000.00439AA0!testb   $01,%r11l O

00000000.00439AA4!jne     02 O

00000000.00439AA8!movq    000D91F1(%rip),%rdi O

00000000.00439AAF!movzwl  -00000148(%rbp),%eax O

00000000.00439AB6!movzbl  -00000146(%rbp),%ecx O

00000000.00439ABD!movzbl  -00000145(%rbp),%edx O

00000000.00439AC4!movslq  %eax,%rsi O

00000000.00439AC7!movslq  %ecx,%r8 O

00000000.00439ACA!movslq  %edx,%rcx O

00000000.00439ACD!movq    %r8,%rdx O

00000000.00439AD0!movl    $00000400,%eax O

00000000.00439AD5!callq   -0000E22A O

Physical GetTime: 2020-01-14  // SUCCESSFUL CALL

// NOW THE SAME CALL AFTER EXITBOOTSERVICES

// USING VIRTUAL ADDRESSES

RS: 0xFFFF8300.0E42CB98, BS: 0x00000000.00000000

GetTime at: 0xFFFF8300.0E3A91C9

RDI/FFFF8300.0E3A91C9  // VA of GetTime

00000000.004B861B!callq   *%rdi S

// Call to GetTime VA

FFFF8300.0E3A91C9!pushq   %rbp S

FFFF8300.0E3A91CA!leaq    00001EDF(%rip),%r8 RBP/00000000.0FF28A90 S

FFFF8300.0E3A91D1!movq    %rsp,%rbp S

FFFF8300.0E3A91D4!subq    $20,%rsp RBP/00000000.0FF286B0 S

FFFF8300.0E3A91D8!callq   000005D1 RSP/00000000.0FF28690 S

FFFF8300.0E3A97AE!pushq   %rbp S

FFFF8300.0E3A97AF!movq    %rsp,%rbp RBP/00000000.0FF286B0 S

FFFF8300.0E3A97B2!pushq   %r12 RBP/00000000.0FF28680 S

FFFF8300.0E3A97B4!movq    %r8,%r12 R12/00000000.00528DD0 S

FFFF8300.0E3A97B7!pushq   %rdi R12/FFFF8300.0E3AB0B0 S

FFFF8300.0E3A97B8!movq    $80000000.00000002,%rdi RDI/FFFF8300.0E3A91C9 S

FFFF8300.0E3A97C2!pushq   %rsi RDI/80000000.00000002 S

FFFF8300.0E3A97C3!movq    %rdx,%rsi RSI/00000000.0FF28948 S

FFFF8300.0E3A97C6!pushq   %rbx RSI/00000000.00000000 S

FFFF8300.0E3A97C7!movq    %rcx,%rbx RBX/00000000.000FFC29 S

FFFF8300.0E3A97CA!subq    $20,%rsp RBX/00000000.0FF28948 S

FFFF8300.0E3A97CE!testq   %rcx,%rcx RCX/00000000.0FF28948 S

FFFF8300.0E3A97D1!je      000000FB S

FFFF8300.0E3A97D7!callq   00000E42 S

FFFF8300.0E3AA61E!pushq   %rbp RBP/00000000.0FF28680 S

FFFF8300.0E3AA61F!movb    00000B64(%rip),%al S

FFFF8300.0E3AA625!movq    %rsp,%rbp %AL/00 S

FFFF8300.0E3AA628!leaveq S

FFFF8300.0E3AA629!retq S

FFFF8300.0E3A97DC!testb   %al,%al S

FFFF8300.0E3A97DE!jne     08 S

FFFF8300.0E3A97E0!movq    %r12,%rcx R12/FFFF8300.0E3AB0B0 S

FFFF8300.0E3A97E3!callq   00001031 S

FFFF8300.0E3AA819!pushq   %rbp RBP/00000000.0FF28680 S

FFFF8300.0E3AA81A!movq    %rsp,%rbp S

FFFF8300.0E3AA81D!pushq   %rbx RBX/00000000.0FF28948 S

FFFF8300.0E3AA81E!movq    %rcx,%rbx RCX/FFFF8300.0E3AB0B0 S

FFFF8300.0E3AA821!subq    $28,%rsp S

FFFF8300.0E3AA825!movq    0000093C(%rip),%rax S

FFFF8300.0E3AA82C!movq    (%rcx),%rcx

// Examine of RAX shows it contains the PA of the “BOOT” Services // Table.

RAX/00000000.0FFD6440 S

FFFF8300.0E3AA82F!callq   *18(%rax)

// DEBUG ACCESS VIOLATION AT 0x00000000.00000000

Console Brk at 00000000.00000000

// Examine RAX

RAX/00000000.0FFD6440  <- PA of “BOOT” Services Table

// Examine the BOOT Services Table Entries

FFD6440/00000000.00000000 

00000000.0FFD6448/00000000.00000000 

00000000.0FFD6450/00000000.00000000 

00000000.0FFD6458/00000000.00000000 

00000000.0FFD6460/00000000.00000000 

00000000.0FFD6468/00000000.00000000 

00000000.0FFD6470/00000000.00000000 

00000000.0FFD6478/00000000.00000000 

00000000.0FFD6480/00000000.00000000 

00000000.0FFD6488/00000000.00000000 

00000000.0FFD6490/00000000.00000000 

00000000.0FFD6498/00000000.00000000 

00000000.0FFD64A0/00000000.00000000 

00000000.0FFD64A8/00000000.00000000 

00000000.0FFD64B0/00000000.00000000 

00000000.0FFD64B8/00000000.00000000 

00000000.0FFD64C0/00000000.00000000

The BOOT Services Table contains zeros, which is the expected state after ExitBootServices has been called.

The question is, why is the RUNTIME implementation of GetTime touching the

BOOT Services table? *18(%rax) RAX/00000000.0FFD6440.  It appears to be touching BS->RaiseTPL during its

RUNTIME implementation or it is unaware of the switch to runtime mode, but there were no errors from the

call to ExitBootServices or SetVirtualAddressMap.  This same code works on every hardware platform and other

VM Hosts, but fails on VMware Hosts. 

[dariusd]

At Runtime, the conditional jump at FFFF8300.0E3A97DE should have been taken.  Here's the corresponding bits of source inlined into the trace:

  if (!EfiAtRuntime ()) {

FFFF8300.0E3A97D7!callq   00000E42 S

{

FFFF8300.0E3AA61E!pushq   %rbp RBP/00000000.0FF28680 S

  return mEfiAtRuntime;

FFFF8300.0E3AA61F!movb    00000B64(%rip),%al S

}

FFFF8300.0E3AA625!movq    %rsp,%rbp %AL/00 S

FFFF8300.0E3AA628!leaveq S

FFFF8300.0E3AA629!retq S

FFFF8300.0E3A97DC!testb   %al,%al S

FFFF8300.0E3A97DE!jne     08 S        <===== should be taken at runtime

    EfiAcquireLock (&Global->RtcLock);

FFFF8300.0E3A97E0!movq    %r12,%rcx R12/FFFF8300.0E3AB0B0 S

FFFF8300.0E3A97E3!callq   00001031 S

The trace shows that mEfiAtRuntime read as zero, which means either that the module's Exit Boot Services event has not fired, or its memory is not mapped properly at runtime, or mEfiAtRuntime's storage was clobbered by something.

Can you set a breakpoint at the module's Exit Boot Services handler function?  It will be located at PcRtc + 0x255b.  See if it fires and sets mEfiAtRuntime in the PcRtc module.

    255b:       55                      push   %rbp

    255c:       c6 05 26 0c 00 00 01    movb   $0x1,0xc26(%rip)        # 0x3189

    2563:       48 89 e5                mov    %rsp,%rbp

    2566:       c9                      leaveq

    2567:       c3                      retq  

and double check the virtual mapping for that page, too.

Thanks,

--

Darius

[GMN2020]

Can you help me out with the value of PcAtRtc?   

I have examined the offset 0x255B from the entry address of ExitBootServices and also from the first internal call within ExitBootServices and neither shows a "push %rbp" instruction.

Keep in mind that I have no listings to work with.   Is PcAtRtc a symbolic name?   If so, I will need its address.

The call to ExitBootServices did not return a bad status, but I have noticed that there is some sensitivity to code sequence that I have not seen on other platforms.  For example, if I insert a memory fence or another Boot Service call just prior to ExitBootServices, I can cause ExitBootServices to fail.  If we can't nail this down, I can provide another example where ExitBootServices fails.

I also wanted to point out that I included a dump of the memory map PA's in the earlier reply if that helps.

Gary

[GMN2020]

oops,  "PcRtc" is the address I need, assuming this is the base of some module or routine.

[GMN2020]

...or just the PA of mEfiAtRuntime would suffice. 

I could check to see that it is set right after ExitBS and again after SetVirtualAddressMap to see if we have stomped on it.

I see you're on the other side of the planet and hopefully safe from the fires! 

[GMN2020]

I was able to locate the routine that checks the mEfiAtRuntime flag and the assy:

testb al,al     <- Which is a curious use of the instruction, but I assume this just sets the condition codes for al.

jne 08          <- should be taken at runtime

Just before a runtime call, al = 0

When I deposit al = 1 the jump is taken and the runtime service completes successfully.

Next, I saved the function address (PA) of GetTime and called it AFTER ExitBS but BEFORE SetVirtual and

stepping into the call, I find the mEfiAtRuntime flag is NOT set.

Calling GetTime using PA's in between ExitBS and SetVirtual is not generally something one would do, so

it may not have worked anyway, but I was able to step to the point where the flag was being checked and it

was zero.

So this would appear to confirm that we are returning from ExitBootServices without the EfiAtRuntime flag

getting set, but with no error status.   Since at this point we had not yet called SetVirtualAddressMap, it would

seem to rule out a corrupt VA map.

So the mystery is, what could cause this? 

[dariusd]

Apologies for not explaining.  To find the PcRtc module in memory, go to the EFI Shell (turn off UEFI Secure Boot for the VM if necessary) and run:

   dh -p Image -b

and look for the Image(PcRtc) entry.  Its handle number is on the left of that text, e.g. in a test VM here it says "55: Image(PcRtc)", so the handle number is 55, but it could be different on yours.  Then run:

   dh 55

and it will show the image base address (ImageBase).  That's the address of the PcRtc module.

--

Darius

[dariusd]

Calling GetTime after ExitBS and before SetVirtual is unconventional and probably uncommon, but it should certainly succeed.  Your experiment does seem to have eliminated the possibility of a virtual memory issue.

The ExitBootServices implementation we use is essentially unchanged from that in UDK2017: edk2/DxeMain.c at vUDK2017 · tianocore/edk2 · GitHub

I think we have only altered it to add an "ExitBootServices failed: <reason>" log message to vmware.log if the ExitBootServices operation fails – does any such message appear in your VM's vmware.log?

In the absence of memory corruption, I do not see anything in our codebase which could cause ExitBootServces to return EFI_SUCCESS without the PcRtc module's ExitBootServices event callback firing and setting that module's mEfiAtRuntime flag.  The call to CoreNotifySignalList at DxeMain.c line 765​ should unconditionally fire all the registered ExitBS notification functions.

So it does seem to suggest memory corruption... but we still have no answer for the who/how/what/where/why.

Does your trace say whether PcRtc's ExitBootServices handler (at its ImageBase + 0x255b) is being called during your bootloader's call to gBS->ExitBootServices?

(P.S.  I'm not on the other side of the world... You are!  :smileysilly:  I'm personally safe from the fires for now, thanks, but there's plenty of fire season left, and still not enough rain.  Fingers crossed!  And best wishes to those who are recovering from the worst of it.)

--

Darius

[GMN2020]

My log file shows what appears to be a successful switch to runtime:

2020-01-22T17:57:38.993Z| vcpu-0| I125: Guest: Firmware has transitioned to runtime.

2020-01-22T17:57:39.936Z| vcpu-0| I125: Tools: Running status rpc handler: 0 => 1.

2020-01-22T17:57:39.936Z| vcpu-0| I125: Tools: Changing running status: 0 => 1.

However, it never called the notification routine that you suggested setting a breakpoint on.

There was a minor difference in offsets.  My PcRtc base address was: CFAD000 + 255B = CFAF55B

But the assy code in your example appears at CFAF57B, so there is a minor difference in

the builds we are using.  Nonetheless, I set both breakpoint addresses and it didn't hit

either location. Stepping through the code it was in the vicinity, but never hit the routine.

The memory range containing PcRtc is marked as Runtime Code, which seems correct.

So it seems that the notification event is not firing. I will look through the UDK code and

see if I can spot anything.  I have noticed that there is some relationship with TPL level.

If I call RaiseTPL to either NOTIFY or APPLICATION, ExitBootServices at least completes.  If

I don't call RaiseTPL first, ExitBootServices hangs. 

[dariusd]

Ahhhh...

If I call RaiseTPL to either NOTIFY or APPLICATION, ExitBootServices at least completes.  If
I don't call RaiseTPL first, ExitBootServices hangs.

That's a fairly major problem.  Calling ExitBootServices at anything other than TPL_APPLICATION violates the EFI spec – refer to the table "TPL Restrictions" at the start of the chapter "Services — Boot Services".  A hang calling ExitBootServices at TPL_APPLICATION suggests that we already have memory corruption at this point.

Is this something you can readily distill down to a minimal repro case?

--

Darius

[GMN2020]

You may have read this wrong.  When I RaiseTPL to APPLICATION, ExitBS completes with no errors (but no EfiAtRuntime flag set).

If I don't call RaiseTPL, ExitBS hangs.   The reason I mentioned TPL is because I am thinking it could be related to the lack of

firing of the ExitBS notification?  

I agree that this is probably a memory corruption and hopefully on my end, but we boot on a pretty wide variety of platforms,

so that makes this an interesting bug.  I will take another look at the memory map today.