Hi list,
I just noticed a serious issue with a missed timer event. After a daily timer, VDR did an automatic shutdown, but not for the next day to record the same timer again, but for the next following timer event!
I never noticed this before, so my guess is that this issue is somehow quite sensitive to bad timing. And: This shutdown was done by the original 1.4.1-2 code, not using any of the experimental shutdown patches since then.
I followed the source code for such situations, and thats what should happen:
cRecordControls::Process(t) and cRecordControl::Process(t) do the timer checks periodically by calling cTimer::Matches(t). As soon as cTimer::Matches(t) returns false, the recording is stopped.
Some minutes later, the next timer is searched by cTimers::GetNextActiveTimer(), returning the closest (oldest) start time timer that has a stop time that is not yet passed.
*speculation* Could the timer still be on the stopped time event? That way GetNextActiveTimer would ignore it. cTimer::StopTime() has a cache that has to be refreshed by calling cTimer::Matches(t). Could it be that Matches was not called after the event and before the shutdown?
There's one call to Matches for sure: The one from cRecordControl::Process, that returned false and stopped the timer. But: If Matches(t) was called /exactly at/ t=StopTime, then Matches(t) returns false, but the cached StartTime/StopTime refer to the last timer hit, not the next one! If there was no call to Matches() after that and before the shutdown, then the timer may be skipped!
Well, thats speculative. There should have been a call to Matches before from the TIMERCHECKDELTA loop in vdr.c. But it may be a good idea to call Matches() from within GetNextActiveTimer(), just to make sure.
Cheers,
Udo
Hi Udo, Hi Klaus,
I just noticed a serious issue with a missed timer event. After a daily timer, VDR did an automatic shutdown, but not for the next day to record the same timer again, but for the next following timer event!
Last week I discovered the same behavior. I have a repeating daily timer (VPS) and two weekly timers. After one daily timer, VDR executed the shutdown with the weekly timer (in 3 days), instead of the daily timer the next day.
The syslog with the Problem is attached.
Greets Patrick
Udo Richter wrote:
I just noticed a serious issue with a missed timer event. After a daily timer, VDR did an automatic shutdown, but not for the next day to record the same timer again, but for the next following timer event!
Ok, I was able to verify and debug this a bit. Using the attached patch, I was able to provoke and monitor this.
The attached patch adds debug code to GetNextActiveTimer, checking whether Matches() does anything, and whether StopTime() is in the past.
This log shows a daily timer running out:
Aug 3 01:33:28 vdr: timer 14 (1 0124-0135 'Das Erste') modified (active) Aug 3 01:33:30 vdr: timer 14 (1 0124-0135 'Das Erste') start Aug 3 01:33:39 vdr: Power button pressed Aug 3 01:33:39 vdr: confirm: Aufnahme läuft - trotzdem ausschalten? Aug 3 01:33:39 vdr: warning: Aufnahme läuft - trotzdem ausschalten? Aug 3 01:33:50 vdr: not confirmed Aug 3 01:35:00 vdr: timer 14 (1 0124-0135 'Das Erste') stop Aug 3 01:35:01 vdr: Start/Stop Timer error: Start changed from Thu Aug 3 01:24:00 2006 to Fri Aug 4 01:24:00 2006, stop from Thu Aug 3 01:35:00 2006 to Fri Aug 4 01:35:00 2006 Aug 3 01:35:01 vdr: next timer event at Fri Aug 4 01:24:00 2006 Aug 3 01:35:01 vdr: confirm: Taste drücken, um Ausschalten abzubrechen Aug 3 01:35:01 vdr: warning: Taste drücken, um Ausschalten abzubrechen Aug 3 01:35:07 vdr: confirmed
'The Start/Stop Timer error' shows that GetNextActiveTimer would have seen the finished Aug 3 timer, not the next Aug 4 timer. The timing for shutdown is actually that short, and the 'next timer' is not updated, even if the shutdown is 5 minutes later.
However, observe that the check is done at 01:35:01. If VDR is a little bit faster, the check could be at 01:35:00, and the call to Matches() would not switch to the Aug 4 timer either. The other debug message should show this, but I could not trigger this. Maybe on a faster machine it would do.
I suggest two changes to VDR: - As the patch does, add a Matches() call to GetNextActiveTimer - In Matches(), change this: @@ -351,7 +351,7 @@ if (DayMatches(t0)) { time_t a = SetTime(t0, begin); time_t b = a + length; - if ((!day || a >= day) && t <= b) { + if ((!day || a >= day) && t < b) { startTime = a; stopTime = b; break; This way the daily timer already jumps to next day at t=StopTime, not at t=StopTime+1. This matches the following line:
return startTime <= t + Margin && t < stopTime; // must stop *before* stopTime to allow adjacent timers
Both changes should fix this issue imho, but its safer to have both.
By the way, in the above situation, VDR did shut down 7 seconds after the timer ended, because UserShutdown was still true. Normally VDR would have waited 5 minutes. But thats another issue.
Cheers,
Udo
--- timers.c.bak 2006-08-03 01:01:35.191684432 +0200 +++ timers.c 2006-08-03 01:59:23.883790392 +0200 @@ -647,6 +647,23 @@ { cTimer *t0 = NULL; for (cTimer *ti = First(); ti; ti = Next(ti)) { + time_t stop=ti->StopTime(); + time_t start=ti->StartTime(); + ti->Matches(); + if (stop!=ti->StopTime() || start!=ti->StartTime()) { + esyslog("Start/Stop Timer error: Start changed from %s to %s, stop from %s to %s", + *TimeToString(start),*TimeToString(ti->StartTime()), + *TimeToString(stop),*TimeToString(ti->StopTime())); + printf("Start/Stop Timer error: Start changed from %s to %s, stop from %s to %s\n", + *TimeToString(start),*TimeToString(ti->StartTime()), + *TimeToString(stop),*TimeToString(ti->StopTime())); + } + if (ti->StopTime() <= time(NULL)) { + esyslog("Start/Stop Timer error: Outdated timer from %s to %s", + *TimeToString(start),*TimeToString(stop)); + printf("Start/Stop Timer error: Outdated timer from %s to %s\n", + *TimeToString(start),*TimeToString(stop)); + } if ((ti->HasFlags(tfActive)) && (!t0 || ti->StopTime() > time(NULL) && ti->Compare(*t0) < 0)) t0 = ti; }
-
Patrick Maier -
Udo Richter