Improve logging of google_assistant messages (#110637)

* Improve logging of google_assistant messages

* Add tests

* Add test

homeassistant/components/cloud/client.py

@@ -270,13 +270,23 @@ class CloudClient(Interface):
         """Process cloud google message to client."""
         gconf = await self.get_google_config()
 
+        msgid: Any = "<UNKNOWN>"
+        if isinstance(payload, dict):
+            msgid = payload.get("requestId")
+        _LOGGER.debug("Received cloud message %s", msgid)
+
         if not self._prefs.google_enabled:
             return ga.api_disabled_response(  # type: ignore[no-any-return, no-untyped-call]
                 payload, gconf.agent_user_id
             )
 
         return await ga.async_handle_message(  # type: ignore[no-any-return, no-untyped-call]
-            self._hass, gconf, gconf.cloud_user, payload, google_assistant.SOURCE_CLOUD
+            self._hass,
+            gconf,
+            gconf.agent_user_id,
+            gconf.cloud_user,
+            payload,
+            google_assistant.SOURCE_CLOUD,
         )
 
     async def async_webhook_message(self, payload: dict[Any, Any]) -> dict[Any, Any]:

homeassistant/components/cloud/google_config.py

@@ -330,10 +330,20 @@ class CloudGoogleConfig(AbstractConfig):
         """Return if we have a Agent User Id registered."""
         return len(self.async_get_agent_users()) > 0
 
-    def get_agent_user_id(self, context: Any) -> str:
+    def get_agent_user_id_from_context(self, context: Any) -> str:
         """Get agent user ID making request."""
         return self.agent_user_id
 
+    def get_agent_user_id_from_webhook(self, webhook_id: str) -> str | None:
+        """Map webhook ID to a Google agent user ID.
+
+        Return None if no agent user id is found for the webhook_id.
+        """
+        if webhook_id != self._prefs.google_local_webhook_id:
+            return None
+
+        return self.agent_user_id
+
     def _2fa_disabled_legacy(self, entity_id: str) -> bool | None:
         """If an entity should be checked for 2FA."""
         entity_configs = self._prefs.google_entity_configs

homeassistant/components/google_assistant/button.py

@@ -51,7 +51,9 @@ class SyncButton(ButtonEntity):
     async def async_press(self) -> None:
         """Press the button."""
         assert self._context
-        agent_user_id = self._google_config.get_agent_user_id(self._context)
+        agent_user_id = self._google_config.get_agent_user_id_from_context(
+            self._context
+        )
         result = await self._google_config.async_sync_entities(agent_user_id)
         if result != 200:
             raise HomeAssistantError(

homeassistant/components/google_assistant/data_redaction.py

@@ -2,35 +2,77 @@
 from __future__ import annotations
 
 from collections.abc import Callable
+from functools import partial
 from typing import Any
 
 from homeassistant.core import callback
-from homeassistant.helpers.redact import async_redact_data, partial_redact
+from homeassistant.helpers.redact import REDACTED, async_redact_data, partial_redact
 
-REQUEST_MSG_TO_REDACT: dict[str, Callable[[str], str]] = {
+GOOGLE_MSG_TO_REDACT: dict[str, Callable[[str], str]] = {
     "agentUserId": partial_redact,
     "uuid": partial_redact,
     "webhookId": partial_redact,
 }
 
-RESPONSE_MSG_TO_REDACT = REQUEST_MSG_TO_REDACT | {id: partial_redact}
+MDNS_TXT_TO_REDACT = [
+    "location_name",
+    "uuid",
+    "external_url",
+    "internal_url",
+    "base_url",
+]
 
-SYNC_MSG_TO_REDACT = REQUEST_MSG_TO_REDACT
+
+def partial_redact_list_item(x: list[str], to_redact: list[str]) -> list[str]:
+    """Redact only specified string in a list of strings."""
+    if not isinstance(x, list):
+        return x
+    result = []
+    for itm in x:
+        if not isinstance(itm, str):
+            result.append(itm)
+            continue
+        for pattern in to_redact:
+            if itm.startswith(pattern):
+                result.append(f"{pattern}={REDACTED}")
+                break
+        else:
+            result.append(itm)
+    return result
+
+
+def partial_redact_txt_list(x: list[str]) -> list[str]:
+    """Redact strings from home-assistant mDNS txt records."""
+    return partial_redact_list_item(x, MDNS_TXT_TO_REDACT)
+
+
+def partial_redact_txt_dict(x: dict[str, str]) -> dict[str, str]:
+    """Redact strings from home-assistant mDNS txt records."""
+    if not isinstance(x, dict):
+        return x
+    result = {}
+    for k, v in x.items():
+        result[k] = REDACTED if k in MDNS_TXT_TO_REDACT else v
+    return result
+
+
+def partial_redact_string(x: str, to_redact: str) -> str:
+    """Redact only a specified string."""
+    if x == to_redact:
+        return partial_redact(x)
+    return x
 
 
 @callback
-def async_redact_request_msg(msg: dict[str, Any]) -> dict[str, Any]:
+def async_redact_msg(msg: dict[str, Any], agent_user_id: str) -> dict[str, Any]:
     """Mask sensitive data in message."""
-    return async_redact_data(msg, REQUEST_MSG_TO_REDACT)
+    return async_redact_data(
-
+        msg,
-
+        GOOGLE_MSG_TO_REDACT
-@callback
+        | {
-def async_redact_response_msg(msg: dict[str, Any]) -> dict[str, Any]:
+            "data": partial_redact_txt_list,
-    """Mask sensitive data in message."""
+            "id": partial(partial_redact_string, to_redact=agent_user_id),
-    return async_redact_data(msg, RESPONSE_MSG_TO_REDACT)
+            "texts": partial_redact_txt_list,
-
+            "txt": partial_redact_txt_dict,
-
+        },
-@callback
+    )
-def async_redact_sync_msg(msg: dict[str, Any]) -> dict[str, Any]:
-    """Mask sensitive data in message."""
-    return async_redact_data(msg, SYNC_MSG_TO_REDACT)

homeassistant/components/google_assistant/helpers.py

@@ -46,7 +46,7 @@ from .const import (
     NOT_EXPOSE_LOCAL,
     SOURCE_LOCAL,
 )
-from .data_redaction import async_redact_request_msg, async_redact_response_msg
+from .data_redaction import async_redact_msg
 from .error import SmartHomeError
 
 SYNC_DELAY = 15
@@ -175,9 +175,16 @@ class AbstractConfig(ABC):
         """Return the webhook ID to be used for actions for a given agent user id via the local SDK."""
 
     @abstractmethod
-    def get_agent_user_id(self, context):
+    def get_agent_user_id_from_context(self, context):
         """Get agent user ID from context."""
 
+    @abstractmethod
+    def get_agent_user_id_from_webhook(self, webhook_id):
+        """Map webhook ID to a Google agent user ID.
+
+        Return None if no agent user id is found for the webhook_id.
+        """
+
     @abstractmethod
     def should_expose(self, state) -> bool:
         """Return if entity should be exposed."""
@@ -409,14 +416,17 @@ class AbstractConfig(ABC):
         payload = await request.json()
 
         if _LOGGER.isEnabledFor(logging.DEBUG):
+            msgid = "<UNKNOWN>"
+            if isinstance(payload, dict):
+                msgid = payload.get("requestId")
             _LOGGER.debug(
-                "Received local message from %s (JS %s):\n%s\n",
+                "Received local message %s from %s (JS %s)",
+                msgid,
                 request.remote,
                 request.headers.get("HA-Cloud-Version", "unknown"),
-                pprint.pformat(async_redact_request_msg(payload)),
             )
 
-        if (agent_user_id := self.get_local_user_id(webhook_id)) is None:
+        if (agent_user_id := self.get_agent_user_id_from_webhook(webhook_id)) is None:
             # No agent user linked to this webhook, means that the user has somehow unregistered
             # removing webhook and stopping processing of this request.
             _LOGGER.error(
@@ -425,7 +435,7 @@ class AbstractConfig(ABC):
                     " found:\n%s\n"
                 ),
                 partial_redact(webhook_id),
-                pprint.pformat(async_redact_request_msg(payload)),
+                pprint.pformat(async_redact_msg(payload, agent_user_id)),
             )
             webhook.async_unregister(self.hass, webhook_id)
             return None
@@ -439,15 +449,16 @@ class AbstractConfig(ABC):
             self.hass,
             self,
             agent_user_id,
+            self.get_local_user_id(webhook_id),
             payload,
             SOURCE_LOCAL,
         )
 
         if _LOGGER.isEnabledFor(logging.DEBUG):
-            _LOGGER.debug(
+            if isinstance(payload, dict):
-                "Responding to local message:\n%s\n",
+                _LOGGER.debug("Responding to local message %s", msgid)
-                pprint.pformat(async_redact_response_msg(result)),
+            else:
-            )
+                _LOGGER.debug("Empty response to local message %s", msgid)
 
         return json_response(result)
 

homeassistant/components/google_assistant/http.py

@@ -144,10 +144,21 @@ class GoogleConfig(AbstractConfig):
             return data[STORE_GOOGLE_LOCAL_WEBHOOK_ID]
         return None
 
-    def get_agent_user_id(self, context):
+    def get_agent_user_id_from_context(self, context):
         """Get agent user ID making request."""
         return context.user_id
 
+    def get_agent_user_id_from_webhook(self, webhook_id):
+        """Map webhook ID to a Google agent user ID.
+
+        Return None if no agent user id is found for the webhook_id.
+        """
+        for agent_user_id, agent_user_data in self._store.agent_user_ids.items():
+            if agent_user_data[STORE_GOOGLE_LOCAL_WEBHOOK_ID] == webhook_id:
+                return agent_user_id
+
+        return None
+
     def should_expose(self, state) -> bool:
         """Return if entity should be exposed."""
         expose_by_default = self._config.get(CONF_EXPOSE_BY_DEFAULT)
@@ -372,6 +383,7 @@ class GoogleAssistantView(HomeAssistantView):
             request.app["hass"],
             self.config,
             request["hass_user"].id,
+            request["hass_user"].id,
             message,
             SOURCE_CLOUD,
         )

