[mythtv-users] Loads of failed / empty recordings.

[~Stack~]

On 10/03/2010 09:14 AM, Peter Foulkes wrote:
> I've spent months trying to solve this and I'm getting nowhere so I am
> looking for help!
> 
> Very frequently I go to play a recording and although the recording
> appears on the list, when I select it I get the error message
> "Recording Unavailable. The file for this recording can not be found"
[snip]
> Any help greatly appreciated. I feel like I am going around in circles
> with this problem and not getting anywhere at all.

I am with you on this...been driving me crazy for a few months now as well.

I don't mean to hi-jack a thread that has been inactive for a few months
now, but I am having similar issues that I wonder if they are related. I
have been playing with configurations and digging through logs like
crazy. Here is my setup and what I have found out.

I have an HDHomeRun recording HD OTA. I have a PVR 500 recording SD from
a cable connection. I have 1.5TB of free hard disk space (don't think it
is a hard drive space issue as others have noted). I am running
Mythbuntu 10.04 with the 0.24 repos and I update regularly.

My PVR 500 doesn't seem to have the "Quick Tuning" option (as previously
discussed in this thread), but the HDHomeRun does. I have the option set
on the HDHomeRun tuners. I have been able to switch to LiveTV right
after one of these failed recordings and I can switch between all of the
tuners without problem. I don't think it is a case of my tuners
switching names.

Frequency of the problem: Ran Mythbuntu 10.04 with 0.23 as soon as I
could and never had a problem. Got the HDHomeRun in November, switched
to the 0.24 repository, and have had the issue about twice a week since
then. For two weeks at the end of December I disconnected the HDHomeRun
and not once did I have this problem. However, the problem has _not_
once occurred with a recording from the HDHomeRun. It always happens
with the PVR 500. The HDHomeRun might be a red herring but it is hard to
ignore those ~two weeks.

I have found that problem happens most commonly when two shows are set
to record with both tuners of the PVR 500 /at the same time/. Shows that
start offset from each other (like one starting on the hour and the
other on the half) have not had issues. Another interesting note is that
quite often one file will not be found and the other file will be a
mixture of the two recordings (often, not always).

Here is an example from tonight. The majority of the log is posted at
the end of the email. Here are the highlights

2011-01-04 20:00:02.988 Started recording: "Dirty Jobs":"Asphalt Paver":
channel 1032 on cardid 1, sourceid 1
2011-01-04 20:00:03.925 Started recording: V:"Red Rain": channel 1008 on
cardid 2, sourceid 1
2011-01-04 20:00:04.341 mpegrecorder.cpp:set_ctrls(): Could not set
Video Peak Bitrate to 6000000
			eno: Device or resource busy (16)
2011-01-04 20:00:04.357 MPEGRec(/dev/video0) Error: StartEncoding failed
			eno: Device or resource busy (16)
2011-01-04 20:00:04.366 MPEGRec(/dev/video0) Error: Failed to start
recording
2011-01-04 20:00:04.950 Reschedule requested for id 0.
2011-01-04 20:00:05.358 TVRec(2): Changing from RecordingOnly to None
2011-01-04 20:00:05.366 Updating status for V:"Red Rain" on cardid 2
(Recording => Recorder Failed)


Both Dirty Jobs and V started recording. The PVR threw a few errors, and
then V failed. As a result V gave the 'empty recording' error while
Dirty Jobs showed a picture of Mike Rowe's face, then cut to the V
recording.

The time before this, the two recordings were my wifes cooking show and
Leverage. The cooking show was a 'empty recording' and Leverage was
broken. While watching Leverage the cooking show would pop in randomly,
after giving a screeching noise and lots of colors, then a few minutes
later would switch back to Leverage with the same light show. This time,
there was just a pixelated screen and Dirty Jobs switched to V.

I am really getting annoyed with this problem and would love some help
tracking it down. Since it happens regularly (not always, but regularly)
it should be pretty easy for me to capture more log files and/or look
through existing log files. I would appreciate any help someone can give.

Thanks and Happy New Year!

~Stack~








2011-01-04 20:00:02.562 TVRec(1): Changing from None to RecordingOnly
2011-01-04 20:00:02.698 TVRec(1): HW Tuner: 1->1
2011-01-04 20:00:02.954 AutoExpire: CalcParams(): Max required Free
Space: 3.0 GB w/freq: 9 min
2011-01-04 20:00:02.988 Started recording: "Dirty Jobs":"Asphalt Paver":
channel 1032 on cardid 1, sourceid 1
2011-01-04 20:00:03.103 TVRec(1): rec->GetPathname():
'/home/user/MythStoragePool2/1032_20110104200000.mpg'
2011-01-04 20:00:03.272 TVRec(2): Changing from None to RecordingOnly
2011-01-04 20:00:03.379 MPEGRec(/dev/video0) Warning: Audio sample rate
32000 Hz
			is not supported by ivtv driver, using 48000 Hz instead.
2011-01-04 20:00:03.380 TVRec(2): HW Tuner: 2->2
2011-01-04 20:00:03.909 AutoExpire: CalcParams(): Max required Free
Space: 3.0 GB w/freq: 7 min
2011-01-04 20:00:03.925 Started recording: V:"Red Rain": channel 1008 on
cardid 2, sourceid 1
2011-01-04 20:00:03.950 Updating status for "Dirty Jobs":"Asphalt Paver"
on cardid 1 (Tuning => Recording)
2011-01-04 20:00:03.961 MainServer::ANN Monitor
2011-01-04 20:00:03.966 adding: NW as a client (events: 0)
2011-01-04 20:00:03.975 MainServer::ANN Monitor
2011-01-04 20:00:03.982 adding: NW as a client (events: 1)
2011-01-04 20:00:04.036 Updating status for V:"Red Rain" on cardid 2
(Tuning => Recording)
2011-01-04 20:00:04.093 TVRec(2): rec->GetPathname():
'/media/myth/recordings/1008_20110104200000.mpg'
2011-01-04 20:00:04.152 MPEGRec(/dev/video0) Warning: Audio sample rate
32000 Hz
			is not supported by ivtv driver, using 48000 Hz instead.
2011-01-04 20:00:04.182 mpegrecorder.cpp:set_ctrls(): Could not set
Audio Sampling Frequency to 1
			eno: Device or resource busy (16)
2011-01-04 20:00:04.282 mpegrecorder.cpp:set_ctrls(): Could not set
Audio Encoding to 1
			eno: Device or resource busy (16)
2011-01-04 20:00:04.291 mpegrecorder.cpp:set_ctrls(): Could not set
Audio L2 Bitrate to 13
			eno: Device or resource busy (16)
2011-01-04 20:00:04.317 mpegrecorder.cpp:set_ctrls(): Could not set MPEG
Stream type to 0
			eno: Device or resource busy (16)
2011-01-04 20:00:04.332 mpegrecorder.cpp:set_ctrls(): Could not set
Video Average Bitrate to 4500000
			eno: Device or resource busy (16)
2011-01-04 20:00:04.341 mpegrecorder.cpp:set_ctrls(): Could not set
Video Peak Bitrate to 6000000
			eno: Device or resource busy (16)
2011-01-04 20:00:04.357 MPEGRec(/dev/video0) Error: StartEncoding failed
			eno: Device or resource busy (16)
