ZWave device inclusion timeout

Thanks. I try specify my problem:
A few days ago, I bought a Fibaro Flood sensor. (FGFS-101). I added to the Z-wave network. Then, the discovery went to timeout.
I try it with HG setup. I attached the picture. It can’t get the device information.

The interesting thing, if I pushing 1-2 times in sec continuously the device ADD button, sometimes HG get the informations from device, sometimes went to timeout too. It does this when I want to change a parameter.
I think, it is not normaly working.

Event:

2017-07-18T18:32:23.000Z,“homegenie”,“12 Timeout”
2017-07-18T18:32:23.000Z,“homegenie”,“01-1D-00-13-0C-16-98-81-AA-AA-AA-AA-AA-AA-AA-AA-AB-0D-1E-BF-13-74-3D-0E-65-3D-93-3F-05-B5-E5”
2017-07-18T18:32:23.000Z,“homegenie”,“SendDataReady”
2017-07-18T18:32:23.000Z,“homegenie”,“06”
2017-07-18T18:32:23.000Z,“homegenie”,“12 Error”
2017-07-18T18:32:23.000Z,“homegenie”,“06-01-04-01-13-01-E8”
“2017-07-18T18:32:23.000Z,”“homegenie”","“HomeAutomation.MiLightRGBW 1 - Meter.Watts 0.0"”"
“2017-07-18T18:32:23.000Z,”“homegenie”","“HomeAutomation.HomeGenie.Automation 1038 Automation Program Program.Status Idle”""
2017-07-18T18:32:23.000Z,“homegenie”,“Message timeout (Node=12, CallbackId=12, Function=B6, CommandClass=SendData)”
2017-07-18T18:32:23.000Z,“homegenie”,“06”
2017-07-18T18:32:23.000Z,“homegenie”,“06-01-04-01-13-00-E9”
`

Unfortunately It does this with several devices.

for example:
Fibaro smoke sensor. Philio 4 in 1 sensor…

I try my devices with other home automatic software. (For example Domoticz, Home Assistant). It works fine with them.

My system is the Ubuntu server 16.04.02 under the Hyper-V host. I use HG 525. I use usb redirector to add my Z-Wave stick to my virtual machine (USB over ethernet)
I try HG on my local notebook (windows 10) with your 526 HG version. The problem the same, so I think, not the usb redirector is the problem.

Well, I returned from vacations and tried to reproduce your problem.

I removed and added my FGFS-101 and the process was not so straightforward as I wish. The inclusion process and initial interview take a lot of time, so the device goes to sleep. So it’s normal that you have to wake it up (see official video from Fibaro about the inclusion of FGFS-101 https://www.youtube.com/watch?v=EwxpFLp4x9o). Actually, the timeout issues are very common with battery-powered devices, both during inclusion and working with device parameters.

But the UX of inclusion in HG is bad right now because there is no message with a request to wake up the device to continue inclusion process. I hope it will be fixed sometime.

I have the same issue with a Fibaro dimmer (FGD-212; permanently powered) so this is not purely related to battery power and the device going back to sleep before the interview process is over. Could it be that HG times out to quickly?

Well, actually it’s possible (especially if you have troubles with mains powered device).
Unfortunately, there is lack of official documentation related to inclusion/exclusion/discover processes.
I can try to increase default timeout in HG if you want and are going to test it in your environment.

Yes, if you can do that I am happy to test.

Btw, is the inclusion/exlcusion/discover process not documented in the official zwave specs that have been disclosed earlier this year?

Ok, I’ll make a test build in a couple of days.

Unfortunately, official ZWave specs only cover Command Classes’ specifications, while inclusion/exclusion/discovery process is related with ZWave functions which are not covered by opened specs.

Hi, @pim555.
Here you are two updated libraries. You need to put MIG.dll into the root folder of HG and MIG.HomeAutomation.dll into the lib/mig/ folder. I haven’t changed text in the UI so it tells you that timeout is 10 seconds but it will wait for 30 seconds.

MIG.HomeAutomation.dll (41.5 KB)
MIG.dll (74.5 KB)

Hey Bounz,

Thanks for making these available. I have installed as per your instruction and run the get status command command from the set-up section of this module (ID = 17). Unfortunately I don’t notice any difference.

not sure how I can attached the log file to this message?

Here is the debug log

2017-09-27 22:41:14.9382 Info WebServiceGateway	192.168.1.115	HTTP	GET	200 /api/HomeAutomation.ZWave/17/ManufacturerSpecific.Get/?_=1506544748612 [OPEN]"					
2017-09-27 22:41:14.9397 Debug ZWaveMessage (RawData=01-09-00-13-11-02-72-04-05-27-A2)					
2017-09-27 22:41:14.9397 Debug ZWaveMessage (Direction=Outbound	 Header=SOF	 NodeId=17	 Type=Request	 Function=SendData	 CommandClass=ManufacturerSpecific
2017-09-27 22:41:15.0384 Trace [[[ BEGIN REQUEST ]]]					
2017-09-27 22:41:15.0384 Trace WaitAck					
2017-09-27 22:41:15.0384 Trace Sending Message (Node=17	 CallbackId=27	 Function=SendData	 CommandClass=ManufacturerSpecific)		
2017-09-27 22:41:15.0384 Debug 01-09-00-13-11-02-72-04-05-27-A2					
2017-09-27 22:41:15.1379 Debug 06-01-04-01-13-01-E8					
2017-09-27 22:41:15.1383 Debug ZWaveMessage (RawData=01-04-01-13-01-E8)					
2017-09-27 22:41:15.1383 Debug ZWaveMessage (Direction=Inbound	 Header=SOF	 NodeId=0	 Type=Response	 Function=SendData	 CommandClass=NotSet)
2017-09-27 22:41:15.1383 Debug 06					
2017-09-27 22:41:15.1383 Trace SendDataReady					
2017-09-27 22:41:15.1396 Debug 01-07-00					
2017-09-27 22:41:15.1396 Trace Expected message length is 9	 currently received length is 3				
2017-09-27 22:41:15.1396 Debug 13-27-00-00-01-CD					
2017-09-27 22:41:15.1396 Trace Merged buffer to message: 01-07-00-13-27-00-00-01-CD					
2017-09-27 22:41:15.1405 Debug ZWaveMessage (RawData=01-07-00-13-27-00-00-01-CD)					
2017-09-27 22:41:15.1405 Debug ZWaveMessage (Direction=Inbound	 Header=SOF	 NodeId=0	 Type=Request	 Function=SendData	 CommandClass=NotSet)
2017-09-27 22:41:15.1405 Debug 06					
2017-09-27 22:41:15.1405 Trace Complete					
2017-09-27 22:41:15.1414 Debug 01					
2017-09-27 22:41:15.1414 Trace [[[ END REQUEST ]]] took 102 ms					
2017-09-27 22:41:15.1414 Debug ZWaveMessage (RawData=01)					
2017-09-27 22:41:15.1414 Debug ZWaveMessage (Direction=Inbound	 Header=SOF	 NodeId=0	 Type=NotSet	 Function=NotSet	 CommandClass=NotSet)
2017-09-27 22:41:15.1425 Debug 15					
2017-09-27 22:41:15.1425 Warn Bad message checksum					
2017-09-27 22:41:15.1425 Debug 0E-00-04-00-11-08-72-05-01-0F-01-02-10-00-86-01-0E					
2017-09-27 22:41:15.1425 Debug ZWaveMessage (RawData=0E-00)					
2017-09-27 22:41:15.1434 Debug ZWaveMessage (Direction=Inbound	 Header=14	 NodeId=0	 Type=NotSet	 Function=NotSet	 CommandClass=NotSet)
2017-09-27 22:41:15.1434 Warn Unhandled message type: 0E-00					
2017-09-27 22:41:15.1434 Debug ZWaveMessage (RawData=04-00)					
2017-09-27 22:41:15.1434 Debug ZWaveMessage (Direction=Inbound	 Header=4	 NodeId=0	 Type=NotSet	 Function=NotSet	 CommandClass=NotSet)
2017-09-27 22:41:15.1444 Warn Unhandled message type: 04-00					
2017-09-27 22:41:15.1444 Debug ZWaveMessage (RawData=11-08-72-05-01-0F-01-02-10-00)					
2017-09-27 22:41:15.1444 Debug ZWaveMessage (Direction=Inbound	 Header=17	 NodeId=0	 Type=NotSet	 Function=NotSet	 CommandClass=NotSet)
2017-09-27 22:41:15.1455 Warn Unhandled message type: 11-08-72-05-01-0F-01-02-10-00					
2017-09-27 22:41:15.1455 Warn Unhandled message type: 86-01-0E					
2017-09-27 22:41:15.1455 Debug 00-04-00-11-08-72-05-01-0F-01-02-10-00-86					
2017-09-27 22:41:15.1455 Debug ZWaveMessage (Direction=Inbound	 Header=134	 NodeId=0	 Type=NotSet	 Function=NotSet	 CommandClass=NotSet)
2017-09-27 22:41:15.1464 Debug ZWaveMessage (RawData=00-04-00-11-08-72)					
2017-09-27 22:41:15.1455 Debug ZWaveMessage (RawData=86-01-0E)					
2017-09-27 22:41:15.1464 Debug ZWaveMessage (Direction=Inbound	 Header=0	 NodeId=0	 Type=NotSet	 Function=NotSet	 CommandClass=NotSet)
2017-09-27 22:41:15.1464 Warn Unhandled message type: 00-04-00-11-08-72					
2017-09-27 22:41:15.1478 Debug ZWaveMessage (RawData=05-01-0F)					
2017-09-27 22:41:15.1478 Debug ZWaveMessage (Direction=Inbound	 Header=5	 NodeId=0	 Type=NotSet	 Function=NotSet	 CommandClass=NotSet)
2017-09-27 22:41:15.1483 Warn Unhandled message type: 05-01-0F					
2017-09-27 22:41:15.1483 Debug ZWaveMessage (RawData=01-02-10-00)					
2017-09-27 22:41:15.1483 Debug ZWaveMessage (Direction=Inbound	 Header=SOF	 NodeId=0	 Type=NotSet	 Function=NotSet	 CommandClass=NotSet)
2017-09-27 22:41:15.1495 Debug 15					
2017-09-27 22:41:15.1495 Warn Bad message checksum					
2017-09-27 22:41:15.1495 Debug ZWaveMessage (RawData=86)					
2017-09-27 22:41:15.1495 Debug ZWaveMessage (Direction=Inbound	 Header=134	 NodeId=0	 Type=NotSet	 Function=NotSet	 CommandClass=NotSet)
2017-09-27 22:41:15.1506 Warn Unhandled message type: 86					
2017-09-27 22:41:15.1513 Debug 01-0E-00-04-00-11-08-72-05-01-0F-01-02-10-00-86					
2017-09-27 22:41:15.1513 Debug ZWaveMessage (RawData=01-0E-00-04-00-11-08-72-05-01-0F-01-02-10-00-86)					
2017-09-27 22:41:15.1513 Debug ZWaveMessage (Direction=Inbound	 Header=SOF	 NodeId=17	 Type=Request	 Function=ApplicationCommandHandler	 CommandClass=ManufacturerSpecific)
2017-09-27 22:41:15.1513 Debug 06					
2017-09-27 22:41:15.1528 Debug NodeUpdated (NodeId=17	 Parameter=ManufacturerSpecific	 Value=ZWaveLib.CommandClasses.ManufacturerSpecificInfo)			
"2017-09-27 22:41:15.1540 Info HomeAutomation.ZWave	17	ZWave Node	ZWaveNode.ManufacturerSpecific	010F:0102:1000"					
"2017-09-27 22:41:15.2542 Info WebServiceGateway	192.168.1.115	HTTP	GET	200 /api/HomeAutomation.ZWave/17/ManufacturerSpecific.Get/?_=1506544748612 [CLOSED AFTER 0.316 seconds]"					
"2017-09-27 22:41:15.2761 Info WebServiceGateway	192.168.1.115	HTTP	GET	200 /api/HomeAutomation.ZWave/17/Version.Report/?_=1506544748613 [OPEN]"					
2017-09-27 22:41:15.2769 Debug ZWaveMessage (RawData=01-09-00-13-11-02-86-11-05-28-4C)					
2017-09-27 22:41:15.2769 Debug ZWaveMessage (Direction=Outbound	 Header=SOF	 NodeId=17	 Type=Request	 Function=SendData	 CommandClass=Version
2017-09-27 22:41:15.7422 Trace [[[ BEGIN REQUEST ]]]					
2017-09-27 22:41:15.7425 Trace WaitAck					
2017-09-27 22:41:15.7425 Debug 01-09-00-13-11-02-86-11-05-28-4C					
2017-09-27 22:41:15.7425 Trace Sending Message (Node=17	 CallbackId=28	 Function=SendData	 CommandClass=Version)		
2017-09-27 22:41:15.7549 Debug 06-01-04-01-13-01-E8					
2017-09-27 22:41:15.7553 Debug ZWaveMessage (RawData=01-04-01-13-01-E8)					
2017-09-27 22:41:15.7553 Debug ZWaveMessage (Direction=Inbound	 Header=SOF	 NodeId=0	 Type=Response	 Function=SendData	 CommandClass=NotSet)
2017-09-27 22:41:15.7553 Debug 06					
2017-09-27 22:41:15.7553 Trace SendDataReady					
2017-09-27 22:41:15.8561 Debug 01-07-00-13-28-00-00-02-C1					
2017-09-27 22:41:15.8566 Debug ZWaveMessage (RawData=01-07-00-13-28-00-00-02-C1)					
2017-09-27 22:41:15.8566 Debug ZWaveMessage (Direction=Inbound	 Header=SOF	 NodeId=0	 Type=Request	 Function=SendData	 CommandClass=NotSet)
2017-09-27 22:41:15.8566 Debug 06					
2017-09-27 22:41:15.8566 Trace Complete					
2017-09-27 22:41:15.8574 Trace [[[ END REQUEST ]]] took 114 ms					
2017-09-27 22:41:15.9576 Debug 01-11-00-04-00-11-0B-86-12-03-04-05-03-03-02-01-03-03-65					
2017-09-27 22:41:15.9576 Debug ZWaveMessage (RawData=01-11-00-04-00-11-0B-86-12-03-04-05-03-03-02-01-03-03-65)					
2017-09-27 22:41:15.9584 Debug ZWaveMessage (Direction=Inbound	 Header=SOF	 NodeId=17	 Type=Request	 Function=ApplicationCommandHandler	 CommandClass=Version)
2017-09-27 22:41:15.9584 Debug 06					
2017-09-27 22:41:15.9584 Debug NodeUpdated (NodeId=17	 Parameter=VersionCommandClass	 Value={"LibraryType":3	 "ProtocolVersion":4	 "ProtocolSubVersion":5	 "ApplicationVersion":3
"2017-09-27 22:41:15.9597 Info HomeAutomation.ZWave	17	ZWave Node	ZWaveNode.VersionReport	{""LibraryType"":3"	 "ProtocolVersion":4	 "ProtocolSubVersion":5	 "ApplicationVersion":3	 "ApplicationSubVersion":3}	
"2017-09-27 22:41:15.9904 Info WebServiceGateway	192.168.1.115	HTTP	GET	200 /api/HomeAutomation.ZWave/17/Version.Report/?_=1506544748613 [CLOSED AFTER 0.714 seconds]"					
"2017-09-27 22:41:16.0241 Info WebServiceGateway	192.168.1.115	HTTP	GET	200 /api/HomeAutomation.ZWave/17/NodeInfo.Get/?_=1506544748614 [OPEN]"					
2017-09-27 22:41:16.0250 Debug Node 17					
2017-09-27 22:41:16.0253 Debug ZWaveMessage (Direction=Outbound	 Header=SOF	 NodeId=17	 Type=Request	 Function=RequestNodeInfo	 CommandClass=NotSet
2017-09-27 22:41:16.0253 Debug ZWaveMessage (RawData=01-04-00-60-11-8A)					
2017-09-27 22:41:16.4579 Trace [[[ BEGIN REQUEST ]]]					
2017-09-27 22:41:16.4579 Trace WaitAck					
2017-09-27 22:41:16.4583 Trace Sending Message (Node=17	 CallbackId=00	 Function=RequestNodeInfo	 CommandClass=NotSet)		
2017-09-27 22:41:16.4583 Debug 01-04-00-60-11-8A					
2017-09-27 22:41:16.4604 Debug 06					
2017-09-27 22:41:16.5608 Debug 01-04-01-60-01-9B					
2017-09-27 22:41:16.5608 Debug ZWaveMessage (RawData=01-04-01-60-01-9B)					
2017-09-27 22:41:16.5614 Debug ZWaveMessage (Direction=Inbound	 Header=SOF	 NodeId=0	 Type=Response	 Function=RequestNodeInfo	 CommandClass=NotSet)
2017-09-27 22:41:16.5614 Debug 06					
2017-09-27 22:41:16.5614 Trace SendDataReady					
2017-09-27 22:41:16.5614 Debug 01-15					
2017-09-27 22:41:16.5614 Trace Expected message length is 23	 currently received length is 2				
2017-09-27 22:41:16.5624 Debug 00-49					
2017-09-27 22:41:16.5624 Trace Expected message length is 23	 currently received length is 4				
2017-09-27 22:41:16.5624 Debug 84-11-0F					
2017-09-27 22:41:16.5624 Trace Merged buffer to message: 01-15-00-49-84-11-0F					
2017-09-27 22:41:16.5624 Trace Expected message length is 23	 currently received length is 7				
2017-09-27 22:41:16.5624 Debug 04-11-01					
2017-09-27 22:41:16.5624 Trace Merged buffer to message: 01-15-00-49-84-11-0F-04-11-01					
2017-09-27 22:41:16.5624 Trace Merged buffer to message: 01-15-00-49					
2017-09-27 22:41:16.5633 Trace Expected message length is 23	 currently received length is 10				
2017-09-27 22:41:16.5633 Debug 5E-86-72-59-73-22					
2017-09-27 22:41:16.5633 Trace Merged buffer to message: 01-15-00-49-84-11-0F-04-11-01-5E-86-72-59-73-22					
2017-09-27 22:41:16.5633 Trace Expected message length is 23	 currently received length is 16				
2017-09-27 22:41:16.5633 Debug 31-32-71-56					
2017-09-27 22:41:16.5633 Trace Expected message length is 23	 currently received length is 20				
2017-09-27 22:41:16.5633 Debug 98-7A-49					
2017-09-27 22:41:16.5633 Trace Merged buffer to message: 01-15-00-49-84-11-0F-04-11-01-5E-86-72-59-73-22-31-32-71-56					
2017-09-27 22:41:16.5633 Trace Merged buffer to message: 01-15-00-49-84-11-0F-04-11-01-5E-86-72-59-73-22-31-32-71-56-98-7A-49					
2017-09-27 22:41:16.5645 Debug ZWaveMessage (RawData=01-15-00-49-84-11-0F-04-11-01-5E-86-72-59-73-22-31-32-71-56-98-7A-49)					
2017-09-27 22:41:16.5645 Debug ZWaveMessage (Direction=Inbound	 Header=SOF	 NodeId=0	 Type=Request	 Function=ApplicationUpdate	 CommandClass=NotSet)
2017-09-27 22:41:16.5645 Debug 06					
2017-09-27 22:41:16.5682 Debug In sendMsg - SecurityHandler					
2017-09-27 22:41:16.5759 Debug In sendRequestNonce - SecurityHandler					
2017-09-27 22:41:16.5759 Debug In sendRequestNonce - not waiting for Nonce - SecurityHandler					
2017-09-27 22:41:16.5764 Debug ZWaveMessage (RawData=01-09-00-13-11-02-98-40-05-29-02)					
2017-09-27 22:41:16.5764 Debug ZWaveMessage (Direction=Outbound	 Header=SOF	 NodeId=17	 Type=Request	 Function=SendData	 CommandClass=Security
"2017-09-27 22:41:20.5486 Info WebServiceGateway	192.168.1.115	HTTP	GET	200 /api/HomeAutomation.HomeGenie/Config/Interfaces.List/?_=1506544748615 [OPEN]"					
"2017-09-27 22:41:20.5519 Info WebServiceGateway	192.168.1.115	HTTP	GET	200 /api/HomeAutomation.HomeGenie/Config/Interfaces.List/?_=1506544748615 [CLOSED AFTER 0.003 seconds]"					
"2017-09-27 22:41:22.2505 Info HGIC:192_168_1_120.HomeAutomation.ZWave	4	Binary Switch	Meter.Watts	0.0"					
"2017-09-27 22:41:22.3086 Info HomeAutomation.X10	A1	X10 Module	Meter.Watts	0.0"					
"2017-09-27 22:41:22.3241 Info HomeAutomation.X10	A2	X10 Module	Meter.Watts	0.0"					
"2017-09-27 22:41:22.3567 Info HomeAutomation.X10	A9	X10 Module	Meter.Watts	0.0"					
"2017-09-27 22:41:22.3823 Info HomeAutomation.X10	D1	X10 Module	Meter.Watts	50.09"					
"2017-09-27 22:41:22.3962 Info HomeAutomation.X10	D2	X10 Module	Meter.Watts	0.0"					
"2017-09-27 22:41:22.4106 Info HomeAutomation.X10	D6	X10 Module	Meter.Watts	12.16"					
"2017-09-27 22:41:22.4228 Info HomeAutomation.X10	E1	X10 Module	Meter.Watts	0.0"					
"2017-09-27 22:41:22.4377 Info HomeAutomation.X10	E2	X10 Module	Meter.Watts	17.22"					
"2017-09-27 22:41:22.4493 Info HomeAutomation.ZWave	4	Binary Switch	Meter.Watts	0.0"					
"2017-09-27 22:41:22.4604 Info HomeAutomation.ZWave	5	Binary Switch	Meter.Watts	0.0"					
"2017-09-27 22:41:22.4720 Info HomeAutomation.ZWave	9	Multilevel Switch	Meter.Watts	0.0"					
"2017-09-27 22:41:22.4902 Info HomeAutomation.ZWave	10	Multilevel Switch	Meter.Watts	0.0"					
"2017-09-27 22:41:22.5076 Info HomeAutomation.ZWave	14	Binary Switch	Meter.Watts	0.0"					
"2017-09-27 22:41:22.5254 Info HomeAutomation.ZWave	15	Binary Switch	Meter.Watts	0.0"					
"2017-09-27 22:41:26.0460 Info WebServiceGateway	192.168.1.115	HTTP	GET	200 /api/HomeAutomation.ZWave/17/NodeInfo.Get/?_=1506544748614 [CLOSED AFTER 10.022 seconds]"					
2017-09-27 22:41:26.4588 Trace Error					
2017-09-27 22:41:26.4595 Warn Message timeout (Node=17	 CallbackId=17	 Function=00	 CommandClass=RequestNodeInfo)		
2017-09-27 22:41:26.4595 Debug 17 Timeout					
2017-09-27 22:41:26.4610 Trace [[[ END REQUEST ]]] took 10002 ms					
"2017-09-27 22:41:26.4610 Info HomeAutomation.ZWave	1	Z-Wave Controller	Controller.Status	Node 17 response timeout!"					
2017-09-27 22:41:26.4613 Warn Could not deliver message to Node 17 (CallbackId=00	 Retry=1)

Hi, @pim555. Sorry for the late answer.

At the end, I realized that I misunderstood your question. As this topic was about timeout during inclusion process I have increased inclusion timers. :slight_smile:

But now, after reading the logs, I think that the problem is related with Security command class, as the last outbound message to that node is with Security command class.
I have the previous generation Fibaro dimmer FGD-211 which does not support any Security command classes at all and it works fine.

What version of HG do you use? I’ll try to check the conformance of Security command class implementation to the opened specs.

P.S. About adding logs: you can just drag-n-drop log files into editor and it will be uploaded. Or use upload button on the editor’s toolbar.

Hi @Bounz,

I was actually assuming it was related to timeout but realized after posting the logs that indeed there seem to be errors related to security class. Would be great if you can fix. I have this dimmer installed for over 1 year but have never been able to use it so far.

I am using Homegenie r526.

Best
Pim

Hi, @pim555.

Just want to say that I remember about your problem but still had no time to dig into Security Command class thoughtfully. Hope I’ll be able to do it in the next week.

Thanks for that!

Best,
Pim.

Hello,
I can confirm the problems with the “timeout”.
I use HG 5.26, Z-Stick (Aeotec) + Smoke Sensor (Fibaro) + Door / Window (Fibaro).
Get the “Inclusion-Mode” constantly error messages (timeout node) of HG.
The sensors are only partially detected. It seems as if not all parameters are read.
Overall, a very unstable condition. I had already read the door / window sensor completely. After a delete and re-learn parameters were missing again.
It would be nice if you had a solution approach.
Thank you for your support.
I use HG for many areas (rain tank, light in the yard, switch off pumps, etc.)
Am a total fan of HG.

Thoralf