feat(client): add logging setup

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`:

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"

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.

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)
 

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:

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()

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)

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]: