Reduce release log spam and harden release logging defaults

This commit is contained in:
Kelsi 2026-02-25 09:46:27 -08:00
parent 5966fedc59
commit c26353eda1
8 changed files with 137 additions and 52 deletions

View file

@ -59,6 +59,10 @@ jobs:
- name: Configure - name: Configure
run: cmake -S . -B build -DCMAKE_BUILD_TYPE=Release run: cmake -S . -B build -DCMAKE_BUILD_TYPE=Release
- name: Verify Release Config
run: |
cmake -LA -N build | grep -E '^CMAKE_BUILD_TYPE:STRING=Release$'
- name: Build - name: Build
run: cmake --build build --parallel $(nproc) run: cmake --build build --parallel $(nproc)
@ -123,6 +127,10 @@ jobs:
-DCMAKE_PREFIX_PATH="$BREW" \ -DCMAKE_PREFIX_PATH="$BREW" \
-DOPENSSL_ROOT_DIR="$(brew --prefix openssl@3)" -DOPENSSL_ROOT_DIR="$(brew --prefix openssl@3)"
- name: Verify Release Config
run: |
cmake -LA -N build | grep -E '^CMAKE_BUILD_TYPE:STRING=Release$'
- name: Build - name: Build
run: cmake --build build --parallel $(sysctl -n hw.logicalcpu) run: cmake --build build --parallel $(sysctl -n hw.logicalcpu)
@ -271,6 +279,11 @@ jobs:
shell: msys2 {0} shell: msys2 {0}
run: cmake -S . -B build -G Ninja -DCMAKE_BUILD_TYPE=Release run: cmake -S . -B build -G Ninja -DCMAKE_BUILD_TYPE=Release
- name: Verify Release Config
shell: msys2 {0}
run: |
cmake -LA -N build | grep -E '^CMAKE_BUILD_TYPE:STRING=Release$'
- name: Build - name: Build
shell: msys2 {0} shell: msys2 {0}
run: cmake --build build --parallel $(nproc) run: cmake --build build --parallel $(nproc)

View file

@ -6,6 +6,13 @@ set(CMAKE_CXX_STANDARD 20)
set(CMAKE_CXX_STANDARD_REQUIRED ON) set(CMAKE_CXX_STANDARD_REQUIRED ON)
set(CMAKE_EXPORT_COMPILE_COMMANDS ON) set(CMAKE_EXPORT_COMPILE_COMMANDS ON)
# Explicitly tag optimized configs so runtime defaults can enforce low-noise logging.
add_compile_definitions(
$<$<CONFIG:Release>:WOWEE_RELEASE_LOGGING>
$<$<CONFIG:RelWithDebInfo>:WOWEE_RELEASE_LOGGING>
$<$<CONFIG:MinSizeRel>:WOWEE_RELEASE_LOGGING>
)
# Output directories # Output directories
set(CMAKE_RUNTIME_OUTPUT_DIRECTORY ${CMAKE_BINARY_DIR}/bin) set(CMAKE_RUNTIME_OUTPUT_DIRECTORY ${CMAKE_BINARY_DIR}/bin)
set(CMAKE_LIBRARY_OUTPUT_DIRECTORY ${CMAKE_BINARY_DIR}/lib) set(CMAKE_LIBRARY_OUTPUT_DIRECTORY ${CMAKE_BINARY_DIR}/lib)

View file

@ -65,6 +65,13 @@ public:
} }
private: private:
static constexpr int kDefaultMinLevelValue =
#if defined(NDEBUG) || defined(WOWEE_RELEASE_LOGGING)
static_cast<int>(LogLevel::WARNING);
#else
static_cast<int>(LogLevel::INFO);
#endif
Logger() = default; Logger() = default;
~Logger() = default; ~Logger() = default;
Logger(const Logger&) = delete; Logger(const Logger&) = delete;
@ -77,13 +84,21 @@ private:
return oss.str(); return oss.str();
} }
std::atomic<int> minLevel_{static_cast<int>(LogLevel::INFO)}; std::atomic<int> minLevel_{kDefaultMinLevelValue};
std::mutex mutex; std::mutex mutex;
std::ofstream fileStream; std::ofstream fileStream;
bool fileReady = false; bool fileReady = false;
bool echoToStdout_ = true; bool echoToStdout_ = true;
std::chrono::steady_clock::time_point lastFlushTime_{}; std::chrono::steady_clock::time_point lastFlushTime_{};
uint32_t flushIntervalMs_ = 250; uint32_t flushIntervalMs_ = 250;
bool dedupeEnabled_ = true;
uint32_t dedupeWindowMs_ = 250;
LogLevel lastLevel_ = LogLevel::DEBUG;
std::string lastMessage_;
std::chrono::steady_clock::time_point lastMessageTime_{};
uint64_t suppressedCount_ = 0;
void emitLineLocked(LogLevel level, const std::string& message);
void flushSuppressedLocked();
void ensureFile(); void ensureFile();
}; };

View file

@ -120,6 +120,7 @@ private:
bool musicInitAttempted = false; bool musicInitAttempted = false;
bool musicPlaying = false; bool musicPlaying = false;
bool missingIntroTracksLogged_ = false;
bool loginMusicVolumeAdjusted_ = false; bool loginMusicVolumeAdjusted_ = false;
int savedMusicVolume_ = 30; int savedMusicVolume_ = 30;
}; };

View file

@ -122,12 +122,9 @@ network::Packet LogonChallengePacket::build(const std::string& account, const Cl
packet.writeUInt8(localIp[1]); packet.writeUInt8(localIp[1]);
packet.writeUInt8(localIp[2]); packet.writeUInt8(localIp[2]);
packet.writeUInt8(localIp[3]); packet.writeUInt8(localIp[3]);
LOG_DEBUG("LOGON_CHALLENGE client IP=", static_cast<int>(localIp[0]), ".",
static_cast<int>(localIp[1]), ".", static_cast<int>(localIp[2]), ".",
static_cast<int>(localIp[3]));
} else { } else {
packet.writeUInt32(0); packet.writeUInt32(0);
LOG_WARNING("LOGON_CHALLENGE client IP detection failed; falling back to 0.0.0.0"); LOG_DEBUG("LOGON_CHALLENGE client IP detection failed; using 0.0.0.0 fallback");
} }
} }

View file

@ -4,6 +4,8 @@
#include <ctime> #include <ctime>
#include <filesystem> #include <filesystem>
#include <cstdlib> #include <cstdlib>
#include <algorithm>
#include <cctype>
namespace wowee { namespace wowee {
namespace core { namespace core {
@ -28,20 +30,35 @@ void Logger::ensureFile() {
flushIntervalMs_ = static_cast<uint32_t>(parsed); flushIntervalMs_ = static_cast<uint32_t>(parsed);
} }
} }
if (const char* dedupe = std::getenv("WOWEE_LOG_DEDUPE")) {
dedupeEnabled_ = !(dedupe[0] == '0' || dedupe[0] == 'f' || dedupe[0] == 'F' ||
dedupe[0] == 'n' || dedupe[0] == 'N');
}
if (const char* dedupeMs = std::getenv("WOWEE_LOG_DEDUPE_MS")) {
char* end = nullptr;
unsigned long parsed = std::strtoul(dedupeMs, &end, 10);
if (end != dedupeMs && parsed <= 60000ul) {
dedupeWindowMs_ = static_cast<uint32_t>(parsed);
}
}
if (const char* level = std::getenv("WOWEE_LOG_LEVEL")) {
std::string v(level);
std::transform(v.begin(), v.end(), v.begin(), [](unsigned char c) {
return static_cast<char>(std::tolower(c));
});
if (v == "debug") setLogLevel(LogLevel::DEBUG);
else if (v == "info") setLogLevel(LogLevel::INFO);
else if (v == "warn" || v == "warning") setLogLevel(LogLevel::WARNING);
else if (v == "error") setLogLevel(LogLevel::ERROR);
else if (v == "fatal") setLogLevel(LogLevel::FATAL);
}
std::error_code ec; std::error_code ec;
std::filesystem::create_directories("logs", ec); std::filesystem::create_directories("logs", ec);
fileStream.open("logs/wowee.log", std::ios::out | std::ios::trunc); fileStream.open("logs/wowee.log", std::ios::out | std::ios::trunc);
lastFlushTime_ = std::chrono::steady_clock::now(); lastFlushTime_ = std::chrono::steady_clock::now();
} }
void Logger::log(LogLevel level, const std::string& message) { void Logger::emitLineLocked(LogLevel level, const std::string& message) {
if (!shouldLog(level)) {
return;
}
std::lock_guard<std::mutex> lock(mutex);
ensureFile();
// Get current time // Get current time
auto now = std::chrono::system_clock::now(); auto now = std::chrono::system_clock::now();
auto time = std::chrono::system_clock::to_time_t(now); auto time = std::chrono::system_clock::to_time_t(now);
@ -92,6 +109,38 @@ void Logger::log(LogLevel level, const std::string& message) {
} }
} }
void Logger::flushSuppressedLocked() {
if (suppressedCount_ == 0) return;
emitLineLocked(lastLevel_, "Previous message repeated " + std::to_string(suppressedCount_) + " times");
suppressedCount_ = 0;
}
void Logger::log(LogLevel level, const std::string& message) {
if (!shouldLog(level)) {
return;
}
std::lock_guard<std::mutex> lock(mutex);
ensureFile();
auto nowSteady = std::chrono::steady_clock::now();
if (dedupeEnabled_ && !lastMessage_.empty() &&
level == lastLevel_ && message == lastMessage_) {
auto elapsedMs = std::chrono::duration_cast<std::chrono::milliseconds>(nowSteady - lastMessageTime_).count();
if (elapsedMs >= 0 && elapsedMs <= static_cast<long long>(dedupeWindowMs_)) {
++suppressedCount_;
lastMessageTime_ = nowSteady;
return;
}
}
flushSuppressedLocked();
emitLineLocked(level, message);
lastLevel_ = level;
lastMessage_ = message;
lastMessageTime_ = nowSteady;
}
void Logger::setLogLevel(LogLevel level) { void Logger::setLogLevel(LogLevel level) {
minLevel_.store(static_cast<int>(level), std::memory_order_relaxed); minLevel_.store(static_cast<int>(level), std::memory_order_relaxed);
} }

