[vdr] Re: Log of Timer Bug

[Klaus Schmidinger <Klaus.Schmidinger@cadsoft.de>]

Carsten Koch wrote:
> 
> Has the timer bug been fixed in the meantime?
> 
> If not, would it make sense if I contribute many logs?
> 
> Here is the latest one I saw:
> 
> Oct 16 23:09:55 vdr vdr[7610]: VDR version 0.96 started
> Oct 16 23:09:55 vdr vdr[7610]: loading ./setup.conf
> Oct 16 23:09:55 vdr vdr[7610]: loading ./channels.conf
> Oct 16 23:09:55 vdr vdr[7610]: loading ./timers.conf
> Oct 16 23:09:55 vdr vdr[7610]: loading ./commands.conf
> Oct 16 23:09:55 vdr vdr[7610]: probing /dev/ost/frontend0
> Oct 16 23:09:55 vdr vdr[7612]: EIT processing thread started (pid=7612) - master
> Oct 16 23:09:55 vdr vdr[7610]: probing /dev/ost/frontend1
> Oct 16 23:09:55 vdr vdr[7613]: EIT processing thread started (pid=7613)
> Oct 16 23:09:55 vdr vdr[7610]: probing /dev/ost/frontend2
> Oct 16 23:09:55 vdr vdr[7610]: found 2 video devices
> Oct 16 23:09:55 vdr vdr[7610]: setting primary DVB to 1
> Oct 16 23:09:55 vdr vdr[7610]: switching to channel 2
> Oct 16 23:09:55 vdr vdr[7614]: LIRC remote control thread started (pid=7614)
> Oct 16 23:09:55 vdr vdr[7610]: SVDRP listening on port 2001
> Oct 16 23:09:55 vdr vdr[7610]: setting watchdog timer to 15 seconds
> Oct 16 23:10:01 vdr vdr[7610]: assuming manual start of VDR
> Oct 16 23:10:02 vdr vdr[7610]: max. latency time 1 seconds
> Oct 16 23:26:10 vdr vdr[7610]: ERROR: channel 269 not sync'ed on DVB card 2!
> Oct 16 23:26:10 vdr vdr[7610]: retrying
> Oct 16 23:37:56 vdr vdr[7610]: system time seen is Tue Oct 16 23:37:56 2001

Apparently VDR "sees" the correct time.

> Oct 16 23:37:56 vdr vdr[7610]: timer 28 start
> Oct 16 23:37:56 vdr vdr[7610]: switching to channel 45
> Oct 16 23:37:56 vdr vdr[7610]: Title: 'Die Harald Schmidt Show' Subtitle: ''
> Oct 16 23:37:56 vdr vdr[7610]: record /video/Die_Wochenshow_-_Classics/2001-10-16.23:15.50.98.rec
> Oct 16 23:37:56 vdr vdr[7610]: creating directory /video/Die_Wochenshow_-_Classics/2001-10-16.23:15.50.98.rec
> Oct 16 23:37:56 vdr vdr[7610]: recording to '/video/Die_Wochenshow_-_Classics/2001-10-16.23:15.50.98.rec/001.vdr'
> Oct 16 23:37:56 vdr vdr[7762]: output thread started (pid=7762)
> Oct 16 23:37:56 vdr vdr[7763]: input thread started (pid=7763)
> Oct 16 23:37:58 vdr vdr[7762]: output thread ended (pid=7762)
> Oct 16 23:37:58 vdr vdr[7763]: input thread ended (pid=7763)
> Oct 16 23:37:58 vdr vdr[7610]: buffer stats: 37976 (3%) used
> Oct 16 23:37:58 vdr vdr[7610]: timer 28 stop
> Oct 16 23:37:58 vdr vdr[7610]: deleting timer 28

So this was a "one shot" timer that was triggered at a completely wrong time.

> Oct 16 23:40:06 vdr vdr[7610]: system time seen is Tue Oct 16 23:40:06 2001
> Oct 16 23:40:06 vdr vdr[7610]: timer 57 start
> Oct 16 23:40:06 vdr vdr[7610]: switching to channel 45
> Oct 16 23:40:06 vdr vdr[7610]: Title: 'Die Harald Schmidt Show' Subtitle: ''
> Oct 16 23:40:06 vdr vdr[7610]: record /video/Die_Wochenshow_-_Classics/2001-10-16.23:15.50.98.rec
> Oct 16 23:40:06 vdr vdr[7610]: recording to '/video/Die_Wochenshow_-_Classics/2001-10-16.23:15.50.98.rec/002.vdr'
> Oct 16 23:40:06 vdr vdr[7768]: output thread started (pid=7768)
> Oct 16 23:40:06 vdr vdr[7769]: input thread started (pid=7769)
> Oct 16 23:40:08 vdr vdr[7768]: output thread ended (pid=7768)
> Oct 16 23:40:08 vdr vdr[7769]: input thread ended (pid=7769)
> Oct 16 23:40:08 vdr vdr[7610]: buffer stats: 28012 (2%) used
> Oct 16 23:40:08 vdr vdr[7610]: timer 57 stop
> Oct 16 23:40:08 vdr vdr[7610]: deleting timer 57

That's odd: did you have the *same* timer programmed twice?

> Oct 16 23:43:44 vdr vdr[7610]: ERROR: channel 269 not sync'ed on DVB card 2!
> Oct 16 23:43:44 vdr vdr[7610]: retrying

Can you please apply the following patch to VDR/config.c? This will dump some
internal information in case a timer is triggered. Hopefully we can then see
why this is happening. Note that as long as the timer is active (i.e. recording)
there will be information writen to the log file, so the log may become pretty
large. Once you get such an error case again, please post the lines around the
start and stop of that timer.

Here's the debug patch:

------------------------------------- snip -----------------------------------------
--- config.c    2001/09/22 13:36:59     1.73
+++ config.c    2001/10/17 16:12:08
@@ -554,6 +554,24 @@
             }
          }
       }
+  if (active && startTime <= t && t < stopTime) {
+     int i;
+     time_t tx = 0;
+     for (i = -1; i <= DaysToCheck; i++) {
+         time_t t0 = IncDay(t, i);
+         if (DayMatches(t0)) {
+            time_t a = SetTime(t0, begin);
+            time_t b = a + length;
+            if (t <= b) {
+               startTime = a;
+               stopTime = b;
+               tx = t0;
+               break;
+               }
+            }
+         }
+     dsyslog(LOG_INFO, "%d %d %d - %d %d - %d %d %d", begin, length, DaysToCheck, i, tx, startTime, t, stopTime);
+     }
   return active && startTime <= t && t < stopTime; // must stop *before* stopTime to allow adjacent timers
 }
------------------------------------- snip -----------------------------------------


Klaus
-- 
_______________________________________________________________

Klaus Schmidinger                       Phone: +49-8635-6989-10
CadSoft Computer GmbH                   Fax:   +49-8635-6989-40
Hofmark 2                               Email:   kls@cadsoft.de
D-84568 Pleiskirchen, Germany           URL:     www.cadsoft.de
_______________________________________________________________