Manually adding Z-Wave neighbor for door sensor (ZD2102)

chris · June 12, 2016, 7:33pm

Check a couple of things with it where it is…

In the Wakeup ‘folder’ in HABmin, make sure that the wakeup node is set to your controller (probably 1), and check that the wakeup period is set to something sensible. I normally use 3600 (1 hour) but others use longer. This is the period between wakeups, and it’s the period at which you can command the device without having to manually wake it up (eg for config changes). It doesn’t impact reports.

Also, check that the association group has node 1 in it as well…

if all these are set, then you should be good to move it back to it’s proper location. After moving it, it might be wise to try and heal the device as that will reconfigure some routing information.

dinki · June 12, 2016, 7:38pm

Thank you for your help and for your patience. Can you tell me where I might find that folder? I don’t see it.

chris · June 12, 2016, 7:41pm

It should show up under the device in HABmin - it’s not a real ‘folder’ - it just looks like a folder in the HABmin device info tree.

dinki · June 12, 2016, 7:53pm

I see it now. I had to reboot as something was preventing it from showing up.

All is well. I’ll go and give it a try.

chris · June 12, 2016, 7:54pm

Good luck

dinki · June 12, 2016, 8:00pm

Did not work at location. It’s back to grey light. I’ve issued the heal command. Do I need to wake it up for this to happen? It’s in regular operation mode right now.

chris · June 12, 2016, 8:03pm

Yes - it will need to wake for the heal to progress.

I’ve not read through all in this thread, but I saw Rich was talking about some of the routing nodes - do you have another mains powered node between the door sensor and the controller?

dinki · June 12, 2016, 8:06pm

Yes. I have a thermostat that is between the controller and the door sensor. I also have a garage sensor that is in very close proximity to the door sensor (about one foot but on the other side of the door in the garage that works fine. That’s the part that’s puzzling me.

I guess I can pull my lamp dimmer and put it closer to see if it makes a difference (just thought of that! ha)

chris · June 12, 2016, 8:10pm

Is the thermostat a mains device?

RF can be tricky - antenna alignment, bits of metal, routes through walls, and, well, most anything else you can think of can make a difference to propagation. So, just because your garage sensor works and it’s right next to the door sensor doesn’t necessarily mean it will work (although it’s a good starting point, and I understand you’d generally expect it to).

The other thing is if one device is ZWave+, then it uses a higher output power (= more range).

dinki · June 12, 2016, 8:18pm

Thermostat is always on so I’m making an assumption that it is a mains device. It is powered by the HVAC system so perhaps it isn’t one.

I’m seeing this in the log:

2016-06-12 14:59:44.675 [DEBUG] [z.internal.ZWaveNetworkMonitor:275 ]- NODE 11: Starting heal
2016-06-12 15:10:42.667 [DEBUG] [ApplicationCommandMessageClass:40  ]- NODE 11: Application Command Request (ALIVE:PING)
2016-06-12 15:10:42.667 [DEBUG] [ApplicationCommandMessageClass:58  ]- NODE 11: Incoming command class ALARM
2016-06-12 15:10:42.667 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:82  ]- NODE 11: Received Alarm Request
2016-06-12 15:10:42.667 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:94  ]- NODE 11: Alarm report - Value = 255
2016-06-12 15:10:42.667 [DEBUG] [z.i.p.c.ZWaveAlarmCommandClass:113 ]- NODE 11: Alarm Type = Burglar (7)
2016-06-12 15:10:42.667 [DEBUG] [.z.internal.ZWaveActiveBinding:466 ]- NODE 11: Got a value event from Z-Wave network, endpoint = 0, command class = ALARM, value = 255
2016-06-12 15:10:55.386 [DEBUG] [.z.i.config.ZWaveConfiguration:977 ]- NODE 11: Heal node
2016-06-12 15:10:55.386 [DEBUG] [z.internal.ZWaveNetworkMonitor:275 ]- NODE 11: Starting heal

Do you know if the sensor is in awake mode or is it in some weird alarm mode and I need to put it in awake mode? I tried removing the battery then pressing the button three times. This is a bit frustrating! haha

chris · June 12, 2016, 8:28pm

What is the device?

These sorts of events happen when the device is not awake. The device will send notifications/alarms etc, but it won’t be able to receive. It’s not ‘awake’, so the binding doesn’t send anything (there’s a bit of a blurb about this in the wiki as it’s a common question).

It’s not ‘wierd’, but no, it’s not awake - you either need to wait for up to 1 hour (assuming the wakeup time was set to 3600), or press the button…

Battery devices in ZWave a probably one of the weakest features and most difficult to understand, so I fully sympathise.

I sense you’re not laughing …

dinki · June 12, 2016, 8:38pm

