Add verbose log level (music-assistant#1109)

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,

music_assistant/server/models/core_controller.py

@@ -60,18 +60,19 @@ 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}")
         if log_level is 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)

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

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),

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."""

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)

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