Nice G.O. Requring Regular Reloads

DocBrownInSpace commented 1 month ago

The problem

Recently switched to the new integration. Unfortunately, after a few days, commands to my garage door stop working. Usually resulting in a cryptic error: "failed to perform action 'data'". See below. Either completely rebooting Home Assistant or reloading the Nice G.O. integration will restore functionality. My current workaround is to run the following daily:

  - action: homeassistant.reload_config_entry
    target:
      device_id: (Nice G.O. Device ID)
    data: {}

As best I can tell, loss of connectivity happens somewhere >1 day, but <7 days.

What version of Home Assistant Core has the issue?

core-2024.9.2

What was the last working version of Home Assistant Core?

No response

What type of installation are you running?

Home Assistant OS

Integration causing the issue

Nice G.O.

Link to integration documentation on our website

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

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

home-assistant[bot] commented 1 month ago

Hey there @icebotyt, mind taking a look at this issue as it has been labeled with an integration (nice_go) you are listed as a code owner for? Thanks!

Code owner commands

Code owners of `nice_go` can trigger bot actions by commenting: - `@home-assistant close` Closes the issue. - `@home-assistant rename Awesome new title` Renames the issue. - `@home-assistant reopen` Reopen the issue. - `@home-assistant unassign nice_go` Removes the current integration label and assignees on the issue, add the integration domain after the command. - `@home-assistant add-label needs-more-information` Add a label (needs-more-information, problem in dependency, problem in custom component) to the issue. - `@home-assistant remove-label needs-more-information` Remove a label (needs-more-information, problem in dependency, problem in custom component) on the issue.

_{^{(message by CodeOwnersMention)}}

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

IceBotYT commented 1 month ago

I appreciate the report. Please download diagnostics and attach them by dragging and dropping onto the comment box.

Ellipsis (...) next to your config entry
Download diagnostics

Please also enable debug logging and attach logs of when the issue occurs. Full debug logging is not in as of this current release unfortunately, but will be added next release, so this may prevent me from assisting you until the debug logs release.

Thanks for your patience while I try to get this integration perfect :)

DocBrownInSpace commented 1 month ago

Here is the diagnostic data. Currently, the integration is working. I've disabled my daily auto-reload, and will post the diagnostic logs once the issue reappears. Thank you! :)

{
  "home_assistant": {
    "installation_type": "Home Assistant OS",
    "version": "2024.9.2",
    "dev": false,
    "hassio": true,
    "virtualenv": false,
    "python_version": "3.12.4",
    "docker": true,
    "arch": "aarch64",
    "timezone": "America/Los_Angeles",
    "os_name": "Linux",
    "os_version": "6.6.31-haos-raspi",
    "supervisor": "2024.09.1",
    "host_os": "Home Assistant OS 13.1",
    "docker_version": "26.1.4",
    "chassis": "embedded",
    "run_as_root": true
  },
  "custom_components": {
    "htd_lync12": {
      "documentation": null,
      "version": "1.0.0",
      "requirements": []
    }
  },
  "integration_manifest": {
    "domain": "nice_go",
    "name": "Nice G.O.",
    "codeowners": [
      "IceBotYT"
    ],
    "config_flow": true,
    "documentation": "https://www.home-assistant.io/integrations/nice_go",
    "iot_class": "cloud_push",
    "loggers": [
      "nice-go"
    ],
    "requirements": [
      "nice-go==0.3.8"
    ],
    "is_built_in": true
  },
  "setup_times": {
    "null": {
      "setup": 6.401899999275429e-05
    },
    "01J6Z4E8HXCD82EQJWHQ4A1MJR": {
      "config_entry_setup": 10.001468172999992
    }
  },
  "data": {
    "entry": {
      "created_at": "2024-09-04T18:23:38.557760+00:00",
      "data": {
        "email": "**REDACTED**",
        "password": "**REDACTED**",
        "refresh_token": "**REDACTED**",
        "refresh_token_creation_time": 1725474218.557429
      },
      "disabled_by": null,
      "domain": "nice_go",
      "entry_id": "01J6Z4E8HXCD82EQJWHQ4A1MJR",
      "minor_version": 1,
      "modified_at": "2024-09-04T18:23:38.557769+00:00",
      "options": {},
      "pref_disable_new_entities": false,
      "pref_disable_polling": false,
      "source": "user",
      "title": "**REDACTED**",
      "unique_id": "**REDACTED**",
      "version": 1
    },
    "coordinator_data": {
      "57B68F18-A968-2AD0-80A2-CC9FE7FA6ACA": {
        "id": "57B68F18-A968-2AD0-80A2-CC9FE7FA6ACA",
        "name": "Home GDO",
        "barrier_status": "closed",
        "light_status": false,
        "fw_version": "2.1.5.3.200.317",
        "connected": true,
        "vacation_mode": false
      }
    }
  }
}

IceBotYT commented 1 month ago

Nothing looks out of the ordinary in your diagnostics.. let's wait for your logs. If those don't help we might have to wait until 2024.10

DocBrownInSpace commented 1 month ago

Just happened this morning. Happened about 24-30 hours after the last reload.

For context: There's an automation triggered by a motion sensor in the garage. That calls a script which turns on all the lights inside the garage (including the Nice/Linear GDO). That script is what you see failing below.

The problem (and error) is identical if I manually try to send any commands, and it affects control of the lights, away mode, and the door itself. It also affects reporting back status (i.e. the status of each entity is frozen).

2024-09-21 08:44:39.495 ERROR (MainThread) [homeassistant.components.script.garage_all_on] Garage - All On: Error executing script. Unexpected error for device at pos 8: 'data'
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 525, in _async_step
    await getattr(self, handler)()
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 780, in _async_device_step
    await device_action.async_call_action_from_config(
  File "/usr/src/homeassistant/homeassistant/components/device_automation/action.py", line 72, in async_call_action_from_config
    await platform.async_call_action_from_config(hass, config, variables, context)
  File "/usr/src/homeassistant/homeassistant/components/light/device_action.py", line 98, in async_call_action_from_config
    await hass.services.async_call(
  File "/usr/src/homeassistant/homeassistant/core.py", line 2761, in async_call
    response_data = await coro
                    ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2804, in _execute_service
    return await target(service_call)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 996, in entity_service_call
    single_response = await _handle_entity_call(
                      ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 1068, in _handle_entity_call
    result = await task
             ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/light/__init__.py", line 626, in async_handle_light_on_service
    await light.async_turn_on(**filter_turn_on_params(light, params))
  File "/usr/src/homeassistant/homeassistant/components/nice_go/light.py", line 43, in async_turn_on
    await self.coordinator.api.light_on(self._device_id)
  File "/usr/local/lib/python3.12/site-packages/nice_go/nice_go_api.py", line 739, in light_on
    result: bool = data["data"]["devicesControl"]
                   ~~~~^^^^^^^^
KeyError: 'data'
2024-09-21 08:44:39.504 ERROR (MainThread) [homeassistant.components.automation.garage_motion_turn_on_light] Garage - All On - Motion: Error executing script. Unexpected error for call_service at pos 3: 'data'
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 525, in _async_step
    await getattr(self, handler)()
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 763, in _async_call_service_step
    response_data = await self._async_run_long_action(
                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 726, in _async_run_long_action
    return await long_task
           ^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2761, in async_call
    response_data = await coro
                    ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2804, in _execute_service
    return await target(service_call)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/script/__init__.py", line 718, in _service_handler
    response = await self._async_start_run(
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/script/__init__.py", line 674, in _async_start_run
    script_result = await coro
                    ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/script/__init__.py", line 707, in _async_run
    return await self.script.async_run(script_vars, context)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 1795, in async_run
    return await asyncio.shield(create_eager_task(run.async_run()))
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 463, in async_run
    await self._async_step(log_exceptions=False)
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 527, in _async_step
    self._handle_exception(
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 557, in _handle_exception
    raise exception
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 525, in _async_step
    await getattr(self, handler)()
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 780, in _async_device_step
    await device_action.async_call_action_from_config(
  File "/usr/src/homeassistant/homeassistant/components/device_automation/action.py", line 72, in async_call_action_from_config
    await platform.async_call_action_from_config(hass, config, variables, context)
  File "/usr/src/homeassistant/homeassistant/components/light/device_action.py", line 98, in async_call_action_from_config
    await hass.services.async_call(
  File "/usr/src/homeassistant/homeassistant/core.py", line 2761, in async_call
    response_data = await coro
                    ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2804, in _execute_service
    return await target(service_call)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 996, in entity_service_call
    single_response = await _handle_entity_call(
                      ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 1068, in _handle_entity_call
    result = await task
             ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/light/__init__.py", line 626, in async_handle_light_on_service
    await light.async_turn_on(**filter_turn_on_params(light, params))
  File "/usr/src/homeassistant/homeassistant/components/nice_go/light.py", line 43, in async_turn_on
    await self.coordinator.api.light_on(self._device_id)
  File "/usr/local/lib/python3.12/site-packages/nice_go/nice_go_api.py", line 739, in light_on
    result: bool = data["data"]["devicesControl"]
                   ~~~~^^^^^^^^
KeyError: 'data'
2024-09-21 08:44:39.516 ERROR (MainThread) [homeassistant.components.automation.garage_motion_turn_on_light] While executing automation automation.garage_motion_turn_on_light
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/automation/__init__.py", line 755, in async_trigger
    return await self.action_script.async_run(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 1795, in async_run
    return await asyncio.shield(create_eager_task(run.async_run()))
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 463, in async_run
    await self._async_step(log_exceptions=False)
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 527, in _async_step
    self._handle_exception(
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 557, in _handle_exception
    raise exception
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 525, in _async_step
    await getattr(self, handler)()
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 763, in _async_call_service_step
    response_data = await self._async_run_long_action(
                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 726, in _async_run_long_action
    return await long_task
           ^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2761, in async_call
    response_data = await coro
                    ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2804, in _execute_service
    return await target(service_call)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/script/__init__.py", line 718, in _service_handler
    response = await self._async_start_run(
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/script/__init__.py", line 674, in _async_start_run
    script_result = await coro
                    ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/script/__init__.py", line 707, in _async_run
    return await self.script.async_run(script_vars, context)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 1795, in async_run
    return await asyncio.shield(create_eager_task(run.async_run()))
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 463, in async_run
    await self._async_step(log_exceptions=False)
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 527, in _async_step
    self._handle_exception(
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 557, in _handle_exception
    raise exception
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 525, in _async_step
    await getattr(self, handler)()
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 780, in _async_device_step
    await device_action.async_call_action_from_config(
  File "/usr/src/homeassistant/homeassistant/components/device_automation/action.py", line 72, in async_call_action_from_config
    await platform.async_call_action_from_config(hass, config, variables, context)
  File "/usr/src/homeassistant/homeassistant/components/light/device_action.py", line 98, in async_call_action_from_config
    await hass.services.async_call(
  File "/usr/src/homeassistant/homeassistant/core.py", line 2761, in async_call
    response_data = await coro
                    ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2804, in _execute_service
    return await target(service_call)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 996, in entity_service_call
    single_response = await _handle_entity_call(
                      ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 1068, in _handle_entity_call
    result = await task
             ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/light/__init__.py", line 626, in async_handle_light_on_service
    await light.async_turn_on(**filter_turn_on_params(light, params))
  File "/usr/src/homeassistant/homeassistant/components/nice_go/light.py", line 43, in async_turn_on
    await self.coordinator.api.light_on(self._device_id)
  File "/usr/local/lib/python3.12/site-packages/nice_go/nice_go_api.py", line 739, in light_on
    result: bool = data["data"]["devicesControl"]
                   ~~~~^^^^^^^^
KeyError: 'data'

IceBotYT commented 1 month ago

This is interesting. I can't see any more info, but it's looking like an error response. We'll have to wait for the extra debug logs to release..

IceBotYT commented 1 month ago

Just wanted to let you know I added more debug logs that should help when 2024.10 comes out

IceBotYT commented 1 month ago

Hi 👋

2024.10 beta is out, if you want to update. If not, no worries, whenever you're ready just send over those logs :)

perilousZ commented 1 month ago

Hello, I am having this same issue. Here are relevant logs from 2024.11. Let me know if this is useful. Thanks!

2024-10-02 21:20:59.201 DEBUG (MainThread) [nice_go._ws_client] Initializing WebSocket connection
2024-10-02 21:20:59.201 DEBUG (MainThread) [nice_go._ws_client] Sending message: {'type': 'connection_init'}
2024-10-02 21:20:59.202 DEBUG (MainThread) [nice_go._ws_client] Waiting for connection_ack
2024-10-02 21:20:59.202 DEBUG (MainThread) [nice_go.nice_go_api] Dispatching event connection_lost
2024-10-02 21:20:59.202 DEBUG (MainThread) [nice_go.nice_go_api] Connection lost, retrying...
2024-10-02 21:20:59.203 DEBUG (MainThread) [nice_go.nice_go_api] Retrying nice_go.nice_go_api.NiceGOApi.connect in 9.09189812990107 seconds as it raised WebSocketError: Expected connection_ack, but received connection_error.
2024-10-02 21:20:59.203 DEBUG (MainThread) [homeassistant.components.nice_go.coordinator] Connection lost to the websocket

IceBotYT commented 1 month ago

Hello, I am having this same issue. Here are relevant logs from 2024.11. Let me know if this is useful.

Thanks!

Hi, this shouldn't be much of an issue. The entities should only be unavailable for a second or two. If it's prolonged then it's an issue on Nice's end. Thanks :)

perilousZ commented 1 month ago

Hello, I am having this same issue. Here are relevant logs from 2024.11. Let me know if this is useful. Thanks!

Hi, this shouldn't be much of an issue. The entities should only be unavailable for a second or two. If it's prolonged then it's an issue on Nice's end. Thanks :)

Ok no problem! I've got logs running on two instances to try to catch any further info that might help. Will update if anything else seems relevant. Thanks for looking into this.

DocBrownInSpace commented 1 month ago

Here you go. Same script as before, but now with more debug! :)

2024-10-03 17:10:20.052 DEBUG (MainThread) [nice_go.nice_go_api] Turning light on for barrier 57B68F18-A968-2AD0-80A2-CC9FE7FA6ACA
2024-10-03 17:10:20.052 DEBUG (MainThread) [nice_go.nice_go_api] API URL: https://knlzm766jbacjfto6rvfkz77sa.appsync-api.us-east-1.amazonaws.com/graphql
2024-10-03 17:10:20.287 DEBUG (MainThread) [nice_go.nice_go_api] Turning light on response: {'errors': [{'errorType': 'UnauthorizedException', 'message': 'Token has expired.'}]}
2024-10-03 17:10:20.288 ERROR (MainThread) [homeassistant.components.script.garage_all_on] Garage - All On: Error executing script. Unexpected error for device at pos 8: 'data'
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 525, in _async_step
    await getattr(self, handler)()
  File "/usr/src/homeassistant/homeassistant/helpers/script.py", line 780, in _async_device_step
    await device_action.async_call_action_from_config(
  File "/usr/src/homeassistant/homeassistant/components/device_automation/action.py", line 72, in async_call_action_from_config
    await platform.async_call_action_from_config(hass, config, variables, context)
  File "/usr/src/homeassistant/homeassistant/components/light/device_action.py", line 98, in async_call_action_from_config
    await hass.services.async_call(
  File "/usr/src/homeassistant/homeassistant/core.py", line 2761, in async_call
    response_data = await coro
                    ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2804, in _execute_service
    return await target(service_call)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 996, in entity_service_call
    single_response = await _handle_entity_call(
                      ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 1068, in _handle_entity_call
    result = await task
             ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/light/__init__.py", line 628, in async_handle_light_on_service
    await light.async_turn_on(**filter_turn_on_params(light, params))
  File "/usr/src/homeassistant/homeassistant/components/nice_go/light.py", line 46, in async_turn_on
    await self.coordinator.api.light_on(self._device_id)
  File "/usr/local/lib/python3.12/site-packages/nice_go/nice_go_api.py", line 748, in light_on
    result: bool = data["data"]["devicesControl"]
                   ~~~~^^^^^^^^
KeyError: 'data'

IceBotYT commented 1 month ago

Thanks for the debug logs. This is very interesting. Can you try deleting the integration and re-adding it? Token should be renewed every 30 days automatically on integration load.. :thinking:

If the issue reoccurs further investigation may be needed

jeffsenn commented 6 days ago

Now that I've started to use this for my gate closer (hass 2024.11.0b1), I noticed this problem as well. (I don't have an automation but the device becomes unavailable in a similar way) I've turned on logging (only after I detected the "disconnected but reload fixes it" issue. I'll try to post info when it happens next for me.

IceBotYT commented 6 days ago

Thanks for the info. Hopefully this shouldn't happen again for 1 month. If it does happen again I'll look into it

jeffsenn commented 5 days ago

Happened in less than a day. Seems to work for awhile with the GQL websocket dropping and successfully reconnecting at intervals from a few mintues to an hour (assume you don't need those logs). Then it just stops being able to reconnect and tries at a sub-minute rate (failing the same way each time). I wonder if they have some DDOS limiting at their end that is making it not able to reconnect. Logs attached (not much there though). I suppose some sort of exponential backoff on re-try time might help (pure speculation)? Unless there is some credential issue. Reloading integration does immediately fix it. log.txt

IceBotYT commented 4 days ago

This line is interesting to me:

[nice_go.nice_go_api] Retrying nice_go.nice_go_api.NiceGOApi.connect in 8.879644186228102 seconds as it raised WebSocketError: Expected connection_ack, but received connection_error.

I will add extra debug logging (probably in the next patch, not this beta) to see what the contents of that connection_error is.

IceBotYT commented 1 day ago

I added extra debug logging, it should be in the next patch release 👍️

home-assistant / core