Merge pull request #4 from MarketDataApp/RESOURCE_LOGGING

IMPROVE: Resource logs lifecycle on client

Author: MarketDataDev01

src/marketdata/api_status.py

@@ -1,4 +1,5 @@
 import datetime
+import logging
 from enum import Enum
 from typing import TYPE_CHECKING
 
@@ -76,6 +77,7 @@ def refresh(self, client: "MarketDataClient") -> bool:
                 check_rate_limits=False,
                 include_api_version=False,
                 populate_rate_limits=False,
+                response_log_level=logging.DEBUG,
             )
             data = response.json()
             self.update(data)

src/marketdata/client.py

@@ -1,5 +1,5 @@
 from importlib.metadata import version
-from logging import Logger
+from logging import DEBUG, INFO, Logger
 from typing import Callable
 
 from httpx import Client, HTTPStatusError, Response
@@ -18,6 +18,7 @@
 from marketdata.resources.stocks import StocksResource
 from marketdata.settings import settings
 from marketdata.types import UserRateLimits
+from marketdata.utils import format_duration_log
 
 
 class MarketDataClient:
@@ -134,10 +135,11 @@ def _setup_rate_limits(self):
         self.logger.debug("Setting up rate limits")
         self._make_request(
             method="GET",
-            url="/user/",
+            url="user/",
             check_rate_limits=False,
             include_api_version=False,
             populate_rate_limits=True,
+            response_log_level=DEBUG,
         )
 
     def _extract_rate_limits(self, response: Response) -> UserRateLimits:
@@ -149,6 +151,18 @@ def _extract_rate_limits(self, response: Response) -> UserRateLimits:
             requests_consumed=int(response.headers["x-api-ratelimit-consumed"]),
         )
 
+    def _pre_request_logs(self, method: str, url: str, **kwargs):
+        self.logger.debug(f"Making request to URL: {self.base_url}/{url}")
+
+    def _post_request_logs(self, response: Response, response_log_level: int = INFO):
+        cf_request_id = response.headers.get("cf-ray")
+        duration = format_duration_log(response.elapsed.total_seconds() * 1000)
+        method = response.request.method
+        status = response.status_code
+        url = response.request.url
+        message = f"{method} {status} {duration} {cf_request_id} {url}"
+        self.logger.log(response_log_level, message)
+
     def _make_request(
         self,
         method: str,
@@ -159,6 +173,7 @@ def _make_request(
         timeout: int = HTTP_TIMEOUT,
         retry_status_codes: list[int] = RETRY_STATUS_CODES,
         raise_for_status: bool = True,
+        response_log_level: int = INFO,
         **kwargs,
     ) -> Response:
         if self.token is NO_TOKEN_VALUE:
@@ -169,7 +184,9 @@ def _make_request(
         if include_api_version:
             url = f"{self.api_version}/{url}"
 
+        self._pre_request_logs(method, url, **kwargs)
         response = self.client.request(method, url, **kwargs, timeout=timeout)
+        self._post_request_logs(response, response_log_level)
 
         self._validate_response_status_code(
             response, retry_status_codes, raise_for_status

src/marketdata/resources/base.py

@@ -18,7 +18,9 @@ class BaseResource:
     def __init__(self, client: "MarketDataClient"):
         self.client = client
         self.logger = self.client.logger
-        self.logger.info(f"Initializing {self.__class__.__name__} API handler resource")
+        self.logger.debug(
+            f"Initializing {self.__class__.__name__} API handler resource"
+        )
 
     def _build_url(
         self,

src/marketdata/resources/funds/candles.py

@@ -38,7 +38,7 @@ def candles(
         extra_params=kwargs,
         excluded_params=["symbol", "resolution"],
     )
-    self.logger.debug(f"Fetching funds candles for symbol: {symbol} using url: {url}")
+    self.logger.debug("Fetching funds candles ...")
 
     response = self.client._make_request(method="GET", url=url)
 

src/marketdata/resources/markets/status.py

@@ -42,7 +42,7 @@ def status(
         extra_params=kwargs,
         excluded_params=[],
     )
-    self.logger.debug(f"Fetching market status using url: {url}")
+    self.logger.debug("Fetching market status...")
 
     response = self.client._make_request(method="GET", url=url)
 

src/marketdata/resources/options/chain.py

@@ -31,7 +31,6 @@ def chain(
     """
     Fetches the options chain for a given symbol with extensive filtering options.
     """
-    self.logger.debug(f"Fetching options chain for symbol: {symbol}")
     user_universal_params = self._validate_user_universal_params(
         self.client.default_params, user_universal_params
     )
@@ -44,7 +43,7 @@ def chain(
         excluded_params=["symbol"],
     )
 
-    self.logger.debug(f"Using {symbol} with url: {url}")
+    self.logger.debug("Fetching options chain...")
 
     response = self.client._make_request(method="GET", url=url)
 

src/marketdata/resources/options/expirations.py

@@ -35,7 +35,6 @@ def expirations(
     """
     Fetches available expiration dates for a given symbol.
     """
-    self.logger.debug(f"Fetching options expirations for symbol: {symbol}")
     user_universal_params = self._validate_user_universal_params(
         self.client.default_params, user_universal_params
     )
@@ -47,7 +46,7 @@ def expirations(
         extra_params=kwargs,
         excluded_params=["symbol"],
     )
-    self.logger.debug(f"Using {symbol} with url: {url}")
+    self.logger.debug("Fetching options expirations...")
 
     response = self.client._make_request(method="GET", url=url)
 

src/marketdata/resources/options/lookup.py

@@ -37,7 +37,6 @@ def lookup(
     Fetches options lookup data for a given lookup string.
     The lookup string should contain the underlying symbol, expiration date, strike price, and option side.
     """
-    self.logger.debug(f"Fetching options lookup for lookup: {lookup}")
     user_universal_params = self._validate_user_universal_params(
         self.client.default_params, user_universal_params
     )
@@ -54,7 +53,7 @@ def lookup(
         extra_params=kwargs,
         excluded_params=excluded_params,
     )
-    self.logger.debug(f"Using {lookup} with url: {url}")
+    self.logger.debug("Fetching options lookup...")
 
     response = self.client._make_request(method="GET", url=url)
 

src/marketdata/resources/options/quotes.py

@@ -56,10 +56,10 @@ def _get_response(symbol: str) -> Response:
             extra_params=kwargs,
             excluded_params=["symbols"],
         )
-        self.logger.debug(f"Using {symbol} with url: {url}")
         response = self.client._make_request(method="GET", url=url)
         return response
 
+    self.logger.debug("Fetching options quotes...")
     with ThreadPoolExecutor(max_workers=MAX_CONCURRENT_REQUESTS) as executor:
         futures = [
             executor.submit(_get_response, symbol) for symbol in input_params.symbols

src/marketdata/resources/options/strikes.py

@@ -35,7 +35,6 @@ def strikes(
     """
     Fetches available strikes for a given symbol.
     """
-    self.logger.debug(f"Fetching options strikes for symbol: {symbol}")
     user_universal_params = self._validate_user_universal_params(
         self.client.default_params, user_universal_params
     )
@@ -47,7 +46,7 @@ def strikes(
         extra_params=kwargs,
         excluded_params=["symbol"],
     )
-    self.logger.debug(f"Using {symbol} with url: {url}")
+    self.logger.debug("Fetching options strikes...")
 
     response = self.client._make_request(method="GET", url=url)