diff --git a/dftt_timecode/__init__.py b/dftt_timecode/__init__.py index 86a614d..7a58ef6 100644 --- a/dftt_timecode/__init__.py +++ b/dftt_timecode/__init__.py @@ -27,6 +27,7 @@ from dftt_timecode.core.dftt_timecode import DfttTimecode from dftt_timecode.core.dftt_timerange import DfttTimeRange +from dftt_timecode.logging_config import configure_logging, get_logger # Read version from package metadata (populated from pyproject.toml) try: @@ -116,4 +117,13 @@ def dtr(*args, **kwargs) -> DfttTimeRange: name = "dftt_timecode" __author__ = "You Ziyuan" -__all__ = ["DfttTimecode", "DfttTimeRange", "timecode", "timerange", "dtc", "dtr"] +__all__ = [ + "DfttTimecode", + "DfttTimeRange", + "timecode", + "timerange", + "dtc", + "dtr", + "configure_logging", + "get_logger", +] diff --git a/dftt_timecode/core/dftt_timecode.py b/dftt_timecode/core/dftt_timecode.py index d760070..5ad1e96 100644 --- a/dftt_timecode/core/dftt_timecode.py +++ b/dftt_timecode/core/dftt_timecode.py @@ -5,7 +5,6 @@ timecode functionality for film and television production workflows. """ -import logging from fractions import Fraction from functools import singledispatchmethod from math import ceil, floor @@ -17,6 +16,7 @@ DFTTTimecodeTypeError, DFTTTimecodeValueError, ) +from dftt_timecode.logging_config import get_logger from dftt_timecode.pattern import ( DLP_REGEX, FCPX_REGEX, @@ -29,23 +29,8 @@ TIME_REGEX, ) -# logging.basicConfig(filename='dftt_timecode_log.txt', -# filemode='w', -# format='%(asctime)s %(filename)s[line:%(lineno)d] %(levelname)s %(message)s', -# datefmt='%Y-%m-%d %a %H:%M:%S', -# level=logging.DEBUG) -#set up logger -logger=logging.getLogger(__name__) -logger.setLevel(logging.DEBUG) -formatter=logging.Formatter('%(asctime)s [%(levelname)s] [%(filename)s:%(lineno)d-%(funcName)s()] %(message)s') - -stream_handler=logging.StreamHandler() -stream_handler.setFormatter(formatter) - -# file_handler=logging.FileHandler('dftt_timecode_log.txt',filemode='w') -# file_handler.setFormatter(formatter) - -logger.addHandler(stream_handler) +# Set up logger with automatic level detection based on git branch +logger = get_logger(__name__) TimecodeType: TypeAlias = Literal['smpte', 'srt', 'dlp', 'ffmpeg', 'fcpx', 'frame', 'time', 'auto'] """Type alias for supported timecode format types. @@ -174,7 +159,7 @@ def __validate_drop_frame(self, drop_frame: bool, fps: float) -> bool: # FPS为29.97以及倍数时候，尊重drop_frame参数(for 29.97/59.94/119.88 NDF) return False if not drop_frame else True else: - return round(self.fps, 2) % 23.98 == 0 + return round(fps, 2) % 23.98 == 0 def __detect_timecode_type(self,timecode_value)->TimecodeType: if SMPTE_NDF_REGEX.match(timecode_value): # SMPTE NDF 强制DF为False @@ -183,7 +168,7 @@ def __detect_timecode_type(self,timecode_value)->TimecodeType: return 'smpte' elif SMPTE_DF_REGEX.match(timecode_value): - + # 判断丢帧状态与帧率是否匹配 不匹配则强制转换 if not self.__drop_frame: raise DFTTTimecodeInitializationError(f'Init Timecode Failed: Timecode value [{timecode_value}] DONOT match drop_frame status [{self.__drop_frame}]! Check input.') @@ -198,7 +183,10 @@ def __detect_timecode_type(self,timecode_value)->TimecodeType: return 'frame' elif TIME_REGEX.match(timecode_value): return 'time' - + else: + # No pattern matched - raise error instead of returning None + logger.error(f'Cannot detect timecode type for value [{timecode_value}]. No matching pattern found.') + raise DFTTTimecodeTypeError(f'Cannot detect timecode type for value [{timecode_value}]. No matching pattern found.') def __apply_strict(self) -> None: """Apply 24h wraparound if strict mode enabled""" if self.__strict: @@ -366,9 +354,10 @@ def _(self, timecode_value: str, timecode_type:TimecodeType='auto', fps=24.0, dr 'frame':self.__init_frame, 'time':self.__init_time } - init_func=timecode_type_handler_map[timecode_type] + init_func=timecode_type_handler_map.get(timecode_type) if not init_func: - raise DFTTTimecodeTypeError(f'Unknown timecode type :{timecode_type}') + logger.error(f'Unknown timecode type: [{timecode_type}]') + raise DFTTTimecodeTypeError(f'Unknown timecode type: [{timecode_type}]') init_func(timecode_value,minus_flag) instance_success_log = f'value type {type(timecode_value)} Timecode instance: type={self.__type}, fps={self.__fps}, dropframe={self.__drop_frame}, strict={self.__strict}' @@ -747,17 +736,25 @@ def timecode_output(self, dest_type: TimecodeType = 'auto', output_part: int = 0 - For 'auto', outputs in the current timecode type - Falls back to SMPTE format if dest_type is invalid """ - if dest_type == 'auto': - func = getattr(self, f'_convert_to_output_{self.__type}') - else: - func = getattr(self, f'_convert_to_output_{dest_type}') - if func: - return func(output_part) - else: + # Determine which format to use + format_type = self.__type if dest_type == 'auto' else dest_type + method_name = f'_convert_to_output_{format_type}' + + # Check if the conversion method exists + if not hasattr(self, method_name): logger.warning( - f'CANNOT find such destination type [{dest_type}], will return SMPTE type') - func = getattr(self, '_convert_to_output_smpte', None) + f'CANNOT find conversion method for type [{format_type}], will return SMPTE type') + return self._convert_to_output_smpte(output_part) + + # Call the conversion method + try: + func = getattr(self, method_name) return func(output_part) + except Exception as e: + # If the conversion method fails, log the error and fall back to SMPTE + logger.error( + f'Error during conversion to [{format_type}]: {type(e).__name__}: {e}. Falling back to SMPTE type') + return self._convert_to_output_smpte(output_part) def set_fps(self, dest_fps: float, rounding: bool = True) -> 'DfttTimecode': """Change the frame rate of the timecode. diff --git a/dftt_timecode/core/dftt_timerange.py b/dftt_timecode/core/dftt_timerange.py index 307e21d..9f75f0a 100644 --- a/dftt_timecode/core/dftt_timerange.py +++ b/dftt_timecode/core/dftt_timerange.py @@ -16,6 +16,10 @@ DFTTTimeRangeTypeError, DFTTTimeRangeValueError, ) +from dftt_timecode.logging_config import get_logger + +# Set up logger with automatic level detection based on git branch +logger = get_logger(__name__) class DfttTimeRange: @@ -155,13 +159,25 @@ def __init__( # Validate 24h constraint if self.__strict_24h and abs(self.__precise_duration) > self.TIME_24H_SECONDS: + logger.error( + f"Duration {abs(self.__precise_duration)}s exceeds 24 hours ({self.TIME_24H_SECONDS}s) in strict mode" + ) raise DFTTTimeRangeValueError("Duration exceeds 24 hours in strict mode") + logger.debug( + f"TimeRange created: start={float(self.__start_precise_time):.3f}s, " + f"duration={float(self.__precise_duration):.3f}s, fps={self.__fps}, " + f"forward={self.__forward}, strict_24h={self.__strict_24h}" + ) + def _init_from_timecodes(self, start_tc, end_tc): """Initialize from start and end timecodes""" # Convert inputs to DfttTimecode objects if isinstance(start_tc, DfttTimecode) and isinstance(end_tc, DfttTimecode): if start_tc.fps != end_tc.fps: + logger.error( + f"FPS mismatch: start_tc fps={start_tc.fps}, end_tc fps={end_tc.fps}" + ) raise DFTTTimeRangeFPSError( "FPS mismatch between start and end timecodes" ) @@ -205,6 +221,7 @@ def _init_from_timecodes(self, start_tc, end_tc): self.__precise_duration += self.TIME_24H_SECONDS if self.__precise_duration == 0: + logger.error("Cannot create zero-length timerange") raise DFTTTimeRangeValueError("Time range cannot be zero-length!") self.__start_precise_time = start_precise @@ -308,6 +325,12 @@ def offset(self, offset_value: Union[float, DfttTimecode, str, int]) -> "DfttTim if self.__strict_24h: new_start = new_start % self.TIME_24H_SECONDS + logger.debug( + f"Offset timerange by {float(offset_precise):.3f}s: " + f"old_start={float(self.__start_precise_time):.3f}s, " + f"new_start={float(new_start):.3f}s" + ) + return DfttTimeRange( start_precise_time=new_start, precise_duration=self.__precise_duration, @@ -365,14 +388,24 @@ def extend(self, extend_value: Union[int, float, DfttTimecode, str]) -> "DfttTim ) if new_duration == 0: + logger.error("Cannot create zero-length timerange via extend") raise DFTTTimeRangeValueError("Cannot create zero-length timerange") # Handle 24h constraint if self.__strict_24h and abs(new_duration) > self.TIME_24H_SECONDS: + logger.error( + f"Extended duration {abs(new_duration):.3f}s exceeds 24 hours in strict mode" + ) raise DFTTTimeRangeValueError( "Duration exceeds 24 hours in strict mode" ) + logger.debug( + f"Extend timerange by {float(extend_precise):.3f}s: " + f"old_duration={float(self.__precise_duration):.3f}s, " + f"new_duration={float(new_duration):.3f}s" + ) + return DfttTimeRange( start_precise_time=self.__start_precise_time, precise_duration=new_duration, @@ -446,6 +479,9 @@ def reverse(self) -> "DfttTimeRange": - Duration magnitude is preserved - This is useful for working with timeranges that play backward """ + logger.debug( + f"Reversing timerange: forward={self.__forward} -> {not self.__forward}" + ) return DfttTimeRange( start_precise_time=self.end_precise_time, precise_duration=self.__precise_duration, @@ -499,16 +535,27 @@ def retime(self, retime_factor: Union[int, float, Fraction]) -> "DfttTimeRange": - Can also use the ``*`` operator for the same effect """ if not isinstance(retime_factor, (int, float, Fraction)): + logger.error(f"Retime factor must be numeric, got {type(retime_factor)}") raise DFTTTimeRangeTypeError("Retime factor must be numeric") if retime_factor == 0: + logger.error("Cannot retime to zero duration") raise DFTTTimeRangeValueError("Cannot retime to zero duration") new_duration = self.__precise_duration * Fraction(retime_factor) if self.__strict_24h and abs(new_duration) > self.TIME_24H_SECONDS: + logger.error( + f"Retimed duration {abs(new_duration):.3f}s exceeds 24 hours in strict mode" + ) raise DFTTTimeRangeValueError("Duration exceeds 24 hours in strict mode") + logger.debug( + f"Retime timerange by factor {retime_factor}: " + f"old_duration={float(self.__precise_duration):.3f}s, " + f"new_duration={float(new_duration):.3f}s" + ) + return DfttTimeRange( start_precise_time=self.__start_precise_time, precise_duration=new_duration, @@ -555,9 +602,13 @@ def separate(self, num_parts: int) -> List["DfttTimeRange"]: - Useful for splitting work into parallel chunks or creating segments """ if num_parts < 2: + logger.error(f"Cannot separate into {num_parts} parts, must be >= 2") raise DFTTTimeRangeValueError("Must separate into at least 2 parts") part_duration = self.__precise_duration / num_parts + logger.debug( + f"Separating timerange into {num_parts} parts, each with duration={float(part_duration):.3f}s" + ) parts = [] for i in range(num_parts): @@ -668,16 +719,25 @@ def intersect(self, other: "DfttTimeRange") -> Optional["DfttTimeRange"]: - Strict_24h is True only if both input timeranges have it enabled """ if not isinstance(other, DfttTimeRange): + logger.error(f"Can only intersect with DfttTimeRange, got {type(other)}") raise DFTTTimeRangeTypeError( "Can only intersect with another DfttTimeRange" ) if self.__forward != other.forward: + logger.error( + f"Cannot intersect timeranges with different directions: " + f"self.forward={self.__forward}, other.forward={other.forward}" + ) raise DFTTTimeRangeMethodError( "Cannot intersect timeranges with different directions" ) if self.__fps != other.fps: + logger.error( + f"Cannot intersect timeranges with different FPS: " + f"self.fps={self.__fps}, other.fps={other.fps}" + ) raise DFTTTimeRangeFPSError( "Cannot intersect timeranges with different FPS" ) @@ -691,9 +751,13 @@ def intersect(self, other: "DfttTimeRange") -> Optional["DfttTimeRange"]: end = max(self.end_precise_time, other.end_precise_time) if (self.__forward and start >= end) or (not self.__forward and start <= end): + logger.debug("No intersection found between timeranges") return None # No intersection duration = end - start if self.__forward else start - end + logger.debug( + f"Intersection found: start={float(start):.3f}s, duration={float(duration):.3f}s" + ) return DfttTimeRange( start_precise_time=start, @@ -775,14 +839,23 @@ def union(self, other: "DfttTimeRange") -> "DfttTimeRange": - :meth:`add`: Add durations (different from union) """ if not isinstance(other, DfttTimeRange): + logger.error(f"Can only union with DfttTimeRange, got {type(other)}") raise DFTTTimeRangeTypeError("Can only union with another DfttTimeRange") if self.__forward != other.forward: + logger.error( + f"Cannot union timeranges with different directions: " + f"self.forward={self.__forward}, other.forward={other.forward}" + ) raise DFTTTimeRangeMethodError( "Cannot union timeranges with different directions" ) if self.__fps != other.fps: + logger.error( + f"Cannot union timeranges with different FPS: " + f"self.fps={self.__fps}, other.fps={other.fps}" + ) raise DFTTTimeRangeFPSError("Cannot union timeranges with different FPS") # Check for overlap or adjacency @@ -793,6 +866,11 @@ def union(self, other: "DfttTimeRange") -> "DfttTimeRange": self.end_precise_time == other.start_precise_time or other.end_precise_time == self.__start_precise_time ): + logger.error( + "Cannot union non-overlapping, non-adjacent timeranges: " + f"self=[{float(self.__start_precise_time):.3f}s, {float(self.end_precise_time):.3f}s], " + f"other=[{float(other.start_precise_time):.3f}s, {float(other.end_precise_time):.3f}s]" + ) raise DFTTTimeRangeMethodError( "Cannot union non-overlapping, non-adjacent timeranges" ) @@ -801,6 +879,9 @@ def union(self, other: "DfttTimeRange") -> "DfttTimeRange": self.end_precise_time == other.start_precise_time or other.end_precise_time == self.__start_precise_time ): + logger.error( + "Cannot union non-overlapping, non-adjacent timeranges (backward)" + ) raise DFTTTimeRangeMethodError( "Cannot union non-overlapping, non-adjacent timeranges" ) @@ -815,6 +896,10 @@ def union(self, other: "DfttTimeRange") -> "DfttTimeRange": duration = end - start if self.__forward else start - end + logger.debug( + f"Union created: start={float(start):.3f}s, duration={float(duration):.3f}s" + ) + return DfttTimeRange( start_precise_time=start, precise_duration=duration, @@ -860,9 +945,14 @@ def add(self, other: "DfttTimeRange") -> "DfttTimeRange": - This is different from :meth:`union` which combines overlapping ranges """ if not isinstance(other, DfttTimeRange): + logger.error(f"Can only add DfttTimeRange, got {type(other)}") raise DFTTTimeRangeTypeError("Can only add another DfttTimeRange") if self.__fps != other.fps: + logger.error( + f"Cannot add timeranges with different FPS: " + f"self.fps={self.__fps}, other.fps={other.fps}" + ) raise DFTTTimeRangeFPSError("Cannot add timeranges with different FPS") # Direction sensitive addition @@ -872,8 +962,15 @@ def add(self, other: "DfttTimeRange") -> "DfttTimeRange": new_duration = self.__precise_duration - other.precise_duration if new_duration == 0: + logger.error("Add operation resulted in zero-length timerange") raise DFTTTimeRangeValueError("Cannot create zero-length timerange") + logger.debug( + f"Add timerange: same_direction={self.__forward == other.forward}, " + f"old_duration={float(self.__precise_duration):.3f}s, " + f"new_duration={float(new_duration):.3f}s" + ) + return DfttTimeRange( start_precise_time=self.__start_precise_time, precise_duration=new_duration, @@ -923,9 +1020,14 @@ def subtract(self, other: "DfttTimeRange") -> "DfttTimeRange": - Can result in zero-length error if durations are equal """ if not isinstance(other, DfttTimeRange): + logger.error(f"Can only subtract DfttTimeRange, got {type(other)}") raise DFTTTimeRangeTypeError("Can only subtract another DfttTimeRange") if self.__fps != other.fps: + logger.error( + f"Cannot subtract timeranges with different FPS: " + f"self.fps={self.__fps}, other.fps={other.fps}" + ) raise DFTTTimeRangeFPSError("Cannot subtract timeranges with different FPS") # Direction sensitive subtraction @@ -935,8 +1037,15 @@ def subtract(self, other: "DfttTimeRange") -> "DfttTimeRange": new_duration = self.__precise_duration + other.precise_duration if new_duration == 0: + logger.error("Subtract operation resulted in zero-length timerange") raise DFTTTimeRangeValueError("Cannot create zero-length timerange") + logger.debug( + f"Subtract timerange: same_direction={self.__forward == other.forward}, " + f"old_duration={float(self.__precise_duration):.3f}s, " + f"new_duration={float(new_duration):.3f}s" + ) + return DfttTimeRange( start_precise_time=self.__start_precise_time, precise_duration=new_duration, diff --git a/dftt_timecode/logging_config.py b/dftt_timecode/logging_config.py new file mode 100644 index 0000000..1172bc8 --- /dev/null +++ b/dftt_timecode/logging_config.py @@ -0,0 +1,172 @@ +""" +Logging configuration for DFTT Timecode library. + +Automatically adjusts log level based on development context: +- **Installed packages** (from PyPI/build): INFO level (production default) +- **Main branch**: INFO level (production-ready code after PR) +- **Development branches** (dev, feature/*): DEBUG level (detailed tracing) + +The logging level can be overridden with the DFTT_LOG_LEVEL environment variable. + +Example: + # Use default log level (INFO for installed packages, branch-dependent for development) + from dftt_timecode import DfttTimecode + tc = DfttTimecode('01:00:00:00', fps=24) + + # Override log level via environment variable + import os + os.environ['DFTT_LOG_LEVEL'] = 'WARNING' + + # Or configure programmatically + import logging + from dftt_timecode import configure_logging + configure_logging(logging.DEBUG) +""" + +import logging +import os +import subprocess +from typing import Optional + + +def _get_git_branch() -> Optional[str]: + """ + Get the current git branch name. + + Returns: + str: The current branch name, or None if not in a git repo or error occurs. + """ + try: + result = subprocess.run( + ['git', 'rev-parse', '--abbrev-ref', 'HEAD'], + capture_output=True, + text=True, + timeout=2, + check=False + ) + if result.returncode == 0: + return result.stdout.strip() + except (subprocess.TimeoutExpired, FileNotFoundError, Exception): + pass + return None + + +def _determine_log_level() -> int: + """ + Determine the appropriate log level based on environment and git branch. + + Priority: + 1. DFTT_LOG_LEVEL environment variable (if set) + 2. DEBUG for development branches (dev, feature/*, etc.) + 3. INFO for main branch OR when git info unavailable (built packages) + + The default for built/installed packages is INFO to avoid verbose output + in production environments. + + Returns: + int: logging level constant (logging.DEBUG, logging.INFO, etc.) + """ + # Check environment variable first (highest priority) + env_level = os.environ.get('DFTT_LOG_LEVEL', '').upper() + if env_level: + level_mapping = { + 'DEBUG': logging.DEBUG, + 'INFO': logging.INFO, + 'WARNING': logging.WARNING, + 'ERROR': logging.ERROR, + 'CRITICAL': logging.CRITICAL, + } + if env_level in level_mapping: + return level_mapping[env_level] + + # Check git branch + branch = _get_git_branch() + + if branch is None: + # No git info available (e.g., installed package from PyPI) + # Default to INFO for production use + return logging.INFO + elif branch == 'main': + # Main branch: production-ready code after PR + return logging.INFO + else: + # Development/feature branches: verbose debugging + return logging.DEBUG + + +def get_logger(name: str) -> logging.Logger: + """ + Get a configured logger for the specified module. + + The logger is configured with: + - Appropriate log level based on git branch (INFO for main, DEBUG for others) + - Formatted output with timestamp, level, file, line number, function name, and message + - Stream handler for console output + + Args: + name: Logger name (typically __name__ from the calling module) + + Returns: + logging.Logger: Configured logger instance + + Example: + >>> from dftt_timecode.logging_config import get_logger + >>> logger = get_logger(__name__) + >>> logger.debug("This is a debug message") + >>> logger.info("This is an info message") + """ + logger = logging.getLogger(name) + + # Avoid adding handlers multiple times + if logger.handlers: + return logger + + # Determine log level + log_level = _determine_log_level() + logger.setLevel(log_level) + + # Create formatter + formatter = logging.Formatter( + '%(asctime)s [%(levelname)s] [%(filename)s:%(lineno)d-%(funcName)s()] %(message)s' + ) + + # Create and configure stream handler + stream_handler = logging.StreamHandler() + stream_handler.setLevel(log_level) + stream_handler.setFormatter(formatter) + + # Add handler to logger + logger.addHandler(stream_handler) + + # Prevent propagation to root logger to avoid duplicate messages + logger.propagate = False + + return logger + + +def configure_logging(level: Optional[int] = None) -> None: + """ + Configure logging for the entire dftt_timecode package. + + This function can be called by users to manually set the log level + for all dftt_timecode loggers. + + Args: + level: Optional logging level (logging.DEBUG, logging.INFO, etc.). + If None, uses automatic detection based on git branch. + + Example: + >>> import logging + >>> from dftt_timecode.logging_config import configure_logging + >>> configure_logging(logging.WARNING) # Only show warnings and above + """ + if level is None: + level = _determine_log_level() + + # Configure all dftt_timecode loggers + for logger_name in logging.Logger.manager.loggerDict: + if logger_name.startswith('dftt_timecode'): + logger = logging.getLogger(logger_name) + logger.setLevel(level) + for handler in logger.handlers: + handler.setLevel(level) diff --git a/test/test_logging_config.py b/test/test_logging_config.py new file mode 100644 index 0000000..6239923 --- /dev/null +++ b/test/test_logging_config.py @@ -0,0 +1,285 @@ +""" +Tests for logging configuration module. + +Tests the automatic log level detection based on git branch and +environment variable configuration. +""" + +import logging +import subprocess +from unittest.mock import patch + +from dftt_timecode.logging_config import ( + _determine_log_level, + _get_git_branch, + configure_logging, + get_logger, +) + + +class TestGitBranchDetection: + """Test git branch detection functionality.""" + + def test_get_git_branch_in_repo(self): + """Test that _get_git_branch returns a branch name when in a git repo.""" + branch = _get_git_branch() + # Should return a string (branch name) or None if not in repo + assert branch is None or isinstance(branch, str) + + @patch('subprocess.run') + def test_get_git_branch_success(self, mock_run): + """Test successful git branch detection.""" + mock_run.return_value.returncode = 0 + mock_run.return_value.stdout = 'main\n' + + branch = _get_git_branch() + assert branch == 'main' + + @patch('subprocess.run') + def test_get_git_branch_not_in_repo(self, mock_run): + """Test behavior when not in a git repository.""" + mock_run.return_value.returncode = 128 + mock_run.return_value.stdout = '' + + branch = _get_git_branch() + assert branch is None + + @patch('subprocess.run') + def test_get_git_branch_timeout(self, mock_run): + """Test behavior when git command times out.""" + mock_run.side_effect = subprocess.TimeoutExpired('git', 2) + + branch = _get_git_branch() + assert branch is None + + @patch('subprocess.run') + def test_get_git_branch_file_not_found(self, mock_run): + """Test behavior when git is not installed.""" + mock_run.side_effect = FileNotFoundError() + + branch = _get_git_branch() + assert branch is None + + +class TestLogLevelDetermination: + """Test log level determination logic.""" + + def test_determine_log_level_with_env_debug(self, monkeypatch): + """Test that DFTT_LOG_LEVEL env var sets DEBUG level.""" + monkeypatch.setenv('DFTT_LOG_LEVEL', 'DEBUG') + level = _determine_log_level() + assert level == logging.DEBUG + + def test_determine_log_level_with_env_info(self, monkeypatch): + """Test that DFTT_LOG_LEVEL env var sets INFO level.""" + monkeypatch.setenv('DFTT_LOG_LEVEL', 'INFO') + level = _determine_log_level() + assert level == logging.INFO + + def test_determine_log_level_with_env_warning(self, monkeypatch): + """Test that DFTT_LOG_LEVEL env var sets WARNING level.""" + monkeypatch.setenv('DFTT_LOG_LEVEL', 'WARNING') + level = _determine_log_level() + assert level == logging.WARNING + + def test_determine_log_level_with_env_error(self, monkeypatch): + """Test that DFTT_LOG_LEVEL env var sets ERROR level.""" + monkeypatch.setenv('DFTT_LOG_LEVEL', 'ERROR') + level = _determine_log_level() + assert level == logging.ERROR + + def test_determine_log_level_with_env_critical(self, monkeypatch): + """Test that DFTT_LOG_LEVEL env var sets CRITICAL level.""" + monkeypatch.setenv('DFTT_LOG_LEVEL', 'CRITICAL') + level = _determine_log_level() + assert level == logging.CRITICAL + + @patch('dftt_timecode.logging_config._get_git_branch') + def test_determine_log_level_with_invalid_env(self, mock_get_branch, monkeypatch): + """Test that invalid DFTT_LOG_LEVEL env var is ignored.""" + monkeypatch.setenv('DFTT_LOG_LEVEL', 'INVALID') + # Mock git to return a dev branch for predictable testing + mock_get_branch.return_value = 'dev' + level = _determine_log_level() + # Should fall back to branch-based detection + assert level == logging.DEBUG + + @patch('dftt_timecode.logging_config._get_git_branch') + def test_determine_log_level_main_branch(self, mock_get_branch, monkeypatch): + """Test that main branch gets INFO level.""" + monkeypatch.delenv('DFTT_LOG_LEVEL', raising=False) + mock_get_branch.return_value = 'main' + + level = _determine_log_level() + assert level == logging.INFO + + @patch('dftt_timecode.logging_config._get_git_branch') + def test_determine_log_level_dev_branch(self, mock_get_branch, monkeypatch): + """Test that dev branch gets DEBUG level.""" + monkeypatch.delenv('DFTT_LOG_LEVEL', raising=False) + mock_get_branch.return_value = 'dev' + + level = _determine_log_level() + assert level == logging.DEBUG + + @patch('dftt_timecode.logging_config._get_git_branch') + def test_determine_log_level_feature_branch(self, mock_get_branch, monkeypatch): + """Test that feature branches get DEBUG level.""" + monkeypatch.delenv('DFTT_LOG_LEVEL', raising=False) + mock_get_branch.return_value = 'feature/new-feature' + + level = _determine_log_level() + assert level == logging.DEBUG + + @patch('dftt_timecode.logging_config._get_git_branch') + def test_determine_log_level_no_git(self, mock_get_branch, monkeypatch): + """Test that INFO is used when git info unavailable (built packages).""" + monkeypatch.delenv('DFTT_LOG_LEVEL', raising=False) + mock_get_branch.return_value = None + + level = _determine_log_level() + assert level == logging.INFO + + def test_env_var_overrides_branch(self, monkeypatch): + """Test that environment variable takes priority over branch detection.""" + monkeypatch.setenv('DFTT_LOG_LEVEL', 'ERROR') + # Even if we're on main branch, env var should win + level = _determine_log_level() + assert level == logging.ERROR + + @patch('dftt_timecode.logging_config._get_git_branch') + def test_installed_package_defaults_to_info(self, mock_get_branch, monkeypatch): + """Test that installed packages (no git) default to INFO level.""" + monkeypatch.delenv('DFTT_LOG_LEVEL', raising=False) + mock_get_branch.return_value = None + + level = _determine_log_level() + # Built/installed packages should use INFO, not DEBUG + assert level == logging.INFO + + +class TestGetLogger: + """Test logger creation and configuration.""" + + def test_get_logger_returns_logger(self): + """Test that get_logger returns a Logger instance.""" + logger = get_logger('test_module') + assert isinstance(logger, logging.Logger) + + def test_get_logger_has_handler(self): + """Test that logger has at least one handler configured.""" + logger = get_logger('test_module_2') + assert len(logger.handlers) > 0 + + def test_get_logger_has_formatter(self): + """Test that logger's handler has a formatter configured.""" + logger = get_logger('test_module_3') + handler = logger.handlers[0] + assert handler.formatter is not None + + def test_get_logger_no_propagate(self): + """Test that logger doesn't propagate to root logger.""" + logger = get_logger('test_module_4') + assert logger.propagate is False + + def test_get_logger_idempotent(self): + """Test that calling get_logger multiple times doesn't add duplicate handlers.""" + logger1 = get_logger('test_module_5') + handler_count_1 = len(logger1.handlers) + + logger2 = get_logger('test_module_5') + handler_count_2 = len(logger2.handlers) + + assert logger1 is logger2 + assert handler_count_1 == handler_count_2 + + @patch('dftt_timecode.logging_config._get_git_branch') + def test_get_logger_level_main_branch(self, mock_get_branch, monkeypatch): + """Test that logger has INFO level on main branch.""" + monkeypatch.delenv('DFTT_LOG_LEVEL', raising=False) + mock_get_branch.return_value = 'main' + + logger = get_logger('test_module_main') + assert logger.level == logging.INFO + + @patch('dftt_timecode.logging_config._get_git_branch') + def test_get_logger_level_dev_branch(self, mock_get_branch, monkeypatch): + """Test that logger has DEBUG level on dev branch.""" + monkeypatch.delenv('DFTT_LOG_LEVEL', raising=False) + mock_get_branch.return_value = 'dev' + + logger = get_logger('test_module_dev') + assert logger.level == logging.DEBUG + + +class TestConfigureLogging: + """Test manual logging configuration.""" + + def test_configure_logging_with_level(self): + """Test that configure_logging sets specified level.""" + # Create a test logger first + logger = get_logger('dftt_timecode.test_config') + + # Configure to WARNING + configure_logging(logging.WARNING) + + # Check that the level was updated + assert logger.level == logging.WARNING + + @patch('dftt_timecode.logging_config._get_git_branch') + def test_configure_logging_without_level(self, mock_get_branch): + """Test that configure_logging uses automatic detection when level not specified.""" + # Create a test logger first + logger = get_logger('dftt_timecode.test_config_2') + + # Mock git to return main branch + mock_get_branch.return_value = 'main' + + # Configure without specifying level + configure_logging() + + # Should use branch-based detection (INFO for main) + assert logger.level == logging.INFO + + def test_configure_logging_updates_handlers(self): + """Test that configure_logging updates handler levels.""" + # Create a test logger first + logger = get_logger('dftt_timecode.test_config_3') + + # Configure to ERROR + configure_logging(logging.ERROR) + + # Check that handlers were updated + for handler in logger.handlers: + assert handler.level == logging.ERROR + + +class TestIntegration: + """Integration tests for logging system.""" + + def test_dftt_timecode_uses_logging_config(self): + """Test that DfttTimecode module uses the new logging config.""" + from dftt_timecode.core.dftt_timecode import logger + + # Should be a proper Logger instance + assert isinstance(logger, logging.Logger) + + # Should have handlers configured + assert len(logger.handlers) > 0 + + def test_logging_exports_from_main_package(self): + """Test that logging functions are exported from main package.""" + from dftt_timecode import configure_logging as conf + from dftt_timecode import get_logger as gl + + assert callable(conf) + assert callable(gl) + + def test_real_world_usage(self): + """Test a real-world usage scenario.""" + # Import and create a timecode + from dftt_timecode import DfttTimecode + + # This should not raise any errors + tc = DfttTimecode('01:00:00:00', fps=24) + assert tc is not None