diff --git a/README.md b/README.md index c51e22f3d..8a95f9ae8 100644 --- a/README.md +++ b/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. diff --git a/musicbot/config.py b/musicbot/config.py index 5eaaec5b7..80a2644d2 100644 --- a/musicbot/config.py +++ b/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, diff --git a/musicbot/constants.py b/musicbot/constants.py index 447e66178..1a1f2d52d 100644 --- a/musicbot/constants.py +++ b/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} diff --git a/musicbot/utils.py b/musicbot/utils.py index 787feefbc..614273f9a 100644 --- a/musicbot/utils.py +++ b/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(): diff --git a/run.py b/run.py index 835291608..0b0fbefca 100644 --- a/run.py +++ b/run.py @@ -1,5 +1,6 @@ #!/usr/bin/env python3 +import argparse import asyncio import importlib.util import logging @@ -9,27 +10,35 @@ import ssl import subprocess import sys +import textwrap import time import traceback from base64 import b64decode from typing import Any, Union +from musicbot.constants import ( + DEFAULT_LOGS_KEPT, + DEFAULT_LOGS_ROTATE_FORMAT, + MAXIMUM_LOGS_LIMIT, +) from musicbot.constants import VERSION as BOTVERSION from musicbot.exceptions import HelpfulError, RestartSignal, TerminateSignal -from musicbot.utils import rotate_log_files, setup_loggers, shutdown_loggers - -# take care of loggers right away -log = logging.getLogger("musicbot.launcher") -setup_loggers() -log.info("Loading MusicBot version: %s", BOTVERSION) -log.info("Log opened: %s", time.ctime()) - +from musicbot.utils import ( + rotate_log_files, + set_logging_level, + set_logging_max_kept_logs, + set_logging_rotate_date_format, + setup_loggers, + shutdown_loggers, +) try: import aiohttp except ImportError: pass +log = logging.getLogger("musicbot.launcher") + class GIT: @classmethod @@ -173,6 +182,8 @@ def sanity_checks(optional: bool = True) -> None: """ Run a collection of pre-startup checks to either automatically correct issues or inform the user of how to correct them. + + :param: optional: Toggle optional start up checks. """ log.info("Starting sanity checks") """Required Checks""" @@ -302,7 +313,7 @@ def req_ensure_env() -> None: bugger_off() try: - # TODO: change these perhaps. + # TODO: change these perhaps. Assert is removed in bytecode. assert os.path.isdir("config"), 'folder "config" not found' assert os.path.isdir("musicbot"), 'folder "musicbot" not found' assert os.path.isfile( @@ -346,7 +357,124 @@ def opt_check_disk_space(warnlimit_mb: int = 200) -> None: ) -################################################# +def parse_cli_args() -> argparse.Namespace: + """ + Parse command line arguments and do reasonable checks and assignments. + + :returns: Command line arguments parsed via argparse. + """ + + # define a few custom arg validators. + def kept_logs_int(value: str) -> int: + """Validator for log rotation limits.""" + try: + val = int(value) + if val > MAXIMUM_LOGS_LIMIT: + raise ValueError("Value is above the maximum limit.") + if val <= -1: + raise ValueError("Value must not be negative.") + return val + except (TypeError, ValueError) as e: + raise argparse.ArgumentTypeError( + f"Value for Max Logs Kept must be a number from 0 to {MAXIMUM_LOGS_LIMIT}", + ) from e + + def log_levels_int(level_name: str) -> int: + """Validator for log level name to existing level int.""" + level_name = level_name.upper() + try: + val = getattr(logging, level_name, None) + if not isinstance(val, int): + raise TypeError(f"Log level '{level_name}' is not available.") + return val + except (TypeError, ValueError) as e: + raise argparse.ArgumentTypeError( + "Log Level must be one of: CRITICAL, ERROR, WARNING, INFO, DEBUG, " + "VOICEDEBUG, FFMPEG, NOISY, or EVERYTHING", + ) from e + + ap = argparse.ArgumentParser( + formatter_class=argparse.RawDescriptionHelpFormatter, + description=textwrap.dedent( + """\ + Launch a music playing discord bot built using discord.py, youtubeDL, and ffmpeg. + Available via Github: + https://github.com/Just-Some-Bots/MusicBot + """ + ), + epilog=textwrap.dedent( + """\ + For more help and support with this bot, join our discord: + https://discord.gg/bots + + This software is provided under the MIT License. + See the `LICENSE` text file for complete details. + """ + ), + ) + + # Show Version and exit option. + ap.add_argument( + "-V", + "--version", + dest="show_version", + action="store_true", + help="Print the MusicBot version information and exit.", + ) + + # No Startup Checks option. + ap.add_argument( + "--no-checks", + dest="do_start_checks", + action="store_false", + help="Skip all startup checks.", + ) + + # Log related options + ap.add_argument( + "--logs-kept", + dest="keep_n_logs", + default=DEFAULT_LOGS_KEPT, + type=kept_logs_int, + help=f"Specify how many log files to keep, between 0 and {MAXIMUM_LOGS_LIMIT} inclusive." + f" (Default: {DEFAULT_LOGS_KEPT})", + ) + ap.add_argument( + "--log-level", + dest="log_level", + default="NOTSET", + type=log_levels_int, + help="Override the log level settings set in config. Must be one of: " + "CRITICAL, ERROR, WARNING, INFO, DEBUG, VOICEDEBUG, FFMPEG, " + "NOISY, or EVERYTHING (Default: NOTSET)", + ) + ap.add_argument( + "--log-rotate-fmt", + dest="old_log_fmt", + default=DEFAULT_LOGS_ROTATE_FORMAT, + type=str, + help="Override the default date format used when rotating log files. " + "This should contain values compatible with strftime(). " + f"(Default: '{DEFAULT_LOGS_ROTATE_FORMAT.replace('%', '%%')}')", + ) + + args = ap.parse_args() + + # Show version and exit. + if args.show_version: + print(f"Just-Some-Bots/MusicBot\nVersion: {BOTVERSION}\n") + sys.exit(0) + + if -1 < args.keep_n_logs <= MAXIMUM_LOGS_LIMIT: + set_logging_max_kept_logs(args.keep_n_logs) + + if args.log_level != logging.NOTSET: + set_logging_level(args.log_level, override=True) + + if args.old_log_fmt != DEFAULT_LOGS_ROTATE_FORMAT: + set_logging_rotate_date_format(args.old_log_fmt) + + return args def respawn_bot_process(pybin: str = "") -> None: @@ -394,12 +522,23 @@ def respawn_bot_process(pybin: str = "") -> None: os.execlp(exec_args[0], *exec_args) -async def main() -> Union[RestartSignal, TerminateSignal, None]: - """All of the MusicBot starts here.""" - # TODO: *actual* CLI arg parsing +async def main( + args: argparse.Namespace, +) -> Union[RestartSignal, TerminateSignal, None]: + """ + All of the MusicBot starts here. + + :param: args: some arguments parsed from the command line. + + :returns: Oddly, returns rather than raises a *Signal or nothing. + """ + # TODO: this function may not need to be async. - if "--no-checks" not in sys.argv: + # Handle startup checks, if they haven't been skipped. + if args.do_start_checks: sanity_checks() + else: + log.info("Skipped startup checks.") exit_signal: Union[RestartSignal, TerminateSignal, None] = None tried_requirementstxt = False @@ -418,7 +557,6 @@ async def main() -> Union[RestartSignal, TerminateSignal, None]: from musicbot import MusicBot # pylint: disable=import-outside-toplevel m = MusicBot(use_certifi=use_certifi) - # await m._doBotInit(use_certifi) await m.run() except ( @@ -467,8 +605,10 @@ async def main() -> Union[RestartSignal, TerminateSignal, None]: err = PIP.run_install("--upgrade -r requirements.txt") if err: # TODO: add the specific error check back. - # The proper thing to do here is tell the user to fix their install, not help make it worse. - # Comprehensive return codes aren't really a feature of pip, we'd need to read the log, and so does the user. + # The proper thing to do here is tell the user to fix + # their install, not help make it worse or insecure. + # Comprehensive return codes aren't really a feature of pip, + # If we need to read the log, then so does the user. print() log.critical( "This is not recommended! You can try to %s to install dependencies anyways.", @@ -527,16 +667,47 @@ async def main() -> Union[RestartSignal, TerminateSignal, None]: if __name__ == "__main__": - # TODO: we should check / force-change working directory. + # take care of loggers right away + setup_loggers() + + # parse arguments before any logs, so --help does not make an empty log. + cli_args = parse_cli_args() + + # Log file creation is defered until this first write. + log.info("Loading MusicBot version: %s", BOTVERSION) + log.info("Log opened: %s", time.ctime()) + + # Check if run.py is in the current working directory. + run_py_dir = os.path.dirname(os.path.realpath(__file__)) + if run_py_dir != os.getcwd(): + # if not, verify musicbot and .git folders exists and change directory. + run_mb_dir = pathlib.Path(run_py_dir).joinpath("musicbot") + run_git_dir = pathlib.Path(run_py_dir).joinpath(".git") + if run_mb_dir.is_dir() and run_git_dir.is_dir(): + log.warning("Changing working directory to: %s", run_py_dir) + os.chdir(run_py_dir) + else: + log.critical( + "Cannot start the bot! You started `run.py` in the wrong directory" + " and we could not locate `musicbot` and `.git` folders to verify" + " a new directory location." + ) + log.error( + "For best results, start `run.py` from the same folder you cloned MusicBot into.\n" + "If you did not use git to clone the repository, you are strongly urged to." + ) + time.sleep(3) # make sure they see the message. + sys.exit(127) + # py3.8 made ProactorEventLoop default on windows. # Now we need to make adjustments for a bug in aiohttp :) loop = asyncio.get_event_loop_policy().get_event_loop() try: - exit_sig = loop.run_until_complete(main()) + exit_sig = loop.run_until_complete(main(cli_args)) except KeyboardInterrupt: # TODO: later this will probably get more cleanup so we can # close other things more proper like too. - log.info("Caught a keyboard interrupt signal.") + log.info("\nCaught a keyboard interrupt signal.") shutdown_loggers() rotate_log_files() raise