From e55abe7e0b5daa9a21680c337dfe9aed4198e568 Mon Sep 17 00:00:00 2001 From: Peter Marsh Date: Sat, 2 Sep 2023 21:12:28 +0200 Subject: [PATCH] Lazily evaluate log message parameters Logging like this: logger.debug("Hello, %s" % name) causes the message string to always be interpolated even if the message is not going to be logged. Logging like this: logger.debug("Hello, %s", name) will mean the string is only ever interpolated if it will be logged. In practice here this will make little difference if the log level is INFO or above, but it does mean a `if` statement can be removed from StreamListener. See: https://docs.python.org/3/howto/logging.html#optimization https://stackoverflow.com/questions/4148790/lazy-logger-message-string-evaluation --- examples/strategies/marketrecorder.py | 18 +++++++------ flumine/execution/baseexecution.py | 4 ++- flumine/streams/datastream.py | 30 ++++++++++++++------- flumine/streams/historicalstream.py | 27 +++++++++++++------ flumine/streams/streams.py | 6 +++-- flumine/utils.py | 38 +++++++++++++++++++++------ 6 files changed, 86 insertions(+), 37 deletions(-) diff --git a/examples/strategies/marketrecorder.py b/examples/strategies/marketrecorder.py index 19f22f71..4b629b5b 100644 --- a/examples/strategies/marketrecorder.py +++ b/examples/strategies/marketrecorder.py @@ -44,7 +44,7 @@ def __init__(self, *args, **kwargs): self._queue = queue.Queue() def add(self) -> None: - logger.info("Adding strategy %s with id %s" % (self.name, self.recorder_id)) + logger.info("Adding strategy %s with id %s", self.name, self.recorder_id) # check local dir if not os.path.isdir(self.local_dir): raise OSError("File dir %s does not exist" % self.local_dir) @@ -94,8 +94,10 @@ def process_closed_market(self, market, data: dict) -> None: # check that file actually exists if not os.path.isfile(file_dir): logger.error( - "File: %s does not exist in /%s/%s/" - % (self.local_dir, market_id, self.recorder_id) + "File: %s does not exist in /%s/%s/", + self.local_dir, + market_id, + self.recorder_id, ) return @@ -117,7 +119,7 @@ def _load_processor(self): # check file still exists (potential race condition) if not os.path.isfile(file_dir): logger.warning( - "File: %s does not exist in %s" % (market.market_id, file_dir) + "File: %s does not exist in %s", market.market_id, file_dir ) continue # compress file @@ -173,8 +175,7 @@ def _clean_up(self) -> None: if seconds_since > self._market_expiration: if self._remove_gz_file: logger.info( - "Removing: %s, age: %ss" - % (gz_path, round(seconds_since, 2)) + "Removing: %s, age: %ss", gz_path, round(seconds_since, 2) ) os.remove(gz_path) txt_path = os.path.join(directory, file.split(".gz")[0]) @@ -183,8 +184,9 @@ def _clean_up(self) -> None: seconds_since = time.time() - file_stats.st_mtime if seconds_since > self._market_expiration: logger.info( - "Removing: %s, age: %ss" - % (txt_path, round(seconds_since, 2)) + "Removing: %s, age: %ss", + txt_path, + round(seconds_since, 2), ) os.remove(txt_path) diff --git a/flumine/execution/baseexecution.py b/flumine/execution/baseexecution.py index 2d3e093a..f6d0b513 100644 --- a/flumine/execution/baseexecution.py +++ b/flumine/execution/baseexecution.py @@ -128,7 +128,9 @@ def _order_logger( self, order: BaseOrder, instruction_report, package_type: OrderPackageType ): logger.info( - "Order %s: %s" % (package_type.value, instruction_report.status), + "Order %s: %s", + package_type.value, + instruction_report.status, extra={ "bet_id": order.bet_id, "order_id": order.id, diff --git a/flumine/streams/datastream.py b/flumine/streams/datastream.py index af124615..45278cdc 100644 --- a/flumine/streams/datastream.py +++ b/flumine/streams/datastream.py @@ -56,15 +56,19 @@ def _process(self, data: list, publish_time: int) -> bool: # removes closed market from cache del self._caches[market_id] logger.info( - "[MarketStream: %s] %s removed, %s markets in cache" - % (self.unique_id, market_id, len(self._caches)) + "[MarketStream: %s] %s removed, %s markets in cache", + self.unique_id, + market_id, + len(self._caches), ) elif market_id not in self._caches: # adds empty object to cache to track live market count self._caches[market_id] = object() logger.info( - "[MarketStream: %s] %s added, %s markets in cache" - % (self.unique_id, market_id, len(self._caches)) + "[MarketStream: %s] %s added, %s markets in cache", + self.unique_id, + market_id, + len(self._caches), ) self._updates_processed += 1 @@ -82,8 +86,10 @@ def _process(self, data: list, publish_time: int) -> bool: # adds empty object to cache to track live market count self._caches[market_id] = object() logger.info( - "[OrderStream: %s] %s added, %s markets in cache" - % (self.unique_id, market_id, len(self._caches)) + "[OrderStream: %s] %s added, %s markets in cache", + self.unique_id, + market_id, + len(self._caches), ) self._updates_processed += 1 @@ -101,8 +107,10 @@ def _process(self, data: list, publish_time: int) -> bool: # adds empty object to cache to track live market count self._caches[market_id] = object() logger.info( - "[RaceStream: %s] %s added, %s markets in cache" - % (self.unique_id, market_id, len(self._caches)) + "[RaceStream: %s] %s added, %s markets in cache", + self.unique_id, + market_id, + len(self._caches), ) self._updates_processed += 1 @@ -120,8 +128,10 @@ def _process(self, data: list, publish_time: int) -> bool: # adds empty object to cache to track live market count self._caches[market_id] = object() logger.info( - "[CricketStream: %s] %s added, %s markets in cache" - % (self.unique_id, market_id, len(self._caches)) + "[CricketStream: %s] %s added, %s markets in cache", + self.unique_id, + market_id, + len(self._caches), ) self._updates_processed += 1 diff --git a/flumine/streams/historicalstream.py b/flumine/streams/historicalstream.py index f33a7e15..a08ae956 100644 --- a/flumine/streams/historicalstream.py +++ b/flumine/streams/historicalstream.py @@ -43,8 +43,10 @@ def _process(self, data: list, publish_time: int) -> bool: logger.warning( "[%s: %s]: Missing marketDefinition on market %s resulting " "in potential missing data in the MarketBook (make sure " - "EX_MARKET_DEF is requested)" - % (self, self.unique_id, market_id) + "EX_MARKET_DEF is requested)", + self, + self.unique_id, + market_id, ) market_book_cache = MarketBookCache( market_id, @@ -55,8 +57,11 @@ def _process(self, data: list, publish_time: int) -> bool: ) self._caches[market_id] = market_book_cache logger.info( - "[%s: %s]: %s added, %s markets in cache" - % (self, self.unique_id, market_id, len(self._caches)) + "[%s: %s]: %s added, %s markets in cache", + self, + self.unique_id, + market_id, + len(self._caches), ) # listener_kwargs filtering @@ -116,8 +121,11 @@ def _process(self, race_updates: list, publish_time: int) -> bool: race_cache.start_time = create_time(publish_time, race_id) self._caches[market_id] = race_cache logger.info( - "[%s: %s]: %s added, %s markets in cache" - % (self, self.unique_id, market_id, len(self._caches)) + "[%s: %s]: %s added, %s markets in cache", + self, + self.unique_id, + market_id, + len(self._caches), ) # filter after start time @@ -151,8 +159,11 @@ def _process(self, cricket_changes: list, publish_time: int) -> bool: ) self._caches[market_id] = cricket_match_cache logger.info( - "[%s: %s]: %s added, %s markets in cache" - % (self, self.unique_id, market_id, len(self._caches)) + "[%s: %s]: %s added, %s markets in cache", + self, + self.unique_id, + market_id, + len(self._caches), ) cricket_match_cache.update_cache(cricket_change, publish_time) diff --git a/flumine/streams/streams.py b/flumine/streams/streams.py index 67ef0f2a..36fc7dd9 100644 --- a/flumine/streams/streams.py +++ b/flumine/streams/streams.py @@ -47,8 +47,10 @@ def __call__(self, strategy: BaseStrategy) -> None: country_code = get_file_md(market, "countryCode") if market_types and market_type and market_type not in market_types: logger.warning( - "Skipping market %s (%s) for strategy %s due to marketType filter" - % (market, market_type, strategy) + "Skipping market %s (%s) for strategy %s due to marketType filter", + market, + market_type, + strategy, ) elif ( country_codes diff --git a/flumine/utils.py b/flumine/utils.py index 3e823739..1938637e 100644 --- a/flumine/utils.py +++ b/flumine/utils.py @@ -237,12 +237,18 @@ def call_strategy_error_handling( return func(market, market_book) except FlumineException as e: logger.error( - "FlumineException %s in %s (%s)" % (e, func.__name__, market.market_id), + "FlumineException %s in %s (%s)", + e, + func.__name__, + market.market_id, exc_info=True, ) except Exception as e: logger.critical( - "Unknown error %s in %s (%s)" % (e, func.__name__, market.market_id), + "Unknown error %s in %s (%s)", + e, + func.__name__, + market.market_id, exc_info=True, ) if config.raise_errors: @@ -255,12 +261,18 @@ def call_middleware_error_handling(middleware, market) -> None: middleware(market) except FlumineException as e: logger.error( - "FlumineException %s in %s (%s)" % (e, middleware, market.market_id), + "FlumineException %s in %s (%s)", + e, + middleware, + market.market_id, exc_info=True, ) except Exception as e: logger.critical( - "Unknown error %s in %s (%s)" % (e, middleware, market.market_id), + "Unknown error %s in %s (%s)", + e, + middleware, + market.market_id, exc_info=True, ) if config.raise_errors: @@ -272,12 +284,18 @@ def call_process_orders_error_handling(strategy, market, strategy_orders: list) strategy.process_orders(market, strategy_orders) except FlumineException as e: logger.error( - "FlumineException %s in %s (%s)" % (e, strategy, market.market_id), + "FlumineException %s in %s (%s)", + e, + strategy, + market.market_id, exc_info=True, ) except Exception as e: logger.critical( - "Unknown error %s in %s (%s)" % (e, strategy, market.market_id), + "Unknown error %s in %s (%s)", + e, + strategy, + market.market_id, exc_info=True, ) if config.raise_errors: @@ -289,12 +307,16 @@ def call_process_raw_data(strategy, clk: str, publish_time: int, datum: dict) -> strategy.process_raw_data(clk, publish_time, datum) except FlumineException as e: logger.error( - "FlumineException %s in %s" % (e, strategy), + "FlumineException %s in %s", + e, + strategy, exc_info=True, ) except Exception as e: logger.critical( - "Unknown error %s in %s" % (e, strategy), + "Unknown error %s in %s", + e, + strategy, exc_info=True, ) if config.raise_errors: