From: Marcel van der Veldt Date: Sun, 25 Feb 2024 22:17:26 +0000 (+0100) Subject: Add verbose log level (#1109) X-Git-Url: https://git.kitaultman.com/?a=commitdiff_plain;h=83bc63bf5face1506480652cee75e6f3405b66ef;p=music-assistant-server.git Add verbose log level (#1109) --- diff --git a/music_assistant/common/models/config_entries.py b/music_assistant/common/models/config_entries.py index abed3c39..52f88888 100644 --- a/music_assistant/common/models/config_entries.py +++ b/music_assistant/common/models/config_entries.py @@ -288,6 +288,7 @@ CONF_ENTRY_LOG_LEVEL = ConfigEntry( 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 3f35884b..5e1adbae 100644 --- a/music_assistant/server/models/core_controller.py +++ b/music_assistant/server/models/core_controller.py @@ -60,7 +60,7 @@ class CoreController: 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 @@ class CoreController: 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 3ad79e64..f2a3510f 100644 --- a/music_assistant/server/models/provider.py +++ b/music_assistant/server/models/provider.py @@ -29,22 +29,14 @@ class Provider: 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 37ad643e..af8b7f32 100644 --- a/music_assistant/server/providers/airplay/__init__.py +++ b/music_assistant/server/providers/airplay/__init__.py @@ -209,8 +209,10 @@ class AirplayStreamJob: # 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 @@ class AirplayStreamJob: 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 @@ class AirplayStreamJob: 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 @@ class AirplayStreamJob: 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 @@ class AirplayProvider(PlayerProvider): 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 @@ class AirplayProvider(PlayerProvider): # 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 9cfebcd7..6077108a 100644 --- a/music_assistant/server/providers/chromecast/__init__.py +++ b/music_assistant/server/providers/chromecast/__init__.py @@ -149,8 +149,11 @@ class ChromecastProvider(PlayerProvider): ), 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 d13ed181..b5c8b6a7 100644 --- a/music_assistant/server/providers/dlna/__init__.py +++ b/music_assistant/server/providers/dlna/__init__.py @@ -154,11 +154,12 @@ def catch_request_errors( 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 @@ class DLNAPlayerProvider(PlayerProvider): 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 13edb6c6..33f33450 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