Log in router

.gitignore

@@ -36,3 +36,4 @@ pxy_bots.zip
 pxy_bots (2).zip
 pxy_bots.zip
 pxy_bots.zip
+pxy_bots.zip

polisplexity/settings.py

@@ -226,3 +226,28 @@ REST_FRAMEWORK = {
 }
 
 AGENTS_INTERNAL_BASE = "http://127.0.0.1:8000"
+
+LOGGING = {
+    # ... keep your existing handlers/formatters ...
+    "version": 1,
+    "disable_existing_loggers": False,
+    "handlers": {
+        "console": {
+            "class": "logging.StreamHandler",
+        },
+    },
+    "loggers": {
+        "pxy_bots": {                 # package logger
+            "handlers": ["console"],
+            "level": "INFO",          # or "DEBUG"
+            "propagate": False,
+        },
+        # make sure __name__ in router resolves here; if your module path is different, use that
+        "pxy_bots.router": {
+            "handlers": ["console"],
+            "level": "INFO",
+            "propagate": False,
+        },
+    },
+}
+

pxy_bots/router.py

@@ -1,6 +1,7 @@
 # pxy_bots/router.py
 import json
 import logging
+import time  # <-- add
 from typing import Dict, Optional, Tuple
 from urllib.parse import urlparse
 
@@ -45,26 +46,36 @@ def pick_db_route(bot_name: str, canon: Dict) -> Optional[Dict]:
     try:
         # Lazy import to avoid circulars at startup
         from .models import CommandRoute, Connection, TelegramBot  # noqa
+
         bot = TelegramBot.objects.filter(name=bot_name, is_active=True).first()
         if not bot:
+            logger.info("router.no_bot bot=%s", bot_name)
             return None
 
         trigger = ((canon.get("command") or {}).get("trigger")) or "message"
         cmd = ((canon.get("command") or {}).get("name")) or None
         cmd = (cmd or "").strip().lstrip("/").lower() or None
 
+        logger.info("router.lookup bot=%s trigger=%s cmd=%s", bot.username, trigger, cmd or "")
+
         qs = (
             CommandRoute.objects
             .select_related("connection")
             .filter(bot=bot, enabled=True, connection__is_active=True, trigger=trigger)
             .order_by("priority", "id")
         )
+        # Log a small snapshot of candidates
+        snapshot = list(qs.values("command_name", "trigger", "priority", "path", "connection__name")[:10])
+        logger.info("router.candidates n=%s sample=%s", qs.count(), snapshot)
 
         # Prefer exact command; then default (blank/null)
-        route = qs.filter(command_name=cmd).first() \
-            or qs.filter(command_name__isnull=True).first() \
+        route = (
+            qs.filter(command_name=cmd).first()
+            or qs.filter(command_name__isnull=True).first()
             or qs.filter(command_name="").first()
+        )
         if not route:
+            logger.info("router.no_match bot=%s trigger=%s cmd=%s", bot.username, trigger, cmd or "")
             return None
 
         conn: Connection = route.connection
@@ -72,14 +83,22 @@ def pick_db_route(bot_name: str, canon: Dict) -> Optional[Dict]:
 
         ok, why = _is_allowed(url, conn.allowed_host_set())
         if not ok:
-            logger.warning("router.db.reject url=%s reason=%s allowed=%s", url, why, conn.allowed_host_set())
+            logger.warning(
+                "router.db.reject url=%s reason=%s allowed=%s route_conn=%s",
+                url, why, conn.allowed_host_set(), conn.name
+            )
             return None
 
         headers = {}
         headers.update(conn.auth_headers())
         headers.update(conn.extra_headers())
 
+        logger.info(
+            "router.route_ok bot=%s trigger=%s cmd=%s url=%s conn=%s timeout=%ss",
+            bot.username, trigger, cmd or "", url, conn.name, conn.timeout_s
+        )
         return {"url": url, "headers": headers, "timeout": conn.timeout_s}
+
     except Exception as e:
         logger.exception("router.db.error: %s", e)
         return None
@@ -96,28 +115,41 @@ def post_json(url: str, payload: Dict, timeout: float = 4.0, headers: Optional[D
     """
     hdrs = {"Content-Type": "application/json", **(headers or {})}
     data = json.dumps(payload, ensure_ascii=False).encode("utf-8")
+    t0 = time.perf_counter()
 
     if _HAS_REQUESTS:
         try:
             r = requests.post(url, data=data, headers=hdrs, timeout=timeout)
+            dt = (time.perf_counter() - t0) * 1000
             try:
                 body = r.json()
+                preview = str(body)[:200].replace("\n", " ")
             except Exception:
                 body = {"text": r.text[:2000]}
+                preview = body["text"][:200].replace("\n", " ")
+            logger.info("router.http requests url=%s status=%s t_ms=%.1f body~=%s", url, r.status_code, dt, preview)
             return r.status_code, body
         except Exception as e:
-            logger.exception("router.requests_failed url=%s", url)
+            dt = (time.perf_counter() - t0) * 1000
+            logger.exception("router.requests_failed url=%s t_ms=%.1f err=%s", url, dt, e.__class__.__name__)
             return 502, {"ok": False, "error": f"requests_failed:{e.__class__.__name__}"}
     else:
         try:
             req = urllib.request.Request(url, data=data, headers=hdrs, method="POST")
             with urllib.request.urlopen(req, timeout=timeout) as resp:  # nosec
                 raw = resp.read(65536)
+                dt = (time.perf_counter() - t0) * 1000
                 try:
                     body = json.loads(raw.decode("utf-8"))
+                    preview = str(body)[:200].replace("\n", " ")
                 except Exception:
-                    body = {"text": raw.decode("utf-8", errors="replace")[:2000]}
-                return getattr(resp, "status", 200), body
+                    txt = raw.decode("utf-8", errors="replace")[:2000]
+                    body = {"text": txt}
+                    preview = txt[:200].replace("\n", " ")
+                status = getattr(resp, "status", 200)
+                logger.info("router.http urllib url=%s status=%s t_ms=%.1f body~=%s", url, status, dt, preview)
+                return status, body
         except Exception as e:
-            logger.exception("router.urllib_failed url=%s", url)
+            dt = (time.perf_counter() - t0) * 1000
+            logger.exception("router.urllib_failed url=%s t_ms=%.1f err=%s", url, dt, e.__class__.__name__)
             return 502, {"ok": False, "error": f"urllib_failed:{e.__class__.__name__}"}