fix: logging overhaul — Alembic fileConfig disable_existing_loggers=False, propagate=False on loggers, ADR docs, catch-up migration for missing columns, sqlparse dep, build archive naming

This commit is contained in:
2026-05-27 11:19:12 +03:00
parent 614bf9123a
commit 143ab15744
5 changed files with 109 additions and 17 deletions

View File

@@ -20,6 +20,18 @@ if "DATABASE_URL" in os.environ:
# Interpret the config file for Python logging.
# This line sets up loggers basically.
# @ADR [LOG-001] disable_existing_loggers=False
# @RATIONALE Python 3.13's logging.config.fileConfig() defaults to
# disable_existing_loggers=True, which sets logger.disabled = True on ALL
# existing loggers not listed in alembic.ini's [loggers] section. This
# includes our 'superset_tools_app' and 'cot' loggers. With disabled=True,
# Logger.isEnabledFor() immediately returns False (see Python 3.13 source),
# silently dropping every logger.info()/warning()/error() call across the
# entire application. The SS-TOOLS logging system manages its own handlers
# via configure_logger() — Alembic's INI-based config is irrelevant here.
# @REJECTED Adding superset_tools_app to alembic.ini [loggers] was rejected
# because it couples app logging config to Alembic's ini format, which is
# fragile and non-obvious for future maintainers.
if config.config_file_name is not None:
fileConfig(config.config_file_name, disable_existing_loggers=False)

View File

@@ -0,0 +1,52 @@
"""add missing columns policy_id provider_id is_multimodal
@ADR [LOG-003] Catch-up migration for columns added in inserted revisions.
@RATIONALE Migrations 9f8e7d6c5b4a (is_multimodal), a7b1c2d3e4f5 (provider_id),
and b1c2d3e4f5a6 (policy_id) were inserted into the chain before the
existing head 86c7b1d6a710. Databases already at 86c7b1d6a710 skip them
because Alembic sees no gap between current and target revision.
This migration adds the same columns with 86c7b1d6a710 as parent, so
it runs on both fresh and pre-stamped databases.
Revision ID: 2df63b7ce038
Revises: 86c7b1d6a710
Create Date: 2026-05-27 11:17:26.789634
"""
from typing import Sequence, Union
from alembic import op
import sqlalchemy as sa
# revision identifiers, used by Alembic.
revision: str = '2df63b7ce038'
down_revision: Union[str, Sequence[str], None] = '86c7b1d6a710'
branch_labels: Union[str, Sequence[str], None] = None
depends_on: Union[str, Sequence[str], None] = None
def upgrade() -> None:
"""Upgrade schema."""
# Add is_multimodal to llm_providers (from 9f8e7d6c5b4a)
op.add_column("llm_providers",
sa.Column("is_multimodal", sa.Boolean(), nullable=False, server_default="false")
)
op.alter_column("llm_providers", "is_multimodal", server_default=None)
# Add provider_id to validation_policies (from a7b1c2d3e4f5)
op.add_column("validation_policies",
sa.Column("provider_id", sa.String(), nullable=True)
)
# Add policy_id to llm_validation_results (from b1c2d3e4f5a6)
op.add_column("llm_validation_results",
sa.Column("policy_id", sa.String(), nullable=True, index=True)
)
def downgrade() -> None:
"""Downgrade schema."""
op.drop_column("llm_validation_results", "policy_id")
op.drop_column("validation_policies", "provider_id")
op.drop_column("llm_providers", "is_multimodal")

View File

@@ -57,5 +57,6 @@ playwright
tenacity
Pillow
ruff>=0.11.0
sqlparse>=0.5.0
lingua-language-detector==2.1.1
testcontainers[postgres]>=4.0

View File

