Discovery Failed for Zigbee Binding

ptmuldoon · March 24, 2018, 10:06pm

So…

I run OH2 as a VM within ESXi.

Today I set up fresh Ubuntu VM install, installed OH2 and then moved my HUSBZB-1 stick over to the new VM. Added the user openhab to dialout and tty, and then installed the zigbee binding via PaperUI.

Result… Discovery seems to work. At least I did not receive the failed message. I still need to reset a lightbulb and try and pair it, but again no error.

So that leads to believe something in my existing OH2 Ubuntu install? But unsure yet where to begin looking to troubleshoot that.

So like Chris said, their is probably nothing wrong with the binding and just need to identify what else could be causing the error.

ptmuldoon · March 25, 2018, 12:43am

Ugh… Now I get the failed message on my test VM machine

And all I did was try and pair an Osram Lightify bulb. All I can possible think is that I tried to pair via PaperUI vs Habmin, and I was also doing it via my phone, vs an actual PC web browser. Not that either should make a difference.

The light flashed 4 times like it paired but never showed in OH2, and now gives the failed message again during discovery.

So now I’m back to guessing why I get the error. 2 separate VM’s and installs, and got the error on both.

5iver · March 25, 2018, 3:45am

I just tested with Zulu (was previously using straight openJDK) and it made no difference. I had two bulbs that I had unpaired and that’s when the issue started. I also get the error on a perfectly fresh manual install with the binding in addons. Same error starting discovery though the REST API too. Do you also see the exceptions in the Karaf console? They come up for me soon after startup, without the long nasty exceptions in the log. And there are two of them, and two exceptions in the log, and I had removed two bulbs.

ptmuldoon · March 25, 2018, 11:17am

How would I go about checking and seeing the exceptions in the Karaf console?

Also, are you using the same dual Zwave/Zigbee HUSBZB-1 stick? Perhaps an issue with the stick itself? I can try and reset the stick before trying again and see what happens.

chris · March 25, 2018, 11:53am

It’s not an issue with the stick. The issue is with the change of class in ESH so it won’t be dependent on hardware.

I did a fresh install this morning and also found no issues - it just seems to be you @5iver .

5iver · March 25, 2018, 6:53pm

https://docs.openhab.org/administration/console.html
or

Yep

Which version of Java and which OS?

chris · March 25, 2018, 6:58pm

Java is 1.8 (not sure exactly what version) and it’s MacOS. I’d be a bit surprised if it’s related to Java or the OS though - I suspect somewhere you’ve got a file that won’t die. Clearly somewhere there’s an incompatibility between the binding that you’re running and the OH runtime.

5iver · March 25, 2018, 8:21pm

I could see that for my production install, but I don’t see how this could be the case for a clean install. Is it possible the stick is in an odd state after deleting Things? This first started for me after deleting two Things and rediscovering.

The exceptions in Karaf is interesting to me…

Exception in thread "pool-6375-thread-201" java.lang.IncompatibleClassChangeError: Expected static field org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService.scheduler
        at org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService.nodeDiscovered(ZigBeeDiscoveryService.java:202)
        at org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService.nodeAdded(ZigBeeDiscoveryService.java:208)
        at com.zsmartsystems.zigbee.ZigBeeNetworkManager$6.run(ZigBeeNetworkManager.java:1171)
        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)
Exception in thread "pool-6375-thread-202" java.lang.IncompatibleClassChangeError: Expected static field org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService.scheduler
        at org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService.nodeDiscovered(ZigBeeDiscoveryService.java:202)
        at org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService.nodeAdded(ZigBeeDiscoveryService.java:208)
        at com.zsmartsystems.zigbee.ZigBeeNetworkManager$6.run(ZigBeeNetworkManager.java:1171)
        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)

The two of them occur right after starting the binding, the network starts up, and devices are being added in. Kicking off discovery does not cause this exception. Why would there only be two, unless it is somehow related to the two devices I deleted?

