search

andyb2000 / HACS-husqvarna_automower_ble

HACS custom component for husqvarna_automower_ble
14 stars 3 forks source link

Failed setup, will retry: Data length mismatch. Read 28 bytes of 24- Event 39 #21

Open cybermatte opened 3 months ago

cybermatte commented 3 months ago

Hi,

What have I missed if I get this:

Husqvarna Automower BLE 0.0.9 Unknown Automower Failed setup, will retry: Data length mismatch. Read 28 bytes of 24

[16:21:00][D][esp32_ble_tracker:270]: Starting scan... [16:21:25][I][bluetooth_proxy:282]: [1] [F0:F8:F2:C6:AA:5F] Connecting v3 without cache [16:21:25][D][esp32_ble_tracker:219]: Pausing scan to make connection... [16:21:25][D][esp32_ble_tracker:307]: End of scan. [16:21:25][I][esp32_ble_client:067]: [1] [F0:F8:F2:C6:AA:5F] 0x00 Attempting BLE connection [16:21:25][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_CONNECT_EVT [16:21:25][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_OPEN_EVT [16:21:25][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_SEARCH_CMPL_EVT [16:21:25][I][esp32_ble_client:227]: [1] [F0:F8:F2:C6:AA:5F] Connected [16:21:25][D][esp32_ble_client:188]: [1] [F0:F8:F2:C6:AA:5F] cfg_mtu status 0, mtu 65 [16:21:25][I][esp32_ble_client:333]: [1] [F0:F8:F2:C6:AA:5F] auth complete. remote BD_ADDR: f0f8f2c6aa5f [16:21:25][D][esp32_ble_client:341]: [1] [F0:F8:F2:C6:AA:5F] auth success. address type = 0 auth mode = 1 [16:21:25][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_READ_CHAR_EVT [16:21:25][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_READ_CHAR_EVT [16:21:26][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_READ_CHAR_EVT [16:21:26][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_READ_CHAR_EVT [16:21:26][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_READ_CHAR_EVT [16:21:26][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_REG_FOR_NOTIFY_EVT [16:21:26][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_WRITE_DESCR_EVT [16:21:31][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_WRITE_CHAR_EVT [16:21:31][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_WRITE_CHAR_EVT [16:21:31][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_NOTIFY_EVT [16:21:31][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_WRITE_CHAR_EVT [16:21:31][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_NOTIFY_EVT [16:21:31][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_WRITE_CHAR_EVT [16:21:31][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_WRITE_CHAR_EVT [16:21:31][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_NOTIFY_EVT [16:21:31][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_NOTIFY_EVT [16:21:31][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_WRITE_CHAR_EVT [16:21:31][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_WRITE_CHAR_EVT [16:21:31][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_NOTIFY_EVT [16:21:31][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_NOTIFY_EVT [16:21:31][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_WRITE_CHAR_EVT [16:21:31][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_WRITE_CHAR_EVT [16:21:31][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_NOTIFY_EVT [16:21:31][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_NOTIFY_EVT [16:21:31][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_WRITE_CHAR_EVT [16:21:31][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_WRITE_CHAR_EVT [16:21:31][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_NOTIFY_EVT [16:21:31][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_NOTIFY_EVT [16:21:31][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_WRITE_CHAR_EVT [16:21:31][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_WRITE_CHAR_EVT [16:21:31][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_NOTIFY_EVT [16:21:31][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_NOTIFY_EVT [16:21:31][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_WRITE_CHAR_EVT [16:21:31][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_WRITE_CHAR_EVT [16:21:31][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_NOTIFY_EVT [16:21:31][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_NOTIFY_EVT [16:21:31][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_WRITE_CHAR_EVT [16:21:31][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_WRITE_CHAR_EVT [16:21:31][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_NOTIFY_EVT [16:21:31][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_NOTIFY_EVT [16:21:31][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_WRITE_CHAR_EVT [16:21:31][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_WRITE_CHAR_EVT [16:21:31][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_NOTIFY_EVT [16:21:31][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_NOTIFY_EVT [16:21:31][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_WRITE_CHAR_EVT [16:21:31][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_WRITE_CHAR_EVT [16:21:31][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_NOTIFY_EVT [16:21:31][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_NOTIFY_EVT [16:21:32][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_WRITE_CHAR_EVT [16:21:32][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_WRITE_CHAR_EVT [16:21:32][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_NOTIFY_EVT [16:21:32][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_NOTIFY_EVT [16:21:32][D][esp32_ble_client:110]: [1] [F0:F8:F2:C6:AA:5F] ESP_GATTC_NOTIFY_EVT [16:21:32][D][esp32_ble_client:306]: [1] [F0:F8:F2:C6:AA:5F] Event 39 [16:21:32][I][esp32_ble_client:084]: [1] [F0:F8:F2:C6:AA:5F] Disconnecting. [16:21:32][D][esp-idf:000][BTU_TASK]: W (9788952) BT_HCI: hci cmd send: disconnect: hdl 0x1, rsn:0x13

[16:21:32][D][esp-idf:000][BTU_TASK]: W (9788956) BT_APPL: gattc_conn_cb: if=3 st=0 id=259 rsn=0x16

[16:21:32][D][esp-idf:000][BTU_TASK]: W (9788959) BT_APPL: gattc_conn_cb: if=4 st=0 id=260 rsn=0x16

[16:21:32][D][esp-idf:000][BTU_TASK]: W (9788966) BT_APPL: gattc_conn_cb: if=5 st=0 id=261 rsn=0x16

[16:21:32][D][esp-idf:000][BTU_TASK]: W (9788976) BT_HCI: hcif disc complete: hdl 0x1, rsn 0x16

I have a Husqvarna Automower 310.

cybermatte commented 3 months ago

2024-08-12 16:32:00.625 DEBUG (MainThread) [custom_components.husqvarna_automower_ble] connecting to F0:F8:F2:C6:AA:5F with channel ID 1189179191 2024-08-12 16:32:07.803 DEBUG (MainThread) [custom_components.husqvarna_automower_ble] connected and paired 2024-08-12 16:32:07.870 WARNING (MainThread) [automower_ble.mower] Response failed validation 2024-08-12 16:32:07.944 INFO (MainThread) [custom_components.husqvarna_automower_ble] Connected to Automower: Automower 310 2024-08-12 16:32:07.945 DEBUG (MainThread) [custom_components.husqvarna_automower_ble.coordinator] Polling device 2024-08-12 16:32:08.021 DEBUG (MainThread) [custom_components.husqvarna_automower_ble.coordinator] battery level: 82 2024-08-12 16:32:08.096 DEBUG (MainThread) [custom_components.husqvarna_automower_ble.coordinator] activity: 0 2024-08-12 16:32:08.168 DEBUG (MainThread) [custom_components.husqvarna_automower_ble.coordinator] state: 2 2024-08-12 16:32:08.273 DEBUG (MainThread) [custom_components.husqvarna_automower_ble.coordinator] next_start_time: None 2024-08-12 16:32:08.362 DEBUG (MainThread) [custom_components.husqvarna_automower_ble.coordinator] errorCode: 0 2024-08-12 16:32:08.426 DEBUG (MainThread) [custom_components.husqvarna_automower_ble.coordinator] NumberOfMessages: 50 2024-08-12 16:32:08.497 DEBUG (MainThread) [custom_components.husqvarna_automower_ble.coordinator] RemainingChargingTime: 1113 2024-08-12 16:32:08.596 ERROR (MainThread) [custom_components.husqvarna_automower_ble.coordinator] Unexpected error fetching husqvarna_automower_ble data Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 312, in _async_refresh self.data = await self._async_update_data() ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/config/custom_components/husqvarna_automower_ble/coordinator.py", line 125, in _async_update_data data["statistics"] = await self.mower.command("GetAllStatistics") ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/site-packages/automower_ble/mower.py", line 50, in command response_dict = command.parse_response(response) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/site-packages/automower_ble/protocol.py", line 208, in parse_response raise ValueError( ValueError: Data length mismatch. Read 28 bytes of 24 2024-08-12 16:32:08.599 DEBUG (MainThread) [custom_components.husqvarna_automower_ble.coordinator] Finished fetching husqvarna_automower_ble data in 0.654 seconds (success: False) 2024-08-12 16:32:08.599 DEBUG (MainThread) [custom_components.husqvarna_automower_ble.coordinator] Shutdown

andyb2000 commented 2 months ago

Hi, The data length mismatch was a problem that was changed in the upstream library and is now reflected in the new code I've pushed. Also "Response failed validation" suggests you need to enter a PIN which I have updated my repo, so I'd suggest you delete the integration and re-add it with your mower pin and see if that now works as expected.

erlandp commented 2 months ago

I have the same problem but with a Husqvarna 315.

andyb2000 commented 2 months ago

I have the same problem but with a Husqvarna 315.

If you delete the integration, disable the PIN on your Husqvarna or enter the pin in the integration does that solve the issue? If the integration doesn't prompt for the pin you need to update to the latest in my master repo.

erlandp commented 2 months ago

I have tried deleting and installing the integration again and disabled PIN on the mower. No luck.

cybermatte commented 2 months ago

Deleted the pin and tried with the MAC + deleting the 0 in the pin input box, I do get:

Automower BLE component for HASS Custom component by @andyb2000

2024-09-05 07:10:43.048 DEBUG (MainThread) [custom_components.husqvarna_automower_ble] connecting to F0:F8:F2:C6:AA:5F with channel ID 46828547 and pin 0 2024-09-05 07:10:48.768 DEBUG (MainThread) [custom_components.husqvarna_automower_ble] connected and paired 2024-09-05 07:10:48.844 WARNING (MainThread) [automower_ble.mower] Response failed validation 2024-09-05 07:10:48.934 INFO (MainThread) [custom_components.husqvarna_automower_ble] Connected to Automower: Automower 310 2024-09-05 07:10:48.935 DEBUG (MainThread) [custom_components.husqvarna_automower_ble.coordinator] Polling device 2024-09-05 07:10:49.010 DEBUG (MainThread) [custom_components.husqvarna_automower_ble.coordinator] battery level: 97 2024-09-05 07:10:49.090 DEBUG (MainThread) [custom_components.husqvarna_automower_ble.coordinator] activity: 0 2024-09-05 07:10:49.158 DEBUG (MainThread) [custom_components.husqvarna_automower_ble.coordinator] state: 2 2024-09-05 07:10:49.234 DEBUG (MainThread) [custom_components.husqvarna_automower_ble.coordinator] next_start_time: None 2024-09-05 07:10:49.309 DEBUG (MainThread) [custom_components.husqvarna_automower_ble.coordinator] errorCode: 0 2024-09-05 07:10:49.383 DEBUG (MainThread) [custom_components.husqvarna_automower_ble.coordinator] NumberOfMessages: 50 2024-09-05 07:10:49.460 DEBUG (MainThread) [custom_components.husqvarna_automower_ble.coordinator] RemainingChargingTime: 0 2024-09-05 07:10:49.572 ERROR (MainThread) [custom_components.husqvarna_automower_ble.coordinator] Unexpected error fetching husqvarna_automower_ble data Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 354, in _async_refresh self.data = await self._async_update_data() ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/config/custom_components/husqvarna_automower_ble/coordinator.py", line 129, in _async_update_data data["statistics"] = await self.mower.command("GetAllStatistics") ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/site-packages/automower_ble/mower.py", line 50, in command response_dict = command.parse_response(response) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/site-packages/automower_ble/protocol.py", line 208, in parse_response raise ValueError( ValueError: Data length mismatch. Read 28 bytes of 24 2024-09-05 07:10:49.575 DEBUG (MainThread) [custom_components.husqvarna_automower_ble.coordinator] Finished fetching husqvarna_automower_ble data in 0.640 seconds (success: False) 2024-09-05 07:10:49.576 DEBUG (MainThread) [custom_components.husqvarna_automower_ble.coordinator] Shutdown

erlandp commented 2 months ago

I get the same. Intergration version 0.0.7. PIN disabled (security setting 'Low'). All previously paired devices deleted from mower. I get the same with PIN set (security setting 'High').

2024-09-06 14:13:50.667 DEBUG (MainThread) [custom_components.husqvarna_automower_ble] connecting to 00:81:F9:5E:BB:00 with channel ID 1565583050 and pin 0 2024-09-06 14:13:56.996 DEBUG (MainThread) [custom_components.husqvarna_automower_ble] connected and paired 2024-09-06 14:13:57.202 INFO (MainThread) [custom_components.husqvarna_automower_ble] Connected to Automower: Automower 315 2024-09-06 14:13:57.203 DEBUG (MainThread) [custom_components.husqvarna_automower_ble.coordinator] Polling device 2024-09-06 14:13:57.313 DEBUG (MainThread) [custom_components.husqvarna_automower_ble.coordinator] battery level: 100 2024-09-06 14:13:57.407 DEBUG (MainThread) [custom_components.husqvarna_automower_ble.coordinator] activity: 5 2024-09-06 14:13:57.509 DEBUG (MainThread) [custom_components.husqvarna_automower_ble.coordinator] state: 7 2024-09-06 14:13:57.612 DEBUG (MainThread) [custom_components.husqvarna_automower_ble.coordinator] next_start_time: 2024-09-07 11:00:00+00:00 2024-09-06 14:13:57.714 DEBUG (MainThread) [custom_components.husqvarna_automower_ble.coordinator] errorCode: 0 2024-09-06 14:13:57.843 DEBUG (MainThread) [custom_components.husqvarna_automower_ble.coordinator] NumberOfMessages: 50 2024-09-06 14:13:57.936 DEBUG (MainThread) [custom_components.husqvarna_automower_ble.coordinator] RemainingChargingTime: 653 2024-09-06 14:13:58.031 ERROR (MainThread) [custom_components.husqvarna_automower_ble.coordinator] Unexpected error fetching husqvarna_automower_ble data Traceback (most recent call last): File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 354, in _async_refresh self.data = await self._async_update_data() ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/config/custom_components/husqvarna_automower_ble/coordinator.py", line 129, in _async_update_data data["statistics"] = await self.mower.command("GetAllStatistics") ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/site-packages/automower_ble/mower.py", line 50, in command response_dict = command.parse_response(response) ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ File "/usr/local/lib/python3.12/site-packages/automower_ble/protocol.py", line 208, in parse_response raise ValueError( ValueError: Data length mismatch. Read 28 bytes of 24 2024-09-06 14:13:58.038 DEBUG (MainThread) [custom_components.husqvarna_automower_ble.coordinator] Finished fetching husqvarna_automower_ble data in 0.835 seconds (success: False) 2024-09-06 14:13:58.039 DEBUG (MainThread) [custom_components.husqvarna_automower_ble.coordinator] Shutdown

heau01 commented 1 month ago

+1 on the same problem on a 310. It seems to connect and read info ok (like battery level etc) looking at the logs, but it still fails to set up the integration with “Data length mismatch Read 28 bytes of 24”

andyb2000 commented 1 month ago

Sorry for being out of action a while, I'll take a look and see what I can do, it does look like it's coming from the underlying library itself, so I may just need to code an exception into our HACS integration to avoid the crash

andyb2000 commented 1 month ago

The common error here is the automower 310 and the "GetAllStatistics" command, I wonder if that mower doesn't support that command for some reason and the upstream library is throwing an exception in automower_ble/protocol.py line 207. I'll investigate further but it may be an issue in the upstream. If possible, can you test this outside of Home assistant via the upstream pip library on another linux box, raspberry pi, etc, and see if you get the same behaviour trying to retrieve all statistics and report back? - https://github.com/alistair23/AutoMower-BLE/tree/main

Meanwhile I'll see if I can do anything to make error handling on the integration more robust.

andyb2000 commented 1 month ago

I've added a try except around that command, see if branch issue21 works around it for you. https://github.com/andyb2000/HACS-husqvarna_automower_ble/tree/issue21

erlandp commented 1 month ago

I'll try the both the branch and the library outside of HA as soon as possible. Thank you for your efforts.

phoffi commented 1 month ago

Hi, i had the same issue with Automower 420. With your issue21 repository HA integration is working now (without other statistics, see image below). image Thank you

heau01 commented 1 month ago

Hi, I've also tested to copy coordinator.py from Issue21. Works for me too, the integration was created - Great job @andyb2000 :-) Of course it would be great if all Diagnostics could work in the future! Also it seems logbook is quite chatty going from Docked to Unavailable many hundreds of times in the night when the mower is docked.

Skärmbild 2024-09-30 105319

erlandp commented 1 month ago

I also could configure the integration now, however missing some diagnostics. After a while the connection was lost and has never reconnected even though the mower and BLE gateway are close to each other.

pott3r3r commented 1 month ago

I'm also experiencing same issue:


Source: helpers/update_coordinator.py:354
integration: Husqvarna Automower BLE (documentation, issues)
First occurred: 12:09:04 (6 occurrences)
Last logged: 12:10:30

Unexpected error fetching husqvarna_automower_ble data
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/helpers/update_coordinator.py", line 354, in _async_refresh
    self.data = await self._async_update_data()
                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/config/custom_components/husqvarna_automower_ble/coordinator.py", line 129, in _async_update_data
    data["statistics"] = await self.mower.command("GetAllStatistics")
                         ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/automower_ble/mower.py", line 50, in command
    response_dict = command.parse_response(response)
                    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/automower_ble/protocol.py", line 208, in parse_response
    raise ValueError(
ValueError: Data length mismatch. Read 28 bytes of 24```

Also tried turning PIN off, but it refuses to work.