[mythtv-users] Random failed IPTV recordings

Thu Sep 22 23:09:41 UTC 2011

Since upgrading from 0.23.1 to 0.24.1, sometimes I'm seeing
zero-length recordings. I'm using Surewest (my provider) IPTV, with
two tuners. The problem seems to occur more often when both tuners are
in use, but it can also happen when only one tuner is used. The system
is Gentoo Linux x86_64, using the 0.24.1_p20110726 ebuild from the
official packaging repository. Here are some extracts from
mythbackend.log (only logging "important" - I had to turn off
"general" because I was getting thousands of h264 errors per second
when recording).

Here's a sample from when both tuners were in use - the recording on
tuner 1 succeeded and the one on tuner 2 failed:

2011-09-21 20:59:29.652 TVRec(1): ASK_RECORDING 1 29 0 0
2011-09-21 20:59:29.687 TVRec(2): ASK_RECORDING 2 29 0 0
2011-09-21 21:00:02.142 TVRec(2): Changing from None to RecordingOnly
2011-09-21 21:00:02.146 TVRec(2): HW Tuner: 2->2
2011-09-21 21:00:02.226 Program #1 not found in PAT!
Program Association Table
 PSIP tableID(0x0) length(13) extension(0x83f)
      version(2) current(1) section(0) last_section(0)
         tsid: 2111
 programCount: 1
  program number   139 has PID 0x141f   data  0x 0 0x8b 0xf4 0x1f