2011-01-04 20:00:04.366 MPEGRec(/dev/video0) Error: Failed to start
recording
2011-01-04 20:00:04.950 Reschedule requested for id 0.
2011-01-04 20:00:05.358 TVRec(2): Changing from RecordingOnly to None
2011-01-04 20:00:05.366 Updating status for V:"Red Rain" on cardid 2
(Recording => Recorder Failed)
2011-01-04 20:00:05.523 MainServer::ANN Monitor
2011-01-04 20:00:05.557 adding: NW as a client (events: 0)
2011-01-04 20:00:05.566 MainServer::ANN Monitor
2011-01-04 20:00:05.573 adding: NW as a client (events: 1)
2011-01-04 20:00:06.024 Reschedule interrupted, will retry
2011-01-04 20:00:06.044 Reschedule requested for id 0.
2011-01-04 20:00:06.049 Reschedule requested for id 0.
2011-01-04 20:00:06.066 Preview Error: Encountered problems running
'/usr/bin/mythpreviewgen --size 0x0 --chanid 1008 --starttime 2011010420000
0  > /dev/null'
2011-01-04 20:00:07.092 Scheduled 748 items in 1.0 = 0.01 match + 1.02 place
2011-01-04 20:00:21.949
RingBuf(/home/user/MythStoragePool2/1008_20110104190000.mpg): Waited 2.0
seconds for data
			to become available... 2262 < 32768
