From 5fbec54ebba3fefaf187ed6d44406c4e64ad493f Mon Sep 17 00:00:00 2001 From: Alex Golec Date: Tue, 22 Feb 2022 06:42:44 -0800 Subject: [PATCH] Use lazy log evaluation throughout (#296) * Use lazy log evaluation throughout * Force client tests to eagerly evaluate --- tda/auth.py | 48 ++++++++++++++++++-------------------- tda/client/asynchronous.py | 19 ++++++++------- tda/client/base.py | 4 ++-- tda/client/synchronous.py | 19 ++++++++------- tda/debug.py | 2 +- tda/streaming.py | 18 +++++++------- tda/utils.py | 8 +++++++ tests/client_test.py | 9 ++++--- 8 files changed, 69 insertions(+), 58 deletions(-) diff --git a/tda/auth.py b/tda/auth.py index 9773c2c..550aa2a 100644 --- a/tda/auth.py +++ b/tda/auth.py @@ -14,6 +14,7 @@ from tda.client import AsyncClient, Client from tda.debug import register_redactions +from tda.utils import LazyLog TOKEN_ENDPOINT = 'https://api.tdameritrade.com/v1/oauth2/token' @@ -25,7 +26,7 @@ def get_logger(): def __update_token(token_path): def update_token(t, *args, **kwargs): - get_logger().info('Updating token to file {}'.format(token_path)) + get_logger().info('Updating token to file %s', token_path) with open(token_path, 'w') as f: json.dump(t, f) @@ -34,7 +35,7 @@ def update_token(t, *args, **kwargs): def __token_loader(token_path): def load_token(): - get_logger().info('Loading token from file {}'.format(token_path)) + get_logger().info('Loading token from file %s', token_path) with open(token_path, 'rb') as f: token_data = f.read() @@ -42,9 +43,8 @@ def load_token(): return json.loads(token_data.decode()) except ValueError: get_logger().warning( - "Unable to load JSON token from file {}, falling back to pickle" - .format(token_path) - ) + 'Unable to load JSON token from file %s, ' + + 'falling back to pickle', token_path) return pickle.loads(token_data) return load_token @@ -56,11 +56,11 @@ def _normalize_api_key(api_key): key_split = api_key.split('@') if len(key_split) != 1: get_logger().warning( - 'API key ends in nonstandard suffix "{}". Ignoring'.format( - '@'.join(key_split[1:]))) + 'API key ends in nonstandard suffix "%s". Ignoring', + LazyLog(lambda: '@'.join(key_split[1:]))) api_key = key_split[0] - get_logger().info('Appending {} to API key'.format(api_key_suffix)) + get_logger().info('Appending %s to API key', api_key_suffix) api_key = api_key + api_key_suffix return api_key @@ -167,8 +167,8 @@ def from_loaded_token(cls, token, unwrapped_token_write_func=None): logger = get_logger() if cls.is_metadata_aware_token(token): logger.info( - 'Loaded metadata aware token with creation timestamp {}' - .format(token['creation_timestamp'])) + 'Loaded metadata aware token with creation timestamp %s', + token['creation_timestamp']) return TokenMetadata( token['creation_timestamp'], unwrapped_token_write_func) elif cls.is_legacy_token(token): @@ -220,12 +220,12 @@ def ensure_refresh_token_update( now = int(time.time()) - logger.info(( + logger.info( 'Updating refresh token:\n'+ - ' - Current timestamp is {}\n'+ - ' - Token creation timestamp is {}\n'+ - ' - Update interval is {} seconds').format( - now, self.creation_timestamp, update_interval_seconds)) + ' - Current timestamp is %s\n'+ + ' - Token creation timestamp is %s\n'+ + ' - Update interval is %s seconds', + now, self.creation_timestamp, update_interval_seconds) if not (self.creation_timestamp is None or now - self.creation_timestamp > @@ -282,8 +282,8 @@ def client_from_login_flow(webdriver, api_key, redirect_url, token_path, file already exists, it will be overwritten with a new one. Updated tokens will be written to this path as well. ''' - get_logger().info(('Creating new token with redirect URL \'{}\' ' + - 'and token path \'{}\'').format(redirect_url, token_path)) + get_logger().info('Creating new token with redirect URL \'%s\' ' + + 'and token path \'%s\'', redirect_url, token_path) api_key = _normalize_api_key(api_key) @@ -352,8 +352,8 @@ def client_from_manual_flow(api_key, redirect_url, token_path, file already exists, it will be overwritten with a new one. Updated tokens will be written to this path as well. ''' - get_logger().info(('Creating new token with redirect URL \'{}\' ' + - 'and token path \'{}\'').format(redirect_url, token_path)) + get_logger().info('Creating new token with redirect URL \'%s\' ' + + 'and token path \'%s\'', redirect_url, token_path) api_key = _normalize_api_key(api_key) @@ -431,11 +431,11 @@ def easy_client(api_key, redirect_uri, token_path, webdriver_func=None, if os.path.isfile(token_path): c = client_from_token_file(token_path, api_key, asyncio=asyncio) - logger.info('Returning client loaded from token file \'{}\''.format( - token_path)) + logger.info( + 'Returning client loaded from token file \'%s\'', token_path) return c else: - logger.warning('Failed to find token file \'{}\''.format(token_path)) + logger.warning('Failed to find token file \'%s\'', token_path) if webdriver_func is not None: with webdriver_func() as driver: @@ -443,7 +443,7 @@ def easy_client(api_key, redirect_uri, token_path, webdriver_func=None, driver, api_key, redirect_uri, token_path, asyncio=asyncio) logger.info( 'Returning client fetched using webdriver, writing' + - 'token to \'{}\''.format(token_path)) + 'token to \'%s\'', token_path) return c else: logger.error('No webdriver_func set, cannot fetch token') @@ -474,8 +474,6 @@ def client_from_access_functions(api_key, token_read_func, called whenever the token is updated, such as when it is refreshed. ''' - logger = get_logger() - token = token_read_func() # Extract metadata and unpack the token, if necessary diff --git a/tda/client/asynchronous.py b/tda/client/asynchronous.py index 13b3284..a43e9d3 100644 --- a/tda/client/asynchronous.py +++ b/tda/client/asynchronous.py @@ -1,5 +1,6 @@ from .base import BaseClient from ..debug import register_redactions_from_response +from ..utils import LazyLog import json @@ -15,8 +16,8 @@ async def _get_request(self, path, params): dest = 'https://api.tdameritrade.com' + path req_num = self._req_num() - self.logger.debug('Req {}: GET to {}, params={}'.format( - req_num, dest, json.dumps(params, indent=4))) + self.logger.debug('Req %s: GET to %s, params=%s', + req_num, dest, LazyLog(lambda: json.dumps(params, indent=4))) resp = await self.session.get(dest, params=params) self._log_response(resp, req_num) @@ -29,8 +30,8 @@ async def _post_request(self, path, data): dest = 'https://api.tdameritrade.com' + path req_num = self._req_num() - self.logger.debug('Req {}: POST to {}, json={}'.format( - req_num, dest, json.dumps(data, indent=4))) + self.logger.debug('Req %s: POST to %s, json=%s', + req_num, dest, LazyLog(lambda: json.dumps(data, indent=4))) resp = await self.session.post(dest, json=data) self._log_response(resp, req_num) @@ -43,8 +44,8 @@ async def _put_request(self, path, data): dest = 'https://api.tdameritrade.com' + path req_num = self._req_num() - self.logger.debug('Req {}: PUT to {}, json={}'.format( - req_num, dest, json.dumps(data, indent=4))) + self.logger.debug('Req %s: PUT to %s, json=%s', + req_num, dest, LazyLog(lambda: json.dumps(data, indent=4))) resp = await self.session.put(dest, json=data) self._log_response(resp, req_num) @@ -57,8 +58,8 @@ async def _patch_request(self, path, data): dest = 'https://api.tdameritrade.com' + path req_num = self._req_num() - self.logger.debug('Req {}: PATCH to {}, json={}'.format( - req_num, dest, json.dumps(data, indent=4))) + self.logger.debug('Req %s: PATCH to %s, json=%s', + req_num, dest, LazyLog(lambda: json.dumps(data, indent=4))) resp = await self.session.patch(dest, json=data) self._log_response(resp, req_num) @@ -71,7 +72,7 @@ async def _delete_request(self, path): dest = 'https://api.tdameritrade.com' + path req_num = self._req_num() - self.logger.debug('Req {}: DELETE to {}'.format(req_num, dest)) + self.logger.debug('Req %s: DELETE to %s', req_num, dest) resp = await self.session.delete(dest) self._log_response(resp, req_num) diff --git a/tda/client/base.py b/tda/client/base.py index a661ab3..d80bd36 100644 --- a/tda/client/base.py +++ b/tda/client/base.py @@ -56,8 +56,8 @@ def __init__(self, api_key, session, *, enforce_enums=True, _DATE = datetime.date def _log_response(self, resp, req_num): - self.logger.debug('Req {}: GET response: {}, content={}'.format( - req_num, resp.status_code, resp.text)) + self.logger.debug('Req %s: GET response: %s, content=%s', + req_num, resp.status_code, resp.text) def _req_num(self): self.request_number += 1 diff --git a/tda/client/synchronous.py b/tda/client/synchronous.py index 7f751de..db03be1 100644 --- a/tda/client/synchronous.py +++ b/tda/client/synchronous.py @@ -1,4 +1,5 @@ from .base import BaseClient +from ..utils import LazyLog from ..debug import register_redactions_from_response import json @@ -11,8 +12,8 @@ def _get_request(self, path, params): dest = 'https://api.tdameritrade.com' + path req_num = self._req_num() - self.logger.debug('Req {}: GET to {}, params={}'.format( - req_num, dest, json.dumps(params, indent=4))) + self.logger.debug('Req %s: GET to %s, params=%s', + req_num, dest, LazyLog(lambda: json.dumps(params, indent=4))) resp = self.session.get(dest, params=params) self._log_response(resp, req_num) @@ -25,8 +26,8 @@ def _post_request(self, path, data): dest = 'https://api.tdameritrade.com' + path req_num = self._req_num() - self.logger.debug('Req {}: POST to {}, json={}'.format( - req_num, dest, json.dumps(data, indent=4))) + self.logger.debug('Req %s: POST to %s, json=%s', + req_num, dest, LazyLog(lambda: json.dumps(data, indent=4))) resp = self.session.post(dest, json=data) self._log_response(resp, req_num) @@ -39,8 +40,8 @@ def _put_request(self, path, data): dest = 'https://api.tdameritrade.com' + path req_num = self._req_num() - self.logger.debug('Req {}: PUT to {}, json={}'.format( - req_num, dest, json.dumps(data, indent=4))) + self.logger.debug('Req %s: PUT to %s, json=%s', + req_num, dest, LazyLog(lambda: json.dumps(data, indent=4))) resp = self.session.put(dest, json=data) self._log_response(resp, req_num) @@ -53,8 +54,8 @@ def _patch_request(self, path, data): dest = 'https://api.tdameritrade.com' + path req_num = self._req_num() - self.logger.debug('Req {}: PATCH to {}, json={}'.format( - req_num, dest, json.dumps(data, indent=4))) + self.logger.debug('Req %s: PATCH to %s, json=%s', + req_num, dest, LazyLog(lambda: json.dumps(data, indent=4))) resp = self.session.patch(dest, json=data) self._log_response(resp, req_num) @@ -67,7 +68,7 @@ def _delete_request(self, path): dest = 'https://api.tdameritrade.com' + path req_num = self._req_num() - self.logger.debug('Req {}: DELETE to {}'.format(req_num, dest)) + self.logger.debug('Req %s: DELETE to %s'.format(req_num, dest)) resp = self.session.delete(dest) self._log_response(resp, req_num) diff --git a/tda/debug.py b/tda/debug.py index 5e1e4d9..735c72d 100644 --- a/tda/debug.py +++ b/tda/debug.py @@ -160,6 +160,6 @@ def write_logs(): print(msg, file=output) atexit.register(write_logs) - get_logger().debug('tda-api version {}'.format(tda.__version__)) + get_logger().debug('tda-api version %s', tda.__version__) return write_logs diff --git a/tda/streaming.py b/tda/streaming.py index caa9e0d..613b14b 100644 --- a/tda/streaming.py +++ b/tda/streaming.py @@ -15,7 +15,7 @@ import websockets.legacy.client as ws_client from websockets.extensions.permessage_deflate import ClientPerMessageDeflateFactory -from .utils import EnumEnforcer +from .utils import EnumEnforcer, LazyLog class StreamJsonDecoder(ABC): @@ -160,8 +160,8 @@ async def _send(self, obj): raise ValueError( 'Socket not open. Did you forget to call login()?') - self.logger.debug('Send {}: Sending {}'.format( - self.req_num(), json.dumps(obj, indent=4))) + self.logger.debug('Send %s: Sending %s', + self.req_num(), LazyLog(lambda: json.dumps(obj, indent=4))) await self._socket.send(json.dumps(obj)) @@ -174,8 +174,8 @@ async def _receive(self): ret = self._overflow_items.pop() self.logger.debug( - 'Receive {}: Returning message from overflow: {}'.format( - self.req_num(), json.dumps(ret, indent=4))) + 'Receive %s: Returning message from overflow: %s', + self.req_num(), LazyLog(lambda: json.dumps(ret, indent=4))) else: raw = await self._socket.recv() try: @@ -187,8 +187,8 @@ async def _receive(self): raise UnparsableMessage(raw, e, msg) self.logger.debug( - 'Receive {}: Returning message from stream: {}'.format( - self.req_num(), json.dumps(ret, indent=4))) + 'Receive %s: Returning message from stream: %s', + self.req_num(), LazyLog(lambda: json.dumps(ret, indent=4))) return ret @@ -222,8 +222,8 @@ async def _init_from_principals(self, principals, websocket_connect_args): # Record streamer subscription keys stream_keys = principals['streamerSubscriptionKeys']['keys'] if len(stream_keys) > 1: - self.logger.warn('Found {} stream keys, using the first one'.format( - len(stream_keys))) + self.logger.warn('Found %s stream keys, using the first one', + len(stream_keys)) self._stream_key = stream_keys[0]['key'] # Initialize socket diff --git a/tda/utils.py b/tda/utils.py index a5e0656..2b32d6a 100644 --- a/tda/utils.py +++ b/tda/utils.py @@ -87,6 +87,14 @@ class AccountIdMismatchException(ValueError): ''' +class LazyLog: + 'Helper to defer evaluation of expensive variables in log messages' + def __init__(self, func): + self.func = func + def __str__(self): + return self.func() + + class Utils(EnumEnforcer): '''Helper for placing orders on equities. Provides easy-to-use implementations for common tasks such as market and limit orders.''' diff --git a/tests/client_test.py b/tests/client_test.py index 231c480..75ea535 100644 --- a/tests/client_test.py +++ b/tests/client_test.py @@ -1,5 +1,6 @@ import asyncio import datetime +import logging import os import pytest import pytz @@ -9,9 +10,7 @@ from tda.client import AsyncClient, Client from tda.orders.generic import OrderBuilder -from .utils import no_duplicates - -from .utils import AsyncMagicMock, ResyncProxy +from .utils import AsyncMagicMock, ResyncProxy, no_duplicates # Constants @@ -60,6 +59,10 @@ def setUp(self): self.mock_session = self.magicmock_class() self.client = self.client_class(API_KEY, self.mock_session) + # Set the logging level to DEBUG to force all lazily-evaluated messages + # to be evaluated + self.client.logger.setLevel('DEBUG') + def make_url(self, path): path = path.format( accountId=ACCOUNT_ID,