From dea9aec268ac805dee7b997fe9641258f6ff1d9a Mon Sep 17 00:00:00 2001
From: Paulus Schoutsen <paulus@paulusschoutsen.nl>
Date: Sat, 8 Apr 2017 14:53:32 -0700
Subject: [PATCH] Warn if start takes a long time. (#6975)

* Warn if start takes a long time.

* ps - cleanup

* Tweak message

* Add tests

* Tweak messagE
---
 homeassistant/core.py | 16 +++++++++++++++-
 tests/test_core.py    | 43 +++++++++++++++++++++++++++++++++++++++++++
 2 files changed, 58 insertions(+), 1 deletion(-)

diff --git a/homeassistant/core.py b/homeassistant/core.py
index ba19f392931..899bed064ed 100644
--- a/homeassistant/core.py
+++ b/homeassistant/core.py
@@ -18,6 +18,7 @@ from time import monotonic
 from types import MappingProxyType
 from typing import Optional, Any, Callable, List  # NOQA
 
+from async_timeout import timeout
 import voluptuous as vol
 from voluptuous.humanize import humanize_error
 
@@ -49,6 +50,8 @@ ENTITY_ID_PATTERN = re.compile(r"^(\w+)\.(\w+)$")
 # Size of a executor pool
 EXECUTOR_POOL_SIZE = 10
 
+# How long to wait till things that run on startup have to finish.
+TIMEOUT_EVENT_START = 15
 
 _LOGGER = logging.getLogger(__name__)
 
@@ -159,7 +162,18 @@ class HomeAssistant(object):
         # pylint: disable=protected-access
         self.loop._thread_ident = threading.get_ident()
         self.bus.async_fire(EVENT_HOMEASSISTANT_START)
-        yield from self.async_stop_track_tasks()
+
+        try:
+            with timeout(TIMEOUT_EVENT_START, loop=self.loop):
+                yield from self.async_stop_track_tasks()
+        except asyncio.TimeoutError:
+            _LOGGER.warning(
+                'Something is blocking Home Assistant from wrapping up the '
+                'start up phase. We\'re going to continue anyway. Please '
+                'report the following info at http://bit.ly/2ogP58T : %s',
+                ', '.join(self.config.components))
+            self._track_task = False
+
         self.state = CoreState.running
         _async_create_timer(self)
 
diff --git a/tests/test_core.py b/tests/test_core.py
index ea7f40aaff7..b2fca047292 100644
--- a/tests/test_core.py
+++ b/tests/test_core.py
@@ -5,6 +5,7 @@ import unittest
 from unittest.mock import patch, MagicMock, sentinel
 from datetime import datetime, timedelta
 
+import logging
 import pytz
 import pytest
 
@@ -867,3 +868,45 @@ def test_timer_out_of_sync(mock_monotonic, loop):
     assert slp_seconds == 1
     assert callback is fire_time_event
     assert abs(nxt - 12.3) < 0.001
+
+
+@asyncio.coroutine
+def test_hass_start_starts_the_timer(loop):
+    """Test when hass starts, it starts the timer."""
+    hass = ha.HomeAssistant(loop=loop)
+
+    try:
+        with patch('homeassistant.core._async_create_timer') as mock_timer:
+            yield from hass.async_start()
+
+        assert hass.state == ha.CoreState.running
+        assert not hass._track_task
+        assert len(mock_timer.mock_calls) == 1
+        assert mock_timer.mock_calls[0][1][0] is hass
+
+    finally:
+        yield from hass.async_stop()
+        assert hass.state == ha.CoreState.not_running
+
+
+@asyncio.coroutine
+def test_start_taking_too_long(loop, caplog):
+    """Test when async_start takes too long."""
+    hass = ha.HomeAssistant(loop=loop)
+    caplog.set_level(logging.WARNING)
+
+    try:
+        with patch('homeassistant.core.timeout',
+                   side_effect=asyncio.TimeoutError), \
+             patch('homeassistant.core._async_create_timer') as mock_timer:
+            yield from hass.async_start()
+
+        assert not hass._track_task
+        assert hass.state == ha.CoreState.running
+        assert len(mock_timer.mock_calls) == 1
+        assert mock_timer.mock_calls[0][1][0] is hass
+        assert 'Something is blocking Home Assistant' in caplog.text
+
+    finally:
+        yield from hass.async_stop()
+        assert hass.state == ha.CoreState.not_running