search

clyra / unifics

[DEPRECATED] Unifi Counter Sensor
GNU General Public License v3.0
13 stars 4 forks source link

Unifics causes chaos when it encounters a permission denied error #34

Open jkfranks9 opened 1 month ago

jkfranks9 commented 1 month ago

At random intervals Unifics gets a permission denied error when updating clients. I don't know why this happens because it runs fine most of the time. But the code takes an exception when this happens, and the following things occur:

It might be tempting to say fix whatever is causing the permission denied error, but how such an error is handled should definitely be cleaner. I don't know what Unifics is doing that is causing HA to grind to a halt for over a minute, but maybe it has something to do with the various async problems that have been reported, and fixed, previously. Just a guess.

I think Unifics should test for an errorCode return in the clients variable when executing the loop at line 197 in sensor.py, and handle the error with a message instead of taking an exception. I think it's worth investigating what else is going on that causes the long delay, but perhaps just handling the error would avoid (mask) that particular problem.

I did remove Unifics for over 24 hours and did not see any problems at all. With Unifics running, I see this error several times a day. It does recover quickly, but is nevertheless an annoyance.

Here is an annotated log snippet:

HA startup:

2024-10-14 08:53:08.846 INFO (MainThread) [homeassistant.setup] Setting up unifics
2024-10-14 08:53:08.846 INFO (MainThread) [homeassistant.setup] Setup of domain unifics took 0.00 seconds
2024-10-14 08:53:08.847 INFO (MainThread) [homeassistant.components.sensor] Setting up unifics.sensor
2024-10-14 08:53:08.848 INFO (MainThread) [homeassistant.setup] Setting up intent
2024-10-14 08:53:08.850 INFO (MainThread) [homeassistant.setup] Setup of domain intent took 0.00 seconds
2024-10-14 08:53:08.852 DEBUG (SyncWorker_1) [custom_components.unifics.api_wrapper] host=192.168.1.1, port=8443, username=homeassistant, site=default, cert=False, udm=True
2024-10-14 08:53:08.864 INFO (MainThread) [homeassistant.setup] Setup of domain zone took 0.86 seconds
2024-10-14 08:53:08.957 INFO (MainThread) [homeassistant.setup] Setup of domain input_number took 0.92 seconds
2024-10-14 08:53:08.963 INFO (MainThread) [homeassistant.setup] Setup of domain timer took 0.90 seconds
2024-10-14 08:53:08.966 INFO (MainThread) [homeassistant.setup] Setup of domain input_button took 0.90 seconds
2024-10-14 08:53:08.974 INFO (MainThread) [homeassistant.setup] Setup of domain input_select took 0.82 seconds
2024-10-14 08:53:08.978 INFO (MainThread) [homeassistant.setup] Setup of domain input_boolean took 0.80 seconds
2024-10-14 08:53:08.981 INFO (MainThread) [homeassistant.setup] Setting up conversation
2024-10-14 08:53:08.987 INFO (MainThread) [homeassistant.setup] Setup of domain conversation took 0.01 seconds
2024-10-14 08:53:09.012 INFO (MainThread) [homeassistant.setup] Setting up device_tracker
2024-10-14 08:53:09.014 INFO (MainThread) [homeassistant.setup] Setup of domain device_tracker took 0.00 seconds
2024-10-14 08:53:09.434 DEBUG (SyncWorker_1) [custom_components.unifics.api_wrapper] unificontrol: OK

Error detected:

