diff --git a/denonavr/api.py b/denonavr/api.py index ecad4dc..8c24958 100644 --- a/denonavr/api.py +++ b/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, ) diff --git a/denonavr/audyssey.py b/denonavr/audyssey.py index 37b28e0..7e36eb7 100644 --- a/denonavr/audyssey.py +++ b/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.""" diff --git a/denonavr/decorators.py b/denonavr/decorators.py index 602ca1a..06f9ce3 100644 --- a/denonavr/decorators.py +++ b/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 diff --git a/denonavr/foundation.py b/denonavr/foundation.py index 8573205..b7cf13f 100644 --- a/denonavr/foundation.py +++ b/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 diff --git a/denonavr/input.py b/denonavr/input.py index fd1ab1b..13d709b 100644 --- a/denonavr/input.py +++ b/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 diff --git a/denonavr/tonecontrol.py b/denonavr/tonecontrol.py index c2e4568..3700634 100644 --- a/denonavr/tonecontrol.py +++ b/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