[mythtv-users] HD-PVR: Encoding Errors Running 0.22

Sat Nov 28 17:30:36 UTC 2009

David Engel wrote:
> On Fri, Nov 27, 2009 at 01:11:11PM -0500, Jeremy Thornhill wrote:
>> I believe the 'device not running' stuff is MythTV's signal monitor
>> detecting that the HD-PVR hardware decided to stop recording. I don't
>> pretend to know the details of why, but it seems that sometimes the
>> hdpvr just mysteriously fails, and when mythtv detects this it tells
>> the HD-PVR to start recording again.
>>
>> So, those 'gaps' that people are seeing are spots where the hd-pvr is
>> cutting out. Once mythtv restarts the device, the recording picks back
>> up.
> 
> I thought everyone already knew this, but just in case...  Mythtv has
> a workaround for the problem for the problem when the hdpvr stops
> recording.  When mythtv hasn't received data in some period of time,
> it assumes the hdpvr stopped and restarts the recording.  If mythtv
> didn't do this, the recording would end at the firts gap you see, the
> backend would be wedged affecting later recordings and there would be
> a lot more unhappy hdpvr users.

Do you know where this timeout is at?  Maybe it needs to be shortened to 
lessen the size of the gaps?

The odd thing is that it's just the video that has the drop outs.  The audio 
doesn't drop out at all.

>> I'm horribly perplexed by my situation though. My device seems to just
>> arbitrarily fail to start recording properly - once it's started, it's
>> fine. The first time I start recording with it after a boot, it's
>> fine. But after that it's a total crap shoot. Sometimes the next
>> recording is fine, sometimes it will fail 2 times and then start,
>> sometimes it will fail 20 times in a row!
> 
> This sounds like an overheating problem...

Well, I've taken the top off and put a fan mesh cover on it and turned it on 
it's side so the bottom it ventilated too.  It seems quite cool like this.

>> Even more bizarre, if I rmmod/modprobe the hdpvr module, it will
>> always record properly immediately thereafter.
> 
> ...and this sounds like a driver problem.
> 
>> I'm at a loss. Is my hdpvr defective? Perhaps something subtle is
>> wrong with my kernel config? The debug messages from the hdpvr module
>> tell me almost nothing. I'm wondering if I could patch the mythtv
>> source to rmmod / modprobe the module when a signal error is detected,
>> as that seems to almost always resolve my problems.
> 
> I don't know about your hdpvr, but I doubt it's your kernel config.
> Yes, the driver debug is so terse it's of little use, at least for
> this problem.
> 
> My guess is it's one of two things.  1) It's a firmware problem.  Has
> anyone been brave enough to try the new 1.5.6.1 firmware yet to see if
> it improves anything?  2) It's a subtle driver problem that doesn't
> affect the driver developers, and consequently, is not getting enough
> attention.  John P Poet is doing what he can, but the original hdpvr
> driver developer has been conspicuously abesnt from this whole
> discussion.

I've put the 1.5.6.1 firmware on mine.  It looks like the problem is still 
there.  And it's odd.  I watched a recording while it recorded last night. 
Unfortunately, I had to go to bed at 1am.  So I exited the recording and THEN 
I got the errors in the log.  It worked flawlessly for an hour up to that 
point.  Here's the messages in the backend log:

2009-11-28 00:10:02.972 TVRec(4): StartRecording(RocknRolla)
2009-11-28 00:10:02.972 TVRec(4): Checking input group recorders - begin
2009-11-28 00:10:02.973 TVRec(4): Checking input group recorders - done
2009-11-28 00:10:02.981 AutoExpire: CalcParams(): Max required Free Space: 2.0 
GB w/freq: 15 min
2009-11-28 00:10:02.982 Started recording: RocknRolla: channel 3176 on cardid 
4, sourceid 1
2009-11-28 00:10:02.997 TVRec(4): Found channel (501) on current card(4).
2009-11-28 00:10:03.013 TVRec(4): ClearFlags(RingBufferReady,) -> 
RunMainLoop,CancelNextRecording,RecorderRunning,
2009-11-28 00:10:03.013 TVRec(4): Request: Program(no) channel(501) input() 
flags(LiveTV,)
2009-11-28 00:10:03.023 MPEGRec(/dev/hdpvr): PauseAndWait pause
2009-11-28 00:10:03.028 TVRec(4): HW Tuner: 4->4
2009-11-28 00:10:03.028 TVRec(4): ClearFlags(PENDINGACTIONS,) -> 
RunMainLoop,CancelNextRecording,RecorderRunning,
2009-11-28 00:10:03.028 TVRec(4): Waiting for recorder pause..
2009-11-28 00:10:03.028 MPEGRec(/dev/hdpvr): StopEncoding
2009-11-28 00:10:03.028 TVRec(4): SetFlags(WaitingForRecPause,) -> 
RunMainLoop,CancelNextRecording,WaitingForRecPause,RecorderRunning,
2009-11-28 00:10:04.739 MPEGRec(/dev/hdpvr): Encoding stopped
2009-11-28 00:10:04.739 TVRec(4): ClearFlags(WaitingForRecPause,) -> 
RunMainLoop,CancelNextRecording,RecorderRunning,
2009-11-28 00:10:04.739 TVRec(4): Recorder paused, calling TuningFrequency
2009-11-28 00:10:04.782 ret_pid(3209) child(3209) status(0x0)
2009-11-28 00:10:04.782 External Tuning program exited with no error
2009-11-28 00:10:04.847 TVRec(4): SwitchLiveTVRingBuffer(discont 1, set_rec 0)
2009-11-28 00:10:04.847 TVRec(4): GetProgramRingBufferForLiveTV()
2009-11-28 00:10:04.868 TVRec(4): StartedRecording(0x82985c0) 
fn(/mythtv_storage/recordings/3176_20091128001004.mpg)
2009-11-28 00:10:04.904 TVRec(4): FinishedRecording(Flight of the Conchords) 
in recgroup: LiveTV
2009-11-28 00:10:04.904 Chain: Updated endtime for '3176_20091128000800' to 
20091128001004
2009-11-28 00:10:04.907 Finished recording Flight of the Conchords "Sally 
Returns": channel 3176
2009-11-28 00:10:04.908 Preview: 
'myth://127.0.0.1:6543/3176_20091128000800.mpg' is not local,
			replacing with '/mythtv_storage/recordings/3176_20091128000800.mpg', which 
