107.6 to109.6 Update fails

cnschulz · May 13, 2020, 2:10am

Gday,

My 109.6 update fails and I’m not finding much help in the logs. Any ideas how to debug this?

20-05-13 01:34:28 INFO (MainThread) [supervisor.api.security] /core/logs access from a0d7b954_ssh
20-05-13 01:43:19 INFO (MainThread) [supervisor.api.security] /supervisor/logs access from a0d7b954_ssh
20-05-13 01:43:40 INFO (MainThread) [supervisor.homeassistant] Update Home Assistant to version 0.109.6
20-05-13 01:43:40 INFO (SyncWorker_9) [supervisor.docker.interface] Update image homeassistant/raspberrypi2-homeassistant:0.107.6 to homeassistant/raspberrypi2-homeassistant:0.109.6
20-05-13 01:43:40 INFO (SyncWorker_9) [supervisor.docker.interface] Pull image homeassistant/raspberrypi2-homeassistant tag 0.109.6.
20-05-13 01:43:44 INFO (SyncWorker_9) [supervisor.docker.interface] Stop homeassistant application
20-05-13 01:43:47 INFO (MainThread) [supervisor.api.security] /supervisor/logs access from a0d7b954_ssh
20-05-13 01:43:52 INFO (SyncWorker_9) [supervisor.docker.interface] Clean homeassistant application
20-05-13 01:43:52 INFO (MainThread) [supervisor.homeassistant] Update pulse/client.config: /data/tmp/homeassistant_pulse
20-05-13 01:43:54 INFO (SyncWorker_16) [supervisor.docker.homeassistant] Start homeassistant homeassistant/raspberrypi2-homeassistant with version 0.109.6
20-05-13 01:43:57 INFO (MainThread) [supervisor.api.security] /supervisor/logs access from a0d7b954_ssh
20-05-13 01:44:24 INFO (MainThread) [supervisor.api.security] /supervisor/logs access from a0d7b954_ssh
20-05-13 01:44:40 INFO (MainThread) [supervisor.api.security] /supervisor/logs access from a0d7b954_ssh
20-05-13 01:44:49 INFO (MainThread) [supervisor.homeassistant] Home Assistant pip installation in progress
20-05-13 01:44:56 INFO (MainThread) [supervisor.api.security] /core/logs access from a0d7b954_ssh
20-05-13 01:45:28 INFO (MainThread) [supervisor.api.security] /core/logs access from a0d7b954_ssh
20-05-13 01:45:40 INFO (MainThread) [supervisor.api.security] /core/logs access from a0d7b954_ssh
20-05-13 01:46:32 INFO (MainThread) [supervisor.api.security] /core/logs access from a0d7b954_ssh
20-05-13 01:47:07 INFO (MainThread) [supervisor.api.security] /core/logs access from a0d7b954_ssh
20-05-13 01:47:28 INFO (MainThread) [supervisor.api.security] /supervisor/logs access from a0d7b954_ssh
20-05-13 01:51:53 INFO (MainThread) [supervisor.homeassistant] Home Assistant pip installation done
20-05-13 01:52:07 INFO (MainThread) [supervisor.api.security] /core/logs access from a0d7b954_ssh
20-05-13 01:58:07 INFO (MainThread) [supervisor.api.security] /core/logs access from a0d7b954_ssh
20-05-13 02:01:57 WARNING (MainThread) [supervisor.homeassistant] Don't wait anymore of Home Assistant startup!
20-05-13 02:01:57 CRITICAL (MainThread) [supervisor.homeassistant] HomeAssistant update fails -> rollback!
20-05-13 02:01:57 INFO (MainThread) [supervisor.homeassistant] Update Home Assistant to version 0.107.6
20-05-13 02:01:57 INFO (SyncWorker_6) [supervisor.docker.interface] Update image homeassistant/raspberrypi2-homeassistant:0.109.6 to homeassistant/raspberrypi2-homeassistant:0.107.6
20-05-13 02:01:57 INFO (SyncWorker_6) [supervisor.docker.interface] Pull image homeassistant/raspberrypi2-homeassistant tag 0.107.6.
20-05-13 02:02:01 INFO (SyncWorker_6) [supervisor.docker.interface] Stop homeassistant application
20-05-13 02:02:05 INFO (SyncWorker_6) [supervisor.docker.interface] Clean homeassistant application
20-05-13 02:02:05 INFO (MainThread) [supervisor.homeassistant] Update pulse/client.config: /data/tmp/homeassistant_pulse
20-05-13 02:02:07 INFO (SyncWorker_17) [supervisor.docker.homeassistant] Start homeassistant homeassistant/raspberrypi2-homeassistant with version 0.107.6
20-05-13 02:02:57 INFO (MainThread) [supervisor.homeassistant] Home Assistant pip installation in progress
20-05-13 02:03:14 INFO (MainThread) [supervisor.api.security] /core/logs access from a0d7b954_ssh
20-05-13 02:03:57 INFO (MainThread) [supervisor.homeassistant] Home Assistant pip installation done
20-05-13 02:04:13 INFO (MainThread) [supervisor.homeassistant] Home Assistant pip installation in progress
20-05-13 02:04:38 INFO (MainThread) [supervisor.api.security] /core/logs access from a0d7b954_ssh
20-05-13 02:05:17 INFO (MainThread) [supervisor.api.security] /supervisor/logs access from a0d7b954_ssh