View file

@ -1235,7 +1235,7 @@ void GameHandler::handlePacket(network::Packet& packet) {
++wardenPacketsAfterGate_; ++wardenPacketsAfterGate_;
} }
if (preLogicalOp && isAuthCharPipelineOpcode(*preLogicalOp)) { if (preLogicalOp && isAuthCharPipelineOpcode(*preLogicalOp)) {
LOG_INFO("AUTH/CHAR RX opcode=0x", std::hex, opcode, std::dec, LOG_DEBUG("AUTH/CHAR RX opcode=0x", std::hex, opcode, std::dec,
" state=", worldStateName(state), " state=", worldStateName(state),
" size=", packet.getSize()); " size=", packet.getSize());
} }
@ -3462,7 +3462,7 @@ bool GameHandler::loadWardenCRFile(const std::string& moduleHashHex) {
for (int i = 0; i < 9; i++) { for (int i = 0; i < 9; i++) {
char s[16]; snprintf(s, sizeof(s), "%s=0x%02X ", names[i], wardenCheckOpcodes_[i]); opcHex += s; char s[16]; snprintf(s, sizeof(s), "%s=0x%02X ", names[i], wardenCheckOpcodes_[i]); opcHex += s;
} }
LOG_INFO("Warden: Check opcodes: ", opcHex); LOG_DEBUG("Warden: Check opcodes: ", opcHex);
} }
size_t entryCount = (static_cast<size_t>(fileSize) - CR_HEADER_SIZE) / CR_ENTRY_SIZE; size_t entryCount = (static_cast<size_t>(fileSize) - CR_HEADER_SIZE) / CR_ENTRY_SIZE;
@ -3522,7 +3522,7 @@ void GameHandler::handleWardenData(network::Packet& packet) {
} }
if (decrypted.size() > 64) if (decrypted.size() > 64)
hex += "... (" + std::to_string(decrypted.size() - 64) + " more)"; hex += "... (" + std::to_string(decrypted.size() - 64) + " more)";
LOG_INFO("Warden: Decrypted (", decrypted.size(), " bytes): ", hex); LOG_DEBUG("Warden: Decrypted (", decrypted.size(), " bytes): ", hex);
} }
if (decrypted.empty()) { if (decrypted.empty()) {
@ -3541,7 +3541,7 @@ void GameHandler::handleWardenData(network::Packet& packet) {
} }
if (socket && socket->isConnected()) { if (socket && socket->isConnected()) {
socket->send(response); socket->send(response);
LOG_INFO("Warden: Sent response (", plaintext.size(), " bytes plaintext)"); LOG_DEBUG("Warden: Sent response (", plaintext.size(), " bytes plaintext)");
} }
}; };
@ -3564,7 +3564,7 @@ void GameHandler::handleWardenData(network::Packet& packet) {
{ {
std::string hashHex; std::string hashHex;
for (auto b : wardenModuleHash_) { char s[4]; snprintf(s, 4, "%02x", b); hashHex += s; } for (auto b : wardenModuleHash_) { char s[4]; snprintf(s, 4, "%02x", b); hashHex += s; }
LOG_INFO("Warden: MODULE_USE hash=", hashHex, " size=", wardenModuleSize_); LOG_DEBUG("Warden: MODULE_USE hash=", hashHex, " size=", wardenModuleSize_);
// Try to load pre-computed challenge/response entries // Try to load pre-computed challenge/response entries
loadWardenCRFile(hashHex); loadWardenCRFile(hashHex);
@ -3574,7 +3574,7 @@ void GameHandler::handleWardenData(network::Packet& packet) {
std::vector<uint8_t> resp = { 0x00 }; // WARDEN_CMSG_MODULE_MISSING std::vector<uint8_t> resp = { 0x00 }; // WARDEN_CMSG_MODULE_MISSING
sendWardenResponse(resp); sendWardenResponse(resp);
wardenState_ = WardenState::WAIT_MODULE_CACHE; wardenState_ = WardenState::WAIT_MODULE_CACHE;
LOG_INFO("Warden: Sent MODULE_MISSING, waiting for module data chunks"); LOG_DEBUG("Warden: Sent MODULE_MISSING, waiting for module data chunks");
break; break;
} }
@ -3598,7 +3598,7 @@ void GameHandler::handleWardenData(network::Packet& packet) {
decrypted.begin() + 3, decrypted.begin() + 3,
decrypted.begin() + 3 + chunkSize); decrypted.begin() + 3 + chunkSize);
LOG_INFO("Warden: MODULE_CACHE chunk ", chunkSize, " bytes, total ", LOG_DEBUG("Warden: MODULE_CACHE chunk ", chunkSize, " bytes, total ",
wardenModuleData_.size(), "/", wardenModuleSize_); wardenModuleData_.size(), "/", wardenModuleSize_);
// Check if module download is complete // Check if module download is complete
@ -3627,7 +3627,7 @@ void GameHandler::handleWardenData(network::Packet& packet) {
std::ofstream wf(cachePath, std::ios::binary); std::ofstream wf(cachePath, std::ios::binary);
if (wf) { if (wf) {
wf.write(reinterpret_cast<const char*>(wardenModuleData_.data()), wardenModuleData_.size()); wf.write(reinterpret_cast<const char*>(wardenModuleData_.data()), wardenModuleData_.size());
LOG_INFO("Warden: Cached module to ", cachePath); LOG_DEBUG("Warden: Cached module to ", cachePath);
} }
} }
@ -3644,7 +3644,7 @@ void GameHandler::handleWardenData(network::Packet& packet) {
// Send MODULE_OK (opcode 0x01) // Send MODULE_OK (opcode 0x01)
std::vector<uint8_t> resp = { 0x01 }; // WARDEN_CMSG_MODULE_OK std::vector<uint8_t> resp = { 0x01 }; // WARDEN_CMSG_MODULE_OK
sendWardenResponse(resp); sendWardenResponse(resp);
LOG_INFO("Warden: Sent MODULE_OK"); LOG_DEBUG("Warden: Sent MODULE_OK");
} }
// No response for intermediate chunks // No response for intermediate chunks
break; break;
@ -3670,7 +3670,7 @@ void GameHandler::handleWardenData(network::Packet& packet) {
} }
if (match) { if (match) {
LOG_INFO("Warden: Found matching CR entry for seed"); LOG_DEBUG("Warden: Found matching CR entry for seed");
// Log the reply we're sending // Log the reply we're sending
{ {
@ -3678,7 +3678,7 @@ void GameHandler::handleWardenData(network::Packet& packet) {
for (int i = 0; i < 20; i++) { for (int i = 0; i < 20; i++) {
char s[4]; snprintf(s, 4, "%02x", match->reply[i]); replyHex += s; char s[4]; snprintf(s, 4, "%02x", match->reply[i]); replyHex += s;
} }
LOG_INFO("Warden: Sending pre-computed reply=", replyHex); LOG_DEBUG("Warden: Sending pre-computed reply=", replyHex);
} }
// Send HASH_RESULT (opcode 0x04 + 20-byte reply) // Send HASH_RESULT (opcode 0x04 + 20-byte reply)
@ -3693,7 +3693,7 @@ void GameHandler::handleWardenData(network::Packet& packet) {
std::vector<uint8_t> newDecryptKey(match->serverKey, match->serverKey + 16); std::vector<uint8_t> newDecryptKey(match->serverKey, match->serverKey + 16);
wardenCrypto_->replaceKeys(newEncryptKey, newDecryptKey); wardenCrypto_->replaceKeys(newEncryptKey, newDecryptKey);
LOG_INFO("Warden: Switched to CR key set"); LOG_DEBUG("Warden: Switched to CR key set");
wardenState_ = WardenState::WAIT_CHECKS; wardenState_ = WardenState::WAIT_CHECKS;
break; break;
@ -3721,7 +3721,7 @@ void GameHandler::handleWardenData(network::Packet& packet) {
const auto& firstCR = wardenCREntries_[0]; const auto& firstCR = wardenCREntries_[0];
std::string expectedHex; std::string expectedHex;
for (int i = 0; i < 20; i++) { char s[4]; snprintf(s, 4, "%02x", firstCR.reply[i]); expectedHex += s; } for (int i = 0; i < 20; i++) { char s[4]; snprintf(s, 4, "%02x", firstCR.reply[i]); expectedHex += s; }
LOG_INFO("Warden: Empirical test — expected reply from CR[0]=", expectedHex); LOG_DEBUG("Warden: Empirical test — expected reply from CR[0]=", expectedHex);
// Test 1: SHA1(moduleImage) // Test 1: SHA1(moduleImage)
{ {
@ -3729,7 +3729,7 @@ void GameHandler::handleWardenData(network::Packet& packet) {
auto h = auth::Crypto::sha1(data); auto h = auth::Crypto::sha1(data);
bool match = (std::memcmp(h.data(), firstCR.reply, 20) == 0); bool match = (std::memcmp(h.data(), firstCR.reply, 20) == 0);
std::string hex; for (auto b : h) { char s[4]; snprintf(s, 4, "%02x", b); hex += s; } std::string hex; for (auto b : h) { char s[4]; snprintf(s, 4, "%02x", b); hex += s; }
LOG_INFO("Warden: SHA1(moduleImage)=", hex, match ? " MATCH!" : ""); LOG_DEBUG("Warden: SHA1(moduleImage)=", hex, match ? " MATCH!" : "");
} }
// Test 2: SHA1(seed || moduleImage) // Test 2: SHA1(seed || moduleImage)
{ {
@ -3739,7 +3739,7 @@ void GameHandler::handleWardenData(network::Packet& packet) {
auto h = auth::Crypto::sha1(data); auto h = auth::Crypto::sha1(data);
bool match = (std::memcmp(h.data(), firstCR.reply, 20) == 0); bool match = (std::memcmp(h.data(), firstCR.reply, 20) == 0);
std::string hex; for (auto b : h) { char s[4]; snprintf(s, 4, "%02x", b); hex += s; } std::string hex; for (auto b : h) { char s[4]; snprintf(s, 4, "%02x", b); hex += s; }
LOG_INFO("Warden: SHA1(seed||image)=", hex, match ? " MATCH!" : ""); LOG_DEBUG("Warden: SHA1(seed||image)=", hex, match ? " MATCH!" : "");
} }
// Test 3: SHA1(moduleImage || seed) // Test 3: SHA1(moduleImage || seed)
{ {
@ -3748,21 +3748,21 @@ void GameHandler::handleWardenData(network::Packet& packet) {
auto h = auth::Crypto::sha1(data); auto h = auth::Crypto::sha1(data);
bool match = (std::memcmp(h.data(), firstCR.reply, 20) == 0); bool match = (std::memcmp(h.data(), firstCR.reply, 20) == 0);
std::string hex; for (auto b : h) { char s[4]; snprintf(s, 4, "%02x", b); hex += s; } std::string hex; for (auto b : h) { char s[4]; snprintf(s, 4, "%02x", b); hex += s; }
LOG_INFO("Warden: SHA1(image||seed)=", hex, match ? " MATCH!" : ""); LOG_DEBUG("Warden: SHA1(image||seed)=", hex, match ? " MATCH!" : "");
} }
// Test 4: SHA1(decompressedData) // Test 4: SHA1(decompressedData)
{ {
auto h = auth::Crypto::sha1(decompressedData); auto h = auth::Crypto::sha1(decompressedData);
bool match = (std::memcmp(h.data(), firstCR.reply, 20) == 0); bool match = (std::memcmp(h.data(), firstCR.reply, 20) == 0);
std::string hex; for (auto b : h) { char s[4]; snprintf(s, 4, "%02x", b); hex += s; } std::string hex; for (auto b : h) { char s[4]; snprintf(s, 4, "%02x", b); hex += s; }
LOG_INFO("Warden: SHA1(decompressed)=", hex, match ? " MATCH!" : ""); LOG_DEBUG("Warden: SHA1(decompressed)=", hex, match ? " MATCH!" : "");
} }
// Test 5: SHA1(rawModuleData) // Test 5: SHA1(rawModuleData)
{ {
auto h = auth::Crypto::sha1(wardenModuleData_); auto h = auth::Crypto::sha1(wardenModuleData_);
bool match = (std::memcmp(h.data(), firstCR.reply, 20) == 0); bool match = (std::memcmp(h.data(), firstCR.reply, 20) == 0);
std::string hex; for (auto b : h) { char s[4]; snprintf(s, 4, "%02x", b); hex += s; } std::string hex; for (auto b : h) { char s[4]; snprintf(s, 4, "%02x", b); hex += s; }
LOG_INFO("Warden: SHA1(rawModule)=", hex, match ? " MATCH!" : ""); LOG_DEBUG("Warden: SHA1(rawModule)=", hex, match ? " MATCH!" : "");
} }
// Test 6: Check if all CR replies are the same (constant hash) // Test 6: Check if all CR replies are the same (constant hash)
{ {
@ -3773,7 +3773,7 @@ void GameHandler::handleWardenData(network::Packet& packet) {
break; break;
} }
} }
LOG_INFO("Warden: All ", wardenCREntries_.size(), " CR replies identical? ", allSame ? "YES" : "NO"); LOG_DEBUG("Warden: All ", wardenCREntries_.size(), " CR replies identical? ", allSame ? "YES" : "NO");
} }
} }
@ -3786,7 +3786,7 @@ void GameHandler::handleWardenData(network::Packet& packet) {
{ {
std::string hex; std::string hex;
for (auto b : reply) { char s[4]; snprintf(s, 4, "%02x", b); hex += s; } for (auto b : reply) { char s[4]; snprintf(s, 4, "%02x", b); hex += s; }
LOG_INFO("Warden: Sending SHA1(moduleImage)=", hex); LOG_DEBUG("Warden: Sending SHA1(moduleImage)=", hex);
} }
// Send HASH_RESULT (opcode 0x04 + 20-byte hash) // Send HASH_RESULT (opcode 0x04 + 20-byte hash)
@ -3807,7 +3807,7 @@ void GameHandler::handleWardenData(network::Packet& packet) {
wardenCrypto_->replaceKeys(ek, dk); wardenCrypto_->replaceKeys(ek, dk);
for (auto& b : newEncryptKey) b = 0; for (auto& b : newEncryptKey) b = 0;
for (auto& b : newDecryptKey) b = 0; for (auto& b : newDecryptKey) b = 0;
LOG_INFO("Warden: Derived and applied key update from seed"); LOG_DEBUG("Warden: Derived and applied key update from seed");
} }
wardenState_ = WardenState::WAIT_CHECKS; wardenState_ = WardenState::WAIT_CHECKS;
@ -3815,7 +3815,7 @@ void GameHandler::handleWardenData(network::Packet& packet) {
} }
case 0x02: { // WARDEN_SMSG_CHEAT_CHECKS_REQUEST case 0x02: { // WARDEN_SMSG_CHEAT_CHECKS_REQUEST
LOG_INFO("Warden: CHEAT_CHECKS_REQUEST (", decrypted.size(), " bytes)"); LOG_DEBUG("Warden: CHEAT_CHECKS_REQUEST (", decrypted.size(), " bytes)");
if (decrypted.size() < 3) { if (decrypted.size() < 3) {
LOG_ERROR("Warden: CHEAT_CHECKS_REQUEST too short"); LOG_ERROR("Warden: CHEAT_CHECKS_REQUEST too short");
@ -3833,14 +3833,14 @@ void GameHandler::handleWardenData(network::Packet& packet) {
strings.emplace_back(reinterpret_cast<const char*>(decrypted.data() + pos), slen); strings.emplace_back(reinterpret_cast<const char*>(decrypted.data() + pos), slen);
pos += slen; pos += slen;
} }
LOG_INFO("Warden: String table: ", strings.size(), " entries"); LOG_DEBUG("Warden: String table: ", strings.size(), " entries");
for (size_t i = 0; i < strings.size(); i++) { for (size_t i = 0; i < strings.size(); i++) {
LOG_INFO("Warden: [", i, "] = \"", strings[i], "\""); LOG_DEBUG("Warden: [", i, "] = \"", strings[i], "\"");
} }
// XOR byte is the last byte of the packet // XOR byte is the last byte of the packet
uint8_t xorByte = decrypted.back(); uint8_t xorByte = decrypted.back();
LOG_INFO("Warden: XOR byte = 0x", [&]{ char s[4]; snprintf(s,4,"%02x",xorByte); return std::string(s); }()); LOG_DEBUG("Warden: XOR byte = 0x", [&]{ char s[4]; snprintf(s,4,"%02x",xorByte); return std::string(s); }());
// Check type enum indices // Check type enum indices
enum CheckType { CT_MEM=0, CT_PAGE_A=1, CT_PAGE_B=2, CT_MPQ=3, CT_LUA=4, enum CheckType { CT_MEM=0, CT_PAGE_A=1, CT_PAGE_B=2, CT_MPQ=3, CT_LUA=4,
@ -3958,7 +3958,7 @@ void GameHandler::handleWardenData(network::Packet& packet) {
pos++; pos++;
checkCount++; checkCount++;
LOG_INFO("Warden: Check #", checkCount, " type=", checkTypeNames[ct], LOG_DEBUG("Warden: Check #", checkCount, " type=", checkTypeNames[ct],
" at offset ", pos - 1); " at offset ", pos - 1);
switch (ct) { switch (ct) {
@ -3984,10 +3984,10 @@ void GameHandler::handleWardenData(network::Packet& packet) {
| (uint32_t(decrypted[pos+2])<<16) | (uint32_t(decrypted[pos+3])<<24); | (uint32_t(decrypted[pos+2])<<16) | (uint32_t(decrypted[pos+3])<<24);
pos += 4; pos += 4;
uint8_t readLen = decrypted[pos++]; uint8_t readLen = decrypted[pos++];
LOG_INFO("Warden: MEM offset=0x", [&]{char s[12];snprintf(s,12,"%08x",offset);return std::string(s);}(), LOG_DEBUG("Warden: MEM offset=0x", [&]{char s[12];snprintf(s,12,"%08x",offset);return std::string(s);}(),
" len=", (int)readLen); " len=", (int)readLen);
if (!moduleName.empty()) { if (!moduleName.empty()) {
LOG_INFO("Warden: MEM module=\"", moduleName, "\""); LOG_DEBUG("Warden: MEM module=\"", moduleName, "\"");
} }
// Lazy-load WoW.exe PE image on first MEM_CHECK // Lazy-load WoW.exe PE image on first MEM_CHECK
@ -4001,7 +4001,7 @@ void GameHandler::handleWardenData(network::Packet& packet) {
// Read bytes from PE image (includes patched runtime globals) // Read bytes from PE image (includes patched runtime globals)
std::vector<uint8_t> memBuf(readLen, 0); std::vector<uint8_t> memBuf(readLen, 0);
if (wardenMemory_->isLoaded() && wardenMemory_->readMemory(offset, readLen, memBuf.data())) { if (wardenMemory_->isLoaded() && wardenMemory_->readMemory(offset, readLen, memBuf.data())) {
LOG_INFO("Warden: MEM_CHECK served from PE image"); LOG_DEBUG("Warden: MEM_CHECK served from PE image");
} else { } else {
LOG_WARNING("Warden: MEM_CHECK fallback to zeros for 0x", LOG_WARNING("Warden: MEM_CHECK fallback to zeros for 0x",
[&]{char s[12];snprintf(s,12,"%08x",offset);return std::string(s);}()); [&]{char s[12];snprintf(s,12,"%08x",offset);return std::string(s);}());
@ -4054,7 +4054,7 @@ void GameHandler::handleWardenData(network::Packet& packet) {
pageResult = 0x4A; // PatternFound pageResult = 0x4A; // PatternFound
} }
} }
LOG_INFO("Warden: PAGE_A request bytes=", consume, LOG_DEBUG("Warden: PAGE_A request bytes=", consume,
" result=0x", [&]{char s[4];snprintf(s,4,"%02x",pageResult);return std::string(s);}()); " result=0x", [&]{char s[4];snprintf(s,4,"%02x",pageResult);return std::string(s);}());
pos += consume; pos += consume;
resultData.push_back(pageResult); resultData.push_back(pageResult);
@ -4093,7 +4093,7 @@ void GameHandler::handleWardenData(network::Packet& packet) {
pageResult = 0x4A; // PatternFound pageResult = 0x4A; // PatternFound
} }
} }
LOG_INFO("Warden: PAGE_B request bytes=", consume, LOG_DEBUG("Warden: PAGE_B request bytes=", consume,
" result=0x", [&]{char s[4];snprintf(s,4,"%02x",pageResult);return std::string(s);}()); " result=0x", [&]{char s[4];snprintf(s,4,"%02x",pageResult);return std::string(s);}());
pos += consume; pos += consume;
resultData.push_back(pageResult); resultData.push_back(pageResult);
@ -4104,7 +4104,7 @@ void GameHandler::handleWardenData(network::Packet& packet) {
if (pos + 1 > checkEnd) { pos = checkEnd; break; } if (pos + 1 > checkEnd) { pos = checkEnd; break; }
uint8_t strIdx = decrypted[pos++]; uint8_t strIdx = decrypted[pos++];
std::string filePath = resolveWardenString(strIdx); std::string filePath = resolveWardenString(strIdx);
LOG_INFO("Warden: MPQ file=\"", (filePath.empty() ? "?" : filePath), "\""); LOG_DEBUG("Warden: MPQ file=\"", (filePath.empty() ? "?" : filePath), "\"");
bool found = false; bool found = false;
std::vector<uint8_t> hash(20, 0); std::vector<uint8_t> hash(20, 0);
@ -4150,7 +4150,7 @@ void GameHandler::handleWardenData(network::Packet& packet) {
if (pos + 1 > checkEnd) { pos = checkEnd; break; } if (pos + 1 > checkEnd) { pos = checkEnd; break; }
uint8_t strIdx = decrypted[pos++]; uint8_t strIdx = decrypted[pos++];
std::string luaVar = resolveWardenString(strIdx); std::string luaVar = resolveWardenString(strIdx);
LOG_INFO("Warden: LUA str=\"", (luaVar.empty() ? "?" : luaVar), "\""); LOG_DEBUG("Warden: LUA str=\"", (luaVar.empty() ? "?" : luaVar), "\"");
// Response: [uint8 result=0][uint16 len=0] // Response: [uint8 result=0][uint16 len=0]
// Lua string doesn't exist // Lua string doesn't exist
resultData.push_back(0x01); // not found resultData.push_back(0x01); // not found
@ -4162,7 +4162,7 @@ void GameHandler::handleWardenData(network::Packet& packet) {
pos += 24; // skip seed + sha1 pos += 24; // skip seed + sha1
uint8_t strIdx = decrypted[pos++]; uint8_t strIdx = decrypted[pos++];
std::string driverName = resolveWardenString(strIdx); std::string driverName = resolveWardenString(strIdx);
LOG_INFO("Warden: DRIVER=\"", (driverName.empty() ? "?" : driverName), "\""); LOG_DEBUG("Warden: DRIVER=\"", (driverName.empty() ? "?" : driverName), "\"");
// Response: [uint8 result=1] (driver NOT found = clean) // Response: [uint8 result=1] (driver NOT found = clean)
resultData.push_back(0x01); resultData.push_back(0x01);
break; break;
@ -4219,7 +4219,7 @@ void GameHandler::handleWardenData(network::Packet& packet) {
} }
} }
LOG_INFO("Warden: Parsed ", checkCount, " checks, result data size=", resultData.size()); LOG_DEBUG("Warden: Parsed ", checkCount, " checks, result data size=", resultData.size());
// --- Compute checksum: XOR of 5 uint32s from SHA1(resultData) --- // --- Compute checksum: XOR of 5 uint32s from SHA1(resultData) ---
auto resultHash = auth::Crypto::sha1(resultData); auto resultHash = auth::Crypto::sha1(resultData);
@ -4244,18 +4244,18 @@ void GameHandler::handleWardenData(network::Packet& packet) {
resp.push_back((checksum >> 24) & 0xFF); resp.push_back((checksum >> 24) & 0xFF);
resp.insert(resp.end(), resultData.begin(), resultData.end()); resp.insert(resp.end(), resultData.begin(), resultData.end());
sendWardenResponse(resp); sendWardenResponse(resp);
LOG_INFO("Warden: Sent CHEAT_CHECKS_RESULT (", resp.size(), " bytes, ", LOG_DEBUG("Warden: Sent CHEAT_CHECKS_RESULT (", resp.size(), " bytes, ",
checkCount, " checks, checksum=0x", checkCount, " checks, checksum=0x",
[&]{char s[12];snprintf(s,12,"%08x",checksum);return std::string(s);}(), ")"); [&]{char s[12];snprintf(s,12,"%08x",checksum);return std::string(s);}(), ")");
break; break;
} }
case 0x03: // WARDEN_SMSG_MODULE_INITIALIZE case 0x03: // WARDEN_SMSG_MODULE_INITIALIZE
LOG_INFO("Warden: MODULE_INITIALIZE (", decrypted.size(), " bytes, no response needed)"); LOG_DEBUG("Warden: MODULE_INITIALIZE (", decrypted.size(), " bytes, no response needed)");
break; break;
default: default:
LOG_INFO("Warden: Unknown opcode 0x", std::hex, (int)wardenOpcode, std::dec, LOG_DEBUG("Warden: Unknown opcode 0x", std::hex, (int)wardenOpcode, std::dec,
" (state=", (int)wardenState_, ", size=", decrypted.size(), ")"); " (state=", (int)wardenState_, ", size=", decrypted.size(), ")");
break; break;
} }

View file

@ -263,7 +263,10 @@ void AuthScreen::render(auth::AuthHandler& authHandler) {
LOG_INFO("AuthScreen: Playing login intro track: ", path); LOG_INFO("AuthScreen: Playing login intro track: ", path);
musicPlaying = music->isPlaying(); musicPlaying = music->isPlaying();
} else { } else {
LOG_WARNING("AuthScreen: No login intro tracks found in assets/"); if (!missingIntroTracksLogged_) {
LOG_WARNING("AuthScreen: No login intro tracks found in assets/");
missingIntroTracksLogged_ = true;
}
} }
} }
} }