Add verbose log level (#1109)
authorMarcel van der Veldt <m.vanderveldt@outlook.com>
Sun, 25 Feb 2024 22:17:26 +0000 (23:17 +0100)
committerGitHub <noreply@github.com>
Sun, 25 Feb 2024 22:17:26 +0000 (23:17 +0100)
music_assistant/common/models/config_entries.py
music_assistant/server/models/core_controller.py
music_assistant/server/models/provider.py
music_assistant/server/providers/airplay/__init__.py
music_assistant/server/providers/chromecast/__init__.py
music_assistant/server/providers/dlna/__init__.py
music_assistant/server/providers/sonos/__init__.py

index abed3c39409a777f004c15c34f50a173bea3b394..52f888883cfc036a9be8582399e31ca3a8238fb1 100644 (file)
@@ -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,
index 3f35884b538abab17921b63636b7a42b5d847575..5e1adbaead037c4a707c4282eeabaeae4ffb629e 100644 (file)
@@ -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)
index 3ad79e645b097a3660eedf4d3455eaadfdb7c64d..f2a3510fc4ae2f9ed31e7b5b6a33c8e648c1d300 100644 (file)
@@ -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
index 37ad643ec3a58320dd003cdae5a82a805da3310e..af8b7f32b2ff6cc59957b7e63b2f13b69d184d07 100644 (file)
@@ -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),
index 9cfebcd77efbe08ce1aea1a03a42125eb8667ee7..6077108a144380f6b069a4ab24db29c48961046d 100644 (file)
@@ -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."""
index d13ed181076f151f60e0d925f2d7e9cdfe35cc9c..b5c8b6a7e7bfc60408a3e12d098466aad399fb6a 100644 (file)
@@ -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)
index 13edb6c68b04e3d458e7764a8dd7ca24859ac672..33f3345099917457757ce1fcafb036fbaf1bbcb3 100644 (file)
@@ -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