Skip to content

Commit

Permalink
Add debug level prefix for advanced logger memory message entries - D…
Browse files Browse the repository at this point in the history 
…river implementation (#525)

## Description

Add debug level prefix for advanced logger memory message entries -
Driver implementation
This change added the existing metadata - debug level into the final
advanced logger memory entries through AdvancedFileLogger. This is a
followup PR for
243bd18.
After this PR checked in, we can easily track the DEBUG_ERRORs through
advanced logger files on UEFI that included this driver.
Added an extra space in the decodeuefilog.py to improve readability of
the log.
For the for loop in the code, ran with perf_trace enabled, and influence
is very low and can be ignored.
Updated the prefix of python script to match the design here. 
Use [ERROR] instead of [DEBUG_ERROR], which could save overall log file
sizes and memory buffer usage.

- [x] Impacts functionality?
- **Functionality** - Does the change ultimately impact how firmware
functions?
- Examples: Add a new library, publish a new PPI, update an algorithm,
...
- [ ] Impacts security?
- **Security** - Does the change have a direct security impact on an
application,
    flow, or firmware?
  - Examples: Crypto algorithm change, buffer overflow fix, parameter
    validation improvement, ...
- [ ] Breaking change?
- **Breaking change** - Will anyone consuming this change experience a
break
    in build or boot behavior?
- Examples: Add a new library class, move a module to a different repo,
call
    a function in a new library class in a pre-existing module, ...
- [ ] Includes tests?
  - **Tests** - Does the change include any explicit test code?
  - Examples: Unit tests, integration tests, robot tests, ...
- [ ] Includes documentation?
- **Documentation** - Does the change contain explicit documentation
additions
    outside direct code modifications (and comments)?
- Examples: Update readme file, add feature readme file, link to
documentation
    on an a separate Web page, ...

## How This Was Tested

Tested with two platforms that uses AdvancedFileLogger and can see debug
level
prefixes in the logs in the EFI Partition and USB UefiLogs folder.
[MM_CORE] [ERROR] Image - MmSupervisorCore.pdb

## Integration Instructions

N/A
  • Loading branch information
@liqiqiii
liqiqiii authored Aug 2, 2024
1 parent 6385ad0 commit f0c8e10
Show file tree
Hide file tree
Showing 3 changed files with 152 additions and 55 deletions.
3 changes: 2 additions & 1 deletion AdvLoggerPkg/AdvLoggerPkg.ci.yaml
View file
Original file line number Diff line number Diff line change
Expand Up @@ -88,7 +88,8 @@
LOGTELEMETRY,
DEBUGAGENT,
POSTMEM,
MMARM
MMARM,
BLKIO
]
},

Expand Down
54 changes: 28 additions & 26 deletions AdvLoggerPkg/Application/DecodeUefiLog/DecodeUefiLog.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -260,9 +260,9 @@ class AdvLogParser ():
ADVANCED_LOGGER_PHASE_SMM = 9
ADVANCED_LOGGER_PHASE_TFA = 10
ADVANCED_LOGGER_PHASE_CNT = 11
PHASE_STRING_LIST = ["[UNSPECIFIED] ", "[SEC] ", "[PEI] ", "[PEI64] ",
"[DXE] ", "[RUNTIME] ", "[MM_CORE] ", "[MM] ",
"[SMM_CORE] ", "[SMM] ", "[TFA] "]
PHASE_STRING_LIST = ["[UNSPECIFIED]", "[SEC]", "[PEI]", "[PEI64]",
"[DXE]", "[RUNTIME]", "[MM_CORE]", "[MM]",
"[SMM_CORE]", "[SMM]", "[TFA]"]

# Debug levels from MU_BASECORE\MdePkg\Include\Library\DebugLib.h
# //
Expand Down Expand Up @@ -293,27 +293,27 @@ class AdvLogParser ():
# #define DEBUG_ERROR 0x80000000 // Error

