Publish errors on the event bus (home-assistant#11964)

* Publish errors on the event bus

* Add block till done to test.

* Update test_system_log.py

* Remove old logger handlers

homeassistant/components/system_log/__init__.py

@@ -16,6 +16,7 @@
 from homeassistant import __path__ as HOMEASSISTANT_PATH
 from homeassistant.components.http import HomeAssistantView
 import homeassistant.helpers.config_validation as cv
+from homeassistant.const import EVENT_HOMEASSISTANT_STOP
 
 CONF_MAX_ENTRIES = 'max_entries'
 CONF_MESSAGE = 'message'
@@ -27,6 +28,8 @@
 DEPENDENCIES = ['http']
 DOMAIN = 'system_log'
 
+EVENT_SYSTEM_LOG = 'system_log_event'
+
 SERVICE_CLEAR = 'clear'
 SERVICE_WRITE = 'write'
 
@@ -46,14 +49,68 @@
 })
 
 
+def _figure_out_source(record, call_stack, hass):
+    paths = [HOMEASSISTANT_PATH[0], hass.config.config_dir]
+    try:
+        # If netdisco is installed check its path too.
+        from netdisco import __path__ as netdisco_path
+        paths.append(netdisco_path[0])
+    except ImportError:
+        pass
+    # If a stack trace exists, extract file names from the entire call stack.
+    # The other case is when a regular "log" is made (without an attached
+    # exception). In that case, just use the file where the log was made from.
+    if record.exc_info:
+        stack = [x[0] for x in traceback.extract_tb(record.exc_info[2])]
+    else:
+        index = -1
+        for i, frame in enumerate(call_stack):
+            if frame == record.pathname:
+                index = i
+                break
+        if index == -1:
+            # For some reason we couldn't find pathname in the stack.
+            stack = [record.pathname]
+        else:
+            stack = call_stack[0:index+1]
+
+    # Iterate through the stack call (in reverse) and find the last call from
+    # a file in Home Assistant. Try to figure out where error happened.
+    for pathname in reversed(stack):
+
+        # Try to match with a file within Home Assistant
+        match = re.match(r'(?:{})/(.*)'.format('|'.join(paths)), pathname)
+        if match:
+            return match.group(1)
+    # Ok, we don't know what this is
+    return record.pathname
+
+
+def _exception_as_string(exc_info):
+    buf = StringIO()
+    if exc_info:
+        traceback.print_exception(*exc_info, file=buf)
+    return buf.getvalue()
+
+
 class LogErrorHandler(logging.Handler):
     """Log handler for error messages."""
 
-    def __init__(self, maxlen):
+    def __init__(self, hass, maxlen):
         """Initialize a new LogErrorHandler."""
         super().__init__()
+        self.hass = hass
         self.records = deque(maxlen=maxlen)
 
