2011-06-28 18:58:39.578125 [(20)]: Controller: epg stop
2011-06-28 18:58:39.593750 [(20)]: Controller: epg start
2011-06-28 18:58:59.484375 [(20)]: Controller: StartTimeShifting 211 WRCDT NBC 1035
2011-06-28 18:58:59.500000 [(20)]: Controller: find free card for channel I211.28458625.microsoft.com
2011-06-28 18:58:59.500000 [(20)]: Controller:   got 1 tuning details for I211.28458625.microsoft.com
2011-06-28 18:58:59.500000 [(20)]: Controller:   channel #1 ATSC:tv: I211.28458625.microsoft.com Freq:697250 ONID:0 TSID:4445 SID:1801 PMT:0x0 FTA:True LCN:10000 phys:211 maj:0 min:0 mod:Mod256Qam 
2011-06-28 18:58:59.515625 [(20)]: Controller:    card:4 type:Atsc is available priority:7 #users:0 same transponder:True
2011-06-28 18:58:59.515625 [(20)]: Controller:    card:5 type:Atsc is available priority:6 #users:0 same transponder:True
2011-06-28 18:58:59.531250 [(20)]: Controller:    card:2 type:Atsc is available priority:5 #users:0 same transponder:True
2011-06-28 18:58:59.531250 [(20)]: Controller:    card:3 type:Atsc is available priority:4 #users:0 same transponder:True
2011-06-28 18:58:59.531250 [(20)]: Controller:    card:6 type:Analog is disabled
2011-06-28 18:58:59.531250 [(20)]: Controller:    card:7 type:Analog is disabled
2011-06-28 18:58:59.531250 [(20)]: Controller:    card:8 type:RadioWebStream cannot tune to channel
2011-06-28 18:58:59.531250 [(20)]: Controller: found 4 available
2011-06-28 18:58:59.531250 [(20)]: AdvancedCardAllocation.GetAvailableCardsForChannel took 36 msec
2011-06-28 18:58:59.546875 [(20)]: card: CardTune 4 I211.28458625.microsoft.com setuptv-1035-4:4:-1
2011-06-28 18:58:59.546875 [(20)]: card: Tune 4 to I211.28458625.microsoft.com
2011-06-28 18:58:59.546875 [(20)]: card: user: setuptv-1035-4:4:-1 tune ATSC:tv: I211.28458625.microsoft.com Freq:697250 ONID:0 TSID:4445 SID:1801 PMT:0x0 FTA:True LCN:10000 phys:211 maj:0 min:0 mod:Mod256Qam
2011-06-28 18:58:59.562500 [(20)]: atsc:Tune:ATSC:tv: I211.28458625.microsoft.com Freq:697250 ONID:0 TSID:4445 SID:1801 PMT:0x0 FTA:True LCN:10000 phys:211 maj:0 min:0 mod:Mod256Qam 
2011-06-28 18:58:59.562500 [(20)]: atsc:using previous channel tuning settings
2011-06-28 18:58:59.562500 [(20)]: dvb:Submiting tunerequest Channel:I211.28458625.microsoft.com subChannel:-1 
2011-06-28 18:58:59.562500 [(20)]: dvb:Getting new subchannel
2011-06-28 18:58:59.562500 [(20)]: dvb:GetNewSubChannel:0 #0
2011-06-28 18:58:59.562500 [(20)]: TvDvbChannel ctor new subchIndex:0
2011-06-28 18:58:59.562500 [(20)]: dvb:Submit tunerequest size:1 new:0
2011-06-28 18:58:59.562500 [(20)]: subch:0 OnBeforeTune
2011-06-28 18:58:59.578125 [(20)]: subch:0 OnAfterTune
2011-06-28 18:58:59.578125 [(20)]: subch:0 OnGraphStart
2011-06-28 18:58:59.578125 [(20)]: dvb:  RunGraph
2011-06-28 18:58:59.906250 [(20)]: dvb:  LockedInOnSignal ok
2011-06-28 18:58:59.906250 [(20)]: subch:0 OnGraphStarted
2011-06-28 18:58:59.906250 [(20)]: subch:0 SetupPmtGrabber:pid 0 sid:709
2011-06-28 18:58:59.906250 [(20)]: subch:0 set pmt grabber pmt:0 sid:709
2011-06-28 18:58:59.906250 [(20)]: WaitForPMT: Waiting for PMT 0
2011-06-28 18:59:00.046875 [(14)]: subch:0 OnPMTReceived() pmt:30 ran:True dynamic:False
2011-06-28 18:59:00.046875 [(20)]: WaitForPMT: Found PMT after 0.140625 seconds.
2011-06-28 18:59:00.046875 [(20)]: subch:0 SendPmt:709 709 FFFFFFFF 14
2011-06-28 18:59:00.062500 [(20)]: Decode pmt
2011-06-28 18:59:00.062500 [(20)]: subch:0 SendPMT: Channel is FTA, nothing to do.
2011-06-28 18:59:00.062500 [(20)]: subch:0 SetMpegPidMapping
2011-06-28 18:59:00.062500 [(20)]: subch:0  pid:7C0 pcr
2011-06-28 18:59:00.062500 [(20)]: subch:0  pid:0 pmt
2011-06-28 18:59:00.062500 [(20)]: subch:0  pid:7C0 video type:MPEG-2
2011-06-28 18:59:00.062500 [(20)]: subch:0    map pid:7C0 video type:MPEG-2
2011-06-28 18:59:00.062500 [(20)]: subch:0  pid:7C1 audio lang: type:AC3
2011-06-28 18:59:00.062500 [(20)]: subch:0    map pid:7C1 audio lang: type:AC3
2011-06-28 18:59:00.078125 [(20)]: subch:0 stop tif
2011-06-28 18:59:00.078125 [(20)]: WaitForPmt: PMT handling took 0.03125 seconds.
2011-06-28 18:59:00.578125 [(20)]: card: Tuner locked: True
2011-06-28 18:59:00.578125 [(20)]: **************************************************
2011-06-28 18:59:00.578125 [(20)]: ***** SIGNAL LEVEL: 76, SIGNAL QUALITY: 53 *****
2011-06-28 18:59:00.578125 [(20)]: **************************************************
2011-06-28 18:59:00.578125 [(20)]: card: tuned user: setuptv-1035-4 subchannel: 0
2011-06-28 18:59:00.578125 [(20)]: user:setuptv-1035-4 add
2011-06-28 18:59:00.578125 [(20)]: card2:setuptv-1035-4 4 0
2011-06-28 18:59:00.578125 [(20)]: Controller: setuptv-1035-4 4 0
2011-06-28 18:59:00.593750 [(20)]: control2:setuptv-1035-4 4 0
2011-06-28 18:59:00.593750 [(20)]: Controller: delete timeshift files D:\zzzTVTimeshift\live4-0.ts
2011-06-28 18:59:00.593750 [(20)]: card: StartTimeShifting 4 D:\zzzTVTimeshift\live4-0.ts 
2011-06-28 18:59:00.609375 [(20)]: card: CAM enabled : False
2011-06-28 18:59:00.609375 [(20)]: subch:0 SetTimeShiftFileName:D:\zzzTVTimeshift\live4-0.ts
2011-06-28 18:59:00.609375 [(20)]: Set video / audio observer
2011-06-28 18:59:00.609375 [(20)]: subch:0 SetTimeShiftFileName fill in pids
2011-06-28 18:59:00.609375 [(20)]: subch:0-0 tswriter StartTimeshifting...
2011-06-28 18:59:00.609375 [(20)]: card: WaitForTimeShiftFile - waiting _eventAudio & _eventVideo
2011-06-28 18:59:00.625000 [(14)]: PID seen - type = Audio
2011-06-28 18:59:00.640625 [(14)]: audioVideoEventHandler Audio
2011-06-28 18:59:00.640625 [(14)]: PID seen - type = Video
2011-06-28 18:59:00.640625 [(14)]: audioVideoEventHandler Video
2011-06-28 18:59:00.640625 [(20)]: card: WaitForTimeShiftFile - video and audio are seen after 0.03125 seconds
2011-06-28 18:59:00.640625 [(20)]: user:setuptv-1035-4 card:4 sub:0 add stream:D:\zzzTVTimeshift\live4-0.ts.tsbuffer
2011-06-28 18:59:00.640625 [(20)]: RTSP: add stream stream4.0 file:D:\zzzTVTimeshift\live4-0.ts.tsbuffer
2011-06-28 18:59:00.656250 [(20)]: Controller: StartTimeShifting started on card:4 to D:\zzzTVTimeshift\live4-0.ts.tsbuffer
2011-06-28 18:59:00.656250 [Channel state thread(18)]: Controller: DoSetChannelStates for 70 channels
2011-06-28 18:59:00.656250 [Channel state thread(18)]: ChannelStates.DoSetChannelStates took 2 msec
2011-06-28 18:59:33.125000 [(12)]: Recorder.start add audioVideoEventHandler
2011-06-28 18:59:33.125000 [(12)]: card: StartRecording 4 D:\zzzTVRecordings\211 WRCDT NBC.ts
2011-06-28 18:59:33.125000 [(12)]: StartRecording to D:\zzzTVRecordings\211 WRCDT NBC.ts
2011-06-28 18:59:33.125000 [(12)]: subch:0 StartRecord(D:\zzzTVRecordings\211 WRCDT NBC.ts)
2011-06-28 18:59:33.125000 [(12)]: subch:0-0 tswriter StartRecording...
2011-06-28 18:59:33.125000 [(12)]: SetRecorderPids
2011-06-28 18:59:33.125000 [(12)]: Set video / audio observer
2011-06-28 18:59:33.140625 [(12)]: DVB subch:0 Started recording
2011-06-28 18:59:33.140625 [(12)]: card: WaitForRecordingFile - waiting _eventAudio & _eventVideo
2011-06-28 18:59:48.140625 [(12)]: card: WaitForRecordingFile - no audio was found after 15 seconds
2011-06-28 18:59:48.140625 [(12)]: card: Recording failed! 4 D:\zzzTVRecordings\211 WRCDT NBC.ts
2011-06-28 18:59:48.140625 [(12)]: card: StopRecording card=4, user=setuptv-1035-4
2011-06-28 18:59:48.140625 [(12)]: card: StopRecording for card:4
2011-06-28 18:59:48.140625 [(12)]: tvdvbchannel.OnStopRecording subch=0, subch index=0
2011-06-28 18:59:48.140625 [(12)]: tvdvbchannel.OnStopRecording subch:0-0 tswriter StopRecording...
2011-06-28 18:59:48.140625 [(12)]: tvcard:FreeSubChannel: subchannels count 1 subch#0 keep graph=False
2011-06-28 18:59:48.140625 [(12)]: tvcard:FreeSubChannel :0 - is timeshifting (skipped)
2011-06-28 18:59:48.156250 [(12)]: user:setuptv-1035-4 remove
2011-06-28 18:59:48.156250 [(12)]: subch:0-0 tswriter StopTimeshifting...
2011-06-28 18:59:48.156250 [(12)]: tvcard:FreeSubChannel: subchannels count 1 subch#0 keep graph=False
2011-06-28 18:59:48.156250 [(12)]: DVB subch:0 Decompose()
2011-06-28 18:59:48.156250 [(12)]: FreeSubChannel CA: freeing sub channel : 0
2011-06-28 18:59:48.156250 [(12)]: tvcard:FreeSubChannel : no subchannels present, stopping graph
2011-06-28 18:59:48.156250 [(12)]: dvb:StopGraph called
2011-06-28 18:59:48.171875 [(12)]: tvcard:FreeAllSubChannels
2011-06-28 18:59:48.171875 [(12)]: dvb:StopGraph
2011-06-28 18:59:48.187500 [TS_File_Cleanup(18)]: card: delete timeshift files D:\zzzTVTimeshift\live4-0.ts
2011-06-28 18:59:48.187500 [(12)]: dvb:StopGraph called
2011-06-28 18:59:48.187500 [(12)]: tvcard:FreeAllSubChannels
2011-06-28 18:59:48.187500 [(12)]: dvb:StopGraph filterstate already stopped, returning.