logging: Fixed broken backtest and quite_logs options so that backtes…

…ting runs will both produce sane results again and stop swamping the console. Additionally reduced log signature length in normal runs. Full signature can be restored by setting the debug flag in Trader().

lumibot/backtesting/backtesting_broker.py

@@ -98,7 +98,7 @@ def _update_datetime(self, update_dt, cash=None, portfolio_value=None):
         self.data_source._update_datetime(new_datetime, cash=cash, portfolio_value=portfolio_value)
         if self.option_source:
             self.option_source._update_datetime(new_datetime, cash=cash, portfolio_value=portfolio_value)
-        logger.debug(f"Current backtesting datetime {self.datetime}")
+        logger.info(f"Current backtesting datetime {self.datetime}")
 
     # =========Clock functions=====================
 

lumibot/strategies/_strategy.py

@@ -884,7 +884,7 @@ def run_backtest(
         save_logfile=False,
         use_quote_data=False,
         show_progress_bar=True,
-        quiet_logs=True,
+        quiet_logs=False,
         trader_class=Trader,
         **kwargs,
     ):
@@ -1515,4 +1515,4 @@ def backtest(
             trader_class=trader_class,
             **kwargs,
         )
-        return results
+        return results

lumibot/traders/trader.py

@@ -25,7 +25,7 @@ def __init__(self, logfile="", backtest=False, debug=False, strategies=None, qui
         strategies: list
             A list of strategies to run. If not specified, you must add strategies using trader.add_strategy(strategy)
         quiet_logs: bool
-            Whether to quiet noisy logs by setting the log level to ERROR. Defaults to True.
+            Whether to quiet backtest logs by setting the log level to ERROR. Defaults to False.
         """
         # Check if the logfile is a valid path
         if logfile:
@@ -35,8 +35,11 @@ def __init__(self, logfile="", backtest=False, debug=False, strategies=None, qui
         # Setting debug and _logfile parameters and setting global log format
         self.debug = debug
         self.backtest = backtest
-        self.log_format = logging.Formatter("%(asctime)s | %(name)s | %(levelname)s | %(message)s")
-        self.quiet_logs = quiet_logs
+        std_format = "%(asctime)s: %(levelname)s: %(message)s"
+        debug_format = "%(asctime)s: %(name)s: %(levelname)s: %(message)s"
+        log_format = std_format if not self.debug else debug_format
+        self.log_format = logging.Formatter(log_format)
+        self.quiet_logs = quiet_logs  # Turns off all logging execpt for error messages in backtesting
 
         if logfile:
             self.logfile = Path(logfile)
@@ -172,11 +175,6 @@ def _set_logger(self):
         logging.getLogger("apscheduler.scheduler").setLevel(logging.ERROR)
         logging.getLogger("apscheduler.executors.default").setLevel(logging.ERROR)
         logging.getLogger("lumibot.data_sources.yahoo_data").setLevel(logging.ERROR)
-
-        if self.quiet_logs:
-            logging.getLogger("asyncio").setLevel(logging.ERROR)
-            logging.getLogger("lumibot.backtesting.backtesting_broker").setLevel(logging.ERROR)
-
         logger = logging.getLogger()
 
         for handler in logger.handlers:
@@ -189,12 +187,18 @@ def _set_logger(self):
 
         if self.debug:
             logger.setLevel(logging.DEBUG)
-        elif self.quiet_logs:
-            logger.setLevel(logging.ERROR)
-            for handler in logger.handlers:
-                if handler.__class__.__name__ == "StreamHandler":
-                    handler.setLevel(logging.ERROR)
+        elif self.is_backtest_broker:
+            logger.setLevel(logging.INFO)
+
+            # Quiet logs turns off all backtesting logging except for error messages
+            if self.quiet_logs:
+                logger.setLevel(logging.ERROR)
+
+            # Ensure console has minimal logging to keep things clean during backtesting
+            stream_handler.setLevel(logging.ERROR)
+
         else:
+            # Live trades should always have full logging.
             logger.setLevel(logging.INFO)
 
         # Setting file logging

tests/test_logging.py

@@ -13,52 +13,6 @@ def test_logging(self, caplog):
         logger.info("This is an info message")
         assert "This is an info message" in caplog.text
 
-    def test_backtest_produces_no_logs_by_default(self, caplog):
-        caplog.set_level(logging.INFO)
-        backtesting_start = datetime.datetime(2023, 1, 2)
-        backtesting_end = datetime.datetime(2023, 1, 4)
-
-        LifecycleLogger.backtest(
-            YahooDataBacktesting,
-            backtesting_start,
-            backtesting_end,
-            parameters={"sleeptime": "1D", "market": "NYSE"},
-            show_plot=False,
-            save_tearsheet=False,
-            show_tearsheet=False,
-            show_indicators=False,
-            save_logfile=False,
-        )
-        # count that this contains 3 new lines. Its an easy proxy for the number of log messages and avoids
-        # the issue where the datetime is always gonna be different.
-        assert caplog.text.count("\n") == 3
-        assert "Starting backtest...\n" in caplog.text
-        assert "Backtesting starting...\n" in caplog.text
-        assert "Backtesting finished\n" in caplog.text
-
-    def test_run_backtest_produces_no_logs_by_default(self, caplog):
-        caplog.set_level(logging.INFO)
-        backtesting_start = datetime.datetime(2023, 1, 2)
-        backtesting_end = datetime.datetime(2023, 1, 4)
-
-        LifecycleLogger.run_backtest(
-            YahooDataBacktesting,
-            backtesting_start,
-            backtesting_end,
-            parameters={"sleeptime": "1D", "market": "NYSE"},
-            show_plot=False,
-            save_tearsheet=False,
-            show_tearsheet=False,
-            show_indicators=False,
-            save_logfile=False,
-        )
-        # count that this contains 3 new lines. Its an easy proxy for the number of log messages and avoids
-        # the issue where the datetime is always gonna be different.
-        assert caplog.text.count("\n") == 3
-        assert "Starting backtest...\n" in caplog.text
-        assert "Backtesting starting...\n" in caplog.text
-        assert "Backtesting finished\n" in caplog.text
-
     def test_backtest_produces_no_logs_when_quiet_logs_is_true(self, caplog):
         caplog.set_level(logging.INFO)
         backtesting_start = datetime.datetime(2023, 1, 2)
@@ -79,10 +33,11 @@ def test_backtest_produces_no_logs_when_quiet_logs_is_true(self, caplog):
         )
         # count that this contains 3 new lines. Its an easy proxy for the number of log messages and avoids
         # the issue where the datetime is always gonna be different.
-        assert caplog.text.count("\n") == 3
+        assert caplog.text.count("\n") == 4
         assert "Starting backtest...\n" in caplog.text
         assert "Backtesting starting...\n" in caplog.text
         assert "Backtesting finished\n" in caplog.text
+        assert "Backtest took " in caplog.text
 
     def test_backtest_produces_logs_when_quiet_logs_is_false(self, caplog):
         caplog.set_level(logging.INFO)
@@ -103,12 +58,12 @@ def test_backtest_produces_logs_when_quiet_logs_is_false(self, caplog):
             quiet_logs=False,
         )
 
-        assert caplog.text.count("\n") == 9
+        assert caplog.text.count("\n") >= 9
         assert "Starting backtest...\n" in caplog.text
         assert "Backtesting starting...\n" in caplog.text
         assert "before_market_opens called\n" in caplog.text
         assert "before_starting_trading called\n" in caplog.text
         assert "on_trading_iteration called\n" in caplog.text
         assert "before_market_closes called\n" in caplog.text
         assert "after_market_closes called\n" in caplog.text
-        assert "Backtesting finished\n" in caplog.text
+        assert "Backtesting finished\n" in caplog.text