From 143ab15744e01458d4fcb11497e29a538455e74b Mon Sep 17 00:00:00 2001 From: busya Date: Wed, 27 May 2026 11:19:12 +0300 Subject: [PATCH] =?UTF-8?q?fix:=20logging=20overhaul=20=E2=80=94=20Alembic?= =?UTF-8?q?=20fileConfig=20disable=5Fexisting=5Floggers=3DFalse,=20propaga?= =?UTF-8?q?te=3DFalse=20on=20loggers,=20ADR=20docs,=20catch-up=20migration?= =?UTF-8?q?=20for=20missing=20columns,=20sqlparse=20dep,=20build=20archive?= =?UTF-8?q?=20naming?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- backend/alembic/env.py | 12 +++++ ...add_missing_columns_policy_id_provider_.py | 52 +++++++++++++++++++ backend/requirements.txt | 1 + backend/src/core/logger.py | 43 ++++++++++++--- build.sh | 18 +++---- 5 files changed, 109 insertions(+), 17 deletions(-) create mode 100644 backend/alembic/versions/2df63b7ce038_add_missing_columns_policy_id_provider_.py diff --git a/backend/alembic/env.py b/backend/alembic/env.py index dd441729..34894bbd 100644 --- a/backend/alembic/env.py +++ b/backend/alembic/env.py @@ -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) diff --git a/backend/alembic/versions/2df63b7ce038_add_missing_columns_policy_id_provider_.py b/backend/alembic/versions/2df63b7ce038_add_missing_columns_policy_id_provider_.py new file mode 100644 index 00000000..1baa76d7 --- /dev/null +++ b/backend/alembic/versions/2df63b7ce038_add_missing_columns_policy_id_provider_.py @@ -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") diff --git a/backend/requirements.txt b/backend/requirements.txt index 92bc298d..eb34e24b 100755 --- a/backend/requirements.txt +++ b/backend/requirements.txt @@ -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 diff --git a/backend/src/core/logger.py b/backend/src/core/logger.py index 7169236c..f26461fb 100755 --- a/backend/src/core/logger.py +++ b/backend/src/core/logger.py @@ -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 diff --git a/build.sh b/build.sh index e8b5f19e..e13aa2fe 100755 --- a/build.sh +++ b/build.sh @@ -225,14 +225,14 @@ bundle_release() { echo "[bundle] Exporting .tar.xz archives..." echo "[bundle] Compressing backend image..." - docker save "${backend_tag}" | xz -T0 -6 > "${DIST_ROOT}/backend.${tag}.tar.xz" + docker save "${backend_tag}" | xz -T0 -6 > "${DIST_ROOT}/ss-tools-backend.${tag}.tar.xz" echo "[bundle] Compressing frontend image..." - docker save "${frontend_tag}" | xz -T0 -6 > "${DIST_ROOT}/frontend.${tag}.tar.xz" + docker save "${frontend_tag}" | xz -T0 -6 > "${DIST_ROOT}/ss-tools-frontend.${tag}.tar.xz" echo "[bundle] Calculating checksums..." ( cd "${DIST_ROOT}" - sha256sum "backend.${tag}.tar.xz" "frontend.${tag}.tar.xz" > "sha256sums.${tag}.txt" + sha256sum "ss-tools-backend.${tag}.tar.xz" "ss-tools-frontend.${tag}.tar.xz" > "sha256sums.${tag}.txt" ) local backend_id frontend_id @@ -290,11 +290,11 @@ release_tag=${tag} backend_image=${backend_tag} backend_image_id=${backend_id} backend_repo_digest=${backend_digest} -backend_archive=backend.${tag}.tar.xz +backend_archive=ss-tools-backend.${tag}.tar.xz frontend_image=${frontend_tag} frontend_image_id=${frontend_id} frontend_repo_digest=${frontend_digest} -frontend_archive=frontend.${tag}.tar.xz +frontend_archive=ss-tools-frontend.${tag}.tar.xz compose_file=docker-compose.enterprise-clean.yml env_template=.env.enterprise-clean.example env_bootstrap_fields=INITIAL_ADMIN_CREATE,INITIAL_ADMIN_USERNAME,INITIAL_ADMIN_PASSWORD,INITIAL_ADMIN_EMAIL @@ -312,14 +312,14 @@ EOF "image": "${backend_tag}", "image_id": "${backend_id}", "repo_digest": "${backend_digest}", - "archive": "backend.${tag}.tar.xz" + "archive": "ss-tools-backend.${tag}.tar.xz" }, { "role": "frontend", "image": "${frontend_tag}", "image_id": "${frontend_id}", "repo_digest": "${frontend_digest}", - "archive": "frontend.${tag}.tar.xz" + "archive": "ss-tools-frontend.${tag}.tar.xz" } ], "compose_file": "docker-compose.enterprise-clean.yml", @@ -338,8 +338,8 @@ EOF echo "[bundle] ✅ Bundle created in ${DIST_ROOT}" echo " # Load images (decompress stream):" - echo " xz -dc ${DIST_ROOT}/backend.${tag}.tar.xz | docker load" - echo " xz -dc ${DIST_ROOT}/frontend.${tag}.tar.xz | docker load" + echo " xz -dc ${DIST_ROOT}/ss-tools-backend.${tag}.tar.xz | docker load" + echo " xz -dc ${DIST_ROOT}/ss-tools-frontend.${tag}.tar.xz | docker load" echo " # Edit .env.enterprise-clean.example -> .env.enterprise-clean, then:" echo " docker compose -f ${DIST_ROOT}/docker-compose.enterprise-clean.yml up" echo ""