@@ -6,9 +6,20 @@
# @RELATION DEPENDS_ON -> [WebSocketLogHandler]
# @PRE Python 3.7+ with cot_logger ContextVars available.
# @POST All log output is single-line JSON with ts, level, trace_id, src, marker, intent, payload, error, span_id.
# @SIDE_EFFECT Configures global logger handlers and formatters; seeds global _enable_belief_state and _task_log_level; writes JSON to console/files.
# @RATIONALE Replaced BeliefFormatter text-based [Entry]/[Exit]/[Action] logging with CotJsonFormatter JSON output. Old format was not machine-parseable and mixed presentation with intent. CotJsonFormatter produces structured JSON consistent with cot_logger.py MarkerLogger protocol.
# @REJECTED Keeping both formatters side-by-side was rejected (two inconsistent output formats would confuse log consumers).
# Both 'superset_tools_app' and 'cot' loggers have propagate=False — no text duplicates via root logger.
# @INVARIANT Every logger.info() call MUST produce exactly one JSON line (see [ADR LOG-002] for why).
# @SIDE_EFFECT Configures global logger handlers and formatters; seeds global _enable_belief_state
# and _task_log_level; sets propagate=False on both loggers; writes JSON to console/files.
# @RELATION DISABLED_BY -> [LOG-001:alembic/env.py:fileConfig]
# If alembic/env.py calls fileConfig() without disable_existing_loggers=False, Python 3.13's
# logging framework sets logger.disabled = True on 'superset_tools_app', silencing ALL output.
# @RATIONALE Replaced BeliefFormatter text-based [Entry]/[Exit]/[Action] logging with CotJsonFormatter
# JSON output. Old format was not machine-parseable and mixed presentation with intent. CotJsonFormatter
# produces structured JSON consistent with cot_logger.py MarkerLogger protocol.
# @REJECTED Keeping both formatters side-by-side was rejected (two inconsistent output formats would
# confuse log consumers).
# @REJECTED Keeping propagate=True was rejected after uvicorn's dictConfig added a root logger handler
# that duplicates every log as plain text (see [ADR LOG-002]).
# @DATA_CONTRACT All log records conform to molecular CoT JSON schema: {ts, level, trace_id, src, marker, intent, span_id?, payload?, error?}
# @INVARIANT CotJsonFormatter.format() always returns valid single-line JSON string.
from contextlib import contextmanager
@@ -162,8 +173,12 @@ def belief_scope(anchor_id: str, message: str = ""):
# @RELATION CALLS -> [CotJsonFormatter]
# @RELATION CALLS -> [CotLoggerModule]
# @PRE config is a valid LoggingConfig instance.
# @POST Logger levels, handlers, formatters, belief state flag, and task log level are updated.
# @SIDE_EFFECT Mutates global _enable_belief_state, _task_log_level; adds/removes handlers on both logger and cot_logger; creates file directories.
# @POST Logger levels, handlers, formatters, belief state flag, task log level, and
# propagate flags (False) are updated. Both loggers emit JSON only — no text duplicates.
# @SIDE_EFFECT Mutates global _enable_belief_state, _task_log_level; adds/removes handlers
# on both logger and cot_logger; sets propagate=False on both; creates file directories.
# @DATA_CONTRACT configure_logger() -> ENABLES both loggers. Every call to logger.info()
# MUST produce exactly one JSON line (not zero, not two). See [ADR LOG-001] and [ADR LOG-002].
def configure_logger(config):
global _enable_belief_state, _task_log_level
_enable_belief_state = config.enable_belief_state
@@ -206,9 +221,21 @@ def configure_logger(config):
cot_handler.setFormatter(CotJsonFormatter())
cot_logger.addHandler(cot_handler)
# Disable propagation to prevent duplicate output via uvicorn's root logger handlers.
# Both loggers have their own dedicated handlers; propagation would cause each message
# to appear twice: once via CotJsonFormatter (JSON) and once via uvicorn's DefaultFormatter (text).
# @ADR [LOG-002] Disable logger propagation to prevent duplicate output
# @RATIONALE Uvicorn's configure_logging() registers a StreamHandler on the root
# logger via logging.config.dictConfig(). Both 'superset_tools_app' and 'cot'
# loggers have their own dedicated handlers with CotJsonFormatter. With
# propagate=True (default), each log message is handled twice:
# 1. Our CotJsonFormatter → structured JSON (desired)
# 2. Propagated to root → uvicorn's DefaultFormatter → plain text (duplicate)
# Setting propagate=False prevents the second emission.
# @REJECTED Removing uvicorn's root logger handler via logging.getLogger().handlers = []
# was rejected because it couples SS-TOOLS to uvicorn's internal logging setup,
# which could change between uvicorn versions. Setting propagate on our own
# loggers is self-contained and version-safe.
# @REJECTED Overriding log level on root logger was rejected (root.setLevel(WARNING))
# because it would suppress legitimate warnings from third-party libraries
# (SQLAlchemy, Alembic, httpx, etc.).
logger.propagate = False
cot_logger.propagate = False
# #endregion configure_logger