From 83f065e0c6453488adc564493655e199a7eecef3 Mon Sep 17 00:00:00 2001 From: liqiqiii <132628835+liqiqiii@users.noreply.github.com> Date: Fri, 2 Aug 2024 00:47:03 -0700 Subject: [PATCH] [Cherry-Pick]Add debug level prefix for advanced logger memory message entries - Driver implementation (#525) 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 https://github.com/microsoft/mu_plus/commit/243bd187e4aa6ac68a3eb323d07554576d39ad47. 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, ... 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 N/A --- AdvLoggerPkg/AdvLoggerPkg.ci.yaml | 3 +- .../DecodeUefiLog/DecodeUefiLog.py | 54 ++++--- .../AdvancedLoggerAccessLib.c | 150 ++++++++++++++---- 3 files changed, 152 insertions(+), 55 deletions(-) diff --git a/AdvLoggerPkg/AdvLoggerPkg.ci.yaml b/AdvLoggerPkg/AdvLoggerPkg.ci.yaml index 644530283c..0ab8fac76b 100644 --- a/AdvLoggerPkg/AdvLoggerPkg.ci.yaml +++ b/AdvLoggerPkg/AdvLoggerPkg.ci.yaml @@ -88,7 +88,8 @@ LOGTELEMETRY, DEBUGAGENT, POSTMEM, - MMARM + MMARM, + BLKIO ] }, diff --git a/AdvLoggerPkg/Application/DecodeUefiLog/DecodeUefiLog.py b/AdvLoggerPkg/Application/DecodeUefiLog/DecodeUefiLog.py index 10e0492cdf..cdc5e7d6f3 100644 --- a/AdvLoggerPkg/Application/DecodeUefiLog/DecodeUefiLog.py +++ b/AdvLoggerPkg/Application/DecodeUefiLog/DecodeUefiLog.py @@ -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 # // @@ -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]" } # @@ -713,7 +713,8 @@ 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 # @@ -721,7 +722,8 @@ def _GetPhaseString(self, Phase): # 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 diff --git a/AdvLoggerPkg/Library/AdvancedLoggerAccessLib/AdvancedLoggerAccessLib.c b/AdvLoggerPkg/Library/AdvancedLoggerAccessLib/AdvancedLoggerAccessLib.c index 893e32256b..b4845011d9 100644 --- a/AdvLoggerPkg/Library/AdvancedLoggerAccessLib/AdvancedLoggerAccessLib.c +++ b/AdvLoggerPkg/Library/AdvancedLoggerAccessLib/AdvancedLoggerAccessLib.c @@ -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 /** @@ -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. @@ -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. @@ -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; @@ -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; } @@ -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; @@ -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;