Publish errors on the event bus (#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 @@ import voluptuous as vol
 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 @@ DEFAULT_MAX_ENTRIES = 50
 DEPENDENCIES = ['http']
 DOMAIN = 'system_log'
 
+EVENT_SYSTEM_LOG = 'system_log_event'
+
 SERVICE_CLEAR = 'clear'
 SERVICE_WRITE = 'write'
 
@@ -46,67 +49,6 @@ SERVICE_WRITE_SCHEMA = vol.Schema({
 })
 
 
-class LogErrorHandler(logging.Handler):
-    """Log handler for error messages."""
-
-    def __init__(self, maxlen):
-        """Initialize a new LogErrorHandler."""
-        super().__init__()
-        self.records = deque(maxlen=maxlen)
-
-    def emit(self, record):
-        """Save error and warning logs.
-
-        Everything logged with error or warning is saved in local buffer. A
-        default upper limit is set to 50 (older entries are discarded) but can
-        be changed if needed.
-        """
-        if record.levelno >= logging.WARN:
-            stack = []
-            if not record.exc_info:
-                try:
-                    stack = [f for f, _, _, _ in traceback.extract_stack()]
-                except ValueError:
-                    # On Python 3.4 under py.test getting the stack might fail.
-                    pass
-            self.records.appendleft([record, stack])
-
-
-@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))
-    logging.getLogger().addHandler(handler)
-
-    hass.http.register_view(AllErrorsView(handler))
-
-    @asyncio.coroutine
-    def async_service_handler(service):
-        """Handle logger services."""
-        if service.service == 'clear':
-            handler.records.clear()
-            return
-        if service.service == 'write':
-            logger = logging.getLogger(
-                service.data.get(CONF_LOGGER, '{}.external'.format(__name__)))
-            level = service.data[CONF_LEVEL]
-            getattr(logger, level)(service.data[CONF_MESSAGE])
-
-    hass.services.async_register(
-        DOMAIN, SERVICE_CLEAR, async_service_handler,
-        schema=SERVICE_CLEAR_SCHEMA)
-    hass.services.async_register(
-        DOMAIN, SERVICE_WRITE, async_service_handler,
-        schema=SERVICE_WRITE_SCHEMA)
-
-    return True
-
-
 def _figure_out_source(record, call_stack, hass):
     paths = [HOMEASSISTANT_PATH[0], hass.config.config_dir]
     try:
@@ -151,14 +93,86 @@ def _exception_as_string(exc_info):
     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 LogErrorHandler(logging.Handler):
+    """Log handler for error messages."""
+
+    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.
+
+        Everything logged with error or warning is saved in local buffer. A
+        default upper limit is set to 50 (older entries are discarded) but can
+        be changed if needed.
+        """
+        if record.levelno >= logging.WARN:
+            stack = []
+            if not record.exc_info:
+                try:
+                    stack = [f for f, _, _, _ in traceback.extract_stack()]
+                except ValueError:
+                    # On Python 3.4 under py.test getting the stack might fail.
+                    pass
+
+            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(hass, conf.get(CONF_MAX_ENTRIES))
+    logging.getLogger().addHandler(handler)
+
+    hass.http.register_view(AllErrorsView(handler))
+
+    @asyncio.coroutine
+    def async_service_handler(service):
+        """Handle logger services."""
+        if service.service == 'clear':
+            handler.records.clear()
+            return
+        if service.service == 'write':
+            logger = logging.getLogger(
+                service.data.get(CONF_LOGGER, '{}.external'.format(__name__)))
+            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)
+    hass.services.async_register(
+        DOMAIN, SERVICE_WRITE, async_service_handler,
+        schema=SERVICE_WRITE_SCHEMA)
+
+    return True
 
 
 class AllErrorsView(HomeAssistantView):
@@ -174,5 +188,6 @@ class AllErrorsView(HomeAssistantView):
     @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 @@ from unittest.mock import MagicMock, patch
 
 import pytest
 
+from homeassistant.core import callback
 from homeassistant.bootstrap import async_setup_component
 from homeassistant.components import system_log
 
@@ -13,7 +14,7 @@ _LOGGER = logging.getLogger('test_logger')
 
 @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,10 +209,10 @@ 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'
 
@@ -200,9 +220,8 @@ def test_homeassistant_path(hass, test_client):
 @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'
 
@@ -210,9 +229,8 @@ def test_config_path(hass, test_client):
 @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'