Ticket #10732: debug.txt

File debug.txt, 61.4 KB (added by anonymous, 14 years ago)
Line 
12012-05-18 08:10:48.318824 C mythbackend version: fixes/0.25 [v0.25-94-gec51a97] www.mythtv.org
22012-05-18 08:10:48.318843 C Qt version: compile: 4.8.1, runtime: 4.8.1
32012-05-18 08:10:48.318845 N Enabled verbose msgs: general record channel
42012-05-18 08:10:48.318863 N Setting Log Level to LOG_INFO
52012-05-18 08:10:48.318904 I Added logging to the console
62012-05-18 08:10:48.318908 I Added database logging to table logging
72012-05-18 08:10:48.318988 N Setting up SIGHUP handler
82012-05-18 08:10:48.319051 N Using runtime prefix = /usr
92012-05-18 08:10:48.319062 N Using configuration directory = /root/.mythtv
102012-05-18 08:10:48.319266 I Assumed character encoding: en_CA.UTF-8
112012-05-18 08:10:48.319607 N Empty LocalHostName.
122012-05-18 08:10:48.319612 I Using localhost value of mythserver
132012-05-18 08:10:48.345722 N Setting QT default locale to EN_CA
142012-05-18 08:10:48.345866 I Current locale EN_CA
152012-05-18 08:10:48.345960 N Reading locale defaults from /usr/share/mythtv//locales/en_ca.xml
162012-05-18 08:10:48.376216 I Current MythTV Schema Version (DBSchemaVer): 1299
172012-05-18 08:10:48.377463 I Loading en_us translation for module mythfrontend
182012-05-18 08:10:48.379670 N MythBackend: Starting up as the master server.
192012-05-18 08:10:48.392055 I TVRec(1): Start channel: 2.
202012-05-18 08:10:48.392622 I V4LChannel(/dev/video0): Device name 'Hauppauge WinTV PVR-250' driver 'ivtv'.
212012-05-18 08:10:48.392661 I V4LChannel(/dev/video0): v4l2: 1 stream io: 0 std io: 1 async io: 0 tuner 1 sliced vbi 1
222012-05-18 08:10:48.411875 I ChannelBase(1): Input #1: 'Tuner 1' schan(2) sourceid(1) ccid(1)
232012-05-18 08:10:48.411886 I ChannelBase(1): Current Input #1: 'Tuner 1'
242012-05-18 08:10:48.413552 I Global TVFormat Setting 'NTSC'
252012-05-18 08:10:48.413594 I V4LChannel(/dev/video0): Input #1: 'Tuner 1' schan(2) tun() v4l1(Unknown) v4l2(NTSC)
262012-05-18 08:10:48.413603 I V4LChannel(/dev/video0): SetFormat(Default) fmt(NTSC) input(1)
272012-05-18 08:10:48.413614 I V4LChannel(/dev/video0): SetInputAndFormat(1, NTSC) (v4l v2) input_switch: 0 mode_switch: 0
282012-05-18 08:10:48.414429 I V4LChannel(/dev/video0): SetFormat(NTSC) fmt(NTSC) input(1)
292012-05-18 08:10:48.416133 I Channel(/dev/video0)::SwitchToInput(in 1, '')
302012-05-18 08:10:48.416995 I V4LChannel(/dev/video0): SetInputAndFormat(1, NTSC) (v4l v2) input_switch: 0 mode_switch: 0
312012-05-18 08:10:48.417012 I DTVChan(/dev/video0): SetChannelByString(2):
322012-05-18 08:10:48.418750 I V4LChannel(/dev/video0): SetFormat(Default) fmt(NTSC) input(1)
332012-05-18 08:10:48.418768 I Channel(/dev/video0)::Tune(2): curList[0].freq(55250)
342012-05-18 08:10:48.418773 I V4LChannel(/dev/video0): Tune(55250000, )
352012-05-18 08:10:48.424544 I Channel(/dev/video0)::Tune(): Frequency is now 55250000
362012-05-18 08:10:48.424565 I DTVChan(/dev/video0): SetChannelByString(2): success
372012-05-18 08:10:48.439432 I TVRec(1): SetFlags(RunMainLoop,) -> RunMainLoop,
382012-05-18 08:10:48.439448 I TVRec(1): ClearFlags(ExitPlayer,FinishRecording,) -> RunMainLoop,
392012-05-18 08:10:48.441382 I TVRec(2): Start channel: 2.
402012-05-18 08:10:48.441681 I V4LChannel(/dev/video1): Device name 'WinTV PVR 500 (unit #1)' driver 'ivtv'.
412012-05-18 08:10:48.441693 I V4LChannel(/dev/video1): v4l2: 1 stream io: 0 std io: 1 async io: 0 tuner 1 sliced vbi 1
422012-05-18 08:10:48.448788 I ChannelBase(2): Input #2: 'Tuner 1' schan(2) sourceid(1) ccid(2)
432012-05-18 08:10:48.448801 I ChannelBase(2): Current Input #2: 'Tuner 1'
442012-05-18 08:10:48.448832 I Global TVFormat Setting 'NTSC'
452012-05-18 08:10:48.448856 I V4LChannel(/dev/video1): Input #2: 'Tuner 1' schan(2) tun() v4l1(Unknown) v4l2(NTSC)
462012-05-18 08:10:48.448864 I V4LChannel(/dev/video1): SetFormat(Default) fmt(NTSC) input(2)
472012-05-18 08:10:48.448875 I V4LChannel(/dev/video1): SetInputAndFormat(2, NTSC) (v4l v2) input_switch: 0 mode_switch: 0
482012-05-18 08:10:48.449529 I V4LChannel(/dev/video1): SetFormat(NTSC) fmt(NTSC) input(2)
492012-05-18 08:10:48.449545 I Channel(/dev/video1)::SwitchToInput(in 2, '')
502012-05-18 08:10:48.450199 I V4LChannel(/dev/video1): SetInputAndFormat(2, NTSC) (v4l v2) input_switch: 0 mode_switch: 0
512012-05-18 08:10:48.450211 I DTVChan(/dev/video1): SetChannelByString(2):
522012-05-18 08:10:48.451534 I V4LChannel(/dev/video1): SetFormat(Default) fmt(NTSC) input(2)
532012-05-18 08:10:48.451550 I Channel(/dev/video1)::Tune(2): curList[0].freq(55250)
542012-05-18 08:10:48.451556 I V4LChannel(/dev/video1): Tune(55250000, )
552012-05-18 08:10:48.468358 I Channel(/dev/video1)::Tune(): Frequency is now 55250000
562012-05-18 08:10:48.468362 I DTVChan(/dev/video1): SetChannelByString(2): success
572012-05-18 08:10:48.474011 I TVRec(2): SetFlags(RunMainLoop,) -> RunMainLoop,
582012-05-18 08:10:48.474031 I TVRec(2): ClearFlags(ExitPlayer,FinishRecording,) -> RunMainLoop,
592012-05-18 08:10:48.476214 I TVRec(3): Start channel: 2.
602012-05-18 08:10:48.476525 I V4LChannel(/dev/video2): Device name 'WinTV PVR 500 (unit #2)' driver 'ivtv'.
612012-05-18 08:10:48.476537 I V4LChannel(/dev/video2): v4l2: 1 stream io: 0 std io: 1 async io: 0 tuner 1 sliced vbi 1
622012-05-18 08:10:48.483783 I ChannelBase(3): Input #3: 'Tuner 1' schan(2) sourceid(1) ccid(3)
632012-05-18 08:10:48.483796 I ChannelBase(3): Current Input #3: 'Tuner 1'
642012-05-18 08:10:48.483820 I Global TVFormat Setting 'NTSC'
652012-05-18 08:10:48.483844 I V4LChannel(/dev/video2): Input #3: 'Tuner 1' schan(2) tun() v4l1(Unknown) v4l2(NTSC)
662012-05-18 08:10:48.483852 I V4LChannel(/dev/video2): SetFormat(Default) fmt(NTSC) input(3)
672012-05-18 08:10:48.483863 I V4LChannel(/dev/video2): SetInputAndFormat(3, NTSC) (v4l v2) input_switch: 0 mode_switch: 0
682012-05-18 08:10:48.484547 I V4LChannel(/dev/video2): SetFormat(NTSC) fmt(NTSC) input(3)
692012-05-18 08:10:48.484563 I Channel(/dev/video2)::SwitchToInput(in 3, '')
702012-05-18 08:10:48.485235 I V4LChannel(/dev/video2): SetInputAndFormat(3, NTSC) (v4l v2) input_switch: 0 mode_switch: 0
712012-05-18 08:10:48.485248 I DTVChan(/dev/video2): SetChannelByString(2):
722012-05-18 08:10:48.486682 I V4LChannel(/dev/video2): SetFormat(Default) fmt(NTSC) input(3)
732012-05-18 08:10:48.486698 I Channel(/dev/video2)::Tune(2): curList[0].freq(55250)
742012-05-18 08:10:48.486704 I V4LChannel(/dev/video2): Tune(55250000, )
752012-05-18 08:10:48.502202 I Channel(/dev/video2)::Tune(): Frequency is now 55250000
762012-05-18 08:10:48.502207 I DTVChan(/dev/video2): SetChannelByString(2): success
772012-05-18 08:10:48.509519 I TVRec(3): SetFlags(RunMainLoop,) -> RunMainLoop,
782012-05-18 08:10:48.509559 I TVRec(3): ClearFlags(ExitPlayer,FinishRecording,) -> RunMainLoop,
792012-05-18 08:10:48.545748 I Found 1 distinct programid authorities
802012-05-18 08:10:48.546338 I New static DB connectionSchedCon
812012-05-18 08:10:48.555087 I Listening on TCP 127.0.0.1:6544
822012-05-18 08:10:48.555121 I Listening on TCP 10.0.0.1:6544
832012-05-18 08:10:49.565083 I Main::Registering HttpStatus Extension
842012-05-18 08:10:49.570846 I Listening on TCP 127.0.0.1:6543
852012-05-18 08:10:49.570954 I Listening on TCP 10.0.0.1:6543
862012-05-18 08:10:49.576918 N AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
872012-05-18 08:10:50.260099 I MainServer::ANN Monitor
882012-05-18 08:10:50.260123 I adding: mythfront as a client (events: 0)
892012-05-18 08:10:50.261832 I MainServer::ANN Monitor
902012-05-18 08:10:50.261851 I adding: mythfront as a client (events: 1)
912012-05-18 08:10:50.361201 I Bonjour: Service registration complete: name 'Mythbackend on mythserver' type '_mythbackend-master._tcp.' domain: 'local.'
922012-05-18 08:10:51.565077 I Reschedule requested for id -1.
932012-05-18 08:10:54.393825 I Scheduled 1506 items in 2.8 = 0.09 match + 2.74 place
942012-05-18 08:10:54.676072 I Scheduler: Seem to be woken up by USER
952012-05-18 08:10:56.290844 I MainServer::ANN Monitor
962012-05-18 08:10:56.290861 I adding: mythserver as a client (events: 2)
972012-05-18 08:10:58.559644 I Running housekeeping thread
982012-05-18 08:11:00.511733 I MainServer::ANN Monitor
992012-05-18 08:11:00.511777 I adding: mythserver as a client (events: 2)
1002012-05-18 08:11:01.520869 I MainServer::ANN Monitor
1012012-05-18 08:11:01.520875 I adding: mythserver as a client (events: 2)
1022012-05-18 08:11:06.072552 I MainServer::ANN Monitor
1032012-05-18 08:11:06.072596 I adding: mythserver as a client (events: 2)
1042012-05-18 08:11:07.652486 I MainServer::ANN Monitor
1052012-05-18 08:11:07.652504 I adding: mythserver as a client (events: 2)
1062012-05-18 08:11:07.662938 I MainServer::ANN Monitor
1072012-05-18 08:11:07.662955 I adding: mythserver as a client (events: 2)
1082012-05-18 08:11:08.678352 I MainServer::ANN Monitor
1092012-05-18 08:11:08.678435 I adding: mythserver as a client (events: 2)
1102012-05-18 08:11:08.728599 I Running Grabber: /usr/share/mythtv/metadata/Movie/tmdb.py -l en -M CBS This Morning
1112012-05-18 08:11:08.733206 I Starting IO manager (write)
1122012-05-18 08:11:08.733426 I Starting IO manager (read)
1132012-05-18 08:11:08.733629 I Starting process signal handler
1142012-05-18 08:11:08.733781 I Starting process manager
1152012-05-18 08:11:08.990713 I MainServer::ANN Monitor
1162012-05-18 08:11:08.990719 I adding: mythserver as a client (events: 2)
1172012-05-18 08:11:08.994101 I MainServer::ANN Monitor
1182012-05-18 08:11:08.994106 I adding: mythserver as a client (events: 2)
1192012-05-18 08:11:09.763580 I Running Grabber: /usr/share/mythtv/metadata/Movie/tmdb.py -l en -M AB Twister
1202012-05-18 08:11:09.894209 I MainServer::ANN Monitor
1212012-05-18 08:11:09.894218 I adding: mythserver as a client (events: 2)
1222012-05-18 08:11:10.440409 I Running Grabber: /usr/share/mythtv/metadata/Television/ttvdb.py -l en -M CBS This Morning
1232012-05-18 08:11:10.443020 I Running Grabber: /usr/share/mythtv/metadata/Television/ttvdb.py -l en -M AB Twister
1242012-05-18 08:11:12.594845 I MainServer::ANN Monitor
1252012-05-18 08:11:12.594863 I adding: mythserver as a client (events: 2)
1262012-05-18 08:11:13.362429 I MainServer::ANN Monitor
1272012-05-18 08:11:13.362435 I adding: mythserver as a client (events: 2)
1282012-05-18 08:11:13.365930 I MainServer::ANN Monitor
1292012-05-18 08:11:13.365936 I adding: mythserver as a client (events: 2)
1302012-05-18 08:11:14.249215 I Running Grabber: /usr/share/mythtv/metadata/Movie/tmdb.py -l en -M Paid Programming
1312012-05-18 08:11:14.653503 I Running Grabber: /usr/share/mythtv/metadata/Television/ttvdb.py -l en -M Paid Programming
1322012-05-18 08:11:15.162319 I Running Grabber: /usr/share/mythtv/metadata/Television/ttvdb.py -l en -D 248938 1 1
1332012-05-18 08:11:16.377331 I Returning Metadata Results: Paid Programming 0 0
1342012-05-18 08:11:18.103915 I MainServer::ANN Monitor
1352012-05-18 08:11:18.103966 I adding: mythserver as a client (events: 2)
1362012-05-18 08:11:18.108823 I MainServer::ANN Monitor
1372012-05-18 08:11:18.108851 I adding: mythserver as a client (events: 2)
1382012-05-18 08:11:19.069550 I MainServer::ANN Monitor
1392012-05-18 08:11:19.069571 I adding: mythserver as a client (events: 2)
1402012-05-18 08:11:19.070322 I Reschedule requested for id 410.
1412012-05-18 08:11:21.958577 I Scheduled 1507 items in 2.9 = 0.03 match + 2.85 place
1422012-05-18 08:11:22.227162 I TVRec(1): RecordPending on inputid 1
1432012-05-18 08:11:22.228071 I TVRec(1): StartRecording("CBS This Morning")
1442012-05-18 08:11:22.229297 I TVRec(1): ASK_RECORDING 1 0 0 0
1452012-05-18 08:11:22.344135 I TVRec(1): StartedRecording(1017_2012-05-18T08:11:00) fn(/myth/1017_20120518081100.mpg)
1462012-05-18 08:11:22.344255 I TVRec(1): ClearFlags(CancelNextRecording,) -> RunMainLoop,
1472012-05-18 08:11:22.344409 I TVRec(1): Changing from None to RecordingOnly
1482012-05-18 08:11:22.344492 I TVRec(1): ClearFlags(FrontendReady,CancelNextRecording,) -> RunMainLoop,
1492012-05-18 08:11:22.344663 I TVRec(1): HandleTuning Request: Program(ProgramInfo(1017_20120518081100.mpg): channame(WIVB) startts(Fri May 18 07:00:00 2012) endts(Fri May 18 09:00:00 2012)
150 recstartts(Fri May 18 08:11:00 2012) recendts(Fri May 18 09:00:00 2012)
151 title(CBS This Morning)) channel() input() flags(Recording,)
1522012-05-18 08:11:22.349943 I TVRec(1): HW Tuner: 1->1
1532012-05-18 08:11:22.349972 I TVRec(1): ClearFlags(PENDINGACTIONS,) -> RunMainLoop,
1542012-05-18 08:11:22.349989 I TVRec(1): No recorder yet, calling TuningFrequency
1552012-05-18 08:11:22.351657 I V4LChannel(/dev/video0): Device name 'Hauppauge WinTV PVR-250' driver 'ivtv'.
1562012-05-18 08:11:22.351696 I V4LChannel(/dev/video0): v4l2: 1 stream io: 0 std io: 1 async io: 0 tuner 1 sliced vbi 1
1572012-05-18 08:11:22.371242 I ChannelBase(1): Input #1: 'Tuner 1' schan(2) sourceid(1) ccid(1)
1582012-05-18 08:11:22.371253 I ChannelBase(1): Current Input #1: 'Tuner 1'
1592012-05-18 08:11:22.371292 I Global TVFormat Setting 'NTSC'
1602012-05-18 08:11:22.371312 I V4LChannel(/dev/video0): Input #1: 'Tuner 1' schan(2) tun() v4l1(Unknown) v4l2(NTSC)
1612012-05-18 08:11:22.371319 I V4LChannel(/dev/video0): SetFormat(Default) fmt(NTSC) input(1)
1622012-05-18 08:11:22.371325 I Channel(/dev/video0)::SwitchToInput(in 1, '')
1632012-05-18 08:11:22.372912 I V4LChannel(/dev/video0): SetInputAndFormat(1, NTSC) (v4l v2) input_switch: 0 mode_switch: 0
1642012-05-18 08:11:22.372923 I DTVChan(/dev/video0): SetChannelByString(17):
1652012-05-18 08:11:22.374061 I V4LChannel(/dev/video0): SetFormat(Default) fmt(NTSC) input(1)
1662012-05-18 08:11:22.374071 I Channel(/dev/video0)::Tune(17): curList[15].freq(139250)
1672012-05-18 08:11:22.374075 I V4LChannel(/dev/video0): Tune(139250000, )
1682012-05-18 08:11:22.384752 I Channel(/dev/video0)::Tune(): Frequency is now 139250000
1692012-05-18 08:11:22.384755 I DTVChan(/dev/video0): SetChannelByString(17): success
1702012-05-18 08:11:22.386384 I TVRec(1): Starting Signal Monitor
1712012-05-18 08:11:22.386397 I TVRec(1): SetupSignalMonitor(1, 0)
1722012-05-18 08:11:22.386464 I TVRec(1): Signal monitor successfully created
1732012-05-18 08:11:22.390304 I TVRec(1): SetFlags(SignalMonitorRunning,) -> RunMainLoop,SignalMonitorRunning,
1742012-05-18 08:11:22.390312 I TVRec(1): ClearFlags(WaitingForSignal,) -> RunMainLoop,SignalMonitorRunning,
1752012-05-18 08:11:22.390317 I TVRec(1): SetFlags(WaitingForSignal,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning,
1762012-05-18 08:11:22.390322 I TVRec(1): ClearFlags(NeedToStartRecorder,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning,
1772012-05-18 08:11:22.390327 I TVRec(1): SetFlags(NeedToStartRecorder,) -> RunMainLoop,WaitingForSignal,NeedToStartRecorder,SignalMonitorRunning,
1782012-05-18 08:11:22.390335 I TVRec(1): Got good signal
1792012-05-18 08:11:22.390368 I TVRec(1): TeardownSignalMonitor() -- begin
1802012-05-18 08:11:22.437014 I TVRec(1): TeardownSignalMonitor() -- end
1812012-05-18 08:11:22.437059 I TVRec(1): ClearFlags(SignalMonitorRunning,) -> RunMainLoop,WaitingForSignal,NeedToStartRecorder,
1822012-05-18 08:11:22.437093 I TVRec(1): ClearFlags(WaitingForSignal,) -> RunMainLoop,NeedToStartRecorder,
1832012-05-18 08:11:22.437213 I TVRec(1): Starting Recorder
1842012-05-18 08:11:22.516610 I Using profile 'Default' to record
1852012-05-18 08:11:22.516639 I TVRec(1): rec->GetPathname(): '/myth/1017_20120518081100.mpg'
1862012-05-18 08:11:22.517184 I DTVRec(1): ResetForNewFile(void)
1872012-05-18 08:11:22.520325 I RecBase(1:/dev/video0): SetRingBuffer(0x7f3f2801e9b0) '/myth/1017_20120518081100.mpg'
1882012-05-18 08:11:22.520369 I RecBase(1:/dev/video0): SetRecording(0x7f3f1088a2f0) title(CBS This Morning)
1892012-05-18 08:11:22.529764 I DTVRec(1): ResetForNewFile(void)
1902012-05-18 08:11:22.536154 N AutoExpire: CalcParams(): Max required Free Space: 2.0 GB w/freq: 15 min
1912012-05-18 08:11:22.537580 I Started recording: "CBS This Morning": channel 1017 on cardid 1, sourceid 1
1922012-05-18 08:11:22.543159 I MainServer::ANN Monitor
1932012-05-18 08:11:22.543166 I adding: mythserver as a client (events: 2)
1942012-05-18 08:11:22.547398 I DevRdB(/dev/video0): buffer size 9400 KB
1952012-05-18 08:11:22.547414 I MPEGRec(/dev/video0): DRB ready
1962012-05-18 08:11:22.547434 I MPEGRec(/dev/video0): Initial startup of recorder
1972012-05-18 08:11:22.547439 I MPEGRec(/dev/video0): StartEncoding
1982012-05-18 08:11:22.547717 I MainServer::ANN Monitor
1992012-05-18 08:11:22.547723 I adding: mythserver as a client (events: 2)
2002012-05-18 08:11:22.558400 I TVRec(1): SetFlags(RecorderRunning,RingBufferReady,) -> RunMainLoop,NeedToStartRecorder,RecorderRunning,RingBufferReady,
2012012-05-18 08:11:22.663886 I MainServer::ANN Monitor
2022012-05-18 08:11:22.663892 I adding: mythserver as a client (events: 2)
2032012-05-18 08:11:22.668142 I MainServer::ANN Monitor
2042012-05-18 08:11:22.668148 I adding: mythserver as a client (events: 2)
2052012-05-18 08:11:22.757954 I TVRec(1): ClearFlags(NeedToStartRecorder,) -> RunMainLoop,RecorderRunning,RingBufferReady,
2062012-05-18 08:11:22.882439 I MPEGRec(/dev/video0): Encoding started
2072012-05-18 08:11:22.882458 I DevRdB(/dev/video0): Start() -- begin
2082012-05-18 08:11:22.882536 I DevRdB(/dev/video0): Start() -- middle
2092012-05-18 08:11:22.882541 I DevRdB(/dev/video0): Start() -- end
2102012-05-18 08:11:23.252297 I MainServer::ANN Monitor
2112012-05-18 08:11:23.252315 I adding: mythserver as a client (events: 2)
2122012-05-18 08:11:23.253346 I Reschedule requested for id 411.
2132012-05-18 08:11:25.385249 E DevRdB(/dev/video0): Poll giving up 2
2142012-05-18 08:11:25.385271 E DevRdB(/dev/video0): fill_ringbuffer: error state
2152012-05-18 08:11:25.385376 E MPEGRec(/dev/video0): Device error detected
2162012-05-18 08:11:25.385380 I MPEGRec(/dev/video0): RestartEncoding
2172012-05-18 08:11:25.385384 I MPEGRec(/dev/video0): StopEncoding
2182012-05-18 08:11:25.794450 I Running Grabber: /usr/share/mythtv/metadata/Movie/tmdb.py -l en -M CBS This Morning
2192012-05-18 08:11:26.192365 I MainServer::ANN Monitor
2202012-05-18 08:11:26.192372 I adding: mythserver as a client (events: 0)
2212012-05-18 08:11:26.194848 I MainServer::ANN Monitor
2222012-05-18 08:11:26.194857 I adding: mythserver as a client (events: 1)
2232012-05-18 08:11:26.302749 I Running Grabber: /usr/share/mythtv/metadata/Television/ttvdb.py -l en -M CBS This Morning
2242012-05-18 08:11:26.371491 I MainServer::ANN Monitor
2252012-05-18 08:11:26.371496 I adding: mythserver as a client (events: 2)
2262012-05-18 08:11:26.374521 I MainServer::ANN Monitor
2272012-05-18 08:11:26.374527 I adding: mythserver as a client (events: 2)
2282012-05-18 08:11:26.488252 I Scheduled 1508 items in 3.2 = 0.03 match + 3.18 place
2292012-05-18 08:11:26.490658 I TVRec(2): RecordPending on inputid 2
2302012-05-18 08:11:26.490866 I TVRec(2): StartRecording("AB Twister")
2312012-05-18 08:11:26.491914 I TVRec(2): ASK_RECORDING 2 0 0 0
2322012-05-18 08:11:26.504410 I TVRec(2): StartedRecording(1018_2012-05-18T08:11:00) fn(/myth/1018_20120518081100.mpg)
2332012-05-18 08:11:26.504458 I TVRec(2): ClearFlags(CancelNextRecording,) -> RunMainLoop,
2342012-05-18 08:11:26.504643 I TVRec(2): Changing from None to RecordingOnly
2352012-05-18 08:11:26.504652 I TVRec(2): ClearFlags(FrontendReady,CancelNextRecording,) -> RunMainLoop,
2362012-05-18 08:11:26.504700 I TVRec(2): HandleTuning Request: Program(ProgramInfo(1018_20120518081100.mpg): channame(Shop TV Canada) startts(Fri May 18 08:00:00 2012) endts(Fri May 18 08:30:00 2012)
237 recstartts(Fri May 18 08:11:00 2012) recendts(Fri May 18 08:30:00 2012)
238 title(AB Twister)) channel() input() flags(Recording,)
2392012-05-18 08:11:26.505991 I TVRec(2): HW Tuner: 2->2
2402012-05-18 08:11:26.506001 I TVRec(2): ClearFlags(PENDINGACTIONS,) -> RunMainLoop,
2412012-05-18 08:11:26.506006 I TVRec(2): No recorder yet, calling TuningFrequency
2422012-05-18 08:11:26.506436 I V4LChannel(/dev/video1): Device name 'WinTV PVR 500 (unit #1)' driver 'ivtv'.
2432012-05-18 08:11:26.506446 I V4LChannel(/dev/video1): v4l2: 1 stream io: 0 std io: 1 async io: 0 tuner 1 sliced vbi 1
2442012-05-18 08:11:26.511550 I ChannelBase(2): Input #2: 'Tuner 1' schan(2) sourceid(1) ccid(2)
2452012-05-18 08:11:26.511558 I ChannelBase(2): Current Input #2: 'Tuner 1'
2462012-05-18 08:11:26.511600 I Global TVFormat Setting 'NTSC'
2472012-05-18 08:11:26.511619 I V4LChannel(/dev/video1): Input #2: 'Tuner 1' schan(2) tun() v4l1(Unknown) v4l2(NTSC)
2482012-05-18 08:11:26.511626 I V4LChannel(/dev/video1): SetFormat(Default) fmt(NTSC) input(2)
2492012-05-18 08:11:26.511631 I Channel(/dev/video1)::SwitchToInput(in 2, '')
2502012-05-18 08:11:26.512581 I V4LChannel(/dev/video1): SetInputAndFormat(2, NTSC) (v4l v2) input_switch: 0 mode_switch: 0
2512012-05-18 08:11:26.512587 I DTVChan(/dev/video1): SetChannelByString(18):
2522012-05-18 08:11:26.514616 I V4LChannel(/dev/video1): SetFormat(Default) fmt(NTSC) input(2)
2532012-05-18 08:11:26.514628 I Channel(/dev/video1)::Tune(18): curList[16].freq(145250)
2542012-05-18 08:11:26.514632 I V4LChannel(/dev/video1): Tune(145250000, )
2552012-05-18 08:11:26.540238 I Channel(/dev/video1)::Tune(): Frequency is now 145250000
2562012-05-18 08:11:26.540249 I DTVChan(/dev/video1): SetChannelByString(18): success
2572012-05-18 08:11:26.547690 I TVRec(2): Starting Signal Monitor
2582012-05-18 08:11:26.547698 I TVRec(2): SetupSignalMonitor(1, 0)
2592012-05-18 08:11:26.547721 I TVRec(2): Signal monitor successfully created
2602012-05-18 08:11:26.549804 I TVRec(2): SetFlags(SignalMonitorRunning,) -> RunMainLoop,SignalMonitorRunning,
2612012-05-18 08:11:26.549813 I TVRec(2): ClearFlags(WaitingForSignal,) -> RunMainLoop,SignalMonitorRunning,
2622012-05-18 08:11:26.549818 I TVRec(2): SetFlags(WaitingForSignal,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning,
2632012-05-18 08:11:26.549824 I TVRec(2): ClearFlags(NeedToStartRecorder,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning,
2642012-05-18 08:11:26.549829 I TVRec(2): SetFlags(NeedToStartRecorder,) -> RunMainLoop,WaitingForSignal,NeedToStartRecorder,SignalMonitorRunning,
2652012-05-18 08:11:26.553834 N AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 15 min
2662012-05-18 08:11:26.554139 I Tuning recording: "AB Twister": channel 1018 on cardid 2, sourceid 1
2672012-05-18 08:11:26.557341 I TVRec(2): Got good signal
2682012-05-18 08:11:26.557433 I Updating status for "AB Twister" on cardid 2 (Tuning => Recording)
2692012-05-18 08:11:26.558837 I TVRec(2): TeardownSignalMonitor() -- begin
2702012-05-18 08:11:26.612106 I TVRec(2): TeardownSignalMonitor() -- end
2712012-05-18 08:11:26.612131 I TVRec(2): ClearFlags(SignalMonitorRunning,) -> RunMainLoop,WaitingForSignal,NeedToStartRecorder,
2722012-05-18 08:11:26.612139 I TVRec(2): ClearFlags(WaitingForSignal,) -> RunMainLoop,NeedToStartRecorder,
2732012-05-18 08:11:26.612177 I TVRec(2): Starting Recorder
2742012-05-18 08:11:26.630493 I Using profile 'Default' to record
2752012-05-18 08:11:26.630503 I TVRec(2): rec->GetPathname(): '/myth/1018_20120518081100.mpg'
2762012-05-18 08:11:26.630664 I DTVRec(2): ResetForNewFile(void)
2772012-05-18 08:11:26.630741 I RecBase(2:/dev/video1): SetRingBuffer(0x7f3f1c04d760) '/myth/1018_20120518081100.mpg'
2782012-05-18 08:11:26.630750 I RecBase(2:/dev/video1): SetRecording(0x7f3f10446e10) title(AB Twister)
2792012-05-18 08:11:26.636747 I DTVRec(2): ResetForNewFile(void)
2802012-05-18 08:11:26.667586 I DevRdB(/dev/video1): buffer size 9400 KB
2812012-05-18 08:11:26.667598 I MPEGRec(/dev/video1): DRB ready
2822012-05-18 08:11:26.667608 I MPEGRec(/dev/video1): Initial startup of recorder
2832012-05-18 08:11:26.667612 I MPEGRec(/dev/video1): StartEncoding
2842012-05-18 08:11:26.668958 I TVRec(2): SetFlags(RecorderRunning,RingBufferReady,) -> RunMainLoop,NeedToStartRecorder,RecorderRunning,RingBufferReady,
2852012-05-18 08:11:26.669633 I TVRec(2): ClearFlags(NeedToStartRecorder,) -> RunMainLoop,RecorderRunning,RingBufferReady,
2862012-05-18 08:11:27.058455 I MPEGRec(/dev/video1): Encoding started
2872012-05-18 08:11:27.058467 I DevRdB(/dev/video1): Start() -- begin
2882012-05-18 08:11:27.058508 I DevRdB(/dev/video1): Start() -- middle
2892012-05-18 08:11:27.058510 I DevRdB(/dev/video1): Start() -- end
2902012-05-18 08:11:27.148668 I Running Grabber: /usr/share/mythtv/metadata/Movie/tmdb.py -l en -M AB Twister
2912012-05-18 08:11:27.405112 E Preview: Encountered problems running '/usr/bin/mythpreviewgen --size 0x0 --chanid 1017 --starttime 20120518081100 --outfile "/myth/1017_20120518081100.mpg.png" --verbose general,record,channel --loglevel info --quiet' (128)
2922012-05-18 08:11:27.482657 I MPEGRec(/dev/video0): Encoding stopped
2932012-05-18 08:11:27.482718 I MPEGRec(/dev/video0): StartEncoding
2942012-05-18 08:11:27.492737 I MainServer::ANN Monitor
2952012-05-18 08:11:27.492745 I adding: mythserver as a client (events: 2)
2962012-05-18 08:11:27.498167 I MainServer::ANN Monitor
2972012-05-18 08:11:27.498173 I adding: mythserver as a client (events: 2)
2982012-05-18 08:11:27.505501 I Running Grabber: /usr/share/mythtv/metadata/Television/ttvdb.py -l en -M AB Twister
2992012-05-18 08:11:27.830539 I MPEGRec(/dev/video0): Encoding started
3002012-05-18 08:11:27.830577 I DevRdB(/dev/video0): Start() -- begin
3012012-05-18 08:11:27.830656 I DevRdB(/dev/video0): Start() -- middle
3022012-05-18 08:11:27.830666 I DevRdB(/dev/video0): Start() -- end
3032012-05-18 08:11:28.216448 I MainServer::ANN Monitor
3042012-05-18 08:11:28.216457 I adding: mythserver as a client (events: 2)
3052012-05-18 08:11:28.217090 I Reschedule requested for id 412.
3062012-05-18 08:11:29.559126 E DevRdB(/dev/video1): Poll giving up 2
3072012-05-18 08:11:29.559153 E DevRdB(/dev/video1): fill_ringbuffer: error state
3082012-05-18 08:11:29.559393 E MPEGRec(/dev/video1): Device error detected
3092012-05-18 08:11:29.559412 I MPEGRec(/dev/video1): RestartEncoding
3102012-05-18 08:11:29.559423 I MPEGRec(/dev/video1): StopEncoding
3112012-05-18 08:11:30.333445 E DevRdB(/dev/video0): Poll giving up 2
3122012-05-18 08:11:30.333454 E DevRdB(/dev/video0): fill_ringbuffer: error state
3132012-05-18 08:11:30.333497 E MPEGRec(/dev/video0): Device error detected
3142012-05-18 08:11:30.333505 I MPEGRec(/dev/video0): RestartEncoding
3152012-05-18 08:11:30.333509 I MPEGRec(/dev/video0): StopEncoding
3162012-05-18 08:11:31.658522 I MPEGRec(/dev/video1): Encoding stopped
3172012-05-18 08:11:31.658553 I MPEGRec(/dev/video1): StartEncoding
3182012-05-18 08:11:31.850859 I Scheduled 1509 items in 3.6 = 0.06 match + 3.57 place
3192012-05-18 08:11:31.853191 I TVRec(3): RecordPending on inputid 3
3202012-05-18 08:11:31.853396 I TVRec(3): StartRecording("Paid Programming")
3212012-05-18 08:11:32.025924 I TVRec(3): StartedRecording(1020_2012-05-18T08:12:00) fn(/myth/1020_20120518081200.mpg)
3222012-05-18 08:11:32.025962 I TVRec(3): ClearFlags(CancelNextRecording,) -> RunMainLoop,
3232012-05-18 08:11:32.026002 I TVRec(3): Changing from None to RecordingOnly
3242012-05-18 08:11:32.026016 I TVRec(3): ClearFlags(FrontendReady,CancelNextRecording,) -> RunMainLoop,
3252012-05-18 08:11:32.026056 I TVRec(3): HandleTuning Request: Program(ProgramInfo(1020_20120518081200.mpg): channame(WUTV) startts(Fri May 18 08:00:00 2012) endts(Fri May 18 08:30:00 2012)
326 recstartts(Fri May 18 08:12:00 2012) recendts(Fri May 18 08:30:00 2012)
327 title(Paid Programming)) channel() input() flags(Recording,)
3282012-05-18 08:11:32.027132 I TVRec(3): HW Tuner: 3->3
3292012-05-18 08:11:32.027141 I TVRec(3): ClearFlags(PENDINGACTIONS,) -> RunMainLoop,
3302012-05-18 08:11:32.027146 I TVRec(3): No recorder yet, calling TuningFrequency
3312012-05-18 08:11:32.027594 I V4LChannel(/dev/video2): Device name 'WinTV PVR 500 (unit #2)' driver 'ivtv'.
3322012-05-18 08:11:32.027603 I V4LChannel(/dev/video2): v4l2: 1 stream io: 0 std io: 1 async io: 0 tuner 1 sliced vbi 1
3332012-05-18 08:11:32.032759 I ChannelBase(3): Input #3: 'Tuner 1' schan(2) sourceid(1) ccid(3)
3342012-05-18 08:11:32.032768 I ChannelBase(3): Current Input #3: 'Tuner 1'
3352012-05-18 08:11:32.032808 I Global TVFormat Setting 'NTSC'
3362012-05-18 08:11:32.032828 I V4LChannel(/dev/video2): Input #3: 'Tuner 1' schan(2) tun() v4l1(Unknown) v4l2(NTSC)
3372012-05-18 08:11:32.032834 I V4LChannel(/dev/video2): SetFormat(Default) fmt(NTSC) input(3)
3382012-05-18 08:11:32.032839 I Channel(/dev/video2)::SwitchToInput(in 3, '')
3392012-05-18 08:11:32.033787 I V4LChannel(/dev/video2): SetInputAndFormat(3, NTSC) (v4l v2) input_switch: 0 mode_switch: 0
3402012-05-18 08:11:32.033794 I DTVChan(/dev/video2): SetChannelByString(20):
3412012-05-18 08:11:32.034940 I V4LChannel(/dev/video2): SetFormat(Default) fmt(NTSC) input(3)
3422012-05-18 08:11:32.034950 I Channel(/dev/video2)::Tune(20): curList[18].freq(157250)
3432012-05-18 08:11:32.034954 I V4LChannel(/dev/video2): Tune(157250000, )
3442012-05-18 08:11:32.042434 I MPEGRec(/dev/video1): Encoding started
3452012-05-18 08:11:32.042441 I DevRdB(/dev/video1): Start() -- begin
3462012-05-18 08:11:32.042472 I DevRdB(/dev/video1): Start() -- middle
3472012-05-18 08:11:32.042475 I DevRdB(/dev/video1): Start() -- end
3482012-05-18 08:11:32.050310 I Channel(/dev/video2)::Tune(): Frequency is now 157250000
3492012-05-18 08:11:32.050314 I DTVChan(/dev/video2): SetChannelByString(20): success
3502012-05-18 08:11:32.052026 I TVRec(3): Starting Signal Monitor
3512012-05-18 08:11:32.052034 I TVRec(3): SetupSignalMonitor(1, 0)
3522012-05-18 08:11:32.052050 I TVRec(3): Signal monitor successfully created
3532012-05-18 08:11:32.053139 I TVRec(3): SetFlags(SignalMonitorRunning,) -> RunMainLoop,SignalMonitorRunning,
3542012-05-18 08:11:32.053145 I TVRec(3): ClearFlags(WaitingForSignal,) -> RunMainLoop,SignalMonitorRunning,
3552012-05-18 08:11:32.053150 I TVRec(3): SetFlags(WaitingForSignal,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning,
3562012-05-18 08:11:32.053155 I TVRec(3): ClearFlags(NeedToStartRecorder,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning,
3572012-05-18 08:11:32.053167 I TVRec(3): SetFlags(NeedToStartRecorder,) -> RunMainLoop,WaitingForSignal,NeedToStartRecorder,SignalMonitorRunning,
3582012-05-18 08:11:32.054212 I TVRec(3): Got good signal
3592012-05-18 08:11:32.054245 I TVRec(3): TeardownSignalMonitor() -- begin
3602012-05-18 08:11:32.057200 N AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 10 min
3612012-05-18 08:11:32.057219 I Tuning recording: "Paid Programming": channel 1020 on cardid 3, sourceid 1
3622012-05-18 08:11:32.059522 I Updating status for "Paid Programming" on cardid 3 (Tuning => Recording)
3632012-05-18 08:11:32.104388 I TVRec(3): TeardownSignalMonitor() -- end
3642012-05-18 08:11:32.104396 I TVRec(3): ClearFlags(SignalMonitorRunning,) -> RunMainLoop,WaitingForSignal,NeedToStartRecorder,
3652012-05-18 08:11:32.104404 I TVRec(3): ClearFlags(WaitingForSignal,) -> RunMainLoop,NeedToStartRecorder,
3662012-05-18 08:11:32.104420 I TVRec(3): Starting Recorder
3672012-05-18 08:11:32.112240 I Using profile 'Default' to record
3682012-05-18 08:11:32.112249 I TVRec(3): rec->GetPathname(): '/myth/1020_20120518081200.mpg'
3692012-05-18 08:11:32.112422 I DTVRec(3): ResetForNewFile(void)
3702012-05-18 08:11:32.112491 I RecBase(3:/dev/video2): SetRingBuffer(0x7f3f1804e850) '/myth/1020_20120518081200.mpg'
3712012-05-18 08:11:32.112504 I RecBase(3:/dev/video2): SetRecording(0x7f3f1047b480) title(Paid Programming)
3722012-05-18 08:11:32.116671 I DTVRec(3): ResetForNewFile(void)
3732012-05-18 08:11:32.129813 I DevRdB(/dev/video2): buffer size 9400 KB
3742012-05-18 08:11:32.129822 I MPEGRec(/dev/video2): DRB ready
3752012-05-18 08:11:32.129842 I MPEGRec(/dev/video2): Initial startup of recorder
3762012-05-18 08:11:32.129850 I MPEGRec(/dev/video2): StartEncoding
3772012-05-18 08:11:32.134460 I TVRec(3): SetFlags(RecorderRunning,RingBufferReady,) -> RunMainLoop,NeedToStartRecorder,RecorderRunning,RingBufferReady,
3782012-05-18 08:11:32.135196 I TVRec(3): ClearFlags(NeedToStartRecorder,) -> RunMainLoop,RecorderRunning,RingBufferReady,
3792012-05-18 08:11:32.197365 I MainServer::ANN Monitor
3802012-05-18 08:11:32.197372 I adding: mythserver as a client (events: 2)
3812012-05-18 08:11:32.201113 I MainServer::ANN Monitor
3822012-05-18 08:11:32.201119 I adding: mythserver as a client (events: 2)
3832012-05-18 08:11:32.430565 I MPEGRec(/dev/video0): Encoding stopped
3842012-05-18 08:11:32.430593 I MPEGRec(/dev/video0): StartEncoding
3852012-05-18 08:11:32.482452 I MPEGRec(/dev/video2): Encoding started
3862012-05-18 08:11:32.482478 I DevRdB(/dev/video2): Start() -- begin
3872012-05-18 08:11:32.482547 I DevRdB(/dev/video2): Start() -- middle
3882012-05-18 08:11:32.482554 I DevRdB(/dev/video2): Start() -- end
3892012-05-18 08:11:32.766503 I MPEGRec(/dev/video0): Encoding started
3902012-05-18 08:11:32.766536 I DevRdB(/dev/video0): Start() -- begin
3912012-05-18 08:11:32.766678 I DevRdB(/dev/video0): Start() -- middle
3922012-05-18 08:11:32.766694 I DevRdB(/dev/video0): Start() -- end
3932012-05-18 08:11:32.778796 I DTVRec(3): FindPSKeyFrames: frame rate = 29970
3942012-05-18 08:11:34.553133 E DevRdB(/dev/video1): Poll giving up 2
3952012-05-18 08:11:34.553154 E DevRdB(/dev/video1): fill_ringbuffer: error state
3962012-05-18 08:11:34.553284 E MPEGRec(/dev/video1): Device error detected
3972012-05-18 08:11:34.553308 I MPEGRec(/dev/video1): RestartEncoding
3982012-05-18 08:11:34.553318 I MPEGRec(/dev/video1): StopEncoding
3992012-05-18 08:11:35.268169 E DevRdB(/dev/video0): Poll giving up 2
4002012-05-18 08:11:35.268209 E DevRdB(/dev/video0): fill_ringbuffer: error state
4012012-05-18 08:11:35.268434 E MPEGRec(/dev/video0): Device error detected
4022012-05-18 08:11:35.268445 I MPEGRec(/dev/video0): RestartEncoding
4032012-05-18 08:11:35.268456 I MPEGRec(/dev/video0): StopEncoding
4042012-05-18 08:11:36.650618 I MPEGRec(/dev/video1): Encoding stopped
4052012-05-18 08:11:36.650660 I MPEGRec(/dev/video1): StartEncoding
4062012-05-18 08:11:37.002499 I MPEGRec(/dev/video1): Encoding started
4072012-05-18 08:11:37.002527 I DevRdB(/dev/video1): Start() -- begin
4082012-05-18 08:11:37.002605 I DevRdB(/dev/video1): Start() -- middle
4092012-05-18 08:11:37.002614 I DevRdB(/dev/video1): Start() -- end
4102012-05-18 08:11:37.049808 I MainServer::ANN Monitor
4112012-05-18 08:11:37.049815 I adding: mythserver as a client (events: 2)
4122012-05-18 08:11:37.192405 I MainServer::ANN Monitor
4132012-05-18 08:11:37.192412 I adding: mythserver as a client (events: 2)
4142012-05-18 08:11:37.366521 I MPEGRec(/dev/video0): Encoding stopped
4152012-05-18 08:11:37.366539 I MPEGRec(/dev/video0): StartEncoding
4162012-05-18 08:11:37.710454 I MPEGRec(/dev/video0): Encoding started
4172012-05-18 08:11:37.710470 I DevRdB(/dev/video0): Start() -- begin
4182012-05-18 08:11:37.710545 I DevRdB(/dev/video0): Start() -- middle
4192012-05-18 08:11:37.710549 I DevRdB(/dev/video0): Start() -- end
4202012-05-18 08:11:37.858349 I MainServer::ANN Monitor
4212012-05-18 08:11:37.858355 I adding: mythserver as a client (events: 0)
4222012-05-18 08:11:37.858639 I MainServer::ANN Monitor
4232012-05-18 08:11:37.858646 I adding: mythserver as a client (events: 1)
4242012-05-18 08:11:37.882384 I MainServer::ANN Monitor
4252012-05-18 08:11:37.882399 I adding: mythserver as a client (events: 0)
4262012-05-18 08:11:37.883218 I MainServer::ANN Monitor
4272012-05-18 08:11:37.883231 I adding: mythserver as a client (events: 1)
4282012-05-18 08:11:37.922243 I MainServer::ANN Monitor
4292012-05-18 08:11:37.922260 I adding: mythserver as a client (events: 0)
4302012-05-18 08:11:37.923478 I MainServer::ANN Monitor
4312012-05-18 08:11:37.923496 I adding: mythserver as a client (events: 1)
4322012-05-18 08:11:39.003927 E Preview: Encountered problems running '/usr/bin/mythpreviewgen --size 0x0 --chanid 1017 --starttime 20120518081100 --outfile "/myth/1017_20120518081100.mpg.png" --verbose general,record,channel --loglevel info --quiet' (128)
4332012-05-18 08:11:39.003959 E Preview: Encountered problems running '/usr/bin/mythpreviewgen --size 0x0 --chanid 1018 --starttime 20120518081100 --outfile "/myth/1018_20120518081100.mpg.png" --verbose general,record,channel --loglevel info --quiet' (128)
4342012-05-18 08:11:39.505473 E DevRdB(/dev/video1): Poll giving up 2
4352012-05-18 08:11:39.505498 E DevRdB(/dev/video1): fill_ringbuffer: error state
4362012-05-18 08:11:39.505663 E MPEGRec(/dev/video1): Device error detected
4372012-05-18 08:11:39.505695 I MPEGRec(/dev/video1): RestartEncoding
4382012-05-18 08:11:39.505705 I MPEGRec(/dev/video1): StopEncoding
4392012-05-18 08:11:39.697542 I Running Grabber: /usr/share/mythtv/metadata/Movie/tmdb.py -l en -M Paid Programming
4402012-05-18 08:11:40.082755 I MainServer::ANN Monitor
4412012-05-18 08:11:40.082763 I adding: mythserver as a client (events: 0)
4422012-05-18 08:11:40.083048 I MainServer::ANN Monitor
4432012-05-18 08:11:40.083058 I adding: mythserver as a client (events: 1)
4442012-05-18 08:11:40.112432 I Running Grabber: /usr/share/mythtv/metadata/Television/ttvdb.py -l en -M Paid Programming
4452012-05-18 08:11:40.217038 E DevRdB(/dev/video0): Poll giving up 2
4462012-05-18 08:11:40.217047 E DevRdB(/dev/video0): fill_ringbuffer: error state
4472012-05-18 08:11:40.217190 E MPEGRec(/dev/video0): Device error detected
4482012-05-18 08:11:40.217197 I MPEGRec(/dev/video0): RestartEncoding
4492012-05-18 08:11:40.217202 I MPEGRec(/dev/video0): StopEncoding
4502012-05-18 08:11:40.413731 I Running Grabber: /usr/share/mythtv/metadata/Television/ttvdb.py -l en -D 248938 1 1
4512012-05-18 08:11:40.614139 I Returning Metadata Results: Paid Programming 0 0
4522012-05-18 08:11:41.007537 I MainServer::ANN Monitor
4532012-05-18 08:11:41.007542 I adding: mythserver as a client (events: 0)
4542012-05-18 08:11:41.007824 I MainServer::ANN Monitor
4552012-05-18 08:11:41.007828 I adding: mythserver as a client (events: 1)
4562012-05-18 08:11:41.602673 I MPEGRec(/dev/video1): Encoding stopped
4572012-05-18 08:11:41.602730 I MPEGRec(/dev/video1): StartEncoding
4582012-05-18 08:11:41.958489 I MPEGRec(/dev/video1): Encoding started
4592012-05-18 08:11:41.958515 I DevRdB(/dev/video1): Start() -- begin
4602012-05-18 08:11:41.958635 I DevRdB(/dev/video1): Start() -- middle
4612012-05-18 08:11:41.958645 I DevRdB(/dev/video1): Start() -- end
4622012-05-18 08:11:42.314717 I MPEGRec(/dev/video0): Encoding stopped
4632012-05-18 08:11:42.314783 I MPEGRec(/dev/video0): StartEncoding
4642012-05-18 08:11:42.658492 I MPEGRec(/dev/video0): Encoding started
4652012-05-18 08:11:42.658519 I DevRdB(/dev/video0): Start() -- begin
4662012-05-18 08:11:42.658609 I DevRdB(/dev/video0): Start() -- middle
4672012-05-18 08:11:42.658620 I DevRdB(/dev/video0): Start() -- end
4682012-05-18 08:11:44.461563 E DevRdB(/dev/video1): Poll giving up 2
4692012-05-18 08:11:44.461587 E DevRdB(/dev/video1): fill_ringbuffer: error state
4702012-05-18 08:11:44.461734 E MPEGRec(/dev/video1): Device error detected
4712012-05-18 08:11:44.461759 I MPEGRec(/dev/video1): RestartEncoding
4722012-05-18 08:11:44.461787 I MPEGRec(/dev/video1): StopEncoding
4732012-05-18 08:11:45.160011 E DevRdB(/dev/video0): Poll giving up 2
4742012-05-18 08:11:45.160049 E DevRdB(/dev/video0): fill_ringbuffer: error state
4752012-05-18 08:11:45.160280 E MPEGRec(/dev/video0): Device error detected
4762012-05-18 08:11:45.160292 I MPEGRec(/dev/video0): RestartEncoding
4772012-05-18 08:11:45.160302 I MPEGRec(/dev/video0): StopEncoding
4782012-05-18 08:11:46.558601 I MPEGRec(/dev/video1): Encoding stopped
4792012-05-18 08:11:46.558644 I MPEGRec(/dev/video1): StartEncoding
4802012-05-18 08:11:46.914492 I MPEGRec(/dev/video1): Encoding started
4812012-05-18 08:11:46.914519 I DevRdB(/dev/video1): Start() -- begin
4822012-05-18 08:11:46.914656 I DevRdB(/dev/video1): Start() -- middle
4832012-05-18 08:11:46.914667 I DevRdB(/dev/video1): Start() -- end
4842012-05-18 08:11:47.258627 I MPEGRec(/dev/video0): Encoding stopped
4852012-05-18 08:11:47.258673 I MPEGRec(/dev/video0): StartEncoding
4862012-05-18 08:11:47.594543 I MPEGRec(/dev/video0): Encoding started
4872012-05-18 08:11:47.594571 I DevRdB(/dev/video0): Start() -- begin
4882012-05-18 08:11:47.594651 I DevRdB(/dev/video0): Start() -- middle
4892012-05-18 08:11:47.594662 I DevRdB(/dev/video0): Start() -- end
4902012-05-18 08:11:49.415581 E DevRdB(/dev/video1): Poll giving up 2
4912012-05-18 08:11:49.415632 E DevRdB(/dev/video1): fill_ringbuffer: error state
4922012-05-18 08:11:49.415724 E MPEGRec(/dev/video1): Device error detected
4932012-05-18 08:11:49.415743 I MPEGRec(/dev/video1): RestartEncoding
4942012-05-18 08:11:49.415765 I MPEGRec(/dev/video1): StopEncoding
4952012-05-18 08:11:50.097520 E DevRdB(/dev/video0): Poll giving up 2
4962012-05-18 08:11:50.097543 E DevRdB(/dev/video0): fill_ringbuffer: error state
4972012-05-18 08:11:50.097779 E MPEGRec(/dev/video0): Device error detected
4982012-05-18 08:11:50.097790 I MPEGRec(/dev/video0): RestartEncoding
4992012-05-18 08:11:50.097800 I MPEGRec(/dev/video0): StopEncoding
5002012-05-18 08:11:51.514626 I MPEGRec(/dev/video1): Encoding stopped
5012012-05-18 08:11:51.514670 I MPEGRec(/dev/video1): StartEncoding
5022012-05-18 08:11:51.870499 I MPEGRec(/dev/video1): Encoding started
5032012-05-18 08:11:51.870526 I DevRdB(/dev/video1): Start() -- begin
5042012-05-18 08:11:51.870605 I DevRdB(/dev/video1): Start() -- middle
5052012-05-18 08:11:51.870615 I DevRdB(/dev/video1): Start() -- end
5062012-05-18 08:11:52.194629 I MPEGRec(/dev/video0): Encoding stopped
5072012-05-18 08:11:52.194676 I MPEGRec(/dev/video0): StartEncoding
5082012-05-18 08:11:52.530531 I MPEGRec(/dev/video0): Encoding started
5092012-05-18 08:11:52.530559 I DevRdB(/dev/video0): Start() -- begin
5102012-05-18 08:11:52.530638 I DevRdB(/dev/video0): Start() -- middle
5112012-05-18 08:11:52.530650 I DevRdB(/dev/video0): Start() -- end
5122012-05-18 08:11:54.371222 E DevRdB(/dev/video1): Poll giving up 2
5132012-05-18 08:11:54.371244 E DevRdB(/dev/video1): fill_ringbuffer: error state
5142012-05-18 08:11:54.371371 E MPEGRec(/dev/video1): Device error detected
5152012-05-18 08:11:54.371395 I MPEGRec(/dev/video1): RestartEncoding
5162012-05-18 08:11:54.371406 I MPEGRec(/dev/video1): StopEncoding
5172012-05-18 08:11:55.031754 E DevRdB(/dev/video0): Poll giving up 2
5182012-05-18 08:11:55.031776 E DevRdB(/dev/video0): fill_ringbuffer: error state
5192012-05-18 08:11:55.032002 E MPEGRec(/dev/video0): Device error detected
5202012-05-18 08:11:55.032014 I MPEGRec(/dev/video0): RestartEncoding
5212012-05-18 08:11:55.032025 I MPEGRec(/dev/video0): StopEncoding
5222012-05-18 08:11:56.470631 I MPEGRec(/dev/video1): Encoding stopped
5232012-05-18 08:11:56.470676 I MPEGRec(/dev/video1): StartEncoding
5242012-05-18 08:11:56.826496 I MPEGRec(/dev/video1): Encoding started
5252012-05-18 08:11:56.826524 I DevRdB(/dev/video1): Start() -- begin
5262012-05-18 08:11:56.826600 I DevRdB(/dev/video1): Start() -- middle
5272012-05-18 08:11:56.826610 I DevRdB(/dev/video1): Start() -- end
5282012-05-18 08:11:57.130608 I MPEGRec(/dev/video0): Encoding stopped
5292012-05-18 08:11:57.130653 I MPEGRec(/dev/video0): StartEncoding
5302012-05-18 08:11:57.466503 I MPEGRec(/dev/video0): Encoding started
5312012-05-18 08:11:57.466530 I DevRdB(/dev/video0): Start() -- begin
5322012-05-18 08:11:57.466613 I DevRdB(/dev/video0): Start() -- middle
5332012-05-18 08:11:57.466624 I DevRdB(/dev/video0): Start() -- end
5342012-05-18 08:11:59.329371 E DevRdB(/dev/video1): Poll giving up 2
5352012-05-18 08:11:59.329379 E DevRdB(/dev/video1): fill_ringbuffer: error state
5362012-05-18 08:11:59.329488 E MPEGRec(/dev/video1): Device error detected
5372012-05-18 08:11:59.329510 I MPEGRec(/dev/video1): RestartEncoding
5382012-05-18 08:11:59.329520 I MPEGRec(/dev/video1): StopEncoding
5392012-05-18 08:11:59.968907 E DevRdB(/dev/video0): Poll giving up 2
5402012-05-18 08:11:59.968928 E DevRdB(/dev/video0): fill_ringbuffer: error state
5412012-05-18 08:11:59.969167 E MPEGRec(/dev/video0): Device error detected
5422012-05-18 08:11:59.969179 I MPEGRec(/dev/video0): RestartEncoding
5432012-05-18 08:11:59.969188 I MPEGRec(/dev/video0): StopEncoding
5442012-05-18 08:12:01.426625 I MPEGRec(/dev/video1): Encoding stopped
5452012-05-18 08:12:01.426669 I MPEGRec(/dev/video1): StartEncoding
5462012-05-18 08:12:01.782498 I MPEGRec(/dev/video1): Encoding started
5472012-05-18 08:12:01.782525 I DevRdB(/dev/video1): Start() -- begin
5482012-05-18 08:12:01.782601 I DevRdB(/dev/video1): Start() -- middle
5492012-05-18 08:12:01.782611 I DevRdB(/dev/video1): Start() -- end
5502012-05-18 08:12:02.066658 I MPEGRec(/dev/video0): Encoding stopped
5512012-05-18 08:12:02.066705 I MPEGRec(/dev/video0): StartEncoding
5522012-05-18 08:12:02.402529 I MPEGRec(/dev/video0): Encoding started
5532012-05-18 08:12:02.402556 I DevRdB(/dev/video0): Start() -- begin
5542012-05-18 08:12:02.402636 I DevRdB(/dev/video0): Start() -- middle
5552012-05-18 08:12:02.402648 I DevRdB(/dev/video0): Start() -- end
5562012-05-18 08:12:04.285420 E DevRdB(/dev/video1): Poll giving up 2
5572012-05-18 08:12:04.285441 E DevRdB(/dev/video1): fill_ringbuffer: error state
5582012-05-18 08:12:04.285544 E MPEGRec(/dev/video1): Device error detected
5592012-05-18 08:12:04.285560 I MPEGRec(/dev/video1): RestartEncoding
5602012-05-18 08:12:04.285565 I MPEGRec(/dev/video1): StopEncoding
5612012-05-18 08:12:04.905482 E DevRdB(/dev/video0): Poll giving up 2
5622012-05-18 08:12:04.905502 E DevRdB(/dev/video0): fill_ringbuffer: error state
5632012-05-18 08:12:04.905733 E MPEGRec(/dev/video0): Device error detected
5642012-05-18 08:12:04.905745 I MPEGRec(/dev/video0): RestartEncoding
5652012-05-18 08:12:04.905755 I MPEGRec(/dev/video0): StopEncoding
5662012-05-18 08:12:06.382604 I MPEGRec(/dev/video1): Encoding stopped
5672012-05-18 08:12:06.382639 I MPEGRec(/dev/video1): StartEncoding
5682012-05-18 08:12:06.738503 I MPEGRec(/dev/video1): Encoding started
5692012-05-18 08:12:06.738530 I DevRdB(/dev/video1): Start() -- begin
5702012-05-18 08:12:06.738606 I DevRdB(/dev/video1): Start() -- middle
5712012-05-18 08:12:06.738616 I DevRdB(/dev/video1): Start() -- end
5722012-05-18 08:12:07.002610 I MPEGRec(/dev/video0): Encoding stopped
5732012-05-18 08:12:07.002656 I MPEGRec(/dev/video0): StartEncoding
5742012-05-18 08:12:07.076784 N AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 10 min
5752012-05-18 08:12:07.094231 N Expiring 2225 MB for 1015 at 2011-07-03T21:00:00 => "Celebrity Rehab With Dr. Drew":Intake
5762012-05-18 08:12:07.098285 E ProgramInfo(1015_20110703210000.mpg): GetPlaybackURL: '1015_20110703210000.mpg' should be local, but it can not be found.
5772012-05-18 08:12:07.098623 E ERROR when trying to delete file: GetPlaybackURL/UNABLE/TO/FIND/LOCAL/FILE/ON/mythserver/1015_20110703210000.mpg. File doesn't exist. Database metadata will not be removed.
5782012-05-18 08:12:07.338446 I MPEGRec(/dev/video0): Encoding started
5792012-05-18 08:12:07.338458 I DevRdB(/dev/video0): Start() -- begin
5802012-05-18 08:12:07.338501 I DevRdB(/dev/video0): Start() -- middle
5812012-05-18 08:12:07.338505 I DevRdB(/dev/video0): Start() -- end
5822012-05-18 08:12:09.241434 E DevRdB(/dev/video1): Poll giving up 2
5832012-05-18 08:12:09.241456 E DevRdB(/dev/video1): fill_ringbuffer: error state
5842012-05-18 08:12:09.241589 E MPEGRec(/dev/video1): Device error detected
5852012-05-18 08:12:09.241610 I MPEGRec(/dev/video1): RestartEncoding
5862012-05-18 08:12:09.241620 I MPEGRec(/dev/video1): StopEncoding
5872012-05-18 08:12:09.841225 E DevRdB(/dev/video0): Poll giving up 2
5882012-05-18 08:12:09.841246 E DevRdB(/dev/video0): fill_ringbuffer: error state
5892012-05-18 08:12:09.841483 E MPEGRec(/dev/video0): Device error detected
5902012-05-18 08:12:09.841495 I MPEGRec(/dev/video0): RestartEncoding
5912012-05-18 08:12:09.841505 I MPEGRec(/dev/video0): StopEncoding
5922012-05-18 08:12:11.338621 I MPEGRec(/dev/video1): Encoding stopped
5932012-05-18 08:12:11.338663 I MPEGRec(/dev/video1): StartEncoding
5942012-05-18 08:12:11.694501 I MPEGRec(/dev/video1): Encoding started
5952012-05-18 08:12:11.694529 I DevRdB(/dev/video1): Start() -- begin
5962012-05-18 08:12:11.694606 I DevRdB(/dev/video1): Start() -- middle
5972012-05-18 08:12:11.694616 I DevRdB(/dev/video1): Start() -- end
5982012-05-18 08:12:11.938626 I MPEGRec(/dev/video0): Encoding stopped
5992012-05-18 08:12:11.938671 I MPEGRec(/dev/video0): StartEncoding
6002012-05-18 08:12:12.274511 I MPEGRec(/dev/video0): Encoding started
6012012-05-18 08:12:12.274541 I DevRdB(/dev/video0): Start() -- begin
6022012-05-18 08:12:12.274626 I DevRdB(/dev/video0): Start() -- middle
6032012-05-18 08:12:12.274637 I DevRdB(/dev/video0): Start() -- end
6042012-05-18 08:12:14.195036 E DevRdB(/dev/video1): Poll giving up 2
6052012-05-18 08:12:14.195045 E DevRdB(/dev/video1): fill_ringbuffer: error state
6062012-05-18 08:12:14.195182 E MPEGRec(/dev/video1): Device error detected
6072012-05-18 08:12:14.195185 I MPEGRec(/dev/video1): RestartEncoding
6082012-05-18 08:12:14.195188 I MPEGRec(/dev/video1): StopEncoding
6092012-05-18 08:12:14.777464 E DevRdB(/dev/video0): Poll giving up 2
6102012-05-18 08:12:14.777484 E DevRdB(/dev/video0): fill_ringbuffer: error state
6112012-05-18 08:12:14.777721 E MPEGRec(/dev/video0): Device error detected
6122012-05-18 08:12:14.777732 I MPEGRec(/dev/video0): RestartEncoding
6132012-05-18 08:12:14.777742 I MPEGRec(/dev/video0): StopEncoding
6142012-05-18 08:12:16.294585 I MPEGRec(/dev/video1): Encoding stopped
6152012-05-18 08:12:16.294629 I MPEGRec(/dev/video1): StartEncoding
6162012-05-18 08:12:16.650503 I MPEGRec(/dev/video1): Encoding started
6172012-05-18 08:12:16.650530 I DevRdB(/dev/video1): Start() -- begin
6182012-05-18 08:12:16.650607 I DevRdB(/dev/video1): Start() -- middle
6192012-05-18 08:12:16.650617 I DevRdB(/dev/video1): Start() -- end
6202012-05-18 08:12:16.874627 I MPEGRec(/dev/video0): Encoding stopped
6212012-05-18 08:12:16.874673 I MPEGRec(/dev/video0): StartEncoding
6222012-05-18 08:12:17.210533 I MPEGRec(/dev/video0): Encoding started
6232012-05-18 08:12:17.210561 I DevRdB(/dev/video0): Start() -- begin
6242012-05-18 08:12:17.210642 I DevRdB(/dev/video0): Start() -- middle
6252012-05-18 08:12:17.210653 I DevRdB(/dev/video0): Start() -- end
6262012-05-18 08:12:19.152384 E DevRdB(/dev/video1): Poll giving up 2
6272012-05-18 08:12:19.152405 E DevRdB(/dev/video1): fill_ringbuffer: error state
6282012-05-18 08:12:19.152486 E MPEGRec(/dev/video1): Device error detected
6292012-05-18 08:12:19.152506 I MPEGRec(/dev/video1): RestartEncoding
6302012-05-18 08:12:19.152517 I MPEGRec(/dev/video1): StopEncoding
6312012-05-18 08:12:19.713518 E DevRdB(/dev/video0): Poll giving up 2
6322012-05-18 08:12:19.713539 E DevRdB(/dev/video0): fill_ringbuffer: error state
6332012-05-18 08:12:19.713770 E MPEGRec(/dev/video0): Device error detected
6342012-05-18 08:12:19.713782 I MPEGRec(/dev/video0): RestartEncoding
6352012-05-18 08:12:19.713791 I MPEGRec(/dev/video0): StopEncoding
6362012-05-18 08:12:21.132398 I MainServer::ANN Monitor
6372012-05-18 08:12:21.132404 I adding: mythserver as a client (events: 2)
6382012-05-18 08:12:21.165656 I MainServer::ANN Monitor
6392012-05-18 08:12:21.165662 I adding: mythserver as a client (events: 2)
6402012-05-18 08:12:21.166161 I TVRec(2): Changing from RecordingOnly to None
6412012-05-18 08:12:21.166177 I TVRec(2): ClearFlags(FrontendReady,CancelNextRecording,) -> RunMainLoop,RecorderRunning,RingBufferReady,
6422012-05-18 08:12:21.166187 I TVRec(2): HandleTuning Request: Program(NULL) channel() input() flags(CloseRec,KillRingBuffer,)
6432012-05-18 08:12:21.250590 I MPEGRec(/dev/video1): Encoding stopped
6442012-05-18 08:12:21.250639 I MPEGRec(/dev/video1): StartEncoding
6452012-05-18 08:12:21.606499 I MPEGRec(/dev/video1): Encoding started
6462012-05-18 08:12:21.606529 I DevRdB(/dev/video1): Start() -- begin
6472012-05-18 08:12:21.606608 I DevRdB(/dev/video1): Start() -- middle
6482012-05-18 08:12:21.606618 I DevRdB(/dev/video1): Start() -- end
6492012-05-18 08:12:21.606651 I MPEGRec(/dev/video1): StopEncoding
6502012-05-18 08:12:21.810587 I MPEGRec(/dev/video0): Encoding stopped
6512012-05-18 08:12:21.810632 I MPEGRec(/dev/video0): StartEncoding
6522012-05-18 08:12:22.146464 I MPEGRec(/dev/video0): Encoding started
6532012-05-18 08:12:22.146480 I DevRdB(/dev/video0): Start() -- begin
6542012-05-18 08:12:22.146523 I DevRdB(/dev/video0): Start() -- middle
6552012-05-18 08:12:22.146528 I DevRdB(/dev/video0): Start() -- end
6562012-05-18 08:12:23.706639 I MPEGRec(/dev/video1): Encoding stopped
6572012-05-18 08:12:23.706679 E DevRdB(/dev/video1): poll error
6582012-05-18 08:12:23.706705 E DevRdB(/dev/video1): fill_ringbuffer: error state
6592012-05-18 08:12:23.706802 E MPEGRec(/dev/video1): Device error detected
6602012-05-18 08:12:23.706820 I MPEGRec(/dev/video1): RestartEncoding
6612012-05-18 08:12:23.726799 I DevRdB(/dev/video1): Stop() -- begin
6622012-05-18 08:12:23.726824 I DevRdB(/dev/video1): Stop() -- end
6632012-05-18 08:12:23.726950 I MPEGRec(/dev/video1): StopEncoding
6642012-05-18 08:12:23.726978 I MPEGRec(/dev/video1): StartEncoding
6652012-05-18 08:12:24.090500 I MPEGRec(/dev/video1): Encoding started
6662012-05-18 08:12:24.090529 I DevRdB(/dev/video1): Start() -- begin
6672012-05-18 08:12:24.090607 I DevRdB(/dev/video1): Start() -- middle
6682012-05-18 08:12:24.090617 I DevRdB(/dev/video1): Start() -- end
6692012-05-18 08:12:24.090634 I MPEGRec(/dev/video1): run finishing up
6702012-05-18 08:12:24.090643 I MPEGRec(/dev/video1): StopEncoding
6712012-05-18 08:12:24.112494 I MainServer::ANN Monitor
6722012-05-18 08:12:24.112500 I adding: mythserver as a client (events: 2)
6732012-05-18 08:12:24.142715 I MainServer::ANN Monitor
6742012-05-18 08:12:24.142721 I adding: mythserver as a client (events: 2)
6752012-05-18 08:12:24.143178 I TVRec(3): Changing from RecordingOnly to None
6762012-05-18 08:12:24.143190 I TVRec(3): ClearFlags(FrontendReady,CancelNextRecording,) -> RunMainLoop,RecorderRunning,RingBufferReady,
6772012-05-18 08:12:24.143198 I TVRec(3): HandleTuning Request: Program(NULL) channel() input() flags(CloseRec,KillRingBuffer,)
6782012-05-18 08:12:24.143204 I MPEGRec(/dev/video2): StopEncoding
6792012-05-18 08:12:24.383025 E DevRdB(/dev/video2): poll error
6802012-05-18 08:12:24.383068 E DevRdB(/dev/video2): fill_ringbuffer: error state
6812012-05-18 08:12:24.383304 E MPEGRec(/dev/video2): Device error detected
6822012-05-18 08:12:24.383321 I MPEGRec(/dev/video2): RestartEncoding
6832012-05-18 08:12:24.383343 I MPEGRec(/dev/video2): Encoding stopped
6842012-05-18 08:12:24.383374 I MPEGRec(/dev/video2): StopEncoding
6852012-05-18 08:12:24.383385 I MPEGRec(/dev/video2): StartEncoding
6862012-05-18 08:12:24.649259 E DevRdB(/dev/video0): Poll giving up 2
6872012-05-18 08:12:24.649279 E DevRdB(/dev/video0): fill_ringbuffer: error state
6882012-05-18 08:12:24.649508 E MPEGRec(/dev/video0): Device error detected
6892012-05-18 08:12:24.649519 I MPEGRec(/dev/video0): RestartEncoding
6902012-05-18 08:12:24.649529 I MPEGRec(/dev/video0): StopEncoding
6912012-05-18 08:12:24.734419 I MPEGRec(/dev/video2): Encoding started
6922012-05-18 08:12:24.734429 I DevRdB(/dev/video2): Start() -- begin
6932012-05-18 08:12:24.734459 I DevRdB(/dev/video2): Start() -- middle
6942012-05-18 08:12:24.734462 I DevRdB(/dev/video2): Start() -- end
6952012-05-18 08:12:24.734501 I MPEGRec(/dev/video2): run finishing up
6962012-05-18 08:12:24.734504 I MPEGRec(/dev/video2): StopEncoding
6972012-05-18 08:12:26.194754 I MPEGRec(/dev/video1): Encoding stopped
6982012-05-18 08:12:26.194776 E DevRdB(/dev/video1): poll error
6992012-05-18 08:12:26.194780 E DevRdB(/dev/video1): fill_ringbuffer: error state
7002012-05-18 08:12:26.214817 I DevRdB(/dev/video1): Stop() -- begin
7012012-05-18 08:12:26.214821 I DevRdB(/dev/video1): Stop() -- end
7022012-05-18 08:12:26.216347 I TVRec(2): ClearFlags(RecorderRunning,) -> RunMainLoop,RingBufferReady,
7032012-05-18 08:12:26.216386 I MPEGRec(/dev/video1): StopEncoding
7042012-05-18 08:12:26.216412 I RecBase(2:/dev/video1): SetRecording(0x0)
7052012-05-18 08:12:26.217435 I TVRec(2): FinishedRecording(1018_2012-05-18T08:11:00) good recq:<RecordingQuality overall_score="1" key="1018_2012-05-18T08:11:00" />
706
7072012-05-18 08:12:26.217481 I TVRec(2): FinishedRecording(1018_2012-05-18T08:11:00)
708 title: AB Twister
709 in recgroup: Default status: Recording:Recorded not_dummy finished_now
7102012-05-18 08:12:26.217901 I SaveVideoProperties(0x38, 0x00)
7112012-05-18 08:12:26.218626 I Updating status for "AB Twister" on cardid 2 (Recording => Recorded)
7122012-05-18 08:12:26.219839 I Reschedule requested for id 0.
7132012-05-18 08:12:26.223534 I Finished recording AB Twister: channel 1018
7142012-05-18 08:12:26.225013 I TVRec(2): ClearFlags(RecorderRunning,) -> RunMainLoop,RingBufferReady,
7152012-05-18 08:12:26.225026 I TVRec(2): Tearing down RingBuffer
7162012-05-18 08:12:26.225600 I TVRec(2): ClearFlags(PENDINGACTIONS,) -> RunMainLoop,RingBufferReady,
7172012-05-18 08:12:26.225653 I TVRec(2): ClearFlags(CancelNextRecording,KillRec,) -> RunMainLoop,RingBufferReady,
7182012-05-18 08:12:26.746566 I MPEGRec(/dev/video0): Encoding stopped
7192012-05-18 08:12:26.746594 I MPEGRec(/dev/video0): StartEncoding
7202012-05-18 08:12:26.834620 I MPEGRec(/dev/video2): Encoding stopped
7212012-05-18 08:12:26.834909 E DevRdB(/dev/video2): poll error
7222012-05-18 08:12:26.834924 E DevRdB(/dev/video2): fill_ringbuffer: error state
7232012-05-18 08:12:26.854776 I DevRdB(/dev/video2): Stop() -- begin
7242012-05-18 08:12:26.854800 I DevRdB(/dev/video2): Stop() -- end
7252012-05-18 08:12:26.973169 I TVRec(3): ClearFlags(RecorderRunning,) -> RunMainLoop,RingBufferReady,
7262012-05-18 08:12:26.973238 I MPEGRec(/dev/video2): StopEncoding
7272012-05-18 08:12:26.973326 I RecBase(3:/dev/video2): SetRecording(0x0)
7282012-05-18 08:12:26.974703 I TVRec(3): FinishedRecording(1020_2012-05-18T08:12:00) good recq:<RecordingQuality overall_score="1" key="1020_2012-05-18T08:12:00" />
729
7302012-05-18 08:12:26.974831 I TVRec(3): FinishedRecording(1020_2012-05-18T08:12:00)
731 title: Paid Programming
732 in recgroup: Default status: Recording:Recorded not_dummy finished_now
7332012-05-18 08:12:26.976509 I SaveVideoProperties(0x38, 0x00)
7342012-05-18 08:12:26.979416 I Finished recording Paid Programming: channel 1020
7352012-05-18 08:12:26.979780 I TVRec(3): ClearFlags(RecorderRunning,) -> RunMainLoop,RingBufferReady,
7362012-05-18 08:12:26.979786 I TVRec(3): Tearing down RingBuffer
7372012-05-18 08:12:26.979993 I TVRec(3): ClearFlags(PENDINGACTIONS,) -> RunMainLoop,RingBufferReady,
7382012-05-18 08:12:26.981019 I TVRec(3): ClearFlags(CancelNextRecording,KillRec,) -> RunMainLoop,RingBufferReady,
7392012-05-18 08:12:26.981041 I Updating status for "Paid Programming" on cardid 3 (Recording => Recorded)
7402012-05-18 08:12:27.082496 I MPEGRec(/dev/video0): Encoding started
7412012-05-18 08:12:27.082524 I DevRdB(/dev/video0): Start() -- begin
7422012-05-18 08:12:27.082603 I DevRdB(/dev/video0): Start() -- middle
7432012-05-18 08:12:27.082614 I DevRdB(/dev/video0): Start() -- end
7442012-05-18 08:12:27.893600 E MainServer: PREVIEW_SUCCESS but no receivers.
7452012-05-18 08:12:27.894897 I MainServer::ANN Monitor
7462012-05-18 08:12:27.894902 I adding: mythserver as a client (events: 2)
7472012-05-18 08:12:27.934698 I MainServer::ANN Monitor
7482012-05-18 08:12:27.934704 I adding: mythserver as a client (events: 2)
7492012-05-18 08:12:27.935455 I TVRec(1): Changing from RecordingOnly to None
7502012-05-18 08:12:27.935472 I TVRec(1): ClearFlags(FrontendReady,CancelNextRecording,) -> RunMainLoop,RecorderRunning,RingBufferReady,
7512012-05-18 08:12:27.935484 I TVRec(1): HandleTuning Request: Program(NULL) channel() input() flags(CloseRec,KillRingBuffer,)
7522012-05-18 08:12:27.935491 I MPEGRec(/dev/video0): StopEncoding
7532012-05-18 08:12:28.996749 I Reschedule interrupted, will retry
7542012-05-18 08:12:28.997030 I Reschedule requested for id 0.
7552012-05-18 08:12:28.997178 I Reschedule requested for id 0.
7562012-05-18 08:12:28.997225 I Reschedule requested for id 0.
7572012-05-18 08:12:29.585349 E DevRdB(/dev/video0): Poll giving up 2
7582012-05-18 08:12:29.585360 E DevRdB(/dev/video0): fill_ringbuffer: error state
7592012-05-18 08:12:29.585443 E MPEGRec(/dev/video0): Device error detected
7602012-05-18 08:12:29.585447 I MPEGRec(/dev/video0): RestartEncoding
7612012-05-18 08:12:30.034589 I MPEGRec(/dev/video0): Encoding stopped
7622012-05-18 08:12:30.034659 I MPEGRec(/dev/video0): StopEncoding
7632012-05-18 08:12:30.034671 I MPEGRec(/dev/video0): StartEncoding
7642012-05-18 08:12:30.390502 I MPEGRec(/dev/video0): Encoding started
7652012-05-18 08:12:30.390530 I DevRdB(/dev/video0): Start() -- begin
7662012-05-18 08:12:30.390609 I DevRdB(/dev/video0): Start() -- middle
7672012-05-18 08:12:30.390620 I DevRdB(/dev/video0): Start() -- end
7682012-05-18 08:12:30.390648 I MPEGRec(/dev/video0): run finishing up
7692012-05-18 08:12:30.390658 I MPEGRec(/dev/video0): StopEncoding
7702012-05-18 08:12:31.689489 I Scheduled 1509 items in 2.7 = 0.00 match + 2.69 place
7712012-05-18 08:12:32.490643 I MPEGRec(/dev/video0): Encoding stopped
7722012-05-18 08:12:32.490687 E DevRdB(/dev/video0): poll error
7732012-05-18 08:12:32.490729 E DevRdB(/dev/video0): fill_ringbuffer: error state
7742012-05-18 08:12:32.510804 I DevRdB(/dev/video0): Stop() -- begin
7752012-05-18 08:12:32.510830 I DevRdB(/dev/video0): Stop() -- end
7762012-05-18 08:12:32.684105 I TVRec(1): ClearFlags(RecorderRunning,) -> RunMainLoop,RingBufferReady,
7772012-05-18 08:12:32.684174 I MPEGRec(/dev/video0): StopEncoding
7782012-05-18 08:12:32.684246 I RecBase(1:/dev/video0): SetRecording(0x0)
7792012-05-18 08:12:32.685385 I TVRec(1): FinishedRecording(1017_2012-05-18T08:11:00) good recq:<RecordingQuality overall_score="1" key="1017_2012-05-18T08:11:00" />
780
7812012-05-18 08:12:32.685503 I TVRec(1): FinishedRecording(1017_2012-05-18T08:11:00)
782 title: CBS This Morning
783 in recgroup: Default status: Recording:Recorded not_dummy finished_now
7842012-05-18 08:12:32.686896 I SaveVideoProperties(0x38, 0x00)
7852012-05-18 08:12:32.690825 I Finished recording CBS This Morning: channel 1017
7862012-05-18 08:12:32.691167 I TVRec(1): ClearFlags(RecorderRunning,) -> RunMainLoop,RingBufferReady,
7872012-05-18 08:12:32.691174 I TVRec(1): Tearing down RingBuffer
7882012-05-18 08:12:32.694039 I TVRec(1): ClearFlags(PENDINGACTIONS,) -> RunMainLoop,RingBufferReady,
7892012-05-18 08:12:32.695069 I TVRec(1): ClearFlags(CancelNextRecording,KillRec,) -> RunMainLoop,RingBufferReady,
7902012-05-18 08:12:32.695093 I Updating status for "CBS This Morning" on cardid 1 (Recording => Recorded)
7912012-05-18 08:12:32.696005 I Reschedule requested for id 0.
7922012-05-18 08:12:32.697802 W MainServer: Unknown socket closing MythSocket(0x2771010)
7932012-05-18 08:12:32.698895 E MythSocket(2771010:-1): writeStringList: Error, socket went unconnected.
794 We wrote 0 of 53 bytes with 1 errors
795 starts with: 45 BACKEND_MESSAGE[]:[]SCHEDULE_CHANGE[]:[]empty
7962012-05-18 08:12:35.383495 I Scheduled 1509 items in 2.7 = 0.00 match + 2.68 place
7972012-05-18 08:12:35.386275 I Reschedule requested for id 0.
7982012-05-18 08:12:38.693457 I Scheduled 1509 items in 3.3 = 0.00 match + 3.30 place
7992012-05-18 08:12:38.990605 N MythBackend exiting
8002012-05-18 08:12:39.008266 I Bonjour: De-registering service '_mythbackend-master._tcp.' on 'Mythbackend on mythserver'
8012012-05-18 08:12:40.935830 I TVRec(1): ClearFlags(RunMainLoop,) -> RingBufferReady,
8022012-05-18 08:12:40.936547 I TVRec(1): ClearFlags(RecorderRunning,) -> RingBufferReady,
8032012-05-18 08:12:40.936591 I TVRec(2): ClearFlags(RunMainLoop,) -> RingBufferReady,
8042012-05-18 08:12:40.937411 I TVRec(2): ClearFlags(RecorderRunning,) -> RingBufferReady,
8052012-05-18 08:12:40.937453 I TVRec(3): ClearFlags(RunMainLoop,) -> RingBufferReady,
8062012-05-18 08:12:40.938264 I TVRec(3): ClearFlags(RecorderRunning,) -> RingBufferReady,
8072012-05-18 08:12:40.938316 I Waiting for threads to exit.