Fibaro Wall Plug Issues

knutz · June 22, 2020, 1:44pm

Has anyone managed to get a Fibaro FGWPG111 UK Wall Plug to work properly without the need for polling?

I have tried everything I can think of to get this product to work with both the inbuilt zwave integration (OpenZWave 1.4) and the OpenZWave(beta) (1.6).
When the device is toggled in HASS, on rare occasions OpenZWave will indicate that the device has returned an expected callback and the Home Assistant toggle switch will stay in the correct position, but usually the toggle switch will revert after few seconds and remain there indicating a different state to the one that the actual device is in.
This can be “fixed” by enabling polling. This results in the toggle switch (and internal Home Assistant state for the device) only being wrong for up to a minute and much more ZWave traffic. However every time the device is toggled it reliably returns power usage data.

Has anyone managed to get HASS to reliably reflect the state of the device without resorting to polling? This is a modern device and so outside the patent issues and does on occasions work as it seems it should.

I have seen many posts online with people complaining about this behaviour but have found none with a resolution. So if you have this problem it would be nice to know I am not alone in this.

Thanks

knutz · June 22, 2020, 2:26pm

I should have said that I am using the latest HASSIO on a Pi3b and an Aeotec Z-Stick Gen 5 controller.

knutz · June 25, 2020, 8:42am

Following a suggestion by mezz64 in another thread I have added an automation that fires when OpenZWave (the MQTT version currently in beta) notifies HASS of a message timeout. The automation then requests all dynamic data from the node.

- alias: "Refresh Wall Plug"
  initial_state: True
  trigger:
  - platform: mqtt
    topic: "OpenZWave/1/event/notification/"
  condition:
    condition: template
    value_template: "{{ trigger.payload_json.Event == \"Notification_Code_MsgTimeout\" }}"
  action:
    data_template:
      topic: "OpenZWave/1/command/requestnodedynamic/"
      payload_template: "{{ trigger.payload.split(',')[0]|lower +'\n}' }}"
    service_template: mqtt.publish

The formation of the mqtt payload is ugly and could be improved by someone more adept than me, but it reliably works to reflect the correct state of any Wall Plug in Hass with this problem. It sends the request to the same node for which the original request timed out.
Hope this helps anyone that hits the same problem.

knutz · June 25, 2020, 5:28pm

Even though it is a bit of a monologue, I will continue to add information on this problem as I find it, in case it is of help to anyone else and maybe someone someday will find a fix, rather than a work around.

I set up a clean install of HASSIO using the latest code and the latest version of the qt-OpenZWave interface. Although qt-OpenZWave is in beta this problem has existed when using the integrated version of OpenZWave. qt-OpenZWave has the advantage of exposing the HASS OpenZWave interface to review over the many MQTT tools available as well as access to OZW-Admin. I have only tried this with an Aeotec Z-Stick Gen 5 controller.

The problem:

When a wall plug is turned on from HASS, the state would change in the GUI before dropping back to the old state within a second or two. HASS would then show an incorrect state for the wall plug. Switching it off again from the GUI would fail because as far as HASS was concerned it was already off.

Observations:

Configuring 3 wall plugs within a few meters of the Z-Stick on a clean build produced the problem on all of them. Occasionally one of them would work and the indication of the requested change of state would remain in place. This one happened to be the one that was furthest from the controller. Running HASS on a Pi with a very long Ethernet cable and power lead allowed me to test this without making any changes other than distance between controller and wall plug and it seems to confirm that, contrary to expectations, increasing the distance between the wall plug and the controller (10m + a wall or 2) makes it work reliably, bringing the controller back close (3m) and it would stop working. I have not as yet come up with any suggestions as to why this counter intuitive situation may arise.

Looking at the OZW-Admin OZW Logs the significant difference between when it works and when it doesn’t, seems to be a chunk of data received from the wall plug. These are received at the same point in the dialogue but differ in both content and length.

The first message is when it works and the second is the same wall plug when it doesn’t:

Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x02, 0x03, 0x25, 0x03, 0xff, 0x2a

Received: 0x01, 0x0a, 0x00, 0x04, 0x00, 0x02, 0x04, 0x22, 0x01, 0x01, 0x02, 0xd7

