Open jat255 opened 1 year ago
Hey there @mdegat01, mind taking a look at this issue as it has been labeled with an integration (influxdb
) you are listed as a code owner for? Thanks!
(message by CodeOwnersMention)
influxdb documentation influxdb source (message by IssueLinks)
Hey there @jc2k, @bdraco, mind taking a look at this issue as it has been labeled with an integration (homekit_controller
) you are listed as a code owner for? Thanks!
(message by CodeOwnersMention)
homekit_controller documentation homekit_controller source (message by IssueLinks)
It might not be an auto resubscribing but when the connection drops and reconnects.
Will need to find the time to look into this.
In that case I'd expect the fallback polling to kick in I think?
Could do with seeing the full log instead of excerpts.
@Jc2k I don't feel comfortable positing the full log publicly. Is there somehow I can send it to you?
The main thing I want to verify right now is that you see log entries like this once a minute:
2023-10-18 01:03:50.927 DEBUG (MainThread) [aiohomekit.controller.ip.connection] xxx.xxx.30.113: raw request: b'GET /characteristics?id=1.272,1.262,1.1027,1.259,1.261,1.1026,1.260,1.263 HTTP/1.1\r\nHost: xxx.xxx.30.113\r\n\r\n'
2023-10-18 01:03:51.059 DEBUG (MainThread) [aiohomekit.controller.ip.connection] xxx.xxx.30.113: raw response: bytearray(b'{"characteristics":[{"aid":1,"iid":272,"value":35},{"aid":1,"iid":262,"value":25.5},{"aid":1,"iid":1027,"value":0},{"aid":1,"iid":259,"value":0},{"aid":1,"iid":261,"value":21.9},{"aid":1,"iid":1026,"value":0},{"aid":1,"iid":260,"value":0},{"aid":1,"iid":263,"value":1}]}')
2023-10-18 01:03:51.059 DEBUG (MainThread) [homeassistant.components.homekit_controller.connection] Called async_set_available_state with True for 93:A8:5B:xx:xx:xx
It must be a GET and return a response like this once.
Or do you see an exception once a minute.
(Or even twice a minute).
Yes, if I grep for that IP or identifier over the ten minutes following (from 01:03 to 01:14), I see plenty of successful log entries corresponding to the thermostat's current data:
I am a bit baffled about how influx could see data that HA can't. Does the "current value" in HA change?
There is a temperature sensor entity and a temperature attribute on the climate entity. Are they both not updating?
I am a bit baffled about how influx could see data that HA can't.
Yes, I don't understand that either. It's almost like HA is processing the data received, but not storing it. The "current value" does not change (currently says 35% for humidity):
vs. what I see in Grafana/Influx (35%):
Or in the Mysa app directly, where it currently reads 34%
There is a temperature sensor entity and a temperature attribute on the climate entity. Are they both not updating?
Correct, both are not updating.
So the log entries I told you to look at, I noticed this repeats:
{"aid":1,"iid":272,"value":35}
I believe that's your humidity, and it's not changing in the data returned by the device.
Can you confirm that Iid 272 isn't changing in your logs and is currently showing the wrong value.
You're correct, 272 is the current humidity, and 261 is the current temperature, as reported in the debug diagnostics:
...
{
"type": "00000011-0000-1000-8000-0026BB765291",
"iid": 261,
"perms": [
"pr",
"ev"
],
"format": "float",
"value": 20.2,
"description": "Current Temperature",
"unit": "celsius",
"minValue": -40,
"maxValue": 125,
"minStep": 0.1
},
....
{
"type": "00000010-0000-1000-8000-0026BB765291",
"iid": 272,
"perms": [
"pr",
"ev"
],
"format": "float",
"value": 34,
"description": "Current Relative Humidity",
"unit": "percentage",
"minValue": 0,
"maxValue": 100,
"minStep": 1
}
...
Here's the full data output from that thermostat in the logs (trimmed so it fits in a GH comment), from 1AM this morning to now. It properly shows the current humidity value of 33% (as of 2:41PM):
Following up on this with some additional insight, it appears that there are two different entities/states being tracked here, which I believe explains the discrepancy between what I was seeing in InfluxDB vs. HA.
If I look at the HVAC climate card I have for this thermostat, it shows the correct (current) temperature and humidity:
I have a chart on this same dashboard that is not updating.
This chart has the following definitions:
series:
- entity: sensor.mysa_xxxxxx_current_temperature
yaxis_id: first
name: Temperature
- entity: sensor.mysa_xxxxxx_current_humidity
yaxis_id: second
name: Humidity
- entity: climate.mysa_xxxxxx_thermostat
yaxis_id: first
attribute: temperature
name: Set point
unit: °F
I take this to mean the climate entity's attributes are getting updated (which is what I'm looking at in Influx), but the associated sensors (which are plotted in that chart) are not.
Indeed, if I look at those two entities in the HA history panel, I see the "climate" entity getting updated as expected (although in whole-digit increments, vs. 0.1 degree resolution for the sensors), while the "sensor" entity is stuck on 71.4 degrees since 1AM:
I believe these sensor entities (sensor.mysa_xxxxxx_current_temperature
and sensor.mysa_xxxxxx_current_humidity
) were created automatically by the integration, as I don't have any reference to them in any of my config files.
Does this provide any more clues as to what's going on?
Slight Tangent: For reasons I don't understand, the sensor.mysa_xxxxxx_current_humidity
and sensor.mysa_xxxxxx_current_temperature
sensors don't show up in Influx. Only climate.mysa_xxxxxx_thermostat
does, which is why I was plotting that rather than the sensor values. Any idea why this would be the case? I don't have any include
/exclude
entries in my InfluxDB integration config.
@Jc2k any ideas what could be causing this behavior?
Nope sorry.
Is there somewhere else I should look to figure out what's happening? Somewhere I can add some debugging code or another integration to change the log level for?
I believe the homekit integration added those sensors that aren't being updated properly, but I haven't a clue where to start looking.
My only hunch right now is that we've only ever seen it for cases where the same characteristic UUID in homekit is consumed by multiple entities. That's a pretty gnarly area of the code base to dive in.
Next months release has quite a bit of cleanup and some of it impacts how data is dispatched from the bit of the code we can see fetching the current value to the actual entities. I am curious if any of that accidentally fixes it.
In the meantime I will try and find some time to look at places where you could add logging.
I faced a similar issue with some Eve devices. Let me try set-up InfluxDB and see if I could reproduce.
There hasn't been any activity on this issue recently. Due to the high number of incoming GitHub notifications, we have to clean some of the old issues, as many of them have already been resolved with the latest updates. Please make sure to update to the latest Home Assistant version and check if that solves the issue. Let us know if that works for you by adding a comment 👍 This issue has now been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.
This is still an active issue on an up to date HA installation, so should not be stale. I mostly use my grafana dashboards to look at this data as it's more reliable.
I am working around this issue by reloading my Eve Weather's (BLE) config entry every 15 minutes.
My only hunch right now is that we've only ever seen it for cases where the same characteristic UUID in homekit is consumed by multiple entities. That's a pretty gnarly area of the code base to dive in.
I think I saw this on the Aqara Video Doorbell G4 where the Mute entity comes through 3 or 4 times. Of course, it works fine in HomeKit itself.
There hasn't been any activity on this issue recently. Due to the high number of incoming GitHub notifications, we have to clean some of the old issues, as many of them have already been resolved with the latest updates. Please make sure to update to the latest Home Assistant version and check if that solves the issue. Let us know if that works for you by adding a comment 👍 This issue has now been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.
Still seeing the behavior on my end
I am also experiencing this
Occurring on
Core 2024.7.2 Supervisor 2024.06.2 Operating System 12.4 Frontend 20240710.0
There hasn't been any activity on this issue recently. Due to the high number of incoming GitHub notifications, we have to clean some of the old issues, as many of them have already been resolved with the latest updates. Please make sure to update to the latest Home Assistant version and check if that solves the issue. Let us know if that works for you by adding a comment 👍 This issue has now been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.
Still happening on my end
The problem
I originally started this as a forum posting, which contains some additional information.
Fundamentally, the issue is that a HomeKit thermostat (Mysa AC) sometimes stops logging state changes into Home Assistant, leading to charts that look like the following, where the values for temperature and humidity just stop:
Curiously, the device continues getting logged to a connected InfluxDB instance via the built-in
influxdb
integration, meaning I can see the updated values in a separate Grafana dashboard (notice the corresponding ramp up in humidity values between 11:30PM and 1:00 AM):With debug logging, I have tracked down the issue to a Homekit device that loses connection. Attached below are the HA logs filtered for this thermostat’s IP (xxx.xxx.30.113) and/or its identifier (93:A8:5B:xx:xx:xx). It appears that at 01:02:46, HA lost connection to the thermostat, but it then regained connection since it received data once again at 01:03:51.059, but those values (and all subsequent ones) are not saved into HA as state changes, even though they are sent to InfluxDB. So something about this “hiccup” causes it to stop logging entirely, even though it’s still receiving information.
Reloading the device via the integrations page appears to resolve the issue temporarily, until the next time the device times out:
Any ideas what's going on here?
What version of Home Assistant Core has the issue?
core-2023.10.1
What was the last working version of Home Assistant Core?
No response
What type of installation are you running?
Home Assistant Container
Integration causing the issue
homekit_controller
Link to integration documentation on our website
https://www.home-assistant.io/integrations/homekit_controller/
Diagnostics information
config_entry-homekit_controller-b475198185de7c629665b7429a54105a.json.txt
Example YAML snippet
No response
Anything in the logs that might be useful for us?
Additional information
No response