Trane TZEMT043AB32MAA (https://www.amazon.com/gp/product/B002BA5VVU/)

Hmf… This part is a bear as I have no idea when it’s not in alarm mode. I checked the pdf instructions (http://download.telldus.se/Manuals/Z-Wave/Vision/ZD2102.pdf) and it says to take the back off like I did and that’s it, but clearly this isn’t the case. It doesn’t really give me any indication that I can tell if it’s awake or not. The light will go off sometimes when I press the button, but I don’t know if that means it’s awake or not as I’m no where near the computer to see.

Nah… I’m surprisingly a good sport when it comes to frustrating things until it gets to the point of being ridiculous or impossible to solve. I sense I’m getting closer and closer to that though!

chris · June 12, 2016, 8:45pm

Typically most devices don’t have any way to show they are awake, and normally, they only stay awake for a few seconds. Normally, it’s a case of pressing the button.

Otherwise, grab a beer (or two!), watch some TV, and come back tomorrow and see if it’s any better. It should have woken up 24 times by itself.

dinki · June 12, 2016, 8:49pm

I may have to do like you say and just wait. To be clear, I need to have it with the back off/alarm mode for this to happen right or does it actually wake up in it’s normal operating state?

chris · June 12, 2016, 8:51pm

It will wake up by itself, in its normal operating mode - so long as the wakeup configuration that we went through earlier was set ok.

dinki · June 14, 2016, 3:39pm

I’ve worked on this some and I’m seeing that the device is now reporting back when the door is opened but I never get a closed response:

Line 22661: 2016-06-14 09:12:40.385 [DEBUG] [.z.internal.ZWaveActiveBinding:466 ]- NODE 13: Got a value event from Z-Wave network, endpoint = 0, command class = BASIC, value = 255

Perhaps I have the device configured incorrectly?

Contact Door_Laundry "Laundry Door [%s]" <door> (Laundry,Doors) { zwave="13:command=SENSOR_BINARY,respond_to_basic=true", imperihab="room:Laundry,label:Laundry Door" }

Here’s a look at the zwave.log file pertaining only to this node:

Search "node 13" (176 hits in 1 file)
  C:\openhab\logs\zwave.log (176 hits)
	Line 181: 2016-06-14 08:23:02.193 [INFO ] [rialApiGetInitDataMessageClass:60  ]- NODE 13: Node found
	Line 200: 2016-06-14 08:23:02.193 [DEBUG] [b.z.i.protocol.ZWaveController:506 ]- NODE 13: Init node thread start
	Line 226: 2016-06-14 08:23:02.364 [DEBUG] [.b.z.i.p.i.ZWaveNodeSerializer:138 ]- NODE 13: Serializing from file etc\zwave\node13.xml
	Line 235: 2016-06-14 08:23:02.427 [DEBUG] [b.z.i.protocol.ZWaveController:539 ]- NODE 13: Restore from config: Ok.
	Line 252: 2016-06-14 08:23:02.442 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:267 ]- NODE 13: Node advancer - EMPTYNODE: queue length(0), free to send(true)
	Line 260: 2016-06-14 08:23:02.442 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:332 ]- NODE 13: Node advancer: loop - EMPTYNODE try 1: stageAdvanced(false)
	Line 266: 2016-06-14 08:23:02.442 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:337 ]- NODE 13: Node advancer: Initialisation starting
	Line 271: 2016-06-14 08:23:02.442 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:890 ]- NODE 13: Node advancer - advancing to PROTOINFO
	Line 279: 2016-06-14 08:23:02.442 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:332 ]- NODE 13: Node advancer: loop - PROTOINFO try 0: stageAdvanced(true)
	Line 281: 2016-06-14 08:23:02.442 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:346 ]- NODE 13: Node advancer: PROTOINFO - send IdentifyNode
	Line 302: 2016-06-14 08:23:02.442 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:240 ]- NODE 13: Node advancer - queued packet. Queue length is 1
	Line 304: 2016-06-14 08:23:02.442 [DEBUG] [b.z.i.protocol.ZWaveController:595 ]- NODE 13: Init node thread finished
	Line 489: 2016-06-14 08:23:02.489 [DEBUG] [i.p.s.IdentifyNodeMessageClass:56  ]- NODE 13: ProtocolInfo
	Line 490: 2016-06-14 08:23:02.489 [DEBUG] [i.p.s.IdentifyNodeMessageClass:72  ]- NODE 13: Listening = false
	Line 491: 2016-06-14 08:23:02.489 [DEBUG] [i.p.s.IdentifyNodeMessageClass:73  ]- NODE 13: Routing = true
	Line 492: 2016-06-14 08:23:02.489 [DEBUG] [i.p.s.IdentifyNodeMessageClass:74  ]- NODE 13: Beaming = true
	Line 493: 2016-06-14 08:23:02.489 [DEBUG] [i.p.s.IdentifyNodeMessageClass:75  ]- NODE 13: Version = 4
	Line 494: 2016-06-14 08:23:02.489 [DEBUG] [i.p.s.IdentifyNodeMessageClass:76  ]- NODE 13: FLIRS = false
	Line 495: 2016-06-14 08:23:02.489 [DEBUG] [i.p.s.IdentifyNodeMessageClass:77  ]- NODE 13: Security = false
	Line 496: 2016-06-14 08:23:02.489 [DEBUG] [i.p.s.IdentifyNodeMessageClass:78  ]- NODE 13: Max Baud = 40000
	Line 497: 2016-06-14 08:23:02.489 [DEBUG] [i.p.s.IdentifyNodeMessageClass:94  ]- NODE 13: Basic = Routing Slave
	Line 498: 2016-06-14 08:23:02.489 [DEBUG] [i.p.s.IdentifyNodeMessageClass:102 ]- NODE 13: Generic = Binary Sensor
	Line 499: 2016-06-14 08:23:02.489 [DEBUG] [i.p.s.IdentifyNodeMessageClass:110 ]- NODE 13: Specific = Routing Binary Sensor
	Line 500: 2016-06-14 08:23:02.489 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:243 ]- NODE 13: Creating new instance of command class NO_OPERATION
	Line 501: 2016-06-14 08:23:02.489 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:243 ]- NODE 13: Creating new instance of command class BASIC
	Line 502: 2016-06-14 08:23:02.489 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:243 ]- NODE 13: Creating new instance of command class SENSOR_BINARY
	Line 509: 2016-06-14 08:23:02.489 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1034]- NODE 13: Node advancer - PROTOINFO: Transaction complete (IdentifyNode:Request) success(true)
	Line 510: 2016-06-14 08:23:02.489 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:202 ]- NODE 13: Node advancer - checking initialisation queue. Queue size 1.
	Line 511: 2016-06-14 08:23:02.489 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:208 ]- NODE 13: Node advancer - message removed from queue. Queue size 0.
	Line 512: 2016-06-14 08:23:02.489 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:267 ]- NODE 13: Node advancer - PROTOINFO: queue length(0), free to send(true)
	Line 513: 2016-06-14 08:23:02.489 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:332 ]- NODE 13: Node advancer: loop - PROTOINFO try 1: stageAdvanced(false)
	Line 514: 2016-06-14 08:23:02.489 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:890 ]- NODE 13: Node advancer - advancing to NEIGHBORS
	Line 515: 2016-06-14 08:23:02.489 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:332 ]- NODE 13: Node advancer: loop - NEIGHBORS try 0: stageAdvanced(true)
	Line 516: 2016-06-14 08:23:02.489 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:356 ]- NODE 13: Node advancer: NEIGHBORS - send RoutingInfo
	Line 517: 2016-06-14 08:23:02.489 [DEBUG] [p.s.GetRoutingInfoMessageClass:30  ]- NODE 13: Request routing info
	Line 520: 2016-06-14 08:23:02.489 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:240 ]- NODE 13: Node advancer - queued packet. Queue length is 1
	Line 744: 2016-06-14 08:23:02.572 [DEBUG] [p.s.GetRoutingInfoMessageClass:49  ]- NODE 13: Got NodeRoutingInfo request.
	Line 745: 2016-06-14 08:23:02.572 [DEBUG] [p.s.GetRoutingInfoMessageClass:79  ]- NODE 13: Neighbor nodes: 5 9
	Line 754: 2016-06-14 08:23:02.573 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1034]- NODE 13: Node advancer - NEIGHBORS: Transaction complete (GetRoutingInfo:Request) success(true)
	Line 755: 2016-06-14 08:23:02.573 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:202 ]- NODE 13: Node advancer - checking initialisation queue. Queue size 1.
	Line 756: 2016-06-14 08:23:02.573 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:208 ]- NODE 13: Node advancer - message removed from queue. Queue size 0.
	Line 757: 2016-06-14 08:23:02.573 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:267 ]- NODE 13: Node advancer - NEIGHBORS: queue length(0), free to send(true)
	Line 758: 2016-06-14 08:23:02.573 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:332 ]- NODE 13: Node advancer: loop - NEIGHBORS try 1: stageAdvanced(false)
	Line 759: 2016-06-14 08:23:02.574 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:890 ]- NODE 13: Node advancer - advancing to FAILED_CHECK
	Line 760: 2016-06-14 08:23:02.574 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:332 ]- NODE 13: Node advancer: loop - FAILED_CHECK try 0: stageAdvanced(true)
	Line 761: 2016-06-14 08:23:02.574 [DEBUG] [i.p.s.IsFailedNodeMessageClass:32  ]- NODE 13: Requesting IsFailedNode status from controller.
	Line 764: 2016-06-14 08:23:02.574 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:240 ]- NODE 13: Node advancer - queued packet. Queue length is 1
	Line 970: 2016-06-14 08:23:02.629 [WARN ] [i.p.s.IsFailedNodeMessageClass:53  ]- NODE 13: Is currently marked as failed by the controller!
	Line 971: 2016-06-14 08:23:02.629 [DEBUG] [.z.internal.protocol.ZWaveNode:260 ]- NODE 13: Node is DEAD.
	Line 972: 2016-06-14 08:23:02.629 [DEBUG] [.z.internal.protocol.ZWaveNode:269 ]- NODE 13: Initialisation incomplete, not signalling state change.
	Line 979: 2016-06-14 08:23:02.630 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1034]- NODE 13: Node advancer - FAILED_CHECK: Transaction complete (IsFailedNodeID:Request) success(true)
	Line 980: 2016-06-14 08:23:02.630 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:202 ]- NODE 13: Node advancer - checking initialisation queue. Queue size 1.
	Line 981: 2016-06-14 08:23:02.630 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:208 ]- NODE 13: Node advancer - message removed from queue. Queue size 0.
	Line 982: 2016-06-14 08:23:02.630 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:267 ]- NODE 13: Node advancer - FAILED_CHECK: queue length(0), free to send(true)
	Line 983: 2016-06-14 08:23:02.630 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:332 ]- NODE 13: Node advancer: loop - FAILED_CHECK try 1: stageAdvanced(false)
	Line 984: 2016-06-14 08:23:02.630 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:890 ]- NODE 13: Node advancer - advancing to WAIT
	Line 985: 2016-06-14 08:23:02.630 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:332 ]- NODE 13: Node advancer: loop - WAIT try 0: stageAdvanced(true)
	Line 986: 2016-06-14 08:23:02.630 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:380 ]- NODE 13: Node advancer: WAIT - Listening=false, FrequentlyListening=false
	Line 987: 2016-06-14 08:23:02.630 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:398 ]- NODE 13: Node advancer: WAIT - Still waiting!
	Line 2979: 2016-06-14 08:24:52.163 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ]- NODE 13: Polling list: item Door_Laundry_Battery is not completed initialisation
	Line 2982: 2016-06-14 08:24:52.163 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ]- NODE 13: Polling list: item Door_Laundry is not completed initialisation
	Line 3098: 2016-06-14 08:24:52.224 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ]- NODE 13: Polling list: item Door_Laundry_Battery is not completed initialisation
	Line 3100: 2016-06-14 08:24:52.224 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ]- NODE 13: Polling list: item Door_Laundry is not completed initialisation
	Line 3215: 2016-06-14 08:24:52.286 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ]- NODE 13: Polling list: item Door_Laundry_Battery is not completed initialisation
	Line 3216: 2016-06-14 08:24:52.286 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ]- NODE 13: Polling list: item Door_Laundry is not completed initialisation
	Line 3428: 2016-06-14 08:27:15.428 [INFO ] [rialApiGetInitDataMessageClass:60  ]- NODE 13: Node found
	Line 3448: 2016-06-14 08:27:15.428 [DEBUG] [b.z.i.protocol.ZWaveController:506 ]- NODE 13: Init node thread start
	Line 3471: 2016-06-14 08:27:15.631 [DEBUG] [.b.z.i.p.i.ZWaveNodeSerializer:138 ]- NODE 13: Serializing from file etc\zwave\node13.xml
	Line 3493: 2016-06-14 08:27:15.709 [DEBUG] [b.z.i.protocol.ZWaveController:539 ]- NODE 13: Restore from config: Ok.
	Line 3494: 2016-06-14 08:27:15.709 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:267 ]- NODE 13: Node advancer - EMPTYNODE: queue length(0), free to send(true)
	Line 3501: 2016-06-14 08:27:15.709 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:332 ]- NODE 13: Node advancer: loop - EMPTYNODE try 1: stageAdvanced(false)
	Line 3505: 2016-06-14 08:27:15.709 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:337 ]- NODE 13: Node advancer: Initialisation starting
	Line 3507: 2016-06-14 08:27:15.709 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:890 ]- NODE 13: Node advancer - advancing to PROTOINFO
	Line 3523: 2016-06-14 08:27:15.709 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:332 ]- NODE 13: Node advancer: loop - PROTOINFO try 0: stageAdvanced(true)
	Line 3526: 2016-06-14 08:27:15.709 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:346 ]- NODE 13: Node advancer: PROTOINFO - send IdentifyNode
	Line 3529: 2016-06-14 08:27:15.709 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:240 ]- NODE 13: Node advancer - queued packet. Queue length is 1
	Line 3530: 2016-06-14 08:27:15.709 [DEBUG] [b.z.i.protocol.ZWaveController:595 ]- NODE 13: Init node thread finished
	Line 3695: 2016-06-14 08:27:15.740 [DEBUG] [i.p.s.IdentifyNodeMessageClass:56  ]- NODE 13: ProtocolInfo
	Line 3696: 2016-06-14 08:27:15.740 [DEBUG] [i.p.s.IdentifyNodeMessageClass:72  ]- NODE 13: Listening = false
	Line 3697: 2016-06-14 08:27:15.740 [DEBUG] [i.p.s.IdentifyNodeMessageClass:73  ]- NODE 13: Routing = true
	Line 3698: 2016-06-14 08:27:15.740 [DEBUG] [i.p.s.IdentifyNodeMessageClass:74  ]- NODE 13: Beaming = true
	Line 3699: 2016-06-14 08:27:15.740 [DEBUG] [i.p.s.IdentifyNodeMessageClass:75  ]- NODE 13: Version = 4
	Line 3700: 2016-06-14 08:27:15.740 [DEBUG] [i.p.s.IdentifyNodeMessageClass:76  ]- NODE 13: FLIRS = false
	Line 3701: 2016-06-14 08:27:15.740 [DEBUG] [i.p.s.IdentifyNodeMessageClass:77  ]- NODE 13: Security = false
	Line 3702: 2016-06-14 08:27:15.740 [DEBUG] [i.p.s.IdentifyNodeMessageClass:78  ]- NODE 13: Max Baud = 40000
	Line 3703: 2016-06-14 08:27:15.740 [DEBUG] [i.p.s.IdentifyNodeMessageClass:94  ]- NODE 13: Basic = Routing Slave
	Line 3704: 2016-06-14 08:27:15.740 [DEBUG] [i.p.s.IdentifyNodeMessageClass:102 ]- NODE 13: Generic = Binary Sensor
	Line 3705: 2016-06-14 08:27:15.740 [DEBUG] [i.p.s.IdentifyNodeMessageClass:110 ]- NODE 13: Specific = Routing Binary Sensor
	Line 3706: 2016-06-14 08:27:15.740 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:243 ]- NODE 13: Creating new instance of command class NO_OPERATION
	Line 3707: 2016-06-14 08:27:15.740 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:243 ]- NODE 13: Creating new instance of command class BASIC
	Line 3708: 2016-06-14 08:27:15.740 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:243 ]- NODE 13: Creating new instance of command class SENSOR_BINARY
	Line 3715: 2016-06-14 08:27:15.756 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1034]- NODE 13: Node advancer - PROTOINFO: Transaction complete (IdentifyNode:Request) success(true)
	Line 3716: 2016-06-14 08:27:15.756 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:202 ]- NODE 13: Node advancer - checking initialisation queue. Queue size 1.
	Line 3717: 2016-06-14 08:27:15.756 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:208 ]- NODE 13: Node advancer - message removed from queue. Queue size 0.
	Line 3718: 2016-06-14 08:27:15.756 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:267 ]- NODE 13: Node advancer - PROTOINFO: queue length(0), free to send(true)
	Line 3719: 2016-06-14 08:27:15.756 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:332 ]- NODE 13: Node advancer: loop - PROTOINFO try 1: stageAdvanced(false)
	Line 3720: 2016-06-14 08:27:15.756 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:890 ]- NODE 13: Node advancer - advancing to NEIGHBORS
	Line 3721: 2016-06-14 08:27:15.756 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:332 ]- NODE 13: Node advancer: loop - NEIGHBORS try 0: stageAdvanced(true)
	Line 3722: 2016-06-14 08:27:15.756 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:356 ]- NODE 13: Node advancer: NEIGHBORS - send RoutingInfo
	Line 3723: 2016-06-14 08:27:15.756 [DEBUG] [p.s.GetRoutingInfoMessageClass:30  ]- NODE 13: Request routing info
	Line 3726: 2016-06-14 08:27:15.756 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:240 ]- NODE 13: Node advancer - queued packet. Queue length is 1
	Line 3960: 2016-06-14 08:27:15.818 [DEBUG] [p.s.GetRoutingInfoMessageClass:49  ]- NODE 13: Got NodeRoutingInfo request.
	Line 3961: 2016-06-14 08:27:15.818 [DEBUG] [p.s.GetRoutingInfoMessageClass:79  ]- NODE 13: Neighbor nodes: 5 9
	Line 3970: 2016-06-14 08:27:15.834 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1034]- NODE 13: Node advancer - NEIGHBORS: Transaction complete (GetRoutingInfo:Request) success(true)
	Line 3971: 2016-06-14 08:27:15.834 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:202 ]- NODE 13: Node advancer - checking initialisation queue. Queue size 1.
	Line 3972: 2016-06-14 08:27:15.834 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:208 ]- NODE 13: Node advancer - message removed from queue. Queue size 0.
	Line 3973: 2016-06-14 08:27:15.834 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:267 ]- NODE 13: Node advancer - NEIGHBORS: queue length(0), free to send(true)
	Line 3974: 2016-06-14 08:27:15.834 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:332 ]- NODE 13: Node advancer: loop - NEIGHBORS try 1: stageAdvanced(false)
	Line 3975: 2016-06-14 08:27:15.834 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:890 ]- NODE 13: Node advancer - advancing to FAILED_CHECK
	Line 3976: 2016-06-14 08:27:15.834 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:332 ]- NODE 13: Node advancer: loop - FAILED_CHECK try 0: stageAdvanced(true)
	Line 3977: 2016-06-14 08:27:15.834 [DEBUG] [i.p.s.IsFailedNodeMessageClass:32  ]- NODE 13: Requesting IsFailedNode status from controller.
	Line 3980: 2016-06-14 08:27:15.834 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:240 ]- NODE 13: Node advancer - queued packet. Queue length is 1
	Line 4191: 2016-06-14 08:27:15.910 [WARN ] [i.p.s.IsFailedNodeMessageClass:53  ]- NODE 13: Is currently marked as failed by the controller!
	Line 4192: 2016-06-14 08:27:15.910 [DEBUG] [.z.internal.protocol.ZWaveNode:260 ]- NODE 13: Node is DEAD.
	Line 4193: 2016-06-14 08:27:15.910 [DEBUG] [.z.internal.protocol.ZWaveNode:269 ]- NODE 13: Initialisation incomplete, not signalling state change.
	Line 4200: 2016-06-14 08:27:15.911 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1034]- NODE 13: Node advancer - FAILED_CHECK: Transaction complete (IsFailedNodeID:Request) success(true)
	Line 4201: 2016-06-14 08:27:15.911 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:202 ]- NODE 13: Node advancer - checking initialisation queue. Queue size 1.
	Line 4202: 2016-06-14 08:27:15.911 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:208 ]- NODE 13: Node advancer - message removed from queue. Queue size 0.
	Line 4203: 2016-06-14 08:27:15.911 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:267 ]- NODE 13: Node advancer - FAILED_CHECK: queue length(0), free to send(true)
	Line 4204: 2016-06-14 08:27:15.911 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:332 ]- NODE 13: Node advancer: loop - FAILED_CHECK try 1: stageAdvanced(false)
	Line 4205: 2016-06-14 08:27:15.911 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:890 ]- NODE 13: Node advancer - advancing to WAIT
	Line 4206: 2016-06-14 08:27:15.912 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:332 ]- NODE 13: Node advancer: loop - WAIT try 0: stageAdvanced(true)
	Line 4207: 2016-06-14 08:27:15.912 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:380 ]- NODE 13: Node advancer: WAIT - Listening=false, FrequentlyListening=false
	Line 4208: 2016-06-14 08:27:15.912 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:398 ]- NODE 13: Node advancer: WAIT - Still waiting!
	Line 4420: 2016-06-14 08:27:16.011 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ]- NODE 13: Polling list: item Door_Laundry_Battery is not completed initialisation
	Line 4423: 2016-06-14 08:27:16.011 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ]- NODE 13: Polling list: item Door_Laundry is not completed initialisation
	Line 5955: 2016-06-14 08:29:05.393 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ]- NODE 13: Polling list: item Door_Laundry_Battery is not completed initialisation
	Line 5957: 2016-06-14 08:29:05.393 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ]- NODE 13: Polling list: item Door_Laundry is not completed initialisation
	Line 6545: 2016-06-14 08:29:33.680 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ]- NODE 13: Polling list: item Door_Laundry_Battery is not completed initialisation
	Line 6546: 2016-06-14 08:29:33.680 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ]- NODE 13: Polling list: item Door_Laundry is not completed initialisation
	Line 6730: 2016-06-14 08:29:46.736 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ]- NODE 13: Polling list: item Door_Laundry_Battery is not completed initialisation
	Line 6731: 2016-06-14 08:29:46.736 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ]- NODE 13: Polling list: item Door_Laundry is not completed initialisation
	Line 6790: 2016-06-14 08:29:58.867 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1020]- NODE 13: Node advancer - WAIT: The WAIT is over!
	Line 6791: 2016-06-14 08:29:58.867 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:202 ]- NODE 13: Node advancer - checking initialisation queue. Queue size 0.
	Line 8094: 2016-06-14 08:32:45.372 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ]- NODE 13: Polling list: item Door_Laundry_Battery is not completed initialisation
	Line 8095: 2016-06-14 08:32:45.372 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ]- NODE 13: Polling list: item Door_Laundry is not completed initialisation
	Line 9636: 2016-06-14 08:37:20.025 [DEBUG] [.z.i.config.ZWaveConfiguration:977 ]- NODE 13: Heal node
	Line 9637: 2016-06-14 08:37:20.027 [DEBUG] [z.internal.ZWaveNetworkMonitor:275 ]- NODE 13: Starting heal
	Line 11832: 2016-06-14 08:43:29.076 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ]- NODE 13: Polling list: item Door_Laundry_Battery is not completed initialisation
	Line 11833: 2016-06-14 08:43:29.076 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ]- NODE 13: Polling list: item Door_Laundry is not completed initialisation
	Line 11836: 2016-06-14 08:43:29.076 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ]- NODE 13: Polling list: item Door_Laundry_Battery is not completed initialisation
	Line 11837: 2016-06-14 08:43:29.076 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ]- NODE 13: Polling list: item Door_Laundry is not completed initialisation
	Line 11840: 2016-06-14 08:43:29.077 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ]- NODE 13: Polling list: item Door_Laundry_Battery is not completed initialisation
	Line 11841: 2016-06-14 08:43:29.077 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ]- NODE 13: Polling list: item Door_Laundry is not completed initialisation
	Line 11844: 2016-06-14 08:43:29.077 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ]- NODE 13: Polling list: item Door_Laundry_Battery is not completed initialisation
	Line 11845: 2016-06-14 08:43:29.077 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ]- NODE 13: Polling list: item Door_Laundry is not completed initialisation
	Line 11848: 2016-06-14 08:43:29.078 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ]- NODE 13: Polling list: item Door_Laundry_Battery is not completed initialisation
	Line 11849: 2016-06-14 08:43:29.078 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ]- NODE 13: Polling list: item Door_Laundry is not completed initialisation
	Line 11852: 2016-06-14 08:43:29.078 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ]- NODE 13: Polling list: item Door_Laundry_Battery is not completed initialisation
	Line 11853: 2016-06-14 08:43:29.078 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ]- NODE 13: Polling list: item Door_Laundry is not completed initialisation
	Line 11856: 2016-06-14 08:43:29.079 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ]- NODE 13: Polling list: item Door_Laundry_Battery is not completed initialisation
	Line 11857: 2016-06-14 08:43:29.079 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ]- NODE 13: Polling list: item Door_Laundry is not completed initialisation
	Line 11866: 2016-06-14 08:43:29.080 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ]- NODE 13: Polling list: item Door_Laundry_Battery is not completed initialisation
	Line 11868: 2016-06-14 08:43:29.080 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ]- NODE 13: Polling list: item Door_Laundry is not completed initialisation
	Line 11877: 2016-06-14 08:43:29.082 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ]- NODE 13: Polling list: item Door_Laundry_Battery is not completed initialisation
	Line 11878: 2016-06-14 08:43:29.082 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ]- NODE 13: Polling list: item Door_Laundry is not completed initialisation
	Line 11886: 2016-06-14 08:43:29.084 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ]- NODE 13: Polling list: item Door_Laundry_Battery is not completed initialisation
	Line 11887: 2016-06-14 08:43:29.084 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ]- NODE 13: Polling list: item Door_Laundry is not completed initialisation
	Line 11895: 2016-06-14 08:43:29.085 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ]- NODE 13: Polling list: item Door_Laundry_Battery is not completed initialisation
	Line 11896: 2016-06-14 08:43:29.085 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ]- NODE 13: Polling list: item Door_Laundry is not completed initialisation
	Line 11904: 2016-06-14 08:43:29.087 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ]- NODE 13: Polling list: item Door_Laundry_Battery is not completed initialisation
	Line 11905: 2016-06-14 08:43:29.087 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ]- NODE 13: Polling list: item Door_Laundry is not completed initialisation
	Line 11914: 2016-06-14 08:43:29.089 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ]- NODE 13: Polling list: item Door_Laundry_Battery is not completed initialisation
	Line 11917: 2016-06-14 08:43:29.089 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ]- NODE 13: Polling list: item Door_Laundry is not completed initialisation
	Line 11929: 2016-06-14 08:43:29.091 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ]- NODE 13: Polling list: item Door_Laundry_Battery is not completed initialisation
	Line 11930: 2016-06-14 08:43:29.091 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ]- NODE 13: Polling list: item Door_Laundry is not completed initialisation
	Line 17104: 2016-06-14 08:57:27.955 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ]- NODE 13: Polling list: item Door_Laundry_Battery is not completed initialisation
	Line 17105: 2016-06-14 08:57:27.955 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ]- NODE 13: Polling list: item Door_Laundry is not completed initialisation
	Line 22652: 2016-06-14 09:12:40.384 [DEBUG] [ApplicationCommandMessageClass:40  ]- NODE 13: Application Command Request (FAILED:PING)
	Line 22653: 2016-06-14 09:12:40.384 [DEBUG] [.z.internal.protocol.ZWaveNode:244 ]- NODE 13: Node has risen from the DEAD. Init stage is PING:{}.
	Line 22654: 2016-06-14 09:12:40.384 [DEBUG] [.z.internal.protocol.ZWaveNode:269 ]- NODE 13: Initialisation incomplete, not signalling state change.
	Line 22655: 2016-06-14 09:12:40.384 [DEBUG] [ApplicationCommandMessageClass:58  ]- NODE 13: Incoming command class BASIC
	Line 22656: 2016-06-14 09:12:40.384 [DEBUG] [z.i.p.c.ZWaveBasicCommandClass:73  ]- NODE 13: Received Basic Request
	Line 22657: 2016-06-14 09:12:40.384 [DEBUG] [z.i.p.c.ZWaveBasicCommandClass:77  ]- NODE 13: Basic Set sent to the controller will be processed as Basic Report
	Line 22658: 2016-06-14 09:12:40.384 [DEBUG] [z.i.p.c.ZWaveBasicCommandClass:106 ]- NODE 13: Basic report, value = 0xFF
	Line 22661: 2016-06-14 09:12:40.385 [DEBUG] [.z.internal.ZWaveActiveBinding:466 ]- NODE 13: Got a value event from Z-Wave network, endpoint = 0, command class = BASIC, value = 255

Do you see anything that stands out? I checked the neighbors in habmin and it’s now seeing the thermostat as a neighbor. In fact, has the same neighbors as the working garage door sensor.

I’m still trying not to buy a repeater until I know for certain that this is a range issue and not a hardware configuration issue. Thanks to all for the help in trying to get this thing working.

dinki · June 21, 2016, 1:50pm

@chris So I purchased the repeater and have added it successfully. I excluded/included the door sensor near the controller and initialized successfully. The repeater was listed as a neighbor. I moved the sensor back in place and did a heal on it. I checked this morning and the sensor shows up green so I’m assuming it’s working. I checked and the repeater is not listed as a neighbor. It is located about 1m/3ft away! The repeater is showing up as yellow. Needless to say, the door sensor still isn’t working. It does update on very rare occasion but always shows status of OPEN even though the door is closed. Here’s the parts from Zwave.log pertaining to the door sensor node:

	Line 276600: 2016-06-21 08:05:18.413 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:260 ]- NODE 15: Putting message SendData in wakeup queue.
	Line 276601: 2016-06-21 08:05:18.413 [DEBUG] [.b.z.i.c.ZWaveBatteryConverter:62  ]- NODE 15: Generating poll message for BATTERY endpoint 0
	Line 276602: 2016-06-21 08:05:18.413 [DEBUG] [i.p.c.ZWaveBatteryCommandClass:137 ]- NODE 15: Creating new message for application command BATTERY_GET
	Line 276603: 2016-06-21 08:05:18.414 [DEBUG] [o.b.z.i.protocol.SerialMessage:113 ]- NODE 15: Creating empty message of class = SendData (0x13), type = Request (0x00)
	Line 276605: 2016-06-21 08:05:18.414 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:255 ]- NODE 15: Message already on the wake-up queue. Removing original.
	Line 276606: 2016-06-21 08:05:18.414 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:260 ]- NODE 15: Putting message SendData in wakeup queue.
	Line 280883: 2016-06-21 08:17:18.767 [DEBUG] [i.c.ZWaveBinarySensorConverter:69  ]- NODE 15: Generating poll message for SENSOR_BINARY, endpoint 0
	Line 280884: 2016-06-21 08:17:18.767 [DEBUG] [.ZWaveBinarySensorCommandClass:131 ]- NODE 15: Creating new message for application command SENSOR_BINARY_GET
	Line 280885: 2016-06-21 08:17:18.768 [DEBUG] [o.b.z.i.protocol.SerialMessage:113 ]- NODE 15: Creating empty message of class = SendData (0x13), type = Request (0x00)
	Line 280887: 2016-06-21 08:17:18.768 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:255 ]- NODE 15: Message already on the wake-up queue. Removing original.
	Line 280888: 2016-06-21 08:17:18.768 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:260 ]- NODE 15: Putting message SendData in wakeup queue.
	Line 280889: 2016-06-21 08:17:18.768 [DEBUG] [.b.z.i.c.ZWaveBatteryConverter:62  ]- NODE 15: Generating poll message for BATTERY endpoint 0
	Line 280890: 2016-06-21 08:17:18.768 [DEBUG] [i.p.c.ZWaveBatteryCommandClass:137 ]- NODE 15: Creating new message for application command BATTERY_GET
	Line 280891: 2016-06-21 08:17:18.769 [DEBUG] [o.b.z.i.protocol.SerialMessage:113 ]- NODE 15: Creating empty message of class = SendData (0x13), type = Request (0x00)
	Line 280893: 2016-06-21 08:17:18.769 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:255 ]- NODE 15: Message already on the wake-up queue. Removing original.
	Line 280894: 2016-06-21 08:17:18.769 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:260 ]- NODE 15: Putting message SendData in wakeup queue.

