diff --git a/README.md b/README.md index 605cb23f..12a04b7f 100644 --- a/README.md +++ b/README.md @@ -274,6 +274,16 @@ client = Finch( ## Advanced +### Logging + +We use the standard library [`logging`](https://docs.python.org/3/library/logging.html) module. + +You can enable logging by setting the environment variable `FINCH_LOG` to `debug`. + +```shell +$ export FINCH_LOG=debug +``` + ### How to tell whether `None` means `null` or missing In an API response, a field may be explicitly `null`, or missing entirely; in either case, its value is `None` in this library. You can differentiate the two cases with `.model_fields_set`: diff --git a/pyproject.toml b/pyproject.toml index 8bdffb3f..b3c0b746 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -47,8 +47,6 @@ target-version = ["py37"] testpaths = ["tests"] addopts = "--tb=short" xfail_strict = true -log_cli = true -log_level = "INFO" asyncio_mode = "auto" filterwarnings = [ "error" diff --git a/src/finch/__init__.py b/src/finch/__init__.py index f8e4ab2e..c720161f 100644 --- a/src/finch/__init__.py +++ b/src/finch/__init__.py @@ -31,6 +31,7 @@ UnprocessableEntityError, APIResponseValidationError, ) +from ._utils._logs import setup_logging as _setup_logging __all__ = [ "types", @@ -64,6 +65,8 @@ "file_from_path", ] +_setup_logging() + # Update the __module__ attribute for exported symbols so that # error messages point to this module instead of the module # it was originally defined in, e.g. diff --git a/src/finch/_base_client.py b/src/finch/_base_client.py index e72ead11..eb5efec2 100644 --- a/src/finch/_base_client.py +++ b/src/finch/_base_client.py @@ -5,6 +5,7 @@ import uuid import email import inspect +import logging import platform import warnings import email.utils @@ -60,7 +61,7 @@ ModelBuilderProtocol, ) from ._utils import is_dict, is_given, is_mapping -from ._compat import model_copy +from ._compat import model_copy, model_dump from ._models import ( BaseModel, GenericModel, @@ -76,6 +77,8 @@ APIResponseValidationError, ) +log: logging.Logger = logging.getLogger(__name__) + # TODO: make base page type vars covariant SyncPageT = TypeVar("SyncPageT", bound="BaseSyncPage[Any]") AsyncPageT = TypeVar("AsyncPageT", bound="BaseAsyncPage[Any]") @@ -428,7 +431,8 @@ def _build_request( self, options: FinalRequestOptions, ) -> httpx.Request: - headers = self._build_headers(options) + if log.isEnabledFor(logging.DEBUG): + log.debug("Request options: %s", model_dump(options, exclude_unset=True)) kwargs: dict[str, Any] = {} @@ -441,6 +445,7 @@ def _build_request( else: raise RuntimeError(f"Unexpected JSON data type, {type(json_data)}, cannot merge with `extra_body`") + headers = self._build_headers(options) params = _merge_mappings(self._custom_query, options.params) # If the given Content-Type header is multipart/form-data then it @@ -893,6 +898,9 @@ def _request( try: response = self._client.send(request, auth=self.custom_auth, stream=stream) + log.debug( + 'HTTP Request: %s %s "%i %s"', request.method, request.url, response.status_code, response.reason_phrase + ) response.raise_for_status() except httpx.HTTPStatusError as err: # thrown on 4xx and 5xx status code if retries > 0 and self._should_retry(err.response): @@ -941,6 +949,7 @@ def _retry_request( ) -> ResponseT | _StreamT: remaining = remaining_retries - 1 timeout = self._calculate_retry_timeout(remaining, options, response_headers) + log.info("Retrying request to %s in %f seconds", options.url, timeout) # In a synchronous context we are blocking the entire thread. Up to the library user to run the client in a # different thread if necessary. @@ -1292,6 +1301,9 @@ async def _request( try: response = await self._client.send(request, auth=self.custom_auth, stream=stream) + log.debug( + 'HTTP Request: %s %s "%i %s"', request.method, request.url, response.status_code, response.reason_phrase + ) response.raise_for_status() except httpx.HTTPStatusError as err: # thrown on 4xx and 5xx status code if retries > 0 and self._should_retry(err.response): @@ -1350,6 +1362,7 @@ async def _retry_request( ) -> ResponseT | _AsyncStreamT: remaining = remaining_retries - 1 timeout = self._calculate_retry_timeout(remaining, options, response_headers) + log.info("Retrying request to %s in %f seconds", options.url, timeout) await anyio.sleep(timeout) diff --git a/src/finch/_compat.py b/src/finch/_compat.py index fed1df05..5a7ce61b 100644 --- a/src/finch/_compat.py +++ b/src/finch/_compat.py @@ -126,10 +126,24 @@ def model_json(model: pydantic.BaseModel, *, indent: int | None = None) -> str: return model.json(indent=indent) # type: ignore -def model_dump(model: pydantic.BaseModel) -> dict[str, Any]: +def model_dump( + model: pydantic.BaseModel, + *, + exclude_unset: bool = False, + exclude_defaults: bool = False, +) -> dict[str, Any]: if PYDANTIC_V2: - return model.model_dump() - return cast("dict[str, Any]", model.dict()) # pyright: ignore[reportDeprecated, reportUnnecessaryCast] + return model.model_dump( + exclude_unset=exclude_unset, + exclude_defaults=exclude_defaults, + ) + return cast( + "dict[str, Any]", + model.dict( # pyright: ignore[reportDeprecated, reportUnnecessaryCast] + exclude_unset=exclude_unset, + exclude_defaults=exclude_defaults, + ), + ) def model_parse(model: type[_ModelT], data: Any) -> _ModelT: diff --git a/src/finch/_types.py b/src/finch/_types.py index d32a6871..45e89382 100644 --- a/src/finch/_types.py +++ b/src/finch/_types.py @@ -104,6 +104,9 @@ def get(timeout: Union[int, NotGiven, None] = NotGiven()) -> Response: ... def __bool__(self) -> Literal[False]: return False + def __repr__(self) -> str: + return "NOT_GIVEN" + NotGivenOr = Union[_T, NotGiven] NOT_GIVEN = NotGiven() diff --git a/src/finch/_utils/_logs.py b/src/finch/_utils/_logs.py new file mode 100644 index 00000000..92371a4e --- /dev/null +++ b/src/finch/_utils/_logs.py @@ -0,0 +1,25 @@ +import os +import logging + +logger: logging.Logger = logging.getLogger("finch") +httpx_logger: logging.Logger = logging.getLogger("httpx") + + +def _basic_config() -> None: + # e.g. [2023-10-05 14:12:26 - finch._base_client:818 - DEBUG] HTTP Request: POST http://127.0.0.1:4010/foo/bar "200 OK" + logging.basicConfig( + format="[%(asctime)s - %(name)s:%(lineno)d - %(levelname)s] %(message)s", + datefmt="%Y-%m-%d %H:%M:%S", + ) + + +def setup_logging() -> None: + env = os.environ.get("FINCH_LOG") + if env == "debug": + _basic_config() + logger.setLevel(logging.DEBUG) + httpx_logger.setLevel(logging.DEBUG) + elif env == "info": + _basic_config() + logger.setLevel(logging.INFO) + httpx_logger.setLevel(logging.INFO) diff --git a/tests/conftest.py b/tests/conftest.py index dd8bbe4c..f981b45d 100644 --- a/tests/conftest.py +++ b/tests/conftest.py @@ -1,10 +1,13 @@ import asyncio +import logging from typing import Iterator import pytest pytest.register_assert_rewrite("tests.utils") +logging.getLogger("finch").setLevel(logging.DEBUG) + @pytest.fixture(scope="session") def event_loop() -> Iterator[asyncio.AbstractEventLoop]: