Zwave Timeout Error Response, R504

[stanleywoon]

Hi, I still getting timeout response for Fibaro FGS211 Relay switch after update to R504. Controller is Aeon Z-stick, it is working on 1.0 R491 before. Logs is displayed as below:

2015-11-30 04:35:09.5581 Info WebServiceGateway   10.0.0.11   HTTP   GET   200 /api/HomeAutomation.ZWave/4/Control.On/null/ [OPEN]
2015-11-30 04:35:09.5581 Debug ZWaveMessage (RawData=01-0A-00-13-04-03-20-01-FF-05-06-3C)
2015-11-30 04:35:09.5581 Debug ZWaveMessage (Direction=Outbound, Header=SOF, NodeId=4, Type=Request, Function=SendData, CommandClass=Basic, CallbackId=6, CallbackStatus=NotSet)
2015-11-30 04:35:09.5581 Info HomeAutomation.ZWave   4   ZWave Node   Status.Level   1
2015-11-30 04:35:09.5656 Info WebServiceGateway   10.0.0.11   HTTP   GET   200 /api/HomeAutomation.ZWave/4/Control.On/null/ [CLOSED AFTER 0.007 seconds]
2015-11-30 04:35:09.7507 Trace [[[ BEGIN REQUEST ]]]
2015-11-30 04:35:09.7507 Trace WaitAck
2015-11-30 04:35:09.7512 Trace Sending Message (Node=4, CallbackId=06, Function=SendData, CommandClass=Basic)
2015-11-30 04:35:09.7512 Debug 01-0A-00-13-04-03-20-01-FF-05-06-3C
2015-11-30 04:35:09.8098 Debug 06-01-04-01-13-01-E8
2015-11-30 04:35:09.8098 Debug ZWaveMessage (RawData=01-04-01-13-01-E8)
2015-11-30 04:35:09.8098 Debug ZWaveMessage (Direction=Inbound, Header=SOF, NodeId=0, Type=Response, Function=SendData, CommandClass=NotSet)
2015-11-30 04:35:09.8098 Debug 06
2015-11-30 04:35:09.8098 Trace SendDataReady
2015-11-30 04:35:09.9113 Debug 01-05-00-13-06-01-EE
2015-11-30 04:35:09.9113 Debug ZWaveMessage (RawData=01-05-00-13-06-01-EE)
2015-11-30 04:35:09.9113 Debug ZWaveMessage (Direction=Inbound, Header=SOF, NodeId=0, Type=Request, Function=SendData, CommandClass=NotSet)
2015-11-30 04:35:09.9113 Debug 06
2015-11-30 04:35:09.9113 Trace Error
2015-11-30 04:35:09.9113 Trace [[[ END REQUEST ]]] took 162 ms
2015-11-30 04:35:09.9113 Warn Could not deliver message to Node 4 (CallbackId=06, Retry=1)
2015-11-30 04:35:10.1139 Trace [[[ BEGIN REQUEST ]]]
2015-11-30 04:35:10.1139 Trace WaitAck
2015-11-30 04:35:10.1139 Trace Sending Message (Node=4, CallbackId=06, Function=SendData, CommandClass=Basic)
2015-11-30 04:35:10.1139 Debug 01-0A-00-13-04-03-20-01-FF-05-06-3C
2015-11-30 04:35:10.2149 Debug 06-01-04-01-13-01-E8
2015-11-30 04:35:10.2149 Debug ZWaveMessage (RawData=01-04-01-13-01-E8)
2015-11-30 04:35:10.2149 Debug ZWaveMessage (Direction=Inbound, Header=SOF, NodeId=0, Type=Response, Function=SendData, CommandClass=NotSet)
2015-11-30 04:35:10.2149 Debug 06
2015-11-30 04:35:10.2149 Trace SendDataReady
2015-11-30 04:35:10.3172 Debug 01-05-00-13-06-01-EE
2015-11-30 04:35:10.3172 Debug ZWaveMessage (RawData=01-05-00-13-06-01-EE)
2015-11-30 04:35:10.3172 Debug ZWaveMessage (Direction=Inbound, Header=SOF, NodeId=0, Type=Request, Function=SendData, CommandClass=NotSet)
2015-11-30 04:35:10.3172 Debug 06
2015-11-30 04:35:10.3172 Trace Error
2015-11-30 04:35:10.3172 Trace [[[ END REQUEST ]]] took 204 ms
2015-11-30 04:35:10.3172 Warn Could not deliver message to Node 4 (CallbackId=06, Retry=2)
2015-11-30 04:35:10.5193 Trace [[[ BEGIN REQUEST ]]]
2015-11-30 04:35:10.5193 Trace WaitAck
2015-11-30 04:35:10.5193 Trace Sending Message (Node=4, CallbackId=06, Function=SendData, CommandClass=Basic)
2015-11-30 04:35:10.5193 Debug 01-0A-00-13-04-03-20-01-FF-05-06-3C
2015-11-30 04:35:10.6195 Debug 06-01-04-01-13-01-E8
2015-11-30 04:35:10.6195 Debug ZWaveMessage (RawData=01-04-01-13-01-E8)
2015-11-30 04:35:10.6195 Debug ZWaveMessage (Direction=Inbound, Header=SOF, NodeId=0, Type=Response, Function=SendData, CommandClass=NotSet)
2015-11-30 04:35:10.6195 Debug 06
2015-11-30 04:35:10.6195 Trace SendDataReady
2015-11-30 04:35:10.7214 Debug 01-05-00-13-06-01-EE
2015-11-30 04:35:10.7214 Debug ZWaveMessage (RawData=01-05-00-13-06-01-EE)
2015-11-30 04:35:10.7214 Debug ZWaveMessage (Direction=Inbound, Header=SOF, NodeId=0, Type=Request, Function=SendData, CommandClass=NotSet)
2015-11-30 04:35:10.7214 Debug 06
2015-11-30 04:35:10.7214 Trace Error
2015-11-30 04:35:10.7214 Trace [[[ END REQUEST ]]] took 203 ms
2015-11-30 04:35:10.7214 Warn Delivery of message to Node 4 failed (CallbackId=06).
2015-11-30 04:35:10.7214 Debug 4 Error
2015-11-30 04:35:10.7214 Info HomeAutomation.ZWave   4   Z-Wave Node   Status.Error   Response timeout!
2015-11-30 04:35:14.0401 Info WebServiceGateway   10.0.0.11   HTTP   GET   200 /api/HomeAutomation.ZWave/4/Control.Off/null/ [OPEN]
2015-11-30 04:35:14.0401 Debug ZWaveMessage (RawData=01-0A-00-13-04-03-20-01-00-05-07-C2)
2015-11-30 04:35:14.0401 Debug ZWaveMessage (Direction=Outbound, Header=SOF, NodeId=4, Type=Request, Function=SendData, CommandClass=Basic, CallbackId=7, CallbackStatus=NotSet)
2015-11-30 04:35:14.0401 Info HomeAutomation.ZWave   4   ZWave Node   Status.Level   0
2015-11-30 04:35:14.0401 Info WebServiceGateway   10.0.0.11   HTTP   GET   200 /api/HomeAutomation.ZWave/4/Control.Off/null/ [CLOSED AFTER 0.007 seconds]
2015-11-30 04:35:14.3261 Trace [[[ BEGIN REQUEST ]]]
2015-11-30 04:35:14.3261 Trace WaitAck
2015-11-30 04:35:14.3261 Trace Sending Message (Node=4, CallbackId=07, Function=SendData, CommandClass=Basic)
2015-11-30 04:35:14.3261 Debug 01-0A-00-13-04-03-20-01-00-05-07-C2
2015-11-30 04:35:14.3385 Debug 06-01-04-01-13-01-E8
2015-11-30 04:35:14.3385 Debug ZWaveMessage (RawData=01-04-01-13-01-E8)
2015-11-30 04:35:14.3385 Debug ZWaveMessage (Direction=Inbound, Header=SOF, NodeId=0, Type=Response, Function=SendData, CommandClass=NotSet)
2015-11-30 04:35:14.3385 Debug 06
2015-11-30 04:35:14.3385 Trace SendDataReady
2015-11-30 04:35:14.5403 Debug 01-05-00-13-07-01-EF
2015-11-30 04:35:14.5403 Debug ZWaveMessage (RawData=01-05-00-13-07-01-EF)
2015-11-30 04:35:14.5403 Debug ZWaveMessage (Direction=Inbound, Header=SOF, NodeId=0, Type=Request, Function=SendData, CommandClass=NotSet)
2015-11-30 04:35:14.5403 Debug 06
2015-11-30 04:35:14.5403 Trace Error
2015-11-30 04:35:14.5403 Trace [[[ END REQUEST ]]] took 216 ms
2015-11-30 04:35:14.5403 Warn Could not deliver message to Node 4 (CallbackId=07, Retry=1)
2015-11-30 04:35:14.7433 Trace [[[ BEGIN REQUEST ]]]
2015-11-30 04:35:14.7433 Trace WaitAck
2015-11-30 04:35:14.7433 Trace Sending Message (Node=4, CallbackId=07, Function=SendData, CommandClass=Basic)
2015-11-30 04:35:14.7433 Debug 01-0A-00-13-04-03-20-01-00-05-07-C2
2015-11-30 04:35:14.8434 Debug 06-01-04-01-13-01-E8
2015-11-30 04:35:14.8434 Debug ZWaveMessage (RawData=01-04-01-13-01-E8)
2015-11-30 04:35:14.8434 Debug ZWaveMessage (Direction=Inbound, Header=SOF, NodeId=0, Type=Response, Function=SendData, CommandClass=NotSet)
2015-11-30 04:35:14.8434 Debug 06
2015-11-30 04:35:14.8434 Trace SendDataReady
2015-11-30 04:35:14.9446 Debug 01-05-00-13-07-01-EF
2015-11-30 04:35:14.9446 Debug ZWaveMessage (RawData=01-05-00-13-07-01-EF)
2015-11-30 04:35:14.9446 Debug ZWaveMessage (Direction=Inbound, Header=SOF, NodeId=0, Type=Request, Function=SendData, CommandClass=NotSet)
2015-11-30 04:35:14.9446 Debug 06
2015-11-30 04:35:14.9446 Trace Error
2015-11-30 04:35:14.9446 Trace [[[ END REQUEST ]]] took 202 ms
2015-11-30 04:35:14.9446 Warn Could not deliver message to Node 4 (CallbackId=07, Retry=2)
2015-11-30 04:35:15.1470 Trace [[[ BEGIN REQUEST ]]]
2015-11-30 04:35:15.1470 Trace WaitAck
2015-11-30 04:35:15.1470 Trace Sending Message (Node=4, CallbackId=07, Function=SendData, CommandClass=Basic)
2015-11-30 04:35:15.1470 Debug 01-0A-00-13-04-03-20-01-00-05-07-C2
2015-11-30 04:35:15.2472 Debug 06-01-04-01-13-01-E8
2015-11-30 04:35:15.2472 Debug ZWaveMessage (RawData=01-04-01-13-01-E8)
2015-11-30 04:35:15.2472 Debug ZWaveMessage (Direction=Inbound, Header=SOF, NodeId=0, Type=Response, Function=SendData, CommandClass=NotSet)
2015-11-30 04:35:15.2472 Debug 06
2015-11-30 04:35:15.2472 Trace SendDataReady
2015-11-30 04:35:15.3490 Debug 01-05-00-13-07-01-EF
2015-11-30 04:35:15.3490 Debug ZWaveMessage (RawData=01-05-00-13-07-01-EF)
2015-11-30 04:35:15.3490 Debug ZWaveMessage (Direction=Inbound, Header=SOF, NodeId=0, Type=Request, Function=SendData, CommandClass=NotSet)
2015-11-30 04:35:15.3490 Debug 06
2015-11-30 04:35:15.3490 Trace Error
2015-11-30 04:35:15.3490 Trace [[[ END REQUEST ]]] took 203 ms
2015-11-30 04:35:15.3490 Warn Delivery of message to Node 4 failed (CallbackId=07).
2015-11-30 04:35:15.3490 Debug 4 Error

