Updating from v0.82.1 to v0.83.3 error

MrBramme · December 5, 2018, 9:14am

My home-assistant won’t come back online after updating the v0.83.3 from v0.82.1.
I’ve found somewhere that there was an issue with Owntracks, so i rolled back to v0.82.1, removed owntracks from my config, and re-updated to v0.83.3 but it’s still staying offline.

my setup:

Raspberry pi 3
Hassbian

The issue:
I update Home-Assistant as I always do and no errors show up there besides the same on that’s been there for ages on my end:

 netdisco 1.2.2 has requirement zeroconf==0.19.1, but you'll have zeroconf 0.21.3 which is incompatible.

I wait 15 minutes, recheck the UI but it’s still unavailable. Normally it’s up again after a few minutes.

My next move is to check the logs and they show only this entry:

2018-12-05 09:48:48 ERROR (MainThread) [coap] Exception CancelledError() can not be represented as errno, setting -1.

So next i check the service status and get this:

... sudo service home-assistant@homeassistant status
● [email protected] - Home Assistant for homeassistant
   Loaded: loaded (/etc/systemd/system/[email protected]; enabled; vendor preset: enabled)
   Active: active (running) since Wed 2018-12-05 09:50:24 CET; 8min ago
 Main PID: 5658 (hass)
   CGroup: /system.slice/system-home\x2dassistant.slice/[email protected]
           ├─5658 /srv/homeassistant/bin/python3 /srv/homeassistant/bin/hass
           └─5679 /srv/homeassistant/bin/python3 -m pip install --quiet sqlalchemy==1.2.14 --upgrade --constraint /srv/homeassistant/lib/python3.5/site-packages/homeassistant/package_constraints.txt

Dec 05 09:50:33 hassbian hass[5658]: 2018-12-05 09:50:33 INFO (MainThread) [homeassistant.loader] Loaded system_log from homeassistant.components.system_log
Dec 05 09:50:33 hassbian hass[5658]: 2018-12-05 09:50:33 INFO (MainThread) [homeassistant.loader] Loaded auth from homeassistant.components.auth
Dec 05 09:50:33 hassbian hass[5658]: 2018-12-05 09:50:33 INFO (MainThread) [homeassistant.loader] Loaded onboarding from homeassistant.components.onboarding
Dec 05 09:50:33 hassbian hass[5658]: 2018-12-05 09:50:33 INFO (MainThread) [homeassistant.loader] Loaded lovelace from homeassistant.components.lovelace
Dec 05 09:50:33 hassbian hass[5658]: 2018-12-05 09:50:33 INFO (MainThread) [homeassistant.loader] Loaded recorder from homeassistant.components.recorder
Dec 05 09:50:33 hassbian hass[5658]: 2018-12-05 09:50:33 INFO (Thread-7) [homeassistant.util.package] Attempting install of sqlalchemy==1.2.14
Dec 05 09:50:33 hassbian hass[5658]: 2018-12-05 09:50:33 INFO (MainThread) [homeassistant.loader] Loaded mqtt from homeassistant.components.mqtt
Dec 05 09:50:33 hassbian hass[5658]: 2018-12-05 09:50:33 INFO (MainThread) [homeassistant.loader] Loaded history from homeassistant.components.history
Dec 05 09:50:33 hassbian hass[5658]: 2018-12-05 09:50:33 INFO (MainThread) [homeassistant.setup] Setting up lovelace
Dec 05 09:50:33 hassbian hass[5658]: 2018-12-05 09:50:33 INFO (MainThread) [homeassistant.setup] Setup of domain lovelace took 0.0 seconds.

Is it possible that the sqlalchemy update is causing the delay? I would assume 15 minutes would have been enough.

Can someone point me into the right direction to fix this?

ViennaCivicEP2 · December 5, 2018, 11:00am

Have your read this one:
Cannot access WebInterface…

Edit:
Maybe i missed you mentioned owntracks already. Somewhere i read that removing it from the config did not help, but can not find it right now.

MrBramme · December 5, 2018, 6:10pm

Thanks for the topic. I found the owntracks thingy somewhere on github, but you pointed me to another possible culprit … the database itself! Trying that now (removing the Owntracks all together + deleting the database so a new one gets created). Will keep you posted

*update: no luck the DB wasn’t recreated, so there’s something going wrong before that step.

ViennaCivicEP2 · December 5, 2018, 6:24pm

What about using the standard home assistant DB (if you disable/comment out sql alchemy)?
Does it get created then?

Maybe you can check if it’s the sql part then

tps · December 5, 2018, 7:03pm

I have the same issue… I’ve even deleted the database so it gets created from scratch, but no UI…

