Z-Wave Refresh command seems to do nothing

After switching to OH3 I noticed that the “REFRESH” command does not seem to do anything any more.
I have a Fibaro Outlet switch which doesn’t report its state automatically.
After sending a command to the device I send a refresh because it doesn’t update the state.
However I noticed that there is no update (ItemStateEvent) from the device.

2021-10-19 11:34:25.344 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'FibaroFGWPv1' received command REFRESH
2021-10-19 11:35:29.029 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'FibaroFGWPv1' received command ON
2021-10-19 11:35:29.052 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'FibaroFGWPv1' received command REFRESH
2021-10-19 11:35:46.589 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'FibaroFGWPv1' received command OFF
2021-10-19 11:35:46.611 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'FibaroFGWPv1' received command REFRESH
2021-10-19 11:37:38.856 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'FibaroFGWPv1' received command ON
2021-10-19 11:37:38.878 [INFO ] [openhab.event.ItemCommandEvent      ] - Item 'FibaroFGWPv1' received command REFRESH

Edit:
I discovered in the z-wave log that the device does not poll because it the initialization is incomplete.
Which is strange because it is a mains powered device. I would have expected it to finish without problems.
I’ve tried to heal the device and and a power cycle but it does nothing.

2021-10-19 11:59:44.173 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Command received zwave:device:controller:node16:switch_binary --> OFF [OnOffType]
2021-10-19 11:59:44.174 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 16: Creating new message for application command SWITCH_BINARY_SET
2021-10-19 11:59:44.175 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 16: SECURITY not supported
2021-10-19 11:59:44.176 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 16: Command Class COMMAND_CLASS_SWITCH_BINARY is NOT required to be secured
2021-10-19 11:59:44.176 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: Adding to device queue
2021-10-19 11:59:44.177 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: Added 177357 to queue - size 41
2021-10-19 11:59:44.179 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 16: Sending REQUEST Message = 01 0A 00 13 10 03 25 01 00 25 9E 6A 
2021-10-19 11:59:44.181 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Polling initialised at 1800 seconds - start in 1500 milliseconds.
2021-10-19 11:59:44.192 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 16: sentData successfully placed on stack.
2021-10-19 11:59:44.193 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: TID 177357: Transaction not completed
2021-10-19 11:59:44.199 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Command received zwave:device:controller:node16:switch_binary --> REFRESH [RefreshType]
2021-10-19 11:59:44.199 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Polling initialised at 1800 seconds - start in 50 milliseconds.
2021-10-19 11:59:44.207 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 16: SendData Request. CallBack ID = 158, Status = Transmission complete and ACK received(0)
2021-10-19 11:59:44.208 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: Response processed after 28ms
2021-10-19 11:59:44.208 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: TID 177357: Transaction completed
2021-10-19 11:59:44.208 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 16: notifyTransactionResponse TID:177357 DONE
2021-10-19 11:59:44.209 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2021-10-19 11:59:44.250 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Polling...
2021-10-19 11:59:44.250 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Polling deferred until initialisation complete

Edit2:
Network heal can not be started:

2021-10-19 12:12:29.130 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Configuration update set action_heal to true (Boolean)
2021-10-19 12:12:29.130 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Starting heal on node!
2021-10-19 12:12:29.130 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 16: Can not start heal as initialisation is not complete (SUC_ROUTE).

Edit3:
I tried removing and re-adding the thing, but it changes nothing.

@chris
Any idea how I can fix the SUC_ROUTE?

The REFRESH should work fine. Without knowing exactly what device, or more importantly what channel, isn’t working, it’s really hard to comment on what is happening.

I’d need to see a debug log, but SUC_ROUTE is part of the heal that is performed when the binding starts, so this is fine. I can’t comment on what is happening though without a debug log - sorry.

I recently had a problem after a OH restart with a mains powered device that did not fully reinitialize. I tried unplugging/replugging, deleting and refinding the thing etc… I ended up restarting OH and it reinitialized.