The item config looks like this:

Contact		Door_Laundry			"Laundry Door [%s]"										<door>		(Laundry,Alarm)			{ zwave="15:command=SENSOR_BINARY,respond_to_basic=true", imperihab="room:Laundry,label:Laundry Door" }
Number		Door_Laundry_Battery	"Laundry Door battery [%d %%]"							<battery>	(Laundry,Battery)		{ zwave="15:command=BATTERY" }

And here’s some shots of the sensor and repeater in Habmin:

I’m really not understanding where the problem lies. This sensor was working fine before switching to OH. The OH server is, however, a bit farther away but I’d hope that the repeater would have solved that. Again, the garage door sensor located almost in the same spot is working fine. Perhaps the battery needs to be changed, but it last reported 85% and the battery is less than two months old.

This will probably be my last post on this subject as I can’t figure out what to do. I guess I’ll build a Mysensors door sensor and tie it into OH via my exisiting Mysensors network. I really prefer not to do this as I’ve invested a good bit of time and a little money on this. It would be most appreciated if you could look over my logs/settings to see if there is an obvious problem with what I’m doing. Your help is greatly appreciated as is your work on this fantastic binding! Thanks again.

EDIT My post was too long so I had to truncate the log file. Please let me know if you need to see more of it.

TheKorn · June 21, 2016, 2:09pm

