Zigbee binding

There are a couple of things not merged at the moment - the updated Ember driver with the retry fix, and the discovery updates.

Possibly - for sure the XML file format changed slightly and this would have caused serialisation errors. I’m not 100% sure this is the case here though - I’ll take a look later.

That’s perfectly ok - it’s just reporting that the device doesn’t support something.

No - I’ve not looked at stopping this yet - the timeout regime should mean they appear less often as time goes on, but I will look at killing them off (can you raise an issue for this one please?).

@5iver is the latest version still looking ok for you? If so I’ll probably try to get this all merged.

I’ve found the reason for the above exception - might be related to old XML files, in any case it’s caught.

There’s one issue that I want to get merged after the current stuff, and that is that I think your dongle requires XOn/XOff flow control - I found a comment in some Silabs docs stating that 57k6 uses this. It might account for some of the retry errors in the logs. I have a PR ready to go for that once I’ve got this merged.

It is currently working well for me and I have no complaints… BUT

  • I have not spent too much time in the logs, other than what I sent after updating,
  • I only used the previous test version a few days before going back to master.
  • I haven’t had it running for more than ~12h (updated earlier today to OH snapshot 1218 to get zwave config parameters back).
  • I haven’t added or removed any devices yet

If you provide a test jar, I’ll check it out… I have nothing to play with in Zigbeeland until transition time is wrapped up. :wink:

I think I may have messed up my limited, small zigbee network here getting ahead of myself.

I downloaded the test binding from Chris posted above here. And since i was running on the latest OH2 build, I uninstalled the Zigbee 2.3 binding and then placed the jar file Chris posted in my Addons folder.

After trying and having issues with my lights (probably my own fault), I then went and removed the binding from the Addon’s folder and reinstalled the zigbee binding from PaperUI.

But now I get some strange errors in the log like this:

2018-02-20 20:57:19.648 [ERROR] [ng.zigbee.handler.ZigBeeThingHandler] - F0D1B8000000EB47: Exception creating channels 
java.lang.ClassCastException: java.lang.String cannot be cast to java.math.BigDecimal
	at org.openhab.binding.zigbee.internal.converter.config.ZclLevelControlConfig.updateConfiguration(ZclLevelControlConfig.java:119) [196:org.openhab.binding.zigbee:2.2.0.201802192145]
	at org.openhab.binding.zigbee.internal.converter.ZigBeeConverterColorColor.updateConfiguration(ZigBeeConverterColorColor.java:428) [196:org.openhab.binding.zigbee:2.2.0.201802192145]
	at org.openhab.binding.zigbee.handler.ZigBeeThingHandler.doNodeInitialisation(ZigBeeThingHandler.java:234) [196:org.openhab.binding.zigbee:2.2.0.201802192145]
	at org.openhab.binding.zigbee.handler.ZigBeeThingHandler.access$0(ZigBeeThingHandler.java:156) [196:org.openhab.binding.zigbee:2.2.0.201802192145]
	at org.openhab.binding.zigbee.handler.ZigBeeThingHandler$1.call(ZigBeeThingHandler.java:150) [196:org.openhab.binding.zigbee:2.2.0.201802192145]
	at org.openhab.binding.zigbee.handler.ZigBeeThingHandler$1.call(ZigBeeThingHandler.java:1) [196:org.openhab.binding.zigbee:2.2.0.201802192145]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
	at java.lang.Thread.run(Thread.java:748) [?:?]
2018-02-20 20:57:19.782 [ERROR] [core.karaf.internal.FeatureInstaller] - Failed installing 'openhab-misc-myopenhab': Error restarting bundles:
	Could not resolve module: org.openhab.binding.zigbee [251]
  Another singleton bundle selected: osgi.identity; type="osgi.bundle"; version:Version="2.2.0.201802192145"; osgi.identity="org.openhab.binding.zigbee"; singleton:="true"

2018-02-20 20:58:21.369 [ERROR] [core.karaf.internal.FeatureInstaller] - Failed installing 'openhab-misc-myopenhab': Error restarting bundles:
	Could not resolve module: org.openhab.binding.zigbee [251]
  Another singleton bundle selected: osgi.identity; type="osgi.bundle"; version:Version="2.2.0.201802192145"; osgi.identity="org.openhab.binding.zigbee"; singleton:="true"

