Aqara motion and vibration sensors not triggering with 2022.3.1

justindotcloud commented 2 years ago

The problem

Hi,

Yesterday I updated to Release 2022.3.1 and immediately noticed that the Aqara motion and vibration sensor with the HomeKit Controller integration don't work anymore. They are still available and connected to HA, but the sensor don't report when being triggered. I reverted to a snapshot of Release 2022.3.0 and the sensors just work fine again. So I hold of from updating right now.

Is this a known issue and/or is there a fix for this?

Justin

What version of Home Assistant Core has the issue?

2022.3.1

What was the last working version of Home Assistant Core?

2022.3.0

What type of installation are you running?

Home Assistant OS

Integration causing the issue

HomeKit Controller with Aqara sensors

Link to integration documentation on our website

https://www.home-assistant.io/integrations/homekit_controller/

Diagnostics information

No response

Example YAML snippet

No response

Anything in the logs that might be useful for us?

No response

Additional information

No response

probot-home-assistant[bot] commented 2 years ago

homekit_controller documentation homekit_controller source _{^{(message by IssueLinks)}}

probot-home-assistant[bot] commented 2 years ago

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)}}

nimbling commented 2 years ago

Just chiming in: I had this too but on 3.0, had to revert to my 2.9 backup for them to start working again.

osono-design commented 2 years ago

Same here, they stopped working with 2022.3.0 and work fine with 2022.2.9

Jc2k commented 2 years ago

Can I just check you guys are all using Aqara? I use an E1 hub and the latest March HA release and events are still working for me. They are also working with Hue. So there's going to be an environmental element to this we need to figure out.

Can you also confirm that polling works and that turning some on/off works?

I'm going to need logs, with the aiohomekit component set to debug.

Someone providing the diagnostics file the issue asks for would be good too.

osono-design commented 2 years ago

Yes, using Aqara Motion sensors. They work fine through Xiaomi Gateway (Aqara) but do not show any motion when connected through HomeKit Controller. Will try to create logs and diagnostics.

ibreek commented 2 years ago

Can I just check you guys are all using Aqara? I use an E1 hub and the latest March HA release and events are still working for me. They are also working with Hue. So there's going to be an environmental element to this we need to figure out.

Can you also confirm that polling works and that turning some on/off works?

I'm going to need logs, with the aiohomekit component set to debug.

Someone providing the diagnostics file the issue asks for would be good too.

I'm using the Aqara M2 hub (in Home Assistant seen as the Homekit integration) and in the Aqara app all my sensors (door/window, button, vibration, motion, temp/hum and TVOC) are working just fine but in Home Assistant all is working fine except the motion and vibration sensors.

In Home Assistant the status of these sensors is continuously 'off'

This has been this way for me since 2022.3.0 See https://github.com/home-assistant/core/issues/67524#issue-1157974984

justindotcloud commented 2 years ago

I have 100% exactly the same setup and behaviour as @ibreek describes. I'm currently upgrading again to collect logs and diagnostics.

Jc2k commented 2 years ago

Sorry I'm replying on my phone at the moment so I may be a bit terse.

Please make sure to be clear about homekit_controller vs homekit, they are very different integrations. And i need to be sure we are talking about HA speaking HomeKit to Aqara, not an iOS device speaking HomeKit to Home Assistant.

The other linked issue was tagged against another integration so has been sent to a completely different team to triage. So this is the first time I'm hearing about it. It also references a similar issue against a third unrelated integration (zha).

So I'm hearing door contacts work but motion events don't. I only have door contacts to test with on Aqara, so that is probably a factor. Though my Hue HomeKit_controller motion sensors work fine, and it's the same code that is used for both.

I'm at a bit of a loss why door contacts would work but motion sensors don't. The event mechanism is the same for every single HomeKit characteristic. The big risk factor for regressions is motion sensors disappearing entirely or events not working entirely.

There was a bug where Aqara sensors would iirc generate motion events when there was no motion. They acknowledged the bug and presumably fixed it, so I doubt that is related. But its interesting to me as its not the first time we've had a weird Aqara bug specific to the motion sensors.

I'm not going to be able to progress this one without log data I think.

osono-design commented 2 years ago

config_entry-homekit_controller-5409f449e48cc72d12d1ae75b92d5991.json (1).txt

I set logger to homeassistant.components.homekit: debug but no specific logs are created, I am afraid.

osono-design commented 2 years ago

I can confirm it is HA speaking HomeKit to Aqara. And it is only the motion sensors which do not provide data, another temp / humidity sensor linked to the same Mi Smart Hub is showing correct data.

Jc2k commented 2 years ago

So homekit_controller uses a hybrid polling and events setup so that it remains as useful as possible should events be unreliable (buggy device, bad network, regression, etc).

That's important because we need to figure out whether temperature/humidity is working because of polling or because of events.

The fact that is working at all proves that we were able to find your device on the network (I believe the Aqara rolls it's port fairly frequently so working zeroconf is really important for this vendor). It proves we were able to "login" (exchanging per session keys) and read from the device.

I believe someone said the motion sensors do appear, and show "off" rather than unavailable.

That's good because it proves enumeration is working and that we can still see the motion sensor in the API. That really narrows things down.

What I really need is for someone to conclusively say - my contact sensor state in HA updates immediately as expected, without any delay.

Or they need to heat their temperature up and see how quickly it reacts. But a negative test result there is less useful, we know that vendors often introduce delays on temperature data to conserve battery life.

Jc2k commented 2 years ago

The correct components to turn on logging for are:

homeassistant.components.homekit_controller aiohomekit

The 2nd will be the most important for fixing this.

Jc2k commented 2 years ago

Oh and it has to be DEBUG level.

justindotcloud commented 2 years ago

Thanks for your swift replies @Jc2k. I'll try to answer all your questions and provide the debug logs you need. Some details on my setup used:

Home Assistant OS 2022.3.1
Aqara M2 Hub
HomeKit Controller integration
Aqara motion, vibration, contact and temperature sensors used

The HomeKit Controller Integration is talking directly to the Aqara M2 Hub, there is no iOS integration in between. The motion and vibration sensors stopped working. Contact and temperature sensors still work as expected.

I believe someone said the motion sensors do appear, and show "off" rather than unavailable.

That is correct. The motion sensors appear and have a "clear" state set when starting HA. In the integration page they keep showing the clear state and battery life. However, motion doesn't change the state from "clear" to "detected".

What I really need is for someone to conclusively say - my contact sensor state in HA updates immediately as expected, without any delay.

I tested an Aqara contact sensor (connected to the same Aqara M2 Hub) and it triggers immediately without any delays.

I've attached the debug log enabled for homeassistant.components.homekit_controller and aiohomekit. I restarted HA after enabling debug, and tried to trigger a motion sensor twice. After that generated to log output attached.

I hope this sheds some light on the issue. Please reach out if I can provide you with more details.

Justin

home-assistant.log

osono-design commented 2 years ago

log.txt

Thank you Jc2K for your efforts!

I can confirm that motion sensor state is set to off and does not change to on despite motion (motion is shown in Mi Home App). I can also confirm that the temperature sensor is updating immediately.

Jc2k commented 2 years ago

Thank you! Unfortunately I'm on child care for a couple of hours now but I'll get to this asap!

Jc2k commented 2 years ago

I have had a quick look over and nothing immediately stands out. I can see event subscription happening (the requests with "ev": true in them). And I can see polling working.

There is a fail safe where events are disabled if the device is failing to start with them on. I can see that mode is not triggered.

There aren't any exceptions I can see either.

Justin, one of your devices is reporting errors when polled. I was hoping it was the cause but I can't see an error in the other log. Can you confirm if you know which device is offline?

When I can be at my desk I need to go through the diagnostic data and find the iid for the motion sensor, then look for that iid in the log. One option is that we aren't subscribing to motion events for some reason, and that's what I need to confirm or rule out next.

justindotcloud commented 2 years ago

Justin, one of your devices is reporting errors when polled. I was hoping it was the cause but I can't see an error in the other log. Can you confirm if you know which device is offline?

Yes, that will be the vibration sensor. I tried to pair it again and see if it would help. At the time of generating the logs I provided, the sensor was briefly in an unavailable state. I've paired the sensor again, which works. The sensor immediately appears in HA and is available. However, triggering the sensor still doesn't change the sensor state in HA unfortunately.

osono-design commented 2 years ago

Probably not relevant but what I also noted is that with 2022.3 new entities for motion sensors with "Motion Sensor Identify" have been created (see also my diagnostic file) and I could not find out what this was for. They do not exist in 2022.2

Jc2k commented 2 years ago

Thats a new feature and unrelated. It should make the device light up or make a noise. It's so when you have lots of the same device (like motion sensors) you can tell which is which.

boheme61 commented 2 years ago

{ "trace": { "last_step": "action/0", "run_id": "42a914f1172548ea8aa12113a3cb449c", "state": "stopped", "script_execution": "finished", "timestamp": { "start": "2022-03-03T23:53:31.296179+00:00", "finish": "2022-03-03T23:53:31.315635+00:00" }, "domain": "automation", "item_id": "1639439236100", "trigger": null, "trace": { "trigger": [ { "path": "trigger", "timestamp": "2022-03-03T23:53:31.296299+00:00", "changed_variables": { "this": { "entity_id": "automation.new_automation_2", "state": "on", "attributes": { "last_triggered": "2022-03-03T23:43:06.001792+00:00", "mode": "single", "current": 0, "id": "1639439236100", "friendly_name": "Turn on OfficeLight" }, "last_changed": "2022-03-03T23:39:07.290166+00:00", "last_updated": "2022-03-03T23:43:06.021085+00:00", "context": { "id": "c98aabb6b51934a0a908ad1a64eff8a1", "parent_id": "88286d06f8887e4ca71be7ccc5e205c7", "user_id": null } }, "trigger": { "platform": null } } } ], "action/0": [ { "path": "action/0", "timestamp": "2022-03-03T23:53:31.298403+00:00", "changed_variables": { "context": { "id": "bd1ee6f75deaf2eb196032425eb4660b", "parent_id": "5581cb51faf87027197ba97249a9eaaa", "user_id": null } } } ] }, "config": { "id": "1639439236100", "alias": "Turn on OfficeLight", "description": "", "trigger": [ { "type": "motion", "platform": "device", "device_id": "9989923a1675323a26bc957e14e8f1f5", "entity_id": "binary_sensor.motion_office", "domain": "binary_sensor" } ], "condition": [ { "alias": "Sun down", "condition": "state", "entity_id": "sun.sun", "state": "below_horizon" } ], "action": [ { "type": "turn_on", "device_id": "28ae9fcf3d37147f5df933d2d55d3339", "entity_id": "light.d1", "domain": "light" } ], "mode": "single" }, "blueprint_inputs": null, "context": { "id": "bd1ee6f75deaf2eb196032425eb4660b", "parent_id": "5581cb51faf87027197ba97249a9eaaa", "user_id": null } }, "logbookEntries": [ { "name": "Turn on OfficeLight", "message": "has been triggered", "source": null, "entity_id": "automation.new_automation_2", "context_id": "bd1ee6f75deaf2eb196032425eb4660b", "when": "2022-03-03T23:53:31.296533+00:00", "domain": "automation" } ] }

boheme61 commented 2 years ago

im in timezone +1 , all my system-settings like-vice,

Jc2k commented 2 years ago

Hello, thank you for that. I'm only able to help with homekit_controller issues. That looks like something from an automation. I am working several layers below that so it is unfortunately not that useful for me.

Jc2k commented 2 years ago

@osono-design so i compared your diagnostic data and logs. In your diagnostics data I see:

              {
                "type": "00000022-0000-1000-8000-0026BB765291",
                "iid": 269,
                "perms": [
                  "pr",
                  "ev"
                ],
                "format": "bool",
                "value": 0,
                "description": "Motion Detected"
              }

This is completely as expected. Here is the same output from my Hue motion sensor which works:

                                    {
                                        "iid": 162,
                                        "type": "00000022-0000-1000-8000-0026BB765291",
                                        "format": "bool",
                                        "value": 0,
                                        "perms": [
                                            "pr",
                                            "ev"
                                        ],
                                    },

Crucially (a) the UUID is identical (so theres no device specific bug like lower case vs upper case) and (b) it has "ev" permissions. That means it should try to subscribe to events.

On this motion sensor device the iid is 269. Earlier in the file i noted your iid was 2 for this particular motion sensor.

In the log i can see:

2022-03-04 11:32:03 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.86.31: raw request: b'PUT /characteristics HTTP/1.1\r\nHost: 192.168.86.31\r\nContent-Length: 51\r\nContent-Type: application/hap+json\r\n\r\n{"characteristics":[{"aid":2,"iid":269,"ev":true}]}'

I.e. it tries to turn events on for the motion detected characteristic. So it was correctly enumerated and we tried to get event data for it.

There are some duplicate requests. For the devices I own these seem to be harmless, and I believe it's always done that, but it is definitely a point of interest.

As far as i can tell from these logs the request to enable events worked. There was no error returned. The connection wasn't interupted.

So far everything looks correct and normal, the device just doesn't send us any events.

Ordinarily i'd try to blame the device about now. I'd suggest a bad firmware upgrade, and coincidental timing. BUT you can fix it just by downgrading HA, which rules that out!

@osono-design What I'd like to do next is get the same logs but for 2022.2.9 if possible. I want to see the same PUT requests, and i'd like to see what happens in the logs when you trigger motion.

Jc2k commented 2 years ago

@justindotcloud it would also be good to see your diagnostic data so i can make the same comparisons as above, and also see the same logs for 2022.2.9 too. Cheers.

boheme61 commented 2 years ago

I am working several layers below that so it is unfortunately not that useful for me.

Timestamps with +timezone .... is several levels below !, i was not "Highlighting" an automation .... just saying

boheme61 commented 2 years ago

DEVICE-INFO JSON

"device": { "name": "Motion Sensor", "model": "MS002", "manfacturer": "Mi", "sw_version": "11", "hw_version": "1.0", "entities": [ { "original_name": "Motion Sensor", "original_device_class": "motion", "entity_category": null, "original_icon": null, "icon": "mdi:motion-sensor", "unit_of_measurement": null, "device_class": "motion", "disabled": false, "disabled_by": null, "state": { "entity_id": "binary_sensor.motion_office", "state": "off", "attributes": { "device_class": "motion", "icon": "mdi:motion-sensor", "friendly_name": "Motion Office" }, "last_changed": "2022-03-04T12:10:01.908848+00:00", "last_updated": "2022-03-04T12:10:01.908848+00:00"

Jc2k commented 2 years ago

Thank you for your trying to help.

homekit_controller does not use timestamps, most homekit devices do not know what time it is.

At the moment I am interested in the complete diagnostic data from config entries in the UI (it needs to have iid data or its not useful) and i'm interested in log data at startup with debug turned on for aiohomekit for 2022.2.9 AND 2022.3.0.

Log data at the time of trying to trigger a motion event is also useful, but right now I am trying to make sure there wasn't a regression in how event subscriptions are written to the device.

osono-design commented 2 years ago

Thank you @Jc2k for your support! Here are diagnostics and log from 2022.2.9:

config_entry-homekit_controller-5409f449e48cc72d12d1ae75b92d5991.json (2).txt log2022_2_9.txt

boheme61 commented 2 years ago

Thank you for your trying to help.

homekit_controller does not use timestamps, most homekit devices do not know what time it is.

ok, well i did had/might still have a startup-debug, from yesterday , didn't find anything useful in that, and i spend most day, yesterday, didn't find anything pointing towards "Homekit-Controller" I will step-out, thx for the job and effort with this "integration"

boheme61 commented 2 years ago

My notes on "Timestamp"

2022-03-03 15:55:42 DEBUG (MainThread) [homeassistant.components.automation.new_automation_2] Loaded automation automation.new_automation_2 with state True from state storage last state <state automation.new_automation_2=on; last_triggered=2022-03-02T17:36:23.167471+00:00, mode=single, current=0, id=1639439236100, friendly_name=Turn on OfficeLight @ 2022-03-03T15:19:59.017174+01:00>

2022-03-03 15:55:42 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=automation.new_automation_2, old_state=None, new_state=<state automation.new_automation_2=on; last_triggered=2022-03-02T18:36:23.167471+01:00, mode=single, current=0, id=1639439236100, friendly_name=Turn on OfficeLight @ 2022-03-03T15:55:42.173668+01:00>>

PS: I know im a stubborn AH, but same "same last_triggered , with different timestamp, might be confusing in "some" core-component, or "top-layer" automation PS_2: i believe first is with 2022.3, and the last from "after rollback to 2022.2.9"

justindotcloud commented 2 years ago

@justindotcloud it would also be good to see your diagnostic data so i can make the same comparisons as above, and also see the same logs for 2022.2.9 too. Cheers.

Thanks again @Jc2k for your time and effort.

I did a fresh restart and fetched the log and diagnostic data with 2022.2.9. Then updated to 2022.3.1 and did the same. Both output files of these two versions. Hope this provides some clarity.

Grtz, Justin

config_entry-homekit_controller-d89362ce1c325095a5b9fa29b367d4d0-2022.2.9.json.txt config_entry-homekit_controller-d89362ce1c325095a5b9fa29b367d4d0-2022.3.1.json.txt home-assistant-2022.2.9.log home-assistant-2022.3.1.log

Jc2k commented 2 years ago

I've ordered an Aqara motion sensor so I can debug this.

In the meantime, it would be good to see a log of you trying to trigger the motion sensor on both versions. As well as the existing log configuration, add homeassistant.core: debug to the mix.

I only need to see the events, not the startup this time.

To make sure the log is valid it would be good if we could see a "working" event (like a contact sensor) before and after trying to trigger the motion sensor.

Annoyingly it doesn't look like we log the raw event, so we are probably going to have to edit the code to add some extra logging after this. Is that something anyone feels up to?

justindotcloud commented 2 years ago

In the meantime, it would be good to see a log of you trying to trigger the motion sensor on both versions. As well as the existing log configuration, add homeassistant.core: debug to the mix.

I only need to see the events, not the startup this time.

To make sure the log is valid it would be good if we could see a "working" event (like a contact sensor) before and after trying to trigger the motion sensor.

Alright, so I did the test you outlined above @Jc2k. These are the steps I took to get the output attached:

While running 2022.2.9 I disabled all Aqara sensors, except 1 contact sensor and 1 vibration sensor (which has the same non-functional behaviour as the motion sensors) to remove any noise from the logs
Added homeassistant.core: debug to the logger and restarted HA
Waited until HA fully loaded all components
Triggered the contact sensor, waited a few seconds and triggered the vibration sensor
Collected logs from the timeframe I triggered the sensors.
Updated HA to 2022.3.1
Repeated step 3, 4 and 5.

I'll try to do some digging in the logs as well to see if I can spot any differences.

config_entry-homekit_controller-d89362ce1c325095a5b9fa29b367d4d0-2022.2.9.json.txt config_entry-homekit_controller-d89362ce1c325095a5b9fa29b367d4d0-2022.3.1.json.txt home-assistant-2022.2.9.log home-assistant-2022.3.1.log

Jc2k commented 2 years ago

Brilliant, thank you so much!

justindotcloud commented 2 years ago

No worries! 🙂

justindotcloud commented 2 years ago

On thing that I noticed already is that log entries for binary_sensor.vibration_sensor do not even appear in in HA 2022.3.1 which might be a result of the issue as well. But it's not helpful. I might do a second run of the actions to be absolutely sure I didn't miss the log entry after triggering the sensor.

Jc2k commented 2 years ago

So the 2022.2.9 logs coincidentally capture a poll:

2022-03-04 17:18:15 DEBUG (MainThread) [homeassistant.components.homekit_controller.connection] Starting HomeKit controller update: 0A:03:85:8D:1B:FB
2022-03-04 17:18:15 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.207: raw request: b'GET /characteristics?id=49.327685,1.1114117,1.1048580,1.1114116,37.327684,37.262147,1.1048579,49.327684,49.262147,37.327683,49.327683,37.327685 HTTP/1.1\r\nHost: 192.168.1.207\r\n\r\n'
2022-03-04 17:18:15 DEBUG (MainThread) [aiohomekit.controller.ip.connection] 192.168.1.207: raw response: bytearray(b'{"characteristics":[{"aid":49,"iid":327685,"value":0},{"aid":1,"iid":1114117,"value":0},{"aid":1,"iid":1048580,"value":3},{"aid":1,"iid":1114116,"value":0},{"aid":37,"iid":327684,"value":2},{"aid":37,"iid":262147,"value":0},{"aid":1,"iid":1048579,"value":3},{"aid":49,"iid":327684,"value":2},{"aid":49,"iid":262147,"value":0},{"aid":37,"iid":327683,"value":100},{"aid":49,"iid":327683,"value":100},{"aid":37,"iid":327685,"value":0}]}')
2022-03-04 17:18:15 DEBUG (MainThread) [homeassistant.components.homekit_controller.connection] Called async_set_available_state with True for 0A:03:85:8D:1B:FB
2022-03-04 17:18:15 DEBUG (MainThread) [homeassistant.components.homekit_controller.connection] Finished HomeKit controller update: 0A:03:85:8D:1B:FB

There isn't one in the march logs. We can ignore that.

But we can see the juicy bits:

2022-03-04 17:18:53 DEBUG (MainThread) [homeassistant.components.homekit_controller.connection] Called async_set_available_state with True for 0A:03:85:8D:1B:FB
2022-03-04 17:18:53 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=binary_sensor.vibration_sensor, old_state=<state binary_sensor.vibration_sensor=off; device_class=motion, friendly_name=Vibration Sensor @ 2022-03-04T17:16:18.665929+01:00>, new_state=<state binary_sensor.vibration_sensor=on; device_class=motion, friendly_name=Vibration Sensor @ 2022-03-04T17:18:53.619627+01:00>>

And we can see the contact sensor too:

2022-03-04 17:18:45 DEBUG (MainThread) [homeassistant.components.homekit_controller.connection] Called async_set_available_state with True for 0A:03:85:8D:1B:FB
2022-03-04 17:18:45 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=binary_sensor.contact_sensor_refrigerator, old_state=<state binary_sensor.contact_sensor_refrigerator=off; device_class=opening, friendly_name=Contact Sensor refrigerator @ 2022-03-04T17:16:18.665086+01:00>, new_state=<state binary_sensor.contact_sensor_refrigerator=on; device_class=opening, friendly_name=Contact Sensor refrigerator @ 2022-03-04T17:18:45.721556+01:00>>

Now looking in the March logs we see:

2022-03-04 17:29:09 DEBUG (MainThread) [homeassistant.components.homekit_controller.connection] Called async_set_available_state with True for 0A:03:85:8D:1B:FB
2022-03-04 17:29:09 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=binary_sensor.contact_sensor_refrigerator, old_state=<state binary_sensor.contact_sensor_refrigerator=off; device_class=opening, friendly_name=Contact Sensor refrigerator @ 2022-03-04T17:27:35.769133+01:00>, new_state=<state binary_sensor.contact_sensor_refrigerator=on; device_class=opening, friendly_name=Contact Sensor refrigerator @ 2022-03-04T17:29:09.874688+01:00>>

For the contact sensor. As reported, we dont see a HA event for the vibration sensor.

What is interesting is this:

Called async_set_available_state with True for 0A:03:85:8D:1B:FB

That is called when ever we process some entity data that confirms the connection is up. So you see it when we poll, and you see it right before we process an event.

So what is interesting in the March log is this line:

2022-03-04 17:29:19 DEBUG (MainThread) [homeassistant.components.homekit_controller.connection] Called async_set_available_state with True for 0A:03:85:8D:1B:FB

Because its not near a confirmed event and its not near a poll. One option is that homekit_controller is processing an event, but its not making it to the state machine.

It's possible something else is calling async_set_available_state of course, so I could do with finding that out...

If i was able to modify your local installation there would be 2 experiments I would want to make. The first would be to change this function:

https://github.com/Jc2k/aiohomekit/blob/main/aiohomekit/controller/ip/connection.py#L569

I'd make it print out decoded on line 578.

https://github.com/home-assistant/core/blob/dev/homeassistant/components/homekit_controller/connection.py#L556

I think i'd do something like:

    def process_new_events(self, new_values_dict) -> None:
        """Process events from accessory into HA state."""
        _LOGGER.debug("Processing new homekit values: %s", new_values_dict)

        self.async_set_available_state(True) 
        .... snip

The 2nd one would be enough to confirm my theory.

justindotcloud commented 2 years ago

I tried the 2nd one @Jc2k, by adding _LOGGER.debug("Processing new homekit values: %s", new_values_dict) below line 558. First I triggered the contact sensor by disconnecting:

2022-03-04 18:53:12 DEBUG (MainThread) [homeassistant.components.homekit_controller.connection] Processing new homekit values: {(41, 262147): {'value': 1}}
2022-03-04 18:53:12 DEBUG (MainThread) [homeassistant.components.homekit_controller.connection] Called async_set_available_state with True for 0A:03:85:8D:1B:FB

and connecting again:

2022-03-04 18:53:14 DEBUG (MainThread) [homeassistant.components.homekit_controller.connection] Processing new homekit values: {(37, 262147): {'value': 0}}
2022-03-04 18:53:14 DEBUG (MainThread) [homeassistant.components.homekit_controller.connection] Called async_set_available_state with True for 0A:03:85:8D:1B:FB

Afterwards, I triggered the vibration sensor as well, which resulted in:

2022-03-04 18:57:01 DEBUG (MainThread) [homeassistant.components.homekit_controller.connection] Processing new homekit values: {(49, 262147): {'value': 1}}
2022-03-04 18:57:01 DEBUG (MainThread) [homeassistant.components.homekit_controller.connection] Called async_set_available_state with True for 0A:03:85:8D:1B:FB

I tried that twice to be sure, and the output was the same.

Jc2k commented 2 years ago

Was that the 2022.3.1 release?

justindotcloud commented 2 years ago

Sorry, forgot to mention. But yes, that's on the 2022.3.1 release.

boheme61 commented 2 years ago

Seems like there are a few of us using Aqara-hub, and as i know some device, like a hub or a cam have a default, factory setting(that u can change in APP, but not change the device software) so maybe that can explain the different "timezones" that seems to be present ... haven't found this in other "working" integrations.

And you do actually use timedate, not that i know it's related .... just learning, by logic :) , and these devices(Aqara m2) are "registered" with wrong timezone, in core.entity_registry ... Edit: maybe not all, as there are different "versions" china/eu etc.

connection.py

6 import datetime

36 from .device_trigger import async_fire_triggers, async_setup_triggers_for_entry 37 38 DEFAULT_SCAN_INTERVAL = datetime.timedelta(seconds=60) 39 RETRY_INTERVAL = 60 # seconds 40 MAX_POLL_FAILURES_TO_DECLARE_UNAVAILABLE = 3

anyway i still wonder why the Aqara-m2 is registered with timezone +00:00 ( haven't found other devices, in other integrations looking like this)

also line 6 " import datetime " , maybe that should be "from datetime import timedelta", for use in automation, and right timezone

boheme61 commented 2 years ago

https://github.com/home-assistant/core/issues/67702

PS: i know it's not the same integration ;)

Jc2k commented 2 years ago

My Aqara motion sensor just arrived. Cute little thing.

Found the root cause, and its completely unrelated to timezones so please stop posting about timezones. They cause a lot of problems, but this time it is not them. The "timedate" that you found is a duration. Durations are not timezone aware.

So a recap:

My motion sensors work (they are Hue)
It turns out that @justindotcloud's were still reporting events, but they were getting swallowed
So far no other reports for non homekit_controller motion sensors
Rolling back to 2022.2.9 fixes it.

Without knowing anything else this sets the scene for a homekit_controller specific bug that is related to a vendor quirk. A reminder - some of these quirks are things like vendors not being able to parse JSON correctly (choking on whitespace, or boolean values).

In the last release cycle I did some work to make homekit_controller more PEP 484 strict. This is hard to add retrospectively if your API's were not designed with it in mind, so sometimes you have to change code to make it work.

One of the bits of code that changed in the last cycle was this:

    @property
    def is_on(self) -> bool:
        """Has motion been detected."""
        return self.service.value(CharacteristicsTypes.MOTION_DETECTED) is True

In theory this is fine, MOTION_DETECTED is a bool. So theres no reason to suspect a bug here. And indeed, for the test motion sensors I have it worked fine.

And even though we have 100's of unittests, the motion sensor ones follow the spec.

Unfortunately the Aqara returns 1 for True and 0 for False. The previous code accidentally worked because 0 is considered False and anything else was considered True.

I'm on child care right now but i'll have a think about the best way to fix this without removing the PEP 484 stuff. I should have a PR in for it today or first thing tomorrow.

justindotcloud commented 2 years ago

Great catch @Jc2k 💪 And thanks again for your time and effort.

Jc2k commented 2 years ago

https://github.com/home-assistant/core/pull/67740 should fix it. I've tagged it for consideration for the next point release. So hopefully it will be in 2022.3.2, but might slip to 2022.3.3 if I have missed the window.

boheme61 commented 2 years ago

I know im "quite" new to HA, and only had Homekit-Controller, since October ... Flawless, 8 temp/humid, 3 motion, removed 2(due to "unreliable" data from temp/humid ... and the upgrade to 2022.3 just caused that i had to work(walk) 3m, to hit the switch(for the light :) , if it wasn't for "those" bug-reports(4-5now) ( in various reported quality) , i had ignored it ... i have to be better to "ignore buzz" :) Thx for a great Integration ;) PS: For whom it concern, seems like the +00:00 is present in " component.websocket_api.http.connection" and obviously in "components.automation/component.tracker/etc." on some "level" "replaced/converted with "friendly_name" @

czyrichard commented 2 years ago

After updating to HA v2022.3.3, the motion sensors refresh rate has become extremely slow. In the Mi Home app, whenever my motion sensors are triggered, the app shows the log immediately. However, it takes HA almost half a minute for the motion sensor status to change from "clear" to "detected". I'm not sure whether other fellows have encountered similar issues, but for now I have to roll back to 2022.2.9.

Jc2k commented 2 years ago

That certainly sounds like instead of the event working you are falling back to polling. That is indeed about half a minute refresh interval.

We've had a few reports that the .2 release fixed this, and the motion sensor I got to test this also works with .2.

So either a regression in .3 (which shouldn't contain any HomeKit changes as I haven't done any homekit fixes since this one) or this is a different bug specific to your environment. Maybe a second bug that only impacts your hardware or firmware combination.

I'll need to see your logs and diagnostic data from 2022.3.3 so I can reproduce the debug steps I did above. I'll also need you to confirm whether it's limited to motion and vibration sensors updating.

home-assistant / core