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..b2320601 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.""" + 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 - 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..932d1a2f 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: Exception, *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)