Add structured logging with structlog across codebase#344
Conversation
- Add structlog==25.5.0 to requirements.txt - Create src/gameLogging/logger.py with getLogger() and redact() helpers - Register LoggerFactory singleton in DI container via bootstrap.py - Add LOG_LEVEL and LOG_FORMAT config support in config.py - Add example logging configuration to config.yml - Replace all print() calls in source files with structured logger calls - Add instrumentation for tick warnings, save/load, map image ops, entity lifecycle, and error handling - Create LOGGING.md documentation - Add tests for logger module (7 new tests) - Update CHANGELOG.md Agent-Logs-Url: https://github.com/Preponderous-Software/roam/sessions/4b656504-ed85-437b-b9aa-7e486c19408c Co-authored-by: dmccoystephenson <21204351+dmccoystephenson@users.noreply.github.com>
- Remove Django==4.1.6 (unused, SQL injection + DoS vulnerabilities) - Remove sqlparse==0.4.3 (unused Django dep, DoS vulnerability) - Remove py==1.11.0 (deprecated, ReDoS vulnerability, no patch) - Upgrade Pillow from 9.4.0 to 10.4.0 (fixes buffer overflow + DoS) Agent-Logs-Url: https://github.com/Preponderous-Software/roam/sessions/4b656504-ed85-437b-b9aa-7e486c19408c Co-authored-by: dmccoystephenson <21204351+dmccoystephenson@users.noreply.github.com>
…write vulnerabilities Agent-Logs-Url: https://github.com/Preponderous-Software/roam/sessions/4b656504-ed85-437b-b9aa-7e486c19408c Co-authored-by: dmccoystephenson <21204351+dmccoystephenson@users.noreply.github.com>
|
@copilot expand logging and audit existing log statements for proper log level usage |
- Fix worldScreen.py: downgrade 2 log statements from ERROR to DEBUG for expected entity lifecycle edge cases (entity not found in room, could not find new location) - Add logging to config.py: log all resolved config values at DEBUG - Add logging to roam.py: screen transitions at INFO, shutdown at INFO - Add logging to worldScreen.py: initialization and room transitions at INFO - Add logging to map.py: room loading from file and generation at INFO - Add logging to roomFactory.py: room creation at DEBUG, entity spawning (chickens/bears) at DEBUG - Add logging to roomPreloader.py: preload success at DEBUG, failures at ERROR - Add logging to stats.py: save/load at INFO - Add logging to saveSelectionScreen.py: save selection, creation, and deletion at INFO - Add logging to inventory.py: item placement and stacking at DEBUG - Update CHANGELOG.md Agent-Logs-Url: https://github.com/Preponderous-Software/roam/sessions/a852a88a-11fa-4ac8-8099-205ab6d83136 Co-authored-by: dmccoystephenson <21204351+dmccoystephenson@users.noreply.github.com>
Expanded logging and audited all existing log levels in commit 33ed66d. Log level fixes:
New logging added to 8 files:
|
There was a problem hiding this comment.
Pull request overview
This PR introduces structured logging (via structlog) across Roam to replace scattered print() statements and add consistent instrumentation for gameplay, saves, and background tasks.
Changes:
- Added a central logging module (
src/gameLogging/logger.py) with helpers and DI integration. - Replaced
print()calls with structured log events in core world/screen/save/map-image/inventory flows. - Added logging configuration documentation (
LOGGING.md) and config.yml keys, plus a newrequirements.txtentry forstructlog.
Reviewed changes
Copilot reviewed 22 out of 23 changed files in this pull request and generated 5 comments.
Show a summary per file
| File | Description |
|---|---|
| tests/gameLogging/test_logger.py | Adds unit tests for getLogger, redact, and LoggerFactory. |
| src/gameLogging/logger.py | New structlog setup, env parsing, redaction helper, and logger factory. |
| src/gameLogging/init.py | Exposes getLogger/redact from the package. |
| src/bootstrap.py | Registers LoggerFactory in the DI container. |
| src/config/config.py | Adds logLevel/logFormat config keys and logs resolved config at DEBUG. |
| src/world/tickCounter.py | Converts tick warnings/save/load prints into structured logs. |
| src/world/roomPreloader.py | Adds debug/error logs for background preloading and failures. |
| src/world/roomJsonReaderWriter.py | Logs room save/load operations. |
| src/world/roomFactory.py | Logs room creation and entity spawn counts. |
| src/world/room.py | Logs entity removal edge cases and missing locations. |
| src/world/map.py | Logs room load/generation events. |
| src/stats/stats.py | Logs stats save/load events. |
| src/screen/worldScreen.py | Logs world init, room transitions, save/load operations, and lifecycle edge cases. |
| src/screen/saveSelectionScreen.py | Logs save selection/creation/deletion. |
| src/roam.py | Logs startup, shutdown, and screen transitions. |
| src/mapimage/mapImageUpdater.py | Logs map-image update lifecycle and failures. |
| src/mapimage/mapImageGenerator.py | Replaces debug prints with structured debug logs. |
| src/inventory/inventoryJsonReaderWriter.py | Logs inventory save/load and validation failures. |
| src/inventory/inventory.py | Logs inventory placement/stacking/full events at DEBUG. |
| requirements.txt | Adds structlog and updates/pins dependency set. |
| config.yml | Documents logging keys (commented). |
| LOGGING.md | Documents logging config, levels, field naming, and redaction. |
| CHANGELOG.md | Adds a changelog entry and a learning-log note about package naming conflicts. |
| _LOG_LEVEL_NAME = os.environ.get("LOG_LEVEL", "INFO").upper() | ||
| _LOG_LEVEL = _VALID_LEVELS.get(_LOG_LEVEL_NAME, logging.INFO) | ||
| _LOG_FORMAT = os.environ.get("LOG_FORMAT", "pretty").lower() |
There was a problem hiding this comment.
LOG_LEVEL is parsed into _LOG_LEVEL, but _LOG_LEVEL is never used, so log-level filtering likely doesn't work (e.g., DEBUG logs may always be emitted). Apply _LOG_LEVEL in structlog configuration (e.g., filtering wrapper/logger or stdlib logging level) so runtime log verbosity is actually controlled by LOG_LEVEL.
| # Custom TRACE level (below DEBUG) | ||
| # --------------------------------------------------------------------------- | ||
| TRACE_LEVEL = 5 | ||
| logging.addLevelName(TRACE_LEVEL, "TRACE") | ||
|
|
There was a problem hiding this comment.
A custom TRACE level is declared and documented, but there’s no logger.trace(...) API wired up (adding a level name alone doesn’t create a logging method). Either implement a trace() method (or expose a supported alternative like logger.log(TRACE_LEVEL, ...)) or remove TRACE from the supported levels/docs to avoid a misleading API.
| # logging | ||
| self.logLevel = os.environ.get( | ||
| "LOG_LEVEL", | ||
| self.getStringValue(configValues, "logLevel", "INFO"), | ||
| ) | ||
| self.logFormat = os.environ.get( | ||
| "LOG_FORMAT", | ||
| self.getStringValue(configValues, "logFormat", "pretty"), | ||
| ) |
There was a problem hiding this comment.
logLevel/logFormat are read from config.yml into Config, but nothing uses these values to configure structlog (logger setup happens from env vars at import time). Either reconfigure logging based on Config (with env taking precedence) or remove these config keys to avoid having non-functional configuration knobs.
| except Exception as e: | ||
| _logger.error("room preload failed", roomX=x, roomY=y, error=str(e)) |
There was a problem hiding this comment.
This catches a broad exception and logs only error=str(e), which drops the traceback. For background preload failures it’s hard to diagnose without stack info; prefer logger.exception(...) or include exc_info=True so the full error context is captured.
| except Exception as e: | |
| _logger.error("room preload failed", roomX=x, roomY=y, error=str(e)) | |
| except Exception: | |
| _logger.exception("room preload failed", roomX=x, roomY=y) |
| except Exception as e: | ||
| print("Error updating map image: " + str(e)) | ||
| _logger.error("error updating map image", error=str(e)) |
There was a problem hiding this comment.
On failure, this logs only error=str(e) and loses the traceback from the background thread. Use logger.exception(...) (or exc_info=True) so map image update failures are diagnosable from logs alone.
|
@copilot You are a coding agent tasked with resolving all open comments and review threads Instructions1. Discover all comments
2. For each comment, do the following:
3. Types of issues to handle:
4. Do NOT:
After making changes
Context
|
|
@copilot You are a coding agent tasked with resolving all open comments and review threads Instructions1. Discover all comments
2. For each comment, do the following:
3. Types of issues to handle:
4. Do NOT:
After making changes
Context
|
Agent-Logs-Url: https://github.com/Preponderous-Software/roam/sessions/310419b7-369a-43bb-be24-e15e41a67901 Co-authored-by: dmccoystephenson <21204351+dmccoystephenson@users.noreply.github.com>
All 5 review comments were addressed in commit 341bebb:
All 342 tests pass. |
| elif result == ScreenType.NONE: | ||
| _logger.info("shutting down") | ||
| self.quitApplication() | ||
| else: | ||
| print("unrecognized screen: " + result) | ||
| _logger.error("unrecognized screen", screen=result) | ||
| self.quitApplication() | ||
| _logger.info("screen transition", screen=str(result)) |
There was a problem hiding this comment.
quitApplication() ends the process via quit(), so the screen transition log after calling self.quitApplication() is unreachable for ScreenType.NONE and the unrecognized screen branch. Consider logging the transition before quitting and/or returning immediately after quitApplication() to make the control flow explicit and ensure the log is emitted.
| from gameLogging.logger import redact | ||
|
|
There was a problem hiding this comment.
The redaction example uses logger.info(...) but the snippet doesn’t define logger. Add logger = getLogger(__name__) (or a short note that logger is assumed to already exist) so the example is copy/pasteable.
| from gameLogging.logger import redact | |
| from gameLogging.logger import getLogger, redact | |
| logger = getLogger(__name__) |
|
@copilot You are a coding agent tasked with resolving all open comments and review threads Instructions1. Discover all comments
2. For each comment, do the following:
3. Types of issues to handle:
4. Do NOT:
After making changes
Context
|
…d example Agent-Logs-Url: https://github.com/Preponderous-Software/roam/sessions/cd09fbf8-ce04-4f70-baca-54352013533f Co-authored-by: dmccoystephenson <21204351+dmccoystephenson@users.noreply.github.com>
Both open review comments addressed in ace899c:
All 342 tests pass, CodeQL clean. |
|
@copilot It is not clear to me how to set the log level. Running |
…setup Agent-Logs-Url: https://github.com/Preponderous-Software/roam/sessions/4ef58052-529c-4106-a2c5-d7ba34a0192c Co-authored-by: dmccoystephenson <21204351+dmccoystephenson@users.noreply.github.com>
Fixed in 310d66c. Three issues addressed:
LOGGING.md now has a "Setting environment variables by platform" section with copy-pasteable examples for bash, cmd.exe, and PowerShell, including warning callouts for the common pitfalls. |
Replaces scattered
print()calls with structured logging viastructlog, enabling runtime behaviour reconstruction from logs alone.Changes
src/gameLogging/logger.py— Central logging module withgetLogger(name),redact()helper, andLoggerFactoryDI singleton. ReadsLOG_LEVEL/LOG_FORMATfrom env (defaults:INFO/pretty). Uses stdlib logging as backend withstructlog.stdlib.filter_by_levelsoLOG_LEVELactually controls log verbosity. Env var values are stripped of whitespace for robustness. NamedgameLoggingto avoid shadowing stdliblogging.src/bootstrap.py— RegistersLoggerFactoryas singleton in DI container.src/config/config.py— Logs all resolved config values atDEBUGon startup. Logging is configured solely via environment variables (LOG_LEVEL/LOG_FORMAT), not config.yml, since structlog is initialised at import time beforeConfigis available.All
print()calls replaced intickCounter.py,worldScreen.py,mapImageUpdater.py,mapImageGenerator.py,inventoryJsonReaderWriter.py,roomJsonReaderWriter.py,room.py,roam.py— using appropriate levels (WARNfor slow ticks,INFOfor save/load,ERRORfor failures,DEBUGfor entity lifecycle).Expanded instrumentation added to
config.py,roam.py,worldScreen.py,map.py,roomFactory.py,roomPreloader.py,stats.py,saveSelectionScreen.py, andinventory.pycovering screen transitions, room transitions, room loading/generation, entity spawning, background preloading, save management, and inventory operations.Log level audit — Fixed 2 incorrect log levels in
worldScreen.py: "living entity not found in room" and "could not find new location for entity" downgraded fromERRORtoDEBUG(expected entity lifecycle edge cases, not error conditions).Exception logging — Background thread error handlers in
roomPreloader.pyandmapImageUpdater.pyuselogger.exception()to preserve full tracebacks for diagnosability.requirements.txt— Addedstructlog==25.5.0, removed unused vulnerable deps (Django, sqlparse, py), upgraded Pillow to 12.2.0..github/workflows/tests.yml— Addedstructlogto CI dependency install step so tests can import the new logging module.LOGGING.md— Documents log levels, env vars, field naming conventions (camelCase), redaction policy, and platform-specific instructions for setting environment variables on Linux/macOS (bash), Windows Command Prompt (cmd.exe), and Windows PowerShell.Instrumentation Coverage
INFOroam.pyDEBUGconfig.pyINFOroam.pyINFOworldScreen.pyINFOworldScreen.pyINFOmap.pyDEBUGroomFactory.pyDEBUGroomFactory.pyDEBUG/ERRORroomPreloader.pyWARNtickCounter.pyINFOstats.py,tickCounter.py,inventoryJsonReaderWriter.py,roomJsonReaderWriter.py,worldScreen.pyINFOsaveSelectionScreen.pyDEBUGinventory.pyINFO/ERRORmapImageUpdater.py,mapImageGenerator.pyDEBUGworldScreen.pyERRORworldScreen.py,room.py,roam.pyUsage
Configure via environment:
Linux / macOS (bash):
Windows — Command Prompt (cmd.exe):
Windows — PowerShell: