[mythtv-users] Failure to record

Mon Jan 10 12:40:44 UTC 2011

I'm running mythbackend 0.24 on a SheevaPlug (very low power Arm based 
machine).  Since I'm using DVB-S and doing no transcoding, the machine is 
powerful enough, although rescheduling can take several minutes.

I've noticed that it frequently fails to record things.  Afterwards, 
Mythweb shows the recording, but with a blank file size and the mpeg file 
doesn't exist in the recordings directory.

The log shows:
2011-01-07 19:29:01.031 Reschedule requested for id 0.
2011-01-07 19:29:01.032 BuildWorkList...
2011-01-07 19:29:01.033 AddNewRecords...
2011-01-07 19:29:01.180  |-- Start DB Query...
2011-01-07 19:29:12.453  |-- 2600 results in 11.2714 sec. Processing...
2011-01-07 19:29:15.360  +-- Cleanup...
2011-01-07 19:29:15.366 AddNotListed...
2011-01-07 19:29:15.375  |-- Start DB Query...
2011-01-07 19:29:15.379  |-- 0 results in 0.002644 sec. Processing...
2011-01-07 19:29:15.386 Sort by time...
2011-01-07 19:29:15.422 PruneOverlaps...
2011-01-07 19:29:15.424 Sort by priority...
2011-01-07 19:29:19.061 BuildListMaps...
2011-01-07 19:29:19.063 SchedNewRecords...
2011-01-07 19:29:19.086 Scheduling:
 	[ Lots of info about the rescheduling ]
--- print list start ---
Title - Subtitle                    Ch Station Day Start  End   S C I  T N 
Pri
Scrubs - My Butterfly               123 E4+1    07 19:00-19:30  1 0 0  A P 
0
Jimmy's Food Factory - Party Party  101 BBC 1 W 07 19:30-20:00  1 7 7  A 7 
-1
Scrubs - My Moment of Un-Truth      123 E4+1    07 19:30-20:00  1 0 0  A P 
0
QI - Hypnosis, Hallucinations & Hy 106361 BBC 1 C 07 20:30-21:00  1 0 0  A 
C 6
 	[ Lots more scheduling stuff ]
---  print list end  ---
2011-01-07 19:33:11.893 Scheduled 225 items in 250.1 = 0.00 match + 250.14 
place
2011-01-07 19:33:11.931 CardUtil:   Group ID 2
2011-01-07 19:33:11.935 CardUtil:   Card ID 8
2011-01-07 19:33:11.936 CardUtil:   Card ID 9
2011-01-07 19:33:11.937 CardUtil:   Card ID 10
2011-01-07 19:33:11.938 CardUtil:   Card ID 11
2011-01-07 19:33:11.940 Scheduler: FillRecordingDir: Starting
2011-01-07 19:33:11.963 Scheduler: FillRecordingDir: Finished
2011-01-07 19:33:11.983 TVRec(7): RecordPending on inputid 7
2011-01-07 19:33:11.995 CardUtil:   Group ID 2
2011-01-07 19:33:11.999 CardUtil:   Card ID 8
2011-01-07 19:33:12.000 CardUtil:   Card ID 9
2011-01-07 19:33:12.001 CardUtil:   Card ID 10
2011-01-07 19:33:12.001 CardUtil:   Card ID 11
2011-01-07 19:33:12.002 TVRec(8): RecordPending on inputid 7
2011-01-07 19:33:12.003 TVRec(9): RecordPending on inputid 7
2011-01-07 19:33:12.005 TVRec(10): RecordPending on inputid 7
2011-01-07 19:33:12.006 TVRec(11): RecordPending on inputid 7
2011-01-07 19:33:12.031 TVRec(7): ASK_RECORDING 7 0 0 0
2011-01-07 19:33:12.051 TVRec(7): StartRecording("Jimmy's Food 
Factory":"Party Party")
2011-01-07 19:33:12.079 TVRec(7): Checking input group recorders - begin
2011-01-07 19:33:12.081 TVRec(7): Checking input group recorders - done
2011-01-07 19:33:12.352 TVRec(7): StartedRecording(0x5184fbf8) 
fn(/home/mythtv/recordings/11311_20110107193300.mpg)
2011-01-07 19:33:12.364 TVRec(7): ClearFlags(CancelNextRecording,) -> 
FrontendReady,RunMainLoop,SignalMonitorRunning,EITScannerRunning,
2011-01-07 19:33:12.598 TVRec(11): ASK_RECORDING 11 0 0 0
2011-01-07 19:33:12.614 TVRec(8): ASK_RECORDING 8 0 0 0
2011-01-07 19:33:12.621 TVRec(9): ASK_RECORDING 9 0 0 0
2011-01-07 19:33:12.764 TVRec(10): ASK_RECORDING 10 0 0 0
2011-01-07 19:33:42.617 TVRec(11): Deleting stale pending recording 7 
'Jimmy's Food Factory'
2011-01-07 19:33:42.632 TVRec(8): Deleting stale pending recording 7 
'Jimmy's Food Factory'
2011-01-07 19:33:42.633 TVRec(9): Deleting stale pending recording 7 
'Jimmy's Food Factory'
2011-01-07 19:33:42.783 TVRec(10): Deleting stale pending recording 7 
'Jimmy's Food Factory'
2011-01-07 19:41:47.213 AutoExpire: CalcParams(): Max required Free Space: 
10.0 GB w/freq: 15 min
2011-01-07 19:43:21.582 UPnpMedia: BuildMediaMap - no VideoStartupDir set, 
skipping scan.
2011-01-07 19:56:47.911 AutoExpire: CalcParams(): Max required Free Space: 
10.0 GB w/freq: 15 min
2011-01-07 20:11:48.432 AutoExpire: CalcParams(): Max required Free Space: 
10.0 GB w/freq: 15 min
2011-01-07 20:13:22.585 UPnpMedia: BuildMediaMap - no VideoStartupDir set, 
skipping scan.
2011-01-07 20:26:48.999 AutoExpire: CalcParams(): Max required Free Space: 
10.0 GB w/freq: 15 min
2011-01-07 20:41:49.526 AutoExpire: CalcParams(): Max required Free Space: 
10.0 GB w/freq: 15 min

So it appears to claim to start recording, but doesn't actually do so... 
A quick gander at the code suggests that the recording is going to be 
considered "stale" and get deleted if it doesn't begin within 30 seconds 
of being made pending.  So why would it be taking so long to begin 
recording (doesn't seem to have anything to do with scheduling - all the 
scheduling stuff seems to have finished by that time...).

Also, as a side note, it seems that it will never start a recording whilst 
the scheduler is running (surely it would be better to consider the 
previous scheduler results to be still current until the new scheduler run 
has completed?)

-- 

  - Steve
    xmpp:steve at nexusuk.org   sip:steve at nexusuk.org   http://www.nexusuk.org/

      Servatis a periculum, servatis a maleficum - Whisper, Evanescence