62.0 blues... Not sure if this is a Hassio or Home Assistant problem

mattlward · February 1, 2018, 2:26am

Since the upgrade to 62.0 from 61.1, my system barely wants to start…

Here are my logs:

2018-01-31 20:09:08 WARNING (Recorder) [homeassistant.components.recorder] Ended unfinished session (id=14 from 2018-02-01 01:59:59.498942)
2018-01-31 20:09:19 WARNING (MainThread) [homeassistant.setup] Setup of mqtt is taking over 10 seconds.
2018-01-31 20:09:57 WARNING (MainThread) [homeassistant.setup] Setup of group is taking over 10 seconds.
2018-01-31 20:09:57 WARNING (MainThread) [homeassistant.setup] Setup of duckdns is taking over 10 seconds.
2018-01-31 20:09:57 WARNING (MainThread) [homeassistant.components.binary_sensor] Setup of platform ping is taking over 10 seconds.
2018-01-31 20:09:57 WARNING (MainThread) [homeassistant.components.sensor] Setup of platform uptime is taking over 10 seconds.
2018-01-31 20:09:57 WARNING (MainThread) [homeassistant.components.sensor] Setup of platform command_line is taking over 10 seconds.
2018-01-31 20:09:57 WARNING (MainThread) [homeassistant.components.sensor] Setup of platform command_line is taking over 10 seconds.
2018-01-31 20:09:57 WARNING (MainThread) [homeassistant.components.sensor] Setup of platform wunderground is taking over 10 seconds.
2018-01-31 20:09:57 WARNING (MainThread) [homeassistant.setup] Setup of logbook is taking over 10 seconds.
2018-01-31 20:09:57 WARNING (MainThread) [homeassistant.setup] Setup of history_graph is taking over 10 seconds.
2018-01-31 20:09:57 WARNING (MainThread) [homeassistant.setup] Setup of panel_iframe is taking over 10 seconds.
2018-01-31 20:09:57 WARNING (MainThread) [homeassistant.setup] Setup of config is taking over 10 seconds.
2018-01-31 20:09:57 WARNING (MainThread) [homeassistant.components.camera] Setup of platform generic is taking over 10 seconds.
2018-01-31 20:09:57 WARNING (MainThread) [homeassistant.components.camera] Setup of platform generic is taking over 10 seconds.
2018-01-31 20:09:57 WARNING (MainThread) [homeassistant.components.sensor] Setup of platform mqtt is taking over 10 seconds.
2018-01-31 20:09:57 WARNING (MainThread) [homeassistant.components.sensor] Setup of platform mqtt is taking over 10 seconds.
2018-01-31 20:09:57 WARNING (MainThread) [homeassistant.components.sensor] Setup of platform mqtt is taking over 10 seconds.
2018-01-31 20:09:57 WARNING (MainThread) [homeassistant.components.sensor] Setup of platform mqtt is taking over 10 seconds.
2018-01-31 20:09:57 WARNING (MainThread) [homeassistant.components.sensor] Setup of platform mqtt is taking over 10 seconds.
2018-01-31 20:09:57 WARNING (MainThread) [homeassistant.components.sensor] Setup of platform mqtt is taking over 10 seconds.
2018-01-31 20:09:57 WARNING (MainThread) [homeassistant.components.sensor] Setup of platform mqtt is taking over 10 seconds.
2018-01-31 20:09:57 WARNING (MainThread) [homeassistant.components.sensor] Setup of platform mqtt is taking over 10 seconds.
2018-01-31 20:09:57 WARNING (MainThread) [homeassistant.components.sensor] Setup of platform mqtt is taking over 10 seconds.
2018-01-31 20:09:57 WARNING (MainThread) [homeassistant.components.sensor] Setup of platform mqtt is taking over 10 seconds.
2018-01-31 20:09:57 WARNING (MainThread) [homeassistant.components.sensor] Setup of platform mqtt is taking over 10 seconds.
2018-01-31 20:09:57 WARNING (MainThread) [homeassistant.components.sensor] Setup of platform mqtt is taking over 10 seconds.
2018-01-31 20:09:57 WARNING (MainThread) [homeassistant.components.sensor] Setup of platform mqtt is taking over 10 seconds.
2018-01-31 20:09:57 WARNING (MainThread) [homeassistant.components.sensor] Setup of platform mqtt is taking over 10 seconds.
2018-01-31 20:09:58 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport TCPTransport (error status in uv_stream_t.shutdown callback)
OSError: [Errno 107] Socket not connected
2018-01-31 20:10:13 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport TCPTransport (error status in uv_stream_t.shutdown callback)
OSError: [Errno 107] Socket not connected
2018-01-31 20:10:27 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport TCPTransport (error status in uv_stream_t.shutdown callback)
OSError: [Errno 107] Socket not connected
2018-01-31 20:10:27 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport TCPTransport (error status in uv_stream_t.shutdown callback)
OSError: [Errno 107] Socket not connected
2018-01-31 20:10:27 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport TCPTransport (error status in uv_stream_t.shutdown callback)
OSError: [Errno 107] Socket not connected
2018-01-31 20:10:46 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport TCPTransport (error status in uv_stream_t.shutdown callback)
OSError: [Errno 107] Socket not connected
2018-01-31 20:10:46 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport TCPTransport (error status in uv_stream_t.shutdown callback)
OSError: [Errno 107] Socket not connected
2018-01-31 20:10:46 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport TCPTransport (error status in uv_stream_t.shutdown callback)
OSError: [Errno 107] Socket not connected
2018-01-31 20:10:46 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport TCPTransport (error status in uv_stream_t.shutdown callback)
OSError: [Errno 107] Socket not connected
2018-01-31 20:11:01 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport TCPTransport (error status in uv_stream_t.shutdown callback)
OSError: [Errno 107] Socket not connected
2018-01-31 20:11:01 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport TCPTransport (error status in uv_stream_t.shutdown callback)
OSError: [Errno 107] Socket not connected
2018-01-31 20:11:01 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport TCPTransport (error status in uv_stream_t.shutdown callback)
OSError: [Errno 107] Socket not connected
2018-01-31 20:11:01 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport TCPTransport (error status in uv_stream_t.shutdown callback)
OSError: [Errno 107] Socket not connected
2018-01-31 20:11:15 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport TCPTransport (error status in uv_stream_t.shutdown callback)
OSError: [Errno 107] Socket not connected
2018-01-31 20:11:15 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport TCPTransport (error status in uv_stream_t.shutdown callback)
OSError: [Errno 107] Socket not connected
2018-01-31 20:11:15 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport TCPTransport (error status in uv_stream_t.shutdown callback)
OSError: [Errno 107] Socket not connected
2018-01-31 20:11:15 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport TCPTransport (error status in uv_stream_t.shutdown callback)
OSError: [Errno 107] Socket not connected
2018-01-31 20:11:30 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport TCPTransport (error status in uv_stream_t.shutdown callback)
OSError: [Errno 107] Socket not connected
2018-01-31 20:11:30 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport TCPTransport (error status in uv_stream_t.shutdown callback)
OSError: [Errno 107] Socket not connected
2018-01-31 20:11:30 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport TCPTransport (error status in uv_stream_t.shutdown callback)
OSError: [Errno 107] Socket not connected
2018-01-31 20:11:30 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport TCPTransport (error status in uv_stream_t.shutdown callback)
OSError: [Errno 107] Socket not connected
2018-01-31 20:11:45 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport TCPTransport (error status in uv_stream_t.shutdown callback)
OSError: [Errno 107] Socket not connected
2018-01-31 20:11:45 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport TCPTransport (error status in uv_stream_t.shutdown callback)
OSError: [Errno 107] Socket not connected
2018-01-31 20:11:45 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport TCPTransport (error status in uv_stream_t.shutdown callback)
OSError: [Errno 107] Socket not connected
2018-01-31 20:11:45 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport TCPTransport (error status in uv_stream_t.shutdown callback)
OSError: [Errno 107] Socket not connected
2018-01-31 20:12:00 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport TCPTransport (error status in uv_stream_t.shutdown callback)
OSError: [Errno 107] Socket not connected
2018-01-31 20:12:00 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport TCPTransport (error status in uv_stream_t.shutdown callback)
OSError: [Errno 107] Socket not connected
2018-01-31 20:12:00 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport TCPTransport (error status in uv_stream_t.shutdown callback)
OSError: [Errno 107] Socket not connected
2018-01-31 20:12:00 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport TCPTransport (error status in uv_stream_t.shutdown callback)
OSError: [Errno 107] Socket not connected
2018-01-31 20:12:15 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport TCPTransport (error status in uv_stream_t.shutdown callback)
OSError: [Errno 107] Socket not connected
2018-01-31 20:12:15 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport TCPTransport (error status in uv_stream_t.shutdown callback)
OSError: [Errno 107] Socket not connected
2018-01-31 20:12:15 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport TCPTransport (error status in uv_stream_t.shutdown callback)
OSError: [Errno 107] Socket not connected
2018-01-31 20:12:15 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport TCPTransport (error status in uv_stream_t.shutdown callback)
OSError: [Errno 107] Socket not connected
2018-01-31 20:12:30 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport TCPTransport (error status in uv_stream_t.shutdown callback)
OSError: [Errno 107] Socket not connected
2018-01-31 20:12:30 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport TCPTransport (error status in uv_stream_t.shutdown callback)
OSError: [Errno 107] Socket not connected
2018-01-31 20:12:30 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport TCPTransport (error status in uv_stream_t.shutdown callback)
OSError: [Errno 107] Socket not connected
2018-01-31 20:12:30 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport TCPTransport (error status in uv_stream_t.shutdown callback)
OSError: [Errno 107] Socket not connected
2018-01-31 20:12:38 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport TCPTransport (error status in uv_stream_t.shutdown callback)
OSError: [Errno 107] Socket not connected
2018-01-31 20:12:38 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport TCPTransport (error status in uv_stream_t.shutdown callback)
OSError: [Errno 107] Socket not connected
2018-01-31 20:12:38 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport TCPTransport (error status in uv_stream_t.shutdown callback)
OSError: [Errno 107] Socket not connected
2018-01-31 20:12:38 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport TCPTransport (error status in uv_stream_t.shutdown callback)
OSError: [Errno 107] Socket not connected
2018-01-31 20:12:49 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport TCPTransport (error status in uv_stream_t.shutdown callback)
OSError: [Errno 107] Socket not connected
2018-01-31 20:12:49 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport TCPTransport (error status in uv_stream_t.shutdown callback)
OSError: [Errno 107] Socket not connected
2018-01-31 20:12:49 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport TCPTransport (error status in uv_stream_t.shutdown callback)
OSError: [Errno 107] Socket not connected
2018-01-31 20:12:49 ERROR (MainThread) [homeassistant.core] Error doing job: Fatal error on transport TCPTransport (error status in uv_stream_t.shutdown callback)
OSError: [Errno 107] Socket not connected

