R503; z-wave timeout

[pim555]

Even though I can control Fibaro in wall switches (lamp switches on/off), they still produce a timeout in the user interface. See below for a log

"2015-11-25 22:50:13.1702 Info WebServiceGateway   192.168.1.103   HTTP   GET   200 /api/HomeAutomation.ZWave/4/Control.On/null/ [OPEN]"                                             
"2015-11-25 22:50:13.1776 Info HomeAutomation.ZWave   4   ZWave Node   Status.Level   1"                                             
"2015-11-25 22:50:13.2763 Info WebServiceGateway   192.168.1.103   HTTP   GET   200 /api/HomeAutomation.ZWave/4/Control.On/null/ [CLOSED AFTER 0.106 seconds]"                                             
2015-11-25 22:50:13.6320 Trace [[[ BEGIN REQUEST ]]]                                             
2015-11-25 22:50:13.6320 Trace WaitAck                                             
2015-11-25 22:50:13.6330 Trace Sending Message (Node=4    CallbackId=15    Function=SendData    CommandClass=Basic)                                    
2015-11-25 22:50:13.6330 Debug 01-0A-00-13-04-03-20-01-FF-05-15-2F                                             
2015-11-25 22:50:13.6386 Debug 06                                             
2015-11-25 22:50:13.6393 Debug 01-04-01-13-01-E8                                             
2015-11-25 22:50:13.6405 Debug 06                                             
2015-11-25 22:50:13.6412 Trace SendDataReady                                             
2015-11-25 22:50:13.7424 Debug 01-07-00-13-15-00-00-02-FC                                             
2015-11-25 22:50:13.7437 Debug 06                                             
2015-11-25 22:50:13.7446 Trace Error                                             
2015-11-25 22:50:13.7456 Trace [[[ END REQUEST ]]] took 113 ms                                             
2015-11-25 22:50:13.7460 Warn Could not deliver message to Node 4 (CallbackId=15    Retry=1)                                          
2015-11-25 22:50:13.8466 Trace [[[ BEGIN REQUEST ]]]                                             
2015-11-25 22:50:13.8473 Trace WaitAck                                             
2015-11-25 22:50:13.8482 Trace Sending Message (Node=4    CallbackId=15    Function=SendData    CommandClass=Basic)                                    
2015-11-25 22:50:13.8491 Debug 01-0A-00-13-04-03-20-01-FF-05-15-2F                                             
2015-11-25 22:50:13.9501 Debug 06-01-04-01-13-01-E8                                             
2015-11-25 22:50:13.9511 Debug 06                                             
2015-11-25 22:50:13.9511 Trace SendDataReady                                             
2015-11-25 22:50:13.9530 Debug 01-07-00-13-15-00-00-02-FC                                             
2015-11-25 22:50:13.9542 Debug 06                                             
2015-11-25 22:50:13.9542 Trace Error                                             
2015-11-25 22:50:13.9560 Trace [[[ END REQUEST ]]] took 108 ms                                             
2015-11-25 22:50:13.9560 Warn Could not deliver message to Node 4 (CallbackId=15    Retry=2)                                          
2015-11-25 22:50:14.0570 Trace [[[ BEGIN REQUEST ]]]                                             
2015-11-25 22:50:14.0570 Trace WaitAck                                             
2015-11-25 22:50:14.0582 Trace Sending Message (Node=4    CallbackId=15    Function=SendData    CommandClass=Basic)                                    
2015-11-25 22:50:14.0594 Debug 01-0A-00-13-04-03-20-01-FF-05-15-2F                                             
2015-11-25 22:50:14.1603 Debug 06-01-04-01-13-01-E8                                             
2015-11-25 22:50:14.1615 Debug 06                                             
2015-11-25 22:50:14.1623 Trace SendDataReady                                             
2015-11-25 22:50:14.1635 Debug 01-07-00-13-15-00-00-02-FC                                             
2015-11-25 22:50:14.1646 Debug 06                                             
2015-11-25 22:50:14.1653 Trace Error                                             
2015-11-25 22:50:14.1664 Trace [[[ END REQUEST ]]] took 108 ms                                             
2015-11-25 22:50:14.1670 Warn Delivery of message to Node 4 failed (CallbackId=15).                                             
2015-11-25 22:50:14.1670 Debug 4 Error                                             
"2015-11-25 22:50:14.1697 Info HomeAutomation.ZWave   4   Z-Wave Node   Status.Error   Response timeout!"                                             

[Gene]

hi pim555

the problem is here:

https://github.com/genielabs/zwave-lib-dotnet/blob/master/ZWaveLib/ZWaveMessage.cs#L162