homeassistant/components/google_assistant/smart_home.py

@@ -3,6 +3,7 @@ import asyncio
 from collections.abc import Callable, Coroutine
 from itertools import product
 import logging
+import pprint
 from typing import Any
 
 from homeassistant.const import ATTR_ENTITY_ID, __version__
@@ -18,11 +19,7 @@ from .const import (
     EVENT_QUERY_RECEIVED,
     EVENT_SYNC_RECEIVED,
 )
-from .data_redaction import (
+from .data_redaction import async_redact_msg
-    async_redact_request_msg,
-    async_redact_response_msg,
-    async_redact_sync_msg,
-)
 from .error import SmartHomeError
 from .helpers import GoogleEntity, RequestData, async_get_entities
 
@@ -38,19 +35,35 @@ HANDLERS: Registry[
 _LOGGER = logging.getLogger(__name__)
 
 
-async def async_handle_message(hass, config, user_id, message, source):
+async def async_handle_message(
+    hass, config, agent_user_id, local_user_id, message, source
+):
     """Handle incoming API messages."""
+    if _LOGGER.isEnabledFor(logging.DEBUG):
+        _LOGGER.debug(
+            "Processing message:\n%s",
+            pprint.pformat(async_redact_msg(message, agent_user_id)),
+        )
+
     data = RequestData(
-        config, user_id, source, message["requestId"], message.get("devices")
+        config, local_user_id, source, message["requestId"], message.get("devices")
     )
 
     response = await _process(hass, data, message)
+    if _LOGGER.isEnabledFor(logging.DEBUG):
+        if response:
+            _LOGGER.debug(
+                "Response:\n%s",
+                pprint.pformat(async_redact_msg(response["payload"], agent_user_id)),
+            )
+        else:
+            _LOGGER.debug("Empty response")
 
     if response and "errorCode" in response["payload"]:
         _LOGGER.error(
-            "Error handling message %s: %s",
+            "Error handling message\n:%s\nResponse:\n%s",
-            async_redact_request_msg(message),
+            pprint.pformat(async_redact_msg(message, agent_user_id)),
-            async_redact_response_msg(response["payload"]),
+            pprint.pformat(async_redact_msg(response["payload"], agent_user_id)),
         )
 
     return response
@@ -121,14 +134,12 @@ async def async_devices_sync(
         context=data.context,
     )
 
-    agent_user_id = data.config.get_agent_user_id(data.context)
+    agent_user_id = data.config.get_agent_user_id_from_context(data.context)
     await data.config.async_connect_agent_user(agent_user_id)
 
     devices = await async_devices_sync_response(hass, data.config, agent_user_id)
     response = create_sync_response(agent_user_id, devices)
 
-    _LOGGER.debug("Syncing entities response: %s", async_redact_sync_msg(response))
-
     return response
 
 
@@ -299,7 +310,7 @@ async def async_devices_identify(
     """
     return {
         "device": {
-            "id": data.config.get_agent_user_id(data.context),
+            "id": data.config.get_agent_user_id_from_context(data.context),
             "isLocalOnly": True,
             "isProxy": True,
             "deviceInfo": {

tests/components/cloud/test_google_config.py

@@ -841,3 +841,17 @@ async def test_google_config_migrate_expose_entity_prefs_default(
     assert async_get_entity_settings(hass, water_heater.entity_id) == {
         "cloud.google_assistant": {"should_expose": False}
     }
+
+
+async def test_google_config_get_agent_user_id(
+    hass: HomeAssistant, mock_cloud_login, cloud_prefs
+) -> None:
+    """Test overridden get_agent_user_id_from_webhook method."""
+    config = CloudGoogleConfig(
+        hass, GACTIONS_SCHEMA({}), "mock-user-id", cloud_prefs, hass.data["cloud"]
+    )
+    assert (
+        config.get_agent_user_id_from_webhook(cloud_prefs.google_local_webhook_id)
+        == config.agent_user_id
+    )
+    assert config.get_agent_user_id_from_webhook("other_id") != config.agent_user_id

tests/components/google_assistant/__init__.py

@@ -54,7 +54,7 @@ class MockConfig(http.GoogleConfig):
         """Return secure devices pin."""
         return self._entity_config
 
-    def get_agent_user_id(self, context):
+    def get_agent_user_id_from_context(self, context):
         """Get agent user ID making request."""
         return context.user_id
 

tests/components/google_assistant/test_data_redaction.py

@@ -0,0 +1,14 @@
+"""Test data redaction helpers."""
+import json
+
+from homeassistant.components.google_assistant.data_redaction import async_redact_msg
+
+from tests.common import load_fixture
+
+
+def test_redact_msg():
+    """Test async_redact_msg."""
+    messages = json.loads(load_fixture("data_redaction.json", "google_assistant"))
+    agent_user_id = "333dee20-1234-1234-1234-2225a0d70d4c"
+    for item in messages:
+        assert async_redact_msg(item["raw"], agent_user_id) == item["redacted"]

tests/components/google_assistant/test_smart_home.py

@@ -84,6 +84,7 @@ async def test_async_handle_message(hass: HomeAssistant) -> None:
         hass,
         config,
         "test-agent",
+        "test-agent",
         {
             "requestId": REQ_ID,
             "inputs": [
@@ -104,6 +105,7 @@ async def test_async_handle_message(hass: HomeAssistant) -> None:
         hass,
         config,
         "test-agent",
+        "test-agent",
         {
             "requestId": REQ_ID,
             "inputs": [
@@ -169,6 +171,7 @@ async def test_sync_message(hass: HomeAssistant, registries) -> None:
         hass,
         config,
         "test-agent",
+        "test-agent",
         {"requestId": REQ_ID, "inputs": [{"intent": "action.devices.SYNC"}]},
         const.SOURCE_CLOUD,
     )
@@ -299,6 +302,7 @@ async def test_sync_in_area(area_on_device, hass: HomeAssistant, registries) ->
         hass,
         config,
         "test-agent",
+        "test-agent",
         {"requestId": REQ_ID, "inputs": [{"intent": "action.devices.SYNC"}]},
         const.SOURCE_CLOUD,
     )
@@ -407,6 +411,7 @@ async def test_query_message(hass: HomeAssistant) -> None:
         hass,
         BASIC_CONFIG,
         "test-agent",
+        "test-agent",
         {
             "requestId": REQ_ID,
             "inputs": [
@@ -494,6 +499,7 @@ async def test_execute(
         hass,
         MockConfig(should_report_state=report_state),
         None,
+        None,
         {
             "requestId": REQ_ID,
             "inputs": [
@@ -654,6 +660,7 @@ async def test_execute_times_out(
             hass,
             MockConfig(should_report_state=report_state),
             None,
+            None,
             {
                 "requestId": REQ_ID,
                 "inputs": [
@@ -800,6 +807,7 @@ async def test_raising_error_trait(hass: HomeAssistant) -> None:
         hass,
         BASIC_CONFIG,
         "test-agent",
+        "test-agent",
         {
             "requestId": REQ_ID,
             "inputs": [
@@ -891,6 +899,7 @@ async def test_unavailable_state_does_sync(hass: HomeAssistant) -> None:
         hass,
         BASIC_CONFIG,
         "test-agent",
+        "test-agent",
         {"requestId": REQ_ID, "inputs": [{"intent": "action.devices.SYNC"}]},
         const.SOURCE_CLOUD,
     )
@@ -984,6 +993,7 @@ async def test_device_class_switch(
         hass,
         BASIC_CONFIG,
         "test-agent",
+        "test-agent",
         {"requestId": REQ_ID, "inputs": [{"intent": "action.devices.SYNC"}]},
         const.SOURCE_CLOUD,
     )
@@ -1033,6 +1043,7 @@ async def test_device_class_binary_sensor(
         hass,
         BASIC_CONFIG,
         "test-agent",
+        "test-agent",
         {"requestId": REQ_ID, "inputs": [{"intent": "action.devices.SYNC"}]},
         const.SOURCE_CLOUD,
     )
@@ -1086,6 +1097,7 @@ async def test_device_class_cover(
         hass,
         BASIC_CONFIG,
         "test-agent",
+        "test-agent",
         {"requestId": REQ_ID, "inputs": [{"intent": "action.devices.SYNC"}]},
         const.SOURCE_CLOUD,
     )
@@ -1133,6 +1145,7 @@ async def test_device_media_player(
         hass,
         BASIC_CONFIG,
         "test-agent",
+        "test-agent",
         {"requestId": REQ_ID, "inputs": [{"intent": "action.devices.SYNC"}]},
         const.SOURCE_CLOUD,
     )
@@ -1171,6 +1184,7 @@ async def test_query_disconnect(hass: HomeAssistant) -> None:
             hass,
             config,
             "test-agent",
+            "test-agent",
             {"inputs": [{"intent": "action.devices.DISCONNECT"}], "requestId": REQ_ID},
             const.SOURCE_CLOUD,
         )
@@ -1198,6 +1212,7 @@ async def test_trait_execute_adding_query_data(hass: HomeAssistant) -> None:
             hass,
             BASIC_CONFIG,
             None,
+            None,
             {
                 "requestId": REQ_ID,
                 "inputs": [
@@ -1256,6 +1271,7 @@ async def test_identify(hass: HomeAssistant) -> None:
         hass,
         BASIC_CONFIG,
         user_agent_id,
+        user_agent_id,
         {
             "requestId": REQ_ID,
             "inputs": [
@@ -1344,6 +1360,7 @@ async def test_reachable_devices(hass: HomeAssistant) -> None:
         hass,
         config,
         user_agent_id,
+        user_agent_id,
         {
             "requestId": REQ_ID,
             "inputs": [
@@ -1430,6 +1447,7 @@ async def test_sync_message_recovery(
         hass,
         BASIC_CONFIG,
         "test-agent",
+        "test-agent",
         {"requestId": REQ_ID, "inputs": [{"intent": "action.devices.SYNC"}]},
         const.SOURCE_CLOUD,
     )
@@ -1490,6 +1508,7 @@ async def test_query_recover(
         hass,
         BASIC_CONFIG,
         "test-agent",
+        "test-agent",
         {
             "requestId": REQ_ID,
             "inputs": [
@@ -1531,6 +1550,7 @@ async def test_proxy_selected(
         hass,
         BASIC_CONFIG,
         "test-agent",
+        "test-agent",
         {
             "requestId": REQ_ID,
             "inputs": [