Provide sockname when logging a protocol error (#935)

bdraco · web-flow · commit 319992bb093d · 2021-08-05T16:17:56.000-05:00
diff --git 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
@@ -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
@@ -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)
