Auto-commit local changes before build (2026-01-16 09:04:12)

.last-branch

@@ -1 +1 @@
-v20260115-17-autotask-ticket-create-trackingid-lookup
+v20260115-19-autotask-ticket-create-debug-logging

containers/backupchecks/src/backend/app/integrations/autotask/client.py

@@ -1,10 +1,16 @@
 import json
+import logging
+import os
+import uuid
 from dataclasses import dataclass
 from typing import Any, Dict, List, Optional
 
 import requests
 
 
+logger = logging.getLogger(__name__)
+
+
 @dataclass
 class AutotaskZoneInfo:
     zone_name: str
@@ -37,6 +43,29 @@ class AutotaskClient:
         self._zone_info: Optional[AutotaskZoneInfo] = None
         self._zoneinfo_base_used: Optional[str] = None
 
+    def _debug_enabled(self) -> bool:
+        """Return True when verbose Autotask integration logging is enabled.
+
+        This is intentionally controlled via an environment variable to avoid
+        writing sensitive payloads to logs by default.
+        """
+        return str(os.getenv("BACKUPCHECKS_AUTOTASK_DEBUG", "")).strip().lower() in {
+            "1",
+            "true",
+            "yes",
+            "on",
+        }
+
+    def _safe_json_preview(self, data: Any, max_chars: int = 1200) -> str:
+        """Serialize JSON-like data for logging, truncating large payloads."""
+        try:
+            s = json.dumps(data, ensure_ascii=False, default=str)
+        except Exception:
+            s = str(data)
+        if len(s) > max_chars:
+            return s[:max_chars] + "…"
+        return s
+
     def _zoneinfo_bases(self) -> List[str]:
         """Return a list of zoneInformation base URLs to try.
 
@@ -430,6 +459,7 @@ class AutotaskClient:
         self,
         tracking_identifier: str,
         company_id: Optional[int] = None,
+        corr_id: Optional[str] = None,
     ) -> Optional[int]:
         """Lookup the most recently created ticket by tracking identifier.
 
@@ -461,8 +491,22 @@ class AutotaskClient:
         }
 
         params = {"search": json.dumps(search_payload)}
+        if self._debug_enabled():
+            logger.info(
+                "[autotask][%s] Tickets/query lookup payload=%s",
+                corr_id or "-",
+                self._safe_json_preview(search_payload, max_chars=1200),
+            )
+
         data = self._request("GET", "Tickets/query", params=params)
         items = self._as_items_list(data)
+        if self._debug_enabled():
+            logger.info(
+                "[autotask][%s] Tickets/query lookup result_count=%s keys=%s",
+                corr_id or "-",
+                len(items),
+                (sorted(list(items[0].keys())) if items and isinstance(items[0], dict) else None),
+            )
         if not items:
             return None
 
@@ -480,8 +524,36 @@ class AutotaskClient:
         if not isinstance(payload, dict) or not payload:
             raise AutotaskError("Ticket payload is empty.")
 
+        corr_id = uuid.uuid4().hex[:10]
+
+        if self._debug_enabled():
+            # Avoid dumping full descriptions by default, but include key routing fields.
+            payload_keys = sorted(list(payload.keys()))
+            logger.info(
+                "[autotask][%s] POST /Tickets payload_keys=%s companyID=%s queueID=%s source=%s status=%s priority=%s trackingIdentifier=%s",
+                corr_id,
+                payload_keys,
+                payload.get("companyID") or payload.get("CompanyID") or payload.get("companyId"),
+                payload.get("queueID") or payload.get("QueueID") or payload.get("queueId"),
+                payload.get("source") or payload.get("Source") or payload.get("sourceId") or payload.get("sourceID"),
+                payload.get("status") or payload.get("Status") or payload.get("statusId") or payload.get("statusID"),
+                payload.get("priority") or payload.get("Priority"),
+                payload.get("trackingIdentifier") or payload.get("TrackingIdentifier"),
+            )
+
         resp = self._request_raw("POST", "Tickets", json_body=payload)
 
+        if self._debug_enabled():
+            location = (resp.headers.get("Location") or resp.headers.get("location") or "").strip()
+            logger.info(
+                "[autotask][%s] POST /Tickets response http=%s content_type=%s content_length=%s location=%s",
+                corr_id,
+                resp.status_code,
+                (resp.headers.get("Content-Type") or resp.headers.get("content-type") or ""),
+                (len(resp.content or b"") if resp is not None else None),
+                location or None,
+            )
+
         data: Any = {}
         if resp.content:
             try:
@@ -489,6 +561,25 @@ class AutotaskClient:
             except Exception:
                 # Some tenants return an empty body or a non-JSON body on successful POST.
                 data = {}
+                if self._debug_enabled():
+                    # Log a short preview of the raw body to understand tenant behaviour.
+                    try:
+                        body_preview = (resp.text or "")[:600]
+                    except Exception:
+                        body_preview = ""
+                    logger.info(
+                        "[autotask][%s] POST /Tickets non-JSON body preview=%s",
+                        corr_id,
+                        body_preview,
+                    )
+
+        if self._debug_enabled():
+            logger.info(
+                "[autotask][%s] POST /Tickets parsed_json_type=%s json_preview=%s",
+                corr_id,
+                type(data).__name__,
+                self._safe_json_preview(data, max_chars=1200),
+            )
 
         ticket_id: Optional[int] = None
 
@@ -526,6 +617,13 @@ class AutotaskClient:
                 except Exception:
                     ticket_id = None
 
+        if self._debug_enabled():
+            logger.info(
+                "[autotask][%s] POST /Tickets extracted_ticket_id=%s",
+                corr_id,
+                ticket_id,
+            )
+
         # If we have an ID, fetch the full ticket object so callers can reliably access ticketNumber etc.
         if ticket_id is not None:
             return self.get_ticket(ticket_id)
@@ -542,7 +640,19 @@ class AutotaskClient:
                 company_id = int(payload[ck])
                 break
 
-        looked_up_id = self._lookup_created_ticket_id(str(tracking_identifier), company_id=company_id)
+        if self._debug_enabled():
+            logger.info(
+                "[autotask][%s] fallback lookup by TrackingIdentifier=%s companyID=%s",
+                corr_id,
+                str(tracking_identifier),
+                company_id,
+            )
+
+        looked_up_id = self._lookup_created_ticket_id(
+            str(tracking_identifier),
+            company_id=company_id,
+            corr_id=corr_id,
+        )
         if looked_up_id is not None:
             return self.get_ticket(looked_up_id)
 
@@ -553,7 +663,6 @@ class AutotaskClient:
 
         raise AutotaskError(
             "Autotask did not return a ticket id. "
-            "Ticket creation may still have succeeded; configure ticket TrackingIdentifier to be unique per run "
+            "Ticket creation may still have succeeded. "
-            "to allow deterministic lookup. "
+            f"(HTTP {resp.status_code}, Correlation={corr_id})."
-            f"(HTTP {resp.status_code})."
         )

docs/changelog.md

@@ -123,6 +123,12 @@ Changes:
 - Ensured the created ticket is reliably retrieved via follow-up GET /Tickets/{id} so ticketNumber/id can always be stored.
 - Eliminated false-negative ticket creation errors when Autotask returns an empty body and no Location header.
 
+## v20260115-19-autotask-ticket-create-debug-logging
+- Added optional verbose Autotask ticket creation logging (guarded by BACKUPCHECKS_AUTOTASK_DEBUG=1).
+- Introduced per-request correlation IDs and included them in ticket creation error messages for log tracing.
+- Logged POST /Tickets response characteristics (status, headers, body preview) to diagnose tenants returning incomplete create responses.
+- Logged fallback Tickets/query lookup payload and result shape to pinpoint why deterministic lookup fails.
+
 ***
 
 ## v0.1.21