cnschulz · May 13, 2020, 2:26am

…rollback fails. Perfect.

20-05-13 02:12:03 INFO (MainThread) [supervisor.api.security] /core/logs access from a0d7b954_ssh
20-05-13 02:21:05 WARNING (MainThread) [supervisor.homeassistant] Don't wait anymore of Home Assistant startup!
20-05-13 02:21:05 ERROR (MainThread) [asyncio] Task exception was never retrieved
future: <Task finished coro=<process_lock.<locals>.wrap_api() done, defined at /usr/src/supervisor/supervisor/utils/__init__.py:22> exception=HomeAssistantError()>
Traceback (most recent call last):
  File "/usr/src/supervisor/supervisor/utils/__init__.py", line 31, in wrap_api
    return await method(api, *args, **kwargs)
  File "/usr/src/supervisor/supervisor/homeassistant.py", line 360, in update
    await _update(rollback)
  File "/usr/src/supervisor/supervisor/homeassistant.py", line 344, in _update
    await self._start()
  File "/usr/src/supervisor/supervisor/homeassistant.py", line 377, in _start
    await self._block_till_run()
  File "/usr/src/supervisor/supervisor/homeassistant.py", line 627, in _block_till_run
    raise HomeAssistantError()
supervisor.exceptions.HomeAssistantError
20-05-13 02:24:51 INFO (MainThread) [supervisor.api.security] /core/logs access from a0d7b954_ssh
20-05-13 02:25:00 INFO

squirtbrnr · May 13, 2020, 2:51am

Go read the breaking changes in 0.108 and 0.109. Also, the log you posted is the supervisor log and won’t tell you anything helpful in finding out why it failed. To find out why it failed you need to look at the homeassistant.log file in the same directory as your configuration.yaml file.

cnschulz · May 14, 2020, 10:36pm

There is nothing abnormal in the homeassistant log. It simply stops logging. Looks like (another) full rebuild. :-\

squirtbrnr · May 14, 2020, 11:18pm

Ok if you don’t want to share the log then go ahead and rebuild and run into the same problem again down the line. I’m betting you have a configuration or integration that had a breaking change and you just need to update your configuration.

For everyone else following along, post your logs, and read the breaking changes before, during, and after updating. Don’t just click update blindly.

cnschulz · May 14, 2020, 11:24pm

I’ll try. There are 3 states that are potentially causing the issue:

current 107.6 state (i can supply logs for that)
logs post 109.6 upgrade but before rollback (hard to catch, ill have to keep a constant eye on it booting via ssh)
post rollback to 107.6 which fails (its VERY scary that a rollback fails) where the log simply stops with no errors reported.

cnschulz · May 14, 2020, 11:49pm

here is my post rollback log: All the “failures” are known and were noted before upgrade.

2020-05-15 09:39:06 WARNING (MainThread) [homeassistant.loader] You are using a custom integration for hacs which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant.
2020-05-15 09:39:09 WARNING (Recorder) [homeassistant.components.recorder] Ended unfinished session (id=65 from 2020-05-14 23:20:57.690882)
2020-05-15 09:39:29 WARNING (MainThread) [homeassistant.loader] You are using a custom integration for samsungtv which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant.
2020-05-15 09:39:29 WARNING (MainThread) [homeassistant.loader] You are using a custom integration for xboxone which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant.
2020-05-15 09:39:29 WARNING (MainThread) [homeassistant.components.template] Template switch 'heater' has no entity ids configured to track nor were we able to extract the entities to track from the value template(s). This entity will only be able to be updated manually.
2020-05-15 09:39:29 WARNING (MainThread) [homeassistant.components.template] Template switch 'air_conditioner' has no entity ids configured to track nor were we able to extract the entities to track from the value template(s). This entity will only be able to be updated manually.
2020-05-15 09:39:40 WARNING (MainThread) [homeassistant.components.switch] Setup of switch platform tplink is taking over 10 seconds.
2020-05-15 09:40:30 ERROR (MainThread) [homeassistant.components.switch] Setup of platform tplink is taking longer than 60 seconds. Startup will proceed without waiting any longer.
2020-05-15 09:40:35 ERROR (SyncWorker_14) [homeassistant.components.bom.weather] Could not get BOM weather station from lat/lon
2020-05-15 09:40:37 ERROR (SyncWorker_8) [miio.device] Unable to discover a device at address 192.168.1.9
2020-05-15 09:40:39 ERROR (MainThread) [homeassistant.components.xiaomi_miio.remote] Device unavailable or token incorrect: Unable to discover the device 192.168.1.9
2020-05-15 09:40:41 WARNING (MainThread) [homeassistant.components.remote] Platform xiaomi_miio not ready yet. Retrying in 30 seconds.
2020-05-15 09:40:42 ERROR (MainThread) [homeassistant.components.withings] Withings auth tokens exired for profile Chris, remove and re-add the integration

cnschulz · May 18, 2020, 10:11pm

@squirtbrnr any ideas?

cnschulz · May 22, 2020, 12:47am

111.0 works fine. 109 must have had an “undocumented feature”