Presence is flapping - Githubissues

MHedish commented 4 years ago

I installed the Docker image and have everything configured. BTW -- I love the idea here! Thanks!

I'm monitoring four different wireless devices and they are all bouncing from present to not present every 30 seconds.

---- 8< ---- Date	Source	Type	Name	Value	User	Displayed Text
2020-01-14 5:59:33.965 PM EST	DEVICE		presence	present		Marc is present

Something's not quite right in the logic.

Unifi Presence.xlsx

xtreme22886 commented 4 years ago

Hi @MHedish, thanks for checking this out and glad you like the idea :).

I'm only reporting on data provided by the Unifi Controller so I'm curious to know which data is causing the flapping.. There are a few things we can do to try and figure out what is going on.

Check out http://:9443/monitoring . This URL will show your the 'monitoring.json' file with all the devices you are currently monitoring and their current status. This file gets updated every 5 seconds (when monitoring is active) so keep refreshing the page and see if the 'present' value keeps flapping here as well.
The logs you are showing, is that for the specific device you are monitoring? Can you please log into the SmartThings IDE and go to 'Live Logging'. Check the logs for 'Unifi Wireless Presence'. We are looking for a debug entry that reads, "Received the following presence update(s):". I'm curious to see if, when and how often they are occurring.
Log into your Unifi Controller and go to the clients section. Make sure you are viewing all wired and wireless clients. Put the display view into icon view instead of list view. Use the search filter in upper right side to filter your devices' mac address. This way, we are looking at only your device in the Unifi Controller. Now look at the icon of this device. While the Unifi thinks it's wireless, you should see a wireless symbol in the upper right corner of the icon for your device. In my experience, when I turn off wifi on my device, one of two things will happen: 1) my device will disappear, 2) my device will still be there but the wireless icon on my device will disappear and it'll show as if it's wired. Let's see what yours is doing. I'd be curious to see if it's flapping on the Unifi Controller.
Since you are logged into the Unifi Controller, you can view the data I'm looking at by browsing to: https://<unifi-controller-ip:8443/api/s/default/stat/user/xx:xx:xx:xx:xx:xx (mac address of device). I'm looking at the 'isWired' and 'last_seen' values to determine if a device is 'on' the network or 'off' the network.
And lastly, view the terminal of the Docker container that is running. It should be refreshing the output every 5 seconds if it's monitoring devices. Here you'll see when the bridge sends an update to SmartThings.

Check these things out and let me know if you find anything out.

MHedish commented 4 years ago

I'll check it out and let you know what I find.

I did a little more hunting around and can tell you that if it is monitoring a device (wireless) that I know isn't present, it doesn't flap. The status correctly shows as present.

Thanks for the quick response. More logs coming your way.

xtreme22886 commented 4 years ago

Thanks for the update! Yeah, I'm seeing a few oddities now but they seem random / not consistent. Let me keep looking at this as well and see what comes up. Thanks for letting me know of this issue!

MHedish commented 4 years ago

1: "Ron's phone" isn't here so it should always report false. "MHOKVOVEN1" is my IoT enabled wall oven; iI's not going anywhere. Should always report true

{ "monitoring": [ { "name": "rons-iphone (a3:db)", "mac": "50:a6:7f:13:a3:db", "id": "unifi-a3:db", "present": false, "last_check": 1579048559 }, { "name": "MHOKVOVEN1 (16:34)", "mac": "d8:28:c9:17:16:34", "id": "unifi-16:34", "present": false, "last_check": 1579048559 } ] } { "monitoring": [ { "name": "rons-iphone (a3:db)", "mac": "50:a6:7f:13:a3:db", "id": "unifi-a3:db", "present": false, "last_check": 1579048584 }, { "name": "MHOKVOVEN1 (16:34)", "mac": "d8:28:c9:17:16:34", "id": "unifi-16:34", "present": true, "last_check": 1579048584 } ] } { "monitoring": [ { "name": "rons-iphone (a3:db)", "mac": "50:a6:7f:13:a3:db", "id": "unifi-a3:db", "present": false, "last_check": 1579048624 }, { "name": "MHOKVOVEN1 (16:34)", "mac": "d8:28:c9:17:16:34", "id": "unifi-16:34", "present": false, "last_check": 1579048624 } ] }

2: Those logs were from the IDE under the (Device) events. Per your request, here is the data from the live log:

Seems the updates are working as expected. Every 30 seconds +/- 5 seconds.

3.

Here's the oven. It's wireless: (BTW it shows a little over a day connected because I just did a rolling firmware update on my devices yesterday to 4.0.80.10875).

My phone does indeed show wireless.

When I manually turn off wi-fi, it disappears from the icon grid. When I turn wi-fi back on, it reappears as wireless.

4. ["oui":"GeneralE","is_guest":false,"first_seen":1534249416,"last_seen":1579050165,"is_wired":false,"hostname":"WICED DHCP Client","name":"MHOKVOVEN1","note":"GE Cafe CT9550SH5SS"

["oui":"GeneralE","is_guest":false,"first_seen":1534249416,"last_seen":1579050407,"is_wired":false,"hostname":"WICED DHCP Client","name":"MHOKVOVEN1","note":"GE Cafe CT9550SH5SS"

["oui":"GeneralE","is_guest":false,"first_seen":1534249416,"last_seen":1579050525,"is_wired":false,"hostname":"WICED DHCP Client","name":"MHOKVOVEN1","note":"GE Cafe CT9550SH5SS"

["oui":"GeneralE","is_guest":false,"first_seen":1534249416,"last_seen":1579050589,"is_wired":false,"hostname":"WICED DHCP Client","name":"MHOKVOVEN1","note":"GE Cafe CT9550SH5SS"

"is_wired" doesn't seem to be changing.

5.

All of the data handlers seem to be doing their job.

xtreme22886 commented 4 years ago

Hey @MHedish, thanks for all the information you provided!. I think I may know what is causing this flapping. Can you do me a favor? I update one thing in my Unifi Bridge so I re-built the Docker image. Can you test out the new image? I think these would be the steps:

Delete existing Docker container
Delete existing Docker image
Re-download Docker image
Create new container using new image
Open the 'Unifi Wireless Presence' SmartApp and click 'Save'. By clicking save, it'll update the new Docker container with information about your Unifi Controller and what to monitor.

That should get things back up and running with the new Docker image and hopefully the issue resolved.

Here is what I did.

The Unifi Controller appears to only update the 'last_seen' value once every 20 seconds.
My Bridge was checking this value and if it was greater than 30 seconds, it would report offline (this matches up with your logs and what you've been seeing)
Since the Unifi Controller only updates that value once every 20 seconds and I was looking for 30 seconds, it allowed a 'not present' state to be triggered. I updated my value I'm looking for to 45 seconds which would allow the Unifi Controller two refreshes. Hopefully this will do it.

Let me know how things go!

MHedish commented 4 years ago

No joy. :(

1-14-2020 11-22-09 PM

I actually deleted the image and container twice just to be sure nothing was cached.

Bump it out to 90 seconds to see if it works and log the heck out of it? Then bring it back down to a more rational number after we check the logs for what the controller is doing?

I'd be interest to see what the values here are:

        isWired = macStats['is_wired'] # If wireless device shows wired, it means it's offline. Stupid Unifi
        lastSeen = macStats['last_seen'] # Get 'Last Seen' epoch time
        timeNow = int(time.time()) # Get current epoch time
        timeDiff = timeNow - lastSeen # Get time elasped since 'Last Seen' in seconds
        if isWired == False: # Bug in Unifi Controller has 'last_seen' time updating even after device has left the network. If a wireless device is now showing 'wired' then it's a good indication that it has left the network
            if timeDiff > 45: # If time since 'last_seen' is greater than 45 seconds, consider the device not present
                results.append({'mac': mac, 'present': False}) # Append results of presence check to results list
            else:
                results.append({'mac': mac, 'present': True}) # Append results of presence check to results list
        else:
            results.append({'mac': mac, 'present': False}) # Append results of presence check to results list

xtreme22886 commented 4 years ago

You got it, logging coming right up! The section you outlined is the only section that would be effecting the status so you've hit the nail on the head 👍. I'm going to be logging 'thresholdLastSeen' so we know what the controller is checking against. And I'll be logging the 'timeDiff' for each mac we are checking.

New Docker image is ready, have at it :).

MHedish commented 4 years ago

While you were updating...

I did a little logging myself. Seems it's updating the "is_wired":true a full 60 seconds later:

1579065124 vs 1579065184

"Htc","is_guest":false,"first_seen":1546633803,"last_seen":1579064984,"is_wired":false,"hostname":"android-cac4d409e5c05e" "Htc","is_guest":false,"first_seen":1546633803,"last_seen":1579065039,"is_wired":false,"hostname":"android-cac4d409e5c05e" "Htc","is_guest":false,"first_seen":1546633803,"last_seen":1579065039,"is_wired":false,"hostname":"android-cac4d409e5c05e" "Htc","is_guest":false,"first_seen":1546633803,"last_seen":1579065124,"is_wired":true,"hostname":"android-cac4d409e5c05e" "Htc","is_guest":false,"first_seen":1546633803,"last_seen":1579065184,"is_wired":true,"hostname":"android-cac4d409e5c05e" "Htc","is_guest":false,"first_seen":1546633803,"last_seen":1579065445,"is_wired":false,"hostname":"android-cac4d409e5c05e" "Htc","is_guest":false,"first_seen":1546633803,"last_seen":1579065510,"is_wired":false,"hostname":"android-cac4d409e5c05e"

This would sure explain why the 30 (or 45) second interval isn't working.

I did see behavior that might be a different trigger to use.

---- 8< ---- wi-fi connected [{"_id":"REDACTED","mac":"40:4e:36:0c:28:f0","site_id":"REDACTED","oui":"Htc","is_guest":false,"first_seen":1546633803,"last_seen":1579065510,"is_wired":false,"hostname":"android-cac4d409e5c05e","name":"HTC-U11-Marc","usergroup_id":"","noted":true,"fingerprint_override":true,"dev_id_override":46,"duration":26189738,"tx_bytes":114705,"tx_packets":430,"rx_bytes":72448,"rx_packets":267,"wifi_tx_attempts":440,"tx_retries":135,"assoc_time":1579065435,"latest_assoc_time":1579065502,"user_id":"REDACTED","_uptime_by_ugw":44,"_last_seen_by_ugw":1579065546,"_is_guest_by_ugw":false,"gw_mac":"fc:ec:da:4b:17:34","network":"LAN","network_id":"REDACTED","ip":"192.168.10.105","uptime":75,"bytes-r":2879,"tx_bytes-r":1764,"rx_bytes-r":1114,"qos_policy_applied":true,"_uptime_by_uap":75,"_last_seen_by_uap":1579065510,"_is_guest_by_uap":false,"ap_mac":"78:8a:20:48:2e:a2","channel":44,"radio":"na","radio_name":"wifi1","essid":"REDACTED","bssid":"78:8a:20:4a:2e:a2","powersave_enabled":false,"is_11r":false,"ccq":333,"rssi":39,"noise":-109,"signal":-57,"tx_rate":360000,"rx_rate":300000,"tx_power":40,"idletime":2,"dhcpend_time":6560,"satisfaction":99,"anomalies":0,"vlan":0,"radio_proto":"ac"}]}

wi-fi disconnected

[{"_id":"REDACTED","mac":"40:4e:36:0c:28:f0","site_id":"REDACTED","oui":"Htc","is_guest":false,"first_seen":1546633803,"last_seen":1579065577,"is_wired":false,"hostname":"android-REDACTED","name":"HTC-U11-Marc","usergroup_id":"","noted":true,"fingerprint_override":true,"dev_id_override":46,"duration":26189880,"tx_bytes":246449059406,"tx_packets":205252545,"rx_bytes":71417246028,"rx_packets":170117374,"wifi_tx_attempts":178110163,"tx_retries":0}]}

---- 8< ----

The "uptime_by_uap" & "last_seen_by_uap" data drops instantly when wi-fi is disconnected. Same epoch as "last_seen" but the API stops populating the back half of those data points. That's an instant drop from the network. It then changes the "is_wired" flag but that epoch is at 60 seconds. It also updates sooner than the "is_wired" boolean when wi-fi is reconnected.

Granted that UAP value most likely changes when the wi-fi devices moves from AP to AP (I didn't walk around to test :) but perhaps the trigger should be "_last_seen_by_uap" is NUL AND "is wired" is TRUE. The "is_wired" trigger seems to be set to allow the device 60 seconds to reconnect to the mesh and if not seen, the USG figures the device is "not present." Just check these to values and you wouldn't need the epochs.

I'm going to pull the latest image and take a look at the logs.

xtreme22886 commented 4 years ago

Damn, you're good at this :). Those are great suggestions and I think I have some rewriting to do haha.

MHedish commented 4 years ago

:)

I'm running the latest image now.

One more suggestion while you're under the hood... Can you obfuscate the pw in the ST app? Having it stare back at me is giving me a tic. :)

xtreme22886 commented 4 years ago

Great suggestion!

Wow, I had no idea there was that option. Thanks for the tip. The SmartApp has been updated now and password is no longer blaring in your face :).

xtreme22886 commented 4 years ago

Trigger has been changed :). Pull the new image and give her a whirl.

MHedish commented 4 years ago

Perfection!

After updating the ST app, I had to re-enter my pw but that was somewhat expected. I don't think anyone else will have that issue. The pw field looks great.

The Docker logs are all good and the response is fantastic. The wi-fi disconnects are happening nearly instantaneously. The five-second poll rate works.

The response when reconnecting to wi-fi is also (expectedly) just as fast. The geo-fence presence is (again as expected) slower to recognize the not-present condition and faster to detect presence. your solution is much more reliable and won't slurp phone power.

The next best part is being able to add/remove devices for presence detection without having to put an app on a mobile device.

Thanks for your work here. This is just what the Doctor ordered.

xtreme22886 / SmartThings_Unifi-Presence-REST

Presence is flapping #1

Perfection!