From 73ed6e039ae77c6d7e0b19d1750fae2efedc8314 Mon Sep 17 00:00:00 2001 From: PeteRager <76050312+PeteRager@users.noreply.github.com> Date: Thu, 23 Mar 2023 11:15:55 -0400 Subject: [PATCH] Improve logging for unavailable sonos hosts (#90172) * Repeated warning messages on unavailable manually specified hosts Sonos logs warning messages every 1 minute 12 seconds for hosts that are not on-line. This fixes the issue and the warning will be logged the first time, and subsequent logs messages will be at DEBUG level * Update homeassistant/components/sonos/__init__.py Co-authored-by: epenet <6771947+epenet@users.noreply.github.com> * Log info message when reconnect succeeds * Use pop to simplify code * Add additional test, fix key error with pop * Use pop with default return value * Update tests/components/sonos/test_init.py Co-authored-by: epenet <6771947+epenet@users.noreply.github.com> * Update tests/components/sonos/test_init.py Co-authored-by: epenet <6771947+epenet@users.noreply.github.com> * Update tests/components/sonos/test_init.py Co-authored-by: epenet <6771947+epenet@users.noreply.github.com> * Update tests/components/sonos/test_init.py Co-authored-by: epenet <6771947+epenet@users.noreply.github.com> * Update tests/components/sonos/test_init.py Co-authored-by: epenet <6771947+epenet@users.noreply.github.com> * Update comment, remove unneeded line of code --------- Co-authored-by: epenet <6771947+epenet@users.noreply.github.com> --- homeassistant/components/sonos/__init__.py | 16 ++++- tests/components/sonos/test_init.py | 71 +++++++++++++++++++++- 2 files changed, 83 insertions(+), 4 deletions(-) diff --git a/homeassistant/components/sonos/__init__.py b/homeassistant/components/sonos/__init__.py index e181e995c74..4b68030f843 100644 --- a/homeassistant/components/sonos/__init__.py +++ b/homeassistant/components/sonos/__init__.py @@ -177,6 +177,7 @@ class SonosDiscoveryManager: self.entry = entry self.data = data self.hosts = set(hosts) + self.hosts_in_error: dict[str, bool] = {} self.discovery_lock = asyncio.Lock() self.creation_lock = asyncio.Lock() self._known_invisible: set[SoCo] = set() @@ -353,10 +354,19 @@ class SonosDiscoveryManager: soco, ) except (OSError, SoCoException, Timeout) as ex: - _LOGGER.warning( - "Could not get visible Sonos devices from %s: %s", ip_addr, ex - ) + if not self.hosts_in_error.get(ip_addr): + _LOGGER.warning( + "Could not get visible Sonos devices from %s: %s", ip_addr, ex + ) + self.hosts_in_error[ip_addr] = True + else: + _LOGGER.debug( + "Could not get visible Sonos devices from %s: %s", ip_addr, ex + ) + else: + if self.hosts_in_error.pop(ip_addr, None): + _LOGGER.info("Connection restablished to Sonos device %s", ip_addr) if new_hosts := { x.ip_address for x in visible_zones diff --git a/tests/components/sonos/test_init.py b/tests/components/sonos/test_init.py index fc063991e61..6cc79e1b2f0 100644 --- a/tests/components/sonos/test_init.py +++ b/tests/components/sonos/test_init.py @@ -1,8 +1,13 @@ """Tests for the Sonos config flow.""" -from unittest.mock import patch +import logging +from unittest.mock import AsyncMock, patch + +import pytest from homeassistant import config_entries, data_entry_flow from homeassistant.components import sonos, zeroconf +from homeassistant.components.sonos import SonosDiscoveryManager +from homeassistant.components.sonos.const import DATA_SONOS_DISCOVERY_MANAGER from homeassistant.core import HomeAssistant from homeassistant.setup import async_setup_component @@ -63,3 +68,67 @@ async def test_not_configuring_sonos_not_creates_entry(hass: HomeAssistant) -> N await hass.async_block_till_done() assert len(mock_setup.mock_calls) == 0 + + +async def test_async_poll_manual_hosts_warnings( + hass: HomeAssistant, caplog: pytest.LogCaptureFixture +) -> None: + """Test that host warnings are not logged repeatedly.""" + await async_setup_component( + hass, + sonos.DOMAIN, + {"sonos": {"media_player": {"interface_addr": "127.0.0.1"}}}, + ) + await hass.async_block_till_done() + manager: SonosDiscoveryManager = hass.data[DATA_SONOS_DISCOVERY_MANAGER] + manager.hosts.add("10.10.10.10") + with caplog.at_level(logging.DEBUG), patch.object( + manager, "_async_handle_discovery_message" + ), patch("homeassistant.components.sonos.async_call_later"), patch( + "homeassistant.components.sonos.async_dispatcher_send" + ), patch.object( + hass, "async_add_executor_job", new=AsyncMock() + ) as mock_async_add_executor_job: + mock_async_add_executor_job.side_effect = [ + OSError(), + OSError(), + [], + [], + OSError(), + ] + # First call fails, it should be logged as a WARNING message + caplog.clear() + await manager.async_poll_manual_hosts() + assert len(caplog.messages) == 1 + record = caplog.records[0] + assert record.levelname == "WARNING" + assert "Could not get visible Sonos devices from" in record.message + + # Second call fails again, it should be logged as a DEBUG message + caplog.clear() + await manager.async_poll_manual_hosts() + assert len(caplog.messages) == 1 + record = caplog.records[0] + assert record.levelname == "DEBUG" + assert "Could not get visible Sonos devices from" in record.message + + # Third call succeeds, it should log an info message + caplog.clear() + await manager.async_poll_manual_hosts() + assert len(caplog.messages) == 1 + record = caplog.records[0] + assert record.levelname == "INFO" + assert "Connection restablished to Sonos device" in record.message + + # Fourth call succeeds again, no need to log + caplog.clear() + await manager.async_poll_manual_hosts() + assert len(caplog.messages) == 0 + + # Fifth call fail again again, should be logged as a WARNING message + caplog.clear() + await manager.async_poll_manual_hosts() + assert len(caplog.messages) == 1 + record = caplog.records[0] + assert record.levelname == "WARNING" + assert "Could not get visible Sonos devices from" in record.message