IMPROVE: Resource logs lifecycle on client

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)
 

src/marketdata/resources/stocks/candles.py

@@ -74,9 +74,6 @@ def _get_response(
             extra_params=kwargs,
             excluded_params=["symbol", "resolution"],
         )
-        self.logger.debug(
-            f"Fetching stock candles for symbol: {symbol} using url: {url}"
-        )
         return self.client._make_request(method="GET", url=url)
 
     if input_params.from_date is not None:
@@ -91,6 +88,7 @@ def _get_response(
     else:
         year_ranges = [(None, None)]
 
+    self.logger.debug("Fetching stock candles...")
     responses = []
     with ThreadPoolExecutor(max_workers=MAX_CONCURRENT_REQUESTS) as executor:
         futures = [

src/marketdata/resources/stocks/earnings.py

@@ -47,7 +47,7 @@ def earnings(
         excluded_params=["symbol"],
     )
 
-    self.logger.debug(f"Fetching stock earnings for symbol: {symbol} using url: {url}")
+    self.logger.debug("Fetching stock earnings...")
 
     response = self.client._make_request(method="GET", url=url)
 

src/marketdata/resources/stocks/news.py

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

src/marketdata/resources/stocks/prices.py

@@ -48,8 +48,7 @@ def prices(
         extra_params=kwargs,
     )
 
-    self.logger.debug(f"Fetching stock prices for symbols: {symbols} using url: {url}")
-
+    self.logger.debug("Fetching stock prices...")
     response = self.client._make_request(method="GET", url=url)
 
     output_model = (

src/marketdata/resources/stocks/quotes.py

@@ -45,7 +45,7 @@ def quotes(
         input_params=input_params,
         extra_params=kwargs,
     )
-    self.logger.debug(f"Fetching stock quotes for symbols: {symbols} using url: {url}")
+    self.logger.debug("Fetching stock quotes...")
 
     response = self.client._make_request(method="GET", url=url)
 

src/marketdata/utils.py

@@ -128,3 +128,13 @@ def get_data_records(data: dict, exclude_keys: list[str] = None) -> list[dict]:
             values.append([v] * max_len)
 
     return [dict(zip(keys, row)) for row in zip(*values)]
+
+
+def format_duration_log(duration_ms: float) -> str:
+    if duration_ms < 1000:
+        return f"{int(duration_ms):03d}ms"
+    elif duration_ms < 10000:
+        return f"{duration_ms / 1000:.2f}s"
+    elif duration_ms < 100000:
+        return f"{duration_ms / 1000:04.1f}s"
+    return f"{duration_ms / 1000:.0f}s".rjust(5)

src/tests/test_client.py

@@ -17,6 +17,7 @@
 from marketdata.sdk_error import MarketDataClientErrorResult
 from marketdata.settings import settings
 from marketdata.types import UserRateLimits
+from marketdata.utils import format_duration_log
 
 
 def test_get_retry_adapter(client):
@@ -290,3 +291,28 @@ def test_client_extract_rate_limits(respx_mock):
         == expected
     )
     assert user_rate_limits.requests_consumed == 1
+
+
+def test_client_pre_and_post_request_logs(client, respx_mock):
+    headers = {
+        "cf-ray": "1234567890",
+        "x-api-ratelimit-limit": "60",
+        "x-api-ratelimit-remaining": "59",
+        "x-api-ratelimit-reset": "1734567890",
+        "x-api-ratelimit-consumed": "1",
+    }
+    respx_mock.get("https://api.marketdata.app/v1/stocks/prices/").respond(
+        json={}, status_code=200, headers=headers
+    )
+    client = MarketDataClient(token="test")
+
+    with patch.object(client.logger, "log") as mock_logger_info:
+        with patch(
+            "marketdata.client.format_duration_log", return_variable="000ms"
+        ) as mock_format:
+            mock_format.return_value = "000ms"
+            client.stocks.prices(symbols="AAPL")
+            last_request = respx_mock.calls.last
+            mock_logger_info.call_args_list[0].assert_called_with(
+                f"GET 200 000ms 1234567890 {last_request.request.url}"
+            )

src/tests/test_utils.py

@@ -6,6 +6,7 @@
 from marketdata.input_types.base import DateFormat, OutputFormat
 from marketdata.utils import (
     check_is_date,
+    format_duration_log,
     format_timestamp,
     merge_csv_texts,
     resume_long_text,
@@ -115,3 +116,27 @@ def test_resume_long_text():
     assert resume_long_text(text, 1000) == text[:1000] + "..."
     assert resume_long_text(text, 10000) == text[:10000] + "..."
     assert resume_long_text(text, 100000) == text
+
+
+def test_format_duration_ms():
+    assert format_duration_log(45) == "045ms"
+    assert format_duration_log(999) == "999ms"
+    assert format_duration_log(0) == "000ms"
+
+
+def test_format_duration_single_digit_s():
+    assert format_duration_log(1230) == "1.23s"
+    assert format_duration_log(1000) == "1.00s"
+    assert format_duration_log(9990) == "9.99s"
+
+
+def test_format_duration_double_digit_s():
+    assert format_duration_log(12300) == "12.3s"
+    assert format_duration_log(10000) == "10.0s"
+    assert format_duration_log(99000) == "99.0s"
+    assert format_duration_log(99900) == "99.9s"
+
+
+def test_format_duration_hundred_s():
+    assert format_duration_log(100000) == " 100s"
+    assert format_duration_log(123456) == " 123s"