I think you also need to enable debug logging for the main binding as well as the ZigBee library. I guess there is an issue during startup and for some reason it’s not configuring the channel.
The following command should enable logging on the binding.
log:set DEBUG org.openhab.binding.zigbee
Or maybe there’s some other filter on the log, but somehow I’d like to see the binding initialisation if possible.
I would not expect the motion sensor to work at the moment, but the socket probably should - I’ve tested both Bitron and SmartThings sockets along with a number of other switches.
here is another log, with the main binding in debug mode, I don’t think i have any filters on the log
The only obvious line I can see in the log is
14:34:24.565 [ERROR] [gbee.dongle.ember.ash.AshFrameHandler] - <-- RX ASH frame: BAD PACKET 11 11 34 7B A1 9C 54 26 C1 01
maybe an unhandled exception is being raised by this packet which cancels out the initialization.
I got it working, the caveat was that I needed to start the device scan before I plugged the socket in. That made it show up.
The Osram socket is produced by Ledvance, marketed as Sylvania in the U.S. and uses the Zigbee Lightlink protocol.
Thanks - I’ll take a look.
I don’t think so - the device is working, and the “ASH” messages are low level device message issues. The problem is more likely to be in the higher level parts of the binding. Anyway, I will take a look at the logs and see what I can see…
I’m running into something similar. I’m on OH snapshot 1078 (Zigbee 2.2.0.201710251639), and have suspicions about this change. I’ve now had two devices, a GE bulb and a Centralite outlet (which has been rock solid until now), which get
2017-11-13 07:15:05.977 [WARN ] [e.core.thing.internal.profiles.ProfileCallbackImpl] - Cannot delegate update 'ON' for item 'Outlet11' to handler for channel 'zigbee:device:9b51c72d:000d6f00040494aa:000D6F00040494AA_1_switch_onoff', because no handler is assigned. Maybe the binding is not installed or not propertly initialized.
when controlling them from the UI. After resetting and rediscovering the bulb, Habmin showed it as online, but same error. Restarting the binding made no change. After restarting OH twice, the bulb is now responding and no error.
Is it possible the Zigbee binding is having issues with this ESH change?
These also had shown up in the Karaf console, but may not be related:
Exception in thread "pool-36-thread-1162" java.lang.IllegalStateException: Could not update state, because callback is missing
at org.eclipse.smarthome.core.thing.binding.BaseThingHandler.updateState(BaseThingHandler.java:289)
at org.openhab.binding.zigbee.handler.ZigBeeThingHandler.setChannelState(ZigBeeThingHandler.java:262)
at org.openhab.binding.zigbee.converter.ZigBeeChannelConverter.updateChannelState(ZigBeeChannelConverter.java:168)
at org.openhab.binding.zigbee.converter.ZigBeeConverterSwitchLevel.attributeUpdated(ZigBeeConverterSwitchLevel.java:112)
at com.zsmartsystems.zigbee.zcl.ZclCluster$1.run(ZclCluster.java:323)
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-36-thread-1185" java.lang.IllegalStateException: Could not update state, because callback is missing
at org.eclipse.smarthome.core.thing.binding.BaseThingHandler.updateState(BaseThingHandler.java:289)
at org.openhab.binding.zigbee.handler.ZigBeeThingHandler.setChannelState(ZigBeeThingHandler.java:262)
at org.openhab.binding.zigbee.converter.ZigBeeChannelConverter.updateChannelState(ZigBeeChannelConverter.java:168)
at org.openhab.binding.zigbee.converter.ZigBeeConverterSwitchOnoff.attributeUpdated(ZigBeeConverterSwitchOnoff.java:135)
at com.zsmartsystems.zigbee.zcl.ZclCluster$1.run(ZclCluster.java:323)
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)Probably not - at least, probably not directly. I think this change only does anything if you do a configuration update which I don’t think you’re doing here. In general at the moment there’s not a lot of configuration for ZigBee devices.
The handler missing error I think means that there was an error during the startup of the device. I think there’s a small window where the thing gets created, before the thing handler is added, and if something bad happens in that time, you end up with no handler.
So, I think you need to take a look at the log during the initialisation and see if there’s something happening there…
OK, I’ll take a look. This only started after updating to 1078, so thought something new may have been introduced.
Has the ZigBee binding changed? Kai merged my PR to try and fix the build problem late last week so it’s possible that the binding has updated?
No. The current jar on Cloudbees has the same number of bytes as the one from 5 Aug.
Ok, thanks - that’s a bit sad. I’ll take another look at it…
I messed that up a little. The last change that I saw on Cloudbees was downloaded on 17 Sept. Still sad though… or extremely improbable that the file sizes could be exactly the same.
In looking through the log, the only oddity that I could spot was a few EMBER_SOURCE_ROUTE_FAILURE, but communications seem to continue OK after they show up and everything else looked right to me (I have filtered a lot out of this).
2017-11-13 07:06:47.899 [DEBUG] [rtsystems.zigbee.internal.ZigBeeNetworkMeshMonitor] - 55930: Starting mesh update
2017-11-13 07:06:47.899 [DEBUG] [rtsystems.zigbee.internal.ZigBeeNetworkMeshMonitor] - 55930: ZigBee node not found during mesh update
2017-11-13 07:06:47.899 [DEBUG] [artsystems.zigbee.internal.ZigBeeNetworkDiscoverer] - 55930: Scheduling node discovery
2017-11-13 07:06:47.899 [DEBUG] [artsystems.zigbee.internal.ZigBeeNetworkDiscoverer] - 55930: Starting node discovery
2017-11-13 07:06:48.033 [DEBUG] [artsystems.zigbee.internal.ZigBeeNetworkDiscoverer] - 55930: Discovery request IEEE_ADDRESS successfull. Advanced to NODE_DESCRIPTOR.
2017-11-13 07:06:48.265 [DEBUG] [artsystems.zigbee.internal.ZigBeeNetworkDiscoverer] - 55930: Discovery request NODE_DESCRIPTOR successfull. Advanced to POWER_DESCRIPTOR.
2017-11-13 07:06:48.265 [DEBUG] [artsystems.zigbee.dongle.ember.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=4, ackNum=3, reTx=false, data=1C 90 80 A9 7A DA]
2017-11-13 07:06:48.267 [DEBUG] [artsystems.zigbee.dongle.ember.ash.AshFrameHandler] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_SOURCE_ROUTE_FAILURE, target=55930]
2017-11-13 07:06:48.267 [DEBUG] [zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspIncomingRouteErrorHandler [status=EMBER_SOURCE_ROUTE_FAILURE, target=55930]
2017-11-13 07:06:48.267 [DEBUG] [zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspIncomingRouteErrorHandler [status=EMBER_SOURCE_ROUTE_FAILURE, target=55930]
2017-11-13 07:06:48.431 [DEBUG] [artsystems.zigbee.internal.ZigBeeNetworkDiscoverer] - 55930: Discovery request POWER_DESCRIPTOR successfull. Advanced to ACTIVE_ENDPOINTS.
2017-11-13 07:06:48.587 [DEBUG] [artsystems.zigbee.internal.ZigBeeNetworkDiscoverer] - 55930/1: Scheduling device discovery
2017-11-13 07:06:48.587 [DEBUG] [artsystems.zigbee.internal.ZigBeeNetworkDiscoverer] - 55930: Discovery request ACTIVE_ENDPOINTS successfull. Advanced to IEEE_ADDRESS.
2017-11-13 07:06:48.587 [DEBUG] [artsystems.zigbee.internal.ZigBeeNetworkDiscoverer] - 55930: Ending node discovery
2017-11-13 07:06:48.587 [DEBUG] [artsystems.zigbee.internal.ZigBeeNetworkDiscoverer] - 55930/1: Starting device discovery
2017-11-13 07:06:50.376 [DEBUG] [ab.binding.zigbee.handler.ZigBeeCoordinatorHandler] - ZigBee Node discovered: IEEE=000D6F00040494AA, NWK=DA7A, Type=ROUTER
2017-11-13 07:06:50.376 [DEBUG] [.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 000D6F00040494AA: Node updated - IEEE=000D6F00040494AA, NWK=DA7A, Type=ROUTER
2017-11-13 07:06:50.386 [INFO ] [ab.binding.zigbee.discovery.ZigBeeDiscoveryService] - 000D6F00040494AA: Starting ZigBee device discovery
2017-11-13 07:06:50.387 [DEBUG] [.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 000D6F00040494AA: Initialising node
2017-11-13 07:06:50.387 [INFO ] [ab.binding.zigbee.discovery.ZigBeeDiscoveryService] - 000D6F00040494AA: Creating ZigBee device zigbee:device with bridge zigbee:coordinator_ember:9b51c72d
2017-11-13 07:06:50.388 [DEBUG] [.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 000D6F00040494AA: Created 1 channels
2017-11-13 07:06:50.389 [DEBUG] [ding.zigbee.discovery.ZigBeeNodePropertyDiscoverer] - 000D6F00040494AA: ZigBee node property discovery start
2017-11-13 07:06:50.389 [DEBUG] [ding.zigbee.discovery.ZigBeeNodePropertyDiscoverer] - 000D6F00040494AA: ZigBee node property discovery using 55930/1
2017-11-13 07:06:50.392 [DEBUG] [inding.zigbee.converter.ZigBeeConverterSwitchOnoff] - 000D6F00040494AA: Initialising device on/off cluster
2017-11-13 07:06:50.598 [DEBUG] [inding.zigbee.converter.ZigBeeConverterSwitchOnoff] - 000D6F00040494AA: ZigBee attribute reports ZclAttribute [cluster=ON_OFF, id=0, name=OnOff, dataType=BOOLEAN, lastValue=false]
2017-11-13 07:06:50.934 [DEBUG] [.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 000D6F00040494AA: Initializing ZigBee thing handler
2017-11-13 07:06:50.944 [DEBUG] [ding.zigbee.discovery.ZigBeeNodePropertyDiscoverer] - 000D6F00040494AA: ZigBee node property discovery start
2017-11-13 07:06:50.945 [DEBUG] [ding.zigbee.discovery.ZigBeeNodePropertyDiscoverer] - 000D6F00040494AA: ZigBee node property discovery using 55930/1
2017-11-13 07:06:52.436 [DEBUG] [ding.zigbee.discovery.ZigBeeNodePropertyDiscoverer] - 000D6F00040494AA: Application version request timeout
2017-11-13 07:06:55.924 [DEBUG] [ding.zigbee.discovery.ZigBeeNodePropertyDiscoverer] - 000D6F00040494AA: ZigBee node property discovery complete: {zigbee_manufacturer=CentraLite, zigbee_logicaltype=ROUTER, zigbee_powerlevel=FULL, zigbee_hwversion=3, zigbee_model=4257050-RZHAC, zigbee_networkaddress=55930, zigbee_powermode=RECEIVER_ON_IDLE, zigbee_powersources=[MAINS], zigbee_powersource=MAINS, zigbee_stkversion=2, zigbee_datecode=ÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿÿ, zigbee_zclversion=1}
But after another reboot, the outlet is responding without errors, so lets see if it occurs again after the big update. But if you’d like, I could open a ticket and attach the log.
This is great, big thanks to everybody contributing to development of this binding!
I’ve ordered an ETRX357USB-LRS+8M from Farnell which should arrive today. Does it need the same baud rate setting as the HUSBZB-1 (it has been mentioned that it is using the same chip)?
I’ve also order a couple of Busch-Jaeger switches and relais, we’ll see how these work. They’re using zigbee lightlink, so I guess they should. Anybody tried components from Busch-Jaeger yet?
No - it is 19200 - this will be the default in the binding.
The binding doesn’t support ZLL as it requires special keys. However, most ZLL components will also work in HA mode so they should work ok. Please report back though 
This error was still popping up after restarts…
2017-11-13 07:15:05.977 [WARN ] [e.core.thing.internal.profiles.ProfileCallbackImpl] - Cannot delegate update 'ON' for item 'Outlet11' to handler for channel 'zigbee:device:9b51c72d:000d6f00040494aa:000D6F00040494AA_1_switch_onoff', because no handler is assigned. Maybe the binding is not installed or not propertly initialized.
so I rolled back to OH snapshot 1072 and it hasn’t come back. There must be something in the latest builds that are causing it.
This is expected. The ZigBee binding (currently at least) recreates the thing after restart. This can take a little while as it needs to communicate with the device, and if you send a command shortly after restart then you will get this error.
I’ll likely change this logic at some point, but at the moment there are more important things to look at.
Understood, but I was referring back to the issue I was reporting here. With build 1078, the error never went away for some devices, even while Habmin reported the device as online. I could not find a way to control the devices this was happening with, unless I reset and rediscovered them. Build 1072 does not display this error, even if trying to control the device right after a restart or while it is shown as offline. And when Habmin shows a device as online, it can always be controlled.
@Solomon_M had reported similar behavior here, so it may have been due to being on a build after 1072?
This is something that I need to look at. There must be a failure (exception) during initialisation between the time the thing is created (or during thing creation), and the time the handler gets created. Unfortunately, ESH has a tendency to eat exceptions in some areas and I think this is another one of them.
Thanks for the clarification. I’ll let you know how it goes