search

hassio-addons / addon-zwave-js-ui

Z-Wave JS UI - Home Assistant Community Add-ons
https://addons.community
MIT License
128 stars 36 forks source link

Problem upgrading to 3.9.2. from 3.4.1 #695

Open othermore opened 2 months ago

othermore commented 2 months ago

Problem/Motivation

I can't update to the last version of the addon. I can't stop the addon. Forcing the update works, but the fresher version of the addon will never start.

Expected behavior

Addon should be stoppable and updatable. New version should work.

Actual behavior

Addon can't be stopped. Addon can't be upgraded. Forcing the upgrade to last version results in addon not starting up.

Full details

I have ZWave JS UI addon version 3.4.1, when the latest version (published 1 week ago I believe) is 3.9.2. There’s been a bunch of intermediate updates I have not installed.

I also have Home Assistant Core 2024.3.3, when the latest version is 2024.7.4.

If I update Home Assistant Core to the latest version, ZWave JS UI stops working because it's too old for this core. However, I can’t install the update for ZWave JS UI (tried both with Home Assistant Core 2024.3.3 and 2024.7.4).

Issue 1: update fails

I try to update through the Home Assistant UI, and as soon as I click on update, the whole Home Assistant freezes. It's running on a VirtualBox and the ha> prompt freezes too (i.e. the whole Virtual Machine stops responding). Only forcing a reboot gets it back, and the update has not happened.

This is what I found in the journald logs around the time of the attempt to update (note I clicked on "update" exactly at 00:15:00):

ago 01 00:14:38 homeassistant addon_a0d7b954_zwavejs2mqtt[435]: 2024-08-01 00:14:38.503 INFO Z-WAVE: [Node 044] Metadata updated: 50-1-value-66049
ago 01 00:14:38 homeassistant addon_a0d7b954_zwavejs2mqtt[435]: 2024-08-01 00:14:38.505 INFO Z-WAVE: [Node 044] Value updated: 50-1-value-66049 0 => 0
ago 01 00:14:51 homeassistant addon_a0d7b954_zwavejs2mqtt[435]: 2024-07-31T22:14:51.764Z CNTRLR » [Node 060] Meter CC values may be stale, refreshing... [Endpoint 1]
ago 01 00:14:51 homeassistant addon_a0d7b954_zwavejs2mqtt[435]: 2024-07-31T22:14:51.767Z CNTRLR » [Node 060] querying meter value (type = Electric, scale = kWh)... [Endpoint 1]
ago 01 00:14:52 homeassistant addon_a0d7b954_zwavejs2mqtt[435]: 2024-08-01 00:14:52.236 INFO Z-WAVE: [Node 060] Metadata updated: 50-1-value-65537
ago 01 00:14:52 homeassistant addon_a0d7b954_zwavejs2mqtt[435]: 2024-08-01 00:14:52.241 INFO Z-WAVE: [Node 060] Value updated: 50-1-value-65537 1.65 => 1.65
ago 01 00:14:52 homeassistant addon_a0d7b954_zwavejs2mqtt[435]: 2024-07-31T22:14:52.246Z CNTRLR » [Node 060] querying meter value (type = Electric, scale = W)... [Endpoint 1]
ago 01 00:14:52 homeassistant addon_core_configurator[435]: INFO:2024-08-01 00:14:52,759:hass_configurator.configurator:127.0.0.1 - "GET / HTTP/1.1" 200 -
ago 01 00:14:52 homeassistant addon_a0d7b954_zwavejs2mqtt[435]: 2024-08-01 00:14:52.759 INFO Z-WAVE: [Node 060] Metadata updated: 50-1-value-66049
ago 01 00:14:52 homeassistant addon_a0d7b954_zwavejs2mqtt[435]: 2024-08-01 00:14:52.761 INFO Z-WAVE: [Node 060] Value updated: 50-1-value-66049 0 => 0
ago 01 00:15:01 homeassistant hassio_supervisor[435]: **2024-08-01 00:15:01.835 INFO (MainThread) [supervisor.backups.manager] Backup 1f3241eb starting stage addon_repositories**
ago 01 00:15:01 homeassistant hassio_supervisor[435]: **2024-08-01 00:15:01.835 INFO (MainThread) [supervisor.backups.manager] Backup 1f3241eb starting stage docker_config**
ago 01 00:15:01 homeassistant hassio_supervisor[435]: **2024-08-01 00:15:01.835 INFO (MainThread) [supervisor.backups.manager] Creating new partial backup with slug 1f3241eb**
ago 01 00:15:01 homeassistant hassio_supervisor[435]: **2024-08-01 00:15:01.837 INFO (MainThread) [supervisor.backups.manager] Backup 1f3241eb starting stage addons**
ago 01 00:15:01 homeassistant addon_cebe7a76_hassio_google_drive_backup[435]: **08-01 00:15:01 INFO A backup directory file was modified, we'll check for new backups soon.**
ago 01 00:15:01 homeassistant hassio_supervisor[435]: **2024-08-01 00:15:01.844 INFO (MainThread) [supervisor.addons.addon] Building backup for add-on a0d7b954_zwavejs2mqtt**
ago 01 00:15:01 homeassistant homeassistant[435]: **2024-08-01 00:15:01.892 WARNING (MainThread) [homeassistant.components.netatmo] API error: 500 (Internal Server Error)**
ago 01 00:15:02 homeassistant hassio_supervisor[435]: **2024-08-01 00:15:02.620 INFO (MainThread) [supervisor.addons.addon] Finish backup for addon a0d7b954_zwavejs2mqtt**
ago 01 00:15:02 homeassistant hassio_supervisor[435]: **2024-08-01 00:15:02.620 INFO (MainThread) [supervisor.backups.manager] Backup 1f3241eb starting stage finishing_file**
ago 01 00:15:02 homeassistant hassio_supervisor[435]: **2024-08-01 00:15:02.624 INFO (MainThread) [supervisor.backups.manager] Creating partial backup with slug 1f3241eb completed**
ago 01 00:15:02 homeassistant hassio_supervisor[435]: **2024-08-01 00:15:02.625 INFO (MainThread) [supervisor.docker.addon] Updating image ghcr.io/hassio-addons/zwave-js-ui/amd64:3.4.1 to ghcr.io/hassio-addons/zwave-js-ui/amd**>
ago 01 00:15:02 homeassistant hassio_supervisor[435]: **2024-08-01 00:15:02.625 INFO (MainThread) [supervisor.docker.interface] Downloading docker image ghcr.io/hassio-addons/zwave-js-ui/amd64 with tag 3.9.2.**

**-- Boot c80eaa9afee04bb3a81716a79acff8d3 --**

ago 01 00:19:43 homeassistant kernel: **Linux version 6.6.33-haos (builder@bfa75d3d66a7) (x86_64-buildroot-linux-gnu-gcc.br_real (Buildroot -gd03dda4f) 12.3.0, GNU ld (GNU Binutils) 2.40) #1 SMP PREEMPT_DYNAMIC Tue Jun 18 13:**>
ago 01 00:19:43 homeassistant kernel: Command line: BOOT_IMAGE=(hd0,gpt4)/bzImage root=PARTUUID=a3ec664e-32ce-4665-95ea-7ae90ce9aa20 rootwait zram.enabled=1 zram.num_devices=3 systemd.machine_id=a2f13a7d358a45f5b34343bb5b91>

So to me it looks like there's nothing useful thing. Last command I see is the JSUI image being downloaded. Then nothing happens until I force a reboot several minutes later.

Issue 2: I can't stop the addon

If I try to stop the addon using the Home Assistant UI, it fails as well. Same behaviour than on issue 1: everything freezes and I need to reboot the machine. Then the journald logs show similar output as stated above:

ago 02 10:58:43 homeassistant addon_a0d7b954_zwavejs2mqtt[439]: 2024-08-02 10:58:43.724 INFO Z-WAVE: [Node 007] Is now asleep
ago 02 10:58:43 homeassistant addon_a0d7b954_zwavejs2mqtt[439]: 2024-08-02T08:58:43.726Z CNTRLR   [Node 007] The node is now asleep.
ago 02 10:58:58 homeassistant homeassistant[439]: 2024-08-02 10:58:58.504 WARNING (MainThread) [homeassistant.components.netatmo] API error: 500 (Internal Server Error)
ago 02 10:59:05 homeassistant addon_a0d7b954_zwavejs2mqtt[439]: 2024-08-02 10:59:05.039 INFO APP: GET /health/zwave 301 0.232 ms - 191
ago 02 10:59:05 homeassistant addon_core_configurator[439]: INFO:2024-08-02 10:59:05,400:hass_configurator.configurator:127.0.0.1 - "GET / HTTP/1.1" 200 -
-- Boot 3dde8bdaa5854e82aeedba0ca6d35f2a --
ago 02 11:06:23 homeassistant kernel: Linux version 6.6.33-haos (builder@bfa75d3d66a7) (x86_64-buildroot-linux-gnu-gcc.br_real (Buildroot -gd03dda4f) 12.3.0, GNU ld (GNU Binutils) 2.40) #1 SMP PREEMPT_DYNAMIC Tue Jun 18 13:51:59 UTC 2024
ago 02 11:06:23 homeassistant kernel: Command line: BOOT_IMAGE=(hd0,gpt4)/bzImage root=PARTUUID=a3ec664e-32ce-4665-95ea-7ae90ce9aa20 rootwait zram.enabled=1 zram.num_devices=3 systemd.machine_id=a2f13a7d358a45f5b34343bb5b91d733 fsck.repair=yes console=ttyS0 co>
ago 02 11:06:23 homeassistant kernel: BIOS-provided physical RAM map:

So my guess is that the first step to install the update is to stop the running one, and that is failing

Issue 3: If I force the update, then I get another error

The only way I found to install the update was stoping the addon by setting it to not start at boot, and then rebooting. That way, when Home Assistant reboots, the add-on is not running. After that, I was able to install the update through the UI.

Immediately after installing this update, the addon is unable to load. The error log line from ZWave JS UI says:

s6-rc-compile: fatal: invalid /etc/s6-overlay/s6-rc.d/discovery/type: must be oneshot, longrun, or bundle s6-rc: fatal: unable to take locks: no such file or directory

I've seen the same exact error log in a ESPHome github issue, so I'm guessing there's some common dependency that causes this error. The post is also for about a week ago, so it may be related.

benishs commented 2 months ago

I believe I'm having a similar issue, but I'm stuck at Z-Wave JS UI 3.6.0 and Home Assistant core 2024.6.4.

In early June my Home Assistant auto-updated Z-Wave JS UI from 3.6.0 to 3.7.1 and it froze the VM (I'm also running VirtualBox). I rolled back to 3.6.0 and it started working again. I asked about this on the Home Assistant Discord, but didn't get any fruitful responses: https://discord.com/channels/330944238910963714/1247691086533496895

I tried updating to Home Assistant Core 2024.7 when that came out, hoping whatever was going on might be sorted out, but ran in to the same error about Z-Wave JS UI 3.6.0 not working with 2024.7; and trying to update Z-Wave JS UI 3.6.0 again (from 2024.7) just crashes the VM, same as trying to update it from 2024.6.4.

I'm happy to share any relevant logs, but am not sure where to look.

othermore commented 2 months ago

Im documenting all my process here. I managed to update to the last version (by setting the addon to not load at boot and then reboot and, without the addon started, update it). But my system is still in this weird state where any change to the ZWave JS UI or the ZWave JS configuration (config change, try to stop it, etc..) makes the whole system crash.

othermore commented 2 months ago

Correcting myself. The ZWave JS Integration does not seem to make the system crash.

I think it did when I was playing around trying to get my system into a stable state, when I removed the integration, but it's not happening anymore with any change to the config I've tried. The issue remains with the ZWave JS UI Addon. Even updating the config to enable log to file or backups makes it crash.

Also note that I ended up fully removing the ZWave JS UI add on and installing it from scratch, and then the only thing I recovered from my prior instalation were the nodes.json file. I also copied some settings manually to the settings json file, but preserving the structure of the new file (I just copied values because it was faster than making the addon not start at boot, so I could update configs without it making the system crash).

This is my very last journalctl log before crash. The only action I did was clic save on the add on settings (without actually making any change).

ago 04 23:30:54 homeassistant addon_a0d7b954_zwavejs2mqtt[452]: 2024-08-04 23:30:54.827 INFO APP: GET /health/zwave 301 0.684 ms - 191
ago 04 23:31:00 homeassistant hassio_supervisor[452]: 2024-08-04 23:31:00.601 INFO (MainThread) [supervisor.homeassistant.core] Home Assistant Core state changed to RUNNING
ago 04 23:31:00 homeassistant hassio_supervisor[452]: 2024-08-04 23:31:00.601 INFO (MainThread) [supervisor.homeassistant.core] Detect a running Home Assistant instance
ago 04 23:31:00 homeassistant hassio_supervisor[452]: 2024-08-04 23:31:00.601 INFO (MainThread) [supervisor.addons.manager] Phase 'application' starting 1 add-ons
ago 04 23:31:00 homeassistant systemd[1]: var-lib-docker-overlay2-8e6796357d81ef41a73b15a12ec1bde3b25526148cbdc769bb8e94827b9771be\x2dinit-merged.mount: Deactivated successfully.
ago 04 23:31:00 homeassistant systemd[1]: mnt-data-docker-overlay2-8e6796357d81ef41a73b15a12ec1bde3b25526148cbdc769bb8e94827b9771be\x2dinit-merged.mount: Deactivated successfully.
ago 04 23:31:00 homeassistant kernel: hassio: port 7(vethd2c30ff) entered blocking state
ago 04 23:31:00 homeassistant kernel: hassio: port 7(vethd2c30ff) entered disabled state
ago 04 23:31:00 homeassistant kernel: vethd2c30ff: entered allmulticast mode
ago 04 23:31:00 homeassistant kernel: vethd2c30ff: entered promiscuous mode
ago 04 23:31:00 homeassistant kernel: hassio: port 7(vethd2c30ff) entered blocking state
ago 04 23:31:00 homeassistant kernel: hassio: port 7(vethd2c30ff) entered forwarding state
ago 04 23:31:00 homeassistant kernel: audit: type=1700 audit(1722807060.684:211): dev=vethd2c30ff prom=256 old_prom=0 auid=4294967295 uid=0 gid=0 ses=4294967295
-- Boot abb5d79505084291a5feeb075ba05d76 --

I've also enabled ZWave JS UI to log to a file and set log level to debug, but I did not get anything interesting in that file (I clicked save at 23:31, that's when the system crashed)

2024-08-04 23:30:20.998 INFO Z-WAVE: [Node 011] Value added 11-112-0-90 => 0
2024-08-04 23:30:20.998 INFO Z-WAVE: [Node 011] Value added 11-112-0-91 => 25
2024-08-04 23:30:20.998 INFO Z-WAVE: [Node 011] Value added 11-112-0-92 => 5
2024-08-04 23:30:20.998 INFO Z-WAVE: [Node 011] Value added 11-112-0-101-1 => 0
2024-08-04 23:30:21.008 INFO Z-WAVE: [Node 011] Value added 11-112-0-101-2 => 0
2024-08-04 23:30:21.008 INFO Z-WAVE: [Node 011] Value added 11-112-0-101-4 => 0
2024-08-04 23:30:21.008 INFO Z-WAVE: [Node 011] Value added 11-112-0-101-8 => 0
2024-08-04 23:30:21.008 INFO Z-WAVE: [Node 011] Value added 11-112-0-102-1 => 0
2024-08-04 23:30:21.016 INFO Z-WAVE: [Node 011] Value added 11-112-0-102-2 => 0
2024-08-04 23:30:21.016 INFO Z-WAVE: [Node 011] Value added 11-112-0-102-4 => 0
2024-08-04 23:30:21.016 INFO Z-WAVE: [Node 011] Value added 11-112-0-102-8 => 0
2024-08-04 23:30:21.017 INFO Z-WAVE: [Node 011] Value added 11-112-0-103-1 => 0
2024-08-04 23:30:21.026 INFO Z-WAVE: [Node 011] Value added 11-112-0-103-2 => 0
2024-08-04 23:30:21.026 INFO Z-WAVE: [Node 011] Value added 11-112-0-103-4 => 0
2024-08-04 23:30:21.026 INFO Z-WAVE: [Node 011] Value added 11-112-0-103-8 => 0
2024-08-04 23:30:21.026 INFO Z-WAVE: [Node 011] Value added 11-112-0-111 => 3
2024-08-04 23:30:21.026 INFO Z-WAVE: [Node 011] Value added 11-112-0-112 => 600
2024-08-04 23:30:21.026 INFO Z-WAVE: [Node 011] Value added 11-112-0-113 => 600
2024-08-04 23:30:21.026 INFO Z-WAVE: [Node 011] Value added 11-112-0-120 => 3
2024-08-04 23:30:21.026 INFO Z-WAVE: [Node 011] Value added 11-112-0-247-1 => 0
2024-08-04 23:30:21.027 INFO Z-WAVE: [Node 011] Value added 11-112-0-247-2 => 0
2024-08-04 23:30:21.027 INFO Z-WAVE: [Node 011] Value added 11-112-0-121 => 3
2024-08-04 23:30:21.027 INFO Z-WAVE: [Node 011] Value added 11-112-0-123 => 3
2024-08-04 23:30:21.027 INFO Z-WAVE: [Node 011] Value added 11-112-0-124 => 3
2024-08-04 23:30:21.028 INFO Z-WAVE: [Node 011] Value added 11-112-0-125 => 3
2024-08-04 23:32:27.208 INFO APP: Listening on port 44920 protocol HTTP
2024-08-04 23:32:27.211 INFO ZNIFFERMANAGER: Zniffer is DISABLED
2024-08-04 23:32:27.212 INFO MQTT: MQTT is disabled
2024-08-04 23:32:27.237 INFO BACKUP: Backup job started with cron: 23 0 * * 1,3,5. Next run: 8/5/2024, 12:23:00 AM
2024-08-04 23:32:27.238 INFO BACKUP: Backup job started with cron: 37 1 * * 5. Next run: 8/9/2024, 1:37:00 AM
2024-08-04 23:32:27.241 INFO Z-WAVE: Connecting to /dev/ttyACM0
2024-08-04 23:32:27.274 INFO Z-WAVE: Zwavejs usage statistics ENABLED
othermore commented 2 months ago

By doing the same workaround (setting the addon to not start at boot, rebooting -with a crash of the system- and then when the addon is not running, updating it) I've managed toupdate to the last version, 3.9.3

However, after the update, I'm getting the following error, and the addon will not start:

2024-08-06T19:13:08.146Z CNTRLR   [Node 016] Timed out while waiting for a response from the node (ZW0201)
s6-rc-compile: fatal: invalid /etc/s6-overlay/s6-rc.d/discovery/type: must be oneshot, longrun, or bundle
s6-rc: fatal: unable to take locks: No such file or directory
s6-linux-init-shutdownd: warning: /run/s6/basedir/scripts/rc.shutdown exited 111
s6-rc-compile: fatal: invalid /etc/s6-overlay/s6-rc.d/discovery/type: must be oneshot, longrun, or bundle
s6-rc: fatal: unable to take locks: No such file or directory
s6-linux-init-shutdownd: warning: /run/s6/basedir/scripts/rc.shutdown exited 111

And this in the journald log

ago 06 21:29:29 homeassistant hassio_supervisor[437]: 2024-08-06 21:29:29.852 WARNING (MainThread) [supervisor.addons.addon] Watchdog found addon Z-Wave JS UI is unhealthy, restarting...
ago 06 21:29:29 homeassistant hassio_supervisor[437]: 2024-08-06 21:29:29.855 INFO (SyncWorker_0) [supervisor.docker.manager] Stopping addon_a0d7b954_zwavejs2mqtt application
ago 06 21:29:29 homeassistant addon_a0d7b954_zwavejs2mqtt[437]: s6-rc: fatal: unable to take locks: No such file or directory
ago 06 21:29:29 homeassistant addon_a0d7b954_zwavejs2mqtt[437]: s6-linux-init-shutdownd: warning: /run/s6/basedir/scripts/rc.shutdown exited 111

The error repeats every time I try to start the addon. I've tried rebooting, but I had no success.

