Logging performance: off-thread console writer, buffered file sinks, and quieter defaults (#402)

* logging: quiet console defaults (LogLevel 3->1) + suppress AI/spell debug filters

Stage 1 / Change A increment 1 (config only, no recompile needed).

- LogLevel 3 -> 1: the dist shipped full DEBUG to the console; on Windows the
  console is flushed per stdio call, so at level 3 every per-spawn DEBUG/DETAIL
  line is a synchronous console write on the world/map-update threads -> the
  LivingWorld / playerbot spawn-burst hang.
- LogFilter_AIAndMovegens 0 -> 1 and LogFilter_SpellCast 0 -> 1: these two
  filters shipped enabled; in a LivingWorld bitmask-7 baseline they are ~50% of
  a LogFileLevel=3 dump (~11k "used AI is" + ~2.7k spell/aura + waypoint). Each
  stays re-enablable for targeted debugging.

Recommended runtime mode is now LogLevel=1 + LogFileLevel=3 (quiet console,
buffered DEBUG to file). Spec: docs/logging-perf/SPEC.md.

Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>

* logging: buffer file sinks + atomic, flush-free hot loggers (Stage 1 / Change A)

Increment 2 - make LogFileLevel=3 debug fast/buffered/un-torn so devs can run
full DEBUG without the world thread stalling on per-line file I/O.

- setvbuf(_IOFBF, 64KB) on all file sinks (openLogFile). The four hot loggers
  (outString/outBasic/outDetail/outDebug) drop their per-line fflush and write
  the timestamp+body+newline under a new m_fileMtx so concurrent map-update
  worker threads cannot tear lines.
- Log::Flush() drains the buffered main + packet logs; called ~1/sec from
  World::Update and once at shutdown (after "Bye!"). Errors still flush at emit
  time and are deliberately NOT under m_fileMtx, so the AntiFreeze watchdog can
  never be blocked by it and error lines stay crash-durable (accepted cost: a
  rare error/debug line interleave, no corruption).
- Initialize() is now idempotent via CloseLogFiles(), fixing the realmd
  double-init handle leak; ~Log() shares the same CloseLogFiles().
- outWorldPacketDump rewritten from one fprintf PER BYTE to a single buffered
  fwrite (byte-identical output).
- PacketLoggingEnabled (default off) is the single gate for packet logging:
  worldLogfile is opened only when set, IsPacketLoggingEnabled() keys off it,
  and both WorldSocket call sites gate on it -> packet logging is off by default
  even on legacy configs with WorldLogFile set + LogLevel=3.

Recommended dev mode: LogLevel=1 + LogFileLevel=3 (quiet console, buffered
DEBUG file). Reviewed by a 3-lens adversarial pass (compile / concurrency /
byte-fidelity): SHIP, no compile blockers. Spec: docs/logging-perf/SPEC.md.

Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>

* logging: off-thread console writer (Stage 1 / increment 3)

Move the console emit off the world + map-update threads so live LogLevel=3
console debug no longer stalls them. On Windows the CRT flushes the console per
stdio call, so console writes can't be batched inline - a dedicated thread does
them.

- ConsoleLogWriter (ACE_Based::Runnable, modeled on SqlDelayThread): producers
  format the line and Enqueue a by-value ConsoleLogRecord into a LockedQueue; one
  writer thread drains it and does Log::SetColor (now static) + OEM transform +
  fwrite + ResetColor, per line, off the hot threads. Bounded with drop+count on
  overflow (the file sink is durable, so dropped/crash-lost console lines are
  harmless). The writer never calls sLog (no reentrancy).
- Every logger's CONSOLE block now routes through Log::ConsoleEmit /
  ConsoleEmitBlank (async when the thread runs, synchronous inline fallback
  otherwise - startup + shutdown tail). The increment-2 m_fileMtx FILE blocks are
  untouched and the public sLog API is unchanged.
- Util::vutf8format returns the formatted OEM/UTF-8 bytes as std::string (same
  vsnprintf + Utf8toWStr + CharToOemBuffW chain as vutf8printf; byte-identical).
- mangosd starts the writer after config/InitColors and stops+drains+joins it at
  shutdown before the final Flush. realmd (a submodule) is intentionally NOT wired
  - it uses the synchronous fallback; its console-thread wiring is a deferred
  submodule follow-up.

Built clean (RelWithDebInfo: mangosd + realmd, 0 errors/warnings) and reviewed by
a 3-lens adversarial pass (concurrency/lifecycle, console-fidelity, style),
SHIP_WITH_FIXES: the no-arg error variants now route through the writer, the
drop-notice fwrite is clamped, and the StopConsoleThread quiescence invariant is
documented. Spec: docs/logging-perf/SPEC.md.

Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>

* logging: address Codex final review of fix/logging-perf-speedfix

Adversarial pre-PR review (Codex) flagged correctness/portability issues in
the off-thread console + buffered-file rework. Fixes (no public sLog API
change, core-side only, no submodule edits):

BLOCKING
- SOAP UAF on shutdown: the SOAP listener is a std::thread, not an ACE task,
  so ACE_Thread_Manager::wait() never joined it; its shared_ptr deleter joined
  only at main() scope exit, AFTER StopConsoleThread() freed the writer -- a
  late SOAP log could enqueue into a freed ConsoleLogWriter. Now soapThread is
  reset() (joined) before StopConsoleThread(), upholding the quiescence
  invariant for SOAP too. (mangosd.cpp)
- ConsoleLogWriter::m_running is now std::atomic<bool>, not volatile bool, so
  Stop()/run() synchronise correctly (volatile is not a memory-model fence;
  matters on weakly-ordered archs). (ConsoleLogWriter.h)

MAJOR
- Console writer started too early: it was launched before the OpenSSL / PID /
  start_db init, whose early-return error paths left the writer thread running
  into stdio teardown. Moved StartConsoleThread() to just after start_db()
  succeeds -- still before SetInitialWorldSettings() (the spawn-burst hot path)
  -- so no fatal early-return leaks a running writer. (mangosd.cpp)
- POSIX truncation regression: vutf8format() clamped to 32 KiB whereas the
  legacy POSIX path used unbounded vfprintf. Oversize messages are now rendered
  in full via a sized second pass (va_copy). (Util.cpp)
- Console byte-fidelity: the trailing newline was being written INSIDE the
  SetColor/ResetColor span; restored the legacy ordering (body -> ResetColor ->
  "\n") by keeping the newline off rec.text and appending it after reset in the
  writer and the sync fallback. (Log.cpp, ConsoleLogWriter.cpp, Log.h)

MINOR / hygiene
- Writer now owns the stdout flush (one fflush per drain batch, off the world
  thread) so redirected/piped consoles stay prompt. (ConsoleLogWriter.cpp)
- Added <utility> for std::move (was relying on a transitive include that GCC/
  Clang may not provide). (Log.cpp)
- Refreshed stale config comments (LogLevel now defaults to 1; AIAndMovegens /
  SpellCast now ship suppressed) and documented PacketLoggingEnabled.
  (mangosd.conf.dist.in)

Note (intentional, not restored): all error console output (timestamp +
message + newline) now goes to stderr consistently. Previously the optional
LogTime timestamp leaked to stdout via outTime() while the message went to
stderr; with the default LogTime=0 the console output is byte-identical to
master.

Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>

* logging: bump world ConfVersion for the new logging config keys

The logging-performance change adds PacketLoggingEnabled and flips the
default LogLevel / LogFilter_AIAndMovegens / LogFilter_SpellCast values in
mangosd.conf.dist, so bump MANGOS_WORLD_VER (drives both the generated
ConfVersion and the compiled MANGOSD_CONFIG_VERSION) to today's date. Servers
running an older mangosd.conf now get the "conf out of date" warning.

Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>

---------

Co-authored-by: Claude Opus 4.8 (1M context) <noreply@anthropic.com>

Author: MadMaxMangos

cmake/MangosParams.cmake

@@ -1,5 +1,5 @@
 set(MANGOS_EXP "CLASSIC")
 set(MANGOS_PKG "Mangos Zero")
-set(MANGOS_WORLD_VER 2026062401)
+set(MANGOS_WORLD_VER 2026062801)
 set(MANGOS_REALM_VER 2026060300)
 set(MANGOS_AHBOT_VER 2021010100)

src/game/Server/WorldSocket.cpp

@@ -657,8 +657,11 @@ int WorldSocket::ProcessIncoming(WorldPacket* new_pct)
         return -1;
     }
 