[Gene]

I think I understood what is this issue about.
HomeGenie Control.On/Off/Toggle commands does not check for command classes implemented by the node, and always send a Basic.Set (0x20) command which may not work with all devices (it works with mine).
I've modified the code so that it will first check what command classes the node is implementing and then issue the proper command (SwitchBinary,SwitchMultiLevel and so on).
You can find the patched library here:

https://sourceforge.net/projects/homegenie/files/testing/

- stop homegenie
- copy the file MIG.HomeAutomation.dll in the homegenie/lib/mig folder
- start homegenie

Let me know if this solves the issue.

g.

[Gene]

Never mind, there is also an issue with ZWaveLib as well that in the SwitchBinary class was calling Basic set instead of sending SwitchBinary.
So also copying ZWaveLib.dll is needed:

https://sourceforge.net/projects/homegenie/files/testing/

- stop hg
- copy ZWaveLib.dll in the homegenie/lib/mig folder
- start hg

g

[stanleywoon]

Hi Gene,

I have replace both dlls and test again, the result still the same. The timeout happened in configuration page as well.

Please find the logs in attachments.

Thanks.

[Gene]

There's no discovery info at all. So try remove/readd the node.

g.

[stanleywoon]

I have remove and re-added the node, still no luck...

[Gene]

I don't see in the log where you remove and then add the node.

g.

[stanleywoon]

I am following the instruction below to re-add, or should I need to do it in hg?

http://aeotec.com/z-wave-usb-stick/913-z-stick-manual-instructions.html

Btw, it is confirmed the switch did proper on/off, just the status always return timeout.