Exception creating channels
Closed this issue · 7 comments
Possibly caused by #427. This just started in OH S1579 and S1580. I've been using the 1.1.11 snapshot libraries for a while now, and update them frequently, but haven't seen any updates recently. My ZHA power outlet is fine, but my ZLL GE Link bulbs are all unresponsive. Here is a log from deleting one through Paper UI and rediscovering.
2019-04-30 00:33:40.611 [DEBUG] [org.openhab.binding.zigbee] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.ConfigDescriptionProvider}={service.id=1105, service.bundleid=305, service.scope=singleton} - org.openhab.binding.zigbee
2019-04-30 00:33:40.617 [DEBUG] [org.openhab.binding.zigbee] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.type.DynamicStateDescriptionProvider}={service.id=1106, service.bundleid=305, service.scope=singleton} - org.openhab.binding.zigbee
2019-04-30 00:33:40.618 [DEBUG] [org.openhab.binding.zigbee] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.firmware.FirmwareUpdateHandler}={service.id=1107, service.bundleid=305, service.scope=singleton} - org.openhab.binding.zigbee
2019-04-30 00:33:40.636 [DEBUG] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 7C25240000163762: Initializing ZigBee thing handler zigbee:device:9b51c72d:7c25240000163762
2019-04-30 00:33:40.641 [DEBUG] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 7C25240000163762: Coordinator status changed to ONLINE.
2019-04-30 00:33:40.641 [DEBUG] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 7C25240000163762: Coordinator is ONLINE. Starting device initialisation.
2019-04-30 00:33:40.652 [DEBUG] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 7C25240000163762: Start initialising ZigBee Thing handler
2019-04-30 00:33:40.654 [DEBUG] [org.openhab.binding.zigbee.discovery.ZigBeeNodePropertyDiscoverer] - 7C25240000163762: ZigBee node property discovery start
2019-04-30 00:33:40.655 [DEBUG] [org.openhab.binding.zigbee.discovery.ZigBeeNodePropertyDiscoverer] - 7C25240000163762: ZigBee node property discovery using 63400/1
2019-04-30 00:33:40.655 [DEBUG] [org.openhab.binding.zigbee.discovery.ZigBeeNodePropertyDiscoverer] - 7C25240000163762: ZigBee node property discovery complete: {zigbee_logicaltype=ROUTER, zigbee_powerlevel=FULL, modelId=ZLL Light, zigbee_networkaddress=63400, zigbee_powersource=MAINS, zigbee_stkversion=2, zigbee_datecode=20140812, zigbee_zclversion=1, vendor=GE_Appliances, zigbee_powermode=RECEIVER_ON_IDLE, zigbee_powersources=[MAINS], hardwareVersion=1, firmwareVersion=0x01030400, zigbee_applicationVersion=4}
2019-04-30 00:33:40.655 [DEBUG] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 7C25240000163762: Checking endpoint 1 channels
2019-04-30 00:33:40.657 [DEBUG] [org.openhab.binding.zigbee.internal.converter.ZigBeeChannelConverterFactoryImpl] - 7C25240000163762: Removing channel zigbee:switch_onoff in favor of zigbee:switch_level
2019-04-30 00:33:40.657 [DEBUG] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 7C25240000163762: Dynamically created 1 channels
2019-04-30 00:33:40.667 [DEBUG] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 7C25240000163762: Updating thing definition as channels have changed from [] to [zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer]
2019-04-30 00:33:40.670 [DEBUG] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 7C25240000163762: Initializing device
2019-04-30 00:33:40.670 [DEBUG] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 7C25240000163762: Initializing channel zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer with org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchLevel@61ae3ad5
2019-04-30 00:33:40.718 [DEBUG] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 7C25240000163762: Channel zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer linked - polling started.
2019-04-30 00:33:40.806 [DEBUG] [org.openhab.binding.zigbee.internal.ZigBeeNetworkStateSerializerImpl] - Saving ZigBee network state
2019-04-30 00:33:40.808 [DEBUG] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 7C25240000163762: Node updated - ZigBeeNode [state=ONLINE, IEEE=7C25240000163762, NWK=F7A8, Type=ROUTER]
2019-04-30 00:33:40.810 [DEBUG] [org.openhab.binding.zigbee.internal.ZigBeeNetworkStateSerializerImpl] - Saving ZigBee network state: Start.
2019-04-30 00:33:40.831 [DEBUG] [org.openhab.binding.zigbee.internal.ZigBeeNetworkStateSerializerImpl] - Saving ZigBee network state: Done.
2019-04-30 00:33:41.482 [DEBUG] [org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchLevel] - 7C25240000163762: ZigBee attribute reports ZclAttribute [cluster=LEVEL_CONTROL, id=0, name=CurrentLevel, dataType=UNSIGNED_8_BIT_INTEGER, lastValue=254, lastReportTime=Tue Apr 30 00:33:41 EDT 2019]
2019-04-30 00:33:41.483 [DEBUG] [org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchLevel] - 7C25240000163762: ZigBee attribute reports ZclAttribute [cluster=LEVEL_CONTROL, id=0, name=CurrentLevel, dataType=UNSIGNED_8_BIT_INTEGER, lastValue=254, lastReportTime=Tue Apr 30 00:33:41 EDT 2019]
2019-04-30 00:33:41.483 [DEBUG] [org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchLevel] - 7C25240000163762: ZigBee attribute reports ZclAttribute [cluster=LEVEL_CONTROL, id=0, name=CurrentLevel, dataType=UNSIGNED_8_BIT_INTEGER, lastValue=254, lastReportTime=Tue Apr 30 00:33:41 EDT 2019]
2019-04-30 00:33:41.484 [DEBUG] [org.openhab.binding.zigbee.converter.ZigBeeBaseChannelConverter] - 7C25240000163762: Channel zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer updated to 100
2019-04-30 00:33:41.484 [DEBUG] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler] - null: Updating ZigBee channel state zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer to 100
2019-04-30 00:33:41.483 [DEBUG] [org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchLevel] - 7C25240000163762: ZigBee attribute reports ZclAttribute [cluster=LEVEL_CONTROL, id=0, name=CurrentLevel, dataType=UNSIGNED_8_BIT_INTEGER, lastValue=254, lastReportTime=Tue Apr 30 00:33:41 EDT 2019]
2019-04-30 00:33:41.485 [DEBUG] [org.openhab.binding.zigbee.converter.ZigBeeBaseChannelConverter] - 7C25240000163762: Channel zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer updated to 100
2019-04-30 00:33:41.485 [DEBUG] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler] - null: Updating ZigBee channel state zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer to 100
2019-04-30 00:33:41.483 [DEBUG] [org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchLevel] - 7C25240000163762: ZigBee attribute reports ZclAttribute [cluster=LEVEL_CONTROL, id=0, name=CurrentLevel, dataType=UNSIGNED_8_BIT_INTEGER, lastValue=254, lastReportTime=Tue Apr 30 00:33:41 EDT 2019]
2019-04-30 00:33:41.483 [DEBUG] [org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchLevel] - 7C25240000163762: ZigBee attribute reports ZclAttribute [cluster=LEVEL_CONTROL, id=0, name=CurrentLevel, dataType=UNSIGNED_8_BIT_INTEGER, lastValue=254, lastReportTime=Tue Apr 30 00:33:41 EDT 2019]
2019-04-30 00:33:41.486 [DEBUG] [org.openhab.binding.zigbee.converter.ZigBeeBaseChannelConverter] - 7C25240000163762: Channel zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer updated to 100
2019-04-30 00:33:41.487 [DEBUG] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler] - null: Updating ZigBee channel state zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer to 100
2019-04-30 00:33:41.483 [DEBUG] [org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchLevel] - 7C25240000163762: ZigBee attribute reports ZclAttribute [cluster=LEVEL_CONTROL, id=0, name=CurrentLevel, dataType=UNSIGNED_8_BIT_INTEGER, lastValue=254, lastReportTime=Tue Apr 30 00:33:41 EDT 2019]
2019-04-30 00:33:41.487 [DEBUG] [org.openhab.binding.zigbee.converter.ZigBeeBaseChannelConverter] - 7C25240000163762: Channel zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer updated to 100
2019-04-30 00:33:41.488 [DEBUG] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler] - null: Updating ZigBee channel state zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer to 100
2019-04-30 00:33:41.490 [DEBUG] [org.openhab.binding.zigbee.handler.ZigbeeIsAliveTracker] - Reset timeout for handler with thingUID=zigbee:device:9b51c72d:7c25240000163762
2019-04-30 00:33:41.483 [DEBUG] [org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchLevel] - 7C25240000163762: ZigBee attribute reports ZclAttribute [cluster=LEVEL_CONTROL, id=0, name=CurrentLevel, dataType=UNSIGNED_8_BIT_INTEGER, lastValue=254, lastReportTime=Tue Apr 30 00:33:41 EDT 2019]
2019-04-30 00:33:41.483 [DEBUG] [org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchLevel] - 7C25240000163762: ZigBee attribute reports ZclAttribute [cluster=LEVEL_CONTROL, id=0, name=CurrentLevel, dataType=UNSIGNED_8_BIT_INTEGER, lastValue=254, lastReportTime=Tue Apr 30 00:33:41 EDT 2019]
2019-04-30 00:33:41.493 [DEBUG] [org.openhab.binding.zigbee.converter.ZigBeeBaseChannelConverter] - 7C25240000163762: Channel zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer updated to 100
2019-04-30 00:33:41.494 [DEBUG] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler] - null: Updating ZigBee channel state zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer to 100
2019-04-30 00:33:41.483 [DEBUG] [org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchLevel] - 7C25240000163762: ZigBee attribute reports ZclAttribute [cluster=LEVEL_CONTROL, id=0, name=CurrentLevel, dataType=UNSIGNED_8_BIT_INTEGER, lastValue=254, lastReportTime=Tue Apr 30 00:33:41 EDT 2019]
2019-04-30 00:33:41.483 [DEBUG] [org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchLevel] - 7C25240000163762: ZigBee attribute reports ZclAttribute [cluster=LEVEL_CONTROL, id=0, name=CurrentLevel, dataType=UNSIGNED_8_BIT_INTEGER, lastValue=254, lastReportTime=Tue Apr 30 00:33:41 EDT 2019]
2019-04-30 00:33:41.495 [DEBUG] [org.openhab.binding.zigbee.converter.ZigBeeBaseChannelConverter] - 7C25240000163762: Channel zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer updated to 100
2019-04-30 00:33:41.495 [DEBUG] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler] - null: Updating ZigBee channel state zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer to 100
2019-04-30 00:33:41.482 [DEBUG] [org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchLevel] - 7C25240000163762: ZigBee attribute reports ZclAttribute [cluster=LEVEL_CONTROL, id=0, name=CurrentLevel, dataType=UNSIGNED_8_BIT_INTEGER, lastValue=254, lastReportTime=Tue Apr 30 00:33:41 EDT 2019]
2019-04-30 00:33:41.496 [DEBUG] [org.openhab.binding.zigbee.converter.ZigBeeBaseChannelConverter] - 7C25240000163762: Channel zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer updated to 100
2019-04-30 00:33:41.496 [DEBUG] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler] - null: Updating ZigBee channel state zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer to 100
2019-04-30 00:33:41.494 [DEBUG] [org.openhab.binding.zigbee.converter.ZigBeeBaseChannelConverter] - 7C25240000163762: Channel zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer updated to 100
2019-04-30 00:33:41.491 [DEBUG] [org.openhab.binding.zigbee.handler.ZigbeeIsAliveTracker] - Reset timeout for handler with thingUID=zigbee:device:9b51c72d:7c25240000163762
2019-04-30 00:33:41.497 [DEBUG] [org.openhab.binding.zigbee.handler.ZigbeeIsAliveTracker] - Reset timeout for handler with thingUID=zigbee:device:9b51c72d:7c25240000163762
2019-04-30 00:33:41.488 [DEBUG] [org.openhab.binding.zigbee.handler.ZigbeeIsAliveTracker] - Reset timeout for handler with thingUID=zigbee:device:9b51c72d:7c25240000163762
2019-04-30 00:33:41.487 [DEBUG] [org.openhab.binding.zigbee.converter.ZigBeeBaseChannelConverter] - 7C25240000163762: Channel zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer updated to 100
2019-04-30 00:33:41.499 [DEBUG] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler] - null: Updating ZigBee channel state zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer to 100
2019-04-30 00:33:41.483 [DEBUG] [org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchLevel] - 7C25240000163762: ZigBee attribute reports ZclAttribute [cluster=LEVEL_CONTROL, id=0, name=CurrentLevel, dataType=UNSIGNED_8_BIT_INTEGER, lastValue=254, lastReportTime=Tue Apr 30 00:33:41 EDT 2019]
2019-04-30 00:33:41.499 [DEBUG] [org.openhab.binding.zigbee.handler.ZigbeeIsAliveTracker] - Reset timeout for handler with thingUID=zigbee:device:9b51c72d:7c25240000163762
2019-04-30 00:33:41.500 [DEBUG] [org.openhab.binding.zigbee.converter.ZigBeeBaseChannelConverter] - 7C25240000163762: Channel zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer updated to 100
2019-04-30 00:33:41.500 [DEBUG] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler] - null: Updating ZigBee channel state zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer to 100
2019-04-30 00:33:41.486 [DEBUG] [org.openhab.binding.zigbee.converter.ZigBeeBaseChannelConverter] - 7C25240000163762: Channel zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer updated to 100
2019-04-30 00:33:41.485 [DEBUG] [org.openhab.binding.zigbee.handler.ZigbeeIsAliveTracker] - Reset timeout for handler with thingUID=zigbee:device:9b51c72d:7c25240000163762
2019-04-30 00:33:41.501 [DEBUG] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler] - null: Updating ZigBee channel state zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer to 100
2019-04-30 00:33:41.483 [DEBUG] [org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchLevel] - 7C25240000163762: ZigBee attribute reports ZclAttribute [cluster=LEVEL_CONTROL, id=0, name=CurrentLevel, dataType=UNSIGNED_8_BIT_INTEGER, lastValue=254, lastReportTime=Tue Apr 30 00:33:41 EDT 2019]
2019-04-30 00:33:41.484 [DEBUG] [org.openhab.binding.zigbee.converter.ZigBeeBaseChannelConverter] - 7C25240000163762: Channel zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer updated to 100
2019-04-30 00:33:41.502 [DEBUG] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler] - null: Updating ZigBee channel state zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer to 100
2019-04-30 00:33:41.502 [DEBUG] [org.openhab.binding.zigbee.handler.ZigbeeIsAliveTracker] - Reset timeout for handler with thingUID=zigbee:device:9b51c72d:7c25240000163762
2019-04-30 00:33:41.498 [DEBUG] [org.openhab.binding.zigbee.handler.ZigbeeIsAliveTracker] - Reset timeout for handler with thingUID=zigbee:device:9b51c72d:7c25240000163762
2019-04-30 00:33:41.497 [DEBUG] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler] - null: Updating ZigBee channel state zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer to 100
2019-04-30 00:33:41.496 [DEBUG] [org.openhab.binding.zigbee.converter.ZigBeeBaseChannelConverter] - 7C25240000163762: Channel zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer updated to 100
2019-04-30 00:33:41.503 [DEBUG] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler] - null: Updating ZigBee channel state zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer to 100
2019-04-30 00:33:41.502 [DEBUG] [org.openhab.binding.zigbee.converter.ZigBeeBaseChannelConverter] - 7C25240000163762: Channel zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer updated to 100
2019-04-30 00:33:41.503 [DEBUG] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler] - null: Updating ZigBee channel state zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer to 100
2019-04-30 00:33:41.504 [DEBUG] [org.openhab.binding.zigbee.handler.ZigbeeIsAliveTracker] - Reset timeout for handler with thingUID=zigbee:device:9b51c72d:7c25240000163762
2019-04-30 00:33:41.505 [DEBUG] [org.openhab.binding.zigbee.handler.ZigbeeIsAliveTracker] - Reset timeout for handler with thingUID=zigbee:device:9b51c72d:7c25240000163762
2019-04-30 00:33:41.506 [DEBUG] [org.openhab.binding.zigbee.handler.ZigbeeIsAliveTracker] - Reset timeout for handler with thingUID=zigbee:device:9b51c72d:7c25240000163762
2019-04-30 00:33:41.506 [DEBUG] [org.openhab.binding.zigbee.handler.ZigbeeIsAliveTracker] - Reset timeout for handler with thingUID=zigbee:device:9b51c72d:7c25240000163762
2019-04-30 00:33:41.508 [DEBUG] [org.openhab.binding.zigbee.handler.ZigbeeIsAliveTracker] - Reset timeout for handler with thingUID=zigbee:device:9b51c72d:7c25240000163762
2019-04-30 00:33:41.509 [DEBUG] [org.openhab.binding.zigbee.handler.ZigbeeIsAliveTracker] - Reset timeout for handler with thingUID=zigbee:device:9b51c72d:7c25240000163762
2019-04-30 00:33:42.204 [ERROR] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 7C25240000163762: Exception creating channels
java.lang.NullPointerException: null
at org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchLevel.getPollingPeriod(ZigBeeConverterSwitchLevel.java:154) ~[305:org.openhab.binding.zigbee:2.5.0.201904290354]
at org.openhab.binding.zigbee.handler.ZigBeeThingHandler.doNodeInitialisation(ZigBeeThingHandler.java:396) [305:org.openhab.binding.zigbee:2.5.0.201904290354]
at org.openhab.binding.zigbee.handler.ZigBeeThingHandler.access$0(ZigBeeThingHandler.java:233) [305:org.openhab.binding.zigbee:2.5.0.201904290354]
at org.openhab.binding.zigbee.handler.ZigBeeThingHandler$1.call(ZigBeeThingHandler.java:227) [305:org.openhab.binding.zigbee:2.5.0.201904290354]
at org.openhab.binding.zigbee.handler.ZigBeeThingHandler$1.call(ZigBeeThingHandler.java:1) [305:org.openhab.binding.zigbee:2.5.0.201904290354]
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) [?:?]
2019-04-30 00:33:42.216 [DEBUG] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 7C25240000163762: Start initialising ZigBee Thing handler
2019-04-30 00:33:42.217 [DEBUG] [org.openhab.binding.zigbee.discovery.ZigBeeNodePropertyDiscoverer] - 7C25240000163762: ZigBee node property discovery start
2019-04-30 00:33:42.219 [DEBUG] [org.openhab.binding.zigbee.discovery.ZigBeeNodePropertyDiscoverer] - 7C25240000163762: ZigBee node property discovery using 63400/1
2019-04-30 00:33:42.219 [DEBUG] [org.openhab.binding.zigbee.discovery.ZigBeeNodePropertyDiscoverer] - 7C25240000163762: ZigBee node property discovery complete: {zigbee_logicaltype=ROUTER, zigbee_powerlevel=FULL, modelId=ZLL Light, zigbee_networkaddress=63400, zigbee_powersource=MAINS, zigbee_stkversion=2, zigbee_datecode=20140812, zigbee_zclversion=1, zigbee_routes=[], zigbee_lastupdate=, zigbee_stkcompliance=0, vendor=GE_Appliances, zigbee_powermode=RECEIVER_ON_IDLE, zigbee_powersources=[MAINS], hardwareVersion=1, firmwareVersion=0x01030400, zigbee_neighbors=[], zigbee_applicationVersion=4, zigbee_device_initialised=true, zigbee_devices=[]}
2019-04-30 00:33:42.219 [DEBUG] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 7C25240000163762: Checking endpoint 1 channels
2019-04-30 00:33:42.221 [DEBUG] [org.openhab.binding.zigbee.internal.converter.ZigBeeChannelConverterFactoryImpl] - 7C25240000163762: Removing channel zigbee:switch_onoff in favor of zigbee:switch_level
2019-04-30 00:33:42.221 [DEBUG] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 7C25240000163762: Dynamically created 1 channels
2019-04-30 00:33:42.221 [DEBUG] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 7C25240000163762: Device initialization will be skipped as the device is already initialized
2019-04-30 00:33:42.222 [ERROR] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 7C25240000163762: Exception creating channels
java.lang.NullPointerException: null
at org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchLevel.getPollingPeriod(ZigBeeConverterSwitchLevel.java:154) ~[305:org.openhab.binding.zigbee:2.5.0.201904290354]
at org.openhab.binding.zigbee.handler.ZigBeeThingHandler.doNodeInitialisation(ZigBeeThingHandler.java:396) [305:org.openhab.binding.zigbee:2.5.0.201904290354]
at org.openhab.binding.zigbee.handler.ZigBeeThingHandler.access$0(ZigBeeThingHandler.java:233) [305:org.openhab.binding.zigbee:2.5.0.201904290354]
at org.openhab.binding.zigbee.handler.ZigBeeThingHandler$1.call(ZigBeeThingHandler.java:227) [305:org.openhab.binding.zigbee:2.5.0.201904290354]
at org.openhab.binding.zigbee.handler.ZigBeeThingHandler$1.call(ZigBeeThingHandler.java:1) [305:org.openhab.binding.zigbee:2.5.0.201904290354]
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) [?:?]
2019-04-30 00:33:42.458 [DEBUG] [org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchLevel] - 7C25240000163762: ZigBee attribute reports ZclAttribute [cluster=ON_OFF, id=0, name=OnOff, dataType=BOOLEAN, lastValue=true, lastReportTime=Tue Apr 30 00:33:42 EDT 2019]
2019-04-30 00:33:42.459 [DEBUG] [org.openhab.binding.zigbee.converter.ZigBeeBaseChannelConverter] - 7C25240000163762: Channel zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer updated to 100
2019-04-30 00:33:42.459 [DEBUG] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler] - null: Updating ZigBee channel state zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer to 100
2019-04-30 00:33:42.459 [DEBUG] [org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchLevel] - 7C25240000163762: ZigBee attribute reports ZclAttribute [cluster=ON_OFF, id=0, name=OnOff, dataType=BOOLEAN, lastValue=true, lastReportTime=Tue Apr 30 00:33:42 EDT 2019]
2019-04-30 00:33:42.466 [DEBUG] [org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchLevel] - 7C25240000163762: ZigBee attribute reports ZclAttribute [cluster=ON_OFF, id=0, name=OnOff, dataType=BOOLEAN, lastValue=true, lastReportTime=Tue Apr 30 00:33:42 EDT 2019]
2019-04-30 00:33:42.459 [DEBUG] [org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchLevel] - 7C25240000163762: ZigBee attribute reports ZclAttribute [cluster=ON_OFF, id=0, name=OnOff, dataType=BOOLEAN, lastValue=true, lastReportTime=Tue Apr 30 00:33:42 EDT 2019]
2019-04-30 00:33:42.467 [DEBUG] [org.openhab.binding.zigbee.converter.ZigBeeBaseChannelConverter] - 7C25240000163762: Channel zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer updated to 100
2019-04-30 00:33:42.467 [DEBUG] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler] - null: Updating ZigBee channel state zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer to 100
2019-04-30 00:33:42.467 [DEBUG] [org.openhab.binding.zigbee.converter.ZigBeeBaseChannelConverter] - 7C25240000163762: Channel zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer updated to 100
2019-04-30 00:33:42.463 [DEBUG] [org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchLevel] - 7C25240000163762: ZigBee attribute reports ZclAttribute [cluster=ON_OFF, id=0, name=OnOff, dataType=BOOLEAN, lastValue=true, lastReportTime=Tue Apr 30 00:33:42 EDT 2019]
2019-04-30 00:33:42.468 [DEBUG] [org.openhab.binding.zigbee.converter.ZigBeeBaseChannelConverter] - 7C25240000163762: Channel zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer updated to 100
2019-04-30 00:33:42.468 [DEBUG] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler] - null: Updating ZigBee channel state zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer to 100
2019-04-30 00:33:42.462 [DEBUG] [org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchLevel] - 7C25240000163762: ZigBee attribute reports ZclAttribute [cluster=ON_OFF, id=0, name=OnOff, dataType=BOOLEAN, lastValue=true, lastReportTime=Tue Apr 30 00:33:42 EDT 2019]
2019-04-30 00:33:42.462 [DEBUG] [org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchLevel] - 7C25240000163762: ZigBee attribute reports ZclAttribute [cluster=ON_OFF, id=0, name=OnOff, dataType=BOOLEAN, lastValue=true, lastReportTime=Tue Apr 30 00:33:42 EDT 2019]
2019-04-30 00:33:42.462 [DEBUG] [org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchLevel] - 7C25240000163762: ZigBee attribute reports ZclAttribute [cluster=ON_OFF, id=0, name=OnOff, dataType=BOOLEAN, lastValue=true, lastReportTime=Tue Apr 30 00:33:42 EDT 2019]
2019-04-30 00:33:42.462 [DEBUG] [org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchLevel] - 7C25240000163762: ZigBee attribute reports ZclAttribute [cluster=ON_OFF, id=0, name=OnOff, dataType=BOOLEAN, lastValue=true, lastReportTime=Tue Apr 30 00:33:42 EDT 2019]
2019-04-30 00:33:42.461 [DEBUG] [org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchLevel] - 7C25240000163762: ZigBee attribute reports ZclAttribute [cluster=ON_OFF, id=0, name=OnOff, dataType=BOOLEAN, lastValue=true, lastReportTime=Tue Apr 30 00:33:42 EDT 2019]
2019-04-30 00:33:42.461 [DEBUG] [org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchLevel] - 7C25240000163762: ZigBee attribute reports ZclAttribute [cluster=ON_OFF, id=0, name=OnOff, dataType=BOOLEAN, lastValue=true, lastReportTime=Tue Apr 30 00:33:42 EDT 2019]
2019-04-30 00:33:42.470 [DEBUG] [org.openhab.binding.zigbee.handler.ZigbeeIsAliveTracker] - Reset timeout for handler with thingUID=zigbee:device:9b51c72d:7c25240000163762
2019-04-30 00:33:42.473 [DEBUG] [org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchLevel] - 7C25240000163762: ZigBee attribute reports ZclAttribute [cluster=ON_OFF, id=0, name=OnOff, dataType=BOOLEAN, lastValue=true, lastReportTime=Tue Apr 30 00:33:42 EDT 2019]
2019-04-30 00:33:42.473 [DEBUG] [org.openhab.binding.zigbee.converter.ZigBeeBaseChannelConverter] - 7C25240000163762: Channel zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer updated to 100
2019-04-30 00:33:42.473 [DEBUG] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 7C25240000163762: Updating ZigBee channel state zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer to 100
2019-04-30 00:33:42.473 [DEBUG] [org.openhab.binding.zigbee.handler.ZigbeeIsAliveTracker] - Reset timeout for handler with thingUID=zigbee:device:9b51c72d:7c25240000163762
2019-04-30 00:33:42.461 [DEBUG] [org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchLevel] - 7C25240000163762: ZigBee attribute reports ZclAttribute [cluster=ON_OFF, id=0, name=OnOff, dataType=BOOLEAN, lastValue=true, lastReportTime=Tue Apr 30 00:33:42 EDT 2019]
2019-04-30 00:33:42.461 [DEBUG] [org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchLevel] - 7C25240000163762: ZigBee attribute reports ZclAttribute [cluster=ON_OFF, id=0, name=OnOff, dataType=BOOLEAN, lastValue=true, lastReportTime=Tue Apr 30 00:33:42 EDT 2019]
2019-04-30 00:33:42.474 [DEBUG] [org.openhab.binding.zigbee.converter.ZigBeeBaseChannelConverter] - 7C25240000163762: Channel zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer updated to 100
2019-04-30 00:33:42.474 [DEBUG] [org.openhab.binding.zigbee.converter.ZigBeeBaseChannelConverter] - 7C25240000163762: Channel zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer updated to 100
2019-04-30 00:33:42.474 [DEBUG] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler] - null: Updating ZigBee channel state zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer to 100
2019-04-30 00:33:42.461 [DEBUG] [org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchLevel] - 7C25240000163762: ZigBee attribute reports ZclAttribute [cluster=ON_OFF, id=0, name=OnOff, dataType=BOOLEAN, lastValue=true, lastReportTime=Tue Apr 30 00:33:42 EDT 2019]
2019-04-30 00:33:42.475 [DEBUG] [org.openhab.binding.zigbee.converter.ZigBeeBaseChannelConverter] - 7C25240000163762: Channel zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer updated to 100
2019-04-30 00:33:42.476 [DEBUG] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler] - null: Updating ZigBee channel state zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer to 100
2019-04-30 00:33:42.472 [DEBUG] [org.openhab.binding.zigbee.handler.ZigbeeIsAliveTracker] - Reset timeout for handler with thingUID=zigbee:device:9b51c72d:7c25240000163762
2019-04-30 00:33:42.470 [DEBUG] [org.openhab.binding.zigbee.converter.ZigBeeBaseChannelConverter] - 7C25240000163762: Channel zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer updated to 100
2019-04-30 00:33:42.476 [DEBUG] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler] - null: Updating ZigBee channel state zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer to 100
2019-04-30 00:33:42.470 [DEBUG] [org.openhab.binding.zigbee.converter.ZigBeeBaseChannelConverter] - 7C25240000163762: Channel zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer updated to 100
2019-04-30 00:33:42.476 [DEBUG] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler] - null: Updating ZigBee channel state zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer to 100
2019-04-30 00:33:42.470 [DEBUG] [org.openhab.binding.zigbee.converter.ZigBeeBaseChannelConverter] - 7C25240000163762: Channel zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer updated to 100
2019-04-30 00:33:42.478 [DEBUG] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler] - null: Updating ZigBee channel state zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer to 100
2019-04-30 00:33:42.470 [DEBUG] [org.openhab.binding.zigbee.converter.ZigBeeBaseChannelConverter] - 7C25240000163762: Channel zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer updated to 100
2019-04-30 00:33:42.478 [DEBUG] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler] - null: Updating ZigBee channel state zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer to 100
2019-04-30 00:33:42.468 [DEBUG] [org.openhab.binding.zigbee.converter.ZigBeeBaseChannelConverter] - 7C25240000163762: Channel zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer updated to 100
2019-04-30 00:33:42.479 [DEBUG] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler] - null: Updating ZigBee channel state zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer to 100
2019-04-30 00:33:42.479 [DEBUG] [org.openhab.binding.zigbee.handler.ZigbeeIsAliveTracker] - Reset timeout for handler with thingUID=zigbee:device:9b51c72d:7c25240000163762
2019-04-30 00:33:42.468 [DEBUG] [org.openhab.binding.zigbee.converter.ZigBeeBaseChannelConverter] - 7C25240000163762: Channel zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer updated to 100
2019-04-30 00:33:42.479 [DEBUG] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler] - null: Updating ZigBee channel state zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer to 100
2019-04-30 00:33:42.468 [DEBUG] [org.openhab.binding.zigbee.converter.ZigBeeBaseChannelConverter] - 7C25240000163762: Channel zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer updated to 100
2019-04-30 00:33:42.468 [DEBUG] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 7C25240000163762: Updating ZigBee channel state zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer to 100
2019-04-30 00:33:42.463 [DEBUG] [org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchLevel] - 7C25240000163762: ZigBee attribute reports ZclAttribute [cluster=ON_OFF, id=0, name=OnOff, dataType=BOOLEAN, lastValue=true, lastReportTime=Tue Apr 30 00:33:42 EDT 2019]
2019-04-30 00:33:42.480 [DEBUG] [org.openhab.binding.zigbee.converter.ZigBeeBaseChannelConverter] - 7C25240000163762: Channel zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer updated to 100
2019-04-30 00:33:42.480 [DEBUG] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler] - null: Updating ZigBee channel state zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer to 100
2019-04-30 00:33:42.480 [DEBUG] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler] - null: Updating ZigBee channel state zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer to 100
2019-04-30 00:33:42.481 [DEBUG] [org.openhab.binding.zigbee.handler.ZigbeeIsAliveTracker] - Reset timeout for handler with thingUID=zigbee:device:9b51c72d:7c25240000163762
2019-04-30 00:33:42.481 [DEBUG] [org.openhab.binding.zigbee.handler.ZigbeeIsAliveTracker] - Reset timeout for handler with thingUID=zigbee:device:9b51c72d:7c25240000163762
2019-04-30 00:33:42.482 [DEBUG] [org.openhab.binding.zigbee.handler.ZigbeeIsAliveTracker] - Reset timeout for handler with thingUID=zigbee:device:9b51c72d:7c25240000163762
2019-04-30 00:33:42.479 [DEBUG] [org.openhab.binding.zigbee.handler.ZigbeeIsAliveTracker] - Reset timeout for handler with thingUID=zigbee:device:9b51c72d:7c25240000163762
2019-04-30 00:33:42.474 [DEBUG] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler] - null: Updating ZigBee channel state zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer to 100
2019-04-30 00:33:42.482 [DEBUG] [org.openhab.binding.zigbee.handler.ZigbeeIsAliveTracker] - Reset timeout for handler with thingUID=zigbee:device:9b51c72d:7c25240000163762
2019-04-30 00:33:42.481 [DEBUG] [org.openhab.binding.zigbee.handler.ZigbeeIsAliveTracker] - Reset timeout for handler with thingUID=zigbee:device:9b51c72d:7c25240000163762
2019-04-30 00:33:42.484 [DEBUG] [org.openhab.binding.zigbee.handler.ZigbeeIsAliveTracker] - Reset timeout for handler with thingUID=zigbee:device:9b51c72d:7c25240000163762
2019-04-30 00:33:42.484 [DEBUG] [org.openhab.binding.zigbee.handler.ZigbeeIsAliveTracker] - Reset timeout for handler with thingUID=zigbee:device:9b51c72d:7c25240000163762
2019-04-30 00:33:42.487 [DEBUG] [org.openhab.binding.zigbee.handler.ZigbeeIsAliveTracker] - Reset timeout for handler with thingUID=zigbee:device:9b51c72d:7c25240000163762
2019-04-30 00:33:42.486 [DEBUG] [org.openhab.binding.zigbee.handler.ZigbeeIsAliveTracker] - Reset timeout for handler with thingUID=zigbee:device:9b51c72d:7c25240000163762
2019-04-30 00:33:42.485 [DEBUG] [org.openhab.binding.zigbee.handler.ZigbeeIsAliveTracker] - Reset timeout for handler with thingUID=zigbee:device:9b51c72d:7c25240000163762
2019-04-30 00:33:42.485 [DEBUG] [org.openhab.binding.zigbee.handler.ZigbeeIsAliveTracker] - Reset timeout for handler with thingUID=zigbee:device:9b51c72d:7c25240000163762
After this, I tried turning off the bulb and got this in the openhab.log...
2019-04-30 00:34:27.070 [DEBUG] [org.eclipse.smarthome.config.core.ConfigDescriptionRegistry] - No config description found for 'thing:zigbee:device:9b51c72d:7c25240000163762', using alias 'thing-type:zigbee:device' instead
2019-04-30 00:34:27.076 [DEBUG] [org.eclipse.smarthome.config.core.status.ConfigStatusService] - There is no config status provider for entity zigbee:device:9b51c72d:7c25240000163762 available.
And this in the zigbee log...
2019-04-30 00:34:30.255 [DEBUG] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 7C25240000163762: Command for channel zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer --> OFF [OnOffType]
2019-04-30 00:34:30.256 [DEBUG] [org.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 7C25240000163762: No handler found for zigbee:device:9b51c72d:7c25240000163762:7C25240000163762_1_dimmer
I was able to get things back to normal by rolling back the org.openhab.binding.zigbee.jar to 2.5.0.201904190356.
@cdjackson, did this issue sneak past you? We probably should revert #427 or get a fix in before others start using this version.
OK... but I'll ping him too!
Bump
I thought you'd pinged @YordanDZhelev - I'm sure I saw an email, but maybe it wasn't through github.
@YordanDZhelev are you able to take a look at this please? Since it seems the binding is currently unusable, it is a little urgent.
I did (in the PR) but no response. I've looked through the code, but this was a big PR and went deeper than I could follow.