Skip to content

Commit efabe9b

Browse files
MadMaxMangosclaude
MadMaxMangos
and
claude
authored
Logging: fix live-console tearing (single-owner stdout) + suppressible filters for runtime debug spam (#403)
* fix(logging): route progress bars through the console writer (no more torn console) PR #402 moved console log emit onto a dedicated writer thread, but BarGoLink still printf()+fflush()ed its progress bars straight to stdout on the loading/world thread. Two unsynchronized writers on one stdout made the "=== N%" bars and the writer thread's log lines interleave character-by- character -> the torn live console. The file log was unaffected (the bar never writes to the file and file writes are m_fileMtx-serialized). The race also recurs at runtime via .reload/.ahbot/playerbot commands that step bars on the world thread while the writer is live, so a writer-start-timing fix alone is insufficient. Make stdout single-owner: the bar now builds one full redraw string and hands it to the writer as a single atomic "raw" record (verbatim - no time prefix, no color, no appended newline), so bar redraws and log lines flow through one FIFO in program order, exactly as before the writer existed. - ProgressBarRender.h (new): pure, dependency-free byte builders, byte-identical to the legacy printf sequences (offline unit test, incl. an n>indic_len guard). - ProgressBar.{h,cpp}: init/step/dtor build one string and emit via a swappable sink; the default sink is a synchronous fwrite(stdout)+fflush, so offline tools and realmd stay byte-for-byte unchanged. - Log.{h,cpp}: ConsoleEmitRaw() enqueues a raw record when the writer runs, else writes verbatim synchronously. ConsoleLogRecord gains isRaw. - ConsoleLogWriter.cpp: Emit honours isRaw (verbatim, no '\n'); the queue-full drop notice gets a leading '\n' so it can no longer land mid-bar. - mangosd.cpp: install the async bar sink right after StartConsoleThread(). Colored output (including the ScriptDev banner) is untouched - only the bar, which was never colored, changed path. Built clean (RelWithDebInfo, mangosd + realmd, 0 errors) and confirmed torn-free in a live smoke test. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com> * feat(logging): suppressible filters for runtime debug spam + console-writer review fixes Two related logging improvements on top of the off-thread console writer. 1) LOG-FILTER SWEEP -- make a busy LogLevel/LogFileLevel=3 run usable. - New filters LogFilter_GridAdd (0x100000) and LogFilter_DbScripts (0x200000); LOG_FILTER_COUNT -> 22. ALL log filters now ship default-on (suppressed) so a fresh level-3 run is quiet out of the box; set any LogFilter_* = 0 to restore that category. ConfVersion bumped so stale configs get the out-of-date notice. - Gated the highest-volume bare DEBUG_LOG/DETAIL_LOG/outString runtime lines onto EXISTING filters (no new bits beyond the two above): SPELL_CAST : "Holder of spell .. in use" (Unit), "Spell Effect DUMMY" x2 COMBAT : SMSG_ATTACKSTART (now logs attacker -> victim via GetGuidStr) MAP_LOADING : grid load-content count, grid IDLE/REMOVAL + differed-unload transitions, both vmap GetHitPosition LoS corrections, AddPersistentState, and the startup "Active Flag" line DB_STRICTED_CHECK: the four "Unused (> MaxPlayerLevel) level" notices GRID_ADD : "X enters grid[x,y]" DB_SCRIPTS : db_scripts process traces Error variants (outError/outErrorDb) and one-time/info lines stay visible. - Fixed a latent config-key typo: logFilterData read "LogFilter_MapLoading" but every config ships "LogFilter_MapsLoading", so the key never bound and the filter only worked by code default. Code now reads "LogFilter_MapsLoading". - GridStates: corrected the mislabeled "moved to IDLE state" -> "REMOVAL state" (IdleState::Update actually transitions to GRID_STATE_REMOVAL). 2) CONSOLE-WRITER REVIEW FIXES (adversarial review of the bar-tearing change). - Single-owner stdout: the bar was made async, but the CLI prompt, CLI command output (utf8print), the beep, and the loglevel-change notices still wrote to stdout directly -- so they could overtake queued bar frames (e.g. the prompt reprinted after .reload landing before/over the bar). All now route through Log::ConsoleEmitRaw, so every non-log-line console write shares the one FIFO and drains in program order. (Log::outTime's printf is dead -- no callers.) - ProgressBarRender.h: include <cstddef> and use std::size_t (do not rely on <string> to expose ::size_t globally -- non-portable on GCC/Clang). Built clean (RelWithDebInfo, mangosd + realmd, 0 errors); filters and the .reload prompt-ordering fix confirmed in live level-3 smoke tests. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com> --------- Co-authored-by: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
1 parent c718ef1 commit efabe9b

20 files changed

Lines changed: 326 additions & 101 deletions

‎cmake/MangosParams.cmake‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,5 @@
11
set(MANGOS_EXP "CLASSIC")
22
set(MANGOS_PKG "Mangos Zero")
3-
set(MANGOS_WORLD_VER 2026062801)
3+
set(MANGOS_WORLD_VER 2026062802)
44
set(MANGOS_REALM_VER 2026060300)
55
set(MANGOS_AHBOT_VER 2021010100)

‎src/game/Object/ObjectMgr.cpp‎

Lines changed: 5 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -1623,7 +1623,7 @@ void ObjectMgr::LoadCreatures()
16231623
| GetLivingWorldDefenderCategory(cInfo, mapEntry, lwIsWaypoint)) & lwAnchorMask;
16241624
if ((cInfo->ExtraFlags & CREATURE_FLAG_EXTRA_ACTIVE) || lwCats != 0)
16251625
{
1626-
sLog.outString("Adding `creature` with Active Flag: Map: %u, Guid %u", data.mapid, guid);
1626+
BASIC_FILTER_LOG(LOG_FILTER_MAP_LOADING, "Adding `creature` with Active Flag: Map: %u, Guid %u", data.mapid, guid);
16271627
m_activeCreatures.insert(ActiveCreatureGuidsOnMap::value_type(data.mapid, guid));
16281628

16291629
if (lwCats != 0)
@@ -2603,7 +2603,7 @@ void ObjectMgr::LoadPetLevelInfo()
26032603
}
26042604
else
26052605
{
2606-
DETAIL_LOG("Unused (> MaxPlayerLevel in mangosd.conf) level %u in `pet_levelstats` table, ignoring.", current_level);
2606+
DETAIL_FILTER_LOG(LOG_FILTER_DB_STRICTED_CHECK, "Unused (> MaxPlayerLevel in mangosd.conf) level %u in `pet_levelstats` table, ignoring.", current_level);
26072607
++count; // make result loading percent "expected" correct in case disabled detail mode for example.
26082608
}
26092609
continue;
@@ -3047,7 +3047,7 @@ void ObjectMgr::LoadPlayerInfo()
30473047
}
30483048
else
30493049
{
3050-
DETAIL_LOG("Unused (> MaxPlayerLevel in mangosd.conf) level %u in `player_classlevelstats` table, ignoring.", current_level);
3050+
DETAIL_FILTER_LOG(LOG_FILTER_DB_STRICTED_CHECK, "Unused (> MaxPlayerLevel in mangosd.conf) level %u in `player_classlevelstats` table, ignoring.", current_level);
30513051
++count; // make result loading percent "expected" correct in case disabled detail mode for example.
30523052
}
30533053
continue;
@@ -3156,7 +3156,7 @@ void ObjectMgr::LoadPlayerInfo()
31563156
}
31573157
else
31583158
{
3159-
DETAIL_LOG("Unused (> MaxPlayerLevel in mangosd.conf) level %u in `player_levelstats` table, ignoring.", current_level);
3159+
DETAIL_FILTER_LOG(LOG_FILTER_DB_STRICTED_CHECK, "Unused (> MaxPlayerLevel in mangosd.conf) level %u in `player_levelstats` table, ignoring.", current_level);
31603160
++count; // make result loading percent "expected" correct in case disabled detail mode for example.
31613161
}
31623162
continue;
@@ -3273,7 +3273,7 @@ void ObjectMgr::LoadPlayerInfo()
32733273
}
32743274
else
32753275
{
3276-
DETAIL_LOG("Unused (> MaxPlayerLevel in mangosd.conf) level %u in `player_xp_for_levels` table, ignoring.", current_level);
3276+
DETAIL_FILTER_LOG(LOG_FILTER_DB_STRICTED_CHECK, "Unused (> MaxPlayerLevel in mangosd.conf) level %u in `player_xp_for_levels` table, ignoring.", current_level);
32773277
++count; // make result loading percent "expected" correct in case disabled detail mode for example.
32783278
}
32793279
continue;

‎src/game/Object/Unit.cpp‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -3088,7 +3088,7 @@ void Unit::SendMeleeAttackStart(Unit* pVictim)
30883088
data << pVictim->GetObjectGuid();
30893089

30903090
SendMessageToSet(&data, true);
3091-
DEBUG_LOG("WORLD: Sent SMSG_ATTACKSTART");
3091+
DEBUG_FILTER_LOG(LOG_FILTER_COMBAT, "WORLD: Sent SMSG_ATTACKSTART: %s -> %s", GetGuidStr().c_str(), pVictim->GetGuidStr().c_str());
30923092
}
30933093

30943094
/**
@@ -4790,7 +4790,7 @@ bool Unit::AddSpellAuraHolder(SpellAuraHolder* holder)
47904790
}
47914791

47924792
holder->ApplyAuraModifiers(true, true); // This is the place where auras are actually applied onto the target
4793-
DEBUG_LOG("Holder of spell %u now is in use", holder->GetId());
4793+
DEBUG_FILTER_LOG(LOG_FILTER_SPELL_CAST, "Holder of spell %u now is in use", holder->GetId());
47944794

47954795
// if aura deleted before boosts apply ignore
47964796
// this can be possible it it removed indirectly by triggered spell effect at ApplyModifier

‎src/game/WorldHandlers/GridStates.cpp‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -155,7 +155,7 @@ IdleState::Update(Map& m, NGridType& grid, GridInfo&, const uint32& x, const uin
155155
{
156156
m.ResetGridExpiry(grid);
157157
grid.SetGridState(GRID_STATE_REMOVAL);
158-
DEBUG_LOG("Grid[%u,%u] on map %u moved to IDLE state", x, y, m.GetId());
158+
DEBUG_FILTER_LOG(LOG_FILTER_MAP_LOADING, "Grid[%u,%u] on map %u moved to REMOVAL state", x, y, m.GetId());
159159
}
160160

161161
/**
@@ -185,7 +185,7 @@ RemovalState::Update(Map& m, NGridType& grid, GridInfo& info, const uint32& x, c
185185
{
186186
if (!m.UnloadGrid(x, y, false))
187187
{
188-
DEBUG_LOG("Grid[%u,%u] for map %u differed unloading due to players or active objects nearby", x, y, m.GetId());
188+
DEBUG_FILTER_LOG(LOG_FILTER_MAP_LOADING, "Grid[%u,%u] for map %u differed unloading due to players or active objects nearby", x, y, m.GetId());
189189
m.ResetGridExpiry(grid);
190190
}
191191
}

‎src/game/WorldHandlers/Map.cpp‎

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -773,7 +773,7 @@ template<class T>
773773
AddToActive(obj);
774774
}
775775

776-
DEBUG_LOG("%s enters grid[%u,%u]", obj->GetGuidStr().c_str(), cell.GridX(), cell.GridY());
776+
DEBUG_FILTER_LOG(LOG_FILTER_GRID_ADD, "%s enters grid[%u,%u]", obj->GetGuidStr().c_str(), cell.GridX(), cell.GridY());
777777

778778
obj->GetViewPoint().Event_AddedToWorld(&(*grid)(cell.CellX(), cell.CellY()));
779779
obj->SetAsNewObject(true);
@@ -2946,7 +2946,7 @@ bool Map::ScriptsStart(DBScriptType type, uint32 id, Object* source, Object* tar
29462946
(execParams & SCRIPT_EXEC_PARAM_UNIQUE_BY_SOURCE) ? sourceGuid : ObjectGuid(),
29472947
(execParams & SCRIPT_EXEC_PARAM_UNIQUE_BY_TARGET) ? targetGuid : ObjectGuid(), ownerGuid))
29482948
{
2949-
DEBUG_LOG("DB-SCRIPTS: Process table `dbscripts [type=%d]` id %u. Skip script as script already started for source %s, target %s - ScriptsStartParams %u", type, id, sourceGuid.GetString().c_str(), targetGuid.GetString().c_str(), execParams);
2949+
DEBUG_FILTER_LOG(LOG_FILTER_DB_SCRIPTS, "DB-SCRIPTS: Process table `dbscripts [type=%d]` id %u. Skip script as script already started for source %s, target %s - ScriptsStartParams %u", type, id, sourceGuid.GetString().c_str(), targetGuid.GetString().c_str(), execParams);
29502950
return true;
29512951
}
29522952
}
@@ -3346,7 +3346,7 @@ bool Map::GetHitPosition(float srcX, float srcY, float srcZ, float& destX, float
33463346
bool result0 = VMAP::VMapFactory::createOrGetVMapManager()->getObjectHitPos(GetId(), srcX, srcY, srcZ, destX, destY, destZ, tempX, tempY, tempZ, modifyDist);
33473347
if (result0)
33483348
{
3349-
DEBUG_LOG("Map::GetHitPosition vmaps corrects gained with static objects! new dest coords are X:%f Y:%f Z:%f", destX, destY, destZ);
3349+
DEBUG_FILTER_LOG(LOG_FILTER_MAP_LOADING, "Map::GetHitPosition vmaps corrects gained with static objects! new dest coords are X:%f Y:%f Z:%f", destX, destY, destZ);
33503350
destX = tempX;
33513351
destY = tempY;
33523352
destZ = tempZ;
@@ -3355,7 +3355,7 @@ bool Map::GetHitPosition(float srcX, float srcY, float srcZ, float& destX, float
33553355
bool result1 = m_dyn_tree.getObjectHitPos(srcX, srcY, srcZ, destX, destY, destZ, tempX, tempY, tempZ, modifyDist);
33563356
if (result1)
33573357
{
3358-
DEBUG_LOG("Map::GetHitPosition vmaps corrects gained with dynamic objects! new dest coords are X:%f Y:%f Z:%f", destX, destY, destZ);
3358+
DEBUG_FILTER_LOG(LOG_FILTER_MAP_LOADING, "Map::GetHitPosition vmaps corrects gained with dynamic objects! new dest coords are X:%f Y:%f Z:%f", destX, destY, destZ);
33593359
destX = tempX;
33603360
destY = tempY;
33613361
destZ = tempZ;

‎src/game/WorldHandlers/MapPersistentStateMgr.cpp‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -794,7 +794,7 @@ MapPersistentState* MapPersistentStateManager::AddPersistentState(MapEntry const
794794
}
795795
}
796796

797-
DEBUG_LOG("MapPersistentStateManager::AddPersistentState: mapid = %d, instanceid = %d, reset time = '" UI64FMTD "', canRset = %u", mapEntry->MapID, instanceId, uint64(resetTime), canReset ? 1 : 0);
797+
DEBUG_FILTER_LOG(LOG_FILTER_MAP_LOADING, "MapPersistentStateManager::AddPersistentState: mapid = %d, instanceid = %d, reset time = '" UI64FMTD "', canRset = %u", mapEntry->MapID, instanceId, uint64(resetTime), canReset ? 1 : 0);
798798

799799
MapPersistentState* state;
800800
if (mapEntry->IsDungeon())

‎src/game/WorldHandlers/ObjectGridLoader.cpp‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -405,7 +405,7 @@ void ObjectGridLoader::LoadN(void)
405405
LoadCell(x, y);
406406
}
407407
}
408-
DEBUG_LOG("%u GameObjects, %u Creatures, and %u Corpses/Bones loaded for grid %u on map %u", i_gameObjects, i_creatures, i_corpses, i_grid.GetGridId(), i_map->GetId());
408+
DEBUG_FILTER_LOG(LOG_FILTER_MAP_LOADING, "%u GameObjects, %u Creatures, and %u Corpses/Bones loaded for grid %u on map %u", i_gameObjects, i_creatures, i_corpses, i_grid.GetGridId(), i_map->GetId());
409409
}
410410

411411
/**

‎src/game/WorldHandlers/ScriptMgr.cpp‎

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -1374,7 +1374,7 @@ bool ScriptAction::HandleScriptStep()
13741374
}
13751375

13761376
// Give some debug log output for easier use
1377-
DEBUG_LOG("DB-SCRIPTS: Process table `db_scripts [type = %d]` id %u, command %u for source %s (%sin world), target %s (%sin world)", m_type, m_script->id, m_script->command, m_sourceGuid.GetString().c_str(), source ? "" : "not ", m_targetGuid.GetString().c_str(), target ? "" : "not ");
1377+
DEBUG_FILTER_LOG(LOG_FILTER_DB_SCRIPTS, "DB-SCRIPTS: Process table `db_scripts [type = %d]` id %u, command %u for source %s (%sin world), target %s (%sin world)", m_type, m_script->id, m_script->command, m_sourceGuid.GetString().c_str(), source ? "" : "not ", m_targetGuid.GetString().c_str(), target ? "" : "not ");
13781378

13791379
// Get expected source and target (if defined with buddy)
13801380
pSource = source && source->isType(TYPEMASK_WORLDOBJECT) ? (WorldObject*)source : NULL;
@@ -2159,12 +2159,12 @@ bool ScriptAction::HandleScriptStep()
21592159

21602160
if (!(m_script->data_flags & SCRIPT_FLAG_COMMAND_ADDITIONAL) && !pCreatureBuddy)
21612161
{
2162-
DEBUG_LOG("DB-SCRIPTS: Process table `db_scripts [type = %d]` id %u, terminate further steps of this script! (as searched other npc %u was not found alive)", m_type, m_script->id, m_script->terminateScript.npcEntry);
2162+
DEBUG_FILTER_LOG(LOG_FILTER_DB_SCRIPTS, "DB-SCRIPTS: Process table `db_scripts [type = %d]` id %u, terminate further steps of this script! (as searched other npc %u was not found alive)", m_type, m_script->id, m_script->terminateScript.npcEntry);
21632163
result = true;
21642164
}
21652165
else if (m_script->data_flags & SCRIPT_FLAG_COMMAND_ADDITIONAL && pCreatureBuddy)
21662166
{
2167-
DEBUG_LOG("DB-SCRIPTS: Process table `db_scripts [type = %d]` id %u, terminate further steps of this script! (as searched other npc %u was found alive)", m_type, m_script->id, m_script->terminateScript.npcEntry);
2167+
DEBUG_FILTER_LOG(LOG_FILTER_DB_SCRIPTS, "DB-SCRIPTS: Process table `db_scripts [type = %d]` id %u, terminate further steps of this script! (as searched other npc %u was found alive)", m_type, m_script->id, m_script->terminateScript.npcEntry);
21682168
result = true;
21692169
}
21702170
}

‎src/game/WorldHandlers/SpellEffects.cpp‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -207,7 +207,7 @@ void Spell::EffectEmpty(SpellEffectIndex /*eff_idx*/)
207207
*/
208208
void Spell::EffectNULL(SpellEffectIndex /*eff_idx*/)
209209
{
210-
DEBUG_LOG("WORLD: Spell Effect DUMMY");
210+
DEBUG_FILTER_LOG(LOG_FILTER_SPELL_CAST, "WORLD: Spell Effect DUMMY");
211211
}
212212