This error seems to be something that always shows up in various flavors during boot with a long delay… This time the system had been “hassio homeassistant restarted” a few times.

018-01-31 20:09:08 WARNING (Recorder) [homeassistant.components.recorder] Ended unfinished session (id=14 from 2018-02-01 01:59:59.498942)

The last error happens several times until the system finally comes up. It takes twice as long or more to restart now.

hassio supervisor logs looks odd on the first line…

core-ssh:/config# hassio supervisor logs

Error decoding json invalid character 's' looking for beginning of value: starting version 3.2.4
18-02-01 02:07:45 INFO (MainThread) [__main__] Initialize Hassio setup
18-02-01 02:07:45 INFO (MainThread) [__main__] Setup HassIO
18-02-01 02:07:45 INFO (SyncWorker_0) [hassio.docker.supervisor] Attach to supervisor homeassistant/armhf-hassio-supervisor with version 0.85
18-02-01 02:07:45 INFO (MainThread) [hassio.misc.host_control] Send 'info' to HostControl.
18-02-01 02:07:46 INFO (MainThread) [hassio.misc.host_control] Receive from HostControl: { "type": "resinos", "version": "1.1", "last_version": "1.1", "hostname": "hassio", "features": ["shutdown", "reboot", "update", "hostname"], "os": "GNU/Linux" }.
18-02-01 02:07:46 INFO (SyncWorker_1) [hassio.docker.interface] Attach to image homeassistant/raspberrypi2-homeassistant with version 0.62.0
18-02-01 02:07:47 INFO (MainThread) [hassio.addons.git] Load addon /data/addons/git/5ef5d199 repository
18-02-01 02:07:47 INFO (MainThread) [hassio.addons.git] Load addon /data/addons/git/a0d7b954 repository
18-02-01 02:07:47 INFO (MainThread) [hassio.addons.git] Load addon /data/addons/git/27e642c6 repository
18-02-01 02:07:47 INFO (MainThread) [hassio.addons.git] Load addon /data/addons/core repository
18-02-01 02:07:47 INFO (MainThread) [hassio.addons] Load addons: 35 all - 35 new - 0 remove
18-02-01 02:07:47 INFO (SyncWorker_4) [hassio.docker.interface] Attach to image homeassistant/armhf-addon-configurator with version 0.2.4
18-02-01 02:07:47 INFO (SyncWorker_8) [hassio.docker.interface] Attach to image hassioaddons/terminal-armhf with version 2.2.1
18-02-01 02:07:47 INFO (SyncWorker_9) [hassio.docker.interface] Attach to image homeassistant/armhf-addon-duckdns with version 1.0
18-02-01 02:07:47 INFO (SyncWorker_10) [hassio.docker.interface] Attach to image homeassistant/armhf-addon-check_config with version 0.7
18-02-01 02:07:47 INFO (SyncWorker_6) [hassio.docker.interface] Attach to image homeassistant/armhf-addon-samba with version 2.0
18-02-01 02:07:47 INFO (SyncWorker_3) [hassio.docker.interface] Attach to image homeassistant/armhf-addon-rpc_shutdown with version 0.3
18-02-01 02:07:47 INFO (SyncWorker_5) [hassio.docker.interface] Attach to image hassioaddons/ide-armhf with version 0.1.0
18-02-01 02:07:47 INFO (SyncWorker_9) [hassio.docker.interface] Attach to image homeassistant/armhf-addon-ssh with version 3.0
18-02-01 02:07:47 INFO (SyncWorker_1) [hassio.docker.interface] Attach to image 5ef5d199/armhf-addon-dasshio with version 0.2.0
18-02-01 02:07:48 INFO (MainThread) [hassio.updater] Fetch update data from https://raw.githubusercontent.com/home-assistant/hassio/master/version.json
18-02-01 02:07:48 INFO (MainThread) [hassio.snapshots] Found 2 snapshot files
18-02-01 02:07:48 INFO (MainThread) [hassio.addons] Startup initialize run 0 addons
18-02-01 02:07:48 INFO (MainThread) [__main__] Run HassIO
18-02-01 02:07:48 INFO (MainThread) [hassio.misc.dns] Start DNS port forwarding for host add-ons
18-02-01 02:07:48 INFO (MainThread) [hassio.core] Ignore Hass.io auto updates on beta mode
18-02-01 02:07:48 INFO (MainThread) [hassio.core] Start API on 172.30.32.2
18-02-01 02:07:48 INFO (MainThread) [hassio.addons] Startup system run 0 addons
18-02-01 02:07:48 INFO (MainThread) [hassio.addons] Startup services run 6 addons
18-02-01 02:07:48 INFO (SyncWorker_4) [hassio.docker.interface] Clean hassioaddons/terminal-armhf docker application
18-02-01 02:07:48 INFO (SyncWorker_19) [hassio.docker.interface] Clean 5ef5d199/armhf-addon-dasshio docker application
18-02-01 02:07:48 INFO (SyncWorker_12) [hassio.docker.interface] Clean hassioaddons/ide-armhf docker application
18-02-01 02:07:48 INFO (SyncWorker_10) [hassio.docker.interface] Clean homeassistant/armhf-addon-rpc_shutdown docker application
18-02-01 02:07:48 INFO (SyncWorker_13) [hassio.docker.interface] Clean homeassistant/armhf-addon-ssh docker application
18-02-01 02:07:48 INFO (SyncWorker_8) [hassio.docker.interface] Clean homeassistant/armhf-addon-samba docker application
18-02-01 02:07:52 INFO (SyncWorker_19) [hassio.docker.addon] Start docker addon 5ef5d199/armhf-addon-dasshio with version 0.2.0
18-02-01 02:07:54 INFO (SyncWorker_10) [hassio.docker.addon] Start docker addon homeassistant/armhf-addon-rpc_shutdown with version 0.3
18-02-01 02:07:54 INFO (SyncWorker_8) [hassio.docker.addon] Start docker addon homeassistant/armhf-addon-samba with version 2.0
18-02-01 02:07:55 INFO (SyncWorker_4) [hassio.docker.addon] Start docker addon hassioaddons/terminal-armhf with version 2.2.1
18-02-01 02:07:55 INFO (SyncWorker_12) [hassio.docker.addon] Start docker addon hassioaddons/ide-armhf with version 0.1.0
18-02-01 02:07:56 INFO (SyncWorker_13) [hassio.docker.addon] Start docker addon homeassistant/armhf-addon-ssh with version 3.0
18-02-01 02:08:01 INFO (SyncWorker_0) [hassio.docker.interface] Clean homeassistant/raspberrypi2-homeassistant docker application
18-02-01 02:08:06 INFO (SyncWorker_0) [hassio.docker.homeassistant] Start homeassistant homeassistant/raspberrypi2-homeassistant with version 0.62.0
18-02-01 02:08:06 INFO (MainThread) [hassio.addons] Startup application run 1 addons
18-02-01 02:08:07 INFO (SyncWorker_5) [hassio.docker.interface] Clean homeassistant/armhf-addon-configurator docker application
18-02-01 02:08:16 INFO (SyncWorker_5) [hassio.docker.addon] Start docker addon homeassistant/armhf-addon-configurator with version 0.2.4
18-02-01 02:08:21 INFO (MainThread) [hassio.tasks] All core tasks are scheduled
18-02-01 02:08:21 INFO (MainThread) [hassio.core] Hass.io is up and running
18-02-01 02:13:21 WARNING (MainThread) [hassio.tasks] Watchdog miss API response from Home-Assistant