debug_levels_dict = {
0x00000001: "[DEBUG_INIT]",
0x00000002: "[DEBUG_WARN]",
0x00000004: "[DEBUG_LOAD]",
0x00000008: "[DEBUG_FS]",
0x00000010: "[DEBUG_POOL]",
0x00000020: "[DEBUG_PAGE]",
0x00000040: "[DEBUG_INFO]",
0x00000080: "[DEBUG_DISPATCH]",
0x00000100: "[DEBUG_VARIABLE]",
0x00000200: "[DEBUG_SMI]",
0x00000400: "[DEBUG_BM]",
0x00001000: "[DEBUG_BLKIO]",
0x00004000: "[DEBUG_NET]",
0x00010000: "[DEBUG_UNDI]",
0x00020000: "[DEBUG_LOADFILE]",
0x00080000: "[DEBUG_EVENT]",
0x00100000: "[DEBUG_GCD]",
0x00200000: "[DEBUG_CACHE]",
0x00400000: "[DEBUG_VERBOSE]",
0x00800000: "[DEBUG_MANAGEABILITY]",
0x80000000: "[DEBUG_ERROR]"
0x00000001: "[INIT]",
0x00000002: "[WARN]",
0x00000004: "[LOAD]",
0x00000008: "[FS]",
0x00000010: "[POOL]",
0x00000020: "[PAGE]",
0x00000040: "[INFO]",
0x00000080: "[DISPATCH]",
0x00000100: "[VARIABLE]",
0x00000200: "[SMI]",
0x00000400: "[BM]",
0x00001000: "[BLKIO]",
0x00004000: "[NET]",
0x00010000: "[UNDI]",
0x00020000: "[LOADFILE]",
0x00080000: "[EVENT]",
0x00100000: "[GCD]",
0x00200000: "[CACHE]",
0x00400000: "[VERBOSE]",
0x00800000: "[MANAGEABILITY]",
0x80000000: "[ERROR]"
}

#
Expand Down Expand Up @@ -713,15 +713,17 @@ def _GetPhaseString(self, Phase):
elif Phase <= self.ADVANCED_LOGGER_PHASE_UNSPECIFIED:
PhaseString = ""
else:
PhaseString = self.PHASE_STRING_LIST[Phase]
# Add an extra space for readability
PhaseString = self.PHASE_STRING_LIST[Phase] + ' '
return PhaseString

#
# Get the formatted debug level string
#
def _GetDebugLevelString(self, DebugLevel):
if DebugLevel in list(self.debug_levels_dict.keys()):
DebugLevelString = self.debug_levels_dict[DebugLevel]
# Add an extra space for readability
DebugLevelString = self.debug_levels_dict[DebugLevel] + ' '
else:
DebugLevelString = ""
return DebugLevelString
Expand Down
150 changes: 122 additions & 28 deletions AdvLoggerPkg/Library/AdvancedLoggerAccessLib/AdvancedLoggerAccessLib.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -27,23 +27,55 @@ STATIC EFI_PHYSICAL_ADDRESS mLowAddress = 0;
STATIC EFI_PHYSICAL_ADDRESS mHighAddress = 0;
STATIC UINT16 mMaxMessageSize = ADVANCED_LOGGER_MAX_MESSAGE_SIZE;
CONST CHAR8 *AdvMsgEntryPrefix[ADVANCED_LOGGER_PHASE_CNT] = {
"[UNSPECIFIED] ",
"[SEC] ",
"[PEI] ",
"[PEI64] ",
"[DXE] ",
"[RUNTIME] ",
"[MM_CORE] ",
"[MM] ",
"[SMM_CORE] ",
"[SMM] ",
"[TFA] ",
"[UNSPECIFIED]",
"[SEC]",
"[PEI]",
"[PEI64]",
"[DXE]",
"[RUNTIME]",
"[MM_CORE]",
"[MM]",
"[SMM_CORE]",
"[SMM]",
"[TFA]",
};

#define ADV_TIME_STAMP_FORMAT "%2.2d:%2.2d:%2.2d.%3.3d : "
#define ADV_TIME_STAMP_RESULT "hh:mm:ss:ttt : "
#define ADV_PHASE_ERR_FORMAT "[%04X] "
#define ADV_PHASE_MAX_SIZE 32
// Define a structure to hold debug level information
typedef struct {
CONST CHAR8 *Name;
UINT32 Value;
} DEBUG_LEVEL;

// Create an array of DebugLevel structures
DEBUG_LEVEL DebugLevels[] = {
{ "[INIT]", 0x00000001 },
{ "[WARN]", 0x00000002 },
{ "[LOAD]", 0x00000004 },
{ "[FS]", 0x00000008 },
{ "[POOL]", 0x00000010 },
{ "[PAGE]", 0x00000020 },
{ "[INFO]", 0x00000040 },
{ "[DISPATCH]", 0x00000080 },
{ "[VARIABLE]", 0x00000100 },
{ "[SMI]", 0x00000200 },
{ "[BM]", 0x00000400 },
{ "[BLKIO]", 0x00001000 },
{ "[NET]", 0x00004000 },
{ "[UNDI]", 0x00010000 },
{ "[LOADFILE]", 0x00020000 },
{ "[EVENT]", 0x00080000 },
{ "[GCD]", 0x00100000 },
{ "[CACHE]", 0x00200000 },
{ "[VERBOSE]", 0x00400000 },
{ "[MANAGEABILITY]", 0x00800000 },
{ "[ERROR]", 0x80000000 }
};

