path: root/Lessons/Lesson_41/README.md

In this lesson we would talk about the `DEBUG` macro in edk2 codebase. Example of a `DEBUG` macro use:
```
DEBUG ((EFI_D_ERROR, "Hello Debug! Check this variable: %d\n", MyVar));
```
So the string formatting is similar to the `Print` function, but there are couple of benefits:
- log levels (`EFI_D_*`) help to categorize log messages. With the configuration through PCD we can easily turn on/off different types of debug messages
- there can be several implementations of the `DEBUG` functionality. Different UEFI stages/modules can have different `DEBUG` implementations

All predefined log message categories are defined in the https://github.com/tianocore/edk2/blob/master/MdePkg/Include/Library/DebugLib.h
```
#define DEBUG_INIT      0x00000001  // Initialization
#define DEBUG_WARN      0x00000002  // Warnings
#define DEBUG_LOAD      0x00000004  // Load events
#define DEBUG_FS        0x00000008  // EFI File system
#define DEBUG_POOL      0x00000010  // Alloc & Free (pool)
#define DEBUG_PAGE      0x00000020  // Alloc & Free (page)
#define DEBUG_INFO      0x00000040  // Informational debug messages
#define DEBUG_DISPATCH  0x00000080  // PEI/DXE/SMM Dispatchers
#define DEBUG_VARIABLE  0x00000100  // Variable
#define DEBUG_BM        0x00000400  // Boot Manager
#define DEBUG_BLKIO     0x00001000  // BlkIo Driver
#define DEBUG_NET       0x00004000  // Network Io Driver
#define DEBUG_UNDI      0x00010000  // UNDI Driver
#define DEBUG_LOADFILE  0x00020000  // LoadFile
#define DEBUG_EVENT     0x00080000  // Event messages
#define DEBUG_GCD       0x00100000  // Global Coherency Database changes
#define DEBUG_CACHE     0x00200000  // Memory range cachability changes
#define DEBUG_VERBOSE   0x00400000  // Detailed debug messages that may
                                    // significantly impact boot performance
#define DEBUG_ERROR     0x80000000  // Error
```
But generally these alias values are used:
```
//
// Aliases of debug message mask bits
//
#define EFI_D_INIT      DEBUG_INIT
#define EFI_D_WARN      DEBUG_WARN
#define EFI_D_LOAD      DEBUG_LOAD
#define EFI_D_FS        DEBUG_FS
#define EFI_D_POOL      DEBUG_POOL
#define EFI_D_PAGE      DEBUG_PAGE
#define EFI_D_INFO      DEBUG_INFO
#define EFI_D_DISPATCH  DEBUG_DISPATCH
#define EFI_D_VARIABLE  DEBUG_VARIABLE
#define EFI_D_BM        DEBUG_BM
#define EFI_D_BLKIO     DEBUG_BLKIO
#define EFI_D_NET       DEBUG_NET
#define EFI_D_UNDI      DEBUG_UNDI
#define EFI_D_LOADFILE  DEBUG_LOADFILE
#define EFI_D_EVENT     DEBUG_EVENT
#define EFI_D_VERBOSE   DEBUG_VERBOSE
#define EFI_D_ERROR     DEBUG_ERROR
```