2011-01-04 20:00:22.192 [mpeg2video @ 0x7f1da8acb5a0]ac-tex damaged at 15 4
2011-01-04 20:00:22.211 [mpeg2video @ 0x7f1da8acb5a0]Warning MVs not
available
2011-01-04 20:00:22.306 [mp2 @ 0x7f1da8acb5a0]incomplete frame
2011-01-04 20:00:22.316 AFD Error: Unknown audio decoding error
2011-01-04 20:00:25.589 ~MythContext waiting for threads to exit.
2011-01-04 20:00:25.880 MainServer::ANN Monitor
2011-01-04 20:00:25.890 adding: NW as a client (events: 0)
2011-01-04 20:00:25.899 MainServer::ANN Monitor
2011-01-04 20:00:25.906 adding: NW as a client (events: 1)
2011-01-04 20:00:47.205 MainServer::ANN Monitor
2011-01-04 20:00:47.214 adding: NW as a client (events: 2)
2011-01-04 20:00:51.656 JobQueue: Commercial Detection Starting for "The
Biggest Loser" recorded from channel 2041 at 2011-01-04T19:00:00
2011-01-04 20:00:51.765 Using runtime prefix = /usr
2011-01-04 20:00:51.812 Using configuration directory = /home/mythtv/.mythtv
2011-01-04 20:00:51.822 Empty LocalHostName.
2011-01-04 20:00:51.829 Using localhost value of NW
2011-01-04 20:00:51.852 New DB connection, total: 1
2011-01-04 20:00:51.868 Connected to database 'mythconverg' at host:
localhost
2011-01-04 20:00:51.880 Closing DB connection named 'DBManager0'
2011-01-04 20:00:51.888 Connected to database 'mythconverg' at host:
localhost
2011-01-04 20:00:51.898 Current locale EN_US
2011-01-04 20:00:51.904 Reading locale defaults from
/usr/share/mythtv//locales/en_us.xml
2011-01-04 20:00:51.948 Loading en_us translation for module mythfrontend
2011-01-04 20:00:52.112 MythCoreContext: Connecting to backend server:
192.168.4.111:6543 (try 1 of 1)
2011-01-04 20:00:52.121 Using protocol version 63
2011-01-04 20:00:52.129 MainServer::ANN Playback
2011-01-04 20:00:52.137 adding: NW as a client (events: 0)
2011-01-04 20:00:52.146 MainServer::ANN Monitor
2011-01-04 20:00:52.153 adding: NW as a client (events: 1)
2011-01-04 20:00:52.271 [mpeg2video @
0x7fe943b3e5a0]mpeg_decode_postinit() failure
2011-01-04 20:00:52.292 [mpeg2video @
0x7fe943b3e5a0]mpeg_decode_postinit() failure
2011-01-04 20:00:52.309 [mpeg2video @
0x7fe943b3e5a0]mpeg_decode_postinit() failure
2011-01-04 20:00:52.317 [mpeg2video @
0x7fe943b3e5a0]mpeg_decode_postinit() failure
2011-01-04 20:00:52.326 [mpeg2video @
0x7fe943b3e5a0]mpeg_decode_postinit() failure
2011-01-04 20:00:52.334 [mpeg2video @
0x7fe943b3e5a0]mpeg_decode_postinit() failure
2011-01-04 20:00:52.342 [mpeg2video @
0x7fe943b3e5a0]mpeg_decode_postinit() failure
2011-01-04 20:00:52.351 [mpeg2video @
0x7fe943b3e5a0]mpeg_decode_postinit() failure
2011-01-04 20:00:52.359 [mpeg2video @
0x7fe943b3e5a0]mpeg_decode_postinit() failure
2011-01-04 20:00:52.382 [mpeg2video @
0x7fe943b3e5a0]mpeg_decode_postinit() failure
2011-01-04 20:00:52.409 [mpeg2video @
0x7fe943b3e5a0]mpeg_decode_postinit() failure
2011-01-04 20:00:52.417 [mpeg2video @
0x7fe943b3e5a0]mpeg_decode_postinit() failure
2011-01-04 20:00:52.425 [mpeg2video @
0x7fe943b3e5a0]mpeg_decode_postinit() failure
2011-01-04 20:00:52.434 [mpeg2video @
0x7fe943b3e5a0]mpeg_decode_postinit() failure
2011-01-04 20:00:52.731 AFD: Opened codec 0x7fe928005b80, id(MPEG2VIDEO)
type(Video)
2011-01-04 20:00:52.737 AFD: codec AC3 has 2 channels
2011-01-04 20:00:52.746 AFD: Opened codec 0x7fe92800e520, id(AC3)
type(Audio)
2011-01-04 20:00:52.943 MythCoreContext: Connecting to backend server:
192.168.4.111:6543 (try 1 of 1)
2011-01-04 20:00:52.987 Using protocol version 63
2011-01-04 20:00:52.995 MainServer::ANN Playback
2011-01-04 20:00:53.003 adding: NW as a client (events: 0)
2011-01-04 20:00:53.012 RecBase(3:3):
GetKeyframePositions(109291,9223372036854775807,#5) out of 7292
2011-01-04 20:00:53.541 AFD: Audio stream changed
2011-01-04 20:01:24.845 AFD: Audio stream changed
2011-01-04 20:01:25.340 AFD: Audio stream changed
2011-01-04 20:01:53.951 MainServer::ANN Monitor
2011-01-04 20:01:53.960 adding: NW as a client (events: 2)
2011-01-04 20:02:52.649 MainServer::ANN Monitor
--Last 2 lines repeat over and over with the next three peppered in
every once in a while--
2011-01-04 20:25:30.090 AutoExpire: CalcParams(): Max required Free
Space: 3.0 GB w/freq: 9 min
2011-01-04 20:38:11.799 AFD: Audio stream changed
2011-01-04 20:46:34.441 UPnpMedia: BuildMediaMap - no VideoStartupDir
set,  skipping scan.
--
2011-01-04 20:59:00.324 Reschedule requested for id 0.
2011-01-04 20:59:02.215 Scheduled 745 items in 1.9 = 0.01 match + 1.86 place
2011-01-04 20:59:29.735 TVRec(1): ASK_RECORDING 1 29 0 0
2011-01-04 20:59:33.396 MainServer::ANN Monitor
2011-01-04 20:59:33.405 adding: NW as a client (events: 2)
2011-01-04 21:00:00.801 TVRec(1): Changing from RecordingOnly to None
2011-01-04 21:00:00.820 Updating status for "Dirty Jobs":"Asphalt Paver"
on cardid 1 (Recording => Recorded)
2011-01-04 21:00:00.821 Finished recording Dirty Jobs "Asphalt Paver":
channel 1032
2011-01-04 21:00:01.024 Finished recording Dirty Jobs "Asphalt Paver":
channel 1032


-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 262 bytes
Desc: OpenPGP digital signature
URL: <http://mythtv.org/pipermail/mythtv-users/attachments/20110104/ad0209db/attachment.pgp>