Parcourir la source

booking: improve send_message logging for live call analysis

- _msg_gql: DEBUG log HTTP status per attempt; WARNING with full response
  body on 4xx; WARNING with complete GQL errors JSON (preserves extensions,
  path, locations) instead of joined strings; transport errors now log before
  raising; attempt number threaded through for multi-attempt tracing
- send_message: INFO before send (res id, idempotency key, content length);
  INFO on success (messageId, created); ISE warning includes res id and
  idempotency; retry attempt logged distinctly; 2FA retry success also logged
ZiB il y a 4 mois
Parent
commit
9dd8ca8d35
1 fichiers modifiés avec 19 ajouts et 7 suppressions
  1. 19 7
      room_cal/service_api/_booking.py

+ 19 - 7
room_cal/service_api/_booking.py

@@ -360,7 +360,7 @@ class _BookingClient:
       'Cookie': self._cookies,
       'Cookie': self._cookies,
     }
     }
 
 
-  async def _msg_gql(self, operation_name: str, query: str, variables: dict) -> dict:
+  async def _msg_gql(self, operation_name: str, query: str, variables: dict, *, attempt: int = 1) -> dict:
     params = {
     params = {
       'hotel_id': str(self._hotel_id),
       'hotel_id': str(self._hotel_id),
       'lang': self._lang,
       'lang': self._lang,
@@ -368,7 +368,7 @@ class _BookingClient:
       'source': 'nav',
       'source': 'nav',
       'tlc': '1',
       'tlc': '1',
     }
     }
-    async def _attempt() -> httpx.Response:
+    async def _do_request() -> httpx.Response:
       async with httpx.AsyncClient() as client:
       async with httpx.AsyncClient() as client:
         return await client.post(
         return await client.post(
           f'{_BASE}/dml/graphql.json',
           f'{_BASE}/dml/graphql.json',
@@ -377,16 +377,21 @@ class _BookingClient:
           headers=self._msg_headers(),
           headers=self._msg_headers(),
         )
         )
     try:
     try:
-      r = await _attempt()
+      r = await _do_request()
     except (httpx.TransportError, OSError, ExceptionGroup) as e:
     except (httpx.TransportError, OSError, ExceptionGroup) as e:
+      _log.warning('booking _msg_gql %s attempt=%d transport error: %s', operation_name, attempt, e)
       raise BookingAuthError(f'Booking.com connection failed — session may be expired, run: {_AUTH_HINT}') from e
       raise BookingAuthError(f'Booking.com connection failed — session may be expired, run: {_AUTH_HINT}') from e
+    _log.debug('booking _msg_gql %s attempt=%d http=%d', operation_name, attempt, r.status_code)
     if r.status_code in (400, 401, 403):
     if r.status_code in (400, 401, 403):
+      _log.warning('booking _msg_gql %s attempt=%d http=%d body=%.500s', operation_name, attempt, r.status_code, r.text)
       await self._ensure_refreshed(trigger='messaging')
       await self._ensure_refreshed(trigger='messaging')
-      r = await _attempt()
+      r = await _do_request()
+      _log.debug('booking _msg_gql %s attempt=%d (after refresh) http=%d', operation_name, attempt, r.status_code)
     await self._check_auth(r)
     await self._check_auth(r)
     r.raise_for_status()
     r.raise_for_status()
     raw = r.json()
     raw = r.json()
     if raw.get('errors'):
     if raw.get('errors'):
+      _log.warning('booking _msg_gql %s attempt=%d gql errors: %s', operation_name, attempt, json.dumps(raw['errors']))
       msgs = ', '.join(e.get('message', '') for e in raw['errors'])
       msgs = ', '.join(e.get('message', '') for e in raw['errors'])
       raise RuntimeError(f'GraphQL error: {msgs}')
       raise RuntimeError(f'GraphQL error: {msgs}')
     return raw
     return raw
@@ -644,17 +649,24 @@ class _BookingClient:
       'content': body,
       'content': body,
       'attachmentIds': [],
       'attachmentIds': [],
     }}
     }}
+    _log.info('booking send_message res=%s idempotency=%s content_len=%d', reservation_id, idempotency, len(body))
     try:
     try:
-      await self._msg_gql('postFreeTextMessage', _POST_FREE_TEXT_MUTATION, payload)
+      raw = await self._msg_gql('postFreeTextMessage', _POST_FREE_TEXT_MUTATION, payload, attempt=1)
+      msg = ((raw.get('data') or {}).get('chatMessage') or {}).get('postFreeTextMessage') or {}
+      result = msg.get('message') or {}
+      _log.info('booking send_message ok res=%s msg_id=%s created=%s', reservation_id, result.get('messageId'), result.get('created'))
     except RuntimeError as e:
     except RuntimeError as e:
       if 'Internal Server Error' not in str(e):
       if 'Internal Server Error' not in str(e):
         raise
         raise
       # GraphQL ISE on send typically means the messaging 2FA session has expired.
       # GraphQL ISE on send typically means the messaging 2FA session has expired.
       # Re-trigger the SMS challenge and retry once.
       # Re-trigger the SMS challenge and retry once.
-      _log.warning('Booking.com send_message failed with ISE — re-triggering 2FA')
+      _log.warning('booking send_message ISE on attempt 1 res=%s idempotency=%s — re-triggering 2FA', reservation_id, idempotency)
       trigger_booking_chat_auth()
       trigger_booking_chat_auth()
       self._reload_from_env()
       self._reload_from_env()
-      await self._msg_gql('postFreeTextMessage', _POST_FREE_TEXT_MUTATION, payload)
+      raw = await self._msg_gql('postFreeTextMessage', _POST_FREE_TEXT_MUTATION, payload, attempt=2)
+      msg = ((raw.get('data') or {}).get('chatMessage') or {}).get('postFreeTextMessage') or {}
+      result = msg.get('message') or {}
+      _log.info('booking send_message ok (after 2FA retry) res=%s msg_id=%s created=%s', reservation_id, result.get('messageId'), result.get('created'))
 
 
   async def set_price(self, d: str, price: int, occupancy: int = 2) -> None:
   async def set_price(self, d: str, price: int, occupancy: int = 2) -> None:
     price = int(round(price))
     price = int(round(price))