diff --git a/.last-branch b/.last-branch index 800bf22..58c7cf5 100644 --- a/.last-branch +++ b/.last-branch @@ -1 +1 @@ -v20260115-17-autotask-ticket-create-trackingid-lookup +v20260115-19-autotask-ticket-create-debug-logging diff --git a/containers/backupchecks/src/backend/app/integrations/autotask/client.py b/containers/backupchecks/src/backend/app/integrations/autotask/client.py index 847867a..0034119 100644 --- a/containers/backupchecks/src/backend/app/integrations/autotask/client.py +++ b/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 " - "to allow deterministic lookup. " - f"(HTTP {resp.status_code})." + "Ticket creation may still have succeeded. " + f"(HTTP {resp.status_code}, Correlation={corr_id})." ) diff --git a/docs/changelog.md b/docs/changelog.md index c68b209..e70b3f0 100644 --- a/docs/changelog.md +++ b/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