Logging - questions, current state, possible improvements

[dgelessus]

Plasma has plStatusLog as its main central logging system, but there are also lots of little logging helper functions built on top of it. A few places also do their own custom logging without plStatusLog.

I tried to make a list to figure out which logging APIs exist, how they relate to each other, and what they do differently. There's quite a few of them and I probably missed some.

List of logging APIs

• plStatusLog: Outputs to .log files in the Log folder, and for internal clients also to the in-game "log drawer" window. Allows setting the color of each log line, but they're only visible in the "log drawer" and not in the .log files, so they're of limited use as log levels. Has a global fLoggingOff flag, but nothing really uses it.
  • hsStatusMessage goes to plasmadbg.log in internal builds. It's compile-time-disabled in external builds.
  • hsDebugMessage goes to plasmadbg.log in debug builds. It's compile-time-disabled in release builds.
  • pnAcLog (global LogMsg function) goes to OLD_ASYNC_LOG.log. It accepts a severity level, which is entirely ignored.
  • plResManager logs to resources.log. It implements a simple log level system with conditional logging.
  • plNetClientMgr::Log goes to network.log (and conditionally also to hsStatusMessage and plNetObjectDebugger).
    • plLoggable (base class of plNetClientMgr) adds a simple log level system on top of this.
      • plNetApp::Static*Msg goes here.
  • plNetClientStatsRecorder goes to StatsRecorder.log.
  • plNetClientStreamRecorder goes to StreamRecorder.log.
  • plDetectorLog goes to Detector.log. It adds a simple log level system.
  • plKickableLog goes to Kickables.log in internal builds with USE_KICKABLE_LOG defined. It adds a simple log color system.
  • plPXErrorHandler translates PhysX error codes/messages and logs them to Simulation.log.
  • plSimulationManager logs to Simulation.log. It adds a very simple log color system.
  • plWaveSet7::Log goes to TexWaves in the log drawer (no .log file).
  • plDXPipeline::IAddErrorMessage goes to pipeline.log.
  • plEAXListener::IFail logs to audio.log. It distinguishes between "major" and not-"major" errors.
  • plSound::IPrintDbgMessage goes to audio.log. It distinguishes between errors and not-errors.
  • LocalizationXMLFile::AddError goes to LocalizationDataMgr.log.
  • pfPatcher's PatcherLog* go to patcher.log. It adds a simple log color system.
  • Python stdout, stderr, and exception tracebacks go to Python.log.
  • Python PtDebugPrint goes to python.log. It adds a log level system that allows conditional logging.
• plVirtualCamNeu logs to camLog.txt in internal builds, bypassing plStatusLog.
• DebugMsg goes to stderr, and on Windows also to OutputDebugString.
  • DEBUG_MSG is the same, but compile-time-disabled in release builds.
    • hsRefCnt's REFCOUNT_DBG_REFS debug output goes here.
    • plNetObjectDebugger::LogMsg goes here.
• External libraries might do whatever.
  • openal-soft in debug builds logs to OutputDebugString.
• There might be more code printing to stdout/stderr. Difficult to say for sure, because there are many ways to print there - [f]printf, [f]puts, cout/cerr, ST::printf, ...

This is all a bit confusing from a developer perspective, especially when new to the codebase. Questions I've asked myself:

• What's the simplest thing to use for quick and dirty temporary debug logging? DebugMsg? DEBUG_MSG? hsDebugMessage?
• What's the right solution for more permanent log messages?
  • Use a class/module-specific logging solution, if one exists?
  • Call one of the generic global log/debug functions (hsStatusMessage, plAcLog)?
  • Use plStatusLogMgr::CreateStatusLog to set up a reusable plStatusLog instance?
  • Just call plStatusLog::AddLineS directly?
• What to do in Python scripts? PtDebugPrint or just standard print?
• Which log calls should be conditionally compiled only in internal and/or debug builds, and which ones should be enabled unconditionally?

I'm also wondering why all of these different logging helpers exist in the first place - or if they are mostly just legacy code. A common pattern in these helper functions is to build on plStatusLog, but hardcode the log file name and add compile-time conditional logging and/or multiple methods for different log levels/colors. Perhaps those features should be integrated into plStatusLog itself somehow, so that not every place that wants log levels or conditional logging has to reimplement them manually?

For reference, some past work on the logging infrastructure:

• plStatusLog++; pnAcLog-- #172
• Key Leaks/Debug Logging #255
• Update all logging to ST::format/ST::string #480

[dpogue]

• What's the simplest thing to use for quick and dirty temporary debug logging?

I've used hsStatusMessage for this because it also prints out to stdout on Linux.

One issue that we ran into when trying to get rid of the pnAcLog and OLD_ASYNC_LOG stuff is that plStatusLog is in PubUtilLib and not NucleusLib.

[Hoikas]

I've been meaning to answer this for awhile, but so much to do, so little time. These are all good observations and questions, so I'll answer the questions with my personal preferences.

What's the simplest thing to use for quick and dirty temporary debug logging? DebugMsg? DEBUG_MSG? hsDebugMessage?

I generally use plStatusLog::AddLineSF. Often, I'll add the colored helper methods (eg KickableLogRed, KickableLogGreen) because FooLogRed("result: {}", bar); is more trivial to type than plStatusLog::AddLineSF("foo", plStatusLog::kRed, "result: {}, bar), especially when iterating quickly.

What's the right solution for more permanent log messages?

Probably manually set up the log with plStatusLogMgr::CreateStatusLog. I leave in my colored helpers for these logs to make my life easier.

What to do in Python scripts? PtDebugPrint or just standard print?

PtDebugPrint - something that needs to be done is an audit of the level arguments to get good coloration in the Python log drawer.

Which log calls should be conditionally compiled only in internal and/or debug builds, and which ones should be enabled unconditionally?

This is a bit of a judgement call - some logs are particularly spammy or only useful during development. These are the ones that I would tend to compile out, eg the kickable log. Given that we are not a paid game and aren't really trying to hide what goes on under the hood, though, I don't see why we should over zealously compile out logging.

[dgelessus]

For reference: I recently consolidated/removed a few of the oddball logging functions. In particular:

• LogMsg from pnAsyncCore is now only used in the netcode. (Decouple pnAsyncCore from some protocol and game logic code #1533)
• plNetObjectDebugger now uses plStatusLog (NetObject.log) instead of DEBUG_MSG. (Make plNetObjectDebugger usable in non-debug builds #1738)
• The DEBUG_MSG macro has been removed as its conditional behavior was effectively unused. (Clean up some unused or redundant debug macros #1740)
• DebugMsg has been renamed to hsDebugPrintToTerminal, to avoid name collisions and to discourage its use (because its output isn't easily visible to the average player/tester). Most uses have been replaced with other logging functions. (Rename global DebugMsg function (and others) to avoid name collisions/confusion #1742)
• hsDebugMessage has been removed in favor of the almost identical hsStatusMessage. (Remove hsDebugMessage in favor of hsStatusMessage #1743)