Bugzilla – Bug 11652
Previous alarm goes off on Boom even though it was changed
Last modified: 2009-10-05 14:32:04 UTC
My Boom's alarm had been set to go off at 10:00 am on Sat/Sun. Saturday morning around 2am, I changed that alarm to go off at 12:00 pm (noon). After the change, I went back to check that it was indeed changed to 12pm, and it was. This morning, the alarm went off at 10am anyway. After this, I checked, both on SqueezeCenter and SqueezeNetwork, and the new alarm said it was indeed set for 12:00pm, but it had gone off at 10am.
Did you change the alarm from the Player (boom) UI or from the Web (SN/SC) UI
I changed the alarm from the Boom UI. I did this again last night, and the same thing happened this morning (i.e. previous alarm went off). After it went off this time, I changed to one of the presets (a radio station) and listened to it, but when the NEW alarm time came around, it interrupted the currently playing stream and played the alarm Favorite again. So it played the alarm at BOTH the old alarm time and the new alarm time, even though only the new alarm time was set for that alarm. The old alarm time did not show as any existing alarm time in the Boom UI, yet it went off. - Tim
It would be very helpful to see a log of this with debug for player.alarmclock enabled. The log should ideally cover the changing of an alarm time and the alarm(s) going off.
Max - can you point me to how to do this? What log are you speaking of? SqueezeCenter log? Some log internal to the Boom? How to I enable the logging you mention? - Tim
SqueezeCenter > Settings > Advanced > Log set Player.Alarmclock to DEBUG wait for the error then attach the portion of the log file that corresponds with the alarm times to this bug Log file is located at: "C:\Documents and Settings\All Users\Application Data\SqueezeCenter\server.log"
I will try that and report back.
There has been no movement on this bug, and QA has not been able to replicate. Please reopen the bug if you still see the issue, and can provide logs.
I am reopening this, as I am able to replicate. I will post logs this weekend. - Tim
Still trying to generate this condition. Wasn't able to yet, but only tried one test. Will try several more and report back.
Well, I haven't been able to recreate this. I will keep alarm debugging on for awhile and see if it happens again. If so I'll reopen this again, but for now, we can reclose it. - Tim
I've seen this bug too. I set the alarm for 12pm the previous week, changed it to 1pm for Monday, and it went off and both 12pm and 1pm. The problem is intermittent enough that I won't have really good debug logs for a while, but I did notice one thing when I turned on debug logs. Even though I only have one alarm configured, Squeezecenter believed there were two. And even after deleting all alarms outright, squeezecenter believed there was still one lurking. This appears to be the $alarmsScheduled variable. Restarting squeezecenter fixed it. I've also had somewhat flaky wireless lately. Is it possible that if a client disappeared and reappeared occasionally that $alarmsScheduled might go out of sync and trigger something bad? Relevant debug log from me adding and deleting only a single alarm included below: [09-08-18 02:17:39.5639] Slim::Utils::Alarm::save (996) Saving alarm. [09-08-18 02:17:39.5644] Slim::Utils::Alarm::save (1016) Alarm saved with id ccb1710e Rescheduling alarms... [09-08-18 02:17:39.5647] Slim::Utils::Alarm::scheduleNext (1340) Asked to schedule next alarm for Boom [09-08-18 02:17:39.5649] Slim::Utils::Alarm::scheduleNext (1346) Previous scheduled alarm wasn't triggered. Clearing nextAlarm and killing timer [09-08-18 02:17:39.5653] Slim::Utils::Alarm::_startStopTimeCheck (1807) 1 scheduled alarm(s) [09-08-18 02:17:39.5656] Slim::Utils::Alarm::findNextTime (457) Potential next time found: 13:0:0 18/8/2009 [09-08-18 02:17:39.5659] Slim::Utils::Alarm::scheduleNext (1373) Next alarm is at 13:0:0 18/8/2009 [09-08-18 02:17:39.5662] Slim::Utils::Alarm::scheduleNext (1385) Scheduling alarm [09-08-18 02:17:39.5664] Slim::Utils::Alarm::_startStopTimeCheck (1807) 2 scheduled alarm(s) [09-08-18 02:17:39.5667] Slim::Utils::Alarm::setRTCAlarm (1419) Asked to set rtc alarm for Boom [09-08-18 02:17:39.5671] Slim::Utils::Alarm::setRTCAlarm (1448) Setting RTC alarm to 46800, volume 50 [09-08-18 02:17:51.8659] Slim::Utils::Alarm::save (996) Saving alarm. [09-08-18 02:17:51.8664] Slim::Utils::Alarm::save (1016) Alarm saved with id ccb1710e Rescheduling alarms... [09-08-18 02:17:51.8667] Slim::Utils::Alarm::scheduleNext (1340) Asked to schedule next alarm for Boom [09-08-18 02:17:51.8669] Slim::Utils::Alarm::scheduleNext (1346) Previous scheduled alarm wasn't triggered. Clearing nextAlarm and killing timer [09-08-18 02:17:51.8673] Slim::Utils::Alarm::_startStopTimeCheck (1807) 1 scheduled alarm(s) [09-08-18 02:17:51.8676] Slim::Utils::Alarm::findNextTime (457) Potential next time found: 12:0:0 18/8/2009 [09-08-18 02:17:51.8679] Slim::Utils::Alarm::scheduleNext (1373) Next alarm is at 12:0:0 18/8/2009 [09-08-18 02:17:51.8682] Slim::Utils::Alarm::scheduleNext (1385) Scheduling alarm [09-08-18 02:17:51.8684] Slim::Utils::Alarm::_startStopTimeCheck (1807) 2 scheduled alarm(s) [09-08-18 02:17:51.8687] Slim::Utils::Alarm::setRTCAlarm (1419) Asked to set rtc alarm for Boom [09-08-18 02:17:51.8691] Slim::Utils::Alarm::setRTCAlarm (1448) Setting RTC alarm to 43200, volume 50
Max: Can you have a look at comment 11, your comments?
Oh, I should note that I'm running Ubuntu Jaunty AMD64, on the latest squeezecenter from the "testing" apt repository, which right now is 7.3.4~28180
How do I properly reopen this bug? OK, it happened for me again yesterday (Wednesday). In fact, it happened twice, and I wasn't even trying. I had a late night, and was changing my alarm a few times. It was at 1pm, I changed it to noon and 9:30am before just shutting it off. My final settings were: Alarm 1: On 12:00 PM Mon Tue Thu Fri Repeat Alarm: Yes Alarm 2: Off 9:30 AM Wed Repeat Alarm: no But the alarm went off at 9:30am and 1pm. And, I suspect this in the logs is a bad sign :P > grep Alarm\ triggered server.log [09-08-19 09:30:00.0012] Slim::Utils::Alarm::sound (510) Alarm triggered for Boom [09-08-19 13:00:00.0008] Slim::Utils::Alarm::sound (510) Alarm triggered for Boom [09-08-19 13:00:00.0242] Slim::Utils::Alarm::sound (510) Alarm triggered for Boom [09-08-19 13:00:00.0507] Slim::Utils::Alarm::sound (510) Alarm triggered for Boom [09-08-19 13:00:00.0698] Slim::Utils::Alarm::sound (510) Alarm triggered for Boom [09-08-19 13:00:00.0870] Slim::Utils::Alarm::sound (510) Alarm triggered for Boom [09-08-19 13:00:00.1038] Slim::Utils::Alarm::sound (510) Alarm triggered for Boom [09-08-19 13:00:00.1266] Slim::Utils::Alarm::sound (510) Alarm triggered for Boom [09-08-19 13:00:00.1489] Slim::Utils::Alarm::sound (510) Alarm triggered for Boom [09-08-19 13:00:00.1757] Slim::Utils::Alarm::sound (510) Alarm triggered for Boom [09-08-19 13:00:00.3703] Slim::Utils::Alarm::sound (510) Alarm triggered for Boom [09-08-19 13:00:00.3999] Slim::Utils::Alarm::sound (510) Alarm triggered for Boom [09-08-19 13:00:00.4310] Slim::Utils::Alarm::sound (510) Alarm triggered for Boom [09-08-19 13:00:00.4530] Slim::Utils::Alarm::sound (510) Alarm triggered for Boom [09-08-19 13:00:00.4791] Slim::Utils::Alarm::sound (510) Alarm triggered for Boom [09-08-19 13:00:00.5021] Slim::Utils::Alarm::sound (510) Alarm triggered for Boom [09-08-19 13:00:00.5277] Slim::Utils::Alarm::sound (510) Alarm triggered for Boom [09-08-19 13:00:00.5498] Slim::Utils::Alarm::sound (510) Alarm triggered for Boom [09-08-19 13:00:00.5751] Slim::Utils::Alarm::sound (510) Alarm triggered for Boom Logs will be attached shortly. There's obviously something weird going on in there.
Created attachment 5643 [details] Log of alarm going off (see 2009-08-19 09:45 and 13:00)
OK, I've duplicated the bug (or at least one way to trigger it) and tested a fix. I am not much of a Perl weenie, nor have I hacked squeezecenter much before, so grain of salt, etc. When wifi is flaky, squeezecenter forgets the existence of my Boom, but it doesn't clear the timer for the next alarm. When wifi returns, the Boom is seen again and Slim::Utils::Alarm::loadAlarms is called. It creates a new alarm list and adds a new timer, but still doesn't forget the old one. $alarmScheduled going higher than the correct number was a good clue about this. I simulated this as follows: 0. clear all alarms * debug logs say $alarmsScheduled == 0 1. set an alarm * debug logs say $alarmsScheduled == 1 2. unplug the boom 3. wait until both the main web UI and the alarm web UI (which seem to catch up at different times) forget the boom exists 4. plug boom back in * debug logs say $alarmsScheduled == 2 (WRONG) 5. delete alarm * debug logs say $alarmsScheduled == 1 (WRONG) 6. wait for original alarm time * alarm goes off (WRONG) I can see a few ways to fix this. I think the alarm code could use some restructuring, but I wanted a small fix, so I just had squeezecenter explicitly forget alarms when it's forgetting a client. This seems to do the trick. At step 3, squeezecenter clears the extra alarm, and steps 4-6 work as they should. Patch will be attached shortly. I didn't notice any changes to the alarm code in 7.4, so I suspect the patch will apply ok to that too.
Created attachment 5667 [details] Manoj's unofficial patch for this bug
I'll take a look at this patch.
I found another bug closely related to this one, which is that when the Boom is disconnected, its timers remain just like its old alarms do. My patch cleared out the old alarms and nextAlarm, but not the old setRTCTimer timer. So that timer goes off, sees no nextAlarm (because of v1 of my patch) and clears out the RTC alarm. This means that if my Boom lost wireless, the built-in RTC alarm would also not go off. And, since setRTCTimer sets a new timer for 24 hours later to rerun it, the RTC alarm on the Boom always gets re-cleared. I haven't seen this happen yet (my wifi has been pretty good lately), but I'm seeing things like this since I still have alarm debugging turned on: [09-08-26 12:30:00.7138] Slim::Utils::Alarm::scheduleNext (1393) Next alarm is at 12:30:0 27/8/2009 [09-08-26 12:30:00.7139] Slim::Utils::Alarm::scheduleNext (1405) Scheduling alarm [09-08-26 12:30:00.7141] Slim::Utils::Alarm::_startStopTimeCheck (1827) 1 scheduled alarm(s) [09-08-26 12:30:00.7143] Slim::Utils::Alarm::_startStopTimeCheck (1831) Starting time checker task [09-08-26 12:30:00.7145] Slim::Utils::Alarm::setRTCAlarm (1439) Asked to set rtc alarm for Boom [09-08-26 12:30:00.7148] Slim::Utils::Alarm::setRTCAlarm (1468) Setting RTC alarm to 45000, volume 50 and later... [09-08-26 19:43:07.0491] Slim::Utils::Alarm::setRTCAlarm (1439) Asked to set rtc alarm for Boom [09-08-26 19:43:07.0495] Slim::Utils::Alarm::setRTCAlarm (1478) Clearing RTC alarm when I know I wasn't interacting with squeezecenter. And when I look 24 hours earlier in the logs: [09-08-25 19:43:07.0042] Slim::Utils::Alarm::setRTCAlarm (1439) Asked to set rtc alarm for Boom [09-08-25 19:43:07.0487] Slim::Utils::Alarm::setRTCAlarm (1478) Clearing RTC alarm and 24 hours before that: [09-08-24 19:43:07.0032] Slim::Utils::Alarm::setRTCAlarm (1439) Asked to set rtc alarm for Boom [09-08-24 19:43:07.0037] Slim::Utils::Alarm::setRTCAlarm (1478) Clearing RTC alarm and 24 hours before that: [09-08-23 19:43:07.0008] Slim::Utils::Alarm::forgetClient (1283) Forgetting saved alarms for Boom [09-08-23 19:43:07.0011] Slim::Utils::Alarm::scheduleNext (1360) Asked to schedule next alarm for Boom [09-08-23 19:43:07.0014] Slim::Utils::Alarm::scheduleNext (1366) Previous scheduled alarm wasn't triggered. Clearing nextAlarm and killing timer [09-08-23 19:43:07.0017] Slim::Utils::Alarm::_startStopTimeCheck (1827) 0 scheduled alarm(s) [09-08-23 19:43:07.0019] Slim::Utils::Alarm::_startStopTimeCheck (1836) Stopping time checker task [09-08-23 19:43:07.0023] Slim::Utils::Alarm::scheduleNext (1413) No future alarms found [09-08-23 19:43:07.0025] Slim::Utils::Alarm::setRTCAlarm (1439) Asked to set rtc alarm for Boom [09-08-23 19:43:07.0029] Slim::Utils::Alarm::setRTCAlarm (1478) Clearing RTC alarm Before my first patch, what would've happened I guess is that the timer would've set a possibly incorrect alarm as the RTC alarm, so it was a bug no matter what. It doesn't help that my added call to scheduleNext() triggers a setRTCAlarm but if I understand this code correctly, there would've been a timer even without that. So the fix I applied was to just clear any existing setRTCAlarm timer after scheduleNext. This still seems hacky though, and I haven't done enough testing to confirm for sure that the problem has gone away. I'm just going to wait 24 hours and check the logs then. The real fix here is that the code that forgets and remembers clients should either *completely* forget and *completely* re-remember the client rather than half-measures, or just reuse old client objects when they come back. It'd be nice if the timers that belong to a client's alarm were clustered around one thing that could be cleared easily. I didn't want to dive into a more wholesale change of this code for many many reasons. v2 of my patch coming up.
Created attachment 5753 [details] Manoj's unofficial patch for this bug v2
== Auto-comment from SVN commit #28390 to the slim repo by andy == == https://svn.slimdevices.com/slim?view=revision&revision=28390 == Fixed bug 11652, patch from Manoj Kasichainula to clean up alarm timers when forgetting a client
This bug has been marked as fixed in the 7.4.0 release version of SqueezeBox Server! * SqueezeCenter: 28672 * Squeezebox 2 and 3: 130 * Transporter: 80 * Receiver: 65 * Boom: 50 * Controller: 7790 * Radio: 7790 Please see the Release Notes for all the details: http://wiki.slimdevices.com/index.php/Release_Notes If you haven't already, please download and install the new version from http://www.logitechsqueezebox.com/support/download-squeezebox-server.html If you are still experiencing this problem, feel free to reopen the bug with your new comments and we'll have another look.