2012-05-18 08:10:48.318824 C  mythbackend version: fixes/0.25 [v0.25-94-gec51a97] www.mythtv.org
2012-05-18 08:10:48.318843 C  Qt version: compile: 4.8.1, runtime: 4.8.1
2012-05-18 08:10:48.318845 N  Enabled verbose msgs:  general record channel
2012-05-18 08:10:48.318863 N  Setting Log Level to LOG_INFO
2012-05-18 08:10:48.318904 I  Added logging to the console
2012-05-18 08:10:48.318908 I  Added database logging to table logging
2012-05-18 08:10:48.318988 N  Setting up SIGHUP handler
2012-05-18 08:10:48.319051 N  Using runtime prefix = /usr
2012-05-18 08:10:48.319062 N  Using configuration directory = /root/.mythtv
2012-05-18 08:10:48.319266 I  Assumed character encoding: en_CA.UTF-8
2012-05-18 08:10:48.319607 N  Empty LocalHostName.
2012-05-18 08:10:48.319612 I  Using localhost value of mythserver
2012-05-18 08:10:48.345722 N  Setting QT default locale to EN_CA
2012-05-18 08:10:48.345866 I  Current locale EN_CA
2012-05-18 08:10:48.345960 N  Reading locale defaults from /usr/share/mythtv//locales/en_ca.xml
2012-05-18 08:10:48.376216 I  Current MythTV Schema Version (DBSchemaVer): 1299
2012-05-18 08:10:48.377463 I  Loading en_us translation for module mythfrontend
2012-05-18 08:10:48.379670 N  MythBackend: Starting up as the master server.
2012-05-18 08:10:48.392055 I  TVRec(1): Start channel: 2.
2012-05-18 08:10:48.392622 I  V4LChannel(/dev/video0): Device name 'Hauppauge WinTV PVR-250' driver 'ivtv'.
2012-05-18 08:10:48.392661 I  V4LChannel(/dev/video0): v4l2: 1 stream io: 0 std io: 1 async io: 0 tuner 1 sliced vbi 1
2012-05-18 08:10:48.411875 I  ChannelBase(1): Input #1: 'Tuner 1' schan(2) sourceid(1) ccid(1)
2012-05-18 08:10:48.411886 I  ChannelBase(1): Current Input #1: 'Tuner 1'
2012-05-18 08:10:48.413552 I  Global TVFormat Setting 'NTSC'
2012-05-18 08:10:48.413594 I  V4LChannel(/dev/video0): Input #1: 'Tuner 1' schan(2) tun() v4l1(Unknown) v4l2(NTSC)
2012-05-18 08:10:48.413603 I  V4LChannel(/dev/video0): SetFormat(Default) fmt(NTSC) input(1)
2012-05-18 08:10:48.413614 I  V4LChannel(/dev/video0): SetInputAndFormat(1, NTSC) (v4l v2) input_switch: 0 mode_switch: 0
2012-05-18 08:10:48.414429 I  V4LChannel(/dev/video0): SetFormat(NTSC) fmt(NTSC) input(1)
2012-05-18 08:10:48.416133 I  Channel(/dev/video0)::SwitchToInput(in 1, '')
2012-05-18 08:10:48.416995 I  V4LChannel(/dev/video0): SetInputAndFormat(1, NTSC) (v4l v2) input_switch: 0 mode_switch: 0
2012-05-18 08:10:48.417012 I  DTVChan(/dev/video0): SetChannelByString(2): 
2012-05-18 08:10:48.418750 I  V4LChannel(/dev/video0): SetFormat(Default) fmt(NTSC) input(1)
2012-05-18 08:10:48.418768 I  Channel(/dev/video0)::Tune(2): curList[0].freq(55250)
2012-05-18 08:10:48.418773 I  V4LChannel(/dev/video0): Tune(55250000, )
2012-05-18 08:10:48.424544 I  Channel(/dev/video0)::Tune(): Frequency is now 55250000
2012-05-18 08:10:48.424565 I  DTVChan(/dev/video0): SetChannelByString(2): success
2012-05-18 08:10:48.439432 I  TVRec(1): SetFlags(RunMainLoop,) -> RunMainLoop,
2012-05-18 08:10:48.439448 I  TVRec(1): ClearFlags(ExitPlayer,FinishRecording,) -> RunMainLoop,
2012-05-18 08:10:48.441382 I  TVRec(2): Start channel: 2.
2012-05-18 08:10:48.441681 I  V4LChannel(/dev/video1): Device name 'WinTV PVR 500 (unit #1)' driver 'ivtv'.
2012-05-18 08:10:48.441693 I  V4LChannel(/dev/video1): v4l2: 1 stream io: 0 std io: 1 async io: 0 tuner 1 sliced vbi 1
2012-05-18 08:10:48.448788 I  ChannelBase(2): Input #2: 'Tuner 1' schan(2) sourceid(1) ccid(2)
2012-05-18 08:10:48.448801 I  ChannelBase(2): Current Input #2: 'Tuner 1'
2012-05-18 08:10:48.448832 I  Global TVFormat Setting 'NTSC'
2012-05-18 08:10:48.448856 I  V4LChannel(/dev/video1): Input #2: 'Tuner 1' schan(2) tun() v4l1(Unknown) v4l2(NTSC)
2012-05-18 08:10:48.448864 I  V4LChannel(/dev/video1): SetFormat(Default) fmt(NTSC) input(2)
2012-05-18 08:10:48.448875 I  V4LChannel(/dev/video1): SetInputAndFormat(2, NTSC) (v4l v2) input_switch: 0 mode_switch: 0
2012-05-18 08:10:48.449529 I  V4LChannel(/dev/video1): SetFormat(NTSC) fmt(NTSC) input(2)
2012-05-18 08:10:48.449545 I  Channel(/dev/video1)::SwitchToInput(in 2, '')
2012-05-18 08:10:48.450199 I  V4LChannel(/dev/video1): SetInputAndFormat(2, NTSC) (v4l v2) input_switch: 0 mode_switch: 0
2012-05-18 08:10:48.450211 I  DTVChan(/dev/video1): SetChannelByString(2): 
2012-05-18 08:10:48.451534 I  V4LChannel(/dev/video1): SetFormat(Default) fmt(NTSC) input(2)
2012-05-18 08:10:48.451550 I  Channel(/dev/video1)::Tune(2): curList[0].freq(55250)
2012-05-18 08:10:48.451556 I  V4LChannel(/dev/video1): Tune(55250000, )
2012-05-18 08:10:48.468358 I  Channel(/dev/video1)::Tune(): Frequency is now 55250000
2012-05-18 08:10:48.468362 I  DTVChan(/dev/video1): SetChannelByString(2): success
2012-05-18 08:10:48.474011 I  TVRec(2): SetFlags(RunMainLoop,) -> RunMainLoop,
2012-05-18 08:10:48.474031 I  TVRec(2): ClearFlags(ExitPlayer,FinishRecording,) -> RunMainLoop,
2012-05-18 08:10:48.476214 I  TVRec(3): Start channel: 2.
2012-05-18 08:10:48.476525 I  V4LChannel(/dev/video2): Device name 'WinTV PVR 500 (unit #2)' driver 'ivtv'.
2012-05-18 08:10:48.476537 I  V4LChannel(/dev/video2): v4l2: 1 stream io: 0 std io: 1 async io: 0 tuner 1 sliced vbi 1
2012-05-18 08:10:48.483783 I  ChannelBase(3): Input #3: 'Tuner 1' schan(2) sourceid(1) ccid(3)
2012-05-18 08:10:48.483796 I  ChannelBase(3): Current Input #3: 'Tuner 1'
2012-05-18 08:10:48.483820 I  Global TVFormat Setting 'NTSC'
2012-05-18 08:10:48.483844 I  V4LChannel(/dev/video2): Input #3: 'Tuner 1' schan(2) tun() v4l1(Unknown) v4l2(NTSC)
2012-05-18 08:10:48.483852 I  V4LChannel(/dev/video2): SetFormat(Default) fmt(NTSC) input(3)
2012-05-18 08:10:48.483863 I  V4LChannel(/dev/video2): SetInputAndFormat(3, NTSC) (v4l v2) input_switch: 0 mode_switch: 0
2012-05-18 08:10:48.484547 I  V4LChannel(/dev/video2): SetFormat(NTSC) fmt(NTSC) input(3)
2012-05-18 08:10:48.484563 I  Channel(/dev/video2)::SwitchToInput(in 3, '')
2012-05-18 08:10:48.485235 I  V4LChannel(/dev/video2): SetInputAndFormat(3, NTSC) (v4l v2) input_switch: 0 mode_switch: 0
2012-05-18 08:10:48.485248 I  DTVChan(/dev/video2): SetChannelByString(2): 
2012-05-18 08:10:48.486682 I  V4LChannel(/dev/video2): SetFormat(Default) fmt(NTSC) input(3)
2012-05-18 08:10:48.486698 I  Channel(/dev/video2)::Tune(2): curList[0].freq(55250)
2012-05-18 08:10:48.486704 I  V4LChannel(/dev/video2): Tune(55250000, )
2012-05-18 08:10:48.502202 I  Channel(/dev/video2)::Tune(): Frequency is now 55250000
2012-05-18 08:10:48.502207 I  DTVChan(/dev/video2): SetChannelByString(2): success
2012-05-18 08:10:48.509519 I  TVRec(3): SetFlags(RunMainLoop,) -> RunMainLoop,
2012-05-18 08:10:48.509559 I  TVRec(3): ClearFlags(ExitPlayer,FinishRecording,) -> RunMainLoop,
2012-05-18 08:10:48.545748 I  Found 1 distinct programid authorities
2012-05-18 08:10:48.546338 I  New static DB connectionSchedCon
2012-05-18 08:10:48.555087 I  Listening on TCP 127.0.0.1:6544
2012-05-18 08:10:48.555121 I  Listening on TCP 10.0.0.1:6544
2012-05-18 08:10:49.565083 I  Main::Registering HttpStatus Extension
2012-05-18 08:10:49.570846 I  Listening on TCP 127.0.0.1:6543
2012-05-18 08:10:49.570954 I  Listening on TCP 10.0.0.1:6543
2012-05-18 08:10:49.576918 N  AutoExpire: CalcParams(): Max required Free Space: 1.0 GB w/freq: 15 min
2012-05-18 08:10:50.260099 I  MainServer::ANN Monitor
2012-05-18 08:10:50.260123 I  adding: mythfront as a client (events: 0)
2012-05-18 08:10:50.261832 I  MainServer::ANN Monitor
2012-05-18 08:10:50.261851 I  adding: mythfront as a client (events: 1)
2012-05-18 08:10:50.361201 I  Bonjour: Service registration complete: name 'Mythbackend on mythserver' type '_mythbackend-master._tcp.' domain: 'local.'
2012-05-18 08:10:51.565077 I  Reschedule requested for id -1.
2012-05-18 08:10:54.393825 I  Scheduled 1506 items in 2.8 = 0.09 match + 2.74 place
2012-05-18 08:10:54.676072 I  Scheduler: Seem to be woken up by USER
2012-05-18 08:10:56.290844 I  MainServer::ANN Monitor
2012-05-18 08:10:56.290861 I  adding: mythserver as a client (events: 2)
2012-05-18 08:10:58.559644 I  Running housekeeping thread
2012-05-18 08:11:00.511733 I  MainServer::ANN Monitor
2012-05-18 08:11:00.511777 I  adding: mythserver as a client (events: 2)
2012-05-18 08:11:01.520869 I  MainServer::ANN Monitor
2012-05-18 08:11:01.520875 I  adding: mythserver as a client (events: 2)
2012-05-18 08:11:06.072552 I  MainServer::ANN Monitor
2012-05-18 08:11:06.072596 I  adding: mythserver as a client (events: 2)
2012-05-18 08:11:07.652486 I  MainServer::ANN Monitor
2012-05-18 08:11:07.652504 I  adding: mythserver as a client (events: 2)
2012-05-18 08:11:07.662938 I  MainServer::ANN Monitor
2012-05-18 08:11:07.662955 I  adding: mythserver as a client (events: 2)
2012-05-18 08:11:08.678352 I  MainServer::ANN Monitor
2012-05-18 08:11:08.678435 I  adding: mythserver as a client (events: 2)
2012-05-18 08:11:08.728599 I  Running Grabber: /usr/share/mythtv/metadata/Movie/tmdb.py -l en -M CBS This Morning
2012-05-18 08:11:08.733206 I  Starting IO manager (write)
2012-05-18 08:11:08.733426 I  Starting IO manager (read)
2012-05-18 08:11:08.733629 I  Starting process signal handler
2012-05-18 08:11:08.733781 I  Starting process manager
2012-05-18 08:11:08.990713 I  MainServer::ANN Monitor
2012-05-18 08:11:08.990719 I  adding: mythserver as a client (events: 2)
2012-05-18 08:11:08.994101 I  MainServer::ANN Monitor
2012-05-18 08:11:08.994106 I  adding: mythserver as a client (events: 2)
2012-05-18 08:11:09.763580 I  Running Grabber: /usr/share/mythtv/metadata/Movie/tmdb.py -l en -M AB Twister
2012-05-18 08:11:09.894209 I  MainServer::ANN Monitor
2012-05-18 08:11:09.894218 I  adding: mythserver as a client (events: 2)
2012-05-18 08:11:10.440409 I  Running Grabber: /usr/share/mythtv/metadata/Television/ttvdb.py -l en -M CBS This Morning
2012-05-18 08:11:10.443020 I  Running Grabber: /usr/share/mythtv/metadata/Television/ttvdb.py -l en -M AB Twister
2012-05-18 08:11:12.594845 I  MainServer::ANN Monitor
2012-05-18 08:11:12.594863 I  adding: mythserver as a client (events: 2)
2012-05-18 08:11:13.362429 I  MainServer::ANN Monitor
2012-05-18 08:11:13.362435 I  adding: mythserver as a client (events: 2)
2012-05-18 08:11:13.365930 I  MainServer::ANN Monitor
2012-05-18 08:11:13.365936 I  adding: mythserver as a client (events: 2)
2012-05-18 08:11:14.249215 I  Running Grabber: /usr/share/mythtv/metadata/Movie/tmdb.py -l en -M Paid Programming
2012-05-18 08:11:14.653503 I  Running Grabber: /usr/share/mythtv/metadata/Television/ttvdb.py -l en -M Paid Programming
2012-05-18 08:11:15.162319 I  Running Grabber: /usr/share/mythtv/metadata/Television/ttvdb.py -l en -D 248938 1 1
2012-05-18 08:11:16.377331 I  Returning Metadata Results: Paid Programming 0 0
2012-05-18 08:11:18.103915 I  MainServer::ANN Monitor
2012-05-18 08:11:18.103966 I  adding: mythserver as a client (events: 2)
2012-05-18 08:11:18.108823 I  MainServer::ANN Monitor
2012-05-18 08:11:18.108851 I  adding: mythserver as a client (events: 2)
2012-05-18 08:11:19.069550 I  MainServer::ANN Monitor
2012-05-18 08:11:19.069571 I  adding: mythserver as a client (events: 2)
2012-05-18 08:11:19.070322 I  Reschedule requested for id 410.
2012-05-18 08:11:21.958577 I  Scheduled 1507 items in 2.9 = 0.03 match + 2.85 place
2012-05-18 08:11:22.227162 I  TVRec(1): RecordPending on inputid 1
2012-05-18 08:11:22.228071 I  TVRec(1): StartRecording("CBS This Morning")
2012-05-18 08:11:22.229297 I  TVRec(1): ASK_RECORDING 1 0 0 0
2012-05-18 08:11:22.344135 I  TVRec(1): StartedRecording(1017_2012-05-18T08:11:00) fn(/myth/1017_20120518081100.mpg)
2012-05-18 08:11:22.344255 I  TVRec(1): ClearFlags(CancelNextRecording,) -> RunMainLoop,
2012-05-18 08:11:22.344409 I  TVRec(1): Changing from None to RecordingOnly
2012-05-18 08:11:22.344492 I  TVRec(1): ClearFlags(FrontendReady,CancelNextRecording,) -> RunMainLoop,
2012-05-18 08:11:22.344663 I  TVRec(1): HandleTuning Request: Program(ProgramInfo(1017_20120518081100.mpg): channame(WIVB) startts(Fri May 18 07:00:00 2012) endts(Fri May 18 09:00:00 2012)
             recstartts(Fri May 18 08:11:00 2012) recendts(Fri May 18 09:00:00 2012)
             title(CBS This Morning)) channel() input() flags(Recording,)
2012-05-18 08:11:22.349943 I  TVRec(1): HW Tuner: 1->1
2012-05-18 08:11:22.349972 I  TVRec(1): ClearFlags(PENDINGACTIONS,) -> RunMainLoop,
2012-05-18 08:11:22.349989 I  TVRec(1): No recorder yet, calling TuningFrequency
2012-05-18 08:11:22.351657 I  V4LChannel(/dev/video0): Device name 'Hauppauge WinTV PVR-250' driver 'ivtv'.
2012-05-18 08:11:22.351696 I  V4LChannel(/dev/video0): v4l2: 1 stream io: 0 std io: 1 async io: 0 tuner 1 sliced vbi 1
2012-05-18 08:11:22.371242 I  ChannelBase(1): Input #1: 'Tuner 1' schan(2) sourceid(1) ccid(1)
2012-05-18 08:11:22.371253 I  ChannelBase(1): Current Input #1: 'Tuner 1'
2012-05-18 08:11:22.371292 I  Global TVFormat Setting 'NTSC'
2012-05-18 08:11:22.371312 I  V4LChannel(/dev/video0): Input #1: 'Tuner 1' schan(2) tun() v4l1(Unknown) v4l2(NTSC)
2012-05-18 08:11:22.371319 I  V4LChannel(/dev/video0): SetFormat(Default) fmt(NTSC) input(1)
2012-05-18 08:11:22.371325 I  Channel(/dev/video0)::SwitchToInput(in 1, '')
2012-05-18 08:11:22.372912 I  V4LChannel(/dev/video0): SetInputAndFormat(1, NTSC) (v4l v2) input_switch: 0 mode_switch: 0
2012-05-18 08:11:22.372923 I  DTVChan(/dev/video0): SetChannelByString(17): 
2012-05-18 08:11:22.374061 I  V4LChannel(/dev/video0): SetFormat(Default) fmt(NTSC) input(1)
2012-05-18 08:11:22.374071 I  Channel(/dev/video0)::Tune(17): curList[15].freq(139250)
2012-05-18 08:11:22.374075 I  V4LChannel(/dev/video0): Tune(139250000, )
2012-05-18 08:11:22.384752 I  Channel(/dev/video0)::Tune(): Frequency is now 139250000
2012-05-18 08:11:22.384755 I  DTVChan(/dev/video0): SetChannelByString(17): success
2012-05-18 08:11:22.386384 I  TVRec(1): Starting Signal Monitor
2012-05-18 08:11:22.386397 I  TVRec(1): SetupSignalMonitor(1, 0)
2012-05-18 08:11:22.386464 I  TVRec(1): Signal monitor successfully created
2012-05-18 08:11:22.390304 I  TVRec(1): SetFlags(SignalMonitorRunning,) -> RunMainLoop,SignalMonitorRunning,
2012-05-18 08:11:22.390312 I  TVRec(1): ClearFlags(WaitingForSignal,) -> RunMainLoop,SignalMonitorRunning,
2012-05-18 08:11:22.390317 I  TVRec(1): SetFlags(WaitingForSignal,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning,
2012-05-18 08:11:22.390322 I  TVRec(1): ClearFlags(NeedToStartRecorder,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning,
2012-05-18 08:11:22.390327 I  TVRec(1): SetFlags(NeedToStartRecorder,) -> RunMainLoop,WaitingForSignal,NeedToStartRecorder,SignalMonitorRunning,
2012-05-18 08:11:22.390335 I  TVRec(1): Got good signal
2012-05-18 08:11:22.390368 I  TVRec(1): TeardownSignalMonitor() -- begin
2012-05-18 08:11:22.437014 I  TVRec(1): TeardownSignalMonitor() -- end
2012-05-18 08:11:22.437059 I  TVRec(1): ClearFlags(SignalMonitorRunning,) -> RunMainLoop,WaitingForSignal,NeedToStartRecorder,
2012-05-18 08:11:22.437093 I  TVRec(1): ClearFlags(WaitingForSignal,) -> RunMainLoop,NeedToStartRecorder,
2012-05-18 08:11:22.437213 I  TVRec(1): Starting Recorder
2012-05-18 08:11:22.516610 I  Using profile 'Default' to record
2012-05-18 08:11:22.516639 I  TVRec(1): rec->GetPathname(): '/myth/1017_20120518081100.mpg'
2012-05-18 08:11:22.517184 I  DTVRec(1): ResetForNewFile(void)
2012-05-18 08:11:22.520325 I  RecBase(1:/dev/video0): SetRingBuffer(0x7f3f2801e9b0) '/myth/1017_20120518081100.mpg'
2012-05-18 08:11:22.520369 I  RecBase(1:/dev/video0): SetRecording(0x7f3f1088a2f0) title(CBS This Morning)
2012-05-18 08:11:22.529764 I  DTVRec(1): ResetForNewFile(void)
2012-05-18 08:11:22.536154 N  AutoExpire: CalcParams(): Max required Free Space: 2.0 GB w/freq: 15 min
2012-05-18 08:11:22.537580 I  Started recording: "CBS This Morning": channel 1017 on cardid 1, sourceid 1
2012-05-18 08:11:22.543159 I  MainServer::ANN Monitor
2012-05-18 08:11:22.543166 I  adding: mythserver as a client (events: 2)
2012-05-18 08:11:22.547398 I  DevRdB(/dev/video0): buffer size 9400 KB
2012-05-18 08:11:22.547414 I  MPEGRec(/dev/video0): DRB ready
2012-05-18 08:11:22.547434 I  MPEGRec(/dev/video0): Initial startup of recorder
2012-05-18 08:11:22.547439 I  MPEGRec(/dev/video0): StartEncoding
2012-05-18 08:11:22.547717 I  MainServer::ANN Monitor
2012-05-18 08:11:22.547723 I  adding: mythserver as a client (events: 2)
2012-05-18 08:11:22.558400 I  TVRec(1): SetFlags(RecorderRunning,RingBufferReady,) -> RunMainLoop,NeedToStartRecorder,RecorderRunning,RingBufferReady,
2012-05-18 08:11:22.663886 I  MainServer::ANN Monitor
2012-05-18 08:11:22.663892 I  adding: mythserver as a client (events: 2)
2012-05-18 08:11:22.668142 I  MainServer::ANN Monitor
2012-05-18 08:11:22.668148 I  adding: mythserver as a client (events: 2)
2012-05-18 08:11:22.757954 I  TVRec(1): ClearFlags(NeedToStartRecorder,) -> RunMainLoop,RecorderRunning,RingBufferReady,
2012-05-18 08:11:22.882439 I  MPEGRec(/dev/video0): Encoding started
2012-05-18 08:11:22.882458 I  DevRdB(/dev/video0): Start() -- begin
2012-05-18 08:11:22.882536 I  DevRdB(/dev/video0): Start() -- middle
2012-05-18 08:11:22.882541 I  DevRdB(/dev/video0): Start() -- end
2012-05-18 08:11:23.252297 I  MainServer::ANN Monitor
2012-05-18 08:11:23.252315 I  adding: mythserver as a client (events: 2)
2012-05-18 08:11:23.253346 I  Reschedule requested for id 411.
2012-05-18 08:11:25.385249 E  DevRdB(/dev/video0): Poll giving up 2
2012-05-18 08:11:25.385271 E  DevRdB(/dev/video0): fill_ringbuffer: error state
2012-05-18 08:11:25.385376 E  MPEGRec(/dev/video0): Device error detected
2012-05-18 08:11:25.385380 I  MPEGRec(/dev/video0): RestartEncoding
2012-05-18 08:11:25.385384 I  MPEGRec(/dev/video0): StopEncoding
2012-05-18 08:11:25.794450 I  Running Grabber: /usr/share/mythtv/metadata/Movie/tmdb.py -l en -M CBS This Morning
2012-05-18 08:11:26.192365 I  MainServer::ANN Monitor
2012-05-18 08:11:26.192372 I  adding: mythserver as a client (events: 0)
2012-05-18 08:11:26.194848 I  MainServer::ANN Monitor
2012-05-18 08:11:26.194857 I  adding: mythserver as a client (events: 1)
2012-05-18 08:11:26.302749 I  Running Grabber: /usr/share/mythtv/metadata/Television/ttvdb.py -l en -M CBS This Morning
2012-05-18 08:11:26.371491 I  MainServer::ANN Monitor
2012-05-18 08:11:26.371496 I  adding: mythserver as a client (events: 2)
2012-05-18 08:11:26.374521 I  MainServer::ANN Monitor
2012-05-18 08:11:26.374527 I  adding: mythserver as a client (events: 2)
2012-05-18 08:11:26.488252 I  Scheduled 1508 items in 3.2 = 0.03 match + 3.18 place
2012-05-18 08:11:26.490658 I  TVRec(2): RecordPending on inputid 2
2012-05-18 08:11:26.490866 I  TVRec(2): StartRecording("AB Twister")
2012-05-18 08:11:26.491914 I  TVRec(2): ASK_RECORDING 2 0 0 0
2012-05-18 08:11:26.504410 I  TVRec(2): StartedRecording(1018_2012-05-18T08:11:00) fn(/myth/1018_20120518081100.mpg)
2012-05-18 08:11:26.504458 I  TVRec(2): ClearFlags(CancelNextRecording,) -> RunMainLoop,
2012-05-18 08:11:26.504643 I  TVRec(2): Changing from None to RecordingOnly
2012-05-18 08:11:26.504652 I  TVRec(2): ClearFlags(FrontendReady,CancelNextRecording,) -> RunMainLoop,
2012-05-18 08:11:26.504700 I  TVRec(2): HandleTuning Request: Program(ProgramInfo(1018_20120518081100.mpg): channame(Shop TV Canada) startts(Fri May 18 08:00:00 2012) endts(Fri May 18 08:30:00 2012)
             recstartts(Fri May 18 08:11:00 2012) recendts(Fri May 18 08:30:00 2012)
             title(AB Twister)) channel() input() flags(Recording,)
2012-05-18 08:11:26.505991 I  TVRec(2): HW Tuner: 2->2
2012-05-18 08:11:26.506001 I  TVRec(2): ClearFlags(PENDINGACTIONS,) -> RunMainLoop,
2012-05-18 08:11:26.506006 I  TVRec(2): No recorder yet, calling TuningFrequency
2012-05-18 08:11:26.506436 I  V4LChannel(/dev/video1): Device name 'WinTV PVR 500 (unit #1)' driver 'ivtv'.
2012-05-18 08:11:26.506446 I  V4LChannel(/dev/video1): v4l2: 1 stream io: 0 std io: 1 async io: 0 tuner 1 sliced vbi 1
2012-05-18 08:11:26.511550 I  ChannelBase(2): Input #2: 'Tuner 1' schan(2) sourceid(1) ccid(2)
2012-05-18 08:11:26.511558 I  ChannelBase(2): Current Input #2: 'Tuner 1'
2012-05-18 08:11:26.511600 I  Global TVFormat Setting 'NTSC'
2012-05-18 08:11:26.511619 I  V4LChannel(/dev/video1): Input #2: 'Tuner 1' schan(2) tun() v4l1(Unknown) v4l2(NTSC)
2012-05-18 08:11:26.511626 I  V4LChannel(/dev/video1): SetFormat(Default) fmt(NTSC) input(2)
2012-05-18 08:11:26.511631 I  Channel(/dev/video1)::SwitchToInput(in 2, '')
2012-05-18 08:11:26.512581 I  V4LChannel(/dev/video1): SetInputAndFormat(2, NTSC) (v4l v2) input_switch: 0 mode_switch: 0
2012-05-18 08:11:26.512587 I  DTVChan(/dev/video1): SetChannelByString(18): 
2012-05-18 08:11:26.514616 I  V4LChannel(/dev/video1): SetFormat(Default) fmt(NTSC) input(2)
2012-05-18 08:11:26.514628 I  Channel(/dev/video1)::Tune(18): curList[16].freq(145250)
2012-05-18 08:11:26.514632 I  V4LChannel(/dev/video1): Tune(145250000, )
2012-05-18 08:11:26.540238 I  Channel(/dev/video1)::Tune(): Frequency is now 145250000
2012-05-18 08:11:26.540249 I  DTVChan(/dev/video1): SetChannelByString(18): success
2012-05-18 08:11:26.547690 I  TVRec(2): Starting Signal Monitor
2012-05-18 08:11:26.547698 I  TVRec(2): SetupSignalMonitor(1, 0)
2012-05-18 08:11:26.547721 I  TVRec(2): Signal monitor successfully created
2012-05-18 08:11:26.549804 I  TVRec(2): SetFlags(SignalMonitorRunning,) -> RunMainLoop,SignalMonitorRunning,
2012-05-18 08:11:26.549813 I  TVRec(2): ClearFlags(WaitingForSignal,) -> RunMainLoop,SignalMonitorRunning,
2012-05-18 08:11:26.549818 I  TVRec(2): SetFlags(WaitingForSignal,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning,
2012-05-18 08:11:26.549824 I  TVRec(2): ClearFlags(NeedToStartRecorder,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning,
2012-05-18 08:11:26.549829 I  TVRec(2): SetFlags(NeedToStartRecorder,) -> RunMainLoop,WaitingForSignal,NeedToStartRecorder,SignalMonitorRunning,
2012-05-18 08:11:26.553834 N  AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 15 min
2012-05-18 08:11:26.554139 I  Tuning recording: "AB Twister": channel 1018 on cardid 2, sourceid 1
2012-05-18 08:11:26.557341 I  TVRec(2): Got good signal
2012-05-18 08:11:26.557433 I  Updating status for "AB Twister" on cardid 2 (Tuning => Recording)
2012-05-18 08:11:26.558837 I  TVRec(2): TeardownSignalMonitor() -- begin
2012-05-18 08:11:26.612106 I  TVRec(2): TeardownSignalMonitor() -- end
2012-05-18 08:11:26.612131 I  TVRec(2): ClearFlags(SignalMonitorRunning,) -> RunMainLoop,WaitingForSignal,NeedToStartRecorder,
2012-05-18 08:11:26.612139 I  TVRec(2): ClearFlags(WaitingForSignal,) -> RunMainLoop,NeedToStartRecorder,
2012-05-18 08:11:26.612177 I  TVRec(2): Starting Recorder
2012-05-18 08:11:26.630493 I  Using profile 'Default' to record
2012-05-18 08:11:26.630503 I  TVRec(2): rec->GetPathname(): '/myth/1018_20120518081100.mpg'
2012-05-18 08:11:26.630664 I  DTVRec(2): ResetForNewFile(void)
2012-05-18 08:11:26.630741 I  RecBase(2:/dev/video1): SetRingBuffer(0x7f3f1c04d760) '/myth/1018_20120518081100.mpg'
2012-05-18 08:11:26.630750 I  RecBase(2:/dev/video1): SetRecording(0x7f3f10446e10) title(AB Twister)
2012-05-18 08:11:26.636747 I  DTVRec(2): ResetForNewFile(void)
2012-05-18 08:11:26.667586 I  DevRdB(/dev/video1): buffer size 9400 KB
2012-05-18 08:11:26.667598 I  MPEGRec(/dev/video1): DRB ready
2012-05-18 08:11:26.667608 I  MPEGRec(/dev/video1): Initial startup of recorder
2012-05-18 08:11:26.667612 I  MPEGRec(/dev/video1): StartEncoding
2012-05-18 08:11:26.668958 I  TVRec(2): SetFlags(RecorderRunning,RingBufferReady,) -> RunMainLoop,NeedToStartRecorder,RecorderRunning,RingBufferReady,
2012-05-18 08:11:26.669633 I  TVRec(2): ClearFlags(NeedToStartRecorder,) -> RunMainLoop,RecorderRunning,RingBufferReady,
2012-05-18 08:11:27.058455 I  MPEGRec(/dev/video1): Encoding started
2012-05-18 08:11:27.058467 I  DevRdB(/dev/video1): Start() -- begin
2012-05-18 08:11:27.058508 I  DevRdB(/dev/video1): Start() -- middle
2012-05-18 08:11:27.058510 I  DevRdB(/dev/video1): Start() -- end
2012-05-18 08:11:27.148668 I  Running Grabber: /usr/share/mythtv/metadata/Movie/tmdb.py -l en -M AB Twister
2012-05-18 08:11:27.405112 E  Preview: Encountered problems running '/usr/bin/mythpreviewgen --size 0x0 --chanid 1017 --starttime 20120518081100 --outfile "/myth/1017_20120518081100.mpg.png" --verbose general,record,channel --loglevel info --quiet' (128)
2012-05-18 08:11:27.482657 I  MPEGRec(/dev/video0): Encoding stopped
2012-05-18 08:11:27.482718 I  MPEGRec(/dev/video0): StartEncoding
2012-05-18 08:11:27.492737 I  MainServer::ANN Monitor
2012-05-18 08:11:27.492745 I  adding: mythserver as a client (events: 2)
2012-05-18 08:11:27.498167 I  MainServer::ANN Monitor
2012-05-18 08:11:27.498173 I  adding: mythserver as a client (events: 2)
2012-05-18 08:11:27.505501 I  Running Grabber: /usr/share/mythtv/metadata/Television/ttvdb.py -l en -M AB Twister
2012-05-18 08:11:27.830539 I  MPEGRec(/dev/video0): Encoding started
2012-05-18 08:11:27.830577 I  DevRdB(/dev/video0): Start() -- begin
2012-05-18 08:11:27.830656 I  DevRdB(/dev/video0): Start() -- middle
2012-05-18 08:11:27.830666 I  DevRdB(/dev/video0): Start() -- end
2012-05-18 08:11:28.216448 I  MainServer::ANN Monitor
2012-05-18 08:11:28.216457 I  adding: mythserver as a client (events: 2)
2012-05-18 08:11:28.217090 I  Reschedule requested for id 412.
2012-05-18 08:11:29.559126 E  DevRdB(/dev/video1): Poll giving up 2
2012-05-18 08:11:29.559153 E  DevRdB(/dev/video1): fill_ringbuffer: error state
2012-05-18 08:11:29.559393 E  MPEGRec(/dev/video1): Device error detected
2012-05-18 08:11:29.559412 I  MPEGRec(/dev/video1): RestartEncoding
2012-05-18 08:11:29.559423 I  MPEGRec(/dev/video1): StopEncoding
2012-05-18 08:11:30.333445 E  DevRdB(/dev/video0): Poll giving up 2
2012-05-18 08:11:30.333454 E  DevRdB(/dev/video0): fill_ringbuffer: error state
2012-05-18 08:11:30.333497 E  MPEGRec(/dev/video0): Device error detected
2012-05-18 08:11:30.333505 I  MPEGRec(/dev/video0): RestartEncoding
2012-05-18 08:11:30.333509 I  MPEGRec(/dev/video0): StopEncoding
2012-05-18 08:11:31.658522 I  MPEGRec(/dev/video1): Encoding stopped
2012-05-18 08:11:31.658553 I  MPEGRec(/dev/video1): StartEncoding
2012-05-18 08:11:31.850859 I  Scheduled 1509 items in 3.6 = 0.06 match + 3.57 place
2012-05-18 08:11:31.853191 I  TVRec(3): RecordPending on inputid 3
2012-05-18 08:11:31.853396 I  TVRec(3): StartRecording("Paid Programming")
2012-05-18 08:11:32.025924 I  TVRec(3): StartedRecording(1020_2012-05-18T08:12:00) fn(/myth/1020_20120518081200.mpg)
2012-05-18 08:11:32.025962 I  TVRec(3): ClearFlags(CancelNextRecording,) -> RunMainLoop,
2012-05-18 08:11:32.026002 I  TVRec(3): Changing from None to RecordingOnly
2012-05-18 08:11:32.026016 I  TVRec(3): ClearFlags(FrontendReady,CancelNextRecording,) -> RunMainLoop,
2012-05-18 08:11:32.026056 I  TVRec(3): HandleTuning Request: Program(ProgramInfo(1020_20120518081200.mpg): channame(WUTV) startts(Fri May 18 08:00:00 2012) endts(Fri May 18 08:30:00 2012)
             recstartts(Fri May 18 08:12:00 2012) recendts(Fri May 18 08:30:00 2012)
             title(Paid Programming)) channel() input() flags(Recording,)
2012-05-18 08:11:32.027132 I  TVRec(3): HW Tuner: 3->3
2012-05-18 08:11:32.027141 I  TVRec(3): ClearFlags(PENDINGACTIONS,) -> RunMainLoop,
2012-05-18 08:11:32.027146 I  TVRec(3): No recorder yet, calling TuningFrequency
2012-05-18 08:11:32.027594 I  V4LChannel(/dev/video2): Device name 'WinTV PVR 500 (unit #2)' driver 'ivtv'.
2012-05-18 08:11:32.027603 I  V4LChannel(/dev/video2): v4l2: 1 stream io: 0 std io: 1 async io: 0 tuner 1 sliced vbi 1
2012-05-18 08:11:32.032759 I  ChannelBase(3): Input #3: 'Tuner 1' schan(2) sourceid(1) ccid(3)
2012-05-18 08:11:32.032768 I  ChannelBase(3): Current Input #3: 'Tuner 1'
2012-05-18 08:11:32.032808 I  Global TVFormat Setting 'NTSC'
2012-05-18 08:11:32.032828 I  V4LChannel(/dev/video2): Input #3: 'Tuner 1' schan(2) tun() v4l1(Unknown) v4l2(NTSC)
2012-05-18 08:11:32.032834 I  V4LChannel(/dev/video2): SetFormat(Default) fmt(NTSC) input(3)
2012-05-18 08:11:32.032839 I  Channel(/dev/video2)::SwitchToInput(in 3, '')
2012-05-18 08:11:32.033787 I  V4LChannel(/dev/video2): SetInputAndFormat(3, NTSC) (v4l v2) input_switch: 0 mode_switch: 0
2012-05-18 08:11:32.033794 I  DTVChan(/dev/video2): SetChannelByString(20): 
2012-05-18 08:11:32.034940 I  V4LChannel(/dev/video2): SetFormat(Default) fmt(NTSC) input(3)
2012-05-18 08:11:32.034950 I  Channel(/dev/video2)::Tune(20): curList[18].freq(157250)
2012-05-18 08:11:32.034954 I  V4LChannel(/dev/video2): Tune(157250000, )
2012-05-18 08:11:32.042434 I  MPEGRec(/dev/video1): Encoding started
2012-05-18 08:11:32.042441 I  DevRdB(/dev/video1): Start() -- begin
2012-05-18 08:11:32.042472 I  DevRdB(/dev/video1): Start() -- middle
2012-05-18 08:11:32.042475 I  DevRdB(/dev/video1): Start() -- end
2012-05-18 08:11:32.050310 I  Channel(/dev/video2)::Tune(): Frequency is now 157250000
2012-05-18 08:11:32.050314 I  DTVChan(/dev/video2): SetChannelByString(20): success
2012-05-18 08:11:32.052026 I  TVRec(3): Starting Signal Monitor
2012-05-18 08:11:32.052034 I  TVRec(3): SetupSignalMonitor(1, 0)
2012-05-18 08:11:32.052050 I  TVRec(3): Signal monitor successfully created
2012-05-18 08:11:32.053139 I  TVRec(3): SetFlags(SignalMonitorRunning,) -> RunMainLoop,SignalMonitorRunning,
2012-05-18 08:11:32.053145 I  TVRec(3): ClearFlags(WaitingForSignal,) -> RunMainLoop,SignalMonitorRunning,
2012-05-18 08:11:32.053150 I  TVRec(3): SetFlags(WaitingForSignal,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning,
2012-05-18 08:11:32.053155 I  TVRec(3): ClearFlags(NeedToStartRecorder,) -> RunMainLoop,WaitingForSignal,SignalMonitorRunning,
2012-05-18 08:11:32.053167 I  TVRec(3): SetFlags(NeedToStartRecorder,) -> RunMainLoop,WaitingForSignal,NeedToStartRecorder,SignalMonitorRunning,
2012-05-18 08:11:32.054212 I  TVRec(3): Got good signal
2012-05-18 08:11:32.054245 I  TVRec(3): TeardownSignalMonitor() -- begin
2012-05-18 08:11:32.057200 N  AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 10 min
2012-05-18 08:11:32.057219 I  Tuning recording: "Paid Programming": channel 1020 on cardid 3, sourceid 1
2012-05-18 08:11:32.059522 I  Updating status for "Paid Programming" on cardid 3 (Tuning => Recording)
2012-05-18 08:11:32.104388 I  TVRec(3): TeardownSignalMonitor() -- end
2012-05-18 08:11:32.104396 I  TVRec(3): ClearFlags(SignalMonitorRunning,) -> RunMainLoop,WaitingForSignal,NeedToStartRecorder,
2012-05-18 08:11:32.104404 I  TVRec(3): ClearFlags(WaitingForSignal,) -> RunMainLoop,NeedToStartRecorder,
2012-05-18 08:11:32.104420 I  TVRec(3): Starting Recorder
2012-05-18 08:11:32.112240 I  Using profile 'Default' to record
2012-05-18 08:11:32.112249 I  TVRec(3): rec->GetPathname(): '/myth/1020_20120518081200.mpg'
2012-05-18 08:11:32.112422 I  DTVRec(3): ResetForNewFile(void)
2012-05-18 08:11:32.112491 I  RecBase(3:/dev/video2): SetRingBuffer(0x7f3f1804e850) '/myth/1020_20120518081200.mpg'
2012-05-18 08:11:32.112504 I  RecBase(3:/dev/video2): SetRecording(0x7f3f1047b480) title(Paid Programming)
2012-05-18 08:11:32.116671 I  DTVRec(3): ResetForNewFile(void)
2012-05-18 08:11:32.129813 I  DevRdB(/dev/video2): buffer size 9400 KB
2012-05-18 08:11:32.129822 I  MPEGRec(/dev/video2): DRB ready
2012-05-18 08:11:32.129842 I  MPEGRec(/dev/video2): Initial startup of recorder
2012-05-18 08:11:32.129850 I  MPEGRec(/dev/video2): StartEncoding
2012-05-18 08:11:32.134460 I  TVRec(3): SetFlags(RecorderRunning,RingBufferReady,) -> RunMainLoop,NeedToStartRecorder,RecorderRunning,RingBufferReady,
2012-05-18 08:11:32.135196 I  TVRec(3): ClearFlags(NeedToStartRecorder,) -> RunMainLoop,RecorderRunning,RingBufferReady,
2012-05-18 08:11:32.197365 I  MainServer::ANN Monitor
2012-05-18 08:11:32.197372 I  adding: mythserver as a client (events: 2)
2012-05-18 08:11:32.201113 I  MainServer::ANN Monitor
2012-05-18 08:11:32.201119 I  adding: mythserver as a client (events: 2)
2012-05-18 08:11:32.430565 I  MPEGRec(/dev/video0): Encoding stopped
2012-05-18 08:11:32.430593 I  MPEGRec(/dev/video0): StartEncoding
2012-05-18 08:11:32.482452 I  MPEGRec(/dev/video2): Encoding started
2012-05-18 08:11:32.482478 I  DevRdB(/dev/video2): Start() -- begin
2012-05-18 08:11:32.482547 I  DevRdB(/dev/video2): Start() -- middle
2012-05-18 08:11:32.482554 I  DevRdB(/dev/video2): Start() -- end
2012-05-18 08:11:32.766503 I  MPEGRec(/dev/video0): Encoding started
2012-05-18 08:11:32.766536 I  DevRdB(/dev/video0): Start() -- begin
2012-05-18 08:11:32.766678 I  DevRdB(/dev/video0): Start() -- middle
2012-05-18 08:11:32.766694 I  DevRdB(/dev/video0): Start() -- end
2012-05-18 08:11:32.778796 I  DTVRec(3): FindPSKeyFrames: frame rate = 29970
2012-05-18 08:11:34.553133 E  DevRdB(/dev/video1): Poll giving up 2
2012-05-18 08:11:34.553154 E  DevRdB(/dev/video1): fill_ringbuffer: error state
2012-05-18 08:11:34.553284 E  MPEGRec(/dev/video1): Device error detected
2012-05-18 08:11:34.553308 I  MPEGRec(/dev/video1): RestartEncoding
2012-05-18 08:11:34.553318 I  MPEGRec(/dev/video1): StopEncoding
2012-05-18 08:11:35.268169 E  DevRdB(/dev/video0): Poll giving up 2
2012-05-18 08:11:35.268209 E  DevRdB(/dev/video0): fill_ringbuffer: error state
2012-05-18 08:11:35.268434 E  MPEGRec(/dev/video0): Device error detected
2012-05-18 08:11:35.268445 I  MPEGRec(/dev/video0): RestartEncoding
2012-05-18 08:11:35.268456 I  MPEGRec(/dev/video0): StopEncoding
2012-05-18 08:11:36.650618 I  MPEGRec(/dev/video1): Encoding stopped
2012-05-18 08:11:36.650660 I  MPEGRec(/dev/video1): StartEncoding
2012-05-18 08:11:37.002499 I  MPEGRec(/dev/video1): Encoding started
2012-05-18 08:11:37.002527 I  DevRdB(/dev/video1): Start() -- begin
2012-05-18 08:11:37.002605 I  DevRdB(/dev/video1): Start() -- middle
2012-05-18 08:11:37.002614 I  DevRdB(/dev/video1): Start() -- end
2012-05-18 08:11:37.049808 I  MainServer::ANN Monitor
2012-05-18 08:11:37.049815 I  adding: mythserver as a client (events: 2)
2012-05-18 08:11:37.192405 I  MainServer::ANN Monitor
2012-05-18 08:11:37.192412 I  adding: mythserver as a client (events: 2)
2012-05-18 08:11:37.366521 I  MPEGRec(/dev/video0): Encoding stopped
2012-05-18 08:11:37.366539 I  MPEGRec(/dev/video0): StartEncoding
2012-05-18 08:11:37.710454 I  MPEGRec(/dev/video0): Encoding started
2012-05-18 08:11:37.710470 I  DevRdB(/dev/video0): Start() -- begin
2012-05-18 08:11:37.710545 I  DevRdB(/dev/video0): Start() -- middle
2012-05-18 08:11:37.710549 I  DevRdB(/dev/video0): Start() -- end
2012-05-18 08:11:37.858349 I  MainServer::ANN Monitor
2012-05-18 08:11:37.858355 I  adding: mythserver as a client (events: 0)
2012-05-18 08:11:37.858639 I  MainServer::ANN Monitor
2012-05-18 08:11:37.858646 I  adding: mythserver as a client (events: 1)
2012-05-18 08:11:37.882384 I  MainServer::ANN Monitor
2012-05-18 08:11:37.882399 I  adding: mythserver as a client (events: 0)
2012-05-18 08:11:37.883218 I  MainServer::ANN Monitor
2012-05-18 08:11:37.883231 I  adding: mythserver as a client (events: 1)
2012-05-18 08:11:37.922243 I  MainServer::ANN Monitor
2012-05-18 08:11:37.922260 I  adding: mythserver as a client (events: 0)
2012-05-18 08:11:37.923478 I  MainServer::ANN Monitor
2012-05-18 08:11:37.923496 I  adding: mythserver as a client (events: 1)
2012-05-18 08:11:39.003927 E  Preview: Encountered problems running '/usr/bin/mythpreviewgen --size 0x0 --chanid 1017 --starttime 20120518081100 --outfile "/myth/1017_20120518081100.mpg.png" --verbose general,record,channel --loglevel info --quiet' (128)
2012-05-18 08:11:39.003959 E  Preview: Encountered problems running '/usr/bin/mythpreviewgen --size 0x0 --chanid 1018 --starttime 20120518081100 --outfile "/myth/1018_20120518081100.mpg.png" --verbose general,record,channel --loglevel info --quiet' (128)
2012-05-18 08:11:39.505473 E  DevRdB(/dev/video1): Poll giving up 2
2012-05-18 08:11:39.505498 E  DevRdB(/dev/video1): fill_ringbuffer: error state
2012-05-18 08:11:39.505663 E  MPEGRec(/dev/video1): Device error detected
2012-05-18 08:11:39.505695 I  MPEGRec(/dev/video1): RestartEncoding
2012-05-18 08:11:39.505705 I  MPEGRec(/dev/video1): StopEncoding
2012-05-18 08:11:39.697542 I  Running Grabber: /usr/share/mythtv/metadata/Movie/tmdb.py -l en -M Paid Programming
2012-05-18 08:11:40.082755 I  MainServer::ANN Monitor
2012-05-18 08:11:40.082763 I  adding: mythserver as a client (events: 0)
2012-05-18 08:11:40.083048 I  MainServer::ANN Monitor
2012-05-18 08:11:40.083058 I  adding: mythserver as a client (events: 1)
2012-05-18 08:11:40.112432 I  Running Grabber: /usr/share/mythtv/metadata/Television/ttvdb.py -l en -M Paid Programming
2012-05-18 08:11:40.217038 E  DevRdB(/dev/video0): Poll giving up 2
2012-05-18 08:11:40.217047 E  DevRdB(/dev/video0): fill_ringbuffer: error state
2012-05-18 08:11:40.217190 E  MPEGRec(/dev/video0): Device error detected
2012-05-18 08:11:40.217197 I  MPEGRec(/dev/video0): RestartEncoding
2012-05-18 08:11:40.217202 I  MPEGRec(/dev/video0): StopEncoding
2012-05-18 08:11:40.413731 I  Running Grabber: /usr/share/mythtv/metadata/Television/ttvdb.py -l en -D 248938 1 1
2012-05-18 08:11:40.614139 I  Returning Metadata Results: Paid Programming 0 0
2012-05-18 08:11:41.007537 I  MainServer::ANN Monitor
2012-05-18 08:11:41.007542 I  adding: mythserver as a client (events: 0)
2012-05-18 08:11:41.007824 I  MainServer::ANN Monitor
2012-05-18 08:11:41.007828 I  adding: mythserver as a client (events: 1)
2012-05-18 08:11:41.602673 I  MPEGRec(/dev/video1): Encoding stopped
2012-05-18 08:11:41.602730 I  MPEGRec(/dev/video1): StartEncoding
2012-05-18 08:11:41.958489 I  MPEGRec(/dev/video1): Encoding started
2012-05-18 08:11:41.958515 I  DevRdB(/dev/video1): Start() -- begin
2012-05-18 08:11:41.958635 I  DevRdB(/dev/video1): Start() -- middle
2012-05-18 08:11:41.958645 I  DevRdB(/dev/video1): Start() -- end
2012-05-18 08:11:42.314717 I  MPEGRec(/dev/video0): Encoding stopped
2012-05-18 08:11:42.314783 I  MPEGRec(/dev/video0): StartEncoding
2012-05-18 08:11:42.658492 I  MPEGRec(/dev/video0): Encoding started
2012-05-18 08:11:42.658519 I  DevRdB(/dev/video0): Start() -- begin
2012-05-18 08:11:42.658609 I  DevRdB(/dev/video0): Start() -- middle
2012-05-18 08:11:42.658620 I  DevRdB(/dev/video0): Start() -- end
2012-05-18 08:11:44.461563 E  DevRdB(/dev/video1): Poll giving up 2
2012-05-18 08:11:44.461587 E  DevRdB(/dev/video1): fill_ringbuffer: error state
2012-05-18 08:11:44.461734 E  MPEGRec(/dev/video1): Device error detected
2012-05-18 08:11:44.461759 I  MPEGRec(/dev/video1): RestartEncoding
2012-05-18 08:11:44.461787 I  MPEGRec(/dev/video1): StopEncoding
2012-05-18 08:11:45.160011 E  DevRdB(/dev/video0): Poll giving up 2
2012-05-18 08:11:45.160049 E  DevRdB(/dev/video0): fill_ringbuffer: error state
2012-05-18 08:11:45.160280 E  MPEGRec(/dev/video0): Device error detected
2012-05-18 08:11:45.160292 I  MPEGRec(/dev/video0): RestartEncoding
2012-05-18 08:11:45.160302 I  MPEGRec(/dev/video0): StopEncoding
2012-05-18 08:11:46.558601 I  MPEGRec(/dev/video1): Encoding stopped
2012-05-18 08:11:46.558644 I  MPEGRec(/dev/video1): StartEncoding
2012-05-18 08:11:46.914492 I  MPEGRec(/dev/video1): Encoding started
2012-05-18 08:11:46.914519 I  DevRdB(/dev/video1): Start() -- begin
2012-05-18 08:11:46.914656 I  DevRdB(/dev/video1): Start() -- middle
2012-05-18 08:11:46.914667 I  DevRdB(/dev/video1): Start() -- end
2012-05-18 08:11:47.258627 I  MPEGRec(/dev/video0): Encoding stopped
2012-05-18 08:11:47.258673 I  MPEGRec(/dev/video0): StartEncoding
2012-05-18 08:11:47.594543 I  MPEGRec(/dev/video0): Encoding started
2012-05-18 08:11:47.594571 I  DevRdB(/dev/video0): Start() -- begin
2012-05-18 08:11:47.594651 I  DevRdB(/dev/video0): Start() -- middle
2012-05-18 08:11:47.594662 I  DevRdB(/dev/video0): Start() -- end
2012-05-18 08:11:49.415581 E  DevRdB(/dev/video1): Poll giving up 2
2012-05-18 08:11:49.415632 E  DevRdB(/dev/video1): fill_ringbuffer: error state
2012-05-18 08:11:49.415724 E  MPEGRec(/dev/video1): Device error detected
2012-05-18 08:11:49.415743 I  MPEGRec(/dev/video1): RestartEncoding
2012-05-18 08:11:49.415765 I  MPEGRec(/dev/video1): StopEncoding
2012-05-18 08:11:50.097520 E  DevRdB(/dev/video0): Poll giving up 2
2012-05-18 08:11:50.097543 E  DevRdB(/dev/video0): fill_ringbuffer: error state
2012-05-18 08:11:50.097779 E  MPEGRec(/dev/video0): Device error detected
2012-05-18 08:11:50.097790 I  MPEGRec(/dev/video0): RestartEncoding
2012-05-18 08:11:50.097800 I  MPEGRec(/dev/video0): StopEncoding
2012-05-18 08:11:51.514626 I  MPEGRec(/dev/video1): Encoding stopped
2012-05-18 08:11:51.514670 I  MPEGRec(/dev/video1): StartEncoding
2012-05-18 08:11:51.870499 I  MPEGRec(/dev/video1): Encoding started
2012-05-18 08:11:51.870526 I  DevRdB(/dev/video1): Start() -- begin
2012-05-18 08:11:51.870605 I  DevRdB(/dev/video1): Start() -- middle
2012-05-18 08:11:51.870615 I  DevRdB(/dev/video1): Start() -- end
2012-05-18 08:11:52.194629 I  MPEGRec(/dev/video0): Encoding stopped
2012-05-18 08:11:52.194676 I  MPEGRec(/dev/video0): StartEncoding
2012-05-18 08:11:52.530531 I  MPEGRec(/dev/video0): Encoding started
2012-05-18 08:11:52.530559 I  DevRdB(/dev/video0): Start() -- begin
2012-05-18 08:11:52.530638 I  DevRdB(/dev/video0): Start() -- middle
2012-05-18 08:11:52.530650 I  DevRdB(/dev/video0): Start() -- end
2012-05-18 08:11:54.371222 E  DevRdB(/dev/video1): Poll giving up 2
2012-05-18 08:11:54.371244 E  DevRdB(/dev/video1): fill_ringbuffer: error state
2012-05-18 08:11:54.371371 E  MPEGRec(/dev/video1): Device error detected
2012-05-18 08:11:54.371395 I  MPEGRec(/dev/video1): RestartEncoding
2012-05-18 08:11:54.371406 I  MPEGRec(/dev/video1): StopEncoding
2012-05-18 08:11:55.031754 E  DevRdB(/dev/video0): Poll giving up 2
2012-05-18 08:11:55.031776 E  DevRdB(/dev/video0): fill_ringbuffer: error state
2012-05-18 08:11:55.032002 E  MPEGRec(/dev/video0): Device error detected
2012-05-18 08:11:55.032014 I  MPEGRec(/dev/video0): RestartEncoding
2012-05-18 08:11:55.032025 I  MPEGRec(/dev/video0): StopEncoding
2012-05-18 08:11:56.470631 I  MPEGRec(/dev/video1): Encoding stopped
2012-05-18 08:11:56.470676 I  MPEGRec(/dev/video1): StartEncoding
2012-05-18 08:11:56.826496 I  MPEGRec(/dev/video1): Encoding started
2012-05-18 08:11:56.826524 I  DevRdB(/dev/video1): Start() -- begin
2012-05-18 08:11:56.826600 I  DevRdB(/dev/video1): Start() -- middle
2012-05-18 08:11:56.826610 I  DevRdB(/dev/video1): Start() -- end
2012-05-18 08:11:57.130608 I  MPEGRec(/dev/video0): Encoding stopped
2012-05-18 08:11:57.130653 I  MPEGRec(/dev/video0): StartEncoding
2012-05-18 08:11:57.466503 I  MPEGRec(/dev/video0): Encoding started
2012-05-18 08:11:57.466530 I  DevRdB(/dev/video0): Start() -- begin
2012-05-18 08:11:57.466613 I  DevRdB(/dev/video0): Start() -- middle
2012-05-18 08:11:57.466624 I  DevRdB(/dev/video0): Start() -- end
2012-05-18 08:11:59.329371 E  DevRdB(/dev/video1): Poll giving up 2
2012-05-18 08:11:59.329379 E  DevRdB(/dev/video1): fill_ringbuffer: error state
2012-05-18 08:11:59.329488 E  MPEGRec(/dev/video1): Device error detected
2012-05-18 08:11:59.329510 I  MPEGRec(/dev/video1): RestartEncoding
2012-05-18 08:11:59.329520 I  MPEGRec(/dev/video1): StopEncoding
2012-05-18 08:11:59.968907 E  DevRdB(/dev/video0): Poll giving up 2
2012-05-18 08:11:59.968928 E  DevRdB(/dev/video0): fill_ringbuffer: error state
2012-05-18 08:11:59.969167 E  MPEGRec(/dev/video0): Device error detected
2012-05-18 08:11:59.969179 I  MPEGRec(/dev/video0): RestartEncoding
2012-05-18 08:11:59.969188 I  MPEGRec(/dev/video0): StopEncoding
2012-05-18 08:12:01.426625 I  MPEGRec(/dev/video1): Encoding stopped
2012-05-18 08:12:01.426669 I  MPEGRec(/dev/video1): StartEncoding
2012-05-18 08:12:01.782498 I  MPEGRec(/dev/video1): Encoding started
2012-05-18 08:12:01.782525 I  DevRdB(/dev/video1): Start() -- begin
2012-05-18 08:12:01.782601 I  DevRdB(/dev/video1): Start() -- middle
2012-05-18 08:12:01.782611 I  DevRdB(/dev/video1): Start() -- end
2012-05-18 08:12:02.066658 I  MPEGRec(/dev/video0): Encoding stopped
2012-05-18 08:12:02.066705 I  MPEGRec(/dev/video0): StartEncoding
2012-05-18 08:12:02.402529 I  MPEGRec(/dev/video0): Encoding started
2012-05-18 08:12:02.402556 I  DevRdB(/dev/video0): Start() -- begin
2012-05-18 08:12:02.402636 I  DevRdB(/dev/video0): Start() -- middle
2012-05-18 08:12:02.402648 I  DevRdB(/dev/video0): Start() -- end
2012-05-18 08:12:04.285420 E  DevRdB(/dev/video1): Poll giving up 2
2012-05-18 08:12:04.285441 E  DevRdB(/dev/video1): fill_ringbuffer: error state
2012-05-18 08:12:04.285544 E  MPEGRec(/dev/video1): Device error detected
2012-05-18 08:12:04.285560 I  MPEGRec(/dev/video1): RestartEncoding
2012-05-18 08:12:04.285565 I  MPEGRec(/dev/video1): StopEncoding
2012-05-18 08:12:04.905482 E  DevRdB(/dev/video0): Poll giving up 2
2012-05-18 08:12:04.905502 E  DevRdB(/dev/video0): fill_ringbuffer: error state
2012-05-18 08:12:04.905733 E  MPEGRec(/dev/video0): Device error detected
2012-05-18 08:12:04.905745 I  MPEGRec(/dev/video0): RestartEncoding
2012-05-18 08:12:04.905755 I  MPEGRec(/dev/video0): StopEncoding
2012-05-18 08:12:06.382604 I  MPEGRec(/dev/video1): Encoding stopped
2012-05-18 08:12:06.382639 I  MPEGRec(/dev/video1): StartEncoding
2012-05-18 08:12:06.738503 I  MPEGRec(/dev/video1): Encoding started
2012-05-18 08:12:06.738530 I  DevRdB(/dev/video1): Start() -- begin
2012-05-18 08:12:06.738606 I  DevRdB(/dev/video1): Start() -- middle
2012-05-18 08:12:06.738616 I  DevRdB(/dev/video1): Start() -- end
2012-05-18 08:12:07.002610 I  MPEGRec(/dev/video0): Encoding stopped
2012-05-18 08:12:07.002656 I  MPEGRec(/dev/video0): StartEncoding
2012-05-18 08:12:07.076784 N  AutoExpire: CalcParams(): Max required Free Space: 3.0 GB w/freq: 10 min
2012-05-18 08:12:07.094231 N  Expiring 2225 MB for 1015 at 2011-07-03T21:00:00 => "Celebrity Rehab With Dr. Drew":Intake
2012-05-18 08:12:07.098285 E  ProgramInfo(1015_20110703210000.mpg): GetPlaybackURL: '1015_20110703210000.mpg' should be local, but it can not be found.
2012-05-18 08:12:07.098623 E  ERROR when trying to delete file: GetPlaybackURL/UNABLE/TO/FIND/LOCAL/FILE/ON/mythserver/1015_20110703210000.mpg. File doesn't exist.  Database metadata will not be removed.
2012-05-18 08:12:07.338446 I  MPEGRec(/dev/video0): Encoding started
2012-05-18 08:12:07.338458 I  DevRdB(/dev/video0): Start() -- begin
2012-05-18 08:12:07.338501 I  DevRdB(/dev/video0): Start() -- middle
2012-05-18 08:12:07.338505 I  DevRdB(/dev/video0): Start() -- end
2012-05-18 08:12:09.241434 E  DevRdB(/dev/video1): Poll giving up 2
2012-05-18 08:12:09.241456 E  DevRdB(/dev/video1): fill_ringbuffer: error state
2012-05-18 08:12:09.241589 E  MPEGRec(/dev/video1): Device error detected
2012-05-18 08:12:09.241610 I  MPEGRec(/dev/video1): RestartEncoding
2012-05-18 08:12:09.241620 I  MPEGRec(/dev/video1): StopEncoding
2012-05-18 08:12:09.841225 E  DevRdB(/dev/video0): Poll giving up 2
2012-05-18 08:12:09.841246 E  DevRdB(/dev/video0): fill_ringbuffer: error state
2012-05-18 08:12:09.841483 E  MPEGRec(/dev/video0): Device error detected
2012-05-18 08:12:09.841495 I  MPEGRec(/dev/video0): RestartEncoding
2012-05-18 08:12:09.841505 I  MPEGRec(/dev/video0): StopEncoding
2012-05-18 08:12:11.338621 I  MPEGRec(/dev/video1): Encoding stopped
2012-05-18 08:12:11.338663 I  MPEGRec(/dev/video1): StartEncoding
2012-05-18 08:12:11.694501 I  MPEGRec(/dev/video1): Encoding started
2012-05-18 08:12:11.694529 I  DevRdB(/dev/video1): Start() -- begin
2012-05-18 08:12:11.694606 I  DevRdB(/dev/video1): Start() -- middle
2012-05-18 08:12:11.694616 I  DevRdB(/dev/video1): Start() -- end
2012-05-18 08:12:11.938626 I  MPEGRec(/dev/video0): Encoding stopped
2012-05-18 08:12:11.938671 I  MPEGRec(/dev/video0): StartEncoding
2012-05-18 08:12:12.274511 I  MPEGRec(/dev/video0): Encoding started
2012-05-18 08:12:12.274541 I  DevRdB(/dev/video0): Start() -- begin
2012-05-18 08:12:12.274626 I  DevRdB(/dev/video0): Start() -- middle
2012-05-18 08:12:12.274637 I  DevRdB(/dev/video0): Start() -- end
2012-05-18 08:12:14.195036 E  DevRdB(/dev/video1): Poll giving up 2
2012-05-18 08:12:14.195045 E  DevRdB(/dev/video1): fill_ringbuffer: error state
2012-05-18 08:12:14.195182 E  MPEGRec(/dev/video1): Device error detected
2012-05-18 08:12:14.195185 I  MPEGRec(/dev/video1): RestartEncoding
2012-05-18 08:12:14.195188 I  MPEGRec(/dev/video1): StopEncoding
2012-05-18 08:12:14.777464 E  DevRdB(/dev/video0): Poll giving up 2
2012-05-18 08:12:14.777484 E  DevRdB(/dev/video0): fill_ringbuffer: error state
2012-05-18 08:12:14.777721 E  MPEGRec(/dev/video0): Device error detected
2012-05-18 08:12:14.777732 I  MPEGRec(/dev/video0): RestartEncoding
2012-05-18 08:12:14.777742 I  MPEGRec(/dev/video0): StopEncoding
2012-05-18 08:12:16.294585 I  MPEGRec(/dev/video1): Encoding stopped
2012-05-18 08:12:16.294629 I  MPEGRec(/dev/video1): StartEncoding
2012-05-18 08:12:16.650503 I  MPEGRec(/dev/video1): Encoding started
2012-05-18 08:12:16.650530 I  DevRdB(/dev/video1): Start() -- begin
2012-05-18 08:12:16.650607 I  DevRdB(/dev/video1): Start() -- middle
2012-05-18 08:12:16.650617 I  DevRdB(/dev/video1): Start() -- end
2012-05-18 08:12:16.874627 I  MPEGRec(/dev/video0): Encoding stopped
2012-05-18 08:12:16.874673 I  MPEGRec(/dev/video0): StartEncoding
2012-05-18 08:12:17.210533 I  MPEGRec(/dev/video0): Encoding started
2012-05-18 08:12:17.210561 I  DevRdB(/dev/video0): Start() -- begin
2012-05-18 08:12:17.210642 I  DevRdB(/dev/video0): Start() -- middle
2012-05-18 08:12:17.210653 I  DevRdB(/dev/video0): Start() -- end
2012-05-18 08:12:19.152384 E  DevRdB(/dev/video1): Poll giving up 2
2012-05-18 08:12:19.152405 E  DevRdB(/dev/video1): fill_ringbuffer: error state
2012-05-18 08:12:19.152486 E  MPEGRec(/dev/video1): Device error detected
2012-05-18 08:12:19.152506 I  MPEGRec(/dev/video1): RestartEncoding
2012-05-18 08:12:19.152517 I  MPEGRec(/dev/video1): StopEncoding
2012-05-18 08:12:19.713518 E  DevRdB(/dev/video0): Poll giving up 2
2012-05-18 08:12:19.713539 E  DevRdB(/dev/video0): fill_ringbuffer: error state
2012-05-18 08:12:19.713770 E  MPEGRec(/dev/video0): Device error detected
2012-05-18 08:12:19.713782 I  MPEGRec(/dev/video0): RestartEncoding
2012-05-18 08:12:19.713791 I  MPEGRec(/dev/video0): StopEncoding
2012-05-18 08:12:21.132398 I  MainServer::ANN Monitor
2012-05-18 08:12:21.132404 I  adding: mythserver as a client (events: 2)
2012-05-18 08:12:21.165656 I  MainServer::ANN Monitor
2012-05-18 08:12:21.165662 I  adding: mythserver as a client (events: 2)
2012-05-18 08:12:21.166161 I  TVRec(2): Changing from RecordingOnly to None
2012-05-18 08:12:21.166177 I  TVRec(2): ClearFlags(FrontendReady,CancelNextRecording,) -> RunMainLoop,RecorderRunning,RingBufferReady,
2012-05-18 08:12:21.166187 I  TVRec(2): HandleTuning Request: Program(NULL) channel() input() flags(CloseRec,KillRingBuffer,)
2012-05-18 08:12:21.250590 I  MPEGRec(/dev/video1): Encoding stopped
2012-05-18 08:12:21.250639 I  MPEGRec(/dev/video1): StartEncoding
2012-05-18 08:12:21.606499 I  MPEGRec(/dev/video1): Encoding started
2012-05-18 08:12:21.606529 I  DevRdB(/dev/video1): Start() -- begin
2012-05-18 08:12:21.606608 I  DevRdB(/dev/video1): Start() -- middle
2012-05-18 08:12:21.606618 I  DevRdB(/dev/video1): Start() -- end
2012-05-18 08:12:21.606651 I  MPEGRec(/dev/video1): StopEncoding
2012-05-18 08:12:21.810587 I  MPEGRec(/dev/video0): Encoding stopped
2012-05-18 08:12:21.810632 I  MPEGRec(/dev/video0): StartEncoding
2012-05-18 08:12:22.146464 I  MPEGRec(/dev/video0): Encoding started
2012-05-18 08:12:22.146480 I  DevRdB(/dev/video0): Start() -- begin
2012-05-18 08:12:22.146523 I  DevRdB(/dev/video0): Start() -- middle
2012-05-18 08:12:22.146528 I  DevRdB(/dev/video0): Start() -- end
2012-05-18 08:12:23.706639 I  MPEGRec(/dev/video1): Encoding stopped
2012-05-18 08:12:23.706679 E  DevRdB(/dev/video1): poll error
2012-05-18 08:12:23.706705 E  DevRdB(/dev/video1): fill_ringbuffer: error state
2012-05-18 08:12:23.706802 E  MPEGRec(/dev/video1): Device error detected
2012-05-18 08:12:23.706820 I  MPEGRec(/dev/video1): RestartEncoding
2012-05-18 08:12:23.726799 I  DevRdB(/dev/video1): Stop() -- begin
2012-05-18 08:12:23.726824 I  DevRdB(/dev/video1): Stop() -- end
2012-05-18 08:12:23.726950 I  MPEGRec(/dev/video1): StopEncoding
2012-05-18 08:12:23.726978 I  MPEGRec(/dev/video1): StartEncoding
2012-05-18 08:12:24.090500 I  MPEGRec(/dev/video1): Encoding started
2012-05-18 08:12:24.090529 I  DevRdB(/dev/video1): Start() -- begin
2012-05-18 08:12:24.090607 I  DevRdB(/dev/video1): Start() -- middle
2012-05-18 08:12:24.090617 I  DevRdB(/dev/video1): Start() -- end
2012-05-18 08:12:24.090634 I  MPEGRec(/dev/video1): run finishing up
2012-05-18 08:12:24.090643 I  MPEGRec(/dev/video1): StopEncoding
2012-05-18 08:12:24.112494 I  MainServer::ANN Monitor
2012-05-18 08:12:24.112500 I  adding: mythserver as a client (events: 2)
2012-05-18 08:12:24.142715 I  MainServer::ANN Monitor
2012-05-18 08:12:24.142721 I  adding: mythserver as a client (events: 2)
2012-05-18 08:12:24.143178 I  TVRec(3): Changing from RecordingOnly to None
2012-05-18 08:12:24.143190 I  TVRec(3): ClearFlags(FrontendReady,CancelNextRecording,) -> RunMainLoop,RecorderRunning,RingBufferReady,
2012-05-18 08:12:24.143198 I  TVRec(3): HandleTuning Request: Program(NULL) channel() input() flags(CloseRec,KillRingBuffer,)
2012-05-18 08:12:24.143204 I  MPEGRec(/dev/video2): StopEncoding
2012-05-18 08:12:24.383025 E  DevRdB(/dev/video2): poll error
2012-05-18 08:12:24.383068 E  DevRdB(/dev/video2): fill_ringbuffer: error state
2012-05-18 08:12:24.383304 E  MPEGRec(/dev/video2): Device error detected
2012-05-18 08:12:24.383321 I  MPEGRec(/dev/video2): RestartEncoding
2012-05-18 08:12:24.383343 I  MPEGRec(/dev/video2): Encoding stopped
2012-05-18 08:12:24.383374 I  MPEGRec(/dev/video2): StopEncoding
2012-05-18 08:12:24.383385 I  MPEGRec(/dev/video2): StartEncoding
2012-05-18 08:12:24.649259 E  DevRdB(/dev/video0): Poll giving up 2
2012-05-18 08:12:24.649279 E  DevRdB(/dev/video0): fill_ringbuffer: error state
2012-05-18 08:12:24.649508 E  MPEGRec(/dev/video0): Device error detected
2012-05-18 08:12:24.649519 I  MPEGRec(/dev/video0): RestartEncoding
2012-05-18 08:12:24.649529 I  MPEGRec(/dev/video0): StopEncoding
2012-05-18 08:12:24.734419 I  MPEGRec(/dev/video2): Encoding started
2012-05-18 08:12:24.734429 I  DevRdB(/dev/video2): Start() -- begin
2012-05-18 08:12:24.734459 I  DevRdB(/dev/video2): Start() -- middle
2012-05-18 08:12:24.734462 I  DevRdB(/dev/video2): Start() -- end
2012-05-18 08:12:24.734501 I  MPEGRec(/dev/video2): run finishing up
2012-05-18 08:12:24.734504 I  MPEGRec(/dev/video2): StopEncoding
2012-05-18 08:12:26.194754 I  MPEGRec(/dev/video1): Encoding stopped
2012-05-18 08:12:26.194776 E  DevRdB(/dev/video1): poll error
2012-05-18 08:12:26.194780 E  DevRdB(/dev/video1): fill_ringbuffer: error state
2012-05-18 08:12:26.214817 I  DevRdB(/dev/video1): Stop() -- begin
2012-05-18 08:12:26.214821 I  DevRdB(/dev/video1): Stop() -- end
2012-05-18 08:12:26.216347 I  TVRec(2): ClearFlags(RecorderRunning,) -> RunMainLoop,RingBufferReady,
2012-05-18 08:12:26.216386 I  MPEGRec(/dev/video1): StopEncoding
2012-05-18 08:12:26.216412 I  RecBase(2:/dev/video1): SetRecording(0x0)
2012-05-18 08:12:26.217435 I  TVRec(2): FinishedRecording(1018_2012-05-18T08:11:00) good recq:<RecordingQuality overall_score="1" key="1018_2012-05-18T08:11:00" />

2012-05-18 08:12:26.217481 I  TVRec(2): FinishedRecording(1018_2012-05-18T08:11:00)
			title: AB Twister
			in recgroup: Default status: Recording:Recorded not_dummy finished_now
2012-05-18 08:12:26.217901 I  SaveVideoProperties(0x38, 0x00)
2012-05-18 08:12:26.218626 I  Updating status for "AB Twister" on cardid 2 (Recording => Recorded)
2012-05-18 08:12:26.219839 I  Reschedule requested for id 0.
2012-05-18 08:12:26.223534 I  Finished recording AB Twister: channel 1018
2012-05-18 08:12:26.225013 I  TVRec(2): ClearFlags(RecorderRunning,) -> RunMainLoop,RingBufferReady,
2012-05-18 08:12:26.225026 I  TVRec(2): Tearing down RingBuffer
2012-05-18 08:12:26.225600 I  TVRec(2): ClearFlags(PENDINGACTIONS,) -> RunMainLoop,RingBufferReady,
2012-05-18 08:12:26.225653 I  TVRec(2): ClearFlags(CancelNextRecording,KillRec,) -> RunMainLoop,RingBufferReady,
2012-05-18 08:12:26.746566 I  MPEGRec(/dev/video0): Encoding stopped
2012-05-18 08:12:26.746594 I  MPEGRec(/dev/video0): StartEncoding
2012-05-18 08:12:26.834620 I  MPEGRec(/dev/video2): Encoding stopped
2012-05-18 08:12:26.834909 E  DevRdB(/dev/video2): poll error
2012-05-18 08:12:26.834924 E  DevRdB(/dev/video2): fill_ringbuffer: error state
2012-05-18 08:12:26.854776 I  DevRdB(/dev/video2): Stop() -- begin
2012-05-18 08:12:26.854800 I  DevRdB(/dev/video2): Stop() -- end
2012-05-18 08:12:26.973169 I  TVRec(3): ClearFlags(RecorderRunning,) -> RunMainLoop,RingBufferReady,
2012-05-18 08:12:26.973238 I  MPEGRec(/dev/video2): StopEncoding
2012-05-18 08:12:26.973326 I  RecBase(3:/dev/video2): SetRecording(0x0)
2012-05-18 08:12:26.974703 I  TVRec(3): FinishedRecording(1020_2012-05-18T08:12:00) good recq:<RecordingQuality overall_score="1" key="1020_2012-05-18T08:12:00" />

2012-05-18 08:12:26.974831 I  TVRec(3): FinishedRecording(1020_2012-05-18T08:12:00)
			title: Paid Programming
			in recgroup: Default status: Recording:Recorded not_dummy finished_now
2012-05-18 08:12:26.976509 I  SaveVideoProperties(0x38, 0x00)
2012-05-18 08:12:26.979416 I  Finished recording Paid Programming: channel 1020
2012-05-18 08:12:26.979780 I  TVRec(3): ClearFlags(RecorderRunning,) -> RunMainLoop,RingBufferReady,
2012-05-18 08:12:26.979786 I  TVRec(3): Tearing down RingBuffer
2012-05-18 08:12:26.979993 I  TVRec(3): ClearFlags(PENDINGACTIONS,) -> RunMainLoop,RingBufferReady,
2012-05-18 08:12:26.981019 I  TVRec(3): ClearFlags(CancelNextRecording,KillRec,) -> RunMainLoop,RingBufferReady,
2012-05-18 08:12:26.981041 I  Updating status for "Paid Programming" on cardid 3 (Recording => Recorded)
2012-05-18 08:12:27.082496 I  MPEGRec(/dev/video0): Encoding started
2012-05-18 08:12:27.082524 I  DevRdB(/dev/video0): Start() -- begin
2012-05-18 08:12:27.082603 I  DevRdB(/dev/video0): Start() -- middle
2012-05-18 08:12:27.082614 I  DevRdB(/dev/video0): Start() -- end
2012-05-18 08:12:27.893600 E  MainServer: PREVIEW_SUCCESS but no receivers.
2012-05-18 08:12:27.894897 I  MainServer::ANN Monitor
2012-05-18 08:12:27.894902 I  adding: mythserver as a client (events: 2)
2012-05-18 08:12:27.934698 I  MainServer::ANN Monitor
2012-05-18 08:12:27.934704 I  adding: mythserver as a client (events: 2)
2012-05-18 08:12:27.935455 I  TVRec(1): Changing from RecordingOnly to None
2012-05-18 08:12:27.935472 I  TVRec(1): ClearFlags(FrontendReady,CancelNextRecording,) -> RunMainLoop,RecorderRunning,RingBufferReady,
2012-05-18 08:12:27.935484 I  TVRec(1): HandleTuning Request: Program(NULL) channel() input() flags(CloseRec,KillRingBuffer,)
2012-05-18 08:12:27.935491 I  MPEGRec(/dev/video0): StopEncoding
2012-05-18 08:12:28.996749 I  Reschedule interrupted, will retry
2012-05-18 08:12:28.997030 I  Reschedule requested for id 0.
2012-05-18 08:12:28.997178 I  Reschedule requested for id 0.
2012-05-18 08:12:28.997225 I  Reschedule requested for id 0.
2012-05-18 08:12:29.585349 E  DevRdB(/dev/video0): Poll giving up 2
2012-05-18 08:12:29.585360 E  DevRdB(/dev/video0): fill_ringbuffer: error state
2012-05-18 08:12:29.585443 E  MPEGRec(/dev/video0): Device error detected
2012-05-18 08:12:29.585447 I  MPEGRec(/dev/video0): RestartEncoding
2012-05-18 08:12:30.034589 I  MPEGRec(/dev/video0): Encoding stopped
2012-05-18 08:12:30.034659 I  MPEGRec(/dev/video0): StopEncoding
2012-05-18 08:12:30.034671 I  MPEGRec(/dev/video0): StartEncoding
2012-05-18 08:12:30.390502 I  MPEGRec(/dev/video0): Encoding started
2012-05-18 08:12:30.390530 I  DevRdB(/dev/video0): Start() -- begin
2012-05-18 08:12:30.390609 I  DevRdB(/dev/video0): Start() -- middle
2012-05-18 08:12:30.390620 I  DevRdB(/dev/video0): Start() -- end
2012-05-18 08:12:30.390648 I  MPEGRec(/dev/video0): run finishing up
2012-05-18 08:12:30.390658 I  MPEGRec(/dev/video0): StopEncoding
2012-05-18 08:12:31.689489 I  Scheduled 1509 items in 2.7 = 0.00 match + 2.69 place
2012-05-18 08:12:32.490643 I  MPEGRec(/dev/video0): Encoding stopped
2012-05-18 08:12:32.490687 E  DevRdB(/dev/video0): poll error
2012-05-18 08:12:32.490729 E  DevRdB(/dev/video0): fill_ringbuffer: error state
2012-05-18 08:12:32.510804 I  DevRdB(/dev/video0): Stop() -- begin
2012-05-18 08:12:32.510830 I  DevRdB(/dev/video0): Stop() -- end
2012-05-18 08:12:32.684105 I  TVRec(1): ClearFlags(RecorderRunning,) -> RunMainLoop,RingBufferReady,
2012-05-18 08:12:32.684174 I  MPEGRec(/dev/video0): StopEncoding
2012-05-18 08:12:32.684246 I  RecBase(1:/dev/video0): SetRecording(0x0)
2012-05-18 08:12:32.685385 I  TVRec(1): FinishedRecording(1017_2012-05-18T08:11:00) good recq:<RecordingQuality overall_score="1" key="1017_2012-05-18T08:11:00" />

2012-05-18 08:12:32.685503 I  TVRec(1): FinishedRecording(1017_2012-05-18T08:11:00)
			title: CBS This Morning
			in recgroup: Default status: Recording:Recorded not_dummy finished_now
2012-05-18 08:12:32.686896 I  SaveVideoProperties(0x38, 0x00)
2012-05-18 08:12:32.690825 I  Finished recording CBS This Morning: channel 1017
2012-05-18 08:12:32.691167 I  TVRec(1): ClearFlags(RecorderRunning,) -> RunMainLoop,RingBufferReady,
2012-05-18 08:12:32.691174 I  TVRec(1): Tearing down RingBuffer
2012-05-18 08:12:32.694039 I  TVRec(1): ClearFlags(PENDINGACTIONS,) -> RunMainLoop,RingBufferReady,
2012-05-18 08:12:32.695069 I  TVRec(1): ClearFlags(CancelNextRecording,KillRec,) -> RunMainLoop,RingBufferReady,
2012-05-18 08:12:32.695093 I  Updating status for "CBS This Morning" on cardid 1 (Recording => Recorded)
2012-05-18 08:12:32.696005 I  Reschedule requested for id 0.
2012-05-18 08:12:32.697802 W  MainServer: Unknown socket closing MythSocket(0x2771010)
2012-05-18 08:12:32.698895 E  MythSocket(2771010:-1): writeStringList: Error, socket went unconnected.
			We wrote 0 of 53 bytes with 1 errors
			starts with: 45      BACKEND_MESSAGE[]:[]SCHEDULE_CHANGE[]:[]empty
2012-05-18 08:12:35.383495 I  Scheduled 1509 items in 2.7 = 0.00 match + 2.68 place
2012-05-18 08:12:35.386275 I  Reschedule requested for id 0.
2012-05-18 08:12:38.693457 I  Scheduled 1509 items in 3.3 = 0.00 match + 3.30 place
2012-05-18 08:12:38.990605 N  MythBackend exiting
2012-05-18 08:12:39.008266 I  Bonjour: De-registering service '_mythbackend-master._tcp.' on 'Mythbackend on mythserver'
2012-05-18 08:12:40.935830 I  TVRec(1): ClearFlags(RunMainLoop,) -> RingBufferReady,
2012-05-18 08:12:40.936547 I  TVRec(1): ClearFlags(RecorderRunning,) -> RingBufferReady,
2012-05-18 08:12:40.936591 I  TVRec(2): ClearFlags(RunMainLoop,) -> RingBufferReady,
2012-05-18 08:12:40.937411 I  TVRec(2): ClearFlags(RecorderRunning,) -> RingBufferReady,
2012-05-18 08:12:40.937453 I  TVRec(3): ClearFlags(RunMainLoop,) -> RingBufferReady,
2012-05-18 08:12:40.938264 I  TVRec(3): ClearFlags(RecorderRunning,) -> RingBufferReady,
2012-05-18 08:12:40.938316 I  Waiting for threads to exit.