search

openhab / org.openhab.binding.zigbee

openHAB binding for ZigBee
Eclipse Public License 2.0
73 stars 111 forks source link

Polling not working with Tradfri E27 bulb #775

Closed weakfl closed 1 year ago

weakfl commented 1 year ago

Outline

I have a Tradfri E27 dimmable light bulb that no longer answers to polling requests (it has worked fine in the past). I've tried changing the polling interval to 70s and back to 60s, and setting the interval seems to be successful.

But polling still times out:

2022-10-01 09:34:25.144 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 000B57FFFEB1BAB5: Polling [zigbee:device:c3cd543626:000b57fffeb1bab5:000B57FFFEB1BAB5_1_dimmer, zigbee:device:c3cd543626:000b57fffeb1bab5:000B57FFFEB1BAB5_1_colortemperature] channels...
[...]
2022-10-01 09:34:54.586 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker LastChance Timeout has been reached for thingUID=zigbee:device:c3cd543626:000b57fffeb1bab5
2022-10-01 09:34:54.590 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 000B57FFFEB1BAB5: Polling stopped
2022-10-01 09:34:54.595 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 000B57FFFEB1BAB5: Polling initialised at 61557ms

Reading attributes through the console however works as expected:

openhab> zigbee node 32147
IEEE Address     : 000B57FFFEB1BAB5
Network Address  : 32147
openhab> zigbee read 32147/1 0008 0                                                                                                                                                                                                                                      
Reading endpoint 7D93/1, cluster server cluster Level Control (0008), attributes Current Level
Response for cluster 0x0008
Attribute    0  Current Level                                       UNSIGNED_8_BIT_INTEGER          254

I'm also seeing some AshFrameHandler exceptions, probably unrelated though:

2022-10-01 09:32:11.231 [ERROR] [e.ember.internal.ash.AshFrameHandler] - AshFrameHandler Exception processing EZSP frame:
java.lang.IllegalArgumentException: No reader defined in ZigBeeDeserializer for UNSIGNED_64_BIT_INTEGER (0x27)
    at com.zsmartsystems.zigbee.serialization.DefaultDeserializer.readZigBeeType(DefaultDeserializer.java:345) ~[bundleFile:?]
    at com.zsmartsystems.zigbee.zcl.field.AttributeReport.deserialize(AttributeReport.java:101) ~[bundleFile:?]
    at com.zsmartsystems.zigbee.zcl.ZclFieldDeserializer.deserialize(ZclFieldDeserializer.java:73) ~[bundleFile:?]
    at com.zsmartsystems.zigbee.zcl.clusters.general.ReportAttributesCommand.deserialize(ReportAttributesCommand.java:111) ~[bundleFile:?]
    at com.zsmartsystems.zigbee.ZigBeeNetworkManager.receiveZclCommand(ZigBeeNetworkManager.java:1158) ~[bundleFile:?]
    at com.zsmartsystems.zigbee.ZigBeeNetworkManager.receiveCommand(ZigBeeNetworkManager.java:986) ~[bundleFile:?]
    at com.zsmartsystems.zigbee.dongle.ember.ZigBeeDongleEzsp.handlePacket(ZigBeeDongleEzsp.java:937) ~[bundleFile:?]
    at com.zsmartsystems.zigbee.dongle.ember.internal.ash.AshFrameHandler$AshReceiveProcessorThread.run(AshFrameHandler.java:399) [bundleFile:?]

Configuration

Configuration Description
Coordinator used Ember EM3588
openHAB version 3.4.0~M2-1
Hardware Raspi

Logs

openhab.log.zip

cdjackson commented 1 year ago

I have a Tradfri E27 dimmable light bulb that no longer answers to polling requests (it has worked fine in the past).

What exactly do you mean by this? You provide above a read command (which is a poll) and it is responding. Can you describe what the problem is - is the device going OFFLINE or something?

There are certainly polls working just fine in this log -:

image image

Polling is not normally used by the binding.

UNSIGNED_64_BIT_INTEGER

This is currently not supported and it never has been so this hasn't changed. I will take a look at adding this, but since it's not used by the binding it's not really going to make much difference.

So, polling works - what is the actual problem that you as a user are seeing? ie forget about the low level zigbee commands - what's the high level issue?

weakfl commented 1 year ago

@cdjackson yes, that's at the beginning of the log when I changed the polling interval to 70s and back to 60s. As stated this seems to be working fine. Subsequent polling attempts just time out and the device goes offline.

Please take a look at the log from 2022-10-01 09:33:23.668 onwards:

I can't see any response to the polling requests. Or am I missing something?

cdjackson commented 1 year ago

The only thing check that is done after this message is to see if the channel is linked. I can only guess at the moment that this returns false since there from what I can tell is no poll being sent - so you don't receive the response as nothing gets sent.

weakfl commented 1 year ago

The only thing check that is done after this message is to see if the channel is linked. I can only guess at the moment that this returns false since there from what I can tell is no poll being sent

Are you referring to the bindtable @cdjackson ?

It was:

openhab> zigbee bindtable 32147
Binding table for node 32147 [000B57FFFEB1BAB5]
Src Address          | Dest Address         | Group | Mode    | Cluster
000B57FFFEB1BAB5/1   | 0022A300002921FD/1   |       | Address | 0006:ON_OFF

I've changed it to:

openhab> zigbee bindtable 32147
Binding table for node 32147 [000B57FFFEB1BAB5]
Src Address          | Dest Address         | Group | Mode    | Cluster
000B57FFFEB1BAB5/1   | 0022A300002921FD/1   |       | Address | 0006:ON_OFF
000B57FFFEB1BAB5/1   | 0022A300002921FD/1   |       | Address | 0008:LEVEL_CONTROL
000B57FFFEB1BAB5/1   | 0022A300002921FD/1   |       | Address | 0300:COLOR_CONTROL

Polling still doesn't work though. I'll try to reset the device next.

Another question:

Is the Level Control (0008) cluster supposed to report the last level even when the On/Off (0006) cluster is off?

openhab> zigbee read 37485/18 0006 0                                                                                                                                                                                                                                     
Reading endpoint 926D/18, cluster server cluster On/Off (0006), attributes On Off
Response for cluster 0x0006
Attribute    0  On Off                                              BOOLEAN                         false

openhab> zigbee read 37485/18 0008 0                                                                                                                                                                                                                                     
Reading endpoint 926D/18, cluster server cluster Level Control (0008), attributes Current Level
Response for cluster 0x0008
Attribute    0  Current Level                                       UNSIGNED_8_BIT_INTEGER          239

The UI state in openHAB isn't updated correctly even if the device is turned off. Imho this should report 0 if 0x0006 is off. Since the channels are consolidated there's currently no way to update the UI state.

EDIT:

This seem to be the case already. Don't know why it didn't work previously...

weakfl commented 1 year ago

@cdjackson to me it looks like polling is generally broken.

I have two more devices for which I have set polling to 60s and they're showing the same behaviour. Not answering to polling and going offline.

As soon as I execute a read command from console the device is shown as online and status is updated in the openHAB UI.

cdjackson commented 1 year ago

Are you referring to the bindtable @cdjackson ?

No - I mean that a channel is linked to an item. Nothing to do with zigbee - this is the openhab linking. It seems that this check is probably failing, so the binding doesn't poll if a channel is not linked to an item.

I can add some more debugging around this area to see what is happening.

cdjackson commented 1 year ago

Please provide updated logs with the new binding.

weakfl commented 1 year ago

No - I mean that a channel is linked to an item. Nothing to do with zigbee - this is the openhab linking. It seems that this check is probably failing, so the binding doesn't poll if a channel is not linked to an item.

They should be linked. I can also control the devices just fine, even if they're shown as offline.

Devices as shown in openHAB UI:

Screenshot 2022-10-03 at 07 39 06 Screenshot 2022-10-03 at 07 39 26 Screenshot 2022-10-03 at 07 40 29

But still (compare with last screenshot):

000B57FFFEB1BAB5: Polling 2 channels...
000B57FFFEB1BAB5: Not polling zigbee:device:c3cd543626:000b57fffeb1bab5:000B57FFFEB1BAB5_1_dimmer - unlinked
000B57FFFEB1BAB5: Not polling zigbee:device:c3cd543626:000b57fffeb1bab5:000B57FFFEB1BAB5_1_colortemperature - unlinked

I can add some more debugging around this area to see what is happening.

Thanks a lot for looking into it @cdjackson. Here are the updated logs:

openhab.log.zip

cdjackson commented 1 year ago 
2022-10-03 07:40:21.682 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - D85DEF11A1001973: Polling 3 channels...
2022-10-03 07:40:21.685 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - D85DEF11A1001973: Not polling zigbee:device:c3cd543626:d85def11a1001973:D85DEF11A1001973_11_dimmer - unlinked
2022-10-03 07:40:21.688 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - D85DEF11A1001973: Polling zigbee:device:c3cd543626:d85def11a1001973:D85DEF11A1001973_10_dimmer
2022-10-03 07:40:21.691 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - D85DEF11A1001973: Not polling zigbee:device:c3cd543626:d85def11a1001973:D85DEF11A1001973_18_dimmer - unlinked
2022-10-03 07:40:21.939 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 000B57FFFEB1BAB5: Polling 2 channels...
2022-10-03 07:40:21.943 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 000B57FFFEB1BAB5: Not polling zigbee:device:c3cd543626:000b57fffeb1bab5:000B57FFFEB1BAB5_1_dimmer - unlinked
2022-10-03 07:40:21.946 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 000B57FFFEB1BAB5: Not polling zigbee:device:c3cd543626:000b57fffeb1bab5:000B57FFFEB1BAB5_1_colortemperature - unlinked

So this confirms what I thought - that the core seems to be reporting that these channels are not linked. I checked that up until my change today, there was no change to this code in the binding for 1.5 years when there were some changes to the way the core managed the link reporting. It's possible that at this time something else changed and I think there's an error there so I'll make another change in a few minutes and we can see if that solves the issue.

weakfl commented 1 year ago

@cdjackson I've seen #777 has already been merged. Should I test the latest build or is something else required?

EDIT: NVM, seems the PR was just related to logging. Sorry for the noise.

cdjackson commented 1 year ago

Yes, please try this out. The PR has no change to logging - just a change to code.

weakfl commented 1 year ago

Yes, please try this out. The PR has no change to logging - just a change to code.

Unfortunately still the same result @cdjackson: openhab.log.zip

cdjackson commented 1 year ago

Please provide a log with the latest binding - I've just changed a little bit of logging.

weakfl commented 1 year ago

@cdjackson I will once a new build is available, #3118 failed to build.

cdjackson commented 1 year ago

I'm not sure what happened with the build, but it seems ok now.

weakfl commented 1 year ago

Thanks Chris.

With the latest build polling seems to be working again, so thanks for that as well. Some devices still go offline, but only very briefly and come back online with the next polling almost immediately.

Here's a debug log in case you're interested: openhab.log.zip

I consider the issue resolved, so feel free to close unless you want to make some follow-up changes.

cdjackson commented 1 year ago

Thanks. I'll close this then.