After receiving the first, OZW reports that the node is switched on, there is no similar report in the second case. Unfortunately I have not found details on how you decode this yet, but it looks like the 6th byte is the node number from examples from the 3 nodes. If anyone can decode this or point me in the right direction it would be fantastic.

After configuring the 3 wall plugs I tested the network with Aeon’s pc test software and it passed every node all with a latency sub 20ms. So there does not seem to be a fundamental z-wave issue.

Also when it is not working OZW times out waiting and it would appear that the wait times could be being added into the RTT values reported. There have been numerous reports in the forum of fibaro wall plug issues where the RTT values are high despite the close proximity and people have suggested it is a z-wave network issue. From my observations this does not appear to be the case and may be a case of misreporting RTT values by OZW. I have no evidence for this but could see how the wait time for a packet that does not arrive may not be excluded from RTT calculations.

Any suggestions for next steps?

Fishwaldo · June 26, 2020, 8:28am

See this:

knutz · June 29, 2020, 7:47am

Thanks for pointing me in the right direction. I am using the add on so will need to change that so I test it.
Thanks again

knutz · July 2, 2020, 1:29pm

I am struggling with the suggestion of @Fishwaldo, but will persevere.
In the mean time a new automation to correct the incorrect status as quickly as possible with less impact on the zwave platform than my previous suggestion above, again based on a suggestion elsewhere by @Fishwaldo:

- alias: "Refresh Wall Plug"
  initial_state: True
  trigger:
  - platform: mqtt
    topic: "OpenZWave/1/command/setvalue/"
  action:
    - delay:
        milliseconds: 200
    - service_template: mqtt.publish
      data_template:
        topic: "OpenZWave/1/command/refreshvalue/"
        payload_template: "{{ trigger.payload.split(',')[0] +'\n}' }}"

This picks up any z-wave setvalue command and queues a refresh value for it. The limitations of it are:

it will run for any device, not just a Wall Plug, but it is fairly lightweight.
It is still not very fast, I assume because it is queued until the set value fully completes, including waiting for the setvalue command timeout error.

It would probably be just as fast and more efficient to trigger on the “Notification_Code_MsgTimeout” as in my first suggested automation but issue the refreshvalue command as per the automation above. The additional complication with this though is the error returns a node number but the refreshvalue requires a ValueIDKey. This would either require a translation of node to ValueIDKey hardcoded in the automation or a lookup in a system table somewhere.

knutz · July 2, 2020, 5:57pm

I have tried adding the CommandClass id=“38” fix into the xml file for the device and it has made no difference. I thought I must be doing something wrong but going through the same steps on a friends system with an old dimmer and it works just as suggested.

The problem I have is not that an interim or wrong value is being returned in a valid message by the Wall Plug, but rather the message itself is either not valid or not being recognised as valid by OZW. This then results in a message timeout rather than a series of requests for the value until a constant value is returned.
Here is a section of the ozwdaemon output (with popping Log Mesages and RTT response messages removed for brevity)

