Merge pull request #102 from NodeJSmith/fix/fix_performance_metric_and_add_logging

- closes #100 
- add more logging, especially where filtering/removal of records happens
- add logic to dump raw response if `OTF_LOG_RAW_RESPONSE` env var is set to true
  - only logging at DEBUG level so need to have that set too, which can be done with OTF_LOG_LEVEL env var
- add `coloredlogs` package to make logs easier to read
- remove headers from request log
- change log format structure slightly, use % formatting
- change some log lines to use % to avoid calling methods/converting to string when not logging at that level
- relax data type on `PerformanceMetric` class, remove custom parsing, was not useful

Author: NodeJSmith

.bumpversion.toml

@@ -1,5 +1,5 @@
 [tool.bumpversion]
-current_version = "0.15.1"
+current_version = "0.15.2"
 
 parse = "(?P<major>\\d+)\\.(?P<minor>\\d+)\\.(?P<patch>\\d+)(?:-(?P<rc_l>rc)(?P<rc>0|[1-9]\\d*))?"
 

pyproject.toml

@@ -1,6 +1,6 @@
 [project]
 name = "otf-api"
-version = "0.15.1"
+version = "0.15.2"
 description = "Python OrangeTheory Fitness API Client"
 authors = [{ name = "Jessica Smith", email = "[email protected]" }]
 requires-python = ">=3.11"
@@ -30,6 +30,7 @@ dependencies = [
     "diskcache>=5.6.3",
     "platformdirs>=4.3.6",
     "packaging>=24.2",
+    "coloredlogs>=15.0.1",
 ]
 
 [project.urls]

source/conf.py

@@ -14,7 +14,7 @@
 project = "OrangeTheory API"
 copyright = "2025, Jessica Smith"
 author = "Jessica Smith"
-release = "0.15.1"
+release = "0.15.2"
 
 # -- General configuration ---------------------------------------------------
 # https://www.sphinx-doc.org/en/master/usage/configuration.html#general-configuration

src/otf_api/__init__.py

@@ -7,13 +7,15 @@
 import logging
 import os
 
+import coloredlogs
+
 from otf_api import models
 from otf_api.api import Otf
 from otf_api.auth import OtfUser
 
 LOG_LEVEL = os.getenv("OTF_LOG_LEVEL", "INFO").upper()
-LOG_LEVEL_NUM = getattr(logging, LOG_LEVEL, logging.INFO)
-LOG_FMT = "{asctime} - {module}.{funcName}:{lineno} - {levelname} - {message}"
+
+LOG_FMT = "%(asctime)s - %(module)s.%(funcName)s:%(lineno)d - %(levelname)s - %(message)s"
 DATE_FMT = "%Y-%m-%d %H:%M:%S%z"
 
 
@@ -24,19 +26,28 @@ def _setup_logging() -> None:
         return  # Already set up
 
     # 2) Set the logger level to INFO (or whatever you need).
-    logger.setLevel(LOG_LEVEL_NUM)
+    logger.setLevel(LOG_LEVEL)
 
     # 3) Create a handler (e.g., console) and set its formatter.
     handler = logging.StreamHandler()
-    handler.setFormatter(logging.Formatter(fmt=LOG_FMT, datefmt=DATE_FMT, style="{"))
+    handler.setFormatter(logging.Formatter(fmt=LOG_FMT, datefmt=DATE_FMT, style="%"))
 
     # 4) Add this handler to your package logger.
     logger.addHandler(handler)
 
+    coloredlogs.install(
+        level=LOG_LEVEL,
+        logger=logger,
+        fmt=LOG_FMT,
+        datefmt=DATE_FMT,
+        style="%",
+        isatty=True,  # Use colored output only if the output is a terminal
+    )
+
 
 _setup_logging()
 
-__version__ = "0.15.1"
+__version__ = "0.15.2"
 
 
 __all__ = ["Otf", "OtfUser", "models"]

src/otf_api/api/bookings/booking_api.py

@@ -8,19 +8,19 @@
 from otf_api import exceptions as exc
 from otf_api import models
 from otf_api.api import utils
-from otf_api.api.client import OtfClient
 from otf_api.models.bookings import HISTORICAL_BOOKING_STATUSES, ClassFilter
 
 from .booking_client import BookingClient
 
 if typing.TYPE_CHECKING:
     from otf_api import Otf
+    from otf_api.api.client import OtfClient
 
 LOGGER = getLogger(__name__)
 
 
 class BookingApi:
-    def __init__(self, otf: "Otf", otf_client: OtfClient):
+    def __init__(self, otf: "Otf", otf_client: "OtfClient"):
         """Initialize the Booking API client.
 
         Args:
@@ -30,6 +30,39 @@ def __init__(self, otf: "Otf", otf_client: OtfClient):
         self.otf = otf
         self.client = BookingClient(otf_client)
 
+    def _get_all_bookings_new(
+        self, exclude_cancelled: bool = True, remove_duplicates: bool = True
+    ) -> list[models.BookingV2]:
+        """Get bookings from the new endpoint with no date filters.
+
+        This is marked as private to avoid random users calling it.
+        Useful for testing and validating models.
+
+        Args:
+            exclude_cancelled (bool): Whether to exclude cancelled bookings. Default is True.
+            remove_duplicates (bool): Whether to remove duplicate bookings. Default is True.
+
+        Returns:
+            list[BookingV2]: List of bookings that match the search criteria.
+        """
+        start_date = pendulum.datetime(1970, 1, 1)
+        end_date = pendulum.today().start_of("day").add(days=45)
+        return self.get_bookings_new(start_date, end_date, exclude_cancelled, remove_duplicates)
+
+    def _get_all_bookings_new_by_date(self) -> dict[datetime, models.BookingV2]:
+        """Get all bookings from the new endpoint by date.
+
+        This is marked as private to avoid random users calling it.
+        Useful for testing and validating models.
+
+        Returns:
+            dict[datetime, BookingV2]: Dictionary of bookings by date.
+        """
+        start_date = pendulum.datetime(1970, 1, 1)
+        end_date = pendulum.today().start_of("day").add(days=45)
+        bookings = self.get_bookings_new_by_date(start_date, end_date)
+        return bookings
+
     def get_bookings_new(
         self,
         start_date: datetime | date | str | None = None,
@@ -79,6 +112,7 @@ def get_bookings_new(
         bookings_resp = self.client.get_bookings_new(
             ends_before=end_date, starts_after=start_date, include_canceled=include_canceled, expand=expand
         )
+        LOGGER.debug("Found %d bookings between %s and %s", len(bookings_resp), start_date, end_date)
 
         # filter out bookings with ids that start with "no-booking-id"
         # no idea what these are, but I am praying for the poor sap stuck with maintaining OTF's data model
@@ -89,7 +123,7 @@ def get_bookings_new(
                 try:
                     results.append(models.BookingV2.create(**b, api=self.otf))
                 except ValueError as e:
-                    LOGGER.warning(f"Failed to create BookingV2 from response: {e}. Booking data:\n{b}")
+                    LOGGER.error("Failed to create BookingV2 from response: %s. Booking data:\n%s", e, b)
                     continue
 
         if not remove_duplicates:
@@ -112,6 +146,9 @@ def _deduplicate_bookings(
             list[BookingV2]: The deduplicated list of bookings.
         """
         # remove duplicates by class_id, keeping the one with the most recent updated_at timestamp
+
+        orig_count = len(results)
+
         seen_classes: dict[str, models.BookingV2] = {}
 
         for booking in results:
@@ -127,11 +164,20 @@ def _deduplicate_bookings(
                     "this is unexpected behavior."
                 )
             if booking.updated_at > existing_booking.updated_at:
+                LOGGER.debug(
+                    "Replacing existing booking for class_id %s with more recent booking %s", class_id, booking
+                )
                 seen_classes[class_id] = booking
 
         results = list(seen_classes.values())
         results = sorted(results, key=lambda x: x.starts_at)
 
