Boot delays

Configuration
1

Been using HA for quite a while now and all working fine. I’ve noticed recently that restarting HA seems to take ages. At one point, the boot sequence seems to just pause. The log file doesn’t say much at all before or after this delay, but it does seem to continue after about 4 mins:

* 2021-08-26 20:49:25 ERROR (MainThread) [homeassistant] Error doing job: Task was destroyed but it is pending!
* 2021-08-26 20:53:20 WARNING (MainThread) [homeassistant.bootstrap] Setup timed out for bootstrap - moving forward

Any ideas how to start diagnosing what could be causing this?

From HA itself, it seems that light groups are not being setup until the boot continues - this could be coincidental, or could be related to it.

p.s. I’m running Home Assistant 2021.8.8 in a docker container.

Thanks

2

This is not related to your specific error message but you might want to check the size of your home-assistant_v2.db file as this used to cause increasing delays on restart (due to database checks) with the database growing over time as historic data is accumulated.

If this is file several MB’s or more (depending on you hardware) then you can consider the following:

  1. Use ‘Recorder: Purge’ under Developer Tools - Services to reduce the size of the database.

  2. Consider reducing ‘purge_keep_days’ in Recorder to prevent the database growing too large.

  3. Make use of the ‘exclude’ option in Recorder to exclude entities that you do not need to track (I expect that analogue data takes up much more storage space than binary data).

  4. Move long term data to another package that it better suited for long-term data retention e.g. Influxdb

1 Like
3

Thanks, but it’s not that. Recorder is configured properly and I’m using MariaDB but the database.

4

Have a look at Configuration - Information, then scroll down to see if any particular integration is particularly slow to start up. You can then reload or remove this integration to see if it makes any difference.

Other than that have a look through the full HA lof in the \config folder. Increasing the log level above the default ‘warning’ level might shed more light on the problem.

5

Hmmm. Still not much further forward. Nothing unusual in the Config->Info section that stands out. Turning on additional logging doesn’t show much either (here’s an extract for bootstrap logs):

2021-08-27 16:37:37 DEBUG (MainThread) [homeassistant.bootstrap] Integration remaining: {'alexa_media': 5.672771, 'harmony': 4.616209, 'device_tracker': 4.532456, 'device_tracker.icloud3': 3.997623}
2021-08-27 16:37:38 DEBUG (MainThread) [homeassistant.bootstrap] Running timeout Zones: {'proximity': <proximity: 0 / 1>, 'ios': <ios: 0 / 1>, 'sensor': <sensor: 1 / 0>, 'device_tracker': <device_tracker: 1 / 0>}
2021-08-27 16:37:38 DEBUG (MainThread) [homeassistant.bootstrap] Integration remaining: {'alexa_media': 6.674281, 'harmony': 5.617719, 'device_tracker': 5.533966, 'device_tracker.icloud3': 4.999133}
2021-08-27 16:37:39 DEBUG (MainThread) [homeassistant.bootstrap] Running timeout Zones: {'proximity': <proximity: 0 / 1>, 'ios': <ios: 0 / 1>, 'device_tracker': <device_tracker: 1 / 0>}
2021-08-27 16:37:39 DEBUG (MainThread) [homeassistant.bootstrap] Integration remaining: {'alexa_media': 7.675957, 'harmony': 6.619395, 'device_tracker': 6.535642, 'device_tracker.icloud3': 6.000809}
2021-08-27 16:37:40 DEBUG (MainThread) [homeassistant.bootstrap] Running timeout Zones: {}
2021-08-27 16:37:40 DEBUG (MainThread) [homeassistant.bootstrap] Integration remaining: {'alexa_media': 8.677034, 'harmony': 7.620472}
2021-08-27 16:37:41 DEBUG (MainThread) [homeassistant.bootstrap] Running timeout Zones: {'media_player': <media_player: 1 / 0>}
2021-08-27 16:37:41 DEBUG (MainThread) [homeassistant.bootstrap] Integration remaining: {'harmony': 8.62231, 'media_player.alexa_media': 0.95535}
2021-08-27 16:37:42 DEBUG (MainThread) [homeassistant.bootstrap] Running timeout Zones: {}
2021-08-27 16:37:42 DEBUG (MainThread) [homeassistant.bootstrap] Integration remaining: {'harmony': 9.623933}
2021-08-27 16:37:43 DEBUG (MainThread) [homeassistant.bootstrap] Running timeout Zones: {}
2021-08-27 16:37:43 DEBUG (MainThread) [homeassistant.bootstrap] Integration remaining: {'harmony': 10.625789}
2021-08-27 16:37:44 DEBUG (MainThread) [homeassistant.bootstrap] Running timeout Zones: {}
2021-08-27 16:37:44 DEBUG (MainThread) [homeassistant.bootstrap] Integration remaining: {'harmony': 11.6272}
2021-08-27 16:37:45 DEBUG (MainThread) [homeassistant.bootstrap] Running timeout Zones: {}
2021-08-27 16:37:45 DEBUG (MainThread) [homeassistant.bootstrap] Integration remaining: {'harmony': 12.627861}
2021-08-27 16:37:46 DEBUG (MainThread) [homeassistant.bootstrap] Running timeout Zones: {}
2021-08-27 16:37:46 DEBUG (MainThread) [homeassistant.bootstrap] Integration remaining: {'harmony': 13.630006}
2021-08-27 16:37:47 DEBUG (MainThread) [homeassistant.bootstrap] Running timeout Zones: {}
2021-08-27 16:37:47 DEBUG (MainThread) [homeassistant.bootstrap] Integration remaining: {'harmony': 14.70478}
2021-08-27 16:37:48 DEBUG (MainThread) [homeassistant.bootstrap] Running timeout Zones: {}
2021-08-27 16:37:48 DEBUG (MainThread) [homeassistant.bootstrap] Integration remaining: {'harmony': 15.706093}
2021-08-27 16:37:48 DEBUG (MainThread) [homeassistant.bootstrap] Integration setup times: {'search': 0.000652, 'system_log': 0.000778, 'lock': 0.001192, 'onboarding': 0.001537, 'binary_sensor': 0.001684, 'logger': 0.001719, 'websocket_api': 0.002802, 'frontend': 0.003015, 'weather': 0.003445, 'water_heater': 0.003818, 'ssdp': 0.006781, 'stt': 0.007018, 'cover': 0.008568, 'sensor': 0.009198, 'stream': 0.01068, 'api': 0.015943, 'discovery': 0.016401, 'auth': 0.017623, 'device_automation': 0.021094, 'ios': 0.02122, 'webhook': 0.021813, 'proximity': 0.023062, 'image': 0.028051, 'calendar': 0.040788, 'script': 0.045389, 'config': 0.047712, 'lovelace': 0.051007, 'analytics': 0.068727, 'my': 0.072116, 'map': 0.073286, 'blueprint': 0.074629, 'remote': 0.078052, 'homekit': 0.079763, 'alarm_control_panel': 0.08903, 'light': 0.102743, 'media_player': 0.106605, 'workday': 0.134995, 'person': 0.140371, 'pushover': 0.190281, 'network': 0.194056, 'camera': 0.197457, 'trace': 0.202544, 'owntracks': 0.225003, 'shell_command': 0.269743, 'default_config': 0.275953, 'sun': 0.280903, 'generic': 0.284093, 'http': 0.302423, 'switch': 0.311467, 'logbook': 0.347965, 'zeroconf': 0.350519, 'time_date': 0.365305, 'uptime': 0.365865, 'notify': 0.372781, 'recorder': 0.375052, 'climate': 0.381464, 'system_health': 0.407317, 'tag': 0.409889, 'ffmpeg': 0.481102, 'nodered': 0.494966, 'history': 0.500318, 'dhcp': 0.509624, 'updater': 0.553603, 'tts': 0.672217, 'energy': 0.70327, 'generic_thermostat': 0.704501, 'scene': 0.722153, 'input_datetime': 0.74089, 'enigma2': 0.768618, 'input_number': 0.821794, 'flux_led': 0.898385, 'timer': 0.966231, 'manual': 1.150902, 'counter': 1.169613, 'input_text': 1.204267, 'scheduler': 1.300522, 'zone': 1.462671, 'lightwave': 1.479644, 'tuya': 1.551893, 'input_select': 1.626707, 'group': 1.690342, 'media_source': 1.699321, 'template': 1.752262, 'plex': 1.838292, 'openweathermap': 1.928058, 'hue': 1.947386, 'arpscan_tracker': 1.974789, 'eufy_security': 1.979342, 'version': 2.022487, 'broadlink': 2.023993, 'ping': 2.024792, 'ipp': 2.044279, 'androidtv': 2.050391, 'climacell': 2.208767, 'braviatv': 2.283331, 'input_boolean': 2.328684, 'mobile_app': 2.515749, 'ziggonext': 2.594596, 'monitor_docker': 2.646572, 'automation': 2.879844, 'google': 3.138519, 'rest': 3.503247, 'cloud': 3.580867, 'hacs': 3.966496, 'darksky': 4.07113, 'mbapi2020': 4.363407, 'homeassistant': 4.63356, 'glances': 4.68357, 'mqtt': 4.863663, 'tado': 5.214895, 'pi_hole': 6.502339, 'icloud3': 6.844075, 'device_tracker': 7.423365, 'alexa_media': 10.485473, 'harmony': 16.25505}
2021-08-27 16:37:48 DEBUG (MainThread) [homeassistant.bootstrap] Waiting for startup to wrap up
2021-08-27 16:42:48 WARNING (MainThread) [homeassistant.bootstrap] Setup timed out for bootstrap - moving forward
2021-08-27 16:42:48 INFO (MainThread) [homeassistant.bootstrap] Home Assistant initialized in 331.35s

It doesn’t seem to show what it’s waiting on or what times-out…

6

I see lots of references to ‘harmony’ in the logs - do you have a Logitech Harmony Hub which might be causing the problem?

Apart from that I don’t know what else to suggest so probably bes to wait and see what others can come up with.

7

I do have a Harmony, but I’ve just tried disabling that integration and restarting and no change, so it’s not that one.

8

I’m having same exact delayed startup. I spotted icloud3 custom component in your log. I too am running the same custom_component and have been troubleshooting it with @gcobb321 for a bit. Try commenting out the icloud3 device tracker from config.yaml and restart and see if it starts fast/normal.

Notice in the snip below the last 3 log lines and the timestamps. After the device_tracker 300 second timeout, bootstrap waits another 300 seconds before timing out. Total startup time - 605 seconds.

I have a hunch this startup delay/timeouts are causing issues/race conditions with the icloud3 component startup logic.

I’ve reproduced this on a clean VM running the 2021.9.x but also have seen the problem on 2021.8.x. I don’t have anything else running on the environment.

2021-09-07 11:49:55 INFO (MainThread) [homeassistant.bootstrap] Setting up stage 1: {'cloud', 'person', 'onboarding', 'system_log', 'device_automation', 'websocket_api', 'http', 'lovelace', 'search', 'analytics', 'image', 'api', 'webhook', 'auth', 'hassio', 'config', 'frontend'}
2021-09-07 11:49:55 DEBUG (MainThread) [homeassistant.bootstrap] Running timeout Zones: {'cloud': <cloud: 0 / 1>, 'person': <person: 0 / 1>, 'onboarding': <onboarding: 0 / 1>, 'lovelace': <lovelace: 1 / 0>, 'analytics': <analytics: 0 / 1>, 'hassio': <hassio: 1 / 0>, 'frontend': <frontend: 0 / 1>, 'image': <image: 1 / 0>}
2021-09-07 11:49:55 DEBUG (MainThread) [homeassistant.bootstrap] Integration remaining: {'lovelace': 0.662267, 'hassio': 0.631032, 'config': 0.620144, 'search': 0.39171, 'image': 0.001515}
2021-09-07 11:49:56 DEBUG (MainThread) [homeassistant.bootstrap] Running timeout Zones: {'onboarding': <onboarding: 0 / 1>, 'hassio': <hassio: 1 / 0>, 'frontend': <frontend: 0 / 1>, 'person': <person: 2 / 0>, 'cloud': <cloud: 1 / 0>}
2021-09-07 11:49:56 DEBUG (MainThread) [homeassistant.bootstrap] Integration remaining: {'hassio': 1.684718, 'person': 0.875192, 'cloud': 0.002089}
2021-09-07 11:49:57 INFO (MainThread) [homeassistant.bootstrap] Setting up stage 2: {'tts', 'tag', 'script', 'input_select', 'wled', 'updater', 'trace', 'device_tracker', 'group', 'map', 'usb', 'blueprint', 'scene', 'network', 'zeroconf', 'input_number', 'media_source', 'counter', 'timer', 'system_health', 'input_boolean', 'mobile_app', 'automation', 'dhcp', 'input_datetime', 'zone', 'history', 'logbook', 'sun', 'ssdp', 'esphome', 'input_text', 'energy', 'my', 'default_config'}
2021-09-07 11:49:58 DEBUG (MainThread) [homeassistant.bootstrap] Running timeout Zones: {'tts': <tts: 0 / 1>, 'tag': <tag: 1 / 0>, 'script': <script: 0 / 1>, 'input_select': <input_select: 1 / 0>, 'wled': <wled: 0 / 1>, 'device_tracker': <device_tracker: 0 / 1>, 'group': <group: 1 / 0>, 'usb': <usb: 0 / 1>, 'scene': <scene: 2 / 0>, 'network': <network: 0 / 1>, 'zeroconf': <zeroconf: 0 / 1>, 'input_number': <input_number: 1 / 0>, 'media_source': <media_source: 1 / 0>, 'counter': <counter: 1 / 0>, 'timer': <timer: 1 / 0>, 'system_health': <system_health: 1 / 0>, 'input_boolean': <input_boolean: 1 / 0>, 'mobile_app': <mobile_app: 0 / 1>, 'automation': <automation: 0 / 1>, 'input_datetime': <input_datetime: 1 / 0>, 'zone': <zone: 1 / 0>, 'logbook': <logbook: 1 / 0>, 'ssdp': <ssdp: 0 / 1>, 'esphome': <esphome: 0 / 1>, 'input_text': <input_text: 1 / 0>, 'energy': <energy: 0 / 1>, 'default_config': <default_config: 0 / 1>}
2021-09-07 11:49:58 DEBUG (MainThread) [homeassistant.bootstrap] Integration remaining: {'tag': 1.637401, 'input_select': 1.636359, 'group': 1.615744, 'scene': 1.603616, 'scene.homeassistant': 1.603149, 'input_number': 1.602269, 'media_source': 1.559125, 'counter': 1.546184, 'timer': 1.545182, 'system_health': 1.544257, 'input_boolean': 1.543468, 'input_datetime': 0.162763, 'zone': 0.162186, 'logbook': 0.133005, 'input_text': 0.072012, 'sensor': 0.009625, 'binary_sensor': 0.007233}
2021-09-07 11:49:59 DEBUG (MainThread) [homeassistant.components.websocket_api.http.connection] [139778701429872] Received {'type': 'subscribe_bootstrap_integrations', 'id': 58}
2021-09-07 11:49:59 DEBUG (MainThread) [homeassistant.bootstrap] Running timeout Zones: {'device_tracker': <device_tracker: 1 / 0>, 'sensor': <sensor: 1 / 0>, 'default_config': <default_config: 1 / 0>}
2021-09-07 11:49:59 DEBUG (MainThread) [homeassistant.bootstrap] Integration remaining: {'wled': 0.971901, 'device_tracker': 0.751532, 'device_tracker.icloud3': 0.659372, 'sensor.mobile_app': 0.606237, 'default_config': 0.016992}
2021-09-07 11:50:00 DEBUG (MainThread) [homeassistant.bootstrap] Running timeout Zones: {'device_tracker': <device_tracker: 1 / 0>}
2021-09-07 11:50:00 DEBUG (MainThread) [homeassistant.bootstrap] Integration remaining: {'device_tracker': 1.75267, 'device_tracker.icloud3': 1.66051}
2021-09-07 11:50:01 DEBUG (MainThread) [homeassistant.bootstrap] Running timeout Zones: {'device_tracker': <device_tracker: 1 / 0>}
2021-09-07 11:50:01 DEBUG (MainThread) [homeassistant.bootstrap] Integration remaining: {'device_tracker': 2.755229, 'device_tracker.icloud3': 2.663069}
2021-09-07 11:50:03 DEBUG (MainThread) [homeassistant.bootstrap] Running timeout Zones: {'device_tracker': <device_tracker: 1 / 0>}
2021-09-07 11:50:03 DEBUG (MainThread) [homeassistant.bootstrap] Integration remaining: {'device_tracker': 3.781756, 'device_tracker.icloud3': 3.689596}
2021-09-07 11:54:57 DEBUG (MainThread) [homeassistant.bootstrap] Running timeout Zones: {'device_tracker': <device_tracker: 1 / 0>}