-    // Dump received packet.
-    sLog.outWorldPacketDump(uint32(get_handle()), new_pct->GetOpcode(), new_pct->GetOpcodeName(), new_pct, true);
+    // Dump received packet (opt-in via PacketLoggingEnabled; off by default).
+    if (sLog.IsPacketLoggingEnabled())
+    {
+        sLog.outWorldPacketDump(uint32(get_handle()), new_pct->GetOpcode(), new_pct->GetOpcodeName(), new_pct, true);
+    }
 
     try
     {
@@ -1051,7 +1054,7 @@ int WorldSocket::iSendPacket(const WorldPacket& pct)
         return -1;
     }
 
-    if (sLog.HasLogLevelOrHigher(LOG_LVL_DEBUG))   // allow server packet logging
+    if (sLog.IsPacketLoggingEnabled())   // server packet logging (opt-in via PacketLoggingEnabled)
     {
         sLog.outWorldPacketDump(uint32(get_handle()), pct.GetOpcode(), pct.GetOpcodeName(), &pct, false);
     }

src/game/WorldHandlers/World.cpp

@@ -1839,6 +1839,18 @@ void World::Update(uint32 diff)
     GameTime::UpdateGameTimers();
     sWorldUpdateTime.UpdateWithDiff(diff);
 