2015-11-25 22:50:13.6330 Debug 01-0A-00-13-04-03-20-01-FF-05-15-2F                                             
2015-11-25 22:50:13.6386 Debug 06                                             
2015-11-25 22:50:13.6393 Debug 01-04-01-13-01-E8                                             
2015-11-25 22:50:13.6405 Debug 06                                             
2015-11-25 22:50:13.6412 Trace SendDataReady                                             
2015-11-25 22:50:13.7424 Debug 01-07-00-13-15-00-00-02-FC           <-- there are extra 2 bytes in the response                                 
2015-11-25 22:50:13.7437 Debug 06

ZWaveLib is expecting to get a message of 7 bytes for reading the callback status (byte 6 = 0x00 = OK).
But fibaro is replying with a message that is 9 bytes.
I don't have any Z-Wave protocol specifications so I don't know how to parse a ZWave message and the code above is built on the data received from my z-wave devices.
This is the sequence with one of my switches:

2015-11-25 23:56:38.2780 Trace [[[ BEGIN REQUEST ]]]
2015-11-25 23:56:38.2780 Trace WaitAck
2015-11-25 23:56:38.2780 Trace Sending Message (Node=7, CallbackId=21, Function=SendData, CommandClass=Basic)
2015-11-25 23:56:38.2790 Debug 01-0A-00-13-07-03-20-01-FF-05-21-18
2015-11-25 23:56:38.2855 Debug 06-01-04-01-13-01-E8
2015-11-25 23:56:38.2863 Debug 06
2015-11-25 23:56:38.2863 Trace SendDataReady
2015-11-25 23:56:38.3870 Debug 01-05-00-13-21-00-C8   <-- 7 bytes as expected
2015-11-25 23:56:38.3870 Debug 06
2015-11-25 23:56:38.3870 Trace Complete
2015-11-25 23:56:38.3885 Trace [[[ END REQUEST ]]] took 110 ms

Fixing that code will probably solve issues with ZWaveLib.

I would change line 171 like this

Code: [Select]

                    else if (Function == ZWaveFunction.SendData && (message.Length == 7 || message.Length == 9))

hoping it will not screw up something else
If you don't have development enviroment installed and can't compile ZWaveLib on your own to test, I will compile it for you and attach the file here so you can test.

Cheers,
g.

[Gene]

I'm attacching the patched ZWaveLib.

- Stop HG
- Replace this file in the folder homegenie/lib/mig.
- Start HG

Cheers,
g.

[dani]

Hi gene,
Instead of to check which kind of message you receive, only the second byte after 0x01 tell you how many bytes follow.
In your samples I saw :
0x01 0x0A ...... Following 10 bytes
0x01 0x07 ....... Following 7 bytes
0x01 0x05 .......  Following 5 bytes
Testing byte 2 of messages will told you the good length for every kind of message, no need to hard value test : message.Lengh == mess[1]+2.
Like that respects zwave protocol I think.

[pim555]

Thanks Gene.

Will give it a try.

[Gene]

Hi gene,
Instead of to check which kind of message you receive, only the second byte after 0x01 tell you how many bytes follow.
In your samples I saw :
0x01 0x0A ...... Following 10 bytes
0x01 0x07 ....... Following 7 bytes
0x01 0x05 .......  Following 5 bytes
Testing byte 2 of messages will told you the good length for every kind of message, no need to hard value test : message.Lengh == mess[1]+2.
Like that respects zwave protocol I think.

yes dani I know that, but it doesn't change the problem with parsing the callback status from a zwave message.
Probably the real fix would be having in ZWaveMessage class a variable indicating the "query stage".
If the query stage is "SendDataReady" then the message is to be considered always as a callback status reply.
Indeed the ZWaveMessage class is trying to detect and parse a ZWave message from a byte sequence despite of the query stage.
For now I prefer trying to parse the message this way unless it turns out that is not possible to interpret the message without knowing the query stage.

g.

[dani]

Thank's Gene for your explanation. About Query Stage

[Gene]

dani, I'm always hoping that someone wants to help

[pim555]

After installing the patched zwavelib file, timeout on switches (Fibaro in wall) is now gone but sensors are still not properly readable. Log lines below

