Добавлен сбор телеметрии на ВМ2

2026-08-26 15:12:51 +03:00
parent 728b9826a3
commit f989097484
32 changed files with 2029 additions and 134 deletions
@@ -5,10 +5,14 @@ import ssl
 from dataclasses import dataclass
 from datetime import UTC, datetime
 from enum import StrEnum
+from time import monotonic
 from typing import Any
 from urllib.parse import urljoin, urlsplit

 import httpx
+from opentelemetry.trace import SpanKind
+
+from app.telemetry import record_crm, record_retry, safe_span


 class CrmOutcome(StrEnum):
@@ -49,6 +53,28 @@ class CrmClient:
        await self._client.aclose()

    async def call(self, method: str, params: dict[str, Any], *, mutating: bool) -> CrmResult:
+        started = monotonic()
+        outcome = "error"
+        operation = method.rsplit(".", 1)[-1]
+        try:
+            with safe_span(
+                "bitrix_sync.crm.request",
+                kind=SpanKind.CLIENT,
+                attributes={"crm.operation": operation},
+            ):
+                result = await self._call(method, params, mutating=mutating)
+            outcome = result.outcome.value
+            if result.outcome in {
+                CrmOutcome.RETRY,
+                CrmOutcome.UNCERTAIN,
+                CrmOutcome.RATE_LIMITED,
+            }:
+                record_retry("crm")
+            return result
+        finally:
+            record_crm(method, outcome, monotonic() - started)
+
+    async def _call(self, method: str, params: dict[str, Any], *, mutating: bool) -> CrmResult:
        if method not in ALLOWED_METHODS:
            raise ValueError("unapproved CRM method")
        url = urljoin(self._base_url, method + ".json")
@@ -20,6 +20,13 @@ from app.domain import (
    validate_phone,
 )
 from app.repository import LeasedTask, LeasedWebhook, Profile, Repository