Above repeats for 300 seconds...

2021-09-07 11:54:57 DEBUG (MainThread) [homeassistant.bootstrap] Integration remaining: {'device_tracker': 298.720789, 'device_tracker.icloud3': 298.628629}
2021-09-07 11:54:58 DEBUG (MainThread) [homeassistant.bootstrap] Running timeout Zones: {'device_tracker': <device_tracker: 1 / 0>}
2021-09-07 11:54:58 DEBUG (MainThread) [homeassistant.bootstrap] Integration remaining: {'device_tracker': 299.721338, 'device_tracker.icloud3': 299.629178}
2021-09-07 11:54:59 DEBUG (MainThread) [homeassistant.bootstrap] Integration setup times: {'select': 0.001268, 'system_log': 0.001302, 'logger': 0.001397, 'stream': 0.004593, 'switch': 0.005894, 'notify': 0.010692, 'onboarding': 0.011393, 'usb': 0.01556, 'light': 0.024841, 'auth': 0.02712, 'webhook': 0.033371, 'cloud': 0.034243, 'api': 0.036845, 'automation': 0.037544, 'my': 0.039448, 'default_config': 0.054385, 'websocket_api': 0.063617, 'device_automation': 0.063843, 'frontend': 0.083648, 'image': 0.092947, 'script': 0.096987, 'analytics': 0.104347, 'ssdp': 0.105621, 'sun': 0.113886, 'history': 0.128164, 'binary_sensor': 0.128416, 'sensor': 0.130485, 'network': 0.142807, 'dhcp': 0.155552, 'zeroconf': 0.157783, 'energy': 0.25472, 'logbook': 0.297836, 'tts': 0.359669, 'input_text': 0.363913, 'search': 0.391904, 'esphome': 0.411711, 'http': 0.41928, 'recorder': 0.420148, 'input_datetime': 0.4545, 'zone': 0.472206, 'config': 0.697782, 'lovelace': 0.753953, 'person': 0.8895, 'mobile_app': 1.083791, 'wled': 1.226784, 'blueprint': 1.561571, 'map': 1.563358, 'trace': 1.565831, 'system_health': 1.708943, 'media_source': 1.723665, 'homeassistant': 1.751842, 'updater': 1.765326, 'scene': 1.767917, 'group': 1.779136, 'tag': 1.803146, 'input_boolean': 1.834971, 'timer': 1.836601, 'counter': 1.837506, 'input_number': 1.893463, 'input_select': 1.897238, 'hassio': 2.15011, 'device_tracker': 300.002439}
2021-09-07 11:54:59 DEBUG (MainThread) [homeassistant.bootstrap] Waiting for startup to wrap up
2021-09-07 11:59:59 WARNING (MainThread) [homeassistant.bootstrap] Setup timed out for bootstrap - moving forward
2021-09-07 11:59:59 INFO (MainThread) [homeassistant.bootstrap] Home Assistant initialized in 605.00s
9

Sorry - disabled iCloud3 on my setup and no difference, so must be a different issue.

10

I’ve found the cause of my startup delays - it’s the eufy security add-on. Disabling this and the delays go away.
Looks like there is already an issue raised for this here

11

Very interesting. I was convinced disabling iCloud3 would have fixed your startup delays. As it turns out I don’t have the eufy add-on installed so that’s not it for me.

So just to confirm, if you disable eufy with icloud3 enabled, HA starts correctly? No delays?

Do you mind if I ask if you’re using icloud3 with findmyfriends or familysharing enabled. IE, is it logging in to your icloud account with your appleid or are you only using it with the mobile_app integration?

12

Yep - iCloud3 works fine for me. I’m only using it with findmyfriends as all direct family phones have the HA iOS app on them.