[vdr] Re: Log of Timer Bug

[Carsten Koch <Carsten.Koch@icem.de>]

Klaus Schmidinger wrote:
...
> > Anybody else who ever experienced a timer not starting at the expected
> > time or being executed at a completely wrong time should please also apply
> > this patch and send me the log data if that happens.
> 
> In order to get even more data please change the 'dsyslog()' call to
> 
>   dsyslog(LOG_INFO, "%d %04d %04d %08X %d %d %d - %d %d - %d %d %d", channel, start, stop, day, begin, length, DaysToCheck, i, tx, startTime, t, stopTime);

Unfortunately, I have not seen a timer not starting at the expected
time or being executed at a completely wrong time since I applied
that log patch, but I do see this log output often WITHOUT a recording
being started. 
See below for a complete VDR session log from start to exit.

So I guess the bug in VDR is not, that the timers are started 
at the wrong time.
The bug is, that the timers are started at the wrong day!
Apparently, the day test only fails "sometimes".
That would also explain why they are started late and why 
they are stopped after a very short time.
If it does not fail long enough to even start a recording, we 
only see the "stray" log entries you find below.

As another confirmation for this theory, I do NOT have a
timer entry for 0708-0745 on the 19th, but I DO have one
on the 20th and 21st. Similarly,  I do NOT have a timer 
entry for 0635-0855 on the 19th, but DO have one on the 21st.

Carsten.


Oct 19 05:32:12 vdr vdr[26229]: VDR version 0.96 started
Oct 19 05:32:12 vdr vdr[26229]: loading ./setup.conf
Oct 19 05:32:12 vdr vdr[26229]: loading ./channels.conf
Oct 19 05:32:12 vdr vdr[26229]: loading ./timers.conf
Oct 19 05:32:12 vdr vdr[26229]: loading ./commands.conf
Oct 19 05:32:12 vdr vdr[26229]: probing /dev/ost/frontend0
Oct 19 05:32:12 vdr vdr[26231]: EIT processing thread started (pid=26231) - master
Oct 19 05:32:12 vdr vdr[26229]: probing /dev/ost/frontend1
Oct 19 05:32:12 vdr vdr[26232]: EIT processing thread started (pid=26232)
Oct 19 05:32:12 vdr vdr[26229]: probing /dev/ost/frontend2
Oct 19 05:32:12 vdr vdr[26229]: found 2 video devices
Oct 19 05:32:12 vdr vdr[26229]: setting primary DVB to 1
Oct 19 05:32:12 vdr vdr[26229]: switching to channel 2
Oct 19 05:32:13 vdr vdr[26233]: LIRC remote control thread started (pid=26233)
Oct 19 05:32:13 vdr vdr[26229]: SVDRP listening on port 2001
Oct 19 05:32:13 vdr vdr[26229]: setting watchdog timer to 15 seconds
Oct 19 05:32:18 vdr vdr[26229]: assuming manual start of VDR
Oct 19 05:32:19 vdr vdr[26229]: max. latency time 1 seconds
Oct 19 05:48:23 vdr vdr[26229]: ERROR: channel 269 not sync'ed on DVB card 2!
Oct 19 05:48:23 vdr vdr[26229]: retrying
Oct 19 06:05:59 vdr vdr[26229]: ERROR: channel 269 not sync'ed on DVB card 2!
Oct 19 06:05:59 vdr vdr[26229]: retrying
Oct 19 06:23:33 vdr vdr[26229]: ERROR: channel 269 not sync'ed on DVB card 2!
Oct 19 06:23:33 vdr vdr[26229]: retrying
Oct 19 06:36:00 vdr vdr[26229]: 33 0635 0855 00000015 23700 8400 31 - 2 1003638960 - 1003638900 1003466160 1003647300
Oct 19 06:41:09 vdr vdr[26229]: ERROR: channel 269 not sync'ed on DVB card 2!
Oct 19 06:41:09 vdr vdr[26229]: retrying
Oct 19 06:58:43 vdr vdr[26229]: ERROR: channel 269 not sync'ed on DVB card 2!
Oct 19 06:58:43 vdr vdr[26229]: retrying
Oct 19 07:15:14 vdr vdr[26229]: 9 0708 0745 00000014 25680 2220 31 - 1 1003554914 - 1003554480 1003468514 1003556700
Oct 19 07:16:19 vdr vdr[26229]: ERROR: channel 269 not sync'ed on DVB card 2!
Oct 19 07:16:19 vdr vdr[26229]: retrying
Oct 19 07:16:44 vdr vdr[26229]: 9 0708 0745 00000014 25680 2220 31 - 1 1003555004 - 1003554480 1003468604 1003556700
Oct 19 07:32:19 vdr vdr[26229]: next timer event at Fri Oct 19 09:58:00 2001 
Oct 19 07:32:19 vdr vdr[26229]: confirm: Press any key to cancel shutdown
Oct 19 07:37:20 vdr vdr[26229]: confirmed
Oct 19 07:37:20 vdr vdr[26229]: executing '/home/cko/bin/killvdr 1003478280 8741'
Oct 19 07:37:20 vdr vdr[26229]: caught signal 15
Oct 19 07:37:20 vdr vdr[26229]: saved setup to ./setup.conf
Oct 19 07:37:20 vdr vdr[26231]: EIT processing thread ended (pid=26231) - master
Oct 19 07:37:20 vdr vdr[26232]: EIT processing thread ended (pid=26232)
Oct 19 07:37:20 vdr vdr[26229]: max. latency time 1 seconds
Oct 19 07:37:20 vdr vdr[26229]: exiting