Improve Alexa debug logging (#184241)

Co-authored-by: Claude Opus 5.5 <noreply@anthropic.com>

homeassistant/components/alexa/handlers.py

@@ -78,6 +78,7 @@ from homeassistant.components.water_heater import (
     WaterHeaterCapabilityAttribute,
 )
 from homeassistant.const import (
+    ATTR_CODE,
     ATTR_ENTITY_ID,
     ATTR_TEMPERATURE,
     SERVICE_ALARM_ARM_AWAY,
@@ -103,6 +104,7 @@ from homeassistant.const import (
     UnitOfTemperature,
 )
 from homeassistant.helpers import network
+from homeassistant.helpers.redact import async_redact_data
 from homeassistant.util import color as color_util, dt as dt_util
 from homeassistant.util.decorator import Registry
 from homeassistant.util.unit_conversion import (
@@ -135,6 +137,7 @@ from .state_report import AlexaDirective, AlexaResponse, async_enable_proactive_
 
 _LOGGER = logging.getLogger(__name__)
 DIRECTIVE_NOT_SUPPORTED = "Entity does not support directive"
+TO_REDACT_SERVICE_DATA = {ATTR_CODE}
 
 MIN_MAX_TEMP = {
     CLIMATE_DOMAIN: {
@@ -161,6 +164,30 @@ HANDLERS: Registry[
 ] = Registry()
 
 
+async def _async_call_service(
+    hass: ha.HomeAssistant,
+    directive: AlexaDirective,
+    domain: str,
+    service: str,
+    service_data: dict[str, Any],
+    *,
+    blocking: bool,
+    context: ha.Context,
+) -> None:
+    """Call an action and log it with the Alexa directive that triggered it."""
+    _LOGGER.debug(
+        "Calling action %s.%s for Alexa directive %s.%s with data: %s",
+        domain,
+        service,
+        directive.namespace,
+        directive.name,
+        async_redact_data(service_data, TO_REDACT_SERVICE_DATA),
+    )
+    await hass.services.async_call(
+        domain, service, service_data, blocking=blocking, context=context
+    )
+
+
 @HANDLERS.register(("Alexa.Discovery", "Discover"))
 async def async_api_discovery(
     hass: ha.HomeAssistant,
@@ -257,7 +284,9 @@ async def async_api_turn_on(
         if not supported & power_features:
             service = media_player.SERVICE_MEDIA_PLAY
 
-    await hass.services.async_call(
+    await _async_call_service(
+        hass,
+        directive,
         domain,
         service,
         {ATTR_ENTITY_ID: entity.entity_id},
@@ -310,7 +339,9 @@ async def async_api_turn_off(
         if not supported & power_features:
             service = media_player.SERVICE_MEDIA_STOP
 
-    await hass.services.async_call(
+    await _async_call_service(
+        hass,
+        directive,
         domain,
         service,
         {ATTR_ENTITY_ID: entity.entity_id},
@@ -332,7 +363,9 @@ async def async_api_set_brightness(
     entity = directive.entity
     brightness = int(directive.payload["brightness"])
 
-    await hass.services.async_call(
+    await _async_call_service(
+        hass,
+        directive,
         entity.domain,
         SERVICE_TURN_ON,
         {ATTR_ENTITY_ID: entity.entity_id, light.ATTR_BRIGHTNESS_PCT: brightness},
@@ -355,7 +388,9 @@ async def async_api_adjust_brightness(
     brightness_delta = int(directive.payload["brightnessDelta"])
 
     # set brightness
-    await hass.services.async_call(
+    await _async_call_service(
+        hass,
+        directive,
         entity.domain,
         SERVICE_TURN_ON,
         {
@@ -384,7 +419,9 @@ async def async_api_set_color(
         float(directive.payload["color"]["brightness"]),
     )
 
-    await hass.services.async_call(
+    await _async_call_service(
+        hass,
+        directive,
         entity.domain,
         SERVICE_TURN_ON,
         {ATTR_ENTITY_ID: entity.entity_id, light.ATTR_RGB_COLOR: rgb},
@@ -406,7 +443,9 @@ async def async_api_set_color_temperature(
     entity = directive.entity
     kelvin = int(directive.payload["colorTemperatureInKelvin"])
 
-    await hass.services.async_call(
+    await _async_call_service(
+        hass,
+        directive,
         entity.domain,
         SERVICE_TURN_ON,
         {ATTR_ENTITY_ID: entity.entity_id, light.ATTR_COLOR_TEMP_KELVIN: kelvin},
@@ -432,7 +471,9 @@ async def async_api_decrease_color_temp(
     )
 
     value = max(min_kelvin, current - 500)
-    await hass.services.async_call(
+    await _async_call_service(
+        hass,
+        directive,
         entity.domain,
         SERVICE_TURN_ON,
         {ATTR_ENTITY_ID: entity.entity_id, light.ATTR_COLOR_TEMP_KELVIN: value},
@@ -458,7 +499,9 @@ async def async_api_increase_color_temp(
     )
 
     value = min(max_kelvin, current + 500)
-    await hass.services.async_call(
+    await _async_call_service(
+        hass,
+        directive,
         entity.domain,
         SERVICE_TURN_ON,
         {ATTR_ENTITY_ID: entity.entity_id, light.ATTR_COLOR_TEMP_KELVIN: value},
@@ -486,7 +529,9 @@ async def async_api_activate(
     elif domain == INPUT_BUTTON_DOMAIN:
         service = input_button.SERVICE_PRESS
 
-    await hass.services.async_call(
+    await _async_call_service(
+        hass,
+        directive,
         domain,
         service,
         {ATTR_ENTITY_ID: entity.entity_id},
@@ -515,7 +560,9 @@ async def async_api_deactivate(
     entity = directive.entity
     domain = entity.domain
 
-    await hass.services.async_call(
+    await _async_call_service(
+        hass,
+        directive,
         domain,
         SERVICE_TURN_OFF,
         {ATTR_ENTITY_ID: entity.entity_id},
@@ -542,7 +589,9 @@ async def async_api_lock(
 ) -> AlexaResponse:
     """Process a lock request."""
     entity = directive.entity
-    await hass.services.async_call(
+    await _async_call_service(
+        hass,
+        directive,
         entity.domain,
         SERVICE_LOCK,
         {ATTR_ENTITY_ID: entity.entity_id},
@@ -591,7 +640,9 @@ async def async_api_unlock(
         raise AlexaInvalidDirectiveError(msg)
 
     entity = directive.entity
-    await hass.services.async_call(
+    await _async_call_service(
+        hass,
+        directive,
         entity.domain,
         SERVICE_UNLOCK,
         {ATTR_ENTITY_ID: entity.entity_id},
@@ -623,8 +674,14 @@ async def async_api_set_volume(
         media_player.ATTR_MEDIA_VOLUME_LEVEL: volume,
     }
 
-    await hass.services.async_call(
-        entity.domain, SERVICE_VOLUME_SET, data, blocking=False, context=context
+    await _async_call_service(
+        hass,
+        directive,
+        entity.domain,
+        SERVICE_VOLUME_SET,
+        data,
+        blocking=False,
+        context=context,
     )
 
     return directive.response()
@@ -671,7 +728,9 @@ async def async_api_select_input(
         media_player.ATTR_INPUT_SOURCE: media_input,
     }
 
-    await hass.services.async_call(
+    await _async_call_service(
+        hass,
+        directive,
         entity.domain,
         media_player.SERVICE_SELECT_SOURCE,
         data,
@@ -710,8 +769,14 @@ async def async_api_adjust_volume(
         media_player.ATTR_MEDIA_VOLUME_LEVEL: volume,
     }
 
-    await hass.services.async_call(
-        entity.domain, SERVICE_VOLUME_SET, data, blocking=False, context=context
+    await _async_call_service(
+        hass,
+        directive,
+        entity.domain,
+        SERVICE_VOLUME_SET,
+        data,
+        blocking=False,
+        context=context,
     )
 
     return directive.response()
@@ -748,8 +813,14 @@ async def async_api_adjust_volume_step(
     data: dict[str, Any] = {ATTR_ENTITY_ID: entity.entity_id}
 
     for _ in range(abs(volume_int)):
-        await hass.services.async_call(
-            entity.domain, service_volume, data, blocking=False, context=context
+        await _async_call_service(
+            hass,
+            directive,
+            entity.domain,
+            service_volume,
+            data,
+            blocking=False,
+            context=context,
         )
 
     return directive.response()
@@ -771,8 +842,14 @@ async def async_api_set_mute(
         media_player.ATTR_MEDIA_VOLUME_MUTED: mute,
     }
 
-    await hass.services.async_call(
-        entity.domain, SERVICE_VOLUME_MUTE, data, blocking=False, context=context
+    await _async_call_service(
+        hass,
+        directive,
+        entity.domain,
+        SERVICE_VOLUME_MUTE,
+        data,
+        blocking=False,
+        context=context,
     )
 
     return directive.response()
@@ -789,8 +866,14 @@ async def async_api_play(
     entity = directive.entity
     data: dict[str, Any] = {ATTR_ENTITY_ID: entity.entity_id}
 
-    await hass.services.async_call(
-        entity.domain, SERVICE_MEDIA_PLAY, data, blocking=False, context=context
+    await _async_call_service(
+        hass,
+        directive,
+        entity.domain,
+        SERVICE_MEDIA_PLAY,
+        data,
+        blocking=False,
+        context=context,
     )
 
     return directive.response()
@@ -807,8 +890,14 @@ async def async_api_pause(
     entity = directive.entity
     data: dict[str, Any] = {ATTR_ENTITY_ID: entity.entity_id}
 
-    await hass.services.async_call(
-        entity.domain, SERVICE_MEDIA_PAUSE, data, blocking=False, context=context
+    await _async_call_service(
+        hass,
+        directive,
+        entity.domain,
+        SERVICE_MEDIA_PAUSE,
+        data,
+        blocking=False,
+        context=context,
     )
 
     return directive.response()
@@ -835,16 +924,28 @@ async def async_api_stop(
         }
         await asyncio.gather(
             *(
-                hass.services.async_call(
-                    entity.domain, service, data, blocking=False, context=context
+                _async_call_service(
+                    hass,
+                    directive,
+                    entity.domain,
+                    service,
+                    data,
+                    blocking=False,
+                    context=context,
                 )
                 for feature, service in feature_services.items()
                 if feature & supported
             )
         )
     else:
-        await hass.services.async_call(
-            entity.domain, SERVICE_MEDIA_STOP, data, blocking=False, context=context
+        await _async_call_service(
+            hass,
+            directive,
+            entity.domain,
+            SERVICE_MEDIA_STOP,
+            data,
+            blocking=False,
+            context=context,
         )
 
     return directive.response()
@@ -861,8 +962,14 @@ async def async_api_next(
     entity = directive.entity
     data: dict[str, Any] = {ATTR_ENTITY_ID: entity.entity_id}
 
-    await hass.services.async_call(
-        entity.domain, SERVICE_MEDIA_NEXT_TRACK, data, blocking=False, context=context
+    await _async_call_service(
+        hass,
+        directive,
+        entity.domain,
+        SERVICE_MEDIA_NEXT_TRACK,
+        data,
+        blocking=False,
+        context=context,
     )
 
     return directive.response()
@@ -879,7 +986,9 @@ async def async_api_previous(
     entity = directive.entity
     data: dict[str, Any] = {ATTR_ENTITY_ID: entity.entity_id}
 
-    await hass.services.async_call(
+    await _async_call_service(
+        hass,
+        directive,
         entity.domain,
         SERVICE_MEDIA_PREVIOUS_TRACK,
         data,
@@ -967,7 +1076,9 @@ async def async_api_set_target_temp(
 
     service = SERVICE_SET_TEMPERATURE[domain]
 
-    await hass.services.async_call(
+    await _async_call_service(
+        hass,
+        directive,
         entity.domain,
         service,
         data,
@@ -1059,7 +1170,9 @@ async def async_api_adjust_target_temp(
 
     service = SERVICE_SET_TEMPERATURE[domain]
 
-    await hass.services.async_call(
+    await _async_call_service(
+        hass,
+        directive,
         entity.domain,
         service,
         data,
@@ -1136,8 +1249,8 @@ async def async_api_set_thermostat_mode(
         data[climate.ATTR_HVAC_MODE] = ha_mode
 
     response = directive.response()
-    await hass.services.async_call(
-        CLIMATE_DOMAIN, service, data, blocking=False, context=context
+    await _async_call_service(
+        hass, directive, CLIMATE_DOMAIN, service, data, blocking=False, context=context
     )
     response.add_context_property(
         {
@@ -1193,8 +1306,8 @@ async def async_api_arm(
     else:
         raise AlexaInvalidDirectiveError(DIRECTIVE_NOT_SUPPORTED)
 
-    await hass.services.async_call(
-        entity.domain, service, data, blocking=False, context=context
+    await _async_call_service(
+        hass, directive, entity.domain, service, data, blocking=False, context=context
     )
 
     # return 0 until alarm integration supports an exit delay
@@ -1237,10 +1350,16 @@ async def async_api_disarm(
     if "authorization" in payload:
         value = payload["authorization"]["value"]
         if payload["authorization"]["type"] == "FOUR_DIGIT_PIN":
-            data["code"] = value
+            data[ATTR_CODE] = value
 
-    await hass.services.async_call(
-        entity.domain, SERVICE_ALARM_DISARM, data, blocking=True, context=context
+    await _async_call_service(
+        hass,
+        directive,
+        entity.domain,
+        SERVICE_ALARM_DISARM,
+        data,
+        blocking=True,
+        context=context,
     )
 
     response.add_context_property(
@@ -1362,8 +1481,8 @@ async def async_api_set_mode(
     if not service:
         raise AlexaInvalidDirectiveError(DIRECTIVE_NOT_SUPPORTED)
 
-    await hass.services.async_call(
-        domain, service, data, blocking=False, context=context
+    await _async_call_service(
+        hass, directive, domain, service, data, blocking=False, context=context
     )
 
     response = directive.response()
@@ -1426,8 +1545,8 @@ async def async_api_toggle_on(
     else:
         raise AlexaInvalidDirectiveError(DIRECTIVE_NOT_SUPPORTED)
 
-    await hass.services.async_call(
-        domain, service, data, blocking=False, context=context
+    await _async_call_service(
+        hass, directive, domain, service, data, blocking=False, context=context
     )
 
     response = directive.response()
@@ -1465,8 +1584,8 @@ async def async_api_toggle_off(
         fan.ATTR_OSCILLATING: False,
     }
 
-    await hass.services.async_call(
-        domain, service, data, blocking=False, context=context
+    await _async_call_service(
+        hass, directive, domain, service, data, blocking=False, context=context
     )
 
     response = directive.response()
@@ -1581,8 +1700,8 @@ async def async_api_set_range(
     else:
         raise AlexaInvalidDirectiveError(DIRECTIVE_NOT_SUPPORTED)
 
-    await hass.services.async_call(
-        domain, service, data, blocking=False, context=context
+    await _async_call_service(
+        hass, directive, domain, service, data, blocking=False, context=context
     )
 
     response = directive.response()
@@ -1751,8 +1870,8 @@ async def async_api_adjust_range(
     else:
         raise AlexaInvalidDirectiveError(DIRECTIVE_NOT_SUPPORTED)
 
-    await hass.services.async_call(
-        domain, service, data, blocking=False, context=context
+    await _async_call_service(
+        hass, directive, domain, service, data, blocking=False, context=context
     )
 
     response = directive.response()
@@ -1804,7 +1923,9 @@ async def async_api_changechannel(
         media_player.ATTR_MEDIA_CONTENT_TYPE: (media_player.MediaType.CHANNEL),
     }
 
-    await hass.services.async_call(
+    await _async_call_service(
+        hass,
+        directive,
         entity.domain,
         media_player.SERVICE_PLAY_MEDIA,
         data,
@@ -1844,8 +1965,14 @@ async def async_api_skipchannel(
         service_media = SERVICE_MEDIA_NEXT_TRACK
 
     for _ in range(abs(channel)):
-        await hass.services.async_call(
-            entity.domain, service_media, data, blocking=False, context=context
+        await _async_call_service(
+            hass,
+            directive,
+            entity.domain,
+            service_media,
+            data,
+            blocking=False,
+            context=context,
         )
 
     response = directive.response()
@@ -1892,7 +2019,9 @@ async def async_api_seek(
         media_player.ATTR_MEDIA_SEEK_POSITION: seek_position,
     }
 
-    await hass.services.async_call(
+    await _async_call_service(
+        hass,
+        directive,
         MEDIA_PLAYER_DOMAIN,
         media_player.SERVICE_MEDIA_SEEK,
         data,
@@ -1932,7 +2061,9 @@ async def async_api_set_eq_mode(
         msg = f"failed to map sound mode {mode} to a mode on {entity.entity_id}"
         raise AlexaInvalidValueError(msg)
 
-    await hass.services.async_call(
+    await _async_call_service(
+        hass,
+        directive,
         entity.domain,
         media_player.SERVICE_SELECT_SOUND_MODE,
         data,
@@ -1980,8 +2111,8 @@ async def async_api_hold(
     else:
         raise AlexaInvalidDirectiveError(DIRECTIVE_NOT_SUPPORTED)
 
-    await hass.services.async_call(
-        entity.domain, service, data, blocking=False, context=context
+    await _async_call_service(
+        hass, directive, entity.domain, service, data, blocking=False, context=context
     )
 
     return directive.response()
@@ -2007,8 +2138,8 @@ async def async_api_resume(
     else:
         raise AlexaInvalidDirectiveError(DIRECTIVE_NOT_SUPPORTED)
 
-    await hass.services.async_call(
-        entity.domain, service, data, blocking=False, context=context
+    await _async_call_service(
+        hass, directive, entity.domain, service, data, blocking=False, context=context
     )
 
     return directive.response()

homeassistant/components/alexa/smart_home.py

@@ -22,6 +22,7 @@ from .auth import Auth
 from .config import AbstractConfig
 from .const import (
     API_DIRECTIVE,
+    API_ENDPOINT,
     API_HEADER,
     CONF_ENDPOINT,
     CONF_ENTITY_CONFIG,
@@ -165,8 +166,14 @@ class SmartHomeView(HomeAssistantView):
         message: dict[str, Any] = await request.json()
 
         if _LOGGER.isEnabledFor(logging.DEBUG):
+            endpoint_id = (
+                message.get(API_DIRECTIVE, {}).get(API_ENDPOINT, {}).get("endpointId")
+            )
             _LOGGER.debug(
-                "Received Alexa Smart Home request: %s",
+                "Received Alexa Smart Home request for entity %s: %s",
+                endpoint_id.replace("#", ".")
+                if isinstance(endpoint_id, str)
+                else endpoint_id,
                 async_redact_auth_data(message),
             )
 

homeassistant/components/alexa/state_report.py

@@ -109,7 +109,8 @@ class AlexaDirective:
         Will raise AlexaInvalidEndpointError if the endpoint in the request is
         malformed or nonexistent.
         """
-        _endpoint_id: str = self._directive[API_ENDPOINT]["endpointId"]
+        # A malformed request can contain a non-string endpointId
+        _endpoint_id = str(self._directive[API_ENDPOINT]["endpointId"])
         self.entity_id = _endpoint_id.replace("#", ".")
 
         entity: State | None = hass.states.get(self.entity_id)
@@ -293,6 +294,7 @@ async def async_enable_proactive_mode(
         return old_extra_arg is not None and old_extra_arg != new_extra_arg
 
     checker = await create_checker(hass, DOMAIN, extra_significant_check)
+    logged_exposure: dict[str, bool] = {}
 
     @callback
     def _async_entity_state_filter(data: EventStateChangedData) -> bool:
@@ -306,11 +308,20 @@ async def async_enable_proactive_mode(
             return False
 
         changed_entity = data["entity_id"]
-        if not smart_home_config.should_expose(changed_entity):
-            _LOGGER.debug("Not exposing %s because filtered by config", changed_entity)
-            return False
+        should_expose = smart_home_config.should_expose(changed_entity)
+        if (
+            _LOGGER.isEnabledFor(logging.DEBUG)
+            and logged_exposure.get(changed_entity) != should_expose
+        ):
+            logged_exposure[changed_entity] = should_expose
+            if should_expose:
+                _LOGGER.debug("Exposing %s", changed_entity)
+            else:
+                _LOGGER.debug(
+                    "Not exposing %s because filtered by config", changed_entity
+                )
 
-        return True
+        return should_expose
 
     async def _async_entity_state_listener(
         event_: Event[EventStateChangedData],

tests/components/alexa/test_smart_home_http.py

@@ -71,3 +71,39 @@ async def test_http_api_disabled(
     config = {"alexa": {}}
     response = await do_http_discovery(config, hass, hass_client)
     assert response.status == HTTPStatus.NOT_FOUND
+
+
+@pytest.mark.parametrize(
+    ("endpoint_id", "logged_entity_id"),
+    [
+        pytest.param("light#kitchen", "light.kitchen", id="string"),
+        pytest.param(123, "123", id="non_string"),
+    ],
+)
+async def test_http_api_logs_entity_id(
+    hass: HomeAssistant,
+    caplog: pytest.LogCaptureFixture,
+    hass_client: ClientSessionGenerator,
+    endpoint_id: str | int,
+    logged_entity_id: str,
+) -> None:
+    """Test the entity ID is logged and an unknown endpoint returns an error."""
+    await async_setup_component(hass, DOMAIN, {"alexa": {"smart_home": None}})
+    http_client = await hass_client()
+    request = get_new_request("Alexa.PowerController", "TurnOn", "light#kitchen")
+    request["directive"]["endpoint"]["endpointId"] = endpoint_id
+
+    with caplog.at_level(logging.DEBUG):
+        response = await http_client.post(
+            smart_home.SMART_HOME_HTTP_ENDPOINT,
+            data=json.dumps(request),
+            headers={"content-type": CONTENT_TYPE_JSON},
+        )
+        response_data = await response.json()
+
+    assert (
+        f"Received Alexa Smart Home request for entity {logged_entity_id}:"
+        in caplog.text
+    )
+    assert response_data["event"]["header"]["name"] == "ErrorResponse"
+    assert response_data["event"]["payload"]["type"] == "NO_SUCH_ENDPOINT"