HomeGenie Forum
Development => Bug reporting => Topic started by: pim555 on November 25, 2015, 10:57:08 PM
-
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!"
-
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
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.
-
I'm attacching the patched ZWaveLib.
- Stop HG
- Replace this file in the folder homegenie/lib/mig.
- Start HG
Cheers,
g.
-
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.
-
Thanks Gene.
Will give it a try.
-
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.
-
Thank's Gene for your explanation. About Query Stage
-
dani, I'm always hoping that someone wants to help :)
-
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"
-
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.