Integration crashes when `Effect Length` is set to 1

[dbuezas]

Describe the bug

Not that there should be any light with 1 led...

Debug log

2022-12-21 12:53:30.656 ERROR (MainThread) [custom_components.uniled.coordinator] Error fetching SP611E data: SP611E: Data Update failed

[monty68]

I am unable to replicate the issue, can you provide full debug logs when the crash occurs, thanks

[dbuezas]

The leds make a quick flash and then go back to their previous state. From what I see, it looks like the controller is the one crashing, not the integration.

2022-12-22 18:17:31.870 DEBUG (MainThread) [custom_components.uniled.lib.classes] : Set Effect Length: 1
2022-12-22 18:17:31.870 DEBUG (MainThread) [custom_components.uniled.lib.ble_device] SP611E: Sending 1 command(s)
2022-12-22 18:17:31.870 DEBUG (MainThread) [custom_components.uniled.lib.ble_retry] SP611E: Starting retry loop
2022-12-22 18:17:31.870 DEBUG (MainThread) [custom_components.uniled.lib.ble_retry] SP611E: Attempt 1
2022-12-22 18:17:31.870 DEBUG (MainThread) [custom_components.uniled.lib.ble_device] SP611E: Sending command: a0680101
2022-12-22 18:17:33.926 DEBUG (MainThread) [custom_components.uniled.lib.ble_device] SP611E: Update
2022-12-22 18:17:33.927 DEBUG (MainThread) [custom_components.uniled.lib.ble_device] SP611E: Sending 1 command(s)
2022-12-22 18:17:33.927 DEBUG (MainThread) [custom_components.uniled.lib.ble_retry] SP611E: Starting retry loop
2022-12-22 18:17:33.927 DEBUG (MainThread) [custom_components.uniled.lib.ble_retry] SP611E: Attempt 1
2022-12-22 18:17:33.927 DEBUG (MainThread) [custom_components.uniled.lib.ble_device] SP611E: Sending command: a07000
2022-12-22 18:17:33.929 DEBUG (MainThread) [custom_components.uniled.lib.ble_device] SP611E: Awaiting status notification
2022-12-22 18:17:35.931 DEBUG (MainThread) [custom_components.uniled.lib.ble_device] SP611E: Timeout waiting for status notification
2022-12-22 18:17:35.931 ERROR (MainThread) [custom_components.uniled.coordinator] Error fetching SP611E data: SP611E: Data Update failed
2022-12-22 18:17:35.933 DEBUG (MainThread) [custom_components.uniled.coordinator] Finished fetching SP611E data in 2.007 seconds (success: False)
2022-12-22 18:17:37.700 DEBUG (MainThread) [custom_components.uniled.lib.ble_device] SP611E: Device disconnected (expected: False); RSSI: -59
2022-12-22 18:18:05.459 DEBUG (MainThread) [custom_components.uniled.lib.ble_device] SP611E: Update
2022-12-22 18:18:05.459 DEBUG (MainThread) [custom_components.uniled.lib.ble_device] SP611E: Connecting; RSSI: -59
2022-12-22 18:18:05.850 DEBUG (MainThread) [custom_components.uniled.lib.ble_device] SP611E: Connected
2022-12-22 18:18:05.850 DEBUG (MainThread) [custom_components.uniled.lib.ble_device] SP611E: Read Characteristic: 0000ffe1-0000-1000-8000-00805f9b34fb (Handle: 2): Vendor specific
2022-12-22 18:18:05.850 DEBUG (MainThread) [custom_components.uniled.lib.ble_device] SP611E: Write Characteristic: 0000ffe1-0000-1000-8000-00805f9b34fb (Handle: 2): Vendor specific
2022-12-22 18:18:05.850 DEBUG (MainThread) [custom_components.uniled.lib.ble_device] SP611E: Subscribe to notifications
2022-12-22 18:18:06.148 DEBUG (MainThread) [custom_components.uniled.lib.ble_device] SP611E: Sending 1 command(s)
2022-12-22 18:18:06.149 DEBUG (MainThread) [custom_components.uniled.lib.ble_retry] SP611E: Starting retry loop
2022-12-22 18:18:06.149 DEBUG (MainThread) [custom_components.uniled.lib.ble_retry] SP611E: Attempt 1
2022-12-22 18:18:06.149 DEBUG (MainThread) [custom_components.uniled.lib.ble_device] SP611E: Sending command: a07000
2022-12-22 18:18:06.153 DEBUG (MainThread) [custom_components.uniled.lib.ble_device] SP611E: Awaiting status notification
2022-12-22 18:18:06.368 DEBUG (MainThread) [custom_components.uniled.lib.ble_device] SP611E: Handle:2, notification data: 534301100f0100be02330719ffb4690010027368
2022-12-22 18:18:06.368 DEBUG (MainThread) [custom_components.uniled.lib.ble_banlanx2] SP611E: Packet 1 - payload size: 15, message length: 16
2022-12-22 18:18:06.397 DEBUG (MainThread) [custom_components.uniled.lib.ble_device] SP611E: Handle:2, notification data: 534302100100
2022-12-22 18:18:06.398 DEBUG (MainThread) [custom_components.uniled.lib.ble_banlanx2] SP611E: Packet 2 - payload size: 1, payload so far: 16, message length: 16 (16)
2022-12-22 18:18:06.398 DEBUG (MainThread) [custom_components.uniled.lib.ble_banlanx2] SP611E: Good Status Message: 0100be02330719ffb469001002736800
2022-12-22 18:18:06.398 DEBUG (MainThread) [custom_components.uniled.lib.classes] : Set Status: UNILEDStatus(power=True, mode=None, level=51, white=None, rgb=(255, 180, 105), rgb2=None, effect=190, fxtype=0, speed=7, length=25, direction=None, input=0, gain=16, chip_type=None, chip_order=2, segment_count=None, segment_length=None, extra={})
2022-12-22 18:18:06.400 INFO (MainThread) [custom_components.uniled.coordinator] Fetching SP611E data recovered
2022-12-22 18:18:06.400 DEBUG (MainThread) [custom_components.uniled.coordinator] Finished fetching SP611E data in 0.941 seconds (success: True)

[monty68]

It does look that way, although it could simply be for your particular version of the device the commands are too close together, I did see some of this behavior when developing and added in a number of small delays to the light entity to give the devices time to react. If you feel confident in editing a python file, you could try:

1. Open number.py into an editor
2. Goto to line 130, it should read await self.coordinator.async_request_refresh()
3. Prefix the line with a hash so it reads #await self.coordinator.async_request_refresh()
4. Save the file, restart HA
5. Retest changing speed to 1 and see if it crashes, may take a bit longer for the UI to update

If this works, I can try adding small delays after changing speed/effect length, etc. before requesting a device status update which may solve your issue.

[dbuezas]

Oh, it wasn't because of multiple requests in quick succession. I did multiple tries and made sure only one command was sent (see gif in the first message)

[monty68]

After sending the Speed change the integration requests a status update from the device, it is the time between this that concerns me and the suggestion above would confirm this either way.

[dbuezas]

I see. Wouldn't this be incompatible with it not failing with 2, but consistently failing woth 1? Also with the fact that the light flashes? (Particularly this makes me suspect the led controller is crashing)

[dbuezas]

Ok, you are indeed right, commenting out the request for a refresh fixes it! 🙇 I guess the flash was a second command sent quickly after by the integration when it crashed then. Interestingly, the number does still update instantly.

It looks like requesting an update isn't necessary, since you already update the state in the setter here https://github.com/monty68/uniled/blob/main/custom_components/uniled/lib/classes.py#L724

[dbuezas]

Regarding why it only crashes when I sent 1 and not any other number, that beats me.

[monty68]

It looks like requesting an update isn't necessary, since you already update the state in the setter here https://github.com/monty68/uniled/blob/main/custom_components/uniled/lib/classes.py#L724

This update refreshes the UI without any confirmation from the device. However, reviewing all the code for some reason only the number entities were forcing a device status refresh, which seems pointless, causing your issue, so they have now been removed.

Regarding why it only crashes when I sent 1 and not any other number, that beats me.

Me too but as I said, I have seen some strange behavior from all of these SP devices, not just the SP611Es

The latest release (v1.0.0) fixes this going forward.