Bugfix async log handler (#4954)

* Bugfix async log handler

* fix boostrap test

* Use hass.data for store handler and cleanup on async_stop

* Update bootstrap.py

homeassistant/bootstrap.py

@@ -529,6 +529,10 @@ def enable_logging(hass: core.HomeAssistant, verbose: bool=False,
     except ImportError:
         pass
 
+    # AsyncHandler allready exists?
+    if hass.data.get(core.DATA_ASYNCHANDLER):
+        return
+
     # Log errors to a file if we have write access to file or config dir
     err_log_path = hass.config.path(ERROR_LOG_FILENAME)
     err_path_exists = os.path.isfile(err_log_path)
@@ -551,6 +555,7 @@ def enable_logging(hass: core.HomeAssistant, verbose: bool=False,
                               datefmt='%y-%m-%d %H:%M:%S'))
 
         async_handler = AsyncHandler(hass.loop, err_handler)
+        hass.data[core.DATA_ASYNCHANDLER] = async_handler
 
         logger = logging.getLogger('')
         logger.addHandler(async_handler)

homeassistant/core.py

@@ -57,8 +57,8 @@ ENTITY_ID_PATTERN = re.compile(r"^(\w+)\.(\w+)$")
 # Size of a executor pool
 EXECUTOR_POOL_SIZE = 10
 
-# Time for cleanup internal pending tasks
+# AsyncHandler for logging
-TIME_INTERVAL_TASKS_CLEANUP = 10
+DATA_ASYNCHANDLER = 'log_asynchandler'
 
 _LOGGER = logging.getLogger(__name__)
 
@@ -294,6 +294,14 @@ class HomeAssistant(object):
         yield from self.async_block_till_done()
         self.executor.shutdown()
         self.state = CoreState.not_running
+
+        # cleanup async layer from python logging
+        if self.data.get(DATA_ASYNCHANDLER):
+            handler = self.data.pop(DATA_ASYNCHANDLER)
+            logger = logging.getLogger('')
+            handler.close()
+            logger.removeHandler(handler)
+
         self.loop.stop()
 
     # pylint: disable=no-self-use

homeassistant/scripts/check_config.py

@@ -231,7 +231,8 @@ def check(config_path):
     yaml.yaml.SafeLoader.add_constructor('!secret', yaml._secret_yaml)
 
     try:
-        bootstrap.from_config_file(config_path, skip_pip=True)
+        with patch('homeassistant.util.logging.AsyncHandler._process'):
+            bootstrap.from_config_file(config_path, skip_pip=True)
         res['secret_cache'] = dict(yaml.__SECRET_CACHE)
     except Exception as err:  # pylint: disable=broad-except
         print(color('red', 'Fatal error while loading config:'), str(err))

homeassistant/util/logging.py

@@ -43,15 +43,12 @@ class AsyncHandler(object):
         self.handleError = handler.handleError
         self.format = handler.format
 
+        self._thread.start()
+
     def close(self):
         """Wrap close to handler."""
         self.emit(None)
 
-    def open(self):
-        """Wrap open to handler."""
-        self._thread.start()
-        self.handler.open()
-
     def emit(self, record):
         """Process a record."""
         ident = self.loop.__dict__.get("_thread_ident")

tests/test_bootstrap.py

@@ -70,6 +70,8 @@ class TestBootstrap:
 
         with mock.patch('os.path.isfile', mock.Mock(return_value=True)), \
                 mock.patch('os.access', mock.Mock(return_value=True)), \
+                mock.patch('homeassistant.bootstrap.enable_logging',
+                           mock.Mock(return_value=True)), \
                 patch_yaml_files(files, True):
             self.hass = bootstrap.from_config_file('config.yaml')
 
@@ -286,7 +288,8 @@ class TestBootstrap:
         assert not bootstrap.setup_component(self.hass, 'comp', {})
         assert 'comp' not in self.hass.config.components
 
-    def test_home_assistant_core_config_validation(self):
+    @mock.patch('homeassistant.bootstrap.enable_logging')
+    def test_home_assistant_core_config_validation(self, log_mock):
         """Test if we pass in wrong information for HA conf."""
         # Extensive HA conf validation testing is done in test_config.py
         assert None is bootstrap.from_config_dict({