is local.
2009-11-28 00:10:04.919 Chain: Appended at 3 '3176_20091128001004'
2009-11-28 00:10:04.957 TVRec(4): Starting Signal Monitor
2009-11-28 00:10:04.957 TVRec(4): SetupSignalMonitor(1, 1)
2009-11-28 00:10:04.957 AnalogSM: /dev/hdpvr card 'Haupauge HD PVR' driver 
'hdpvr' version '512'
2009-11-28 00:10:04.957 TVRec(4): Signal monitor successfully created
2009-11-28 00:10:04.957 AnalogSM: /dev/hdpvr hd-pvr start encoding
2009-11-28 00:10:04.957 TVRec(4): SetFlags(SignalMonitorRunning,) -> 
RunMainLoop,CancelNextRecording,SignalMonitorRunning,RecorderRunning,
2009-11-28 00:10:04.958 TVRec(4): ClearFlags(WaitingForSignal,) -> 
RunMainLoop,CancelNextRecording,SignalMonitorRunning,RecorderRunning,
2009-11-28 00:10:04.958 TVRec(4): SetFlags(WaitingForSignal,) -> 
RunMainLoop,CancelNextRecording,WaitingForSignal,SignalMonitorRunning,RecorderRunning,
2009-11-28 00:10:04.958 RecBase(4:/dev/hdpvr): SetRingBuffer(0x0)
2009-11-28 00:10:04.958 TVRec(4): SetFlags(DummyRecorderRunning,) -> 
RunMainLoop,CancelNextRecording,WaitingForSignal,SignalMonitorRunning,ANYRECRUNNING,
2009-11-28 00:10:04.958 DummyDTVRecorder -- started
2009-11-28 00:10:04.958 TVRec(4): SetFlags(RingBufferReady,) -> 
RunMainLoop,CancelNextRecording,WaitingForSignal,SignalMonitorRunning,ANYRECRUNNING,RingBufferReady,
2009-11-28 00:10:04.958 TVRec(4): ClearFlags(NeedToStartRecorder,) -> 
RunMainLoop,CancelNextRecording,WaitingForSignal,SignalMonitorRunning,ANYRECRUNNING,RingBufferReady,
2009-11-28 00:10:04.958 TVRec(4): SetFlags(NeedToStartRecorder,) -> 
RunMainLoop,CancelNextRecording,WaitingForSignal,NeedToStartRecorder,SignalMonitorRunning,ANYRECRUNNING,RingBufferReady,
2009-11-28 00:10:04.961 AutoExpire: CalcParams(): Max required Free Space: 2.0 
GB w/freq: 15 min
2009-11-28 00:10:05.027 mythbackend version: branches/release-0-22-fixes 
[Unknown] www.mythtv.org
2009-11-28 00:10:05.028 Using runtime prefix = /usr/local
2009-11-28 00:10:05.028 Using configuration directory = /home/mythtv/.mythtv
2009-11-28 00:10:05.028 Empty LocalHostName.
2009-11-28 00:10:05.028 Using localhost value of pdvr
2009-11-28 00:10:05.034 New DB connection, total: 1
2009-11-28 00:10:05.037 Connected to database 'mythconverg' at host: 127.0.0.1
2009-11-28 00:10:05.037 Closing DB connection named 'DBManager0'
2009-11-28 00:10:05.038 Connected to database 'mythconverg' at host: 127.0.0.1
2009-11-28 00:10:05.050 Current MythTV Schema Version (DBSchemaVer): 1244
2009-11-28 00:10:05.051 New DB connection, total: 2
2009-11-28 00:10:05.052 Connected to database 'mythconverg' at host: 127.0.0.1
2009-11-28 00:10:05.302 AnalogSM: /dev/hdpvr hd-pvr wait for data
2009-11-28 00:10:05.335 AnalogSM: /dev/hdpvr hd-pvr data ready.  Stop encoding
2009-11-28 00:10:07.512 AFD: Opened codec 0x8277be0, id(H264) type(Video)
2009-11-28 00:10:07.512 AFD: codec AC3 has 2 channels
2009-11-28 00:10:07.513 AFD: Opened codec 0x828cc70, id(AC3) type(Audio)
2009-11-28 00:10:07.538 AnalogSM: /dev/hdpvr hd-pvr waiting for valid resolution
2009-11-28 00:10:07.539 AnalogSM: /dev/hdpvr hd-pvr resolution 1920 x 1080
2009-11-28 00:10:07.540 TVRec(4): Got good signal
2009-11-28 00:10:07.540 TVRec(4): TeardownSignalMonitor() -- begin
2009-11-28 00:10:07.591 TVRec(4): TeardownSignalMonitor() -- end
2009-11-28 00:10:07.591 TVRec(4): ClearFlags(SignalMonitorRunning,) -> 
RunMainLoop,CancelNextRecording,WaitingForSignal,NeedToStartRecorder,ANYRECRUNNING,RingBufferReady,
2009-11-28 00:10:07.591 TVRec(4): ClearFlags(WaitingForSignal,) -> 
RunMainLoop,CancelNextRecording,NeedToStartRecorder,ANYRECRUNNING,RingBufferReady,
2009-11-28 00:10:07.592 TVRec(4): Restarting Recorder
2009-11-28 00:10:07.592 TVRec(4): ClearFlags(DummyRecorderRunning,) -> 
RunMainLoop,CancelNextRecording,NeedToStartRecorder,RecorderRunning,RingBufferReady,
2009-11-28 00:10:07.596 TVRec(4): FinishedRecording(RocknRolla) in recgroup: 
LiveTV
2009-11-28 00:10:07.597 Chain: Updated endtime for '3176_20091128001004' to 
20091128001007
2009-11-28 00:10:07.599 Finished recording RocknRolla: channel 3176
2009-11-28 00:10:07.601 TVRec(4): SwitchLiveTVRingBuffer(discont 1, set_rec 0)
2009-11-28 00:10:07.601 TVRec(4): GetProgramRingBufferForLiveTV()
2009-11-28 00:10:07.639 TVRec(4): StartedRecording(0x82a4868) 
fn(/mythtv_storage/recordings/3176_20091128001000.mpg)
2009-11-28 00:10:07.665 TVRec(4): FinishedRecording(RocknRolla) in recgroup: 
LiveTV
2009-11-28 00:10:07.667 Chain: Updated endtime for '3176_20091128001004' to 
20091128001007
2009-11-28 00:10:07.675 Finished recording RocknRolla: channel 3176
2009-11-28 00:10:07.681 Chain: Appended at 4 '3176_20091128001000'
2009-11-28 00:10:07.682 RecBase(4:/dev/hdpvr): SetRingBuffer(0x82e0e28) 
'/mythtv_storage/recordings/3176_20091128001000.mpg'
2009-11-28 00:10:07.688 RecBase(4:/dev/hdpvr): SetRecording(0xb11fed14) 
title(RocknRolla)
2009-11-28 00:10:07.688 MPEGRec(/dev/hdpvr): Reset(void)
2009-11-28 00:10:07.689 DTVRec(4): ResetForNewFile(void)
2009-11-28 00:10:07.690 MPEGRec(/dev/hdpvr): PauseAndWait unpause
2009-11-28 00:10:07.690 MPEGRec(/dev/hdpvr): Checking Resolution
2009-11-28 00:10:07.691 MPEGRec(/dev/hdpvr): Got Resolution 1920x1080
2009-11-28 00:10:07.691 MPEGRec(/dev/hdpvr): StartEncoding
2009-11-28 00:10:07.695 TVRec(4): Pseudo LiveTV recording starting.
			Recording: RocknRolla 3176 Sat Nov 28 00:10:00 2009 Sat Nov 28 02:10:00 2009
			Recording: RocknRolla 3176 Sat Nov 28 00:10:00 2009 Sat Nov 28 02:10:00 2009