+    def _create_entry(self, record, call_stack):
+        return {
+            'timestamp': record.created,
+            'level': record.levelname,
+            'message': record.getMessage(),
+            'exception': _exception_as_string(record.exc_info),
+            'source': _figure_out_source(record, call_stack, self.hass),
+            }
+
     def emit(self, record):
         """Save error and warning logs.
 
@@ -69,18 +126,20 @@ def emit(self, record):
                 except ValueError:
                     # On Python 3.4 under py.test getting the stack might fail.
                     pass
-            self.records.appendleft([record, stack])
+
+            entry = self._create_entry(record, stack)
+            self.records.appendleft(entry)
+            self.hass.bus.fire(EVENT_SYSTEM_LOG, entry)
 
 
 @asyncio.coroutine
 def async_setup(hass, config):
     """Set up the logger component."""
     conf = config.get(DOMAIN)
-
     if conf is None:
         conf = CONFIG_SCHEMA({DOMAIN: {}})[DOMAIN]
 
-    handler = LogErrorHandler(conf.get(CONF_MAX_ENTRIES))
+    handler = LogErrorHandler(hass, conf.get(CONF_MAX_ENTRIES))
     logging.getLogger().addHandler(handler)
 
     hass.http.register_view(AllErrorsView(handler))
@@ -97,6 +156,15 @@ def async_service_handler(service):
             level = service.data[CONF_LEVEL]
             getattr(logger, level)(service.data[CONF_MESSAGE])
 
+    @asyncio.coroutine
+    def async_shutdown_handler(event):
+        """Remove logging handler when Home Assistant is shutdown."""
+        # This is needed as older logger instances will remain
+        logging.getLogger().removeHandler(handler)
+
+    hass.bus.async_listen_once(EVENT_HOMEASSISTANT_STOP,
+                               async_shutdown_handler)
+
     hass.services.async_register(
         DOMAIN, SERVICE_CLEAR, async_service_handler,
         schema=SERVICE_CLEAR_SCHEMA)
@@ -107,60 +175,6 @@ def async_service_handler(service):
     return True
 
 
-def _figure_out_source(record, call_stack, hass):
-    paths = [HOMEASSISTANT_PATH[0], hass.config.config_dir]
-    try:
-        # If netdisco is installed check its path too.
-        from netdisco import __path__ as netdisco_path
-        paths.append(netdisco_path[0])
-    except ImportError:
-        pass
-    # If a stack trace exists, extract file names from the entire call stack.
-    # The other case is when a regular "log" is made (without an attached
-    # exception). In that case, just use the file where the log was made from.
-    if record.exc_info:
-        stack = [x[0] for x in traceback.extract_tb(record.exc_info[2])]
-    else:
-        index = -1
-        for i, frame in enumerate(call_stack):
-            if frame == record.pathname:
-                index = i
-                break
-        if index == -1:
-            # For some reason we couldn't find pathname in the stack.
-            stack = [record.pathname]
-        else:
-            stack = call_stack[0:index+1]
-
-    # Iterate through the stack call (in reverse) and find the last call from
-    # a file in Home Assistant. Try to figure out where error happened.
-    for pathname in reversed(stack):
-
-        # Try to match with a file within Home Assistant
-        match = re.match(r'(?:{})/(.*)'.format('|'.join(paths)), pathname)
-        if match:
-            return match.group(1)
-    # Ok, we don't know what this is
-    return record.pathname
-
-
-def _exception_as_string(exc_info):
-    buf = StringIO()
-    if exc_info:
-        traceback.print_exception(*exc_info, file=buf)
-    return buf.getvalue()
-
-
-def _convert(record, call_stack, hass):
-    return {
-        'timestamp': record.created,
-        'level': record.levelname,
-        'message': record.getMessage(),
-        'exception': _exception_as_string(record.exc_info),
-        'source': _figure_out_source(record, call_stack, hass),
-        }
-
-
 class AllErrorsView(HomeAssistantView):
     """Get all logged errors and warnings."""
 
@@ -174,5 +188,6 @@ def __init__(self, handler):
     @asyncio.coroutine
     def get(self, request):
         """Get all errors and warnings."""
-        return self.json([_convert(x[0], x[1], request.app['hass'])
-                          for x in self.handler.records])
+        # deque is not serializable (it's just "list-like") so it must be
+        # converted to a list before it can be serialized to json
+        return self.json(list(self.handler.records))

tests/components/test_system_log.py

@@ -5,6 +5,7 @@
 
 import pytest
 
+from homeassistant.core import callback
 from homeassistant.bootstrap import async_setup_component
 from homeassistant.components import system_log
 
@@ -13,7 +14,7 @@
 
 @pytest.fixture(autouse=True)
 @asyncio.coroutine
-def setup_test_case(hass):
+def setup_test_case(hass, test_client):
     """Setup system_log component before test case."""
     config = {'system_log': {'max_entries': 2}}
     yield from async_setup_component(hass, system_log.DOMAIN, config)
@@ -85,6 +86,25 @@ def test_error(hass, test_client):
     assert_log(log, '', 'error message', 'ERROR')
 
 
+@asyncio.coroutine
+def test_error_posted_as_event(hass, test_client):
+    """Test that error are posted as events."""
+    events = []
+
+    @callback
+    def event_listener(event):
+        """Listen to events of type system_log_event."""
+        events.append(event)
+
+    hass.bus.async_listen(system_log.EVENT_SYSTEM_LOG, event_listener)
+
+    _LOGGER.error('error message')
+    yield from hass.async_block_till_done()
+
+    assert len(events) == 1
+    assert_log(events[0].data, '', 'error message', 'ERROR')
+
+
 @asyncio.coroutine
 def test_critical(hass, test_client):
     """Test that critical are logged and retrieved correctly."""
@@ -189,30 +209,28 @@ def log_error_from_test_path(path):
 @asyncio.coroutine
 def test_homeassistant_path(hass, test_client):
     """Test error logged from homeassistant path."""
-    log_error_from_test_path('venv_path/homeassistant/component/component.py')
-
     with patch('homeassistant.components.system_log.HOMEASSISTANT_PATH',
                new=['venv_path/homeassistant']):
+        log_error_from_test_path(
+            'venv_path/homeassistant/component/component.py')
         log = (yield from get_error_log(hass, test_client, 1))[0]
     assert log['source'] == 'component/component.py'
 
 
 @asyncio.coroutine
 def test_config_path(hass, test_client):
     """Test error logged from config path."""
-    log_error_from_test_path('config/custom_component/test.py')
-
     with patch.object(hass.config, 'config_dir', new='config'):
+        log_error_from_test_path('config/custom_component/test.py')
         log = (yield from get_error_log(hass, test_client, 1))[0]
     assert log['source'] == 'custom_component/test.py'
 
 
 @asyncio.coroutine
 def test_netdisco_path(hass, test_client):
     """Test error logged from netdisco path."""
-    log_error_from_test_path('venv_path/netdisco/disco_component.py')
-
     with patch.dict('sys.modules',
                     netdisco=MagicMock(__path__=['venv_path/netdisco'])):
+        log_error_from_test_path('venv_path/netdisco/disco_component.py')
         log = (yield from get_error_log(hass, test_client, 1))[0]
     assert log['source'] == 'disco_component.py'