Ticket #11262: backlog.3

File backlog.3, 30.2 KB (added by Saul <jaglover@…>, 8 years ago)

Backend log with -v channel,record - with poll time 5000 ms

Line 
12012-12-02 06:31:35.739881 C  mythbackend version: fixes/0.26 [v0.26.0] www.mythtv.org
22012-12-02 06:31:35.739914 C  Qt version: compile: 4.8.3, runtime: 4.8.3
32012-12-02 06:31:35.739920 N  Enabled verbose msgs:  general channel record
42012-12-02 06:31:35.739931 N  Setting Log Level to LOG_INFO
52012-12-02 06:31:35.740442 I  Added logging to the console
62012-12-02 06:31:35.741040 I  Setup Interrupt handler
72012-12-02 06:31:35.741054 I  Setup Terminated handler
82012-12-02 06:31:35.741065 I  Setup Segmentation fault handler
92012-12-02 06:31:35.741088 I  Setup Aborted handler
102012-12-02 06:31:35.741098 I  Setup Bus error handler
112012-12-02 06:31:35.741108 I  Setup Floating point exception handler
122012-12-02 06:31:35.741118 I  Setup Illegal instruction handler
132012-12-02 06:31:35.741131 I  Setup Real-time signal 0 handler
142012-12-02 06:31:35.741247 N  Using runtime prefix = /usr
152012-12-02 06:31:35.741287 N  Using configuration directory = /root/.mythtv
162012-12-02 06:31:35.741389 I  Assumed character encoding: en_US.UTF-8
172012-12-02 06:31:35.741838 N  Empty LocalHostName.
182012-12-02 06:31:35.741848 I  Using localhost value of zeus
192012-12-02 06:31:35.754763 N  Setting QT default locale to en_US
202012-12-02 06:31:35.754836 I  Current locale en_US
212012-12-02 06:31:35.754889 N  Reading locale defaults from /usr/share/mythtv//locales/en_us.xml
222012-12-02 06:31:35.763206 I  Current MythTV Schema Version (DBSchemaVer): 1307
232012-12-02 06:31:35.763893 I  Loading en_us translation for module mythfrontend
242012-12-02 06:31:35.764664 N  MythBackend: Starting up as the master server.
252012-12-02 06:31:35.769548 I  TVRec(5): Start channel: 2.
262012-12-02 06:31:35.769734 I  V4LChannel(/dev/video1): Device name 'Hauppauge WinTV-HVR2250' driver 'saa7164'.
272012-12-02 06:31:35.769758 I  V4LChannel(/dev/video1): v4l2: 1 stream io: 0 std io: 1 async io: 0 tuner 1 sliced vbi 0
282012-12-02 06:31:35.777862 I  ChannelBase(5): Input #5: 'tuner' schan(2) sourceid(1) ccid(5)
292012-12-02 06:31:35.777875 I  ChannelBase(5): Current Input #5: 'tuner'
302012-12-02 06:31:35.778436 I  Global TVFormat Setting 'NTSC'
312012-12-02 06:31:35.778480 I  V4LChannel(/dev/video1): Input #5: 'tuner' schan(2) tun() v4l1(Unknown) v4l2(NTSC)
322012-12-02 06:31:35.778496 I  V4LChannel(/dev/video1): SetFormat(Default) fmt(NTSC) input(5)
332012-12-02 06:31:35.801230 I  V4LChannel(/dev/video1): SetInputAndFormat(5, NTSC) (v4l v2) input_switch: 0 mode_switch: 1
342012-12-02 06:31:35.803830 I  V4LChannel(/dev/video1): SetFormat(NTSC) fmt(NTSC) input(5)
352012-12-02 06:31:35.804452 I  Channel(/dev/video1)::SwitchToInput(in 5, '')
362012-12-02 06:31:35.805374 I  V4LChannel(/dev/video1): SetInputAndFormat(5, NTSC) (v4l v2) input_switch: 0 mode_switch: 1
372012-12-02 06:31:35.808471 I  DTVChan(/dev/video1): SetChannelByString(2):
382012-12-02 06:31:35.809163 I  V4LChannel(/dev/video1): SetFormat(Default) fmt(NTSC) input(5)
392012-12-02 06:31:35.809185 I  Channel(/dev/video1)::Tune(2): curList[0].freq(55250)
402012-12-02 06:31:35.809194 I  V4LChannel(/dev/video1): Tune(55250000, )
412012-12-02 06:31:35.969940 I  Added logging to mythlogserver at TCP:35327
422012-12-02 06:31:36.097501 I  Channel(/dev/video1)::Tune(): Frequency is now 55250000
432012-12-02 06:31:36.097509 I  DTVChan(/dev/video1): SetChannelByString(2): success
442012-12-02 06:31:36.107715 I  TVRec(5): SetFlags(RunMainLoop,) -> RunMainLoop,
452012-12-02 06:31:36.107736 I  TVRec(5): ClearFlags(ExitPlayer,FinishRecording,) -> RunMainLoop,
462012-12-02 06:31:36.108552 I  TVRec(6): Start channel: 63.
472012-12-02 06:31:36.108621 I  V4LChannel(/dev/video2): Device name 'Hauppauge WinTV-HVR2250' driver 'saa7164'.
482012-12-02 06:31:36.108637 I  V4LChannel(/dev/video2): v4l2: 1 stream io: 0 std io: 1 async io: 0 tuner 1 sliced vbi 0
492012-12-02 06:31:36.116206 I  ChannelBase(6): Input #6: 'tuner' schan(63) sourceid(1) ccid(6)
502012-12-02 06:31:36.116217 I  ChannelBase(6): Current Input #6: 'tuner'
512012-12-02 06:31:36.116239 I  Global TVFormat Setting 'NTSC'
522012-12-02 06:31:36.116267 I  V4LChannel(/dev/video2): Input #6: 'tuner' schan(63) tun() v4l1(Unknown) v4l2(NTSC)
532012-12-02 06:31:36.116281 I  V4LChannel(/dev/video2): SetFormat(Default) fmt(NTSC) input(6)
542012-12-02 06:31:36.116964 I  V4LChannel(/dev/video2): SetInputAndFormat(6, NTSC) (v4l v2) input_switch: 0 mode_switch: 1
552012-12-02 06:31:36.120030 I  V4LChannel(/dev/video2): SetFormat(NTSC) fmt(NTSC) input(6)
562012-12-02 06:31:36.120044 I  Channel(/dev/video2)::SwitchToInput(in 6, '')
572012-12-02 06:31:36.120989 I  V4LChannel(/dev/video2): SetInputAndFormat(6, NTSC) (v4l v2) input_switch: 0 mode_switch: 1
582012-12-02 06:31:36.123773 I  DTVChan(/dev/video2): SetChannelByString(63):
592012-12-02 06:31:36.124391 I  V4LChannel(/dev/video2): SetFormat(Default) fmt(NTSC) input(6)
602012-12-02 06:31:36.124411 I  Channel(/dev/video2)::Tune(63): curList[61].freq(457250)
612012-12-02 06:31:36.124419 I  V4LChannel(/dev/video2): Tune(457250000, )
622012-12-02 06:31:36.417561 I  Channel(/dev/video2)::Tune(): Frequency is now 457250000
632012-12-02 06:31:36.417568 I  DTVChan(/dev/video2): SetChannelByString(63): success
642012-12-02 06:31:36.423096 I  TVRec(6): SetFlags(RunMainLoop,) -> RunMainLoop,
652012-12-02 06:31:36.423116 I  TVRec(6): ClearFlags(ExitPlayer,FinishRecording,) -> RunMainLoop,
662012-12-02 06:31:36.423860 I  TVRec(7): Start channel: 108-246.
672012-12-02 06:31:36.428012 I  DVBChan(7:/dev/dvb/adapter0/frontend0): Opening DVB channel
682012-12-02 06:31:36.430037 I  DVBChan(7:/dev/dvb/adapter0/frontend0): Using DVB card /dev/dvb/adapter0/frontend0, with frontend 'LG Electronics LGDT3303 VSB/QAM Frontend'.
692012-12-02 06:31:36.432170 I  ChannelBase(7): Input #7: 'DVBInput' schan(108-246) sourceid(4) ccid(7)
702012-12-02 06:31:36.432181 I  ChannelBase(7): Current Input #7: 'DVBInput'
712012-12-02 06:31:36.432416 I  DTVChan(/dev/dvb/adapter0/frontend0): SetChannelByString(108-246):
722012-12-02 06:31:36.434193 I  DVBChan(7:/dev/dvb/adapter0/frontend0): 699000000 qam_256 a auto auto a a auto a v fec: auto msys: UNDEFINED rolloff: 0.35
732012-12-02 06:31:36.434248 I  DVBChan(7:/dev/dvb/adapter0/frontend0): Old Params: 0 auto a auto auto a a auto a v fec: auto msys: UNDEFINED rolloff: 0.35
74                        DVBChan(7:/dev/dvb/adapter0/frontend0): New Params: 699000000 qam_256 a auto auto a a auto a v fec: auto msys: UNDEFINED rolloff: 0.35
752012-12-02 06:31:36.434260 I  DVBChan(7:/dev/dvb/adapter0/frontend0): Tune(): Tuning to 699000000Hz
762012-12-02 06:31:36.438194 I  DVBChan: wait_for_backend: Status:
772012-12-02 06:31:36.438203 I  DVBChan(7:/dev/dvb/adapter0/frontend0): Tune(): Frequency tuning successful.
782012-12-02 06:31:36.438212 I  DTVChan(/dev/dvb/adapter0/frontend0): SetChannelByString(108-246): success
792012-12-02 06:31:36.438224 I  DVBChan(7:/dev/dvb/adapter0/frontend0): Closing DVB channel
802012-12-02 06:31:36.438399 I  TVRec(7): SetFlags(RunMainLoop,) -> RunMainLoop,
812012-12-02 06:31:36.438415 I  TVRec(7): ClearFlags(ExitPlayer,FinishRecording,) -> RunMainLoop,
822012-12-02 06:31:36.440012 I  TVRec(8): Start channel: 106-317.
832012-12-02 06:31:36.442074 I  DVBChan(8:/dev/dvb/adapter0/frontend0): Opening DVB channel
842012-12-02 06:31:36.442086 I  DVBChan(7:/dev/dvb/adapter0/frontend0): Opening DVB channel
852012-12-02 06:31:36.444096 I  DVBChan(7:/dev/dvb/adapter0/frontend0): Using DVB card /dev/dvb/adapter0/frontend0, with frontend 'LG Electronics LGDT3303 VSB/QAM Frontend'.
862012-12-02 06:31:36.446228 I  ChannelBase(7): Input #7: 'DVBInput' schan(108-246) sourceid(4) ccid(7)
872012-12-02 06:31:36.446239 I  ChannelBase(7): Current Input #7: 'DVBInput'
882012-12-02 06:31:36.448301 I  ChannelBase(8): Input #8: 'DVBInput' schan(106-317) sourceid(4) ccid(8)
892012-12-02 06:31:36.448312 I  ChannelBase(8): Current Input #8: 'DVBInput'
902012-12-02 06:31:36.448540 I  DTVChan(/dev/dvb/adapter0/frontend0): SetChannelByString(106-317):
912012-12-02 06:31:36.449941 I  DVBChan(8:/dev/dvb/adapter0/frontend0): 687000000 qam_256 a auto auto a a auto a v fec: auto msys: UNDEFINED rolloff: 0.35
922012-12-02 06:31:36.449953 I  DVBChan(8:/dev/dvb/adapter0/frontend0): tuning on slave channel
932012-12-02 06:31:36.450000 I  DVBChan(7:/dev/dvb/adapter0/frontend0): Old Params: 699000000 qam_256 a auto auto a a auto a v fec: auto msys: UNDEFINED rolloff: 0.35
94                        DVBChan(7:/dev/dvb/adapter0/frontend0): New Params: 687000000 qam_256 a auto auto a a auto a v fec: auto msys: UNDEFINED rolloff: 0.35
952012-12-02 06:31:36.450011 I  DVBChan(7:/dev/dvb/adapter0/frontend0): Tune(): Tuning to 687000000Hz
962012-12-02 06:31:36.453929 I  DVBChan: wait_for_backend: Status:
972012-12-02 06:31:36.453938 I  DVBChan(7:/dev/dvb/adapter0/frontend0): Tune(): Frequency tuning successful.
982012-12-02 06:31:36.453945 I  DTVChan(/dev/dvb/adapter0/frontend0): SetChannelByString(106-317): success
992012-12-02 06:31:36.453955 I  DVBChan(8:/dev/dvb/adapter0/frontend0): Closing DVB channel
1002012-12-02 06:31:36.453963 I  DVBChan(7:/dev/dvb/adapter0/frontend0): Closing DVB channel
1012012-12-02 06:31:36.454133 I  TVRec(8): SetFlags(RunMainLoop,) -> RunMainLoop,
1022012-12-02 06:31:36.454149 I  TVRec(8): ClearFlags(ExitPlayer,FinishRecording,) -> RunMainLoop,
1032012-12-02 06:31:36.524965 I  Found 1 distinct programid authorities
1042012-12-02 06:31:36.525247 I  New static DB connectionSchedCon
1052012-12-02 06:31:36.528916 I  Listening on TCP 127.0.0.1:6544
1062012-12-02 06:31:36.528966 I  Listening on TCP 192.168.2.4:6544
1072012-12-02 06:31:36.531065 I  Listening on TCP [::1]:6544
1082012-12-02 06:31:36.531144 I  Listening on TCP [fe80::21d:60ff:fe40:5a17%eth0]:6544
1092012-12-02 06:31:37.454647 I  Main::Registering HttpStatus Extension
1102012-12-02 06:31:37.456288 I  Listening on TCP 127.0.0.1:6543
1112012-12-02 06:31:37.456349 I  Listening on TCP 192.168.2.4:6543
1122012-12-02 06:31:37.458908 I  Listening on TCP [::1]:6543
1132012-12-02 06:31:37.459003 I  Listening on TCP [fe80::21d:60ff:fe40:5a17%eth0]:6543
1142012-12-02 06:31:37.460670 N  AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
1152012-12-02 06:31:39.529997 I  Reschedule requested for MATCH 0 0 0 - SchedulerInit
1162012-12-02 06:31:39.597666 I  Scheduled 28 items in 0.0 = 0.01 match + 0.03 check + 0.01 place
1172012-12-02 06:31:39.611258 I  Scheduler: Seem to be woken up by USER
1182012-12-02 06:31:46.526501 I  Running housekeeping thread
1192012-12-02 06:31:48.365671 I  MainServer::ANN Monitor
1202012-12-02 06:31:48.365683 I  adding: zeus as a client (events: 0)
1212012-12-02 06:31:48.365980 I  MainServer::ANN Monitor
1222012-12-02 06:31:48.365987 I  adding: zeus as a client (events: 1)
1232012-12-02 06:31:48.383824 I  Getting next free recorder after : -1
1242012-12-02 06:31:48.383841 I  Checking card 5. Best card so far -1
1252012-12-02 06:31:48.384282 I  Checking card 6. Best card so far 5
1262012-12-02 06:31:48.384687 I  Checking card 7. Best card so far 6
1272012-12-02 06:31:48.385436 I  Checking card 8. Best card so far 6
1282012-12-02 06:31:48.386159 I  Best card is 6
1292012-12-02 06:31:48.388281 I  MainServer::ANN Playback
1302012-12-02 06:31:48.388289 I  adding: zeus as a client (events: 0)
1312012-12-02 06:31:48.394664 I  TVRec(6): Found channel (63) on current card(6).
1322012-12-02 06:31:48.395603 I  TVRec(6): Changing from None to WatchingLiveTV
1332012-12-02 06:31:48.395622 I  TVRec(6): ClearFlags(FrontendReady,CancelNextRecording,) -> RunMainLoop,
1342012-12-02 06:31:48.395639 I  TVRec(6): HandleTuning Request: Program(NULL) channel() input() flags(LiveTV,)
1352012-12-02 06:31:48.395663 I  ChannelBase(6): Looking for startchannel '63' on input 'tuner'
1362012-12-02 06:31:48.397917 I  ChannelBase(6): Found startchannel '63' on input 'tuner'
1372012-12-02 06:31:48.397993 I  TVRec(6): HW Tuner: 6->6
1382012-12-02 06:31:48.398005 I  TVRec(6): ClearFlags(PENDINGACTIONS,) -> RunMainLoop,
1392012-12-02 06:31:48.398019 I  TVRec(6): No recorder yet, calling TuningFrequency
1402012-12-02 06:31:48.398304 I  V4LChannel(/dev/video2): Device name 'Hauppauge WinTV-HVR2250' driver 'saa7164'.
1412012-12-02 06:31:48.398322 I  V4LChannel(/dev/video2): v4l2: 1 stream io: 0 std io: 1 async io: 0 tuner 1 sliced vbi 0
1422012-12-02 06:31:48.406148 I  ChannelBase(6): Input #6: 'tuner' schan(63) sourceid(1) ccid(6)
1432012-12-02 06:31:48.406160 I  ChannelBase(6): Current Input #6: 'tuner'
1442012-12-02 06:31:48.406187 I  Global TVFormat Setting 'NTSC'
1452012-12-02 06:31:48.406217 I  V4LChannel(/dev/video2): Input #6: 'tuner' schan(63) tun() v4l1(Unknown) v4l2(NTSC)
1462012-12-02 06:31:48.406230 I  V4LChannel(/dev/video2): SetFormat(Default) fmt(NTSC) input(6)
1472012-12-02 06:31:48.406240 I  Channel(/dev/video2)::SwitchToInput(in 6, '')
1482012-12-02 06:31:48.428505 I  V4LChannel(/dev/video2): SetInputAndFormat(6, NTSC) (v4l v2) input_switch: 0 mode_switch: 1
1492012-12-02 06:31:48.430753 I  DTVChan(/dev/video2): SetChannelByString(63):
1502012-12-02 06:31:48.432326 I  V4LChannel(/dev/video2): SetFormat(Default) fmt(NTSC) input(6)
1512012-12-02 06:31:48.432344 I  Channel(/dev/video2)::Tune(63): curList[61].freq(457250)
1522012-12-02 06:31:48.432353 I  V4LChannel(/dev/video2): Tune(457250000, )
1532012-12-02 06:31:48.727691 I  Channel(/dev/video2)::Tune(): Frequency is now 457250000
1542012-12-02 06:31:48.727700 I  DTVChan(/dev/video2): SetChannelByString(63): success
1552012-12-02 06:31:48.733022 I  TVRec(6): CreateLiveTVRingBuffer(63)
1562012-12-02 06:31:48.733405 I  TVRec(6): GetProgramRingBufferForLiveTV()
1572012-12-02 06:31:48.736145 N  AutoExpire: CalcParams(): Max required Free Space: 2.0 GB w/freq: 15 min
1582012-12-02 06:31:48.751562 I  TVRec(6): StartedRecording(1063_2012-12-02T12:31:48Z) fn(/home/mythtv/rec/1063_20121202123148.mpg)
1592012-12-02 06:31:48.753189 I  Chain: Appended@0 '1063_20121202123148'
1602012-12-02 06:31:48.754017 I  TVRec(6): Starting Signal Monitor
1612012-12-02 06:31:48.754033 I  TVRec(6): SetupSignalMonitor(1, 1)
1622012-12-02 06:31:48.754085 I  TVRec(6): Signal monitor successfully created
1632012-12-02 06:31:48.754264 I  TVRec(6): SetFlags(SignalMonitorRunning,) -> RunMainLoop,SignalMonitorRunning,
1642012-12-02 06:31:48.754281 I  TVRec(6): ClearFlags(WaitingForSignal,) -> RunMainLoop,SignalMonitorRunning,
1652012-12-02 06:31:48.754294 I  TVRec(6): SetFlags(WaitingForSignal,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning,
1662012-12-02 06:31:48.754307 I  TVRec(6): SetFlags(DummyRecorderRunning,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning,DummyRecorderRunning,
1672012-12-02 06:31:48.754313 I  DummyDTVRecorder -- started
1682012-12-02 06:31:48.754325 I  TVRec(6): SetFlags(RingBufferReady,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning,DummyRecorderRunning,RingBufferReady,
1692012-12-02 06:31:48.754337 I  TVRec(6): ClearFlags(NeedToStartRecorder,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning,DummyRecorderRunning,RingBufferReady,
1702012-12-02 06:31:48.754350 I  TVRec(6): SetFlags(NeedToStartRecorder,) -> RunMainLoop,WaitingForSignal,NeedToStartRecorder,SignalMonitorRunning,DummyRecorderRunning,RingBufferReady,
1712012-12-02 06:31:48.754365 I  TVRec(6): Got good signal
1722012-12-02 06:31:48.754415 I  TVRec(6): TeardownSignalMonitor() -- begin
1732012-12-02 06:31:48.804574 I  TVRec(6): TeardownSignalMonitor() -- end
1742012-12-02 06:31:48.804589 I  TVRec(6): ClearFlags(SignalMonitorRunning,) -> RunMainLoop,WaitingForSignal,NeedToStartRecorder,DummyRecorderRunning,RingBufferReady,
1752012-12-02 06:31:48.804603 I  TVRec(6): ClearFlags(WaitingForSignal,) -> RunMainLoop,NeedToStartRecorder,DummyRecorderRunning,RingBufferReady,
1762012-12-02 06:31:48.804640 I  TVRec(6): Starting Recorder
1772012-12-02 06:31:48.805021 I  TVRec(6): FinishedRecording(1063_2012-12-02T12:31:48Z)
178                        title: Brigadoon
179                        in recgroup: LiveTV status: Recording:Recorded is_dummy finished_now
1802012-12-02 06:31:48.805303 I  Chain: Updated endtime for '1063_20121202123148' to 20121202123148
1812012-12-02 06:31:48.805799 I  TVRec(6): ClearFlags(DummyRecorderRunning,) -> RunMainLoop,NeedToStartRecorder,RingBufferReady,
1822012-12-02 06:31:48.818378 I  Using profile 'Live TV' to record
1832012-12-02 06:31:48.818415 I  TVRec(6): SwitchLiveTVRingBuffer(discont 1, set_next_rec 0) curRec(1063_2012-12-02T12:31:48Z) curRec.size(0)
1842012-12-02 06:31:48.818828 I  TVRec(6): GetProgramRingBufferForLiveTV()
1852012-12-02 06:31:48.821111 N  AutoExpire: CalcParams(): Max required Free Space: 2.0 GB w/freq: 15 min
1862012-12-02 06:31:48.827048 E  RecordingInfo::InsertProgram(ProgramInfo(1063_20121202123148.mpg): channame(Turner Classic Movies) startts(Sun Dec 2 11:00:00 2012) endts(Sun Dec 2 13:00:00 2012)
187             recstartts(Sun Dec 2 12:31:48 2012) recendts(Sun Dec 2 13:00:00 2012)
188             title(Brigadoon)): recording already exists...
1892012-12-02 06:31:48.829714 I  TVRec(6): StartedRecording(1063_2012-12-02T12:31:49Z) fn(/home/mythtv/rec/1063_20121202123149.mpg)
1902012-12-02 06:31:48.831925 I  Chain: Appended@1 '1063_20121202123149'
1912012-12-02 06:31:48.832230 I  DTVRec(6): ResetForNewFile(void)
1922012-12-02 06:31:48.833034 I  RecBase(6:/dev/video2): SetRingBuffer(0x7fa338031e60) '/home/mythtv/rec/1063_20121202123149.mpg'
1932012-12-02 06:31:48.833054 I  RecBase(6:/dev/video2): SetRecording(0x7fa338040450) title(Brigadoon)
1942012-12-02 06:31:48.838857 I  TVRec(6): SetFlags(CancelNextRecording,) -> RunMainLoop,CancelNextRecording,NeedToStartRecorder,RingBufferReady,
1952012-12-02 06:31:48.838889 I  DTVRec(6): ResetForNewFile(void)
1962012-12-02 06:31:48.839808 I  V4LRec(6:/dev/video2): vbi_format  rate: 27000000
197                                  offset: 0
198                        samples_per_line: 1440
199                                  starts: 10, 274
200                                  counts: 18, 18
201                                   flags: 0x0
2022012-12-02 06:31:48.850916 I  DevRdB(/dev/video2): buffer size 9400 KB
2032012-12-02 06:31:48.850942 I  MPEGRec(/dev/video2): DRB ready
2042012-12-02 06:31:48.851046 I  MPEGRec(/dev/video2): Initial startup of recorder
2052012-12-02 06:31:48.851058 I  MPEGRec(/dev/video2): StartEncoding
2062012-12-02 06:31:48.851099 I  DevRdB(/dev/video2): Start() -- begin
2072012-12-02 06:31:48.851178 I  DevRdB(/dev/video2): Start() -- middle
2082012-12-02 06:31:48.851185 I  DevRdB(/dev/video2): Start() -- end
2092012-12-02 06:31:48.854047 I  TVRec(6): SetFlags(RecorderRunning,RingBufferReady,) -> RunMainLoop,CancelNextRecording,NeedToStartRecorder,RecorderRunning,RingBufferReady,
2102012-12-02 06:31:48.854066 I  TVRec(6): ClearFlags(NeedToStartRecorder,) -> RunMainLoop,CancelNextRecording,RecorderRunning,RingBufferReady,
2112012-12-02 06:31:49.493052 I  DTVRec(6): FindPSKeyFrames: frame rate = 29970
2122012-12-02 06:31:49.836213 I  TVRec(6): SetFlags(FrontendReady,) -> FrontendReady,RunMainLoop,CancelNextRecording,RecorderRunning,RingBufferReady,
2132012-12-02 06:31:54.756586 I  TVRec(6): StopLiveTV(void) curRec: 0x7fa338040450 pseudoRec: 0x0
2142012-12-02 06:31:54.757126 I  TVRec(6): Changing from WatchingLiveTV to None
2152012-12-02 06:31:54.757153 I  TVRec(6): ClearFlags(FrontendReady,CancelNextRecording,) -> RunMainLoop,RecorderRunning,RingBufferReady,
2162012-12-02 06:31:54.757170 I  TVRec(6): HandleTuning Request: Program(NULL) channel() input() flags(KillRec,KillRingBuffer,)
2172012-12-02 06:31:55.003889 I  MPEGRec(/dev/video2): run finishing up
2182012-12-02 06:31:55.003899 I  MPEGRec(/dev/video2): StopEncoding
2192012-12-02 06:31:55.023984 I  DevRdB(/dev/video2): Stop() -- begin
2202012-12-02 06:31:55.024218 I  DevRdB(/dev/video2): Stop() -- end
2212012-12-02 06:31:55.311559 I  TVRec(6): ClearFlags(RecorderRunning,) -> RunMainLoop,RingBufferReady,
2222012-12-02 06:31:55.311664 I  RecordingQuality() start(2012-12-02T11:00:00Z) end(2012-12-02T13:00:00Z) score(1)
2232012-12-02 06:31:55.311727 I  RecBase(6:/dev/video2): SetRecording(0x0)
2242012-12-02 06:31:55.312765 I  TVRec(6): FinishedRecording(1063_2012-12-02T12:31:49Z) good recq:<RecordingQuality overall_score="1" key="1063_2012-12-02T12:31:49Z" />
225
2262012-12-02 06:31:55.312826 I  TVRec(6): FinishedRecording(1063_2012-12-02T12:31:49Z)
227                        title: Brigadoon
228                        in recgroup: LiveTV status: Recorder Failed:Recorder Failed not_dummy finished_now
2292012-12-02 06:31:55.313103 I  Chain: Updated endtime for '1063_20121202123149' to 20121202123155
2302012-12-02 06:31:55.313736 I  SaveVideoProperties(0x38, 0x20)
2312012-12-02 06:31:55.315045 I  TVRec(6): ClearFlags(RecorderRunning,) -> RunMainLoop,RingBufferReady,
2322012-12-02 06:31:55.315057 I  TVRec(6): Tearing down RingBuffer
2332012-12-02 06:31:55.315422 I  TVRec(6): ClearFlags(PENDINGACTIONS,) -> RunMainLoop,RingBufferReady,
2342012-12-02 06:31:55.315771 I  TVRec(6): SetFlags(FrontendReady,) -> FrontendReady,RunMainLoop,RingBufferReady,
2352012-12-02 06:31:55.319013 I  Getting next free recorder after : -1
2362012-12-02 06:31:55.319023 I  Checking card 5. Best card so far -1
2372012-12-02 06:31:55.319557 I  Checking card 6. Best card so far 5
2382012-12-02 06:31:55.320007 I  Checking card 7. Best card so far 6
2392012-12-02 06:31:55.320712 I  Checking card 8. Best card so far 6
2402012-12-02 06:31:55.321402 I  Best card is 6
2412012-12-02 06:31:55.323617 I  MainServer::ANN Playback
2422012-12-02 06:31:55.323625 I  adding: zeus as a client (events: 0)
2432012-12-02 06:31:55.329488 I  TVRec(6): Found channel (63) on current card(6).
2442012-12-02 06:31:55.340415 I  TVRec(6): Changing from None to WatchingLiveTV
2452012-12-02 06:31:55.340434 I  TVRec(6): ClearFlags(FrontendReady,CancelNextRecording,) -> RunMainLoop,RingBufferReady,
2462012-12-02 06:31:55.340448 I  TVRec(6): HandleTuning Request: Program(NULL) channel() input() flags(LiveTV,)
2472012-12-02 06:31:55.340461 I  ChannelBase(6): Looking for startchannel '63' on input 'tuner'
2482012-12-02 06:31:55.342228 I  ChannelBase(6): Found startchannel '63' on input 'tuner'
2492012-12-02 06:31:55.342262 I  TVRec(6): HW Tuner: 6->6
2502012-12-02 06:31:55.342273 I  TVRec(6): ClearFlags(PENDINGACTIONS,) -> RunMainLoop,RingBufferReady,
2512012-12-02 06:31:55.342281 I  TVRec(6): No recorder yet, calling TuningFrequency
2522012-12-02 06:31:55.342551 I  V4LChannel(/dev/video2): Device name 'Hauppauge WinTV-HVR2250' driver 'saa7164'.
2532012-12-02 06:31:55.342568 I  V4LChannel(/dev/video2): v4l2: 1 stream io: 0 std io: 1 async io: 0 tuner 1 sliced vbi 0
2542012-12-02 06:31:55.350423 I  ChannelBase(6): Input #6: 'tuner' schan(63) sourceid(1) ccid(6)
2552012-12-02 06:31:55.350434 I  ChannelBase(6): Current Input #6: 'tuner'
2562012-12-02 06:31:55.350461 I  Global TVFormat Setting 'NTSC'
2572012-12-02 06:31:55.350491 I  V4LChannel(/dev/video2): Input #6: 'tuner' schan(63) tun() v4l1(Unknown) v4l2(NTSC)
2582012-12-02 06:31:55.350503 I  V4LChannel(/dev/video2): SetFormat(Default) fmt(NTSC) input(6)
2592012-12-02 06:31:55.350513 I  Channel(/dev/video2)::SwitchToInput(in 6, '')
2602012-12-02 06:31:55.352380 I  V4LChannel(/dev/video2): SetInputAndFormat(6, NTSC) (v4l v2) input_switch: 0 mode_switch: 1
2612012-12-02 06:31:55.355112 I  DTVChan(/dev/video2): SetChannelByString(63):
2622012-12-02 06:31:55.356593 I  V4LChannel(/dev/video2): SetFormat(Default) fmt(NTSC) input(6)
2632012-12-02 06:31:55.356609 I  Channel(/dev/video2)::Tune(63): curList[61].freq(457250)
2642012-12-02 06:31:55.356618 I  V4LChannel(/dev/video2): Tune(457250000, )
2652012-12-02 06:31:55.647919 I  Channel(/dev/video2)::Tune(): Frequency is now 457250000
2662012-12-02 06:31:55.647927 I  DTVChan(/dev/video2): SetChannelByString(63): success
2672012-12-02 06:31:55.654060 I  TVRec(6): CreateLiveTVRingBuffer(63)
2682012-12-02 06:31:55.654434 I  TVRec(6): GetProgramRingBufferForLiveTV()
2692012-12-02 06:31:55.656848 N  AutoExpire: CalcParams(): Max required Free Space: 2.0 GB w/freq: 15 min
2702012-12-02 06:31:55.665076 I  TVRec(6): StartedRecording(1063_2012-12-02T12:31:55Z) fn(/home/mythtv/rec/1063_20121202123155.mpg)
2712012-12-02 06:31:55.666451 I  Chain: Appended@0 '1063_20121202123155'
2722012-12-02 06:31:55.667332 I  TVRec(6): Starting Signal Monitor
2732012-12-02 06:31:55.667342 I  TVRec(6): SetupSignalMonitor(1, 1)
2742012-12-02 06:31:55.667369 I  TVRec(6): Signal monitor successfully created
2752012-12-02 06:31:55.667474 I  TVRec(6): SetFlags(SignalMonitorRunning,) -> RunMainLoop,SignalMonitorRunning,RingBufferReady,
2762012-12-02 06:31:55.667489 I  TVRec(6): ClearFlags(WaitingForSignal,) -> RunMainLoop,SignalMonitorRunning,RingBufferReady,
2772012-12-02 06:31:55.667502 I  TVRec(6): SetFlags(WaitingForSignal,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning,RingBufferReady,
2782012-12-02 06:31:55.667515 I  TVRec(6): SetFlags(DummyRecorderRunning,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning,DummyRecorderRunning,RingBufferReady,
2792012-12-02 06:31:55.667520 I  DummyDTVRecorder -- started
2802012-12-02 06:31:55.667532 I  TVRec(6): SetFlags(RingBufferReady,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning,DummyRecorderRunning,RingBufferReady,
2812012-12-02 06:31:55.667545 I  TVRec(6): ClearFlags(NeedToStartRecorder,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning,DummyRecorderRunning,RingBufferReady,
2822012-12-02 06:31:55.667558 I  TVRec(6): SetFlags(NeedToStartRecorder,) -> RunMainLoop,WaitingForSignal,NeedToStartRecorder,SignalMonitorRunning,DummyRecorderRunning,RingBufferReady,
2832012-12-02 06:31:55.667567 I  TVRec(6): Got good signal
2842012-12-02 06:31:55.667614 I  TVRec(6): TeardownSignalMonitor() -- begin
2852012-12-02 06:31:55.717661 I  TVRec(6): TeardownSignalMonitor() -- end
2862012-12-02 06:31:55.717676 I  TVRec(6): ClearFlags(SignalMonitorRunning,) -> RunMainLoop,WaitingForSignal,NeedToStartRecorder,DummyRecorderRunning,RingBufferReady,
2872012-12-02 06:31:55.717689 I  TVRec(6): ClearFlags(WaitingForSignal,) -> RunMainLoop,NeedToStartRecorder,DummyRecorderRunning,RingBufferReady,
2882012-12-02 06:31:55.717714 I  TVRec(6): Starting Recorder
2892012-12-02 06:31:55.718061 I  TVRec(6): FinishedRecording(1063_2012-12-02T12:31:55Z)
290                        title: Brigadoon
291                        in recgroup: LiveTV status: Recording:Recorded is_dummy finished_now
2922012-12-02 06:31:55.718332 I  Chain: Updated endtime for '1063_20121202123155' to 20121202123155
2932012-12-02 06:31:55.718774 I  TVRec(6): ClearFlags(DummyRecorderRunning,) -> RunMainLoop,NeedToStartRecorder,RingBufferReady,
2942012-12-02 06:31:55.731784 I  Using profile 'Live TV' to record
2952012-12-02 06:31:55.731813 I  TVRec(6): SwitchLiveTVRingBuffer(discont 1, set_next_rec 0) curRec(1063_2012-12-02T12:31:55Z) curRec.size(0)
2962012-12-02 06:31:55.732218 I  TVRec(6): GetProgramRingBufferForLiveTV()
2972012-12-02 06:31:55.734492 N  AutoExpire: CalcParams(): Max required Free Space: 2.0 GB w/freq: 15 min
2982012-12-02 06:31:55.740288 E  RecordingInfo::InsertProgram(ProgramInfo(1063_20121202123155.mpg): channame(Turner Classic Movies) startts(Sun Dec 2 11:00:00 2012) endts(Sun Dec 2 13:00:00 2012)
299             recstartts(Sun Dec 2 12:31:55 2012) recendts(Sun Dec 2 13:00:00 2012)
300             title(Brigadoon)): recording already exists...
3012012-12-02 06:31:55.743020 I  TVRec(6): StartedRecording(1063_2012-12-02T12:31:56Z) fn(/home/mythtv/rec/1063_20121202123156.mpg)
3022012-12-02 06:31:55.745181 I  Chain: Appended@1 '1063_20121202123156'
3032012-12-02 06:31:55.745408 I  DTVRec(6): ResetForNewFile(void)
3042012-12-02 06:31:55.745524 I  RecBase(6:/dev/video2): SetRingBuffer(0x7fa338019660) '/home/mythtv/rec/1063_20121202123156.mpg'
3052012-12-02 06:31:55.745538 I  RecBase(6:/dev/video2): SetRecording(0x7fa3380308a0) title(Brigadoon)
3062012-12-02 06:31:55.751984 I  TVRec(6): SetFlags(CancelNextRecording,) -> RunMainLoop,CancelNextRecording,NeedToStartRecorder,RingBufferReady,
3072012-12-02 06:31:55.752020 I  DTVRec(6): ResetForNewFile(void)
3082012-12-02 06:31:55.752906 I  V4LRec(6:/dev/video2): vbi_format  rate: 27000000
309                                  offset: 0
310                        samples_per_line: 1440
311                                  starts: 10, 274
312                                  counts: 18, 18
313                                   flags: 0x0
3142012-12-02 06:31:55.763008 I  DevRdB(/dev/video2): buffer size 9400 KB
3152012-12-02 06:31:55.763023 I  MPEGRec(/dev/video2): DRB ready
3162012-12-02 06:31:55.763092 I  MPEGRec(/dev/video2): Initial startup of recorder
3172012-12-02 06:31:55.763099 I  MPEGRec(/dev/video2): StartEncoding
3182012-12-02 06:31:55.763117 I  DevRdB(/dev/video2): Start() -- begin
3192012-12-02 06:31:55.763187 I  DevRdB(/dev/video2): Start() -- middle
3202012-12-02 06:31:55.763195 I  DevRdB(/dev/video2): Start() -- end
3212012-12-02 06:31:55.767133 I  TVRec(6): SetFlags(RecorderRunning,RingBufferReady,) -> RunMainLoop,CancelNextRecording,NeedToStartRecorder,RecorderRunning,RingBufferReady,
3222012-12-02 06:31:55.767150 I  TVRec(6): ClearFlags(NeedToStartRecorder,) -> RunMainLoop,CancelNextRecording,RecorderRunning,RingBufferReady,
3232012-12-02 06:31:56.420091 I  DTVRec(6): FindPSKeyFrames: frame rate = 29970
3242012-12-02 06:31:56.430448 I  TVRec(6): StopLiveTV(void) curRec: 0x7fa3380308a0 pseudoRec: 0x0
3252012-12-02 06:31:56.430798 I  TVRec(6): Changing from WatchingLiveTV to None
3262012-12-02 06:31:56.430818 I  TVRec(6): ClearFlags(FrontendReady,CancelNextRecording,) -> RunMainLoop,RecorderRunning,RingBufferReady,
3272012-12-02 06:31:56.430834 I  TVRec(6): HandleTuning Request: Program(NULL) channel() input() flags(KillRec,KillRingBuffer,)
3282012-12-02 06:31:56.924254 I  MPEGRec(/dev/video2): run finishing up
3292012-12-02 06:31:56.924267 I  MPEGRec(/dev/video2): StopEncoding
3302012-12-02 06:31:56.944355 I  DevRdB(/dev/video2): Stop() -- begin
3312012-12-02 06:31:56.944586 I  DevRdB(/dev/video2): Stop() -- end
3322012-12-02 06:31:57.228324 I  TVRec(6): ClearFlags(RecorderRunning,) -> RunMainLoop,RingBufferReady,
3332012-12-02 06:31:57.228414 I  RecordingQuality() start(2012-12-02T11:00:00Z) end(2012-12-02T13:00:00Z) score(1)
3342012-12-02 06:31:57.228474 I  RecBase(6:/dev/video2): SetRecording(0x0)
3352012-12-02 06:31:57.229021 I  TVRec(6): FinishedRecording(1063_2012-12-02T12:31:56Z) good recq:<RecordingQuality overall_score="1" key="1063_2012-12-02T12:31:56Z" />
336
3372012-12-02 06:31:57.229074 I  TVRec(6): FinishedRecording(1063_2012-12-02T12:31:56Z)
338                        title: Brigadoon
339                        in recgroup: LiveTV status: Recorder Failed:Recorder Failed not_dummy finished_now
3402012-12-02 06:31:57.229324 I  Chain: Updated endtime for '1063_20121202123156' to 20121202123157
3412012-12-02 06:31:57.229957 I  SaveVideoProperties(0x38, 0x20)
3422012-12-02 06:31:57.231260 I  TVRec(6): ClearFlags(RecorderRunning,) -> RunMainLoop,RingBufferReady,
3432012-12-02 06:31:57.231271 I  TVRec(6): Tearing down RingBuffer
3442012-12-02 06:31:57.231442 I  TVRec(6): ClearFlags(PENDINGACTIONS,) -> RunMainLoop,RingBufferReady,
3452012-12-02 06:32:13.996888 C  Received Interrupt: Code 128, PID 0, UID 0, Value 0x00000000
3462012-12-02 06:32:13.997772 N  MythBackend exiting
3472012-12-02 06:32:15.647060 I  TVRec(5): ClearFlags(RunMainLoop,) -> 0x0
3482012-12-02 06:32:15.647286 I  TVRec(5): ClearFlags(RecorderRunning,) -> 0x0
3492012-12-02 06:32:15.647310 I  TVRec(6): ClearFlags(RunMainLoop,) -> RingBufferReady,
3502012-12-02 06:32:15.647644 I  TVRec(6): ClearFlags(RecorderRunning,) -> RingBufferReady,
3512012-12-02 06:32:15.647678 I  TVRec(7): ClearFlags(RunMainLoop,) -> 0x0
3522012-12-02 06:32:15.647771 I  DVBChan(7:/dev/dvb/adapter0/frontend0): Closing DVB channel
3532012-12-02 06:32:15.647806 I  TVRec(7): ClearFlags(RecorderRunning,) -> 0x0
3542012-12-02 06:32:15.647823 I  TVRec(8): ClearFlags(RunMainLoop,) -> 0x0
3552012-12-02 06:32:15.647876 I  DVBChan(8:/dev/dvb/adapter0/frontend0): Closing DVB channel
3562012-12-02 06:32:15.647908 I  TVRec(8): ClearFlags(RecorderRunning,) -> 0x0
3572012-12-02 06:32:15.647932 I  Waiting for threads to exit.