ВМ1: реализован сбор логов

VM1_app/codebase/backend/bitrix-local-app/app/main.py

@@ -16,11 +16,13 @@ from typing import Annotated, Any, Literal
 from urllib.parse import quote, urlparse
 
 import httpx
+import structlog
 import uvicorn
 from cryptography.hazmat.primitives.ciphers.aead import AESGCM
 from fastapi import Depends, FastAPI, Header, HTTPException, Request
 from fastapi.exceptions import RequestValidationError
 from fastapi.responses import HTMLResponse, JSONResponse
+from opentelemetry import trace
 from pydantic import BaseModel, ConfigDict, Field, model_validator
 from pydantic_settings import BaseSettings, SettingsConfigDict
 from sqlalchemy import func, or_, select, text
@@ -37,9 +39,19 @@ from app.models import (
     PortalInstallation,
     now,
 )
+from app.logging_security import redact_event
 from app.postgres import create_postgres_engine
+from app.telemetry import (
+    TelemetryRuntime,
+    add_trace_context,
+    current_traceparent,
+    init_telemetry,
+    instrument_fastapi,
+    origin_links,
+)
 
-logger = logging.getLogger("bitrix-local-app")
+logger = structlog.get_logger("bitrix-local-app")
+EXPECTED_BITRIX_DB_REVISION = "0002_inbox_trace_context"
 
 BITRIX_SENDER_PREFIX = re.compile(
     r"^\[b\][^\r\n\[]+:\[/b\]\s*(?:\[br\]\s*)?",
@@ -57,6 +69,7 @@ CONNECTOR_ICON_DATA_URI = "data:image/svg+xml," + quote(
 class Settings(BaseSettings):
     model_config = SettingsConfigDict(extra="ignore")
     app_env: str = "production-like"
+    log_level: str = "INFO"
     bitrix_database_url: str
     bitrix_client_id: str
     bitrix_client_secret: str
@@ -78,6 +91,28 @@ class Settings(BaseSettings):
     bitrix_worker_poll_sec: float = Field(default=1, ge=0.05, le=30)
 
 
+def configure_logging(level: str, telemetry: TelemetryRuntime | None = None) -> None:
+    logging.basicConfig(level=level, format="%(message)s")
+    if telemetry and telemetry.logging_handler not in logging.getLogger().handlers:
+        telemetry.logging_handler.addFilter(
+            lambda record: not record.name.startswith("opentelemetry")
+        )
+        logging.getLogger().addHandler(telemetry.logging_handler)
+    structlog.configure(
+        processors=[
+            structlog.contextvars.merge_contextvars,
+            add_trace_context,
+            redact_event,
+            structlog.processors.TimeStamper(fmt="iso", utc=True, key="timestamp"),
+            structlog.stdlib.add_log_level,
+            structlog.processors.JSONRenderer(),
+        ],
+        logger_factory=structlog.stdlib.LoggerFactory(),
+        wrapper_class=structlog.stdlib.BoundLogger,
+        cache_logger_on_first_use=True,
+    )
+
+
 class TokenCipher:
     def __init__(self, encoded_key: str, version: str) -> None:
         try:
@@ -309,8 +344,8 @@ def normalize_event(payload: dict[str, Any]) -> dict[str, Any] | None:
                 normalized_file["_bitrix_file_id"] = str(file_id)
             if not normalized_file["download_url"] and not file_id:
                 logger.warning(
-                    "inbound file has no supported download reference; keys=%s",
-                    sorted(str(key) for key in item),
+                    "inbound_file.unsupported_reference",
+                    keys=sorted(str(key) for key in item),
                 )
             files.append(normalized_file)
         if not text_value and not files:
@@ -498,6 +533,8 @@ def create_app(settings: Settings | None = None) -> FastAPI:
 
     @asynccontextmanager
     async def lifespan(app: FastAPI):
+        telemetry = init_telemetry()
+        configure_logging(cfg.log_level, telemetry)
         engine = create_postgres_engine(
             cfg.bitrix_database_url,
             pool_size=5,
@@ -527,6 +564,8 @@ def create_app(settings: Settings | None = None) -> FastAPI:
                 await task
         await app.state.http.aclose()
         await engine.dispose()
+        if telemetry:
+            telemetry.shutdown()
 
     app = FastAPI(
         title="HAN Bitrix24 Local App",
@@ -540,9 +579,13 @@ def create_app(settings: Settings | None = None) -> FastAPI:
     @app.middleware("http")
     async def request_context(request: Request, call_next):
         request.state.request_id = request.headers.get("X-Request-ID") or str(uuid.uuid4())
-        response = await call_next(request)
-        response.headers["X-Request-ID"] = request.state.request_id
-        return response
+        with structlog.contextvars.bound_contextvars(
+            request_id=request.state.request_id,
+            **{"service.name": "bitrix-local-app"},
+        ):
+            response = await call_next(request)
+            response.headers["X-Request-ID"] = request.state.request_id
+            return response
 
     @app.exception_handler(HTTPException)
     async def http_error(_: Request, exc: HTTPException):
@@ -579,9 +622,22 @@ def create_app(settings: Settings | None = None) -> FastAPI:
             async with request.app.state.sessions() as session:
                 portal = await active_portal(session)
                 await session.scalar(select(func.now()))
+                revision = await session.scalar(
+                    text("SELECT version_num FROM bitrix_local.alembic_version")
+                )
             worker_ok = all(not task.done() for task in request.app.state.workers)
-            if portal and portal.install_status == "installed" and worker_ok:
+            if (
+                portal
+                and portal.install_status == "installed"
+                and worker_ok
+                and revision == EXPECTED_BITRIX_DB_REVISION
+            ):
                 return {"status": "ready", "portal": "installed", "workers": "running"}
+            if revision != EXPECTED_BITRIX_DB_REVISION:
+                return JSONResponse(
+                    {"status": "not_ready", "reason": "migration_required"},
+                    status_code=503,
+                )
             return JSONResponse(
                 {"status": "not_ready", "reason": "portal_not_installed"}, status_code=503
             )
@@ -655,7 +711,12 @@ def create_app(settings: Settings | None = None) -> FastAPI:
             normalized = normalize_event(payload)
             if normalized is None:
                 return {"status": "ignored"}
-            created = await save_inbox(request.app, normalized)
+            created = await save_inbox(
+                request.app,
+                normalized,
+                request.state.request_id,
+                current_traceparent(),
+            )
             return JSONResponse(
                 {"status": "accepted" if created else "duplicate"},
                 status_code=202 if created else 200,
@@ -731,6 +792,8 @@ def create_app(settings: Settings | None = None) -> FastAPI:
                     external_chat_id=dto.external_chat_id,
                     request_fingerprint=fp,
                     payload_json=body,
+                    request_id=request.state.request_id,
+                    traceparent=current_traceparent(),
                     status="sending",
                     lease_until=now() + timedelta(seconds=cfg.bitrix_http_timeout_sec + 5),
                 )
@@ -768,12 +831,10 @@ def create_app(settings: Settings | None = None) -> FastAPI:
             )
         except Exception as exc:
             logger.error(
-                "outbound delivery failed",
-                extra={
-                    "request_id": request.state.request_id,
-                    "message_id": str(dto.message_id),
-                    "error_type": type(exc).__name__,
-                },
+                "outbound.delivery_failed",
+                request_id=request.state.request_id,
+                message_id=str(dto.message_id),
+                error_type=type(exc).__name__,
             )
             async with request.app.state.sessions() as session:
                 current = await session.get(OutboundMessage, row.id, with_for_update=True)
@@ -845,6 +906,7 @@ def create_app(settings: Settings | None = None) -> FastAPI:
         result = await reconcile_setup(request.app)
         return {"status": "completed" if all(result.values()) else "partial", "steps": result}
 
+    instrument_fastapi(app)
     return app
 
 
@@ -960,7 +1022,12 @@ async def uninstall_payload(app: FastAPI, payload: dict[str, Any]) -> None:
             await session.commit()
 
 
-async def save_inbox(app: FastAPI, normalized: dict[str, Any]) -> bool:
+async def save_inbox(
+    app: FastAPI,
+    normalized: dict[str, Any],
+    request_id: str,
+    traceparent: str | None,
+) -> bool:
     fingerprint = hashlib.sha256(
         json.dumps(normalized, sort_keys=True, separators=(",", ":")).encode()
     ).hexdigest()
@@ -971,6 +1038,8 @@ async def save_inbox(app: FastAPI, normalized: dict[str, Any]) -> bool:
         bitrix_message_id=normalized["bitrix_message_id"],
         payload_fingerprint=fingerprint,
         normalized_json=normalized,
+        request_id=request_id,
+        traceparent=traceparent,
     )
     async with app.state.sessions() as session:
         session.add(row)
@@ -1168,8 +1237,9 @@ async def worker_loop(app: FastAPI, kind: str) -> None:
                 await process_setup(app)
         except Exception as exc:
             logger.error(
-                "worker iteration failed",
-                extra={"worker_kind": kind, "error_type": type(exc).__name__},
+                "worker.iteration_failed",
+                worker_kind=kind,
+                error_type=type(exc).__name__,
             )
         try:
             await asyncio.wait_for(app.state.stop.wait(), app.state.settings.bitrix_worker_poll_sec)
@@ -1182,45 +1252,57 @@ async def process_inbox(app: FastAPI) -> None:
         row = await claim_one(session, InboxEvent, ["received", "retry"])
     if not row:
         return
-    try:
-        payload = json.loads(json.dumps(row.normalized_json))
-        await resolve_inbound_file_urls(app, payload)
-        response = await app.state.http.post(
-            app.state.settings.bitrix_api_forward_url,
-            json=payload,
-            headers={
-                "Authorization": f"Bearer {app.state.settings.bitrix_api_forward_token}",
-                "X-Request-ID": str(uuid.uuid4()),
-            },
-            follow_redirects=False,
-        )
-        duplicate = response.status_code in {200, 204}
-        if response.status_code != 201 and not duplicate:
-            response.raise_for_status()
-        async with app.state.sessions() as session:
-            current = await session.get(InboxEvent, row.id, with_for_update=True)
-            current.status = "ack_pending"
-            current.api_ack_status = "duplicate" if duplicate else "created"
-            current.lease_until = None
-            session.add(
-                DeliveryAckOutbox(
-                    inbox_event_id=current.id,
-                    payload_json={
-                        "external_chat_id": str(current.external_chat_id),
-                        "bitrix_message_id": current.bitrix_message_id,
-                    },
-                )
+    tracer = trace.get_tracer("han.bitrix.inbox")
+    with (
+        tracer.start_as_current_span(
+            "bitrix.inbox.forward",
+            links=origin_links(row.traceparent),
+        ),
+        structlog.contextvars.bound_contextvars(
+            request_id=row.request_id,
+            inbox_id=str(row.id),
+            **{"service.name": "bitrix-local-app"},
+        ),
+    ):
+        try:
+            payload = json.loads(json.dumps(row.normalized_json))
+            await resolve_inbound_file_urls(app, payload)
+            response = await app.state.http.post(
+                app.state.settings.bitrix_api_forward_url,
+                json=payload,
+                headers={
+                    "Authorization": f"Bearer {app.state.settings.bitrix_api_forward_token}",
+                    "X-Request-ID": row.request_id or str(uuid.uuid4()),
+                },
+                follow_redirects=False,
             )
-            await session.commit()
-    except Exception as exc:
-        logger.error(
-            "inbound forward failed",
-            extra={
-                "inbox_id": str(row.id),
-                "error_type": type(exc).__name__,
-            },
-        )
-        await mark_retry(app, InboxEvent, row.id, "api_forward_failed")
+            duplicate = response.status_code in {200, 204}
+            if response.status_code != 201 and not duplicate:
+                response.raise_for_status()
+            async with app.state.sessions() as session:
+                current = await session.get(InboxEvent, row.id, with_for_update=True)
+                current.status = "ack_pending"
+                current.api_ack_status = "duplicate" if duplicate else "created"
+                current.lease_until = None
+                session.add(
+                    DeliveryAckOutbox(
+                        inbox_event_id=current.id,
+                        request_id=current.request_id,
+                        traceparent=current.traceparent,
+                        payload_json={
+                            "external_chat_id": str(current.external_chat_id),
+                            "bitrix_message_id": current.bitrix_message_id,
+                        },
+                    )
+                )
+                await session.commit()
+        except Exception as exc:
+            logger.error(
+                "inbound.forward_failed",
+                inbox_id=str(row.id),
+                error_type=type(exc).__name__,
+            )
+            await mark_retry(app, InboxEvent, row.id, "api_forward_failed")
 
 
 async def resolve_inbound_file_urls(app: FastAPI, payload: dict[str, Any]) -> None:
@@ -1252,27 +1334,41 @@ async def process_ack(app: FastAPI) -> None:
         portal = await active_portal(session)
     if not row or not portal:
         return
-    try:
-        await app.state.bitrix.call(
-            portal,
-            "imconnector.send.status.delivery",
-            {
-                "CONNECTOR": app.state.settings.bitrix_connector_id,
-                "LINE": app.state.settings.bitrix_open_line_id,
-                "MESSAGES[0][im][chat_id]": row.payload_json["external_chat_id"],
-                "MESSAGES[0][message][id]": row.payload_json["bitrix_message_id"] or "",
-            },
-        )
-        async with app.state.sessions() as session:
-            current = await session.get(DeliveryAckOutbox, row.id, with_for_update=True)
-            event = await session.get(InboxEvent, current.inbox_event_id, with_for_update=True)
-            current.status = "completed"
-            current.lease_until = None
-            event.status = "completed"
-            event.delivery_ack_status = "sent"
-            await session.commit()
-    except Exception:
-        await mark_retry(app, DeliveryAckOutbox, row.id, "delivery_ack_failed")
+    tracer = trace.get_tracer("han.bitrix.ack")
+    with (
+        tracer.start_as_current_span(
+            "bitrix.delivery_ack.process",
+            links=origin_links(row.traceparent),
+        ),
+        structlog.contextvars.bound_contextvars(
+            request_id=row.request_id,
+            ack_outbox_id=str(row.id),
+            **{"service.name": "bitrix-local-app"},
+        ),
+    ):
+        try:
+            await app.state.bitrix.call(
+                portal,
+                "imconnector.send.status.delivery",
+                {
+                    "CONNECTOR": app.state.settings.bitrix_connector_id,
+                    "LINE": app.state.settings.bitrix_open_line_id,
+                    "MESSAGES[0][im][chat_id]": row.payload_json["external_chat_id"],
+                    "MESSAGES[0][message][id]": row.payload_json["bitrix_message_id"] or "",
+                },
+            )
+            async with app.state.sessions() as session:
+                current = await session.get(DeliveryAckOutbox, row.id, with_for_update=True)
+                event = await session.get(
+                    InboxEvent, current.inbox_event_id, with_for_update=True
+                )
+                current.status = "completed"
+                current.lease_until = None
+                event.status = "completed"
+                event.delivery_ack_status = "sent"
+                await session.commit()
+        except Exception:
+            await mark_retry(app, DeliveryAckOutbox, row.id, "delivery_ack_failed")
 
 
 async def process_outbound(app: FastAPI) -> None:
@@ -1285,20 +1381,30 @@ async def process_outbound(app: FastAPI) -> None:
         )
     if not row:
         return
-    try:
-        await asyncio.wait_for(
-            deliver_outbound(app, row.id),
-            timeout=app.state.settings.bitrix_http_timeout_sec,
-        )
-    except Exception as exc:
-        logger.error(
-            "outbound retry failed",
-            extra={
-                "outbound_id": str(row.id),
-                "error_type": type(exc).__name__,
-            },
-        )
-        await mark_retry(app, OutboundMessage, row.id, "bitrix_delivery_failed")
+    tracer = trace.get_tracer("han.bitrix.outbound")
+    with (
+        tracer.start_as_current_span(
+            "bitrix.outbound.process",
+            links=origin_links(row.traceparent),
+        ),
+        structlog.contextvars.bound_contextvars(
+            request_id=row.request_id,
+            outbound_id=str(row.id),
+            **{"service.name": "bitrix-local-app"},
+        ),
+    ):
+        try:
+            await asyncio.wait_for(
+                deliver_outbound(app, row.id),
+                timeout=app.state.settings.bitrix_http_timeout_sec,
+            )
+        except Exception as exc:
+            logger.error(
+                "outbound.retry_failed",
+                outbound_id=str(row.id),
+                error_type=type(exc).__name__,
+            )
+            await mark_retry(app, OutboundMessage, row.id, "bitrix_delivery_failed")
 
 
 async def process_setup(app: FastAPI) -> None: