Add actual CLI args, and use them to set logging options.

README.md

@@ -29,6 +29,12 @@ This fork contains changes that may or may not be merged into upstream.
 Cherry-picking (or otherwise copying) is welcome should you feel inclined.  
 Here is a list of changes made so far, with most recent first:
 
+- Add actual command-line arguments to control logging, show version, and skip startup checks.
+  - Update logging to defer log file creation until the first log is emitted.
+  - Update log file rotation to use file modification time, not just sort by filename.
+  - Allow CLI log-level to override log level set in config/options.ini.
+- Playing compound links now works better and does not double-queue the carrier video.
+- Majority of function definitions now have some kind of docstring.
 - Enforce code checks using `Pylint` and `isort` to reduce inconsistency and clean up code.
 - Ensure source code complies with mypy checks, and fix various bugs on the way.
   - Updates MusicBot logging to enable time-based log files and safely close the logs in most cases.

musicbot/config.py

@@ -14,6 +14,7 @@
     DEFAULT_BLACKLIST_FILE,
     DEFAULT_FOOTER_TEXT,
     DEFAULT_I18N_FILE,
+    DEFAULT_LOG_LEVEL,
     DEFAULT_OPTIONS_FILE,
     EXAMPLE_OPTIONS_FILE,
 )
@@ -599,8 +600,14 @@ class ConfigDefaults:
     delete_messages: bool = True
     delete_invoking: bool = False
     persistent_queue: bool = True
-    debug_level: int = logging.INFO
-    debug_level_str: str = "INFO"
+
+    debug_level: int = getattr(logging, DEFAULT_LOG_LEVEL, logging.INFO)
+    debug_level_str: str = (
+        DEFAULT_LOG_LEVEL
+        if logging.getLevelName(debug_level) == DEFAULT_LOG_LEVEL
+        else "INFO"
+    )
+
     status_message: str = ""
     write_current_song: bool = False
     allow_author_skip: bool = True
@@ -718,11 +725,14 @@ def getdebuglevel(
             int_level = getattr(logging, val)
             return (str_level, int_level)
 
+        int_level = getattr(logging, DEFAULT_LOG_LEVEL, logging.INFO)
+        str_level = logging.getLevelName(int_level)
         log.warning(
-            'Invalid DebugLevel option "%s" given, falling back to INFO',
+            'Invalid DebugLevel option "%s" given, falling back to level: %s',
             val,
+            str_level,
         )
-        return ("INFO", logging.INFO)
+        return (str_level, int_level)
 
     def getdatasize(
         self,

musicbot/constants.py

@@ -14,9 +14,8 @@
 # constant string exempt from i18n
 DEFAULT_FOOTER_TEXT: str = f"Just-Some-Bots/MusicBot ({VERSION})"
 
-DEFAULT_MUSICBOT_LOG_FILE: str = "logs/musicbot.log"
-DEFAULT_DISCORD_LOG_FILE: str = "logs/discord.log"
 
+# File path constants
 DEFAULT_OPTIONS_FILE: str = "config/options.ini"
 DEFAULT_PERMS_FILE: str = "config/permissions.ini"
 DEFAULT_I18N_FILE: str = "config/i18n/en.json"
@@ -31,8 +30,25 @@
 EXAMPLE_PERMS_FILE: str = "config/example_permissions.ini"
 EXAMPLE_COMMAND_ALIAS_FILE: str = "config/example_aliases.json"
 
+
+# Logging related constants
+DEFAULT_MUSICBOT_LOG_FILE: str = "logs/musicbot.log"
+DEFAULT_DISCORD_LOG_FILE: str = "logs/discord.log"
+# Default is 0, for no rotation at all.
+DEFAULT_LOGS_KEPT: int = 0
+MAXIMUM_LOGS_LIMIT: int = 100
+# This value is run through strftime() and then sandwitched between
+DEFAULT_LOGS_ROTATE_FORMAT: str = ".ended-%Y-%j-%H%m%S"
+# Default log level can be one of:
+# CRITICAL, ERROR, WARNING, INFO, DEBUG,
+# VOICEDEBUG, FFMPEG, NOISY, or EVERYTHING
+DEFAULT_LOG_LEVEL: str = "INFO"
+
+
+# Discord and other API constants
 DISCORD_MSG_CHAR_LIMIT: int = 2000
 
+
 EMOJI_CHECK_MARK_BUTTON: str = "\u2705"
 EMOJI_CROSS_MARK_BUTTON: str = "\u274E"
 EMOJI_IDLE_ICON: str = "\U0001f634"  # same as \N{SLEEPING FACE}

musicbot/utils.py

@@ -2,6 +2,7 @@
 import glob
 import inspect
 import logging
+import os
 import pathlib
 import re
 import sys
@@ -15,6 +16,8 @@
 
 from .constants import (
     DEFAULT_DISCORD_LOG_FILE,
+    DEFAULT_LOGS_KEPT,
+    DEFAULT_LOGS_ROTATE_FORMAT,
     DEFAULT_MUSICBOT_LOG_FILE,
     DISCORD_MSG_CHAR_LIMIT,
 )
@@ -97,7 +100,16 @@ def setup_loggers() -> None:
 
     # Setup logging to file for musicbot.
     try:
-        fhandler = logging.FileHandler(filename=log_file, encoding="utf-8", mode="w")
+        # We could use a RotatingFileHandler or TimedRotatingFileHandler
+        # however, these require more options than we currently consider
+        # such as file size or fixed rotation time.
+        # For now, out local implementation should be fine...
+        fhandler = logging.FileHandler(
+            filename=log_file,
+            encoding="utf-8",
+            mode="w",
+            delay=True,
+        )
     except Exception as e:
         raise RuntimeError(
             f"Could not create or use the log file due to an error:\n{str(e)}"
@@ -147,7 +159,10 @@ def setup_loggers() -> None:
     # Setup logging for discord module.
     dlogger = logging.getLogger("discord")
     dhandler = logging.FileHandler(
-        filename=DEFAULT_DISCORD_LOG_FILE, encoding="utf-8", mode="w"
+        filename=DEFAULT_DISCORD_LOG_FILE,
+        encoding="utf-8",
+        mode="w",
+        delay=True,
     )
     dhandler.setFormatter(
         logging.Formatter("[{asctime}] {levelname} - {name}: {message}", style="{")
@@ -183,8 +198,24 @@ def mute_discord_console_log() -> None:
             print()
 
 
-def set_logging_level(level: int) -> None:
-    """sets the logging level for musicbot and discord.py"""
+def set_logging_level(level: int, override: bool = False) -> None:
+    """
+    Sets the logging level for musicbot and discord.py loggers.
+    If `override` is set True, the log level will be set and future calls
+    to this function must also use `override` to set a new level.
+    This allows log-level to be set by CLI arguments, overriding the
+    setting used in configuration file.
+    """
+    if hasattr(logging, "mb_level_override") and not override:
+        log.debug(
+            "Log level was previously set via override to: %s",
+            getattr(logging, "mb_level_override"),
+        )
+        return
+
+    if override:
+        setattr(logging, "mb_level_override", logging.getLevelName(level))
+
     set_lvl_name = logging.getLevelName(level)
     log.info("Changing log level to:  %s", set_lvl_name)
 
@@ -198,6 +229,18 @@ def set_logging_level(level: int) -> None:
         dlogger.setLevel(level)
 
 
+# TODO: perhaps add config file option for max logs kept.
+def set_logging_max_kept_logs(number: int) -> None:
+    """Inform the logger how many logs it should keep."""
+    setattr(logging, "mb_max_logs_kept", number)
+
+
+# TODO: perhaps add a config file option for date format.
+def set_logging_rotate_date_format(sftime: str) -> None:
+    """Inform the logger how it should format rotated file date strings."""
+    setattr(logging, "mb_rot_date_fmt", sftime)
+
+
 def shutdown_loggers() -> None:
     """Removes all musicbot and discord log handlers"""
     # This is the last log line of the logger session.
@@ -216,27 +259,41 @@ def shutdown_loggers() -> None:
     dlogger.handlers.clear()
 
 
-def rotate_log_files(max_kept: int = 2, date_fmt: str = ".ended-%Y-%j-%H%m%S") -> None:
+def rotate_log_files(max_kept: int = -1, date_fmt: str = "") -> None:
     """
     Handles moving and pruning log files.
-    By default the last-run log file is always kept.
+    By default the primary log file is always kept, and never rotated.
     If `max_kept` is set to 0, no rotation is done.
     If `max_kept` is set 1 or greater, up to this number of logs will be kept.
     This should only be used before setup_loggers() or after shutdown_loggers()
 
+    Note: this implementation uses file glob to select then sort files based
+    on their modification time.
+    The glob uses the following pattern: `{stem}*.{suffix}`
+    Where `stem` and `suffix` are take from the configured log file name.
+
     :param: max_kept:  number of old logs to keep.
     :param: date_fmt:  format compatible with datetime.strftime() for rotated filename.
     """
-    # TODO: this needs to be more reliable. Extra or renamed files in the
-    # log directory might break this implementation.
-    # We should probably use a method to read file times rather than using glob...
+    # Use the input arguments or fall back to settings or defaults.
+    if max_kept <= -1:
+        max_kept = getattr(logging, "mb_max_logs_kept", DEFAULT_LOGS_KEPT)
+        if max_kept <= -1:
+            max_kept = DEFAULT_LOGS_KEPT
+
+    if date_fmt == "":
+        date_fmt = getattr(logging, "mb_rot_date_fmt", DEFAULT_LOGS_ROTATE_FORMAT)
+        if date_fmt == "":
+            date_fmt = DEFAULT_LOGS_ROTATE_FORMAT
+
+    # Rotation can be disabled by setting 0.
     if not max_kept:
         return
 
-    # date that will be used for files rotated now.
+    # Format a date that will be used for files rotated now.
     before = datetime.datetime.now().strftime(date_fmt)
 
-    # rotate musicbot logs
+    # Rotate musicbot logs
     logfile = pathlib.Path(DEFAULT_MUSICBOT_LOG_FILE)
     logpath = logfile.parent
     if logfile.is_file():
@@ -245,24 +302,30 @@ def rotate_log_files(max_kept: int = 2, date_fmt: str = ".ended-%Y-%j-%H%m%S") -
         print(f"Moving the log file from this run to:  {new_name}")
         logfile.rename(new_name)
 
-    # make sure we are in limits
+    # Clean up old, out-of-limits, musicbot log files
     logstem = glob.escape(logfile.stem)
-    logglob = sorted(logpath.glob(f"{logstem}*.log"), reverse=True)
+    logglob = sorted(
+        logpath.glob(f"{logstem}*.log"),
+        key=os.path.getmtime,
+        reverse=True,
+    )
     if len(logglob) > max_kept:
         for path in logglob[max_kept:]:
             if path.is_file():
                 path.unlink()
 
-    # rotate discord.py logs
+    # Rotate discord.py logs
     dlogfile = pathlib.Path(DEFAULT_DISCORD_LOG_FILE)
     dlogpath = dlogfile.parent
     if dlogfile.is_file():
         new_name = dlogfile.parent.joinpath(f"{dlogfile.stem}{before}{dlogfile.suffix}")
         dlogfile.rename(new_name)
 
-    # make sure we are in limits
+    # Clean up old, out-of-limits, discord log files
     logstem = glob.escape(dlogfile.stem)
-    logglob = sorted(dlogpath.glob(f"{logstem}*.log"), reverse=True)
+    logglob = sorted(
+        dlogpath.glob(f"{logstem}*.log"), key=os.path.getmtime, reverse=True
+    )
     if len(logglob) > max_kept:
         for path in logglob[max_kept:]:
             if path.is_file():