[mythtv-users] Problem with record 'The Closer'

Tue Oct 19 12:24:06 UTC 2010

  My system is having problems recording 'The Closer' on TBS. This has 
happened several days in a row despite rebooting everything.
The symptoms - the audio gets further out of sync as you watch the show. 
At about 35-40 minutes in, it starts stuttering and echoing for a couple 
minutes, getting progressively worse to the point that the audio is not 
even understandable and then it just stops recording.
It is being recorded from an HDPVR that is just 2 months old. (I did 
hook it up to a windows box and updated the firmware when I got it.)
Other recordings from the same tuner seem to be fine.

I'm suspecting the HDPVR but would expect all recordings from it to be 
bad. Can anyone point to any other possible culprit?

Mythbuntu - mythbackend version: branches/release-0-23-fixes [s25362]

Here are snippets of the backend log from the time of the recording and 
dmesg output.

2010-10-18 13:59:51.749 TVRec(12): Changing from None to RecordingOnly
2010-10-18 13:59:51.766 TVRec(12): HW Tuner: 12->12
2010-10-18 13:59:52.859 ret_pid(0) child(15029) status(0x0)
2010-10-18 13:59:53.859 ret_pid(0) child(15029) status(0x0)
2010-10-18 13:59:54.860 ret_pid(0) child(15029) status(0x0)
2010-10-18 13:59:55.860 ret_pid(0) child(15029) status(0x0)
2010-10-18 13:59:56.820 ret_pid(15029) child(15029) status(0x0)
2010-10-18 13:59:56.821 External Tuning program exited with no error
2010-10-18 13:59:57.014 TVRec(12): rec->GetFileName(): 
'/video/media/2138_20101018140000.mpg'
2010-10-18 13:59:57.211 AutoExpire: CalcParams(): Max required Free 
Space: 22.0 GB w/freq: 7 min
2010-10-18 13:59:57.211 Started recording: The Closer "Mom Duty": 
channel 2138 on cardid 12, sourceid 2
2010-10-18 14:00:18.718 AutoExpire: CalcParams(): Max required Free 
Space: 22.0 GB w/freq: 7 min
2010-10-18 14:00:28.004 ProgramInfo(): Updated pathname '':'' -> 
'2107_20101018140000.mpg'
2010-10-18 14:00:28.007 JobQueue: Commercial Flagging Starting for 
Comedy Central Presents recorded from channel 2107 at Mon Oct 18 
14:00:00 2010
2010-10-18 14:00:28.057 ProgramInfo(): Updated pathname '':'' -> 
'2107_20101018140000.mpg'
2010-10-18 14:00:28.130 Using runtime prefix = /usr
2010-10-18 14:00:28.130 Using configuration directory = /home/mythtv/.mythtv
2010-10-18 14:00:28.131 Empty LocalHostName.
2010-10-18 14:00:28.131 Using localhost value of docbuntu
2010-10-18 14:00:28.136 New DB connection, total: 1
2010-10-18 14:00:28.139 Connected to database 'mythconverg' at host: 
localhost
2010-10-18 14:00:28.139 Closing DB connection named 'DBManager0'
2010-10-18 14:00:28.139 Connected to database 'mythconverg' at host: 
localhost
2010-10-18 14:00:28.142 ProgramInfo(): Updated pathname '':'' -> 
'2107_20101018140000.mpg'
2010-10-18 14:00:28.176 MythContext: Connecting to backend server: 
192.168.1.8:6543 (try 1 of 1)
2010-10-18 14:00:28.177 Using protocol version 56
2010-10-18 14:00:28.178 MainServer::ANN Playback
2010-10-18 14:00:28.178 adding: docbuntu as a client (events: 0)
2010-10-18 14:00:28.178 MainServer::ANN Monitor
2010-10-18 14:00:28.179 adding: docbuntu as a client (events: 1)
2010-10-18 14:00:28.219 ProgramInfo(): Updated pathname '':'' -> 
'2107_20101018140000.mpg'
2010-10-18 14:00:31.075 AFD: Opened codec 0x2317630, id(H264) type(Video)
2010-10-18 14:00:31.076 AFD: codec AAC has 2 channels
2010-10-18 14:00:31.076 AFD: Opened codec 0x2317e50, id(AAC) type(Audio)
2010-10-18 14:00:31.085 MythContext: Connecting to backend server: 
127.0.0.1:6543 (try 1 of 1)
2010-10-18 14:00:31.088 Using protocol version 56
2010-10-18 14:00:31.089 MainServer::ANN Playback
2010-10-18 14:00:31.090 adding: docbuntu as a client (events: 0)
2010-10-18 14:00:31.095 Should be local only query: GetKeyframePositions
2010-10-18 14:00:33.009 ProgramInfo(): Updated pathname '':'' -> 
'2138_20101018140000.mpg'
2010-10-18 14:00:33.011 JobQueue: Commercial Flagging Starting for The 
Closer "Mom Duty" recorded from channel 2138 at Mon Oct 18 14:00:00 2010
2010-10-18 14:00:33.063 ProgramInfo(): Updated pathname '':'' -> 
'2138_20101018140000.mpg'
2010-10-18 14:00:33.097 Using runtime prefix = /usr
2010-10-18 14:00:33.097 Using configuration directory = /home/mythtv/.mythtv
2010-10-18 14:00:33.098 Empty LocalHostName.
2010-10-18 14:00:33.098 Using localhost value of docbuntu
2010-10-18 14:00:33.103 New DB connection, total: 1
2010-10-18 14:00:33.106 Connected to database 'mythconverg' at host: 
localhost
2010-10-18 14:00:33.106 Closing DB connection named 'DBManager0'
2010-10-18 14:00:33.106 Connected to database 'mythconverg' at host: 
localhost
2010-10-18 14:00:33.108 ProgramInfo(): Updated pathname '':'' -> 
'2138_20101018140000.mpg'
2010-10-18 14:00:33.133 MythContext: Connecting to backend server: 
192.168.1.8:6543 (try 1 of 1)
2010-10-18 14:00:33.134 Using protocol version 56
2010-10-18 14:00:33.135 MainServer::ANN Playback
2010-10-18 14:00:33.135 adding: docbuntu as a client (events: 0)
2010-10-18 14:00:33.135 MainServer::ANN Monitor
2010-10-18 14:00:33.136 adding: docbuntu as a client (events: 1)
2010-10-18 14:00:33.184 ProgramInfo(): Updated pathname '':'' -> 
'2138_20101018140000.mpg'
2010-10-18 14:00:33.280 AFD: Opened codec 0x1e07210, id(H264) type(Video)
2010-10-18 14:00:33.280 AFD: codec AAC has 2 channels
2010-10-18 14:00:33.281 AFD: Opened codec 0x1e08d90, id(AAC) type(Audio)
2010-10-18 14:00:33.282 MythContext: Connecting to backend server: 
192.168.1.8:6543 (try 1 of 1)
2010-10-18 14:00:33.282 Using protocol version 56
2010-10-18 14:00:33.283 MainServer::ANN Playback
2010-10-18 14:00:33.283 adding: docbuntu as a client (events: 0)
2010-10-18 14:00:33.283 RecBase(12:/dev/video0): 
GetKeyframePositions(766,9223372036854775807,#0) out of 7
2010-10-18 14:07:18.864 AutoExpire: CalcParams(): Max required Free 
Space: 22.0 GB w/freq: 7 min
2010-10-18 14:08:31.646 [h264 @ 0x7f692511a380]B picture before any 
references, skipping
2010-10-18 14:08:31.646 [h264 @ 0x7f692511a380]decode_slice_header error
2010-10-18 14:08:31.647 [h264 @ 0x7f692511a380]no frame!
2010-10-18 14:08:31.647 AFD Error: Unknown decoding error
2010-10-18 14:08:31.647 [h264 @ 0x7f692511a380]B picture before any 
references, skipping
2010-10-18 14:08:31.648 [h264 @ 0x7f692511a380]decode_slice_header error
2010-10-18 14:08:31.648 [h264 @ 0x7f692511a380]no frame!

<snip>

2010-10-18 14:30:07.682 ~MythContext waiting for threads to exit.
2010-10-18 14:30:08.887 mythbackend version: branches/release-0-23-fixes 
[s25362] www.mythtv.org

<snip>

2010-10-18 14:39:52.965 [h264 @ 0x7fd701601380]non-existing PPS referenced
2010-10-18 14:39:52.983 Should be local only query: GetKeyframePositions
2010-10-18 14:39:52.983 Dec: DoFastForward(): desiredFrame(28559) > 
last_frame(1277)
2010-10-18 14:39:52.983 Dec: DoFastForward(): Desired frame is way past 
the end of the keyframe map!
             Seeking to last keyframe instead.
2010-10-18 14:39:52.984 [h264 @ 0x7fd701601380]sps_id out of range
2010-10-18 14:39:52.984 [h264 @ 0x7fd701601380]non-existing SPS 31 
referenced in buffering period
2010-10-18 14:39:52.984 [h264 @ 0x7fd701601380]non-existing PPS referenced
2010-10-18 14:39:52.984 [h264 @ 0x7fd701601380]B picture before any 
references, skipping
2010-10-18 14:39:52.985 [h264 @ 0x7fd701601380]decode_slice_header error
2010-10-18 14:39:52.985 [h264 @ 0x7fd701601380]no frame!
2010-10-18 14:39:52.985 AFD Error: Unknown decoding error
2010-10-18 14:39:52.985 [h264 @ 0x7fd701601380]sps_id out of range
2010-10-18 14:39:52.985 [h264 @ 0x7fd701601380]non-existing SPS 15 
referenced in buffering period
2010-10-18 14:39:52.986 [h264 @ 0x7fd701601380]non-existing PPS referenced
2010-10-18 14:39:52.986 [h264 @ 0x7fd701601380]number of reference 
frames exceeds max (probably corrupt input), discarding one
2010-10-18 14:39:52.987 [h264 @ 0x7fd701601380]number of reference 
frames exceeds max (probably corrupt input), discarding one
2010-10-18 14:39:52.987 [h264 @ 0x7fd701601380]number of reference 
frames exceeds max (probably corrupt input), discarding one
2010-10-18 14:39:52.987 [h264 @ 0x7fd701601380]number of reference 
frames exceeds max (probably corrupt input), discarding one
2010-10-18 14:39:52.987 [h264 @ 0x7fd701601380]number of reference 
frames exceeds max (probably corrupt input), discarding one

<snip>

2010-10-18 14:39:53.027 [h264 @ 0x7fd701601380]B picture before any 
references, skipping
2010-10-18 14:39:53.027 [h264 @ 0x7fd701601380]decode_slice_header error
2010-10-18 14:39:53.027 [h264 @ 0x7fd701601380]no frame!
2010-10-18 14:39:53.027 AFD Error: Unknown decoding error
2010-10-18 14:39:53.028 [h264 @ 0x7fd701601380]B picture before any 
references, skipping
2010-10-18 14:39:53.028 [h264 @ 0x7fd701601380]decode_slice_header error
2010-10-18 14:39:53.028 [h264 @ 0x7fd701601380]no frame!
2010-10-18 14:39:53.028 AFD Error: Unknown decoding error
2010-10-18 14:39:53.046 Should be local only query: GetKeyframePositions
2010-10-18 14:39:53.046 Dec: DoFastForward(): desiredFrame(28799) > 
last_frame(1277)
2010-10-18 14:39:53.047 Dec: DoFastForward(): Desired frame is way past 
the end of the keyframe map!
             Seeking to last keyframe instead.
2010-10-18 14:39:53.047 [h264 @ 0x7fd701601380]sps_id out of range
2010-10-18 14:39:53.047 [h264 @ 0x7fd701601380]non-existing SPS 15 
referenced in buffering period
2010-10-18 14:39:53.047 [h264 @ 0x7fd701601380]non-existing PPS referenced
2010-10-18 14:39:53.053 [h264 @ 0x7fd701601380]sps_id out of range
2010-10-18 14:39:53.053 [h264 @ 0x7fd701601380]non-existing SPS 31 
referenced in buffering period
2010-10-18 14:39:53.053 [h264 @ 0x7fd701601380]non-existing PPS referenced

<snip>

2010-10-18 14:49:56.815 DevRdB(/dev/video0) Error: Poll giving up
2010-10-18 14:49:56.817 MPEGRec(/dev/video0) Error: Device error detected
2010-10-18 14:49:56.817 DevRdB(/dev/video0): Stop(): Not running.
2010-10-18 14:50:18.278 DevRdB(/dev/video0) Error: Poll giving up
2010-10-18 14:50:18.283 MPEGRec(/dev/video0) Error: Device error detected
2010-10-18 14:50:18.283 DevRdB(/dev/video0): Stop(): Not running.
2010-10-18 14:51:00.680 MPEGRec(/dev/video0) Error: StartEncoding failed
             eno: Resource temporarily unavailable (11)
2010-10-18 14:51:03.681 MPEGRec(/dev/video0) Warning: Unable to set 
audio input.

and from dmesg below you can see where I have toggled the power off and 
on to get the HDPVR to begin recording again. It was not turned off 
during the recording in question. Every now and then it stops recording 
with a failed status and I have found that just turning off and back on 
seems to fix it.

root at docbuntu:/var/log/mythtv# dmesg | grep hdpvr
[   15.597023] hdpvr 1-4:1.0: untested firmware version 0x15, the driver 
might not work
[   15.910861] hdpvr 1-4:1.0: device now attached to /dev/video0
[   15.910880] usbcore: registered new interface driver hdpvr
[58801.741294] hdpvr 1-4:1.0: device /dev/video0 disconnected
[58810.718062] hdpvr 1-4:1.0: untested firmware version 0x15, the driver 
might not work
[58811.030881] hdpvr 1-4:1.0: device now attached to /dev/video0
[255658.340037] hdpvr 1-4:1.0: device /dev/video0 disconnected
[255665.098739] hdpvr 1-4:1.0: untested firmware version 0x15, the 
driver mightnot work
[255665.411734] hdpvr 1-4:1.0: device now attached to /dev/video0
root at docbuntu:/var/log/mythtv#

-- 
_________________________________________________________

  Jim Morton