Bugzilla – Bug 9534
Backup Alarm fails to go off
Last modified: 2009-10-05 14:31:20 UTC
I had an alarm set today to connect to KCRW Live. I woke up independently and saw (roughly) this screen: NOW PLAYING (CONNECTING...) KCRW Live I waited a few minutes, then 12 minutes after the alarm was supposed to go off, gave up and tried hitting a couple of favorite music streams, including the above one, and they all worked. I'm not sure why the initial connection would've failed. I have it configured (as is the default) to connect directly to the stream rather than going through the squeezecenter. But, after it doesn't succeed, it's supposed to switch to random songs in my squeezecenter or beeping, but it didn't do that here. This same alarm has worked in the past (though yesterday, it was having trouble maintaining a stable connection to the same stream). AFAIK, there is no wifi issues, because I've had squeezebox wifi issues before, and in those cases, the display just disappears, but I believe I am on a clear channel now. Even if I weren't, it should still revert to the beep alarm, right? I'm currently regularly updating from the squeezecenter testing repository, so on 7.2.1, svn 23202.
Whats the URL for the station you had problems with? Can you turn Alarm log to DEBUG then attach the log to this bug.
By the alarm log, do you mean under Advanced->Logging->(player.alarmclock)? I assume this won't produce logs about the original event, just any future failures, correct? If this happens again (which might require another failure on KCRW's end), which file contains the logs to attach? I've set it to debug in the mean time. The URL of my alarm is http://media.kcrw.com/live/kcrwlive.pls (which I now realize might mean the "Connecting..." delay was on the playlist (which I guess is the server's responsibility) not the stream itself). BTW, I don't know if this is related, but I see a *lot* of this error message in my server.log: [08-09-18 15:34:46.9461] Slim::Utils::Misc::msg (1398) Warning: [15:34:46.9459] Use of uninitialized value in array element at /usr/share/perl5/Slim/Display/Squeezebox2.pm line 289. There's roughly one per second. I'm now running 7.2.1~23213.
QA to try to reproduce.
Thanks for digging into this further. Since the initial report, I haven't seen any other failures. But having the alarm be unreliable worries me, so I appreciate trying to reproduce.
Created attachment 4061 [details] Log for alarm failure, 2008-09-25
I'm not sure if this is the same bug. Actually, my suspicion is that it's different. but I think the alarm failed to go off today as well. I woke up on my own, about 80 minutes after the alarm was supposed to go off. For some reason, the Boom is displaying: HOME Now Playing -> server.log w/ debug alarm log is attached. Squeezecenter is now on svn 23279.
I was playing a little bit trying to figure out where the warnings were coming from. One thing that may be a factor: I had the Boom and my Squeezebox 3 set to synchronize with each other (but with all the other options besides the main one turned off). When I set a Boom alarm upstairs, my downstairs Squeezebox 3 would also come on, and I got all those warnings. I undid that one synch option, and this prevented the alarm from going off downstairs, but also seems to have made all the warnings I described above go away. So: 1. There appears to be a bug in synchronization, or at least a way to configure synch to trigger a bunch of perl warnings. All I had enabled was Settings -> Player Tab -> [Boom] [Synchronize] -> Synchronize set to my squeezebox 3 and vice versa. 2. Given that I didn't have power synchronization enabled, does it actually make sense for the alarm to turn on both players? This feels like a UI issue. 3. Back to this bug (which is the one that's really important to me): Is it possible that this synchronization setting was what caused these two alarm errors? I didn't mention it before because I forgot that I'd played with it. Now running svn 23315.
Created attachment 4080 [details] Log for alarm failure, 2008-09-29 This one is a log of the type of failure I initially reported in this bug.
I've now replicated the original report (with the "CONNECTING...") hanging at the top. In this case, I had snoozed the alarm a few times, but as I understand it, the way the alarm functions after a snooze should be the same. A log is attached (2008-09-29). If I were to guess, I'd guess this isn't even actually an alarm failure, and really is a firmware bug where there's a type of operation which isn't covered by timeout logic.
Can someone please ack that they are reading these reports and I'm not just tossing them into empty space? This Boom is rather useless to me if the alarm doesn't work. Thanks. To deal with the muliplication warnings spewing in the logs, I hacked my server.prefs, and changed preampVolumeControl from "~" to "0" on the Boom. The Boom doesn't have a preamp volume control setting, yet Squeezebox2.pm expects it. I don't know if this could be related to the alarm failure. I've also switched to the stable branch of squeezecenter for now, just in case.
(In reply to comment #10) > Can someone please ack that they are reading these reports and I'm not just > tossing them into empty space? This Boom is rather useless to me if the alarm > doesn't work. Thanks. We are looking into it :) Thank you for all the logs and information.
(In reply to comment #7) > I was playing a little bit trying to figure out where the warnings were coming > from. One thing that may be a factor: I had the Boom and my Squeezebox 3 set to > synchronize with each other (but with all the other options besides the main > one turned off). When I set a Boom alarm upstairs, my downstairs Squeezebox 3 > would also come on, and I got all those warnings. I undid that one synch > option, and this prevented the alarm from going off downstairs, but also seems > to have made all the warnings I described above go away. So: > > 1. There appears to be a bug in synchronization, or at least a way to configure > synch to trigger a bunch of perl warnings. All I had enabled was Settings -> > Player Tab -> [Boom] [Synchronize] -> Synchronize set to my squeezebox 3 and > vice versa. > > 2. Given that I didn't have power synchronization enabled, does it actually > make sense for the alarm to turn on both players? This feels like a UI issue. > Please add your comments and experiences to BUG 8593 in regards to Sync'd players and alarms
Max: Can you take a look at the log and give us your thoughts?
As far as the alarm is concerned, the log attached to comment 8 looks absolutely fine. The alarm went off exactly when it was meant to and was snoozed several times over at least half an hour. It checked to make sure things were playing and was told that they were. There are lots of *warnings* in the log. Someone should take a look at these but I don't think the problem lies directly with the alarm code.
Andy: care to have a look at the logs and comment? re-assign and target as you see fit.
After filtering out the constant warnings about multiplication from the 2008-09-29 log (which I realize after some experimentation are probably harmless in my case, though really annoying), I get these messages from the last iteration of the alarm, when it failed: [08-09-29 11:50:14.7096] Slim::Utils::Alarm::stopSnooze (737) Snooze expired [08-09-29 11:50:14.7099] Slim::Utils::Alarm::stopSnooze (747) unpausing music [08-09-29 11:50:14.7141] Slim::Utils::Alarm::stopSnooze (753) Fading volume [08-09-29 11:50:14.7158] Slim::Utils::Alarm::_setAlarmSubscription (1094) Adding alarm subscription [08-09-29 11:50:14.7163] Slim::Utils::Alarm::_alarmEnd (1780) _alarmEnd called with request: pause [08-09-29 11:50:14.7165] Slim::Utils::Alarm::_alarmEnd (1791) Ignoring self-created request [08-09-29 11:50:20.0939] Slim::Utils::Scanner::Remote::__ANON__ (195) Error: Can't connect to remote server to retrieve playlist: Connect timed out: . [08-09-29 11:50:20.4083] Slim::Player::TranscodingHelper::getConvertCommand (311) Error: Didn't find any command matches for type: unk format: mp3 [08-09-29 11:50:20.4412] Slim::Utils::Misc::msg (1398) Warning: [11:50:20.4409] Use of uninitialized value in pack at /usr/share/perl5/Slim/Player/Squeezebox2.pm line 515. Those last 3 lines look a bit scary, especially the last one, which I'd guess is a failure in creating a message to send to the hardware. If the line numbers match up with what is currently on my squeezecenter box: $client->sendFrame('cont', \(pack('NCnC*',$metaint, $loop, $guids_length, @guids)));
Due to the open sourcy nature of our software, our logs are perhaps scarier than most to help community members diagnose problems. :) I would say from looking at this line... [08-09-29 11:50:20.0939] Slim::Utils::Scanner::Remote::__ANON__ (195) Error: Can't connect to remote server to retrieve playlist: Connect timed out: . ...that the radio station (or the network in between you and them) was having some kind of problem at the time the alarm was scheduled to trigger. For this case, we have implemented a backup plan. SC picks a set of random tracks from the local database, but perhaps it ran into another bug while trying to do so. The odd thing is I don't see any log entries about that stuff. I see: Alarm triggered, so the alarm's going off Alarm playlist, so it knows what to play 5 seconds later, Error, can't connect 20 seconds later, checking whether alarm is playing (presumably not) 41 seconds later, snooze(?!) if the alarm wasn't going off, why would you hit snooze? Was something playing after all? I would like QA to verify in 7.2.1 the functionality that if an alarm with a radio station fails to play, that the local-track-backup is actually working.
You may need to set up some kind of simple mp3 streaming server to test this
At the "checking whether alarm is playing" stage, the alarm believed that it was playing. If not, it would have logged "Alarm active but client not playing". It checks whether the client is playing by doing if (! (Slim::Player::Source::playmode($client) =~ /play/)) { // it's not playing } I talked to Andy about this at the time and he recommended this way of doing it, however it looks like we're missing something. It would be useful to test with failing radio stations and see if this check catches them or not. The snooze in the logs puzzled me as well.
The snoozing in the logs is because I'm bad at waking up. :) The first time I hit this problem, I did not snooze the alarm at all, so I don't think snoozing is triggering this. I should note that I tried doing a factory reset on the Boom after the failure on the 29th. I haven't had any other problems this week, but it's only been a few days, and KCRW's network might be better.
So, first, I did a bit of debugging. The errors that look like: [08-10-04 19:11:27.1944] Slim::Utils::Scanner::Remote::__ANON__ (196) Error: Can't connect to remote server to retrieve playlist: 404 Resource Not Found. Are not actually playlist fetch errors. I added a little debugging code (I could've turned on debug mode, but this was easier :). The failures, are actually in connecting to some of the streams listed in the playlist. I do notice that in the past few days, the "CHECKING STREAM..." stage of opening KCRW takes longer, so this makes sense. I think the same is true for the "Connect timed out" messages. The following message though looks more rare. It shows up for all the alarm failure cases I know of, and no other times: [08-09-25 11:00:01.3052] Slim::Player::TranscodingHelper::getConvertCommand (311) Error: Didn't find any command matches for type: unk format: mp3 This appears to be the squeezecenter deciding it needs to transcode, and failing. I'm not sure why the player would sit in "CONNECTING..." rather than fail in the other ways I've seen when it tries to play formats it doesn't understand. Maybe this is a consequence of alarm code. I also have another alarm failure log. This one I trimmed somewhat because it was annoyingly long. The alarm was set for 11am, and I snoozed it a couple of times. It was supposed to go off at 11:40am but failed with the same "CONNECTING..." hang. And again, I was able to connect interactively later just fine.
Created attachment 4109 [details] Log for alarm failure, 2008-10-03
Did some further debugging on this. I don't think I know this code well, but with some educated guesses, I think there are two problems. 1. Slim/Player/Protocols/HTTP.pm : canDirectStream() has the following snippet: # Check the available types - direct stream MP3, but not Ogg. my ($command, $type, $format) = Slim::Player::TranscodingHelper::getConvertCommand($client, $url); if (defined $command && $command eq '-' || $format eq 'mp3') { return $url; } from http://svn.slimdevices.com/7.2/trunk/server/Slim/Player/Protocols/HTTP.pm?view=diff&r1=6983&r2=6984 it seems like, as the above comment indicates, it's trying to avoid streaming ogg directly. But the || in the if statement is incorrect. It will try to direct-stream if there is no transcoding required *or* the listed format is mp3. In the error case I'm seeing, "defined $command" should be false, so I think changing the || to an && will fix the bug. To confirm things, I dug up an online ogg stream (the streams at http://www.cbc.ca/listen/ogg.html). I know ogg streams have nothing to do with my alarm shenanigans, but this was exploratory to figure out if I'm interpreting this correctly. The CBC ogg stream indeed works directly from my computer, but the squeezebox tries to direct-stream it and fails. When I tried changing the || to a &&, the initial attempt at direct streaming indeed doesn't continue, but for some weird reason (based on headers the squeezebox gets from the squeezecenter? it's weird) it tries direct streaming later and still fails. I didn't try digging further because this isn't the core issue I'm trying to figure out, but it's probably easiest for those of you who actually know this code to figure out what's going on. Meanwhile mp3 streams seem to keep working, so unless someone tells me otherwise, I'm going to leave my fix in and see if the "unk" type triggers this bug again. 2. The squeezecenter, regardless of any of this, should've detected that playback failed and tried a backup alarm, but it didn't. I think I've duplicated behavior like this too, also using that ogg stream. When I try playing one of the ogg streams on the squeezebox, even though the squeezebox reports an error (and there's an error in the logs), the web UI carries on like nothing is wrong. This seems to be evidence of the server ignoring player errors when it encounters weird formats, though I don't know enough to say this is the same problem. I haven't tried digging up the code to figure this out.
So, my shot in the dark bugfix didn't help. Got another failure today. It still looks like a bug to me, but it's probably not the bug causing my woes. Guessing from the logs, I'd say the first time it read the headers, it was fine, but then the 302 redirect sent the direct stream setup code to a URL with text/html woes. I have a much more detailed log to post today, because I enabled debug logging of network.asynchttp, player.streaming*, player.sync (probably not necessary), and scan.scanner in addition to player.alarmclock. The log's pretty verbose (I could've trimmed the last 20k lines but didn't want to accidentally lose something important) so I gzipped it. What strikes about this log is - it really hits every single stream in the playlist, seems wasteful, but probably unrelated - the stream that I suspect is choking, http://scfire-mtc-aa02.stream.aol.com:80/stream/1046 , returned text/html as the MIME type. Searching for "mtc-aa02" and reading from that point on tells a sorted tale.
Created attachment 4113 [details] Log for alarm failure, 2008-10-06 with More Debug
OK, I got to spend a little more time looking at the latest server.log. When I look at the 2008-10-06 log from 11:21am (the time the last snooze was supposed to expire), there *is* a direct streaming going on. When squeezecenter fetches http://scfire-dll-aa03.stream.aol.com/stream/1046, it gets back a normal response, but when the Boom is made to, it gets back a 302 redirect. And if I understand correctly, all header processing on the boom is being offloaded to squeezecenter, which makes sense. But when Slim::Player::Squeezebox2::directHeaders tries to interpret the header received by the Boom (log lines at [08-10-06 11:21:43.7551]), it sees the 302, and immediately tries to play the redirected URL. But for some reason, it decides the format of that redirected URL is unknown. Again, I don't understand this code, but I wonder if it's because the new URL wasn't scanned previously because the redirect wasn't present 4 seconds earlier during squeezecenter's scan of the old URL.
Can you tell me what other players you have or is the boom your only device.
Manoj: Does it always fail to work for you, or just some of the time? I wonder if you have chosen a stream that is unstable or changes a lot. The fact that the scanner saw a stream with a good response but Boom got a 302 redirect shortly after is interesting. I think those popular Shoutcast streams with many URLs dynamically redirect people based on the load of the server. We may not be handling that situation correctly, as the scanner assumes if it sees a good stream it will continue to work when the player accesses it (a split-second later). Can you reproduce this with a stream with only 1 URL?
I have a squeezebox 3 in addition to the boom. I generally use the squeezebox 3 in the evenings and nights, and the boom as an alarm around 11am or after and 3-4am. I play KCRW a lot, and I never noticed problems except with the alarm, but I also never use any of my squeezeboxes at 11am except as a boom alarm. I've not seen this with any other streams, including my current other main music stream (http://sc1.liquidviewer.com:9010/listen.pls), which often (maybe always?) has only one stream in it. I have only ever reproduced this sporadically, and only with KCRW, and only as an alarm at 11am or snoozes on that soon after. I've posted a log file so far for every failure I've had.
The strategy of playing a selection of 10 random tracks if the alarm stream cannot connect does not seem to be working in yesterday's build. I'm hoping this specific case was a duplicate of bug 9097, in which case that bug will be fixed in tomorrow's build. If the strategy does work, then I'll probably move this bug to a target of 'monitor' to keep an eye on moving forward.
I see no evidence in the logs that Squeezecenter is even attempting to give up on the failed playback, and someone (Max, whom I presume is a developer) reported here that Squeezecenter seems to in fact think that playback is succeeding. And, even if that bug is fixed, there is still an underlying bug with the failure to handle 302's. I can switch back to the testing repository just in case, but I'm not expecting this to be helpful.
The alarm's fallback behaviour of 10 random tracks does not use or depend on RandomPlay and so is unlikely to be related to bug 9097. The key thing to look for in logs is the bit where it says "checking whether client is playing for alarm" (or something along those lines). The method that the alarm uses to detect if music is playing clearly does not catch all cases. The code simply does if (! (Slim::Player::Source::playmode($client) =~ /play/)) { # play fallback } However, in this case (and assumedly others), the playmode is returned as 'play' when the player is in fact not playing. There is another issue in that the alarm fallback method does not currently work when connected to SN. There's a bug open on that. PS Manoj: Yes, I am a developer - I wrote the new alarm code. Mea culpe.
Another alarm failure after only one snooze yesterday morning. Same type of problem with inability to handle the redirected URL in the logs. I used a different alarm yesterday because I needed reliability, meaning this is 3 days in a row that the Boom alarm failed on KCRW. I suspect that y'all should be able to reproduce this pretty easily now if my logs aren't enough. A snipped version of the newest server.log will be attached shortly. There is one difference: I enabled network.protocol and network.protocol.slimproto logging this time, so you can see some of the state of the Boom. Maybe this will help answer why squeezecenter thinks the Boom is playing when it's not? I'm thinking more and more that squeezecenter doesn't know the format of the URL before it tries to play it, and therefore croaks. It seems to try to do a database lookup on the URL to get the format. If it's never seen the format, it of course can't be in the db. If the solution is indeed properly checking the track before attempting to play it (or inserting a proper check into the play routine), then I can't really suggest what the clean fix for this is. It requires someone who knows the real design path of the project to suggest and implement something good. I'm also reaching the limits of the time I can spend on this without constructive feedback.
Created attachment 4121 [details] Log for alarm failure, 2008-10-08 with Even More Debug
Ah, the penny has just dropped a bit. The alarm doesn't check whether the music is playing after a snooze ends, only when the alarm starts initially. So if a radio station works when the alarm goes off, but then fails for some reason when it is restarted after a snooze, the alarm won't notice. I'll try and get this fixed for 7.2.1.
Hmm, that makes sense. But the first failure (2008-09-25) didn't have a snooze at all. (after grepping out "Uninitialized value in multiplication") [08-09-25 11:00:01.3052] Slim::Player::TranscodingHelper::getConvertCommand (311) Error: Didn't find any command matches for type: unk format: mp3 [08-09-25 11:00:01.3252] Slim::Utils::Misc::msg (1398) Warning: [11:00:01.3249] Use of uninitialized value in pack at /usr/share/perl5/Slim/Player/Squeezebox2.pm line 515. [08-09-25 11:00:20.0776] Slim::Utils::Alarm::_checkPlaying (1008) Checking whether client is playing for alarm 98f5ac76 [08-09-25 12:00:00.0776] Slim::Utils::Alarm::_timeout (1047) Alarm 98f5ac76 ending automatically due to timeout [08-09-25 12:00:00.0881] Slim::Utils::Alarm::popAlarmScreensaver (1689) Attempting to pop alarm screensaver. Current mode: SCREENSAVER.datetime [08-09-25 12:00:00.0883] Slim::Utils::Alarm::popAlarmScreensaver (1691) Popping alarm screensaver
Agreed - I still think there is a problem with squeezecenter reporting itself as playing when it isn't. However, I really should be checking for playback at the end of a snooze anyway. It probably won't help in your case, unfortunately, but it may catch a few other situations. I'll check in a patch for this in a bit.
Max: take a look at Bug 8577, don't know if this helps or not, you put in a fix that may affect this behavior.
I'm not sure that's relevant, but I don't know anything about the smoke tests or indeed Jive.
Max, I'm going to reassign this bug to you for now, since it appears you are working on patch? feel free to assign it back to me if this is not right, or when you have a fix checked it. Manoj, thank you very much for all the hard work you have done, and the debugging you have posted. I have still not been able to reproduce the error here, but will keep trying.
Change 23496 adds a check to try and ensure that music is playing after a snooze ends. This will not fix this bug, unfortunately. However, the lack of a check after a snooze was an ommission that needed fixing and may help to prevent similar problems from occurring. For this bug to be fixed, a more accurate method for determining whether a player is playing needs to be found. Alternately, Slim::Player::Source::playmode needs to be modified so as not to return 'play' in this situation. I don't think I can do any more on this, I'm afraid.
I found one bug, in errorOpening the playmode was never reset to stop. Change 23515 fixes this. This is probably the source of this bug, so marking fixed.
whoooooa. I'm glad you probably found the bug that makes the Boom not revert to a backup alarm, and thanks for fixing it, but what about the problem where it fails to deal with redirected streams properly? James: I'm wondering if I see the redirects from where I am because I'm on a huge ISP (Comcast) and AOL is redirecting to a local version of the stream or something. In which case, from an office, you might never reproduce it. You'd probably have to just set up your own server that returned 200 the first time and 302 the 2nd. I also suspect they're only changing around the streams at certain times of the day (say 11am to noon or something).
(In reply to comment #43) > > James: I'm wondering if I see the redirects from where I am because I'm on a > huge ISP (Comcast) and AOL is redirecting to a local version of the stream or > something. In which case, from an office, you might never reproduce it. You'd > probably have to just set up your own server that returned 200 the first time > and 302 the 2nd. I also suspect they're only changing around the streams at > certain times of the day (say 11am to noon or something). > This is more then likely why I can't repo this issue. Can you try the latest nightly build 7.2.1-23518 or higher. Let me know if this build works for you or not.
I'm sitting on the debian testing apt repository and it hasn't been updated in at least a week I think. Will that get updated? Given that I've seen no fix for the fundamental problem with redirects, I can hope that the backup alarm feature will work, but there is no reason to believe that the original bug is fixed. Isn't the original bug already known well enough to fix it?
BTW, if it'll help y'all, I'm happy to open a new bug for the redirect-handling bug and point it at the attachments and discussion in this one, since it really is a separate bug with a separate fix.
(In reply to comment #46) > BTW, if it'll help y'all, I'm happy to open a new bug for the redirect-handling > bug and point it at the attachments and discussion in this one, since it really > is a separate bug with a separate fix. > That sounds like a good idea To manually download the nightly, go here: http://wiki.slimdevices.com/index.php/Nightly_Builds
The testing repo seems to have restarted, so I'm running current builds again. I haven't seen the original bug (the 302 bug) in the last week, so I don't know yet for sure that this makes the alarm behave more reliably. Given my guess as to the 302 bug, I probably need to clear the track database to make this a more likely event as well. I'll try to get to that and report back when I see this again.
The bug seems to have come back (or it never left, and it just took this long to get triggered again). I see no difference from before in this log, so I'm thinking the previous fix didn't work. I'm now on 7.2.1~23629 (later than the 23518 requested). The only difference from before is that I'm on Ubuntu Intrepid now (which isn't yet released, but the log entries make me think this is just the old bug sticking its head up again). I haven't yet filed the bug for redirects causing failures on music streams (and need to get around to it) but I am reporting the higher-layer problem that the squeezebox doesn't revert to a backup solution when playback of the stream fails. Log will be attached shortly.
Created attachment 4178 [details] Log for alarm failure, 2008-10-27
Another failure on Friday. Any update? (log coming up)
Created attachment 4197 [details] Log for alarm failure, 2008-11-01
This seems to be quite similar to a problem I've been having with alarms. In my case I'm having alarms sometimes failing to engage at all and redirecting to a random playlist and in other cases having SC "think" it is playing the stream when in fact nothing is actually playing. I've done a lot of trial and error and think I've found out what's going on. Let me know if this has any relevance to 9534. For background I'm using SC 7.2 with an SB3 and a SBC. My main alarm has been set to Sky FM's "Mostly Classical". It works sometimes but not always. Lately it's been failing most of the time. When it fails it reverts to a random playlist. The list URL for the playlist is http://www.sky.fm/mp3/classical.pls. It works fine when selected directly from "Playlists". At 7:00 am I tried to set an alarm to play CBC Radio 1 Montreal for news. The URL for this is: http://origin.www.cbc.ca/mrl2/livemedia/cbcr1-montreal.asx This link results in SC (and the SBC) saying that CBC Radio 1 Montreal is playing when, in fact, nothing is working. It works fine when selected directly from Playlists. I tried switching this alarm link to CBC Radio 2 Toronto and it works fine. That's when I figured out that my CBC 2 link was actually the mms:// address instead of the .asx pointer. So I found the mms:// address for Radio 1 Montreal and the alarm worked just fine: mms://wm.cbc.ca/cbcr1-montreal So, armed with that knowledge I figured out the actually stream address for SKY FM's Mostly Classical: http://scfire-mtc-aa01.stream.aol.com:80/stream/1006 Again, it seems to work just fine in the alarm, no hangs. Does this have any connection to the KCRW original hangs? You were trying to connect to a playlist pointer: http://www.kcrw.com/pls/kcrwsimulcast.pls Have you tried setting up the alarm to actually use the stream URL rather than the pointer? When I connect to the KCRW pointer above I actually connect to the following stream: http://scfire-chi0l-2.stream.aol.com:80/stream/1046 Max: Does this make any sense in terms of the way the alarm connects to a stream vs connecting to the stream directly through SC? Hope this helps.
changing target to something in the (near) future
Max, do we currently try to play the SC backup alarm after a timeout?
Yes. It sets a timer for 20 seconds after it tries to start playback. When the timer fires, it checks if the player is reported to be playing and, if not, plays the fallback tone.
Manjo: Please try the suggestion in Comment 53. Let us know if that resolves the issue, QA is still not able to reproduce this.
Has Max already checked in a patch for this? If so, it's not mentioned here, so at the moment, I actually have no idea if this is fixed, because I don't use those pls's anymore. I need an alarm that's actually reliable. I've been using local music, and just found a radiotime.com link that I hope works better. But I'm also using a backup alarm when I have a meeting to get to in the morning, which is of course a weird thing to do when one already has a $300 alarm clock. #53 is either not my situation (at least not usually) because my boom did *not* ever fallback to random songs when it failed. Also, simply pointing at a single stream is both irrelevant (because a single stream could exhibit the same issues, though I'm not entirely sure that the code path will be the same) and will be unreliable (because AOL could rearrange the streams, and does so). Also, it doesn't fix the more fundamental issue that the alarm code doesn't properly detect that the squeezebox is not playing and fallback to the built-in alarm. I've already uploaded substantial evidence for the 2 bugs (the failure to handle a redirect when the server sends it after the initial playlist scan, and the failure of the alarm code to detect that the boom is not playing anything), and I don't see what is missing for someone to fix these, if I interpreted the log files correctly (again, unless Max or someone else already fixed them and just neglected to update this issue). If you still need to reproduce this, given the variability of the test case, and the fact that you're coming from a different client ISP, I think the only way you could ever reproduce it is to set up a small server that sends a 200 the first time and a 302 the second and see what happens.
Other people are having similar symptoms. I didn't search very hard for other threads but found: http://forums.slimdevices.com/showthread.php?t=55818
Actually, the depends-on change is not quite correct, I think. There appear to be two distinct bugs: 1. streaming fails in certain cases 2. failures of various sorts (including streaming) aren't noticed by the alarm code, thus the backup is never invoked. These can be fixed independently. This I assume is why, when I asked a few weeks ago, whether a separate bug for the streaming failures would be a good idea, I heard yes.
Bug 10362 MAY be related
QA to figure out what cases this affects. Do we have a streaming server we could test with now?
Changing Summary 'Alarm fails to go off, hangs in "connecting..."'
*** Bug 10669 has been marked as a duplicate of this bug. ***
I tested with 2 players, simulating a drop in DNS/Network, one player wired and 1 player wireless. The wired player properly started the back up alarm at the scheduled time The wireless player failed to start the back up alarm at the scheduled time See attached log 01:cc is Wired 04:a4 is Wireless Note: the log only shows the wired player. Test Setup: Set both booms with 1 alarm (default values) to go off 30 min after start of test - using ANY internet steam as alarm source Network HUB attached to wireless AP; boom / Server attached to hub Wireless AP with boom attached Pull network connection from wireless AP to simulate network interruption Wait 30 min Notice that only the wired boom's back up alarm starts, the Wireless boom fails to produce any sound.
Created attachment 4633 [details] Server Log
From what I can tell from that log, the wired boom was still connected to SqueezeCenter when the alarm went off and so SqueezeCenter was able to control it at alarm time. SqueezeCenter told it to play the internet stream and then checked back 20 seconds later to see if it was playing. It found it wasn't and so launched the backup alarm tone. The wireless player was different. At alarm time, SqueezeCenter triggered the alarm, but found that the player was not connected. It therefore did no more. The wireless Boom's RTC alarm should also have kicked in at this time and sounded an alarm using its internal alarm tone. We obviously don't have logs for this as it wasn't connected to SqueezeCenter. All we can tell is that the alarm was scheduled correctly and that it did go off within SqueezeCenter at the right time. The relevant bit from the scheduling is below: 09-01-13 08:14:13.5157] Slim::Utils::Alarm::loadAlarms (1231) Loading saved alarms from prefs for BOOM:04:a4 [09-01-13 08:14:13.5161] Slim::Utils::Alarm::loadAlarms (1264) Alarms loaded. Rescheduling... [09-01-13 08:14:13.5164] Slim::Utils::Alarm::scheduleNext (1280) Asked to schedule next alarm for BOOM:04:a4 [09-01-13 08:14:13.5168] Slim::Utils::Alarm::findNextTime (437) Potential next time found: 8:30:0 13/1/2009 [09-01-13 08:14:13.5171] Slim::Utils::Alarm::scheduleNext (1313) Next alarm is at 8:30:0 13/1/2009 [09-01-13 08:14:13.5174] Slim::Utils::Alarm::scheduleNext (1325) Scheduling alarm [09-01-13 08:14:13.5178] Slim::Utils::Alarm::_startStopTimeCheck (1747) 2 scheduled alarm(s) [09-01-13 08:14:13.5181] Slim::Utils::Alarm::setRTCAlarm (1357) Asked to set rtc alarm for BOOM:04:a4 [09-01-13 08:14:13.5185] Slim::Utils::Alarm::setRTCAlarm (1388) Setting RTC alarm to 30600, volume 50 You can see at the bottom that it set the Boom's built in RTC alarm for 30600 (8.5 hours after midnight). This should therefore have gone off. It would be worthwhile repeating this test and then, once the Boom is disconnected from the server, verifying on the Boom that the RTC alarm is set correctly. Felix will be able to provide details on how to do this.
James: Two things to check about the RTC alarm. When the alarm time is set from SC and then Boom gets disconnected - is the time shown on Boom correct? and is the bell sign (indicating an alarm) shown?
(In reply to comment #68) > James: Two things to check about the RTC alarm. When the alarm time is set from > SC and then Boom gets disconnected - is the time shown on Boom correct? and is > the bell sign (indicating an alarm) shown? > Yes, the Clock is proper and counting up. Alarm bell is shown One thing I didn't note in the bug. on the wireless boom (not connected to server) the alarm bell was flashing, but no sound was coming out. I verified the volume on the boom was at 50 (alarm default) even changing the volume didn't produce sound.
The bug that was combined with this is one is (yet again) not the bug I describe. My bug is that when playing a network stream fails in at least some ways, even when wireless is up and running and happy, squeezecenter can't tell that nothing is actually playing, and doesn't resort to the backup of playing random music in my library. I'd be ok with the backup being the built-in alarm of the Boom, but given that the Boom (in my case) is perfectly able to connect to the 'net and to squeezecenter, I suspect it will not resort to its built-in alarm. I just want to make clear that even if this other bug is fixed, it doesn't fix mine.
(In reply to comment #65, James wrote:) > I tested with 2 players, simulating a drop in DNS/Network, one player wired and > 1 player wireless. > The wired player properly started the back up alarm at the scheduled time > The wireless player failed to start the back up alarm at the scheduled time Just for interest's sake, in my setup I'm using a wired SB3 and it is this player that is failing to make the alarm stream connection. Also, as Manoj noted in Comment #58 the provider can change the stream associated with a playlist. That happened to me over the holidays with Sky FM's Mostly Classical. But it only took me one missed alarm (actually I got the SB3's built-in tone instead) to find out this had happened and I was able to find the new stream and plug it in. Still, it's a pain.
I agree. We should not mix the backup alarm and the built in RTC (real time clock) alarm. Sorry about that. - Backup alarm - kicks in if still connected to SC, but primary music source fails - RTC alarm - kicks in if SBB has lost connection to SC Let's discuss the backup alarm in this bug and the RTC alarm here: bug 10705
So, to summarize the important parts of the conversation (since there's been enough other miscellaneous conversation to confuse things), it appears the core of this bug is that "playing" state of the player isn't always correct. So, when the alarm code in squeezecenter tries to play the alarm, it doesn't detect that the player really isn't doing anything. I'm wondering, is https://bugs-archive.lyrion.org/show_bug.cgi?id=10681 related by any chance? I'm not sure if that would end up fixing my situation, but perhaps code in that area is what needs fixing?
I found another case where squeezecenter fails to detect that playback is not actually happening. See https://bugs-archive.lyrion.org/show_bug.cgi?id=10636#c6 . I don't know if this is the same situation though.
Hi. Please reply so I know someone still cares about this issue. I'd *really* like to see it fixed, because I'd like the alarm clock to be dependable. Thanks! OK, I now have an easily reproducable test case for either this bug, or something just like it. See https://bugs-archive.lyrion.org/show_bug.cgi?id=11216 . This caused my alarm to fail yesterday, in a similar way to the streaming bugs I used to have with KCRW. The player thinks it's playing, but it's making no playback progress. Presumably, anything that makes a convert.conf pipeline produce no output, like this did, will also trigger this.
We're certainly still working on this bug and the related issues. QA to try to reproduce this again using James's repro instructions, to see if THAT bug has been fixed with some recent changes. I'll put comments in your new bug about that case.
Hmm, if you mean the James earlier in the bug, the issue he was reacting to was different than the one I originally claimed. See comment #70. (It'd be nice if Bugzilla let you yank out portions of a bug to stick in another bug to avoid confusion). The process I described in #74 is the only way I know of right now to reproduce it without setting up your own custom shoutcast server.
Just to confirm: I was able to duplicate this behavior by replacing the "flc flc transcode *" entry in /etc/squeezecenter/convert.conf with /bin/false and trying to play one of my whole CD flacs. This of course also worked with replacing the "mp3 mp3 * *" section with /bin/false.
We are now planning to make a 7.3.3 release. Please review your bugs (all marked open against 7.3.3) to see if they can be fixed in the next few weeks, or if they should be retargeted for 7.4 or future. Thanks!
Hello, can someone please confirm that they saw my messages over the last couple of weeks, and that I've already included a perfectly easy way to reproduce this problem? James's reproduction instructions (if they are the ones earlier in this bug) don't actually cover this bug, as someone tried to merge my bug with an unrelated bug. There seems to be a pattern where someone posts to this bug about an unrelated problem, I say that the problem they describe is not the one I'm talking about, then there's no activity for a few weeks, then repeat. So it'd be great if someone could look at this bug and actually focus on it for a short while, especially since I have an easy way to reproduce it (#74 and #75). Thanks.
QA to reproduce, get player.source player.alarmclock log and assign to Alan if reproducible.
Since there's now a planned 7.3.3 release, bugs which won't make the cut-off are being moved to the next target out. If you feel that this bug needs to be addressed more (or less) urgently than the 7.4 release, please cc chris@slimdevices.com and leave a comment in the bug to that effect so we can review it. Thanks.
For some reason Bugzilla did not change the target when I did this yesterday. Or maybe it was me. In either case, I'm trying it again.
Created attachment 5011 [details] Alarm Error Log Attached is a log with Player.Source and Player.Alarm set to debug. Simulated a failed playlist by modifying the convert.comf file as described. The alarm 'went off' on the boom. I.E. the bell was flashing, yet no sound was produced, and the 'backup' alarm did not go off. At the end of the log I pressed 'power' on the front of boom to stop the alarm.
This specific failure mode has been fixed with the fix to bug 9673.
Any chance for a backport to 7.3? If 7.4 is in reasonable condition (as a calibrator, I normally stick with the testing apt repository) I could consider that too, but the forums seemed to be warning us away. Thanks.
I'm not really sure. I think that 7.3.3 is pretty much done and it does not seem to me that this is severe enough to backport at this late stage. The change is pretty low risk but I would not say that it is risk free. In its favour, it does resolve a particularly irritating problem: the fact that SC, SP and players report that a track for which transcoding has failed, is playing. I have tagged this for the bug-review meeting for further guidance.
The more serious bug, IMO, is that the alarm clock can't be trusted to be reliable, as various sorts of failures in squeezecenter will make the alarm fail.
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.