I powered down my machine and restarted it multiple times but no success.

It’s a Fibaro FGWP101 and I am sending the refresh to the switch channel.

Classic:
While it was not working yesterday this morning it seems to work fine.
Sorry to have bothered you.

Just for the future: What part of the debug log do you need? Everything from an openhab start or just the part where I send the command and the refresh?

The part showing the problem :slight_smile:

So if there was a problem (or question) with the initialisation I would need to see that - ie you asked about “how to fix the SUC_ROUTE” during initialisation so that the device completed init.

The main issue is that I am not competent enough to pinpoint the issue exactly, so I don’t know where to look. :slight_smile:

Openhab uptime was > 1 month and the last successful heal of the device was ~ 1 month ago.
If you need the logs from the device initialization I need to shutdown/restart openhab so the log contains the appropriate entries.


One other thing I noticed:
The device has a parameter (70) which is/should be set to 65535 as a default.
Sometimes it would render as -1 in the Thing view and I had to manually change it to 65535 before I could start the heal (because values < 0 are not allowed).
I have another FGWP101 which still shows it like that.

grafik

grafik

How can I fix this? I have to change it to 65535 every time before I can click on heal/reinitialize etc.

See, now I have a different problem. I’m (arguably!) competent to find the problem, but often I don’t have all the other information about the system to be able to say where to look :slight_smile: .

I guess in this case it’s still running a heal at 2am (or whenever) and that is failing, so getting a log of that failure would be good. Or it might still be officially initialising as these steps fail during initialisation, so maybe restarting the binding would show me why it’s failing.

It’s not an easy answer at times - hence my sort of tongue in cheek answer that I need to see the log that shows the problem :slight_smile: . Obviously this is exactly what I need to see - but exactly what that is can be hard to determine.

This is a printing issue I think. 65535 is also -1 if the value is 16 bits long, so probably this is the same thing printed in a different way.

Got it - I’ll try to provide these logs next time.

It’s not only a printing issue, one time the value is interpreted as a signed integer and one time as a unsigned integer. I checked the node.xml and these show different values (both devices are zwave:fibaro_fgwp101_00_000 with the same firmware version)
I already tried reinitializing the device but it still results in -1.

<entry>
  <int>70</int>
  <configurationParameter>
    <index>70</index>
    <size>2</size>
    <value>65535</value>
    <readOnly>false</readOnly>
    <writeOnly>false</writeOnly>
  </configurationParameter>
</entry>
<entry>
  <int>70</int>
  <configurationParameter>
    <index>70</index>
    <size>2</size>
    <value>-1</value>
    <readOnly>false</readOnly>
    <writeOnly>false</writeOnly>
  </configurationParameter>
</entry>

Any idea how I can fix this?

So this looks well in hand.

However, I thought I might add a little background to when the OH restart solved my one-time issue. The powered device in question is at the far reaches of my house (actually outside) and has only a few neighbors. It was still providing readings and showing online, just stuck in an “initialization from file” step (not sure which one). After my unsuccessful attempts noted above, using the Zniffer I ID’ed the nodes on the route back to the controller and healed the individual devices along that path before restarting. My thought was the initialization was taking too long with slow (and multi-hop) routes and eventually timed out. I also have the Heal disabled, so I was sure my situation happened during a restart.

Bob

I’ve got another node (NODE 52) that shows the same behavior.
The last successful heal was 2021-10-23T14:54:39Z so it’s not a startup/initialization issue.
The device is available to the controller via 1 hop, so maybe things get tricky because of that.
I’ve aggregated the logfiles since then and I’ll pm you a download link since I can’t upload huge files here.


Any idea how to fix the signed/unsigned issue ?

Hm - the behavior seems to be consistent. Sometimes the network heal gets stuck and the refresh does not work any more. Is there any technical reason why the refresh gets rejected?