/* PR_START p/fix_cli_logging 01 */ Fix logging setup in the CLI

Author: plypaul

dbt-metricflow/dbt_metricflow/cli/cli_configuration.py

@@ -3,6 +3,7 @@
 import logging
 import os
 import pathlib
+from logging import StreamHandler
 from logging.handlers import TimedRotatingFileHandler
 from typing import Dict, Optional
 
@@ -23,9 +24,13 @@
 class CLIConfiguration:
     """Configuration object used for the MetricFlow CLI."""
 
+    LOG_FILE_NAME = "metricflow.log"
     DBT_PROFILES_DIR_ENV_VAR_NAME = "DBT_PROFILES_DIR"
     DBT_PROJECT_DIR_ENV_VAR_NAME = "DBT_PROJECT_DIR"
 
+    # Message to log when logging has been set up. Useful for checking the logging in tests.
+    LOG_SETUP_MESSAGE = "Set up MF CLI logging"
+
     def __init__(self) -> None:  # noqa: D107
         self.verbose = False
         self._dbt_project_metadata: Optional[dbtProjectMetadata] = None
@@ -121,28 +126,44 @@ def _configure_logging(self, log_file_path: pathlib.Path) -> None:
         we can swap this out and return to full lazy loading for any context attributes that are slow
         to initialize.
         """
-        logger.debug(LazyFormat("Setting up logging to rotating file", log_file_path=self.log_file_path))
+        root_logger = logging.getLogger()
+        previous_root_logger_level = root_logger.level
+        previous_root_logger_handlers = tuple(root_logger.handlers)
 
-        log_format = "%(asctime)s %(levelname)s %(filename)s:%(lineno)d [%(threadName)s] - %(message)s"
-        logging.basicConfig(level=logging.INFO, format=log_format)
+        # Show >= CRITICAL logs in the console
+        stream_handler = StreamHandler()
+        stream_handler_log_level = logging.CRITICAL
+        stream_handler.setLevel(stream_handler_log_level)
 
+        # Show >= INFO logs in the log file
+        log_file_handler_log_level = logging.INFO
         log_file_handler = TimedRotatingFileHandler(
             filename=log_file_path,
             # Rotate every day to a new file, keep 7 days worth.
             when="D",
             interval=1,
             backupCount=7,
         )
+        log_file_handler.setLevel(log_file_handler_log_level)
 
-        formatter = logging.Formatter(fmt=log_format)
-        log_file_handler.setFormatter(formatter)
-        log_file_handler.setLevel(logging.INFO)
+        root_logger_level = logging.INFO
+        log_format = "%(asctime)s %(levelname)s %(filename)s:%(lineno)d [%(threadName)s] - %(message)s"
+        # `logging.basicConfig` is a no-op without the `force=True` if any handlers have been added to the root logger.
+        # Imported modules might add handlers, so set the flag to ensure that the above handlers are used.
+        logging.basicConfig(
+            level=root_logger_level, format=log_format, handlers=[stream_handler, log_file_handler], force=True
+        )
 
-        root_logger = logging.getLogger()
-        # StreamHandler to the console would have been setup by logging.basicConfig
-        for handler in root_logger.handlers:
-            handler.setLevel(logging.CRITICAL)
-        root_logger.addHandler(log_file_handler)
+        logger.info(
+            LazyFormat(
+                CLIConfiguration.LOG_SETUP_MESSAGE,
+                root_logger_level=logging.getLevelName(root_logger_level),
+                root_logger_handlers=root_logger.handlers,
+                previous_root_logger_level=logging.getLevelName(previous_root_logger_level),
+                previous_root_logger_handlers=previous_root_logger_handlers,
+                log_format=log_format,
+            )
+        )
 
     @property
     def dbt_project_metadata(self) -> dbtProjectMetadata:
@@ -162,7 +183,7 @@ def log_file_path(self) -> pathlib.Path:
         # The dbt Project.log_path attribute is currently sourced from the final runtime config value accessible
         # through the CLI state flags. As such, it will deviate from the default based on the DBT_LOG_PATH environment
         # variable. Should this behavior change, we will need to update this call.
-        return pathlib.Path(self.dbt_project_metadata.project.log_path, "metricflow.log")
+        return pathlib.Path(self.dbt_project_metadata.project.log_path, CLIConfiguration.LOG_FILE_NAME)
 
     @property
     def sql_client(self) -> SqlClient:

dbt-metricflow/dbt_metricflow/cli/main.py

@@ -20,7 +20,6 @@
 from dbt_semantic_interfaces.validations.validator_helpers import SemanticManifestValidationResults
 from halo import Halo
 from metricflow_semantics.dag.dag_visualization import display_dag_as_svg
-from metricflow_semantics.toolkit.mf_logging.lazy_formattable import LazyFormat
 from update_checker import UpdateChecker
 
 import dbt_metricflow.cli.custom_click_types as click_custom
@@ -90,7 +89,7 @@ def exit_signal_handler(signal_type: int, frame) -> None:  # type: ignore
 
         try:
             # Note: we may wish to add support for canceling all queries if zombie queries are a problem
-            logger.debug(LazyFormat(lambda: "Closing client connections"))
+            logger.debug("Closing client connections")
             cfg.sql_client.close()
         finally:
             sys.exit(-1)