Add Structured logging, and X-Request-ID support

Author: gregsvo

postmark/clients/account_client.py

@@ -1,6 +1,7 @@
 import logging
 import os
 import sys
+import time
 from typing import Any, Dict, List, Optional, Union
 
 import httpx
@@ -93,7 +94,7 @@ async def request(self, method: str, endpoint: str, **kwargs) -> httpx.Response:
         """
         Make a request to the Postmark API using the configured account token.
         """
-        logger.debug(f"Making {method} request to {endpoint}")
+        logger.debug("Making request", extra={"method": method, "endpoint": endpoint})
 
         async for attempt in AsyncRetrying(
             retry=retry_if_exception_type(
@@ -105,32 +106,69 @@ async def request(self, method: str, endpoint: str, **kwargs) -> httpx.Response:
         ):
             with attempt:
                 try:
+                    start = time.monotonic()
                     response = await self._http_client.request(
                         method, endpoint, **kwargs
                     )
                     response.raise_for_status()
-                    logger.debug(f"Request successful: {response.status_code}")
+                    duration_ms = round((time.monotonic() - start) * 1000)
+                    request_id = response.headers.get("X-Request-Id")
+                    logger.debug(
+                        "Request successful",
+                        extra={
+                            "method": method,
+                            "endpoint": endpoint,
+                            "status_code": response.status_code,
+                            "duration_ms": duration_ms,
+                            "request_id": request_id,
+                        },
+                    )
                     return response
 
                 except httpx.TimeoutException as e:
-                    logger.error(f"Request timeout for {method} {endpoint}")
+                    duration_ms = round((time.monotonic() - start) * 1000)
+                    logger.error(
+                        "Request timed out",
+                        extra={
+                            "method": method,
+                            "endpoint": endpoint,
+                            "duration_ms": duration_ms,
+                        },
+                    )
                     raise TimeoutException("Request timed out after 30 seconds") from e
 
                 except httpx.HTTPStatusError as e:
+                    duration_ms = round((time.monotonic() - start) * 1000)
+                    request_id = e.response.headers.get("X-Request-Id")
                     message, error_code = parse_error_response(e.response)
                     http_status = e.response.status_code
 
-                    logger.error(f"API error {error_code or http_status}: {message}")
+                    logger.error(
+                        "API error",
+                        extra={
+                            "method": method,
+                            "endpoint": endpoint,
+                            "status_code": http_status,
+                            "error_code": error_code or http_status,
+                            "postmark_message": message,
+                            "duration_ms": duration_ms,
+                            "request_id": request_id,
+                        },
+                    )
 
                     exception_class = get_exception_class(error_code or 0, http_status)
                     raise exception_class(
                         message=message,
                         error_code=error_code or 0,
                         http_status=http_status,
+                        request_id=request_id,
                     ) from e
 
                 except httpx.RequestError as e:
-                    logger.error(f"Request failed: {e}")
+                    logger.error(
+                        "Request failed",
+                        extra={"method": method, "endpoint": endpoint, "error": str(e)},
+                    )
                     raise PostmarkException(f"Request failed: {str(e)}") from e
 
         raise AssertionError("The Postmark API is unreachable.")

postmark/clients/server_client.py

@@ -1,6 +1,7 @@
 import logging
 import os
 import sys
+import time
 from typing import Any, Dict, List, Optional, Union
 
 import httpx
@@ -104,7 +105,7 @@ async def request(self, method: str, endpoint: str, **kwargs) -> httpx.Response:
         """
         Make a request to the Postmark API using the configured token.
         """
-        logger.debug(f"Making {method} request to {endpoint}")
+        logger.debug("Making request", extra={"method": method, "endpoint": endpoint})
 
         async for attempt in AsyncRetrying(
             retry=retry_if_exception_type(
@@ -116,23 +117,56 @@ async def request(self, method: str, endpoint: str, **kwargs) -> httpx.Response:
         ):
             with attempt:
                 try:
+                    start = time.monotonic()
                     response = await self._http_client.request(
                         method, endpoint, **kwargs
                     )
                     response.raise_for_status()
-                    logger.debug(f"Request successful: {response.status_code}")
+                    duration_ms = round((time.monotonic() - start) * 1000)
+                    request_id = response.headers.get("X-Request-Id")
+                    logger.debug(
+                        "Request successful",
+                        extra={
+                            "method": method,
+                            "endpoint": endpoint,
+                            "status_code": response.status_code,
+                            "duration_ms": duration_ms,
+                            "request_id": request_id,
+                        },
+                    )
                     return response
 
                 except httpx.TimeoutException as e:
-                    logger.error(f"Request timeout for {method} {endpoint}")
+                    duration_ms = round((time.monotonic() - start) * 1000)
+                    logger.error(
+                        "Request timed out",
+                        extra={
+                            "method": method,
+                            "endpoint": endpoint,
+                            "duration_ms": duration_ms,
+                        },
+                    )
                     raise TimeoutException("Request timed out after 30 seconds") from e
 
                 except httpx.HTTPStatusError as e:
+                    duration_ms = round((time.monotonic() - start) * 1000)
+                    request_id = e.response.headers.get("X-Request-Id")
                     # Parse Postmark error response
                     message, error_code = parse_error_response(e.response)
                     http_status = e.response.status_code
 
-                    logger.error(f"API error {error_code or http_status}: {message}")
+                    logger.error(
+                        "API error",
+                        extra={
+                            "method": method,
+                            "endpoint": endpoint,
+                            "status_code": http_status,
+                            "error_code": error_code or http_status,
+                            "postmark_message": message,
+                            "duration_ms": duration_ms,
+                            "request_id": request_id,
+                        },
+                    )
 
                     # Get exception class
                     exception_class = get_exception_class(error_code or 0, http_status)
@@ -142,10 +176,14 @@ async def request(self, method: str, endpoint: str, **kwargs) -> httpx.Response:
                         message=message,
                         error_code=error_code or 0,
                         http_status=http_status,
+                        request_id=request_id,
                     ) from e
 
                 except httpx.RequestError as e:
-                    logger.error(f"Request failed: {e}")
+                    logger.error(
+                        "Request failed",
+                        extra={"method": method, "endpoint": endpoint, "error": str(e)},
+                    )
                     raise PostmarkException(f"Request failed: {str(e)}") from e
 
         raise AssertionError("The Postmark API is unreachable.")

postmark/exceptions.py

@@ -46,11 +46,19 @@ class PostmarkAPIException(PostmarkException):
     Always carries both a Postmark error_code and an http_status.
     """
 
-    def __init__(self, message: str, error_code: int, http_status: int):
+    def __init__(
+        self,
+        message: str,
+        error_code: int,
+        http_status: int,
+        request_id: Optional[str] = None,
+    ):
         super().__init__(message, error_code, http_status)
+        self.request_id = request_id
 
     def __str__(self):
-        return f"[{self.error_code}] {self.message} (HTTP {self.http_status})"
+        base = f"[{self.error_code}] {self.message} (HTTP {self.http_status})"
+        return f"{base} [request_id={self.request_id}]" if self.request_id else base
 
 
 class InvalidAPIKeyException(PostmarkAPIException):
@@ -62,8 +70,14 @@ class InvalidAPIKeyException(PostmarkAPIException):
 class InactiveRecipientException(PostmarkAPIException):
     """406 - Inactive recipient."""
 
-    def __init__(self, message: str, error_code: int, http_status: int):
-        super().__init__(message, error_code, http_status)
+    def __init__(
+        self,
+        message: str,
+        error_code: int,
+        http_status: int,
+        request_id: Optional[str] = None,
+    ):
+        super().__init__(message, error_code, http_status, request_id)
         match = re.search(r"Found inactive addresses: ([^.]+)", message)
         self.inactive_recipients: list[str] = (
             [addr.strip() for addr in match.group(1).split(",")] if match else []

postmark/models/outbound/manager.py

@@ -79,7 +79,7 @@ async def send(self, message: Union[Email, Dict[str, Any]]) -> SendResponse:
         """Send a single email."""
         email_payload = _parse_email(message)
 
-        logger.debug(f"Sending email to {email_payload.to}")
+        logger.debug("Sending email", extra={"recipient": email_payload.to})
         response = await self.client.post(
             "/email",
             json=email_payload.model_dump(by_alias=True, exclude_none=True),
@@ -137,7 +137,9 @@ async def send_bulk(
                 "Bulk email must include at least one recipient in messages"
             )
 
-        logger.debug(f"Sending bulk email to {len(bulk_payload.messages)} recipients")
+        logger.debug(
+            "Sending bulk email", extra={"recipient_count": len(bulk_payload.messages)}
+        )
         response = await self.client.post(
             "/email/bulk",
             json=bulk_payload.model_dump(by_alias=True, exclude_none=True),
@@ -160,7 +162,7 @@ async def send_with_template(
     ) -> SendResponse:
         """Send an email using a template."""
         email = _parse_template_email(message)
-        logger.debug(f"Sending template email to {email.to}")
+        logger.debug("Sending template email", extra={"recipient": email.to})
         response = await self.client.post(
             "/email/withTemplate",
             json=email.model_dump(by_alias=True, exclude_none=True),

tests/conftest.py

@@ -25,6 +25,7 @@ def make_response(data: dict | list) -> Mock:
     response = Mock(spec=Response)
     response.json.return_value = data
     response.raise_for_status = Mock()
+    response.headers = {}
     return response
 
 

tests/test_account_client.py

@@ -32,6 +32,7 @@ def mock_ok_response(self):
         response = Mock(spec=Response)
         response.raise_for_status = Mock()
         response.status_code = 200
+        response.headers = {}
         return response
 
     # -------------------------------------------------------------------------
@@ -135,6 +136,7 @@ async def test_async_context_manager(self):
     async def test_401_raises_invalid_api_key(self, client):
         mock_response = Mock(spec=Response)
         mock_response.status_code = 401
+        mock_response.headers = {}
         mock_response.json.return_value = {
             "ErrorCode": 10,
             "Message": "Invalid API key",
@@ -157,6 +159,7 @@ async def test_401_raises_invalid_api_key(self, client):
     async def test_422_raises_validation_exception(self, client):
         mock_response = Mock(spec=Response)
         mock_response.status_code = 422
+        mock_response.headers = {}
         mock_response.json.return_value = {
             "ErrorCode": 300,
             "Message": "Invalid request body",
@@ -200,13 +203,15 @@ async def test_retries_on_rate_limit(self):
 
         failing_resp = Mock(spec=Response)
         failing_resp.status_code = 429
+        failing_resp.headers = {}
         failing_resp.json.return_value = {"ErrorCode": 429, "Message": "Rate limit"}
         failing_resp.raise_for_status.side_effect = HTTPStatusError(
             "429", request=Mock(), response=failing_resp
         )
         ok_resp = Mock(spec=Response)
         ok_resp.raise_for_status = Mock()
         ok_resp.status_code = 200
+        ok_resp.headers = {}
 
         with patch("asyncio.sleep", new_callable=AsyncMock):
             with patch.object(
@@ -226,6 +231,7 @@ async def test_retries_exhausted_reraises(self):
 
         mock_response = Mock(spec=Response)
         mock_response.status_code = 500
+        mock_response.headers = {}
         mock_response.json.return_value = {"ErrorCode": 500, "Message": "Server error"}
         mock_response.raise_for_status.side_effect = HTTPStatusError(
             "500", request=Mock(), response=mock_response
@@ -249,6 +255,7 @@ async def test_no_retry_on_validation_error(self):
 
         mock_response = Mock(spec=Response)
         mock_response.status_code = 422
+        mock_response.headers = {}
         mock_response.json.return_value = {
             "ErrorCode": 300,
             "Message": "Validation error",
@@ -271,6 +278,7 @@ async def test_retries_disabled_with_zero(self):
 
         mock_response = Mock(spec=Response)
         mock_response.status_code = 500
+        mock_response.headers = {}
         mock_response.json.return_value = {"ErrorCode": 500, "Message": "Server error"}
         mock_response.raise_for_status.side_effect = HTTPStatusError(
             "500", request=Mock(), response=mock_response