Duplicate priorities-update in certain circumstances

[dermotduffy]

2.0.0-alpha.7

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

Bug report

Under certain circumstances a spurious priorities-update API response is generated.

Steps to reproduce

1. Subscribe to priorities-update (in one terminals):

$ echo '{"command":"serverinfo", "subscribe":["priorities-update"] }' | nc hyperion 19444

2. Set an effect (in another terminal):

$ echo '{"origin": "Home Assistant", "priority": 128, "effect": {"name": "Cold mood blobs"}, "command": "effect"}' | nc hyperion 19444

3. Observe the priority updates in the first terminal.

What is expected?

At most two priority updates (one priority becoming non-visible, another becoming visible).

What is actually happening?

{"command":"priorities-update","data":{"priorities":[{"active":false,"componentId":"EFFECT","origin":"Home Assistant@::ffff:10.100.0.20","owner":"Cold mood blobs","priority":128,"visible":false},{"active":true,"componentId":"V4L","origin":"System","owner":"V4L2:/dev/video0","priority":240,"visible":true}],"priorities_autoselect":true}}
{"command":"priorities-update","data":{"priorities":[{"active":true,"componentId":"EFFECT","origin":"Home Assistant@::ffff:10.100.0.20","owner":"Cold mood blobs","priority":128,"visible":true},{"active":true,"componentId":"V4L","origin":"System","owner":"V4L2:/dev/video0","priority":240,"visible":false}],"priorities_autoselect":true}}
{"command":"priorities-update","data":{"priorities":[{"active":true,"componentId":"EFFECT","origin":"Home Assistant@::ffff:10.100.0.20","owner":"Cold mood blobs","priority":128,"visible":true},{"active":true,"componentId":"V4L","origin":"System","owner":"V4L2:/dev/video0","priority":240,"visible":false}],"priorities_autoselect":true}}

Note the last two updates are identical.

A similar effect can be seen on clear:

$ echo '{"priority": 128, "command": "clear"}' | nc hyperion 19444
{"command":"clear","success":true,"tan":0}

... will then produce two identical updates ...

{"command":"priorities-update","data":{"priorities":[{"active":true,"componentId":"V4L","origin":"System","owner":"V4L2:/dev/video0","priority":240,"visible":true}],"priorities_autoselect":true}}
{"command":"priorities-update","data":{"priorities":[{"active":true,"componentId":"V4L","origin":"System","owner":"V4L2:/dev/video0","priority":240,"visible":true}],"priorities_autoselect":true}}

System

Hyperion Server:

• Build: master (GitHub-f719f0b/838092e-1597257777)
• Build time: Aug 19 2020 04:01:56
• Git Remote: https://github.com/hyperion-project/hyperion.ng.git
• Version: 2.0.0-alpha.7
• UI Lang: auto (BrowserLang: en-US)
• UI Access: default
• Avail Capt: dispmanx,v4l2,framebuffer,qt

Hyperion Server OS:

• Distribution: Raspbian GNU/Linux 10 (buster)
• Arch: arm
• Kernel: linux (5.4.51+ (WS: 32))
• Browser: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/84.0.4147.135 Safari/53

[Paulchen-Panther]

@dermotduffy
Can you please test my PR #1036 ?

[dermotduffy]

@Paulchen-Panther Verified fixed in your PR. Thanks!

[dermotduffy]

@Paulchen-Panther This still appears to be a problem (brand new build from head):

Subscribe (in 1 terminal):

$ telnet hyperion 19444
Escape character is '^]'.
{"command": "serverinfo", "subscribe": ["priorities-update"]}

Send a color command (in another terminal):

echo '{"origin": "Home Assistant", "priority": 128, "color": [10,100,255], "command": "color"}' | nc hyperion 19444

Output I get (in the first terminal), two identical calls back:

{"command":"priorities-update","data":{"priorities":[{"active":true,"componentId":"COLOR","origin":"Home Assistant@IP","priority":128,"value":{"HSL":[0,1,0.5196154713630676],"RGB":[10,100,255]},"visible":true},{"active":false,"componentId":"V4L","origin":"System","priority":240,"visible":false}],"priorities_autoselect":true}}
{"command":"priorities-update","data":{"priorities":[{"active":true,"componentId":"COLOR","origin":"Home Assistant@IP","priority":128,"value":{"HSL":[0,1,0.5196154713630676],"RGB":[10,100,255]},"visible":true},{"active":false,"componentId":"V4L","origin":"System","priority":240,"visible":false}],"priorities_autoselect":true}}

[Paulchen-Panther]

@dermotduffy

No problem. I'll look again.

[Paulchen-Panther]

Could you please test PR #1062 ? Many Thanks.

[dermotduffy]

Thanks @Paulchen-Panther . That works in that only a single color priority is produced (hurray!), however I notice that the problem of no priority update on effect is back again:

Subscribe (in 1 terminal):

$ telnet hyperion 19444
Escape character is '^]'.
{"command": "serverinfo", "subscribe": ["priorities-update"]}

Send an effect update (in another terminal):

$ echo '{"command":"effect", "effect":{"name":"Red mood blobs" }, "priority":50, "origin":"My Fancy App"}' | nc hyperion 19444
{"command":"effect","success":true,"tan":0}

I'd expect a priority update, yet I receive none.

[Paulchen-Panther]

thanks for the feedback. I hadn't tested the effect. take care of that.

[Paulchen-Panther]

@dermotduffy
Another test? PR #1062

[dermotduffy]

Sorry to be the bearer of bad news -- now it works for effect, but is back to broken for color. The below is output from a single color set command:

{"command":"priorities-update","data":{"priorities":[{"active":true,"componentId":"COLOR","origin":"Home Assistant@IP","priority":12,"value":{"HSL":[0,1,0.5313801765441895],"RGB":[16,100,255]},"visible":true},{"active":true,"componentId":"EFFECT","origin":"My Fancy App@IP","owner":"Red mood blobs","priority":50,"visible":false},{"active":true,"componentId":"COLOR","origin":"Home Assistant@IP","priority":128,"value":{"HSL":[0,1,0.5313801765441895],"RGB":[16,100,255]},"visible":false},{"active":false,"componentId":"V4L","origin":"System","priority":240,"visible":false}],"priorities_autoselect":true}}
{"command":"priorities-update","data":{"priorities":[{"active":true,"componentId":"COLOR","origin":"Home Assistant@IP","priority":12,"value":{"HSL":[0,1,0.5313801765441895],"RGB":[16,100,255]},"visible":true},{"active":true,"componentId":"EFFECT","origin":"My Fancy App@IP","owner":"Red mood blobs","priority":50,"visible":false},{"active":true,"componentId":"COLOR","origin":"Home Assistant@IP","priority":128,"value":{"HSL":[0,1,0.5313801765441895],"RGB":[16,100,255]},"visible":false},{"active":false,"componentId":"V4L","origin":"System","priority":240,"visible":false}],"priorities_autoselect":true}}

[Paulchen-Panther]

I cannot reproduce the duplicate issues.
Here I am using the generated artifacts from PR:

[dermotduffy]

Hmm. Thanks @Paulchen-Panther . That gif shows what I would have expected. Let me play around and make sure I'm not making some user error on my side. Report back shortly.

[dermotduffy]

Fresh build, from head + PR1062. I get a single update, but only if the priority is lower than what is present. See gif:

[dermotduffy]

(Same happens with effects -- it appears the correct number of updates are generated, but only if the new priority "wins").

[Paulchen-Panther]

Give it another try on PR #1062 ?

[dermotduffy]

Same. See below:

[dermotduffy]

Build verification:

Hyperion Server: 
- Build:       fix-993-maybe-this-time (Paulchen Panther-65c45042/871ac095-1603649159)
- Build time:  Oct 25 2020 18:38:11
- Git Remote:  https://github.com/hyperion-project/hyperion.ng.git
- Version:     2.0.0-alpha.8
- UI Lang:     auto (BrowserLang: en-US)
- UI Access:   default
- Avail Capt:  dispmanx,v4l2,framebuffer,qt

871ac09 is your most recent commit on #1062

[Paulchen-Panther]

I cannot reproduce it. For me the background effect runs with prio 254 and the X11 grabber with prio 250. Here is the result:

[dermotduffy]

Thanks @Paulchen-Panther . I have tried another fresh rebuild, and all sorts of various settings, priorities, removing my hyperion.db, etc.

Here is my main finding: It only fails to work if the new priority is the same as the old priority AND the new priority is the lowest/active priority. In all other cases it works correctly,

This still does not not match what your gif is showing (where you use priority 100, and don't appear to have a lower priority in the serverinfo output), so right now I have no explanation for the difference we are seeing.

[Paulchen-Panther]

I see exactly the same in your example as in my example. First a new priority 100 (color) is registered and an output appears. Then I overwrite the Prio 100 with a different color. The Prio 100 is also the currently active color for me.
If you can give me a reproducible order, I can look again.

[dermotduffy]

• Start hyperiond fresh.
• Only System @ 254 on the remote control listings on the UI.
• Send this (it will work):

echo '{"origin": "Home Assistant", "priority": 100, "color": [1,1,1], "command": "color"}' | nc hyperion 19444

• Send this (it will not work -- no priority update):

echo '{"origin": "Home Assistant", "priority": 100, "color": [2,2,2], "command": "color"}' | nc hyperion 19444

[This was reproducible for me]

Hyperion Server: 
- Build:       pr1062 (Paulchen Panther-65c45042/871ac095-1603649159)
- Build time:  Oct 27 2020 03:29:39
- Git Remote:  https://github.com/hyperion-project/hyperion.ng.git
- Version:     2.0.0-alpha.8
- UI Lang:     auto (BrowserLang: en-US)
- UI Access:   expert
- Avail Capt:  dispmanx,v4l2,framebuffer,qt

Hyperion Server OS: 
- Distribution: Raspbian GNU/Linux 10 (buster)
- Architecture: arm
- CPU Model:    ARMv7 Processor rev 3 (v7l)
- CPU Type:     Raspberry Pi 4 Model B Rev 1.2
- CPU Revision: b03112
- CPU Hardware: BCM2711
- Kernel:       linux (5.4.51-v7l+ (WS: 32))
- Browser:      Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/86.0.4240.111 Safari/537.36 

If you still cannot reproduce it, do you happen to have an arml7:buster hyperiod binary I could try from your build, just to rule out something weird happening in the build process?

[Paulchen-Panther]

Thank you for the detailed description. I'll get back to you if there are any improvements.

[dermotduffy]

@Paulchen-Panther I dug into this a little this evening, and discovered the same thing it seems you did: an uninitialized variable. I'm guessing we were getting different values, and this was causing the different behavior we were seeing.

Either way: I've done a new build with your latest fix on #1062 and it looks good to me!

[dermotduffy]

@Paulchen-Panther Unrelated: Given the volume of fixes there's been on the API code (thank you!), would it be at all possible to get a new official Hyperion build after this change is in? (I have a number of parts of the Home Assistant integration work ready that depend on these fixes being in an official build).

Thank you for considering.

[Paulchen-Panther]

I will advise me internally with the other members.
Also a big thank you for the constant testing and feedback. 👍

[dermotduffy]

@Paulchen-Panther Quick check: do you have any news on a release ETA as discussed here? Just want to know roughly, so I can plan accordingly. Thank you!