diff --git a/src/marketdata/api_status.py b/src/marketdata/api_status.py index 97133b6..f803528 100644 --- a/src/marketdata/api_status.py +++ b/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) diff --git a/src/marketdata/client.py b/src/marketdata/client.py index d20c840..d271bc6 100644 --- a/src/marketdata/client.py +++ b/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 diff --git a/src/marketdata/resources/base.py b/src/marketdata/resources/base.py index a98560c..1515c4d 100644 --- a/src/marketdata/resources/base.py +++ b/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, diff --git a/src/marketdata/resources/funds/candles.py b/src/marketdata/resources/funds/candles.py index 471a431..85b3f3b 100644 --- a/src/marketdata/resources/funds/candles.py +++ b/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) diff --git a/src/marketdata/resources/markets/status.py b/src/marketdata/resources/markets/status.py index a2267a8..74fb51e 100644 --- a/src/marketdata/resources/markets/status.py +++ b/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) diff --git a/src/marketdata/resources/options/chain.py b/src/marketdata/resources/options/chain.py index ebb2b8d..8530cac 100644 --- a/src/marketdata/resources/options/chain.py +++ b/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) diff --git a/src/marketdata/resources/options/expirations.py b/src/marketdata/resources/options/expirations.py index 302fc10..88dc7c7 100644 --- a/src/marketdata/resources/options/expirations.py +++ b/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) diff --git a/src/marketdata/resources/options/lookup.py b/src/marketdata/resources/options/lookup.py index 3e85d00..86abb16 100644 --- a/src/marketdata/resources/options/lookup.py +++ b/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) diff --git a/src/marketdata/resources/options/quotes.py b/src/marketdata/resources/options/quotes.py index 823989b..096ef95 100644 --- a/src/marketdata/resources/options/quotes.py +++ b/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 diff --git a/src/marketdata/resources/options/strikes.py b/src/marketdata/resources/options/strikes.py index d65603a..67c5de1 100644 --- a/src/marketdata/resources/options/strikes.py +++ b/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) diff --git a/src/marketdata/resources/stocks/candles.py b/src/marketdata/resources/stocks/candles.py index 8724078..a3cc450 100644 --- a/src/marketdata/resources/stocks/candles.py +++ b/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 = [ diff --git a/src/marketdata/resources/stocks/earnings.py b/src/marketdata/resources/stocks/earnings.py index a75120d..60b53f3 100644 --- a/src/marketdata/resources/stocks/earnings.py +++ b/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) diff --git a/src/marketdata/resources/stocks/news.py b/src/marketdata/resources/stocks/news.py index c0d156c..0167f01 100644 --- a/src/marketdata/resources/stocks/news.py +++ b/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) diff --git a/src/marketdata/resources/stocks/prices.py b/src/marketdata/resources/stocks/prices.py index c48f7bb..4146c28 100644 --- a/src/marketdata/resources/stocks/prices.py +++ b/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 = ( diff --git a/src/marketdata/resources/stocks/quotes.py b/src/marketdata/resources/stocks/quotes.py index aa0329d..ef552b6 100644 --- a/src/marketdata/resources/stocks/quotes.py +++ b/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) diff --git a/src/marketdata/utils.py b/src/marketdata/utils.py index e855f6a..7c08f96 100644 --- a/src/marketdata/utils.py +++ b/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) diff --git a/src/tests/test_client.py b/src/tests/test_client.py index ab72082..c3a0078 100644 --- a/src/tests/test_client.py +++ b/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}" + ) diff --git a/src/tests/test_utils.py b/src/tests/test_utils.py index 5738167..586528c 100644 --- a/src/tests/test_utils.py +++ b/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"