Attribute reporting class cast exception

[zsmartsystems]

Attribute reporting class cast exception

[cdjackson]

@openhab-5iver I guess that this isn't completely reproducible? If it is, can you provide a log of what's happening? Or is this always happening with a specific device?

The library sends a ReadAttributesCommand command, and it seems that we've correlated a ReportAttributesCommand when we expected a ReadAttributesResponse. I'll take a look at the code later, but I think the main thing used for the correlation is the transaction ID. So, it might be that a device is responding with the wrong response packet - or it might be that both are allowed.

Probably the solution will be to allow both responses, but it would be good to understand a bit what is happening if you can reproduce a log.

[5iver]

I guess that this isn't completely reproducible? If it is, can you provide a log of what's happening? Or is this always happening with a specific device?

Nope. Never seen it before. At the time, I noticed a bulb turn on and drop offline (not the bulb in the error). Power cycling it and restarting the binding did bring it back online. It was about 4 minutes after the last restart that this came up. I'll turn on debug and restart the binding a few times to see if I can reproduce it.

[cdjackson]

Ok, thanks. If it's not systematic, then it might be a bug with the transaction correlation, or it might still be that the device decided to use the different response frame for some reason (eg if the device was just about to send a report). Seems strange, but who knows.

If you do catch a log of this any time, please attach, but I'll look at a few possible options anyway...

[5iver]

Here is a debug log with a new one, but I think you can recreate it yourself by shutting the binding down and then immediately starting the binding. Doing a bunde:restart may do it too. The exception comes up a few minutes later. There are also a few other exceptions that came up in this log, likely related to the binding not completely shutting down when the bundle is stopped. After a bundle:stop, the logs keep going. Yes, I only have one instance of the binding running :). But I don't think I have restarted OH since dropping in an updated jar, so maybe this is all just be due to that?

The exception in question is at 2018-01-04 04:52:13.605, but if you search for exception, you'll find others.
exception creating channels.zip

[cdjackson]

There are also a few other exceptions that came up in this log, likely related to the binding not completely shutting down when the bundle is stopped.

I assume you mean the InterruptedExceptions? These are caused by the shutdown itself - you closed the binding, so various threads have exited -:

2018-01-04 04:50:00.161 [DEBUG] [org.openhab.binding.zigbee                        ] - BundleEvent STOPPING - org.openhab.binding.zigbee
2018-01-04 04:50:00.414 [DEBUG] [.openhab.binding.zigbee.handler.ZigBeeThingHandler] - 7CE5240000139646: Handler dispose.
2018-01-04 04:50:00.417 [DEBUG] [org.openhab.binding.zigbee                        ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.core.thing.binding.firmware.FirmwareUpdateHandler}={service.id=1042, service.bundleid=16, service.scope=singleton} - org.openhab.binding.zigbee
2018-01-04 04:50:00.419 [DEBUG] [artsystems.zigbee.internal.ZigBeeNetworkDiscoverer] - Error in rediscoverNode 
java.lang.InterruptedException: null

[cdjackson]

I'm unable to replicate this. I'm also unable to tie together your log - I can't find the request that is being made, with the response...

What happens is the transaction is correlating based on the transaction ID - it a message comes in with a transaction ID matching the requests transaction ID, then it's considered a match. I will modify this to also check the addresses are from the correct endpoint - that ought to limit the opportunity for false matches.

In the log here though, I don't see the request being made so I can't work out if the TID is matching with the response - I have to assume it is as the tests on the transaction matcher are working fine.

Given that you seem to be able to repeat this, I'm not sure it will solve the issue - if you get any other logs showing the 10 seconds or so before the exception that would be good...

[cdjackson]

Please let me know if this is still occurring with the latest binding...

[5iver]

I could not get this exception to reoccur with the latest (2.3.0.201801052345).

[cdjackson]

Ok, thanks for testing - I'll close this.

[puzzle-star]

Hi @cdjackson

For some reason I always reproduce the strangest errors... :-)

My understanding from looking at the logs below:

• This is happening not because the device sends the wrong respone, but because by "chance" a report comes from the device with the same TID as the last command sent to the device
• The probability of this happening is low, but not negligible
• It is easy to reproduce in my case, as I was keeping alive the device to register it by pushing its button at half second intervals. In turn, the device is responding with an attribute report (Xiaomi...), so we have plenty of reports (but this just increases the probability of the issue, and is not responsible for the error itself)

So the way to fix it is probably considering not only the source address/endpoint of the device to match the response, but also the destination address/endpoint, as, at least from my logs:

• The destination address/endpoint of a response matches the one of the originating command (0/0 as I see in the logs, but could be any)
• The destination endpoint of the report is the one used when binding (0/1 in my case)

Or maybe we should just not match commands as responses

Could you please reopen the issue? (or should I open a new one?)

Here the relevant parts of the log:

2018-09-03 18:58:24.268 [DEBUG] [.zsmartsystems.zigbee.zcl.ZclCluster] - readSync request: ZclAttribute [cluster=RELATIVE_HUMIDITY_MEASUREMENT, id=0, name=MeasuredValue, dataType=UNSIGNED_16_BIT_INTEGER, lastValue=null]
2018-09-03 18:58:24.270 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Relative humidity measurement: 0/0 -> 16824/1, cluster=0405, TID=08, identifiers=[0]]
2018-09-03 18:58:24.272 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=8, commandId=0]
2018-09-03 18:58:24.274 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=16824/1, profile=0104, cluster=1029, addressMode=DEVICE, radius=31, apsCounter=8, payload=00 08 00 00 00]

2018-09-03 18:58:30.288 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReportAttributesCommand [Basic: 16824/1 -> 0/1, cluster=0000, TID=05, reports=[Attribute Report: attributeDataType=CHARACTER_STRING, attributeIdentifier=5, attributeValue=lumi.sensor_ht]]
2018-09-03 18:58:30.661 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReportAttributesCommand [Basic: 16824/1 -> 0/1, cluster=0000, TID=06, reports=[Attribute Report: attributeDataType=CHARACTER_STRING, attributeIdentifier=5, attributeValue=lumi.sensor_ht]]
2018-09-03 18:58:31.406 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReportAttributesCommand [Basic: 16824/1 -> 0/1, cluster=0000, TID=07, reports=[Attribute Report: attributeDataType=CHARACTER_STRING, attributeIdentifier=5, attributeValue=lumi.sensor_ht]]

2018-09-03 18:58:32.192 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=16824/1, destinationAddress=0/1, profile=0104, cluster=0, addressMode=null, radius=0, apsCounter=0, payload=18 08 0A 05 00 42 0E 6C 75 6D 69 2E 73 65 6E 73 6F 72 5F 68 74]
2018-09-03 18:58:32.193 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=8, commandId=10]
2018-09-03 18:58:32.195 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReportAttributesCommand [Basic: 16824/1 -> 0/1, cluster=0000, TID=08, reports=[Attribute Report: attributeDataType=CHARACTER_STRING, attributeIdentifier=5, attributeValue=lumi.sensor_ht]]
2018-09-03 18:58:32.198 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction complete: ReadAttributesCommand [Relative humidity measurement: 0/0 -> 16824/1, cluster=0405, TID=08, identifiers=[0]]
2018-09-03 18:58:32.200 [ERROR] [ng.zigbee.handler.ZigBeeThingHandler] - 00158D0002379093: Exception creating channels
java.lang.ClassCastException: com.zsmartsystems.zigbee.zcl.clusters.general.ReportAttributesCommand cannot be cast to com.zsmartsystems.zigbee.zcl.clusters.general.ReadAttributesResponse
        at com.zsmartsystems.zigbee.zcl.ZclCluster.readSync(ZclCluster.java:247) [188:com.zsmartsystems.zigbee:1.0.14]
        at com.zsmartsystems.zigbee.zcl.clusters.ZclRelativeHumidityMeasurementCluster.getMeasuredValue(ZclRelativeHumidityMeasurementCluster.java:163) [188:com.zsmartsystems.zigbee:1.0.14]
        at org.openhab.binding.zigbee.internal.converter.ZigBeeConverterRelativeHumidity.handleRefresh(ZigBeeConverterRelativeHumidity.java:64) [224:org.openhab.binding.zigbee:2.4.0.201808311821]
        at org.openhab.binding.zigbee.handler.ZigBeeThingHandler.doNodeInitialisation(ZigBeeThingHandler.java:294) [224:org.openhab.binding.zigbee:2.4.0.201808311821]
        at org.openhab.binding.zigbee.handler.ZigBeeThingHandler.access$000(ZigBeeThingHandler.java:71) [224:org.openhab.binding.zigbee:2.4.0.201808311821]
        at org.openhab.binding.zigbee.handler.ZigBeeThingHandler$1.call(ZigBeeThingHandler.java:153) [224:org.openhab.binding.zigbee:2.4.0.201808311821]
        at org.openhab.binding.zigbee.handler.ZigBeeThingHandler$1.call(ZigBeeThingHandler.java:150) [224:org.openhab.binding.zigbee:2.4.0.201808311821]
        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) [?:?]

Best Regards,
Pedro

[cdjackson]

I've sen this sort of issue in the past and I'd already added some checks in the response matcher to combat this (this is the request.getDestinationAddress().equals(response.getSourceAddress() check).

I'd suggest to open another issue with a more targeted title (ie one that better represents this issue).

So the way to fix it is probably considering not only the source address/endpoint of the device to match the response, but also the destination address/endpoint, as, at least from my logs:

I'm not completely sure this will resolve it. Given that TIDs are allocated by the sender, there is nothing to stop such a mismatch if they happen to coincide (if that makes sense).

Or maybe we should just not match commands as responses

Maybe, but this again isn't so easy as you can't be sure that a command will be met with a response (I think!). I'd need to check this, but I think there are instances where this doesn't work and it could be complex. Unless we somehow match specific commands to specific responses - and that is a total nightmare.

Anyways, I'd suggest to open a specific issue on this and we can discuss potential solutions.