Just out of curiosity, what other devices do you have on your zwave network?

Reason why I ask is because I wound up accidentally DoS’ing my Z-wave network by setting up, shall we say, overly aggressive power reporting on a bunch of my devices. (Think 20-some devices reporting power every 5 seconds for no good reason, in addition to all the other z-wave traffic.) Once I backed down the power reporting to non-stupid frequencies, everything fell right into place.

Just a WAG, but might be some food for thought.

dinki · June 21, 2016, 2:31pm

Any ideas are welcome. My network consists of Zstick 2, 2 Lamp switch Module, Garage Door Sensor (Battery), Trane thermostat, Lamp dimmer module, Repeater, one problematic door sensor (battery). Can you tell me where the power reporting settings are located? Is that battery power you’re reporting or something else?

TheKorn · June 21, 2016, 3:46pm

Well where it’s set depends on exactly what type of dimmer, lamp module, etc. (i.e. they’re device specific z-wave options.) Your particular devices might not support power reporting at all, for example.

And by power reporting, I don’t mean battery level I mean power being used by the end device. i.e. how much power is the lamp plugged into the lamp dimmer using.

However, you don’t have a large zwave network at all, so even reporting power every 5 seconds I wouldn’t expect three devices to cause a problem. (You have other devices, but only three that I would expect could even possibly be configured to be chatty.)