From 83bc63bf5face1506480652cee75e6f3405b66ef Mon Sep 17 00:00:00 2001 From: Marcel van der Veldt Date: Sun, 25 Feb 2024 23:17:26 +0100 Subject: [PATCH] Add verbose log level (#1109) --- .../common/models/config_entries.py | 1 + .../server/models/core_controller.py | 5 ++-- music_assistant/server/models/provider.py | 12 ++-------- .../server/providers/airplay/__init__.py | 23 +++++++++++-------- .../server/providers/chromecast/__init__.py | 7 ++++-- .../server/providers/dlna/__init__.py | 16 ++++++++----- .../server/providers/sonos/__init__.py | 10 +++++--- 7 files changed, 41 insertions(+), 33 deletions(-) diff --git a/music_assistant/common/models/config_entries.py b/music_assistant/common/models/config_entries.py index abed3c394..52f888883 100644 --- a/music_assistant/common/models/config_entries.py +++ b/music_assistant/common/models/config_entries.py @@ -288,6 +288,7 @@ class CoreConfig(Config): ConfigValueOption("warning", "WARNING"), ConfigValueOption("error", "ERROR"), ConfigValueOption("debug", "DEBUG"), + ConfigValueOption("verbose", "VERBOSE"), ), default_value="GLOBAL", advanced=True, diff --git a/music_assistant/server/models/core_controller.py b/music_assistant/server/models/core_controller.py index 3f35884b5..5e1adbaea 100644 --- a/music_assistant/server/models/core_controller.py +++ b/music_assistant/server/models/core_controller.py @@ -60,7 +60,7 @@ async def reload(self, config: CoreConfig | None = None) -> None: self._set_logger(log_level) await self.setup(config) - def _set_logger(self, log_level: int | None = None) -> None: + def _set_logger(self, log_level: str | None = None) -> None: """Set the logger settings.""" mass_logger = logging.getLogger(ROOT_LOGGER_NAME) self.logger = logging.getLogger(f"{ROOT_LOGGER_NAME}.{self.domain}") @@ -68,10 +68,11 @@ def _set_logger(self, log_level: int | None = None) -> None: log_level = self.mass.config.get_raw_core_config_value( self.domain, CONF_LOG_LEVEL, "GLOBAL" ) + self.log_level = log_level if log_level == "GLOBAL": self.logger.setLevel(mass_logger.level) else: - self.logger.setLevel(log_level) + self.logger.setLevel("DEBUG" if log_level == "VERBOSE" else log_level) # if the root logger's level is higher, we need to adjust that too if logging.getLogger().level > self.logger.level: logging.getLogger().setLevel(self.logger.level) diff --git a/music_assistant/server/models/provider.py b/music_assistant/server/models/provider.py index 3ad79e645..f2a3510fc 100644 --- a/music_assistant/server/models/provider.py +++ b/music_assistant/server/models/provider.py @@ -29,22 +29,14 @@ def __init__( self.config = config mass_logger = logging.getLogger(ROOT_LOGGER_NAME) self.logger = mass_logger.getChild(f"providers.{self.domain}") - log_level = config.get_value(CONF_LOG_LEVEL) + self.log_level = log_level = config.get_value(CONF_LOG_LEVEL) if log_level == "GLOBAL": self.logger.setLevel(mass_logger.level) else: - self.logger.setLevel(log_level) + self.logger.setLevel("DEBUG" if log_level == "VERBOSE" else log_level) # if the root logger's level is higher, we need to adjust that too if logging.getLogger().level > self.logger.level: logging.getLogger().setLevel(self.logger.level) - # apply logger settings to modules/packages used by this provider - for pkg_name in manifest.requirements: - dependency = pkg_name.split("=")[0].split("<")[0].split(">")[0] - # unless log level is explicitly set to debug, - # we silence the dependency logger to warning level - conf_log_level = self.config.get_value(CONF_LOG_LEVEL) - level = logging.DEBUG if conf_log_level == logging.DEBUG else logging.WARNING - logging.getLogger(dependency).setLevel(level) self.logger.debug("Log level configured to %s", log_level) self.cache = mass.cache self.available = False diff --git a/music_assistant/server/providers/airplay/__init__.py b/music_assistant/server/providers/airplay/__init__.py index 37ad643ec..af8b7f32b 100644 --- a/music_assistant/server/providers/airplay/__init__.py +++ b/music_assistant/server/providers/airplay/__init__.py @@ -209,8 +209,10 @@ async def init_cliraop(self, start_ntp: int) -> None: # NOTE: This may not work as we might need to do # some fancy hashing with the plain password first?! extra_args += ["-P", device_password] - if self.airplay_player.logger.level == logging.DEBUG: + if self.prov.log_level == "DEBUG": extra_args += ["-d", "5"] + elif self.prov.log_level == "VERBOSE": + extra_args += ["-d", "10"] args = [ self.prov.cliraop_bin, @@ -273,7 +275,8 @@ def send_data(): with open(named_pipe, "w") as f: f.write(command) - self.airplay_player.logger.debug("sending command %s", command) + if self.prov.log_level == "VERBOSE": + self.airplay_player.logger.debug("sending command %s", command) await self.mass.create_task(send_data) async def _log_watcher(self) -> None: @@ -293,23 +296,23 @@ async def _log_watcher(self) -> None: mass_player.elapsed_time_last_updated = time.time() continue if "set pause" in line or "Pause at" in line: - logger.info("raop streaming paused") + logger.debug("raop streaming paused") mass_player.state = PlayerState.PAUSED self.mass.players.update(airplay_player.player_id) continue if "Restarted at" in line or "restarting w/ pause" in line: - logger.info("raop streaming restarted after pause") + logger.debug("raop streaming restarted after pause") mass_player.state = PlayerState.PLAYING self.mass.players.update(airplay_player.player_id) continue if "Stopped at" in line: - logger.info("raop streaming stopped") + logger.debug("raop streaming stopped") mass_player.state = PlayerState.IDLE self.mass.players.update(airplay_player.player_id) continue if "restarting w/o pause" in line: # streaming has started - logger.info("raop streaming started") + logger.debug("raop streaming started") mass_player.state = PlayerState.PLAYING mass_player.elapsed_time = 0 mass_player.elapsed_time_last_updated = time.time() @@ -319,7 +322,8 @@ async def _log_watcher(self) -> None: logger.warning(line) continue # debug log everything else - logger.debug(line) + if self.prov.log_level == "VERBOSE": + logger.debug(line) # if we reach this point, the process exited logger.debug( @@ -428,10 +432,9 @@ async def on_mdns_service_state_change( player_id = f"ap{raw_id.lower()}" # handle removed player if state_change == ServiceStateChange.Removed: - self.logger.debug("Airplay device %s removed", name) if mass_player := self.mass.players.get(player_id): # the player has become unavailable - self.logger.info("Player removed %s", display_name) + self.logger.info("Player offline: %s", display_name) mass_player.available = False self.mass.players.update(player_id) return @@ -608,7 +611,7 @@ async def _stream_audio( # should not happen, but just in case raise RuntimeError("Player is synced") synced_player_ids = [x.player_id for x in self._get_sync_clients(player_id)] - self.logger.info( + self.logger.debug( "Starting RAOP stream for Queue %s to %s", queue.display_name, "/".join(synced_player_ids), diff --git a/music_assistant/server/providers/chromecast/__init__.py b/music_assistant/server/providers/chromecast/__init__.py index 9cfebcd77..6077108a1 100644 --- a/music_assistant/server/providers/chromecast/__init__.py +++ b/music_assistant/server/providers/chromecast/__init__.py @@ -149,8 +149,11 @@ def __init__( ), self.mass.aiozc.zeroconf, ) - # silence pychromecast logging - logging.getLogger("pychromecast").setLevel(self.logger.level + 10) + # set-up pychromecast logging + if self.log_level == "VERBOSE": + logging.getLogger("pychromecast").setLevel(logging.DEBUG) + else: + logging.getLogger("pychromecast").setLevel(self.logger.level + 10) async def loaded_in_mass(self) -> None: """Call after the provider has been loaded.""" diff --git a/music_assistant/server/providers/dlna/__init__.py b/music_assistant/server/providers/dlna/__init__.py index d13ed1810..b5c8b6a7e 100644 --- a/music_assistant/server/providers/dlna/__init__.py +++ b/music_assistant/server/providers/dlna/__init__.py @@ -154,11 +154,12 @@ async def wrapper(self: _DLNAPlayerProviderT, *args: _P.args, **kwargs: _P.kwarg player_id = kwargs["player_id"] if "player_id" in kwargs else args[0] dlna_player = self.dlnaplayers[player_id] dlna_player.last_command = time.time() - self.logger.debug( - "Handling command %s for player %s", - func.__name__, - dlna_player.player.display_name, - ) + if self.log_level == "VERBOSE": + self.logger.debug( + "Handling command %s for player %s", + func.__name__, + dlna_player.player.display_name, + ) if not dlna_player.available: self.logger.warning("Device disappeared when trying to call %s", func.__name__) return None @@ -282,7 +283,10 @@ async def handle_async_init(self) -> None: self.dlnaplayers = {} self.lock = asyncio.Lock() # silence the async_upnp_client logger - logging.getLogger("async_upnp_client").setLevel(self.logger.level + 10) + if self.log_level == "VERBOSE": + logging.getLogger("async_upnp_client").setLevel(logging.DEBUG) + else: + logging.getLogger("async_upnp_client").setLevel(self.logger.level + 10) self.requester = AiohttpSessionRequester(self.mass.http_session, with_sleep=True) self.upnp_factory = UpnpFactory(self.requester, non_strict=True) self.notify_server = DLNANotifyServer(self.requester, self.mass) diff --git a/music_assistant/server/providers/sonos/__init__.py b/music_assistant/server/providers/sonos/__init__.py index 13edb6c68..33f334509 100644 --- a/music_assistant/server/providers/sonos/__init__.py +++ b/music_assistant/server/providers/sonos/__init__.py @@ -90,10 +90,14 @@ async def setup( soco_config.REQUEST_TIMEOUT = 9.5 soco_config.ZGT_EVENT_FALLBACK = False zonegroupstate.EVENT_CACHE_TIMEOUT = SUBSCRIPTION_TIMEOUT - # silence the soco logger a bit - logging.getLogger("soco").setLevel(logging.INFO) - logging.getLogger("urllib3.connectionpool").setLevel(logging.INFO) prov = SonosPlayerProvider(mass, manifest, config) + # set-up soco logging + if prov.log_level == "VERBOSE": + logging.getLogger("soco").setLevel(logging.DEBUG) + logging.getLogger("urllib3.connectionpool").setLevel(logging.INFO) + else: + logging.getLogger("pychromecast").setLevel(prov.logger.level + 10) + logging.getLogger("urllib3.connectionpool").setLevel(logging.WARNING) await prov.handle_async_init() return prov