Logging improvements (#301)

denonavr/api.py

@@ -471,14 +471,14 @@ async def _async_establish_connection(self) -> None:
             raise AvrTimoutError(f"TimeoutException: {err}", "telnet connect") from err
         except ConnectionRefusedError as err:
             _LOGGER.debug(
-                "%s: Connection refused on telnet connect", self.host, exc_info=True
+                "%s: Connection refused on telnet connect: %s", self.host, err
             )
             raise AvrNetworkError(
                 f"ConnectionRefusedError: {err}", "telnet connect"
             ) from err
         except (OSError, IOError) as err:
             _LOGGER.debug(
-                "%s: Connection failed on telnet reconnect", self.host, exc_info=True
+                "%s: Connection failed on telnet reconnect: %s", self.host, err
             )
             raise AvrNetworkError(f"OSError: {err}", "telnet connect") from err
         _LOGGER.debug("%s: telnet connection established", self.host)
@@ -578,13 +578,13 @@ async def _async_reconnect(self) -> None:
                     _LOGGER.debug(
                         "%s: Timeout exception on telnet reconnect", self.host
                     )
-                except AvrNetworkError as ex:
-                    _LOGGER.debug("%s: %s", self.host, ex, exc_info=True)
-                except Exception:  # pylint: disable=broad-except
+                except AvrNetworkError as err:
+                    _LOGGER.debug("%s: %s", self.host, err)
+                except Exception as err:  # pylint: disable=broad-except
                     _LOGGER.error(
                         "%s: Unexpected exception on telnet reconnect",
                         self.host,
-                        exc_info=True,
+                        exc_info=err,
                     )
                 else:
                     _LOGGER.info("%s: Telnet reconnected", self.host)
@@ -682,7 +682,7 @@ async def _async_run_callbacks(
                 # We don't want a single bad callback to trip up the
                 # whole system and prevent further execution
                 _LOGGER.error(
-                    "%s: Raw callback caused an unhandled exception %s",
+                    "%s: Raw callback caused an unhandled exception: %s",
                     self.host,
                     err,
                 )
@@ -695,7 +695,7 @@ async def _async_run_callbacks(
                     # We don't want a single bad callback to trip up the
                     # whole system and prevent further execution
                     _LOGGER.error(
-                        "%s: Event callback caused an unhandled exception %s",
+                        "%s: Event callback caused an unhandled exception: %s",
                         self.host,
                         err,
                     )
@@ -708,7 +708,7 @@ async def _async_run_callbacks(
                     # We don't want a single bad callback to trip up the
                     # whole system and prevent further execution
                     _LOGGER.error(
-                        "%s: Event callback caused an unhandled exception %s",
+                        "%s: Event callback caused an unhandled exception: %s",
                         self.host,
                         err,
                     )

denonavr/audyssey.py

@@ -124,9 +124,9 @@ async def async_update_audyssey(
                     global_update=global_update,
                     cache_id=cache_id,
                 )
-            except AvrProcessingError:
+            except AvrProcessingError as err:
                 # Don't raise an error here, because not all devices support it
-                _LOGGER.debug("Updating Audyssey failed", exc_info=True)
+                _LOGGER.debug("Updating Audyssey failed: %s", err)
 
     async def _async_set_audyssey(self, cmd: AppCommandCmd) -> None:
         """Set Audyssey parameter."""

denonavr/decorators.py

@@ -45,26 +45,21 @@ async def wrapper(*args, **kwargs):
         try:
             return await func(*args, **kwargs)
         except httpx.HTTPStatusError as err:
-            _LOGGER.debug("HTTP status error on request %s", err.request, exc_info=True)
+            _LOGGER.debug("HTTP status error on request %s: %s", err.request, err)
             # Separate handling of 403 errors
             if err.response.status_code == 403:
                 raise AvrForbiddenError(f"HTTPStatusError: {err}", err.request) from err
             raise AvrRequestError(f"HTTPStatusError: {err}", err.request) from err
         except httpx.TimeoutException as err:
-            _LOGGER.debug(
-                "HTTP timeout exception on request %s", err.request, exc_info=True
-            )
+            _LOGGER.debug("HTTP timeout exception on request %s: %s", err.request, err)
             raise AvrTimoutError(f"TimeoutException: {err}", err.request) from err
         except httpx.NetworkError as err:
-            _LOGGER.debug(
-                "Network error exception on request %s", err.request, exc_info=True
-            )
+            _LOGGER.debug("Network error exception on request %s: %s", err.request, err)
             raise AvrNetworkError(f"NetworkError: {err}", err.request) from err
         except httpx.RemoteProtocolError as err:
             _LOGGER.debug(
                 "Remote protocol error exception on request %s",
                 err.request,
-                exc_info=True,
             )
             raise AvrInvalidResponseError(
                 f"RemoteProtocolError: {err}", err.request
@@ -76,7 +71,7 @@ async def wrapper(*args, **kwargs):
             UnicodeDecodeError,
         ) as err:
             _LOGGER.debug(
-                "Defusedxml parse error on request %s", (args, kwargs), exc_info=True
+                "Defusedxml parse error on request %s: %s", (args, kwargs), err
             )
             raise AvrInvalidResponseError(
                 f"XMLParseError: {err}", (args, kwargs)
@@ -109,7 +104,7 @@ async def wrapper(*args, **kwargs):
         try:
             return await cached_func(*args, **kwargs)
         except Exception as err:
-            _LOGGER.debug("Exception %s raised, clearing cache", err)
+            _LOGGER.debug("Exception raised, clearing cache: %s", err)
             cached_func.cache_clear()
             raise
 

denonavr/foundation.py

@@ -143,16 +143,19 @@ def get_own_zone(self) -> str:
     async def async_setup(self) -> None:
         """Ensure that configuration is loaded from receiver asynchronously."""
         async with self._setup_lock:
-            # Own setup
+            _LOGGER.debug("Starting device setup")
             # Reduce read timeout during receiver identification
             # deviceinfo endpoint takes very long to return 404
             timeout = self.api.timeout
             self.api.timeout = httpx.Timeout(self.api.timeout.connect)
             try:
+                _LOGGER.debug("Identifying receiver")
                 await self.async_identify_receiver()
+                _LOGGER.debug("Getting device info")
                 await self.async_get_device_info()
             finally:
                 self.api.timeout = timeout
+            _LOGGER.debug("Identifying update method")
             await self.async_identify_update_method()
 
             # Add tags for a potential AppCommand.xml update
@@ -166,6 +169,7 @@ async def async_setup(self) -> None:
             self.telnet_api.register_callback(power_event, self._async_power_callback)
 
             self._is_setup = True
+            _LOGGER.debug("Finished device setup")
 
     async def async_update(
         self, global_update: bool = False, cache_id: Optional[Hashable] = None
@@ -196,9 +200,9 @@ async def async_identify_receiver(self) -> None:
                 )
             except (AvrTimoutError, AvrNetworkError) as err:
                 _LOGGER.debug(
-                    "Connection error on port %s when identifying receiver",
+                    "Connection error on port %s when identifying receiver: %s",
                     r_type.port,
-                    exc_info=err,
+                    err,
                 )
 
                 # Raise error only when occurred at both types
@@ -210,22 +214,32 @@ async def async_identify_receiver(self) -> None:
                 _LOGGER.debug(
                     (
                         "Request error on port %s when identifying receiver, "
-                        "device is not a %s receivers"
+                        "device is not a %s receiver: %s"
                     ),
                     r_type.port,
                     r_type.type,
-                    exc_info=err,
+                    err,
                 )
             else:
                 is_avr_x = self._is_avr_x(xml)
                 if is_avr_x:
                     self.receiver = r_type
+                    _LOGGER.info(
+                        "Identified %s receiver using port %s",
+                        r_type.type,
+                        r_type.port,
+                    )
                     # Receiver identified, return
                     return
 
         # If check of Deviceinfo.xml was not successful, receiver is type AVR
         self.receiver = AVR
         self.api.port = AVR.port
+        _LOGGER.info(
+            "Identified %s receiver using port %s",
+            AVR.type,
+            AVR.port,
+        )
 
     @staticmethod
     def _is_avr_x(deviceinfo: ET.Element) -> bool:
@@ -275,13 +289,11 @@ async def async_identify_update_method(self) -> None:
                 )
             except (AvrTimoutError, AvrNetworkError) as err:
                 _LOGGER.debug(
-                    "Connection error when identifying update method", exc_info=err
+                    "Connection error when identifying update method: %s", err
                 )
                 raise
             except AvrRequestError as err:
-                _LOGGER.debug(
-                    "Request error when identifying update method", exc_info=err
-                )
+                _LOGGER.debug("Request error when identifying update method: %s", err)
                 self.use_avr_2016_update = False
                 _LOGGER.info("AVR-X device, AppCommand.xml interface not supported")
             else:
@@ -294,11 +306,11 @@ async def async_identify_update_method(self) -> None:
                 xml = await self.api.async_get_xml(self.urls.mainzone)
             except (AvrTimoutError, AvrNetworkError) as err:
                 _LOGGER.debug(
-                    "Connection error when identifying update method", exc_info=err
+                    "Connection error when identifying update method: %s", err
                 )
                 raise
             except AvrRequestError as err:
-                _LOGGER.debug("Request error getting friendly name", exc_info=err)
+                _LOGGER.debug("Request error getting friendly name: %s", err)
                 _LOGGER.info(
                     "Receiver name could not be determined. Using standard"
                     " name: Denon AVR"
@@ -320,7 +332,7 @@ async def async_verify_avr_2016_update_method(
             # Result is cached that it can be reused during update
             await self.api.async_get_global_appcommand(cache_id=cache_id)
         except (AvrTimoutError, AvrNetworkError) as err:
-            _LOGGER.debug("Connection error when verifying update method", exc_info=err)
+            _LOGGER.debug("Connection error when verifying update method: %s", err)
             raise
         except AvrForbiddenError:
             # Recovery in case receiver changes port from 80 to 8080 which
@@ -338,7 +350,7 @@ async def async_verify_avr_2016_update_method(
             else:
                 raise
         except AvrIncompleteResponseError as err:
-            _LOGGER.debug("Request error when verifying update method", exc_info=err)
+            _LOGGER.debug("Request error when verifying update method: %s", err)
             # Only AVR_X devices support both interfaces
             if self.receiver == AVR_X:
                 _LOGGER.warning(
@@ -378,10 +390,10 @@ async def async_get_device_info(self) -> None:
         try:
             res = await self.api.async_get(command, port=port)
         except AvrTimoutError as err:
-            _LOGGER.debug("Timeout when getting device info", exc_info=err)
+            _LOGGER.debug("Timeout when getting device info: %s", err)
             raise
         except AvrNetworkError as err:
-            _LOGGER.debug("Network error getting device info", exc_info=err)
+            _LOGGER.debug("Network error getting device info: %s", err)
             raise
         except AvrRequestError as err:
             _LOGGER.error(
@@ -444,7 +456,7 @@ async def async_update_power_appcommand(
                     self.urls.appcommand, tuple(power_appcommand), cache_id=cache_id
                 )
         except AvrRequestError as err:
-            _LOGGER.debug("Error when getting power status", exc_info=err)
+            _LOGGER.debug("Error when getting power status: %s", err)
             raise
 
         # Extract relevant information
@@ -482,7 +494,7 @@ async def async_update_power_status_xml(
                     xml = await self.api.async_get_xml(url, cache_id=cache_id)
                 except AvrRequestError as err:
                     _LOGGER.debug(
-                        "Error when getting power status from url %s", url, exc_info=err
+                        "Error when getting power status from url %s: %s", url, err
                     )
                     continue
 
@@ -661,7 +673,7 @@ async def async_update_attrs_appcommand(
                     url, tags, cache_id=cache_id
                 )
         except AvrRequestError as err:
-            _LOGGER.debug("Error when getting status update", exc_info=err)
+            _LOGGER.debug("Error when getting status update: %s", err)
             raise
 
         # Extract relevant information
@@ -696,10 +708,10 @@ async def async_update_attrs_appcommand(
 
                 except (AttributeError, IndexError) as err:
                     _LOGGER.debug(
-                        "Failed updating attribute %s for zone %s",
+                        "Failed updating attribute %s for zone %s: %s",
                         pattern.update_attribute,
                         self._device.zone,
-                        exc_info=err,
+                        err,
                     )
 
             if start == success:
@@ -737,7 +749,7 @@ async def async_update_attrs_status_xml(
                 xml = await self._device.api.async_get_xml(url, cache_id=cache_id)
             except AvrRequestError as err:
                 _LOGGER.debug(
-                    "Error when getting status update from url %s", url, exc_info=err
+                    "Error when getting status update from url %s: %s", url, err
                 )
                 continue
             attrs = deepcopy(update_attrs)
@@ -756,10 +768,10 @@ async def async_update_attrs_status_xml(
 
                 except (AttributeError, IndexError) as err:
                     _LOGGER.debug(
-                        "Failed updating attribute %s for zone %s",
+                        "Failed updating attribute %s for zone %s: %s",
                         name,
                         self._device.zone,
-                        exc_info=err,
+                        err,
                     )
 
             # All done, no need for continuing

denonavr/input.py

@@ -426,7 +426,7 @@ async def async_get_sources_deviceinfo(self) -> Dict[str, str]:
                 self._device.urls.deviceinfo, cache_id=id(self._device)
             )
         except AvrRequestError as err:
-            _LOGGER.debug("Error when getting sources", exc_info=err)
+            _LOGGER.debug("Error when getting sources: %s", err)
             raise
 
         receiver_sources = {}
@@ -484,7 +484,7 @@ async def async_get_changed_sources_appcommand(
                     self._device.urls.appcommand, tags, cache_id=cache_id
                 )
         except AvrRequestError as err:
-            _LOGGER.debug("Error when getting changed sources", exc_info=err)
+            _LOGGER.debug("Error when getting changed sources: %s", err)
             raise
 
         for child in xml.findall(
@@ -547,7 +547,7 @@ async def async_get_changed_sources_status_xml(
                     f" {self._device.receiver.type}"
                 )
         except AvrRequestError as err:
-            _LOGGER.debug("Error when getting changed sources", exc_info=err)
+            _LOGGER.debug("Error when getting changed sources: %s", err)
             raise
 
         # Get the relevant tags from XML structure

denonavr/tonecontrol.py

@@ -111,9 +111,9 @@ async def async_update_tone_control(
                     global_update=global_update,
                     cache_id=cache_id,
                 )
-            except AvrProcessingError:
+            except AvrProcessingError as err:
                 # Don't raise an error here, because not all devices support it
-                _LOGGER.debug("Updating tone control failed", exc_info=True)
+                _LOGGER.debug("Updating tone control failed: %s", err)
 
     async def async_set_tone_control_command(
         self, parameter_type: str, value: int