Improve GetDebugLogFile() and SaveMessageToDebugLogFile().

This commit is contained in:
jief666 2020-10-19 15:04:03 +03:00
parent 7ac3952a92
commit 2d124e41e3
2 changed files with 108 additions and 91 deletions

View File

@ -294,17 +294,20 @@ MemLogVA (
Marker); Marker);
mMemLog->Cursor += DataWritten; mMemLog->Cursor += DataWritten;
//
// Write to standard debug device also
//
// Jief : use SerialPortWrite instead of DebugPrint to avoid 256 chars message length limitation.
// Jief : do this before CallBack to preserve order of messages sent from inside callback.
SerialPortWrite((UINT8*)LastMessage, mMemLog->Cursor - LastMessage);
// DebugPrint(DEBUG_INFO, "%a", LastMessage);
// //
// Pass this last message to callback if defined // Pass this last message to callback if defined
// //
if (mMemLog->Callback != NULL) { if (mMemLog->Callback != NULL) {
mMemLog->Callback(DebugMode, LastMessage); mMemLog->Callback(DebugMode, LastMessage);
} }
//
// Write to standard debug device also
//
DebugPrint(DEBUG_INFO, "%a", LastMessage);
} }
/** /**
@ -532,13 +535,6 @@ MemLogfVA (
vprintf_with_callback_timestamp_emitcr(Format, Marker, transmitS8Printf, NULL, &printfNewline, Timing, 1); vprintf_with_callback_timestamp_emitcr(Format, Marker, transmitS8Printf, NULL, &printfNewline, Timing, 1);
size_t DataWritten = mMemLog->Cursor - mMemLog->Buffer - LastMessage; size_t DataWritten = mMemLog->Cursor - mMemLog->Buffer - LastMessage;
//
// Pass this last message to callback if defined
//
if (mMemLog->Callback != NULL) {
mMemLog->Callback(DebugMode, mMemLog->Buffer + LastMessage);
}
// //
// Check driver debug mask value and global mask // Check driver debug mask value and global mask
// //
@ -549,8 +545,16 @@ MemLogfVA (
// Write to standard debug device also // Write to standard debug device also
// //
// Jief : use SerialPortWrite instead of DebugPrint to avoid 256 chars message length limitation. // Jief : use SerialPortWrite instead of DebugPrint to avoid 256 chars message length limitation.
// Jief : do this before CallBack to preserve order of messages sent from inside callback.
SerialPortWrite((UINT8*)(mMemLog->Buffer + LastMessage), DataWritten); SerialPortWrite((UINT8*)(mMemLog->Buffer + LastMessage), DataWritten);
// DebugPrint(DEBUG_INFO, "%a", LastMessage); // DebugPrint(DEBUG_INFO, "%a", LastMessage);
//
// Pass this last message to callback if defined
//
if (mMemLog->Callback != NULL) {
mMemLog->Callback(DebugMode, mMemLog->Buffer + LastMessage);
}
} }
/** /**

View File

@ -74,8 +74,11 @@ PrintBytes(IN void *Bytes, IN UINTN Number)
} }
static EFI_FILE_PROTOCOL* gLogFile = NULL; static EFI_FILE_PROTOCOL* gLogFile = NULL;
STATIC BOOLEAN FirstTimeSave = TRUE; // Do not keep a pointer to MemLogBuffer. Because a reallocation, it could become invalid.
// Avoid debug looping. TO be able to call DBG from inside function that DBG calls, we need to suspend callback to avoid a loop.
// Just instanciante this, the destructor will restore the callback.
class SuspendMemLogCallback class SuspendMemLogCallback
{ {
MEM_LOG_CALLBACK memlogCallBack_saved; MEM_LOG_CALLBACK memlogCallBack_saved;
@ -87,6 +90,12 @@ public:
~SuspendMemLogCallback() { SetMemLogCallback(memlogCallBack_saved); }; ~SuspendMemLogCallback() { SetMemLogCallback(memlogCallBack_saved); };
}; };
#if DEBUG_BOOTLOG == 0
#define DGB_nbCallback(...)
#else
#define DGB_nbCallback(...) do { SuspendMemLogCallback smc; DBG(__VA_ARGS__); } while (0)
#endif
void closeDebugLog() void closeDebugLog()
{ {
EFI_STATUS Status; EFI_STATUS Status;
@ -96,66 +105,61 @@ void closeDebugLog()
SuspendMemLogCallback smc; SuspendMemLogCallback smc;
Status = gLogFile->Close(gLogFile); Status = gLogFile->Close(gLogFile);
DBG("closeDebugLog() -> %s\n", efiStrError(Status));
gLogFile = NULL; gLogFile = NULL;
//DGB_nbCallback("closeDebugLog() -> %s\n", efiStrError(Status));
} }
EFI_FILE_PROTOCOL* GetDebugLogFile() static UINTN GetDebugLogFile()
{ {
EFI_STATUS Status; EFI_STATUS Status;
EFI_LOADED_IMAGE *LoadedImage;
EFI_FILE_PROTOCOL *RootDir;
EFI_FILE_PROTOCOL *LogFile; EFI_FILE_PROTOCOL *LogFile;
// Avoid debug looping. We don't want DBG from this function to call this function through the callback. if ( gLogFile ) return 0;
SuspendMemLogCallback smc;
// get RootDir from device we are loaded from // // get RootDir from device we are loaded from
Status = gBS->HandleProtocol(gImageHandle, &gEfiLoadedImageProtocolGuid, (VOID **) &LoadedImage); // Status = gBS->HandleProtocol(gImageHandle, &gEfiLoadedImageProtocolGuid, (VOID **) &LoadedImage);
if (EFI_ERROR(Status)) { // if (EFI_ERROR(Status)) {
DBG(" GetDebugLogFile() -> HandleProtocol : %s\n", efiStrError(Status)); // DGB_nbCallback(" GetDebugLogFile() -> HandleProtocol : %s\n", efiStrError(Status));
return NULL; // }
} // RootDir = EfiLibOpenRoot(LoadedImage->DeviceHandle);
RootDir = EfiLibOpenRoot(LoadedImage->DeviceHandle); // if (RootDir == NULL) {
if (RootDir == NULL) { // DGB_nbCallback(" GetDebugLogFile() -> EfiLibOpenRoot : %s\n", efiStrError(Status));
DBG(" GetDebugLogFile() -> EfiLibOpenRoot : %s\n", efiStrError(Status)); // }
return NULL; //
} // // Open log file from current root
// Status = RootDir->Open(RootDir, &LogFile, SWPrintf("%ls\\%ls", self.getCloverDirFullPath().wc_str(), DEBUG_LOG).wc_str(),
// EFI_FILE_MODE_READ | EFI_FILE_MODE_WRITE, 0);
if ( !self.isInitialized() ) return 0;
// Open log file from current root // Open log file from current root
Status = RootDir->Open(RootDir, &LogFile, SWPrintf("%ls\\%ls", self.getCloverDirFullPath().wc_str(), DEBUG_LOG).wc_str(), Status = self.getCloverDir().Open(&self.getCloverDir(), &LogFile, DEBUG_LOG, EFI_FILE_MODE_READ | EFI_FILE_MODE_WRITE, 0);
EFI_FILE_MODE_READ | EFI_FILE_MODE_WRITE, 0);
if ( !EFI_ERROR (Status) && GlobalConfig.ScratchDebugLogAtStart ) if ( !EFI_ERROR (Status) && GlobalConfig.ScratchDebugLogAtStart )
{ {
// Here, we are not at the beginning. Some log was already sent. // Here, we may not be at the first line sent to log.
// That's because the setting GlobalConfig.ScratchDebugLogAtStart is not set before the first log sent. // That's because the setting GlobalConfig.ScratchDebugLogAtStart is not set before the first log is sent.
DBG(" GetDebugLogFile() -> deleting the log '%ls'\n", DEBUG_LOG); DGB_nbCallback("GetDebugLogFile() -> deleting the log '%ls'\n", DEBUG_LOG);
EFI_STATUS StatusDelete; EFI_STATUS StatusDelete;
StatusDelete = LogFile->Delete(LogFile); StatusDelete = LogFile->Delete(LogFile);
if ( StatusDelete == EFI_SUCCESS) { if ( StatusDelete == EFI_SUCCESS) {
GlobalConfig.ScratchDebugLogAtStart = false; GlobalConfig.ScratchDebugLogAtStart = false;
FirstTimeSave = true;
LogFile = NULL;
Status = EFI_NOT_FOUND; // to make be reopened in the next lines. Status = EFI_NOT_FOUND; // to make be reopened in the next lines.
}else{ }else{
DBG(" Cannot delete log file '%ls\\%ls' : %s\n", self.getCloverDirFullPath().wc_str(), DEBUG_LOG, efiStrError(StatusDelete)); DGB_nbCallback("Cannot delete log file '%ls\\%ls' : %s\n", self.getCloverDirFullPath().wc_str(), DEBUG_LOG, efiStrError(StatusDelete));
RootDir->Close(RootDir);
return NULL;
} }
}else{ }else{
// DBG(" GetDebugLogFile() -> open log : %s\n", efiStrError(Status)); // DGB_nbCallback(" GetDebugLogFile() -> open log : %s\n", efiStrError(Status));
} }
// If the log file is not found try to create it // If the log file is not found try to create it
if (Status == EFI_NOT_FOUND) { if (Status == EFI_NOT_FOUND) {
Status = RootDir->Open(RootDir, &LogFile, SWPrintf("%ls\\%ls", self.getCloverDirFullPath().wc_str(), DEBUG_LOG).wc_str(), // Status = RootDir->Open(RootDir, &LogFile, SWPrintf("%ls\\%ls", self.getCloverDirFullPath().wc_str(), DEBUG_LOG).wc_str(), EFI_FILE_MODE_READ | EFI_FILE_MODE_WRITE | EFI_FILE_MODE_CREATE, 0);
EFI_FILE_MODE_READ | EFI_FILE_MODE_WRITE | EFI_FILE_MODE_CREATE, 0); Status = self.getCloverDir().Open(&self.getCloverDir(), &LogFile, DEBUG_LOG, EFI_FILE_MODE_READ | EFI_FILE_MODE_WRITE | EFI_FILE_MODE_CREATE, 0);
} }
RootDir->Close(RootDir);
RootDir = NULL;
// Jief : do we need that ?
// if (EFI_ERROR(Status)) { // if (EFI_ERROR(Status)) {
// // try on first EFI partition // // try on first EFI partition
// Status = egFindESP(&RootDir); // Status = egFindESP(&RootDir);
@ -172,63 +176,72 @@ EFI_FILE_PROTOCOL* GetDebugLogFile()
// } // }
// } // }
if (EFI_ERROR(Status)) { // Jief : Instead of EfiLibFileInfo, let's use SetPosition to get the size.
DBG(" GetDebugLogFile() -> !opened : %s\n", efiStrError(Status)); // if (!EFI_ERROR(Status)) {
LogFile = NULL; // EFI_FILE_INFO *Info = EfiLibFileInfo(LogFile);
} // if (Info) {
// Status = LogFile->SetPosition(LogFile, Info->FileSize);
// if ( EFI_ERROR(Status) ) {
// DBG("SaveMessageToDebugLogFile SetPosition error %s\n", efiStrError(Status));
// }
// }
// }
return LogFile; if (!EFI_ERROR(Status)) {
Status = LogFile->SetPosition(LogFile, 0xFFFFFFFFFFFFFFFFULL);
if ( EFI_ERROR (Status) ) {
DGB_nbCallback("GetDebugLogFile() -> Cannot set log position to 0xFFFFFFFFFFFFFFFFULL : %s\n", efiStrError(Status));
LogFile->Close(LogFile);
}else{
UINTN size;
Status = LogFile->GetPosition(LogFile, &size);
if ( EFI_ERROR (Status) ) {
DGB_nbCallback("GetDebugLogFile() -> Cannot get log position : %s\n", efiStrError(Status));
LogFile->Close(LogFile);
}else{
//DGB_nbCallback("GetDebugLogFile() -> opened. log position = %lld (lwo %lld)\n", size, lastWrittenOffset);
gLogFile = LogFile;
return size;
}
}
}
return 0;
} }
VOID SaveMessageToDebugLogFile(IN CHAR8 *LastMessage) VOID SaveMessageToDebugLogFile(IN CHAR8 *LastMessage)
{ {
// STATIC UINTN Position = 0;
CHAR8 *MemLogBuffer;
UINTN MemLogLen;
CHAR8 *Text;
UINTN TextLen;
EFI_FILE_HANDLE LogFile;
EFI_STATUS Status; EFI_STATUS Status;
// Avoid debug looping. We don't want DBG from this function to call this function through the callback. UINTN lastWrittenOffset = GetDebugLogFile();
SuspendMemLogCallback smc;
MemLogBuffer = GetMemLogBuffer(); if ( gLogFile == NULL ) return;
MemLogLen = GetMemLogLen();
Text = LastMessage;
TextLen = AsciiStrLen(LastMessage);
LogFile = GetDebugLogFile();
// Write to the log file
if (LogFile != NULL) {
// Advance to the EOF so we append
EFI_FILE_INFO *Info = EfiLibFileInfo(LogFile);
if (Info) {
Status = LogFile->SetPosition(LogFile, Info->FileSize);
if ( EFI_ERROR(Status) ) {
DBG("SaveMessageToDebugLogFile SetPosition error %s\n", efiStrError(Status));
}
// If we haven't had root before this write out whole log
if (FirstTimeSave) {
Text = MemLogBuffer;
TextLen = MemLogLen;
FirstTimeSave = FALSE;
DBG("SaveMessageToDebugLogFile first time\n");
}
// Write out this message // Write out this message
const char* lastWrittenPointer = GetMemLogBuffer() + lastWrittenOffset;
UINTN TextLen = strlen(lastWrittenPointer);
UINTN TextLen2 = TextLen; UINTN TextLen2 = TextLen;
Status = LogFile->Write(LogFile, &TextLen2, Text);
Status = gLogFile->Write(gLogFile, &TextLen2, lastWrittenPointer);
lastWrittenOffset += TextLen2;
if ( EFI_ERROR(Status) ) { if ( EFI_ERROR(Status) ) {
DBG("SaveMessageToDebugLogFile write error %s\n", efiStrError(Status)); DGB_nbCallback("SaveMessageToDebugLogFile write error %s\n", efiStrError(Status));
closeDebugLog();
}else{ }else{
if ( TextLen2 != TextLen ) { if ( TextLen2 != TextLen ) {
DBG("SaveMessageToDebugLogFile TextLen2(%lld) != TextLen(%lld)\n", TextLen2, TextLen); DGB_nbCallback("SaveMessageToDebugLogFile TextLen2(%lld) != TextLen(%lld)\n", TextLen2, TextLen);
closeDebugLog();
}else{
// Not all Firmware implements Flush. So we have to close everytime to force flush. Let's Close() instead of Flush()
// Is there a performance difference ? Is it worth to create a setting ? Probably not...
// Status = LogFile->Flush(LogFile);
// if ( EFI_ERROR(Status) ) {
// DGB_nbCallback("SaveMessageToDebugLogFile Cannot flush error %s\n", efiStrError(Status));
// closeDebugLog();
// }
} }
} }
} // Not all Firmware implements Flush. So we have to close everytime to force flush.
LogFile->Close(LogFile); closeDebugLog();
}
} }
void EFIAPI MemLogCallback(IN INTN DebugMode, IN CHAR8 *LastMessage) void EFIAPI MemLogCallback(IN INTN DebugMode, IN CHAR8 *LastMessage)