tps · December 5, 2018, 7:07pm

Well, my db was created! But, still no UI.

genik · December 5, 2018, 7:43pm

Today I had the same problem.
Clearing the cache in the chrome browser has returned to the work of Hassio

MrBramme · December 5, 2018, 7:55pm

I have just been able to resolve the issue as well ! Goodie !!!
(note: i removed the owntracks config at this point)
The issue is the pip cache on my end… I noticed that after 30 min, the home-assistant service still showed the sqlalchemy update ongoing … not normal. so I …

Copied the sqlalchemy line in question
stopped the HA service
logged in as the homeassistant user on the CLI
activated the venv
ran that command myself (without the --quiet parameter)
noticed that it was stuck forever on “collecting sqlalchemy”
googled around a but
ran that same command again but added the parameter --no-cache-dir
… success, it installed

So I restarted the service and again … same issue on another package. Went through the same process, restarted and … GREAT SUCCES

Am up and running with the new version now, re-added owntracks using the new config. all is well in home-assistant land

Hope this helps you as well @tps !

tps · December 5, 2018, 11:31pm

No joy, unfortunately. Logs stop, ‘netstat -ap| grep 8123’ shows nothing listening on port 8123. Running strace on the hass process repeats over and over:
strace -p 2754
strace: Process 2754 attached
epoll_wait(3, [{EPOLLIN, {u32=4, u64=5669597348888580}}], 1, -1000) = 1
recv(4, “\21\0”, 4096, 0) = 2
send(5, “\0”, 1, 0) = 1
recv(4, “\0”, 4096, 0) = 1
recv(4, 0xf6bc50, 4096, 0) = -1 EAGAIN (Resource temporarily unavailable)
epoll_wait(3, [], 1, 0) = 0
getrandom("\230\2/Y@\336\263\30\205\343Ka\301W\246\352", 16, GRND_NONBLOCK) = 16
getpid() = 2754
epoll_wait(3, [], 1, 0) = 0
epoll_wait(3, [], 1, 0) = 0
getrandom("$k\321\10\266\335\356\325\211\327UX~\210\275\236", 16, GRND_NONBLOCK) = 16
getpid() = 2754
getpid() = 2754
getrandom("\214\352\214#\0\t\305\3422\212\32m!\331\2533", 16, GRND_NONBLOCK) = 16
getpid() = 2754
futex(0x3eb1a4, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x3eb1a0,
FUTEX_OP_SET<<28|0<<12|FUTEX_OP_CMP_GT<<24|0x1) = 1
futex(0x3eb1d0, FUTEX_WAKE_PRIVATE, 1) = 1
epoll_wait(3, [], 1, 0) = 0
epoll_wait(3, [], 1, 0) = 0
epoll_wait(3, [{EPOLLIN, {u32=4, u64=5669597348888580}}], 1, -1000) = 1
futex(0x3eb1a4, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 12953,
{tv_sec=1544052138, tv_nsec=649757000}, 0xffffffff) = 0
futex(0x3eb1d0, FUTEX_WAKE_PRIVATE, 1) = 0
recv(4, “\0”, 4096, 0) = 1
recv(4, 0xf6be18, 4096, 0) = -1 EAGAIN (Resource temporarily unavailable)
epoll_wait(3, [], 1, 0) = 0
getpid() = 2754
epoll_wait(3, [], 1, 0) = 0
getrandom("~\213\1\0\353\321\236X\275\213\371(\266\207\240\4", 16, GRND_NONBLOCK) = 16
getpid() = 2754
epoll_wait(3, [], 1, 0) = 0
epoll_wait(3, [], 1, 0) = 0
epoll_wait(3, [{EPOLLIN, {u32=4, u64=5669597348888580}}], 1, -1000) = 1
futex(0x3eb1a4, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 12955,
{tv_sec=1544052144, tv_nsec=109088000}, 0xffffffff) = -1 EAGAIN (Resource temporarily
unavailable)
futex(0x3eb1d0, FUTEX_WAKE_PRIVATE, 1) = 0
recv(4, “\0”, 4096, 0) = 1
recv(4, 0xf6be18, 4096, 0) = -1 EAGAIN (Resource temporarily unavailable)
epoll_wait(3, [], 1, 0) = 0
getpid() = 2754
epoll_wait(3, [], 1, 0) = 0
getrandom("\356\341\303\20\\10\271\27\260\351\253\333\341\217\3227", 16, GRND_NONBLOCK)
= 16
getpid() = 2754
epoll_wait(3, [], 1, 0) = 0
epoll_wait(3, [], 1, 0) = 0

This is the first time I haven’t been able to figure out what is going on when HA breaks on upgrade…