Unifi Integration: Clients stuck Away

mkmer commented 4 years ago

The problem

After upgrading past 105.5, my clients become randomly move to "away" state and are stuck there until the client actually disconnects, or I restart Home Assistant. I have tried every version up to 107.7. Some are worse than others, but the issue remains in all versions after 105.5.

I'm suspect of clients roaming/disconnecting and reconnecting very quickly as the source of the issue. I see several unfi controller log events where the client first shows disconnected then shows roamed to another access point, without a "connect" event. This behavior is also present while running 105.5 and does not appear to cause trouble.

Environment

arch	x86_64
dev	false
docker	true
hassio	false
os_name	Linux
os_version	5.3.0-18-generic
python_version	3.7.7
version	0.107.7
virtualenv	false

Frontend version: 20200318.1 - latest

Unifi controller: Current Version 5.12.66 (Build: atag_5.12.66_13102)

Home Assistant release with the issue: 106.0 -> 107.7
Last working Home Assistant release (if known): 105.5
Operating environment (Hass.io/Docker/Windows/etc.): Docker
Integration causing this issue: Unifi
Link to integration documentation on our website: https://www.home-assistant.io/integrations/unifi

Problem-relevant `configuration.yaml`

Using the integration via the web page setup, no YAML config for Unifi.

Traceback/Error logs

Additional information

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

Hey there @kane610, mind taking a look at this issue as its been labeled with a integration (unifi) you are listed as a codeowner for? Thanks!

Kane610 commented 4 years ago

Are all your access points unifi APs?

mkmer commented 4 years ago

Yes, it's a full on unifi solution :) 2 switches, 2 AP, 1 USG.

I'm VERY suspicious of the events where the controller shows "disconnected" then the very next event is "roam", with no "connect" event. It appears that every time I see this type of event, HA shows that client as away until they disconnect/connect. It's not a problem in HA 0.105.5 (I've switch back for now).

Kane610 commented 4 years ago

I changed the whole backend from polling all data to push over websocket. But there have been so many issues that I will revert to a polling implementation which has worked well for a long time

mkmer commented 4 years ago

Well - V0.107.7 was the most stable I've had since 0.105.5 - I'd say you're really close... It was stable enough for me to figure out the event sequence hanging things up, at least in my configuration. Maybe you can get push notifications for the roaming events to trigger a "home" event just like a "connect" event?

kylehendricks commented 4 years ago

Also have been having this issue, probably for the same amount of time. I wonder if this is only an issue with setups that have multiple APs?

Kane610 commented 4 years ago

Could you enable debug for unifi in hass and share logs when this happens?

Maes152 commented 4 years ago

Happened to my wife last night. Screenshot

HASS noted her as Away from 03:18 AM. Only at 08:36, when her phone apparently reconnected to the wifi, did HASS note her as Home. In reality the phone was on the wifi the whole time. What looks weird to me is that the unifi log says she roams from one AP to another 15 min after it says she disconnected. That shouldn't be possible.

Does your integration read / interpret the log? Or do you simply grab the states from the controller? This has happened to me during the day as well and I was able to see that even though the log says she disconnected, the clients overview does show her as active.

I have used Domoticz in the past for over 5 years with a bash script that just grabbed the states and used grep to filter out clients. In all that time we have never seen an erroneous home/away state.

I'll paste the code down here, maybe it will help you.

Click

Kane610 commented 4 years ago

I will revert the implementation to a polling solution since web socket obviously doesn't work

mkmer commented 4 years ago

I'm not sure I'd say it "doesn't work" - it appears that there is some sort of bug in the controller where it declares a device "disconnected" - then declares it "roaming to different AP" without a "connect" event.
Not knowing anything about the API, just saying.... any event about a device other than disconnect should probably change the state of the device to "home". Maybe that's not possible?

Kane610 commented 4 years ago

Ok, I'll look at adding roaming events to keep device marked as at home

Maes152 commented 4 years ago

I don't think that will solve the problem. In my screenshot in the previous post you can clearly see there are 15 minutes between the disconnect event and the roaming event. To my understanding that is probably a lot more than anyone has set as the buffer in HASS. Besides, who says it can't be more than those 15 minutes?

Kane610 commented 4 years ago

Ok, can you share proper debug logs from hass with UniFi integration debug enabled and point out where in the log this issue appears

Maes152 commented 4 years ago

Alright. With the risk of looking a total noob. I'm quite new to Home Assistant. If I put this in my configuration.yaml that should be enough, right?

logger:
  default: debug
  logs:
    homeassistant.components.unifi: debug

Kane610 commented 4 years ago

logger:
  default: info
  logs:
    aiounifi: debug
    homeassistant.components.unifi: debug

Kane610 commented 4 years ago

preferrably you disable everything else to not have unnecessary stuff in the logs

Maes152 commented 4 years ago

I can't disable anything else unfortunately. It's a production system and if something stops working my wife will destroy me and tear apart my permission slip for unnecessarily over complicating everything that should just work in a house. Like automatic roller blinds and lights.

Might be a while before you hear from me. I can't force these unifi events to happen but it usually happens at least once a day.

kylehendricks commented 4 years ago

Not sure if this helps but devices are immediately going to not_home when I restart even though both phones in the house are connected to the wifi. I saw these logs as my wife's phone moved between AP's but I'm still seeing her as not_home.


2020-04-08 16:58:16 DEBUG (MainThread) [aiounifi.websocket] { "data" : [ { "_id" : "5e8e3ae8e4b08a37d17ffd66" , "ap_from" : "YY:YY:YY:YY:YY:YY" , "ap_to" : "ZZ:ZZ:ZZ:ZZ:ZZ:ZZ" , "channel" : "8" , "channel_from" : "11" , "channel_to" : "8" , "datetime" : "2020-04-08T20:58:15Z" , "key" : "EVT_WU_Roam" , "msg" : "User[XX:XX:XX:XX:XX:XX] roams from AP[YY:YY:YY:YY:YY:YY] to AP[ZZ:ZZ:ZZ:ZZ:ZZ:ZZ] from \"channel 11(ng)\" to \"channel 8(ng)\" on \"hen\"" , "radio" : "ng" , "radio_from" : "ng" , "radio_to" : "ng" , "site_id" : "SITE_ID_XXXXX" , "ssid" : "hen" , "subsystem" : "wlan" , "time" : 1586379495654 , "user" : "XX:XX:XX:XX:XX:XX"}] , "meta" : { "message" : "events" , "rc" : "ok"}}
2020-04-08 16:58:26 DEBUG (MainThread) [aiounifi.websocket] { "data" : [ { "_id" : "5e8e3af0e4b08a37d17ffd67" , "ap" : "ZZ:ZZ:ZZ:ZZ:ZZ:ZZ" , "ap_name" : "Living Room" , "datetime" : "2020-04-08T20:58:24Z" , "key" : "EVT_AP_Notification" , "msg" : "AP[ZZ:ZZ:ZZ:ZZ:ZZ:ZZ] event: { \"assoc_delta\" : \"160000\" , \"assoc_status\" : \"0\" , \"auth_delta\" : \"0\" , \"auth_ts\" : \"11235292.891029\" , \"dns_resp_seen\" : \"yes\" , \"event_id\" : \"1\" , \"event_type\" : \"soft failure\" , \"ip_assign_type\" : \"roamed\" , \"mac\" : \"XX:XX:XX:XX:XX:XX\" , \"message_type\" : \"STA_ASSOC_TRACKER\" , \"vap\" : \"ath0\" , \"wpa_auth_delta\" : \"200000\"}" , "payload" : "{ \"assoc_delta\" : \"160000\" , \"assoc_status\" : \"0\" , \"auth_delta\" : \"0\" , \"auth_ts\" : \"11235292.891029\" , \"dns_resp_seen\" : \"yes\" , \"event_id\" : \"1\" , \"event_type\" : \"soft failure\" , \"ip_assign_type\" : \"roamed\" , \"mac\" : \"XX:XX:XX:XX:XX:XX\" , \"message_type\" : \"STA_ASSOC_TRACKER\" , \"vap\" : \"ath0\" , \"wpa_auth_delta\" : \"200000\"}" , "site_id" : "SITE_ID_XXXXX" , "subsystem" : "wlan" , "time" : 1586379504806}] , "meta" : { "message" : "events" , "rc" : "ok"}}```

Kane610 commented 4 years ago

@kylehendricks logs please

kylehendricks commented 4 years ago

here's all the unifi logs after a fresh restart. All device_tracker's are showing not_home.

Edit: Sorry, I was trying to grep out unifi logs but realized some of the logs are multiline so a lot of the aiounifi logs are missing.

2020-04-08 16:53:09 INFO (MainThread) [homeassistant.setup] Setup of domain unifi took 0.7 seconds.
2020-04-08 16:53:11 DEBUG (MainThread) [aiounifi.api] [{'_id': '59dd4eb2e4b0d91b20d5b11c',
2020-04-08 16:53:11 DEBUG (MainThread) [aiounifi.api] [{'_id': '59dd4ddce4b0d91b20d5b10a',
2020-04-08 16:53:11 DEBUG (MainThread) [aiounifi.api] [{'_id': '59dd4e2ae4b0d91b20d5b10e',
2020-04-08 16:53:11 DEBUG (MainThread) [aiounifi.api] [{'_id': '59dd2adfe4b0b2e16ed2c4f2',
2020-04-08 16:53:11 DEBUG (MainThread) [aiounifi.controller] [{'_id': 'SITE_ID',
2020-04-08 16:53:11 DEBUG (MainThread) [aiounifi.websocket] Websocket starting
2020-04-08 16:53:11 INFO (MainThread) [homeassistant.components.device_tracker] Setting up device_tracker.unifi
2020-04-08 16:53:11 INFO (MainThread) [homeassistant.components.switch] Setting up switch.unifi
2020-04-08 16:53:11 DEBUG (MainThread) [homeassistant.components.unifi.unifi_client] New UniFi client -MBP (ac:bc:32:99:ae:45)
2020-04-08 16:53:11 DEBUG (MainThread) [homeassistant.components.unifi.unifi_client] New UniFi client samsung-printer (00:15:99:85:a3:3c)
2020-04-08 16:53:11 DEBUG (MainThread) [homeassistant.components.unifi.unifi_client] New UniFi client espressif (30:ae:a4:1c:93:20)
2020-04-08 16:53:11 DEBUG (MainThread) [homeassistant.components.unifi.unifi_client] New UniFi client 's Pixel XL (40:4e:36:25:69:1b)
2020-04-08 16:53:11 DEBUG (MainThread) [homeassistant.components.unifi.unifi_client] New UniFi client LTAD0013 (ac:ed:5c:35:43:69)
2020-04-08 16:53:11 DEBUG (MainThread) [homeassistant.components.unifi.unifi_client] New UniFi client smoke_alarm (30:ae:a4:26:8f:38)
2020-04-08 16:53:11 DEBUG (MainThread) [homeassistant.components.unifi.unifi_client] New UniFi client Ecobee (44:61:32:ce:34:a3)
2020-04-08 16:53:11 DEBUG (MainThread) [homeassistant.components.unifi.unifi_client] New UniFi client Google-Home-Mini (44:07:0b:b4:1d:fb)
2020-04-08 16:53:11 DEBUG (MainThread) [homeassistant.components.unifi.unifi_client] New UniFi client Garage Door Opener (64:52:99:5a:d2:cd)
2020-04-08 16:53:11 DEBUG (MainThread) [homeassistant.components.unifi.unifi_client] New UniFi client  (3c:28:6d:2e:e4:9f)
2020-04-08 16:53:11 DEBUG (MainThread) [homeassistant.components.unifi.unifi_client] New UniFi client basement_sensor (30:ae:a4:12:c2:28)
2020-04-08 16:53:11 DEBUG (MainThread) [homeassistant.components.unifi.unifi_client] New UniFi client Sump Sensor (30:ae:a4:02:8a:48)
2020-04-08 16:53:11 DEBUG (MainThread) [homeassistant.components.unifi.unifi_client] New UniFi client iPad (04:52:f3:8c:e1:f8)
2020-04-08 16:53:11 DEBUG (MainThread) [homeassistant.components.unifi.unifi_client] New UniFi client  (64:b5:c6:b4:c0:68)
2020-04-08 16:53:11 DEBUG (MainThread) [homeassistant.components.unifi.unifi_client] New UniFi client rockrobo (50:ec:50:1c:36:6a)
2020-04-08 16:53:11 DEBUG (MainThread) [homeassistant.components.unifi.unifi_client] New UniFi client QCA4002 (04:4e:af:81:a4:a5)
2020-04-08 16:53:11 DEBUG (MainThread) [homeassistant.components.unifi.unifi_client] New UniFi client IotaWatt (84:f3:eb:26:91:4f)
2020-04-08 16:53:11 DEBUG (MainThread) [homeassistant.components.unifi.device_tracker] New UniFi device tracker Living Room (f0:9f:c2:a3:f2:3c)
2020-04-08 16:53:11 DEBUG (MainThread) [homeassistant.components.unifi.device_tracker] New UniFi device tracker Garage (74:83:c2:89:0d:d7)
2020-04-08 16:53:11 DEBUG (MainThread) [aiounifi.websocket] Websocket running
2020-04-08 16:53:11 INFO (MainThread) [homeassistant.components.sensor] Setting up sensor.unifi
2020-04-08 16:58:16 DEBUG (MainThread) [homeassistant.components.unifi.unifi_client] Updating client device_tracker.pixel_xl 40:4e:36:25:69:1b
2020-04-08 16:58:16 DEBUG (MainThread) [aiounifi.websocket] { "data" : [ { "_id" : "5e8e3ae8e4b08a37d17ffd66" , "ap_from" : "74:83:c2:89:0d:d7" , "ap_to" : "f0:9f:c2:a3:f2:3c" , "channel" : "8" , "channel_from" : "11" , "channel_to" : "8" , "datetime" : "2020-04-08T20:58:15Z" , "key" : "EVT_WU_Roam" , "msg" : "User[40:4e:36:25:69:1b] roams from AP[74:83:c2:89:0d:d7] to AP[f0:9f:c2:a3:f2:3c] from \"channel 11(ng)\" to \"channel 8(ng)\" on \"MY_SSID\"" , "radio" : "ng" , "radio_from" : "ng" , "radio_to" : "ng" , "site_id" : "SITE_ID" , "ssid" : "MY_SSID" , "subsystem" : "wlan" , "time" : 1586379495654 , "user" : "40:4e:36:25:69:1b"}] , "meta" : { "message" : "events" , "rc" : "ok"}}
2020-04-08 16:58:26 DEBUG (MainThread) [aiounifi.websocket] { "data" : [ { "_id" : "5e8e3af0e4b08a37d17ffd67" , "ap" : "f0:9f:c2:a3:f2:3c" , "ap_name" : "Living Room" , "datetime" : "2020-04-08T20:58:24Z" , "key" : "EVT_AP_Notification" , "msg" : "AP[f0:9f:c2:a3:f2:3c] event: { \"assoc_delta\" : \"160000\" , \"assoc_status\" : \"0\" , \"auth_delta\" : \"0\" , \"auth_ts\" : \"11235292.891029\" , \"dns_resp_seen\" : \"yes\" , \"event_id\" : \"1\" , \"event_type\" : \"soft failure\" , \"ip_assign_type\" : \"roamed\" , \"mac\" : \"40:4e:36:25:69:1b\" , \"message_type\" : \"STA_ASSOC_TRACKER\" , \"vap\" : \"ath0\" , \"wpa_auth_delta\" : \"200000\"}" , "payload" : "{ \"assoc_delta\" : \"160000\" , \"assoc_status\" : \"0\" , \"auth_delta\" : \"0\" , \"auth_ts\" : \"11235292.891029\" , \"dns_resp_seen\" : \"yes\" , \"event_id\" : \"1\" , \"event_type\" : \"soft failure\" , \"ip_assign_type\" : \"roamed\" , \"mac\" : \"40:4e:36:25:69:1b\" , \"message_type\" : \"STA_ASSOC_TRACKER\" , \"vap\" : \"ath0\" , \"wpa_auth_delta\" : \"200000\"}" , "site_id" : "SITE_ID" , "subsystem" : "wlan" , "time" : 1586379504806}] , "meta" : { "message" : "events" , "rc" : "ok"}}
2020-04-08 17:04:16 DEBUG (MainThread) [aiounifi.websocket] { "data" : [ { "_id" : "5e8e3c4de4b08a37d17ffd6b" , "ap" : "74:83:c2:89:0d:d7" , "ap_name" : "Garage" , "datetime" : "2020-04-08T21:04:13Z" , "key" : "EVT_AP_Notification" , "msg" : "AP[74:83:c2:89:0d:d7] event: { \"assoc_status\" : \"0\" , \"event_id\" : \"3\" , \"event_type\" : \"sta_leave\" , \"mac\" : \"40:4e:36:25:69:1b\" , \"message_type\" : \"STA_ASSOC_TRACKER\" , \"vap\" : \"ath0\"}" , "payload" : "{ \"assoc_status\" : \"0\" , \"event_id\" : \"3\" , \"event_type\" : \"sta_leave\" , \"mac\" : \"40:4e:36:25:69:1b\" , \"message_type\" : \"STA_ASSOC_TRACKER\" , \"vap\" : \"ath0\"}" , "site_id" : "SITE_ID" , "subsystem" : "wlan" , "time" : 1586379853732}] , "meta" : { "message" : "events" , "rc" : "ok"}}
2020-04-08 17:06:26 DEBUG (MainThread) [aiounifi.websocket] { "data" : [ { "_id" : "5e8e3cd0e4b08a37d17ffd6f" , "ap" : "f0:9f:c2:a3:f2:3c" , "ap_name" : "Living Room" , "datetime" : "2020-04-08T21:06:24Z" , "key" : "EVT_AP_Notification" , "msg" : "AP[f0:9f:c2:a3:f2:3c] event: { \"assoc_delta\" : \"0\" , \"assoc_status\" : \"0\" , \"auth_delta\" : \"0\" , \"auth_ts\" : \"0.0\" , \"dns_resp_seen\" : \"yes\" , \"event_id\" : \"1\" , \"event_type\" : \"fixup\" , \"ip_assign_type\" : \"dhcp\" , \"ip_delta\" : \"-1995397296\" , \"mac\" : \"3c:28:6d:2e:e4:9f\" , \"message_type\" : \"STA_ASSOC_TRACKER\" , \"vap\" : \"ath3\" , \"wpa_auth_delta\" : \"10000\"}" , "payload" : "{ \"assoc_delta\" : \"0\" , \"assoc_status\" : \"0\" , \"auth_delta\" : \"0\" , \"auth_ts\" : \"0.0\" , \"dns_resp_seen\" : \"yes\" , \"event_id\" : \"1\" , \"event_type\" : \"fixup\" , \"ip_assign_type\" : \"dhcp\" , \"ip_delta\" : \"-1995397296\" , \"mac\" : \"3c:28:6d:2e:e4:9f\" , \"message_type\" : \"STA_ASSOC_TRACKER\" , \"vap\" : \"ath3\" , \"wpa_auth_delta\" : \"10000\"}" , "site_id" : "SITE_ID" , "subsystem" : "wlan" , "time" : 1586379984356}] , "meta" : { "message" : "events" , "rc" : "ok"}}
2020-04-08 17:08:26 DEBUG (MainThread) [aiounifi.websocket] { "data" : [ { "_id" : "5e8e3d49e4b08a37d17ffd70" , "ap" : "f0:9f:c2:a3:f2:3c" , "ap_name" : "Living Room" , "datetime" : "2020-04-08T21:08:25Z" , "key" : "EVT_AP_Notification" , "msg" : "AP[f0:9f:c2:a3:f2:3c] event: { \"arp_reply_gw_seen\" : \"yes\" , \"assoc_status\" : \"0\" , \"auth_ts\" : \"0.0\" , \"dns_resp_seen\" : \"yes\" , \"event_id\" : \"1\" , \"event_type\" : \"fixup\" , \"mac\" : \"3c:28:6d:2e:e4:9f\" , \"message_type\" : \"STA_ASSOC_TRACKER\" , \"vap\" : \"ath3\"}" , "payload" : "{ \"arp_reply_gw_seen\" : \"yes\" , \"assoc_status\" : \"0\" , \"auth_ts\" : \"0.0\" , \"dns_resp_seen\" : \"yes\" , \"event_id\" : \"1\" , \"event_type\" : \"fixup\" , \"mac\" : \"3c:28:6d:2e:e4:9f\" , \"message_type\" : \"STA_ASSOC_TRACKER\" , \"vap\" : \"ath3\"}" , "site_id" : "SITE_ID" , "subsystem" : "wlan" , "time" : 1586380105186}] , "meta" : { "message" : "events" , "rc" : "ok"}}

Kane610 commented 4 years ago

Can you share your full log privately?

mkmer commented 4 years ago

OK - I've spent some time "hacking" on the Unifi_client.py - I'm by no means an expert in this... (added imports & such as needed...)

Line 28: WIRELESS_CLIENT = (WIRELESS_CLIENT_CONNECTED, WIRELESS_CLIENT_DISCONNECTED,WIRELESS_CLIENT_ROAM)

and Line 72: (self.client.event.event == WIRELESS_CLIENT_CONNECTED) or (self.client.event.event == WIRELESS_CLIENT_ROAM)

Adding the ROAM event to "connected" appears to have fixed all of my "client away" issues...

Kane610 commented 4 years ago

@mkmer thanks! I will add that

Kane610 commented 4 years ago

@kylehendricks it does indeed look like the same issue mkmer mentions, clients roaming between APs. This will be fixed for 0.109

Kane610 commented 4 years ago

@Maes152 lets start by adding the roaming event and we can see how it affects you

mkmer commented 4 years ago

On more note: This is found in aiounifi/events.py WIRELESS_CLIENT_ROAM = "EVT_WC_Roam"

The log file shows it as: WIRELESS_CLIENT_ROAM = "EVT_WU_Roam"

I had also changed this in order to get the whole thing working more consistently.

Kane610 commented 4 years ago

Fix is now a part of HASS dev branch. Don't expect it to be included prior to 0.109. Please try it out

GatoPharaoh commented 4 years ago

@Kane610 just a quick feedback. I‘ve been running #33942 for three days as well as #34067 for the past 24 hours. No issues so far - device tracking seems to work perfectly again. No false marking when roaming or on non-unifi APs.

Kane610 commented 4 years ago

@GatoPharaoh thanks for the feedback and trying out the fixes!

bastienvans commented 4 years ago

Just leaving my $0.02.

I recently started having the issue of clients sticking to away mode.

This happened after I introduced a USG in my setup. I had been running 2 UniFi APs with ISP router for over a year with no issues. Adding an USG seem to break everything. Maybe something worth looking into.

Cheers.

mkmer commented 4 years ago

@Kane610 - Following up from my side too: Clients continue to function normally with the fix #33942 in place.

One "strange" side effect I'm still seeing are 2 - 3 second "away" states on the apple clients on my network (Android clients do not appear to have this behavior). Even with the away timer set to 2 minutes. The Unifi controller event log does not have disconnect times > 2 minutes for these clients, yet the history shows ~2 second away events.

mkmer commented 4 years ago

@Kane610 - I may have missed one spot where it should be looking at the WIRELESS_CLIENT_ROAM. Not sure.

controller.py Line 157:

elif signal == "new_data" and data:
    if "event" in data:
        if data["event"].event in (
            WIRELESS_CLIENT_CONNECTED,
            WIRELESS_GUEST_CONNECTED,
            **WIRELESS_CLIENT_ROAM,**
        ):
            self.update_wireless_clients()

mkmer commented 4 years ago

I think my short away problem is related to the wired bug - picking through the code, it looks like the system will declare a client away immediately if it's detecting the wired bug, regardless of the timeout setting. I'm sure @Kane610 understands this better than me, and I may just be reading implementation incorrectly. I suspect (for some reason) my apple devices are poking the wired bug. Maybe there is a way to see in the log file if the wired bug is being triggered?

Kane610 commented 4 years ago

@Kane610 - I may have missed one spot where it should be looking at the WIRELESS_CLIENT_ROAM. Not sure.
controller.py Line 157:
elif signal == "new_data" and data:
    if "event" in data:
        if data["event"].event in (
            WIRELESS_CLIENT_CONNECTED,
            WIRELESS_GUEST_CONNECTED,
            **WIRELESS_CLIENT_ROAM,**
        ):
            self.update_wireless_clients()

That is only to keep track of wireless devices in order to avoid the wired bug. Roaming is not needed there since it is either wireless or wired.

Kane610 commented 4 years ago

I think my short away problem is related to the wired bug - picking through the code, it looks like the system will declare a client away immediately if it's detecting the wired bug, regardless of the timeout setting. I'm sure @Kane610 understands this better than me, and I may just be reading implementation incorrectly. I suspect (for some reason) my apple devices are poking the wired bug. Maybe there is a way to see in the log file if the wired bug is being triggered?

It could be that the controller reports it as disconnecting from wireless before going the wired state, so it is not necessarily the wired bug but rather the change from polling to pushing . Still the detection timer shouldn't mark it as disconnected 🤔

mkmer commented 4 years ago

I've done some more research on this - It appears that when a client disconnects/connects rapidly multiple times (as seen on the unifi controller log), HA will show the client Home -> away -> Home where the away is on the order of 3 to 4 seconds. The series of connect/disconnects are always 2 disconnect/connect pairs within 1 minute. This happens even with the integration timeout set to 120 or 180 seconds.

I was suspicious of a race condition now that you have changed to event base triggers. One of the changes I tried was in the device tracker call back - confirming that the client is still disconnected when the call back sets the client disconnected. Still problem still occurs.

I'm thinking there is some time delay between setting, clearing, setting the async calls to start and stop the timer trigger... I'm not familiar with how the calls are processed.

Additionally, I tried commenting out the wired bug fix code just to see if that was the source for short away - but it also made no difference.

With all that said - I don't have a solution, but I can say what didn't fix it :)

IT is covered by having delay times on my automations, it's more of an annoyance at this point.

mkmer commented 4 years ago

@kane610: This is VERY strange. I have added logging elements to the device_tracker.py to log connect and disconnect scheduled and disconnect events in an attempt to figure this out.

How the heck did the client become "away" without executing the "is_connected" code in device tracker?

"Short event" 17:57:26 the client changed to "away" 17:57:32 the client changed to "home"

The log file shows no disconnect event until 17:57:31: 2020-04-16 17:56:53 DEBUG (MainThread) [homeassistant.components.unifi.device_tracker] Updating UniFi tracked device device_tracker.libbys_iphone connected 2020-04-16 17:57:05 DEBUG (MainThread) [homeassistant.components.unifi.device_tracker] Updating UniFi tracked device device_tracker.libbys_iphone connected 2020-04-16 17:57:07 DEBUG (MainThread) [homeassistant.components.unifi.device_tracker] Updating UniFi tracked device device_tracker.libbys_iphone connected 2020-04-16 17:57:20 DEBUG (MainThread) [homeassistant.components.unifi.device_tracker] Updating UniFi tracked device device_tracker.libbys_iphone connected

2020-04-16 17:57:31 DEBUG (MainThread) [homeassistant.components.unifi.device_tracker] Updating UniFi tracked device device_tracker.libbys_iphone disconnect scheduled ^^^^^^^ this event is the only disconnect logged... 2020-04-16 17:57:32 DEBUG (MainThread) [homeassistant.components.unifi.device_tracker] Updating UniFi tracked device device_tracker.libbys_iphone connected ^^^^^^^^^^^^^^^^this event made client switch to "home" 2020-04-16 17:57:35 DEBUG (MainThread) [homeassistant.components.unifi.device_tracker] Updating UniFi tracked device device_tracker.libbys_iphone connected

mkmer commented 4 years ago

OK - I guess I've found the cause - in device_tracker there is a section of code that is trying to filter clients that are not in the filter SSID list. For some reason, on calls to is_connected, the filter is triggering sometimes.
So - I don't have an in depth understanding of why/how the ESSID for the client is being cleared after a disconnect, but this piece of code is the cause of "short away" triggers for the clients.

@Kane610: any ideas why/how to fix it? if ( not self.is_wired and self.controller.option_ssid_filter and self.client.essid not in self.controller.option_ssid_filter ): LOGGER.debug("Updating UniFi tracked device %s:%s filtered!", self.entity_id, self.client.essid) return False

Resulting events: 2020-04-17 10:11:48 DEBUG (MainThread) [homeassistant.components.unifi.device_tracker] Updating UniFi tracked device device_tracker.mike_s_pixel disconnect scheduled 2020-04-17 10:14:13 DEBUG (MainThread) [homeassistant.components.unifi.device_tracker] Updating UniFi tracked device device_tracker.libbys_iphone: filtered! 2020-04-17 10:14:13 DEBUG (MainThread) [homeassistant.components.unifi.device_tracker] Updating UniFi tracked device device_tracker.libbys_iphone: filtered! 2020-04-17 10:14:18 DEBUG (MainThread) [homeassistant.components.unifi.device_tracker] Updating UniFi tracked device device_tracker.libbys_iphone disconnect scheduled 2020-04-17 10:14:43 DEBUG (MainThread) [homeassistant.components.unifi.device_tracker] Updating UniFi tracked device device_tracker.libbys_iphone disconnect scheduled 2020-04-17 10:14:46 DEBUG (MainThread) [homeassistant.components.unifi.device_tracker] Updating UniFi tracked device device_tracker.libbys_iphone: filtered!

Kane610 commented 4 years ago

Thanks for digging into it @mkmer, maybe that should make sure the essid is not blank?

home-assistant / core