213213
/**
@@ -3119,7 +3119,7 @@ void Spell::EffectDualWield(SpellEffectIndex /*eff_idx*/)
31193119
void Spell::EffectPull(SpellEffectIndex /*eff_idx*/)
31203120
{
31213121
// TODO: create a proper pull towards distract spell center for distract
3122-
DEBUG_LOG("WORLD: Spell Effect DUMMY");
3122+
DEBUG_FILTER_LOG(LOG_FILTER_SPELL_CAST, "WORLD: Spell Effect DUMMY");
31233123
}
31243124

31253125
/**

‎src/mangosd/CliThread.cpp‎

Lines changed: 7 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -31,6 +31,7 @@
3131
#include "CliThread.h"
3232
#include "World.h"
3333
#include "Util.h"
34+
#include "Log.h"
3435

3536
#ifdef _WIN32
3637
#include <windows.h>
@@ -41,8 +42,11 @@
4142
*/
4243
static void prompt(void* callback = NULL, bool status = true)
4344
{
44-
printf("mangos>");
45-
fflush(stdout);
45+
// Route the prompt through the console writer (verbatim, no newline) so it
46+
// shares the single serialized stdout with bar redraws and log lines and
47+
// cannot overtake queued output -- e.g. the bar frames from a just-finished
48+
// .reload that this same callback follows on the world thread.
49+
sLog.ConsoleEmitRaw("mangos>");
4650
}
4751

4852
// Non-blocking keypress detector, when return pressed, return 1, else always return 0
@@ -78,7 +82,7 @@ int CliThread::svc()
7882

7983
if (beep_)
8084
{
81-
printf("\a"); // \a = Alert
85+
sLog.ConsoleEmitRaw("\a"); // \a = Alert (through the writer, single-owner stdout)
8286
}
8387

8488
prompt();

0 commit comments

Comments
 (0)