The DEBUG macro itself is also defined in the `DebugLib` library header (https://github.com/tianocore/edk2/blob/master/MdePkg/Include/Library/DebugLib.h).

If you'll split all the preprocessing hell it generally looks like this when it is used:
```
if (DebugPrintEnabled ()) {
  if (DebugPrintLevelEnabled (PrintLevel)) {
    DebugPrint (PrintLevel, ##__VA_ARGS__);
  }
}
```

The `DEBUG` macro interface is defined in a `DebugLib` header. But for the actual implementation we need to look at a particular library instance that is used.

If you look at the https://github.com/tianocore/edk2/blob/master/OvmfPkg/OvmfPkgX64.dsc you'll see that:
- `DebugLib` has different implementations in different UEFI stages
- `DebugLib` has different implementations based on a `DEBUG_ON_SERIAL_PORT` definition
```
[LibraryClasses.common.SEC]
!ifdef $(DEBUG_ON_SERIAL_PORT)
  DebugLib|MdePkg/Library/BaseDebugLibSerialPort/BaseDebugLibSerialPort.inf
!else
  DebugLib|OvmfPkg/Library/PlatformDebugLibIoPort/PlatformRomDebugLibIoPort.inf
!endif
```
```
[LibraryClasses.common.PEI_CORE]
# [LibraryClasses.common.PEIM]
# [LibraryClasses.common.DXE_CORE]
# [LibraryClasses.common.DXE_RUNTIME_DRIVER]
# [LibraryClasses.common.UEFI_DRIVER]
# [LibraryClasses.common.DXE_DRIVER]
# [LibraryClasses.common.UEFI_APPLICATION]
# [LibraryClasses.common.DXE_SMM_DRIVER]
# [LibraryClasses.common.SMM_CORE]
!ifdef $(DEBUG_ON_SERIAL_PORT)
  DebugLib|MdePkg/Library/BaseDebugLibSerialPort/BaseDebugLibSerialPort.inf
!else
  DebugLib|OvmfPkg/Library/PlatformDebugLibIoPort/PlatformDebugLibIoPort.inf
!endif
```

As `DEBUG_ON_SERIAL_PORT` is not defined by default, the main library in our case would be `PlatformDebugLibIoPort` (https://github.com/tianocore/edk2/tree/master/OvmfPkg/Library/PlatformDebugLibIoPort):
```
DebugLib|OvmfPkg/Library/PlatformDebugLibIoPort/PlatformDebugLibIoPort.inf
```

As you remember `DEBUG` macro gets translated to something like:
```
if (DebugPrintEnabled ()) {
  if (DebugPrintLevelEnabled (PrintLevel)) {
    DebugPrint (PrintLevel, ##__VA_ARGS__);
  }
}
```

Let's look at the https://github.com/tianocore/edk2/blob/master/OvmfPkg/Library/PlatformDebugLibIoPort/DebugLib.c to see how `DebugPrintEnabled`, `DebugPrintLevelEnabled` and `DebugPrint` are implemented.


`DEBUG` macro first checks `DebugPrintEnabled` result. This function checks PCD `PcdDebugPropertyMask` if it has `DEBUG_PROPERTY_DEBUG_PRINT_ENABLED` bit set:
```
BOOLEAN
EFIAPI
DebugPrintEnabled (
  VOID
  )
{
  return (BOOLEAN) ((PcdGet8(PcdDebugPropertyMask) & DEBUG_PROPERTY_DEBUG_PRINT_ENABLED) != 0);
}
```
Then `DebugPrintLevelEnabled` function checks if passed `ErrorLevel` is present in the PCD `PcdFixedDebugPrintErrorLevel`:
```
BOOLEAN
EFIAPI
DebugPrintLevelEnabled (
  IN  CONST UINTN        ErrorLevel
  )
{
  return (BOOLEAN) ((ErrorLevel & PcdGet32(PcdFixedDebugPrintErrorLevel)) != 0);
}
```

Then actual `DebugPrint` function is executed. It simply passes control to `DebugVPrint`:
```
VOID
EFIAPI
DebugPrint (
  IN  UINTN        ErrorLevel,
  IN  CONST CHAR8  *Format,
  ...
  )
{
  VA_LIST         Marker;

  VA_START (Marker, Format);
  DebugVPrint (ErrorLevel, Format, Marker);
  VA_END (Marker);
}
```

And `DebugVPrint` in turn passes control to `DebugPrintMarker`:
```
VOID
EFIAPI
DebugVPrint (
  IN  UINTN         ErrorLevel,
  IN  CONST CHAR8   *Format,
  IN  VA_LIST       VaListMarker
  )
{
  DebugPrintMarker (ErrorLevel, Format, VaListMarker, NULL);
}
```

`DebugPrintMarker` is the main debug function. It check if passed `ErrorLevel` is present in `GetDebugPrintErrorLevel()` output and in the end performs write of the debug string to the I/O port defined by PCD `PcdDebugIoPort`:
```
VOID
DebugPrintMarker (
  IN  UINTN         ErrorLevel,
  IN  CONST CHAR8   *Format,
  IN  VA_LIST       VaListMarker,
  IN  BASE_LIST     BaseListMarker
  )
{
  CHAR8    Buffer[MAX_DEBUG_MESSAGE_LENGTH];
  UINTN    Length;

  //
  // If Format is NULL, then ASSERT().
  //
  ASSERT (Format != NULL);

  //
  // Check if the global mask disables this message or the device is inactive
  //
  if ((ErrorLevel & GetDebugPrintErrorLevel ()) == 0 ||
      !PlatformDebugLibIoPortFound ()) {
    return;
  }

  //
  // Convert the DEBUG() message to an ASCII String
  //
  if (BaseListMarker == NULL) {
    Length = AsciiVSPrint (Buffer, sizeof (Buffer), Format, VaListMarker);
  } else {
    Length = AsciiBSPrint (Buffer, sizeof (Buffer), Format, BaseListMarker);
  }

  //
  // Send the print string to the debug I/O port
  //
  IoWriteFifo8 (PcdGet16 (PcdDebugIoPort), Length, Buffer);
}
```

`GetDebugPrintErrorLevel()` is a function from `DebugPrintErrorLevelLib` library. Our `OvmfPkgX64.dsc` defines this implementation for it:
```
[LibraryClasses]
  ...
  DebugPrintErrorLevelLib|MdePkg/Library/BaseDebugPrintErrorLevelLib/BaseDebugPrintErrorLevelLib.inf
```
If you'll look at it sources you'll see that it simply checks for another PCD `PcdDebugPrintErrorLevel` (https://github.com/tianocore/edk2/blob/master/MdePkg/Library/BaseDebugPrintErrorLevelLib/BaseDebugPrintErrorLevelLib.c):
```
UINT32
EFIAPI
GetDebugPrintErrorLevel (
  VOID
  )
{
  //
  // Retrieve the current debug print error level mask from PcdDebugPrintErrorLevel.
  //
  return PcdGet32 (PcdDebugPrintErrorLevel);
}
```

## Summary:
The code `DEBUG (( ErrorLevel, String, ... ))` does the following:
- checks if `PcdDebugPropertyMask` has `DEBUG_PROPERTY_DEBUG_PRINT_ENABLED`
- checks if passed `ErrorLevel` is set in `PcdFixedDebugPrintErrorLevel` 
- checks if passed `ErrorLevel` is set in `PcdDebugPrintErrorLevel`
- writes formatted String to I/O port defined by `PcdDebugIoPort`



# Check if `PcdDebugPropertyMask` has `DEBUG_PROPERTY_DEBUG_PRINT_ENABLED`

OVMF DSC file defines this PCD PcdDebugPropertyMask like this https://github.com/tianocore/edk2/blob/master/OvmfPkg/OvmfPkgX64.dsc:
```
[PcdsFixedAtBuild]
!if $(SOURCE_DEBUG_ENABLE) == TRUE
  gEfiMdePkgTokenSpaceGuid.PcdDebugPropertyMask|0x17
!else
  gEfiMdePkgTokenSpaceGuid.PcdDebugPropertyMask|0x2F
!endif
```
It also redefines this PCD for Shell:
```
[Components]
  ShellPkg/Application/Shell/Shell.inf {
    ...
    <PcdsFixedAtBuild>
    ...
    gEfiMdePkgTokenSpaceGuid.PcdDebugPropertyMask|0xFF
  }
```

You can check bit definitions for this PCD in a https://github.com/tianocore/edk2/blob/master/MdePkg/MdePkg.dec:
```
## The mask is used to control DebugLib behavior.<BR><BR>
#  BIT0 - Enable Debug Assert.<BR>
#  BIT1 - Enable Debug Print.<BR>
#  BIT2 - Enable Debug Code.<BR>
#  BIT3 - Enable Clear Memory.<BR>
#  BIT4 - Enable BreakPoint as ASSERT.<BR>
#  BIT5 - Enable DeadLoop as ASSERT.<BR>
# @Prompt Debug Property.
# @Expression  0x80000002 | (gEfiMdePkgTokenSpaceGuid.PcdDebugPropertyMask & 0xC0) == 0
gEfiMdePkgTokenSpaceGuid.PcdDebugPropertyMask|0|UINT8|0x00000005
```
So if the `SOURCE_DEBUG_ENABLE` is:
- TRUE: these features are enabled: Debug Assert/Debug Print/Debug Code/BreakPoint as ASSERT.
- FALSE: these features are enabled: Debug Assert/Debug Print/Debug Code/Clear Memory/DeadLoop as ASSERT.

In a `DEBUG` macro we compare this PCD aginst `DEBUG_PROPERTY_DEBUG_PRINT_ENABLED` (https://github.com/tianocore/edk2/blob/master/MdePkg/Include/Library/DebugLib.h):
```
//
// Declare bits for PcdDebugPropertyMask
//
#define DEBUG_PROPERTY_DEBUG_ASSERT_ENABLED       0x01
#define DEBUG_PROPERTY_DEBUG_PRINT_ENABLED        0x02
#define DEBUG_PROPERTY_DEBUG_CODE_ENABLED         0x04
#define DEBUG_PROPERTY_CLEAR_MEMORY_ENABLED       0x08
#define DEBUG_PROPERTY_ASSERT_BREAKPOINT_ENABLED  0x10
#define DEBUG_PROPERTY_ASSERT_DEADLOOP_ENABLED    0x20
```

As you can see this check would pass no matter of `SOURCE_DEBUG_ENABLE` setting.

# Checks if passed `ErrorLevel` is set in `PcdFixedDebugPrintErrorLevel`

This PCD is declared in https://github.com/tianocore/edk2/blob/master/MdePkg/MdePkg.dec:
```
[PcdsFixedAtBuild]
  gEfiMdePkgTokenSpaceGuid.PcdFixedDebugPrintErrorLevel|0xFFFFFFFF|UINT32|0x30001016
```

This PCD is not redefined in the OVMF DSC file, so this is a final value. `0xFFFFFFFF` means that `DEBUG` message would pass this check no matter of its `EFI_D_*` print level.


# Checks if passed `ErrorLevel` is set in `PcdDebugPrintErrorLevel`

This PCD is declared in a https://github.com/tianocore/edk2/blob/master/MdePkg/MdePkg.dec
```
[PcdsFixedAtBuild]
  gEfiMdePkgTokenSpaceGuid.PcdDebugPrintErrorLevel|0x80000000|UINT32|0x00000006
```

By default it is defined in the `MdePkg.dec` and in the `MdePkg.dsc` as `0x80000000` https://github.com/tianocore/edk2/blob/master/MdePkg/MdePkg.dsc:
```
[PcdsFixedAtBuild]
  gEfiMdePkgTokenSpaceGuid.PcdDebugPrintErrorLevel|0x80000000
```
The `0x80000000` value means that only error messages (`EFI_D_ERROR`) would be printed (ErrorLevel bit definitions again are in https://github.com/tianocore/edk2/blob/master/MdePkg/Include/Library/DebugLib.h).


Although when we compile OVMF our main DSC is `OvmfPkgX64.dsc` https://github.com/tianocore/edk2/blob/master/OvmfPkg/OvmfPkgX64.dsc. And this DSC redefines `PcdDebugPrintErrorLevel` PCD:
```
[PcdsFixedAtBuild]
  gEfiMdePkgTokenSpaceGuid.PcdDebugPrintErrorLevel|0x8000004F
```
The `0x8000004F` value is equal to: `EFI_D_ERROR | EFI_D_INFO | EFI_D_FS | EFI_D_LOAD | EFI_D_WARN | EFI_D_INIT`.

So it means that when DEBUG statement is enabled, only these categories of messages would be printed.


# Writes formatted String to I/O port defined by `PcdDebugIoPort`

The `PcdDebugIoPort` PCD is defined in https://github.com/tianocore/edk2/blob/master/OvmfPkg/OvmfPkg.dec
```
[PcdsFixedAtBuild]
  gUefiOvmfPkgTokenSpaceGuid.PcdDebugIoPort|0x402|UINT16|4
```

This PCD controls the destination I/O port for the debug messages in `PlatformDebugLibIoPort`

# Testing

To see debug messages we need to recompile OVMF in debug mode.

To do this use:
```
build --platform=OvmfPkg/OvmfPkgX64.dsc --arch=X64 --buildtarget=DEBUG --tagname=GCC5
```
The build results would be in a folder
```
Build/OvmfX64/DEBUG_GCC5
```

Now let's run QEMU with these parameters:
```
qemu-system-x86_64 \
  -drive if=pflash,format=raw,readonly,file=Build/OvmfX64/DEBUG_GCC5/FV/OVMF.fd \
  -drive format=raw,file=fat:rw:~/UEFI_disk \
  -net none \
  -nographic \
  -global isa-debugcon.iobase=0x402 \
  -debugcon file:debug.log
```

This would create `debug.log` file with all log `DEBUG` messages from OVMF. This file would be recreated every time you run this command.

In a separate terminal window you can run:
```
tail -f debug.log
```
to follow this file content runtime.

I've included the profuced `debug.log` to the current folder.


# Replace GUIDs in a log file

If you start looking at the `debug.log` file, you'll see that it is full of GUIDs:
```
$ head debug.log
SecCoreStartupWithStack(0xFFFCC000, 0x820000)
Register PPI Notify: DCD0BE23-9586-40F4-B643-06522CED4EDE
Install PPI: 8C8CE578-8A3D-4F1C-9935-896185C32DD3
Install PPI: 5473C07A-3DCB-4DCA-BD6F-1E9689E7349A
The 0th FV start address is 0x00000820000, size is 0x000E0000, handle is 0x820000
Register PPI Notify: 49EDB1C1-BF21-4761-BB12-EB0031AABB39
Register PPI Notify: EA7CA24B-DED5-4DAD-A389-BF827E8F9B38
Install PPI: B9E0ABFE-5979-4914-977F-6DEE78C278A6
Install PPI: DBE23AA9-A345-4B97-85B6-B226F1617389
DiscoverPeimsAndOrderWithApriori(): Found 0x7 PEI FFS files in the 0th FV
```
It would be nice to replace them with meaningfull text for readability.

Luckily edk2 build system creates a file with names for used GUIDs:
```
$ head Build/OvmfX64/DEBUG_GCC5/FV/Guid.xref
8c1a6b71-0c4b-4497-aaad-07404edf142c PCDLesson
1BA0062E-C779-4582-8566-336AE8F78F09 ResetVector
df1ccef6-f301-4a63-9661-fc6030dcc880 SecMain
52C05B14-0B98-496c-BC3B-04B50211D680 PeiCore
9B3ADA4F-AE56-4c24-8DEA-F03B7558AE50 PcdPeim
A3610442-E69F-4DF3-82CA-2360C4031A23 ReportStatusCodeRouterPei
9D225237-FA01-464C-A949-BAABC02D31D0 StatusCodeHandlerPei
86D70125-BAA3-4296-A62F-602BEBBB9081 DxeIpl
222c386d-5abc-4fb4-b124-fbb82488acf4 PlatformPei
89E549B0-7CFE-449d-9BA3-10D8B2312D71 S3Resume2Pei
```

Let's create a python app that would parse this file, create a `GUID:NAME` dictionary and use it to replace all GUIDs with their names in a `debug.log` file. The result would be written to the `debug_parsed.log` file:
```
from shutil import copyfile

GUIDS_FILE_PATH = "Build/OvmfX64/DEBUG_GCC5/FV/Guid.xref"
EXTRA_GUIDS_FILE_PATH = ""
LOG_IN_FILE_PATH = "debug.log"
LOG_OUT_FILE_PATH = "debug_parsed.log"

guids = {}

with open(GUIDS_FILE_PATH) as p:
    for line in p:
        l = line.split(" ")
        if len(l)==2:
            guids[l[0].upper()] = l[1][:-1]

if EXTRA_GUIDS_FILE_PATH:
    with open(EXTRA_GUIDS_FILE_PATH) as p:
        for line in p:
            l = line.split(" ")
            if len(l)==2:
                guids[l[0].upper()] = l[1][:-1]

copyfile(LOG_IN_FILE_PATH, LOG_OUT_FILE_PATH)

f = open(LOG_OUT_FILE_PATH, 'r')
filedata = f.read()
f.close()

for key,val in guids.items():
    filedata = filedata.replace(key, val)

f = open(LOG_OUT_FILE_PATH, 'w')
f.write(filedata)
f.close()
```
I've also added a possibility to include another `GUID:NAME` file with a help of `EXTRA_GUIDS_FILE_PATH` variable. This can be usefull if for some reason any guids are not present in the main `Guid.xref` file.

Put this script in edk2 folder and run it with `python` or `python3`:
```
python replace_guids.py
```

Now look at the created `debug_parsed.log` file:
```
$ head debug_parsed.log
SecCoreStartupWithStack(0xFFFCC000, 0x820000)
Register PPI Notify: gEfiPeiSecurity2PpiGuid
Install PPI: gEfiFirmwareFileSystem2Guid
Install PPI: gEfiFirmwareFileSystem3Guid
The 0th FV start address is 0x00000820000, size is 0x000E0000, handle is 0x820000
Register PPI Notify: gEfiPeiFirmwareVolumeInfoPpiGuid
Register PPI Notify: gEfiPeiFirmwareVolumeInfo2PpiGuid
Install PPI: gEfiPeiLoadFilePpiGuid
Install PPI: gEfiTemporaryRamSupportPpiGuid
DiscoverPeimsAndOrderWithApriori(): Found 0x7 PEI FFS files in the 0th FV
```

It is much easier to read now!