+        new_count = len(results)
+        diff = orig_count - new_count
+
+        if diff:
+            LOGGER.debug("Removed %d duplicate bookings, returning %d unique bookings", diff, new_count)
+
         return results
 
     def get_bookings_new_by_date(
@@ -615,36 +661,3 @@ def rate_class(
             if e.response.status_code == 403:
                 raise exc.AlreadyRatedError(f"Workout {performance_summary_id} is already rated.") from None
             raise
-
-    def _get_all_bookings_new(
-        self, exclude_cancelled: bool = True, remove_duplicates: bool = True
-    ) -> list[models.BookingV2]:
-        """Get bookings from the new endpoint with no date filters.
-
-        This is marked as private to avoid random users calling it.
-        Useful for testing and validating models.
-
-        Args:
-            exclude_cancelled (bool): Whether to exclude cancelled bookings. Default is True.
-            remove_duplicates (bool): Whether to remove duplicate bookings. Default is True.
-
-        Returns:
-            list[BookingV2]: List of bookings that match the search criteria.
-        """
-        start_date = pendulum.datetime(1970, 1, 1)
-        end_date = pendulum.today().start_of("day").add(days=45)
-        return self.get_bookings_new(start_date, end_date, exclude_cancelled, remove_duplicates)
-
-    def _get_all_bookings_new_by_date(self) -> dict[datetime, models.BookingV2]:
-        """Get all bookings from the new endpoint by date.
-
-        This is marked as private to avoid random users calling it.
-        Useful for testing and validating models.
-
-        Returns:
-            dict[datetime, BookingV2]: Dictionary of bookings by date.
-        """
-        start_date = pendulum.datetime(1970, 1, 1)
-        end_date = pendulum.today().start_of("day").add(days=45)
-        bookings = self.get_bookings_new_by_date(start_date, end_date)
-        return bookings

src/otf_api/api/client.py

@@ -1,4 +1,6 @@
 import atexit
+import json
+import os
 import re
 from json import JSONDecodeError
 from logging import getLogger
@@ -47,6 +49,7 @@ def __init__(self, user: OtfUser | None = None):
         self.session = httpx.Client(
             headers=HEADERS, auth=self.user.httpx_auth, timeout=httpx.Timeout(20.0, connect=60.0)
         )
+        self.log_raw_response = os.getenv("OTF_LOG_RAW_RESPONSE", "false").lower() == "true"
         atexit.register(self.session.close)
 
     def __getstate__(self):
@@ -110,7 +113,7 @@ def do(
         """
         full_url = str(URL.build(scheme="https", host=base_url, path=path))
         request = self._build_request(method, full_url, params, headers, **kwargs)
-        LOGGER.debug(f"Making {method!r} request to '{full_url}', params: {params}, headers: {headers}")
+        LOGGER.debug("Making %r request to '%s'", method, str(request.url))
 
         try:
             response = self.session.send(request)
@@ -158,10 +161,14 @@ def _map_http_error(
             if error_code == "602":
                 raise exc.OutsideSchedulingWindowError("Class is outside scheduling window")
 
-        msg = f"HTTP error {error.response.status_code} for {request.method} {request.url}"
-        LOGGER.error(msg)
+        LOGGER.error("HTTP error %s for %s %s", response.status_code, request.method, request.url)
         error_cls = exc.RetryableOtfRequestError if response.status_code >= 500 else exc.OtfRequestError
-        raise error_cls(message=msg, original_exception=error, request=request, response=response)
+        raise error_cls(
+            message=f"HTTP error {response.status_code} for {request.method} {request.url}",
+            original_exception=error,
+            request=request,
+            response=response,
+        )
 
     def _handle_transport_error(self, error: Exception, request: httpx.Request) -> None:
         """Handle transport errors during API requests.
@@ -177,7 +184,7 @@ def _handle_transport_error(self, error: Exception, request: httpx.Request) -> N
         url = request.url
 
         if not isinstance(error, httpx.HTTPStatusError):
-            LOGGER.exception(f"Unexpected error during {method!r} {url!r}: {type(error).__name__} - {error}")
+            LOGGER.exception("Unexpected error during %r %r: %s - %s", method, url, type(error).__name__, error)
             return
 
         json_data = get_json_from_response(error.response)
@@ -190,7 +197,7 @@ def _map_logical_error(self, data: dict, response: httpx.Response, request: http
         data_status: int | None = data.get("Status") or data.get("status") or None
 
         if isinstance(data, dict) and isinstance(data_status, int) and not 200 <= data_status <= 299:
-            LOGGER.error(f"API returned error: {data}")
+            LOGGER.error("API returned error: %s", data)
             raise exc.OtfRequestError("Bad API response", None, response=response, request=request)
 
         raise exc.OtfRequestError(
@@ -202,17 +209,20 @@ def _handle_response(self, method: str, response: httpx.Response, request: httpx
             if method == "GET":
                 raise exc.OtfRequestError("Empty response", None, response=response, request=request)
 
-            LOGGER.debug(f"No content returned from {method} {response.url}")
+            LOGGER.debug("No content returned from %s %s", method, response.url)
             return None
 
         try:
             json_data = response.json()
         except JSONDecodeError as e:
-            LOGGER.error(f"Invalid JSON: {e}")
-            LOGGER.error(f"Response content: {response.text}")
+            LOGGER.error("Invalid JSON: %s", e)
+            LOGGER.error("Response content: %s", response.text)
             raise
 
         if is_error_response(json_data):
             self._map_logical_error(json_data, response, request)
 
+        if self.log_raw_response:
+            LOGGER.debug("Response from %s %s: %s", method, response.url, json.dumps(json_data, indent=4))
+
         return json_data

src/otf_api/api/members/member_api.py

@@ -3,18 +3,18 @@
 from typing import Any
 
 from otf_api import models
-from otf_api.api.client import OtfClient
 
 from .member_client import MemberClient
 
 if typing.TYPE_CHECKING:
     from otf_api import Otf
+    from otf_api.api.client import OtfClient
 
 LOGGER = getLogger(__name__)
 
 
 class MemberApi:
-    def __init__(self, otf: "Otf", otf_client: OtfClient):
+    def __init__(self, otf: "Otf", otf_client: "OtfClient"):
         """Initialize the Member API client.
 
         Args: