From 21da3ebc27ac594f4e39fdb93cb5f838547ad386 Mon Sep 17 00:00:00 2001 From: Maschell Date: Fri, 13 May 2022 16:13:03 +0200 Subject: [PATCH] Improve logging --- .github/workflows/pr.yml | 11 +++++++++ Makefile | 7 +++++- README.md | 9 ++++++++ source/ElfUtils.cpp | 34 +++++++++++++-------------- source/main.cpp | 20 ++++++++-------- source/module/ModuleDataFactory.cpp | 30 ++++++++++++------------ source/utils/logger.h | 36 ++++++++++++++++++++--------- 7 files changed, 93 insertions(+), 54 deletions(-) diff --git a/.github/workflows/pr.yml b/.github/workflows/pr.yml index 7464b72..171b7bf 100644 --- a/.github/workflows/pr.yml +++ b/.github/workflows/pr.yml @@ -10,6 +10,17 @@ jobs: - name: clang-format run: | docker run --rm -v ${PWD}:/src wiiuenv/clang-format:13.0.0-2 -r ./source + check-build-with-logging: + runs-on: ubuntu-18.04 + needs: clang-format + steps: + - uses: actions/checkout@v2 + - name: build binary with logging + run: | + docker build . -t builder + docker run --rm -v ${PWD}:/project builder make DEBUG=VERBOSE + docker run --rm -v ${PWD}:/project builder make clean + docker run --rm -v ${PWD}:/project builder make DEBUG=1 build-binary: runs-on: ubuntu-18.04 needs: clang-format diff --git a/Makefile b/Makefile index d8eb196..e5f11d4 100644 --- a/Makefile +++ b/Makefile @@ -38,11 +38,16 @@ CFLAGS += $(INCLUDE) -D__WIIU__ -D__WUT__ CXXFLAGS := $(CFLAGS) -std=c++20 -fno-exceptions -fno-rtti -ifeq ($(DEBUG),1) +ifeq ($(DEBUG),1) CXXFLAGS += -DDEBUG -g CFLAGS += -DDEBUG -g endif +ifeq ($(DEBUG),VERBOSE) +CXXFLAGS += -DDEBUG -DVERBOSE_DEBUG -g +CFLAGS += -DDEBUG -DVERBOSE_DEBUG -g +endif + ASFLAGS := -g $(ARCH) LDFLAGS = -g $(ARCH) $(RPXSPECS) -Wl,-Map,$(notdir $*.map) diff --git a/README.md b/README.md index 4a37f84..61100a2 100644 --- a/README.md +++ b/README.md @@ -23,6 +23,15 @@ When launching an given enviroment, all `.rpx` files in `[ENVIRONMENT]/modules/s - Make sure not to call `exit` in the setup payloads - The files will be run in the order of their ordered filenames. +## Buildflags + +### Logging +Building via `make` only logs errors (via OSReport). To enable logging via the [LoggingModule](https://github.com/wiiu-env/LoggingModule) set `DEBUG` to `1` or `VERBOSE`. + +`make` Logs errors only (via OSReport). +`make DEBUG=1` Enables information and error logging via [LoggingModule](https://github.com/wiiu-env/LoggingModule). +`make DEBUG=VERBOSE` Enables verbose information and error logging via [LoggingModule](https://github.com/wiiu-env/LoggingModule). + ## Building Make you to have [wut](https://github.com/devkitPro/wut/) installed and use the following command for build: ``` diff --git a/source/ElfUtils.cpp b/source/ElfUtils.cpp index 599f493..83fbd0c 100644 --- a/source/ElfUtils.cpp +++ b/source/ElfUtils.cpp @@ -25,12 +25,12 @@ bool ElfUtils::doRelocation(std::vector> &relocD uint32_t functionAddress = 0; OSDynLoad_FindExport(rplHandle, isData, functionName.c_str(), (void **) &functionAddress); if (functionAddress == 0) { - DEBUG_FUNCTION_LINE("Failed to find export for %s %s %d", functionName.c_str(), rplName.c_str(), isData); + DEBUG_FUNCTION_LINE_ERR("Failed to find export for %s %s %d", functionName.c_str(), rplName.c_str(), isData); return false; } if (!ElfUtils::elfLinkOne(curReloc->getType(), curReloc->getOffset(), curReloc->getAddend(), (uint32_t) curReloc->getDestination(), functionAddress, tramp_data, tramp_length, RELOC_TYPE_IMPORT)) { - DEBUG_FUNCTION_LINE("Relocation failed\n"); + DEBUG_FUNCTION_LINE_ERR("Relocation failed\n"); return false; } } @@ -68,7 +68,7 @@ bool ElfUtils::elfLinkOne(char type, size_t offset, int32_t addend, uint32_t des *((uint16_t *) (target)) = static_cast((value + 0x8000) >> 16); break; case R_PPC_DTPMOD32: - DEBUG_FUNCTION_LINE("################IMPLEMENT ME\n"); + DEBUG_FUNCTION_LINE_ERR("################IMPLEMENT ME\n"); //*((int32_t *)(target)) = tlsModuleIndex; break; case R_PPC_DTPREL32: @@ -86,18 +86,18 @@ bool ElfUtils::elfLinkOne(char type, size_t offset, int32_t addend, uint32_t des case R_PPC_REL14: { auto distance = static_cast(value) - static_cast(target); if (distance > 0x7FFC || distance < -0x7FFC) { - DEBUG_FUNCTION_LINE("***14-bit relative branch cannot hit target."); + DEBUG_FUNCTION_LINE_ERR("***14-bit relative branch cannot hit target."); return false; } if (distance & 3) { - DEBUG_FUNCTION_LINE("***RELOC ERROR %d: lower 2 bits must be zero before shifting.", -470040); + DEBUG_FUNCTION_LINE_ERR("***RELOC ERROR %d: lower 2 bits must be zero before shifting.", -470040); return false; } if ((distance >= 0 && (distance & 0xFFFF8000)) || (distance < 0 && ((distance & 0xFFFF8000) != 0xFFFF8000))) { - DEBUG_FUNCTION_LINE("***RELOC ERROR %d: upper 17 bits before shift must all be the same.", -470040); + DEBUG_FUNCTION_LINE_ERR("***RELOC ERROR %d: upper 17 bits before shift must all be the same.", -470040); return false; } @@ -112,8 +112,8 @@ bool ElfUtils::elfLinkOne(char type, size_t offset, int32_t addend, uint32_t des auto distance = static_cast(value) - static_cast(target); if (distance > 0x1FFFFFC || distance < -0x1FFFFFC) { if (trampolin_data == nullptr) { - DEBUG_FUNCTION_LINE("***24-bit relative branch cannot hit target. Trampolin isn't provided\n"); - DEBUG_FUNCTION_LINE("***value %08X - target %08X = distance %08X\n", value, target, distance); + DEBUG_FUNCTION_LINE_ERR("***24-bit relative branch cannot hit target. Trampolin isn't provided\n"); + DEBUG_FUNCTION_LINE_ERR("***value %08X - target %08X = distance %08X\n", value, target, distance); return false; } else { relocation_trampolin_entry_t *freeSlot = nullptr; @@ -131,13 +131,13 @@ bool ElfUtils::elfLinkOne(char type, size_t offset, int32_t addend, uint32_t des } } if (freeSlot == nullptr) { - DEBUG_FUNCTION_LINE("***24-bit relative branch cannot hit target. Trampolin data list is full\n"); - DEBUG_FUNCTION_LINE("***value %08X - target %08X = distance %08X\n", value, target, (target - (uint32_t) & (freeSlot->trampolin[0]))); + DEBUG_FUNCTION_LINE_ERR("***24-bit relative branch cannot hit target. Trampolin data list is full\n"); + DEBUG_FUNCTION_LINE_ERR("***value %08X - target %08X = distance %08X\n", value, target, (target - (uint32_t) & (freeSlot->trampolin[0]))); return false; } - if (target - (uint32_t) & (freeSlot->trampolin[0]) > 0x1FFFFFC) { - DEBUG_FUNCTION_LINE("**Cannot link 24-bit jump (too far to tramp buffer)."); - DEBUG_FUNCTION_LINE("***value %08X - target %08X = distance %08X\n", value, target, (target - (uint32_t) & (freeSlot->trampolin[0]))); + if (target - (uint32_t) & (freeSlot->trampoline[0]) > 0x1FFFFFC) { + DEBUG_FUNCTION_LINE_ERR("**Cannot link 24-bit jump (too far to tramp buffer)."); + DEBUG_FUNCTION_LINE_ERR("***value %08X - target %08X = distance %08X\n", value, target, (target - (uint32_t) & (freeSlot->trampolin[0]))); return false; } @@ -161,17 +161,17 @@ bool ElfUtils::elfLinkOne(char type, size_t offset, int32_t addend, uint32_t des } if (distance & 3) { - DEBUG_FUNCTION_LINE("***RELOC ERROR %d: lower 2 bits must be zero before shifting.", -470022); + DEBUG_FUNCTION_LINE_ERR("***RELOC ERROR %d: lower 2 bits must be zero before shifting.", -470022); return false; } if (distance < 0 && (distance & 0xFE000000) != 0xFE000000) { - DEBUG_FUNCTION_LINE("***RELOC ERROR %d: upper 7 bits before shift must all be the same (1).", -470040); + DEBUG_FUNCTION_LINE_ERR("***RELOC ERROR %d: upper 7 bits before shift must all be the same (1).", -470040); return false; } if (distance >= 0 && (distance & 0xFE000000)) { - DEBUG_FUNCTION_LINE("***RELOC ERROR %d: upper 7 bits before shift must all be the same (0).", -470040); + DEBUG_FUNCTION_LINE_ERR("***RELOC ERROR %d: upper 7 bits before shift must all be the same (0).", -470040); return false; } @@ -179,7 +179,7 @@ bool ElfUtils::elfLinkOne(char type, size_t offset, int32_t addend, uint32_t des break; } default: - DEBUG_FUNCTION_LINE("***ERROR: Unsupported Relocation_Add Type (%08X):", type); + DEBUG_FUNCTION_LINE_ERR("***ERROR: Unsupported Relocation_Add Type (%08X):", type); return false; } return true; diff --git a/source/main.cpp b/source/main.cpp index 6955f67..8f73dc2 100644 --- a/source/main.cpp +++ b/source/main.cpp @@ -63,7 +63,7 @@ extern "C" uint32_t textStart(); std::string EnvironmentSelectionScreen(const std::map &payloads, int32_t autobootIndex); std::optional getFileContent(const std::string &path) { - DEBUG_FUNCTION_LINE("Read %s", path.c_str()); + DEBUG_FUNCTION_LINE_VERBOSE("Read from file %s", path.c_str()); FILE *f = fopen(path.c_str(), "r"); if (f) { char buf[128]{}; @@ -72,12 +72,12 @@ std::optional getFileContent(const std::string &path) { return std::string(buf); } - DEBUG_FUNCTION_LINE("Failed"); + DEBUG_FUNCTION_LINE_ERR("Failed to load %s", path.c_str()); return {}; } bool writeFileContent(const std::string &path, const std::string &content) { - DEBUG_FUNCTION_LINE("Write to file %s: %s", path.c_str(), content.c_str()); + DEBUG_FUNCTION_LINE_VERBOSE("Write to file %s: %s", path.c_str(), content.c_str()); FILE *f = fopen(path.c_str(), "w"); if (f) { fputs(content.c_str(), f); @@ -89,7 +89,6 @@ bool writeFileContent(const std::string &path, const std::string &content) { extern "C" void __fini(); - int main(int argc, char **argv) { initLogging(); @@ -133,7 +132,7 @@ int main(int argc, char **argv) { auto res = getFileContent(AUTOBOOT_CONFIG_PATH); auto autobootIndex = -1; if (res) { - DEBUG_FUNCTION_LINE("Got result %s", res->c_str()); + DEBUG_FUNCTION_LINE_VERBOSE("Got result %s", res->c_str()); for (int i = 0; i < environmentDirs.GetFilecount(); i++) { if (environmentDirs.GetFilename(i) == res.value()) { DEBUG_FUNCTION_LINE("Found environment %s from config at index %d", res.value().c_str(), i); @@ -144,7 +143,7 @@ int main(int argc, char **argv) { } } } else { - DEBUG_FUNCTION_LINE("No config found"); + DEBUG_FUNCTION_LINE_ERR("No config found"); } std::map environmentPaths; @@ -162,12 +161,12 @@ int main(int argc, char **argv) { } if (forceMenu || (btn & VPAD_BUTTON_X) == VPAD_BUTTON_X) { - DEBUG_FUNCTION_LINE("Open menu!"); + DEBUG_FUNCTION_LINE_VERBOSE("Open menu!"); environment_path = EnvironmentSelectionScreen(environmentPaths, autobootIndex); if (environmentPaths.empty()) { noEnvironmentsFound = true; } else { - DEBUG_FUNCTION_LINE("Selected %s", environment_path.c_str()); + DEBUG_FUNCTION_LINE_VERBOSE("Selected %s", environment_path.c_str()); } } } @@ -184,12 +183,13 @@ int main(int argc, char **argv) { auto moduleData = ModuleDataFactory::load(setupModules.GetFilepath(i), destination_address_end, ((uint32_t) gModuleData) - MEMORY_REGION_START, gModuleData->trampolines, DYN_LINK_TRAMPOLIN_LIST_LENGTH); if (!moduleData) { - DEBUG_FUNCTION_LINE("Failed to load %s", setupModules.GetFilepath(i)); + DEBUG_FUNCTION_LINE_ERR("Failed to load %s", setupModules.GetFilepath(i)); continue; } DEBUG_FUNCTION_LINE("Loaded module data"); auto relocData = moduleData.value()->getRelocationDataList(); if (!ElfUtils::doRelocation(relocData, gModuleData->trampolines, DYN_LINK_TRAMPOLIN_LIST_LENGTH)) { + DEBUG_FUNCTION_LINE_ERR("Relocations failed"); OSFatal("Relocations failed"); } else { DEBUG_FUNCTION_LINE("Relocation done"); @@ -213,7 +213,7 @@ int main(int argc, char **argv) { if (strcmp(argv[i], "void forceDefaultTitleIDToWiiUMenu(void)") == 0) { if ((i + 1) < argc) { i++; - DEBUG_FUNCTION_LINE("call forceDefaultTitleIDToWiiUMenu"); + DEBUG_FUNCTION_LINE_VERBOSE("call forceDefaultTitleIDToWiiUMenu"); // clang-format off auto forceDefaultTitleIDToWiiUMenu = (void(*)()) argv[i]; // clang-format on diff --git a/source/module/ModuleDataFactory.cpp b/source/module/ModuleDataFactory.cpp index d672a05..27286b9 100644 --- a/source/module/ModuleDataFactory.cpp +++ b/source/module/ModuleDataFactory.cpp @@ -33,13 +33,13 @@ ModuleDataFactory::load(const std::string &path, uint32_t destination_address_en uint8_t *buffer = nullptr; uint32_t fsize = 0; if (LoadFileToMem(path.c_str(), &buffer, &fsize) < 0) { - DEBUG_FUNCTION_LINE("Failed to load file"); + DEBUG_FUNCTION_LINE_ERR("Failed to load file"); return {}; } // Load ELF data if (!reader.load(reinterpret_cast(buffer), fsize)) { - DEBUG_FUNCTION_LINE("Can't find or process %s", path.c_str()); + DEBUG_FUNCTION_LINE_ERR("Can't find or process %s", path.c_str()); free(buffer); return {}; } @@ -60,7 +60,7 @@ ModuleDataFactory::load(const std::string &path, uint32_t destination_address_en } if (sizeOfModule > maximum_size) { - DEBUG_FUNCTION_LINE("Module is too big."); + DEBUG_FUNCTION_LINE_ERR("Module is too big."); free(destinations); free(buffer); return {}; @@ -88,7 +88,7 @@ ModuleDataFactory::load(const std::string &path, uint32_t destination_address_en totalSize += sectionSize; if (totalSize > maximum_size) { - DEBUG_FUNCTION_LINE("Couldn't load setup module because it's too big."); + DEBUG_FUNCTION_LINE_ERR("Couldn't load setup module because it's too big."); free(destinations); free(buffer); return {}; @@ -111,7 +111,7 @@ ModuleDataFactory::load(const std::string &path, uint32_t destination_address_en destination -= 0xC0000000; destinations[psec->get_index()] -= 0xC0000000; } else { - DEBUG_FUNCTION_LINE("Unhandled case"); + DEBUG_FUNCTION_LINE_ERR("Unhandled case"); free(destinations); free(buffer); return std::nullopt; @@ -150,7 +150,7 @@ ModuleDataFactory::load(const std::string &path, uint32_t destination_address_en if ((psec->get_type() == SHT_PROGBITS || psec->get_type() == SHT_NOBITS) && (psec->get_flags() & SHF_ALLOC)) { DEBUG_FUNCTION_LINE("Linking (%d)... %s", i, psec->get_name().c_str()); if (!linkSection(reader, psec->get_index(), (uint32_t) destinations[psec->get_index()], offset_text, offset_data, trampolin_data, trampolin_data_length)) { - DEBUG_FUNCTION_LINE("elfLink failed"); + DEBUG_FUNCTION_LINE_ERR("elfLink failed"); free(destinations); free(buffer); return std::nullopt; @@ -193,7 +193,7 @@ std::vector> ModuleDataFactory::getImportRelocat for (uint32_t i = 0; i < sec_num; ++i) { section *psec = reader.sections[i]; if (psec->get_type() == SHT_RELA || psec->get_type() == SHT_REL) { - DEBUG_FUNCTION_LINE("Found relocation section %s", psec->get_name().c_str()); + DEBUG_FUNCTION_LINE_VERBOSE("Found relocation section %s", psec->get_name().c_str()); relocation_section_accessor rel(reader, psec); for (uint32_t j = 0; j < (uint32_t) rel.get_entries_num(); ++j) { Elf64_Addr offset; @@ -204,7 +204,7 @@ std::vector> ModuleDataFactory::getImportRelocat Elf_Half sym_section_index; if (!rel.get_entry(j, offset, sym_value, sym_name, type, addend, sym_section_index)) { - DEBUG_FUNCTION_LINE("Failed to get relocation"); + DEBUG_FUNCTION_LINE_ERR("Failed to get relocation"); break; } @@ -214,7 +214,7 @@ std::vector> ModuleDataFactory::getImportRelocat } auto rplInfo = ImportRPLInformation::createImportRPLInformation(infoMap[sym_section_index]); if (!rplInfo) { - DEBUG_FUNCTION_LINE("Failed to create import information"); + DEBUG_FUNCTION_LINE_ERR("Failed to create import information"); break; } @@ -237,7 +237,7 @@ bool ModuleDataFactory::linkSection(elfio &reader, uint32_t section_index, uint3 for (uint32_t i = 0; i < sec_num; ++i) { section *psec = reader.sections[i]; if (psec->get_info() == section_index) { - DEBUG_FUNCTION_LINE("Found relocation section %s", psec->get_name().c_str()); + DEBUG_FUNCTION_LINE_VERBOSE("Found relocation section %s", psec->get_name().c_str()); relocation_section_accessor rel(reader, psec); for (uint32_t j = 0; j < (uint32_t) rel.get_entries_num(); ++j) { Elf64_Addr offset; @@ -248,7 +248,7 @@ bool ModuleDataFactory::linkSection(elfio &reader, uint32_t section_index, uint3 Elf_Half sym_section_index; if (!rel.get_entry(j, offset, sym_value, sym_name, type, addend, sym_section_index)) { - DEBUG_FUNCTION_LINE("Failed to get relocation"); + DEBUG_FUNCTION_LINE_ERR("Failed to get relocation"); break; } @@ -265,23 +265,23 @@ bool ModuleDataFactory::linkSection(elfio &reader, uint32_t section_index, uint3 } else if (adjusted_sym_value == 0x0) { // } else { - DEBUG_FUNCTION_LINE("Unhandled case %08X", adjusted_sym_value); + DEBUG_FUNCTION_LINE_ERR("Unhandled case %08X", adjusted_sym_value); return false; } if (sym_section_index == SHN_ABS) { // } else if (sym_section_index > SHN_LORESERVE) { - DEBUG_FUNCTION_LINE("NOT IMPLEMENTED: %04X", sym_section_index); + DEBUG_FUNCTION_LINE_ERR("NOT IMPLEMENTED: %04X", sym_section_index); return false; } if (!ElfUtils::elfLinkOne(type, offset, addend, destination, adjusted_sym_value, trampolin_data, trampolin_data_length, RELOC_TYPE_FIXED)) { - DEBUG_FUNCTION_LINE("Link failed"); + DEBUG_FUNCTION_LINE_ERR("Link failed"); return false; } } - DEBUG_FUNCTION_LINE("done"); + DEBUG_FUNCTION_LINE_VERBOSE("done"); } } return true; diff --git a/source/utils/logger.h b/source/utils/logger.h index 061d52e..f9dcd75 100644 --- a/source/utils/logger.h +++ b/source/utils/logger.h @@ -1,5 +1,6 @@ #pragma once +#include #include #include @@ -7,22 +8,33 @@ extern "C" { #endif +#define LOG_APP_TYPE "O" +#define LOG_APP_NAME "environment_loader" + +#define __FILENAME_X__ (strrchr(__FILE__, '\\') ? strrchr(__FILE__, '\\') + 1 : __FILE__) +#define __FILENAME__ (strrchr(__FILE__, '/') ? strrchr(__FILE__, '/') + 1 : __FILENAME_X__) + +#define LOG(LOG_FUNC, FMT, ARGS...) LOG_EX(LOG_FUNC, "", "", FMT, ##ARGS) + +#define LOG_EX(LOG_FUNC, LOG_LEVEL, LINE_END, FMT, ARGS...) \ + do { \ + LOG_FUNC("[(%s)%18s][%23s]%30s@L%04d: " LOG_LEVEL "" FMT "" LINE_END, LOG_APP_TYPE, LOG_APP_NAME, __FILENAME__, __FUNCTION__, __LINE__, ##ARGS); \ + } while (0) + + #ifdef DEBUG -#define __FILENAME_X__ (strrchr(__FILE__, '\\') ? strrchr(__FILE__, '\\') + 1 : __FILE__) -#define __FILENAME__ (strrchr(__FILE__, '/') ? strrchr(__FILE__, '/') + 1 : __FILENAME_X__) - +#ifdef VERBOSE_DEBUG +#define DEBUG_FUNCTION_LINE_VERBOSE(FMT, ARGS...) LOG(WHBLogPrintf, FMT, ##ARGS) +#else #define DEBUG_FUNCTION_LINE_VERBOSE(FMT, ARGS...) while (0) +#endif -#define DEBUG_FUNCTION_LINE(FMT, ARGS...) \ - do { \ - WHBLogPrintf("[%23s]%30s@L%04d: " FMT "", __FILENAME__, __FUNCTION__, __LINE__, ##ARGS); \ - } while (0) +#define DEBUG_FUNCTION_LINE(FMT, ARGS...) LOG(WHBLogPrintf, FMT, ##ARGS) -#define DEBUG_FUNCTION_LINE_WRITE(FMT, ARGS...) \ - do { \ - WHBLogWritef("[%23s]%30s@L%04d: " FMT "", __FILENAME__, __FUNCTION__, __LINE__, ##ARGS); \ - } while (0) +#define DEBUG_FUNCTION_LINE_WRITE(FMT, ARGS...) LOG(WHBLogWritef, FMT, ##ARGS) + +#define DEBUG_FUNCTION_LINE_ERR(FMT, ARGS...) LOG_EX(WHBLogPrintf, "##ERROR## ", "", FMT, ##ARGS) #else @@ -32,6 +44,8 @@ extern "C" { #define DEBUG_FUNCTION_LINE_WRITE(FMT, ARGS...) while (0) +#define DEBUG_FUNCTION_LINE_ERR(FMT, ARGS...) LOG_EX(OSReport, "##ERROR## ", "\n", FMT, ##ARGS) + #endif void initLogging();