2024-10-14 12:30:40.930 DEBUG (MainThread) [custom_components.unifics.sensor] Finished fetching sensor data in 0.127 seconds (success: True)
2024-10-14 12:31:25.924 DEBUG (MainThread) [custom_components.unifics.sensor] Finished fetching sensor data in 0.117 seconds (success: True)
2024-10-14 12:32:10.933 DEBUG (MainThread) [custom_components.unifics.sensor] Finished fetching sensor data in 0.129 seconds (success: True)
2024-10-14 12:32:56.134 DEBUG (MainThread) [custom_components.unifics.sensor] Finished fetching sensor data in 0.331 seconds (success: True)
2024-10-14 12:32:56.135 ERROR (MainThread) [custom_components.unifics.sensor] Error while trying to update clients: 'str' object has no attribute 'get'
2024-10-14 12:32:56.138 ERROR (MainThread) [custom_components.unifics.sensor] client: errorCode
2024-10-14 12:34:30.699 INFO (Thread-6) [pychromecast.socket_client] [SHIELD(5688c2f1-bee8-34a8-56dc-bcd0fad4d125.local.):8009] Heartbeat timeout, resetting connection
2024-10-14 12:34:30.699 INFO (Thread-6) [pychromecast.controllers] Receiver:channel_disconnected
2024-10-14 12:34:30.798 ERROR (MainThread) [custom_components.unifics.sensor] raw data clients: {'errorCode': 403, 'message': 'No permission'}
2024-10-14 12:34:30.798 WARNING (MainThread) [homeassistant.helpers.entity] Updating state for sensor.unifi_counter (<class 'custom_components.unifics.sensor.UnifiSensor'>) took 94.663 seconds. Please report it to the author of the 'unifics' custom integration
2024-10-14 12:34:30.876 INFO (Thread-6) [pychromecast.socket_client] [SHIELD(192.168.1.190):8009] Connection reestablished!
2024-10-14 12:34:31.423 INFO (MainThread) [hass_nabucasa.iot] Timeout while waiting to receive message
2024-10-14 12:34:31.424 WARNING (MainThread) [hass_nabucasa.iot] Connection closed: Cannot write to closing transport
2024-10-14 12:34:31.426 INFO (MainThread) [custom_components.epson_projector_link.projector.projector] _listen: Connection ended
2024-10-14 12:34:31.427 INFO (MainThread) [slixmpp.xmlstream.xmlstream] connection_lost: (None,)
2024-10-14 12:34:31.518 WARNING (MainThread) [homeassistant.util.loop] Detected blocking call to load_default_certs with args (<ssl.SSLContext object at 0x7f6d3bc1d0>, <Purpose.SERVER_AUTH: _ASN1Object(nid=129, shortname='serverAuth', longname='TLS Web Server Authentication', oid='1.3.6.1.5.5.7.3.1')>) in /usr/local/lib/python3.12/ssl.py, line 713: context.load_default_certs(purpose) inside the event loop; This is causing stability issues. Please create a bug report at https://github.com/home-assistant/core/issues?q=is%3Aopen+is%3Aissue
For developers, please see https://developers.home-assistant.io/docs/asyncio_blocking_operations/#load_default_certs
Traceback (most recent call last):
  File "<frozen runpy>", line 198, in _run_module_as_main
  File "<frozen runpy>", line 88, in _run_code
  File "/usr/src/homeassistant/homeassistant/__main__.py", line 223, in <module>
    sys.exit(main())
  File "/usr/src/homeassistant/homeassistant/__main__.py", line 209, in main
    exit_code = runner.run(runtime_conf)
  File "/usr/src/homeassistant/homeassistant/runner.py", line 189, in run
    return loop.run_until_complete(setup_and_run_hass(runtime_config))
  File "/usr/local/lib/python3.12/asyncio/base_events.py", line 674, in run_until_complete
    self.run_forever()
  File "/usr/local/lib/python3.12/asyncio/base_events.py", line 641, in run_forever
    self._run_once()
  File "/usr/local/lib/python3.12/asyncio/base_events.py", line 1990, in _run_once
    handle._run()
  File "/usr/local/lib/python3.12/asyncio/events.py", line 88, in _run
    self._context.run(self._callback, *self._args)
  File "/usr/local/lib/python3.12/site-packages/slixmpp/xmlstream/xmlstream.py", line 1107, in handler_callback_routine
    await cb(data)
  File "/usr/local/lib/python3.12/site-packages/aioharmony/hubconnector_xmpp.py", line 290, in _disconnected_handler
    self._init_super()
  File "/usr/local/lib/python3.12/site-packages/aioharmony/hubconnector_xmpp.py", line 71, in _init_super
    super(HubConnector, self).__init__(
  File "/usr/local/lib/python3.12/site-packages/slixmpp/clientxmpp.py", line 59, in __init__
    BaseXMPP.__init__(self, jid, 'jabber:client', **kwargs)
  File "/usr/local/lib/python3.12/site-packages/slixmpp/basexmpp.py", line 76, in __init__
    XMLStream.__init__(self, **kwargs)
  File "/usr/local/lib/python3.12/site-packages/slixmpp/xmlstream/xmlstream.py", line 301, in __init__
    self.ssl_context = ssl.create_default_context()
  File "/usr/local/lib/python3.12/ssl.py", line 713, in create_default_context
    context.load_default_certs(purpose)

2024-10-14 12:34:31.673 WARNING (MainThread) [homeassistant.components.androidtv_remote] Disconnected from SHIELD at 192.168.1.190

Unifics recovers, but notify_zigbee_device_unavailable automation runs, showing the entire zigbee network was unavailable.
There are also a couple of other errors that always exist after the initial unifics error detection: MQTT client is disconnected; snitun.multiplexer.core ping failure

2024-10-14 12:34:31.779 DEBUG (MainThread) [custom_components.unifics.sensor] Finished fetching sensor data in 0.617 seconds (success: True)
2024-10-14 12:34:32.017 INFO (MainThread) [custom_components.epson_projector_link.projector.projector] connect: Connection opened
2024-10-14 12:34:32.070 INFO (MainThread) [music_assistant.client] Connected to Music Assistant Server 80f315d05f5c469f836c32dc10cd61c7, Version 2.2.7, Schema Version 26
2024-10-14 12:34:32.565 INFO (MainThread) [homeassistant.components.androidtv_remote] Reconnected to SHIELD at 192.168.1.190
2024-10-14 12:34:32.783 INFO (MainThread) [matter_server.client.connection] Connected to Matter Fabric 2 (3771498967642612336), Schema version 11, CHIP SDK Version 2024.9.0
2024-10-14 12:34:32.845 INFO (MainThread) [homeassistant.components.media_player] Setting up mass.media_player
2024-10-14 12:34:32.885 INFO (MainThread) [matter_server.client] Matter client initialized.
...
2024-10-14 12:34:34.214 INFO (MainThread) [homeassistant.components.automation.notify_zigbee_device_unavailable] Notify Zigbee Device Unavailable: Running automation actions
2024-10-14 12:34:34.215 INFO (MainThread) [homeassistant.components.automation.notify_zigbee_device_unavailable] Notify Zigbee Device Unavailable: Executing step call service
2024-10-14 12:34:34.217 INFO (MainThread) [homeassistant.components.system_log.external] From state: <state sensor.current_zigbee_unavailable_devices=0; device_list=['Back Door Sensor Door', 'Studio Window Sensor Door', 'Studio Motion Detector Occupancy', 'Laundry Room Motion Detector Occupancy', 'Master Bath Motion Detector Occupancy', 'Master BR Vent 1', 'Master BR Vent 2', 'CC2530 Router Led', 'Sonoff Router', 'Office Human Sensor Presence', 'Hall Light', 'Dining Table Light'], friendly_name=Current Zigbee Unavailable Devices @ 2024-10-14T08:54:37.745323-04:00>
2024-10-14 12:34:34.218 INFO (MainThread) [homeassistant.components.automation.notify_zigbee_device_unavailable] Notify Zigbee Device Unavailable: Executing step call service
2024-10-14 12:34:34.219 INFO (MainThread) [homeassistant.components.system_log.external] To state: <state sensor.current_zigbee_unavailable_devices=12; device_list=['Back Door Sensor Door', 'Studio Window Sensor Door', 'Studio Motion Detector Occupancy', 'Laundry Room Motion Detector Occupancy', 'Master Bath Motion Detector Occupancy', 'Master BR Vent 1', 'Master BR Vent 2', 'CC2530 Router Led', 'Sonoff Router', 'Office Human Sensor Presence', 'Hall Light', 'Dining Table Light'], friendly_name=Current Zigbee Unavailable Devices @ 2024-10-14T12:34:34.199670-04:00>
...
2024-10-14 12:34:34.327 ERROR (MainThread) [homeassistant.components.automation.save_notifications_on_create] Save Notifications On Create: Error executing script. Error for call_service at pos 1: Error talking to MQTT: The client is not currently connected.
2024-10-14 12:34:34.328 ERROR (MainThread) [homeassistant.components.automation.save_notifications_on_create] Error while executing automation automation.save_notifications_on_create: Error talking to MQTT: The client is not currently connected.
2024-10-14 12:34:35.086 INFO (MainThread) [hass_nabucasa.iot] Connected
...
2024-10-14 12:34:48.522 INFO (MainThread) [homeassistant.components.unifi] Will try to reconnect to UniFi Network
2024-10-14 12:34:51.089 INFO (MainThread) [homeassistant.components.mqtt.client] MQTT client initialized, birth message sent
2024-10-14 12:35:16.914 DEBUG (MainThread) [custom_components.unifics.sensor] Finished fetching sensor data in 0.110 seconds (success: True)
2024-10-14 12:36:01.453 ERROR (MainThread) [snitun.multiplexer.core] Ping fails, no response from peer
2024-10-14 12:36:01.938 DEBUG (MainThread) [custom_components.unifics.sensor] Finished fetching sensor data in 0.135 seconds (success: True)
2024-10-14 12:36:07.858 INFO (MainThread) [snitun.utils.aiohttp_client] AioHTTP snitun client connected to: us-east-1-12.ui.nabu.casa:443
2024-10-14 12:36:46.965 DEBUG (MainThread) [custom_components.unifics.sensor] Finished fetching sensor data in 0.162 seconds (success: True)
2024-10-14 12:37:32.098 DEBUG (MainThread) [custom_components.unifics.sensor] Finished fetching sensor data in 0.294 seconds (success: True)
2024-10-14 12:38:16.943 DEBUG (MainThread) [custom_components.unifics.sensor] Finished fetching sensor data in 0.140 seconds (success: True)
2024-10-14 12:39:01.946 DEBUG (MainThread) [custom_components.unifics.sensor] Finished fetching sensor data in 0.134 seconds (success: True)
2024-10-14 12:39:46.938 DEBUG (MainThread) [custom_components.unifics.sensor] Finished fetching sensor data in 0.136 seconds (success: True)
clyra commented 1 month ago

HI,

Thanks for the report. Which HA version are you running?

jkfranks9 commented 1 month ago

HA OS: Core 2024.10.3, Supervisor 2024.10.2, OS 13.2. But this started a few updates ago, not sure exactly what I was running then.

clyra commented 2 weeks ago

hey,

Bad news / good news... This weekend I got some time to look into the problem, and to look into the code of other integrations trying to find the solution. To my surprise I just discovered that the oficial Ubiquity Network integration can do the same things as mine now. I wrote mine sometime ago because the oficial integration was focused on presence detection but now it can do much more. So, the bad news, I'm willing to deprecate the unifics integration in favor of the oficial integration. I also should write how to configure the Ubiquity Network integration because there's a little catch (by default one kind of sensor comes disabled).

jkfranks9 commented 2 weeks ago

Thank you for digging into this! I also use the official UniFi Network integration, but never noticed that it provides the same counts you do. I enabled the various clients sensors and everything is there in slightly different form, so that will work for me.

Thanks again for providing your integration. I've used it ever since I discovered it.