Skip to content

Commit

Permalink
AdvLoggerPkg: Fix message handling and LineParserTestApp (#634)
Browse files Browse the repository at this point in the history 
## Description

Fixes #629 

A case existed where the target buffer was not correct whenever the same
line buffer was extended (previous message overwritten).

Debug level strings could overwrite characters if a new debug level was
changed when residual characters were added to the same line buffer. To
simplify handling of strings, this change makes the phases and debug
message levels a fixed size. This is a breaking change but less error
prone.

The LineParserTestApp needed to be updated for debug level strings, so
that is done.

- [x] Impacts functionality?
- [ ] Impacts security?
- [x] Breaking change?
- [x] Includes tests?
- [ ] Includes documentation?
- [x] Backport to release branch?

## How This Was Tested

- LineParserTestApp
- Step through parsing with debugger and check variable values
- Log output

## Integration Instructions

- If any tools or code depend on exact string matches, note the change
in the debug message level and phase strings.

Signed-off-by: Michael Kubacki <[email protected]>
  • Loading branch information
@makubacki @ProjectMuBot
makubacki authored and ProjectMuBot committed Feb 25, 2025
1 parent 117c54b commit da8da86
Show file tree
Hide file tree
Showing 3 changed files with 83 additions and 88 deletions.
6 changes: 5 additions & 1 deletion AdvLoggerPkg/AdvLoggerPkg.ci.yaml
View file
Original file line number Diff line number Diff line change
Expand Up @@ -91,7 +91,11 @@
MMARM,
BLKIO,
dlink,
uintn
uintn,
mcore,
rtdxe,
smmcr,
unspd,
]
},

Expand Down
81 changes: 36 additions & 45 deletions AdvLoggerPkg/Library/AdvancedLoggerAccessLib/AdvancedLoggerAccessLib.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -27,17 +27,17 @@ 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]",
"[UNSPD]",
"[SEC ]",
"[PEI ]",
"[PEI64]",
"[DXE]",
"[RUNTIME]",
"[MM_CORE]",
"[MM]",
"[SMM_CORE]",
"[SMM]",
"[TFA]",
"[DXE ]",
"[RTDXE]",
"[MCORE]",
"[MM ]",
"[SMMCR]",
"[SMM ]",
"[TFA ]",
};

// Define a structure to hold debug level information
Expand All @@ -48,27 +48,27 @@ typedef struct {

// 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 }
{ "[INIT]", 0x00000001 },
{ "[WARN]", 0x00000002 },
{ "[LOAD]", 0x00000004 },
{ "[FS ]", 0x00000008 },
{ "[POOL]", 0x00000010 },
{ "[PAGE]", 0x00000020 },
{ "[INFO]", 0x00000040 },
{ "[DISP]", 0x00000080 },
{ "[VARI]", 0x00000100 },
{ "[SMI ]", 0x00000200 },
{ "[BM ]", 0x00000400 },
{ "[BLIO]", 0x00001000 },
{ "[NETw]", 0x00004000 },
{ "[UNDI]", 0x00010000 },
{ "[LDFL]", 0x00020000 },
{ "[EVNT]", 0x00080000 },
{ "[GCD ]", 0x00100000 },
{ "[CACH]", 0x00200000 },
{ "[VERB]", 0x00400000 },
{ "[MBTY]", 0x00800000 },
{ "[ERR ]", 0x80000000 }
};

