From 323d624180820eb4888ead44cfadd3cc7738801d Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Thu, 5 Aug 2021 09:38:28 -0500 Subject: [PATCH 1/6] Provide sockname when logging an error - It was difficult to determine which socket was causing an issue as seen in https://github.com/home-assistant/core/issues/54033 --- tests/test_logger.py | 21 +++++++++++++++++++++ zeroconf/_core.py | 28 +++++++++++++++++++--------- zeroconf/_logger.py | 11 +++++++++++ 3 files changed, 51 insertions(+), 9 deletions(-) diff --git a/tests/test_logger.py b/tests/test_logger.py index cedda7e9..2d8bbb08 100644 --- a/tests/test_logger.py +++ b/tests/test_logger.py @@ -61,3 +61,24 @@ def test_log_exception_warning(): assert not mock_log_warning.mock_calls assert mock_log_debug.mock_calls + + +def test_log_exception_once(): + """Test we only log with warning level once.""" + quiet_logger = QuietLogger() + exc = Exception() + with patch("zeroconf._logger.log.warning") as mock_log_warning, patch( + "zeroconf._logger.log.debug" + ) as mock_log_debug: + quiet_logger.log_exception_once(exc, "the exceptional exception warning") + + assert mock_log_warning.mock_calls + assert not mock_log_debug.mock_calls + + with patch("zeroconf._logger.log.warning") as mock_log_warning, patch( + "zeroconf._logger.log.debug" + ) as mock_log_debug: + quiet_logger.log_exception_once(exc, "the exceptional exception warning") + + assert not mock_log_warning.mock_calls + assert mock_log_debug.mock_calls diff --git a/zeroconf/_core.py b/zeroconf/_core.py index 37b72d59..fd4a99a1 100644 --- a/zeroconf/_core.py +++ b/zeroconf/_core.py @@ -226,10 +226,10 @@ def datagram_received( if self.suppress_duplicate_packet(data, now): # Guard against duplicate packets log.debug( - 'Ignoring duplicate message received from %r:%r (socket %d) (%d bytes) as [%r]', + 'Ignoring duplicate message received from %r:%r [socket %s] (%d bytes) as [%r]', addr, port, - self.transport.get_extra_info('socket').fileno(), + self._socket_description, len(data), data, ) @@ -249,20 +249,20 @@ def datagram_received( msg = DNSIncoming(data, scope, now) if msg.valid: log.debug( - 'Received from %r:%r (socket %d): %r (%d bytes) as [%r]', + 'Received from %r:%r [socket %s]: %r (%d bytes) as [%r]', addr, port, - self.transport.get_extra_info('socket').fileno(), + self._socket_description, msg, len(data), data, ) else: log.debug( - 'Received from %r:%r (socket %d): (%d bytes) [%r]', + 'Received from %r:%r [socket %s]: (%d bytes) [%r]', addr, port, - self.transport.get_extra_info('socket').fileno(), + self._socket_description, len(data), data, ) @@ -316,12 +316,22 @@ def _respond_query( self.zc.handle_assembled_query(packets, addr, port, v6_flow_scope) + @property + def _socket_description(self) -> str: + """A human readable description of the socket.""" + fileno = self.transport.get_extra_info('socket').fileno() + sockname = self.transport.get_extra_info('sockname') + return f"{fileno} ({sockname}" + def error_received(self, exc: Exception) -> None: """Likely socket closed or IPv6.""" assert self.transport is not None - self.log_warning_once( - 'Error with socket %d: %s', self.transport.get_extra_info('socket').fileno(), exc - ) + # We preformat the message string with the socket as we want + # log_exception_once to log a warrning message once PER EACH + # different socket in case there are problems with multiple + # sockets + msg_str = f"Error with socket {self._socket_description}): %s" + self.log_exception_once(exc, msg_str, exc) def connection_made(self, transport: asyncio.BaseTransport) -> None: self.transport = cast(asyncio.DatagramTransport, transport) diff --git a/zeroconf/_logger.py b/zeroconf/_logger.py index e779a765..75af46a1 100644 --- a/zeroconf/_logger.py +++ b/zeroconf/_logger.py @@ -61,3 +61,14 @@ def log_warning_once(cls, *args: Any) -> None: logger = log.debug cls._seen_logs[msg_str] = cast(int, cls._seen_logs[msg_str]) + 1 logger(*args) + + @classmethod + def log_exception_once(cls, exc_info, *args: Any) -> None: + msg_str = args[0] + if msg_str not in cls._seen_logs: + cls._seen_logs[msg_str] = 0 + logger = log.warning + else: + logger = log.debug + cls._seen_logs[msg_str] = cast(int, cls._seen_logs[msg_str]) + 1 + logger(*args, exc_info=exc_info) From 12f5cfdc607c73c23d185e94edfdd969b02f5e75 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Thu, 5 Aug 2021 09:39:04 -0500 Subject: [PATCH 2/6] Update zeroconf/_core.py --- zeroconf/_core.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/zeroconf/_core.py b/zeroconf/_core.py index fd4a99a1..871d2c0f 100644 --- a/zeroconf/_core.py +++ b/zeroconf/_core.py @@ -321,7 +321,7 @@ def _socket_description(self) -> str: """A human readable description of the socket.""" fileno = self.transport.get_extra_info('socket').fileno() sockname = self.transport.get_extra_info('sockname') - return f"{fileno} ({sockname}" + return f"{fileno} ({sockname})" def error_received(self, exc: Exception) -> None: """Likely socket closed or IPv6.""" From 4db915bb9ba22d07e6073188b6f5ea4b1b451ea0 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Thu, 5 Aug 2021 09:48:28 -0500 Subject: [PATCH 3/6] mypy --- zeroconf/_core.py | 2 +- zeroconf/_logger.py | 3 ++- 2 files changed, 3 insertions(+), 2 deletions(-) diff --git a/zeroconf/_core.py b/zeroconf/_core.py index 871d2c0f..b2320601 100644 --- a/zeroconf/_core.py +++ b/zeroconf/_core.py @@ -319,13 +319,13 @@ def _respond_query( @property def _socket_description(self) -> str: """A human readable description of the socket.""" + assert self.transport is not None fileno = self.transport.get_extra_info('socket').fileno() sockname = self.transport.get_extra_info('sockname') return f"{fileno} ({sockname})" def error_received(self, exc: Exception) -> None: """Likely socket closed or IPv6.""" - assert self.transport is not None # We preformat the message string with the socket as we want # log_exception_once to log a warrning message once PER EACH # different socket in case there are problems with multiple diff --git a/zeroconf/_logger.py b/zeroconf/_logger.py index 75af46a1..53623284 100644 --- a/zeroconf/_logger.py +++ b/zeroconf/_logger.py @@ -23,6 +23,7 @@ import logging import sys from typing import Any, Dict, Union, cast +from types import TracebackType log = logging.getLogger(__name__.split('.', maxsplit=1)[0]) log.addHandler(logging.NullHandler()) @@ -63,7 +64,7 @@ def log_warning_once(cls, *args: Any) -> None: logger(*args) @classmethod - def log_exception_once(cls, exc_info, *args: Any) -> None: + def log_exception_once(cls, exc_info: TracebackType, *args: Any) -> None: msg_str = args[0] if msg_str not in cls._seen_logs: cls._seen_logs[msg_str] = 0 From dd38f680e87395e4f2e77ccbbaa0093c8182a198 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Thu, 5 Aug 2021 09:54:13 -0500 Subject: [PATCH 4/6] tweak --- zeroconf/_logger.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/zeroconf/_logger.py b/zeroconf/_logger.py index 53623284..72c463ea 100644 --- a/zeroconf/_logger.py +++ b/zeroconf/_logger.py @@ -22,8 +22,8 @@ import logging import sys -from typing import Any, Dict, Union, cast from types import TracebackType +from typing import Any, Dict, Union, cast log = logging.getLogger(__name__.split('.', maxsplit=1)[0]) log.addHandler(logging.NullHandler()) From 691e13bbd61ff15eb8eec4ced7d50abc3844c5a5 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Thu, 5 Aug 2021 09:57:50 -0500 Subject: [PATCH 5/6] tweak --- zeroconf/_logger.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/zeroconf/_logger.py b/zeroconf/_logger.py index 72c463ea..9777361a 100644 --- a/zeroconf/_logger.py +++ b/zeroconf/_logger.py @@ -64,7 +64,7 @@ def log_warning_once(cls, *args: Any) -> None: logger(*args) @classmethod - def log_exception_once(cls, exc_info: TracebackType, *args: Any) -> None: + def log_exception_once(cls, exc: Exception, *args: Any) -> None: msg_str = args[0] if msg_str not in cls._seen_logs: cls._seen_logs[msg_str] = 0 @@ -72,4 +72,4 @@ def log_exception_once(cls, exc_info: TracebackType, *args: Any) -> None: else: logger = log.debug cls._seen_logs[msg_str] = cast(int, cls._seen_logs[msg_str]) + 1 - logger(*args, exc_info=exc_info) + logger(*args, exc_info=exc) From a403f5074e6240823ee25eef2136fa91a561dc67 Mon Sep 17 00:00:00 2001 From: "J. Nick Koston" Date: Thu, 5 Aug 2021 10:00:11 -0500 Subject: [PATCH 6/6] tweak --- zeroconf/_logger.py | 1 - 1 file changed, 1 deletion(-) diff --git a/zeroconf/_logger.py b/zeroconf/_logger.py index 9777361a..932d1a2f 100644 --- a/zeroconf/_logger.py +++ b/zeroconf/_logger.py @@ -22,7 +22,6 @@ import logging import sys -from types import TracebackType from typing import Any, Dict, Union, cast log = logging.getLogger(__name__.split('.', maxsplit=1)[0])