Skip to content

Commit

Permalink
Add prefix for advanced logger memory message entries (#388)
Browse files Browse the repository at this point in the history 
# Preface

Please ensure you have read the [contribution
docs](https://github.com/microsoft/mu/blob/master/CONTRIBUTING.md) prior
to submitting the pull request. In particular,
[pull request
guidelines](https://github.com/microsoft/mu/blob/master/CONTRIBUTING.md#pull-request-best-practices).

## Description

This change introduces a new message entry structure, which contains
extra information of log producer and can be used to differentiate the
different boot phases, i.e. PEI, DXE, SMM, etc. Platforms that have
multiple firmware entities can leverage this extra information to
distinguish coalesced memory logging regions.

The updated applications (UEFI shell app and host OS Python script) are
also updated to support new message entry structure while maintaining
the backwards compatibility.

Resolves #375.

For each item, place an "x" in between `[` and `]` if true. Example:
`[x]`.
_(you can also check items in the GitHub UI)_

- [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, ...
- [x] 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, ...
- [x] 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

This change was tested on QEMU Q35 and verified that prefix are properly
injected for DXE phase prints.

## Integration Instructions

The log parsers are updated, thus platforms use the existing parser
should pick up the latest tool from mu_plus. For platforms that carry
their own implementation, they should add the proper support in their
own implementation before picking up this change from mu_plus.
  • Loading branch information
@kuqin12 @kenlautner
kuqin12 authored and kenlautner committed Jan 19, 2024
1 parent ad7b45a commit a19c8f1
Show file tree
Hide file tree
Showing 16 changed files with 680 additions and 72 deletions.
97 changes: 86 additions & 11 deletions AdvLoggerPkg/Application/DecodeUefiLog/DecodeUefiLog.py
View file
Original file line number Diff line number Diff line change
Expand Up @@ -186,6 +186,11 @@ class AdvLogParser ():
V3_LOGGER_INFO_SIZE = 80
V3_LOGGER_INFO_VERSION = 3

# V4 and V3 are the same definition, just an indicator for single firmware systems that
# starting from V4, all the message will have v2 message entry format.
V4_LOGGER_INFO_SIZE = V3_LOGGER_INFO_SIZE
V4_LOGGER_INFO_VERSION = 4

# ---------------------------------------------------------------------- #
#
#
Expand All @@ -199,6 +204,42 @@ class AdvLogParser ():
#
MESSAGE_ENTRY_SIZE = 18
MAX_MESSAGE_SIZE = 512
# ---------------------------------------------------------------------- #
#
#
# typedef struct {
# UINT32 Signature; // Signature
# UINT8 MajorVersion; // Major version of advanced logger message structure
# UINT8 MinorVersion; // Minor version of advanced logger message structure
# UINT32 DebugLevel; // Debug Level
# UINT64 TimeStamp; // Time stamp
# UINT16 Phase; // Boot phase that produced this message entry
# UINT16 MessageLen; // Number of bytes in Message
# UINT16 MessageOffset; // Offset of Message from start of structure,
# // used to calculate the address of the Message
# CHAR8 MessageText[]; // Message Text
# } ADVANCED_LOGGER_MESSAGE_ENTRY_V2;
#
#
MESSAGE_ENTRY_SIZE_V2 = 24
ADVANCED_LOGGER_PHASE_UNSPECIFIED = 0
ADVANCED_LOGGER_PHASE_SEC = 1
ADVANCED_LOGGER_PHASE_PEI = 2
ADVANCED_LOGGER_PHASE_PEI64 = 3
ADVANCED_LOGGER_PHASE_DXE = 4
ADVANCED_LOGGER_PHASE_RUNTIME = 5
ADVANCED_LOGGER_PHASE_MM_CORE = 6
ADVANCED_LOGGER_PHASE_MM = 7
ADVANCED_LOGGER_PHASE_SMM_CORE = 8
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] "]
#
# ---------------------------------------------------------------------- #
#
#
# The dictionary entries for MessageLineEntry is based on the UEFI structure above.
#
Expand Down Expand Up @@ -296,7 +337,7 @@ def _InitializeLoggerInfo(self, InFile, StartLine):
if InFile.tell() != (self.V1_LOGGER_INFO_SIZE):
raise Exception('Error initializing logger info. AmountRead: %d' % InFile.tell())

elif Version == self.V2_LOGGER_INFO_VERSION or Version == self.V3_LOGGER_INFO_VERSION:
elif Version == self.V2_LOGGER_INFO_VERSION or Version == self.V3_LOGGER_INFO_VERSION or Version == self.V4_LOGGER_INFO_VERSION:
Size = self.V2_LOGGER_INFO_SIZE if Version == self.V2_LOGGER_INFO_VERSION else self.V3_LOGGER_INFO_SIZE
BaseAddress = struct.unpack("=Q", InFile.read(8))[0] + Size
LoggerInfo["LogBuffer"] = Size
Expand Down Expand Up @@ -326,7 +367,7 @@ def _InitializeLoggerInfo(self, InFile, StartLine):
InFile.read(1) # skip Pad2 field

# If at v3, there will be 8 bytes for print level and pads, which we do not care.
if Version == self.V3_LOGGER_INFO_VERSION:
if Version == self.V3_LOGGER_INFO_VERSION or Version == self.V4_LOGGER_INFO_VERSION:
InFile.read(4)
InFile.read(4)

Expand Down Expand Up @@ -360,12 +401,28 @@ def _ReadMessageEntry(self, LoggerInfo):
MessageEntry = {}

InFile = LoggerInfo["InFile"]

EntryStart = InFile.tell()
MessageEntry["Signature"] = InFile.read(4).decode('utf-8', 'replace')
MessageEntry["DebugLevel"] = struct.unpack("=I", InFile.read(4))[0]
MessageEntry["TimeStamp"] = struct.unpack("=Q", InFile.read(8))[0]
MessageEntry["MessageLen"] = struct.unpack("=H", InFile.read(2))[0]
MessageEntry["MessageText"] = InFile.read(MessageEntry["MessageLen"]).decode('utf-8', 'replace')

if (MessageEntry["Signature"] == 'ALMS'):
MessageEntry["DebugLevel"] = struct.unpack("=I", InFile.read(4))[0]
MessageEntry["TimeStamp"] = struct.unpack("=Q", InFile.read(8))[0]
MessageEntry["MessageLen"] = struct.unpack("=H", InFile.read(2))[0]
MessageEntry["MessageText"] = InFile.read(MessageEntry["MessageLen"]).decode('utf-8', 'replace')
MessageEntry["Phase"] = self.ADVANCED_LOGGER_PHASE_UNSPECIFIED
elif (MessageEntry["Signature"] == 'ALM2'):
MessageEntry["MajorVersion"] = struct.unpack("=B", InFile.read(1))[0]
MessageEntry["MinorVersion"] = struct.unpack("=B", InFile.read(1))[0]
MessageEntry["DebugLevel"] = struct.unpack("=I", InFile.read(4))[0]
MessageEntry["TimeStamp"] = struct.unpack("=Q", InFile.read(8))[0]
MessageEntry["Phase"] = struct.unpack("=H", InFile.read(2))[0]
MessageEntry["MessageLen"] = struct.unpack("=H", InFile.read(2))[0]
MessageEntry["MessageOffset"] = struct.unpack("=H", InFile.read(2))[0]
# Offset is from the start of the structure, so we do that from the beginning of this file
InFile.seek(EntryStart + MessageEntry["MessageOffset"])
MessageEntry["MessageText"] = InFile.read(MessageEntry["MessageLen"]).decode('utf-8', 'replace')
else:
raise Exception("Message Block has wrong signature at offset 0x%X" % InFile.tell())

Skip = InFile.tell()
Norm = int((int((Skip + 7) / 8)) * 8)
Expand All @@ -374,7 +431,10 @@ def _ReadMessageEntry(self, LoggerInfo):
InFile.read(Skip)

NextMessage = InFile.tell()
NextMessageLen = self.MESSAGE_ENTRY_SIZE + int(int((MessageEntry["MessageLen"] + 7) / 8) * 8)
if MessageEntry["Signature"] == 'ALMS':
NextMessageLen = self.MESSAGE_ENTRY_SIZE + int(int((MessageEntry["MessageLen"] + 7) / 8) * 8)
elif MessageEntry["Signature"] == 'ALM2':
NextMessageLen = MessageEntry["MessageOffset"] + int(int((MessageEntry["MessageLen"] + 7) / 8) * 8)
NextMessage = NextMessage + NextMessageLen

return (MessageEntry, NextMessage)
Expand All @@ -401,14 +461,15 @@ def _GetNextMessageBlock(self, LoggerInfo):

(MessageEntry, NextMessage) = self._ReadMessageEntry(LoggerInfo)

if MessageEntry["Signature"] != 'ALMS':
print("Log signature was incorrect. Should be 'ALMS', was '%s'" % MessageEntry["Signature"])
if MessageEntry["Signature"] != 'ALMS' and MessageEntry["Signature"] != 'ALM2':
print("Log signature was incorrect. Should be either 'ALMS' or 'ALM2', was '%s'" % MessageEntry["Signature"])
raise Exception("Message Block has wrong signature at offset 0x%X" % InFile.tell())

MessageBlock["Message"] = MessageEntry["MessageText"]
MessageBlock["DebugLevel"] = MessageEntry["DebugLevel"]
MessageBlock["MessageLen"] = MessageEntry["MessageLen"]
MessageBlock["TimeStamp"] = MessageEntry["TimeStamp"]
MessageBlock["Phase"] = MessageEntry["Phase"]

return (self.SUCCESS, MessageBlock)

Expand Down Expand Up @@ -476,6 +537,7 @@ def _GetNextFormattedLine(self, AccessMessageLineEntry, LoggerInfo):
AccessMessageLineEntry["ResidualChar"] = AccessMessageBlock["Message"]
AccessMessageLineEntry["TimeStamp"] = AccessMessageBlock["TimeStamp"]
AccessMessageLineEntry["DebugLevel"] = AccessMessageBlock["DebugLevel"]
AccessMessageLineEntry["Phase"] = AccessMessageBlock["Phase"]

return (Status, AccessMessageLineEntry)

Expand Down Expand Up @@ -515,6 +577,18 @@ def _GetTimeStamp(self, Ticks, Frequency, BaseTime):

return Timestamp

#
# Get the formatted phase string
#
def _GetPhaseString(self, Phase):
if Phase >= self.ADVANCED_LOGGER_PHASE_CNT:
PhaseString = f"[{Phase:04}] "
elif Phase <= self.ADVANCED_LOGGER_PHASE_UNSPECIFIED:
PhaseString = ""
else:
PhaseString = self.PHASE_STRING_LIST[Phase]
return PhaseString

#
# Get all of the formated message lines
#
Expand All @@ -533,7 +607,8 @@ def _GetLines(self, lines, LoggerInfo):

if CurrentLine >= StartLine:
Ticks = MessageLine["TimeStamp"]
NewLine = self._GetTimeStamp(Ticks, LoggerInfo["Frequency"], LoggerInfo["BaseTime"]) + MessageLine["Message"].rstrip("\r\n")
PhaseString = self._GetPhaseString(MessageLine["Phase"])
NewLine = self._GetTimeStamp(Ticks, LoggerInfo["Frequency"], LoggerInfo["BaseTime"]) + PhaseString + MessageLine["Message"].rstrip("\r\n")
lines.append(NewLine + '\n')

CurrentLine += 1
Expand Down
44 changes: 38 additions & 6 deletions AdvLoggerPkg/Include/AdvancedLoggerInternal.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -11,11 +11,26 @@
#ifndef __ADVANCED_LOGGER_INTERNAL_H__
#define __ADVANCED_LOGGER_INTERNAL_H__

#define ADVANCED_LOGGER_SIGNATURE SIGNATURE_32('A','L','O','G')
#define ADVANCED_LOGGER_HW_LVL_VER 3
#define ADVANCED_LOGGER_SIGNATURE SIGNATURE_32('A','L','O','G')
#define ADVANCED_LOGGER_HW_LVL_VER 4
#define ADVANCED_LOGGER_MSG_MAJ_VER 2
#define ADVANCED_LOGGER_MSG_MIN_VER 0

#define ADVANCED_LOGGER_VERSION ADVANCED_LOGGER_HW_LVL_VER

#define ADVANCED_LOGGER_PHASE_UNSPECIFIED 0
#define ADVANCED_LOGGER_PHASE_SEC 1
#define ADVANCED_LOGGER_PHASE_PEI 2
#define ADVANCED_LOGGER_PHASE_PEI64 3
#define ADVANCED_LOGGER_PHASE_DXE 4
#define ADVANCED_LOGGER_PHASE_RUNTIME 5
#define ADVANCED_LOGGER_PHASE_MM_CORE 6
#define ADVANCED_LOGGER_PHASE_MM 7
#define ADVANCED_LOGGER_PHASE_SMM_CORE 8
#define ADVANCED_LOGGER_PHASE_SMM 9
#define ADVANCED_LOGGER_PHASE_TFA 10
#define ADVANCED_LOGGER_PHASE_CNT 11

//
// These Pcds are used to carve out a PEI memory buffer from the temporary RAM.
//
Expand Down Expand Up @@ -59,13 +74,30 @@ typedef struct {
CHAR8 MessageText[]; // Message Text
} ADVANCED_LOGGER_MESSAGE_ENTRY;

#define MESSAGE_ENTRY_SIZE(LenOfMessage) (ALIGN_VALUE(sizeof(ADVANCED_LOGGER_MESSAGE_ENTRY) + LenOfMessage ,8))
typedef struct {
UINT32 Signature; // Signature
UINT8 MajorVersion; // Major version of advanced logger message structure
UINT8 MinorVersion; // Minor version of advanced logger message structure
UINT32 DebugLevel; // Debug Level
UINT64 TimeStamp; // Time stamp
UINT16 Phase; // Boot phase that produced this message entry
UINT16 MessageLen; // Number of bytes in Message
UINT16 MessageOffset; // Offset of Message from start of structure,
// used to calculate the address of the Message
CHAR8 MessageText[]; // Message Text
} ADVANCED_LOGGER_MESSAGE_ENTRY_V2;

#define MESSAGE_ENTRY_SIZE(LenOfMessage) (ALIGN_VALUE(sizeof(ADVANCED_LOGGER_MESSAGE_ENTRY) + LenOfMessage ,8))
#define MESSAGE_ENTRY_SIZE_V2(LenOfEntry, LenOfMessage) (ALIGN_VALUE(LenOfEntry + LenOfMessage ,8))

#define NEXT_LOG_ENTRY(LogEntry) ((ADVANCED_LOGGER_MESSAGE_ENTRY *) ((UINTN) LogEntry + MESSAGE_ENTRY_SIZE(LogEntry->MessageLen)))
#define NEXT_LOG_ENTRY(LogEntry) ((ADVANCED_LOGGER_MESSAGE_ENTRY *)((UINTN)LogEntry + MESSAGE_ENTRY_SIZE(LogEntry->MessageLen)))
#define NEXT_LOG_ENTRY_V2(LogEntryV2) ((ADVANCED_LOGGER_MESSAGE_ENTRY_V2 *)((UINTN)LogEntryV2 + MESSAGE_ENTRY_SIZE_V2(LogEntryV2->MessageOffset, LogEntryV2->MessageLen)))

#define MESSAGE_ENTRY_SIGNATURE SIGNATURE_32('A','L','M','S')
#define MESSAGE_ENTRY_SIGNATURE SIGNATURE_32('A','L','M','S')
#define MESSAGE_ENTRY_SIGNATURE_V2 SIGNATURE_32('A','L','M','2')

#define MESSAGE_ENTRY_FROM_MSG(a) BASE_CR (a, ADVANCED_LOGGER_MESSAGE_ENTRY, MessageText)
#define MESSAGE_ENTRY_FROM_MSG(a) BASE_CR (a, ADVANCED_LOGGER_MESSAGE_ENTRY, MessageText)
#define MESSAGE_ENTRY_FROM_MSG_V2(a, offset) ((UINTN)a - offset)

//
// Insure the size of is a multiple of 8 bytes
Expand Down
16 changes: 9 additions & 7 deletions AdvLoggerPkg/Include/Library/AdvancedLoggerAccessLib.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -41,13 +41,14 @@ MAX MESSAGE size.
typedef struct {
// Message is IN/OUT. On the first input, it must be NULL. On subsequent
// calls, the previously returned pointer to know where to get the next
// message. Message is a pointer into the physical memory buffer, and it NOT
// message. Message is a pointer into the physical memory buffer, and is NOT
// properly terminated.
CONST CHAR8 *Message; // NULL (first), Pointer to Current Message Text
UINT32 DebugLevel; // DEBUG Message Level
UINT16 MessageLen; // Number of bytes in Message
UINT16 Reserved;
UINT16 Phase; // Boot phase that produced this message entry
UINT64 TimeStamp; // Time stamp
UINT16 MessageOffset; // Offset of Message in the physical memory buffer
} ADVANCED_LOGGER_ACCESS_MESSAGE_BLOCK_ENTRY;

typedef struct {
Expand All @@ -56,11 +57,12 @@ typedef struct {
// formatting a line. Message will point to a properly NULL terminated ASCII STRING.

// BlockEntry is used to manage the current place in the physical memory buffer.
CHAR8 *Message; // Pointer to Message Text
UINT32 DebugLevel; // DEBUG Message Level
UINT16 MessageLen; // Number of bytes in Message
UINT16 Reserved;
UINT64 TimeStamp; // Time stamp
CHAR8 *Message; // Pointer to Message Text
UINT32 DebugLevel; // DEBUG Message Level
UINT16 MessageLen; // Number of bytes in Message
UINT16 Phase; // Boot phase that produced this message entry
UINT64 TimeStamp; // Time stamp
UINT16 MessageOffset; // Offset of Message in the physical memory buffer

// The following are private members for GetNextBlock. Initialize these
// members to NULL and 0 respectively.
Expand Down
Loading

0 comments on commit a19c8f1

Please sign in to comment.