[ATrpms-users] occasional zero length mythtv recordings

[Jeffrey J. Kosowsky]

Axel Thimm wrote at about 11:41:23 +0200 on Wednesday, December 26, 2007:
 > On Wed, Dec 26, 2007 at 12:08:32AM -0500, Jeffrey J. Kosowsky wrote:
 > > I am using the latest mythtv 0.20.2-169 packages with a pchdtv 5500
 > > (and also an older winfast 2000xp).
 > > 
 > > I notice that occasionally I get zero length recordings - i.e. the
 > > show itself shows up in mythfrontend with the appropriate timeslot and
 > > description but the recording itself is an empty file.
 > > 
 > > It probably happens about 5-10% of the time but I have not noticed a
 > > definite pattern though it tends to happen mostly to a couple of shows
 > > that I record at about 4-6AM on Sunday morning. The only thing about
 > > that timeslot is that it is the time that my daily & weekly cron
 > > scripts run then, including an f-prot antivirus scan.
 > > 
 > > Could the system load be affecting the ability to record or is there
 > > some other (known) explanation for such zero length recordings?
 > 
 > I would second this assumption, but in any case there should be a log
 > entry that states that. 
Yes. That is the strange thing. I don't see any log entries in
/var/log/mythtv/mythbackend.log (or even in /var/log/messages)
 mentioning problems.

The only relevant entries I have are:
	2007-12-23 05:30:02.589 TVRec(1): Changing from None to RecordingOnly
	2007-12-23 05:30:02.618 TVRec(1): HW Tuner: 1->1
	2007-12-23 05:30:02.646 DVBChan(0) Warning: Symbol Rate setting (0) is out of range (min/max:5056941/10762000)
	2007-12-23 05:30:02.664 Started recording: Hometime "Fold-Down Bed": channel 2041 on cardid 1, sourceid 2
	2007-12-23 06:00:00.983 TVRec(1): Changing from RecordingOnly to None
	2007-12-23 06:00:01.464 Finished recording Hometime "Fold-Down Bed": channel 2041
	2007-12-23 06:00:01.486 Reschedule requested for id 0.
	2007-12-23 06:00:02.011 Scheduled 93 items in 0.5 = 0.03 match + 0.50 place

The only log difference I see between this failed recording and all
the other successful recordings is that during a successful recording,
I get a SECOND "Finished recording..." line between the "Reschedule
requested for id 0" line and the "Scheduled X items..." line. Also, in
a successful recording, I get a series of lines following the
"Scehduled XX items..." line that seem to describe the recorded stream
that don't appear in the corresponding failed recording

Here is an example of a SUCCESSFUL recording of the same show:
	 2007-12-16 05:30:02.624 TVRec(1): Changing from None to RecordingOnly
	 2007-12-16 05:30:02.650 TVRec(1): HW Tuner: 1->1
	 2007-12-16 05:30:02.683 DVBChan(0) Warning: Symbol Rate setting (0) is out of range (min/max:5056941/10762000)
	 2007-12-16 05:30:02.731 Started recording: Hometime "Pint-Sized Fireplace": channel 2041 on cardid 1, sourceid 2
	 2007-12-16 06:00:00.170 TVRec(1): Changing from RecordingOnly to None
	 2007-12-16 06:00:00.253 Finished recording Hometime "Pint-Sized Fireplace": channel 2041
	 2007-12-16 06:00:00.293 Reschedule requested for id 0.
	 2007-12-16 06:00:01.049 Finished recording Hometime "Pint-Sized Fireplace": channel 2041
	 2007-12-16 06:00:01.109 Scheduled 87 items in 0.8 = 0.00 match + 0.81 place
	 0: start_time: 8230.118 duration: 161.642
	 1: start_time: 8230.086 duration: 161.637
	 stream: start_time: 91445.405 duration: 1796.378 bitrate=18504 kb/s
	 2007-12-16 06:00:01.211 AFD: Opened codec 0xae1d2d20, id(MPEG2VIDEO) type(Video)
	 2007-12-16 06:00:01.241 AFD: Opened codec 0xae1d3320, id(AC3) type(Audio)
	 [mpeg2video @ 0x35782c0]ac-tex damaged at 10 67
	 [mpeg2video @ 0x35782c0]00 motion_type at 57 67
	 [mpeg2video @ 0x35782c0]00 motion_type at 83 67
	 CC length(103) seq_num(1) 0x74 0x61 
	 CC length(103) seq_num(1) 0x74 0x61 
	 CC length(103) seq_num(1) 0x74 0x61 

Note that I get the DVBChan(0) Warning even when recording works (and
also whenever I start mythbackend). I'm not sure what it means (does
anybody?) but it doesn't seem like the problem here.

 > Maybe during the cron jobs your disk fills up
 > (logwatch can create huge temporary files) and therefore any other
 > created file is truncated to zero?
 > 
Probably not disk full since my root partition is only about 50% full
(with 8GB free) and programs get recorded on a separate partition with
plenty of free space.

 > You can simulate the 4:00 cron jobs by calling them explicitely to
 > monitor what is happening.

Yup. But looking at the log files, I'm beginning to think that load is
less of an issue.