2011-09-21 21:00:02.236 But there is only one program in the PAT, so
we'll just use it
2011-09-21 21:00:02.257 AutoExpire: CalcParams(): Max required Free
Space: 3.0 GB w/freq: 14 min
2011-09-21 21:00:02.341 TVRec(1): Changing from None to RecordingOnly
2011-09-21 21:00:02.348 TVRec(1): HW Tuner: 1->1
2011-09-21 21:00:02.383 New DB connection, total: 5
2011-09-21 21:00:02.401 TVRec(2): rec->GetPathname():
'/var/space/mythtv/Recordings/1139_20110921210000.mpg'
2011-09-21 21:00:02.452 TVRec(1): rec->GetPathname():
'/var/space/mythtv/Recordings/1613_20110921210000.mpg'
2011-09-21 21:00:02.463 AutoExpire: CalcParams(): Max required Free
Space: 3.0 GB w/freq: 7 min
2011-09-21 21:00:02.484 Updating status for "Drew Carey's
Improv-A-Ganza" on cardid 2 (Tuning => Recording)
2011-09-21 21:01:02.857 Using runtime prefix = /usr
2011-09-21 21:01:02.858 Using configuration directory = /home/mythtv/.mythtv
2011-09-21 21:01:02.859 Unable to read configuration file mysql.txt
2011-09-21 21:01:02.860 Empty LocalHostName.
2011-09-21 21:01:02.948 New DB connection, total: 1
2011-09-21 21:01:02.957 Closing DB connection named 'DBManager0'
2011-09-21 21:01:03.071 Using protocol version 63
2011-09-21 21:01:03.071 adding: legend as a client (events: 0)
2011-09-21 21:01:03.072 adding: legend as a client (events: 1)
2011-09-21 21:01:03.495 Using protocol version 63
2011-09-21 21:01:03.520 adding: legend as a client (events: 0)
2011-09-21 21:01:03.520 RecBase(2:/dev/video):
GetKeyframePositions(1633,9223372036854775807,#11) out of 120
2011-09-21 21:01:07.070 Using runtime prefix = /usr
2011-09-21 21:01:07.071 Using configuration directory = /home/mythtv/.mythtv
2011-09-21 21:01:07.071 Unable to read configuration file mysql.txt
2011-09-21 21:01:07.072 Empty LocalHostName.
2011-09-21 21:01:07.086 New DB connection, total: 1
2011-09-21 21:01:07.092 Closing DB connection named 'DBManager0'
2011-09-21 21:01:09.101
RingBuf(/var/space/mythtv/Recordings/1613_20110921210000.mpg) Error:
OpenFile(): File too small (0B).
2011-09-21 21:01:09.180 Using protocol version 63
2011-09-21 21:01:09.181 adding: legend as a client (events: 0)
2011-09-21 21:01:09.182 adding: legend as a client (events: 1)
2011-09-21 21:01:09.193
RingBuf(/var/space/mythtv/Recordings/1613_20110921210000.mpg) Warning:
Peek() requested 2048 bytes, but only returning -1
2011-09-21 21:01:09.194
RingBuf(/var/space/mythtv/Recordings/1613_20110921210000.mpg) Error:
Invalid file descriptor in 'safe_read()'
2011-09-21 21:01:09.194 Player(0), Warning: OpenFile() waiting on data
2011-09-21 21:01:09.245
RingBuf(/var/space/mythtv/Recordings/1613_20110921210000.mpg) Warning:
Peek() requested 2048 bytes, but only returning 0
2011-09-21 21:01:09.254 Player(0), Warning: OpenFile() waiting on data
2011-09-21 21:01:09.305
RingBuf(/var/space/mythtv/Recordings/1613_20110921210000.mpg) Warning:
Peek() requested 2048 bytes, but only returning 0
2011-09-21 21:01:09.305 Player(0), Warning: OpenFile() waiting on data
2011-09-21 21:01:09.356
RingBuf(/var/space/mythtv/Recordings/1613_20110921210000.mpg) Warning:
Peek() requested 2048 bytes, but only returning 0
2011-09-21 21:01:09.357 Player(0), Warning: OpenFile() waiting on data
2011-09-21 21:01:09.407
RingBuf(/var/space/mythtv/Recordings/1613_20110921210000.mpg) Warning:
Peek() requested 2048 bytes, but only returning 0
2011-09-21 21:01:09.407 Player(0), Warning: OpenFile() waiting on data
2011-09-21 21:01:09.458
RingBuf(/var/space/mythtv/Recordings/1613_20110921210000.mpg) Warning:
Peek() requested 2048 bytes, but only returning 0
2011-09-21 21:01:09.458 Player(0), Warning: OpenFile() waiting on data
2011-09-21 21:01:09.509
RingBuf(/var/space/mythtv/Recordings/1613_20110921210000.mpg) Warning:
Peek() requested 2048 bytes, but only returning 0
2011-09-21 21:01:09.591 Player(0), Warning: OpenFile() waiting on data
2011-09-21 21:01:09.641
RingBuf(/var/space/mythtv/Recordings/1613_20110921210000.mpg) Warning:
Peek() requested 2048 bytes, but only returning 0
2011-09-21 21:01:09.642 Player(0), Warning: OpenFile() waiting on data
2011-09-21 21:01:09.693
RingBuf(/var/space/mythtv/Recordings/1613_20110921210000.mpg) Warning:
Peek() requested 2048 bytes, but only returning 0
2011-09-21 21:01:09.705 Player(0), Warning: OpenFile() waiting on data
2011-09-21 21:01:09.756
RingBuf(/var/space/mythtv/Recordings/1613_20110921210000.mpg) Warning:
Peek() requested 2048 bytes, but only returning 0
2011-09-21 21:01:09.756 Player(0), Warning: OpenFile() waiting on data
2011-09-21 21:01:09.807
RingBuf(/var/space/mythtv/Recordings/1613_20110921210000.mpg) Warning:
Peek() requested 2048 bytes, but only returning 0
2011-09-21 21:01:09.813 Player(0), Warning: OpenFile() waiting on data
2011-09-21 21:01:09.922
RingBuf(/var/space/mythtv/Recordings/1613_20110921210000.mpg) Warning:
Peek() requested 2048 bytes, but only returning 0
2011-09-21 21:01:09.922 Player(0), Warning: OpenFile() waiting on data
2011-09-21 21:01:09.973
RingBuf(/var/space/mythtv/Recordings/1613_20110921210000.mpg) Warning:
Peek() requested 2048 bytes, but only returning 0
2011-09-21 21:01:09.986 Player(0), Warning: OpenFile() waiting on data
2011-09-21 21:01:10.037
RingBuf(/var/space/mythtv/Recordings/1613_20110921210000.mpg) Warning:
Peek() requested 2048 bytes, but only returning 0
2011-09-21 21:01:10.038 Player(0), Warning: OpenFile() waiting on data
2011-09-21 21:01:10.088
RingBuf(/var/space/mythtv/Recordings/1613_20110921210000.mpg) Warning:
Peek() requested 2048 bytes, but only returning 0
2011-09-21 21:01:10.152 Player(0), Warning: OpenFile() waiting on data
2011-09-21 21:01:10.203
RingBuf(/var/space/mythtv/Recordings/1613_20110921210000.mpg) Warning:
Peek() requested 2048 bytes, but only returning 0
2011-09-21 21:01:10.203 Player(0), Error: OpenFile(): Could not read
first 2048 bytes of
'/var/space/mythtv/Recordings/1613_20110921210000.mpg'

and here's one from when only one tuner was in use:

2011-09-15 20:29:30.397 TVRec(1): ASK_RECORDING 1 29 0 0
2011-09-15 20:30:00.451 TVRec(1): Changing from RecordingOnly to None
2011-09-15 20:30:00.452 Updating status for "California's Gold":"Lunar
Landing" on cardid 1 (Recording => Recorded)
2011-09-15 20:30:01.933 adding: legend as a client (events: 0)
2011-09-15 20:30:01.945 adding: legend as a client (events: 1)
2011-09-15 20:30:02.139 TVRec(1): Changing from None to RecordingOnly
2011-09-15 20:30:02.142 TVRec(1): HW Tuner: 1->1
2011-09-15 20:30:02.237 TVRec(1): rec->GetPathname():
'/var/space/mythtv/Recordings/1606_20110915203000.mpg'
2011-09-15 20:30:02.240 AutoExpire: CalcParams(): Max required Free
Space: 3.0 GB w/freq: 14 min
2011-09-15 20:30:42.317 Using runtime prefix = /usr
2011-09-15 20:30:42.318 Using configuration directory = /home/mythtv/.mythtv
2011-09-15 20:30:42.318 Unable to read configuration file mysql.txt
2011-09-15 20:30:42.319 Empty LocalHostName.
2011-09-15 20:30:42.334 New DB connection, total: 1
2011-09-15 20:30:42.340 Closing DB connection named 'DBManager0'
2011-09-15 20:30:44.370
RingBuf(/var/space/mythtv/Recordings/1606_20110915203000.mpg) Error:
OpenFile(): File too small (0B).
2011-09-15 20:30:44.410 Using protocol version 63
2011-09-15 20:30:44.410 adding: legend as a client (events: 0)
2011-09-15 20:30:44.412 adding: legend as a client (events: 1)
2011-09-15 20:30:44.422
RingBuf(/var/space/mythtv/Recordings/1606_20110915203000.mpg) Warning:
Peek() requested 2048 bytes, but only returning -1
2011-09-15 20:30:44.423 Player(0), Warning: OpenFile() waiting on data
2011-09-15 20:30:44.423
RingBuf(/var/space/mythtv/Recordings/1606_20110915203000.mpg) Error:
Invalid file descriptor in 'safe_read()'
2011-09-15 20:30:44.474
RingBuf(/var/space/mythtv/Recordings/1606_20110915203000.mpg) Warning:
Peek() requested 2048 bytes, but only returning 0
2011-09-15 20:30:44.479 Player(0), Warning: OpenFile() waiting on data
2011-09-15 20:30:44.529
RingBuf(/var/space/mythtv/Recordings/1606_20110915203000.mpg) Warning:
Peek() requested 2048 bytes, but only returning 0
2011-09-15 20:30:44.564 Player(0), Warning: OpenFile() waiting on data
2011-09-15 20:30:44.614
RingBuf(/var/space/mythtv/Recordings/1606_20110915203000.mpg) Warning:
Peek() requested 2048 bytes, but only returning 0
2011-09-15 20:30:44.615 Player(0), Warning: OpenFile() waiting on data
2011-09-15 20:30:44.665
RingBuf(/var/space/mythtv/Recordings/1606_20110915203000.mpg) Warning:
Peek() requested 2048 bytes, but only returning 0
2011-09-15 20:30:44.665 Player(0), Warning: OpenFile() waiting on data
2011-09-15 20:30:44.716
RingBuf(/var/space/mythtv/Recordings/1606_20110915203000.mpg) Warning:
Peek() requested 2048 bytes, but only returning 0
2011-09-15 20:30:44.719 Player(0), Warning: OpenFile() waiting on data
2011-09-15 20:30:44.769
RingBuf(/var/space/mythtv/Recordings/1606_20110915203000.mpg) Warning:
Peek() requested 2048 bytes, but only returning 0
2011-09-15 20:30:44.770 Player(0), Warning: OpenFile() waiting on data
2011-09-15 20:30:44.820
RingBuf(/var/space/mythtv/Recordings/1606_20110915203000.mpg) Warning:
Peek() requested 2048 bytes, but only returning 0
2011-09-15 20:30:44.834 Player(0), Warning: OpenFile() waiting on data
2011-09-15 20:30:44.884
RingBuf(/var/space/mythtv/Recordings/1606_20110915203000.mpg) Warning:
Peek() requested 2048 bytes, but only returning 0
2011-09-15 20:30:44.887 Player(0), Warning: OpenFile() waiting on data
2011-09-15 20:30:44.938
RingBuf(/var/space/mythtv/Recordings/1606_20110915203000.mpg) Warning:
Peek() requested 2048 bytes, but only returning 0
2011-09-15 20:30:45.010 Player(0), Warning: OpenFile() waiting on data
2011-09-15 20:30:45.061
RingBuf(/var/space/mythtv/Recordings/1606_20110915203000.mpg) Warning:
Peek() requested 2048 bytes, but only returning 0
2011-09-15 20:30:45.061 Player(0), Warning: OpenFile() waiting on data
2011-09-15 20:30:45.111
RingBuf(/var/space/mythtv/Recordings/1606_20110915203000.mpg) Warning:
Peek() requested 2048 bytes, but only returning 0
2011-09-15 20:30:45.125 Player(0), Warning: OpenFile() waiting on data
2011-09-15 20:30:45.175
RingBuf(/var/space/mythtv/Recordings/1606_20110915203000.mpg) Warning:
Peek() requested 2048 bytes, but only returning 0
2011-09-15 20:30:45.176 Player(0), Warning: OpenFile() waiting on data
2011-09-15 20:30:45.226
RingBuf(/var/space/mythtv/Recordings/1606_20110915203000.mpg) Warning:
Peek() requested 2048 bytes, but only returning 0
2011-09-15 20:30:45.240 Player(0), Warning: OpenFile() waiting on data
2011-09-15 20:30:45.290
RingBuf(/var/space/mythtv/Recordings/1606_20110915203000.mpg) Warning:
Peek() requested 2048 bytes, but only returning 0
2011-09-15 20:30:45.290 Player(0), Warning: OpenFile() waiting on data
2011-09-15 20:30:45.341
RingBuf(/var/space/mythtv/Recordings/1606_20110915203000.mpg) Warning:
Peek() requested 2048 bytes, but only returning 0
2011-09-15 20:30:45.355 Player(0), Warning: OpenFile() waiting on data
2011-09-15 20:30:45.406
RingBuf(/var/space/mythtv/Recordings/1606_20110915203000.mpg) Warning:
Peek() requested 2048 bytes, but only returning 0
2011-09-15 20:30:45.406 Player(0), Warning: OpenFile() waiting on data
2011-09-15 20:30:45.456
RingBuf(/var/space/mythtv/Recordings/1606_20110915203000.mpg) Warning:
Peek() requested 2048 bytes, but only returning 0
2011-09-15 20:30:45.470 Player(0), Error: OpenFile(): Could not read
first 2048 bytes of
'/var/space/mythtv/Recordings/1606_20110915203000.mpg'

I've added "record" to my mythbackend verbosity options so that when
this happens again I can give better information. Any ideas?
-- 
Manuel A. McLure WW1FA <manuel at mclure.org> <http://www.mclure.org>
...for in Ulthar, according to an ancient and significant law,
no man may kill a cat.                       -- H.P. Lovecraft