Other logs look fine, to me. I have a feeling I need to wait on 62.1, did not want to wait while on 61.1 because of a know issue that is now fixed.

Thanks Matt

Clickbeast · February 1, 2018, 4:59am

What version of raspberry pi are you using? I saw other reports of issues after upgrading for older models

mattlward · February 1, 2018, 2:01pm

I am running a RPi 2. May have to go to a 3, but this really came on quickly and stinks of something consuming to much CPU during boot. Once running it is very stable.

Clickbeast · February 1, 2018, 3:35pm

That could be it, but worth noting my opinion is just a shot in the dark. There’s a few other posts of users with similar boot up issues and using older revisions of the pi.

I’ve only ever had Hass.io on an Rp3 so I don’t have much context to compare to

keith-michael · February 5, 2018, 6:47pm

Here to report similar problems. Since .62 or so my system is slower than usual. My log contains tons of ‘Timer got out of sync’ messages. Zwave now takes 2-3 times longer to respond after a restart. Even hours later, Zwave seems slower. When I look at the host and use the TOP command I see python3 eating up the CPU. It usually goes from 20% then jumps over 50%, goes down to 5% or so, then repeats.

I’m running HASSIO on a virtual Ubuntu system. I tossed another virtual CPU at machine the other day but it hasn’t helped.