I had seen a similar error before already, when I updated last time while keeping an existing configuration. I only solved that by removing the whole addon and installing a fresh one, and then manually setting everything again.

So this time I went for a temporary solution until I find out what's going on: reverting to prior version (loading the backup)

After reverting, the add on started again, and it showed this:

s6-rc: info: service s6rc-oneshot-runner: starting
s6-rc: info: service s6rc-oneshot-runner successfully started
s6-rc: info: service base-addon-banner: starting

-----------------------------------------------------------
 Add-on: Z-Wave JS UI
 Fully configurable Z-Wave JS gateway and control panel
-----------------------------------------------------------
 Add-on version: 3.9.2
 There is an update available for this add-on!
 Latest add-on version: 3.9.3
 Please consider upgrading as soon as possible.
 System: Home Assistant OS 12.4  (amd64 / qemux86-64)
 Home Assistant Core: 2024.7.4
 Home Assistant Supervisor: 2024.08.0
-----------------------------------------------------------
 Please, share the above information when looking for help
 or support in, e.g., GitHub, forums or the Discord chat.
-----------------------------------------------------------
s6-rc: info: service base-addon-banner successfully started
s6-rc: info: service fix-attrs: starting
s6-rc: info: service base-addon-log-level: starting
s6-rc: info: service fix-attrs successfully started
s6-rc: info: service base-addon-log-level successfully started
s6-rc: info: service legacy-cont-init: starting
s6-rc: info: service legacy-cont-init successfully started
s6-rc: info: service init-zwave-js-ui: starting
s6-rc: info: service init-nginx: starting
s6-rc: info: service init-zwave-js-ui successfully started
s6-rc: info: service zwave-js-ui: starting
s6-rc: info: service zwave-js-ui successfully started
s6-rc: info: service discovery: starting
[21:53:32] INFO: Starting the Z-Wave JS UI...
s6-rc: info: service init-nginx successfully started
s6-rc: info: service nginx: starting
s6-rc: info: service nginx successfully started
2024-08-06 21:53:33.935 INFO APP: Version: 9.16.2
2024-08-06 21:53:33.939 INFO APP: Application path:/opt
  ______  __          __                      _  _____     _    _ _____ 
 |___  /  \ \        / /                     | |/ ____|   | |  | |_   _|
    / /____\ \  /\  / /_ ___   _____         | | (___     | |  | | | |  
   / /______\ \/  \/ / _' \ \ / / _ \    _   | |\___ \    | |  | | | |  
  / /__      \  /\  / (_| |\ V /  __/   | |__| |____) |   | |__| |_| |_ 
 /_____|      \/  \/ \__,_| \_/ \___|    \____/|_____/     \____/|_____|

2024-08-06 21:53:33.953 WARN STORE: scenes.json not found
2024-08-06 21:53:33.970 INFO LOGGER: Cleaning up log files...
2024-08-06 21:53:34.063 WARN Z-WAVE: Zwavejs driver is not ready yet, statistics will be enabled on driver initialization
[21:53:34] INFO: Starting NGinx...

Which tells me that the first thing the add on does is starting the s6rc-oneshot-runner, and apparently this does not work with the new version (but it did not work after update earlier either, it's weird!)

othermore commented 2 months ago

Looks like the problems I was facing were a combo of

benishs commented 1 month ago

For what it's worth, I'm using a different controller (Zooz ZST10) but think I'm having a similar problem.

I also have the VirtualBox USB controller set as USB 2.0: https://go.benish.io/TJSNxBfH But it's unclear if I should have that set to something else.

othermore commented 1 month ago

I think it's an issue with the USB 2.0 driver. I ended up solving it by switching to usb3, which required a firmware update of the controller in my case, plus plugging the controller directly to the server without a USB hub that I was using.

See the full details and the solution here: https://community.home-assistant.io/t/help-z-wave-js-ui-addon-breaking-my-system/758887

benishs commented 1 month ago

@othermore Thank you for chasing this down and the link to that other thread! I'll try your solution when I have a moment.

benishs commented 1 week ago

@othermore I updated my Zooz ZST10 to the latest firmware and set the VirtualBox USB controller to USB 3 and that has solved my issue as well. Thanks!