Zigbee binding

zigbee
beginners
Tags: #<Tag:0x00007f01569a6880> #<Tag:0x00007f01569a65b0>

(Chris Jackson) #1747

I have created a PR yesterday that will allow disabling of the mesh info update, so this might also help you.

Please can you provide a bit more of the log - ie a few seconds of data from before the event so I an see what it was trying to send.


(Stefan Hauser) #1748

I had exactly the same error with an Osram power outlet, until I realized that the channel name changed from zigbee:device:xx:yyy:zzz_switch_on_off to just zigbee:device:xx:yyy:zzz_switch after the upgrade.
After correcting that in my item configuration, everything works again (though I get the “Error 0xffff setting server binding” error as well).
Hope that helps.


(Fredrik Andersson) #1749

This goes in repeat. The device that left the network when i pushed the button has not rejoined either. So its lost.So if i push the inclusion/update button on the device right after a neighbor update is successful, the device leaves.

2018-12-26 07:20:06.859 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 000D6F0012EA8781: Routing table NEW: [RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0]]
2018-12-26 07:20:06.861 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 000D6F0012EA8781: Routing table OLD: [RoutingTable [destinationAddress=0, status=INACTIVE, memoryConstrained=false, manyToOne=false, routeRecordRequired=false, nextHopAddress=0]]
2018-12-26 07:20:06.863 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 000D6F0012EA8781: Routing table unchanged
2018-12-26 07:20:06.865 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000D6F0012EA8781: Node SVC Discovery: request ROUTES successful. Advanced to null.
2018-12-26 07:20:06.867 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000D6F0012EA8781: Node SVC Discovery: running
2018-12-26 07:20:06.869 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 000D6F0012EA8781: Node SVC Discovery: complete
2018-12-26 07:20:06.870 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 000D6F0012EA8781: Node 0 update
2018-12-26 07:20:06.880 [DEBUG] [nal.ZigBeeNetworkStateSerializerImpl] - Saving ZigBee network state: Start.
2018-12-26 07:20:06.959 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=AB]
2018-12-26 07:20:07.001 [DEBUG] [nal.ZigBeeNetworkStateSerializerImpl] - Saving ZigBee network state: Done.
2018-12-26 07:20:14.477 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=47654]
2018-12-26 07:20:14.480 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=47654]
2018-12-26 07:20:15.553 [DEBUG] [s.zigbee.dongle.ember.ezsp.EzspFrame] - Error creating instance of EzspFrame
java.lang.reflect.InvocationTargetException: null
	at sun.reflect.GeneratedConstructorAccessor308.newInstance(Unknown Source) ~[?:?]
	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[?:?]
	at java.lang.reflect.Constructor.newInstance(Constructor.java:423) ~[?:?]
	at com.zsmartsystems.zigbee.dongle.ember.ezsp.EzspFrame.createHandler(EzspFrame.java:404) [305:com.zsmartsystems.zigbee.dongle.ember:1.1.8]
	at com.zsmartsystems.zigbee.dongle.ember.internal.ash.AshFrameHandler$1.run(AshFrameHandler.java:196) [305:com.zsmartsystems.zigbee.dongle.ember:1.1.8]
Caused by: java.lang.ArrayIndexOutOfBoundsException: 76
	at com.zsmartsystems.zigbee.dongle.ember.internal.serializer.EzspDeserializer.deserializeUInt8(EzspDeserializer.java:77) ~[?:?]
	at com.zsmartsystems.zigbee.dongle.ember.internal.serializer.EzspDeserializer.deserializeUInt8Array(EzspDeserializer.java:124) ~[?:?]
	at com.zsmartsystems.zigbee.dongle.ember.ezsp.command.EzspGpepIncomingMessageHandler.<init>(EzspGpepIncomingMessageHandler.java:142) ~[?:?]
	... 5 more
2018-12-26 07:20:18.845 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction cancelled: ManagementLqiRequest [0/0 -> 47654/0, cluster=0031, TID=44, startIndex=0]
2018-12-26 07:20:18.848 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D000247ECE1: Node SVC Discovery: ManagementLqiRequest response CommandResult [TIMEOUT]
2018-12-26 07:20:18.852 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D000247ECE1: Node SVC Discovery: request NEIGHBORS failed. Retry 1, wait 2304ms before retry.
2018-12-26 07:20:20.557 [DEBUG] [s.zigbee.dongle.ember.ezsp.EzspFrame] - Error creating instance of EzspFrame
java.lang.reflect.InvocationTargetException: null
	at sun.reflect.GeneratedConstructorAccessor308.newInstance(Unknown Source) ~[?:?]
	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[?:?]
	at java.lang.reflect.Constructor.newInstance(Constructor.java:423) ~[?:?]
	at com.zsmartsystems.zigbee.dongle.ember.ezsp.EzspFrame.createHandler(EzspFrame.java:404) [305:com.zsmartsystems.zigbee.dongle.ember:1.1.8]
	at com.zsmartsystems.zigbee.dongle.ember.internal.ash.AshFrameHandler$1.run(AshFrameHandler.java:196) [305:com.zsmartsystems.zigbee.dongle.ember:1.1.8]
Caused by: java.lang.ArrayIndexOutOfBoundsException: 76
	at com.zsmartsystems.zigbee.dongle.ember.internal.serializer.EzspDeserializer.deserializeUInt8(EzspDeserializer.java:77) ~[?:?]
	at com.zsmartsystems.zigbee.dongle.ember.internal.serializer.EzspDeserializer.deserializeUInt8Array(EzspDeserializer.java:124) ~[?:?]
	at com.zsmartsystems.zigbee.dongle.ember.ezsp.command.EzspGpepIncomingMessageHandler.<init>(EzspGpepIncomingMessageHandler.java:142) ~[?:?]
	... 5 more
2018-12-26 07:20:21.159 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D000247ECE1: Node SVC Discovery: running
2018-12-26 07:20:21.162 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Sending transaction: ManagementLqiRequest [null -> 47654/0, cluster=0031, TID=NULL, startIndex=0] ==== ManagementLqiRequest [null -> 47654/0, cluster=0031, TID=NULL, startIndex=0]
2018-12-26 07:20:21.165 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementLqiRequest [0/0 -> 47654/0, cluster=0031, TID=45, startIndex=0]
2018-12-26 07:20:21.168 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=47654/0, profile=0000, cluster=0031, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=45, payload=00 00]
2018-12-26 07:20:21.170 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - EzspSendUnicastRequest [type=EMBER_OUTGOING_DIRECT, indexOrDestination=47654, apsFrame=EmberApsFrame [profileId=0, clusterId=49, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=45], messageTag=45, messageContents=00 00]
2018-12-26 07:20:21.287 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=AC]
2018-12-26 07:20:23.560 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=47654]
2018-12-26 07:20:23.563 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=47654]
2018-12-26 07:20:25.564 [DEBUG] [s.zigbee.dongle.ember.ezsp.EzspFrame] - Error creating instance of EzspFrame
java.lang.reflect.InvocationTargetException: null
	at sun.reflect.GeneratedConstructorAccessor308.newInstance(Unknown Source) ~[?:?]
	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[?:?]
	at java.lang.reflect.Constructor.newInstance(Constructor.java:423) ~[?:?]
	at com.zsmartsystems.zigbee.dongle.ember.ezsp.EzspFrame.createHandler(EzspFrame.java:404) [305:com.zsmartsystems.zigbee.dongle.ember:1.1.8]
	at com.zsmartsystems.zigbee.dongle.ember.internal.ash.AshFrameHandler$1.run(AshFrameHandler.java:196) [305:com.zsmartsystems.zigbee.dongle.ember:1.1.8]
Caused by: java.lang.ArrayIndexOutOfBoundsException: 76
	at com.zsmartsystems.zigbee.dongle.ember.internal.serializer.EzspDeserializer.deserializeUInt8(EzspDeserializer.java:77) ~[?:?]
	at com.zsmartsystems.zigbee.dongle.ember.internal.serializer.EzspDeserializer.deserializeUInt8Array(EzspDeserializer.java:124) ~[?:?]
	at com.zsmartsystems.zigbee.dongle.ember.ezsp.command.EzspGpepIncomingMessageHandler.<init>(EzspGpepIncomingMessageHandler.java:142) ~[?:?]
	... 5 more
2018-12-26 07:20:28.800 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=47654]
2018-12-26 07:20:28.803 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=47654]
2018-12-26 07:20:30.561 [DEBUG] [s.zigbee.dongle.ember.ezsp.EzspFrame] - Error creating instance of EzspFrame
java.lang.reflect.InvocationTargetException: null
	at sun.reflect.GeneratedConstructorAccessor308.newInstance(Unknown Source) ~[?:?]
	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[?:?]
	at java.lang.reflect.Constructor.newInstance(Constructor.java:423) ~[?:?]
	at com.zsmartsystems.zigbee.dongle.ember.ezsp.EzspFrame.createHandler(EzspFrame.java:404) [305:com.zsmartsystems.zigbee.dongle.ember:1.1.8]
	at com.zsmartsystems.zigbee.dongle.ember.internal.ash.AshFrameHandler$1.run(AshFrameHandler.java:196) [305:com.zsmartsystems.zigbee.dongle.ember:1.1.8]
Caused by: java.lang.ArrayIndexOutOfBoundsException: 76
	at com.zsmartsystems.zigbee.dongle.ember.internal.serializer.EzspDeserializer.deserializeUInt8(EzspDeserializer.java:77) ~[?:?]
	at com.zsmartsystems.zigbee.dongle.ember.internal.serializer.EzspDeserializer.deserializeUInt8Array(EzspDeserializer.java:124) ~[?:?]
	at com.zsmartsystems.zigbee.dongle.ember.ezsp.command.EzspGpepIncomingMessageHandler.<init>(EzspGpepIncomingMessageHandler.java:142) ~[?:?]
	... 5 more
2018-12-26 07:20:32.643 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=47654]
2018-12-26 07:20:32.645 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=47654]
2018-12-26 07:20:33.165 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction cancelled: ManagementLqiRequest [0/0 -> 47654/0, cluster=0031, TID=45, startIndex=0]
2018-12-26 07:20:33.169 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D000247ECE1: Node SVC Discovery: ManagementLqiRequest response CommandResult [TIMEOUT]
2018-12-26 07:20:33.171 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D000247ECE1: Node SVC Discovery: request NEIGHBORS failed. Retry 2, wait 2304ms before retry.
2018-12-26 07:20:34.212 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspMessageSentHandler [type=EMBER_OUTGOING_DIRECT, indexOrDestination=47654, apsFrame=EmberApsFrame [profileId=0, clusterId=49, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=AB], messageTag=44, status=EMBER_DELIVERY_FAILED, messageContents=]
2018-12-26 07:20:35.479 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D000247ECE1: Node SVC Discovery: running
2018-12-26 07:20:35.490 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Sending transaction: ManagementLqiRequest [null -> 47654/0, cluster=0031, TID=NULL, startIndex=0] ==== ManagementLqiRequest [null -> 47654/0, cluster=0031, TID=NULL, startIndex=0]
2018-12-26 07:20:35.493 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementLqiRequest [0/0 -> 47654/0, cluster=0031, TID=46, startIndex=0]
2018-12-26 07:20:35.496 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=47654/0, profile=0000, cluster=0031, addressMode=DEVICE, radius=31, apsSecurity=false, apsCounter=46, payload=00 00]
2018-12-26 07:20:35.499 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - EzspSendUnicastRequest [type=EMBER_OUTGOING_DIRECT, indexOrDestination=47654, apsFrame=EmberApsFrame [profileId=0, clusterId=49, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=46], messageTag=46, messageContents=00 00]
2018-12-26 07:20:35.612 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspSendUnicastResponse [status=EMBER_SUCCESS, sequence=AD]
2018-12-26 07:20:37.884 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=47654]
2018-12-26 07:20:37.886 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=47654]
2018-12-26 07:20:40.578 [DEBUG] [s.zigbee.dongle.ember.ezsp.EzspFrame] - Error creating instance of EzspFrame
java.lang.reflect.InvocationTargetException: null
	at sun.reflect.GeneratedConstructorAccessor308.newInstance(Unknown Source) ~[?:?]
	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[?:?]
	at java.lang.reflect.Constructor.newInstance(Constructor.java:423) ~[?:?]
	at com.zsmartsystems.zigbee.dongle.ember.ezsp.EzspFrame.createHandler(EzspFrame.java:404) [305:com.zsmartsystems.zigbee.dongle.ember:1.1.8]
	at com.zsmartsystems.zigbee.dongle.ember.internal.ash.AshFrameHandler$1.run(AshFrameHandler.java:196) [305:com.zsmartsystems.zigbee.dongle.ember:1.1.8]
Caused by: java.lang.ArrayIndexOutOfBoundsException: 76
	at com.zsmartsystems.zigbee.dongle.ember.internal.serializer.EzspDeserializer.deserializeUInt8(EzspDeserializer.java:77) ~[?:?]
	at com.zsmartsystems.zigbee.dongle.ember.internal.serializer.EzspDeserializer.deserializeUInt8Array(EzspDeserializer.java:124) ~[?:?]
	at com.zsmartsystems.zigbee.dongle.ember.ezsp.command.EzspGpepIncomingMessageHandler.<init>(EzspGpepIncomingMessageHandler.java:142) ~[?:?]
	... 5 more
2018-12-26 07:20:43.129 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=47654]
2018-12-26 07:20:43.131 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=47654]
2018-12-26 07:20:45.582 [DEBUG] [s.zigbee.dongle.ember.ezsp.EzspFrame] - Error creating instance of EzspFrame
java.lang.reflect.InvocationTargetException: null
	at sun.reflect.GeneratedConstructorAccessor308.newInstance(Unknown Source) ~[?:?]
	at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[?:?]
	at java.lang.reflect.Constructor.newInstance(Constructor.java:423) ~[?:?]
	at com.zsmartsystems.zigbee.dongle.ember.ezsp.EzspFrame.createHandler(EzspFrame.java:404) [305:com.zsmartsystems.zigbee.dongle.ember:1.1.8]
	at com.zsmartsystems.zigbee.dongle.ember.internal.ash.AshFrameHandler$1.run(AshFrameHandler.java:196) [305:com.zsmartsystems.zigbee.dongle.ember:1.1.8]
Caused by: java.lang.ArrayIndexOutOfBoundsException: 76
	at com.zsmartsystems.zigbee.dongle.ember.internal.serializer.EzspDeserializer.deserializeUInt8(EzspDeserializer.java:77) ~[?:?]
	at com.zsmartsystems.zigbee.dongle.ember.internal.serializer.EzspDeserializer.deserializeUInt8Array(EzspDeserializer.java:124) ~[?:?]
	at com.zsmartsystems.zigbee.dongle.ember.ezsp.command.EzspGpepIncomingMessageHandler.<init>(EzspGpepIncomingMessageHandler.java:142) ~[?:?]
	... 5 more
2018-12-26 07:20:46.965 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=47654]
2018-12-26 07:20:46.968 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspIncomingRouteErrorHandler [status=EMBER_MAC_INDIRECT_TIMEOUT, target=47654]
2018-12-26 07:20:47.493 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction cancelled: ManagementLqiRequest [0/0 -> 47654/0, cluster=0031, TID=46, startIndex=0]
2018-12-26 07:20:47.499 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D000247ECE1: Node SVC Discovery: ManagementLqiRequest response CommandResult [TIMEOUT]
2018-12-26 07:20:47.502 [DEBUG] [iscovery.ZigBeeNodeServiceDiscoverer] - 00158D000247ECE1: Node SVC Discovery: request NEIGHBORS failed. Retry 3, wait 2304ms before retry.

(Chris Jackson) #1750

I’m not sure that we can fix this - at least not without understanding the root cause. This is likely a problem with the Xiaomi devices and incompatibility with ZigBee. Maybe stopping the neighbor updates will help - maybe not.


(Tobias) #1751

I still receive the errors

2018-12-18 06:12:44.985 [ERROR] [converter.ZigBeeConverterSwitchOnoff] - 7CB03EAA00AF1CEE: Error 0xffff setting server binding

accompanied by severe Zigbee adapter issues.

@chris wrote this is harmless. However, my Elelabs ZigBee USB adapter, connected by the Ember EM35x Coordinator, is very unstable and switches to “Status Unknown” frequently. Together with the unstable Tradfri binding, this is driving me crazy these days :frowning:

2018-12-27 00:13:42.134 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 
java.lang.NullPointerException: null
	at com.zsmartsystems.zigbee.dongle.ember.EmberNcp.getVersion(EmberNcp.java:148) ~[?:?]
	at com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp.initialiseEzspProtocol(ZigBeeDongleEzsp.java:799) ~[?:?]
	at com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp.initialize(ZigBeeDongleEzsp.java:289) ~[?:?]
	at com.zsmartsystems.zigbee.ZigBeeNetworkManager.initialize(ZigBeeNetworkManager.java:326) ~[?:?]
	at org.openhab.binding.zigbee.handler.ZigBeeCoordinatorHandler.initialiseZigBee(ZigBeeCoordinatorHandler.java:385) ~[?:?]
	at org.openhab.binding.zigbee.handler.ZigBeeCoordinatorHandler.lambda$0(ZigBeeCoordinatorHandler.java:466) ~[?:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[?:?]
	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) [?:?]

Can somebody help?


(Chris Jackson) #1752

As described previously, this can be ignored - it is just a logging issue. The bind is in fact working ok (at least in the logs I have seen). This is just a response correlation issue.

What is the “Status Unknown”? Are you sure you are talking about the coordinator status, or are you referring to the firmware version? The firmware version will always show as unknown in PaperUI as there are no firmware providers.

Please provide an image of what you mean as I don’t think that UNKNOWN is a valid thing status and may just be your misunderstanding.

I don’t think that this is related to ZigBee binding - or are you running Tradfri devices in ZigBee?

Please provide a debug logfile showing the error you are having.


(Tobias) #1753

@chris: Thanks for the clarification. Your responsiveness is really impressive - thanks for helping :slight_smile:

I talk about the " Ember EM35x Coordinator" status: Currently it is a green label, showing “online”. But the whole day it frequently switched to a grey “unknown” or “offline” on this page!

shot

I will try to provide a debug log as soon as the issues occurs again. And right, the Tradfri issue is another story as I directly use the Tradfri binding and no direct connection to the devices…


(Jared Frank) #1754

Chris - sorry for the delay. I just posted up the network xml requested at the link below. The device in question is a smart outlet that should allow for power usage tracking as well as on/off control (and apparently dimmer though I haven’t been using that). I also included a bit of regular logs from today - I noticed a few java exceptions scroll past so just in case there is anything in there that may be of use for you. (I’m on the newest libraries of yours now. - had you already implemented your traffic prioritization to resolve my delay issues when the network is super busy? I was only able to jump to 1.1.8 today as I was out of town but it does seem like I have the same delay issues)

EDIT I noticed the errors that did pop up earlier were referencing 1.1.5 still - even though the script deleted the old files/updated the new ones and the karaf was only showing the new versions it still had the old stuff in memory. As a note to others - I did experience tons of errors upon my first subsequent restart. I cleaned the cache (sudo openhab-cli clean-cache) and everything is starting up with no issue.

Thank you!


(Chris Jackson) #1755

Please provide a debug log file that shows this. This likely indicates that the device is not communicating, and the binding restarts communication.


(Chris Jackson) #1756

Thanks for the XML - can you tell me what device changed from a switch to a dimmer?

No - this is not implemented yet. Currently I’ve implemented some parts that would improve the situation where there are timeouts by using more information from the network layer, but the prioritisation and queue optimisation is not included.


(Kim Andersen) #1757

Great possitive info, @chris.
Since I updated from binding 2.4, lib 1.1.6 to 2.5-snapshot binding and lib 1.1.8 the day before yesterday, my devices seems to be running pretty good. This goes for the Trust motion sensor, and, (big surprise), the Philips Hue Dimmer Switch. Last one used to only work for a coupple of hours.

What exactly caused this change, I have no idea.


(Chris Jackson) #1758

Thanks for the feedback - good to know :slight_smile:

My guess is the aging change, coupled with the handling of rejoining nodes. I think the rejoining node problem I first discovered in one of your logs :wink:


(Kim Andersen) #1759

I hope so, then all this struggle hasn´t been all useless :slight_smile:


(Chris Jackson) #1760

Let’s see :slight_smile: . I won’t claim all problems are solved, but I do hope that with these changes, it will be a bit better. Please let me know how it goes over the coming days…


(Jared Frank) #1761

The device was a 'Samjin Outlet" I named it “washing machine” on my setup.Zigbee network address is 49145 and the mac address is 286D97000100A0D1. Hopefully that helps you track it down. I’m not sure when it switch to detecting the level control in favor of a switch… I just know my routines stopped working when it did as the channel name changed to reflect the dimmer.

Any Idea of an approx eta on some of that prioritization? I’ve got the latest code running now but I may get in trouble for the frequent long delays from other members of the household :sweat_smile:


(Chris Jackson) #1762

Thanks. So this device has both the OnOff and LevelControl clusters, so in this case, it will now only provide the dimmer channel - previously you would have had two channels - a switch and a dimmer. So what you see with just the dimmer channel is correct.

Yes, you will nee to change to use the dimmer channel. This change was added a little while ago to bring the binding in line with ESH requirements.

Probably another few weeks - it is the main thing I’m working on, but there are always other things to look at as well that take a few hours each day…

My hope is to have it in a working state before I go on holiday in mid/late Jan, so hopefully I will have something to try well before that.


(Kim Andersen) #1763

All of a sudden, totally out of the blue, this happened just a few minutes ago:

2018-12-28 15:50:42.910 [WARN ] [e.ember.internal.ash.AshFrameHandler] - ASH: ERROR received (code 81). Disconnecting.
2018-12-28 15:50:43.046 [WARN ] [e.ember.internal.ash.AshFrameHandler] - ASH: ERROR received (code 81). Disconnecting.
2018-12-28 15:50:43.048 [WARN ] [e.ember.internal.ash.AshFrameHandler] - ASH: ERROR received (code 81). Disconnecting.

==> /var/log/openhab2/events.log <==

2018-12-28 15:50:43.052 [hingStatusInfoChangedEvent] - 'zigbee:coordinator_ember:4beca465' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR)
2018-12-28 15:50:43.054 [hingStatusInfoChangedEvent] - 'zigbee:device:4beca465:001788011032a21b' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)

==> /var/log/openhab2/openhab.log <==

2018-12-28 15:50:43.053 [WARN ] [e.ember.internal.ash.AshFrameHandler] - ASH: ERROR received (code 81). Disconnecting.

==> /var/log/openhab2/events.log <==

2018-12-28 15:50:43.058 [hingStatusInfoChangedEvent] - 'zigbee:philips_sml001:4beca465:0017880102139d00' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)

==> /var/log/openhab2/openhab.log <==

2018-12-28 15:50:43.060 [WARN ] [e.ember.internal.ash.AshFrameHandler] - ASH: ERROR received (code 81). Disconnecting.
2018-12-28 15:50:43.062 [WARN ] [e.ember.internal.ash.AshFrameHandler] - ASH: ERROR received (code 81). Disconnecting.

==> /var/log/openhab2/events.log <==

2018-12-28 15:50:43.067 [hingStatusInfoChangedEvent] - 'zigbee:device:4beca465:00158d00019533d3' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2018-12-28 15:50:43.085 [hingStatusInfoChangedEvent] - 'zigbee:device:4beca465:7cb03eaa00a05370' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)

I believe its the coordinator which went offline. It´s offline right now, for god knows what reason.

EDIT.
I made a change to the Ember settings in PaperUI, (nothing important, just wanted to see if it could be back ONLINE). And it did…
And now it seems to be running again.

And some more info… This is highly strange…
It seem to be due to either some hardware issue or Grafana… It happens when I try to show 3 Grafana charts in one sitemap page… I just refreshed the sitemap page, and this happened:

2018-12-28 16:11:26.466 [WARN ] [su.litvak.chromecast.api.v2.Channel ] - Error while reading
su.litvak.chromecast.api.v2.ChromeCastException: Remote socket closed
	at su.litvak.chromecast.api.v2.Channel.read(Channel.java:425) ~[238:org.openhab.binding.chromecast:2.4.0]
	at su.litvak.chromecast.api.v2.Channel.access$200(Channel.java:51) ~[238:org.openhab.binding.chromecast:2.4.0]
	at su.litvak.chromecast.api.v2.Channel$ReadThread.run(Channel.java:137) [238:org.openhab.binding.chromecast:2.4.0]
2018-12-28 16:11:27.135 [WARN ] [su.litvak.chromecast.api.v2.Channel ] -  <--  null payload in message 
2018-12-28 16:11:26.999 [WARN ] [e.ember.internal.ash.AshFrameHandler] - ASH: ERROR received (code 81). Disconnecting.
2018-12-28 16:11:27.269 [WARN ] [e.ember.internal.ash.AshFrameHandler] - ASH: ERROR received (code 81). Disconnecting.
2018-12-28 16:11:27.271 [WARN ] [e.ember.internal.ash.AshFrameHandler] - ASH: ERROR received (code 81). Disconnecting.
2018-12-28 16:11:27.273 [WARN ] [e.ember.internal.ash.AshFrameHandler] - ASH: ERROR received (code 81). Disconnecting.
2018-12-28 16:11:27.274 [WARN ] [e.ember.internal.ash.AshFrameHandler] - ASH: ERROR received (code 81). Disconnecting.
2018-12-28 16:11:27.276 [WARN ] [e.ember.internal.ash.AshFrameHandler] - ASH: ERROR received (code 81). Disconnecting.
2018-12-28 16:11:27.278 [WARN ] [e.ember.internal.ash.AshFrameHandler] - ASH: ERROR received (code 81). Disconnecting.
2018-12-28 16:11:27.280 [WARN ] [e.ember.internal.ash.AshFrameHandler] - ASH: ERROR received (code 81). Disconnecting.
2018-12-28 16:11:27.281 [WARN ] [e.ember.internal.ash.AshFrameHandler] - ASH: ERROR received (code 81). Disconnecting.
2018-12-28 16:11:27.283 [WARN ] [e.ember.internal.ash.AshFrameHandler] - ASH: ERROR received (code 81). Disconnecting.

==> /var/log/openhab2/events.log <==

2018-12-28 16:11:26.386 [vent.ItemStateChangedEvent] - Nilan_AirTemp_TempControl changed from 18.4 to 18.39
2018-12-28 16:11:27.139 [vent.ItemStateChangedEvent] - Nilan_AirTemp_EffPct changed from 89.03 to 89.2
2018-12-28 16:11:27.276 [vent.ItemStateChangedEvent] - TrustMotionPresence changed from ON to OFF
2018-12-28 16:11:27.279 [vent.ItemStateChangedEvent] - ZWaveNode5ZW100MultiSensor6_BinarySensor changed from ON to OFF
2018-12-28 16:11:27.281 [GroupItemStateChangedEvent] - gMotionAlarm changed from ON to OFF through ZWaveNode5ZW100MultiSensor6_MotionAlarm

2018-12-28 16:11:27.283 [vent.ItemStateChangedEvent] - ZWaveNode5ZW100MultiSensor6_MotionAlarm changed from ON to OFF

==> /var/log/openhab2/openhab.log <==

==> /var/log/openhab2/events.log <==

==> /var/log/openhab2/openhab.log <==

==> /var/log/openhab2/events.log <==

==> /var/log/openhab2/openhab.log <==

==> /var/log/openhab2/events.log <==

==> /var/log/openhab2/openhab.log <==

==> /var/log/openhab2/events.log <==

==> /var/log/openhab2/openhab.log <==

==> /var/log/openhab2/events.log <==

2018-12-28 16:11:27.402 [hingStatusInfoChangedEvent] - 'chromecast:chromecast:255f3cf49521e13fa5f92fc38ae7ac51' changed from ONLINE to OFFLINE
2018-12-28 16:11:27.407 [hingStatusInfoChangedEvent] - 'chromecast:chromecast:255f3cf49521e13fa5f92fc38ae7ac51' changed from OFFLINE to OFFLINE (COMMUNICATION_ERROR): Interrupted while waiting for response
2018-12-28 16:11:27.410 [hingStatusInfoChangedEvent] - 'zigbee:coordinator_ember:4beca465' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR)
2018-12-28 16:11:27.414 [hingStatusInfoChangedEvent] - 'zigbee:device:4beca465:001788011032a21b' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2018-12-28 16:11:27.417 [hingStatusInfoChangedEvent] - 'zigbee:philips_sml001:4beca465:0017880102139d00' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2018-12-28 16:11:27.426 [hingStatusInfoChangedEvent] - 'zigbee:device:4beca465:00158d00019533d3' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
2018-12-28 16:11:27.432 [hingStatusInfoChangedEvent] - 'zigbee:device:4beca465:7cb03eaa00a05370' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)

This is really odd behaiour… I know I had problems with Grafana rendering more than one chart, but I have not seen it mess up other bindings before.
Chromecast binding returned online by itself, Ember coordinator didn´t.


(Chris Jackson) #1764

I know what this is, and I’m slowly working toward automatic recovery of this. The dongle now goes offline if this happens (as I see in the log), and shortly it will automatically recover.

The problem is that the dongle didn’t receive a message within a certain time - this isn’t new logs before. It might be caused by your system locking up for a second or two, or there might be a bug somewhere. Either way, once the dongle does in to this state, it needs to be reset.

Hopefully this will be automatically recovered in the next week or two.


(Kim Andersen) #1765

Yeah, like you say, it´s probably due to something locking up my system. In my system it´s Grafana , trying to render three charts, (it takes aprox 5 sec for one chart).
Something is really wrong with Grafana after I upgraded to openhab 2.4. I just cant seem to find the reason… It worked fine using openhab 2.3.

I´ll have to dig into this…

I just reset the Ember coordinator again… It did came online, and my devices came online as well. But they do not respond anymore.


(Chris Jackson) #1766

Do you have the sniffer log from this period?