+    ///- Flush buffered log files about once per second. The file sinks are
+    ///  fully buffered (setvbuf), so this bounds how long a buffered line waits
+    ///  to reach disk; error paths still flush immediately at emit time. Safe as
+    ///  a function-local static: World::Update runs only on the world thread.
+    static uint32 logFlushTimer = 0;
+    logFlushTimer += diff;
+    if (logFlushTimer >= 1000)
+    {
+        logFlushTimer = 0;
+        sLog.Flush();
+    }
+
     ///-Update mass mailer tasks if any
     sMassMailMgr.Update();
 

src/mangosd/mangosd.conf.dist.in

@@ -260,7 +260,10 @@ MaxWhoListReturns                 = 49
 #    LogLevel
 #        Server console level of logging
 #        0 = Minimum; 1 = Basic&Error; 2 = Detail; 3 = Full/Debug
-#        Default: 3
+#        Default: 1 - Basic&Error (keeps the live console light; level 3 in
+#                     particular is very chatty and can stall startup under
+#                     large spawn loads -- prefer raising LogFileLevel instead
+#                     to capture detail to disk without the console cost)
 #
 #    LogTime
 #        Include time in server console output [hh:mm:ss]
@@ -303,9 +306,13 @@ MaxWhoListReturns                 = 49
 #    LogFilter_Damage
 #    LogFilter_Combat
 #    LogFilter_SpellCast
-#        Log filters (disabled by default, mostly debug only output affected cases)
+#        Log filters (mostly debug-only output for the affected cases)
 #        Default: 0 - include in log if log level permit
 #                 1 - not include with any log level
+#        NOTE: LogFilter_AIAndMovegens and LogFilter_SpellCast now ship as 1
+#              (suppressed). Both are extremely high-volume on busy or debug
+#              servers (movement generators; every spell cast) and otherwise
+#              dominate the logs. Set either to 0 to restore its verbose output.
 #
 #    LogWhispers
 #        Log whispers between players to database, character.character_whispers
@@ -318,6 +325,15 @@ MaxWhoListReturns                 = 49
 #        Default: ""          - no log file created
 #                 "world.log" - recommended name to create a log file
 #
+#    PacketLoggingEnabled
+#        Master switch for world packet logging (the WorldLogFile dump). Packet
+#        logging is high-volume and was historically turned on implicitly
+#        whenever WorldLogFile was set; it is now OFF unless this is explicitly
+#        set to 1, so an existing config that sets WorldLogFile (even at
+#        LogLevel 3) no longer pays the packet-dump cost by accident.
+#        Default: 0 - do not write packet dumps (recommended)
+#                 1 - write packet dumps to WorldLogFile
+#
 #    WorldLogTimestamp
 #        Logfile with timestamp of server start in name
 #        Default: 0 - no timestamp in name
