Node reboot button error

jeverley commented 6 months ago

Currently running Home Assistant core 2024.3.0.

Encountering an error when attempting to reboot a node with integration versions 2024.1.1 2024.2.1b0 (details included below).

Let me know if I can provide any other details to assist with troubleshooting.

Failed to call service button/press. 'ButtonEntityDescription' object has no attribute 'press_action

Logger: homeassistant.components.websocket_api.http.connection
Source: components/websocket_api/commands.py:239
integration: Home Assistant WebSocket API (documentation, issues)
First occurred: 19:07:22 (1 occurrences)
Last logged: 19:07:22

[139643142076224] 'ButtonEntityDescription' object has no attribute 'press_action'
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/websocket_api/commands.py", line 239, in handle_call_service
    response = await hass.services.async_call(
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2319, in async_call
    response_data = await coro
                    ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2356, in _execute_service
    return await target(service_call)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 905, in entity_service_call
    single_response = await _handle_entity_call(
                      ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 975, in _handle_entity_call
    result = await task
             ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/button/__init__.py", line 139, in _async_press_action
    await self.async_press()
  File "/config/custom_components/linksys_velop/button.py", line 295, in async_press
    action=self.entity_description.press_action,
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
AttributeError: 'ButtonEntityDescription' object has no attribute 'press_action'

uvjim commented 6 months ago

I can see the error. I'm not in a position to fix it at the moment. I should hopefully have it resolved in the next few days.

uvjim commented 6 months ago

Should be fixed now in the beta I just released. Could you test 2024.3.1b0 please?

jeverley commented 6 months ago

Will get this tested shortly and report back, thanks @uvjim.

jeverley commented 6 months ago

Looks like we're getting a different error now in the logs:

Logger: homeassistant.components.websocket_api.http.connection
Source: components/websocket_api/commands.py:239
integration: Home Assistant WebSocket API (documentation, issues)
First occurred: 13:55:05 (1 occurrences)
Last logged: 13:55:05

[139625060891072] Timeout Error
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/websocket_api/commands.py", line 239, in handle_call_service
    response = await hass.services.async_call(
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2319, in async_call
    response_data = await coro
                    ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2356, in _execute_service
    return await target(service_call)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 905, in entity_service_call
    single_response = await _handle_entity_call(
                      ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 975, in _handle_entity_call
    result = await task
             ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/button/__init__.py", line 139, in _async_press_action
    await self.async_press()
  File "/config/custom_components/linksys_velop/button.py", line 294, in async_press
    await _async_button_pressed(
  File "/config/custom_components/linksys_velop/button.py", line 190, in _async_button_pressed
    await action(**action_arguments)
  File "/usr/local/lib/python3.12/site-packages/pyvelop/mesh.py", line 845, in async_reboot_node
    await self._async_make_request(
  File "/usr/local/lib/python3.12/site-packages/pyvelop/mesh.py", line 309, in _async_make_request
    raise err from None
  File "/usr/local/lib/python3.12/site-packages/pyvelop/mesh.py", line 307, in _async_make_request
    req_resp = await req.execute(timeout=self._timeout)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/pyvelop/jnap.py", line 194, in execute
    raise MeshTimeoutError from err
pyvelop.exceptions.MeshTimeoutError: Timeout Error

uvjim commented 6 months ago

I'd expect that error until the node comes back online. The coordinator will poll based on your settings and it can take a few minutes for a node to start responding again.

Edit: Thinking about it you shouldn't see those unless you're rebooting the primary node (which you can't do from a button). Do you see those errors in normal usage?

jeverley commented 6 months ago

Interestingly I also seem to be getting a timeout error using the service "Linksys Velop: Reboot Node" with secondary nodes.

It does work however if I specify my primary node and enable "Is Primary".

uvjim commented 6 months ago

The service ultimately does the same as the button so I'm not surprised you're getting it with that as well.

Do you know if the secondary node actually reboots?

I'll try and test properly in the next couple of days.

uvjim commented 6 months ago

@jeverley - I've had a chance to test this on a node in my setup that has devices connected but it isn't much of an issue if they drop for a period of time. I've tried executing the node reboot from both the HASS and the library directly. Neither of them cause a timeout error to happen.

I turned debug logging on to trace this through as well. The below screenshot shows the block of logging related to the reboot request. I'm wondering if for some reason the node is being resolved to an incorrect IP address to send the request to (although it's odd that it is affecting all secondary nodes). Would you be able to turn debug logging on and double check as well please?

You'll need something like this in your configuration.yaml

logger:
  default: warning
  logs:
    custom_components.linksys_velop: debug
    pyvelop: debug

viking2010 commented 6 months ago

Any update on this issue as I'm also getting the same problem.

uvjim commented 6 months ago

@viking2010 as per previous comment. Still awaiting logs as I'm unable to recreate the issue in my setup.

jeverley commented 6 months ago

I'll get some logs up this afternoon, haven't been able to disrupt the network with family over for Easter.

jeverley commented 5 months ago

Hi @uvjim, please find the logs attached below - note I've redacted some of the 'status' check poll responses to remove specifics of my network's client devices.

I am able to make JNAP requests using postman if it would help in retrieving raw responses from my mesh, what request body is the pyvelop library sending for the reboot request?

Another thing I've noticed is that the reboot issue only seems to apply to the 'Dining Room' secondary node, I can reboot my other secondary nodes successfully. All nodes are running the same firmware.

I also tried renaming dining room to just 'Dining' to check whether the issue was to do with the name, however the reboot request still times out.

The device for which the reboot fails is the only one using a wireless backhaul.

Reboot secondary node 'Dining Room' via service fails:

2024-04-07 10:47:48.850 DEBUG (MainThread) [custom_components.linksys_velop.service_handler] _async_service_call --> entered, call: <ServiceCall linksys_velop.reboot_node (c:01HTVZ9Y3000ERYZSKS07VNEDV): mesh=3b698fcd471a2a6da0588827d0ae964f, node_name=Dining Room>
2024-04-07 10:47:48.947 DEBUG (MainThread) [custom_components.linksys_velop.service_handler] _async_service_call --> Using Mesh: Linksys23996.lan
2024-04-07 10:47:49.035 DEBUG (MainThread) [custom_components.linksys_velop.service_handler] reboot_node --> entered, kwargs: {'node_name': 'Dining Room'}
2024-04-07 10:47:49.118 DEBUG (MainThread) [pyvelop.mesh] async_reboot_node --> entered, node_name: Dining Room, force: False
2024-04-07 10:47:49.201 DEBUG (MainThread) [pyvelop.mesh] _async_make_request --> entered
2024-04-07 10:47:49.287 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> entered
2024-04-07 10:47:49.371 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> URL: http://192.168.20.172/JNAP/, Headers: {'X-JNAP-Authorization': '**REDACTED**', 'Content-Type': 'application/json; charset=UTF-8', 'X-JNAP-Action': 'http://linksys.com/jnap/core/Reboot'}, Payload: [], Timeout: 10
2024-04-07 10:47:50.038 DEBUG (MainThread) [pyvelop.jnap.verbose] Request.execute --> action: http://linksys.com/jnap/nodes/storage/GetNodesPartitions --> payload: {} --> response: {'result': '_ErrorUnknownAction'}
2024-04-07 10:47:50.114 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> exited
2024-04-07 10:47:50.190 DEBUG (MainThread) [pyvelop.mesh] _async_make_request --> exited
2024-04-07 10:47:50.570 DEBUG (MainThread) [pyvelop.jnap.verbose] Request.execute --> action: http://linksys.com/jnap/nodes/storage/GetSMBServerSettings --> payload: {} --> response: {'result': '_ErrorUnknownAction'}
2024-04-07 10:47:50.645 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> exited
2024-04-07 10:47:50.723 DEBUG (MainThread) [pyvelop.mesh] _async_make_request --> exited
2024-04-07 10:47:50.803 DEBUG (MainThread) [pyvelop.jnap.verbose] Request.execute --> action: http://linksys.com/jnap/homekit/GetHomeKitSettings --> payload: {} --> response: {'result': 'OK', 'output': {'isEnabled': False, 'isPaired': False}}
2024-04-07 10:47:50.889 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> exited
2024-04-07 10:47:50.983 DEBUG (MainThread) [pyvelop.mesh] _async_make_request --> exited
2024-04-07 10:47:51.118 DEBUG (MainThread) [pyvelop.jnap.verbose] Request.execute --> action: http://linksys.com/jnap/nodes/networkconnections/GetNodesWirelessNetworkConnections --> payload: {} --> response: {'result': 'OK', 'output': {REDACTED}}
2024-04-07 10:47:51.200 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> exited
2024-04-07 10:47:51.276 DEBUG (MainThread) [pyvelop.mesh] _async_make_request --> exited
2024-04-07 10:47:52.756 DEBUG (MainThread) [pyvelop.jnap.verbose] Request.execute --> action: http://linksys.com/jnap/core/Transaction --> payload: [{'action': 'http://linksys.com/jnap/firewall/GetALGSettings', 'request': {}}, {'action': 'http://linksys.com/jnap/nodes/diagnostics/GetBackhaulInfo', 'request': {}}, {'action': 'http://linksys.com/jnap/nodes/setup/GetSelectedChannels', 'request': {}}, {'action': 'http://linksys.com/jnap/devicelist/GetDevices3', 'request': {}}, {'action': 'http://linksys.com/jnap/router/GetExpressForwardingSettings', 'request': {}}, {'action': 'http://linksys.com/jnap/firmwareupdate/GetFirmwareUpdateSettings', 'request': {}}, {'action': 'http://linksys.com/jnap/guestnetwork/GetGuestRadioSettings2', 'request': {}}, {'action': 'http://linksys.com/jnap/router/GetLANSettings', 'request': {}}, {'action': 'http://linksys.com/jnap/macfilter/GetMACFilterSettings', 'request': {}}, {'action': 'http://linksys.com/jnap/parentalcontrol/GetParentalControlSettings', 'request': {}}, {'action': 'http://linksys.com/jnap/healthcheck/GetHealthCheckResults', 'request': {'healthCheckModule': 'SpeedTest', 'includeModuleResults': True, 'lastNumberOfResults': 10}}, {'action': 'http://linksys.com/jnap/healthcheck/GetHealthCheckStatus', 'request': {}}, {'action': 'http://linksys.com/jnap/nodes/topologyoptimization/GetTopologyOptimizationSettings2', 'request': {}}, {'action': 'http://linksys.com/jnap/nodes/firmwareupdate/GetFirmwareUpdateStatus', 'request': {}}, {'action': 'http://linksys.com/jnap/routerupnp/GetUPnPSettings', 'request': {}}, {'action': 'http://linksys.com/jnap/router/GetWANStatus3', 'request': {}}, {'action': 'http://linksys.com/jnap/wirelessap/GetWPSServerSettings', 'request': {}}] --> response: {REDACTED}
2024-04-07 10:47:52.858 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> exited
2024-04-07 10:47:52.944 DEBUG (MainThread) [pyvelop.mesh] _async_make_request --> exited
2024-04-07 10:47:53.067 DEBUG (MainThread) [pyvelop.mesh] _set_raw_value --> Unknown action URI 'http://linksys.com/jnap/nodes/storage/GetNodesPartitions'
2024-04-07 10:47:53.159 DEBUG (MainThread) [pyvelop.mesh] _set_raw_value --> Unknown action URI 'http://linksys.com/jnap/nodes/storage/GetSMBServerSettings'
2024-04-07 10:47:53.255 DEBUG (MainThread) [pyvelop.mesh] _async_gather_details --> exited
2024-04-07 10:47:53.344 DEBUG (MainThread) [pyvelop.mesh] async_gather_details --> exited
2024-04-07 10:47:53.435 DEBUG (MainThread) [custom_components.linksys_velop] _async_get_mesh_data --> looking for new devices
2024-04-07 10:47:53.523 DEBUG (MainThread) [custom_components.linksys_velop] _async_get_mesh_data --> devices compared
2024-04-07 10:47:53.612 DEBUG (MainThread) [custom_components.linksys_velop] _async_get_mesh_data --> comparing nodes
2024-04-07 10:47:53.701 DEBUG (MainThread) [custom_components.linksys_velop] _async_get_mesh_data --> nodes compared
2024-04-07 10:47:53.801 DEBUG (MainThread) [custom_components.linksys_velop] _async_get_mesh_data --> exited
2024-04-07 10:47:53.801 DEBUG (MainThread) [custom_components.linksys_velop] Finished fetching linksys_velop data in 6.855 seconds (success: True)
2024-04-07 10:47:59.779 WARNING (MainThread) [custom_components.linksys_velop.service_handler] Timeout Error
2024-04-07 10:47:59.863 DEBUG (MainThread) [custom_components.linksys_velop.service_handler] _async_service_call --> exited

Reboot secondary node 'Dining Room' via button fails:

2024-04-07 10:50:34.148 DEBUG (MainThread) [pyvelop.mesh] async_reboot_node --> entered, node_name: Dining Room, force: False
2024-04-07 10:50:34.236 DEBUG (MainThread) [pyvelop.mesh] _async_make_request --> entered
2024-04-07 10:50:34.336 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> entered
2024-04-07 10:50:34.435 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> URL: http://192.168.20.172/JNAP/, Headers: {'X-JNAP-Authorization': '**REDACTED**', 'Content-Type': 'application/json; charset=UTF-8', 'X-JNAP-Action': 'http://linksys.com/jnap/core/Reboot'}, Payload: [], Timeout: 10
2024-04-07 10:50:44.766 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection] [140632206620864] Timeout Error
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/websocket_api/commands.py", line 239, in handle_call_service
    response = await hass.services.async_call(
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2543, in async_call
    response_data = await coro
                    ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/core.py", line 2580, in _execute_service
    return await target(service_call)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 971, in entity_service_call
    single_response = await _handle_entity_call(
                      ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/helpers/service.py", line 1043, in _handle_entity_call
    result = await task
             ^^^^^^^^^^
  File "/usr/src/homeassistant/homeassistant/components/button/__init__.py", line 138, in _async_press_action
    await self.async_press()
  File "/config/custom_components/linksys_velop/button.py", line 294, in async_press
    await _async_button_pressed(
  File "/config/custom_components/linksys_velop/button.py", line 190, in _async_button_pressed
    await action(**action_arguments)
  File "/usr/local/lib/python3.12/site-packages/pyvelop/mesh.py", line 845, in async_reboot_node
    await self._async_make_request(
  File "/usr/local/lib/python3.12/site-packages/pyvelop/mesh.py", line 309, in _async_make_request
    raise err from None
  File "/usr/local/lib/python3.12/site-packages/pyvelop/mesh.py", line 307, in _async_make_request
    req_resp = await req.execute(timeout=self._timeout)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/pyvelop/jnap.py", line 194, in execute
    raise MeshTimeoutError from err
pyvelop.exceptions.MeshTimeoutError: Timeout Error

Reboot secondary node 'Conservatory' via service works:

2024-04-07 10:48:26.491 DEBUG (MainThread) [custom_components.linksys_velop.service_handler] _async_service_call --> entered, call: <ServiceCall linksys_velop.reboot_node (c:01HTVZB2X054THS2QJ3HXWCXZM): mesh=3b698fcd471a2a6da0588827d0ae964f, node_name=Conservatory>
2024-04-07 10:48:26.581 DEBUG (MainThread) [custom_components.linksys_velop.service_handler] _async_service_call --> Using Mesh: Linksys23996.lan
2024-04-07 10:48:26.668 DEBUG (MainThread) [custom_components.linksys_velop.service_handler] reboot_node --> entered, kwargs: {'node_name': 'Conservatory'}
2024-04-07 10:48:26.754 DEBUG (MainThread) [pyvelop.mesh] async_reboot_node --> entered, node_name: Conservatory, force: False
2024-04-07 10:48:26.841 DEBUG (MainThread) [pyvelop.mesh] _async_make_request --> entered
2024-04-07 10:48:26.928 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> entered
2024-04-07 10:48:27.028 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> URL: http://192.168.1.219/JNAP/, Headers: {'X-JNAP-Authorization': '**REDACTED**', 'Content-Type': 'application/json; charset=UTF-8', 'X-JNAP-Action': 'http://linksys.com/jnap/core/Reboot'}, Payload: [], Timeout: 10
2024-04-07 10:48:28.029 DEBUG (MainThread) [pyvelop.jnap.verbose] Request.execute --> action: http://linksys.com/jnap/core/Reboot --> payload: [] --> response: {'result': 'OK', 'sideEffects': ['DeviceRestart']}
2024-04-07 10:48:28.117 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> exited
2024-04-07 10:48:28.195 DEBUG (MainThread) [pyvelop.mesh] _async_make_request --> exited
2024-04-07 10:48:28.272 DEBUG (MainThread) [pyvelop.mesh] async_reboot_node --> exited
2024-04-07 10:48:28.350 DEBUG (MainThread) [custom_components.linksys_velop.service_handler] reboot_node --> exited
2024-04-07 10:48:28.428 DEBUG (MainThread) [custom_components.linksys_velop.service_handler] _async_service_call --> exited

Reboot secondary node 'Conservatory' via button works:

2024-04-07 11:40:37.874 DEBUG (MainThread) [pyvelop.mesh] async_reboot_node --> entered, node_name: Conservatory, force: False
2024-04-07 11:40:37.963 DEBUG (MainThread) [pyvelop.mesh] _async_make_request --> entered
2024-04-07 11:40:38.044 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> entered
2024-04-07 11:40:38.126 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> URL: http://192.168.1.219/JNAP/, Headers: {'X-JNAP-Authorization': '**REDACTED**', 'Content-Type': 'application/json; charset=UTF-8', 'X-JNAP-Action': 'http://linksys.com/jnap/core/Reboot'}, Payload: [], Timeout: 10
2024-04-07 11:40:39.001 DEBUG (MainThread) [pyvelop.jnap.verbose] Request.execute --> action: http://linksys.com/jnap/core/Reboot --> payload: [] --> response: {'result': 'OK', 'sideEffects': ['DeviceRestart']}
2024-04-07 11:40:39.078 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> exited
2024-04-07 11:40:39.157 DEBUG (MainThread) [pyvelop.mesh] _async_make_request --> exited
2024-04-07 11:40:39.234 DEBUG (MainThread) [pyvelop.mesh] async_reboot_node --> exited

Reboot all nodes via primary 'Office' - seems to work, 'Dining Room' light does flash blue, though suppose that could be reconnecting to the mesh..

2024-04-07 11:17:50.619 DEBUG (MainThread) [custom_components.linksys_velop.service_handler] _async_service_call --> entered, call: <ServiceCall linksys_velop.reboot_node (c:01HTW10XP3W69E9AEJMR0BME8R): mesh=3b698fcd471a2a6da0588827d0ae964f, node_name=Office, is_primary=True>
2024-04-07 11:17:50.701 DEBUG (MainThread) [custom_components.linksys_velop.service_handler] _async_service_call --> Using Mesh: Linksys23996.lan
2024-04-07 11:17:50.782 DEBUG (MainThread) [custom_components.linksys_velop.service_handler] reboot_node --> entered, kwargs: {'node_name': 'Office', 'is_primary': True}
2024-04-07 11:17:50.862 DEBUG (MainThread) [pyvelop.mesh] async_reboot_node --> entered, node_name: Office, force: True
2024-04-07 11:17:50.958 DEBUG (MainThread) [pyvelop.mesh] _async_make_request --> entered
2024-04-07 11:17:51.052 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> entered
2024-04-07 11:17:51.134 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> URL: http://192.168.1.6/JNAP/, Headers: {'X-JNAP-Authorization': '**REDACTED**', 'Content-Type': 'application/json; charset=UTF-8', 'X-JNAP-Action': 'http://linksys.com/jnap/core/Reboot'}, Payload: [], Timeout: 10
2024-04-07 11:17:52.060 DEBUG (MainThread) [pyvelop.jnap.verbose] Request.execute --> action: http://linksys.com/jnap/core/Reboot --> payload: [] --> response: {'result': 'OK', 'sideEffects': ['DeviceRestart']}
2024-04-07 11:17:52.137 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> exited
2024-04-07 11:17:52.215 DEBUG (MainThread) [pyvelop.mesh] _async_make_request --> exited
2024-04-07 11:17:52.296 DEBUG (MainThread) [pyvelop.mesh] async_reboot_node --> exited
2024-04-07 11:17:52.372 DEBUG (MainThread) [custom_components.linksys_velop.service_handler] reboot_node --> exited
2024-04-07 11:17:52.449 DEBUG (MainThread) [custom_components.linksys_velop.service_handler] _async_service_call --> exited
2024-04-07 11:18:43.029 DEBUG (MainThread) [custom_components.linksys_velop] _async_get_mesh_data --> entered
2024-04-07 11:18:43.107 DEBUG (MainThread) [custom_components.linksys_velop] _async_get_mesh_data --> retrieving existing devices for comparison
2024-04-07 11:18:43.189 DEBUG (MainThread) [custom_components.linksys_velop] _async_get_mesh_data --> retrieving existing nodes for comparison
2024-04-07 11:18:43.266 DEBUG (MainThread) [custom_components.linksys_velop] _async_get_mesh_data --> previous_node_serials: {'20J20607824005', '20J20M35A20749', '20J20607823996', '20J20607824117'}
2024-04-07 11:18:43.351 DEBUG (MainThread) [custom_components.linksys_velop] _async_get_mesh_data --> gathering details
2024-04-07 11:18:43.432 DEBUG (MainThread) [pyvelop.mesh] async_gather_details --> entered
2024-04-07 11:18:43.508 DEBUG (MainThread) [pyvelop.mesh] _async_gather_details --> entered, args: JNAPActionMappings.CMP_MESH_DETAILS
2024-04-07 11:18:43.584 DEBUG (MainThread) [pyvelop.mesh] _async_make_request --> entered
2024-04-07 11:18:43.660 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> entered
2024-04-07 11:18:43.735 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> URL: http://Linksys23996.lan/JNAP/, Headers: {'X-JNAP-Authorization': '**REDACTED**', 'Content-Type': 'application/json; charset=UTF-8', 'X-JNAP-Action': 'http://linksys.com/jnap/core/Transaction'}, Payload: [{"action": "http://linksys.com/jnap/firewall/GetALGSettings", "request": {}}, {"action": "http://linksys.com/jnap/nodes/diagnostics/GetBackhaulInfo", "request": {}}, {"action": "http://linksys.com/jnap/nodes/setup/GetSelectedChannels", "request": {}}, {"action": "http://linksys.com/jnap/devicelist/GetDevices3", "request": {}}, {"action": "http://linksys.com/jnap/router/GetExpressForwardingSettings", "request": {}}, {"action": "http://linksys.com/jnap/firmwareupdate/GetFirmwareUpdateSettings", "request": {}}, {"action": "http://linksys.com/jnap/guestnetwork/GetGuestRadioSettings2", "request": {}}, {"action": "http://linksys.com/jnap/router/GetLANSettings", "request": {}}, {"action": "http://linksys.com/jnap/macfilter/GetMACFilterSettings", "request": {}}, {"action": "http://linksys.com/jnap/parentalcontrol/GetParentalControlSettings", "request": {}}, {"action": "http://linksys.com/jnap/healthcheck/GetHealthCheckResults", "request": {"healthCheckModule": "SpeedTest", "includeModuleResults": true, "lastNumberOfResults": 10}}, {"action": "http://linksys.com/jnap/healthcheck/GetHealthCheckStatus", "request": {}}, {"action": "http://linksys.com/jnap/nodes/topologyoptimization/GetTopologyOptimizationSettings2", "request": {}}, {"action": "http://linksys.com/jnap/nodes/firmwareupdate/GetFirmwareUpdateStatus", "request": {}}, {"action": "http://linksys.com/jnap/routerupnp/GetUPnPSettings", "request": {}}, {"action": "http://linksys.com/jnap/router/GetWANStatus3", "request": {}}, {"action": "http://linksys.com/jnap/wirelessap/GetWPSServerSettings", "request": {}}], Timeout: 10
2024-04-07 11:18:43.811 DEBUG (MainThread) [pyvelop.mesh] _async_make_request --> entered
2024-04-07 11:18:43.886 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> entered
2024-04-07 11:18:43.962 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> URL: http://Linksys23996.lan/JNAP/, Headers: {'X-JNAP-Authorization': '**REDACTED**', 'Content-Type': 'application/json; charset=UTF-8', 'X-JNAP-Action': 'http://linksys.com/jnap/homekit/GetHomeKitSettings'}, Payload: {}, Timeout: 10
2024-04-07 11:18:44.039 DEBUG (MainThread) [pyvelop.mesh] _async_make_request --> entered
2024-04-07 11:18:44.116 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> entered
2024-04-07 11:18:44.192 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> URL: http://Linksys23996.lan/JNAP/, Headers: {'X-JNAP-Authorization': '**REDACTED**', 'Content-Type': 'application/json; charset=UTF-8', 'X-JNAP-Action': 'http://linksys.com/jnap/nodes/networkconnections/GetNodesWirelessNetworkConnections'}, Payload: {}, Timeout: 10
2024-04-07 11:18:44.267 DEBUG (MainThread) [pyvelop.mesh] _async_make_request --> entered
2024-04-07 11:18:44.345 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> entered
2024-04-07 11:18:44.423 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> URL: http://Linksys23996.lan/JNAP/, Headers: {'X-JNAP-Authorization': '**REDACTED**', 'Content-Type': 'application/json; charset=UTF-8', 'X-JNAP-Action': 'http://linksys.com/jnap/nodes/storage/GetNodesPartitions'}, Payload: {}, Timeout: 10
2024-04-07 11:18:44.501 DEBUG (MainThread) [pyvelop.mesh] _async_make_request --> entered
2024-04-07 11:18:44.585 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> entered
2024-04-07 11:18:44.662 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> URL: http://Linksys23996.lan/JNAP/, Headers: {'X-JNAP-Authorization': '**REDACTED**', 'Content-Type': 'application/json; charset=UTF-8', 'X-JNAP-Action': 'http://linksys.com/jnap/nodes/storage/GetSMBServerSettings'}, Payload: {}, Timeout: 10
2024-04-07 11:18:48.922 DEBUG (MainThread) [custom_components.linksys_velop] _async_get_mesh_data --> error type: <class 'pyvelop.exceptions.MeshConnectionError'>
2024-04-07 11:18:49.000 ERROR (MainThread) [custom_components.linksys_velop] _async_get_mesh_data --> Connection Error
2024-04-07 11:18:49.001 ERROR (MainThread) [custom_components.linksys_velop] Error fetching linksys_velop data: Connection Error
2024-04-07 11:18:49.001 DEBUG (MainThread) [custom_components.linksys_velop] Finished fetching linksys_velop data in 6.055 seconds (success: False)
2024-04-07 11:19:49.027 DEBUG (MainThread) [custom_components.linksys_velop] _async_get_mesh_data --> entered
2024-04-07 11:19:49.106 DEBUG (MainThread) [custom_components.linksys_velop] _async_get_mesh_data --> retrieving existing devices for comparison
2024-04-07 11:19:49.187 DEBUG (MainThread) [custom_components.linksys_velop] _async_get_mesh_data --> retrieving existing nodes for comparison
2024-04-07 11:19:49.268 DEBUG (MainThread) [custom_components.linksys_velop] _async_get_mesh_data --> previous_node_serials: {'20J20607824005', '20J20M35A20749', '20J20607823996', '20J20607824117'}
2024-04-07 11:19:49.349 DEBUG (MainThread) [custom_components.linksys_velop] _async_get_mesh_data --> gathering details
2024-04-07 11:19:49.428 DEBUG (MainThread) [pyvelop.mesh] async_gather_details --> entered
2024-04-07 11:19:49.508 DEBUG (MainThread) [pyvelop.mesh] _async_gather_details --> entered, args: JNAPActionMappings.CMP_MESH_DETAILS
2024-04-07 11:19:49.587 DEBUG (MainThread) [pyvelop.mesh] _async_make_request --> entered
2024-04-07 11:19:49.665 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> entered
2024-04-07 11:19:49.743 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> URL: http://Linksys23996.lan/JNAP/, Headers: {'X-JNAP-Authorization': '**REDACTED**', 'Content-Type': 'application/json; charset=UTF-8', 'X-JNAP-Action': 'http://linksys.com/jnap/core/Transaction'}, Payload: [{"action": "http://linksys.com/jnap/firewall/GetALGSettings", "request": {}}, {"action": "http://linksys.com/jnap/nodes/diagnostics/GetBackhaulInfo", "request": {}}, {"action": "http://linksys.com/jnap/nodes/setup/GetSelectedChannels", "request": {}}, {"action": "http://linksys.com/jnap/devicelist/GetDevices3", "request": {}}, {"action": "http://linksys.com/jnap/router/GetExpressForwardingSettings", "request": {}}, {"action": "http://linksys.com/jnap/firmwareupdate/GetFirmwareUpdateSettings", "request": {}}, {"action": "http://linksys.com/jnap/guestnetwork/GetGuestRadioSettings2", "request": {}}, {"action": "http://linksys.com/jnap/router/GetLANSettings", "request": {}}, {"action": "http://linksys.com/jnap/macfilter/GetMACFilterSettings", "request": {}}, {"action": "http://linksys.com/jnap/parentalcontrol/GetParentalControlSettings", "request": {}}, {"action": "http://linksys.com/jnap/healthcheck/GetHealthCheckResults", "request": {"healthCheckModule": "SpeedTest", "includeModuleResults": true, "lastNumberOfResults": 10}}, {"action": "http://linksys.com/jnap/healthcheck/GetHealthCheckStatus", "request": {}}, {"action": "http://linksys.com/jnap/nodes/topologyoptimization/GetTopologyOptimizationSettings2", "request": {}}, {"action": "http://linksys.com/jnap/nodes/firmwareupdate/GetFirmwareUpdateStatus", "request": {}}, {"action": "http://linksys.com/jnap/routerupnp/GetUPnPSettings", "request": {}}, {"action": "http://linksys.com/jnap/router/GetWANStatus3", "request": {}}, {"action": "http://linksys.com/jnap/wirelessap/GetWPSServerSettings", "request": {}}], Timeout: 10
2024-04-07 11:19:49.822 DEBUG (MainThread) [pyvelop.mesh] _async_make_request --> entered
2024-04-07 11:19:49.904 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> entered
2024-04-07 11:19:49.980 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> URL: http://Linksys23996.lan/JNAP/, Headers: {'X-JNAP-Authorization': '**REDACTED**', 'Content-Type': 'application/json; charset=UTF-8', 'X-JNAP-Action': 'http://linksys.com/jnap/homekit/GetHomeKitSettings'}, Payload: {}, Timeout: 10
2024-04-07 11:19:50.058 DEBUG (MainThread) [pyvelop.mesh] _async_make_request --> entered
2024-04-07 11:19:50.134 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> entered
2024-04-07 11:19:50.211 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> URL: http://Linksys23996.lan/JNAP/, Headers: {'X-JNAP-Authorization': '**REDACTED**', 'Content-Type': 'application/json; charset=UTF-8', 'X-JNAP-Action': 'http://linksys.com/jnap/nodes/networkconnections/GetNodesWirelessNetworkConnections'}, Payload: {}, Timeout: 10
2024-04-07 11:19:50.300 DEBUG (MainThread) [pyvelop.mesh] _async_make_request --> entered
2024-04-07 11:19:50.386 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> entered
2024-04-07 11:19:50.464 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> URL: http://Linksys23996.lan/JNAP/, Headers: {'X-JNAP-Authorization': '**REDACTED**', 'Content-Type': 'application/json; charset=UTF-8', 'X-JNAP-Action': 'http://linksys.com/jnap/nodes/storage/GetNodesPartitions'}, Payload: {}, Timeout: 10
2024-04-07 11:19:50.542 DEBUG (MainThread) [pyvelop.mesh] _async_make_request --> entered
2024-04-07 11:19:50.619 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> entered
2024-04-07 11:19:50.705 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> URL: http://Linksys23996.lan/JNAP/, Headers: {'X-JNAP-Authorization': '**REDACTED**', 'Content-Type': 'application/json; charset=UTF-8', 'X-JNAP-Action': 'http://linksys.com/jnap/nodes/storage/GetSMBServerSettings'}, Payload: {}, Timeout: 10
2024-04-07 11:19:53.237 DEBUG (MainThread) [pyvelop.jnap.verbose] Request.execute --> action: http://linksys.com/jnap/nodes/storage/GetNodesPartitions --> payload: {} --> response: {'result': '_ErrorUnknownAction'}
2024-04-07 11:19:53.313 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> exited
2024-04-07 11:19:53.389 DEBUG (MainThread) [pyvelop.mesh] _async_make_request --> exited
2024-04-07 11:19:53.472 DEBUG (MainThread) [pyvelop.jnap.verbose] Request.execute --> action: http://linksys.com/jnap/nodes/storage/GetSMBServerSettings --> payload: {} --> response: {'result': '_ErrorUnknownAction'}
2024-04-07 11:19:53.550 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> exited
2024-04-07 11:19:53.630 DEBUG (MainThread) [pyvelop.mesh] _async_make_request --> exited
2024-04-07 11:19:53.732 DEBUG (MainThread) [pyvelop.jnap.verbose] Request.execute --> action: http://linksys.com/jnap/homekit/GetHomeKitSettings --> payload: {} --> response: {'result': 'OK', 'output': {'isEnabled': False, 'isPaired': False}}
2024-04-07 11:19:53.811 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> exited
2024-04-07 11:19:53.890 DEBUG (MainThread) [pyvelop.mesh] _async_make_request --> exited
2024-04-07 11:19:54.003 DEBUG (MainThread) [pyvelop.jnap.verbose] Request.execute --> action: http://linksys.com/jnap/nodes/networkconnections/GetNodesWirelessNetworkConnections --> payload: {} --> response: {'result': 'OK', 'output': {REDACTED}}
2024-04-07 11:19:54.087 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> exited
2024-04-07 11:19:54.166 DEBUG (MainThread) [pyvelop.mesh] _async_make_request --> exited
2024-04-07 11:19:57.540 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> exited
2024-04-07 11:19:57.616 DEBUG (MainThread) [pyvelop.mesh] _async_make_request --> exited
2024-04-07 11:19:57.696 DEBUG (MainThread) [pyvelop.mesh] _set_raw_value --> Unknown action URI 'http://linksys.com/jnap/nodes/storage/GetNodesPartitions'
2024-04-07 11:19:57.774 DEBUG (MainThread) [pyvelop.mesh] _set_raw_value --> Unknown action URI 'http://linksys.com/jnap/nodes/storage/GetSMBServerSettings'
2024-04-07 11:19:57.856 DEBUG (MainThread) [pyvelop.mesh] _async_gather_details --> exited
2024-04-07 11:19:57.933 DEBUG (MainThread) [pyvelop.mesh] async_gather_details --> exited
2024-04-07 11:19:58.012 DEBUG (MainThread) [custom_components.linksys_velop] _async_get_mesh_data --> looking for new devices
2024-04-07 11:19:58.090 DEBUG (MainThread) [custom_components.linksys_velop] _async_get_mesh_data --> devices compared
2024-04-07 11:19:58.166 DEBUG (MainThread) [custom_components.linksys_velop] _async_get_mesh_data --> comparing nodes
2024-04-07 11:19:58.243 DEBUG (MainThread) [custom_components.linksys_velop] _async_get_mesh_data --> nodes compared
2024-04-07 11:19:58.322 DEBUG (MainThread) [custom_components.linksys_velop] _async_get_mesh_data --> exited
2024-04-07 11:19:58.322 INFO (MainThread) [custom_components.linksys_velop] Fetching linksys_velop data recovered
2024-04-07 11:19:58.323 DEBUG (MainThread) [custom_components.linksys_velop] Finished fetching linksys_velop data in 9.376 seconds (success: True)
2024-04-07 11:20:58.024 DEBUG (MainThread) [custom_components.linksys_velop] _async_get_mesh_data --> entered
2024-04-07 11:20:58.104 DEBUG (MainThread) [custom_components.linksys_velop] _async_get_mesh_data --> retrieving existing devices for comparison
2024-04-07 11:20:58.185 DEBUG (MainThread) [custom_components.linksys_velop] _async_get_mesh_data --> retrieving existing nodes for comparison
2024-04-07 11:20:58.267 DEBUG (MainThread) [custom_components.linksys_velop] _async_get_mesh_data --> previous_node_serials: {'20J20607824005', '20J20M35A20749', '20J20607823996', '20J20607824117'}
2024-04-07 11:20:58.344 DEBUG (MainThread) [custom_components.linksys_velop] _async_get_mesh_data --> gathering details
2024-04-07 11:20:58.422 DEBUG (MainThread) [pyvelop.mesh] async_gather_details --> entered
2024-04-07 11:20:58.500 DEBUG (MainThread) [pyvelop.mesh] _async_gather_details --> entered, args: JNAPActionMappings.CMP_MESH_DETAILS
2024-04-07 11:20:58.581 DEBUG (MainThread) [pyvelop.mesh] _async_make_request --> entered
2024-04-07 11:20:58.656 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> entered
2024-04-07 11:20:58.732 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> URL: http://Linksys23996.lan/JNAP/, Headers: {'X-JNAP-Authorization': '**REDACTED**', 'Content-Type': 'application/json; charset=UTF-8', 'X-JNAP-Action': 'http://linksys.com/jnap/core/Transaction'}, Payload: [{"action": "http://linksys.com/jnap/firewall/GetALGSettings", "request": {}}, {"action": "http://linksys.com/jnap/nodes/diagnostics/GetBackhaulInfo", "request": {}}, {"action": "http://linksys.com/jnap/nodes/setup/GetSelectedChannels", "request": {}}, {"action": "http://linksys.com/jnap/devicelist/GetDevices3", "request": {}}, {"action": "http://linksys.com/jnap/router/GetExpressForwardingSettings", "request": {}}, {"action": "http://linksys.com/jnap/firmwareupdate/GetFirmwareUpdateSettings", "request": {}}, {"action": "http://linksys.com/jnap/guestnetwork/GetGuestRadioSettings2", "request": {}}, {"action": "http://linksys.com/jnap/router/GetLANSettings", "request": {}}, {"action": "http://linksys.com/jnap/macfilter/GetMACFilterSettings", "request": {}}, {"action": "http://linksys.com/jnap/parentalcontrol/GetParentalControlSettings", "request": {}}, {"action": "http://linksys.com/jnap/healthcheck/GetHealthCheckResults", "request": {"healthCheckModule": "SpeedTest", "includeModuleResults": true, "lastNumberOfResults": 10}}, {"action": "http://linksys.com/jnap/healthcheck/GetHealthCheckStatus", "request": {}}, {"action": "http://linksys.com/jnap/nodes/topologyoptimization/GetTopologyOptimizationSettings2", "request": {}}, {"action": "http://linksys.com/jnap/nodes/firmwareupdate/GetFirmwareUpdateStatus", "request": {}}, {"action": "http://linksys.com/jnap/routerupnp/GetUPnPSettings", "request": {}}, {"action": "http://linksys.com/jnap/router/GetWANStatus3", "request": {}}, {"action": "http://linksys.com/jnap/wirelessap/GetWPSServerSettings", "request": {}}], Timeout: 10
2024-04-07 11:20:58.811 DEBUG (MainThread) [pyvelop.mesh] _async_make_request --> entered
2024-04-07 11:20:58.887 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> entered
2024-04-07 11:20:58.971 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> URL: http://Linksys23996.lan/JNAP/, Headers: {'X-JNAP-Authorization': '**REDACTED**', 'Content-Type': 'application/json; charset=UTF-8', 'X-JNAP-Action': 'http://linksys.com/jnap/homekit/GetHomeKitSettings'}, Payload: {}, Timeout: 10
2024-04-07 11:20:59.054 DEBUG (MainThread) [pyvelop.mesh] _async_make_request --> entered
2024-04-07 11:20:59.140 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> entered
2024-04-07 11:20:59.221 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> URL: http://Linksys23996.lan/JNAP/, Headers: {'X-JNAP-Authorization': '**REDACTED**', 'Content-Type': 'application/json; charset=UTF-8', 'X-JNAP-Action': 'http://linksys.com/jnap/nodes/networkconnections/GetNodesWirelessNetworkConnections'}, Payload: {}, Timeout: 10
2024-04-07 11:20:59.315 DEBUG (MainThread) [pyvelop.mesh] _async_make_request --> entered
2024-04-07 11:20:59.400 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> entered
2024-04-07 11:20:59.478 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> URL: http://Linksys23996.lan/JNAP/, Headers: {'X-JNAP-Authorization': '**REDACTED**', 'Content-Type': 'application/json; charset=UTF-8', 'X-JNAP-Action': 'http://linksys.com/jnap/nodes/storage/GetNodesPartitions'}, Payload: {}, Timeout: 10
2024-04-07 11:20:59.556 DEBUG (MainThread) [pyvelop.mesh] _async_make_request --> entered
2024-04-07 11:20:59.632 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> entered
2024-04-07 11:20:59.708 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> URL: http://Linksys23996.lan/JNAP/, Headers: {'X-JNAP-Authorization': '**REDACTED**', 'Content-Type': 'application/json; charset=UTF-8', 'X-JNAP-Action': 'http://linksys.com/jnap/nodes/storage/GetSMBServerSettings'}, Payload: {}, Timeout: 10
2024-04-07 11:21:01.580 DEBUG (MainThread) [pyvelop.jnap.verbose] Request.execute --> action: http://linksys.com/jnap/nodes/storage/GetNodesPartitions --> payload: {} --> response: {'result': '_ErrorUnknownAction'}
2024-04-07 11:21:01.662 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> exited
2024-04-07 11:21:01.766 DEBUG (MainThread) [pyvelop.mesh] _async_make_request --> exited
2024-04-07 11:21:01.869 DEBUG (MainThread) [pyvelop.jnap.verbose] Request.execute --> action: http://linksys.com/jnap/nodes/storage/GetSMBServerSettings --> payload: {} --> response: {'result': '_ErrorUnknownAction'}
2024-04-07 11:21:01.952 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> exited
2024-04-07 11:21:02.036 DEBUG (MainThread) [pyvelop.mesh] _async_make_request --> exited
2024-04-07 11:21:02.258 DEBUG (MainThread) [pyvelop.jnap.verbose] Request.execute --> action: http://linksys.com/jnap/homekit/GetHomeKitSettings --> payload: {} --> response: {'result': 'OK', 'output': {'isEnabled': False, 'isPaired': False}}
2024-04-07 11:21:02.349 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> exited
2024-04-07 11:21:02.438 DEBUG (MainThread) [pyvelop.mesh] _async_make_request --> exited
2024-04-07 11:21:02.534 DEBUG (MainThread) [pyvelop.jnap.verbose] Request.execute --> action: http://linksys.com/jnap/nodes/networkconnections/GetNodesWirelessNetworkConnections --> payload: {} --> response: {'result': 'OK', 'output': {REDACTED}}
2024-04-07 11:21:02.624 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> exited
2024-04-07 11:21:02.714 DEBUG (MainThread) [pyvelop.mesh] _async_make_request --> exited
2024-04-07 11:21:05.532 DEBUG (MainThread) [pyvelop.jnap] Request.execute --> exited
2024-04-07 11:21:05.614 DEBUG (MainThread) [pyvelop.mesh] _async_make_request --> exited
2024-04-07 11:21:05.702 DEBUG (MainThread) [pyvelop.mesh] _set_raw_value --> Unknown action URI 'http://linksys.com/jnap/nodes/storage/GetNodesPartitions'
2024-04-07 11:21:05.795 DEBUG (MainThread) [pyvelop.mesh] _set_raw_value --> Unknown action URI 'http://linksys.com/jnap/nodes/storage/GetSMBServerSettings'
2024-04-07 11:21:05.879 DEBUG (MainThread) [pyvelop.mesh] _async_gather_details --> exited
2024-04-07 11:21:05.987 DEBUG (MainThread) [pyvelop.mesh] async_gather_details --> exited
2024-04-07 11:21:06.070 DEBUG (MainThread) [custom_components.linksys_velop] _async_get_mesh_data --> looking for new devices
2024-04-07 11:21:06.157 DEBUG (MainThread) [custom_components.linksys_velop] _async_get_mesh_data --> devices compared
2024-04-07 11:21:06.247 DEBUG (MainThread) [custom_components.linksys_velop] _async_get_mesh_data --> comparing nodes
2024-04-07 11:21:06.349 DEBUG (MainThread) [custom_components.linksys_velop] _async_get_mesh_data --> nodes compared
2024-04-07 11:21:06.436 DEBUG (MainThread) [custom_components.linksys_velop] _async_get_mesh_data --> exited
2024-04-07 11:21:06.437 DEBUG (MainThread) [custom_components.linksys_velop] Finished fetching linksys_velop data in 8.491 seconds (success: True)

uvjim commented 5 months ago

Is 192.168.20.172 the correct IP for that node? It doesn't seem to line up with the other IP addresses mentioned in the logs.

jeverley commented 5 months ago

Is 192.168.20.172 the correct IP for that node? It doesn't seem to line up with the other IP addresses mentioned in the logs.

I believe that address range is used within the Velop internal backhaul WiFi mesh.

Its regular IP is 192.168.1.121

I suspect that we might have found the root cause there if Home Assistant is trying to reach the backhaul IP address range.

uvjim commented 5 months ago

That explains the timeout then. It suggests that the node is reported the incorrect address at some point and that is still being used.

You could try the following options (shouldn't need to do all of them): -

Delete the node in the HASS UI and then manually reboot the Dining Room node.

or

Drop the node from the Mesh and rejoin it (depending on your setup this could be disruptive)

I have seen something similar happen before, but I never got to the bottom of why it reported the wrong address.

uvjim commented 5 months ago

I am able to make JNAP requests using postman if it would help in retrieving raw responses from my mesh, what request body is the pyvelop library sending for the reboot request?

Realised I didn't reply to this. The way the library works is that you give it the name of the node. It will then lookup the address (as it knows it) for that node. A direct JNAP request is then made to that address for the reboot.

That is the only area, IIRC, where the library communicates directly with a secondary node. Everything else is done by making requests to the primary.

The service and button essentially do the same thing, ultimately calling the same method to cause the reboot.

jeverley commented 5 months ago

I can see both addresses are reported in http://linksys.com/jnap/devicelist/GetDevices3, which I suspect is where the lib is pulling the device IPs from.

Interestingly for the wired devices the regular network address is reported first in the connections array, which I suspect is why the lib chooses that as the primary address?

My suspicion is that the 192.168.20.x addresses are actually used for internal communication between the mesh nodes, i.e. in the event that the main DHCP server is down.

I wonder if one way for the the lib to select the correct address would be to look at the GetBackhaulInfo result, since I can see that the secondary nodes all contain the correct addresses there - I've included my responses below for each.

"devices": [
    {
        "deviceID": "e3495c07-83f3-4da2-0d4e-24f5a2bef213",
        "lastChangeRevision": 715,
        "model": {
            "deviceType": "Infrastructure",
            "manufacturer": "Linksys",
            "modelNumber": "WHW03",
            "hardwareVersion": "2",
            "description": "Velop"
        },
        "unit": {
            "serialNumber": "20J20607823996",
            "firmwareVersion": "2.1.19.209783",
            "firmwareDate": "2022-01-20T00:22:05Z"
        },
        "isAuthority": true,
        "nodeType": "Master",
        "isHomeKitSupported": true,
        "friendlyName": "Linksys23996",
        "knownInterfaces": [
            {
                "macAddress": "24:F5:A2:BE:F2:13",
                "interfaceType": "Wired"
            }
        ],
        "connections": [
            {
                "macAddress": "24:F5:A2:BE:F2:13",
                "ipAddress": "192.168.1.6"
            }
        ],
        "properties": [
            {
                "name": "userDeviceLocation",
                "value": "Office"
            },
            {
                "name": "userDeviceName",
                "value": "Office"
            }
        ],
        "maxAllowedProperties": 16
    },
    {
        "deviceID": "f9d4cb57-0214-2e55-9174-24f5a2bef470",
        "lastChangeRevision": 1123,
        "model": {
            "deviceType": "Infrastructure",
            "manufacturer": "Linksys",
            "modelNumber": "WHW03",
            "hardwareVersion": "2",
            "description": "Velop"
        },
        "unit": {
            "serialNumber": "20J20607824117",
            "firmwareVersion": "2.1.19.209783",
            "firmwareDate": "2020-03-25T04:48:53Z"
        },
        "isAuthority": false,
        "nodeType": "Slave",
        "isHomeKitSupported": true,
        "friendlyName": "LINKSYS24117",
        "knownInterfaces": [
            {
                "macAddress": "2A:F5:A2:BE:F4:73",
                "interfaceType": "Wireless"
            },
            {
                "macAddress": "24:F5:A2:BE:F4:70",
                "interfaceType": "Unknown"
            },
            {
                "macAddress": "2A:F5:A2:BE:F4:72",
                "interfaceType": "Unknown"
            },
            {
                "macAddress": "24:F5:A2:BE:F4:71",
                "interfaceType": "Unknown"
            },
            {
                "macAddress": "32:F5:A2:BE:F4:71",
                "interfaceType": "Unknown"
            }
        ],
        "connections": [
            {
                "macAddress": "24:F5:A2:BE:F4:70",
                "ipAddress": "192.168.1.215",
                "ipv6Address": "fe80:0000:0000:0000:26f5:a2ff:febe:f470"
            },
            {
                "macAddress": "24:F5:A2:BE:F4:71",
                "ipAddress": "192.168.20.166"
            }
        ],
        "properties": [
            {
                "name": "userDeviceLocation",
                "value": "Lounge"
            },
            {
                "name": "userDeviceName",
                "value": "Lounge"
            }
        ],
        "maxAllowedProperties": 16
    },
    {
        "deviceID": "e6761993-3db5-e0cd-b296-24f5a2bef240",
        "lastChangeRevision": 1065,
        "model": {
            "deviceType": "Infrastructure",
            "manufacturer": "Linksys",
            "modelNumber": "WHW03",
            "hardwareVersion": "2",
            "description": "Velop"
        },
        "unit": {
            "serialNumber": "20J20607824005",
            "firmwareVersion": "2.1.19.209783",
            "firmwareDate": "2020-03-25T04:48:53Z"
        },
        "isAuthority": false,
        "nodeType": "Slave",
        "isHomeKitSupported": true,
        "friendlyName": "LINKSYS24005",
        "knownInterfaces": [
            {
                "macAddress": "2A:F5:A2:BE:F2:42",
                "interfaceType": "Unknown"
            },
            {
                "macAddress": "24:F5:A2:BE:F2:40",
                "interfaceType": "Unknown"
            },
            {
                "macAddress": "24:F5:A2:BE:F2:41",
                "interfaceType": "Unknown"
            },
            {
                "macAddress": "2A:F5:A2:BE:F2:43",
                "interfaceType": "Unknown"
            },
            {
                "macAddress": "32:F5:A2:BE:F2:41",
                "interfaceType": "Unknown"
            }
        ],
        "connections": [
            {
                "macAddress": "24:F5:A2:BE:F2:40",
                "ipAddress": "192.168.1.219",
                "ipv6Address": "fe80:0000:0000:0000:26f5:a2ff:febe:f240"
            },
            {
                "macAddress": "24:F5:A2:BE:F2:41",
                "ipAddress": "192.168.20.120"
            }
        ],
        "properties": [
            {
                "name": "userDeviceLocation",
                "value": "Conservatory"
            },
            {
                "name": "userDeviceName",
                "value": "Conservatory"
            }
        ],
        "maxAllowedProperties": 16
    },
    {
        "deviceID": "952f3555-3437-cc36-ed6c-c4411e972eaf",
        "lastChangeRevision": 1094,
        "model": {
            "deviceType": "Infrastructure",
            "manufacturer": "Linksys",
            "modelNumber": "WHW03",
            "description": "Velop"
        },
        "unit": {
            "serialNumber": "20J20M35A20749",
            "firmwareVersion": "2.1.19.209783"
        },
        "isAuthority": false,
        "nodeType": "Slave",
        "isHomeKitSupported": true,
        "knownInterfaces": [
            {
                "macAddress": "C4:41:1E:97:2E:B0",
                "interfaceType": "Unknown"
            },
            {
                "macAddress": "CA:41:1E:97:2E:B2",
                "interfaceType": "Wireless",
                "band": "5GHz"
            },
            {
                "macAddress": "C4:41:1E:97:2E:AF",
                "interfaceType": "Unknown"
            },
            {
                "macAddress": "CA:41:1E:97:2E:B1",
                "interfaceType": "Unknown"
            },
            {
                "macAddress": "D2:41:1E:97:2E:B0",
                "interfaceType": "Unknown"
            }
        ],
        "connections": [
            {
                "macAddress": "C4:41:1E:97:2E:B0",
                "ipAddress": "192.168.20.172"
            },
            {
                "macAddress": "C4:41:1E:97:2E:AF",
                "ipAddress": "192.168.1.121",
                "ipv6Address": "fe80:0000:0000:0000:c641:1eff:fe97:2eaf"
            }
        ],
        "properties": [
            {
                "name": "userDeviceLocation",
                "value": "Dining"
            },
            {
                "name": "userDeviceName",
                "value": "Dining"
            }
        ],
        "maxAllowedProperties": 16
    }
]

Note that 952f3555-3437-cc36-ed6c-c4411e972eaf is the 'Dining' secondary node, with the accessible IP listed in ipAddress.

"backhaulDevices": [
    {
        "deviceUUID": "952f3555-3437-cc36-ed6c-c4411e972eaf",
        "ipAddress": "192.168.1.121",
        "parentIPAddress": "192.168.1.219",
        "connectionType": "Wireless",
        "wirelessConnectionInfo": {
            "radioID": "5GH",
            "channel": 112,
            "apRSSI": -72,
            "stationRSSI": -65,
            "apBSSID": "24:F5:A2:BE:F2:43",
            "stationBSSID": "CA:41:1E:97:2E:B2"
        },
        "speedMbps": "126.833",
        "timestamp": "2024-04-08T08:14:09Z"
    },
    {
        "deviceUUID": "f9d4cb57-0214-2e55-9174-24f5a2bef470",
        "ipAddress": "192.168.1.215",
        "parentIPAddress": "192.168.1.6",
        "connectionType": "Wired",
        "speedMbps": "1024",
        "timestamp": "2024-04-08T08:14:19Z"
    },
    {
        "deviceUUID": "e6761993-3db5-e0cd-b296-24f5a2bef240",
        "ipAddress": "192.168.1.219",
        "parentIPAddress": "192.168.1.6",
        "connectionType": "Wired",
        "speedMbps": "1024",
        "timestamp": "2024-04-08T08:14:12Z"
    }
]

uvjim commented 5 months ago

Now you're asking... It's been ages since I did any work on the library. 😂

I just checked and it doesn't seem to matter for the majority of methods. The reboot one does seem to assume that the first address returned is the one to use.

I can test that independently so I'll address in there.

If it's OK, I'll need a bit of time because life keeps getting in the way. Hopefully I'll get it done this week though.

jeverley commented 5 months ago

Now you're asking... It's been ages since I did any work on the library. 😂

I just checked and it doesn't seem to matter for the majority of methods. The reboot one does seem to assume that the first address returned is the one to use.

I can test that independently so I'll address in there.

If it's OK, I'll need a bit of time because life keeps getting in the way. Hopefully I'll get it done this week though.

Of course, and if there's anything I can do to help let me know.

uvjim commented 5 months ago

Interesting... none of my nodes report a second connection despite at least one of them being wireless (all the others are wired). I'll work from the output you have in this issue. Are you able to test the module on a system outside of HASS? You should just be able to install it using pip. If so it'd be interesting to see what you get with the command...

python -m pyvelop node details "<node name>" --primary-node "<primary node ip>" -vvvv

It should prompt you for the password (same as the one you used for setting up the integration). I'm hoping that it spits out something like this (with debug messages).

Hopefully you'll see two lots of connections. If you can confirm that, I'll look to see if I can flag one of them as the "useable" connection. That way I can make sure that one is used when directing any requests to it.

uvjim commented 5 months ago

@viking2010

Any update on this issue as I'm also getting the same problem.

Are you also running the latest beta of this integration? Are you seeing the timeout issue mentioned or the AttributeError - I'm checking because the AttributeError should have been fixed in the beta.

uvjim commented 5 months ago

@jeverley I've just uploaded a new version of the library 2024.4.1 to PyPI. It should resolve the problem with using the wrong address. I have no easy way of testing as I'm not seeing the issue. However, it doesn't break my environment and still reboots my nodes. If you can test, that would be great.

I'll look to get this integration updated.

jeverley commented 5 months ago

@jeverley I've just uploaded a new version of the library 2024.4.1 to PyPI. It should resolve the problem with using the wrong address. I have no easy way of testing as I'm not seeing the issue. However, it doesn't break my environment and still reboots my nodes. If you can test, that would be great.

I'll look to get this integration updated.

Sorry for the slow reply, I've had a busy start to the week.

I'll get that tested tomorrow and let you know how it goes, also yes I was running the latest previous beta release.

uvjim commented 5 months ago

@jeverley there's no need for you to mess around with Python tomorrow (unless you really want to), I've pushed 2024.4.1b0 which includes all the other changes and bumps the pyvelop version.

I have seen a funny happen with one of my secondary nodes (definitely nothing to do with the library) - since a reboot it has decided that my credentials are invalid even though all other nodes are working fine. It doesn't matter for me as that is a plug-in node that I can reboot in other ways.

Let me know how you get on.

jeverley commented 5 months ago

@jeverley there's no need for you to mess around with Python tomorrow (unless you really want to), I've pushed 2024.4.1b0 which includes all the other changes and bumps the pyvelop version.

I have seen a funny happen with one of my secondary nodes (definitely nothing to do with the library) - since a reboot it has decided that my credentials are invalid even though all other nodes are working fine. It doesn't matter for me as that is a plug-in node that I can reboot in other ways.

Let me know how you get on.

Thanks @uvjim that's resolved the issue and I can successfully restart the node!

I can now also see the correct MAC, IP and IPv6 address under the node's Status attribute, it was showing the .20 connection details previously.

I suspect my mesh might have the secondary subnet as it's using bridge mode (which comes with its own limitations, but the integration is able to expose a lot of parameters/information which are otherwise hidden in the Linksys UI).

I haven't encountered the credentials issue after two successive reboots, however I'll keep an eye out for it - though like you say it likely isn't a library problem anyway.

uvjim commented 5 months ago

@jeverley Brilliant. I'll do a full release later today and get out of this seemingly never ending beta cycle I find myself in. 😂

uvjim commented 5 months ago

Should be fixed by #452. Released in 2024.1.1.

uvjim / linksys_velop

Node reboot button error #451