1. [ozw.mqtt.commands] [debug]: Got  "OpenZWave/1/command/setvalue/"  Message:  "{\"ValueIDKey\": 38354960, \"Value\": true}"
2. [ozw.mqtt.commands.setValue] [info]: Setting  38354960  to Value  QVariant(bool, true)
3. [ozw.values] [debug]: setData Called for Row 12  With Value QVariant(bool, true)
4. [ozw.values] [debug]: valueModel Changed! QTOZW_ValueIds::Value - 12 :  QVariant(bool, true)
5. [ozw.values] [debug]: valueModel Changed! vidKey: 38354960 QVariant(bool, true)
6. [ozw.library] [info]: Info - Node: 2 Value::Set - COMMAND_CLASS_SWITCH_BINARY - Switch - 0 - 1 - True
7. [ozw.library] [info]: Info - Node: 2 SwitchBinary::Set - Setting to On
8. [ozw.library] [debug]: Detail - Node: 2 Queuing (Send) SwitchBinaryCmd_Set (Node=2): 0x01, 0x0a, 0x00, 0x13, 0x02, 0x03, 0x25, 0x01, 0xff, 0x25, 0xd2, 0xcb
9. [ozw.library] [debug]: Detail - Node: 2 Queuing (Send) SwitchBinaryCmd_Get (Node=2): 0x01, 0x09, 0x00, 0x13, 0x02, 0x02, 0x25, 0x02, 0x25, 0xd3, 0x34
10. [ozw.library] [info]: Info - Node: 2 Sending (Send) message (Callback ID=0xd2, Expected Reply=0x13) - SwitchBinaryCmd_Set (Node=2): 0x01, 0x0a, 0x00, 0x13, 0x02, 0x03, 0x25, 0x01, 0xff, 0x25, 0xd2, 0xcb
11. [ozw.mqtt.commands] [info]: Processed Message for  "setvalue" :  "{\"ValueIDKey\": 38354960, \"Value\": true}"
12. [ozw.library] [info]: Info - Node: 2 Encrypted Flag is 0
13. [ozw.library] [debug]: Detail - Node: 2   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
14. [ozw.library] [debug]: Detail - Node: 2   ZW_SEND_DATA delivered to Z-Wave stack
15. [ozw.library] [debug]: Detail - Node: 2   Received: 0x01, 0x07, 0x00, 0x13, 0xd2, 0x00, 0x00, 0x03, 0x3a
16. [ozw.library] [debug]: Detail - Node: 2   ZW_SEND_DATA Request with callback ID 0xd2 received (expected 0xd2)
17. [ozw.library] [debug]: Detail - Node: 2   Expected callbackId was received
18. [ozw.library] [debug]: Detail - Node: 2   Expected reply was received
19. [ozw.library] [debug]: Detail - Node: 2   Message transaction complete
20. [ozw.library] [debug]: Detail - Node: 2 Removing current message
21. [ozw.library] [info]: Info - Node: 2 Sending (Send) message (Callback ID=0xd3, Expected Reply=0x04) - SwitchBinaryCmd_Get (Node=2): 0x01, 0x09, 0x00, 0x13, 0x02, 0x02, 0x25, 0x02, 0x25, 0xd3, 0x34
22. [ozw.library] [info]: Info - Node: 2 Encrypted Flag is 0
23. [ozw.library] [debug]: Detail - Node: 2   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
24. [ozw.library] [debug]: Detail - Node: 2   ZW_SEND_DATA delivered to Z-Wave stack
25. [ozw.library] [debug]: Detail - Node: 2   Received: 0x01, 0x07, 0x00, 0x13, 0xd3, 0x00, 0x00, 0x02, 0x3a
26. [ozw.library] [debug]: Detail - Node: 2   ZW_SEND_DATA Request with callback ID 0xd3 received (expected 0xd3)
27. [ozw.library] [debug]: Detail - Node: 2   Expected callbackId was received
28. [ozw.library] [debug]: Detail - Node: 2   Received: 0x01, 0x0a, 0x00, 0x04, 0x00, 0x02, 0x04, 0x22, 0x01, 0x01, 0x02, 0xd7
29. [ozw.library] [debug]: Detail - Node: 2   Received: 0x01, 0x10, 0x00, 0x04, 0x00, 0x02, 0x0a, 0x32, 0x02, 0x21, 0x32, 0x00, 0x3f, 0x00, 0x00, 0x00, 0x00, 0xff
30. [ozw.library] [info]: Info - Node: 2 Received Meter Report for Electric - W (1) with Units W (2) on Index 2: 6.3
31. [ozw.library] [debug]: Detail - Node: 2 Refreshed Value: old value=0.0, new value=6.3, type=decimal
32. [ozw.library] [debug]: Detail - Node: 2 Changes to this value are not verified
33. [ozw.library] [debug]: Detail - Node: 2 Refreshed Value: old value=false, new value=false, type=bool
34. [ozw.library] [debug]: Detail - Node: 2 Changes to this value are not verified
35. [ozw.library] [debug]: Detail - Node: 2 Notification: ValueChanged CC: COMMAND_CLASS_METER Instance: 1 Index: 2
36. [ozw.library] [debug]: Detail - Node: 2 Notification: ValueChanged CC: COMMAND_CLASS_METER Instance: 1 Index: 256
37. [ozw.notifications] [debug]: Notification pvt_valueChanged:  562949991989266 Thread:  0x76fbb410
38. [ozw.mqtt.publisher] [debug]: Publishing Event valueChanged: 562949991989266
39. [ozw.notifications] [debug]: Notification pvt_valueChanged:  72057594076495888 Thread:  0x76fbb410
40. [ozw.library] [critical]: Error - Node: 2 ERROR: Dropping command, expected response not received after 1 attempt(s). Command: "SwitchBinaryCmd_Get (Node=2): 0x01, 0x09, 0x00, 0x13, 0x02, 0x02, 0x25, 0x02, 0x25, 0xd3, 0x34"
41. [ozw.library] [debug]: Detail - Node: 2 Removing current message
42. [ozw.library] [debug]: Detail - Node: 2 Notification: Notification - TimeOut
43. [ozw.notifications] [debug]: Notification pvt_ozwNotification NotificationTypes::Notification_Code_MsgTimeout Thread:  0x76fbb410
44. [ozw.mqtt.publisher] [debug]: Publishing Event ozwNotification

Line 40 shows the error raised because OZW does not think it has received a response to the SwitchBinaryCmd_Get requested in line 9.
The response OZW did receive and did not recognise as a response is on line 28, starting 0x01, 0x0a, rather than the expected 0x01, 0x09.

Any suggestions for what is causing this and how I may fix it, or investigate further would be very welcome.
Thanks again

freshcoast · July 3, 2020, 12:14am

I don’t have an answer for your problem, but I can clarify the logging. Line 28 is an unsolicited message for the Application Status Command Class, and OZW does not handle that class in any particular way. It’s unrelated to the Switch Binary commands.

0x25, 0x02 in line 21 are the bytes that represent the Switch Binary Get command. The response to that would be the Switch Binary Report command which would contain bytes 0x25, 0x03, and as you can see that was never received.

freshcoast · July 3, 2020, 12:19am

I could be wrong about that. It might be saying the node is busy.

knutz · July 3, 2020, 6:19pm

Thanks for taking the time to help.
Can I just confirm that I have understood you correctly with a couple of sections of logs below. The first is a failed interaction with the Wall Plug close to the controller (3m & 1 drywall), and the second is a successful interaction with the same Wall Plug at a distance (12m & 3 drywalls). After moving it away. I did not heal the network but in the past I have and it would still work.

Up to and including line 27 the interaction is identical in both, except for the last 2 bytes of the hex strings which are the callback id and possibly a checksum (but I am guessing at that). The callback id also at byte 5 of the callback messages. So the callbacks for the SwitchBinaryCmd_Set and SwitchBinaryCmd_Get are reported as being successful in both cases but it is the next message from the Wall Plug that is different (line 28).
Are you saying that line 28 on the good interaction:

Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x02, 0x03, 0x25, 0x03, 0xff, 0x2a

is the Switch Binary Report, and the 0x25, 0x03 at bytes 8 & 9 are those that you refer to and define it as such?
And that because the same line in the failed interaction:

Received: 0x01, 0x0a, 0x00, 0x04, 0x00, 0x02, 0x04, 0x22, 0x01, 0x01, 0x02, 0xd7

does not have 0x25, 0x03 towards the end, it is some other unsolicited message.

It would be a great help if you can confirm that I have understood this correctly and if I haven’t please set me straight.
It would also be a great help if you can point me at a source of information to decode the unsolicited response, but I am beginning to think no such source is available.
With regard to the node being busy, in both cases the node sends out a Meter Report as the next message, but that is about 3 seconds after line 28, and the gap similar in both cases.,
Thanks again!

Failed interaction

1. [ozw.mqtt.commands] [debug]: Got  "OpenZWave/1/command/setvalue/"  Message:  "{\"ValueIDKey\": 38354960, \"Value\": true}"
2. [ozw.mqtt.commands.setValue] [info]: Setting  38354960  to Value  QVariant(bool, true)
3. [ozw.values] [debug]: setData Called for Row 12  With Value QVariant(bool, true)
4. [ozw.values] [debug]: valueModel Changed! QTOZW_ValueIds::Value - 12 :  QVariant(bool, true)
5. [ozw.values] [debug]: valueModel Changed! vidKey: 38354960 QVariant(bool, true)
6. [ozw.library] [info]: Info - Node: 2 Value::Set - COMMAND_CLASS_SWITCH_BINARY - Switch - 0 - 1 - True
7. [ozw.library] [info]: Info - Node: 2 SwitchBinary::Set - Setting to On
8. [ozw.library] [debug]: Detail - Node: 2 Queuing (Send) SwitchBinaryCmd_Set (Node=2): 0x01, 0x0a, 0x00, 0x13, 0x02, 0x03, 0x25, 0x01, 0xff, 0x25, 0xd9, 0xc0
9. [ozw.library] [debug]: Detail - Node: 2 Queuing (Send) SwitchBinaryCmd_Get (Node=2): 0x01, 0x09, 0x00, 0x13, 0x02, 0x02, 0x25, 0x02, 0x25, 0xda, 0x3d
10. [ozw.library] [info]: Info - Node: 2 Sending (Send) message (Callback ID=0xd9, Expected Reply=0x13) - SwitchBinaryCmd_Set (Node=2): 0x01, 0x0a, 0x00, 0x13, 0x02, 0x03, 0x25, 0x01, 0xff, 0x25, 0xd9, 0xc0
11. [ozw.mqtt.commands] [info]: Processed Message for  "setvalue" :  "{\"ValueIDKey\": 38354960, \"Value\": true}"
12. [ozw.library] [info]: Info - Node: 2 Encrypted Flag is 0
13. [ozw.library] [debug]: Detail - Node: 2   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
14. [ozw.library] [debug]: Detail - Node: 2   ZW_SEND_DATA delivered to Z-Wave stack
15. [ozw.library] [debug]: Detail - Node: 2   Received: 0x01, 0x07, 0x00, 0x13, 0xd9, 0x00, 0x00, 0x02, 0x30
16. [ozw.library] [debug]: Detail - Node: 2   ZW_SEND_DATA Request with callback ID 0xd9 received (expected 0xd9)
17. [ozw.library] [debug]: Detail - Node: 2   Expected callbackId was received
18. [ozw.library] [debug]: Detail - Node: 2   Expected reply was received
19. [ozw.library] [debug]: Detail - Node: 2   Message transaction complete
20. [ozw.library] [debug]: Detail - Node: 2 Removing current message
21. [ozw.library] [info]: Info - Node: 2 Sending (Send) message (Callback ID=0xda, Expected Reply=0x04) - SwitchBinaryCmd_Get (Node=2): 0x01, 0x09, 0x00, 0x13, 0x02, 0x02, 0x25, 0x02, 0x25, 0xda, 0x3d
22. [ozw.library] [info]: Info - Node: 2 Encrypted Flag is 0
23. [ozw.library] [debug]: Detail - Node: 2   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
24. [ozw.library] [debug]: Detail - Node: 2   ZW_SEND_DATA delivered to Z-Wave stack
25. [ozw.library] [debug]: Detail - Node: 2   Received: 0x01, 0x07, 0x00, 0x13, 0xda, 0x00, 0x00, 0x02, 0x33
26. [ozw.library] [debug]: Detail - Node: 2   ZW_SEND_DATA Request with callback ID 0xda received (expected 0xda)
27. [ozw.library] [debug]: Detail - Node: 2   Expected callbackId was received
28. [ozw.library] [debug]: Detail - Node: 2   Received: 0x01, 0x0a, 0x00, 0x04, 0x00, 0x02, 0x04, 0x22, 0x01, 0x01, 0x02, 0xd7

29. [ozw.library] [critical]: Error - Node: 2 ERROR: Dropping command, expected response not received after 1 attempt(s). Command: "SwitchBinaryCmd_Get (Node=2): 0x01, 0x09, 0x00, 0x13, 0x02, 0x02, 0x25, 0x02, 0x25, 0xda, 0x3d"
30. [ozw.library] [debug]: Detail - Node: 2 Removing current message
31. [ozw.library] [debug]: Detail - Node: 2 Notification: Notification - TimeOut
32. [ozw.notifications] [debug]: Notification pvt_ozwNotification NotificationTypes::Notification_Code_MsgTimeout Thread:  0x76f2e410

Good Interaction

1. [ozw.mqtt.commands] [debug]: Got  "OpenZWave/1/command/setvalue/"  Message:  "{\"ValueIDKey\": 38354960, \"Value\": true}"
2. [ozw.mqtt.commands.setValue] [info]: Setting  38354960  to Value  QVariant(bool, true)
3. [ozw.values] [debug]: setData Called for Row 12  With Value QVariant(bool, true)
4. [ozw.values] [debug]: valueModel Changed! QTOZW_ValueIds::Value - 12 :  QVariant(bool, true)
5. [ozw.values] [debug]: valueModel Changed! vidKey: 38354960 QVariant(bool, true)
6. [ozw.library] [info]: Info - Node: 2 Value::Set - COMMAND_CLASS_SWITCH_BINARY - Switch - 0 - 1 - True
7. [ozw.library] [info]: Info - Node: 2 SwitchBinary::Set - Setting to On
8. [ozw.library] [debug]: Detail - Node: 2 Queuing (Send) SwitchBinaryCmd_Set (Node=2): 0x01, 0x0a, 0x00, 0x13, 0x02, 0x03, 0x25, 0x01, 0xff, 0x25, 0xe1, 0xf8
9. [ozw.library] [debug]: Detail - Node: 2 Queuing (Send) SwitchBinaryCmd_Get (Node=2): 0x01, 0x09, 0x00, 0x13, 0x02, 0x02, 0x25, 0x02, 0x25, 0xe2, 0x05
10. [ozw.library] [info]: Info - Node: 2 Sending (Send) message (Callback ID=0xe1, Expected Reply=0x13) - SwitchBinaryCmd_Set (Node=2): 0x01, 0x0a, 0x00, 0x13, 0x02, 0x03, 0x25, 0x01, 0xff, 0x25, 0xe1, 0xf8
11. [ozw.mqtt.commands] [info]: Processed Message for  "setvalue" :  "{\"ValueIDKey\": 38354960, \"Value\": true}"
12. [ozw.library] [info]: Info - Node: 2 Encrypted Flag is 0
13. [ozw.library] [debug]: Detail - Node: 2   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
14. [ozw.library] [debug]: Detail - Node: 2   ZW_SEND_DATA delivered to Z-Wave stack
15. [ozw.library] [debug]: Detail - Node: 2   Received: 0x01, 0x07, 0x00, 0x13, 0xe1, 0x00, 0x00, 0x31, 0x3b
16. [ozw.library] [debug]: Detail - Node: 2   ZW_SEND_DATA Request with callback ID 0xe1 received (expected 0xe1)
17. [ozw.library] [debug]: Detail - Node: 2   Expected callbackId was received
18. [ozw.library] [debug]: Detail - Node: 2   Expected reply was received
19. [ozw.library] [debug]: Detail - Node: 2   Message transaction complete
20. [ozw.library] [debug]: Detail - Node: 2 Removing current message
21. [ozw.library] [info]: Info - Node: 2 Sending (Send) message (Callback ID=0xe2, Expected Reply=0x04) - SwitchBinaryCmd_Get (Node=2): 0x01, 0x09, 0x00, 0x13, 0x02, 0x02, 0x25, 0x02, 0x25, 0xe2, 0x05
22. [ozw.library] [info]: Info - Node: 2 Encrypted Flag is 0
23. [ozw.library] [debug]: Detail - Node: 2   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
24. [ozw.library] [debug]: Detail - Node: 2   ZW_SEND_DATA delivered to Z-Wave stack
25. [ozw.library] [debug]: Detail - Node: 2   Received: 0x01, 0x07, 0x00, 0x13, 0xe2, 0x00, 0x00, 0x3b, 0x32
26. [ozw.library] [debug]: Detail - Node: 2   ZW_SEND_DATA Request with callback ID 0xe2 received (expected 0xe2)
27. [ozw.library] [debug]: Detail - Node: 2   Expected callbackId was received
28. [ozw.library] [debug]: Detail - Node: 2   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x02, 0x03, 0x25, 0x03, 0xff, 0x2a
29. [ozw.library] [info]: Info - Node: 2 Received SwitchBinary report from node 2: level=On
30. [ozw.library] [debug]: Detail - Node: 2 Refreshed Value: old value=false, new value=true, type=bool
31. [ozw.library] [debug]: Detail - Node: 2 Changes to this value are not verified
32. [ozw.library] [debug]: Detail - Node: 2   Expected reply and command class was received
33. [ozw.library] [debug]: Detail - Node: 2   Message transaction complete
34. [ozw.library] [debug]: Detail - Node: 2 Removing current message
35. [ozw.library] [debug]: Detail - Node: 2 Notification: ValueChanged CC: COMMAND_CLASS_SWITCH_BINARY Instance: 1 Index: 0
36. [ozw.notifications] [debug]: Notification pvt_valueChanged:  38354960 Thread:  0x76f2e410
37. [ozw.mqtt.publisher] [debug]: Publishing Event valueChanged: 38354960
38. [ozw.library] [debug]: Detail - Node: 2   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x02, 0x03, 0x25, 0x03, 0xff, 0x2a
39. [ozw.library] [info]: Info - Node: 2 Received SwitchBinary report from node 2: level=On
40. [ozw.library] [debug]: Detail - Node: 2 Refreshed Value: old value=true, new value=true, type=bool
41. [ozw.library] [debug]: Detail - Node: 2 Changes to this value are not verified
42. [ozw.library] [debug]: Detail - Node: 2 Notification: ValueChanged CC: COMMAND_CLASS_SWITCH_BINARY Instance: 1 Index: 0
43. [ozw.notifications] [debug]: Notification pvt_valueChanged:  38354960 Thread:  0x76f2e410

freshcoast · July 3, 2020, 7:47pm

Yes, this is Binary Switch Command Class (0x25), command Binary Switch Report (0x03), with value 100% On (0xff).

28. [ozw.library] [debug]: Detail - Node: 2   Received: 0x01, 0x0a, 0x00, 0x04, 0x00, 0x02, 0x04, 0x22, 0x01, 0x01, 0x02, 0xd7

I believe this is a message for Application Status Command Class (0x22), command Application Busy (0x01), with status “Try again in 2 seconds”.

You can view the source code to see how OZW is parsing the message payloads. If you look further, you’ll see that the Application Status Command class is not handled, at least that was my view.

The public Z-Wave spec is available here. There are documents that describe all of the command classes.

The ZWave 500 Programmers Guide and the Serial API Programming Guide also seem to be public now. Those describe the format of the data frames, which is what OZW is printing for the “Received” logs. The entire (?) set of published Z-Wave docs is here.

knutz · July 4, 2020, 3:40pm

Thank you, Thank you, Thank you @freshcoast
That would all make sense. And looking in the logs at the time between OZW sending out the SwitchBinaryCmd_Set and the SwitchBinaryCmd_Get, is 0.5 of a second in the case that works and 0.1 of a second in the case that doesn’t. So the Wall Plug has potentially much more time to be ready to service the get command.
Now I guess the next question is for @fishwaldo if I am not being too presumptuous, “Can the OZW team add in the Application Status Command Class, at least Application Busy?”. It is not likely that the application busy feature is only implemented in one device from one manufacturer. Would it be best for me to open a bug report or feature request somewhere?

Thanks again!

Fishwaldo · July 6, 2020, 11:09am

It will only happen when we get to implementing S2 Support - To handle it right now is not possible.

S2 is planned for 1.8 timeframe…

knutz · July 6, 2020, 3:37pm

Ok, thanks.
Something to look forward to.

Olen · August 23, 2020, 9:51am

I have a bunch of fibaro devices (no uk wall plugs though, onlye eu versions). And before switching to qt-ozw they worked fine.
After the switch, more often than not HA does not receive the updates, and the state of the actual switches and lights, and what HA shows, will go out of sync.
I have now added the fix-automations from this thread to see if it helps.
So far, I have not been able to check if it is HA that don’t parse the events from MQTT correctly, or if it is my Zwave-stack (and qt-openzwave) that either misses some packets, or are unable to push them to MQTT.

