Use lazy log evaluation throughout (#296)

* Use lazy log evaluation throughout

* Force client tests to eagerly evaluate

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,17 +35,16 @@ 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()
             try:
                 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,19 +431,19 @@ 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:
                 c = client_from_login_flow(
                     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

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)

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

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)

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

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

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.'''

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,