2018-02-20 20:59:23.384 [ERROR] [core.karaf.internal.FeatureInstaller] - Failed installing 'openhab-misc-myopenhab': Error restarting bundles:
	Could not resolve module: org.openhab.binding.zigbee [251]
  Another singleton bundle selected: osgi.identity; type="osgi.bundle"; version:Version="2.2.0.201802192145"; osgi.identity="org.openhab.binding.zigbee"; singleton:="true"

2018-02-20 21:00:00.078 [INFO ] [arthome.model.script.speedtest.rules] - --> speedtest executed...
2018-02-20 21:00:01.079 [INFO ] [lipse.smarthome.io.net.exec.ExecUtil] - executed commandLine '[phantomjs, /etc/openhab2/scripts/weather.js]'
2018-02-20 21:00:34.779 [ERROR] [core.karaf.internal.FeatureInstaller] - Failed installing 'openhab-misc-myopenhab': Error restarting bundles:
	Could not resolve module: org.openhab.binding.zigbee [251]
  Another singleton bundle selected: osgi.identity; type="osgi.bundle"; version:Version="2.2.0.201802192145"; osgi.identity="org.openhab.binding.zigbee"; singleton:="true"

My bulbs all show as online also, yet I can only control 2 of the 6 that I paired.

The singleton:="true" is usually a dead giveaway that you have two bindings running. Confirm with bundle:list | grep Zigbee. Sometimes an OH restart can help. Otherwise, bundle:uninstall X, where X is ID of the bundle you want to remove.

@5iver

Thanks. An OH2 reboot was not clearing it. But yes, in the Karaf console they were both there. I uninstalled the 2.2 one, and rebooted. And now do have control of all bulbs again.

The one thing I have noticed is that I am experiencing a delay when placing 4 bulbs in a group. The group works, but each bulb turns on separately about 1/2 second apart from each other. And these are color bulbs, so changing any color or dimming goes 1 bulb at a time.

This is in an actual group setup, and not via a rule. These 4 bulbs are Osram RGBW recessed lights.

Do you see this all the time? After a reboot, my system is pretty busy, especially with a combo zwave/zigbee controller, and I can see similar delays, but not just for Zigbee bulbs. Right now, with a steady system load, I still see a very very slight delay, but it’s there. I assume you mean OH groups and not zigbee groups? I don’t think Chris has implemented zigbee groups/groupcasting.

Yes, I meant OH groups, and the delay seemed fairly regular but I also am struggling to keep the zigbee bulbs connected.

They worked last night, but this morning could not control any of them. I will try to login in remotely to my OH install today if i can and check the logs but guessing the controller is not seeing the lights again.

So as an update. Last night I needed to repair my 6 non-hue zigbee bulbs with the controller again. And then this morning had control of 4 of them only with 2 being unresponsive although they were left powered on all night.

I think chris mentioned he is working on better persistence with the binding and I’m happy to test anything anytime.

And I’ll see what I have working at home later tonight. I do wonder if perhaps running a Hue and Lightify bridge in conjunction with the binding is causing some interference?

Hi, I’ve just configured openhab with a telegesis dongle and the latest test binding (org.openhab.binding.zigbee_2.2.0.201802192145.jar). After pairing an Ikea tradfri bulb I get the following error in the logs and it never finishes initializing:

2018-02-22 21:13:38.984 [DEBUG] [internal.ZigBeeNodeServiceDiscoverer] - 000B57FFFE9E2837: Node SVC Discovery running
2018-02-22 21:13:38.989 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=36, ieeeAddr=000B57FFFE9E2837, requestType=0, startIndex=0]
2018-02-22 21:13:38.995 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=65533/0, profile=0000, cluster=0, addressMode=DEVICE, radius=31, sequence=54, payload=00 37 28 9E FE FF 57 0B 00 00 00]
2018-02-22 21:13:39.000 [DEBUG] [ngle.telegesis.ZigBeeDongleTelegesis] - Telegesis send: TelegesisSendMulticastCommand [radius=31, address=65533, sourceEp=0, destEp=0, profileId=0, clusterId=0, messageData=00 37 28 9E FE FF 57 0B 00 00 00]
2018-02-22 21:13:39.004 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis queue: 1
2018-02-22 21:13:39.008 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis: TelegesisSendMulticastCommand [radius=31, address=65533, sourceEp=0, destEp=0, profileId=0, clusterId=0, messageData=00 37 28 9E FE FF 57 0B 00 00 00]
2018-02-22 21:13:39.022 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis Data: 41 54 2B 53 45 4E 44 4D 43 41 53 54 42 3A 30 42 2C 31 46 2C 46 46 46 44 2C 30 30 2C 30 30 2C 30 30 30 30 2C 30 30 30 30 0D 00 37 28 9E FE FF 57 0B 00 00 00 0D 0A
2018-02-22 21:13:39.146 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data: 4F 4B
2018-02-22 21:13:39.152 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisSendMulticastCommand [radius=31, address=65533, sourceEp=0, destEp=0, profileId=0, clusterId=0, messageData=00 37 28 9E FE FF 57 0B 00 00 00, status=SUCCESS]
2018-02-22 21:13:49.027 [DEBUG] [internal.ZigBeeNodeServiceDiscoverer] - 56466: Node SVC Discovery NetworkAddressRequest returned null
2018-02-22 21:13:49.030 [DEBUG] [internal.ZigBeeNodeServiceDiscoverer] - 000B57FFFE9E2837: Node SVC Discovery request NWK_ADDRESS failed. Retry 22, wait 53832ms before retry.

I’ve now added a tradfri motion sensor (000B57FFFE9707AE) and tradfri switch (000B57FFFEEE19F6). Original e27 1000lm bulb is 000B57FFFE9E2837.

