#16 Crash in qemu + OVMF after a call to DEBUG()

Unstable_(example)
closed
None
5
2015-02-17
2014-06-16
No

Complete thread at https://sourceforge.net/p/edk2/mailman/edk2-devel/thread/CAGstE8C-74qwYcaZaajbqy_-ncZcginRqZuQEHM_owDDKfVYog%40mail.gmail.com/#msg32333486

The patch is not present in the latest git commit ecfd1ded9a799c3a572d4eb7fbb52582fe4d3390
I create a bug report so the patch is not lost.

On 06/02/14 15:42, Ludovic Rousseau wrote:

Using my own build OVMF (edk2 revision 15538) I do not get any display
in the serial console and the qemu is consuming 100% CPU untill I kill
it.

If I uncomment the 1st Print() call I have:
Print(L"a\n");
DEBUG(( D_INFO, (CHAR8 )"D_INFO\r\n"));
//Print(L"b\n");
DEBUG(( D_ERROR, (CHAR8
)"D_ERROR\r\n"));
//Print(L"c\n");

And the serial output is:
FS0:> debug1.efi
a
!!!! X64 Exception Type - 000000000000000E CPU Apic ID - 00000000 !!!!
RIP - 0000000006BA58DE, CS - 0000000000000028, RFLAGS - 0000000000000287
ExceptionData - 0000000000000000
RAX - FFFFFFFFFFFFFFF0, RCX - 0000000000000000, RDX - 0000000000000007
RBX - 0000000080000000, RSP - 0000000007F6A4F0, RBP - 0000000007F6A530
RSI - 000000000000000E, RDI - 0000000006BAA790
R8 - 0000000000000000, R9 - 0000000007F69EA7, R10 - 00000000069A169D
R11 - 0000000000000040, R12 - 0000000000000005, R13 - 0000000000000000
R14 - 0000000000000000, R15 - 0000000000000000
DS - 0000000000000008, ES - 0000000000000008, FS - 0000000000000008
GS - 0000000000000008, SS - 0000000000000008
CR0 - 0000000080000033, CR2 - FFFFFFFFFFFFFFF0, CR3 - 0000000007F09000
CR4 - 0000000000000668, CR8 - 0000000000000000
DR0 - 0000000000000000, DR1 - 0000000000000000, DR2 - 0000000000000000
DR3 - 0000000000000000, DR6 - 00000000FFFF0FF0, DR7 - 0000000000000400
GDTR - 0000000007EF2D98 000000000000003F, LDTR - 0000000000000000
IDTR - 0000000007C1E018 0000000000000FFF, TR - 0000000000000000
FXSAVE_STATE - 0000000007F6A150
!!!! Find PE image
/home/lroussea/Documents/UEFI/edk2/Build/OvmfX64/DEBUG_GCC47/X64/MdeModulePkg/Universal/Console/ConSplitterDxe/ConSplitterDxe/DEBUG/ConSplitterDxe.dll
(ImageBase=0000000006B9F000, EntryPoint=0000000006B9F2AF) !!!!

Attached is a gzip compressed version of my
/home/lroussea/Documents/UEFI/edk2/Build/OvmfX64/DEBUG_GCC47/X64/MdeModulePkg/Universal/Console/ConSplitterDxe/ConSplitterDxe/DEBUG/ConSplitterDxe.dll
file. I hope that is OK for the mailing list.

(1) For the file you attached:

$ objdump --file-headers ConSplitterDxe.dll
...
start address 0x00000000000002cf

(2) The crash dump above says:
EntryPoint=0000000006B9F2AF
ImageBase=0000000006B9F000

--> EntryPoint-ImageBase = 0x2AF

If you compare the EntryPoint offset 0x2AF against the (relative) start
address 0x2cf from (1), you can see that whatever the crash dump reports
needs to be incremented by 0x20 (== 0x2cf-0x2AF) to get an offset that
objdump lists:

AbsDumpAddress - AbsDumpImageBase + 0x20 == objdump offset

(eg. for the entry point, 0x6B9F2AF - 0x6B9F000 + 0x20 == 0x2CF)

(3) So, let's apply the same formula to the RIP:

RIP - ImageBase + 0x20 ==
0x6BA58DE - 0x6B9F000 + 0x20 == 0x68FE

(4) Let's see what the disassembly says:

$ objdump -S ConSplitterDxe.dll
...

00000000000068d6 <ConSplitterTextOutSetAttribute>:
68d6: 55 push %rbp
68d7: 48 89 e5 mov %rsp,%rbp
68da: 48 83 ec 40 sub $0x40,%rsp
68de: 48 89 4d 10 mov %rcx,0x10(%rbp)
68e2: 48 89 55 18 mov %rdx,0x18(%rbp)
68e6: 48 b8 e2 88 00 00 00 movabs $0x88e2,%rax
68ed: 00 00 00
68f0: ff d0 callq %rax
68f2: 84 c0 test %al,%al
68f4: 74 3e je 6934 <ConSplitterTextOutSetAttribute+0x5e>
68f6: 48 8b 45 10 mov 0x10(%rbp),%rax
68fa: 48 83 e8 10 sub $0x10,%rax
==> 68fe: 48 8b 00 mov (%rax),%rax
6901: 48 3d 54 6f 53 70 cmp $0x70536f54,%rax
6907: 74 2b je 6934 <ConSplitterTextOutSetAttribute+0x5e>
6909: 49 b8 1c bb 00 00 00 movabs $0xbb1c,%r8
6910: 00 00 00
6913: ba cb 11 00 00 mov $0x11cb,%edx
6918: 48 b9 28 ba 00 00 00 movabs $0xba28,%rcx
691f: 00 00 00
6922: 48 b8 00 88 00 00 00 movabs $0x8800,%rax
6929: 00 00 00
692c: ff d0 callq
%rax

This function is the SetAttribute() member of the public
EFI_SIMPLE_TEXT_OUTPUT_PROTOCOL interface that ConSplitterDxe installs,
so it can be called by anyone.

The mov instruction at the marker crashes; it tries to "dereference" RAX
and load the value stored at that address into RAX (basically, RAX =
*RAX). According to CR2 (see Jeff's previous email), we get a page fault
for trying to dereference a pointer with value 0xFFFFFFFFFFFFFFF0, and
indeed if you look at the RAX value in the register dump, that's what
RAX contains.

(5) Let's correlate the above disassembly with the source code (at SVN
r15538). I claim that in the following code:

EFI_STATUS
EFIAPI
ConSplitterTextOutSetAttribute (
IN EFI_SIMPLE_TEXT_OUTPUT_PROTOCOL This,
IN UINTN Attribute
)
{
EFI_STATUS Status;
TEXT_OUT_SPLITTER_PRIVATE_DATA
Private;
UINTN Index;
EFI_STATUS ReturnStatus;

Private = TEXT_OUT_SPLITTER_PRIVATE_DATA_FROM_THIS (This);

the TEXT_OUT_SPLITTER_PRIVATE_DATA_FROM_THIS() macro crashes. Namely,

TEXT_OUT_SPLITTER_PRIVATE_DATA_FROM_THIS (This)

expands to

CR (This,
TEXT_OUT_SPLITTER_PRIVATE_DATA,
TextOut,
TEXT_OUT_SPLITTER_PRIVATE_DATA_SIGNATURE
)

expands to

(DebugAssertEnabled () && (BASE_CR (This, TEXT_OUT_SPLITTER_PRIVATE_DATA, TextOut)->Signature != TEXT_OUT_SPLITTER_PRIVATE_DATA_SIGNATURE)) ?
(TEXT_OUT_SPLITTER_PRIVATE_DATA *) (_ASSERT (CR has Bad Signature), This) :
BASE_CR (This, TEXT_OUT_SPLITTER_PRIVATE_DATA, TextOut)

Let's consider just the condition,

DebugAssertEnabled () &&
BASE_CR (This, TEXT_OUT_SPLITTER_PRIVATE_DATA, TextOut)->Signature != TEXT_OUT_SPLITTER_PRIVATE_DATA_SIGNATURE

which means

DebugAssertEnabled () &&
BASE_CR (This, TEXT_OUT_SPLITTER_PRIVATE_DATA, TextOut)->Signature != SIGNATURE_32 ('T', 'o', 'S', 'p')

ie.

DebugAssertEnabled () &&
(
(TEXT_OUT_SPLITTER_PRIVATE_DATA) (
(CHAR8
)This -
(CHAR8 )&((TEXT_OUT_SPLITTER_PRIVATE_DATA )0)->TextOut
)
)->Signature != SIGNATURE_32 ('T', 'o', 'S', 'p')

Looking at the TEXT_OUT_SPLITTER_PRIVATE_DATA structure:

typedef struct {
UINT64 Signature;
EFI_HANDLE VirtualHandle;
EFI_SIMPLE_TEXT_OUTPUT_PROTOCOL TextOut;

the "TextOut" field starts at offset 8 + 8 == 16 == 0x10. Hence we can
reformulate,

DebugAssertEnabled () &&
(
(TEXT_OUT_SPLITTER_PRIVATE_DATA) ((CHAR8 )This - 0x10)
)->Signature != SIGNATURE_32 ('T', 'o', 'S', 'p')

Basically this macro adjusts a pointer from the embedded (third field)
STO protocol to the first (signature) field, which is at offset zero.

(6) Let's see the disassembly again:

00000000000068d6 <ConSplitterTextOutSetAttribute>:
68d6: 55 push %rbp
68d7: 48 89 e5 mov %rsp,%rbp
68da: 48 83 ec 40 sub $0x40,%rsp
68de: 48 89 4d 10 mov %rcx,0x10(%rbp)

First incoming parameter, ie. "This", is spilled to the stack, from RCX.
(EFIAPI calling convention.)

68e2:       48 89 55 18             mov    %rdx,0x18(%rbp)

Second parameter, ie. "Attribute", is stored on the stack, from RDX.
(Same.)

68e6:       48 b8 e2 88 00 00 00    movabs $0x88e2,%rax
68ed:       00 00 00
68f0:       ff d0                   callq  *%rax

This is the call to DebugAssertEnabled(). (Search the rest of the
disassembly output, not quoted here, for "88e2:" -- it's the start
address of DebugAssertEnabled().)

68f2:       84 c0                   test   %al,%al
68f4:       74 3e                   je     6934 <ConSplitterTextOutSetAttribute+0x5e>

After DebugAssertEnabled() returns nonzero, we proceed to check the
signature:

68f6:       48 8b 45 10             mov    0x10(%rbp),%rax

We load the value of "This" from the stack back to RAX.

68fa:       48 83 e8 10             sub    $0x10,%rax

We decrease the value of RAX with 0x10. This happens to be the offset of
the TextOut field in TEXT_OUT_SPLITTER_PRIVATE_DATA.

==> 68fe: 48 8b 00 mov (%rax),%rax

We try to load the signature at *RAX (the Signature field is at offset
zero in the struct), into RAX. Too bad we crash because here (ie. after
the decrease by 0x10) RAX equals 0xFFFFFFFFFFFFFFF0. Which in turn means
the original value of RAX, therefore "This", was zero (a null pointer).

6901:       48 3d 54 6f 53 70       cmp    $0x70536f54,%rax

Had the signature loaded fine, we'd compare it against SIGNATURE_32
('T', 'o', 'S', 'p').

So, the problem is that ConSplitterTextOutSetAttribute() is called with
a This==NULL pointer. See RCX in the register dump -- it's still zero.

(7) Now assume for a second that this is a calling convention problem in
gnu-efi. In the SysV ABI, the first two integer/pointer arguments are
passed in RDI and RSI. Their values are, according to the dump:

RDI (ie. This): 0x6BAA790 -- looks closely related to ConSplitterDxe's
ImageBase; could be a static variable in the driver (offset is 0xB790
relative to ImageBase).

RSI (ie. Attribute): 0xE -- corresponds to:
EFI_YELLOW ==
EFI_BROWN | EFI_BRIGHT ==
(EFI_GREEN | EFI_RED) | 0x08 ==
0x02 | 0x04 | 0x08

So, we should search for an EFI_YELLOW foreground setting in gnu-efi
that misses the EFIAPI convention.

... DbgPrint() uses EFI_YELLOW for "ps.AttrError", which is consistent
with the D_ERROR in your code.

Please try the attached patch.

Thanks,
Laszlo

1 Attachments

Discussion

  • Nigel Croxon

    Nigel Croxon - 2014-06-19

    reviewed, tested and accpeted. Pushed to git tree with commit 6caab22f23434f41f42cfe7591d9a7ae66de9f0a

     
  • Nigel Croxon

    Nigel Croxon - 2014-06-19
    • status: open --> accepted
     
  • Nigel Croxon

    Nigel Croxon - 2014-06-19
    • assigned_to: Nigel Croxon
     
  • Nigel Croxon

    Nigel Croxon - 2015-02-17
    • status: accepted --> closed
     

Log in to post a comment.

Get latest updates about Open Source Projects, Conferences and News.

Sign up for the SourceForge newsletter:





No, thanks