#define ADV_LOG_TIME_STAMP_FORMAT "%2.2d:%2.2d:%2.2d.%3.3d : "
Expand Down Expand Up @@ -365,9 +365,7 @@ AdvancedLoggerAccessLibGetNextFormattedLine (
CHAR8 *TargetPtr;
UINT16 TargetLen;
UINT16 PhaseStringLen;
UINT16 CurrPhaseStringLen;
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 };
Expand Down Expand Up @@ -462,24 +460,17 @@ AdvancedLoggerAccessLibGetNextFormattedLine (
if (!EFI_ERROR (Status)) {
LineEntry->ResidualChar = LineEntry->BlockEntry.Message;
LineEntry->ResidualLen = LineEntry->BlockEntry.MessageLen;

FormatTimeStamp (TimeStampString, sizeof (TimeStampString), LineEntry->BlockEntry.TimeStamp);
CopyMem (LineBuffer, TimeStampString, sizeof (TimeStampString) - sizeof (CHAR8));
CurrPhaseStringLen = FormatPhasePrefix (PhaseString, sizeof (PhaseString), LineEntry->BlockEntry.Phase);
if (PhaseStringLen != CurrPhaseStringLen) {
// Update the PhaseStringLen
PhaseStringLen = CurrPhaseStringLen;
}

PhaseStringLen = FormatPhasePrefix (PhaseString, sizeof (PhaseString), LineEntry->BlockEntry.Phase);
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];
}

DebugLevelStringLen = FormatDebugLevelPrefix (DebugLevelString, sizeof (DebugLevelString), LineEntry->BlockEntry.DebugLevel);
CopyMem (LineBuffer + sizeof (TimeStampString) - sizeof (CHAR8) + PhaseStringLen, DebugLevelString, DebugLevelStringLen);

TargetPtr = &LineBuffer[TargetLen + sizeof (TimeStampString) - sizeof (CHAR8) + PhaseStringLen + DebugLevelStringLen];
}
} while (!EFI_ERROR (Status));

Expand Down
84 changes: 42 additions & 42 deletions AdvLoggerPkg/UnitTests/LineParser/LineParserTestApp.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -51,54 +51,54 @@ CHAR8 *InternalMemoryLog[] = {
"\nIf the EFI_GRAPHICS_OUTPUT_PROTOCOL is installed on the handle ",
"that represents a combination of video output devices, then the set ",
"of modes returned by this service is the subset of modes ",
"supported by the graphics controller and the all of the video output ",
"supported by the graphics controller and all of the video output ",
"devices represented by the handle.\n"
};

// The following text represents the output lines from the line parser given the above input

/* spell-checker: disable */
CHAR8 Line00[] = "09:06:45.012 : First normal test line\n";
CHAR8 Line01[] = "09:06:45.012 : The QueryMode() function returns information for an available graphics mod\n";
CHAR8 Line02[] = "09:06:45.012 : e that the graphics device and the set of active video output devices supp\n";
CHAR8 Line03[] = "09:06:45.012 : orts.\n";
CHAR8 Line04[] = "09:06:45.012 : If ModeNumber is not between 0 and MaxMode - 1, then EFI_INVALID_PARAMETER\n";
CHAR8 Line05[] = "09:06:45.012 : is returned.\n";
CHAR8 Line06[] = "09:06:45.012 : MaxMode is available from the Mode structure of the EFI_GRAPHICS_OUTPUT_PR\n";
CHAR8 Line07[] = "09:06:45.012 : OTOCOL.\n";
CHAR8 Line08[] = "09:06:45.012 : The size of the Info structure should never be assumed and the value of Si\n";
CHAR8 Line09[] = "09:06:45.012 : zeOfInfo is the only valid way to know the size of Info.\n";
CHAR8 Line10[] = "09:06:45.012 : \n";
CHAR8 Line11[] = "09:06:45.012 : If the EFI_GRAPHICS_OUTPUT_PROTOCOL is installed on the handle that repres\n";
CHAR8 Line12[] = "09:06:45.012 : ents a single video output device, then the set of modes returned by this \n";
CHAR8 Line13[] = "09:06:45.012 : service is the subset of modes supported by both the graphics controller a\n";
CHAR8 Line14[] = "09:06:45.012 : nd the video output device.\n";
CHAR8 Line15[] = "09:06:45.012 : \n";
CHAR8 Line16[] = "09:06:45.012 : If the EFI_GRAPHICS_OUTPUT_PROTOCOL is installed on the handle that repres\n";
CHAR8 Line17[] = "09:06:45.012 : ents a combination of video output devices, then the set of modes returned\n";
CHAR8 Line18[] = "09:06:45.012 : by this service is the subset of modes supported by the graphics controll\n";
CHAR8 Line19[] = "09:06:45.012 : er and the all of the video output devices represented by the handle.\n";

