From 24df6c701ee22b2c0b5a35b88f62890fa8c47731 Mon Sep 17 00:00:00 2001 From: g3n35i5 Date: Sun, 5 Feb 2023 17:18:42 +0100 Subject: [PATCH] refactor: Improved logging behavior --- ffmpeg_normalize/__init__.py | 2 + ffmpeg_normalize/__main__.py | 24 +++++------ ffmpeg_normalize/_cmd_utils.py | 15 ++++--- ffmpeg_normalize/_ffmpeg_normalize.py | 13 +++--- ffmpeg_normalize/_logger.py | 58 +++++++++++++-------------- ffmpeg_normalize/_media_file.py | 36 ++++++++--------- ffmpeg_normalize/_streams.py | 32 +++++++-------- requirements.txt | 1 + 8 files changed, 88 insertions(+), 93 deletions(-) diff --git a/ffmpeg_normalize/__init__.py b/ffmpeg_normalize/__init__.py index 81efa94..c973c55 100644 --- a/ffmpeg_normalize/__init__.py +++ b/ffmpeg_normalize/__init__.py @@ -4,6 +4,8 @@ from ._streams import AudioStream, MediaStream, SubtitleStream, VideoStream from ._version import __version__ +__module_name__ = "ffmpeg_normalize" + __all__ = [ "FFmpegNormalize", "FFmpegNormalizeError", diff --git a/ffmpeg_normalize/__main__.py b/ffmpeg_normalize/__main__.py index fb9b556..7194007 100644 --- a/ffmpeg_normalize/__main__.py +++ b/ffmpeg_normalize/__main__.py @@ -12,10 +12,10 @@ from ._errors import FFmpegNormalizeError from ._ffmpeg_normalize import NORMALIZATION_TYPES, FFmpegNormalize -from ._logger import setup_custom_logger +from ._logger import setup_cli_logger from ._version import __version__ -logger = setup_custom_logger() +_logger = logging.getLogger(__name__) def create_parser() -> argparse.ArgumentParser: @@ -442,19 +442,13 @@ def create_parser() -> argparse.ArgumentParser: def main() -> None: cli_args = create_parser().parse_args() - - if cli_args.quiet: - logger.setLevel(logging.ERROR) - elif cli_args.debug: - logger.setLevel(logging.DEBUG) - elif cli_args.verbose: - logger.setLevel(logging.INFO) + setup_cli_logger(arguments=cli_args) def error(message: object) -> NoReturn: - if logger.getEffectiveLevel() == logging.DEBUG: - logger.error(f"FFmpegNormalizeError: {message}") + if _logger.getEffectiveLevel() == logging.DEBUG: + _logger.error(f"FFmpegNormalizeError: {message}") else: - logger.error(message) + _logger.error(message) sys.exit(1) def _split_options(opts: str) -> list[str]: @@ -515,7 +509,7 @@ def _split_options(opts: str) -> list[str]: ) if cli_args.output and len(cli_args.input) > len(cli_args.output): - logger.warning( + _logger.warning( "There are more input files than output file names given. " "Please specify one output file name per input file using -o ... " "Will apply default file naming for the remaining ones." @@ -524,7 +518,7 @@ def _split_options(opts: str) -> list[str]: for index, input_file in enumerate(cli_args.input): if cli_args.output is not None and index < len(cli_args.output): if cli_args.output_folder and cli_args.output_folder != "normalized": - logger.warning( + _logger.warning( f"Output folder {cli_args.output_folder} is ignored for " f"input file {input_file}" ) @@ -540,7 +534,7 @@ def _split_options(opts: str) -> list[str]: + cli_args.extension, ) if not os.path.isdir(cli_args.output_folder) and not cli_args.dry_run: - logger.warning( + _logger.warning( f"Output directory '{cli_args.output_folder}' does not exist, will create" ) os.makedirs(cli_args.output_folder, exist_ok=True) diff --git a/ffmpeg_normalize/_cmd_utils.py b/ffmpeg_normalize/_cmd_utils.py index 1ecc83f..6b97bcb 100644 --- a/ffmpeg_normalize/_cmd_utils.py +++ b/ffmpeg_normalize/_cmd_utils.py @@ -11,9 +11,8 @@ from ffmpeg_progress_yield import FfmpegProgress from ._errors import FFmpegNormalizeError -from ._logger import setup_custom_logger -logger = setup_custom_logger() +_logger = logging.getLogger(__name__) NUL = "NUL" if system() in ("Windows", "cli") else "/dev/null" DUR_REGEX = re.compile( @@ -75,14 +74,14 @@ def run_ffmpeg_command(self, cmd: list[str]) -> Iterator[int]: int: Progress percentage """ # wrapper for 'ffmpeg-progress-yield' - logger.debug(f"Running command: {cmd}") + _logger.debug(f"Running command: {cmd}") ff = FfmpegProgress(cmd, dry_run=self.dry) yield from ff.run_command_with_progress() self.output = ff.stderr - if logger.getEffectiveLevel() == logging.DEBUG and self.output is not None: - logger.debug( + if _logger.getEffectiveLevel() == logging.DEBUG and self.output is not None: + _logger.debug( f"ffmpeg output: {CommandRunner.prune_ffmpeg_progress_from_output(self.output)}" ) @@ -97,10 +96,10 @@ def run_command(self, cmd: list[str]) -> CommandRunner: Raises: RuntimeError: If command returns non-zero exit code """ - logger.debug(f"Running command: {cmd}") + _logger.debug(f"Running command: {cmd}") if self.dry: - logger.debug("Dry mode specified, not actually running command") + _logger.debug("Dry mode specified, not actually running command") return self p = subprocess.Popen( @@ -187,7 +186,7 @@ def ffmpeg_has_loudnorm() -> bool: output = CommandRunner().run_command([get_ffmpeg_exe(), "-filters"]).get_output() supports_loudnorm = "loudnorm" in output if not supports_loudnorm: - logger.error( + _logger.error( "Your ffmpeg does not support the 'loudnorm' filter. " "Please make sure you are running ffmpeg v4.2 or above." ) diff --git a/ffmpeg_normalize/_ffmpeg_normalize.py b/ffmpeg_normalize/_ffmpeg_normalize.py index 85c51ac..9379117 100644 --- a/ffmpeg_normalize/_ffmpeg_normalize.py +++ b/ffmpeg_normalize/_ffmpeg_normalize.py @@ -2,19 +2,20 @@ import json import os +import logging from typing import TYPE_CHECKING, Literal from tqdm import tqdm from ._cmd_utils import ffmpeg_has_loudnorm, get_ffmpeg_exe from ._errors import FFmpegNormalizeError -from ._logger import setup_custom_logger + from ._media_file import MediaFile if TYPE_CHECKING: from ._streams import LoudnessStatisticsWithMetadata -logger = setup_custom_logger() +_logger = logging.getLogger(__name__) NORMALIZATION_TYPES = ("ebu", "rms", "peak") PCM_INCOMPATIBLE_FORMATS = {"flac", "mp3", "mp4", "ogg", "oga", "opus", "webm"} @@ -142,7 +143,7 @@ def __init__( self.keep_loudness_range_target = keep_loudness_range_target if self.keep_loudness_range_target and loudness_range_target != 7.0: - logger.warning( + _logger.warning( "Setting --keep-loudness-range-target will override your set loudness range target value! " "Remove --keep-loudness-range-target or remove the --lrt/--loudness-range-target option." ) @@ -219,7 +220,7 @@ def run_normalization(self) -> None: for index, media_file in enumerate( tqdm(self.media_files, desc="File", disable=not self.progress, position=0) ): - logger.info( + _logger.info( f"Normalizing file {media_file} ({index + 1} of {self.file_count})" ) @@ -228,7 +229,7 @@ def run_normalization(self) -> None: except Exception as e: if len(self.media_files) > 1: # simply warn and do not die - logger.error( + _logger.error( f"Error processing input file {media_file}, will " f"continue batch-processing. Error was: {e}" ) @@ -236,7 +237,7 @@ def run_normalization(self) -> None: # raise the error so the program will exit raise e - logger.info(f"Normalized file written to {media_file.output_file}") + _logger.info(f"Normalized file written to {media_file.output_file}") if self.print_stats and self.stats: print(json.dumps(self.stats, indent=4)) diff --git a/ffmpeg_normalize/_logger.py b/ffmpeg_normalize/_logger.py index decc04d..57c073e 100644 --- a/ffmpeg_normalize/_logger.py +++ b/ffmpeg_normalize/_logger.py @@ -2,12 +2,12 @@ import logging import sys -from platform import system +import colorlog +import argparse +from ffmpeg_normalize import __module_name__ as LOGGER_NAME from tqdm import tqdm -_global_log: logging.Logger | None = None - # https://stackoverflow.com/questions/38543506/ class TqdmLoggingHandler(logging.StreamHandler): @@ -37,37 +37,35 @@ def set_mp_lock() -> None: pass -def setup_custom_logger() -> logging.Logger: - """ - Grab or create the global logger +def setup_cli_logger(arguments: argparse.Namespace) -> None: + """Configurs the CLI logger. + + Args: + arguments (argparse.Namespace): The CLI arguments. """ - # \033[1;30m - black - # \033[1;31m - red - # \033[1;32m - green - # \033[1;33m - yellow - # \033[1;34m - blue - # \033[1;35m - magenta - # \033[1;36m - cyan - # \033[1;37m - white - - global _global_log - if _global_log is not None: - return _global_log - - if system() not in ("Windows", "cli"): - logging.addLevelName(logging.ERROR, "ERROR") - logging.addLevelName(logging.WARNING, "WARNING") - logging.addLevelName(logging.INFO, "INFO") - logging.addLevelName(logging.DEBUG, "DEBUG") - - logger = logging.Logger("ffmpeg_normalize") - logger.setLevel(logging.WARNING) + + logger = colorlog.getLogger(LOGGER_NAME) + handler = TqdmLoggingHandler() - handler.setFormatter(logging.Formatter(fmt="%(levelname)s: %(message)s")) + handler.setFormatter(colorlog.ColoredFormatter( + "%(log_color)s%(levelname)s: %(message)s", + log_colors={ + 'DEBUG': 'cyan', + 'INFO': 'green', + 'WARNING': 'yellow', + 'ERROR': 'red', + 'CRITICAL': 'red,bg_white', + }) + ) logger.addHandler(handler) - _global_log = logger + logger.setLevel(logging.WARNING) - return logger + if arguments.quiet: + logger.setLevel(logging.ERROR) + elif arguments.debug: + logger.setLevel(logging.DEBUG) + elif arguments.verbose: + logger.setLevel(logging.INFO) diff --git a/ffmpeg_normalize/_media_file.py b/ffmpeg_normalize/_media_file.py index 73c9116..abb2403 100644 --- a/ffmpeg_normalize/_media_file.py +++ b/ffmpeg_normalize/_media_file.py @@ -2,6 +2,7 @@ import os import re +import logging import shlex from shutil import move, rmtree from tempfile import mkdtemp @@ -11,13 +12,12 @@ from ._cmd_utils import DUR_REGEX, NUL, CommandRunner from ._errors import FFmpegNormalizeError -from ._logger import setup_custom_logger from ._streams import AudioStream, SubtitleStream, VideoStream if TYPE_CHECKING: from ffmpeg_normalize import FFmpegNormalize -logger = setup_custom_logger() +_logger = logging.getLogger(__name__) AUDIO_ONLY_FORMATS = {"aac", "ast", "flac", "mp3", "mka", "oga", "ogg", "opus", "wav"} ONE_STREAM = {"aac", "ast", "flac", "mp3", "wav"} @@ -86,7 +86,7 @@ def parse_streams(self) -> None: Raises: FFmpegNormalizeError: If no audio streams are found """ - logger.debug(f"Parsing streams of {self.input_file}") + _logger.debug(f"Parsing streams of {self.input_file}") cmd = [ self.ffmpeg_normalize.ffmpeg_exe, @@ -105,8 +105,8 @@ def parse_streams(self) -> None: output = CommandRunner().run_command(cmd).get_output() - logger.debug("Stream parsing command output:") - logger.debug(output) + _logger.debug("Stream parsing command output:") + _logger.debug(output) output_lines = [line.strip() for line in output.split("\n")] @@ -115,9 +115,9 @@ def parse_streams(self) -> None: if "Duration" in line: if duration_search := DUR_REGEX.search(line): duration = _to_ms(**duration_search.groupdict()) / 1000 - logger.debug(f"Found duration: {duration} s") + _logger.debug(f"Found duration: {duration} s") else: - logger.warning("Could not extract duration from input file!") + _logger.warning("Could not extract duration from input file!") if not line.startswith("Stream"): continue @@ -130,7 +130,7 @@ def parse_streams(self) -> None: continue if "Audio" in line: - logger.debug(f"Found audio stream at index {stream_id}") + _logger.debug(f"Found audio stream at index {stream_id}") sample_rate_match = re.search(r"(\d+) Hz", line) sample_rate = ( int(sample_rate_match.group(1)) if sample_rate_match else None @@ -147,13 +147,13 @@ def parse_streams(self) -> None: ) elif "Video" in line: - logger.debug(f"Found video stream at index {stream_id}") + _logger.debug(f"Found video stream at index {stream_id}") self.streams["video"][stream_id] = VideoStream( self.ffmpeg_normalize, self, stream_id ) elif "Subtitle" in line: - logger.debug(f"Found subtitle stream at index {stream_id}") + _logger.debug(f"Found subtitle stream at index {stream_id}") self.streams["subtitle"][stream_id] = SubtitleStream( self.ffmpeg_normalize, self, stream_id ) @@ -167,7 +167,7 @@ def parse_streams(self) -> None: self.output_ext.lower() in ONE_STREAM and len(self.streams["audio"].values()) > 1 ): - logger.warning( + _logger.warning( "Output file only supports one stream. " "Keeping only first audio stream." ) @@ -180,7 +180,7 @@ def run_normalization(self) -> None: """ Run the normalization process for this file. """ - logger.debug(f"Running normalization for {self.input_file}") + _logger.debug(f"Running normalization for {self.input_file}") # run the first pass to get loudness stats self._first_pass() @@ -210,7 +210,7 @@ def _first_pass(self) -> None: """ Run the first pass of the normalization process. """ - logger.debug(f"Parsing normalization info for {self.input_file}") + _logger.debug(f"Parsing normalization info for {self.input_file}") for index, audio_stream in enumerate(self.streams["audio"].values()): if self.ffmpeg_normalize.normalization_type == "ebu": @@ -279,7 +279,7 @@ def _second_pass(self) -> Iterator[int]: FIXME: make this method simpler """ - logger.info(f"Running second pass for {self.input_file}") + _logger.info(f"Running second pass for {self.input_file}") # get the target output stream types depending on the options output_stream_types: list[Literal["audio", "video", "subtitle"]] = ["audio"] @@ -335,7 +335,7 @@ def _second_pass(self) -> Iterator[int]: cmd.extend(["-c:v", self.ffmpeg_normalize.video_codec]) else: if not self.ffmpeg_normalize.video_disable: - logger.warning( + _logger.warning( f"The chosen output extension {self.output_ext} does not support video/cover art. It will be disabled." ) @@ -393,10 +393,10 @@ def _second_pass(self) -> Iterator[int]: yield from CommandRunner().run_ffmpeg_command(cmd) except Exception as e: cmd_str = " ".join([shlex.quote(c) for c in cmd]) - logger.error(f"Error while running command {cmd_str}! Error: {e}") + _logger.error(f"Error while running command {cmd_str}! Error: {e}") raise e else: - logger.debug( + _logger.debug( f"Moving temporary file from {temp_file} to {self.output_file}" ) move(temp_file, self.output_file) @@ -405,4 +405,4 @@ def _second_pass(self) -> Iterator[int]: rmtree(temp_dir, ignore_errors=True) raise e - logger.debug("Normalization finished") + _logger.debug("Normalization finished") diff --git a/ffmpeg_normalize/_streams.py b/ffmpeg_normalize/_streams.py index b621864..5b2fc76 100644 --- a/ffmpeg_normalize/_streams.py +++ b/ffmpeg_normalize/_streams.py @@ -3,17 +3,17 @@ import json import os import re +import logging from typing import TYPE_CHECKING, Iterator, Literal, TypedDict from ._cmd_utils import NUL, CommandRunner, dict_to_filter_opts from ._errors import FFmpegNormalizeError -from ._logger import setup_custom_logger if TYPE_CHECKING: from ._ffmpeg_normalize import FFmpegNormalize from ._media_file import MediaFile -logger = setup_custom_logger() +_logger = logging.getLogger(__name__) class EbuLoudnessStatistics(TypedDict): input_i: float @@ -114,7 +114,7 @@ def __init__( and self.duration and self.duration <= 3 ): - logger.warning( + _logger.warning( "Audio stream has a duration of less than 3 seconds. " "Normalization may not work. " "See https://github.com/slhck/ffmpeg-normalize/issues/87 for more info." @@ -141,7 +141,7 @@ def _constrain(number: float, min_range: float, max_range: float, name: str | No raise ValueError("min must be smaller than max") result = max(min(number, max_range), min_range) if result != number and name is not None: - logger.warning( + _logger.warning( f"Constraining {name} to range of [{min_range}, {max_range}]: {number} -> {result}" ) return result @@ -177,7 +177,7 @@ def get_pcm_codec(self) -> str: elif self.bit_depth in [16, 24, 32, 64]: return f"pcm_s{self.bit_depth}le" else: - logger.warning( + _logger.warning( f"Unsupported bit depth {self.bit_depth}, falling back to pcm_s16le" ) return "pcm_s16le" @@ -208,7 +208,7 @@ def parse_astats(self) -> Iterator[int]: Yields: int: The progress of the command. """ - logger.info(f"Running first pass astats filter for stream {self.stream_id}") + _logger.info(f"Running first pass astats filter for stream {self.stream_id}") filter_str = self._get_filter_str_with_pre_filter( "astats=measure_overall=Peak_level+RMS_level:measure_perchannel=0" @@ -233,7 +233,7 @@ def parse_astats(self) -> Iterator[int]: yield from cmd_runner.run_ffmpeg_command(cmd) output = cmd_runner.get_output() - logger.debug( + _logger.debug( f"astats command output: {CommandRunner.prune_ffmpeg_progress_from_output(output)}" ) @@ -266,7 +266,7 @@ def parse_loudnorm_stats(self) -> Iterator[int]: Yields: int: The progress of the command. """ - logger.info(f"Running first pass loudnorm filter for stream {self.stream_id}") + _logger.info(f"Running first pass loudnorm filter for stream {self.stream_id}") opts = { "i": self.media_file.ffmpeg_normalize.target_level, @@ -302,7 +302,7 @@ def parse_loudnorm_stats(self) -> Iterator[int]: yield from cmd_runner.run_ffmpeg_command(cmd) output = cmd_runner.get_output() - logger.debug( + _logger.debug( f"Loudnorm first pass command output: {CommandRunner.prune_ffmpeg_progress_from_output(output)}" ) @@ -346,7 +346,7 @@ def _parse_loudnorm_output(output_lines: list[str]) -> EbuLoudnessStatistics: "\n".join(output_lines[loudnorm_start:loudnorm_end]) ) - logger.debug(f"Loudnorm stats parsed: {json.dumps(loudnorm_stats)}") + _logger.debug(f"Loudnorm stats parsed: {json.dumps(loudnorm_stats)}") for key in [ "input_i", @@ -385,7 +385,7 @@ def get_second_pass_opts_ebu(self) -> str: ) if float(self.loudness_statistics["ebu"]["input_i"]) > 0: - logger.warning( + _logger.warning( "Input file had measured input loudness greater than zero " f"({self.loudness_statistics['ebu']['input_i']}), capping at 0" ) @@ -394,7 +394,7 @@ def get_second_pass_opts_ebu(self) -> str: will_use_dynamic_mode = self.media_file.ffmpeg_normalize.dynamic if self.media_file.ffmpeg_normalize.keep_loudness_range_target: - logger.debug("Keeping target loudness range in second pass loudnorm filter") + _logger.debug("Keeping target loudness range in second pass loudnorm filter") self.media_file.ffmpeg_normalize.loudness_range_target = ( self.loudness_statistics["ebu"]["input_lra"] ) @@ -404,7 +404,7 @@ def get_second_pass_opts_ebu(self) -> str: < self.loudness_statistics["ebu"]["input_lra"] and not will_use_dynamic_mode ): - logger.warning( + _logger.warning( f"Input file had loudness range of {self.loudness_statistics['ebu']['input_lra']}. " f"This is larger than the loudness range target ({self.media_file.ffmpeg_normalize.loudness_range_target}). " "Normalization will revert to dynamic mode. Choose a higher target loudness range if you want linear normalization. " @@ -413,7 +413,7 @@ def get_second_pass_opts_ebu(self) -> str: will_use_dynamic_mode = True if will_use_dynamic_mode and not self.ffmpeg_normalize.sample_rate: - logger.warning( + _logger.warning( "In dynamic mode, the sample rate will automatically be set to 192 kHz by the loudnorm filter. " "Specify -ar/--sample-rate to override it." ) @@ -463,12 +463,12 @@ def get_second_pass_opts_peakrms(self) -> str: "Can only set adjustment for peak and RMS normalization" ) - logger.info( + _logger.info( f"Adjusting stream {self.stream_id} by {adjustment} dB to reach {target_level}" ) clip_amount = self.loudness_statistics["max"] + adjustment if clip_amount > 0: - logger.warning(f"Adjusting will lead to clipping of {clip_amount} dB") + _logger.warning(f"Adjusting will lead to clipping of {clip_amount} dB") return f"volume={adjustment}dB" diff --git a/requirements.txt b/requirements.txt index 4cce13f..0067887 100644 --- a/requirements.txt +++ b/requirements.txt @@ -1,3 +1,4 @@ tqdm>=4.64.1 colorama>=0.4.6 ffmpeg-progress-yield>=0.5.0 +colorlog==6.7.0