[mythtv] Backend missing some DVB recordings

Roger James roger at beardandsandals.co.uk
Fri Aug 8 12:24:29 UTC 2008 

I recently noticed that my debian 0.21-0.11etch1backend has been mssing 
some DVB recordings. The problem seems to associated trying to record on 
a card that is currently watching live tv. I am afraid I have not been 
paying much attention to the list lately as everything appeared to be 
running OK. I had a quick search but could not find anyting recent of 
relevance, my apologies if I missed something. Looking at the logs I 
think the symptons are as follows.

1. A diskless myth front end (minimyth) starts watching live tv. I am 
guessing that this is using capture card 1.

2008-08-05 10:05:33.470 TVRec(1): Changing from None to WatchingLiveTV
2008-08-05 10:05:33.487 TVRec(1): HW Tuner: 1->1
2008-08-05 10:05:34.773 AutoExpire: CalcParams(): Max required Free 
Space: 3.0 GB w/freq: 15 min
2008-08-05 10:05:36.057 Finished recording Quincy, ME "DUI": channel 1008
2008-08-05 10:05:37.172 Finished recording Quincy, ME "DUI": channel 1008
2008-08-05 10:05:37.235 AutoExpire: CalcParams(): Max required Free 
Space: 3.0 GB w/freq: 15 min
2008-08-05 10:05:37.315 MainServer::HandleAnnounce Playback
2008-08-05 10:05:37.332 adding: mythfe as a client (events: 0)
2008-08-05 10:05:37.335 MainServer::HandleAnnounce FileTransfer
2008-08-05 10:05:37.336 adding: mythfe as a remote file transfer
2008-08-05 10:05:38.464 Using runtime prefix = /usr, libdir = /usr/lib
2008-08-05 10:05:38.510 Empty LocalHostName.
2008-08-05 10:05:38.512 Using localhost value of myth
2008-08-05 10:05:38.707 New DB connection, total: 1
2008-08-05 10:05:38.738 Connected to database 'mythconverg' at host: myth
2008-08-05 10:05:38.745 Closing DB connection named 'DBManager0'
2008-08-05 10:05:38.749 Connected to database 'mythconverg' at host: myth
2008-08-05 10:05:38.755 New DB connection, total: 2
2008-08-05 10:05:38.758 Connected to database 'mythconverg' at host: myth
2008-08-05 10:05:38.768 Current Schema Version: 1214
2008-08-05 10:05:38.806 Preview Error: Previewer file 
'/myth_recordings/1008_20080805100533.mpg' is not valid.
2008-08-05 10:05:38.829 Preview Error: Run() file not local: 
'/myth_recordings/1008_20080805100533.mpg'
2008-08-05 10:05:38.861 Preview Error: Preview process not ok.
            fileinfo(/myth_recordings/1008_20080805100533.mpg.png) 
exists: 0 readable: 0 size: 0
2008-08-05 10:06:02.811 MythSocket(aadcac20:35): writeData: Error, 
zerocnt timeout
2008-08-05 10:06:22.093 UPnpMedia: BuildMediaMap VIDEO scan starting in 
:/share/Movies/dvd:
2008-08-05 10:06:22.098 UPnpMedia: BuildMediaMap Done. Found 0 objects

2. I think at some point the frontend (mythfe) is powered off without 
telling livetv to stop, or someone swtiches off the TV display that is 
attached to it. So it continues capturing programs.

2008-08-05 14:15:03.123 Finished recording Heartbeat "Honor amongst 
Thieves": channel 1008
...
2008-08-05 15:25:03.706 Finished recording Pie in the Sky "Breaking 
Bread": channel 1008
...
2008-08-05 19:25:03.932 Finished recording Home to Roost "Crime Watch": 
channel 1008

3. The scheduler rerquests a number of programs to be recorded but 
nothing gets captured and no files are written.

2008-08-05 19:29:29.419 TVRec(1): ASK_RECORDING 1 29 0 0
2008-08-05 19:30:02.420 AutoExpire: CalcParams(): Max required Free 
Space: 3.0 GB w/freq: 15 min
2008-08-05 19:30:02.429 Started recording: Pop Go the Sixties "Peter and 
Gordon": channel 1017 on cardid 1, sourceid 1
2008-08-05 19:34:00.583 Reschedule requested for id 0.
2008-08-05 19:34:02.628 Scheduled 222 items in 2.0 = 0.00 match + 2.03 place
2008-08-05 19:34:29.709 TVRec(1): ASK_RECORDING 1 29 0 0
2008-08-05 19:35:02.698 AutoExpire: CalcParams(): Max required Free 
Space: 3.0 GB w/freq: 15 min
2008-08-05 19:35:02.709 Started recording: Batman "Catwoman Goes to 
College": channel 1017 on cardid 1, sourceid 1
2008-08-05 19:36:46.183 AutoExpire: CalcParams(): Max required Free 
Space: 3.0 GB w/freq: 15 min
2008-08-05 19:37:27.333 UPnpMedia: BuildMediaMap VIDEO scan starting in 
:/share/Movies/dvd:
2008-08-05 19:37:27.335 UPnpMedia: BuildMediaMap Done. Found 0 objects
2008-08-05 19:51:46.341 AutoExpire: CalcParams(): Max required Free 
Space: 3.0 GB w/freq: 15 min
2008-08-05 19:59:00.172 Reschedule requested for id 0.
2008-08-05 19:59:09.123 Scheduled 222 items in 8.9 = 0.01 match + 8.94 place
2008-08-05 19:59:29.212 TVRec(1): ASK_RECORDING 1 29 0 0
2008-08-05 20:00:02.207 AutoExpire: CalcParams(): Max required Free 
Space: 3.0 GB w/freq: 15 min
2008-08-05 20:00:02.218 Started recording: The Sky at Night "Double 
Vision": channel 1017 on cardid 1, sourceid 1
2008-08-05 20:06:46.507 AutoExpire: CalcParams(): Max required Free 
Space: 3.0 GB w/freq: 15 min
2008-08-05 20:07:32.357 UPnpMedia: BuildMediaMap VIDEO scan starting in 
:/share/Movies/dvd:
2008-08-05 20:07:32.359 UPnpMedia: BuildMediaMap Done. Found 0 objects
2008-08-05 20:21:46.674 AutoExpire: CalcParams(): Max required Free 
Space: 3.0 GB w/freq: 15 min
2008-08-05 20:33:04.401 Finished recording Home to Roost "Paper Chase": 
channel 1008
2008-08-05 20:33:04.526 AutoExpire: CalcParams(): Max required Free 
Space: 3.0 GB w/freq: 15 min
2008-08-05 20:33:04.772 TVRec(1): RingBufferChanged()
2008-08-05 20:33:04.920 Finished recording Home to Roost "Paper Chase": 
channel 1008
2008-08-05 20:33:07.706 Using runtime prefix = /usr, libdir = /usr/lib
2008-08-05 20:33:07.747 Empty LocalHostName.
2008-08-05 20:33:07.751 Using localhost value of myth
2008-08-05 20:33:08.017 New DB connection, total: 1
2008-08-05 20:33:08.060 Connected to database 'mythconverg' at host: myth
2008-08-05 20:33:08.068 Closing DB connection named 'DBManager0'
2008-08-05 20:33:08.073 Connected to database 'mythconverg' at host: myth
2008-08-05 20:33:08.079 New DB connection, total: 2
2008-08-05 20:33:08.082 Connected to database 'mythconverg' at host: myth
2008-08-05 20:33:08.091 Current Schema Version: 1214
2008-08-05 20:33:11.034 AFD: Opened codec 0x82a3ea0, id(MPEG2VIDEO) 
type(Video)
2008-08-05 20:33:11.039 AFD: codec MP3 has 2 channels
2008-08-05 20:33:11.041 AFD: Opened codec 0x82a4490, id(MP3) type(Audio)
2008-08-05 20:33:11.042 AFD: codec MP3 has 1 channels
2008-08-05 20:33:11.063 AFD: Opened codec 0x82a4ad0, id(MP3) type(Audio)
2008-08-05 20:33:11.084 AFD: Opened codec 0x82a5110, id(DVB_SUBTITLE) 
type(Subtitle)
2008-08-05 20:33:11.974 Preview: Grabbed preview 
'/myth_recordings/1008_20080805192502.mpg' 544x576 at 64s
2008-08-05 20:36:46.830 AutoExpire: CalcParams(): Max required Free 
Space: 3.0 GB w/freq: 15 min
2008-08-05 20:37:33.365 UPnpMedia: BuildMediaMap VIDEO scan starting in 
:/share/Movies/dvd:
2008-08-05 20:37:33.367 UPnpMedia: BuildMediaMap Done. Found 0 objects
2008-08-05 20:51:46.991 AutoExpire: CalcParams(): Max required Free 
Space: 3.0 GB w/freq: 15 min
2008-08-05 20:59:00.598 Reschedule requested for id 0.
2008-08-05 20:59:09.792 Scheduled 222 items in 9.2 = 0.01 match + 9.18 place
2008-08-05 20:59:29.979 TVRec(1): ASK_RECORDING 1 29 0 0
2008-08-05 21:00:02.888 AutoExpire: CalcParams(): Max required Free 
Space: 3.0 GB w/freq: 15 min
2008-08-05 21:00:02.900 Started recording: Bonekickers "The Lines of 
War": channel 1004 on cardid 1, sourceid 1
2008-08-05 21:06:47.143 AutoExpire: CalcParams(): Max required Free 
Space: 3.0 GB w/freq: 15 min
2008-08-05 21:07:33.377 UPnpMedia: BuildMediaMap VIDEO scan starting in 
:/share/Movies/dvd:
2008-08-05 21:07:33.381 UPnpMedia: BuildMediaMap Done. Found 0 objects
2008-08-05 21:21:47.314 AutoExpire: CalcParams(): Max required Free 
Space: 3.0 GB w/freq: 15 min
2008-08-05 21:36:47.469 AutoExpire: CalcParams(): Max required Free 
Space: 3.0 GB w/freq: 15 min
2008-08-05 21:37:36.391 UPnpMedia: BuildMediaMap VIDEO scan starting in 
:/share/Movies/dvd:
2008-08-05 21:37:36.397 UPnpMedia: BuildMediaMap Done. Found 0 objects
2008-08-05 21:51:47.625 AutoExpire: CalcParams(): Max required Free 
Space: 3.0 GB w/freq: 15 min
2008-08-05 22:03:04.064 Finished recording Pie in the Sky "Breaking 
Bread": channel 1008
2008-08-05 22:03:04.192 TVRec(1): RingBufferChanged()
2008-08-05 22:03:04.236 AutoExpire: CalcParams(): Max required Free 
Space: 3.0 GB w/freq: 15 min
2008-08-05 22:03:04.465 Finished recording Pie in the Sky "Breaking 
Bread": channel 1008
2008-08-05 22:03:07.382 Using runtime prefix = /usr, libdir = /usr/lib
2008-08-05 22:03:07.423 Empty LocalHostName.
2008-08-05 22:03:07.427 Using localhost value of myth
2008-08-05 22:03:07.694 New DB connection, total: 1
2008-08-05 22:03:07.737 Connected to database 'mythconverg' at host: myth
2008-08-05 22:03:07.744 Closing DB connection named 'DBManager0'
2008-08-05 22:03:07.748 Connected to database 'mythconverg' at host: myth
2008-08-05 22:03:07.754 New DB connection, total: 2
2008-08-05 22:03:07.757 Connected to database 'mythconverg' at host: myth
2008-08-05 22:03:07.765 Current Schema Version: 1214
2008-08-05 22:03:10.660 AFD: Opened codec 0x82a3b20, id(MPEG2VIDEO) 
type(Video)
2008-08-05 22:03:10.665 AFD: codec MP3 has 2 channels
2008-08-05 22:03:10.671 AFD: Opened codec 0x82a4110, id(MP3) type(Audio)
2008-08-05 22:03:10.672 AFD: codec MP3 has 1 channels
2008-08-05 22:03:10.673 AFD: Opened codec 0x82a4700, id(MP3) type(Audio)
2008-08-05 22:03:10.694 AFD: Opened codec 0x82a4cf0, id(DVB_SUBTITLE) 
type(Subtitle)
2008-08-05 22:03:11.915 Preview: Grabbed preview 
'/myth_recordings/1008_20080805203303.mpg' 544x576 at 64s
2008-08-05 22:06:47.787 AutoExpire: CalcParams(): Max required Free 
Space: 3.0 GB w/freq: 15 min
2008-08-05 22:07:43.407 UPnpMedia: BuildMediaMap VIDEO scan starting in 
:/share/Movies/dvd:
2008-08-05 22:07:43.410 UPnpMedia: BuildMediaMap Done. Found 0 objects
2008-08-05 22:21:47.944 AutoExpire: CalcParams(): Max required Free 
Space: 3.0 GB w/freq: 15 min
2008-08-05 22:36:48.102 AutoExpire: CalcParams(): Max required Free 
Space: 3.0 GB w/freq: 15 min
2008-08-05 22:37:43.420 UPnpMedia: BuildMediaMap VIDEO scan starting in 
:/share/Movies/dvd:
2008-08-05 22:37:43.423 UPnpMedia: BuildMediaMap Done. Found 0 objects
2008-08-05 22:51:48.261 AutoExpire: CalcParams(): Max required Free 
Space: 3.0 GB w/freq: 15 min
2008-08-05 23:06:48.422 AutoExpire: CalcParams(): Max required Free 
Space: 3.0 GB w/freq: 15 min
2008-08-05 23:07:49.428 UPnpMedia: BuildMediaMap VIDEO scan starting in 
:/share/Movies/dvd:
2008-08-05 23:07:49.439 UPnpMedia: BuildMediaMap Done. Found 0 objects
2008-08-05 23:21:48.599 AutoExpire: CalcParams(): Max required Free 
Space: 3.0 GB w/freq: 15 min
2008-08-05 23:35:02.969 Finished recording Taggart "The Wages of Sin": 
channel 1008
2008-08-05 23:35:03.103 AutoExpire: CalcParams(): Max required Free 
Space: 3.0 GB w/freq: 15 min
2008-08-05 23:35:03.484 TVRec(1): RingBufferChanged()

5. The card continues capturing live tv.

2008-08-05 23:35:03.771 Finished recording Taggart "The Wages of Sin": 
channel 1008

Has anyone else come across a problem like this? I apologise again if I 
have missed it on the list.

I am right in thinking that the scheduler has asked the same card that 
is currently recording live TV to be switched to another channel. What 
happens if the frontend has gone away at this point, or maybe it is 
still there but has no user interaction.

Any information/help gratefully received.

Roger

More information about the mythtv-dev mailing list