diff --git a/CHANGELOG.md b/CHANGELOG.md index 42ccef9a..4ff15d15 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,6 +1,13 @@ Changelog ========= +[1.4.1](../../releases/tag/v1.4.1) - Unreleased +----------------------------------------------- + +### Internal changes + +- Improved logging of HTTP requests + [1.4.0](../../releases/tag/v1.4.0) - 2023-08-22 ----------------------------------------------- diff --git a/pyproject.toml b/pyproject.toml index 020cb64f..fb9400dd 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -1,6 +1,6 @@ [project] name = "apify_client" -version = "1.4.0" +version = "1.4.1" description = "Apify API client for Python" readme = "README.md" license = {text = "Apache Software License"} diff --git a/src/apify_client/_http_client.py b/src/apify_client/_http_client.py index e83709d9..7bacc847 100644 --- a/src/apify_client/_http_client.py +++ b/src/apify_client/_http_client.py @@ -13,7 +13,7 @@ from apify_shared.utils import ignore_docs, is_content_type_json, is_content_type_text, is_content_type_xml from ._errors import ApifyApiError, InvalidResponseBodyError, _is_retryable_error -from ._logging import logger_name +from ._logging import log_context, logger_name from ._utils import _retry_with_exp_backoff, _retry_with_exp_backoff_async DEFAULT_BACKOFF_EXPONENTIAL_FACTOR = 2 @@ -133,6 +133,9 @@ def call( stream: Optional[bool] = None, parse_response: Optional[bool] = True, ) -> httpx.Response: + log_context.method.set(method) + log_context.url.set(url) + if stream and parse_response: raise ValueError('Cannot stream response and parse it at the same time!') @@ -141,7 +144,8 @@ 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}) + log_context.attempt.set(attempt) + logger.debug('Sending request') try: request = httpx_client.build_request( method=method, @@ -157,7 +161,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}) + logger.debug('Request successful', extra={'status_code': response.status_code}) if not stream: if parse_response: _maybe_parsed_body = self._maybe_parse_response(response) @@ -168,17 +172,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}) + logger.debug('Request threw exception', exc_info=e) if not _is_retryable_error(e): - logger.debug('Exception is not retryable', exc_info=e, extra={'attempt': attempt}) + 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(f'Request to {url} unsuccessful', extra={'attempt': attempt, 'status_code': response.status_code}) + 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={'attempt': attempt, 'status_code': response.status_code}) + logger.debug('Status code is not retryable', extra={'status_code': response.status_code}) stop_retrying() raise ApifyApiError(response, attempt) @@ -204,6 +208,9 @@ async def call( stream: Optional[bool] = None, parse_response: Optional[bool] = True, ) -> httpx.Response: + log_context.method.set(method) + log_context.url.set(url) + if stream and parse_response: raise ValueError('Cannot stream response and parse it at the same time!') @@ -212,6 +219,7 @@ async def call( httpx_async_client = self.httpx_async_client async def _make_request(stop_retrying: Callable, attempt: int) -> httpx.Response: + log_context.attempt.set(attempt) logger.debug('Sending request') try: request = httpx_async_client.build_request( diff --git a/src/apify_client/_logging.py b/src/apify_client/_logging.py index 1033e712..f568bf5f 100644 --- a/src/apify_client/_logging.py +++ b/src/apify_client/_logging.py @@ -3,7 +3,7 @@ import json import logging from contextvars import ContextVar -from typing import TYPE_CHECKING, Any, Callable, Dict, Optional, Tuple, Type, cast +from typing import TYPE_CHECKING, Any, Callable, Dict, NamedTuple, Optional, Tuple, Type, cast # Conditional import only executed when type checking, otherwise we'd get circular dependency issues if TYPE_CHECKING: @@ -15,12 +15,22 @@ # Logger used throughout the library logger = logging.getLogger(logger_name) +# Context containing the details of the request and the resource client making the request +LogContext = NamedTuple('LogContext', [ + ('attempt', ContextVar[Optional[int]]), + ('client_method', ContextVar[Optional[str]]), + ('method', ContextVar[Optional[str]]), + ('resource_id', ContextVar[Optional[str]]), + ('url', ContextVar[Optional[str]]), +]) -# 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) +log_context = LogContext( + attempt=ContextVar('attempt', default=None), + client_method=ContextVar('client_method', default=None), + method=ContextVar('method', default=None), + resource_id=ContextVar('resource_id', default=None), + url=ContextVar('url', default=None), +) # Metaclass for resource clients which wraps all their public methods @@ -41,18 +51,16 @@ def _injects_client_details_to_log_context(fun: Callable) -> Callable: if inspect.iscoroutinefunction(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) + log_context.client_method.set(fun.__qualname__) + log_context.resource_id.set(resource_client.resource_id) return await fun(resource_client, *args, **kwargs) return async_wrapper elif inspect.isasyncgenfunction(fun): @functools.wraps(fun) async def async_generator_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) + log_context.client_method.set(fun.__qualname__) + log_context.resource_id.set(resource_client.resource_id) async for item in fun(resource_client, *args, **kwargs): yield item @@ -60,9 +68,8 @@ async def async_generator_wrapper(resource_client: '_BaseBaseClient', *args: Any 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) + log_context.client_method.set(fun.__qualname__) + log_context.resource_id.set(resource_client.resource_id) return fun(resource_client, *args, **kwargs) return wrapper @@ -72,9 +79,11 @@ def wrapper(resource_client: '_BaseBaseClient', *args: Any, **kwargs: Any) -> An # 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() + record.client_method = log_context.client_method.get() + record.resource_id = log_context.resource_id.get() + record.method = log_context.method.get() + record.url = log_context.url.get() + record.attempt = log_context.attempt.get() return True @@ -86,6 +95,7 @@ def filter(self, record: logging.LogRecord) -> bool: class _DebugLogFormatter(logging.Formatter): empty_record = logging.LogRecord('dummy', 0, 'dummy', 0, 'dummy', None, None) + # Gets the extra fields from the log record which are not present on an empty record def _get_extra_fields(self, record: logging.LogRecord) -> Dict[str, Any]: extra_fields: Dict[str, Any] = {} for key, value in record.__dict__.items():