Log exceptions thrown by signal callbacks (#20015)

* Log exceptions thrown by signal callbacks

* Fix unsub

* Simplify traceback print

* Typing

* Add test

* lint

* Review comments

* Rework MQTT test case

* Fix bad merge

* Fix bad merge

homeassistant/helpers/dispatcher.py

@@ -5,6 +5,7 @@ from typing import Any, Callable
 from homeassistant.core import callback
 from homeassistant.loader import bind_hass
 from homeassistant.util.async_ import run_callback_threadsafe
+from homeassistant.util.logging import catch_log_exception
 from .typing import HomeAssistantType
 
 
@@ -40,13 +41,18 @@ def async_dispatcher_connect(hass: HomeAssistantType, signal: str,
     if signal not in hass.data[DATA_DISPATCHER]:
         hass.data[DATA_DISPATCHER][signal] = []
 
-    hass.data[DATA_DISPATCHER][signal].append(target)
+    wrapped_target = catch_log_exception(
+        target, lambda *args:
+        "Exception in {} when dispatching '{}': {}".format(
+            target.__name__, signal, args))
+
+    hass.data[DATA_DISPATCHER][signal].append(wrapped_target)
 
     @callback
     def async_remove_dispatcher() -> None:
         """Remove signal listener."""
         try:
-            hass.data[DATA_DISPATCHER][signal].remove(target)
+            hass.data[DATA_DISPATCHER][signal].remove(wrapped_target)
         except (KeyError, ValueError):
             # KeyError is key target listener did not exist
             # ValueError if listener did not exist within signal

tests/components/mqtt/test_init.py

@@ -13,10 +13,10 @@ from homeassistant.components import mqtt
 from homeassistant.const import (EVENT_CALL_SERVICE, ATTR_DOMAIN, ATTR_SERVICE,
                                  EVENT_HOMEASSISTANT_STOP)
 
-from tests.common import (get_test_home_assistant, mock_coro,
-                          mock_mqtt_component,
-                          threadsafe_coroutine_factory, fire_mqtt_message,
-                          async_fire_mqtt_message, MockConfigEntry)
+from tests.common import (
+    MockConfigEntry, async_fire_mqtt_message, async_mock_mqtt_component,
+    fire_mqtt_message, get_test_home_assistant, mock_coro, mock_mqtt_component,
+    threadsafe_coroutine_factory)
 
 
 @pytest.fixture
@@ -297,23 +297,6 @@ class TestMQTTCallbacks(unittest.TestCase):
                 "b'\\x9a' on test-topic with encoding utf-8" in \
                 test_handle.output[0]
 
-    def test_message_callback_exception_gets_logged(self):
-        """Test exception raised by message handler."""
-        @callback
-        def bad_handler(*args):
-            """Record calls."""
-            raise Exception('This is a bad message callback')
-        mqtt.subscribe(self.hass, 'test-topic', bad_handler)
-
-        with self.assertLogs(level='WARNING') as test_handle:
-            fire_mqtt_message(self.hass, 'test-topic', 'test')
-
-            self.hass.block_till_done()
-            assert \
-                "Exception in bad_handler when handling msg on 'test-topic':" \
-                " 'test'" in \
-                test_handle.output[0]
-
     def test_all_subscriptions_run_when_decode_fails(self):
         """Test all other subscriptions still run when decode fails for one."""
         mqtt.subscribe(self.hass, 'test-topic', self.record_calls,
@@ -766,3 +749,21 @@ def test_mqtt_subscribes_topics_on_connect(hass):
 async def test_setup_fails_without_config(hass):
     """Test if the MQTT component fails to load with no config."""
     assert not await async_setup_component(hass, mqtt.DOMAIN, {})
+
+
+async def test_message_callback_exception_gets_logged(hass, caplog):
+    """Test exception raised by message handler."""
+    await async_mock_mqtt_component(hass)
+
+    @callback
+    def bad_handler(*args):
+        """Record calls."""
+        raise Exception('This is a bad message callback')
+
+    await mqtt.async_subscribe(hass, 'test-topic', bad_handler)
+    async_fire_mqtt_message(hass, 'test-topic', 'test')
+    await hass.async_block_till_done()
+
+    assert \
+        "Exception in bad_handler when handling msg on 'test-topic':" \
+        " 'test'" in caplog.text

tests/helpers/test_dispatcher.py

@@ -3,7 +3,7 @@ import asyncio
 
 from homeassistant.core import callback
 from homeassistant.helpers.dispatcher import (
-    dispatcher_send, dispatcher_connect)
+    async_dispatcher_connect, dispatcher_send, dispatcher_connect)
 
 from tests.common import get_test_home_assistant
 
@@ -134,3 +134,20 @@ class TestHelpersDispatcher:
         self.hass.block_till_done()
 
         assert calls == [3, 2, 'bla']
+
+
+async def test_callback_exception_gets_logged(hass, caplog):
+    """Test exception raised by signal handler."""
+    @callback
+    def bad_handler(*args):
+        """Record calls."""
+        raise Exception('This is a bad message callback')
+
+    async_dispatcher_connect(hass, 'test', bad_handler)
+    dispatcher_send(hass, 'test', 'bad')
+    await hass.async_block_till_done()
+    await hass.async_block_till_done()
+
+    assert \
+        "Exception in bad_handler when dispatching 'test': ('bad',)" \
+        in caplog.text