@@ -389,7 +405,7 @@ MaxWhoListReturns                 = 49
 
 LogSQL                       = 1
 PidFile                      = ""
-LogLevel                     = 3
+LogLevel                     = 1
 LogTime                      = 0
 LogFile                      = "world-server.log"
 LogTimestamp                 = 0
@@ -406,13 +422,14 @@ LogFilter_CellEnvelope       = 1
 LogFilter_PeriodicAffects    = 0
 LogFilter_PlayerMoves        = 1
 LogFilter_SQLText            = 1
-LogFilter_AIAndMovegens      = 0
+LogFilter_AIAndMovegens      = 1
 LogFilter_PlayerStats        = 0
 LogFilter_Damage             = 0
 LogFilter_Combat             = 0
-LogFilter_SpellCast          = 0
+LogFilter_SpellCast          = 1
 LogWhispers                  = 1
 WorldLogFile                 = "world-packets.log"
+PacketLoggingEnabled         = 0
 WorldLogTimestamp            = 0
 DBErrorLogFile               = "world-database.log"
 ElunaErrorLogFile            = "ElunaErrors.log"

src/mangosd/mangosd.cpp

@@ -485,6 +485,14 @@ int main(int argc, char** argv)
         return 1;
     }
 
+    // Move the console emit off the world/map-update threads. Started only after
+    // the fallible init above (OpenSSL / PID file / DB) so the early-return error
+    // paths never leave a writer thread running into stdio teardown; still placed
+    // before SetInitialWorldSettings() -- the LivingWorld spawn burst -- so the
+    // hot console path is covered. Config/InitColors already applied, so colors
+    // are set; from here the per-call console flush runs on the writer thread.
+    sLog.StartConsoleThread();
+
     ///- Set Realm to Offline, if crash happens. Only used once.
     LoginDatabase.DirectPExecute("UPDATE `realmlist` SET `realmflags` = `realmflags` | %u WHERE `id` = '%u'", REALM_FLAG_OFFLINE, realmID);
 
@@ -677,7 +685,33 @@ int main(int argc, char** argv)
     _set_abort_behavior(0, _WRITE_ABORT_MSG | _CALL_REPORTFAULT);
 #endif
 
+#ifdef ENABLE_SOAP
+    // Join the SOAP listener before stopping the console writer. SOAP runs on a
+    // std::thread (NOT an ACE task), so ACE_Thread_Manager::wait() above did NOT
+    // join it; its shared_ptr deleter would otherwise join only at main() scope
+    // exit -- AFTER StopConsoleThread() deletes the writer -- leaving a window
+    // where a late SOAP log could enqueue into a freed ConsoleLogWriter (UAF).
+    // Resetting here runs the deleter (join + delete) now, so the writer's
+    // quiescence invariant holds for SOAP too.
+    soapThread.reset();
+#endif
+
+    // Stop and join the off-thread console writer before the final shutdown lines:
+    // later lines ("Bye!") then take the synchronous fallback. Placed after EVERY
+    // console-producing thread is gone -- world/map ACE workers (joined by
+    // ACE_Thread_Manager::wait above), the CLI thread, and the SOAP std::thread
+    // (joined just above) -- so no concurrent producer can race the writer delete.
+    // The remaining main-thread shutdown lines are drained by the still-running
+    // writer before it joins. Precedes the final Flush.
+    sLog.StopConsoleThread();
+
     sLog.outString("Bye!");
+
+    // Final flush of the buffered file logs before exit. ~Log/CloseLogFiles also
+    // flush via fclose, but this guarantees "Bye!" and any late shutdown lines
+    // reach disk first.
+    sLog.Flush();
+
     return code;
 }
 /// @}

src/shared/CMakeLists.txt

@@ -109,6 +109,8 @@ source_group("LockedQueue" FILES ${SRC_GRP_LOCKQ})
 set(SRC_GRP_LOG
   Log/Log.cpp
   Log/Log.h
+  Log/ConsoleLogWriter.cpp
+  Log/ConsoleLogWriter.h
 )
 source_group("Log" FILES ${SRC_GRP_LOG})
 