2018-03-25 15:42:59.964 [DEBUG] [s.zigbee.dongle.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=1, ackNum=2, reTx=false, data=11 00 28]
2018-03-25 15:42:59.964 [DEBUG] [s.zigbee.dongle.ember.internal.ash.AshFrameHandler] - RX EZSP: EzspGetNetworkParametersResponse [status=EMBER_SUCCESS, nodeType=EMBER_COORDINATOR, parameters=EmberNetworkParameters [extendedPanId=3DAB5D4A2336BFDE, panId=3330, radioTxPower=0, radioChannel=25, joinMethod=EMBER_USE_MAC_ASSOCIATION, nwkManagerId=0, nwkUpdateId=0, channels=07FFF800]]
2018-03-25 15:42:59.965 [DEBUG] [zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] - EzspGetNetworkParametersResponse [status=EMBER_SUCCESS, nodeType=EMBER_COORDINATOR, parameters=EmberNetworkParameters [extendedPanId=3DAB5D4A2336BFDE, panId=3330, radioTxPower=0, radioChannel=25, joinMethod=EMBER_USE_MAC_ASSOCIATION, nwkManagerId=0, nwkUpdateId=0, channels=07FFF800]]
2018-03-25 15:42:59.965 [DEBUG] [s.zigbee.dongle.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue: 1
2018-03-25 15:42:59.966 [DEBUG] [s.zigbee.dongle.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=3, notRdy=false]
2018-03-25 15:42:59.966 [DEBUG] [s.zigbee.dongle.ember.internal.ash.AshFrameHandler] - TX EZSP: EzspGetCurrentSecurityStateRequest []
2018-03-25 15:42:59.967 [DEBUG] [s.zigbee.dongle.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=2, ackNum=3, reTx=false, data=12 00 69]
2018-03-25 15:43:00.085 [DEBUG] [s.zigbee.dongle.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=3, ackNum=3, reTx=false, data=12 80 69 00 74 00 C8 6F FF 0A 00 6F 0D 00]
2018-03-25 15:43:00.086 [DEBUG] [s.zigbee.dongle.ember.internal.ash.AshFrameHandler] - ASH: Frame acked and removed AshFrameData [frmNum=2, ackNum=3, reTx=false, data=12 00 69]
2018-03-25 15:43:00.086 [DEBUG] [s.zigbee.dongle.ember.internal.ash.AshFrameHandler] - RX EZSP: EzspGetCurrentSecurityStateResponse [status=EMBER_SUCCESS, state=EmberCurrentSecurityState [bitmask=[EMBER_HAVE_TRUST_CENTER_LINK_KEY, EMBER_TRUST_CENTER_USES_HASHED_LINK_KEY, EMBER_GLOBAL_LINK_KEY], trustCenterLongAddress=000D6F000AFF6FC8]]
2018-03-25 15:43:00.087 [DEBUG] [s.zigbee.dongle.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=4, notRdy=false]
2018-03-25 15:43:00.087 [DEBUG] [zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] - EzspGetCurrentSecurityStateResponse [status=EMBER_SUCCESS, state=EmberCurrentSecurityState [bitmask=[EMBER_HAVE_TRUST_CENTER_LINK_KEY, EMBER_TRUST_CENTER_USES_HASHED_LINK_KEY, EMBER_GLOBAL_LINK_KEY], trustCenterLongAddress=000D6F000AFF6FC8]]
2018-03-25 15:43:00.087 [DEBUG] [zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] - EZSP dongle initialize done: Initialised false
2018-03-25 15:43:00.087 [DEBUG] [g.zigbee.internal.ZigBeeNetworkStateSerializerImpl] - Loading ZigBee network state: Start.
2018-03-25 15:43:00.273 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNetworkManager     ] - 000D6F000AFF6FC8: Node 0 added to the network
2018-03-25 15:43:00.276 [DEBUG] [ab.binding.zigbee.discovery.ZigBeeDiscoveryService] - 000D6F000AFF6FC8: Discovery notification
2018-03-25 15:43:00.276 [DEBUG] [g.zigbee.internal.ZigBeeNetworkStateSerializerImpl] - Saving ZigBee network state: Start.
2018-03-25 15:43:00.279 [DEBUG] [g.zigbee.internal.ZigBeeNetworkStateSerializerImpl] - Saving ZigBee network state: Done.
2018-03-25 15:43:00.280 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNetworkManager     ] - 7CE5240000073901: Node 24511 added to the network
2018-03-25 15:43:00.280 [DEBUG] [ab.binding.zigbee.discovery.ZigBeeDiscoveryService] - 7CE5240000073901: Discovery notification
2018-03-25 15:43:00.281 [DEBUG] [g.zigbee.internal.ZigBeeNetworkStateSerializerImpl] - Saving ZigBee network state: Start.
2018-03-25 15:43:00.286 [DEBUG] [g.zigbee.internal.ZigBeeNetworkStateSerializerImpl] - Saving ZigBee network state: Done.
2018-03-25 15:43:00.287 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNetworkManager     ] - 7CE52400000636F0: Node 57849 added to the network
2018-03-25 15:43:00.287 [DEBUG] [ab.binding.zigbee.discovery.ZigBeeDiscoveryService] - 7CE52400000636F0: Discovery notification
2018-03-25 15:43:00.288 [DEBUG] [g.zigbee.internal.ZigBeeNetworkStateSerializerImpl] - Saving ZigBee network state: Start.
2018-03-25 15:43:00.296 [DEBUG] [g.zigbee.internal.ZigBeeNetworkStateSerializerImpl] - Saving ZigBee network state: Done.
2018-03-25 15:43:00.296 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNetworkManager     ] - 7CE524000013F1F0: Node 16868 added to the network
2018-03-25 15:43:00.296 [DEBUG] [ab.binding.zigbee.discovery.ZigBeeDiscoveryService] - 7CE524000013F1F0: Discovery notification
2018-03-25 15:43:00.297 [DEBUG] [g.zigbee.internal.ZigBeeNetworkStateSerializerImpl] - Saving ZigBee network state: Start.
2018-03-25 15:43:00.308 [DEBUG] [g.zigbee.internal.ZigBeeNetworkStateSerializerImpl] - Saving ZigBee network state: Done.
2018-03-25 15:43:00.308 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNetworkManager     ] - 7CE52400001261EF: Node 53682 added to the network
2018-03-25 15:43:00.309 [DEBUG] [ab.binding.zigbee.discovery.ZigBeeDiscoveryService] - 7CE52400001261EF: Discovery notification
2018-03-25 15:43:00.310 [DEBUG] [g.zigbee.internal.ZigBeeNetworkStateSerializerImpl] - Saving ZigBee network state: Start.
2018-03-25 15:43:00.323 [DEBUG] [g.zigbee.internal.ZigBeeNetworkStateSerializerImpl] - Saving ZigBee network state: Done.
2018-03-25 15:43:00.324 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNetworkManager     ] - 7CE524000013F335: Node 41899 added to the network
2018-03-25 15:43:00.324 [DEBUG] [ab.binding.zigbee.discovery.ZigBeeDiscoveryService] - 7CE524000013F335: Discovery notification
2018-03-25 15:43:00.325 [DEBUG] [g.zigbee.internal.ZigBeeNetworkStateSerializerImpl] - Saving ZigBee network state: Start.
2018-03-25 15:43:00.341 [DEBUG] [g.zigbee.internal.ZigBeeNetworkStateSerializerImpl] - Saving ZigBee network state: Done.

chris · March 25, 2018, 8:29pm

I don’t think it’s anything to do with the stick. It’s a class error…

Well, this linked to the change in ESH -:

        scheduler.schedule(pollingRunnable, 10, TimeUnit.MILLISECONDS);

It was the definition of scheduler that changed… The error is it was expecting a static field - this field used to be static, and was changed to be non-static. It looks like you have an old ZigBee binding (and I know you’ll say it’s not the case, but that’s where the logging is pointing in my opinion).

5iver · March 25, 2018, 9:20pm

openhab> list |grep -i zig
236 │ Active   │  80 │ 2.3.0.201803251536     │ ZigBee Binding
openhab> feature:list |grep -i zig
openhab-binding-zigbee                      │ 2.3.0.SNAPSHOT   │          │ Uninstalled │ openhab-addons-2.3.0-SNAPSHOT        │ ZigBee Binding

Downloaded today. After updating to the latest snapshot (1241), removing the jar from addons, and installing Zigbee through PaperUI, I get the same exceptions in Karaf and when running discovery.

openhab> list |grep -i zig
235 │ Active   │  80 │ 2.3.0.201803251536     │ ZigBee Binding
openhab> feature:list |grep -i zig
openhab-binding-zigbee                      │ 2.3.0.SNAPSHOT   │ x        │ Started     │ openhab-addons-2.3.0-SNAPSHOT        │ ZigBee Binding

5iver · March 29, 2018, 7:15pm

Short version… could you try this with a fresh install and configure the network for a dongle that already has devices paired?

Detailed version…

Fresh install of Fedora 27,
a manual install of OH 2.3.0 snapshot 1243 downloaded from here,
installed the Zigbee binding through PaperUI,
add a Ember EM35x coorindinator Thing in Habmin (which looks to have a bug because nothing looks to change after hitting Save, but going back to Things shows the new one),
configure it with the same settings (port, baud, channel, panid, epanid, network key) previously used on the controller

When I do this, the logs look good and nodes are added to the nietwork, but no Things are added. Discovery throws the same error and there are a lot of the exceptions in the Karaf console (probably one for each device). Is it possible this issue has something to do with trying to use the previous network configuration? I don’t have another dongle I could reset to try from a clean state, but I may end up wiping my network to try it from scratch.

chris · March 29, 2018, 7:20pm

I really can’t see how this can be related to the dongle. The dongle has nothing to do with the Java code

Also, note that ZigBee is totally different to ZWave - wiping a dongle doesn’t really do anything since the dongle doesn’t store the list of devices (or anything) like ZWave. Each device stands on its own once it is in the network - ie once it’s been sent the keys to the network it has access…

If from this you expect that devices can join a coordinator just by setting all this stuff the same as previously, don’t expect it to work. There is something else that you can’t currently set that will scupper such plans (and that’s the security counter).

5iver · March 29, 2018, 10:55pm

I’m just trying to come up with a way for you to be able to reproduce the error. I’m not sure if you did a manual install or used apt-get, but from what I’ve seen, this shouldn’t matter. But in your testing of this…

… I was curious if you tried (or could try) doing a discovery on a network that already had devices. That’s currently the only possible difference I can identify, but I don’t have another dongle to setup a new network and see if the error still occurs. I’ve tried several OSs, Java versions, OH installation methods, OH repositories, etc., with the same results. With all the testing I’ve done, I do not see how this issue could possibly be isolated to my systems (… and @ptmuldoon’s). The only constant really being that my dongle was configured each time to use the network that my other devices are on.

It looks to me like the Zigbee binding in the distribution has somehow not yet been recompiled against the updated ESH bundles (!?), or there is some other issue here.

I don’t quite understand what you mean by this. If I use my existing dongle in a fresh OH install, can’t I just use the previous configuration, or do I need to reset all devices and start over? Or is this only the case with a new/replacement dongle?

chris · March 29, 2018, 11:03pm

Manual - I’m on a Mac.

Yes - I do this all the time, but as I said earlier, the coordinator doesn’t actually know if there are devices in the network or not.

As the error is a Java class type error - it’s not related to this though.

To me it looks the other way around - the error says it’s expecting a static field in the ZigBeeDiscovryService, which presumably means it’s not static. The system was changed from static, to not static. So the way I read this, ESH is expecting a static field as it’s still the old complication, and the ZigBee binding is not providing a static field (if that makes sense ). I’m not 100% sure of this though!

Yes - you can. No problem with this…

Correct - what you can’t do is take another coordinator, type in all the same parameters, and expect that to work - it won’t (yet). This is on my hitlist though so it will be added soon.

5iver · March 30, 2018, 1:47am

That did make sense . And as expected, using an older version of the binding causes the same errors. Hmmm…

But I just found a way to get rid of the error! I had noticed once that when I reset one of the two bulbs that I had deleted the Things for, it flashed again like it had been paired. In looking in the logs, everything looks normal for these two bulbs, just no handlers. This seemed odd, since they were reset and I hadn’t run discovery but they must have been paired. So, I reset them again, but turned them off right after. I no longer got the exception in Karaf or the log! I restarted the binding, I ran discovery, no exception. As soon as I turn the lights on… exception! Turning them back off does not stop the exception, until I reset the bulbs and then turn them off. I will try pairing another device tomorrow to see if the exception comes back, and put some logs together.

5iver · March 30, 2018, 7:38pm

Are you still seeing this issue? It sounded like you were getting it on at least a couple systems. I’m convinced it’s not just me, and I’m baffled why others aren’t reporting it.

ptmuldoon · March 30, 2018, 9:26pm

@5iver. Scott. Yes I am still getting the error and can try and again this weekend by resetting all bulbs again.

I think/wonder if a hard reset of a bulb is causing an issue and if i pair an unpair from a hue/lightify app first may help.

ptmuldoon · March 31, 2018, 2:04am

Ok,

So not much of an update, but I made sure all of my existing Zigbee bulbs are currently 1) paired with another controller, ie… either Hue Hub or Lightify Hub, and 2) also physically powered off. And then after that, running discovery on the my Zigbee stick still gives the error. This is on my main OH2 install.

I can move the stick tomorrow to a new OH2 install and see if that helps. But like Scott, the error continues for me.

chris · March 31, 2018, 8:05am

Sorry guys, but I don’t think there’s anything I can do at the moment. I can’t reproduce this, and there was absolutely no change to the binding (last change was over a month ago) so I really can’t see how the binding should be at fault given the error started just over a week ago when ESH changed.

The error here is related to Java classes - not the stick management, so all you are doing by removing and adding devices is exercising the discovery which is where the change was made in ESH, but it’s not actually related to the stick.

ptmuldoon · March 31, 2018, 12:38pm

So I just tried again this morning on my other Clean/Test VM OH2 install and repeated the error

After setting up OH2 the Ember Controller, my first scan work correctly. I then unpaired a bulb from my Lightify Hub and attempted to pair with OH2. The light flashes like it is paired with the controller, but does not appear in either PaperUI or Habmin as being found.

And then when attempting a second device scan, I get the Failed Error again.

I will try and reset OH to an my earlier VM snap shot and maybe try with a different bulb. Just guess, but I’m in the USA and I now these lightify bulbs use the Zigbee HA standard, and not ZLL. Probably nothing to do with it, but it’s trial and error.

Side note. On my clean, fresh OH2 install. I do need seem to install the serial transport binding in order to get the Zigbee stick working. Should the Zigbee binding install that automatically?

feature:install openhab-transport-serial

I may or may not have lots of time today as I wait for my car to be fixed