Bugzilla – Bug 15943
'ghost' fallback alarms in SqueezePlay >7.4.2
Last modified: 2010-04-08 17:26:09 UTC
Created attachment 6688 [details] log file showing a ghost alarm at 18:10 Users are facing 'Ghost' Alarms (see http://forums.slimdevices.com/showthread.php?p=527506#post527506) at times when they didn't schedule an alarm. One user posted a log (attached to this bug) showing this bug and for me it looks like this can happen when a prior alarm is canceled with the 'pause' button. This closes the alarm-popup (because on upcoming 'set'-alarm comes from the server) but doesn't reset the internal 'alarmInProgress' variable I think. Later when the user runs into a server dis-/reconnection the AlarmSnoozeApplet still thinks an alarm is running and as (of course) there is no audio, the sledgehammer will start a fallback alarm. Relevant sections in the logs are the following ----------- AlarmSnoozeApplet.lua:255 notify_playerModeChange: player (LocalPlayer {nyx.protogenoi.com}) mode has been changed to pause [...] AlarmSnoozeApplet.lua:315 notify_serverDisconnected: SlimServer {mysqueezebox.com} - server alarm in progress, but player still connected to SlimServer {mysqueezebox.com} [...] Mar 23 18:10:31 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:222 alarm_sledgehammerRearm: audio not in good shape while alarm is firing. restart timer asynchronously at 1.5secs ----------- Note that you never see a log entry from the _alarmOff-method, which proves, that the alarmInProgress is not reset. You should be able to reproduce the bug with the following pattern (though I didn't test it myself due to time constraints) - schedule an alarm, exit it with pause - restart your router (mysqueezebox disconnects/reconnects) - a 'ghost' alarm should start ?
One important addition from the original poster: He doesn't stop the alarm by pressing pause, but lets it timeout. This will lead to the same trouble with alarmInProgress variable.
(In reply to comment #1) > One important addition from the original poster: > He doesn't stop the alarm by pressing pause, but lets it timeout. > > This will lead to the same trouble with alarmInProgress variable. That's correct and it is interesting to notice that the second user experiencing this ghost radio is doing the same thing: http://forums.slimdevices.com/showpost.php?p=527603&postcount=26 Shouldn't the radio properly stop the alarm after it timeout rather than pause it? Thanks Ludo
*** This bug has been confirmed by popular vote. ***
I Have it too. I usually let My SqueezeboxRadio turns the alarm off and I just change the volume nothing else and then form time to time I have my SQRadio on when I come back from work... I hear my SQRadio turning off before I live the morning. I am just connected to mysqueebox.com Thank you.
Ben, if this hasn't gotten fixed by the time you go on Vaca, please assign this back to me to figure out what to with it. Thanks.
I don't doubt that this is happening to people, but my first few test cases show behavior exactly as expected. This debug is for an active alarm that is allowed to time out. This alarm is set for being an every day alarm. Correct state behavior at time of alarm timeout is to see alarmInProgress go from server to nil, and alarmState go from active to set. Also, fallback timer should show that it's running again with a wakeup of a bit less than a day worth of seconds. This is what was observed as well. Mar 25 15:02:59 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:80 ---------------------------------- Mar 25 15:02:59 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:81 **** self.alarmInProgress: server Mar 25 15:02:59 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:82 **** status.audioState: 0 Mar 25 15:02:59 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:83 **** self.localPlayer.alarmState: active Mar 25 15:02:59 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:84 **** RTC fallback running?: false Mar 25 15:03:00 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:276 notify_playerModeChange: player (LocalPlayer {Radio}) mode has been changed to pause Mar 25 15:03:00 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:278 notify_playerModeChange: - audioState is 0 Mar 25 15:03:00 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:115 notify_playerAlarmState received for LocalPlayer {Radio} with alarmState of set Mar 25 15:03:00 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:117 **************************** notify_playerAlarmState received: set 1269633720 Mar 25 15:03:00 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:608 stopping decodeStatePoller Mar 25 15:03:00 squeezeplay: INFO applet.AlarmSnooze - AlarmSnoozeApplet.lua:194 storing epochseconds of next alarm: 1269633720 Mar 25 15:03:00 squeezeplay: INFO squeezeplay.applets - AppletManager.lua:708 store settings: AlarmSnooze Mar 25 15:03:00 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:657 _startTimer: starting RTC fallback alarm timer (86350000) Mar 25 15:03:00 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:80 ---------------------------------- Mar 25 15:03:00 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:81 **** self.alarmInProgress: nil Mar 25 15:03:00 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:82 **** status.audioState: 0 Mar 25 15:03:00 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:83 **** self.localPlayer.alarmState: set Mar 25 15:03:00 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:84 **** RTC fallback running?: true Mar 25 15:03:00 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:87 **** RTC time: 86350 Mar 25 15:03:01 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:80 ---------------------------------- Mar 25 15:03:01 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:81 **** self.alarmInProgress: nil Mar 25 15:03:01 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:82 **** status.audioState: 0 Mar 25 15:03:01 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:83 **** self.localPlayer.alarmState: set Mar 25 15:03:01 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:84 **** RTC fallback running?: true Mar 25 15:03:01 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:87 **** RTC time: 86349 Mar 25 15:03:02 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:80 ---------------------------------- This debug is for an active alarm that times out, that is not set for the following day. Correct state behavior at time of alarm timeout is to see alarmInProgress go from server to nil, and alarmState go from active to nil. The fallback timer should not be running after alarm timeout here. This is what was observed as well. Mar 25 15:05:58 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:80 ---------------------------------- Mar 25 15:05:58 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:81 **** self.alarmInProgress: server Mar 25 15:05:58 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:82 **** status.audioState: 1 Mar 25 15:05:58 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:83 **** self.localPlayer.alarmState: active Mar 25 15:05:58 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:84 **** RTC fallback running?: false Mar 25 15:05:59 squeezeplay: INFO applet.SlimMenus - SlimMenusApplet.lua:441 _menuSink(1) nil menuDirective: add isCurrentServer:true Mar 25 15:05:59 squeezeplay: INFO applet.SlimMenus - SlimMenusApplet.lua:713 hiding any 'connecting to server' popup after menu response from current server, SlimServer {mediumspicy} Mar 25 15:05:59 squeezeplay: INFO applet.AlarmSnooze - AlarmSnoozeApplet.lua:239 notify_playerLoaded(LocalPlayer {Radio}) Mar 25 15:05:59 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:245 notify_playerLoaded: called while `server` alarm in progress Mar 25 15:05:59 squeezeplay: INFO applet.ChooseMusicSource - ChooseMusicSourceApplet.lua:543 Hiding popup, exists?: nil Mar 25 15:05:59 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:80 ---------------------------------- Mar 25 15:05:59 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:81 **** self.alarmInProgress: server Mar 25 15:05:59 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:82 **** status.audioState: 0 Mar 25 15:05:59 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:83 **** self.localPlayer.alarmState: active Mar 25 15:05:59 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:84 **** RTC fallback running?: false Mar 25 15:06:00 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:276 notify_playerModeChange: player (LocalPlayer {Radio}) mode has been changed to pause Mar 25 15:06:00 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:278 notify_playerModeChange: - audioState is 0 Mar 25 15:06:00 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:115 notify_playerAlarmState received for LocalPlayer {Radio} with alarmState of none Mar 25 15:06:00 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:117 **************************** notify_playerAlarmState received: none nil Mar 25 15:06:00 squeezeplay: INFO applet.AlarmSnooze - AlarmSnoozeApplet.lua:156 no alarm set, clearing settings Mar 25 15:06:00 squeezeplay: INFO squeezeplay.applets - AppletManager.lua:708 store settings: AlarmSnooze Mar 25 15:06:00 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:608 stopping decodeStatePoller Mar 25 15:06:00 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:80 ---------------------------------- Mar 25 15:06:00 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:81 **** self.alarmInProgress: nil Mar 25 15:06:00 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:82 **** status.audioState: 0 Mar 25 15:06:00 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:83 **** self.localPlayer.alarmState: nil Mar 25 15:06:00 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:84 **** RTC fallback running?: false Mar 25 15:06:01 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:80 ----------------------------------
Created attachment 6702 [details] patch to call _alarmOff() for pause and soft power off I've had no luck at all reproducing this, but from analyzing Stefan's log the critical problem is clearly that self.alarmInProgress is not unsetting itself, then mysb.com hiccupping and causing the sledgehammer to kick in when it shouldn't. This patch now calls _alarmOff() (which in turn unsets self.alarmInProgress) in two more places. When the alarm window is up and pause is hit, and when a playerPower of 'off' notification comes to the applet. I will also post the full file. If anyone who is experiencing this problem can scp the patched file to their radio and try to reproduce it would be much appreciated. Without the ability to reproduce the error, I'm only guessing that this is a full fix for the issue.
Created attachment 6703 [details] patched AlarmSnoozeApplet.lua file This is the full patched file, plus one notable exception. I've uncommented the statusPoller(). This will cause the state variables in question to dump to the messages file every second. If the problem can be reproduced, this should give additional information as to what's going on, particularly with self.alarmInProgress. Note that what's likely more important is not when the ghost alarm sounds, but when the previous alarm is dismissed. for anyone that wants to try, to get this file to your radio: Settings->Advanced->Remote Login enable it and copy down the ip address download this file and save it as AlarmSnoozeApplet.lua from a linux or OS X terminal, type scp AlarmSnoozeApplet.lua root@the.radios.ip.address:/usr/share/jive/applets/AlarmSnooze/. or from windows use something like WinSCP to copy it to that location on your radio. reboot the radio, set an alarm, and try to reproduce.
Ben, I'm able to reproduce it with 7.4.2 (testing with a local server as its easier for me). 1) schedule a repeating (!) alarm 2) hit pause when alarm triggers 3) shutdown server => fallback alarm You only used a single alarm and get the following event *** notify_playerAlarmStatereceived: none nil which resets the alarmInProgress-state. If you have a repeating or second alarm, then a when you hit pause (or I guess on a timeout) you get: *** notify_playerAlarmState received: set 1269711360 from the server which doesn't run through code that resets alarmInProgress. Looking at the patch (didn't try it out) I guess you solved the pause-problem, for alarm-timeouts I'm not sure (does a timeout equal a power off ??). I'd suggest thinking about the window-close-listener again we had somewhen inbetween 7.4.1 and 7.4.2. When the alarm windows is closing and (alarmInProgress != nil && alarmInProgress!='snooze') it should call _alarmOff. This would solve the pause and timeout problem and maybe even some future things we again don't think of.
Stefan, a couple clarification points.. I >>*** notify_playerAlarmState received: set 1269711360 >>from the server which doesn't run through code that resets alarmInProgress. I don't believe that to be true. when the server sends a playerAlarmState of 'set', alarmInProgress is set to nil unless an 'rtc' alarm is in progress. Note that when these ghost alarms are being heard, the debug shows self.alarmInProgress as 'server', not 'rtc', and the decode state poller is clearly running since that is what is kicking off the ghost alarm. elseif alarmState == 'set' then self:_stopDecodeStatePoller() if self.alarmInProgress ~= 'rtc' then self.alarmInProgress = nil end end I tested the scenario you put in the last comment. I can't reproduce a ghost alarm, and the state variables are exactly as I'd expect-- alarmInProgress gets set to nil after the 'set' comes in for alarmState notification. AlarmSnoozeApplet.lua:80 ---------------------------------- Mar 26 13:39:12 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:81 **** self.alarmInProgress: server Mar 26 13:39:12 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:82 **** status.audioState: 1 Mar 26 13:39:12 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:83 **** self.localPlayer.alarmState: active Mar 26 13:39:12 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:84 **** RTC fallback running?: false Mar 26 13:39:12 squeezeplay: INFO applet.SlimMenus - SlimMenusApplet.lua:441 _menuSink(1) nil menuDirective: add isCurrentServer:true Mar 26 13:39:12 squeezeplay: INFO applet.SlimMenus - SlimMenusApplet.lua:713 hiding any 'connecting to server' popup after menu response from current server, SlimServer {mediumspicy} Mar 26 13:39:12 squeezeplay: INFO applet.AlarmSnooze - AlarmSnoozeApplet.lua:239 notify_playerLoaded(LocalPlayer {Radio}) Mar 26 13:39:12 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:245 notify_playerLoaded: called while `server` alarm in progress Mar 26 13:39:12 squeezeplay: INFO applet.ChooseMusicSource - ChooseMusicSourceApplet.lua:543 Hiding popup, exists?: nil Mar 26 13:39:12 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:260 notify_playerModeChange: player (LocalPlayer {Radio}) mode has been changed to pause Mar 26 13:39:12 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:262 notify_playerModeChange: - audioState is 1 Mar 26 13:39:12 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:115 notify_playerAlarmState received for LocalPlayer {Radio} with alarmState of set Mar 26 13:39:12 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:117 **************************** notify_playerAlarmState received: set 1269715140 Mar 26 13:39:13 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:592 stopping decodeStatePoller Mar 26 13:39:13 squeezeplay: INFO applet.AlarmSnooze - AlarmSnoozeApplet.lua:194 storing epochseconds of next alarm: 1269715140 Mar 26 13:39:13 squeezeplay: INFO squeezeplay.applets - AppletManager.lua:708 store settings: AlarmSnooze Mar 26 13:39:13 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:641 _startTimer: starting RTC fallback alarm timer (86397000) Mar 26 13:39:13 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:80 ---------------------------------- Mar 26 13:39:13 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:81 **** self.alarmInProgress: nil Mar 26 13:39:13 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:82 **** status.audioState: 1 Mar 26 13:39:13 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:83 **** self.localPlayer.alarmState: set Mar 26 13:39:13 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:84 **** RTC fallback running?: true Mar 26 13:39:13 squeezeplay: WARN applet.AlarmSnooze - AlarmSnoozeApplet.lua:87 **** RTC time: 86397 Something else has to be at play here.
Just to note, the debug in the previous comment is with the stock 7.5 radio firmware, not the patched version from this bug. I compared 7.5 AlarmSnoozeApplet to 7.4.2 AlarmSnoozeApplet and these areas of code are identical. The window listener to run _alarmOff() when the popup is exited could be re-added, but when that code was in a few months ago it drew fiery criticism as being the wrong approach, esp. from those that felt there should be an option to not have that window appear at all.
I'm leaving on vacation for a week and want to summarize what my understanding of the issue is so if someone else internally takes a stab at it before I get back. 1. the core issue is that the state variable self.alarmInProgress is erroneously set to 'server' when no alarm is in progress. 2. the users that have reported this issue typically have had an alarm go off and dismissed it either with hitting the pause key or letting the alarm timeout 3. Stefan's original log shows a server hiccup in between the an alarm correctly went off and the "ghost" fallback alarm firing at a later time. That is what triggers the "ghost", but the seeds for it happening happened IMO at step 2. I believe the key to fixing the issue is making sure the right things happen at the time of the alarm getting stopped. Notably, that should be to make sure that _alarmOff() is called appropriately, which should always set self.alarmInProgress correctly to nil. Thus far I have not once reproduced the issue with 7.5 SBS r30423 and 7.5 Squeezebox Radio firmware r8661. The patch attached to this bug adds a bit of code to make sure _alarmOff() is called in a few more particular situations (hitting pause when the window is up and soft power off), but I'm not confident it covers all conditions seen by users experiencing this issue.
>> I don't believe that to be true. >> when the server sends a playerAlarmState of 'set', alarmInProgress is set to >> nil unless an 'rtc' alarm is in progress. No - not in 7.4.2 I have a SVN checkout with Revision 8401 of AlarmSnoozeApplet (latest revision in the 7.4.x branch) there the code looks: ------ elseif alarmState == 'set' then log:warn('an upcoming alarm is set, but none is currently active') self:_stopDecodeStatePoller() end ------ so the alarmInProgress is not reset. On trunk (revision 8626) I can see the code Ben posted above (with the resetting of alarmInProgress) indeed. So my conclusion: this bug might be fixed already in 7.5, but not in 7.4.x. I'm pretty sure QA should be able to reproduce the bug with 7.4.x firmware and the steps from comment #9
Aha, you're right. Thanks Stefan. I think this might be fixed in 7.5 already after that assessment. Would love to hear if this issue is being seen by anyone running 7.5 firmware on their radio. My guess is no...
relevant code is in revision 8455 see diff: http://svn.slimdevices.com/jive/7.5/trunk/squeezeplay/src/squeezeplay/share/applets/AlarmSnooze/AlarmSnoozeApplet.lua?r1=8408&r2=8455 this should be merged back to 7.4.x-branch then I think the bug will be fixed for the pause-key and timeout as well.
How can I test out the 7.5 branch? btw, I run ubuntu on my server. Thanks Ludo
This appears to have been fixed in 7.5.0, and that version will be released shortly.
This bug has been marked fixed in a released version of Squeezebox Server or the accompanying firmware or mysqueezebox.com release. If you are still seeing this issue, please let us know!