+from app.telemetry import (
+    record_business_alert,
+    record_dead_letter,
+    record_limiter,
+    record_retry,
+    record_transition,
+)

 INSERT_CRM_COMMAND = text(
    """
@@ -81,6 +88,7 @@ class WorkflowEngine:
            await self._manual(workflow_id, exc.code, task.user_id)
            await self.repository.complete_task(task, workflow_id)
        except RetryableWorkflow as exc:
+            record_retry("task")
            delay = exc.retry_after or full_jitter_delay(
                task.attempt_count + 1,
                self.settings.retry_base_seconds,
@@ -508,10 +516,12 @@ class WorkflowEngine:
            )
            if limiter_delay <= 0:
                break
+            record_limiter(limiter_delay)
            await asyncio.sleep(limiter_delay)
        async with self._in_flight:
            result = await self.crm.call(method, params, mutating=mutating)
        status = result.outcome.value
+        record_transition("command", status)
        async with self.repository.transaction() as connection:
            await connection.execute(
                UPDATE_CRM_COMMAND,
@@ -580,6 +590,7 @@ class WorkflowEngine:
        *,
        selected_external_id: str | None = None,
    ) -> None:
+        record_business_alert(alert_type)
        fingerprint = safe_hash(f"{alert_type}:{user_id}")
        assert fingerprint is not None
        async with self.repository.transaction() as connection:
@@ -727,6 +738,7 @@ class WorkflowEngine:
            )

    async def _technical_failure(self, workflow_id: uuid.UUID, code: str) -> None:
+        record_dead_letter("crm_command")
        async with self.repository.transaction() as connection:
            await connection.execute(
                text(
@@ -12,20 +12,38 @@ from sqlalchemy import text
 from app.config import Settings, load_settings
 from app.repository import Repository
 from app.security import WebhookValidationError, parse_bounded_form, validate_webhook
+from app.telemetry import (
+    init_telemetry,
+    instrument_fastapi,
+    log_event,
+    record_webhook,
+    shutdown_telemetry,
+)


@asynccontextmanager
 async def lifespan(app: FastAPI):
-    settings = load_settings()
-    app.state.settings = settings
-    app.state.repository = (
-        Repository(settings.database_url.get_secret_value(), settings.db_pool_size)
-        if settings.enabled and settings.database_url
-        else None
-    )
-    yield
-    if app.state.repository:
-        await app.state.repository.close()
+    init_telemetry("bitrix-sync-api")
+    app.state.repository = None
+    try:
+        settings = load_settings()
+        app.state.settings = settings
+        app.state.repository = (
+            Repository(settings.database_url.get_secret_value(), settings.db_pool_size)
+            if settings.enabled and settings.database_url
+            else None
+        )
+        log_event(
+            "service.started",
+            "Bitrix sync API started",
+            attributes={"mode": settings.mode},
+        )
+        yield
+    finally:
+        if app.state.repository:
+            await app.state.repository.close()
+        log_event("service.stopped", "Bitrix sync API stopped")
+        shutdown_telemetry()


 app = FastAPI(
@@ -35,6 +53,7 @@ app = FastAPI(
    redoc_url=None,
    lifespan=lifespan,
 )
+instrument_fastapi(app)


 def settings(request: Request) -> Settings:
@@ -107,29 +126,30 @@ async def alert_webhook(


 async def _receive(request: Request, receiver: str, query: dict[str, str]) -> Response:
-    config = settings(request)
-    if not config.enabled:
-        raise HTTPException(status_code=503, detail="sync_disabled")
-    if request.headers.get("content-type", "").split(";", 1)[0].lower() != (
-        "application/x-www-form-urlencoded"
-    ):
-        raise HTTPException(status_code=400, detail="invalid_content_type")
-    content_length = request.headers.get("content-length")
-    if content_length and (
-        not content_length.isdigit() or int(content_length) > config.webhook_max_body_bytes
-    ):
-        raise HTTPException(status_code=413, detail="body_too_large")
-    body = await request.body()
-    if len(body) > config.webhook_max_body_bytes:
-        raise HTTPException(status_code=413, detail="body_too_large")
-    form = parse_bounded_form(body, max_fields=config.webhook_max_fields)
-    # The container is reachable only from the trusted VM2 nginx network.
-    # nginx overwrites X-Real-IP from the TCP peer after its CIDR check.
-    source_ip = request.headers.get("x-real-ip") or (request.client.host if request.client else "")
-    alert_entity_type_id = (
-        await _alert_entity_type(repository(request)) if receiver == "alert" else None
-    )
    try:
+        config = settings(request)
+        if not config.enabled:
+            raise HTTPException(status_code=503, detail="sync_disabled")
+        if request.headers.get("content-type", "").split(";", 1)[0].lower() != (
+            "application/x-www-form-urlencoded"
+        ):
+            raise HTTPException(status_code=400, detail="invalid_content_type")
+        content_length = request.headers.get("content-length")
+        if content_length and (
+            not content_length.isdigit() or int(content_length) > config.webhook_max_body_bytes
+        ):
+            raise HTTPException(status_code=413, detail="body_too_large")
+        body = await request.body()
+        if len(body) > config.webhook_max_body_bytes:
+            raise HTTPException(status_code=413, detail="body_too_large")
+        form = parse_bounded_form(body, max_fields=config.webhook_max_fields)
+        # nginx overwrites X-Real-IP from the TCP peer after its CIDR check.
+        source_ip = request.headers.get("x-real-ip") or (
+            request.client.host if request.client else ""
+        )
+        alert_entity_type_id = (
+            await _alert_entity_type(repository(request)) if receiver == "alert" else None
+        )
        event = validate_webhook(
            receiver,
            query,
@@ -139,12 +159,21 @@ async def _receive(request: Request, receiver: str, query: dict[str, str]) -> Re
            alert_entity_type_id=alert_entity_type_id,
        )
    except PermissionError as exc:
+        record_webhook(receiver, "rejected")
        raise HTTPException(status_code=403, detail="forbidden") from exc
    except WebhookValidationError as exc:
+        record_webhook(receiver, "rejected")
        raise HTTPException(status_code=400, detail="malformed_webhook") from exc
+    except HTTPException:
+        record_webhook(receiver, "rejected")
+        raise
+    except Exception:
+        record_webhook(receiver, "error")
+        raise
    await repository(request).insert_webhook(
        event.receiver_type, event.event_type, event.entity_id, event.source_ip
    )
+    record_webhook(receiver, "accepted")
    return Response(status_code=202)


@@ -170,4 +199,5 @@ def run() -> None:
        host="0.0.0.0",  # noqa: S104 - container-only port, not host-published
        port=8080,
        proxy_headers=False,
+        access_log=False,
    )
@@ -2,6 +2,7 @@ from __future__ import annotations

 import asyncio
 from datetime import UTC, datetime, timedelta
+from time import monotonic
 from typing import Any

 from sqlalchemy import text
@@ -9,6 +10,13 @@ from sqlalchemy import text
 from app.config import load_settings
 from app.crm import CrmClient, CrmOutcome
 from app.repository import Repository
+from app.telemetry import (
+    init_telemetry,
+    log_event,
+    record_reconciliation,
+    safe_span,
+    shutdown_telemetry,
+)


 class IncrementalReconciler:
@@ -127,25 +135,44 @@ class IncrementalReconciler:


 async def reconciliation_main() -> None:
-    settings = load_settings()
-    if not settings.enabled:
-        return
-    assert settings.database_url and settings.crm_rest_webhook_url and settings.portal_host
-    assert settings.contact_registered_field
-    repository = Repository(settings.database_url.get_secret_value(), settings.db_pool_size)
-    crm = CrmClient(
-        settings.crm_rest_webhook_url.get_secret_value(),
-        settings.portal_host,
-        settings.http_timeout_sec,
-    )
-    reconciler = IncrementalReconciler(
-        repository, crm, settings.rest_field_name(settings.contact_registered_field)
-    )
+    init_telemetry("bitrix-sync-reconciliation")
+    repository: Repository | None = None
+    crm: CrmClient | None = None
+    started = monotonic()
+    outcome = "error"
+    count = 0
    try:
-        await reconciler.run_once(settings.reconciliation_overlap_seconds)
+        settings = load_settings()
+        if not settings.enabled:
+            outcome = "skipped"
+            log_event("reconciliation.disabled", "Bitrix sync reconciliation is disabled")
+            return
+        assert settings.database_url and settings.crm_rest_webhook_url and settings.portal_host
+        assert settings.contact_registered_field
+        repository = Repository(settings.database_url.get_secret_value(), settings.db_pool_size)
+        crm = CrmClient(
+            settings.crm_rest_webhook_url.get_secret_value(),
+            settings.portal_host,
+            settings.http_timeout_sec,
+        )
+        reconciler = IncrementalReconciler(
+            repository, crm, settings.rest_field_name(settings.contact_registered_field)
+        )
+        with safe_span("bitrix_sync.reconciliation.run"):
+            count = await reconciler.run_once(settings.reconciliation_overlap_seconds)
+        outcome = "success"
+        log_event(
+            "reconciliation.completed",
+            "Bitrix sync reconciliation completed",
+            attributes={"scanned_count": count},
+        )
    finally:
-        await crm.close()
-        await repository.close()
+        record_reconciliation(outcome, count, started)
+        if crm is not None:
+            await crm.close()
+        if repository is not None:
+            await repository.close()
+        shutdown_telemetry()


 def run() -> None:
@@ -13,6 +13,7 @@ from sqlalchemy import text
 from sqlalchemy.ext.asyncio import AsyncConnection, AsyncEngine, create_async_engine

 from app.domain import safe_hash
+from app.telemetry import record_status_snapshot


 def postgres_ssl_context() -> ssl.SSLContext:
@@ -541,6 +542,10 @@ class Repository:
                "SELECT status, count(*) count "
                "FROM bitrix_sync.crm_commands GROUP BY status"
            ),
+            "queue_oldest_age_seconds": (
+                "SELECT coalesce(extract(epoch from now()-min(created_at)),0) "
+                "FROM han_app.sync_queue WHERE status IN ('pending','retry_wait','leased')"
+            ),
            "webhook_lag_seconds": (
                "SELECT coalesce(extract(epoch from now()-min(received_at)),0) "
                "FROM bitrix_sync.webhook_inbox WHERE status IN ('received','retry_wait')"
@@ -559,4 +564,5 @@ class Repository:
                else:
                    output[key] = result.scalar_one_or_none()
        output["generated_at"] = datetime.now(UTC).isoformat()
+        record_status_snapshot(output)
        return output
@@ -0,0 +1,514 @@
+from __future__ import annotations
+
+import json
+import logging
+import os
+import re
+import sys
+from collections.abc import Iterator, Mapping
+from contextlib import contextmanager
+from dataclasses import dataclass
+from datetime import UTC, datetime
+from time import monotonic
+from typing import Any
+
+from fastapi import FastAPI
+from opentelemetry import metrics, trace
+from opentelemetry.exporter.otlp.proto.grpc._log_exporter import OTLPLogExporter
+from opentelemetry.exporter.otlp.proto.grpc.metric_exporter import OTLPMetricExporter
+from opentelemetry.exporter.otlp.proto.grpc.trace_exporter import OTLPSpanExporter
+from opentelemetry.instrumentation.fastapi import FastAPIInstrumentor
+from opentelemetry.instrumentation.httpx import HTTPXClientInstrumentor
+from opentelemetry.instrumentation.sqlalchemy import SQLAlchemyInstrumentor
+from opentelemetry.propagate import set_global_textmap
+from opentelemetry.sdk._logs import LoggerProvider, LoggingHandler
+from opentelemetry.sdk._logs.export import BatchLogRecordProcessor
+from opentelemetry.sdk.metrics import MeterProvider
+from opentelemetry.sdk.metrics.export import PeriodicExportingMetricReader
+from opentelemetry.sdk.resources import Resource
+from opentelemetry.sdk.trace import TracerProvider
+from opentelemetry.sdk.trace.export import BatchSpanProcessor
+from opentelemetry.trace import SpanKind, Status, StatusCode
+from opentelemetry.trace.propagation.tracecontext import TraceContextTextMapPropagator
+
+SERVICE_NAMES = frozenset(
+    {"bitrix-sync-api", "bitrix-sync-worker", "bitrix-sync-reconciliation"}
+)
+_SECRET_KEYS = re.compile(
+    r"(authorization|cookie|token|secret|password|phone|email|full.?name|"
+    r"message|payload|body|query|url|dsn|statement|object.?key|filename)",
+    re.IGNORECASE,
+)
+_SENSITIVE_VALUES = (
+    re.compile(r"(?i)\bbearer\s+\S+"),
+    re.compile(r"(?i)\b(?:token|password|secret|code)=\S+"),
+    re.compile(r"https?://[^\s?#]+[?#]\S+"),
+    re.compile(r"\b[A-Za-z0-9_-]{20,}\.[A-Za-z0-9_-]{20,}\.[A-Za-z0-9_-]{10,}\b"),
+    re.compile(r"\b[\w.+-]+@[\w.-]+\.[A-Za-z]{2,}\b"),
+    re.compile(r"(?<!\w)\+?\d[\d ()-]{8,}\d(?!\w)"),
+)
+_SAFE_CODES = frozenset(
+    {
+        "success",
+        "retry",
+        "uncertain",
+        "permanent",
+        "rate_limited",
+        "error",
+        "disabled",
+        "skipped",
+    }
+)
+_SAFE_TASK_TYPES = frozenset(
+    {"contact.map_or_create", "contact.update", "contact.deactivate", "contact.webhook", "rebind"}
+)
+_SAFE_RECEIVERS = frozenset({"contact", "alert", "unknown"})
+_SAFE_CRM_OPERATIONS = frozenset({"batch", "get", "add", "update", "list", "findbycomm"})
+_SAFE_QUEUE_STATES = frozenset(
+    {"pending", "retry_wait", "leased", "processed", "received", "processing", "failed"}
+)
+_SAFE_ALERT_TYPES = frozenset(
+    {
+        "duplicate_contacts",
+        "contact_owned_by_other_user",
+        "mapping_identity_mismatch",
+        "rebind_target_owned",
+        "unknown_citizenship_enum",
+        "technical_configuration_failure",
+    }
+)
+_configured_service_name = "bitrix-sync-api"
+_runtime: TelemetryRuntime | None = None
+_logging_configured = False
+
+
+def _safe_scalar(value: Any) -> Any:
+    if value is None or isinstance(value, (bool, int, float)):
+        return value
+    text = str(value)
+    for pattern in _SENSITIVE_VALUES:
+        text = pattern.sub("[REDACTED]", text)
+    return text[:512]
+
+
+def redact(value: Any, *, key: str = "") -> Any:
+    """Return a bounded telemetry-safe copy without mutating application data."""
+    if key and _SECRET_KEYS.search(key):
+        return "[REDACTED]"
+    if isinstance(value, Mapping):
+        return {
+            str(item_key)[:64]: redact(item, key=str(item_key))
+            for item_key, item in value.items()
+        }
+    if isinstance(value, (list, tuple, set, frozenset)):
+        return [redact(item) for item in list(value)[:32]]
+    return _safe_scalar(value)
+
+
+def _trace_fields() -> dict[str, str]:
+    context = trace.get_current_span().get_span_context()
+    if not context.is_valid:
+        return {}
+    return {
+        "trace_id": format(context.trace_id, "032x"),
+        "span_id": format(context.span_id, "016x"),
+    }
+
+
+class JsonFormatter(logging.Formatter):
+    def format(self, record: logging.LogRecord) -> str:
+        event = {
+            "timestamp": (
+                datetime.now(UTC).isoformat(timespec="milliseconds").replace("+00:00", "Z")
+            ),
+            "level": record.levelname,
+            "service.name": _configured_service_name,
+            "service.version": os.getenv("RELEASE_VERSION", "unknown"),
+            "environment": os.getenv("APP_ENV", "production-like"),
+            "module": record.name,
+            "event": getattr(
+                record,
+                "event_name",
+                "log",
+            ),
+            "message": record.getMessage(),
+            **_trace_fields(),
+        }
+        attributes = getattr(record, "telemetry_attributes", None)
+        if isinstance(attributes, Mapping):
+            event.update(attributes)
+        if record.exc_info:
+            event["error.type"] = record.exc_info[0].__name__
+        return json.dumps(redact(event), ensure_ascii=False, separators=(",", ":"), default=str)
+
+
+class RedactionFilter(logging.Filter):
+    def filter(self, record: logging.LogRecord) -> bool:
+        record.msg = redact(record.getMessage()) if hasattr(record, "event_name") else "[REDACTED]"
+        record.args = ()
+        attributes = getattr(record, "telemetry_attributes", None)
+        safe_attributes = dict(attributes) if isinstance(attributes, Mapping) else {}
+        if record.exc_info:
+            safe_attributes["error.type"] = record.exc_info[0].__name__
+            record.exc_info = None
+            record.exc_text = None
+        record.telemetry_attributes = redact(safe_attributes)
+        return True
+
+
+class RedactingBatchSpanProcessor(BatchSpanProcessor):
+    """Remove sensitive auto-instrumentation attributes before queueing/export."""
+
+    def on_end(self, span: Any) -> None:
+        attributes = getattr(span, "_attributes", None)
+        if isinstance(attributes, Mapping):
+            sanitized = dict(attributes)
+            for key in list(sanitized):
+                key_text = str(key)
+                if _SECRET_KEYS.search(key_text) or key_text in {
+                    "http.target",
+                    "url.full",
+                    "db.statement",
+                }:
+                    sanitized[key] = "[REDACTED]"
+                else:
+                    sanitized[key] = _safe_scalar(sanitized[key])
+            span._attributes = sanitized
+        super().on_end(span)
+
+
+@dataclass(slots=True)
+class TelemetryRuntime:
+    tracer_provider: TracerProvider | None = None
+    meter_provider: MeterProvider | None = None
+    logger_provider: LoggerProvider | None = None
+
+    def shutdown(self) -> None:
+        for provider in (self.logger_provider, self.meter_provider, self.tracer_provider):
+            if provider is None:
+                continue
+            try:
+                provider.shutdown()
+            except Exception:
+                logging.getLogger(__name__).warning(
+                    "Telemetry shutdown failed",
+                    extra={"event_name": "telemetry.shutdown.failed"},
+                )
+
+
+def _resource(service_name: str) -> Resource:
+    return Resource.create(
+        {
+            "service.name": service_name,
+            "service.namespace": "han-chat",
+            "service.version": os.getenv("RELEASE_VERSION", "unknown"),
+            "deployment.environment": os.getenv("APP_ENV", "production-like"),
+        }
+    )
+
+
+def _configure_stdout(service_name: str) -> None:
+    global _configured_service_name, _logging_configured
+    _configured_service_name = service_name
+    if _logging_configured:
+        return
+    handler = logging.StreamHandler(sys.stdout)
+    handler.setFormatter(JsonFormatter())
+    handler.addFilter(RedactionFilter())
+    root = logging.getLogger()
+    root.addHandler(handler)
+    level_name = os.getenv("LOG_LEVEL", "INFO").upper()
+    root.setLevel(getattr(logging, level_name, logging.INFO))
+    _logging_configured = True
+
+
+def init_telemetry(service_name: str) -> TelemetryRuntime:
+    """Initialize all signals; exporter failures never stop the business process."""
+    global _runtime
+    if service_name not in SERVICE_NAMES:
+        raise ValueError("unregistered bitrix-sync process service.name")
+    _configure_stdout(service_name)
+    if _runtime is not None:
+        return _runtime
+    runtime = TelemetryRuntime()
+    _runtime = runtime
+    endpoint = os.getenv("OTEL_EXPORTER_OTLP_ENDPOINT", "").strip()
+    if not endpoint:
+        return runtime
+
+    try:
+        resource = _resource(service_name)
+        insecure = endpoint.startswith("http://")
+        set_global_textmap(TraceContextTextMapPropagator())
+
+        tracer_provider = TracerProvider(resource=resource)
+        tracer_provider.add_span_processor(
+            RedactingBatchSpanProcessor(
+                OTLPSpanExporter(endpoint=endpoint, insecure=insecure, timeout=3),
+                max_queue_size=2048,
+                schedule_delay_millis=5000,
+                max_export_batch_size=512,
+                export_timeout_millis=3000,
+            )
+        )
+        trace.set_tracer_provider(tracer_provider)
+        runtime.tracer_provider = tracer_provider
+
+        metric_reader = PeriodicExportingMetricReader(
+            OTLPMetricExporter(endpoint=endpoint, insecure=insecure, timeout=3),
+            export_interval_millis=30_000,
+            export_timeout_millis=3000,
+        )
+        meter_provider = MeterProvider(resource=resource, metric_readers=[metric_reader])
+        metrics.set_meter_provider(meter_provider)
+        runtime.meter_provider = meter_provider
+
+        logger_provider = LoggerProvider(resource=resource)
+        logger_provider.add_log_record_processor(
+            BatchLogRecordProcessor(
+                OTLPLogExporter(endpoint=endpoint, insecure=insecure, timeout=3),
+                max_queue_size=2048,
+                schedule_delay_millis=5000,
+                max_export_batch_size=512,
+                export_timeout_millis=3000,
+            )
+        )
+        otlp_handler = LoggingHandler(level=logging.NOTSET, logger_provider=logger_provider)
+        otlp_handler.addFilter(RedactionFilter())
+        logging.getLogger().addHandler(otlp_handler)
+        runtime.logger_provider = logger_provider
+
+        def sanitize_httpx_request(span: trace.Span, request: Any) -> None:
+            if not span.is_recording():
+                return
+            url = request[1]
+            host = getattr(url, "host", "")
+            scheme = getattr(url, "scheme", "https")
+            safe_url = f"{scheme}://{host}/[REDACTED]"
+            span.set_attribute("url.full", safe_url)
+            span.set_attribute("http.url", safe_url)
+
+        HTTPXClientInstrumentor().instrument(request_hook=sanitize_httpx_request)
+        SQLAlchemyInstrumentor().instrument(enable_commenter=False)
+    except Exception:
+        logging.getLogger(__name__).exception(
+            "Telemetry initialization failed; stdout fallback remains active",
+            extra={"event_name": "telemetry.init.failed"},
+        )
+    return runtime
+
+
+def instrument_fastapi(app: FastAPI) -> None:
+    try:
+        FastAPIInstrumentor.instrument_app(
+            app,
+            excluded_urls="/health/live",
+            http_capture_headers_server_request=[],
+            http_capture_headers_server_response=[],
+        )
+    except Exception:
+        logging.getLogger(__name__).exception(
+            "FastAPI instrumentation failed",
+            extra={"event_name": "telemetry.fastapi.failed"},
+        )
+
+
+def shutdown_telemetry() -> None:
+    global _runtime
+    if _runtime is not None:
+        _runtime.shutdown()
+        _runtime = None
+
+
+def log_event(
+    event: str,
+    message: str,
+    *,
+    level: int = logging.INFO,
+    attributes: Mapping[str, Any] | None = None,
+) -> None:
+    logging.getLogger("bitrix_sync").log(
+        level,
+        message,
+        extra={"event_name": event, "telemetry_attributes": redact(attributes or {})},
+    )
+
+
+@contextmanager
+def safe_span(
+    name: str,
+    *,
+    kind: SpanKind = SpanKind.INTERNAL,
+    attributes: Mapping[str, Any] | None = None,
+) -> Iterator[trace.Span]:
+    safe_attributes: dict[str, bool | int | float | str] = {}
+    for key, value in redact(attributes or {}).items():
+        if not isinstance(value, (bool, int, float, str)):
+            continue
+        key_text = str(key)[:64]
+        if key_text == "workflow.type":
+            value = _bounded(str(value), _SAFE_TASK_TYPES)
+        elif key_text == "crm.operation":
+            value = _bounded(str(value), _SAFE_CRM_OPERATIONS)
+        elif key_text == "receiver":
+            value = _bounded(str(value), _SAFE_RECEIVERS, "unknown")
+        safe_attributes[key_text] = value
+    with trace.get_tracer("han.bitrix_sync").start_as_current_span(
+        name[:128], kind=kind, attributes=safe_attributes
+    ) as span:
+        try:
+            yield span
+        except Exception as exc:
+            span.set_status(Status(StatusCode.ERROR, type(exc).__name__))
+            raise
+
+
+def _bounded(value: str, allowed: frozenset[str], fallback: str = "other") -> str:
+    return value if value in allowed else fallback
+
+
+def _metric_fail_open(function: Any) -> Any:
+    def wrapped(*args: Any, **kwargs: Any) -> None:
+        try:
+            function(*args, **kwargs)
+        except Exception:
+            return
+
+    return wrapped
+
+
+@_metric_fail_open
+def record_claim(queue: str, count: int) -> None:
+    queue_name = _bounded(queue, frozenset({"task", "webhook", "rebind"}))
+    metrics.get_meter("han.bitrix_sync").create_counter(
+        "bitrix_sync_claimed_items", unit="{item}"
+    ).add(max(0, count), {"queue": queue_name})
+
+
+@_metric_fail_open
+def record_workflow(task_type: str, outcome: str, duration_seconds: float) -> None:
+    attrs = {
+        "workflow.type": _bounded(task_type, _SAFE_TASK_TYPES),
+        "outcome": _bounded(outcome, _SAFE_CODES),
+    }
+    meter = metrics.get_meter("han.bitrix_sync")
+    meter.create_counter("bitrix_sync_workflows", unit="{workflow}").add(1, attrs)
+    meter.create_histogram("bitrix_sync_workflow_duration", unit="s").record(
+        max(0.0, duration_seconds), attrs
+    )
+
+
+@_metric_fail_open
+def record_webhook(receiver: str, outcome: str) -> None:
+    metrics.get_meter("han.bitrix_sync").create_counter(
+        "bitrix_sync_webhooks", unit="{webhook}"
+    ).add(
+        1,
+        {
+            "receiver": _bounded(receiver, _SAFE_RECEIVERS, "unknown"),
+            "outcome": _bounded(outcome, frozenset({"accepted", "rejected", "error"})),
+        },
+    )
+
+
+@_metric_fail_open
+def record_crm(method: str, outcome: str, duration_seconds: float) -> None:
+    operation = method.rsplit(".", 1)[-1]
+    operation = _bounded(operation, _SAFE_CRM_OPERATIONS)
+    attrs = {"operation": operation, "outcome": _bounded(outcome, _SAFE_CODES)}
+    meter = metrics.get_meter("han.bitrix_sync")
+    meter.create_counter("bitrix_sync_crm_calls", unit="{call}").add(1, attrs)
+    meter.create_histogram("bitrix_sync_crm_duration", unit="s").record(
+        max(0.0, duration_seconds), attrs
+    )
+
+
+@_metric_fail_open
+def record_limiter(delay_seconds: float) -> None:
+    metrics.get_meter("han.bitrix_sync").create_histogram(
+        "bitrix_sync_limiter_delay", unit="s"
+    ).record(max(0.0, delay_seconds))
+
+
+@_metric_fail_open
+def record_transition(kind: str, state: str) -> None:
+    metrics.get_meter("han.bitrix_sync").create_counter(
+        "bitrix_sync_transitions", unit="{transition}"
+    ).add(
+        1,
+        {
+            "kind": _bounded(kind, frozenset({"workflow", "command", "webhook"})),
+            "state": _bounded(
+                state,
+                frozenset(
+                    {
+                        "succeeded",
+                        "retry",
+                        "uncertain",
+                        "permanent",
+                        "rate_limited",
+                        "waiting_manual",
+                        "processed",
+                        "error",
+                    }
+                ),
+            ),
+        },
+    )
+
+
+@_metric_fail_open
+def record_retry(kind: str) -> None:
+    metrics.get_meter("han.bitrix_sync").create_counter(
+        "bitrix_sync_retries", unit="{retry}"
+    ).add(1, {"kind": _bounded(kind, frozenset({"task", "webhook", "rebind", "crm"}))})
+
+
+@_metric_fail_open
+def record_dead_letter(operation: str) -> None:
+    metrics.get_meter("han.bitrix_sync").create_counter(
+        "bitrix_sync_dead_letters", unit="{item}"
+    ).add(1, {"operation": _bounded(operation, frozenset({"crm_command"}))})
+
+
+@_metric_fail_open
+def record_business_alert(alert_type: str) -> None:
+    metrics.get_meter("han.bitrix_sync").create_counter(
+        "bitrix_sync_business_alerts", unit="{alert}"
+    ).add(1, {"alert.type": _bounded(alert_type, _SAFE_ALERT_TYPES)})
+
+
+@_metric_fail_open
+def record_status_snapshot(status: Mapping[str, Any]) -> None:
+    meter = metrics.get_meter("han.bitrix_sync")
+    depth = meter.create_histogram("bitrix_sync_queue_depth", unit="{item}")
+    for queue_name in ("queue", "workflows", "commands"):
+        values = status.get(queue_name)
+        if not isinstance(values, Mapping):
+            continue
+        for state, count in values.items():
+            if isinstance(count, int):
+                depth.record(
+                    max(0, count),
+                    {
+                        "queue": queue_name,
+                        "state": _bounded(str(state), _SAFE_QUEUE_STATES),
+                    },
+                )
+    for key in ("queue_oldest_age_seconds", "webhook_lag_seconds"):
+        value = status.get(key)
+        if isinstance(value, (int, float)):
+            meter.create_histogram(f"bitrix_sync_{key}", unit="s").record(max(0.0, value))
+
+
+@_metric_fail_open
+def record_reconciliation(outcome: str, count: int, started: float) -> None:
+    attrs = {"outcome": _bounded(outcome, frozenset({"success", "error", "skipped"}))}
+    meter = metrics.get_meter("han.bitrix_sync")
+    meter.create_counter("bitrix_sync_reconciliation_runs", unit="{run}").add(1, attrs)
+    meter.create_histogram("bitrix_sync_reconciliation_duration", unit="s").record(
+        max(0.0, monotonic() - started), attrs
+    )
+    meter.create_histogram("bitrix_sync_reconciliation_items", unit="{item}").record(
+        max(0, count), attrs
+    )
@@ -4,43 +4,62 @@ import asyncio
 import signal
 import socket
 import uuid
+from time import monotonic

 from app.config import load_settings
 from app.crm import CrmClient
 from app.domain import full_jitter_delay
 from app.engine import RetryableWorkflow, WorkflowEngine
 from app.repository import Repository
+from app.telemetry import (
+    init_telemetry,
+    log_event,
+    record_claim,
+    record_retry,
+    record_workflow,
+    safe_span,
+    shutdown_telemetry,
+)


 async def worker_main() -> None:
-    settings = load_settings()
-    if not settings.enabled:
-        return
-    assert settings.database_url and settings.crm_rest_webhook_url and settings.portal_host
-    repository = Repository(settings.database_url.get_secret_value(), settings.db_pool_size)
-    crm = CrmClient(
-        settings.crm_rest_webhook_url.get_secret_value(),
-        settings.portal_host,
-        settings.http_timeout_sec,
-    )
-    engine = WorkflowEngine(repository, crm, settings)
-    stop = asyncio.Event()
-    loop = asyncio.get_running_loop()
-    for event in (signal.SIGINT, signal.SIGTERM):
-        try:
-            loop.add_signal_handler(event, stop.set)
-        except NotImplementedError:
-            pass
-    worker_id = f"{socket.gethostname()}:{uuid.uuid4()}"
+    init_telemetry("bitrix-sync-worker")
+    repository: Repository | None = None
+    crm: CrmClient | None = None
    try:
+        settings = load_settings()
+        if not settings.enabled:
+            log_event("worker.disabled", "Bitrix sync worker is disabled")
+            return
+        assert settings.database_url and settings.crm_rest_webhook_url and settings.portal_host
+        repository = Repository(settings.database_url.get_secret_value(), settings.db_pool_size)
+        crm = CrmClient(
+            settings.crm_rest_webhook_url.get_secret_value(),
+            settings.portal_host,
+            settings.http_timeout_sec,
+        )
+        engine = WorkflowEngine(repository, crm, settings)
+        stop = asyncio.Event()
+        loop = asyncio.get_running_loop()
+        for event in (signal.SIGINT, signal.SIGTERM):
+            try:
+                loop.add_signal_handler(event, stop.set)
+            except NotImplementedError:
+                pass
+        worker_id = f"{socket.gethostname()}:{uuid.uuid4()}"
+        log_event("worker.started", "Bitrix sync worker started")
        while not stop.is_set():
-            tasks = await repository.claim_tasks(
-                worker_id, settings.claim_size, settings.lease_seconds
-            )
-            webhooks = await repository.claim_webhooks(
-                worker_id, settings.claim_size, settings.lease_seconds
-            )
-            rebind_ids = await repository.pending_rebind_ids(settings.claim_size)
+            with safe_span("bitrix_sync.worker.claim"):
+                tasks = await repository.claim_tasks(
+                    worker_id, settings.claim_size, settings.lease_seconds
+                )
+                webhooks = await repository.claim_webhooks(
+                    worker_id, settings.claim_size, settings.lease_seconds
+                )
+                rebind_ids = await repository.pending_rebind_ids(settings.claim_size)
+            record_claim("task", len(tasks))
+            record_claim("webhook", len(webhooks))
+            record_claim("rebind", len(rebind_ids))
            if not tasks and not webhooks and not rebind_ids:
                try:
                    await asyncio.wait_for(stop.wait(), timeout=1)
@@ -49,29 +68,68 @@ async def worker_main() -> None:
            for task in tasks:
                if stop.is_set():
                    break
-                await engine.process(task)
+                started = monotonic()
+                outcome = "success"
+                try:
+                    with safe_span(
+                        "bitrix_sync.worker.process",
+                        attributes={"workflow.type": task.task_type},
+                    ):
+                        await engine.process(task)
+                except Exception:
+                    outcome = "error"
+                    raise
+                finally:
+                    record_workflow(task.task_type, outcome, monotonic() - started)
            for item in webhooks:
                if stop.is_set():
                    break
+                started = monotonic()
+                outcome = "success"
                try:
-                    await engine.process_webhook(item)
+                    with safe_span(
+                        "bitrix_sync.worker.webhook",
+                        attributes={"receiver": item.receiver_type},
+                    ):
+                        await engine.process_webhook(item)
                except RetryableWorkflow as exc:
+                    outcome = "retry"
+                    record_retry("webhook")
                    delay = exc.retry_after or full_jitter_delay(
                        item.attempt_count + 1,
                        settings.retry_base_seconds,
                        settings.retry_max_seconds,
                    )
                    await repository.retry_webhook(item, exc.code, delay)
+                except Exception:
+                    outcome = "error"
+                    raise
+                finally:
+                    record_workflow("contact.webhook", outcome, monotonic() - started)
            for request_id in rebind_ids:
                if stop.is_set():
                    break
+                started = monotonic()
+                outcome = "success"
                try:
-                    await engine.process_rebind(request_id)
+                    with safe_span("bitrix_sync.worker.rebind"):
+                        await engine.process_rebind(request_id)
                except RetryableWorkflow:
+                    outcome = "retry"
+                    record_retry("rebind")
                    continue
+                except Exception:
+                    outcome = "error"
+                    raise
+                finally:
+                    record_workflow("rebind", outcome, monotonic() - started)
    finally:
-        await crm.close()
-        await repository.close()
+        if crm is not None:
+            await crm.close()
+        if repository is not None:
+            await repository.close()
+        log_event("worker.stopped", "Bitrix sync worker stopped")
+        shutdown_telemetry()


 def run() -> None: