Alarm not working with 8.3?

[mherger]

Alarm not working with 8.3?

> Shows the Material client shutting down the alarm 99% of the time in all
> 8.x versions.
Does it really _fail_ the alarm, or just log that one statement? Because
we still believe this was a 8.3 only issue...

[mherger]

Alarm not working with 8.3?

> Do note that the SB devices themselves appear to use cometd as well as
> indicated by this log snippet:

But that's ok, isn't it? If you hit power off on the device then the
alarm is expected to stop.

> So it isn't strictly necessary to be using Material, it may also be e.g.

The difference here is that the above is an interaction between the user
and the system, whereas in the case of Material it's an automated
reaction to some state change (a subscription).

[gordonb3]

But are these cometd "playerprefs"?.. I can get various sources reported rather than "ALARM", such as the player itself - pressing pause,
If I try and emulate what I was doing in Material By taking control of the SB Radio under test from a Touch and then release control again I do not see an unknown source with "playerprefs" reported by the alarm.
If I leave the Touch controlling the SB Radio and turn off the Radio after the alarm has succeeded then I see a power request with source reported as "Squeezeplay-fab4"

All the failures I have seen have been with a Stop request and a source including "Playerprefs" and Safari

I don't think it is specific to cometd. The ignore routine inside _alarmEnd is already there so there is a known bug (although the person that knows may have left Logitech a long time ago) with the state change that causes a response that shuts down the alarm. The only thing different here is that we are now seeing an external source accessing this bug and the ignore routine failing to block that auto created request.

When you say occurrences - do you mean actual alarm failures but no cometd shown as the source...

No, my aim was to see a failed alarm so what I meant here is that the alarm did in fact sound and the log showed that the attempt to stop it was successfully blocked by the ignore routine.

[gordonb3]

> Shows the Material client shutting down the alarm 99% of the time in all
> 8.x versions.
Does it really _fail_ the alarm, or just log that one statement? Because
we still believe this was a 8.3 only issue...

> Do note that the SB devices themselves appear to use cometd as well as
> indicated by this log snippet:

But that's ok, isn't it? If you hit power off on the device then the
alarm is expected to stop.

> So it isn't strictly necessary to be using Material, it may also be e.g.

The difference here is that the above is an interaction between the user
and the system, whereas in the case of Material it's an automated
reaction to some state change (a subscription).

See my reaction to Kev. In my view this is simply unfortunate timing of parallel developments and yes it does require a fairly specific environment so the majority of users will not be affected by the bug.

As for the randomness like I mentioned earlier there does appear to be a time factor involved as well. Can't really pinpoint it, but yesterday I couldn't make the alarm fail until I subscribed to a third player in my Material session. The logs are also somewhat puzzling as for every alarm that is being triggered there is an _alarmEnd response but there is always only one, i.e. if the Material client pops up issuing this request 'ALARM' which is expected to show up there doesn't. I mentioned earlier that I suspected this to be a logging issue but in hindsight I think LMS may be blocking multiple prefsync requests issued simultaneously and only serving the one that is first in queue. This makes it plausible that you could never replicate this if you run LMS on a workstation class machine where LMS is likely to win that election every time.

[KeBul]

Todays testing update, No MaterialSkin and MaterialSkin-Test for Craig

I wasn't expecting to do much on this today with other plans afoot, but my wife tested positive for Covid-19 this morning so we are isolating at home.

I decided to short cut my testing plans as well... I'd run almost a day without Material installed, 28 alarms triggered successfully during that period and no failures seen and as Craig had taken the time to produce a MaterialSkin-Test build without the "playprefs unsubscribe" I decided to drop that in and test that.

So far it's looking good, MaterialSkin vTest was installed just after 3pm and the first alarm scheduled for 3:15, 14 alarm triggers later still no failures and I've been adhoc testing all sorts of scenarios around use of Material, including many attempts at how I managed to get it to fail previously.

Alarms are due to start again soon, I've gradually increased the alarms configured - I'm amazed, it's up to 33 now!! I'll carry on testing and then continue tomorrow - there's no guarantee because the failure is so unpredictable, but so far, including the run without Material installed, this must be the most alarms in sequence without a failure I've had since I started testing.

I'll report back again tomorrow.

Kev

[KeBul]

Another day of alarms... no changes to the set up, just alarms set every 15 minutes and some use of MaterialSkin.

41 alarms, no failures, so looking like Craig's proposed tweak in MaterialSkin has helped the situation.

I don't think I can do any more with this current setup, depending how I feel tomorrow I may go back to the released version of Material and see if I can break it again and then try with a different OS/Browser.

Kev

[mherger]

Alarm not working with 8.3?

> 41 alarms, no failures, so looking like Craig's proposed tweak in
> MaterialSkin has helped the situation.
>
> I don't think I can do any more with this current setup, depending how I
> feel tomorrow I may go back to the released version of Material and see
> if I can break it again and then try with a different OS/Browser.

Thank you very much for all your effort! If I may ask for another favor:
would 8.2 really not be impacted by this issue? Can you confirm this
with the added log line somebody suggested?

[gordonb3]

Another day of alarms... no changes to the set up, just alarms set every 15 minutes and some use of MaterialSkin.

41 alarms, no failures, so looking like Craig's proposed tweak in MaterialSkin has helped the situation.

I don't think I can do any more with this current setup, depending how I feel tomorrow I may go back to the released version of Material and see if I can break it again and then try with a different OS/Browser.

Kev

If you could I would appreciate you verifying the patch for the LMS side I posted earlier (with the 'bad' MaterialSkin). Obviously it is good when the current issue gets solved from whatever side but I think the objective should be to stop this forever rather than rely on Craig fixing it all.

[mherger]

Rather than just blocking player-refs notifications we should probably just ignore any player specific notification:

diff --git a/Slim/Utils/Alarm.pm b/Slim/Utils/Alarm.pm
index e6acade08..abf4be8a6 100644
--- a/Slim/Utils/Alarm.pm
+++ b/Slim/Utils/Alarm.pm
@@ -1982,6 +1982,11 @@ sub _alarmEnd {
                main::DEBUGLOG && $isDebug && $log->debug('Ignoring self-created request');
                return;
        }
+       elsif ($source && $source !~ m|^/[a-z0-9]+/slim/request| && $source =~ m|^/[a-z0-9]+/slim/\w+/(?:[0-9a-f]:){5}[0-9a-f]|i) {
+               warn Data::Dump::dump($request, 'Alarm: ignored event');
+               main::DEBUGLOG && $isDebug && $log->debug('Ignoring notification to subscriber');
+               return;
+       }
        elsif ($source) {
                warn Data::Dump::dump($request, 'Alarm: fired event');
                $log->error("Unknown source: $source");

Would anybody be able to apply this and test? I think that (most) interactive actions taken by a user would be `/abc213/slim/request`, whereas notification come with a MAC address in the source element. As notifications already are in response to some action we should ignore them.

[KeBul]

Thank you very much for all your effort! If I may ask for another favor:
would 8.2 really not be impacted by this issue? Can you confirm this
with the added log line somebody suggested?

Honestly it's a pleasure to be able to help.

So thinking about how I've managed to reproduce the issue under 8.3 has made me realise that any claim of it not happening on 8.2 is potentially false because my day to day use of my 8.2 system is nothing like the 8.3 system... mainly because most my players are now on the 8.3 system - it's only the 2 bedroom players that remained on 8.2... and these are very rarely controlled by Material.

Late this afternoon I set up my test player (Spare Radio 2 or SR2) on the 8.2.1 system, Version of material is 3.0.1 same as on the 8.3 system. SB Radio "Back Bedroom" replaces the Lounge player as the in use player that I go back to in Material. Same alarm setup every 15 minutes to play for 5 minutes (timeout).
LMS had been restarted earlier this morning when I'd updated MaterialSkin, the system had been unused since so took that as a decent fresh start.

I let the test run through 4 successful alarms starting at 15:45 - then opened Material and did the usual stuff... here's my test actions/results log...

Moved SR2 to LMS 8.2.1 system

Added 15 minute alarms till 10:30pm tonight using default Web UI

15:45 - Alarm OK - timeout to end
16:00 - Alarm OK - timeout to end
16:15 - Alarm OK - timeout to end
16:30 - Alarm OK - timeout to end

Start Material, v3.0.1 (same as LMS 8.3 system) MacOS/Safari 16

Select SR2 from drop down, then select Back Bedroom which is playing a long playlist…

16:45 - Alarm fail, no stream no fallback alarm
17:00 - Alarm fail, no stream no fallback alarm
17:15 - Alarm fail, no stream no fallback alarm
17:30 - Alarm fail, no stream no fallback alarm
17:45 - Alarm OK - timeout to end

So there you have it, as gordonb3 has found it fails in 8.2 as well.

Here's the failure log file - no extra debug stuff as per Michael's 21 Nov nightly of 8.3 as I have no idea how to add that code to 8.2.1
I've removed most of the lines of searching for next available alarm to make it more readable

[22-11-26 16:45:00.0026] Slim::Utils::Alarm::sound (516) Alarm triggered for Spare Radio 2
[22-11-26 16:45:00.0033] Slim::Utils::Alarm::sound (560) Sounding alarm
[22-11-26 16:45:00.0053] Slim::Utils::Alarm::sound (589) Current Power State: Off
[22-11-26 16:45:00.0092] Slim::Utils::Alarm:ushAlarmScreensaver (1839) Attempting to push into alarm screensaver: . Current mode: INPUT.List
[22-11-26 16:45:00.0100] Slim::Utils::Alarm::sound (609) Current vol: 18 Alarm vol: 18
[22-11-26 16:45:00.0106] Slim::Utils::Alarm::sound (622) Alarm playlist shufflemode: 0
[22-11-26 16:45:00.0119] Slim::Utils::Alarm::sound (628) Alarm playlist url: sounds://_LIVE_bbc_radio_two
[22-11-26 16:45:00.0250] Slim::Utils::Alarm::_setAlarmSubscription (1204) Adding alarm subscription
[22-11-26 16:45:00.0257] Slim::Utils::Alarm::sound (697) Scheduling time out in 300 seconds
[22-11-26 16:45:00.0262] Slim::Utils::Alarm::_startStopTimeCheck (1880) 1 scheduled alarm(s)
[22-11-26 16:45:00.0264] Slim::Utils::Alarm::scheduleNext (1391) Asked to schedule next alarm for Spare Radio 2

[22-11-26 16:45:00.0407] Slim::Utils::Alarm::findNextTime (466) Last alarm due: 16:45:0 26/11/2022
[22-11-26 16:45:00.0409] Slim::Utils::Alarm::scheduleNext (1424) Next alarm is at 17:0:0 26/11/2022
[22-11-26 16:45:00.0411] Slim::Utils::Alarm::scheduleNext (1435) Scheduling alarm
[22-11-26 16:45:00.0414] Slim::Utils::Alarm::_startStopTimeCheck (1880) 2 scheduled alarm(s)
[22-11-26 16:45:00.0469] Slim::Control::Request::renderAsArray (2233) Error: request should set useIxHashes in Slim::Control::Request->new()
[22-11-26 16:45:00.0473] Slim::Control::Request::renderAsArray (2233) Backtrace:

frame 0: Slim::Utils::Log::logBacktrace (/usr/local/slimserver/Slim/Control/Request.pm line 2233)
frame 1: Slim::Control::Request::renderAsArray (/usr/local/slimserver/Slim/Web/Cometd.pm line 940)
frame 2: Slim::Web::Cometd::requestCallback (/usr/local/slimserver/Slim/Web/Cometd.pm line 791)
frame 3: Slim::Web::Cometd::__ANON__ (/usr/local/slimserver/Slim/Control/Request.pm line 2058)
frame 4: (eval) (/usr/local/slimserver/Slim/Control/Request.pm line 2058)
frame 5: Slim::Control::Request::notify (/usr/local/slimserver/Slim/Control/Request.pm line 859)
frame 6: Slim::Control::Request::checkNotifications (/usr/local/slimserver/slimserver.pl line 711)
frame 7: main::idle (/usr/local/slimserver/slimserver.pl line 680)
frame 8: main::main (/usr/local/slimserver/slimserver.pl line 1224)

[22-11-26 16:45:00.0478] Slim::Utils::Alarm::_alarmEnd (1970) _alarmEnd called with request: stop
[22-11-26 16:45:00.0480] Slim::Utils::Alarm::_alarmEnd (1992) Stopping alarm
[22-11-26 16:45:00.0489] Slim::Utils::Alarm:opAlarmScreensaver (1866) Attempting to pop alarm screensaver. Current mode: INPUT.List
[22-11-26 16:45:00.0548] Slim::Control::Request::renderAsArray (2233) Error: request should set useIxHashes in Slim::Control::Request->new()
[22-11-26 16:45:00.0552] Slim::Control::Request::renderAsArray (2233) Backtrace:..

The same backtrace is repeated 5 times

Cheers

Kev

[KeBul]

Saturday's testing results...

Results of Michael's request for me to test under 8.2 is posted above...

But prior to that first thing today on my 8.3 system I removed Craig's MaterialSkin vTest version and re-installed v3.0.1 standard release, then started testing again

Here's my actions/results log for that series:

More alarm testing… Sat 26th
Put released material back on system
9:30 - Alarm OK - timeout to end
Opened Material, usual switch between players, started music on lounge and left monitoring
9:45 - Alarm OK - Turned off in Material from player drop down, left monitoring Lounge (i.e. didn’t actually switch to SR2)
10:00 - Alarm OK - timeout to end, switched to player in Material, then back to Lounge
10:15 - Alarm fail - no screen pop, no fallback, source playerprefs/Safari
10:30 - Alarm fail - no screen pop, no fallback, source playerprefs/Safari
10:45 - Alarm fail - no screen pop, no fallback, source playerprefs/Safari

Failures started on the 3rd Alarm after starting to use Material, unlike the previous two days of testing with no MaterialSkin and then MaterialSkin vTest which produced 69 successful alarms and no failures.

I wanted to try prove my thoughts it could be MacOS/IOS/Safari specific, so I removed my Mac from the network, re-started LMS and continued to test using a Windows 8 machine with Chromium base MS Edge browser, here's my actions/results log for that:

Restart LMS

11:00 - Alarm OK - timeout to end
11:15 - Alarm OK - timeout to end
11:30 - Alarm OK - timeout to end
11:45 - Alarm OK - timeout to end
12:00 - Alarm OK - Opened Material Win8 MS edge - selected SR2, then player pulldown power off, then select Lounge and play
12:15 - Alarm OK
12:30 - Alarm OK - Turned off in Material from player drop down, left monitoring Lounge (i.e. didn’t actually switch to SR2)
12:45 - Alarm OK - timeout to end, switched to player in Material, then back to Lounge
13:00 - Alarm OK - timeout to end, switch to SR2 in M, in drop down turn player on/off, went back to Lounge
13:15 - Alarm OK - Turned off in Material from player drop down, left monitoring Lounge (i.e. didn’t actually switch to SR2)
13:30 - Alarm OK - timeout to end, switched to player in Material, then back to Lounge
13:45 - Alarm triggered to Fallback, turned off on player front panel, on Material switch to SR2 and hit play to play stream - worked OK
turned off SR2 from Material dropdown and change to monitoring Lounge BUT logfile showed a stop request from source “playerprefs"
14:00 - Alarm triggered to Fallback, turned off on player in Material dropdown, logfile showed a stop request from source “playerprefs”. Closed Material web browser.
14:15 - Alarm fail - source playerprefs/MSEdge

So that's that sorted, definitely not OS/Browser specific.

Cheers

Kev

[KeBul]

If you could I would appreciate you verifying the patch for the LMS side I posted earlier (with the 'bad' MaterialSkin). Obviously it is good when the current issue gets solved from whatever side but I think the objective should be to stop this forever rather than rely on Craig fixing it all.

Sorry Gordon (?), been testing all day - just got to this...

Rather than just blocking player-refs notifications we should probably just ignore any player specific notification:

"code removed by KeBul"

Would anybody be able to apply this and test? I think that (most) interactive actions taken by a user would be `/abc213/slim/request`, whereas notification come with a MAC address in the source element. As notifications already are in response to some action we should ignore them.

Happy to do both of these, but just want to confirm how

I've struggled to find Alarm.pm in my LMS install, but have now found one in:

/usr/local/slimserver/Slim/Utils

But a search is also showing Alarm.pm in other places are these all the same file? is it just a case of editing your changes into that file?

I'm using pCP with LMS installed and Filezilla to view/search for the files.

Cheers

Kev

[Paul Webster]

/usr/local/slimserver/Slim/Utils

That is the one - see the first line of mherger's "diff".

[KeBul]

That is the one - see the first line of mherger's "diff".

Cheers Paul - was multi-tasking with cooking dinner, so didn't spot that.

Kev

[KeBul]

Alrighty, editing finished - back to testing.

I've put gordonb3's fix from post #154 into Alarm.pm and am currently testing that.

Michael's code from post #173 is in Alarm_MH.pm waiting in the wings for its turn to be tested.

I'll report back

Kev