2018-02-22 21:48:04.500 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis queue: 1
2018-02-22 21:48:04.502 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis: TelegesisSendUnicastCommand [address=33812, sourceEp=0, destEp=0, profileId=0, clusterId=2, messageData=00 14 84, messageId=null]
2018-02-22 21:48:04.511 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis Data: 41 54 2B 53 45 4E 44 55 43 41 53 54 42 3A 30 33 2C 38 34 31 34 2C 30 30 2C 30 30 2C 30 30 30 30 2C 30 30 30 32 0D 00 14 84 0D 0A
2018-02-22 21:48:04.642 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data: 53 45 51 3A 43 46
2018-02-22 21:48:04.646 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data: 4F 4B
2018-02-22 21:48:04.651 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisSendUnicastCommand [address=33812, sourceEp=0, destEp=0, profileId=0, clusterId=2, messageData=00 14 84, messageId=207, status=SUCCESS]
2018-02-22 21:48:07.987 [DEBUG] [internal.ZigBeeNodeServiceDiscoverer] - 000B57FFFE9E2837: Node SVC Discovery running
2018-02-22 21:48:07.994 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=8A, ieeeAddr=000B57FFFE9E2837, requestType=0, startIndex=0]
2018-02-22 21:48:08.000 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=65533/0, profile=0000, cluster=0, addressMode=DEVICE, radius=31, sequence=138, payload=00 37 28 9E FE FF 57 0B 00 00 00]
2018-02-22 21:48:08.005 [DEBUG] [ngle.telegesis.ZigBeeDongleTelegesis] - Telegesis send: TelegesisSendMulticastCommand [radius=31, address=65533, sourceEp=0, destEp=0, profileId=0, clusterId=0, messageData=00 37 28 9E FE FF 57 0B 00 00 00]
2018-02-22 21:48:08.010 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis queue: 1
2018-02-22 21:48:08.016 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis: TelegesisSendMulticastCommand [radius=31, address=65533, sourceEp=0, destEp=0, profileId=0, clusterId=0, messageData=00 37 28 9E FE FF 57 0B 00 00 00]
2018-02-22 21:48:08.030 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis Data: 41 54 2B 53 45 4E 44 4D 43 41 53 54 42 3A 30 42 2C 31 46 2C 46 46 46 44 2C 30 30 2C 30 30 2C 30 30 30 30 2C 30 30 30 30 0D 00 37 28 9E FE FF 57 0B 00 00 00 0D 0A
2018-02-22 21:48:08.157 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data: 4F 4B
2018-02-22 21:48:08.160 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisSendMulticastCommand [radius=31, address=65533, sourceEp=0, destEp=0, profileId=0, clusterId=0, messageData=00 37 28 9E FE FF 57 0B 00 00 00, status=SUCCESS]
2018-02-22 21:48:09.331 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data: 4E 41 43 4B 3A 43 46
2018-02-22 21:48:09.334 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisNackMessageEvent [messageId=207]
2018-02-22 21:48:09.338 [DEBUG] [ngle.telegesis.ZigBeeDongleTelegesis] - Telegesis RX: TelegesisNackMessageEvent [messageId=207]
2018-02-22 21:48:09.341 [DEBUG] [ngle.telegesis.ZigBeeDongleTelegesis] - Unhandled Telegesis Frame: TelegesisNackMessageEvent [messageId=207]
2018-02-22 21:48:14.515 [DEBUG] [internal.ZigBeeNodeServiceDiscoverer] - 000B57FFFEEE19F6: Node SVC Discovery NodeDescriptorResponse returned null
2018-02-22 21:48:14.519 [DEBUG] [internal.ZigBeeNodeServiceDiscoverer] - 000B57FFFEEE19F6: Node SVC Discovery request NODE_DESCRIPTOR failed. Retry 16, wait 41591ms before retry.
2018-02-22 21:48:18.035 [DEBUG] [internal.ZigBeeNodeServiceDiscoverer] - 56466: Node SVC Discovery NetworkAddressRequest returned null
2018-02-22 21:48:18.040 [DEBUG] [internal.ZigBeeNodeServiceDiscoverer] - 000B57FFFE9E2837: Node SVC Discovery request NWK_ADDRESS failed. Retry 52, wait 49346ms before retry.
2018-02-22 21:48:23.114 [DEBUG] [internal.ZigBeeNodeServiceDiscoverer] - 000B57FFFE9707AE: Node SVC Discovery running
2018-02-22 21:48:23.118 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NodeDescriptorRequest [0/0 -> 61706/0, cluster=0002, TID=8B, nwkAddrOfInterest=61706]
2018-02-22 21:48:23.124 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=61706/0, profile=0000, cluster=2, addressMode=DEVICE, radius=31, sequence=139, payload=00 0A F1]
2018-02-22 21:48:23.129 [DEBUG] [ngle.telegesis.ZigBeeDongleTelegesis] - Telegesis send: TelegesisSendUnicastCommand [address=61706, sourceEp=0, destEp=0, profileId=0, clusterId=2, messageData=00 0A F1, messageId=null]
2018-02-22 21:48:23.134 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis queue: 1
2018-02-22 21:48:23.139 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis: TelegesisSendUnicastCommand [address=61706, sourceEp=0, destEp=0, profileId=0, clusterId=2, messageData=00 0A F1, messageId=null]
2018-02-22 21:48:23.151 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis Data: 41 54 2B 53 45 4E 44 55 43 41 53 54 42 3A 30 33 2C 46 31 30 41 2C 30 30 2C 30 30 2C 30 30 30 30 2C 30 30 30 32 0D 00 0A F1 0D 0A
2018-02-22 21:48:23.281 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data: 53 45 51 3A 44 31
2018-02-22 21:48:23.285 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data: 4F 4B
2018-02-22 21:48:23.287 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisSendUnicastCommand [address=61706, sourceEp=0, destEp=0, profileId=0, clusterId=2, messageData=00 0A F1, messageId=209, status=SUCCESS]
2018-02-22 21:48:27.970 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data: 4E 41 43 4B 3A 44 31
2018-02-22 21:48:27.973 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisNackMessageEvent [messageId=209]
2018-02-22 21:48:27.976 [DEBUG] [ngle.telegesis.ZigBeeDongleTelegesis] - Telegesis RX: TelegesisNackMessageEvent [messageId=209]
2018-02-22 21:48:27.979 [DEBUG] [ngle.telegesis.ZigBeeDongleTelegesis] - Unhandled Telegesis Frame: TelegesisNackMessageEvent [messageId=209]
2018-02-22 21:48:33.157 [DEBUG] [internal.ZigBeeNodeServiceDiscoverer] - 000B57FFFE9707AE: Node SVC Discovery NodeDescriptorResponse returned null
2018-02-22 21:48:33.162 [DEBUG] [internal.ZigBeeNodeServiceDiscoverer] - 000B57FFFE9707AE: Node SVC Discovery request NODE_DESCRIPTOR failed. Retry 16, wait 28613ms before retry.
2018-02-22 21:48:52.692 [INFO ] [ipse.smarthome.model.script.occupied] - House Occupied set to ON. Trigger: Room_Occupied
2018-02-22 21:48:52.703 [INFO ] [ipse.smarthome.model.script.occupied] - Downstairs Occupied set to ON. Trigger: Room_Occupied
2018-02-22 21:48:56.113 [DEBUG] [internal.ZigBeeNodeServiceDiscoverer] - 000B57FFFEEE19F6: Node SVC Discovery running
2018-02-22 21:48:56.118 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NodeDescriptorRequest [0/0 -> 33812/0, cluster=0002, TID=8C, nwkAddrOfInterest=33812]
2018-02-22 21:48:56.121 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=33812/0, profile=0000, cluster=2, addressMode=DEVICE, radius=31, sequence=140, payload=00 14 84]
2018-02-22 21:48:56.124 [DEBUG] [ngle.telegesis.ZigBeeDongleTelegesis] - Telegesis send: TelegesisSendUnicastCommand [address=33812, sourceEp=0, destEp=0, profileId=0, clusterId=2, messageData=00 14 84, messageId=null]
2018-02-22 21:48:56.127 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis queue: 1
2018-02-22 21:48:56.130 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis: TelegesisSendUnicastCommand [address=33812, sourceEp=0, destEp=0, profileId=0, clusterId=2, messageData=00 14 84, messageId=null]
2018-02-22 21:48:56.143 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis Data: 41 54 2B 53 45 4E 44 55 43 41 53 54 42 3A 30 33 2C 38 34 31 34 2C 30 30 2C 30 30 2C 30 30 30 30 2C 30 30 30 32 0D 00 14 84 0D 0A
2018-02-22 21:48:56.271 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data: 53 45 51 3A 44 32
2018-02-22 21:48:56.275 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data: 4F 4B
2018-02-22 21:48:56.278 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisSendUnicastCommand [address=33812, sourceEp=0, destEp=0, profileId=0, clusterId=2, messageData=00 14 84, messageId=210, status=SUCCESS]
2018-02-22 21:49:00.960 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data: 4E 41 43 4B 3A 44 32
2018-02-22 21:49:00.966 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisNackMessageEvent [messageId=210]
2018-02-22 21:49:00.969 [DEBUG] [ngle.telegesis.ZigBeeDongleTelegesis] - Telegesis RX: TelegesisNackMessageEvent [messageId=210]
2018-02-22 21:49:00.971 [DEBUG] [ngle.telegesis.ZigBeeDongleTelegesis] - Unhandled Telegesis Frame: TelegesisNackMessageEvent [messageId=210]
2018-02-22 21:49:01.780 [DEBUG] [internal.ZigBeeNodeServiceDiscoverer] - 000B57FFFE9707AE: Node SVC Discovery running
2018-02-22 21:49:01.784 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NodeDescriptorRequest [0/0 -> 61706/0, cluster=0002, TID=8D, nwkAddrOfInterest=61706]
2018-02-22 21:49:01.787 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=61706/0, profile=0000, cluster=2, addressMode=DEVICE, radius=31, sequence=141, payload=00 0A F1]
2018-02-22 21:49:01.791 [DEBUG] [ngle.telegesis.ZigBeeDongleTelegesis] - Telegesis send: TelegesisSendUnicastCommand [address=61706, sourceEp=0, destEp=0, profileId=0, clusterId=2, messageData=00 0A F1, messageId=null]
2018-02-22 21:49:01.794 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis queue: 1
2018-02-22 21:49:01.797 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis: TelegesisSendUnicastCommand [address=61706, sourceEp=0, destEp=0, profileId=0, clusterId=2, messageData=00 0A F1, messageId=null]
2018-02-22 21:49:01.807 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis Data: 41 54 2B 53 45 4E 44 55 43 41 53 54 42 3A 30 33 2C 46 31 30 41 2C 30 30 2C 30 30 2C 30 30 30 30 2C 30 30 30 32 0D 00 0A F1 0D 0A
2018-02-22 21:49:01.937 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data: 53 45 51 3A 44 33
2018-02-22 21:49:01.941 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data: 4F 4B
2018-02-22 21:49:01.944 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisSendUnicastCommand [address=61706, sourceEp=0, destEp=0, profileId=0, clusterId=2, messageData=00 0A F1, messageId=211, status=SUCCESS]
2018-02-22 21:49:06.148 [DEBUG] [internal.ZigBeeNodeServiceDiscoverer] - 000B57FFFEEE19F6: Node SVC Discovery NodeDescriptorResponse returned null
2018-02-22 21:49:06.152 [DEBUG] [internal.ZigBeeNodeServiceDiscoverer] - 000B57FFFEEE19F6: Node SVC Discovery request NODE_DESCRIPTOR failed. Retry 17, wait 10945ms before retry.
2018-02-22 21:49:06.627 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data: 4E 41 43 4B 3A 44 33
2018-02-22 21:49:06.630 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisNackMessageEvent [messageId=211]
2018-02-22 21:49:06.632 [DEBUG] [ngle.telegesis.ZigBeeDongleTelegesis] - Telegesis RX: TelegesisNackMessageEvent [messageId=211]
2018-02-22 21:49:06.634 [DEBUG] [ngle.telegesis.ZigBeeDongleTelegesis] - Unhandled Telegesis Frame: TelegesisNackMessageEvent [messageId=211]
2018-02-22 21:49:07.389 [DEBUG] [internal.ZigBeeNodeServiceDiscoverer] - 000B57FFFE9E2837: Node SVC Discovery running
2018-02-22 21:49:07.393 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NetworkAddressRequest [0/0 -> 65533/0, cluster=0000, TID=8E, ieeeAddr=000B57FFFE9E2837, requestType=0, startIndex=0]
2018-02-22 21:49:07.397 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=65533/0, profile=0000, cluster=0, addressMode=DEVICE, radius=31, sequence=142, payload=00 37 28 9E FE FF 57 0B 00 00 00]
2018-02-22 21:49:07.401 [DEBUG] [ngle.telegesis.ZigBeeDongleTelegesis] - Telegesis send: TelegesisSendMulticastCommand [radius=31, address=65533, sourceEp=0, destEp=0, profileId=0, clusterId=0, messageData=00 37 28 9E FE FF 57 0B 00 00 00]
2018-02-22 21:49:07.403 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis queue: 1
2018-02-22 21:49:07.407 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis: TelegesisSendMulticastCommand [radius=31, address=65533, sourceEp=0, destEp=0, profileId=0, clusterId=0, messageData=00 37 28 9E FE FF 57 0B 00 00 00]
2018-02-22 21:49:07.418 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis Data: 41 54 2B 53 45 4E 44 4D 43 41 53 54 42 3A 30 42 2C 31 46 2C 46 46 46 44 2C 30 30 2C 30 30 2C 30 30 30 30 2C 30 30 30 30 0D 00 37 28 9E FE FF 57 0B 00 00 00 0D 0A
2018-02-22 21:49:07.545 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data: 4F 4B
2018-02-22 21:49:07.550 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisSendMulticastCommand [radius=31, address=65533, sourceEp=0, destEp=0, profileId=0, clusterId=0, messageData=00 37 28 9E FE FF 57 0B 00 00 00, status=SUCCESS]
2018-02-22 21:49:11.812 [DEBUG] [internal.ZigBeeNodeServiceDiscoverer] - 000B57FFFE9707AE: Node SVC Discovery NodeDescriptorResponse returned null
2018-02-22 21:49:11.817 [DEBUG] [internal.ZigBeeNodeServiceDiscoverer] - 000B57FFFE9707AE: Node SVC Discovery request NODE_DESCRIPTOR failed. Retry 17, wait 46221ms before retry.
2018-02-22 21:49:17.101 [DEBUG] [internal.ZigBeeNodeServiceDiscoverer] - 000B57FFFEEE19F6: Node SVC Discovery running
2018-02-22 21:49:17.104 [DEBUG] [internal.ZigBeeNodeServiceDiscoverer] - 56466: Node SVC Discovery NetworkAddressRequest returned null
2018-02-22 21:49:17.107 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: NodeDescriptorRequest [0/0 -> 33812/0, cluster=0002, TID=8F, nwkAddrOfInterest=33812]
2018-02-22 21:49:17.108 [DEBUG] [internal.ZigBeeNodeServiceDiscoverer] - 000B57FFFE9E2837: Node SVC Discovery request NWK_ADDRESS failed. Retry 53, wait 125608ms before retry.
2018-02-22 21:49:17.112 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=33812/0, profile=0000, cluster=2, addressMode=DEVICE, radius=31, sequence=143, payload=00 14 84]
2018-02-22 21:49:17.117 [DEBUG] [ngle.telegesis.ZigBeeDongleTelegesis] - Telegesis send: TelegesisSendUnicastCommand [address=33812, sourceEp=0, destEp=0, profileId=0, clusterId=2, messageData=00 14 84, messageId=null]
2018-02-22 21:49:17.121 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis queue: 1
2018-02-22 21:49:17.126 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis: TelegesisSendUnicastCommand [address=33812, sourceEp=0, destEp=0, profileId=0, clusterId=2, messageData=00 14 84, messageId=null]
2018-02-22 21:49:17.136 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis Data: 41 54 2B 53 45 4E 44 55 43 41 53 54 42 3A 30 33 2C 38 34 31 34 2C 30 30 2C 30 30 2C 30 30 30 30 2C 30 30 30 32 0D 00 14 84 0D 0A
2018-02-22 21:49:17.266 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data: 53 45 51 3A 44 35
2018-02-22 21:49:17.270 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data: 4F 4B
2018-02-22 21:49:17.273 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisSendUnicastCommand [address=33812, sourceEp=0, destEp=0, profileId=0, clusterId=2, messageData=00 14 84, messageId=213, status=SUCCESS]
2018-02-22 21:49:21.956 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data: 4E 41 43 4B 3A 44 35
2018-02-22 21:49:21.958 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisNackMessageEvent [messageId=213]
2018-02-22 21:49:21.963 [DEBUG] [ngle.telegesis.ZigBeeDongleTelegesis] - Telegesis RX: TelegesisNackMessageEvent [messageId=213]
2018-02-22 21:49:21.967 [DEBUG] [ngle.telegesis.ZigBeeDongleTelegesis] - Unhandled Telegesis Frame: TelegesisNackMessageEvent [messageId=213]
2018-02-22 21:49:27.144 [DEBUG] [internal.ZigBeeNodeServiceDiscoverer] - 000B57FFFEEE19F6: Node SVC Discovery NodeDescriptorResponse returned null
2018-02-22 21:49:27.148 [DEBUG] [internal.ZigBeeNodeServiceDiscoverer] - 000B57FFFEEE19F6: Node SVC Discovery request NODE_DESCRIPTOR failed. Retry 18, wait 43780ms before retry.