CHAR8 Line00V2[] = "09:06:45.012 : [DXE] First normal test line\n";
CHAR8 Line01V2[] = "09:06:45.012 : [DXE] The QueryMode() function returns information for an available graphics mod\n";
CHAR8 Line02V2[] = "09:06:45.012 : [DXE] e that the graphics device and the set of active video output devices supp\n";
CHAR8 Line03V2[] = "09:06:45.012 : [DXE] orts.\n";
CHAR8 Line04V2[] = "09:06:45.012 : [DXE] If ModeNumber is not between 0 and MaxMode - 1, then EFI_INVALID_PARAMETER\n";
CHAR8 Line05V2[] = "09:06:45.012 : [DXE] is returned.\n";
CHAR8 Line06V2[] = "09:06:45.012 : [DXE] MaxMode is available from the Mode structure of the EFI_GRAPHICS_OUTPUT_PR\n";
CHAR8 Line07V2[] = "09:06:45.012 : [DXE] OTOCOL.\n";
CHAR8 Line08V2[] = "09:06:45.012 : [DXE] The size of the Info structure should never be assumed and the value of Si\n";
CHAR8 Line09V2[] = "09:06:45.012 : [DXE] zeOfInfo is the only valid way to know the size of Info.\n";
CHAR8 Line10V2[] = "09:06:45.012 : [DXE] \n";
CHAR8 Line11V2[] = "09:06:45.012 : [DXE] If the EFI_GRAPHICS_OUTPUT_PROTOCOL is installed on the handle that repres\n";
CHAR8 Line12V2[] = "09:06:45.012 : [DXE] ents a single video output device, then the set of modes returned by this \n";
CHAR8 Line13V2[] = "09:06:45.012 : [DXE] service is the subset of modes supported by both the graphics controller a\n";
CHAR8 Line14V2[] = "09:06:45.012 : [DXE] nd the video output device.\n";
CHAR8 Line15V2[] = "09:06:45.012 : [DXE] \n";
CHAR8 Line16V2[] = "09:06:45.012 : [DXE] If the EFI_GRAPHICS_OUTPUT_PROTOCOL is installed on the handle that repres\n";
CHAR8 Line17V2[] = "09:06:45.012 : [DXE] ents a combination of video output devices, then the set of modes returned\n";
CHAR8 Line18V2[] = "09:06:45.012 : [DXE] by this service is the subset of modes supported by the graphics controll\n";
CHAR8 Line19V2[] = "09:06:45.012 : [DXE] er and the all of the video output devices represented by the handle.\n";
CHAR8 Line00[] = "09:06:45.012 : [INFO] First normal test line\n";
CHAR8 Line01[] = "09:06:45.012 : [ERR ] The QueryMode() function returns information for an available graphics mod\n";
CHAR8 Line02[] = "09:06:45.012 : [ERR ] e that the graphics device and the set of active video output devices supp\n";
CHAR8 Line03[] = "09:06:45.012 : [ERR ] orts.\n";
CHAR8 Line04[] = "09:06:45.012 : [ERR ] If ModeNumber is not between 0 and MaxMode - 1, then EFI_INVALID_PARAMETER\n";
CHAR8 Line05[] = "09:06:45.012 : [ERR ] is returned.\n";
CHAR8 Line06[] = "09:06:45.012 : [INFO] MaxMode is available from the Mode structure of the EFI_GRAPHICS_OUTPUT_PR\n";
CHAR8 Line07[] = "09:06:45.012 : [INFO] OTOCOL.\n";
CHAR8 Line08[] = "09:06:45.012 : [ERR ] The size of the Info structure should never be assumed and the value of Si\n";
CHAR8 Line09[] = "09:06:45.012 : [ERR ] zeOfInfo is the only valid way to know the size of Info.\n";
CHAR8 Line10[] = "09:06:45.012 : [ERR ] \n";
CHAR8 Line11[] = "09:06:45.012 : [ERR ] If the EFI_GRAPHICS_OUTPUT_PROTOCOL is installed on the handle that repres\n";
CHAR8 Line12[] = "09:06:45.012 : [INFO] ents a single video output device, then the set of modes returned by this \n";
CHAR8 Line13[] = "09:06:45.012 : [ERR ] service is the subset of modes supported by both the graphics controller a\n";
CHAR8 Line14[] = "09:06:45.012 : [ERR ] nd the video output device.\n";
CHAR8 Line15[] = "09:06:45.012 : [ERR ] \n";
CHAR8 Line16[] = "09:06:45.012 : [ERR ] If the EFI_GRAPHICS_OUTPUT_PROTOCOL is installed on the handle that repres\n";
CHAR8 Line17[] = "09:06:45.012 : [ERR ] ents a combination of video output devices, then the set of modes returned\n";
CHAR8 Line18[] = "09:06:45.012 : [INFO] by this service is the subset of modes supported by the graphics controll\n";
CHAR8 Line19[] = "09:06:45.012 : [ERR ] er and all of the video output devices represented by the handle.\n";

