[bug] Heal on a single node seems not to work

[Madelaide]

System Health

version	core-2021.3.3
installation_type	Home Assistant OS
dev	false
hassio	true
docker	true
virtualenv	false
python_version	3.8.7
os_name	Linux
os_version	5.4.99
arch	x86_64
timezone	Australia/Adelaide

Home Assistant Cloud

logged_in	false
can_reach_cert_server	ok
can_reach_cloud_auth	ok
can_reach_cloud	ok

Home Assistant Supervisor

host_os	Home Assistant OS 5.12
update_channel	beta
supervisor_version	supervisor-2021.03.4
docker_version	19.03.13
disk_total	78.0 GB
disk_used	23.7 GB
healthy	true
supported	true
board	ova
supervisor_api	ok
version_api	ok
installed_addons	Samba share (9.3.1), Visual Studio Code (3.1.1), Grafana (6.1.3), InfluxDB (4.0.3), Glances (0.11.1), Log Viewer (0.9.1), Terminal & SSH (9.0.2), Mosquitto broker (5.1.1), Z-Wave JS to MQTT (0.6.2)

Lovelace

dashboards	3
resources	2
views	9
mode	storage

1. select either a node with listed neighbours or a node with no listed neighbours (but in the same proximity)
2. select Heal Node
3. note minimal log message
4. wait
5. no change, extant node with neighbours listed does not change, node with no listed neighbours (new node) also no change
6. same issue for aeotec smart switch6, aeotec 6n1 sensor, fibaro dimmer 211

screenshot below

PS: I tried to include the zwave log at DEBUG level, but I have 4 logs and there is no date on them, the highest number log doesnt seem to have the heal command in it, so it's unclear if it is today's log or not (with no date showing).

But this snippet shows the node interviews okay and finds its nodes fine.

22:46:45.501 CNTRLR [Node 006] Interview stage completed: CommandClasses
22:46:45.501 CNTRLR [Node 006] Interview stage completed: OverwriteConfig
22:46:45.502 CNTRLR » [Node 006] requesting node neighbors...
22:46:45.508 CNTRLR « [Node 005] node neighbors received: 6, 7, 8, 9, 10, 15, 18, 19, 20, 21, 23,
27, 31, 36, 37, 41, 42, 44, 45, 49, 50, 51, 53, 55, 56, 57, 58, 59, 60, 62, 63
, 64, 75, 80, 82, 87, 88, 89, 93, 94, 102, 107, 109, 111, 112, 113, 117, 118,
119, 124, 125, 130
22:46:45.509 CNTRLR [Node 005] Interview stage completed: Neighbors
22:46:45.509 CNTRLR [Node 005] Interview completed
22:46:45.520 CNTRLR « [Node 006] node neighbors received: 5, 7, 8, 9, 10, 15, 18, 19, 21, 23, 31,
36, 37, 38, 41, 42, 44, 50, 51, 53, 55, 56, 57, 59, 60, 62, 63, 64, 75, 82, 87
, 88, 89, 92, 93, 94, 102, 107, 109, 110, 111, 112, 113, 118, 119, 124, 126, 1
30, 131
22:46:45.521 CNTRLR [Node 006] Interview stage completed: Neighbors
22:46:45.521 CNTRLR [Node 006] Interview completed

[robertsLando]

@Madelaide Could you please go to control panel table and press on Dump Nodes yellow bottom on top of the table? If you don't see it please be sure to have the latest version (2.2.0) installed

[Madelaide]

Here is the dump file.
nodes_dump.json.zip

[Madelaide]

[robertsLando]

Fixes in zwave-js/zwave-js-ui#863 , wait until next release

[Madelaide]

The nodes graph does now work for me, thankyou; but this ticket is not about that, it is about Healing.

I have installed the update today, but it has not fixed the heal issue.

[robertsLando]

I have installed the update today, but it has not fixed the heal issue.

What's the issue about healing? I thought that the problem was you didn't see the graph connections with neightbors

[Madelaide]

Yes, that was another issue which you fixed.

This issue, see logs above, is that selecting Heal on a node surrounded by nodes does nothing. Even a node (6) with 56 neighbours in the image above, when "heal node" is selected, nothing happens. And a new node adjacent (cm) from that node, has no new nodes when the heal command is selected - it appears not to execute/work. Nothing I have seen in the logs anyway.

[robertsLando]

@Madelaide if it doesn't do anything doesn't mean it didn't work. It could mean that it's already healed. @AlCalzone

[AlCalzone]

1. To verify that actually nothing happens, I need to see a zwave-js log (level debug) of the heal node process. @Madelaide
2. Does the map update magically once the command was completed? @robertsLando

[robertsLando]

Does the map update magically once the command was completed

Nope ATM but I think he tried a refresh...

[Madelaide]

Thankyou. I’ll try this again when I am home.

Ps: I had trouble previously determining which log file I was meant to be checking. There is as no date stamp on the entries and it was unclear if the times were local or utc.

[Madelaide]

zwavejs2mqtt-store (9) 2.zip

I ran two heals at 7pm; one on node 6 which has many neighbours, one on node 137 which has 4, i did se the debug node filter to 6 and 137, and clicked save - which restarted the zw engine it seems. Anyway, the filter doesnt seem to work.

[AlCalzone]

I checked the code again - so far, healNode checks if a heal network process is active and exits otherwise.
This does make sense to cancel ongoing processes, but keeps you from actually healing single nodes. I'll have to change that.

[Madelaide]

zwavejs2mqtt-store (11) 2.zip

In this example, I ran a Heal on node 114 (fibaros pick up many nodes in my house) around 21:20, and then I turned off node 23 at around 21;22 - the latter is in the zwjs log, but node 114 has nothing in the last hour, and there is no Heal in the log

[Madelaide]

Oh I see you found the issue, great, well maybe the second log(s) help anyway.

[Madelaide]

PS: I put this on node-zwave-js it seems; should it have been on the other repo?

[AlCalzone]

I moved it here, since the problem lies here.

[Madelaide]

UPDATE: note I installed 2.4.1 today, the Heal node still behaves the same, zero heal information in the zwave log, no nodes updated.

Not sure if this is related...

Error: Not Found
at /opt/app.js:936:15
at Layer.handle [as handle_request] (/opt/node_modules/express/lib/router/layer.js:95:5)
at trim_prefix (/opt/node_modules/express/lib/router/index.js:317:13)
at /opt/node_modules/express/lib/router/index.js:284:7
at Function.process_params (/opt/node_modules/express/lib/router/index.js:335:12)
at next (/opt/node_modules/express/lib/router/index.js:275:10)
at /opt/node_modules/express-session/index.js:502:7
at readCallback (/opt/node_modules/session-file-store/lib/session-file-helpers.js:193:20)
at /opt/node_modules/graceful-fs/graceful-fs.js:123:16
at FSReqCallback.readFileAfterClose [as oncomplete] (internal/fs/read_file_context.js:63:3)

[AlCalzone]

What's the zwave-js version in 2.4.1?

[Madelaide]

There are many version numbers floating around the ui, hopefully this is one you requested:
Z-Wave JS to MQTT
Current version: 0.8.1 ( Changelog )

Changelog
What’s changed

⬆️ Dependency updates

Update database to ff8e408 @frenck (#92)
⬆️ Upgrades ZwaveJS2Mqtt to v2.4.1 @frenck (#91)
⬆️ Bump frenck/action-addon-linter from v2.0.0 to v2.1 @dependabot (#93)

or this

Network Connected
ws://a0d7b954-zwavejs2mqtt:3000
Driver Version: 6.6.3
Server Version: 1.2.1
Home ID: xxx
Nodes ready: 72 / 75

[AlCalzone]

Driver Version: 6.6.3

This is only fixed in v7.0.0, so you'll need to wait for that update.

[Madelaide]

I have installed the public update, and server version is 7.0.0.

Heal on node 124 does this and no more...

2021-04-01 08:00:23.662 INFO ZWAVE: Success zwave api call healNode { success: true, message: 'Success zwave api call', result: false }

PS: i have THREE zwave debug logs zwavejs_357/8/9 and NONE of them have a date in the logs, and none of them have any entries for this morning that I can see.

PLEASE add the date to the log!

[Madelaide]

PPS: these logs are 30, 70 and 15 MB each

[Madelaide]

I update HA today, the update with the yaml debugging, and now the log has a date, time looks to UTC and not local (ie the time now is 15:04)

2021-04-01T04:31:58.999Z CNTRLR [Node 023] [~] [Multilevel Switch] currentValue: 0 => 0 [Endpoint 0]
2021-04-01T04:31:59.010Z SERIAL « [ACK] (0x06)
2021-04-01T04:31:59.013Z SERIAL « 0x0104011301e8 (6 bytes)
2021-04-01T04:31:59.013Z SERIAL » [ACK] (0x06)
2021-04-01T04:31:59.013Z DRIVER « [RES] [SendData]
was sent: true
2021-04-01T04:32:03.175Z SERIAL « 0x01070013430101a109 (9 bytes)
2021-04-01T04:32:03.176Z SERIAL » [ACK] (0x06)
2021-04-01T04:32:03.176Z DRIVER « [REQ] [SendData]
callback id: 67
transmit status: NoAck
2021-04-01T04:32:04.016Z SERIAL » 0x01090013170226022544b5 (11 bytes)
2021-04-01T04:32:04.020Z SERIAL « [ACK] (0x06)
2021-04-01T04:32:04.026Z SERIAL « 0x0104011301e8 (6 bytes)
2021-04-01T04:32:04.027Z SERIAL » [ACK] (0x06)
2021-04-01T04:32:04.027Z DRIVER « [RES] [SendData]
was sent: true
2021-04-01T04:32:04.045Z SERIAL « 0x0107001344000003ac (9 bytes)
2021-04-01T04:32:04.046Z SERIAL » [ACK] (0x06)
2021-04-01T04:32:04.047Z DRIVER « [REQ] [SendData]
callback id: 68
transmit status: OK
2021-04-01T04:32:04.055Z SERIAL « 0x01090004001703260300c3 (11 bytes)

[AlCalzone]

I suggest you delete the old logs and try again. That way the logs should be smaller too.