search

dcramer / hass-luxor

FXLuminaire Luxor integration for Home Assistant
MIT License
9 stars 9 forks source link

Quickly changing on/off status of multiple groups fails to complete #10

Closed DigitalBites closed 1 year ago

DigitalBites commented 1 year ago

HA version 2023.8.3/latest

Thank you for such a great integration. This worked right away for me, but when I started to integrate some of the groups into my scenes in home assistant I noticed an issue.

When you in rapid secession turn on, off or any combination there of of multiple groups - it appears the controller is abandoning the subsequent requests. first one wins and then there is an error in the logs that it disconnects (although it continues to work for later single status change calls). You can still turn on/off other groups one at a time.

Another example of this is having a card setup in the front end with the header toggle available. As soon as you toggle it only one of the groups will change status with the same error.

Log output when it successfully turns on/off a light:

2023-08-22 22:25:22.609 DEBUG (MainThread) [custom_components.luxor.scene] Finished fetching luxor_scene data in 0.019 seconds (success: True)
2023-08-22 22:25:22.630 DEBUG (MainThread) [custom_components.luxor.scene] Finished fetching luxor_scene data in 0.021 seconds (success: True)
2023-08-22 22:25:42.382 DEBUG (MainThread) [custom_components.luxor.light] Finished fetching luxor_light data in 0.032 seconds (success: True)
2023-08-22 22:25:42.384 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection] [140624855906624] Server disconnected
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/websocket_api/commands.py", line 226, in handle_call_service
    await hass.services.async_call(
  File "/usr/src/homeassistant/homeassistant/core.py", line 1974, in async_call
    response_data = await coro
                    ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2011, in _execute_service
    return await target(service_call)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/homeassistant/__init__.py", line 130, in async_handle_turn_service
    await asyncio.gather(*tasks)
  File "/usr/src/homeassistant/homeassistant/core.py", line 1974, in async_call
    response_data = await coro
                    ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2011, in _execute_service
    return await target(service_call)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/entity_component.py", line 235, in handle_service
    return await service.entity_service_call(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 898, in entity_service_call
    task.result()  # pop exception if have
    ^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 1199, in async_request_call
    return await coro
           ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 942, in _handle_entity_call
    result = await task
             ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/light/__init__.py", line 591, in async_handle_light_off_service
    await light.async_turn_off(**filter_turn_off_params(light, params))
  File "/config/custom_components/luxor/light.py", line 135, in async_turn_off
    api_response = await api_instance.illuminate_group(
                   ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/deps/lib/python3.11/site-packages/luxor_openapi_asyncio/api_client.py", line 185, in __call_api
    response_data = await self.request(
                    ^^^^^^^^^^^^^^^^^^^
  File "/config/deps/lib/python3.11/site-packages/luxor_openapi_asyncio/rest.py", line 219, in POST
    return (await self.request("POST", url,
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/deps/lib/python3.11/site-packages/luxor_openapi_asyncio/rest.py", line 166, in request
    r = await self.pool_manager.request(**args)
        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/aiohttp/client.py", line 560, in _request
    await resp.start(conn)
  File "/usr/local/lib/python3.11/site-packages/aiohttp/client_reqrep.py", line 899, in start
    message, payload = await protocol.read()  # type: ignore[union-attr]
                       ^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/aiohttp/streams.py", line 616, in read
    await self._waiter
aiohttp.client_exceptions.ServerDisconnectedError: Server disconnected

Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/entity.py", line 1199, in async_request_call
    return await coro
           ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 942, in _handle_entity_call
    result = await task
             ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/light/__init__.py", line 591, in async_handle_light_off_service
    await light.async_turn_off(**filter_turn_off_params(light, params))
  File "/config/custom_components/luxor/light.py", line 135, in async_turn_off
    api_response = await api_instance.illuminate_group(
                   ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/deps/lib/python3.11/site-packages/luxor_openapi_asyncio/api_client.py", line 185, in __call_api
    response_data = await self.request(
                    ^^^^^^^^^^^^^^^^^^^
  File "/config/deps/lib/python3.11/site-packages/luxor_openapi_asyncio/rest.py", line 219, in POST
    return (await self.request("POST", url,
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/deps/lib/python3.11/site-packages/luxor_openapi_asyncio/rest.py", line 166, in request
    r = await self.pool_manager.request(**args)
        ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/aiohttp/client.py", line 560, in _request
    await resp.start(conn)
  File "/usr/local/lib/python3.11/site-packages/aiohttp/client_reqrep.py", line 899, in start
    message, payload = await protocol.read()  # type: ignore[union-attr]
                       ^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.11/site-packages/aiohttp/streams.py", line 616, in read
    await self._waiter
aiohttp.client_exceptions.ServerDisconnectedError: Server disconnected

Here's the relevant debug lines from the log file:

2023-08-22 22:25:17.287 WARNING (SyncWorker_4) [homeassistant.loader] We found a custom integration luxor which has not been tested by Home Assistant. This component might cause stability problems, be sure to disable it if you experience issues with Home Assistant
2023-08-22 22:25:19.270 INFO (MainThread) [homeassistant.bootstrap] Setting up stage 2: {'application_credentials', 'energy', 'map', 'nws', 'input_boolean', 'assist_pipeline', 'person', 'climate', 'input_button', 'rachio', 'script', 'default_config', 'hardware', 'airvisual_pro', 'media_source', 'input_number', 'lovelace', 'nfandroidtv', 'trace', 'tag', 'ffmpeg', 'analytics', 'mqtt', 'dyson_local', 'template', 'input_text', 'wemo', 'search', 'stream', 'apple_tv', 'myq', 'opower', 'scene', 'config', 'mjpeg', 'automation', 'nodered', 'diagnostics', 'conversation', 'counter', 'device_tracker', 'system_health', 'luxor', 'zone', 'cover', 'media_player', 'light', 'co2signal', 'homekit', 'sun', 'blueprint', 'monoprice', 'zwave_js', 'my', 'timer', 'input_datetime', 'file_upload', 'sensor', 'repairs', 'ecobee', 'ge_home', 'influxdb', 'airvisual', 'tts', 'auth', 'flume', 'ios', 'notify', 'enphase_envoy', 'stt', 'onboarding', 'homeassistant_alerts', 'bhyve', 'device_automation', 'input_select', 'schedule', 'history', 'group', 'version', 'braviatv', 'esphome', 'logbook', 'mobile_app', 'image_upload'}
2023-08-22 22:25:22.201 INFO (MainThread) [homeassistant.setup] Setting up luxor
2023-08-22 22:25:22.201 INFO (MainThread) [homeassistant.setup] Setup of domain luxor took 0.0 seconds
2023-08-22 22:25:22.589 INFO (MainThread) [homeassistant.components.scene] Setting up scene.luxor
2023-08-22 22:25:22.609 DEBUG (MainThread) [custom_components.luxor.scene] Finished fetching luxor_scene data in 0.019 seconds (success: True)
2023-08-22 22:25:22.630 DEBUG (MainThread) [custom_components.luxor.scene] Finished fetching luxor_scene data in 0.021 seconds (success: True)
2023-08-22 22:25:25.081 INFO (MainThread) [homeassistant.components.light] Setting up light.luxor
2023-08-22 22:25:25.256 DEBUG (MainThread) [custom_components.luxor.light] Finished fetching luxor_light data in 0.174 seconds (success: True)
2023-08-22 22:25:25.309 DEBUG (MainThread) [custom_components.luxor.light] Finished fetching luxor_light data in 0.052 seconds (success: True)
2023-08-22 22:25:42.382 DEBUG (MainThread) [custom_components.luxor.light] Finished fetching luxor_light data in 0.032 seconds (success: True)
  File "/config/custom_components/luxor/light.py", line 135, in async_turn_off
  File "/config/deps/lib/python3.11/site-packages/luxor_openapi_asyncio/api_client.py", line 185, in __call_api
  File "/config/deps/lib/python3.11/site-packages/luxor_openapi_asyncio/rest.py", line 219, in POST
  File "/config/deps/lib/python3.11/site-packages/luxor_openapi_asyncio/rest.py", line 166, in request
  File "/config/custom_components/luxor/light.py", line 135, in async_turn_off
  File "/config/deps/lib/python3.11/site-packages/luxor_openapi_asyncio/api_client.py", line 185, in __call_api
  File "/config/deps/lib/python3.11/site-packages/luxor_openapi_asyncio/rest.py", line 219, in POST
  File "/config/deps/lib/python3.11/site-packages/luxor_openapi_asyncio/rest.py", line 166, in request
2023-08-22 22:25:46.420 DEBUG (MainThread) [custom_components.luxor.light] Finished fetching luxor_light data in 0.034 seconds (success: True)
2023-08-22 22:26:46.132 DEBUG (MainThread) [custom_components.luxor.light] Finished fetching luxor_light data in 0.038 seconds (success: True)
2023-08-22 22:27:46.136 DEBUG (MainThread) [custom_components.luxor.light] Finished fetching luxor_light data in 0.042 seconds (success: True)
2023-08-22 22:28:46.144 DEBUG (MainThread) [custom_components.luxor.light] Finished fetching luxor_light data in 0.049 seconds (success: True)

Update: clarification/spelling

DigitalBites commented 1 year ago

Yesterday evening, I had a chance to start digging into the Home Assistant code and then the Luxor API that is used by this and I believe have found the cause of the issue.

The API has a default pool connection size of 100. Reading that API documentation, it appears that it will queue calls beyond that threshold and going back to my initial thoughts that the landscape lighting controller is getting overwhelmed by repeated requests in the above scenarios, I changed the default pool configuration from 100 -> 1. Applying this patch fixed the issue, more testing is necessary and I need to see if this is a simple parameter/configuration that can be applied via parameter/inputs from this module.

For those interested, that line in the configuration for the API is here -> 

lib/python3.11/site-packages/luxor_openapi_asyncio/configuration.py:173:        self.connection_pool_maxsize = 100

Changing that value, restarting HA appears to solve this problem. I'll see what can be done from a pull request for this module to influence a change to the default value to what this module requires.