src/shared/Log/ConsoleLogWriter.cpp

@@ -0,0 +1,131 @@
+/**
+ * MaNGOS is a full featured server for World of Warcraft, supporting
+ * the following clients: 1.12.x, 2.4.3, 3.3.5a, 4.3.4a and 5.4.8
+ *
+ * Copyright (C) 2005-2025 MaNGOS <https://www.getmangos.eu>
+ *
+ * This program is free software; you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License as published by
+ * the Free Software Foundation; either version 2 of the License, or
+ * (at your option) any later version.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License
+ * along with this program; if not, write to the Free Software
+ * Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA  02111-1307  USA
+ *
+ * World of Warcraft, and all World of Warcraft or Warcraft art, images,
+ * and lore are copyrighted by Blizzard Entertainment, Inc.
+ */
+
+/**
+ * @file ConsoleLogWriter.cpp
+ * @brief Off-thread console log writer implementation
+ *
+ * Implements the dedicated thread that renders queued console log records,
+ * moving the per-call console flush (and the SetConsoleTextAttribute / OEM
+ * transform) off the world and map-update threads.
+ */
+
+#include "ConsoleLogWriter.h"
+
+#include <cstdio>
+
+ConsoleLogWriter::ConsoleLogWriter()
+    : m_depth(0), m_dropped(0), m_running(true)
+{
+}
+
+void ConsoleLogWriter::Enqueue(ConsoleLogRecord& rec)
+{
+    if (m_depth.value() >= MAX_CONSOLE_QUEUE)
+    {
+        ++m_dropped;
+        return;
+    }
+    ++m_depth;
+    m_queue.add(rec);
+}
+
+void ConsoleLogWriter::run()
+{
+    while (m_running)
+    {
+        if (!DrainOnce())
+        {
+            ACE_Based::Thread::Sleep(5);
+        }
+    }
+    // Authoritative final drain: runs on the writer thread while wait()
+    // blocks the caller, so any straggler enqueued before Stop() is rendered.
+    DrainOnce();
+}
+
+bool ConsoleLogWriter::DrainOnce()
+{
+    bool didWork = false;
+
+    long dropped = m_dropped.value();
+    if (dropped > 0)
+    {
+        m_dropped -= dropped;
+        char note[96];
+        int n = snprintf(note, sizeof(note),
+            "[Log] %ld console line(s) dropped (queue full)\n", dropped);
+        if (n >= (int)sizeof(note))
+        {
+            n = (int)sizeof(note) - 1;                       // clamp: never fwrite past note[]
+        }
+        if (n > 0)
+        {
+            Log::SetColor(true, RED);
+            fwrite(note, 1, (size_t)n, stdout);
+            Log::ResetColor(true);
+        }
+        didWork = true;
+    }
+
+    ConsoleLogRecord rec;
+    while (m_queue.next(rec))
+    {
+        --m_depth;
+        Emit(rec);
+        didWork = true;
+    }
+
+    // The writer owns the console stream, so it owns the flush: a redirected /
+    // piped stdout is fully buffered, and flushing here (off the world/map
+    // threads) makes output prompt without any producer paying for it. A real
+    // console is effectively unbuffered, so this is a cheap no-op there.
+    if (didWork)
+    {
+        fflush(stdout);
+    }
+
+    return didWork;
+}
+
+void ConsoleLogWriter::Emit(const ConsoleLogRecord& rec)
+{
+    FILE* out = rec.toStdout ? stdout : stderr;
+    if (rec.applyColor)
+    {
+        Log::SetColor(rec.toStdout, rec.color);
+    }
+    if (!rec.text.empty())
+    {
+        fwrite(rec.text.data(), 1, rec.text.size(), out);
+    }
+    if (rec.applyColor)
+    {
+        Log::ResetColor(rec.toStdout);
+    }
+    // Newline is written AFTER ResetColor so the line terminator stays outside
+    // the color span, byte-matching the legacy console ordering. The producer
+    // (Log::ConsoleEmit) deliberately leaves it off rec.text.
+    fputc('\n', out);
+}