And it all works fine? Or is there an issue you want looked at?

Sorry @chris I didn’t mean to be that vague, I wrote this in a hurry!

Basically none of the 3 devices work (bulb, motion sensor, switch). They each have similar error messages in the logs:

For bulb:

2018-02-22 21:48:18.035 [DEBUG] [internal.ZigBeeNodeServiceDiscoverer] - 56466: Node SVC Discovery NetworkAddressRequest returned null
2018-02-22 21:48:18.040 [DEBUG] [internal.ZigBeeNodeServiceDiscoverer] - 000B57FFFE9E2837: Node SVC Discovery request NWK_ADDRESS failed. Retry 52, wait 49346ms before retry.

For motion sensor:

2018-02-22 21:48:33.157 [DEBUG] [internal.ZigBeeNodeServiceDiscoverer] - 000B57FFFE9707AE: Node SVC Discovery NodeDescriptorResponse returned null
2018-02-22 21:48:33.162 [DEBUG] [internal.ZigBeeNodeServiceDiscoverer] - 000B57FFFE9707AE: Node SVC Discovery request NODE_DESCRIPTOR failed. Retry 16, wait 28613ms before retry.

For switch:

2018-02-22 21:49:27.144 [DEBUG] [internal.ZigBeeNodeServiceDiscoverer] - 000B57FFFEEE19F6: Node SVC Discovery NodeDescriptorResponse returned null
2018-02-22 21:49:27.148 [DEBUG] [internal.ZigBeeNodeServiceDiscoverer] - 000B57FFFEEE19F6: Node SVC Discovery request NODE_DESCRIPTOR failed. Retry 18, wait 43780ms before retry.

Any suggestions as to what this might be / what I should try?

Generally, this “just” means the device isn’t responding to the request. Normally, this probably means that the device is out of range maybe. Battery operated devices in ZigBee can be especially prone to this as from what I’ve seen many don’t respect the protocol requirement to check for messages at least every 7.5 seconds (this obviously doesn’t relate to the bulb - I don’t know if the switch is battery operated?).

I would suggest to ensure they are close to the controller. Try and get it working with a simple configuration first.

If there’s still no response, then I’m not sure of the next step…

Since I’m still seeing my bulbs become unresponsive on the default 2.3 binding installed via PaperUI/Habmin, what would be the best way to switch to the Test 2.2 binding and avoid having 2 bindings running?

I had previously uninstalled 2.3, Stopped OH2 and then added the Test 2.2 to my Addons Folder. Is that the correct approach?

The best way to switch would be to wait for Chris to merge the changes into master :stuck_out_tongue_winking_eye:

Otherwise, try a restart after the uninstall, and make sure the zigbee binding isn’t listed in your addons.cfg. But if you see two bindings again, just uninstall the one you don’t want.

Agreed - I hope to get this all merged today so I can start a major refactoring to split the bundles…

I’ve just noticed a bulb that was not responding, although the others in the room were still working. I don’t have a debug log from when it started, but have one now while trying to turn it ON/OFF. The only thing I see in the log, other than the ON/OFF commands, are some discovery messages…

2018-02-25 05:39:01.467 [DEBUG] [ystems.zigbee.internal.ZigBeeNodeServiceDiscoverer] - 7CE524000011F4D1: Node SVC Discovery already scheduled or running
2018-02-25 05:41:38.285 [DEBUG] [ystems.zigbee.internal.ZigBeeNodeServiceDiscoverer] - 7CE524000011F4D1: Node SVC Discovery running
2018-02-25 05:41:48.287 [DEBUG] [ystems.zigbee.internal.ZigBeeNodeServiceDiscoverer] - 7CE524000011F4D1: Node SVC Discovery ManagementLqiRequest response CommandResult [TIMEOUT]
2018-02-25 05:41:48.288 [DEBUG] [ystems.zigbee.internal.ZigBeeNodeServiceDiscoverer] - 7CE524000011F4D1: Node SVC Discovery request NEIGHBORS failed. Retry 328, wait 668100ms before retry.

… like maybe it hung during discovery. After restarting the binding, the bulb became responsive again. I doubt there’s anything worthwhile in it, but would you like the log?

Feel free to send it over. It’s probably not useful, but I’d just like to have a look at some of the other management frames that might be kicking around to see if there’s anything else that I could use to trigger off…

Hi @chris,
Last year, there was a discussion on Github whether it was appropriate to keep the “color mode” channel of certain lamps. It was decided for consistency’s sake, to leave it out.

Back then, I argued that it would be needed to know what the lamp’s actual state is. Because I now wanted to make a rule that acts upon a certain lamp’s state, I had to take another approach that works without the color mode channel. To avoid ambiguity, I decided to avoid operating lamps in color temperature mode, and convert all such commands into HSB commands. This way, the color channel would always provide an accurate state. I no longer need color mode, since I exclusively use a single mode.

I the following thread, I make the case for leaving the lamps in HSB mode, and converting all CT commands into HSB commands. It has some code how I currently convert it.

Wouldn’t it make sense for the binding to do this in stead? It could still expose a CT channel (for any color lamp), but only send out HSB/RGB commands to the lamps. Then, we would always have an accurate state in the color channel.