2015-11-26 23:23:00.1130 Trace [[[ BEGIN REQUEST ]]]                                             
2015-11-26 23:23:00.1130 Trace WaitAck                                             
2015-11-26 23:23:00.1140 Trace Sending Message (Node=2    CallbackId=25    Function=SendData    CommandClass=Configuration)                                    
2015-11-26 23:23:00.1146 Debug 01-0F-00-13-02-08-70-04-65-04-00-00-00-E1-05-25-3D                                             
2015-11-26 23:23:00.1295 Debug 06-01-04-01-13-01-E8                                             
2015-11-26 23:23:00.1295 Debug 06                                             
2015-11-26 23:23:00.1308 Trace SendDataReady                                             
2015-11-26 23:23:00.4320 Debug 01-07-00-13-25-01-00-17-D8                                             
2015-11-26 23:23:00.4329 Debug 06                                             
2015-11-26 23:23:00.4329 Trace Error                                             
2015-11-26 23:23:00.4341 Trace [[[ END REQUEST ]]] took 320 ms                                             
2015-11-26 23:23:00.4346 Warn Could not deliver message to Node 2 (CallbackId=25    Retry=1)                                          
2015-11-26 23:23:00.5351 Trace [[[ BEGIN REQUEST ]]]                                             
2015-11-26 23:23:00.5356 Trace WaitAck                                             
2015-11-26 23:23:00.5356 Trace Sending Message (Node=2    CallbackId=25    Function=SendData    CommandClass=Configuration)                                    
2015-11-26 23:23:00.5368 Debug 01-0F-00-13-02-08-70-04-65-04-00-00-00-E1-05-25-3D                                             
2015-11-26 23:23:00.6375 Debug 06-01-04-01-13-01-E8                                             
2015-11-26 23:23:00.6385 Debug 06                                             
2015-11-26 23:23:00.6385 Trace SendDataReady                                             
2015-11-26 23:23:00.7397 Debug 01-07-00-13-25-01-00-08-C7                                             
2015-11-26 23:23:00.7408 Debug 06                                             
2015-11-26 23:23:00.7408 Trace Error                                             
2015-11-26 23:23:00.7421 Trace [[[ END REQUEST ]]] took 206 ms                                             
2015-11-26 23:23:00.7425 Warn Could not deliver message to Node 2 (CallbackId=25    Retry=2)                                          
2015-11-26 23:23:00.8432 Trace [[[ BEGIN REQUEST ]]]                                             
2015-11-26 23:23:00.8436 Trace WaitAck                                             
2015-11-26 23:23:00.8436 Trace Sending Message (Node=2    CallbackId=25    Function=SendData    CommandClass=Configuration)                                    
2015-11-26 23:23:00.8450 Debug 01-0F-00-13-02-08-70-04-65-04-00-00-00-E1-05-25-3D                                             
2015-11-26 23:23:00.9458 Debug 06-01-04-01-13-01-E8                                             
2015-11-26 23:23:00.9510 Debug 06                                             
2015-11-26 23:23:00.9510 Trace SendDataReady                                             
2015-11-26 23:23:00.9523 Debug 01-07-00-13-25-00-00-02                                             
2015-11-26 23:23:00.9533 Debug 15                                             
2015-11-26 23:23:00.9537 Warn Bad message checksum                                             
2015-11-26 23:23:00.9537 Debug CC                                             
2015-11-26 23:23:00.9624 Warn Unhandled message type: CC                                             
2015-11-26 23:23:00.9629 Debug 01-07-00-13-25-00-00-02-CC                                             
2015-11-26 23:23:00.9638 Debug 06                                             
2015-11-26 23:23:00.9638 Trace Complete                                             
2015-11-26 23:23:00.9652 Trace [[[ END REQUEST ]]] took 121 ms                                             
2015-11-26 23:23:00.9657 Warn Delivery of message to Node 2 failed (CallbackId=25).                                             
2015-11-26 23:23:00.9657 Debug 2 Error                                             
2015-11-26 23:23:00.9679 Warn Node is flagged as sleeping    message will be re-sent on Wake Up (Node=2    CallbackId=2    Function=25    CommandClass=SendData)                                 
2015-11-26 23:23:00.9686 Trace Adding message 01-0F-00-13-02-08-70-04-65-04-00-00-00-E1-05-25-3D                                             
2015-11-26 23:23:00.9686 Debug 2 WakeUpSleepingStatus 1                                             
"2015-11-26 23:23:00.9702 Info HomeAutomation.ZWave   2   Z-Wave Node   Status.Error   Response timeout!"                                             
"2015-11-26 23:23:00.9720 Info HomeAutomation.ZWave   2   ZWave Node   ZWaveNode.WakeUpSleepingStatus   1"                                             

[Gene]

Hi pim,

I uploaded a new fix, that hopefully will solve this issue (and the RaZbeery issue too).

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

Wake up your sensor to make proper tests.

g.