However, I also have an issue where restarting ozw takes more than two minutes, leading to a mqtt timeout on startup almost every time, so I don’t want to play to much with the zwave network until that is fixed.

tung256 · November 27, 2020, 8:49pm

i have the exact setup as you with the rpi3 and zwave stick and the this fibaro zwave plug.
so what’s the easiest solution?

knutz · November 30, 2020, 1:17am

Hi, OZW development plans include enhancements that will hopefully address this issue in the future but until then I am using the code below in automations.yaml.
The code is a bit ugly but I think it should work for any device without any customisation on your part. It does request a refresh value for all ZWave devices after they have been set to a new value so if you have a lot of them it may impact your performance. If you have problems let me know and I can try and help.
Good Luck

#---WALL PLUG REFRESH---------------------------------------

- alias: "Refresh Wall Plug"
  initial_state: True
  trigger:
  - platform: mqtt
    topic: "OpenZWave/1/command/setvalue/"
  action:
    - delay:
        milliseconds: 200
    - service_template: mqtt.publish
      data_template:
        topic: "OpenZWave/1/command/refreshvalue/"
        payload_template: "{{ trigger.payload.split(',')[0] +'\n}' }}"

zemos · December 6, 2020, 1:46pm

Hi @knutz. I have added your code to my automations.yaml but it gives me

String does not match the pattern of “DEPRECATED^”

at line: - service_template: mqtt.publish

When I run this automation, I receive error:

Refresh Wall Plug: Error executing script. Unexpected error for call_service at pos 2: Error rendering data template: UndefinedError: 'trigger' is undefined
While executing automation automation.refresh_wall_plug_2
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/template.py", line 353, in async_render
    render_result = compiled.render(kwargs)
  File "/usr/local/lib/python3.8/site-packages/jinja2/environment.py", line 1090, in render
    self.environment.handle_exception()
  File "/usr/local/lib/python3.8/site-packages/jinja2/environment.py", line 832, in handle_exception
    reraise(*rewrite_traceback_stack(source=source))
  File "/usr/local/lib/python3.8/site-packages/jinja2/_compat.py", line 28, in reraise
    raise value.with_traceback(tb)
  File "<template>", line 1, in top-level template code
  File "/usr/local/lib/python3.8/site-packages/jinja2/sandbox.py", line 407, in getattr
    value = getattr(obj, attribute)
jinja2.exceptions.UndefinedError: 'trigger' is undefined

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 144, in async_prepare_call_from_config
    service_data.update(template.render_complex(config[conf], variables))
  File "/usr/src/homeassistant/homeassistant/helpers/template.py", line 93, in render_complex
    return {
  File "/usr/src/homeassistant/homeassistant/helpers/template.py", line 94, in <dictcomp>
    render_complex(key, variables): render_complex(item, variables)
  File "/usr/src/homeassistant/homeassistant/helpers/template.py", line 98, in render_complex
    return value.async_render(variables)
  File "/usr/src/homeassistant/homeassistant/helpers/template.py", line 355, in async_render
    raise TemplateError(err) from err
homeassistant.exceptions.TemplateError: UndefinedError: 'trigger' is undefined

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 253, in _async_step
    await getattr(
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 432, in _async_call_service_step
    domain, service, service_data = async_prepare_call_from_config(
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 146, in async_prepare_call_from_config
    raise HomeAssistantError(f"Error rendering data template: {ex}") from ex
homeassistant.exceptions.HomeAssistantError: Error rendering data template: UndefinedError: 'trigger' is undefined
Connection lost. Reconnecting…

knutz · December 10, 2020, 8:34am

Hi, The short answer is I do not know why you are getting this error.
But the code I posted will work with only one of the many ways of running Open Z-Wave. It will only work if you are using the new OpenZWave Add-on and OpenZWave (beta) Integration, that communicate via MQTT.
I have not followed it myself but I found this post describing the setup.
https://community.home-assistant.io/t/get-openzwave-beta-working/200121
If you do not recognise the steps involved then my code will be of no use to you.
Good Luck