#define ADV_LOG_TIME_STAMP_FORMAT "%2.2d:%2.2d:%2.2d.%3.3d : "
#define ADV_LOG_TIME_STAMP_RESULT "hh:mm:ss:ttt : "
#define ADV_LOG_PHASE_ERR_FORMAT "[%04X] "
#define ADV_LOG_PHASE_MAX_SIZE 32
#define ADV_LOG_DEBUG_LEVEL_MAX_SIZE 32

/**
Expand Down Expand Up @@ -88,21 +120,19 @@ FormatTimeStamp (
TimeStampLen = AsciiSPrint (
MessageBuffer,
MessageBufferSize,
ADV_TIME_STAMP_FORMAT,
ADV_LOG_TIME_STAMP_FORMAT,
Hours,
Minutes,
Seconds,
Milliseconds
);

ASSERT (TimeStampLen == AsciiStrLen (ADV_TIME_STAMP_RESULT));
ASSERT (TimeStampLen == AsciiStrLen (ADV_LOG_TIME_STAMP_RESULT));

return (UINT16)TimeStampLen;
}

/**
FormatPhasePrefix
Adds a phase indicator to the message being returned. If phase is recognized and specified,
returns the phase prefix in from the AdvMsgEntryPrefix, otherwise raw phase value is returned.
Expand All @@ -128,14 +158,64 @@ FormatPhasePrefix (
} else if (Phase < ADVANCED_LOGGER_PHASE_CNT) {
// Normal message we recognize
PhaseStringLen = AsciiSPrint (MessageBuffer, MessageBufferSize, AdvMsgEntryPrefix[Phase]);
// Verify string length and add an extra space for readability
if (PhaseStringLen < MessageBufferSize - 1) {
MessageBuffer[PhaseStringLen] = ' ';
MessageBuffer[PhaseStringLen + 1] = '\0';
PhaseStringLen++;
}
} else {
// Unrecognized phase, just print the raw value
PhaseStringLen = AsciiSPrint (MessageBuffer, MessageBufferSize, ADV_PHASE_ERR_FORMAT, Phase);
PhaseStringLen = AsciiSPrint (MessageBuffer, MessageBufferSize, ADV_LOG_PHASE_ERR_FORMAT, Phase);
}

return (UINT16)PhaseStringLen;
}

/**
Adds a debug level indicator to the message being returned. If debug level is recognized and specified,
returns the debug_level prefix in from the AdvMsgEntryPrefix, otherwise raw debug level value is returned.
@param MessageBuffer
@param MessageBufferSize
@param DebugLevel
@retval Number of characters printed
*/
STATIC
UINT16
FormatDebugLevelPrefix (
IN CHAR8 *MessageBuffer,
IN UINTN MessageBufferSize,
IN UINT32 DebugLevel
)
{
if ((MessageBuffer == NULL) || (MessageBufferSize == 0)) {
return 0;
}

UINTN DebugLevelStringLen;
UINTN Index;

// Print the debug flags
for (Index = 0; Index < ARRAY_SIZE (DebugLevels); Index++) {
if ((DebugLevel & DebugLevels[Index].Value) == DebugLevels[Index].Value) {
DebugLevelStringLen = AsciiSPrint (MessageBuffer, MessageBufferSize, DebugLevels[Index].Name);
// Verify string length and add an extra space for readability
if (DebugLevelStringLen < MessageBufferSize - 1) {
MessageBuffer[DebugLevelStringLen] = ' ';
MessageBuffer[DebugLevelStringLen + 1] = '\0';
DebugLevelStringLen++;
}

return (UINT16)DebugLevelStringLen;
}
}

// If this is not a known debug level, just don't print it out and return 0
return 0;
}

