diff --git a/src/dab_project/cli.py b/src/dab_project/cli.py index 64268a2..77cfae2 100644 --- a/src/dab_project/cli.py +++ b/src/dab_project/cli.py @@ -1,6 +1,8 @@ import argparse +import logging import sys +from dab_project.logging_config import setup_logging from dab_project.tasks.base_task import Task @@ -12,16 +14,23 @@ def main(): parser.add_argument( "--catalog", type=str, default="lake_dev", help="The catalog to use (default: lake_dev)" ) + parser.add_argument( + "-v", "--verbose", action="store_true", help="Enable verbose (DEBUG) logging" + ) args = parser.parse_args() + # Setup logging based on verbose flag + setup_logging(verbose=args.verbose) + logger = logging.getLogger(__name__) + for component in args.components: try: task = Task.create_task_factory(component) task.run(catalog_name=args.catalog) except ValueError as e: - print(f"Error with component '{component}': {e}") + logger.error(f"Error with component '{component}': {e}") sys.exit(1) except Exception as e: - print(f"An unexpected error occurred with component '{component}': {e}") + logger.error(f"An unexpected error occurred with component '{component}': {e}") sys.exit(1) diff --git a/src/dab_project/logging_config.py b/src/dab_project/logging_config.py new file mode 100644 index 0000000..66c2ac5 --- /dev/null +++ b/src/dab_project/logging_config.py @@ -0,0 +1,44 @@ +"""Logging configuration for dab_project.""" + +import logging +import sys + + +def setup_logging(verbose: bool = False) -> None: + """ + Configure logging for the dab_project application. + + Parameters + ---------- + verbose : bool, optional + If True, set logging level to DEBUG. Otherwise, set to INFO (default: False) + + Notes + ----- + Log format: YYYY-MM-DD HH:MM:SS,mmm - LEVEL - module - message + Example: 2025-04-23 10:35:42,789 - INFO - auth - User login successful + + Currently logs to console only, but can be extended to log to files in the future. + """ + log_level = logging.DEBUG if verbose else logging.INFO + + # Create formatter with the specified format + # Note: %(asctime)s defaults to 'YYYY-MM-DD HH:MM:SS,mmm' format + formatter = logging.Formatter( + fmt="%(asctime)s - %(levelname)s - %(name)s - %(message)s", + ) + + # Configure root logger + root_logger = logging.getLogger() + root_logger.setLevel(log_level) + + # Remove any existing handlers to avoid duplicate logs + root_logger.handlers.clear() + + # Create console handler + console_handler = logging.StreamHandler(sys.stdout) + console_handler.setLevel(log_level) + console_handler.setFormatter(formatter) + + # Add handler to root logger + root_logger.addHandler(console_handler) diff --git a/src/dab_project/tasks/base_task.py b/src/dab_project/tasks/base_task.py index 03029ba..44f575f 100644 --- a/src/dab_project/tasks/base_task.py +++ b/src/dab_project/tasks/base_task.py @@ -72,6 +72,7 @@ def run(self, catalog_name: str) -> None: def _log_start(self) -> None: self.logger.info(f"Starting ETL task: {self.name}") + self.logger.debug(f"Task class: {self.__class__.__module__}.{self.__class__.__name__}") def _log_exit(self, success: bool, error: Optional[Exception] = None) -> None: if success: diff --git a/tests/test_logging.py b/tests/test_logging.py new file mode 100644 index 0000000..5f440b2 --- /dev/null +++ b/tests/test_logging.py @@ -0,0 +1,121 @@ +"""Tests for logging configuration.""" + +import logging +import re + +import pytest + +from dab_project.logging_config import setup_logging + + +@pytest.fixture(autouse=True) +def reset_logging(): + """Reset logging configuration after each test.""" + yield + # Clear all handlers after each test + root_logger = logging.getLogger() + root_logger.handlers.clear() + root_logger.setLevel(logging.WARNING) + + +def test_setup_logging_default_level(capsys): + """Test that default logging level is INFO.""" + setup_logging(verbose=False) + + logger = logging.getLogger("test_module") + logger.debug("This is a debug message") + logger.info("This is an info message") + logger.warning("This is a warning message") + + captured = capsys.readouterr() + # DEBUG should not be logged + assert "This is a debug message" not in captured.out + # INFO and higher should be logged + assert "This is an info message" in captured.out + assert "This is a warning message" in captured.out + + +def test_setup_logging_verbose_level(capsys): + """Test that verbose flag enables DEBUG logging.""" + setup_logging(verbose=True) + + logger = logging.getLogger("test_module") + logger.debug("This is a debug message") + logger.info("This is an info message") + + captured = capsys.readouterr() + # Both DEBUG and INFO should be logged + assert "This is a debug message" in captured.out + assert "This is an info message" in captured.out + + +def test_logging_format(capsys): + """Test that log format matches expected pattern.""" + setup_logging(verbose=False) + + logger = logging.getLogger("test_module") + logger.info("Test message") + + captured = capsys.readouterr() + # Expected format: YYYY-MM-DD HH:MM:SS,mmm - LEVEL - module - message + # Example: 2025-04-23 10:35:42,789 - INFO - test_module - Test message + log_pattern = r"\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2},\d{3} - INFO - test_module - Test message" + + assert re.search(log_pattern, captured.out) is not None + + +def test_logging_different_levels(capsys): + """Test logging at different levels.""" + setup_logging(verbose=False) + + logger = logging.getLogger("test_module") + logger.info("Info message") + logger.warning("Warning message") + logger.error("Error message") + logger.critical("Critical message") + + captured = capsys.readouterr() + assert "Info message" in captured.out + assert "Warning message" in captured.out + assert "Error message" in captured.out + assert "Critical message" in captured.out + assert "- INFO -" in captured.out + assert "- WARNING -" in captured.out + assert "- ERROR -" in captured.out + assert "- CRITICAL -" in captured.out + + +def test_logging_no_duplicate_handlers(capsys): + """Test that calling setup_logging multiple times doesn't create duplicate handlers.""" + # Call setup_logging twice + setup_logging(verbose=False) + setup_logging(verbose=False) + + logger = logging.getLogger("test_module") + logger.info("Test message") + + captured = capsys.readouterr() + # Count occurrences - should appear only once + assert captured.out.count("Test message") == 1 + + +def test_setup_logging_root_logger_level(): + """Test that root logger level is set correctly.""" + setup_logging(verbose=False) + root_logger = logging.getLogger() + assert root_logger.level == logging.INFO + + setup_logging(verbose=True) + root_logger = logging.getLogger() + assert root_logger.level == logging.DEBUG + + +def test_setup_logging_handler_count(): + """Test that setup_logging creates exactly one handler.""" + setup_logging(verbose=False) + root_logger = logging.getLogger() + assert len(root_logger.handlers) == 1 + + # Calling again should still result in only one handler + setup_logging(verbose=False) + assert len(root_logger.handlers) == 1