diff --git a/dbtmetabase/__init__.py b/dbtmetabase/__init__.py index 580eaad..5f9e172 100644 --- a/dbtmetabase/__init__.py +++ b/dbtmetabase/__init__.py @@ -4,10 +4,12 @@ from .dbt import DbtReader from .metabase import MetabaseClient +logger = logging.getLogger(__name__) + __all__ = ["DbtReader", "MetabaseClient"] try: __version__ = importlib.metadata.version("dbt-metabase") except importlib.metadata.PackageNotFoundError: + logger.warning("No version found in metadata") __version__ = "0.0.0-UNKONWN" - logging.warning("No version found in metadata") diff --git a/dbtmetabase/__main__.py b/dbtmetabase/__main__.py index b06c67a..e4242c3 100644 --- a/dbtmetabase/__main__.py +++ b/dbtmetabase/__main__.py @@ -1,16 +1,55 @@ import functools import logging +from logging.handlers import RotatingFileHandler from pathlib import Path from typing import Callable, Iterable, List, Optional, Union import click import yaml +from rich.logging import RichHandler from typing_extensions import cast from .dbt import DbtReader -from .logger import logging as package_logger from .metabase import MetabaseClient +LOG_PATH = Path.home().absolute() / ".dbt-metabase" / "logs" / "dbtmetabase.log" + +logger = logging.getLogger(__name__) + + +def _setup_logger(level: int = logging.INFO): + """Basic logger configuration for the CLI. + + Args: + level (int, optional): Logging level. Defaults to logging.INFO. + """ + + LOG_PATH.parent.mkdir(parents=True, exist_ok=True) + file_handler = RotatingFileHandler( + filename=LOG_PATH, + maxBytes=int(1e6), + backupCount=3, + ) + file_handler.setFormatter( + logging.Formatter("%(asctime)s — %(name)s — %(levelname)s — %(message)s") + ) + file_handler.setLevel(logging.WARNING) + + rich_handler = RichHandler( + level=level, + rich_tracebacks=True, + markup=True, + show_time=False, + ) + + logging.basicConfig( + level=level, + format="%(asctime)s — %(message)s", + datefmt="%Y-%m-%d %H:%M:%S %z", + handlers=[file_handler, rich_handler], + force=True, + ) + def _comma_separated_list_callback( ctx: click.Context, @@ -203,8 +242,7 @@ def wrapper( verbose: bool, **kwargs, ): - if verbose: - package_logger.LOGGING_LEVEL = logging.DEBUG + _setup_logger(level=logging.DEBUG if verbose else logging.INFO) return func( dbt_reader=DbtReader( diff --git a/dbtmetabase/dbt.py b/dbtmetabase/dbt.py index 14ef85b..0040351 100644 --- a/dbtmetabase/dbt.py +++ b/dbtmetabase/dbt.py @@ -1,11 +1,12 @@ import dataclasses import json +import logging import re from enum import Enum from pathlib import Path from typing import Iterable, List, Mapping, MutableMapping, Optional, Sequence -from .logger.logging import logger +logger = logging.getLogger(__name__) # Allowed metabase.* fields _METABASE_COMMON_META_FIELDS = [ @@ -143,17 +144,17 @@ def read_models( model_database = node["database"].upper() if node["resource_type"] != "model": - logger().debug("Skipping %s not of resource type model", model_name) + logger.debug("Skipping %s not of resource type model", model_name) continue if node["config"]["materialized"] == "ephemeral": - logger().debug( + logger.debug( "Skipping ephemeral model %s not manifested in database", model_name ) continue if model_database != self.database: - logger().debug( + logger.debug( "Skipping %s in database %s, not in target database %s", model_name, model_database, @@ -162,7 +163,7 @@ def read_models( continue if self.schema and model_schema != self.schema: - logger().debug( + logger.debug( "Skipping %s in schema %s not in target schema %s", model_name, model_schema, @@ -171,7 +172,7 @@ def read_models( continue if model_schema in self.schema_excludes: - logger().debug( + logger.debug( "Skipping %s in schema %s marked for exclusion", model_name, model_schema, @@ -179,7 +180,7 @@ def read_models( continue if not self.model_selected(model_name): - logger().debug( + logger.debug( "Skipping %s not included in includes or excluded by excludes", model_name, ) @@ -202,17 +203,17 @@ def read_models( source_database = node["database"].upper() if node["resource_type"] != "source": - logger().debug("Skipping %s not of resource type source", source_name) + logger.debug("Skipping %s not of resource type source", source_name) continue if source_database != self.database: - logger().debug( + logger.debug( "Skipping %s not in target database %s", source_name, self.database ) continue if self.schema and source_schema != self.schema: - logger().debug( + logger.debug( "Skipping %s in schema %s not in target schema %s", source_name, source_schema, @@ -221,7 +222,7 @@ def read_models( continue if source_schema in self.schema_excludes: - logger().debug( + logger.debug( "Skipping %s in schema %s marked for exclusion", source_name, source_schema, @@ -229,7 +230,7 @@ def read_models( continue if not self.model_selected(source_name): - logger().debug( + logger.debug( "Skipping %s not included in includes or excluded by excludes", source_name, ) @@ -330,7 +331,7 @@ def _read_model_relationships( # Note, sometimes only the referenced model is returned. depends_on_nodes = list(child["depends_on"][model_type]) if len(depends_on_nodes) > 2: - logger().warning( + logger.warning( "Expected at most two nodes, got %d {} nodes, skipping %s {}", len(depends_on_nodes), unique_id, @@ -341,7 +342,7 @@ def _read_model_relationships( # Otherwise, the primary key of the current model would be (incorrectly) determined to be a foreign key. is_incoming_relationship_test = depends_on_nodes[1] != unique_id if len(depends_on_nodes) == 2 and is_incoming_relationship_test: - logger().debug( + logger.debug( "Skip this incoming relationship test, concerning nodes %s.", depends_on_nodes, ) @@ -353,7 +354,7 @@ def _read_model_relationships( depends_on_nodes.remove(unique_id) if len(depends_on_nodes) != 1: - logger().warning( + logger.warning( "Expected single node after filtering, got %d nodes, skipping %s", len(depends_on_nodes), unique_id, @@ -369,7 +370,7 @@ def _read_model_relationships( ) if not fk_target_table_alias: - logger().debug( + logger.debug( "Could not resolve depends on model id %s to a model in manifest", depends_on_id, ) @@ -447,7 +448,7 @@ def set_column_foreign_key( if not table or not field: if table or field: - logger().warning( + logger.warning( "Foreign key requires table and field for column %s", metabase_column.name, ) @@ -462,7 +463,7 @@ def set_column_foreign_key( [x.strip('"').upper() for x in table_path] ) metabase_column.fk_target_field = field.strip('"').upper() - logger().debug( + logger.debug( "Relation from %s to %s.%s", metabase_column.name, metabase_column.fk_target_table, @@ -503,6 +504,6 @@ def parse_ref(text: str) -> Optional[str]: # We are catching the rightmost argument of either source or ref which is ultimately the table name matches = re.findall(r"['\"]([\w\_\-\ ]+)['\"][ ]*\)$", text.strip()) if matches: - logger().debug("%s -> %s", text, matches[0]) + logger.debug("%s -> %s", text, matches[0]) return matches[0] return None diff --git a/dbtmetabase/logger/__init__.py b/dbtmetabase/logger/__init__.py deleted file mode 100644 index e69de29..0000000 diff --git a/dbtmetabase/logger/logging.py b/dbtmetabase/logger/logging.py deleted file mode 100644 index fcfe003..0000000 --- a/dbtmetabase/logger/logging.py +++ /dev/null @@ -1,75 +0,0 @@ -import logging -from functools import lru_cache -from logging.handlers import RotatingFileHandler -from pathlib import Path -from typing import Optional, Union - -from rich.logging import RichHandler - -# Log File Format -LOG_FILE_FORMAT = "%(asctime)s — %(name)s — %(levelname)s — %(message)s" - -# Log File Path -LOG_PATH = Path.home().absolute() / ".dbt-metabase" / "logs" - -# Console Output Level -LOGGING_LEVEL = logging.INFO - - -def rotating_log_handler( - name: str, - path: Path, - formatter: str, -) -> RotatingFileHandler: - """This handler writes warning and higher level outputs to logs in a home .dbt-metabase directory rotating them as needed""" - path.mkdir(parents=True, exist_ok=True) - handler = RotatingFileHandler( - str(path / "{log_name}.log".format(log_name=name)), - maxBytes=int(1e6), - backupCount=3, - ) - handler.setFormatter(logging.Formatter(formatter)) - handler.setLevel(logging.WARNING) - return handler - - -@lru_cache(maxsize=10) -def logger( - name: str = "dbtmetabase", - level: Optional[Union[int, str]] = None, - path: Optional[Path] = None, - formatter: Optional[str] = None, -) -> logging.Logger: - """Builds and caches loggers. Can be configured with module level attributes or on a call by call basis. - Simplifies logger management without having to instantiate separate pointers in each module. - - Args: - name (str, optional): Logger name, also used for output log file name in `~/.dbt-metabase/logs` directory. - level (Union[int, str], optional): Logging level, this is explicitly passed to console handler which effects what level of log messages make it to the console. Defaults to logging.INFO. - path (Path, optional): Path for output warning level+ log files. Defaults to `~/.dbt-metabase/logs` - formatter (str, optional): Format for output log files. Defaults to a "time — name — level — message" format - - Returns: - logging.Logger: Prepared logger with rotating logs and console streaming. Can be executed directly from function. - """ - if isinstance(level, str): - level = getattr(logging, level, logging.INFO) - if level is None: - level = LOGGING_LEVEL - if path is None: - path = LOG_PATH - if formatter is None: - formatter = LOG_FILE_FORMAT - _logger = logging.getLogger(name) - _logger.setLevel(level) - _logger.addHandler(rotating_log_handler(name, path, formatter)) - _logger.addHandler( - RichHandler( - level=level, - rich_tracebacks=True, - markup=True, - show_time=False, - ) - ) - _logger.propagate = False - return _logger diff --git a/dbtmetabase/metabase.py b/dbtmetabase/metabase.py index ce7fcce..26cf859 100644 --- a/dbtmetabase/metabase.py +++ b/dbtmetabase/metabase.py @@ -1,5 +1,6 @@ from __future__ import annotations +import logging import re import time from pathlib import Path @@ -16,7 +17,8 @@ ModelType, NullValue, ) -from .logger.logging import logger + +logger = logging.getLogger(__name__) class MetabaseArgumentError(ValueError): @@ -88,7 +90,7 @@ def execute(self): table = tables.get(table_key) if not table: - logger().warning( + logger.warning( "Model %s not found in %s schema", table_key, schema_name ) synced = False @@ -99,7 +101,7 @@ def execute(self): field = table.get("fields", {}).get(column_name) if not field: - logger().warning( + logger.warning( "Column %s not found in %s model", column_name, table_key ) synced = False @@ -122,7 +124,7 @@ def execute(self): f"/api/{update['kind']}/{update['id']}", json=update["body"], ) - logger().info( + logger.info( "Update to %s %s applied successfully", update["kind"], update["id"], @@ -165,7 +167,7 @@ def _export_model(self, model: MetabaseModel) -> bool: api_table = self.tables.get(table_key) if not api_table: - logger().error("Table %s does not exist in Metabase", table_key) + logger.error("Table %s does not exist in Metabase", table_key) return False # Empty strings not accepted by Metabase @@ -194,9 +196,9 @@ def _export_model(self, model: MetabaseModel) -> bool: if body_table: self.queue_update(entity=api_table, delta=body_table) - logger().info("Table %s will be updated", table_key) + logger.info("Table %s will be updated", table_key) else: - logger().info("Table %s is up-to-date", table_key) + logger.info("Table %s is up-to-date", table_key) for column in model.columns: success &= self._export_column(schema_name, model_name, column) @@ -227,7 +229,7 @@ def _export_column( api_field = self.tables.get(table_key, {}).get("fields", {}).get(column_name) if not api_field: - logger().error( + logger.error( "Field %s.%s does not exist in Metabase", table_key, column_name, @@ -255,14 +257,14 @@ def _export_column( ) if not target_table or not target_field: - logger().info( + logger.info( "Passing on fk resolution for %s. Target field %s was not resolved during dbt model parsing.", table_key, target_field, ) else: - logger().debug( + logger.debug( "Looking for field %s in table %s", target_field, target_table, @@ -276,7 +278,7 @@ def _export_column( if fk_target_field: fk_target_field_id = fk_target_field.get("id") if fk_target_field.get(semantic_type_key) != "type/PK": - logger().info( + logger.info( "Target field %s will be set to PK for %s column FK", fk_target_field_id, column_name, @@ -288,13 +290,13 @@ def _export_column( entity=fk_target_field, delta=body_fk_target_field ) else: - logger().info( + logger.info( "Target field %s is already PK, needed for %s column", fk_target_field_id, column_name, ) else: - logger().error( + logger.error( "Unable to find foreign key target %s.%s", target_table, target_field, @@ -351,9 +353,9 @@ def _export_column( if body_field: self.queue_update(entity=api_field, delta=body_field) - logger().info("Field %s.%s will be updated", model_name, column_name) + logger.info("Field %s.%s will be updated", model_name, column_name) else: - logger().info("Field %s.%s is up-to-date", model_name, column_name) + logger.info("Field %s.%s is up-to-date", model_name, column_name) return success @@ -450,7 +452,7 @@ def execute(self) -> Mapping: continue # Iter through collection - logger().info("Exploring collection %s", collection["name"]) + logger.info("Exploring collection %s", collection["name"]) for item in self.client.api( "get", f"/api/collection/{collection['id']}/items" ): @@ -467,7 +469,7 @@ def execute(self) -> Mapping: exposure = self.client.api("get", f"/api/{exposure_type}/{exposure_id}") exposure_name = exposure.get("name", "Exposure [Unresolved Name]") - logger().info( + logger.info( "Introspecting exposure: %s", exposure_name, ) @@ -507,7 +509,7 @@ def execute(self) -> Mapping: self._extract_card_exposures(dashboard_item_reference["id"]) if not self.models_exposed: - logger().info("No models mapped to exposure") + logger.info("No models mapped to exposure") # Extract creator info if "creator" in exposure: @@ -605,7 +607,7 @@ def _extract_card_exposures( # Normal question source_table = self.table_names.get(source_table_id) if source_table: - logger().info( + logger.info( "Model extracted from Metabase question: %s", source_table, ) @@ -623,7 +625,7 @@ def _extract_card_exposures( # Joined model parsed joined_table = self.table_names.get(query_join.get("source-table")) if joined_table: - logger().info( + logger.info( "Model extracted from Metabase question join: %s", joined_table, ) @@ -651,7 +653,7 @@ def _extract_card_exposures( continue if clean_exposure: - logger().info( + logger.info( "Model extracted from native query: %s", clean_exposure, ) @@ -801,7 +803,7 @@ def __init__( raise MetabaseArgumentError("Credentials or session ID required") self.session.headers["X-Metabase-Session"] = session_id - logger().info("Session established successfully") + logger.info("Session established successfully") def api( self, @@ -832,7 +834,7 @@ def api( response.raise_for_status() except requests.exceptions.HTTPError: if critical: - logger().error("HTTP request failed: %s", response.text) + logger.error("HTTP request failed: %s", response.text) raise return {}