2009-11-28 00:10:07.762 Using profile 'Default' to record
2009-11-28 00:10:07.762 TVRec(4): ClearFlags(NeedToStartRecorder,) -> 
RunMainLoop,CancelNextRecording,RecorderRunning,RingBufferReady,
2009-11-28 00:10:07.770 AutoExpire: CalcParams(): Max required Free Space: 2.0 
GB w/freq: 15 min
2009-11-28 00:10:08.038 MPEGRec(/dev/hdpvr): Encoding started
2009-11-28 00:10:08.079 CreatePATSingleProgram()
2009-11-28 00:10:08.079 PAT in input stream
2009-11-28 00:10:08.079 Program Association Table
  PSIP tableID(0x0) length(17) extension(0x0)
       version(1) current(1) section(0) last_section(0)
          tsid: 0
  programCount: 2
   program number     0 has PID 0x  1f   data  0x 0 0x 0 0xe0 0x1f
   program number     1 has PID 0x 100   data  0x 0 0x 1 0xe1 0x 0

2009-11-28 00:10:08.080 desired_program(1) pid(0x100)
2009-11-28 00:10:08.080 pmt_pid(0x100)
2009-11-28 00:10:08.080 PAT for output stream
2009-11-28 00:10:08.080 Program Association Table
  PSIP tableID(0x0) length(13) extension(0x0)
       version(1) current(1) section(0) last_section(0)
          tsid: 0
  programCount: 1
   program number     1 has PID 0x 100   data  0x 0 0x 1 0xe1 0x 0

2009-11-28 00:10:08.080 CreatePMTSingleProgram()
2009-11-28 00:10:08.081 PMT in input stream
2009-11-28 00:10:08.081 Program Map Table ver(0) pid(0x100) pnum(1) len(59)
   Registration Descriptor: 'HDMV' Blu-Ray A/V for read-only media (H.264 TS)
   Unknown(136) Descriptor (0x88) length(4)

  Stream #0 pid(0x1011) type(video-h264  0x1b)
   Registration Descriptor: 'HDMV' Blu-Ray A/V for read-only media (H.264 TS)
  Stream #1 pid(0x1100) type(audio-ac3  0x81)
   Registration Descriptor: 'AC-3' ATSC audio stream A/52
   Audio Stream Descriptor  full_srv(1) sample_rate(48kbps) bit_rate(=384kbps, 14)
       bsid(6) bs_mode(0) channels(2/0) Dolby(Not indicated)
       mainID(0)

2009-11-28 00:10:08.081 PMT for output stream
2009-11-28 00:10:08.082 Program Map Table ver(0) pid(0x100) pnum(1) len(59)
   Registration Descriptor: 'HDMV' Blu-Ray A/V for read-only media (H.264 TS)
   Unknown(136) Descriptor (0x88) length(4)

  Stream #0 pid(0x1011) type(video-h264  0x1b)
   Registration Descriptor: 'HDMV' Blu-Ray A/V for read-only media (H.264 TS)
  Stream #1 pid(0x1100) type(audio-ac3  0x81)
   Registration Descriptor: 'AC-3' ATSC audio stream A/52
   Audio Stream Descriptor  full_srv(1) sample_rate(48kbps) bit_rate(=384kbps, 14)
       bsid(6) bs_mode(0) channels(2/0) Dolby(Not indicated)
       mainID(0)

2009-11-28 00:10:08.082 PID 0x1011 Found Payload Start
2009-11-28 00:10:08.099 PID 0x1100 Found Payload Start
2009-11-28 00:10:09.499 RecBase(4:/dev/hdpvr): 
GetKeyframePositions(1,9223372036854775807,#0) out of 1
2009-11-28 00:10:10.837 Preview: Grabbed preview 
'/mythtv_storage/recordings/3176_20091128000800.mpg' 1920x1088 at 79s
2009-11-28 00:10:30.205 TVRec(1): Deleting stale pending recording 4 'RocknRolla'
2009-11-28 00:10:31.197 Expiring 12 MBytes for 3176 @ Fri Nov 27 23:40:00 2009 
=> Flight of the Conchords "Sally Returns"
2009-11-28 00:10:31.204 Expiring 0 MBytes for 3176 @ Fri Nov 27 23:40:00 2009 
=> Flight of the Conchords "Sally Returns"
2009-11-28 00:12:31.211 Expiring 0 MBytes for 3176 @ Sat Nov 28 00:10:00 2009 
=> RocknRolla
2009-11-28 00:14:31.219 AutoExpire: CalcParams(): Max required Free Space: 2.0 
GB w/freq: 15 min
2009-11-28 00:29:31.295 AutoExpire: CalcParams(): Max required Free Space: 2.0 
GB w/freq: 15 min
2009-11-28 00:44:31.359 AutoExpire: CalcParams(): Max required Free Space: 2.0 
GB w/freq: 15 min
2009-11-28 00:57:12.842 TVRec(4): StopLiveTV(void) curRec: 0x82a4868 
pseudoRec: 0xab0eff50
2009-11-28 00:57:12.848 TVRec(4): Changing from Watching WatchingLiveTV to 
Watching RecordingOnly
2009-11-28 00:57:12.848 TVRec(4): 
ClearFlags(FrontendReady,CancelNextRecording,) -> 
RunMainLoop,RecorderRunning,RingBufferReady,
2009-11-28 00:57:12.849 TVRec(4): SetFlags(FrontendReady,) -> 
FrontendReady,RunMainLoop,RecorderRunning,RingBufferReady,
2009-11-28 00:57:21.096 DevRdB(/dev/hdpvr) Error: Poll giving up
2009-11-28 00:57:21.096 DevRdB(/dev/hdpvr): fill_ringbuffer: error state
2009-11-28 00:57:21.100 MPEGRec(/dev/hdpvr) Error: Device error detected
2009-11-28 00:57:21.100 MPEGRec(/dev/hdpvr): RestartEncoding
2009-11-28 00:57:21.100 DevRdB(/dev/hdpvr): Stop(): Not running.
2009-11-28 00:57:21.100 MPEGRec(/dev/hdpvr): StopEncoding
2009-11-28 00:57:22.433 MPEGRec(/dev/hdpvr): Encoding stopped
2009-11-28 00:57:22.433 MPEGRec(/dev/hdpvr): Checking Resolution
2009-11-28 00:57:22.434 MPEGRec(/dev/hdpvr): Got Resolution 1920x1080
2009-11-28 00:57:22.434 MPEGRec(/dev/hdpvr): StartEncoding
2009-11-28 00:57:22.788 MPEGRec(/dev/hdpvr): Encoding started
2009-11-28 00:57:22.828 MPEGRec(/dev/hdpvr): PID 0x1100 discontinuity detected
2009-11-28 00:57:22.828 MPEGRec(/dev/hdpvr): PID 0x1011 discontinuity detected
2009-11-28 00:59:07.039 DevRdB(/dev/hdpvr) Error: Poll giving up
2009-11-28 00:59:07.039 DevRdB(/dev/hdpvr): fill_ringbuffer: error state
2009-11-28 00:59:07.043 MPEGRec(/dev/hdpvr) Error: Device error detected
2009-11-28 00:59:07.043 MPEGRec(/dev/hdpvr): RestartEncoding
2009-11-28 00:59:07.043 DevRdB(/dev/hdpvr): Stop(): Not running.
2009-11-28 00:59:07.044 MPEGRec(/dev/hdpvr): StopEncoding
2009-11-28 00:59:08.378 MPEGRec(/dev/hdpvr): Encoding stopped
2009-11-28 00:59:08.378 MPEGRec(/dev/hdpvr): Checking Resolution
2009-11-28 00:59:08.379 MPEGRec(/dev/hdpvr): Got Resolution 1920x1080
2009-11-28 00:59:08.379 MPEGRec(/dev/hdpvr): StartEncoding
2009-11-28 00:59:08.734 MPEGRec(/dev/hdpvr): Encoding started
2009-11-28 00:59:08.774 MPEGRec(/dev/hdpvr): PID 0x1100 discontinuity detected
2009-11-28 00:59:08.775 MPEGRec(/dev/hdpvr): PID 0x1011 discontinuity detected
2009-11-28 00:59:32.016 AutoExpire: CalcParams(): Max required Free Space: 2.0 
GB w/freq: 15 min
2009-11-28 01:04:27.520 DevRdB(/dev/hdpvr) Error: Poll giving up
2009-11-28 01:04:27.520 DevRdB(/dev/hdpvr): fill_ringbuffer: error state
2009-11-28 01:04:27.524 MPEGRec(/dev/hdpvr) Error: Device error detected
2009-11-28 01:04:27.524 MPEGRec(/dev/hdpvr): RestartEncoding
2009-11-28 01:04:27.524 DevRdB(/dev/hdpvr): Stop(): Not running.
2009-11-28 01:04:27.524 MPEGRec(/dev/hdpvr): StopEncoding
2009-11-28 01:04:28.859 MPEGRec(/dev/hdpvr): Encoding stopped
2009-11-28 01:04:28.859 MPEGRec(/dev/hdpvr): Checking Resolution
2009-11-28 01:04:28.860 MPEGRec(/dev/hdpvr): Got Resolution 1920x1080
2009-11-28 01:04:28.860 MPEGRec(/dev/hdpvr): StartEncoding
2009-11-28 01:04:29.209 MPEGRec(/dev/hdpvr): Encoding started
2009-11-28 01:04:29.249 MPEGRec(/dev/hdpvr): PID 0x1100 discontinuity detected
2009-11-28 01:04:29.250 MPEGRec(/dev/hdpvr): PID 0x1011 discontinuity detected
2009-11-28 01:06:53.672 DevRdB(/dev/hdpvr) Error: Poll giving up
2009-11-28 01:06:53.672 DevRdB(/dev/hdpvr): fill_ringbuffer: error state
2009-11-28 01:06:53.675 MPEGRec(/dev/hdpvr) Error: Device error detected
2009-11-28 01:06:53.675 MPEGRec(/dev/hdpvr): RestartEncoding
2009-11-28 01:06:53.675 DevRdB(/dev/hdpvr): Stop(): Not running.
2009-11-28 01:06:53.675 MPEGRec(/dev/hdpvr): StopEncoding
2009-11-28 01:06:55.009 MPEGRec(/dev/hdpvr): Encoding stopped
2009-11-28 01:06:55.009 MPEGRec(/dev/hdpvr): Checking Resolution
2009-11-28 01:06:55.010 MPEGRec(/dev/hdpvr): Giving up detecting resolution
2009-11-28 01:06:55.010 MPEGRec(/dev/hdpvr): StartEncoding
2009-11-28 01:06:55.265 MPEGRec(/dev/hdpvr) Error: StartEncoding failed
			eno: Resource temporarily unavailable (11)
2009-11-28 01:06:55.266 MPEGRec(/dev/hdpvr): usingv4l2(1) has_v4l2_vbi(0) 
has_buggy_vbi(1)
2009-11-28 01:06:55.311 DevRdB(/dev/hdpvr): buffer size 9400 KB
2009-11-28 01:06:55.311 MPEGRec(/dev/hdpvr): DRB ready
2009-11-28 01:14:32.058 AutoExpire: CalcParams(): Max required Free Space: 2.0 
GB w/freq: 15 min
2009-11-28 01:29:32.090 AutoExpire: CalcParams(): Max required Free Space: 2.0 
GB w/freq: 15 min
2009-11-28 01:44:32.121 AutoExpire: CalcParams(): Max required Free Space: 2.0 
GB w/freq: 15 min
2009-11-28 01:59:32.153 AutoExpire: CalcParams(): Max required Free Space: 2.0 
GB w/freq: 15 min
2009-11-28 02:10:00.370 TVRec(4): ClearFlags(FinishRecording,) -> 
FrontendReady,RunMainLoop,RecorderRunning,RingBufferReady,
2009-11-28 02:10:00.370 TVRec(4): Changing from Watching RecordingOnly to None
2009-11-28 02:10:00.370 TVRec(4): 
ClearFlags(FrontendReady,CancelNextRecording,) -> 
RunMainLoop,RecorderRunning,RingBufferReady,
2009-11-28 02:10:00.370 TVRec(4): Request: Program(no) channel() input() 
flags(CloseRec,KillRingBuffer,)
2009-11-28 02:10:00.371 Unknown type, recording width was 0
2009-11-28 02:10:00.372 MPEGRec(/dev/hdpvr): StartRecording finishing up
2009-11-28 02:10:00.372 MPEGRec(/dev/hdpvr): StopEncoding
2009-11-28 02:10:00.373 MPEGRec(/dev/hdpvr): Encoding stopped
2009-11-28 02:10:00.374 MPEGRec(/dev/hdpvr): SetStreamData(0x0) -- begin
2009-11-28 02:10:00.381 MPEGRec(/dev/hdpvr): SetStreamData(0x0) -- end 1
2009-11-28 02:10:00.381 TVRec(4): ClearFlags(RecorderRunning,) -> 
RunMainLoop,RingBufferReady,
2009-11-28 02:10:00.389 TVRec(4): FinishedRecording(RocknRolla) in recgroup: 
Default
2009-11-28 02:10:00.390 Finished recording RocknRolla: channel 3176
2009-11-28 02:10:00.390 TVRec(4): ClearFlags(RecorderRunning,) -> 
RunMainLoop,RingBufferReady,
2009-11-28 02:10:00.390 TVRec(4): Tearing down RingBuffer
2009-11-28 02:10:00.391 TVRec(4): ClearFlags(PENDINGACTIONS,) -> 
RunMainLoop,RingBufferReady,

I didn't see any messages in the kernel log.

To me it seems like there's a timing issue somewhere that watching a program 
while it's recording seems to work around it.  Or I'm just extremely lucky it 
hasn't... :)

Alan