mi
515 lines
18 KiB
Python
515 lines
18 KiB
Python
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
|
|
)
|