Added logger with basic debugging info (#86)

Logging was missing for a long time from the client, and it made it
harder to debug the client.

This adds some basic logging to the HTTP calls, using the standard
Python logger, enriched by contextual information from the client
methods which are doing the HTTP calls by some funky metaclass
programming.

There is a `_DebugLogFormatter` class which is great for testing, used
like this:

```python
import logging
from apify_client._logging import _DebugLogFormatter

client_logger = logging.getLogger('apify_client')
client_logger.setLevel(logging.DEBUG)
handler = logging.StreamHandler()
handler.setFormatter(_DebugLogFormatter())
client_logger.addHandler(handler)
```

Author: fnesveda

CHANGELOG.md

@@ -17,6 +17,7 @@ Changelog
 - added `py.typed` file to signal type checkers that this package is typed
 - added method to update status message for a run
 - added option to set up webhooks for actor builds
+- added logger with basic debugging info
 
 ### Internal changes
 

docs/docs.md

@@ -186,6 +186,25 @@ async def main():
 asyncio.run(main())
 ```
 
+### Logging
+
+The library logs some useful debug information to the `apify_client` logger
+when sending requests to the Apify API.
+To have them printed out to the standard output, you need to add a handler to the logger:
+
+```python
+import logging
+apify_client_logger = logging.getLogger('apify_client')
+apify_client_logger.setLevel(logging.DEBUG)
+apify_client_logger.addHandler(logging.StreamHandler())
+```
+
+The log records have useful properties added with the `extra` argument,
+like `attempt`, `status_code`, `url`, `client_method` and `resource_id`.
+To print those out, you'll need to use a custom log formatter.
+To learn more about log formatters and how to use them,
+please refer to the official Python [documentation on logging](https://docs.python.org/3/howto/logging.html#formatters).
+
 ## API Reference
 
 All public classes, methods and their parameters can be inspected in this API reference.

docs/res/intro.md

@@ -185,3 +185,22 @@ async def main():
 
 asyncio.run(main())
 ```
+
+### Logging
+
+The library logs some useful debug information to the `apify_client` logger
+when sending requests to the Apify API.
+To have them printed out to the standard output, you need to add a handler to the logger:
+
+```python
+import logging
+apify_client_logger = logging.getLogger('apify_client')
+apify_client_logger.setLevel(logging.DEBUG)
+apify_client_logger.addHandler(logging.StreamHandler())
+```
+
+The log records have useful properties added with the `extra` argument,
+like `attempt`, `status_code`, `url`, `client_method` and `resource_id`.
+To print those out, you'll need to use a custom log formatter.
+To learn more about log formatters and how to use them,
+please refer to the official Python [documentation on logging](https://docs.python.org/3/howto/logging.html#formatters).

src/apify_client/_http_client.py

@@ -1,5 +1,6 @@
 import gzip
 import json as jsonlib
+import logging
 import os
 import sys
 from http import HTTPStatus
@@ -8,13 +9,16 @@
 import httpx
 
 from ._errors import ApifyApiError, InvalidResponseBodyError, _is_retryable_error
+from ._logging import logger_name
 from ._types import JSONSerializable
 from ._utils import _is_content_type_json, _is_content_type_text, _is_content_type_xml, _retry_with_exp_backoff, _retry_with_exp_backoff_async
 from ._version import __version__
 
 DEFAULT_BACKOFF_EXPONENTIAL_FACTOR = 2
 DEFAULT_BACKOFF_RANDOM_FACTOR = 1
 
+logger = logging.getLogger(logger_name)
+
 
 class _BaseHTTPClient:
     def __init__(
@@ -129,6 +133,7 @@ def call(
         httpx_client = self.httpx_client
 
         def _make_request(stop_retrying: Callable, attempt: int) -> httpx.Response:
+            logger.debug(f'Sending request to {url}', extra={'attempt': attempt})
             try:
                 request = httpx_client.build_request(
                     method=method,
@@ -144,6 +149,7 @@ def _make_request(stop_retrying: Callable, attempt: int) -> httpx.Response:
 
                 # If response status is < 300, the request was successful, and we can return the result
                 if response.status_code < 300:
+                    logger.debug(f'Request to {url} successful', extra={'attempt': attempt, 'status_code': response.status_code})
                     if not stream:
                         if parse_response:
                             _maybe_parsed_body = self._maybe_parse_response(response)
@@ -154,13 +160,17 @@ def _make_request(stop_retrying: Callable, attempt: int) -> httpx.Response:
                     return response
 
             except Exception as e:
+                logger.debug(f'Request to {url} threw exception', exc_info=e, extra={'attempt': attempt})
                 if not _is_retryable_error(e):
+                    logger.debug('Exception is not retryable', exc_info=e, extra={'attempt': attempt})
                     stop_retrying()
                 raise e
 
             # We want to retry only requests which are server errors (status >= 500) and could resolve on their own,
             # and also retry rate limited requests that throw 429 Too Many Requests errors
+            logger.debug(f'Request to {url} unsuccessful', extra={'attempt': attempt, 'status_code': response.status_code})
             if response.status_code < 500 and response.status_code != HTTPStatus.TOO_MANY_REQUESTS:
+                logger.debug('Status code is not retryable', extra={'attempt': attempt, 'status_code': response.status_code})
                 stop_retrying()
             raise ApifyApiError(response, attempt)
 
@@ -194,6 +204,7 @@ async def call(
         httpx_async_client = self.httpx_async_client
 
         async def _make_request(stop_retrying: Callable, attempt: int) -> httpx.Response:
+            logger.debug('Sending request')
             try:
                 request = httpx_async_client.build_request(
                     method=method,
@@ -209,6 +220,7 @@ async def _make_request(stop_retrying: Callable, attempt: int) -> httpx.Response
 
                 # If response status is < 300, the request was successful, and we can return the result
                 if response.status_code < 300:
+                    logger.debug('Request successful', extra={'status_code': response.status_code})
                     if not stream:
                         if parse_response:
                             _maybe_parsed_body = self._maybe_parse_response(response)
@@ -219,13 +231,17 @@ async def _make_request(stop_retrying: Callable, attempt: int) -> httpx.Response
                     return response
 
             except Exception as e:
+                logger.debug('Request threw exception', exc_info=e)
                 if not _is_retryable_error(e):
+                    logger.debug('Exception is not retryable', exc_info=e)
                     stop_retrying()
                 raise e
 
             # We want to retry only requests which are server errors (status >= 500) and could resolve on their own,
             # and also retry rate limited requests that throw 429 Too Many Requests errors
+            logger.debug('Request unsuccessful', extra={'status_code': response.status_code})
             if response.status_code < 500 and response.status_code != HTTPStatus.TOO_MANY_REQUESTS:
+                logger.debug('Status code is not retryable', extra={'status_code': response.status_code})
                 stop_retrying()
             raise ApifyApiError(response, attempt)
 

src/apify_client/_logging.py

@@ -0,0 +1,94 @@
+import functools
+import inspect
+import json
+import logging
+from contextvars import ContextVar
+from typing import TYPE_CHECKING, Any, Callable, Dict, Optional, Tuple, Type, cast
+
+# Conditional import only executed when type checking, otherwise we'd get circular dependency issues
+if TYPE_CHECKING:
+    from .clients.base.base_client import _BaseBaseClient
+
+# Name of the logger used throughout the library
+logger_name = __name__.split('.')[0]
+
+# Logger used throughout the library
+logger = logging.getLogger(logger_name)
+
+
+# Context variables containing the current resource client running in that context
+# Used during logging to inject the resource client context to the log
+ctx_client_method = ContextVar[Optional[str]]('client_method', default=None)
+ctx_resource_id = ContextVar[Optional[str]]('resource_id', default=None)
+ctx_url = ContextVar[Optional[str]]('url', default=None)
+
+
+# Metaclass for resource clients which wraps all their public methods
+# With injection of their details to the log context vars
+class _WithLogDetailsClient(type):
+    def __new__(cls: Type[type], name: str, bases: Tuple, attrs: Dict) -> '_WithLogDetailsClient':
+        for attr_name, attr_value in attrs.items():
+            if not attr_name.startswith('_'):
+                if inspect.isfunction(attr_value):
+                    attrs[attr_name] = _injects_client_details_to_log_context(attr_value)
+
+        return cast(_WithLogDetailsClient, type.__new__(cls, name, bases, attrs))
+
+
+# Wraps an unbound method so that its call will inject the details
+# of the resource client (which is the `self` argument of the method)
+# to the log context vars
+def _injects_client_details_to_log_context(fun: Callable) -> Callable:
+    if inspect.iscoroutinefunction(fun) or inspect.isasyncgenfunction(fun):
+        @functools.wraps(fun)
+        async def async_wrapper(resource_client: '_BaseBaseClient', *args: Any, **kwargs: Any) -> Any:
+            ctx_client_method.set(fun.__qualname__)
+            ctx_resource_id.set(resource_client.resource_id)
+            ctx_url.set(resource_client.url)
+
+            return await fun(resource_client, *args, **kwargs)
+        return async_wrapper
+    else:
+        @functools.wraps(fun)
+        def wrapper(resource_client: '_BaseBaseClient', *args: Any, **kwargs: Any) -> Any:
+            ctx_client_method.set(fun.__qualname__)
+            ctx_resource_id.set(resource_client.resource_id)
+            ctx_url.set(resource_client.url)
+
+            return fun(resource_client, *args, **kwargs)
+        return wrapper
+
+
+# A filter which lets every log record through,
+# but adds the current logging context to the record
+class _ContextInjectingFilter(logging.Filter):
+    def filter(self, record: logging.LogRecord) -> bool:
+        record.client_method = ctx_client_method.get()
+        record.resource_id = ctx_resource_id.get()
+        record.url = ctx_url.get()
+        return True
+
+
+logger.addFilter(_ContextInjectingFilter())
+
+
+# Log formatter useful for debugging of the client
+# Will print out all the extra fields added to the log record
+class _DebugLogFormatter(logging.Formatter):
+    empty_record = logging.LogRecord('dummy', 0, 'dummy', 0, 'dummy', None, None)
+
+    def _get_extra_fields(self, record: logging.LogRecord) -> Dict[str, Any]:
+        extra_fields: Dict[str, Any] = {}
+        for key, value in record.__dict__.items():
+            if key not in self.empty_record.__dict__:
+                extra_fields[key] = value
+
+        return extra_fields
+
+    def format(self, record: logging.LogRecord) -> str:
+        extra = self._get_extra_fields(record)
+
+        log_string = super().format(record)
+        if extra:
+            log_string = f'{log_string} ({json.dumps(extra)})'
+        return log_string

src/apify_client/clients/base/base_client.py

@@ -3,14 +3,16 @@
 from typing import TYPE_CHECKING, Any, Dict, Optional, Union
 
 from ..._http_client import _HTTPClient, _HTTPClientAsync
+from ..._logging import _WithLogDetailsClient
 from ..._utils import _make_async_docs, _to_safe_id
 
 # Conditional import only executed when type checking, otherwise we'd get circular dependency issues
 if TYPE_CHECKING:
     from ...client import ApifyClient, ApifyClientAsync
 
 
-class _BaseBaseClient:
+class _BaseBaseClient(metaclass=_WithLogDetailsClient):
+    resource_id: Optional[str]
     url: str
     params: Dict
     http_client: Union[_HTTPClient, _HTTPClientAsync]