cleveragents/cleveragents-core

Fork 3

BUG-HUNT: [consistency] `configure_structlog()` with `cache_logger_on_first_use=True` leaves already-cached loggers using stale processor chain — reconfiguration does not take effect for existing loggers #6570

New issue

Open

opened 2026-04-09 21:29:58 +00:00 by HAL9000 · 1 comment

HAL9000 commented

2026-04-09 21:29:58 +00:00

Owner

Bug Report: [consistency] — Stale Processor Chain in Cached Structlog Loggers After Reconfiguration

Severity Assessment

Impact: If any structlog logger emits a log record before configure_structlog() is called (using the default structlog processor chain that has no secrets masking), that logger's processor chain is cached. Subsequent calls to configure_structlog() do not invalidate these caches. The affected logger will permanently bypass secrets masking (secrets_masking_processor) and any other custom processors, leaking API keys, tokens, and credentials to stdout/stderr in plain text.
Likelihood: Medium — structlog loggers are created at module import time across ~50+ modules (e.g., container.py:120, audit_service.py:62, acms_service.py:94). Any module that emits a log record during import or early initialization — before configure_structlog() runs — will be affected.
Priority: Medium

Location

File: src/cleveragents/config/logging.py
Function/Class: configure_structlog()
Lines: 67–70

Description

configure_structlog() calls structlog.configure() with cache_logger_on_first_use=True:

# src/cleveragents/config/logging.py lines 67-70
structlog.configure(
    processors=shared_processors,
    logger_factory=structlog.stdlib.LoggerFactory(),
    wrapper_class=structlog.stdlib.BoundLogger,
    cache_logger_on_first_use=True,
)

From the structlog documentation:

"Once a bound logger has been used, its processors chain is frozen, cached, and is not affected by subsequent calls to structlog.configure()."

This means: any logger that calls .info(), .warning(), etc. before configure_structlog() runs will cache structlog's default processor chain (which includes only a PrintLoggerFactory with no secrets masking, no redaction, and no structured output). Subsequent configure_structlog() calls do NOT update these cached loggers.

The codebase has module-level loggers in nearly every file:

# Many files like audit_service.py, container.py, acms_service.py:
_logger = structlog.get_logger(__name__)   # Module-level, created at import time

The container.py code comments (lines 932–938) acknowledge this risk and carefully call configure_structlog() first, but other entry points (e.g., reactive/application.py) may log before configure_structlog() is called — and with cache_logger_on_first_use=True, those loggers will be permanently misconfigured.

Evidence

# src/cleveragents/config/logging.py lines 57-70
shared_processors: list[structlog.types.Processor] = [
    structlog.contextvars.merge_contextvars,
    structlog.stdlib.add_log_level,
    structlog.stdlib.add_logger_name,
    structlog.processors.TimeStamper(fmt="iso"),
    secrets_masking_processor,  # ← This masking is NEVER applied to already-cached loggers
    structlog.stdlib.ProcessorFormatter.wrap_for_formatter,
]

structlog.configure(
    processors=shared_processors,
    logger_factory=structlog.stdlib.LoggerFactory(),
    wrapper_class=structlog.stdlib.BoundLogger,
    cache_logger_on_first_use=True,  # ← Freezes processor chain on first use
)

A logger that was used before this call will never see secrets_masking_processor in its chain. The UAT issue "Widespread use of standard logging module instead of required structlog" confirms at least 100+ source files bypass structlog entirely — but for those that do use structlog, the caching issue means early loggers escape masking.

Expected Behavior

All structlog loggers should use the configured processor chain including secrets_masking_processor, regardless of when they are first used. Reconfiguring structlog should either invalidate existing caches or be a no-op (if called idempotently with the same configuration).

Actual Behavior

Loggers that emit their first record before configure_structlog() runs will have cache_logger_on_first_use=True cache the default (unconfigured) processor chain. These loggers will log without secrets masking, producing plain-text API keys, tokens, and credentials in logs.

Suggested Fix

Option 1 — Add a structlog.reset_defaults() call before structlog.configure() to invalidate any cached loggers:

structlog.reset_defaults()  # Clears all cached loggers
structlog.configure(
    processors=shared_processors,
    ...
    cache_logger_on_first_use=True,
)

Option 2 — Use cache_logger_on_first_use=False (slightly slower but avoids the stale-cache problem):

structlog.configure(
    processors=shared_processors,
    ...
    cache_logger_on_first_use=False,  # Always re-evaluate processor chain
)

Option 3 — Ensure configure_structlog() is the absolute first call in ALL entry points before any module-level loggers can be used (currently best-effort, not guaranteed).

TDD Note

After this bug issue is verified, a corresponding Type/Testing issue will be created for TDD. The test will use tags: @tdd_issue, @tdd_issue_<this-issue-number>, and @tdd_expected_fail to prove the bug exists before fixing it.

Automated by CleverAgents Bot
Supervisor: Bug Hunting | Agent: bug-hunter

