ZHA Fan incorrect state on HA restart

[cgarwood]

Home Assistant release with the issue: 0.77

Last working Home Assistant release (if known): none

Operating environment (Hass.io/Docker/Windows/etc.): Ubuntu, Python 3.6 venv install

Component/platform: zha fan

Description of problem: When restarting Home Assistant, the state of all of my ZHA Zigbee fans shows as on regardless of if they are actually on or if they are actually off. My best guess is that it's not correctly polling the state of the fans when the component loads. My Zigbee fans are all the King of Fans zigbee modules. Not completely positive if this is a ZHA component issue, or an upstream zigpy issue. @rcloran ?

Problem-relevant configuration.yaml entries and (fill out even if it seems unimportant):

zha:
  usb_path: /dev/zigbee
  database_path: /home/hass/zigbee.db

Traceback (if applicable):

None

Additional information: N/A

[rcloran]

From a quick scan of the code, looks like this doesn’t poll at startup. @igorbernstein2 — should it?

[igorbernstein2]

I would think that update_before_add=True would trigger a poll on startup? https://github.com/home-assistant/home-assistant/blob/dev/homeassistant/components/fan/zha.py#L49

I'll try to find some time in the next week to reproduce the issue

[cgarwood]

Here's a pastebin of my HA log with debug logging. Starting HomeAssistant with all the fans off, and then turning one of them on. I have a few Xiaomi temperature sensors and a Hue light in my zha network as well. https://paste.ubuntu.com/p/N69X4MpmGP/ (paste expires in a month)

[cgarwood]

I added a couple debug lines to components/fans/zha.py. It looks like async_update is being called when it sets up the entities, with the following result:

018-09-04 18:33:42 DEBUG (MainThread) [homeassistant.components.fan.zha] zha fan async_update called
2018-09-04 18:33:42 DEBUG (MainThread) [homeassistant.components.fan.zha] zha fan async_update result: {'fan_mode': 1} :: fan.king_of_fans__inc_hdc52eastwindfan_0020ce42_1_514
2018-09-04 18:33:42 DEBUG (MainThread) [homeassistant.components.fan.zha] zha fan async_update called
2018-09-04 18:33:42 DEBUG (MainThread) [homeassistant.components.fan.zha] zha fan async_update result: {'fan_mode': 1} :: fan.king_of_fans__inc_hdc52eastwindfan_0020db24_1_514
2018-09-04 18:33:42 DEBUG (MainThread) [homeassistant.components.fan.zha] zha fan async_update called
2018-09-04 18:33:42 DEBUG (MainThread) [homeassistant.components.fan.zha] zha fan async_update result: {'fan_mode': 1} :: fan.king_of_fans__inc_hdc52eastwindfan_0020d023_1_514

async_update code is:

@asyncio.coroutine
    def async_update(self):
        """Retrieve latest state."""
        _LOGGER.debug('zha fan async_update called')
        result = yield from zha.safe_read(self._endpoint.fan, ['fan_mode'])
        _LOGGER.debug('zha fan async_update result: %s :: %s', result, self.entity_id)
        new_value = result.get('fan_mode', None)
        self._state = VALUE_TO_SPEED.get(new_value, None)

One thing to note, the entity_id that it returns is different from the entity_id stored in the entity_registry, and what the entity_id shows up as on the frontend after it's been setup.

I'm also seeing similar behavior with a hue light (showing as on after a HA restart, regardless of its actual physical state

[cgarwood]

I wonder if this is at all related? https://github.com/home-assistant/home-assistant/issues/14804

[cgarwood]

Further testing... Doesn't matter what speed the fan is set to, on HA restart it is showing a fan_mode of 1

I added a log line to log the results of yield from zha.safe_read(self._endpoint.fan, ['fan_mode']) in the async_set_speed() function (after setting the speed) and it is always returning 1 as well, no matter what the speed is set to. Quirk with the receiver not sending the correct value?

This is about the end of my Python and zigbee knowledge. Not sure how much more I'll be able to troubleshoot on my own, but I'm willing to run custom code/dev builds and give more debug logs, just let me know what you need.

[igorbernstein2]

I haven't had time to look at it yet, but one possibility is to try to read the value using the bellows cli client directly to see if the issue is in zigpy or home assistant:

https://github.com/zigpy/bellows

[cgarwood]

Not completely positive what I'm doing but here are the results I got on the FanControl (514) cluster for a fan that was turned off:

(home-assistant) hass@homeassistant:~$ bellows -d /dev/zigbee zcl 00:22:a3:00:00:20:ce:42 1 514 read_attribute 0
0=0
(home-assistant) hass@homeassistant:~$ bellows -d /dev/zigbee zcl 00:22:a3:00:00:20:ce:42 1 514 read_attribute 1
1=5
(home-assistant) hass@homeassistant:~$ bellows -d /dev/zigbee zcl 00:22:a3:00:00:20:ce:42 1 514 read_attribute 2
Attribute 2 not successful. Status=134
(home-assistant) hass@homeassistant:~$ bellows -d /dev/zigbee zcl 00:22:a3:00:00:20:ce:42 1 514 read_attribute 3
Attribute 3 not successful. Status=134

And this was for a fan that was turned on on medium speed:

(home-assistant) hass@homeassistant:~$ bellows -d /dev/zigbee zcl 00:22:a3:00:00:20:d0:23 1 514 read_attribute 0
0=2
(home-assistant) hass@homeassistant:~$ bellows -d /dev/zigbee zcl 00:22:a3:00:00:20:d0:23 1 514 read_attribute 1
1=5
(home-assistant) hass@homeassistant:~$ bellows -d /dev/zigbee zcl 00:22:a3:00:00:20:d0:23 1 514 read_attribute 2
Attribute 2 not successful. Status=134
(home-assistant) hass@homeassistant:~$ bellows -d /dev/zigbee zcl 00:22:a3:00:00:20:d0:23 1 514 read_attribute 3
Attribute 3 not successful. Status=134

Looks like attribute 0 is returning the correct information

[igorbernstein]

I've been able to reproduce the problem on both 0.70.1 and dev (0d7ee9b93ba1b2336eeee7122a3cfc66ca218e22)

I think the issue applies to all zha components: I see the same issue with a GE smart switch (45856GE) as well as the King of Fans controller. I think there is something wrong with zha's caching.

@cgarwood tell me if this fixes your problem (please note that this isn't a solution, but simply a diagnosis step):

Force allow_cache=False here:

https://github.com/home-assistant/home-assistant/blob/0d7ee9b93ba1b2336eeee7122a3cfc66ca218e22/homeassistant/components/zha/__init__.py#L433

[cgarwood]

@igorbernstein2 I tried forcing allow_cache=False in that file. On HA restart all of the fans now show as Off, regardless of if they are on or off now. On HA 0.78.0b1 so its running the latest build of zigpy/bellows.

[cgarwood]

OK, I restarted again this morning and it reported the correct values for the fan. And then just to try it out I restarted another time, and it's back to showing everything off.

I added more debugging statements to zha's safe_read so show when it's getting called and what it's returning, as well as to the async_update on the zha fan component so I can see when it gets called.

Here's the interesting log output for safe_read when it sets up the fan and tries to read the fan_mode (allow_cache=False):

018-09-12 08:44:29 INFO (MainThread) [homeassistant.components.fan] Setting up fan.zha
2018-09-12 08:44:29 INFO (MainThread) [homeassistant.components.fan] Setting up fan.zha
2018-09-12 08:44:29 INFO (MainThread) [homeassistant.components.fan] Setting up fan.zha
2018-09-12 08:44:29 DEBUG (MainThread) [homeassistant.components.zha] safe_read result: <zigpy.zcl.clusters.smartenergy.Metering object at 0x7fb918337198> :: [1024] :: {}
2018-09-12 08:44:29 DEBUG (MainThread) [homeassistant.components.zha] safe_read result: <zigpy.zcl.clusters.homeautomation.ElectricalMeasurement object at 0x7fb918337710> :: ['active_power'] :: {'active_power': 0}
2018-09-12 08:44:29 DEBUG (MainThread) [homeassistant.components.zha] safe_read exception: <zigpy.quirks.kof.KofOnOff object at 0x7fb91834bb38> :: ['on_off'] :: Message send failure EmberStatus.MAX_MESSAGE_LIMIT_REACHED
2018-09-12 08:44:29 DEBUG (MainThread) [homeassistant.components.zha] safe_read exception: <zigpy.zcl.clusters.measurement.TemperatureMeasurement object at 0x7fb91834bdd8> :: [0] :: Message send failure EmberStatus.MAX_MESSAGE_LIMIT_REACHED
2018-09-12 08:44:29 DEBUG (MainThread) [homeassistant.components.zha] safe_read exception: <zigpy.zcl.clusters.measurement.PressureMeasurement object at 0x7fb91834bef0> :: [0] :: Message send failure EmberStatus.MAX_MESSAGE_LIMIT_REACHED
2018-09-12 08:44:29 DEBUG (MainThread) [homeassistant.components.zha] safe_read exception: <zigpy.zcl.clusters.measurement.RelativeHumidity object at 0x7fb91834bf60> :: [0] :: Message send failure EmberStatus.MAX_MESSAGE_LIMIT_REACHED
2018-09-12 08:44:29 DEBUG (MainThread) [homeassistant.components.zha] safe_read exception: <zigpy.zcl.clusters.hvac.Fan object at 0x7fb91833dd30> :: ['fan_mode'] :: Message send failure EmberStatus.MAX_MESSAGE_LIMIT_REACHED
2018-09-12 08:44:29 DEBUG (MainThread) [homeassistant.components.fan.zha] fan async_update: {} fan.king_of_fans__inc_hdc52eastwindfan_0020ce42_1_514
2018-09-12 08:44:29 DEBUG (MainThread) [homeassistant.components.zha] safe_read exception: <zigpy.zcl.clusters.hvac.Fan object at 0x7fb91834b198> :: ['fan_mode'] :: Message send failure EmberStatus.MAX_MESSAGE_LIMIT_REACHED
2018-09-12 08:44:29 DEBUG (MainThread) [homeassistant.components.fan.zha] fan async_update: {} fan.king_of_fans__inc_hdc52eastwindfan_0020db24_1_514
2018-09-12 08:44:29 DEBUG (MainThread) [homeassistant.components.zha] safe_read exception: <zigpy.zcl.clusters.hvac.Fan object at 0x7fb91834bc18> :: ['fan_mode'] :: Message send failure EmberStatus.MAX_MESSAGE_LIMIT_REACHED
2018-09-12 08:44:29 DEBUG (MainThread) [homeassistant.components.fan.zha] fan async_update: {} fan.king_of_fans__inc_hdc52eastwindfan_0020d023_1_514
2018-09-12 08:44:29 DEBUG (MainThread) [homeassistant.components.zha] safe_read exception: <zigpy.quirks.kof.KofLevelControl object at 0x7fb91834bba8> :: ['current_level'] :: Message send failure EmberStatus.MAX_MESSAGE_LIMIT_REACHED
2018-09-12 08:44:29 DEBUG (MainThread) [homeassistant.components.zha] safe_read result: <zigpy.zcl.clusters.lighting.Color object at 0x7fb918337f60> :: ['color_capabilities'] :: {'color_capabilities': 31}
2018-09-12 08:44:29 DEBUG (MainThread) [homeassistant.components.zha] safe_read result: <zigpy.quirks.kof.KofOnOff object at 0x7fb91833dc50> :: ['on_off'] :: {'on_off': <Bool.false: 0>}

(some of the safe_read results may be for my Hue light, zigbee outlet, or xiaomi temp/humidity sensors)

All of the fan_mode read attempts are returning EmberStatus.MAX_MESSAGE_LIMIT_REACHED.

[cgarwood]

friendly bump to see if there are any ideas or other things i should troubleshoot :smiley:

[cytech]

i have the same issue with king of fans controller. the fan light state is reported properly but not the fan state after restart. with HA 0.79.3

[igorbernstein2]

Sorry, I've been busy and havent had a chance to debug this further. @cytech do you own other zigbee devices? if so, can you comment if they have the same issue?

[cytech]

i have 5 sengled bulbs, 1 cree bulb and 4 KOF fan controllers. all the bulbs , as well as the lights connected on the fan controllers, report state correctly on restart. it is just the 4 fan entities that do not report. right now i am getting around it by firing a script that checks the states and resets the fans to the current (or new) state. they then show up in the interface correctly. I am still trying to figure it out because I finally moved all the fans off of a wink hub to the new Ha zha fan.

[roofuskit]

I have multiple Sengled bulbs and a Centralite zigbee outlet that HA has the wrong state for upon restart. The ones that HA has the wrong state for all show on when off after a HA restart. Not all of my zigbee bulbs have this problem.

[Adminiuga]

19177 addresses this issue by enabling attribute reporting and making fan.zha to report its status back to hass

[Adminiuga]

This should be fixed in 0.86.1, but you need to "reconfigure" FAN device so it sends ZCL attribute updates. To do so, in HA UI navigate to configuration panel -> Zha panel, pick the node representing the FAN and click on Reconfigure Node. If successful, in home-assistant.log you should see something like:

2019-01-29 15:29:25 DEBUG (MainThread) [homeassistant.components.zha.api] Reconfiguring node with ieee_address: 00:22:a3:00:cc:dd:ee:ff
2019-01-29 15:29:25 DEBUG (MainThread) [homeassistant.components.zha.helpers] fan.mbr: bound  'fan' cluster: Status.SUCCESS
2019-01-29 15:29:25 DEBUG (MainThread) [homeassistant.components.zha.helpers] light.king_of_fans_inc_hbuniversalcfremote_ccddeeff_1: bound  'level' cluster: Status.SUCCESS
2019-01-29 15:29:25 DEBUG (MainThread) [homeassistant.components.zha.helpers] fan.mbr: reporting 'fan_mode' attr on 'fan' cluster: 5/900/1: Result: '[[<ConfigureReportingResponseRecord status=0 direction=0 attrid=0>]]'
2019-01-29 15:29:26 DEBUG (MainThread) [homeassistant.components.zha.entities.entity] fan.mbr: finished configuration

as long as you have debug logging enabled.