CHAR8 Line00V2[] = "09:06:45.012 : [DXE ] [INFO] First normal test line\n";
CHAR8 Line01V2[] = "09:06:45.012 : [DXE ] [ERR ] The QueryMode() function returns information for an available graphics mod\n";
CHAR8 Line02V2[] = "09:06:45.012 : [DXE ] [ERR ] e that the graphics device and the set of active video output devices supp\n";
CHAR8 Line03V2[] = "09:06:45.012 : [DXE ] [ERR ] orts.\n";
CHAR8 Line04V2[] = "09:06:45.012 : [DXE ] [ERR ] If ModeNumber is not between 0 and MaxMode - 1, then EFI_INVALID_PARAMETER\n";
CHAR8 Line05V2[] = "09:06:45.012 : [DXE ] [ERR ] is returned.\n";
CHAR8 Line06V2[] = "09:06:45.012 : [DXE ] [INFO] MaxMode is available from the Mode structure of the EFI_GRAPHICS_OUTPUT_PR\n";
CHAR8 Line07V2[] = "09:06:45.012 : [DXE ] [INFO] OTOCOL.\n";
CHAR8 Line08V2[] = "09:06:45.012 : [DXE ] [ERR ] The size of the Info structure should never be assumed and the value of Si\n";
CHAR8 Line09V2[] = "09:06:45.012 : [DXE ] [ERR ] zeOfInfo is the only valid way to know the size of Info.\n";
CHAR8 Line10V2[] = "09:06:45.012 : [DXE ] [ERR ] \n";
CHAR8 Line11V2[] = "09:06:45.012 : [DXE ] [ERR ] If the EFI_GRAPHICS_OUTPUT_PROTOCOL is installed on the handle that repres\n";
CHAR8 Line12V2[] = "09:06:45.012 : [DXE ] [INFO] ents a single video output device, then the set of modes returned by this \n";
CHAR8 Line13V2[] = "09:06:45.012 : [DXE ] [ERR ] service is the subset of modes supported by both the graphics controller a\n";
CHAR8 Line14V2[] = "09:06:45.012 : [DXE ] [ERR ] nd the video output device.\n";
CHAR8 Line15V2[] = "09:06:45.012 : [DXE ] [ERR ] \n";
CHAR8 Line16V2[] = "09:06:45.012 : [DXE ] [ERR ] If the EFI_GRAPHICS_OUTPUT_PROTOCOL is installed on the handle that repres\n";
CHAR8 Line17V2[] = "09:06:45.012 : [DXE ] [ERR ] ents a combination of video output devices, then the set of modes returned\n";
CHAR8 Line18V2[] = "09:06:45.012 : [DXE ] [INFO] by this service is the subset of modes supported by the graphics controll\n";
CHAR8 Line19V2[] = "09:06:45.012 : [DXE ] [ERR ] er and all of the video output devices represented by the handle.\n";

/* spell-checker: enable */

Expand Down

0 comments on commit da8da86

Please sign in to comment.