Avoid checking if debug logging is enabled on every WebSocket message (#142258)

Co-authored-by: epenet <6771947+epenet@users.noreply.github.com>

homeassistant/components/websocket_api/http.py

@@ -14,7 +14,7 @@ from aiohttp import WSMsgType, web
 from aiohttp.http_websocket import WebSocketWriter
 
 from homeassistant.components.http import KEY_HASS, HomeAssistantView
-from homeassistant.const import EVENT_HOMEASSISTANT_STOP
+from homeassistant.const import EVENT_HOMEASSISTANT_STOP, EVENT_LOGGING_CHANGED
 from homeassistant.core import Event, HomeAssistant, callback
 from homeassistant.helpers.dispatcher import async_dispatcher_send
 from homeassistant.helpers.event import async_call_later
@@ -73,6 +73,7 @@ class WebSocketHandler:
         "_authenticated",
         "_closing",
         "_connection",
+        "_debug",
         "_handle_task",
         "_hass",
         "_logger",
@@ -107,6 +108,12 @@ class WebSocketHandler:
         self._message_queue: deque[bytes] = deque()
         self._ready_future: asyncio.Future[int] | None = None
         self._release_ready_queue_size: int = 0
+        self._async_logging_changed()
+
+    @callback
+    def _async_logging_changed(self, event: Event | None = None) -> None:
+        """Handle logging change."""
+        self._debug = self._logger.isEnabledFor(logging.DEBUG)
 
     def __repr__(self) -> str:
         """Return the representation."""
@@ -137,7 +144,6 @@ class WebSocketHandler:
         logger = self._logger
         wsock = self._wsock
         loop = self._loop
-        is_debug_log_enabled = partial(logger.isEnabledFor, logging.DEBUG)
         debug = logger.debug
         can_coalesce = connection.can_coalesce
         ready_message_count = len(message_queue)
@@ -157,14 +163,14 @@ class WebSocketHandler:
 
                 if not can_coalesce or ready_message_count == 1:
                     message = message_queue.popleft()
-                    if is_debug_log_enabled():
+                    if self._debug:
                         debug("%s: Sending %s", self.description, message)
                     await send_bytes_text(message)
                     continue
 
                 coalesced_messages = b"".join((b"[", b",".join(message_queue), b"]"))
                 message_queue.clear()
-                if is_debug_log_enabled():
+                if self._debug:
                     debug("%s: Sending %s", self.description, coalesced_messages)
                 await send_bytes_text(coalesced_messages)
         except asyncio.CancelledError:
@@ -325,6 +331,9 @@ class WebSocketHandler:
         unsub_stop = hass.bus.async_listen(
             EVENT_HOMEASSISTANT_STOP, self._async_handle_hass_stop
         )
+        cancel_logging_listener = hass.bus.async_listen(
+            EVENT_LOGGING_CHANGED, self._async_logging_changed
+        )
 
         writer = wsock._writer  # noqa: SLF001
         if TYPE_CHECKING:
@@ -354,6 +363,7 @@ class WebSocketHandler:
                 "%s: Unexpected error inside websocket API", self.description
             )
         finally:
+            cancel_logging_listener()
             unsub_stop()
 
             self._cancel_peak_checker()
@@ -401,7 +411,7 @@ class WebSocketHandler:
         except ValueError as err:
             raise Disconnect("Received invalid JSON during auth phase") from err
 
-        if self._logger.isEnabledFor(logging.DEBUG):
+        if self._debug:
             self._logger.debug("%s: Received %s", self.description, auth_msg_data)
         connection = await auth.async_handle(auth_msg_data)
         # As the webserver is now started before the start
@@ -463,7 +473,6 @@ class WebSocketHandler:
         wsock = self._wsock
         async_handle_str = connection.async_handle
         async_handle_binary = connection.async_handle_binary
-        _debug_enabled = partial(self._logger.isEnabledFor, logging.DEBUG)
 
         # Command phase
         while not wsock.closed:
@@ -496,7 +505,7 @@ class WebSocketHandler:
             except ValueError as ex:
                 raise Disconnect("Received invalid JSON.") from ex
 
-            if _debug_enabled():
+            if self._debug:
                 self._logger.debug(
                     "%s: Received %s", self.description, command_msg_data
                 )

tests/components/websocket_api/test_http.py

@@ -16,6 +16,7 @@ from homeassistant.components.websocket_api import (
 )
 from homeassistant.components.websocket_api.connection import ActiveConnection
 from homeassistant.core import HomeAssistant, callback
+from homeassistant.setup import async_setup_component
 from homeassistant.util.dt import utcnow
 
 from tests.common import async_fire_time_changed
@@ -523,3 +524,36 @@ async def test_binary_message(
     assert "Received binary message for non-existing handler 0" in caplog.text
     assert "Received binary message for non-existing handler 3" in caplog.text
     assert "Received binary message for non-existing handler 10" in caplog.text
+
+
+async def test_enable_disable_debug_logging(
+    hass: HomeAssistant,
+    websocket_client: MockHAClientWebSocket,
+    caplog: pytest.LogCaptureFixture,
+) -> None:
+    """Test enabling and disabling debug logging."""
+    assert await async_setup_component(hass, "logger", {"logger": {}})
+    await hass.services.async_call(
+        "logger",
+        "set_level",
+        {"homeassistant.components.websocket_api": "DEBUG"},
+        blocking=True,
+    )
+    await hass.async_block_till_done()
+    await websocket_client.send_json({"id": 1, "type": "ping"})
+    msg = await websocket_client.receive_json()
+    assert msg["id"] == 1
+    assert msg["type"] == "pong"
+    assert 'Sending b\'{"id":1,"type":"pong"}\'' in caplog.text
+    await hass.services.async_call(
+        "logger",
+        "set_level",
+        {"homeassistant.components.websocket_api": "WARNING"},
+        blocking=True,
+    )
+    await hass.async_block_till_done()
+    await websocket_client.send_json({"id": 2, "type": "ping"})
+    msg = await websocket_client.receive_json()
+    assert msg["id"] == 2
+    assert msg["type"] == "pong"
+    assert 'Sending b\'{"id":2,"type":"pong"}\'' not in caplog.text