Always fallback alarm

[Heinz]

Hello,

the first of my two alarms (one set at 06:50 and the other at 7:00, both play the same Station) on the Squeezebox Radio (7.6) is going to fallback alarm all the time. The second, however, is working fine. The radio is connected to a local server via wifi.
Could someone please have a look into messages.txt and give me some advice how to solve this problem?

Thanks

[bluegaspode]

Heinz,

for some reason at 6:50 your server is not sending the alarm signal to the radio.
This is why your Radio decides to sound the fallback alarm, because it does not know what stream to play.

At 7:00 everything works as expected. The server actively tells the Radio to start the alarm.

One interesting thing: at 6:50:24 your server sends a 'clear all alarms' message to the radio, which (if I remember it right) only happens when the server is starting.
But then I don't see any server connected/disconnected messages which typically happen when the server is down.

So we need to find out why the server misses to signal the first alarm.

Is your server going into standby or does it hibernate in the night?
How long does the server need to start-up. The Radio tries to wake the server up 5min before the alarm, maybe this is not enough (though 5min actually is very long).

I think in your case the server log (with activated debug logging on channel 'player.alarmclock') might help us to see what's up on the server side (though I'm not very experienced with the server code, but it might give some clues).

[Heinz]

Bluegaspode,

thanks for your reply.
The server runs 24/7, so it doesn't need WOL.
How can I enable debugging on the server, and what file contains the log? I'm running Ubuntu 10.04.

[bluegaspode]

Web-Interface->Settings->Advanced->Logging

Log is then on the server under
/var/log/squeezeboxserver/server.log

[Heinz]

Here it is.
The alarm is triggered 6:51:30, which is too late. Do you have any ideas why this is exactly 90 seconds too late?

[bluegaspode]

I looked into the code around the message that the alarm will be ignored and found the following text:

# Check if this alarm is still current - we could be running really late due to hibernation or similar

ok - this gives a little clue, but you said your server does run 24/7.
So I digged a bit deeper into the code to see how the timer are internally scheduled within SBS.
As it turns out, a third party library is used, where the following interesting comment for the 'timer' function is given:

---------
The timer is based on a monotonic clock, that is, if somebody is sitting in front of the machine while the timer is running and changes the system clock, the timer will nevertheless run (roughly) the same time.
--------
I interpret this that the seconds are just counted down - if the server hibernates or sleeps for 5mins the timer would trigger 5mins later.
Also when there are daylight saving changes in the night, the server would not respect them, which is a but strange for an alarm clock.

Another interesting comment there:
-----
The timer does his best not to drift, but it will not invoke the timer more often then once per event loop iteration, and might drift in other cases. If that isn't acceptable, look at EV:eriodic, which can provide long-term stable timers.
-----
Aha - a hint to a better method!

So well. For some reason the timer drifts on your computer (maybe because your computer sleeps for a very short time in the night), but I guess we will never find out why.
And SqueezeboxServer uses a function that isn't foolproof against drifts.

Are you happy trying out some new code?
I'm no perl programmer so what I'm suggesting might not work at all, but maybe we can change the one line responsible for all timers, to use this more robust function.

Based on the documentation found here: http://search.cpan.org/~mlehmann/EV-4.03/EV.pm
SB-Server currently uses the function:

$w = EV::timer $after, $repeat, $callback

and a better one would be

$w = EV::periodic $at, $interval, $reschedule_cb, $callback

Looks easy to change indeed.

In Squeezeboxserver this line is called in the file
Slim/Utils/Timers.pm around line 231 (the last line of this snippet):

