Alpha 9 - APA102 LED's still fail to clear properly

[flexage]

• I confirm that this is an issue rather than a question.

Bug report

I reported an issue previously during Alpha 8 about APA-102 LED's retaining what looked like their last frame when clearing an effect/colour/source (Issue #1007).

Sorry, it looks like I confirmed this as fixed to soon...

I ended up staying on Alpha 6 for a while as it was the most stable for me, but recently I have been trying Alpha 9.

I am still getting the last frame of the video effect/color/protobuffer output 'sticking' on my LED's when the source is cleared.

I checked the "Refresh Time" on the LED Device, as you mentioned on the old issue, and it was set to 5000 - must have been a default, potentially from a very old (pre-alpha) version, I had to enable expert settings to find it. I tried setting it to 0 but it didn't have an effect on the problem.

Steps to reproduce

See old issue #1007

What is expected?

See old issue #1007

What is actually happening?

See old issue #1007

System

[Lord-Grey]

@flexage You to validate that I got it right, it is Test 3 from #1007 that does not work.
Test1 and Test 2 are ok.
Correct?

[damnms]

i guess i hit the same problem, running a esp32 with WLED which works like a charm, but hyperion has problems talking to the LEDs

[Joeboyc2]

Hi All,

I think i have i similar, possible related issue to this.

My issue manifests itself when the "LED Device" switch if togged off, The LEDs will stay on.
If I switch it back on, I can control the Light again, but the only way to turn them of is to set a black colour

Happy to supply logs if that will help troubleshooting this further

[Lord-Grey]

Happy to supply logs if that will help troubleshooting this further

@Joeboyc2 Yes, please.

[Joeboyc2]

Hey @Lord-Grey ,
Not much in the logs im afraid :| when toggling the "LED device" switch all i get in the log is as follows:

Jan 27 21:51:57 Hyperion hyperiond[489]: 2021-01-27T21:51:57.993 hyperiond COMPONENTREG : <DEBUG> ComponentRegister.cpp:36:setNewComponentState() | LED device: disabled
Jan 27 21:53:07 Hyperion hyperiond[489]: 2021-01-27T21:53:07.659 hyperiond COMPONENTREG : <DEBUG> ComponentRegister.cpp:36:setNewComponentState() | LED device: enabled
Jan 27 21:53:13 Hyperion hyperiond[489]: 2021-01-27T21:53:13.291 hyperiond COMPONENTREG : <DEBUG> ComponentRegister.cpp:36:setNewComponentState() | LED device: disabled

I have the logging set to Debug so I guess there isn't really an error happening as such.
Is there anything more i can do to get some better data about this issue?

[flexage]

@Lord-Grey I am very sorry for becoming quiet on this issue, things have been busy.

The problem still persists, I will do my best to document the steps that I am taking that lead to it below, along with some logs.

Brief LED Hardware Overview

I have 2 Hyperion LED Instances

The first is APA102 LED's wired to the Pi

The second is a WLED over the LAN

The steps below cause the same issue on both instances simultaneously, although it seems very occasionally the WLED strip will recover and return to the desired source successfully, however this is not very often at all.

Steps To Reproduce:

1. Set a colour via JSON-RPC (Home Assistant) - Priorty 128: The desired colour is shown correctly on the LEDs

2. Enable Grabbing via Android App (Protobuf - Hyperion Android Grabber App) - Priority 100: The grabber feed is shown correctly on the LEDs

3. Disable Grabbing via Android App - The protobuf source is removed from the sources list, the active source should now return to the JSON-RPC one with the Priority of 128, but instead, the LED's are showing the last state of the Protobuf/Android Grabber (frozen on the last frame)

I have noticed that at this point, if I resend the colour via JSON-RPC, the LEDs will update to show the colour - so the issue might be around reverting back to the previous source, rather than clearing the source? Maybe, maybe not.

##Logs:

 2021-02-04T00:50:25.990Z [hyperiond WEBSOCKET] (DEBUG) (WebSocketClient.cpp:204:sendClose()) send close: 1000 
 2021-02-04T00:50:27.364Z [hyperiond WEBSOCKET] (DEBUG) (WebSocketClient.cpp:30:WebSocketClient()) New connection from ::ffff:10.1.0.145
 2021-02-04T00:50:27.365Z [hyperiond WEBSOCKET] (DEBUG) (JsonAPI.cpp:81:handleInstanceSwitch()) Client '::ffff:10.1.0.145' switch to Hyperion instance 0
 2021-02-04T00:50:29.590Z [hyperiond WEBSOCKET] (DEBUG) (JsonAPI.cpp:1054:handleLoggingCommand()) log streaming activated for client ::ffff:10.1.0.145
 2021-02-04T00:50:29.613Z [hyperiond WEBSOCKET] (DEBUG) (JsonAPI.cpp:1063:handleLoggingCommand()) log streaming deactivated for client  ::ffff:10.1.0.145
 2021-02-04T00:51:22.855Z [hyperiond PROTOSERVER] (DEBUG) (ProtoServer.cpp:68:newConnection()) New connection from ::ffff:10.1.0.146
 2021-02-04T00:51:22.894Z [hyperiond HYPERION] (DEBUG) (PriorityMuxer.cpp:161:registerInput()) Register new input 'Proto@::ffff:10.1.0.146/PROTOSERVER' with priority 100 as inactive
 2021-02-04T00:51:22.895Z [hyperiond HYPERION] (DEBUG) (PriorityMuxer.cpp:251:setInputImage()) Priority 100 is now active
 2021-02-04T00:51:22.895Z [hyperiond HYPERION] (DEBUG) (PriorityMuxer.cpp:351:setCurrentTime()) Set visible priority to 100
 2021-02-04T00:51:22.894Z [hyperiond HYPERION] (DEBUG) (PriorityMuxer.cpp:161:registerInput()) Register new input 'Proto@::ffff:10.1.0.146/PROTOSERVER' with priority 100 as inactive
 2021-02-04T00:51:22.896Z [hyperiond HYPERION] (DEBUG) (PriorityMuxer.cpp:251:setInputImage()) Priority 100 is now active
 2021-02-04T00:51:22.897Z [hyperiond HYPERION] (DEBUG) (PriorityMuxer.cpp:351:setCurrentTime()) Set visible priority to 100
 2021-02-04T00:51:43.299Z [hyperiond HYPERION] (DEBUG) (PriorityMuxer.cpp:270:clearInput()) Removed source priority 100
 2021-02-04T00:51:43.299Z [hyperiond HYPERION] (DEBUG) (PriorityMuxer.cpp:270:clearInput()) Removed source priority 100
 2021-02-04T00:51:43.300Z [hyperiond HYPERION] (DEBUG) (PriorityMuxer.cpp:351:setCurrentTime()) Set visible priority to 128
 2021-02-04T00:51:43.301Z [hyperiond HYPERION] (DEBUG) (PriorityMuxer.cpp:351:setCurrentTime()) Set visible priority to 128
 2021-02-04T00:51:43.303Z [hyperiond PROTOSERVER] (DEBUG) (ProtoClientConnection.cpp:75:disconnected()) Socket Closed
 2021-02-04T00:52:01.879Z [hyperiond WEBSOCKET] (DEBUG) (WebSocketClient.cpp:204:sendClose()) send close: 1000 
 2021-02-04T00:52:02.788Z [hyperiond WEBSOCKET] (DEBUG) (WebSocketClient.cpp:30:WebSocketClient()) New connection from ::ffff:10.1.0.145
 2021-02-04T00:52:02.788Z [hyperiond WEBSOCKET] (DEBUG) (JsonAPI.cpp:81:handleInstanceSwitch()) Client '::ffff:10.1.0.145' switch to Hyperion instance 0
 2021-02-04T00:52:04.308Z [hyperiond WEBSOCKET] (DEBUG) (JsonAPI.cpp:1054:handleLoggingCommand()) log streaming activated for client ::ffff:10.1.0.145

##System Info:

Hyperion Server: 
- Build:           (HEAD detached at 83338dc3) (Paulchen Panther-ca50487e/83338dc3-1605733041)
- Build time:      Nov 18 2020 21:34:12
- Git Remote:      https://github.com/hyperion-project/hyperion.ng
- Version:         2.0.0-alpha.9
- UI Lang:         auto (BrowserLang: en-GB)
- UI Access:       default
- Avail Capt:      dispmanx,v4l2,framebuffer,qt
- Database:        read/write

Hyperion Server OS: 
- Distribution:   Raspbian GNU/Linux 10 (buster)
- Architecture:   arm
- CPU Model:      ARMv7 Processor rev 4 (v7l)
- CPU Type:       Raspberry Pi 3 Model B Rev 1.3
- CPU Revision:   a02083
- CPU Hardware:   BCM2835
- Kernel:         linux (4.19.97-v7+ (WS: 32))
- Qt Version:     5.7.1
- Python Version: 3.5.3
- Browser:        Mozilla/5.0 (Macintosh; Intel Mac OS X 11_1_0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/88.0.4324.96 Safari/537.36 

[Lord-Grey]

@flexage Thank you very much for the detailed explanation and walkthrough of the error scenario.
I can now at minimum explain to why you face the outcome.

If you set a Color effect (via JSON or UI) , only one update is send to the LEDs.
Depending on the LEDs they maintain that stable state or hyperion ensures this via refresh timeings.

When you now stream via grabbing, the new feed of updates overwrite the color set before.
After the continuous stream of grabber updates is stopped, the color effect is not reissued.
Unfortunately, the source list let you assume that a continuous stream of color is happening....

Given that you are using APA102 hyperion's LED refresh feature kicks in (as these devices do not maintain a stable state).
The LED device routine refreshes the APA with the last color set (which is the one from the grabber) every 1 second (assume you run with the default time).

Hopefully this provides you at minimum a good understanding, why your LEDs show a stable state of the last update from your grabber rather than falling back to some state happening in the past....

[flexage]

@Lord-Grey Thank you for the detailed explanation of what is happening under the hood. I can follow what you are saying, and why this is happening.

My only question is, is this desired behaviour?

On the other side of it, after the information you have provided I think I can implement a workaround on my Home Automation platform to reissue the solid colour command after the grabber is disabled. So thank you again for taking a look into this.

[Lord-Grey]

My only question is, is this desired behaviour?

I would agree that the current presentation, showing a color in the source list and not getting back to it, is counter intuitive.
As I do not have an immediate answer how to solve it, I at minimum wanted to give you and others the background of the behavior....

[Paulchen-Panther]

@Lord-Grey @flexage
I cannot reproduce this behavior with the LED Device 'File'. So it does not seem to be a fundamental problem with the PriorityMuxer.
The output (Powershell terminal on the left) shows the particular color that should be sent to the connected device. The two terminals on the right, I used to set the color with priority 128 and the flat connection (QT Grabber) with priority 128. You can clearly see that after terminating the flat Connection the color is set to red again.
The conclusion is that the error is in the LEDDevice management.

[Lord-Grey]

@Paulchen-Panther Thanks for the Test.
Let me have a look again.
It might be that the color update is ignored, if the update come within the device’s Latchtime.
And key is that the test is done with smoothing being off.

[Joeboyc2]

Hi Guys,
I think another key thing that should be looked in to here is the fact that when toggling the "LED Device" switch, the lights also stay on.

I attempted to look through the code myself as i feel this might be something to do with the power off mechanism, but it really didn't find much :(

[flexage]

@Paulchen-Panther thank you for investigating this issue against the file device, your findings confirmed the behaviour I was expecting to see, namely that when taking away a higher priority source, it will return to a lesser priority source, if one is active.

@Lord-Grey Did your investigations around the Color Update and Device Latchtime reveal anything?

Are there any steps I can take on my end to assist?

[Lord-Grey]

Fixed by #1361

[flexage]

@Lord-Grey @Paulchen-Panther Thank you to all involved for the work on producing a fix for this issue 🎉

I have several Hyperion installations around my house, but it was only the installation on my main living room tv that had apa102's connected, and suffered from this issue.

As the issue had taken quite some time to identify and resolve (Sept 2020 to Nov 2021) I had moved the main living room tv over to HyperHDR after not experiencing the same issue when testing with it.

I somehow missed the release in November 2021, so was unaware that a fix had been released until having just seen a github notification about this months release.

So I just wanted to apologise for being late in thanking you for the fix!

I see the last 2 releases have been substantial ones - I am eager to test them out!

Thanks again! 🙏