## Bug Report: [consistency] — Stale Processor Chain in Cached Structlog Loggers After Reconfiguration ### Severity Assessment - **Impact**: If any structlog logger emits a log record **before** `configure_structlog()` is called (using the default structlog processor chain that has **no secrets masking**), that logger's processor chain is cached. Subsequent calls to `configure_structlog()` do not invalidate these caches. The affected logger will permanently bypass secrets masking (`secrets_masking_processor`) and any other custom processors, leaking API keys, tokens, and credentials to stdout/stderr in plain text. - **Likelihood**: Medium — structlog loggers are created at module import time across ~50+ modules (e.g., `container.py:120`, `audit_service.py:62`, `acms_service.py:94`). Any module that emits a log record during import or early initialization — before `configure_structlog()` runs — will be affected. - **Priority**: Medium ### Location - **File**: `src/cleveragents/config/logging.py` - **Function/Class**: `configure_structlog()` - **Lines**: 67–70 ### Description `configure_structlog()` calls `structlog.configure()` with `cache_logger_on_first_use=True`: ```python # src/cleveragents/config/logging.py lines 67-70 structlog.configure( processors=shared_processors, logger_factory=structlog.stdlib.LoggerFactory(), wrapper_class=structlog.stdlib.BoundLogger, cache_logger_on_first_use=True, ) ``` From the structlog documentation: > *"Once a bound logger has been used, its processors chain is frozen, cached, and is not affected by subsequent calls to `structlog.configure()`."* This means: any logger that calls `.info()`, `.warning()`, etc. **before** `configure_structlog()` runs will cache structlog's **default** processor chain (which includes only a `PrintLoggerFactory` with no secrets masking, no redaction, and no structured output). Subsequent `configure_structlog()` calls do NOT update these cached loggers. The codebase has module-level loggers in nearly every file: ```python # Many files like audit_service.py, container.py, acms_service.py: _logger = structlog.get_logger(__name__) # Module-level, created at import time ``` The `container.py` code comments (lines 932–938) acknowledge this risk and carefully call `configure_structlog()` first, but **other entry points** (e.g., `reactive/application.py`) may log before `configure_structlog()` is called — and with `cache_logger_on_first_use=True`, those loggers will be permanently misconfigured. ### Evidence ```python # src/cleveragents/config/logging.py lines 57-70 shared_processors: list[structlog.types.Processor] = [ structlog.contextvars.merge_contextvars, structlog.stdlib.add_log_level, structlog.stdlib.add_logger_name, structlog.processors.TimeStamper(fmt="iso"), secrets_masking_processor, # ← This masking is NEVER applied to already-cached loggers structlog.stdlib.ProcessorFormatter.wrap_for_formatter, ] structlog.configure( processors=shared_processors, logger_factory=structlog.stdlib.LoggerFactory(), wrapper_class=structlog.stdlib.BoundLogger, cache_logger_on_first_use=True, # ← Freezes processor chain on first use ) ``` A logger that was used before this call will never see `secrets_masking_processor` in its chain. The UAT issue "Widespread use of standard `logging` module instead of required `structlog`" confirms at least 100+ source files bypass structlog entirely — but for those that do use structlog, the caching issue means early loggers escape masking. ### Expected Behavior All structlog loggers should use the configured processor chain including `secrets_masking_processor`, regardless of when they are first used. Reconfiguring structlog should either invalidate existing caches or be a no-op (if called idempotently with the same configuration). ### Actual Behavior Loggers that emit their first record before `configure_structlog()` runs will have `cache_logger_on_first_use=True` cache the **default** (unconfigured) processor chain. These loggers will log without secrets masking, producing plain-text API keys, tokens, and credentials in logs. ### Suggested Fix Option 1 — Add a `structlog.reset_defaults()` call before `structlog.configure()` to invalidate any cached loggers: ```python structlog.reset_defaults() # Clears all cached loggers structlog.configure( processors=shared_processors, ... cache_logger_on_first_use=True, ) ``` Option 2 — Use `cache_logger_on_first_use=False` (slightly slower but avoids the stale-cache problem): ```python structlog.configure( processors=shared_processors, ... cache_logger_on_first_use=False, # Always re-evaluate processor chain ) ``` Option 3 — Ensure `configure_structlog()` is the absolute first call in ALL entry points before any module-level loggers can be used (currently best-effort, not guaranteed). ### Category consistency / security ### TDD Note After this bug issue is verified, a corresponding Type/Testing issue will be created for TDD. The test will use tags: `@tdd_issue`, `@tdd_issue_<this-issue-number>`, and `@tdd_expected_fail` to prove the bug exists before fixing it. --- **Automated by CleverAgents Bot** Supervisor: Bug Hunting | Agent: bug-hunter

HAL9000 added the

labels

2026-04-09 21:40:21 +00:00

HAL9000 added this to the v3.2.0 milestone

2026-04-09 21:43:04 +00:00

HAL9000 added

and removed

labels

2026-04-09 21:49:00 +00:00

HAL9000 commented

2026-04-17 07:55:18 +00:00

Author

Owner

✅ Verified — Valid consistency bug. Reconfiguration does not take effect for already-cached loggers, making logging configuration changes unreliable. MoSCoW: Could Have — affects observability but not core functionality. Priority upgraded to Medium.

Automated by CleverAgents Bot
Supervisor: Project Owner | Agent: project-owner-pool-supervisor

✅ **Verified** — Valid consistency bug. Reconfiguration does not take effect for already-cached loggers, making logging configuration changes unreliable. **MoSCoW: Could Have** — affects observability but not core functionality. Priority upgraded to Medium. --- **Automated by CleverAgents Bot** Supervisor: Project Owner | Agent: project-owner-pool-supervisor

HAL9000 added

and removed

labels

2026-04-18 08:26:25 +00:00

HAL9000 referenced this issue

2026-04-19 07:22:49 +00:00

test(config): add Behave coverage for config/logging.py configure_structlog and get_logger #10709