sub _makeTimer {
	my ($objRef, $when, $subptr, @args) = @_;
	
	if ( !defined $objRef ) {
		$objRef = '';
	}
	
	my $now = EV::now;
	
	# We could use AnyEvent->timer here but paying the overhead
	# cost of proxying the method is silly
	my $w;
	$w = EV::timer( $when - $now, 0, sub {

I'd suggest changing the last line to

$w = EV::periodic($when, 0,0, sub {

then restart the server and try some simple alarms first if we broke anything.
If these are working schedule your normal alarm and then we'll see what happens.

If it really works we could start a bug report in the hope that Logitech reviews this fix and integrates it into the server.

[Heinz]

I tried the change you suggested, but squeezeboxserver didn't even start up.
It's strange to see that the server drifts that much. This is an issue i have to look into further. I use it for web and local services and didn't notice any odd behaviour so far (it's running for almost 6 years now - maybe I'll check the CMOS battery).

Anyway, it would be nice to see squeezeboxserver not failing due to drift and so I would be happy to help where I can.

[bluegaspode]

I tried the change you suggested, but squeezeboxserver didn't even start up.

Hhmm - ok
Will try myself on the weekend, when I find some time.

[cran]

---------
The timer is based on a monotonic clock, that is, if somebody is sitting in front of the machine while the timer is running and changes the system clock, the timer will nevertheless run (roughly) the same time.
--------
I interpret this that the seconds are just counted down - if the server hibernates or sleeps for 5mins the timer would trigger 5mins later.
Also when there are daylight saving changes in the night, the server would not respect them, which is a but strange for an alarm clock.

Another interesting comment there:
-----
The timer does his best not to drift, but it will not invoke the timer more often then once per event loop iteration, and might drift in other cases. If that isn't acceptable, look at EV:eriodic, which can provide long-term stable timers.
-----

That sounds like a very good approach to the problem. From looking at my ntpd log I can tell that my server's clock is off by many seconds (and would be totally useless without ntpd):

Aug 4 00:36:55 regis ntpd[990]: time reset +2.649129 s
Aug 4 00:52:21 regis ntpd[990]: time reset +2.666362 s
Aug 4 01:08:29 regis ntpd[990]: time reset +2.784663 s
Aug 4 01:24:17 regis ntpd[990]: time reset +2.726872 s
Aug 4 01:40:05 regis ntpd[990]: time reset +2.728198 s
Aug 4 01:55:20 regis ntpd[990]: time reset +2.634140 s
Aug 4 02:10:28 regis ntpd[990]: time reset +2.611686 s
Aug 4 02:26:14 regis ntpd[990]: time reset +2.720763 s
Aug 4 02:41:18 regis ntpd[990]: time reset +2.603887 s
Aug 4 02:57:04 regis ntpd[990]: time reset +2.719497 s
Aug 4 03:12:51 regis ntpd[990]: time reset +2.725046 s
Aug 4 03:27:59 regis ntpd[990]: time reset +2.613932 s
Aug 4 03:43:05 regis ntpd[990]: time reset +2.605977 s
Aug 4 03:58:12 regis ntpd[990]: time reset +2.611431 s
Aug 4 04:13:37 regis ntpd[990]: time reset +2.660828 s
Aug 4 04:29:35 regis ntpd[990]: time reset +2.755782 s
Aug 4 04:44:48 regis ntpd[990]: time reset +2.629014 s
Aug 4 05:00:31 regis ntpd[990]: time reset +2.712094 s
Aug 4 05:16:05 regis ntpd[990]: time reset +2.686916 s
Aug 4 05:31:09 regis ntpd[990]: time reset +2.602980 s
Aug 4 05:46:50 regis ntpd[990]: time reset +2.707192 s
Aug 4 06:02:14 regis ntpd[990]: time reset +2.657796 s
Aug 4 06:17:44 regis ntpd[990]: time reset +2.676087 s
Aug 4 06:33:20 regis ntpd[990]: time reset +2.694464 s
Aug 4 06:49:15 regis ntpd[990]: time reset +2.748388 s
Aug 4 07:04:32 regis ntpd[990]: time reset +2.637098 s
Aug 4 07:23:00 regis ntpd[990]: time reset +3.189679 s

Please let me know what I can do to help testing or debugging.

[bluegaspode]

Hi cran,

yes these ntpd logs seem to show the culprit. The internal clock runs too slow and as the timer of the Squeezebox server is using a 'monotonic' clock as to the documentation, it does not adopt.

ntpd ajusts the server time, but Squeezebox Server right now does not care.


I'll try tweaking the server code myself a bit maybe tonight or on the weekend, to use this other timer function, maybe we can achieve something.