/**
Get Next Message Block.
Expand Down Expand Up @@ -286,8 +366,11 @@ AdvancedLoggerAccessLibGetNextFormattedLine (
UINT16 TargetLen;
UINT16 PhaseStringLen;
UINT16 CurrPhaseStringLen;
CHAR8 TimeStampString[] = { ADV_TIME_STAMP_RESULT };
CHAR8 PhaseString[ADV_PHASE_MAX_SIZE] = { 0 };
UINT16 DebugLevelStringLen;
UINT16 CurrDebugLevelStringLen;
CHAR8 TimeStampString[] = { ADV_LOG_TIME_STAMP_RESULT };
CHAR8 PhaseString[ADV_LOG_PHASE_MAX_SIZE] = { 0 };
CHAR8 DebugLevelString[ADV_LOG_DEBUG_LEVEL_MAX_SIZE] = { 0 };

if (LineEntry == NULL) {
return EFI_INVALID_PARAMETER;
Expand All @@ -298,7 +381,7 @@ AdvancedLoggerAccessLibGetNextFormattedLine (
// reuse the previous LineBuffer
//
if (LineEntry->Message == NULL) {
LineBuffer = AllocatePool (mMaxMessageSize + sizeof (TimeStampString) + ADV_PHASE_MAX_SIZE);
LineBuffer = AllocatePool (mMaxMessageSize + sizeof (TimeStampString) + ADV_LOG_PHASE_MAX_SIZE);
if (LineBuffer == NULL) {
return EFI_OUT_OF_RESOURCES;
}
Expand All @@ -314,15 +397,18 @@ AdvancedLoggerAccessLibGetNextFormattedLine (
// GetNextLine.

// In case this is a restart of the same Message, initialize the time stamp and prefix.
PhaseStringLen = 0;
PhaseStringLen = 0;
DebugLevelStringLen = 0;
if (LineEntry->BlockEntry.Message != NULL) {
FormatTimeStamp (TimeStampString, sizeof (TimeStampString), LineEntry->BlockEntry.TimeStamp);
CopyMem (LineBuffer, TimeStampString, sizeof (TimeStampString) - sizeof (CHAR8));
PhaseStringLen = FormatPhasePrefix (PhaseString, sizeof (PhaseString), LineEntry->BlockEntry.Phase);
CopyMem (LineBuffer + sizeof (TimeStampString) - sizeof (CHAR8), PhaseString, PhaseStringLen);
DebugLevelStringLen = FormatDebugLevelPrefix (DebugLevelString, sizeof (DebugLevelString), LineEntry->BlockEntry.DebugLevel);
CopyMem (LineBuffer + sizeof (TimeStampString) + PhaseStringLen - sizeof (CHAR8), DebugLevelString, DebugLevelStringLen);
}

TargetPtr = &LineBuffer[sizeof (TimeStampString) - sizeof (CHAR8) + PhaseStringLen];
TargetPtr = &LineBuffer[sizeof (TimeStampString) - sizeof (CHAR8) + PhaseStringLen + DebugLevelStringLen];
TargetLen = 0;
Status = EFI_SUCCESS;

Expand Down Expand Up @@ -380,17 +466,25 @@ AdvancedLoggerAccessLibGetNextFormattedLine (
CopyMem (LineBuffer, TimeStampString, sizeof (TimeStampString) - sizeof (CHAR8));
CurrPhaseStringLen = FormatPhasePrefix (PhaseString, sizeof (PhaseString), LineEntry->BlockEntry.Phase);
if (PhaseStringLen != CurrPhaseStringLen) {
// Adjust the TargetPtr to point to the end of the PhaseString
// Update the PhaseStringLen
PhaseStringLen = CurrPhaseStringLen;
TargetPtr = &LineBuffer[sizeof (TimeStampString) - sizeof (CHAR8) + PhaseStringLen];
}

CopyMem (LineBuffer + sizeof (TimeStampString) - sizeof (CHAR8), PhaseString, PhaseStringLen);

CurrDebugLevelStringLen = FormatDebugLevelPrefix (DebugLevelString, sizeof (DebugLevelString), LineEntry->BlockEntry.DebugLevel);
if (DebugLevelStringLen != CurrDebugLevelStringLen) {
// Adjust the TargetPtr to point to the end of the DebugLevelString
DebugLevelStringLen = CurrDebugLevelStringLen;
TargetPtr = &LineBuffer[sizeof (TimeStampString) - sizeof (CHAR8) + PhaseStringLen + DebugLevelStringLen];
}

CopyMem (LineBuffer + sizeof (TimeStampString) - sizeof (CHAR8) + PhaseStringLen, DebugLevelString, DebugLevelStringLen);
}
} while (!EFI_ERROR (Status));

if (!EFI_ERROR (Status)) {
LineEntry->MessageLen = TargetLen + sizeof (TimeStampString) - sizeof (CHAR8) + PhaseStringLen;
LineEntry->MessageLen = TargetLen + sizeof (TimeStampString) - sizeof (CHAR8) + PhaseStringLen + DebugLevelStringLen;
LineEntry->TimeStamp = LineEntry->BlockEntry.TimeStamp;
LineEntry->DebugLevel = LineEntry->BlockEntry.DebugLevel;
LineEntry->Phase = LineEntry->BlockEntry.Phase;
Expand Down

0 comments on commit f0c8e10

Please sign in to comment.