Fail tests if wrapped callbacks or coroutines throw (#35010)

homeassistant/util/logging.py

@@ -124,12 +124,8 @@ class AsyncHandler:
         self.handler.set_name(name)  # type: ignore
 
 
-def catch_log_exception(
+def log_exception(format_err: Callable[..., Any], *args: Any) -> None:
-    func: Callable[..., Any], format_err: Callable[..., Any], *args: Any
+    """Log an exception with additional context."""
-) -> Callable[[], None]:
-    """Decorate a callback to catch and log exceptions."""
-
-    def log_exception(*args: Any) -> None:
     module = inspect.getmodule(inspect.stack()[1][0])
     if module is not None:
         module_name = module.__name__
@@ -145,6 +141,12 @@ def catch_log_exception(
     friendly_msg = format_err(*args)
     logging.getLogger(module_name).error("%s\n%s", friendly_msg, exc_msg)
 
+
+def catch_log_exception(
+    func: Callable[..., Any], format_err: Callable[..., Any], *args: Any
+) -> Callable[[], None]:
+    """Decorate a callback to catch and log exceptions."""
+
     # Check for partials to properly determine if coroutine function
     check_func = func
     while isinstance(check_func, partial):
@@ -159,7 +161,7 @@ def catch_log_exception(
             try:
                 await func(*args)
             except Exception:  # pylint: disable=broad-except
-                log_exception(*args)
+                log_exception(format_err, *args)
 
         wrapper_func = async_wrapper
     else:
@@ -170,7 +172,7 @@ def catch_log_exception(
             try:
                 func(*args)
             except Exception:  # pylint: disable=broad-except
-                log_exception(*args)
+                log_exception(format_err, *args)
 
         wrapper_func = wrapper
     return wrapper_func
@@ -186,20 +188,7 @@ def catch_log_coro_exception(
         try:
             return await target
         except Exception:  # pylint: disable=broad-except
-            module = inspect.getmodule(inspect.stack()[1][0])
+            log_exception(format_err, *args)
-            if module is not None:
-                module_name = module.__name__
-            else:
-                # If Python is unable to access the sources files, the frame
-                # will be missing information, so let's guard.
-                # https://github.com/home-assistant/home-assistant/issues/24982
-                module_name = __name__
-
-            # Do not print the wrapper in the traceback
-            frames = len(inspect.trace()) - 1
-            exc_msg = traceback.format_exc(-frames)
-            friendly_msg = format_err(*args)
-            logging.getLogger(module_name).error("%s\n%s", friendly_msg, exc_msg)
             return None
 
     return coro_wrapper()

tests/components/mqtt/test_alarm_control_panel.py

@@ -2,6 +2,8 @@
 import copy
 import json
 
+import pytest
+
 from homeassistant.components import alarm_control_panel
 from homeassistant.const import (
     STATE_ALARM_ARMED_AWAY,
@@ -551,6 +553,7 @@ async def test_discovery_update_alarm(hass, mqtt_mock, caplog):
     )
 
 
+@pytest.mark.no_fail_on_log_exception
 async def test_discovery_broken(hass, mqtt_mock, caplog):
     """Test handling of bad discovery message."""
     data1 = '{ "name": "Beer" }'

tests/components/mqtt/test_binary_sensor.py

@@ -3,6 +3,8 @@ import copy
 from datetime import datetime, timedelta
 import json
 
+import pytest
+
 from homeassistant.components import binary_sensor, mqtt
 from homeassistant.components.mqtt.discovery import async_start
 from homeassistant.const import (
@@ -184,6 +186,43 @@ async def test_setting_sensor_value_via_mqtt_message(hass, mqtt_mock):
     assert state.state == STATE_OFF
 
 
+async def test_invalid_sensor_value_via_mqtt_message(hass, mqtt_mock, caplog):
+    """Test the setting of the value via MQTT."""
+    assert await async_setup_component(
+        hass,
+        binary_sensor.DOMAIN,
+        {
+            binary_sensor.DOMAIN: {
+                "platform": "mqtt",
+                "name": "test",
+                "state_topic": "test-topic",
+                "payload_on": "ON",
+                "payload_off": "OFF",
+            }
+        },
+    )
+
+    state = hass.states.get("binary_sensor.test")
+
+    assert state.state == STATE_OFF
+
+    async_fire_mqtt_message(hass, "test-topic", "0N")
+    state = hass.states.get("binary_sensor.test")
+    assert state.state == STATE_OFF
+    assert "No matching payload found for entity" in caplog.text
+    caplog.clear()
+    assert "No matching payload found for entity" not in caplog.text
+
+    async_fire_mqtt_message(hass, "test-topic", "ON")
+    state = hass.states.get("binary_sensor.test")
+    assert state.state == STATE_ON
+
+    async_fire_mqtt_message(hass, "test-topic", "0FF")
+    state = hass.states.get("binary_sensor.test")
+    assert state.state == STATE_ON
+    assert "No matching payload found for entity" in caplog.text
+
+
 async def test_setting_sensor_value_via_mqtt_message_and_template(hass, mqtt_mock):
     """Test the setting of the value via MQTT."""
     assert await async_setup_component(
@@ -548,6 +587,7 @@ async def test_expiration_on_discovery_and_discovery_update_of_binary_sensor(
     assert state.state == STATE_UNAVAILABLE
 
 
+@pytest.mark.no_fail_on_log_exception
 async def test_discovery_broken(hass, mqtt_mock, caplog):
     """Test handling of bad discovery message."""
     data1 = '{ "name": "Beer",' '  "off_delay": -1 }'

tests/components/mqtt/test_camera.py

@@ -1,6 +1,8 @@
 """The tests for mqtt camera component."""
 import json
 
+import pytest
+
 from homeassistant.components import camera, mqtt
 from homeassistant.components.mqtt.discovery import async_start
 from homeassistant.setup import async_setup_component
@@ -155,6 +157,7 @@ async def test_discovery_update_camera(hass, mqtt_mock, caplog):
     )
 
 
+@pytest.mark.no_fail_on_log_exception
 async def test_discovery_broken(hass, mqtt_mock, caplog):
     """Test handling of bad discovery message."""
     entry = MockConfigEntry(domain=mqtt.DOMAIN)

tests/components/mqtt/test_climate.py

@@ -868,6 +868,7 @@ async def test_discovery_update_climate(hass, mqtt_mock, caplog):
     )
 
 
+@pytest.mark.no_fail_on_log_exception
 async def test_discovery_broken(hass, mqtt_mock, caplog):
     """Test handling of bad discovery message."""
     data1 = '{ "name": "Beer",' '  "power_command_topic": "test_topic#" }'

tests/components/mqtt/test_common.py

@@ -252,7 +252,6 @@ async def help_test_unique_id(hass, domain, config):
     """Test unique id option only creates one entity per unique_id."""
     await async_mock_mqtt_component(hass)
     assert await async_setup_component(hass, domain, config,)
-    async_fire_mqtt_message(hass, "test-topic", "payload")
     assert len(hass.states.async_entity_ids(domain)) == 1
 
 

tests/components/mqtt/test_cover.py

@@ -1,4 +1,6 @@
 """The tests for the MQTT cover platform."""
+import pytest
+
 from homeassistant.components import cover
 from homeassistant.components.cover import (
     ATTR_CURRENT_POSITION,
@@ -1831,6 +1833,7 @@ async def test_discovery_update_cover(hass, mqtt_mock, caplog):
     )
 
 
+@pytest.mark.no_fail_on_log_exception
 async def test_discovery_broken(hass, mqtt_mock, caplog):
     """Test handling of bad discovery message."""
     data1 = '{ "name": "Beer",' '  "command_topic": "test_topic#" }'

tests/components/mqtt/test_device_trigger.py

@@ -134,6 +134,7 @@ async def test_get_non_existing_triggers(hass, device_reg, entity_reg, mqtt_mock
     assert_lists_same(triggers, [])
 
 
+@pytest.mark.no_fail_on_log_exception
 async def test_discover_bad_triggers(hass, device_reg, entity_reg, mqtt_mock):
     """Test bad discovery message."""
     config_entry = MockConfigEntry(domain=DOMAIN, data={})

tests/components/mqtt/test_fan.py

@@ -1,4 +1,6 @@
 """Test MQTT fans."""
+import pytest
+
 from homeassistant.components import fan
 from homeassistant.const import (
     ATTR_ASSUMED_STATE,
@@ -681,6 +683,7 @@ async def test_discovery_update_fan(hass, mqtt_mock, caplog):
     await help_test_discovery_update(hass, mqtt_mock, caplog, fan.DOMAIN, data1, data2)
 
 
+@pytest.mark.no_fail_on_log_exception
 async def test_discovery_broken(hass, mqtt_mock, caplog):
     """Test handling of bad discovery message."""
     data1 = '{ "name": "Beer" }'

tests/components/mqtt/test_init.py

@@ -821,6 +821,7 @@ async def test_setup_fails_without_config(hass):
     assert not await async_setup_component(hass, mqtt.DOMAIN, {})
 
 
+@pytest.mark.no_fail_on_log_exception
 async def test_message_callback_exception_gets_logged(hass, caplog):
     """Test exception raised by message handler."""
     await async_mock_mqtt_component(hass)

tests/components/mqtt/test_legacy_vacuum.py

@@ -2,6 +2,8 @@
 from copy import deepcopy
 import json
 
+import pytest
+
 from homeassistant.components import vacuum
 from homeassistant.components.mqtt import CONF_COMMAND_TOPIC
 from homeassistant.components.mqtt.vacuum import schema_legacy as mqttvacuum
@@ -612,6 +614,7 @@ async def test_discovery_update_vacuum(hass, mqtt_mock, caplog):
     )
 
 
+@pytest.mark.no_fail_on_log_exception
 async def test_discovery_broken(hass, mqtt_mock, caplog):
     """Test handling of bad discovery message."""
     data1 = '{ "name": "Beer",' '  "command_topic": "test_topic#" }'

tests/components/mqtt/test_light.py

@@ -153,6 +153,8 @@ light:
   payload_off: "off"
 
 """
+import pytest
+
 from homeassistant.components import light, mqtt
 from homeassistant.components.mqtt.discovery import async_start
 from homeassistant.const import ATTR_ASSUMED_STATE, STATE_OFF, STATE_ON
@@ -1420,6 +1422,7 @@ async def test_discovery_update_light(hass, mqtt_mock, caplog):
     )
 
 
+@pytest.mark.no_fail_on_log_exception
 async def test_discovery_broken(hass, mqtt_mock, caplog):
     """Test handling of bad discovery message."""
     data1 = '{ "name": "Beer" }'

tests/components/mqtt/test_light_json.py

@@ -89,6 +89,8 @@ light:
 """
 import json
 
+import pytest
+
 from homeassistant.components import light
 from homeassistant.const import (
     ATTR_ASSUMED_STATE,
@@ -1155,6 +1157,7 @@ async def test_discovery_update_light(hass, mqtt_mock, caplog):
     )
 
 
+@pytest.mark.no_fail_on_log_exception
 async def test_discovery_broken(hass, mqtt_mock, caplog):
     """Test handling of bad discovery message."""
     data1 = '{ "name": "Beer" }'
@@ -1214,5 +1217,5 @@ async def test_entity_id_update_discovery_update(hass, mqtt_mock):
 async def test_entity_debug_info_message(hass, mqtt_mock):
     """Test MQTT debug info."""
     await help_test_entity_debug_info_message(
-        hass, mqtt_mock, light.DOMAIN, DEFAULT_CONFIG
+        hass, mqtt_mock, light.DOMAIN, DEFAULT_CONFIG, payload='{"state":"ON"}'
     )

tests/components/mqtt/test_light_template.py

@@ -26,6 +26,8 @@ If your light doesn't support white value feature, omit `white_value_template`.
 
 If your light doesn't support RGB feature, omit `(red|green|blue)_template`.
 """
+import pytest
+
 from homeassistant.components import light
 from homeassistant.const import (
     ATTR_ASSUMED_STATE,
@@ -901,6 +903,7 @@ async def test_discovery_update_light(hass, mqtt_mock, caplog):
     )
 
 
+@pytest.mark.no_fail_on_log_exception
 async def test_discovery_broken(hass, mqtt_mock, caplog):
     """Test handling of bad discovery message."""
     data1 = '{ "name": "Beer" }'
@@ -961,6 +964,15 @@ async def test_entity_id_update_discovery_update(hass, mqtt_mock):
 
 async def test_entity_debug_info_message(hass, mqtt_mock):
     """Test MQTT debug info."""
-    await help_test_entity_debug_info_message(
+    config = {
-        hass, mqtt_mock, light.DOMAIN, DEFAULT_CONFIG
+        light.DOMAIN: {
-    )
+            "platform": "mqtt",
+            "schema": "template",
+            "name": "test",
+            "command_topic": "test-topic",
+            "command_on_template": "on,{{ transition }}",
+            "command_off_template": "off,{{ transition|d }}",
+            "state_template": '{{ value.split(",")[0] }}',
+        }
+    }
+    await help_test_entity_debug_info_message(hass, mqtt_mock, light.DOMAIN, config)

tests/components/mqtt/test_lock.py

@@ -1,4 +1,6 @@
 """The tests for the MQTT lock platform."""
+import pytest
+
 from homeassistant.components.lock import (
     DOMAIN as LOCK_DOMAIN,
     SERVICE_LOCK,
@@ -366,6 +368,7 @@ async def test_discovery_update_lock(hass, mqtt_mock, caplog):
     await help_test_discovery_update(hass, mqtt_mock, caplog, LOCK_DOMAIN, data1, data2)
 
 
+@pytest.mark.no_fail_on_log_exception
 async def test_discovery_broken(hass, mqtt_mock, caplog):
     """Test handling of bad discovery message."""
     data1 = '{ "name": "Beer" }'

tests/components/mqtt/test_sensor.py

@@ -2,6 +2,8 @@
 from datetime import datetime, timedelta
 import json
 
+import pytest
+
 from homeassistant.components import mqtt
 from homeassistant.components.mqtt.discovery import async_start
 import homeassistant.components.sensor as sensor
@@ -361,6 +363,7 @@ async def test_discovery_update_sensor(hass, mqtt_mock, caplog):
     )
 
 
+@pytest.mark.no_fail_on_log_exception
 async def test_discovery_broken(hass, mqtt_mock, caplog):
     """Test handling of bad discovery message."""
     data1 = '{ "name": "Beer",' '  "state_topic": "test_topic#" }'

tests/components/mqtt/test_state_vacuum.py

@@ -2,6 +2,8 @@
 from copy import deepcopy
 import json
 
+import pytest
+
 from homeassistant.components import vacuum
 from homeassistant.components.mqtt import CONF_COMMAND_TOPIC, CONF_STATE_TOPIC
 from homeassistant.components.mqtt.vacuum import CONF_SCHEMA, schema_state as mqttvacuum
@@ -298,6 +300,7 @@ async def test_no_fan_vacuum(hass, mqtt_mock):
     assert state.attributes.get(ATTR_BATTERY_LEVEL) == 61
 
 
+@pytest.mark.no_fail_on_log_exception
 async def test_status_invalid_json(hass, mqtt_mock):
     """Test to make sure nothing breaks if the vacuum sends bad JSON."""
     config = deepcopy(DEFAULT_CONFIG)
@@ -406,6 +409,7 @@ async def test_discovery_update_vacuum(hass, mqtt_mock, caplog):
     )
 
 
+@pytest.mark.no_fail_on_log_exception
 async def test_discovery_broken(hass, mqtt_mock, caplog):
     """Test handling of bad discovery message."""
     data1 = '{ "schema": "state", "name": "Beer",' '  "command_topic": "test_topic#"}'
@@ -460,5 +464,5 @@ async def test_entity_id_update_discovery_update(hass, mqtt_mock):
 async def test_entity_debug_info_message(hass, mqtt_mock):
     """Test MQTT debug info."""
     await help_test_entity_debug_info_message(
-        hass, mqtt_mock, vacuum.DOMAIN, DEFAULT_CONFIG_2
+        hass, mqtt_mock, vacuum.DOMAIN, DEFAULT_CONFIG_2, payload="{}"
     )

tests/components/mqtt/test_switch.py

@@ -314,6 +314,7 @@ async def test_discovery_update_switch(hass, mqtt_mock, caplog):
     )
 
 
+@pytest.mark.no_fail_on_log_exception
 async def test_discovery_broken(hass, mqtt_mock, caplog):
     """Test handling of bad discovery message."""
     data1 = '{ "name": "Beer" }'

tests/conftest.py

@@ -19,6 +19,7 @@ from homeassistant.setup import async_setup_component
 from homeassistant.util import location
 
 from tests.async_mock import patch
+from tests.ignore_uncaught_exceptions import IGNORE_UNCAUGHT_EXCEPTIONS
 
 pytest.register_assert_rewrite("tests.common")
 
@@ -36,6 +37,13 @@ logging.basicConfig(level=logging.DEBUG)
 logging.getLogger("sqlalchemy.engine").setLevel(logging.INFO)
 
 
+def pytest_configure(config):
+    """Register marker for tests that log exceptions."""
+    config.addinivalue_line(
+        "markers", "no_fail_on_log_exception: mark test to not fail on logged exception"
+    )
+
+
 def check_real(func):
     """Force a function to require a keyword _test_real to be passed in."""
 
@@ -95,6 +103,11 @@ def hass(loop, hass_storage, request):
 
     loop.run_until_complete(hass.async_stop(force=True))
     for ex in exceptions:
+        if (
+            request.module.__name__,
+            request.function.__name__,
+        ) in IGNORE_UNCAUGHT_EXCEPTIONS:
+            continue
         if isinstance(ex, ServiceNotFound):
             continue
         raise ex
@@ -242,3 +255,15 @@ def hass_ws_client(aiohttp_client, hass_access_token, hass):
         return websocket
 
     return create_client
+
+
+@pytest.fixture(autouse=True)
+def fail_on_log_exception(request, monkeypatch):
+    """Fixture to fail if a callback wrapped by catch_log_exception or coroutine wrapped by async_create_catching_coro throws."""
+    if "no_fail_on_log_exception" in request.keywords:
+        return
+
+    def log_exception(format_err, *args):
+        raise
+
+    monkeypatch.setattr("homeassistant.util.logging.log_exception", log_exception)

tests/helpers/test_dispatcher.py

@@ -1,6 +1,8 @@
 """Test dispatcher helpers."""
 from functools import partial
 
+import pytest
+
 from homeassistant.core import callback
 from homeassistant.helpers.dispatcher import (
     async_dispatcher_connect,
@@ -128,6 +130,7 @@ async def test_simple_function_multiargs(hass):
     assert calls == [3, 2, "bla"]
 
 
+@pytest.mark.no_fail_on_log_exception
 async def test_callback_exception_gets_logged(hass, caplog):
     """Test exception raised by signal handler."""
 

tests/ignore_uncaught_exceptions.py

@@ -0,0 +1,12 @@
+"""List of tests that have uncaught exceptions today. Will be shrunk over time."""
+IGNORE_UNCAUGHT_EXCEPTIONS = [
+    ("test_homeassistant_bridge", "test_homeassistant_bridge_fan_setup",),
+    (
+        "tests.components.owntracks.test_device_tracker",
+        "test_mobile_multiple_async_enter_exit",
+    ),
+    (
+        "tests.components.smartthings.test_init",
+        "test_event_handler_dispatches_updated_devices",
+    ),
+]

tests/util/test_logging.py

@@ -3,6 +3,8 @@ import asyncio
 import logging
 import threading
 
+import pytest
+
 import homeassistant.util.logging as logging_util
 
 
@@ -65,6 +67,7 @@ async def test_async_handler_thread_log(loop):
     assert queue.empty()
 
 
+@pytest.mark.no_fail_on_log_exception
 async def test_async_create_catching_coro(hass, caplog):
     """Test exception logging of wrapped coroutine."""