Ticket #11262: backlog.2

File backlog.2, 88.3 KB (added by jaglover@…, 11 years ago)

Backend log with -v channel,record

Line 
12012-12-01 18:16:08.735453 C  mythbackend version: fixes/0.26 [v0.26.0] www.mythtv.org
22012-12-01 18:16:08.735500 C  Qt version: compile: 4.8.3, runtime: 4.8.3
32012-12-01 18:16:08.735509 N  Enabled verbose msgs:  general channel record
42012-12-01 18:16:08.735524 N  Setting Log Level to LOG_INFO
52012-12-01 18:16:08.736111 I  Added logging to the console
62012-12-01 18:16:08.737112 I  Setup Interrupt handler
72012-12-01 18:16:08.737126 I  Setup Terminated handler
82012-12-01 18:16:08.737136 I  Setup Segmentation fault handler
92012-12-01 18:16:08.737145 I  Setup Aborted handler
102012-12-01 18:16:08.737154 I  Setup Bus error handler
112012-12-01 18:16:08.737163 I  Setup Floating point exception handler
122012-12-01 18:16:08.737173 I  Setup Illegal instruction handler
132012-12-01 18:16:08.737185 I  Setup Real-time signal 0 handler
142012-12-01 18:16:08.737939 N  Using runtime prefix = /usr
152012-12-01 18:16:08.737962 N  Using configuration directory = /root/.mythtv
162012-12-01 18:16:08.738151 I  Assumed character encoding: en_US.UTF-8
172012-12-01 18:16:08.741664 N  Empty LocalHostName.
182012-12-01 18:16:08.741675 I  Using localhost value of zeus
192012-12-01 18:16:08.789383 N  Setting QT default locale to en_US
202012-12-01 18:16:08.789476 I  Current locale en_US
212012-12-01 18:16:08.793270 N  Reading locale defaults from /usr/share/mythtv//locales/en_us.xml
222012-12-01 18:16:08.816717 I  Current MythTV Schema Version (DBSchemaVer): 1307
232012-12-01 18:16:08.817521 I  Loading en_us translation for module mythfrontend
242012-12-01 18:16:08.818200 N  MythBackend: Starting up as the master server.
252012-12-01 18:16:08.832400 I  TVRec(5): Start channel: 2.
262012-12-01 18:16:08.832604 I  V4LChannel(/dev/video1): Device name 'Hauppauge WinTV-HVR2250' driver 'saa7164'.
272012-12-01 18:16:08.832628 I  V4LChannel(/dev/video1): v4l2: 1 stream io: 0 std io: 1 async io: 0 tuner 1 sliced vbi 0
282012-12-01 18:16:08.840772 I  ChannelBase(5): Input #5: 'tuner' schan(2) sourceid(1) ccid(5)
292012-12-01 18:16:08.840783 I  ChannelBase(5): Current Input #5: 'tuner'
302012-12-01 18:16:08.841348 I  Global TVFormat Setting 'NTSC'
312012-12-01 18:16:08.841393 I  V4LChannel(/dev/video1): Input #5: 'tuner' schan(2) tun() v4l1(Unknown) v4l2(NTSC)
322012-12-01 18:16:08.841427 I  V4LChannel(/dev/video1): SetFormat(Default) fmt(NTSC) input(5)
332012-12-01 18:16:08.862247 I  V4LChannel(/dev/video1): SetInputAndFormat(5, NTSC) (v4l v2) input_switch: 0 mode_switch: 1
342012-12-01 18:16:08.864998 I  V4LChannel(/dev/video1): SetFormat(NTSC) fmt(NTSC) input(5)
352012-12-01 18:16:08.865618 I  Channel(/dev/video1)::SwitchToInput(in 5, '')
362012-12-01 18:16:08.866550 I  V4LChannel(/dev/video1): SetInputAndFormat(5, NTSC) (v4l v2) input_switch: 0 mode_switch: 1
372012-12-01 18:16:08.869474 I  DTVChan(/dev/video1): SetChannelByString(2):
382012-12-01 18:16:08.870164 I  V4LChannel(/dev/video1): SetFormat(Default) fmt(NTSC) input(5)
392012-12-01 18:16:08.870187 I  Channel(/dev/video1)::Tune(2): curList[0].freq(55250)
402012-12-01 18:16:08.870196 I  V4LChannel(/dev/video1): Tune(55250000, )
412012-12-01 18:16:08.964582 I  Added logging to mythlogserver at TCP:35327
422012-12-01 18:16:09.160153 I  Channel(/dev/video1)::Tune(): Frequency is now 55250000
432012-12-01 18:16:09.160163 I  DTVChan(/dev/video1): SetChannelByString(2): success
442012-12-01 18:16:09.171219 I  TVRec(5): SetFlags(RunMainLoop,) -> RunMainLoop,
452012-12-01 18:16:09.171238 I  TVRec(5): ClearFlags(ExitPlayer,FinishRecording,) -> RunMainLoop,
462012-12-01 18:16:09.172107 I  TVRec(6): Start channel: 57.
472012-12-01 18:16:09.172177 I  V4LChannel(/dev/video2): Device name 'Hauppauge WinTV-HVR2250' driver 'saa7164'.
482012-12-01 18:16:09.172194 I  V4LChannel(/dev/video2): v4l2: 1 stream io: 0 std io: 1 async io: 0 tuner 1 sliced vbi 0
492012-12-01 18:16:09.179743 I  ChannelBase(6): Input #6: 'tuner' schan(57) sourceid(1) ccid(6)
502012-12-01 18:16:09.179754 I  ChannelBase(6): Current Input #6: 'tuner'
512012-12-01 18:16:09.179777 I  Global TVFormat Setting 'NTSC'
522012-12-01 18:16:09.179807 I  V4LChannel(/dev/video2): Input #6: 'tuner' schan(57) tun() v4l1(Unknown) v4l2(NTSC)
532012-12-01 18:16:09.179820 I  V4LChannel(/dev/video2): SetFormat(Default) fmt(NTSC) input(6)
542012-12-01 18:16:09.180590 I  V4LChannel(/dev/video2): SetInputAndFormat(6, NTSC) (v4l v2) input_switch: 0 mode_switch: 1
552012-12-01 18:16:09.183773 I  V4LChannel(/dev/video2): SetFormat(NTSC) fmt(NTSC) input(6)
562012-12-01 18:16:09.183787 I  Channel(/dev/video2)::SwitchToInput(in 6, '')
572012-12-01 18:16:09.184734 I  V4LChannel(/dev/video2): SetInputAndFormat(6, NTSC) (v4l v2) input_switch: 0 mode_switch: 1
582012-12-01 18:16:09.187397 I  DTVChan(/dev/video2): SetChannelByString(57):
592012-12-01 18:16:09.188025 I  V4LChannel(/dev/video2): SetFormat(Default) fmt(NTSC) input(6)
602012-12-01 18:16:09.188045 I  Channel(/dev/video2)::Tune(57): curList[55].freq(421250)
612012-12-01 18:16:09.188054 I  V4LChannel(/dev/video2): Tune(421250000, )
622012-12-01 18:16:09.480695 I  Channel(/dev/video2)::Tune(): Frequency is now 421250000
632012-12-01 18:16:09.480704 I  DTVChan(/dev/video2): SetChannelByString(57): success
642012-12-01 18:16:09.486914 I  TVRec(6): SetFlags(RunMainLoop,) -> RunMainLoop,
652012-12-01 18:16:09.486935 I  TVRec(6): ClearFlags(ExitPlayer,FinishRecording,) -> RunMainLoop,
662012-12-01 18:16:09.487680 I  TVRec(7): Start channel: 106-319.
672012-12-01 18:16:09.491853 I  DVBChan(7:/dev/dvb/adapter0/frontend0): Opening DVB channel
682012-12-01 18:16:09.493856 I  DVBChan(7:/dev/dvb/adapter0/frontend0): Using DVB card /dev/dvb/adapter0/frontend0, with frontend 'LG Electronics LGDT3303 VSB/QAM Frontend'.
692012-12-01 18:16:09.495334 I  ChannelBase(7): Input #7: 'DVBInput' schan(106-319) sourceid(4) ccid(7)
702012-12-01 18:16:09.495341 I  ChannelBase(7): Current Input #7: 'DVBInput'
712012-12-01 18:16:09.495501 I  DTVChan(/dev/dvb/adapter0/frontend0): SetChannelByString(106-319):
722012-12-01 18:16:09.511344 I  DVBChan(7:/dev/dvb/adapter0/frontend0): 687000000 qam_256 a auto auto a a auto a v fec: auto msys: UNDEFINED rolloff: 0.35
732012-12-01 18:16:09.511384 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: 687000000 qam_256 a auto auto a a auto a v fec: auto msys: UNDEFINED rolloff: 0.35
752012-12-01 18:16:09.511392 I  DVBChan(7:/dev/dvb/adapter0/frontend0): Tune(): Tuning to 687000000Hz
762012-12-01 18:16:09.515305 I  DVBChan: wait_for_backend: Status:
772012-12-01 18:16:09.515311 I  DVBChan(7:/dev/dvb/adapter0/frontend0): Tune(): Frequency tuning successful.
782012-12-01 18:16:09.515317 I  DTVChan(/dev/dvb/adapter0/frontend0): SetChannelByString(106-319): success
792012-12-01 18:16:09.515326 I  DVBChan(7:/dev/dvb/adapter0/frontend0): Closing DVB channel
802012-12-01 18:16:09.515523 I  TVRec(7): SetFlags(RunMainLoop,) -> RunMainLoop,
812012-12-01 18:16:09.515539 I  TVRec(7): ClearFlags(ExitPlayer,FinishRecording,) -> RunMainLoop,
822012-12-01 18:16:09.517892 I  TVRec(8): Start channel: 106-317.
832012-12-01 18:16:09.520223 I  DVBChan(8:/dev/dvb/adapter0/frontend0): Opening DVB channel
842012-12-01 18:16:09.520232 I  DVBChan(7:/dev/dvb/adapter0/frontend0): Opening DVB channel
852012-12-01 18:16:09.522294 I  DVBChan(7:/dev/dvb/adapter0/frontend0): Using DVB card /dev/dvb/adapter0/frontend0, with frontend 'LG Electronics LGDT3303 VSB/QAM Frontend'.
862012-12-01 18:16:09.523908 I  ChannelBase(7): Input #7: 'DVBInput' schan(106-319) sourceid(4) ccid(7)
872012-12-01 18:16:09.523916 I  ChannelBase(7): Current Input #7: 'DVBInput'
882012-12-01 18:16:09.525321 I  ChannelBase(8): Input #8: 'DVBInput' schan(106-317) sourceid(4) ccid(8)
892012-12-01 18:16:09.525328 I  ChannelBase(8): Current Input #8: 'DVBInput'
902012-12-01 18:16:09.525483 I  DTVChan(/dev/dvb/adapter0/frontend0): SetChannelByString(106-317):
912012-12-01 18:16:09.526467 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-01 18:16:09.526476 I  DVBChan(8:/dev/dvb/adapter0/frontend0): tuning on slave channel
932012-12-01 18:16:09.526511 I  DVBChan(7:/dev/dvb/adapter0/frontend0): Old Params: 687000000 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-01 18:16:09.526523 I  DVBChan(7:/dev/dvb/adapter0/frontend0): Tune(): Tuning to 687000000Hz
962012-12-01 18:16:09.530402 I  DVBChan: wait_for_backend: Status:
972012-12-01 18:16:09.530408 I  DVBChan(7:/dev/dvb/adapter0/frontend0): Tune(): Frequency tuning successful.
982012-12-01 18:16:09.530413 I  DTVChan(/dev/dvb/adapter0/frontend0): SetChannelByString(106-317): success
992012-12-01 18:16:09.530420 I  DVBChan(8:/dev/dvb/adapter0/frontend0): Closing DVB channel
1002012-12-01 18:16:09.530426 I  DVBChan(7:/dev/dvb/adapter0/frontend0): Closing DVB channel
1012012-12-01 18:16:09.530629 I  TVRec(8): SetFlags(RunMainLoop,) -> RunMainLoop,
1022012-12-01 18:16:09.530647 I  TVRec(8): ClearFlags(ExitPlayer,FinishRecording,) -> RunMainLoop,
1032012-12-01 18:16:09.599666 I  Found 1 distinct programid authorities
1042012-12-01 18:16:09.601005 I  New static DB connectionSchedCon
1052012-12-01 18:16:09.624932 I  Listening on TCP 127.0.0.1:6544
1062012-12-01 18:16:09.624984 I  Listening on TCP 192.168.2.4:6544
1072012-12-01 18:16:09.638980 I  Listening on TCP [::1]:6544
1082012-12-01 18:16:09.639103 I  Listening on TCP [fe80::21d:60ff:fe40:5a17%eth0]:6544
1092012-12-01 18:16:10.821160 I  Main::Registering HttpStatus Extension
1102012-12-01 18:16:10.822856 I  Listening on TCP 127.0.0.1:6543
1112012-12-01 18:16:10.822920 I  Listening on TCP 192.168.2.4:6543
1122012-12-01 18:16:10.825482 I  Listening on TCP [::1]:6543
1132012-12-01 18:16:10.825570 I  Listening on TCP [fe80::21d:60ff:fe40:5a17%eth0]:6543
1142012-12-01 18:16:10.829566 N  AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
1152012-12-01 18:16:12.647134 I  Reschedule requested for MATCH 0 0 0 - SchedulerInit
1162012-12-01 18:16:12.841187 I  Scheduled 28 items in 0.2 = 0.10 match + 0.05 check + 0.02 place
1172012-12-01 18:16:12.854909 I  Scheduler: Seem to be woken up by USER
1182012-12-01 18:16:19.235410 I  MainServer::ANN Monitor
1192012-12-01 18:16:19.235421 I  adding: zeus as a client (events: 0)
1202012-12-01 18:16:19.235724 I  MainServer::ANN Monitor
1212012-12-01 18:16:19.235731 I  adding: zeus as a client (events: 1)
1222012-12-01 18:16:19.315609 I  Getting next free recorder after : -1
1232012-12-01 18:16:19.315625 I  Checking card 5. Best card so far -1
1242012-12-01 18:16:19.316108 I  Checking card 6. Best card so far 5
1252012-12-01 18:16:19.316527 I  Checking card 7. Best card so far 6
1262012-12-01 18:16:19.317294 I  Checking card 8. Best card so far 6
1272012-12-01 18:16:19.318049 I  Best card is 6
1282012-12-01 18:16:19.320374 I  MainServer::ANN Playback
1292012-12-01 18:16:19.320382 I  adding: zeus as a client (events: 0)
1302012-12-01 18:16:19.327514 I  TVRec(6): Found channel (57) on current card(6).
1312012-12-01 18:16:19.338765 I  TVRec(6): Changing from None to WatchingLiveTV
1322012-12-01 18:16:19.338786 I  TVRec(6): ClearFlags(FrontendReady,CancelNextRecording,) -> RunMainLoop,
1332012-12-01 18:16:19.338805 I  TVRec(6): HandleTuning Request: Program(NULL) channel() input() flags(LiveTV,)
1342012-12-01 18:16:19.338831 I  ChannelBase(6): Looking for startchannel '57' on input 'tuner'
1352012-12-01 18:16:19.341026 I  ChannelBase(6): Found startchannel '57' on input 'tuner'
1362012-12-01 18:16:19.341099 I  TVRec(6): HW Tuner: 6->6
1372012-12-01 18:16:19.341111 I  TVRec(6): ClearFlags(PENDINGACTIONS,) -> RunMainLoop,
1382012-12-01 18:16:19.341124 I  TVRec(6): No recorder yet, calling TuningFrequency
1392012-12-01 18:16:19.341406 I  V4LChannel(/dev/video2): Device name 'Hauppauge WinTV-HVR2250' driver 'saa7164'.
1402012-12-01 18:16:19.341433 I  V4LChannel(/dev/video2): v4l2: 1 stream io: 0 std io: 1 async io: 0 tuner 1 sliced vbi 0
1412012-12-01 18:16:19.349425 I  ChannelBase(6): Input #6: 'tuner' schan(57) sourceid(1) ccid(6)
1422012-12-01 18:16:19.349436 I  ChannelBase(6): Current Input #6: 'tuner'
1432012-12-01 18:16:19.349461 I  Global TVFormat Setting 'NTSC'
1442012-12-01 18:16:19.349491 I  V4LChannel(/dev/video2): Input #6: 'tuner' schan(57) tun() v4l1(Unknown) v4l2(NTSC)
1452012-12-01 18:16:19.349505 I  V4LChannel(/dev/video2): SetFormat(Default) fmt(NTSC) input(6)
1462012-12-01 18:16:19.349515 I  Channel(/dev/video2)::SwitchToInput(in 6, '')
1472012-12-01 18:16:19.351573 I  V4LChannel(/dev/video2): SetInputAndFormat(6, NTSC) (v4l v2) input_switch: 0 mode_switch: 1
1482012-12-01 18:16:19.354183 I  DTVChan(/dev/video2): SetChannelByString(57):
1492012-12-01 18:16:19.355770 I  V4LChannel(/dev/video2): SetFormat(Default) fmt(NTSC) input(6)
1502012-12-01 18:16:19.355787 I  Channel(/dev/video2)::Tune(57): curList[55].freq(421250)
1512012-12-01 18:16:19.355796 I  V4LChannel(/dev/video2): Tune(421250000, )
1522012-12-01 18:16:19.601047 I  Running housekeeping thread
1532012-12-01 18:16:19.650499 I  Channel(/dev/video2)::Tune(): Frequency is now 421250000
1542012-12-01 18:16:19.650511 I  DTVChan(/dev/video2): SetChannelByString(57): success
1552012-12-01 18:16:19.655927 I  TVRec(6): CreateLiveTVRingBuffer(57)
1562012-12-01 18:16:19.656334 I  TVRec(6): GetProgramRingBufferForLiveTV()
1572012-12-01 18:16:19.659438 N  AutoExpire: CalcParams(): Max required Free Space: 2.0 GB w/freq: 15 min
1582012-12-01 18:16:19.685868 I  TVRec(6): StartedRecording(1057_2012-12-02T00:16:19Z) fn(/home/mythtv/rec/1057_20121202001619.mpg)
1592012-12-01 18:16:19.687469 I  Chain: Appended@0 '1057_20121202001619'
1602012-12-01 18:16:19.688369 I  TVRec(6): Starting Signal Monitor
1612012-12-01 18:16:19.688387 I  TVRec(6): SetupSignalMonitor(1, 1)
1622012-12-01 18:16:19.688439 I  TVRec(6): Signal monitor successfully created
1632012-12-01 18:16:19.688601 I  TVRec(6): SetFlags(SignalMonitorRunning,) -> RunMainLoop,SignalMonitorRunning,
1642012-12-01 18:16:19.688617 I  TVRec(6): ClearFlags(WaitingForSignal,) -> RunMainLoop,SignalMonitorRunning,
1652012-12-01 18:16:19.688630 I  TVRec(6): SetFlags(WaitingForSignal,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning,
1662012-12-01 18:16:19.688643 I  TVRec(6): SetFlags(DummyRecorderRunning,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning,DummyRecorderRunning,
1672012-12-01 18:16:19.688649 I  DummyDTVRecorder -- started
1682012-12-01 18:16:19.688661 I  TVRec(6): SetFlags(RingBufferReady,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning,DummyRecorderRunning,RingBufferReady,
1692012-12-01 18:16:19.688674 I  TVRec(6): ClearFlags(NeedToStartRecorder,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning,DummyRecorderRunning,RingBufferReady,
1702012-12-01 18:16:19.688687 I  TVRec(6): SetFlags(NeedToStartRecorder,) -> RunMainLoop,WaitingForSignal,NeedToStartRecorder,SignalMonitorRunning,DummyRecorderRunning,RingBufferReady,
1712012-12-01 18:16:19.688703 I  TVRec(6): Got good signal
1722012-12-01 18:16:19.688831 I  TVRec(6): TeardownSignalMonitor() -- begin
1732012-12-01 18:16:19.738890 I  TVRec(6): TeardownSignalMonitor() -- end
1742012-12-01 18:16:19.738910 I  TVRec(6): ClearFlags(SignalMonitorRunning,) -> RunMainLoop,WaitingForSignal,NeedToStartRecorder,DummyRecorderRunning,RingBufferReady,
1752012-12-01 18:16:19.738924 I  TVRec(6): ClearFlags(WaitingForSignal,) -> RunMainLoop,NeedToStartRecorder,DummyRecorderRunning,RingBufferReady,
1762012-12-01 18:16:19.738968 I  TVRec(6): Starting Recorder
1772012-12-01 18:16:19.739471 I  TVRec(6): FinishedRecording(1057_2012-12-02T00:16:19Z)
178                        title: Fixing Pete
179                        in recgroup: LiveTV status: Recording:Recorded is_dummy finished_now
1802012-12-01 18:16:19.739786 I  Chain: Updated endtime for '1057_20121202001619' to 20121202001619
1812012-12-01 18:16:19.740226 I  TVRec(6): ClearFlags(DummyRecorderRunning,) -> RunMainLoop,NeedToStartRecorder,RingBufferReady,
1822012-12-01 18:16:19.752886 I  Using profile 'Live TV' to record
1832012-12-01 18:16:19.752924 I  TVRec(6): SwitchLiveTVRingBuffer(discont 1, set_next_rec 0) curRec(1057_2012-12-02T00:16:19Z) curRec.size(0)
1842012-12-01 18:16:19.753352 I  TVRec(6): GetProgramRingBufferForLiveTV()
1852012-12-01 18:16:19.755720 N  AutoExpire: CalcParams(): Max required Free Space: 2.0 GB w/freq: 15 min
1862012-12-01 18:16:19.761858 E  RecordingInfo::InsertProgram(ProgramInfo(1057_20121202001619.mpg): channame(Hallmark Movie Channel HD) startts(Sat Dec 1 23:00:00 2012) endts(Sun Dec 2 01:00:00 2012)
187             recstartts(Sun Dec 2 00:16:19 2012) recendts(Sun Dec 2 01:00:00 2012)
188             title(Fixing Pete)): recording already exists...
1892012-12-01 18:16:19.764493 I  TVRec(6): StartedRecording(1057_2012-12-02T00:16:20Z) fn(/home/mythtv/rec/1057_20121202001620.mpg)
1902012-12-01 18:16:19.766615 I  Chain: Appended@1 '1057_20121202001620'
1912012-12-01 18:16:19.766902 I  DTVRec(6): ResetForNewFile(void)
1922012-12-01 18:16:19.767691 I  RecBase(6:/dev/video2): SetRingBuffer(0x7f414001f6a0) '/home/mythtv/rec/1057_20121202001620.mpg'
1932012-12-01 18:16:19.767711 I  RecBase(6:/dev/video2): SetRecording(0x7f414003fbe0) title(Fixing Pete)
1942012-12-01 18:16:19.773538 I  TVRec(6): SetFlags(CancelNextRecording,) -> RunMainLoop,CancelNextRecording,NeedToStartRecorder,RingBufferReady,
1952012-12-01 18:16:19.773552 I  DTVRec(6): ResetForNewFile(void)
1962012-12-01 18:16:19.776352 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-01 18:16:19.787529 I  DevRdB(/dev/video2): buffer size 9400 KB
2032012-12-01 18:16:19.787555 I  MPEGRec(/dev/video2): DRB ready
2042012-12-01 18:16:19.787659 I  MPEGRec(/dev/video2): Initial startup of recorder
2052012-12-01 18:16:19.787669 I  MPEGRec(/dev/video2): StartEncoding
2062012-12-01 18:16:19.787700 I  DevRdB(/dev/video2): Start() -- begin
2072012-12-01 18:16:19.787791 I  DevRdB(/dev/video2): Start() -- middle
2082012-12-01 18:16:19.787798 I  DevRdB(/dev/video2): Start() -- end
2092012-12-01 18:16:19.788709 I  TVRec(6): SetFlags(RecorderRunning,RingBufferReady,) -> RunMainLoop,CancelNextRecording,NeedToStartRecorder,RecorderRunning,RingBufferReady,
2102012-12-01 18:16:19.788727 I  TVRec(6): ClearFlags(NeedToStartRecorder,) -> RunMainLoop,CancelNextRecording,RecorderRunning,RingBufferReady,
2112012-12-01 18:16:20.454789 I  DTVRec(6): FindPSKeyFrames: frame rate = 29970
2122012-12-01 18:16:20.759361 I  TVRec(6): SetFlags(FrontendReady,) -> FrontendReady,RunMainLoop,CancelNextRecording,RecorderRunning,RingBufferReady,
2132012-12-01 18:16:23.918275 I  RecBase(6:/dev/video2): GetKeyframePositions(76,9223372036854775807,#0) out of 5
2142012-12-01 18:16:25.445409 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
2152012-12-01 18:16:27.952685 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
2162012-12-01 18:16:30.460370 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
2172012-12-01 18:16:35.473317 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
2182012-12-01 18:16:37.980715 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
2192012-12-01 18:16:42.991446 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
2202012-12-01 18:16:45.497675 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
2212012-12-01 18:16:48.005021 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
2222012-12-01 18:16:49.685947 I  TVRec(6): StopLiveTV(void) curRec: 0x7f414003fbe0 pseudoRec: 0x0
2232012-12-01 18:16:49.696576 I  TVRec(6): Changing from WatchingLiveTV to None
2242012-12-01 18:16:49.696602 I  TVRec(6): ClearFlags(FrontendReady,CancelNextRecording,) -> RunMainLoop,RecorderRunning,RingBufferReady,
2252012-12-01 18:16:49.696620 I  TVRec(6): HandleTuning Request: Program(NULL) channel() input() flags(KillRec,KillRingBuffer,)
2262012-12-01 18:16:50.025273 I  MPEGRec(/dev/video2): run finishing up
2272012-12-01 18:16:50.025285 I  MPEGRec(/dev/video2): StopEncoding
2282012-12-01 18:16:50.045361 I  DevRdB(/dev/video2): Stop() -- begin
2292012-12-01 18:16:50.045629 I  DevRdB(/dev/video2): Stop() -- end
2302012-12-01 18:16:50.337811 I  TVRec(6): ClearFlags(RecorderRunning,) -> RunMainLoop,RingBufferReady,
2312012-12-01 18:16:50.337929 I  RecordingQuality() start(2012-12-01T23:00:00Z) end(2012-12-02T01:00:00Z) score(1)
2322012-12-01 18:16:50.337991 I  RecBase(6:/dev/video2): SetRecording(0x0)
2332012-12-01 18:16:50.339361 I  TVRec(6): FinishedRecording(1057_2012-12-02T00:16:20Z) good recq:<RecordingQuality overall_score="1" key="1057_2012-12-02T00:16:20Z" />
234
2352012-12-01 18:16:50.339427 I  TVRec(6): FinishedRecording(1057_2012-12-02T00:16:20Z)
236                        title: Fixing Pete
237                        in recgroup: LiveTV status: Recorder Failed:Recorder Failed not_dummy finished_now
2382012-12-01 18:16:50.339752 I  Chain: Updated endtime for '1057_20121202001620' to 20121202001650
2392012-12-01 18:16:50.340407 I  SaveVideoProperties(0x38, 0x20)
2402012-12-01 18:16:50.341804 I  TVRec(6): ClearFlags(RecorderRunning,) -> RunMainLoop,RingBufferReady,
2412012-12-01 18:16:50.341816 I  TVRec(6): Tearing down RingBuffer
2422012-12-01 18:16:50.342010 I  TVRec(6): ClearFlags(PENDINGACTIONS,) -> RunMainLoop,RingBufferReady,
2432012-12-01 18:16:50.345100 I  MainServer::ANN Playback
2442012-12-01 18:16:50.345109 I  adding: zeus as a client (events: 0)
2452012-12-01 18:16:50.356247 I  TVRec(7): Changing from None to WatchingLiveTV
2462012-12-01 18:16:50.356264 I  TVRec(7): ClearFlags(FrontendReady,CancelNextRecording,) -> RunMainLoop,
2472012-12-01 18:16:50.356280 I  TVRec(7): HandleTuning Request: Program(NULL) channel() input() flags(LiveTV,)
2482012-12-01 18:16:50.356295 I  ChannelBase(7): Looking for startchannel '108-270' on input 'DVBInput'
2492012-12-01 18:16:50.358623 I  ChannelBase(7): Found startchannel '108-270' on input 'DVBInput'
2502012-12-01 18:16:50.358640 I  TVRec(7): HW Tuner: 7->7
2512012-12-01 18:16:50.358650 I  TVRec(7): ClearFlags(PENDINGACTIONS,) -> RunMainLoop,
2522012-12-01 18:16:50.358659 I  TVRec(7): No recorder yet, calling TuningFrequency
2532012-12-01 18:16:50.358887 I  DVBChan(7:/dev/dvb/adapter0/frontend0): Opening DVB channel
2542012-12-01 18:16:50.360949 I  DVBChan(7:/dev/dvb/adapter0/frontend0): Using DVB card /dev/dvb/adapter0/frontend0, with frontend 'LG Electronics LGDT3303 VSB/QAM Frontend'.
2552012-12-01 18:16:50.363200 I  ChannelBase(7): Input #7: 'DVBInput' schan(108-270) sourceid(4) ccid(7)
2562012-12-01 18:16:50.363211 I  ChannelBase(7): Current Input #7: 'DVBInput'
2572012-12-01 18:16:50.363240 I  DTVChan(/dev/dvb/adapter0/frontend0): SetChannelByString(108-270):
2582012-12-01 18:16:50.365679 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
2592012-12-01 18:16:50.365736 I  DVBChan(7:/dev/dvb/adapter0/frontend0): Old Params: 687000000 qam_256 a auto auto a a auto a v fec: auto msys: UNDEFINED rolloff: 0.35
260                        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
2612012-12-01 18:16:50.365748 I  DVBChan(7:/dev/dvb/adapter0/frontend0): Tune(): Tuning to 699000000Hz
2622012-12-01 18:16:50.369677 I  DVBChan: wait_for_backend: Status:
2632012-12-01 18:16:50.369686 I  DVBChan(7:/dev/dvb/adapter0/frontend0): Tune(): Frequency tuning successful.
2642012-12-01 18:16:50.369692 I  DTVChan(/dev/dvb/adapter0/frontend0): SetChannelByString(108-270): success
2652012-12-01 18:16:50.369704 I  TVRec(7): CreateLiveTVRingBuffer(108-270)
2662012-12-01 18:16:50.370091 I  TVRec(7): GetProgramRingBufferForLiveTV()
2672012-12-01 18:16:50.372614 N  AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 14 min
2682012-12-01 18:16:50.402244 I  TVRec(7): StartedRecording(5350_2012-12-02T00:16:50Z) fn(/home/mythtv/rec/5350_20121202001650.mpg)
2692012-12-01 18:16:50.403905 I  Chain: Appended@2 '5350_20121202001650'
2702012-12-01 18:16:50.404971 I  TVRec(7): Starting Signal Monitor
2712012-12-01 18:16:50.404983 I  TVRec(7): SetupSignalMonitor(1, 1)
2722012-12-01 18:16:50.404994 I  DVBChan(7:/dev/dvb/adapter0/frontend0): Opening DVB channel
2732012-12-01 18:16:50.407258 I  DVBSM(/dev/dvb/adapter0/frontend0): Can measure Signal Strength
2742012-12-01 18:16:50.408095 I  DVBSM(/dev/dvb/adapter0/frontend0): Can measure S/N
2752012-12-01 18:16:50.408105 I  DVBSM(/dev/dvb/adapter0/frontend0): Can measure Bit Error Rate
2762012-12-01 18:16:50.408927 I  DVBSM(/dev/dvb/adapter0/frontend0): Can count Uncorrected Blocks
2772012-12-01 18:16:50.408944 I  DVBSM(/dev/dvb/adapter0/frontend0): DVBSignalMonitor::ctor initial flags Seen() Match() Wait(Sig,SNR,BER,UB,)
2782012-12-01 18:16:50.408981 I  TVRec(7): Signal monitor successfully created
2792012-12-01 18:16:50.408997 I  TVRec(7): Setting up table monitoring.
2802012-12-01 18:16:50.410760 I  Using profile 'Live TV' to record
2812012-12-01 18:16:50.410789 I  TVRec(7): MPEG program number: 270
2822012-12-01 18:16:50.410820 I  DTVSM(/dev/dvb/adapter0/frontend0)::SetProgramNumber(270):
2832012-12-01 18:16:50.410874 I  TVRec(7): Successfully set up MPEG table monitoring.
2842012-12-01 18:16:50.411076 I  TVRec(7): SetFlags(SignalMonitorRunning,) -> RunMainLoop,SignalMonitorRunning,
2852012-12-01 18:16:50.411092 I  TVRec(7): ClearFlags(WaitingForSignal,) -> RunMainLoop,SignalMonitorRunning,
2862012-12-01 18:16:50.411104 I  TVRec(7): SetFlags(WaitingForSignal,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning,
2872012-12-01 18:16:50.411117 I  TVRec(7): SetFlags(DummyRecorderRunning,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning,DummyRecorderRunning,
2882012-12-01 18:16:50.411122 I  DummyDTVRecorder -- started
2892012-12-01 18:16:50.411134 I  TVRec(7): SetFlags(RingBufferReady,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning,DummyRecorderRunning,RingBufferReady,
2902012-12-01 18:16:50.411147 I  TVRec(7): ClearFlags(NeedToStartRecorder,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning,DummyRecorderRunning,RingBufferReady,
2912012-12-01 18:16:50.411161 I  TVRec(7): SetFlags(NeedToStartRecorder,) -> RunMainLoop,WaitingForSignal,NeedToStartRecorder,SignalMonitorRunning,DummyRecorderRunning,RingBufferReady,
2922012-12-01 18:16:50.411233 I  TVRec(7): SetFlags(CancelNextRecording,) -> RunMainLoop,CancelNextRecording,WaitingForSignal,NeedToStartRecorder,SignalMonitorRunning,DummyRecorderRunning,RingBufferReady,
2932012-12-01 18:16:50.469505 I  DVBSM(/dev/dvb/adapter0/frontend0): UpdateValues -- Signal Locked
2942012-12-01 18:16:50.469524 I  SH(/dev/dvb/adapter0/frontend0): AddListener(0x7f4134019980) -- begin
2952012-12-01 18:16:50.469531 I  SH(/dev/dvb/adapter0/frontend0): AddListener(0x7f4134019980) -- locked
2962012-12-01 18:16:50.469663 I  DVBSH(/dev/dvb/adapter0/frontend0): run(): begin
2972012-12-01 18:16:50.470954 I  PIDInfo(/dev/dvb/adapter0/frontend0): Opening filter for pid 0x0
2982012-12-01 18:16:50.471040 I  PIDInfo(/dev/dvb/adapter0/frontend0): Closing filter for pid 0x0
2992012-12-01 18:16:50.633959 I  DVBSH(/dev/dvb/adapter0/frontend0): RunTS(): begin
3002012-12-01 18:16:50.634007 I  PIDInfo(/dev/dvb/adapter0/frontend0): Opening filter for pid 0x0
3012012-12-01 18:16:50.634127 I  PIDInfo(/dev/dvb/adapter0/frontend0): Opening filter for pid 0x1
3022012-12-01 18:16:50.660774 I  CreatePATSingleProgram()
3032012-12-01 18:16:50.660785 I  PAT in input stream
3042012-12-01 18:16:50.660828 I  Program Association Section
305 PSIP tableID(0x0) length(37) extension(0x119)
306      version(5) current(1) section(0) last_section(0)
307      tsid(281) programCount(7)
308  program number     0 has PID 0x1ffc
309  program number   233 has PID 0x1dc0
310  program number   246 has PID 0x1e90
311  program number   265 has PID 0x00e0
312  program number   270 has PID 0x00a0
313  program number   318 has PID 0x00b0
314  program number   320 has PID 0x00c0
315
3162012-12-01 18:16:50.660834 I  desired_program(270) pid(0xa0)
3172012-12-01 18:16:50.660870 I  pmt_pid(0xa0)
3182012-12-01 18:16:50.660876 I  PAT for output stream
3192012-12-01 18:16:50.660893 I  Program Association Section
320 PSIP tableID(0x0) length(13) extension(0x119)
321      version(5) current(1) section(0) last_section(0)
322      tsid(281) programCount(1)
323  program number     1 has PID 0x00a0
324
3252012-12-01 18:16:50.660934 I  PIDInfo(/dev/dvb/adapter0/frontend0): Opening filter for pid 0xa0
3262012-12-01 18:16:50.669716 I  SH(/dev/dvb/adapter0/frontend0): AddListener(0x7f4134019980) -- end
3272012-12-01 18:16:50.680469 I  CreatePMTSingleProgram()
3282012-12-01 18:16:50.680474 I  PMT in input stream
3292012-12-01 18:16:50.680773 I  Program Map Section
330 PSIP tableID(0x2) length(70) extension(0x10e)
331      version(17) current(1) section(0) last_section(0)
332      pnum(270) pid(0xa0)
333  Stream #0 pid(0xa1) type(0x02 video-mpeg2)
334    STD Descriptor (0x11) length(1)
335    Smooting Buffer Descriptor (0x10) length(6)
336    Data Stream Alignment Descriptor (0x06) length(1)
337    Caption Service Descriptor  services(1)
338     lang(eng) type(1) easy_reader(0) wide(0) service_num(1)
339  Stream #1 pid(0xa2) type(0x81 audio-ac3)
340    Registration Descriptor: 'AC-3' ATSC audio stream A/52
341    Audio Stream Descriptor  full_srv(1) sample_rate(48kbps) bit_rate(=384kbps, 14)
342      bsid(8) bs_mode(0) channels(2/0) Dolby(Not indicated)
343      mainID(0)
344    ISO-639 Language: code(eng) canonical(eng) eng(English)
345
3462012-12-01 18:16:50.680808 I  PMT for output stream
3472012-12-01 18:16:50.680886 I  Program Map Section
348 PSIP tableID(0x2) length(70) extension(0x1)
349      version(17) current(1) section(0) last_section(0)
350      pnum(1) pid(0xa0)
351  Stream #0 pid(0xa1) type(0x02 video-mpeg2)
352    STD Descriptor (0x11) length(1)
353    Smooting Buffer Descriptor (0x10) length(6)
354    Data Stream Alignment Descriptor (0x06) length(1)
355    Caption Service Descriptor  services(1)
356     lang(eng) type(1) easy_reader(0) wide(0) service_num(1)
357  Stream #1 pid(0xa2) type(0x81 audio-ac3)
358    Registration Descriptor: 'AC-3' ATSC audio stream A/52
359    Audio Stream Descriptor  full_srv(1) sample_rate(48kbps) bit_rate(=384kbps, 14)
360      bsid(8) bs_mode(0) channels(2/0) Dolby(Not indicated)
361      mainID(0)
362    ISO-639 Language: code(eng) canonical(eng) eng(English)
363
3642012-12-01 18:16:50.680959 I  PIDInfo(/dev/dvb/adapter0/frontend0): Opening filter for pid 0xa1
3652012-12-01 18:16:50.680998 I  PIDInfo(/dev/dvb/adapter0/frontend0): Opening filter for pid 0xa2
3662012-12-01 18:16:50.720096 I  TVRec(7): Got good signal
3672012-12-01 18:16:50.720151 I  TVRec(7): TeardownSignalMonitor() -- begin
3682012-12-01 18:16:50.720160 I  DVBSM(/dev/dvb/adapter0/frontend0): Stop() -- begin
3692012-12-01 18:16:50.770390 I  SH(/dev/dvb/adapter0/frontend0): RemoveListener(0x7f4134019980) -- begin
3702012-12-01 18:16:50.770402 I  SH(/dev/dvb/adapter0/frontend0): RemoveListener(0x7f4134019980) -- locked
3712012-12-01 18:16:50.788568 I  DVBSH(/dev/dvb/adapter0/frontend0): RunTS(): shutdown
3722012-12-01 18:16:50.788582 I  PIDInfo(/dev/dvb/adapter0/frontend0): Closing filter for pid 0x0
3732012-12-01 18:16:50.788625 I  PIDInfo(/dev/dvb/adapter0/frontend0): Closing filter for pid 0x1
3742012-12-01 18:16:50.788649 I  PIDInfo(/dev/dvb/adapter0/frontend0): Closing filter for pid 0xa0
3752012-12-01 18:16:50.788670 I  PIDInfo(/dev/dvb/adapter0/frontend0): Closing filter for pid 0xa1
3762012-12-01 18:16:50.788697 I  PIDInfo(/dev/dvb/adapter0/frontend0): Closing filter for pid 0xa2
3772012-12-01 18:16:50.947730 I  DVBSH(/dev/dvb/adapter0/frontend0): RunTS(): end
3782012-12-01 18:16:50.947741 I  DVBSH(/dev/dvb/adapter0/frontend0): run(): end
3792012-12-01 18:16:50.947805 I  SH(/dev/dvb/adapter0/frontend0): RemoveListener(0x7f4134019980) -- end
3802012-12-01 18:16:50.947815 I  DVBSM(/dev/dvb/adapter0/frontend0): Stop() -- end
3812012-12-01 18:16:50.947867 I  TVRec(7): TeardownSignalMonitor() -- end
3822012-12-01 18:16:50.947884 I  TVRec(7): ClearFlags(SignalMonitorRunning,) -> RunMainLoop,CancelNextRecording,WaitingForSignal,NeedToStartRecorder,DummyRecorderRunning,RingBufferReady,
3832012-12-01 18:16:50.947903 I  TVRec(7): ClearFlags(WaitingForSignal,) -> RunMainLoop,CancelNextRecording,NeedToStartRecorder,DummyRecorderRunning,RingBufferReady,
3842012-12-01 18:16:50.948408 I  TVRec(7): Starting Recorder
3852012-12-01 18:16:50.948742 I  TVRec(7): FinishedRecording(5350_2012-12-02T00:16:50Z)
386                        title:
387                        in recgroup: LiveTV status: Recording:Recorded is_dummy finished_now
3882012-12-01 18:16:50.949049 I  Chain: Updated endtime for '5350_20121202001650' to 20121202001650
3892012-12-01 18:16:50.949539 I  TVRec(7): ClearFlags(DummyRecorderRunning,) -> RunMainLoop,CancelNextRecording,NeedToStartRecorder,RingBufferReady,
3902012-12-01 18:16:50.951688 I  Using profile 'Live TV' to record
3912012-12-01 18:16:50.951718 I  TVRec(7): SwitchLiveTVRingBuffer(discont 1, set_next_rec 0) curRec(5350_2012-12-02T00:16:50Z) curRec.size(0)
3922012-12-01 18:16:50.952127 I  TVRec(7): GetProgramRingBufferForLiveTV()
3932012-12-01 18:16:50.954447 N  AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 14 min
3942012-12-01 18:16:50.960311 E  RecordingInfo::InsertProgram(ProgramInfo(5350_20121202001650.mpg): channame() startts(Sun Dec 2 00:16:50 2012) endts(Sun Dec 2 00:30:00 2012)
395             recstartts(Sun Dec 2 00:16:50 2012) recendts(Sun Dec 2 00:30:00 2012)
396             title()): recording already exists...
3972012-12-01 18:16:50.962597 I  TVRec(7): StartedRecording(5350_2012-12-02T00:16:51Z) fn(/home/mythtv/rec/5350_20121202001651.mpg)
3982012-12-01 18:16:50.964972 I  Chain: Appended@3 '5350_20121202001651'
3992012-12-01 18:16:50.965196 I  DTVRec(7): ResetForNewFile(void)
4002012-12-01 18:16:50.965239 I  RecBase(7:/dev/dvb/adapter0/frontend0): SetRingBuffer(0x7f4134033720) '/home/mythtv/rec/5350_20121202001651.mpg'
4012012-12-01 18:16:50.965277 I  DTVRec(7): SetPAT(270 on 0xa0)
4022012-12-01 18:16:50.965292 I  CreatePATSingleProgram()
4032012-12-01 18:16:50.965296 I  PAT in input stream
4042012-12-01 18:16:50.965346 I  Program Association Section
405 PSIP tableID(0x0) length(37) extension(0x119)
406      version(5) current(1) section(0) last_section(0)
407      tsid(281) programCount(7)
408  program number     0 has PID 0x1ffc
409  program number   233 has PID 0x1dc0
410  program number   246 has PID 0x1e90
411  program number   265 has PID 0x00e0
412  program number   270 has PID 0x00a0
413  program number   318 has PID 0x00b0
414  program number   320 has PID 0x00c0
415
4162012-12-01 18:16:50.965355 I  desired_program(270) pid(0xa0)
4172012-12-01 18:16:50.965367 I  pmt_pid(0xa0)
4182012-12-01 18:16:50.965371 I  PAT for output stream
4192012-12-01 18:16:50.965394 I  Program Association Section
420 PSIP tableID(0x0) length(13) extension(0x119)
421      version(5) current(1) section(0) last_section(0)
422      tsid(281) programCount(1)
423  program number     1 has PID 0x00a0
424
4252012-12-01 18:16:50.965418 I  DTVRec(7): SetPMT(270)
4262012-12-01 18:16:50.965435 I  CreatePMTSingleProgram()
4272012-12-01 18:16:50.965439 I  PMT in input stream
4282012-12-01 18:16:50.965545 I  Program Map Section
429 PSIP tableID(0x2) length(70) extension(0x10e)
430      version(17) current(1) section(0) last_section(0)
431      pnum(270) pid(0xa0)
432  Stream #0 pid(0xa1) type(0x02 video-mpeg2)
433    STD Descriptor (0x11) length(1)
434    Smooting Buffer Descriptor (0x10) length(6)
435    Data Stream Alignment Descriptor (0x06) length(1)
436    Caption Service Descriptor  services(1)
437     lang(eng) type(1) easy_reader(0) wide(0) service_num(1)
438  Stream #1 pid(0xa2) type(0x81 audio-ac3)
439    Registration Descriptor: 'AC-3' ATSC audio stream A/52
440    Audio Stream Descriptor  full_srv(1) sample_rate(48kbps) bit_rate(=384kbps, 14)
441      bsid(8) bs_mode(0) channels(2/0) Dolby(Not indicated)
442      mainID(0)
443    ISO-639 Language: code(eng) canonical(eng) eng(English)
444
4452012-12-01 18:16:50.965582 I  PMT for output stream
4462012-12-01 18:16:50.965674 I  Program Map Section
447 PSIP tableID(0x2) length(70) extension(0x1)
448      version(17) current(1) section(0) last_section(0)
449      pnum(1) pid(0xa0)
450  Stream #0 pid(0xa1) type(0x02 video-mpeg2)
451    STD Descriptor (0x11) length(1)
452    Smooting Buffer Descriptor (0x10) length(6)
453    Data Stream Alignment Descriptor (0x06) length(1)
454    Caption Service Descriptor  services(1)
455     lang(eng) type(1) easy_reader(0) wide(0) service_num(1)
456  Stream #1 pid(0xa2) type(0x81 audio-ac3)
457    Registration Descriptor: 'AC-3' ATSC audio stream A/52
458    Audio Stream Descriptor  full_srv(1) sample_rate(48kbps) bit_rate(=384kbps, 14)
459      bsid(8) bs_mode(0) channels(2/0) Dolby(Not indicated)
460      mainID(0)
461    ISO-639 Language: code(eng) canonical(eng) eng(English)
462
4632012-12-01 18:16:50.965689 I  RecBase(7:/dev/dvb/adapter0/frontend0): SetRecording(0x7f413401ea60) title()
4642012-12-01 18:16:50.966136 I  DTVRec(7): ResetForNewFile(void)
4652012-12-01 18:16:50.966183 I  DVBRec(7:/dev/dvb/adapter0/frontend0): Card opened successfully
4662012-12-01 18:16:50.966237 I  SH(/dev/dvb/adapter0/frontend0): AddListener(0x7f4134019980) -- begin
4672012-12-01 18:16:50.966245 I  SH(/dev/dvb/adapter0/frontend0): AddListener(0x7f4134019980) -- locked
4682012-12-01 18:16:50.966348 I  DVBSH(/dev/dvb/adapter0/frontend0): run(): begin
4692012-12-01 18:16:50.971189 I  TVRec(7): SetFlags(RecorderRunning,RingBufferReady,) -> RunMainLoop,CancelNextRecording,NeedToStartRecorder,RecorderRunning,RingBufferReady,
4702012-12-01 18:16:50.971216 I  TVRec(7): ClearFlags(NeedToStartRecorder,) -> RunMainLoop,CancelNextRecording,RecorderRunning,RingBufferReady,
4712012-12-01 18:16:50.979467 I  DevRdB(/dev/dvb/adapter0/frontend0): buffer size 9400 KB
4722012-12-01 18:16:50.979501 I  DevRdB(/dev/dvb/adapter0/frontend0): Start() -- begin
4732012-12-01 18:16:50.979590 I  DevRdB(/dev/dvb/adapter0/frontend0): Start() -- middle
4742012-12-01 18:16:50.979607 I  DevRdB(/dev/dvb/adapter0/frontend0): Start() -- end
4752012-12-01 18:16:50.979623 I  DVBSH(/dev/dvb/adapter0/frontend0): RunTS(): begin
4762012-12-01 18:16:50.979674 I  PIDInfo(/dev/dvb/adapter0/frontend0): Opening filter for pid 0x0
4772012-12-01 18:16:50.979795 I  PIDInfo(/dev/dvb/adapter0/frontend0): Opening filter for pid 0x1
4782012-12-01 18:16:50.979837 I  PIDInfo(/dev/dvb/adapter0/frontend0): Opening filter for pid 0xa0
4792012-12-01 18:16:50.979872 I  PIDInfo(/dev/dvb/adapter0/frontend0): Opening filter for pid 0xa1
4802012-12-01 18:16:50.979912 I  PIDInfo(/dev/dvb/adapter0/frontend0): Opening filter for pid 0xa2
4812012-12-01 18:16:50.979954 I  PIDInfo(/dev/dvb/adapter0/frontend0): Opening filter for pid 0xb0
4822012-12-01 18:16:50.979988 I  PIDInfo(/dev/dvb/adapter0/frontend0): Opening filter for pid 0xc0
4832012-12-01 18:16:50.980029 I  PIDInfo(/dev/dvb/adapter0/frontend0): Opening filter for pid 0xe0
4842012-12-01 18:16:50.980067 I  PIDInfo(/dev/dvb/adapter0/frontend0): Opening filter for pid 0x1dc0
4852012-12-01 18:16:50.980109 I  PIDInfo(/dev/dvb/adapter0/frontend0): Opening filter for pid 0x1e90
4862012-12-01 18:16:50.980153 I  PIDInfo(/dev/dvb/adapter0/frontend0): Opening filter for pid 0x1ffc
4872012-12-01 18:16:51.061025 I  DTVRec(7): FindMPEG2Keyframes: frame rate = 29970
4882012-12-01 18:16:51.061227 I  DTVRec(7): PID 0xa1 Found Payload Start
4892012-12-01 18:16:51.066343 I  SH(/dev/dvb/adapter0/frontend0): AddListener(0x7f4134019980) -- end
4902012-12-01 18:16:51.124303 I  DTVRec(7): PID 0xa2 Found Payload Start
4912012-12-01 18:16:52.953866 I  RecBase(7:/dev/dvb/adapter0/frontend0): GetKeyframePositions(16,9223372036854775807,#3) out of 5
4922012-12-01 18:16:53.197544 I  RecBase(7:/dev/dvb/adapter0/frontend0): GetKeyframePositions(16,9223372036854775807,#3) out of 5
4932012-12-01 18:17:27.956957 N  AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 14 min
4942012-12-01 18:17:27.973657 N  Expiring 1757 MB for 1063 at 2011-10-31T02:30:01Z => "A Funny Thing Happened on the Way to the Forum"
4952012-12-01 18:17:27.976285 E  ProgramInfo(1063_20111030213001.nuv): GetPlaybackURL: '1063_20111030213001.nuv' should be local, but it can not be found.
4962012-12-01 18:17:27.976396 E  ERROR when trying to delete file: GetPlaybackURL/UNABLE/TO/FIND/LOCAL/FILE/ON/zeus/1063_20111030213001.nuv. File doesn't exist.  Database metadata will not be removed.
4972012-12-01 18:17:43.684599 I  TVRec(7): StopLiveTV(void) curRec: 0x7f413401ea60 pseudoRec: 0x0
4982012-12-01 18:17:43.685169 I  TVRec(7): Changing from WatchingLiveTV to None
4992012-12-01 18:17:43.685193 I  TVRec(7): ClearFlags(FrontendReady,CancelNextRecording,) -> RunMainLoop,RecorderRunning,RingBufferReady,
5002012-12-01 18:17:43.685210 I  TVRec(7): HandleTuning Request: Program(NULL) channel() input() flags(KillRec,KillRingBuffer,)
5012012-12-01 18:17:43.685263 I  SH(/dev/dvb/adapter0/frontend0): RemoveListener(0x7f4134019980) -- begin
5022012-12-01 18:17:43.685277 I  SH(/dev/dvb/adapter0/frontend0): RemoveListener(0x7f4134019980) -- locked
5032012-12-01 18:17:43.685286 I  DevRdB(/dev/dvb/adapter0/frontend0): Stop() -- begin
5042012-12-01 18:17:43.685357 I  DevRdB(/dev/dvb/adapter0/frontend0): Stop() -- end
5052012-12-01 18:17:43.685478 I  DVBSH(/dev/dvb/adapter0/frontend0): RunTS(): shutdown
5062012-12-01 18:17:43.685491 I  PIDInfo(/dev/dvb/adapter0/frontend0): Closing filter for pid 0x0
5072012-12-01 18:17:43.685533 I  PIDInfo(/dev/dvb/adapter0/frontend0): Closing filter for pid 0x1
5082012-12-01 18:17:43.685559 I  PIDInfo(/dev/dvb/adapter0/frontend0): Closing filter for pid 0xa0
5092012-12-01 18:17:43.685583 I  PIDInfo(/dev/dvb/adapter0/frontend0): Closing filter for pid 0xa1
5102012-12-01 18:17:43.685607 I  PIDInfo(/dev/dvb/adapter0/frontend0): Closing filter for pid 0xa2
5112012-12-01 18:17:43.685631 I  PIDInfo(/dev/dvb/adapter0/frontend0): Closing filter for pid 0xb0
5122012-12-01 18:17:43.685653 I  PIDInfo(/dev/dvb/adapter0/frontend0): Closing filter for pid 0xc0
5132012-12-01 18:17:43.685676 I  PIDInfo(/dev/dvb/adapter0/frontend0): Closing filter for pid 0xe0
5142012-12-01 18:17:43.685698 I  PIDInfo(/dev/dvb/adapter0/frontend0): Closing filter for pid 0x1dc0
5152012-12-01 18:17:43.685721 I  PIDInfo(/dev/dvb/adapter0/frontend0): Closing filter for pid 0x1e90
5162012-12-01 18:17:43.685744 I  PIDInfo(/dev/dvb/adapter0/frontend0): Closing filter for pid 0x1ffc
5172012-12-01 18:17:43.843956 I  DevRdB(/dev/dvb/adapter0/frontend0): Stop() -- begin
5182012-12-01 18:17:43.843965 I  DevRdB(/dev/dvb/adapter0/frontend0): Stop() -- end
5192012-12-01 18:17:43.844999 I  DVBSH(/dev/dvb/adapter0/frontend0): RunTS(): end
5202012-12-01 18:17:43.845008 I  DVBSH(/dev/dvb/adapter0/frontend0): run(): end
5212012-12-01 18:17:43.845138 I  SH(/dev/dvb/adapter0/frontend0): RemoveListener(0x7f4134019980) -- end
5222012-12-01 18:17:43.845163 I  DVBRec(7:/dev/dvb/adapter0/frontend0): Close() -- begin
5232012-12-01 18:17:43.845186 I  DVBRec(7:/dev/dvb/adapter0/frontend0): Close() -- end
5242012-12-01 18:17:43.885511 I  TVRec(7): ClearFlags(RecorderRunning,) -> RunMainLoop,RingBufferReady,
5252012-12-01 18:17:43.885596 I  RecordingQuality() start(2012-12-02T00:16:50Z) end(2012-12-02T00:30:00Z) score(0)
5262012-12-01 18:17:43.885709 I  RecBase(7:/dev/dvb/adapter0/frontend0): SetRecording(0x0)
5272012-12-01 18:17:43.886275 I  TVRec(7): FinishedRecording(5350_2012-12-02T00:16:51Z) damaged recq:<RecordingQuality overall_score="0" key="5350_2012-12-02T00:16:51Z" countinuity_error_count="0" packet_count="75580">
528    <Gap start="2012-12-02T00:17:39Z" end="2012-12-02T00:30:00Z" duration="740" />
529</RecordingQuality>
530
5312012-12-01 18:17:43.886329 I  TVRec(7): FinishedRecording(5350_2012-12-02T00:16:51Z)
532                        title:
533                        in recgroup: LiveTV status: Recorder Failed:Recorder Failed not_dummy finished_now
5342012-12-01 18:17:43.886645 I  Chain: Updated endtime for '5350_20121202001651' to 20121202001743
5352012-12-01 18:17:43.887360 I  SaveVideoProperties(0x38, 0x20)
5362012-12-01 18:17:43.888683 I  TVRec(7): ClearFlags(RecorderRunning,) -> RunMainLoop,RingBufferReady,
5372012-12-01 18:17:43.888698 I  DVBChan(7:/dev/dvb/adapter0/frontend0): Closing DVB channel
5382012-12-01 18:17:43.888724 I  TVRec(7): Tearing down RingBuffer
5392012-12-01 18:17:43.888973 I  TVRec(7): ClearFlags(PENDINGACTIONS,) -> RunMainLoop,RingBufferReady,
5402012-12-01 18:17:43.891709 I  MainServer::ANN Playback
5412012-12-01 18:17:43.891718 I  adding: zeus as a client (events: 0)
5422012-12-01 18:17:43.892868 I  TVRec(6): Changing from None to WatchingLiveTV
5432012-12-01 18:17:43.892886 I  TVRec(6): ClearFlags(FrontendReady,CancelNextRecording,) -> RunMainLoop,RingBufferReady,
5442012-12-01 18:17:43.892902 I  TVRec(6): HandleTuning Request: Program(NULL) channel() input() flags(LiveTV,)
5452012-12-01 18:17:43.892916 I  ChannelBase(6): Looking for startchannel '39' on input 'tuner'
5462012-12-01 18:17:43.894616 I  ChannelBase(6): Found startchannel '39' on input 'tuner'
5472012-12-01 18:17:43.894648 I  TVRec(6): HW Tuner: 6->6
5482012-12-01 18:17:43.894659 I  TVRec(6): ClearFlags(PENDINGACTIONS,) -> RunMainLoop,RingBufferReady,
5492012-12-01 18:17:43.894668 I  TVRec(6): No recorder yet, calling TuningFrequency
5502012-12-01 18:17:43.894940 I  V4LChannel(/dev/video2): Device name 'Hauppauge WinTV-HVR2250' driver 'saa7164'.
5512012-12-01 18:17:43.894956 I  V4LChannel(/dev/video2): v4l2: 1 stream io: 0 std io: 1 async io: 0 tuner 1 sliced vbi 0
5522012-12-01 18:17:43.902703 I  ChannelBase(6): Input #6: 'tuner' schan(39) sourceid(1) ccid(6)
5532012-12-01 18:17:43.902716 I  ChannelBase(6): Current Input #6: 'tuner'
5542012-12-01 18:17:43.902743 I  Global TVFormat Setting 'NTSC'
5552012-12-01 18:17:43.902773 I  V4LChannel(/dev/video2): Input #6: 'tuner' schan(39) tun() v4l1(Unknown) v4l2(NTSC)
5562012-12-01 18:17:43.902787 I  V4LChannel(/dev/video2): SetFormat(Default) fmt(NTSC) input(6)
5572012-12-01 18:17:43.902797 I  Channel(/dev/video2)::SwitchToInput(in 6, '')
5582012-12-01 18:17:43.924962 I  V4LChannel(/dev/video2): SetInputAndFormat(6, NTSC) (v4l v2) input_switch: 0 mode_switch: 1
5592012-12-01 18:17:43.927113 I  DTVChan(/dev/video2): SetChannelByString(39):
5602012-12-01 18:17:43.928962 I  V4LChannel(/dev/video2): SetFormat(Default) fmt(NTSC) input(6)
5612012-12-01 18:17:43.928979 I  Channel(/dev/video2)::Tune(39): curList[37].freq(313250)
5622012-12-01 18:17:43.928987 I  V4LChannel(/dev/video2): Tune(313250000, )
5632012-12-01 18:17:44.220427 I  Channel(/dev/video2)::Tune(): Frequency is now 313250000
5642012-12-01 18:17:44.220440 I  DTVChan(/dev/video2): SetChannelByString(39): success
5652012-12-01 18:17:44.226126 I  TVRec(6): CreateLiveTVRingBuffer(39)
5662012-12-01 18:17:44.226551 I  TVRec(6): GetProgramRingBufferForLiveTV()
5672012-12-01 18:17:44.229121 N  AutoExpire: CalcParams(): Max required Free Space: 2.0 GB w/freq: 15 min
5682012-12-01 18:17:44.296075 I  TVRec(6): StartedRecording(1039_2012-12-02T00:17:44Z) fn(/home/mythtv/rec/1039_20121202001744.mpg)
5692012-12-01 18:17:44.297139 I  Chain: Appended@4 '1039_20121202001744'
5702012-12-01 18:17:44.297782 I  TVRec(6): Starting Signal Monitor
5712012-12-01 18:17:44.297790 I  TVRec(6): SetupSignalMonitor(1, 1)
5722012-12-01 18:17:44.297810 I  TVRec(6): Signal monitor successfully created
5732012-12-01 18:17:44.297892 I  TVRec(6): SetFlags(SignalMonitorRunning,) -> RunMainLoop,SignalMonitorRunning,RingBufferReady,
5742012-12-01 18:17:44.297901 I  TVRec(6): ClearFlags(WaitingForSignal,) -> RunMainLoop,SignalMonitorRunning,RingBufferReady,
5752012-12-01 18:17:44.297910 I  TVRec(6): SetFlags(WaitingForSignal,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning,RingBufferReady,
5762012-12-01 18:17:44.297919 I  TVRec(6): SetFlags(DummyRecorderRunning,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning,DummyRecorderRunning,RingBufferReady,
5772012-12-01 18:17:44.297923 I  DummyDTVRecorder -- started
5782012-12-01 18:17:44.297932 I  TVRec(6): SetFlags(RingBufferReady,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning,DummyRecorderRunning,RingBufferReady,
5792012-12-01 18:17:44.297940 I  TVRec(6): ClearFlags(NeedToStartRecorder,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning,DummyRecorderRunning,RingBufferReady,
5802012-12-01 18:17:44.297949 I  TVRec(6): SetFlags(NeedToStartRecorder,) -> RunMainLoop,WaitingForSignal,NeedToStartRecorder,SignalMonitorRunning,DummyRecorderRunning,RingBufferReady,
5812012-12-01 18:17:44.297956 I  TVRec(6): Got good signal
5822012-12-01 18:17:44.297986 I  TVRec(6): TeardownSignalMonitor() -- begin
5832012-12-01 18:17:44.348060 I  TVRec(6): TeardownSignalMonitor() -- end
5842012-12-01 18:17:44.348101 I  TVRec(6): ClearFlags(SignalMonitorRunning,) -> RunMainLoop,WaitingForSignal,NeedToStartRecorder,DummyRecorderRunning,RingBufferReady,
5852012-12-01 18:17:44.348116 I  TVRec(6): ClearFlags(WaitingForSignal,) -> RunMainLoop,NeedToStartRecorder,DummyRecorderRunning,RingBufferReady,
5862012-12-01 18:17:44.348140 I  TVRec(6): Starting Recorder
5872012-12-01 18:17:44.348524 I  TVRec(6): FinishedRecording(1039_2012-12-02T00:17:44Z)
588                        title: Storage Wars Texas
589                        in recgroup: LiveTV status: Recording:Recorded is_dummy finished_now
5902012-12-01 18:17:44.348802 I  Chain: Updated endtime for '1039_20121202001744' to 20121202001744
5912012-12-01 18:17:44.349222 I  TVRec(6): ClearFlags(DummyRecorderRunning,) -> RunMainLoop,NeedToStartRecorder,RingBufferReady,
5922012-12-01 18:17:44.361375 I  Using profile 'Live TV' to record
5932012-12-01 18:17:44.361425 I  TVRec(6): SwitchLiveTVRingBuffer(discont 1, set_next_rec 0) curRec(1039_2012-12-02T00:17:44Z) curRec.size(0)
5942012-12-01 18:17:44.361846 I  TVRec(6): GetProgramRingBufferForLiveTV()
5952012-12-01 18:17:44.364168 N  AutoExpire: CalcParams(): Max required Free Space: 2.0 GB w/freq: 15 min
5962012-12-01 18:17:44.371587 E  RecordingInfo::InsertProgram(ProgramInfo(1039_20121202001744.mpg): channame(A & E Network) startts(Sun Dec 2 00:00:00 2012) endts(Sun Dec 2 00:30:00 2012)
597             recstartts(Sun Dec 2 00:17:44 2012) recendts(Sun Dec 2 00:30:00 2012)
598             title(Storage Wars Texas)): recording already exists...
5992012-12-01 18:17:44.374440 I  TVRec(6): StartedRecording(1039_2012-12-02T00:17:45Z) fn(/home/mythtv/rec/1039_20121202001745.mpg)
6002012-12-01 18:17:44.376746 I  Chain: Appended@5 '1039_20121202001745'
6012012-12-01 18:17:44.376959 I  DTVRec(6): ResetForNewFile(void)
6022012-12-01 18:17:44.377075 I  RecBase(6:/dev/video2): SetRingBuffer(0x7f414005a1f0) '/home/mythtv/rec/1039_20121202001745.mpg'
6032012-12-01 18:17:44.377090 I  RecBase(6:/dev/video2): SetRecording(0x7f414002caa0) title(Storage Wars Texas)
6042012-12-01 18:17:44.382864 I  TVRec(6): SetFlags(CancelNextRecording,) -> RunMainLoop,CancelNextRecording,NeedToStartRecorder,RingBufferReady,
6052012-12-01 18:17:44.382923 I  DTVRec(6): ResetForNewFile(void)
6062012-12-01 18:17:44.383981 I  V4LRec(6:/dev/video2): vbi_format  rate: 27000000
607                                  offset: 0
608                        samples_per_line: 1440
609                                  starts: 10, 274
610                                  counts: 18, 18
611                                   flags: 0x0
6122012-12-01 18:17:44.394522 I  DevRdB(/dev/video2): buffer size 9400 KB
6132012-12-01 18:17:44.394535 I  MPEGRec(/dev/video2): DRB ready
6142012-12-01 18:17:44.394585 I  MPEGRec(/dev/video2): Initial startup of recorder
6152012-12-01 18:17:44.394592 I  MPEGRec(/dev/video2): StartEncoding
6162012-12-01 18:17:44.394606 I  DevRdB(/dev/video2): Start() -- begin
6172012-12-01 18:17:44.394659 I  DevRdB(/dev/video2): Start() -- middle
6182012-12-01 18:17:44.394667 I  DevRdB(/dev/video2): Start() -- end
6192012-12-01 18:17:44.398030 I  TVRec(6): SetFlags(RecorderRunning,RingBufferReady,) -> RunMainLoop,CancelNextRecording,NeedToStartRecorder,RecorderRunning,RingBufferReady,
6202012-12-01 18:17:44.398048 I  TVRec(6): ClearFlags(NeedToStartRecorder,) -> RunMainLoop,CancelNextRecording,RecorderRunning,RingBufferReady,
6212012-12-01 18:17:45.049486 I  DTVRec(6): FindPSKeyFrames: frame rate = 29970
6222012-12-01 18:17:47.551242 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
6232012-12-01 18:17:47.880452 I  MainServer::ANN Playback
6242012-12-01 18:17:47.880461 I  adding: zeus as a client (events: 0)
6252012-12-01 18:17:47.881079 I  MainServer::HandleAnnounce FileTransfer
6262012-12-01 18:17:47.881085 I  adding: zeus as a remote file transfer
6272012-12-01 18:17:48.505762 I  RecBase(6:/dev/video2): GetKeyframePositions(76,9223372036854775807,#0) out of 5
6282012-12-01 18:17:50.058122 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
6292012-12-01 18:17:52.564373 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
6302012-12-01 18:17:57.576593 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
6312012-12-01 18:18:02.589232 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
6322012-12-01 18:18:05.096524 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
6332012-12-01 18:18:07.603603 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
6342012-12-01 18:18:10.111167 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
6352012-12-01 18:18:12.616513 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
6362012-12-01 18:18:15.123613 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
6372012-12-01 18:18:17.630713 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
6382012-12-01 18:18:20.137795 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
6392012-12-01 18:18:25.150272 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
6402012-12-01 18:18:27.368232 N  Expiring 0 MB for 1057 at 2012-12-02T00:16:19Z => "Fixing Pete"
6412012-12-01 18:18:27.368297 N  Expiring 16 MB for 1057 at 2012-12-02T00:16:20Z => "Fixing Pete"
6422012-12-01 18:18:27.368353 N  Expiring 0 MB for 5350 at 2012-12-02T00:16:50Z =>
6432012-12-01 18:18:27.657739 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
6442012-12-01 18:18:30.165138 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
6452012-12-01 18:18:32.672618 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
6462012-12-01 18:18:35.180197 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
6472012-12-01 18:18:37.687610 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
6482012-12-01 18:18:42.698893 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
6492012-12-01 18:18:45.206309 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
6502012-12-01 18:18:50.219071 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
6512012-12-01 18:18:52.724541 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
6522012-12-01 18:18:57.736164 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
6532012-12-01 18:19:00.241308 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
6542012-12-01 18:19:02.746171 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
6552012-12-01 18:19:05.253381 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
6562012-12-01 18:19:07.760394 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
6572012-12-01 18:19:10.267516 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
6582012-12-01 18:19:12.774879 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
6592012-12-01 18:19:15.282523 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
6602012-12-01 18:19:17.789838 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
6612012-12-01 18:19:20.297536 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
6622012-12-01 18:19:22.805374 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
6632012-12-01 18:19:25.313072 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
6642012-12-01 18:19:27.818130 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
6652012-12-01 18:19:30.325489 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
6662012-12-01 18:19:32.831232 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
6672012-12-01 18:19:37.844375 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
6682012-12-01 18:19:40.352182 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
6692012-12-01 18:19:42.858864 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
6702012-12-01 18:19:45.364211 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
6712012-12-01 18:19:47.869624 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
6722012-12-01 18:19:50.374817 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
6732012-12-01 18:19:52.882311 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
6742012-12-01 18:19:55.388768 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
6752012-12-01 18:20:00.401234 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
6762012-12-01 18:20:05.413783 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
6772012-12-01 18:20:07.919108 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
6782012-12-01 18:20:10.424292 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
6792012-12-01 18:20:12.929533 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
6802012-12-01 18:20:15.435191 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
6812012-12-01 18:20:17.941455 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
6822012-12-01 18:20:25.457050 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
6832012-12-01 18:20:27.367368 N  Expiring 13 MB for 5350 at 2012-12-02T00:16:51Z =>
6842012-12-01 18:20:27.367437 N  Expiring 0 MB for 1039 at 2012-12-02T00:17:44Z => "Storage Wars Texas":"A Jenny for Your Thoughts"
6852012-12-01 18:20:30.468760 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
6862012-12-01 18:20:35.479051 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
6872012-12-01 18:20:37.986103 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
6882012-12-01 18:20:45.502325 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
6892012-12-01 18:20:48.009604 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
6902012-12-01 18:20:53.020165 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
6912012-12-01 18:20:55.525537 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
6922012-12-01 18:20:58.031574 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
6932012-12-01 18:21:00.538504 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
6942012-12-01 18:21:05.549023 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
6952012-12-01 18:21:08.056571 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
6962012-12-01 18:21:10.564183 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
6972012-12-01 18:21:13.069130 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
6982012-12-01 18:21:15.574421 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
6992012-12-01 18:21:20.585319 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
7002012-12-01 18:21:20.605508 I  Running housekeeping thread
7012012-12-01 18:21:20.606510 I  Running mythfilldatabase
7022012-12-01 18:21:20.608745 I  Starting process signal handler
7032012-12-01 18:21:20.608813 I  Starting process manager
7042012-12-01 18:21:20.608923 I  Starting IO manager (read)
7052012-12-01 18:21:20.608962 I  Starting IO manager (write)
7062012-12-01 18:21:23.091678 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
7072012-12-01 18:21:28.106944 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
7082012-12-01 18:21:30.615370 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
7092012-12-01 18:21:33.123038 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
7102012-12-01 18:21:35.631451 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
7112012-12-01 18:21:38.138107 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
7122012-12-01 18:21:40.642755 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
7132012-12-01 18:21:43.150262 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
7142012-12-01 18:21:45.655398 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
7152012-12-01 18:21:48.161724 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
7162012-12-01 18:21:50.669105 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
7172012-12-01 18:21:53.176284 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
7182012-12-01 18:21:58.187050 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
7192012-12-01 18:22:00.694346 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
7202012-12-01 18:22:03.199272 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
7212012-12-01 18:22:05.706247 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
7222012-12-01 18:22:08.214745 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
7232012-12-01 18:22:10.721443 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
7242012-12-01 18:22:15.733096 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
7252012-12-01 18:22:18.239314 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
7262012-12-01 18:22:20.745771 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
7272012-12-01 18:22:23.252998 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
7282012-12-01 18:22:28.265075 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
7292012-12-01 18:22:30.770377 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
7302012-12-01 18:22:33.277487 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
7312012-12-01 18:22:38.288108 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
7322012-12-01 18:22:45.803477 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
7332012-12-01 18:22:48.310783 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
7342012-12-01 18:22:50.818171 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
7352012-12-01 18:22:53.325778 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
7362012-12-01 18:22:55.831454 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
7372012-12-01 18:22:58.337125 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
7382012-12-01 18:23:00.844289 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
7392012-12-01 18:23:03.351418 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
7402012-12-01 18:23:05.858103 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
7412012-12-01 18:23:08.364169 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
7422012-12-01 18:23:13.376852 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
7432012-12-01 18:23:15.884071 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
7442012-12-01 18:23:18.391212 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
7452012-12-01 18:23:20.898097 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
7462012-12-01 18:23:23.404545 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
7472012-12-01 18:23:30.921055 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
7482012-12-01 18:23:35.932522 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
7492012-12-01 18:23:40.944761 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
7502012-12-01 18:23:43.450644 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
7512012-12-01 18:23:45.957571 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
7522012-12-01 18:23:48.464199 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
7532012-12-01 18:23:50.973655 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
7542012-12-01 18:23:53.481061 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
7552012-12-01 18:23:55.986300 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
7562012-12-01 18:23:58.493405 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
7572012-12-01 18:24:01.000482 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
7582012-12-01 18:24:03.507658 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
7592012-12-01 18:24:08.519352 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
7602012-12-01 18:24:11.025949 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
7612012-12-01 18:24:13.531415 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
7622012-12-01 18:24:16.038037 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
7632012-12-01 18:24:18.544644 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
7642012-12-01 18:24:21.051478 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
7652012-12-01 18:24:23.558104 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
7662012-12-01 18:24:26.063070 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
7672012-12-01 18:24:28.571127 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
7682012-12-01 18:24:31.077423 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
7692012-12-01 18:24:33.582206 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
7702012-12-01 18:24:36.089782 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
7712012-12-01 18:24:38.595588 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
7722012-12-01 18:24:41.102732 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
7732012-12-01 18:24:43.610105 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
7742012-12-01 18:24:46.178567 I  MainServer::ANN Monitor
7752012-12-01 18:24:46.178581 I  adding: zeus as a client (events: 0)
7762012-12-01 18:24:46.178955 I  MainServer::ANN Monitor
7772012-12-01 18:24:46.178963 I  adding: zeus as a client (events: 1)
7782012-12-01 18:24:46.179548 I  Reschedule requested for MATCH 0 0 0 - MythFillDatabase
7792012-12-01 18:24:46.325092 I  Scheduled 28 items in 0.1 = 0.06 match + 0.04 check + 0.03 place
7802012-12-01 18:24:48.620307 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
7812012-12-01 18:24:51.127480 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
7822012-12-01 18:24:56.139921 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
7832012-12-01 18:24:58.647636 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
7842012-12-01 18:25:01.154264 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
7852012-12-01 18:25:03.661558 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
7862012-12-01 18:25:06.168217 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
7872012-12-01 18:25:08.675242 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
7882012-12-01 18:25:16.192735 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
7892012-12-01 18:25:18.698407 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
7902012-12-01 18:25:21.205913 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
7912012-12-01 18:25:23.711432 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
7922012-12-01 18:25:31.228817 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
7932012-12-01 18:25:33.734318 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
7942012-12-01 18:25:36.241424 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
7952012-12-01 18:25:41.254060 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
7962012-12-01 18:25:43.759671 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
7972012-12-01 18:25:46.266854 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
7982012-12-01 18:25:48.772268 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
7992012-12-01 18:25:51.279347 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
8002012-12-01 18:25:56.290578 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
8012012-12-01 18:25:58.797779 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
8022012-12-01 18:26:03.810235 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
8032012-12-01 18:26:06.317096 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
8042012-12-01 18:26:08.824449 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
8052012-12-01 18:26:11.331620 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
8062012-12-01 18:26:13.838228 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
8072012-12-01 18:26:16.345183 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
8082012-12-01 18:26:18.853223 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
8092012-12-01 18:26:21.358066 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
8102012-12-01 18:26:23.865054 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
8112012-12-01 18:26:26.371433 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
8122012-12-01 18:26:26.608037 I  Running housekeeping thread
8132012-12-01 18:26:28.877786 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
8142012-12-01 18:26:31.384135 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
8152012-12-01 18:26:33.890590 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
8162012-12-01 18:26:36.398098 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
8172012-12-01 18:26:38.903182 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
8182012-12-01 18:26:41.410096 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
8192012-12-01 18:26:43.917281 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
8202012-12-01 18:26:46.424433 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
8212012-12-01 18:26:48.931178 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
8222012-12-01 18:26:53.944610 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
8232012-12-01 18:26:56.450921 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
8242012-12-01 18:26:58.961114 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
8252012-12-01 18:27:01.468604 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
8262012-12-01 18:27:03.974989 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
8272012-12-01 18:27:06.482301 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
8282012-12-01 18:27:08.988098 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
8292012-12-01 18:27:11.493347 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
8302012-12-01 18:27:14.000961 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
8312012-12-01 18:27:16.508059 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
8322012-12-01 18:27:19.014520 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
8332012-12-01 18:27:21.521423 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
8342012-12-01 18:27:24.027051 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
8352012-12-01 18:27:26.533474 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
8362012-12-01 18:27:29.038962 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
8372012-12-01 18:27:34.048231 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
8382012-12-01 18:27:36.554289 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
8392012-12-01 18:27:39.059324 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
8402012-12-01 18:27:41.564299 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
8412012-12-01 18:27:44.071410 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
8422012-12-01 18:27:49.082336 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
8432012-12-01 18:27:54.093264 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
8442012-12-01 18:27:56.598851 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
8452012-12-01 18:27:59.104752 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
8462012-12-01 18:28:01.611465 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
8472012-12-01 18:28:04.118313 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
8482012-12-01 18:28:06.623908 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
8492012-12-01 18:28:11.635765 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
8502012-12-01 18:28:16.648324 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
8512012-12-01 18:28:19.154845 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
8522012-12-01 18:28:21.660363 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
8532012-12-01 18:28:34.186013 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
8542012-12-01 18:28:36.693635 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
8552012-12-01 18:28:39.200709 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
8562012-12-01 18:28:41.707807 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
8572012-12-01 18:28:44.213127 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
8582012-12-01 18:28:46.718519 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
8592012-12-01 18:28:49.225404 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
8602012-12-01 18:28:51.731380 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
8612012-12-01 18:28:56.742907 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
8622012-12-01 18:29:01.755727 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
8632012-12-01 18:29:04.260369 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
8642012-12-01 18:29:06.768402 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
8652012-12-01 18:29:09.274404 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
8662012-12-01 18:29:11.781467 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
8672012-12-01 18:29:14.288722 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
8682012-12-01 18:29:16.794758 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
8692012-12-01 18:29:19.300964 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
8702012-12-01 18:29:24.312890 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
8712012-12-01 18:29:26.818726 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
8722012-12-01 18:29:31.831555 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
8732012-12-01 18:29:34.337350 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
8742012-12-01 18:29:36.843584 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
8752012-12-01 18:29:39.351288 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
8762012-12-01 18:29:41.857368 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
8772012-12-01 18:29:44.364404 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
8782012-12-01 18:29:46.871637 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
8792012-12-01 18:29:51.883072 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
8802012-12-01 18:29:54.390749 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
8812012-12-01 18:29:56.897948 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
8822012-12-01 18:29:59.404745 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
8832012-12-01 18:30:00.968199 I  TVRec(6): Switching Buffer (!has_rec(0) && !rec_soon(0) && (2012-12-02T00:30:00Z >= 2012-12-02T00:30:00Z(1) ))
8842012-12-01 18:30:00.968241 I  TVRec(6): SwitchLiveTVRingBuffer(discont 0, set_next_rec 1) curRec(1039_2012-12-02T00:17:45Z) curRec.size(0)
8852012-12-01 18:30:00.969040 I  TVRec(6): GetProgramRingBufferForLiveTV()
8862012-12-01 18:30:00.972784 N  AutoExpire: CalcParams(): Max required Free Space: 2.0 GB w/freq: 15 min
8872012-12-01 18:30:01.039154 I  TVRec(6): StartedRecording(1039_2012-12-02T00:30:00Z) fn(/home/mythtv/rec/1039_20121202003000.mpg)
8882012-12-01 18:30:01.041059 I  Chain: Appended@6 '1039_20121202003000'
8892012-12-01 18:30:01.041101 I  DTVRec(6): SetNextRecord(0x7f4140035670, 0x7f41400196f0)
8902012-12-01 18:30:01.130497 I  TVRec(6): SetFlags(RingBufferReady,) -> RunMainLoop,CancelNextRecording,RecorderRunning,RingBufferReady,
8912012-12-01 18:30:01.130510 I  TVRec(6): Enabling Full LiveTV UI.
8922012-12-01 18:30:01.130553 I  Waiting for ringbuffer switch
8932012-12-01 18:30:01.130558 I  TVRec(6): Enabling Full LiveTV UI.
8942012-12-01 18:30:01.910941 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
8952012-12-01 18:30:01.943332 I  RecordingQuality() start(2012-12-02T00:00:00Z) end(2012-12-02T00:30:00Z) score(1)
8962012-12-01 18:30:01.943346 I  DTVRec(6): ResetForNewFile(void)
8972012-12-01 18:30:01.943551 I  RecBase(6:/dev/video2): SetRingBuffer(0x7f41400196f0) '/home/mythtv/rec/1039_20121202003000.mpg'
8982012-12-01 18:30:01.943563 I  RecBase(6:/dev/video2): SetRecording(0x7f41400286b0) title(Storage Wars Texas)
8992012-12-01 18:30:01.943597 I  TVRec(6): RingBufferChanged()
9002012-12-01 18:30:01.944625 I  TVRec(6): FinishedRecording(1039_2012-12-02T00:17:45Z) good recq:<RecordingQuality overall_score="1" key="1039_2012-12-02T00:17:45Z" />
901
9022012-12-01 18:30:01.944710 I  TVRec(6): FinishedRecording(1039_2012-12-02T00:17:45Z)
903                        title: Storage Wars Texas
904                        in recgroup: LiveTV status: Unknown:Recorder Failed not_dummy finished_now
9052012-12-01 18:30:01.945042 I  Chain: Updated endtime for '1039_20121202001745' to 20121202003001
9062012-12-01 18:30:01.945805 I  SaveVideoProperties(0x38, 0x20)
9072012-12-01 18:30:01.949122 I  DTVRec(6): FindPSKeyFrames: frame rate = 29970
9082012-12-01 18:30:01.966598 I  RecBase(6:/dev/video2): GetKeyframePositions(0,9223372036854775807,#4) out of 4
9092012-12-01 18:30:04.417556 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
9102012-12-01 18:30:06.924467 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
9112012-12-01 18:30:09.430733 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
9122012-12-01 18:30:11.938176 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
9132012-12-01 18:30:14.445694 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
9142012-12-01 18:30:19.458230 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
9152012-12-01 18:30:21.965367 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
9162012-12-01 18:30:26.978328 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
9172012-12-01 18:30:29.483214 W  DevRdB(/dev/video2): Poll took an unusually long time 2501 ms
9182012-12-01 18:30:31.988776 W  DevRdB(/dev/video2): Poll took an unusually long time 2502 ms
9192012-12-01 18:30:34.494062 W  DevRdB(/dev/video2): Poll took an unusually long time 2503 ms
9202012-12-01 18:30:38.490561 I  TVRec(6): StopLiveTV(void) curRec: 0x7f40ec08f820 pseudoRec: 0x0
9212012-12-01 18:30:38.491540 I  TVRec(6): Changing from WatchingLiveTV to None
9222012-12-01 18:30:38.491561 I  TVRec(6): ClearFlags(FrontendReady,CancelNextRecording,) -> RunMainLoop,RecorderRunning,RingBufferReady,
9232012-12-01 18:30:38.491576 I  TVRec(6): HandleTuning Request: Program(NULL) channel() input() flags(KillRec,KillRingBuffer,)
9242012-12-01 18:30:38.518835 I  MPEGRec(/dev/video2): run finishing up
9252012-12-01 18:30:38.518845 I  MPEGRec(/dev/video2): StopEncoding
9262012-12-01 18:30:38.538929 I  DevRdB(/dev/video2): Stop() -- begin
9272012-12-01 18:30:38.539173 I  DevRdB(/dev/video2): Stop() -- end
9282012-12-01 18:30:38.841459 I  TVRec(6): ClearFlags(RecorderRunning,) -> RunMainLoop,RingBufferReady,
9292012-12-01 18:30:38.841560 I  RecordingQuality() start(2012-12-02T00:30:00Z) end(2012-12-02T01:00:00Z) score(1)
9302012-12-01 18:30:38.841634 I  RecBase(6:/dev/video2): SetRecording(0x0)
9312012-12-01 18:30:38.842213 I  TVRec(6): FinishedRecording(1039_2012-12-02T00:30:00Z) good recq:<RecordingQuality overall_score="1" key="1039_2012-12-02T00:30:00Z" />
932
9332012-12-01 18:30:38.842265 I  TVRec(6): FinishedRecording(1039_2012-12-02T00:30:00Z)
934                        title: Storage Wars Texas
935                        in recgroup: LiveTV status: Recorder Failed:Recorder Failed not_dummy finished_now
9362012-12-01 18:30:38.842587 I  Chain: Updated endtime for '1039_20121202003000' to 20121202003038
9372012-12-01 18:30:38.843259 I  SaveVideoProperties(0x38, 0x20)
9382012-12-01 18:30:38.846139 I  TVRec(6): ClearFlags(RecorderRunning,) -> RunMainLoop,RingBufferReady,
9392012-12-01 18:30:38.846152 I  TVRec(6): Tearing down RingBuffer
9402012-12-01 18:30:38.846346 I  TVRec(6): ClearFlags(PENDINGACTIONS,) -> RunMainLoop,RingBufferReady,
9412012-12-01 18:30:38.846661 I  TVRec(6): SetFlags(FrontendReady,) -> FrontendReady,RunMainLoop,RingBufferReady,
9422012-12-01 18:30:38.849742 I  Getting next free recorder after : -1
9432012-12-01 18:30:38.849752 I  Checking card 5. Best card so far -1
9442012-12-01 18:30:38.850224 I  Checking card 6. Best card so far 5
9452012-12-01 18:30:38.850639 I  Checking card 7. Best card so far 6
9462012-12-01 18:30:38.851410 I  Checking card 8. Best card so far 6
9472012-12-01 18:30:38.852125 I  Best card is 6
9482012-12-01 18:30:38.856683 I  MainServer::ANN Playback
9492012-12-01 18:30:38.856691 I  adding: zeus as a client (events: 0)
9502012-12-01 18:30:38.863219 I  TVRec(6): Found channel (39) on current card(6).
9512012-12-01 18:30:38.874174 I  TVRec(6): Changing from None to WatchingLiveTV
9522012-12-01 18:30:38.874203 I  TVRec(6): ClearFlags(FrontendReady,CancelNextRecording,) -> RunMainLoop,RingBufferReady,
9532012-12-01 18:30:38.874218 I  TVRec(6): HandleTuning Request: Program(NULL) channel() input() flags(LiveTV,)
9542012-12-01 18:30:38.874233 I  ChannelBase(6): Looking for startchannel '39' on input 'tuner'
9552012-12-01 18:30:38.894865 I  ChannelBase(6): Found startchannel '39' on input 'tuner'
9562012-12-01 18:30:38.894940 I  TVRec(6): HW Tuner: 6->6
9572012-12-01 18:30:38.894954 I  TVRec(6): ClearFlags(PENDINGACTIONS,) -> RunMainLoop,RingBufferReady,
9582012-12-01 18:30:38.894964 I  TVRec(6): No recorder yet, calling TuningFrequency
9592012-12-01 18:30:38.895324 I  V4LChannel(/dev/video2): Device name 'Hauppauge WinTV-HVR2250' driver 'saa7164'.
9602012-12-01 18:30:38.895342 I  V4LChannel(/dev/video2): v4l2: 1 stream io: 0 std io: 1 async io: 0 tuner 1 sliced vbi 0
9612012-12-01 18:30:38.903175 I  ChannelBase(6): Input #6: 'tuner' schan(39) sourceid(1) ccid(6)
9622012-12-01 18:30:38.903187 I  ChannelBase(6): Current Input #6: 'tuner'
9632012-12-01 18:30:38.903798 I  Global TVFormat Setting 'NTSC'
9642012-12-01 18:30:38.903833 I  V4LChannel(/dev/video2): Input #6: 'tuner' schan(39) tun() v4l1(Unknown) v4l2(NTSC)
9652012-12-01 18:30:38.903846 I  V4LChannel(/dev/video2): SetFormat(Default) fmt(NTSC) input(6)
9662012-12-01 18:30:38.903856 I  Channel(/dev/video2)::SwitchToInput(in 6, '')
9672012-12-01 18:30:38.915955 I  V4LChannel(/dev/video2): SetInputAndFormat(6, NTSC) (v4l v2) input_switch: 0 mode_switch: 1
9682012-12-01 18:30:38.918225 I  DTVChan(/dev/video2): SetChannelByString(39):
9692012-12-01 18:30:38.919720 I  V4LChannel(/dev/video2): SetFormat(Default) fmt(NTSC) input(6)
9702012-12-01 18:30:38.919736 I  Channel(/dev/video2)::Tune(39): curList[37].freq(313250)
9712012-12-01 18:30:38.919745 I  V4LChannel(/dev/video2): Tune(313250000, )
9722012-12-01 18:30:39.216968 I  Channel(/dev/video2)::Tune(): Frequency is now 313250000
9732012-12-01 18:30:39.216982 I  DTVChan(/dev/video2): SetChannelByString(39): success
9742012-12-01 18:30:39.222496 I  TVRec(6): CreateLiveTVRingBuffer(39)
9752012-12-01 18:30:39.222928 I  TVRec(6): GetProgramRingBufferForLiveTV()
9762012-12-01 18:30:39.225533 N  AutoExpire: CalcParams(): Max required Free Space: 2.0 GB w/freq: 15 min
9772012-12-01 18:30:39.235376 I  TVRec(6): StartedRecording(1039_2012-12-02T00:30:39Z) fn(/home/mythtv/rec/1039_20121202003039.mpg)
9782012-12-01 18:30:39.236977 I  Chain: Appended@0 '1039_20121202003039'
9792012-12-01 18:30:39.237890 I  TVRec(6): Starting Signal Monitor
9802012-12-01 18:30:39.237901 I  TVRec(6): SetupSignalMonitor(1, 1)
9812012-12-01 18:30:39.237929 I  TVRec(6): Signal monitor successfully created
9822012-12-01 18:30:39.238063 I  TVRec(6): SetFlags(SignalMonitorRunning,) -> RunMainLoop,SignalMonitorRunning,RingBufferReady,
9832012-12-01 18:30:39.238080 I  TVRec(6): ClearFlags(WaitingForSignal,) -> RunMainLoop,SignalMonitorRunning,RingBufferReady,
9842012-12-01 18:30:39.238092 I  TVRec(6): SetFlags(WaitingForSignal,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning,RingBufferReady,
9852012-12-01 18:30:39.238105 I  TVRec(6): SetFlags(DummyRecorderRunning,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning,DummyRecorderRunning,RingBufferReady,
9862012-12-01 18:30:39.238111 I  DummyDTVRecorder -- started
9872012-12-01 18:30:39.238123 I  TVRec(6): SetFlags(RingBufferReady,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning,DummyRecorderRunning,RingBufferReady,
9882012-12-01 18:30:39.238135 I  TVRec(6): ClearFlags(NeedToStartRecorder,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning,DummyRecorderRunning,RingBufferReady,
9892012-12-01 18:30:39.238149 I  TVRec(6): SetFlags(NeedToStartRecorder,) -> RunMainLoop,WaitingForSignal,NeedToStartRecorder,SignalMonitorRunning,DummyRecorderRunning,RingBufferReady,
9902012-12-01 18:30:39.238160 I  TVRec(6): Got good signal
9912012-12-01 18:30:39.238207 I  TVRec(6): TeardownSignalMonitor() -- begin
9922012-12-01 18:30:39.288460 I  TVRec(6): TeardownSignalMonitor() -- end
9932012-12-01 18:30:39.288476 I  TVRec(6): ClearFlags(SignalMonitorRunning,) -> RunMainLoop,WaitingForSignal,NeedToStartRecorder,DummyRecorderRunning,RingBufferReady,
9942012-12-01 18:30:39.288488 I  TVRec(6): ClearFlags(WaitingForSignal,) -> RunMainLoop,NeedToStartRecorder,DummyRecorderRunning,RingBufferReady,
9952012-12-01 18:30:39.288515 I  TVRec(6): Starting Recorder
9962012-12-01 18:30:39.288880 I  TVRec(6): FinishedRecording(1039_2012-12-02T00:30:39Z)
997                        title: Storage Wars Texas
998                        in recgroup: LiveTV status: Recording:Recorded is_dummy finished_now
9992012-12-01 18:30:39.289149 I  Chain: Updated endtime for '1039_20121202003039' to 20121202003039
10002012-12-01 18:30:39.289571 I  TVRec(6): ClearFlags(DummyRecorderRunning,) -> RunMainLoop,NeedToStartRecorder,RingBufferReady,
10012012-12-01 18:30:39.335733 I  Using profile 'Live TV' to record
10022012-12-01 18:30:39.335758 I  TVRec(6): SwitchLiveTVRingBuffer(discont 1, set_next_rec 0) curRec(1039_2012-12-02T00:30:39Z) curRec.size(0)
10032012-12-01 18:30:39.336186 I  TVRec(6): GetProgramRingBufferForLiveTV()
10042012-12-01 18:30:39.339365 N  AutoExpire: CalcParams(): Max required Free Space: 2.0 GB w/freq: 15 min
10052012-12-01 18:30:39.344866 E  RecordingInfo::InsertProgram(ProgramInfo(1039_20121202003039.mpg): channame(A & E Network) startts(Sun Dec 2 00:30:00 2012) endts(Sun Dec 2 01:00:00 2012)
1006             recstartts(Sun Dec 2 00:30:39 2012) recendts(Sun Dec 2 01:00:00 2012)
1007             title(Storage Wars Texas)): recording already exists...
10082012-12-01 18:30:39.346786 I  TVRec(6): StartedRecording(1039_2012-12-02T00:30:40Z) fn(/home/mythtv/rec/1039_20121202003040.mpg)
10092012-12-01 18:30:39.348427 I  Chain: Appended@1 '1039_20121202003040'
10102012-12-01 18:30:39.348626 I  DTVRec(6): ResetForNewFile(void)
10112012-12-01 18:30:39.349190 I  RecBase(6:/dev/video2): SetRingBuffer(0x7f41400411d0) '/home/mythtv/rec/1039_20121202003040.mpg'
10122012-12-01 18:30:39.349202 I  RecBase(6:/dev/video2): SetRecording(0x7f414004d970) title(Storage Wars Texas)
10132012-12-01 18:30:39.354569 I  DTVRec(6): ResetForNewFile(void)
10142012-12-01 18:30:39.354569 I  TVRec(6): SetFlags(CancelNextRecording,) -> RunMainLoop,CancelNextRecording,NeedToStartRecorder,RingBufferReady,
10152012-12-01 18:30:39.355445 I  V4LRec(6:/dev/video2): vbi_format  rate: 27000000
1016                                  offset: 0
1017                        samples_per_line: 1440
1018                                  starts: 10, 274
1019                                  counts: 18, 18
1020                                   flags: 0x0
10212012-12-01 18:30:39.365588 I  DevRdB(/dev/video2): buffer size 9400 KB
10222012-12-01 18:30:39.365603 I  MPEGRec(/dev/video2): DRB ready
10232012-12-01 18:30:39.365654 I  MPEGRec(/dev/video2): Initial startup of recorder
10242012-12-01 18:30:39.365660 I  MPEGRec(/dev/video2): StartEncoding
10252012-12-01 18:30:39.365674 I  DevRdB(/dev/video2): Start() -- begin
10262012-12-01 18:30:39.365759 I  DevRdB(/dev/video2): Start() -- middle
10272012-12-01 18:30:39.365765 I  DevRdB(/dev/video2): Start() -- end
10282012-12-01 18:30:39.369710 I  TVRec(6): SetFlags(RecorderRunning,RingBufferReady,) -> RunMainLoop,CancelNextRecording,NeedToStartRecorder,RecorderRunning,RingBufferReady,
10292012-12-01 18:30:39.369727 I  TVRec(6): ClearFlags(NeedToStartRecorder,) -> RunMainLoop,CancelNextRecording,RecorderRunning,RingBufferReady,
10302012-12-01 18:30:39.979013 I  DTVRec(6): FindPSKeyFrames: frame rate = 29970
10312012-12-01 18:30:39.992815 I  TVRec(6): StopLiveTV(void) curRec: 0x7f414004d970 pseudoRec: 0x0
10322012-12-01 18:30:39.993261 I  TVRec(6): Changing from WatchingLiveTV to None
10332012-12-01 18:30:39.993283 I  TVRec(6): ClearFlags(FrontendReady,CancelNextRecording,) -> RunMainLoop,RecorderRunning,RingBufferReady,
10342012-12-01 18:30:39.993301 I  TVRec(6): HandleTuning Request: Program(NULL) channel() input() flags(KillRec,KillRingBuffer,)
10352012-12-01 18:30:40.483159 I  MPEGRec(/dev/video2): run finishing up
10362012-12-01 18:30:40.483170 I  MPEGRec(/dev/video2): StopEncoding
10372012-12-01 18:30:40.503257 I  DevRdB(/dev/video2): Stop() -- begin
10382012-12-01 18:30:40.503489 I  DevRdB(/dev/video2): Stop() -- end
10392012-12-01 18:30:40.769069 I  TVRec(6): ClearFlags(RecorderRunning,) -> RunMainLoop,RingBufferReady,
10402012-12-01 18:30:40.769166 I  RecordingQuality() start(2012-12-02T00:30:00Z) end(2012-12-02T01:00:00Z) score(1)
10412012-12-01 18:30:40.769233 I  RecBase(6:/dev/video2): SetRecording(0x0)
10422012-12-01 18:30:40.769746 I  TVRec(6): FinishedRecording(1039_2012-12-02T00:30:40Z) good recq:<RecordingQuality overall_score="1" key="1039_2012-12-02T00:30:40Z" />
1043
10442012-12-01 18:30:40.769799 I  TVRec(6): FinishedRecording(1039_2012-12-02T00:30:40Z)
1045                        title: Storage Wars Texas
1046                        in recgroup: LiveTV status: Recorder Failed:Recorder Failed not_dummy finished_now
10472012-12-01 18:30:40.770054 I  Chain: Updated endtime for '1039_20121202003040' to 20121202003040
10482012-12-01 18:30:40.770697 I  SaveVideoProperties(0x38, 0x20)
10492012-12-01 18:30:40.772110 I  TVRec(6): ClearFlags(RecorderRunning,) -> RunMainLoop,RingBufferReady,
10502012-12-01 18:30:40.772122 I  TVRec(6): Tearing down RingBuffer
10512012-12-01 18:30:40.772279 I  TVRec(6): ClearFlags(PENDINGACTIONS,) -> RunMainLoop,RingBufferReady,
10522012-12-01 18:31:02.599376 C  Received Interrupt: Code 128, PID 0, UID 0, Value 0x00000000
10532012-12-01 18:31:02.600956 N  MythBackend exiting
10542012-12-01 18:31:04.257658 I  TVRec(5): ClearFlags(RunMainLoop,) -> 0x0
10552012-12-01 18:31:04.258017 I  TVRec(5): ClearFlags(RecorderRunning,) -> 0x0
10562012-12-01 18:31:04.258047 I  TVRec(6): ClearFlags(RunMainLoop,) -> RingBufferReady,
10572012-12-01 18:31:04.258441 I  TVRec(6): ClearFlags(RecorderRunning,) -> RingBufferReady,
10582012-12-01 18:31:04.258473 I  TVRec(7): ClearFlags(RunMainLoop,) -> RingBufferReady,
10592012-12-01 18:31:04.258691 I  DVBChan(7:/dev/dvb/adapter0/frontend0): Closing DVB channel
10602012-12-01 18:31:04.258728 I  TVRec(7): ClearFlags(RecorderRunning,) -> RingBufferReady,
10612012-12-01 18:31:04.258750 I  TVRec(8): ClearFlags(RunMainLoop,) -> 0x0
10622012-12-01 18:31:04.258825 I  DVBChan(8:/dev/dvb/adapter0/frontend0): Closing DVB channel
10632012-12-01 18:31:04.258864 I  TVRec(8): ClearFlags(RecorderRunning,) -> 0x0
10642012-12-01 18:31:04.258896 I  Waiting for threads to exit.