TVserver does not record anything on schedule (1 Viewer)

[artisticcheese]

I don't have Debug shortcut since I use TVserver in stand-alone mode, so I attached all the logs TVServer produced below.

MediaPortal Version: 1.2.2
Windows Version: Windows 7
1. TV Card: SiliconDust HD HomeRUn


Hello,

For some reason TVServer will just stop recording any new programs for no apparent reason. TVService is running but nothing is being recorded, even though 7 of programs are scheduled for today, not a single one recorded. Logs are attached. If I restart TVservice then it'll again record 3-4 episodes and then will stop recording again.

 

[elliottmc]

Your logs are huge, which is going to make it dificult to identify one problem. However,

2012-01-26 06:25:25.902343 [scheduler thread(9)]: Scheduler: Time to record PBS 6:25 AM-7:00 AM Arthur
2012-01-26 06:25:25.917968 [scheduler thread(9)]: Controller: find free card for channel PBS
2012-01-26 06:25:25.917968 [scheduler thread(9)]: Controller: find card for channel PBS
2012-01-26 06:25:25.917968 [scheduler thread(9)]: Controller:   got 1 tuning details for PBS
2012-01-26 06:25:25.917968 [scheduler thread(9)]: Controller:   channel #1 ATSC:tv: Unknown 505250-5E9 Freq:505250 ONID:0 TSID:3194 SID:1513 PMT:0x30 FTA:True LCN:10000 phys:72 maj:0 min:0 mod:Mod256Qam 
2012-01-26 06:25:25.917968 [scheduler thread(9)]: Controller:    card:1 type:DvbIP is disabled
2012-01-26 06:25:25.917968 [scheduler thread(9)]: Controller:    card:2 type:RadioWebStream is disabled
2012-01-26 06:25:25.917968 [scheduler thread(9)]: Controller:    card:3 type:Atsc can tune to channel
2012-01-26 06:25:25.917968 [scheduler thread(9)]: Controller:    card:3 type:Atsc users: 0
2012-01-26 06:25:25.917968 [scheduler thread(9)]: Controller:    card:4 type:Atsc can tune to channel
2012-01-26 06:25:25.917968 [scheduler thread(9)]: Controller:    card:4 type:Atsc users: 0
2012-01-26 06:25:25.917968 [scheduler thread(9)]: Controller:    card:5 type:DvbIP is disabled
2012-01-26 06:25:25.917968 [scheduler thread(9)]: Controller: found 2 card(s) for channel
2012-01-26 06:25:25.917968 [scheduler thread(9)]: AdvancedCardAllocation.GetAvailableCardsForChannel took 9 msec
2012-01-26 06:25:25.917968 [scheduler thread(9)]: Controller:    card:3 type:Atsc is available
2012-01-26 06:25:25.917968 [scheduler thread(9)]: Controller:    card:4 type:Atsc is available
2012-01-26 06:25:25.917968 [scheduler thread(9)]: Controller: found 2 free card(s)
2012-01-26 06:25:25.917968 [scheduler thread(9)]: AdvancedCardAllocation.GetFreeCardsForChannel took 12 msec
2012-01-26 06:25:25.917968 [scheduler thread(9)]: scheduler: try max 2 of 2 FREE cards for recording
2012-01-26 06:25:25.917968 [scheduler thread(9)]: Controller: epg stop
2012-01-26 06:25:25.917968 [scheduler thread(9)]: Scheduler : record, first tune to channel
2012-01-26 06:25:25.917968 [scheduler thread(9)]: card: Tune 3 to Unknown 505250-5E9
2012-01-26 06:25:25.917968 [scheduler thread(9)]: card: user: scheduler165:3:-1 tune ATSC:tv: Unknown 505250-5E9 Freq:505250 ONID:0 TSID:3194 SID:1513 PMT:0x30 FTA:True LCN:10000 phys:72 maj:0 min:0 mod:Mod256Qam
2012-01-26 06:25:25.917968 [scheduler thread(9)]: atsc:Tune:ATSC:tv: Unknown 505250-5E9 Freq:505250 ONID:0 TSID:3194 SID:1513 PMT:0x30 FTA:True LCN:10000 phys:72 maj:0 min:0 mod:Mod256Qam 
2012-01-26 06:25:25.917968 [scheduler thread(9)]: atsc:using previous channel tuning settings
2012-01-26 06:25:25.917968 [scheduler thread(9)]: dvb:Submiting tunerequest Channel:Unknown 505250-5E9 subChannel:-1 
2012-01-26 06:25:25.917968 [scheduler thread(9)]: dvb:Getting new subchannel
2012-01-26 06:25:25.917968 [scheduler thread(9)]: dvb:GetNewSubChannel:0 #0
2012-01-26 06:25:25.949218 [scheduler thread(9)]: TvDvbChannel ctor new subchIndex:0
2012-01-26 06:25:25.949218 [scheduler thread(9)]: dvb:Submit tunerequest size:1 new:0
2012-01-26 06:25:25.949218 [scheduler thread(9)]: subch:0 OnBeforeTune
2012-01-26 06:25:25.949218 [scheduler thread(9)]: subch:0 OnAfterTune
2012-01-26 06:25:25.949218 [scheduler thread(9)]: RunGraph
2012-01-26 06:25:25.949218 [scheduler thread(9)]: subch:0 OnGraphStart
2012-01-26 06:25:25.949218 [scheduler thread(9)]: dvb:  RunGraph
2012-01-26 06:25:25.949218 [scheduler thread(9)]: dvb:  LockedInOnSignal waiting 20ms
2012-01-26 06:25:25.980468 [scheduler thread(9)]: dvb:  LockedInOnSignal waiting 20ms
2012-01-26 06:25:26.011718 [scheduler thread(9)]: dvb:  LockedInOnSignal waiting 20ms
2012-01-26 06:25:26.042968 [scheduler thread(9)]: dvb:  LockedInOnSignal waiting 20ms
2012-01-26 06:25:26.074218 [scheduler thread(9)]: dvb:  LockedInOnSignal waiting 20ms
[COLOR="Red"]2012-01-26 06:25:27.980468 [scheduler thread(9)]: dvb:  LockedInOnSignal could not lock onto channel - no signal or bad signal[/COLOR]
2012-01-26 06:25:27.980468 [scheduler thread(9)]: tvcard:FreeSubChannel: subchannels count 1 subch#0 keep graph=False
2012-01-26 06:25:27.980468 [scheduler thread(9)]: DVB subch:0 Decompose()
2012-01-26 06:25:27.980468 [scheduler thread(9)]: FreeSubChannel CA: freeing sub channel : 0
2012-01-26 06:25:27.980468 [scheduler thread(9)]: tvcard:FreeSubChannel : no subchannels present, pausing graph
2012-01-26 06:25:27.980468 [scheduler thread(9)]: dvb:StopGraph called
2012-01-26 06:25:27.980468 [scheduler thread(9)]: tvcard:FreeAllSubChannels
2012-01-26 06:25:27.980468 [scheduler thread(9)]: dvb:StopGraph
2012-01-26 06:25:27.996093 [scheduler thread(9)]: Controller: epg start
2012-01-26 06:25:27.996093 [scheduler thread(9)]: scheduler: recording failed, lets try next available card.

it seems to be having trouble tuning to the channel.

When a recording fails, are you still able to tune to the channel and watch TV ?

Mark

 

[artisticcheese]

Yes, I can watch TV fine, also once it fails it never records again, ever. Untill I restart TV service and then it will again record 2-3 episodes and then stop.

 

[elliottmc]

Just to clarify, if it fails, you are able to restart the TV service without rebooting the computer, and all is fine?

I was wondering about overheating as a possible cause (TV cards can get quite warm).

Have you checked for updated drivers for your TV card? Are others using the same card with no problems?

I'm not an expert, so I can't guess what might be going wrong from your logs.

Mark

 

[artisticcheese]

It's failing right now but if I tune manually to channel it works. How can I get additional debugging information?

2012-01-30 14:22:22.906250 [scheduler thread(11)]: dvbubmit tunerequest size:1 new:0
2012-01-30 14:22:22.906250 [scheduler thread(11)]: subch:0 OnBeforeTune
2012-01-30 14:22:22.908203 [scheduler thread(11)]: subch:0 OnAfterTune
2012-01-30 14:22:22.909179 [scheduler thread(11)]: RunGraph
2012-01-30 14:22:22.909179 [scheduler thread(11)]: subch:0 OnGraphStart
2012-01-30 14:22:22.910156 [scheduler thread(11)]: dvb: RunGraph
2012-01-30 14:22:22.912109 [scheduler thread(11)]: dvb: LockedInOnSignal waiting 20ms
2012-01-30 14:22:22.932617 [scheduler thread(11)]: dvb: LockedInOnSignal waiting 20ms
2012-01-30 14:22:22.953125 [scheduler thread(11)]: dvb: LockedInOnSignal waiting 20ms
2012-01-30 14:22:22.974609 [scheduler thread(11)]: dvb: LockedInOnSignal waiting 20ms
2012-01-30 14:22:22.995117 [scheduler thread(11)]: dvb: LockedInOnSignal waiting 20ms
2012-01-30 14:22:24.943359 [scheduler thread(11)]: dvb: LockedInOnSignal could not lock onto channel - no signal or bad signal
2012-01-30 14:22:24.943359 [scheduler thread(11)]: tvcard:FreeSubChannel: subchannels count 1 subch#0 keep graph=False
2012-01-30 14:22:24.943359 [scheduler thread(11)]: DVB subch:0 Decompose()
2012-01-30 14:22:24.943359 [scheduler thread(11)]: FreeSubChannel CA: freeing sub channel : 0
2012-01-30 14:22:24.948242 [scheduler thread(11)]: tvcard:FreeSubChannel : no subchannels present, pausing graph
2012-01-30 14:22:24.952148 [scheduler thread(11)]: dvbtopGraph called
2012-01-30 14:22:24.953125 [scheduler thread(11)]: tvcard:FreeAllSubChannels

 

[elliottmc]

Run 'MediaPortal Debug-Mode' from your start menu. It will collect all logs. Make sure you do this on your server (if you are running a multiseat setup) so we have server and client logs.

Mark

 

[artisticcheese]

I don't have this in menu since my TVservice is in single mode installation (that is TVServer is installed on it's own box with no TVClient). To further proove that it's not issue with card or signal. I restart TVService right in the middle of schedule where it was supposed to be recording something. So you can see events that TVservice can not record becouse it's bad signal at 6:40:21, I restart service at boom at 6:40:28 it successfully starts recording. NO other changes to anything.

2012-01-31 06:40:19.363281 [scheduler thread(11)]: dvb:StopGraph
2012-01-31 06:40:19.378906 [scheduler thread(11)]: Controller: epg start
2012-01-31 06:40:19.378906 [scheduler thread(11)]: scheduler: recording failed, lets try next available card.
2012-01-31 06:40:19.394531 [scheduler thread(11)]: Scheduler : card is not tuned to the same transponder and not recording, kicking all users. record on card:4 priority:2
2012-01-31 06:40:19.394531 [scheduler thread(11)]: Controller: epg stop
2012-01-31 06:40:19.394531 [scheduler thread(11)]: Scheduler : record, first tune to channel
2012-01-31 06:40:19.394531 [scheduler thread(11)]: card: Tune 4 to Unknown 505250-5E9
2012-01-31 06:40:19.394531 [scheduler thread(11)]: card: user: scheduler199:4:-1 tune ATSC:tv: Unknown 505250-5E9 Freq:505250 ONID:0 TSID:3194 SID:1513 PMT:0x30 FTA:True LCN:10000 phys:72 maj:0 min:0 mod:Mod256Qam
2012-01-31 06:40:19.410156 [scheduler thread(11)]: atsc:Tune:ATSC:tv: Unknown 505250-5E9 Freq:505250 ONID:0 TSID:3194 SID:1513 PMT:0x30 FTA:True LCN:10000 phys:72 maj:0 min:0 mod:Mod256Qam 
2012-01-31 06:40:19.410156 [scheduler thread(11)]: atsc:using previous channel tuning settings
2012-01-31 06:40:19.410156 [scheduler thread(11)]: dvb:Submiting tunerequest Channel:Unknown 505250-5E9 subChannel:-1 
2012-01-31 06:40:19.410156 [scheduler thread(11)]: dvb:Getting new subchannel
2012-01-31 06:40:19.410156 [scheduler thread(11)]: dvb:GetNewSubChannel:0 #0
2012-01-31 06:40:19.410156 [scheduler thread(11)]: TvDvbChannel ctor new subchIndex:0
2012-01-31 06:40:19.410156 [scheduler thread(11)]: dvb:Submit tunerequest size:1 new:0
2012-01-31 06:40:19.410156 [scheduler thread(11)]: subch:0 OnBeforeTune
2012-01-31 06:40:19.410156 [scheduler thread(11)]: subch:0 OnAfterTune
2012-01-31 06:40:19.410156 [scheduler thread(11)]: RunGraph
2012-01-31 06:40:19.410156 [scheduler thread(11)]: subch:0 OnGraphStart
2012-01-31 06:40:19.410156 [scheduler thread(11)]: dvb:  RunGraph
2012-01-31 06:40:19.410156 [scheduler thread(11)]: dvb:  LockedInOnSignal waiting 20ms
2012-01-31 06:40:19.441406 [scheduler thread(11)]: dvb:  LockedInOnSignal waiting 20ms
2012-01-31 06:40:19.472656 [scheduler thread(11)]: dvb:  LockedInOnSignal waiting 20ms
2012-01-31 06:40:19.503906 [scheduler thread(11)]: dvb:  LockedInOnSignal waiting 20ms
2012-01-31 06:40:19.535156 [scheduler thread(11)]: dvb:  LockedInOnSignal waiting 20ms
2012-01-31 06:40:21.457031 [scheduler thread(11)]: dvb:  LockedInOnSignal could not lock onto channel - no signal or bad signal
2012-01-31 06:40:21.457031 [scheduler thread(11)]: tvcard:FreeSubChannel: subchannels count 1 subch#0 keep graph=False
2012-01-31 06:40:21.457031 [scheduler thread(11)]: DVB subch:0 Decompose()
2012-01-31 06:40:21.457031 [scheduler thread(11)]: FreeSubChannel CA: freeing sub channel : 0
2012-01-31 06:40:21.457031 [scheduler thread(11)]: tvcard:FreeSubChannel : no subchannels present, pausing graph
2012-01-31 06:40:21.457031 [scheduler thread(11)]: dvb:StopGraph called
2012-01-31 06:40:21.457031 [scheduler thread(11)]: tvcard:FreeAllSubChannels
2012-01-31 06:40:21.457031 [scheduler thread(11)]: dvb:StopGraph
2012-01-31 06:40:21.472656 [scheduler thread(11)]: Controller: epg start
2012-01-31 06:40:21.472656 [scheduler thread(11)]: scheduler: recording failed, lets try next available card.
2012-01-31 06:40:21.472656 [TVService(6)]: Scheduler: thread stopped.
2012-01-31 06:40:21.488281 [TVService(6)]: Controller: scheduler stopped...
2012-01-31 06:40:21.488281 [TVService(6)]: Controller: stop epg grabber...
2012-01-31 06:40:21.503906 [TVService(6)]: Controller: epg stopped...
2012-01-31 06:40:21.503906 [TVService(6)]: Controller: dispose card:MediaPortal IPTV Source Filter
2012-01-31 06:40:21.503906 [TVService(6)]: Controller: dispose card:RadioWebStream Card (builtin)
2012-01-31 06:40:21.503906 [TVService(6)]: RadioWebStream:Dispose()
2012-01-31 06:40:21.503906 [TVService(6)]: Controller: dispose card:Silicondust HDHomeRun Tuner 101429EC-0
2012-01-31 06:40:21.503906 [TVService(6)]: dvb:Decompose
2012-01-31 06:40:21.503906 [TVService(6)]: tvcard:FreeAllSubChannels
2012-01-31 06:40:21.519531 [TVService(6)]:   stop
2012-01-31 06:40:21.628906 [TVService(6)]:   Disposing ConditionalAccess
2012-01-31 06:40:21.628906 [TVService(6)]:   free...
2012-01-31 06:40:21.628906 [TVService(6)]:   free pins...
2012-01-31 06:40:21.628906 [TVService(6)]:   free graph...
2012-01-31 06:40:21.644531 [TVService(6)]: Remove filter from graph: BDA MPEG2 Transport Information Filter 0002
2012-01-31 06:40:21.644531 [TVService(6)]: Remove filter from graph: BDA MPEG2 Transport Information Filter
2012-01-31 06:40:21.644531 [TVService(6)]: Remove filter from graph: MediaPortal Ts Analyzer
2012-01-31 06:40:21.644531 [TVService(6)]: Remove filter from graph: MPEG2-Demultiplexer
2012-01-31 06:40:21.660156 [TVService(6)]: Remove filter from graph: Inf Tee
2012-01-31 06:40:21.675781 [TVService(6)]: Remove filter from graph: Silicondust HDHomeRun Tuner 101429EC-0
2012-01-31 06:40:21.675781 [TVService(6)]: Remove filter from graph: Generic Network Provider
2012-01-31 06:40:21.691406 [TVService(6)]:   free devices...
2012-01-31 06:40:21.894531 [TVService(6)]:   decompose done...
2012-01-31 06:40:21.894531 [TVService(6)]: Controller: dispose card:Silicondust HDHomeRun Tuner 101429EC-1
2012-01-31 06:40:21.894531 [TVService(6)]: dvb:Decompose
2012-01-31 06:40:21.894531 [TVService(6)]: tvcard:FreeAllSubChannels
2012-01-31 06:40:21.894531 [TVService(6)]:   stop
2012-01-31 06:40:22.019531 [TVService(6)]:   Disposing ConditionalAccess
2012-01-31 06:40:22.019531 [TVService(6)]:   free...
2012-01-31 06:40:22.019531 [TVService(6)]:   free pins...
2012-01-31 06:40:22.019531 [TVService(6)]:   free graph...
2012-01-31 06:40:22.019531 [TVService(6)]: Remove filter from graph: BDA MPEG2 Transport Information Filter 0002
2012-01-31 06:40:22.019531 [TVService(6)]: Remove filter from graph: BDA MPEG2 Transport Information Filter
2012-01-31 06:40:22.019531 [TVService(6)]: Remove filter from graph: MediaPortal Ts Analyzer
2012-01-31 06:40:22.035156 [TVService(6)]: Remove filter from graph: MPEG2-Demultiplexer
2012-01-31 06:40:22.035156 [TVService(6)]: Remove filter from graph: Inf Tee
2012-01-31 06:40:22.035156 [TVService(6)]: Remove filter from graph: Silicondust HDHomeRun Tuner 101429EC-1
2012-01-31 06:40:22.035156 [TVService(6)]: Remove filter from graph: Generic Network Provider
2012-01-31 06:40:22.050781 [TVService(6)]:   free devices...
2012-01-31 06:40:22.285156 [TVService(6)]:   decompose done...
2012-01-31 06:40:22.285156 [TVService(6)]: Controller: dispose card:MediaPortal IPTV Source Filter_1
2012-01-31 06:40:22.285156 [TVService(6)]: TV Service: Stop plugins
2012-01-31 06:40:22.285156 [TVService(6)]: plugin: ComSkipLauncher stop
2012-01-31 06:40:22.285156 [TVService(6)]: plugin: xmltv stopped
2012-01-31 06:40:22.285156 [TVService(6)]: xmltv: UnRegistered xmltv as PowerEventHandler to tvservice
2012-01-31 06:40:22.285156 [TVService(6)]: TV Service: Plugins stopped
2012-01-31 06:40:22.285156 [TVService(6)]: TV Service: OnStop asking PowerEventThread to exit
2012-01-31 06:40:22.285156 [PowerEventThread(8)]: TV service PowerEventThread finished
2012-01-31 06:40:22.300781 [TVService(6)]: TV Service: stopped
2012-01-31 06:40:23.535156 [(4)]: Setting up EventWaitHandle with name: Global\MPTVServiceInitializedEvent
2012-01-31 06:40:23.894531 [(6)]: TV service: Starting
2012-01-31 06:40:23.894531 [TVService(6)]: TVService v1.2.2.0 is starting up on Windows 7 ( Service Pack 1 ) [6.1.7601.65536]
2012-01-31 06:40:23.894531 [TVService(6)]: Build: 1.2.2.0
2012-01-31 06:40:23.910156 [TVService(6)]: Controller: Initializing TVServer
2012-01-31 06:40:23.910156 [TVService(6)]: Controller: 1 init attempt
2012-01-31 06:40:23.910156 [PowerEventThread(9)]: TV service PowerEventThread message loop is running
2012-01-31 06:40:23.941406 [TVService(6)]: C:\ProgramData\Team MediaPortal\MediaPortal TV Server\gentle.config
2012-01-31 06:40:23.941406 [TVService(6)]: Controller: using SQLServer database connection: Password
2012-01-31 06:40:23.941406 [TVService(6)]: ----------------------------
2012-01-31 06:40:23.941406 [TVService(6)]: Detecting Cards
2012-01-31 06:40:24.003906 [TVService(6)]: Detected IP TV Card 0
2012-01-31 06:40:24.066406 [TVService(6)]: Detected IP TV Card 1
2012-01-31 06:40:24.144531 [TVService(6)]: Found card:silicondust hdhomerun tuner 101429ec-0
2012-01-31 06:40:24.144531 [TVService(6)]: silicondust hdhomerun detected - prefer cable mode: True
2012-01-31 06:40:24.191406 [TVService(6)]: Detected DVB card:silicondust hdhomerun tuner 101429ec-0
2012-01-31 06:40:24.191406 [TVService(6)]: Detecting type by MSNP 0: 0dad2fdd-5fd7-11d3-8f50-00c04f7971e2
2012-01-31 06:40:24.191406 [TVService(6)]: Detected ATSC* card:silicondust hdhomerun tuner 101429ec-0
2012-01-31 06:40:24.207031 [TVService(6)]: Found card:silicondust hdhomerun tuner 101429ec-1
2012-01-31 06:40:24.207031 [TVService(6)]: silicondust hdhomerun detected - prefer cable mode: True
2012-01-31 06:40:24.300781 [TVService(6)]: Detected DVB card:silicondust hdhomerun tuner 101429ec-1
2012-01-31 06:40:24.316406 [TVService(6)]: Detecting type by MSNP 0: 0dad2fdd-5fd7-11d3-8f50-00c04f7971e2
2012-01-31 06:40:24.316406 [TVService(6)]: Detected ATSC* card:silicondust hdhomerun tuner 101429ec-1
2012-01-31 06:40:24.316406 [TVService(6)]: Remove filter from graph: DVBC Network Provider
2012-01-31 06:40:24.316406 [TVService(6)]: Remove filter from graph: ATSC Network Provider
2012-01-31 06:40:24.316406 [TVService(6)]: Remove filter from graph: DVBS Network Provider
2012-01-31 06:40:24.316406 [TVService(6)]: Remove filter from graph: DVBT Network Provider
2012-01-31 06:40:24.332031 [TVService(6)]: Controller: started at TVServer
2012-01-31 06:40:24.332031 [TVService(6)]: Controller: local ip address:192.168.1.40
2012-01-31 06:40:24.332031 [TVService(6)]: Controller: server running on TVServer
2012-01-31 06:40:24.347656 [TVService(6)]: Controller: NOT preloading card :Silicondust HDHomeRun Tuner 101429EC-0
2012-01-31 06:40:24.347656 [TVService(6)]: Controller: NOT preloading card :Silicondust HDHomeRun Tuner 101429EC-1
2012-01-31 06:40:24.347656 [TVService(6)]: Controller: setup hybrid cards
2012-01-31 06:40:24.378906 [TVService(6)]: Controller: card MediaPortal IPTV Source Filter: current timeshiftpath = D:\shifting
2012-01-31 06:40:24.378906 [TVService(6)]: Controller: card RadioWebStream Card (builtin): current timeshiftpath = D:\shifting
2012-01-31 06:40:24.394531 [TVService(6)]: Controller: card Silicondust HDHomeRun Tuner 101429EC-0: current timeshiftpath = D:\shifting
2012-01-31 06:40:24.394531 [TVService(6)]: Controller: card Silicondust HDHomeRun Tuner 101429EC-1: current timeshiftpath = D:\shifting
2012-01-31 06:40:24.410156 [TVService(6)]: Controller: card MediaPortal IPTV Source Filter_1: current timeshiftpath = C:\ProgramData\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer
2012-01-31 06:40:24.410156 [TVService(6)]: Controller: setup streaming
2012-01-31 06:40:24.535156 [TVService(6)]: Scheduler: started
2012-01-31 06:40:24.597656 [TVService(6)]: Scheduler: loaded 19 schedules
2012-01-31 06:40:24.597656 [TVService(6)]: Scheduler: thread started.
2012-01-31 06:40:24.628906 [TVService(6)]: DiskManagement: started
2012-01-31 06:40:24.628906 [TVService(6)]: Controller: setup HeartBeat Monitor
2012-01-31 06:40:24.628906 [HeartBeatMonitor(11)]: Controller: Heartbeat Monitor initiated, max timeout allowed is 30 sec.
2012-01-31 06:40:24.644531 [TVService(6)]: ExecutePendingDeletions: number of pending deletions : 0
2012-01-31 06:40:24.644531 [TVService(6)]: Controller: recalculating program states
2012-01-31 06:40:24.675781 [TVService(6)]: schedule.SynchProgramStatesForAll
2012-01-31 06:40:24.769531 [scheduler thread(10)]: Scheduler: Time to record PBS 6:40 AM-7:00 AM Arthur
2012-01-31 06:40:24.769531 [scheduler thread(10)]: Controller: find free card for channel PBS
2012-01-31 06:40:24.800781 [scheduler thread(10)]: Controller: find card for channel PBS
2012-01-31 06:40:24.816406 [scheduler thread(10)]: Controller:   got 1 tuning details for PBS
2012-01-31 06:40:24.832031 [scheduler thread(10)]: Controller:   channel #1 ATSC:tv: Unknown 505250-5E9 Freq:505250 ONID:0 TSID:3194 SID:1513 PMT:0x30 FTA:True LCN:10000 phys:72 maj:0 min:0 mod:Mod256Qam 
2012-01-31 06:40:24.832031 [scheduler thread(10)]: Controller:    card:1 type:DvbIP is disabled
2012-01-31 06:40:24.832031 [scheduler thread(10)]: Controller:    card:2 type:RadioWebStream is disabled
2012-01-31 06:40:24.847656 [scheduler thread(10)]: Controller:    card:3 type:Atsc can tune to channel
2012-01-31 06:40:24.847656 [scheduler thread(10)]: Controller:    card:3 type:Atsc users: 0
2012-01-31 06:40:24.847656 [scheduler thread(10)]: Controller:    card:4 type:Atsc can tune to channel
2012-01-31 06:40:24.847656 [scheduler thread(10)]: Controller:    card:4 type:Atsc users: 0
2012-01-31 06:40:24.847656 [scheduler thread(10)]: Controller:    card:5 type:DvbIP is disabled
2012-01-31 06:40:24.847656 [scheduler thread(10)]: Controller: found 2 card(s) for channel
2012-01-31 06:40:24.847656 [scheduler thread(10)]: AdvancedCardAllocation.GetAvailableCardsForChannel took 56 msec
2012-01-31 06:40:24.847656 [scheduler thread(10)]: Controller:    card:3 type:Atsc is available
2012-01-31 06:40:24.847656 [scheduler thread(10)]: Controller:    card:4 type:Atsc is available
2012-01-31 06:40:24.847656 [scheduler thread(10)]: Controller: found 2 free card(s)
2012-01-31 06:40:24.847656 [scheduler thread(10)]: AdvancedCardAllocation.GetFreeCardsForChannel took 72 msec
2012-01-31 06:40:24.863281 [scheduler thread(10)]: scheduler: try max 2 of 2 FREE cards for recording
2012-01-31 06:40:24.863281 [scheduler thread(10)]: Controller: epg stop
2012-01-31 06:40:24.863281 [scheduler thread(10)]: Scheduler : record, first tune to channel
2012-01-31 06:40:24.863281 [scheduler thread(10)]: card: Tune 3 to Unknown 505250-5E9
2012-01-31 06:40:24.863281 [scheduler thread(10)]: card: user: scheduler199:3:-1 tune ATSC:tv: Unknown 505250-5E9 Freq:505250 ONID:0 TSID:3194 SID:1513 PMT:0x30 FTA:True LCN:10000 phys:72 maj:0 min:0 mod:Mod256Qam
2012-01-31 06:40:24.878906 [scheduler thread(10)]: atsc:Tune:ATSC:tv: Unknown 505250-5E9 Freq:505250 ONID:0 TSID:3194 SID:1513 PMT:0x30 FTA:True LCN:10000 phys:72 maj:0 min:0 mod:Mod256Qam 
2012-01-31 06:40:24.878906 [scheduler thread(10)]: atsc:BuildGraph
2012-01-31 06:40:24.910156 [scheduler thread(10)]: dvb:AddNetworkProviderFilter
2012-01-31 06:40:24.910156 [scheduler thread(10)]: dvb:AddNetworkProviderFilter
2012-01-31 06:40:24.910156 [scheduler thread(10)]: dvb:Add Generic Network Provider
2012-01-31 06:40:24.910156 [scheduler thread(10)]: dvb:  Add Mediaportal TsWriter filter
2012-01-31 06:40:24.925781 [scheduler thread(10)]: atsc:CreateTuningSpace()
2012-01-31 06:40:24.925781 [scheduler thread(10)]: atsc:found correct tuningspace MediaPortal ATSC TuningSpace
2012-01-31 06:40:24.925781 [scheduler thread(10)]: dvb:Add MPEG2 Demultiplexer filter
2012-01-31 06:40:24.957031 [scheduler thread(10)]: dvb:AddAndConnectBDABoardFilters
2012-01-31 06:40:24.972656 [scheduler thread(10)]: dvb: find bda tuner
2012-01-31 06:40:25.035156 [scheduler thread(10)]: dvb:  using [Tuner]: Silicondust HDHomeRun Tuner 101429EC-0
2012-01-31 06:40:25.035156 [scheduler thread(10)]: dvb:  Render [Network provider]->[Tuner] OK
2012-01-31 06:40:25.035156 [scheduler thread(10)]: dvb:  Setting lastFilter to Tuner filter
2012-01-31 06:40:25.066406 [scheduler thread(10)]: dvb:  WinTv CI module not detected.
2012-01-31 06:40:25.066406 [scheduler thread(10)]: dvb:add Inf Tee filter
2012-01-31 06:40:25.066406 [scheduler thread(10)]: dvb:  Render ...->[inftee]
2012-01-31 06:40:25.066406 [scheduler thread(10)]: dvb:  Setting lastFilter to Inf Tee
2012-01-31 06:40:25.066406 [scheduler thread(10)]: dvb:  Render [inftee]->[demux]
2012-01-31 06:40:25.066406 [scheduler thread(10)]: dvb:  AddTransportStreamFiltersToGraph
2012-01-31 06:40:25.066406 [scheduler thread(10)]:     add BDA MPEG2 Transport Information Filter filter
2012-01-31 06:40:25.082031 [TVService(6)]: Controller: initalized
2012-01-31 06:40:25.082031 [TVService(6)]: Controller: TVServer initialized okay
2012-01-31 06:40:25.082031 [TVService(6)]: TV Service: Load plugins
2012-01-31 06:40:25.113281 [scheduler thread(10)]:     pinTif:name:IB Input [3/0] Direction:Input Connected:False
2012-01-31 06:40:25.113281 [scheduler thread(10)]:     Connect tif and mpeg2 sections and tables
2012-01-31 06:40:25.113281 [scheduler thread(10)]: dvb:try tif:name:001 [5/0] Direction:Output Connected:False
2012-01-31 06:40:25.128906 [scheduler thread(10)]:     tif connected
2012-01-31 06:40:25.144531 [scheduler thread(10)]: dvb:  Render ..->[TsWriter]
2012-01-31 06:40:25.144531 [scheduler thread(10)]: dvb: Checking for hardware specific extensions
2012-01-31 06:40:25.160156 [scheduler thread(10)]: CAM is Default model
2012-01-31 06:40:25.160156 [scheduler thread(10)]: Check for ViXS ATSC QAM card
2012-01-31 06:40:25.160156 [TVService(6)]: PluginManager: Loaded ComSkipLauncher version:1.0.2.0 author:and-81
2012-01-31 06:40:25.160156 [scheduler thread(10)]: ViXS ATSC: could not find MPEG2 Transport pin!
2012-01-31 06:40:25.160156 [scheduler thread(10)]: Check for Generic ATSC QAM card
2012-01-31 06:40:25.160156 [scheduler thread(10)]: GenericATSC: tuner pin not found!
2012-01-31 06:40:25.160156 [scheduler thread(10)]: dvb:  AddTransportStreamFiltersToGraph
2012-01-31 06:40:25.160156 [TVService(6)]: PluginManager: Loaded ConflictsManager version:1.0.0.1 author:Broceliande
2012-01-31 06:40:25.175781 [scheduler thread(10)]:     add BDA MPEG2 Transport Information Filter filter
2012-01-31 06:40:25.175781 [TVService(6)]: PluginManager: Loaded Power Scheduler version:0.1.0.0 author:micheloe
2012-01-31 06:40:25.222656 [TVService(6)]: PluginManager: Loaded ServerBlaster version:1.1.1.0 author:joboehl with ralphy mods
2012-01-31 06:40:25.222656 [TVService(6)]: PluginManager: Loaded TV Movie EPG import version:1.0.3.0 author:rtv
2012-01-31 06:40:25.238281 [TVService(6)]: PluginManager: Loaded WebEPG version:1.0.0.0 author:Arion_p - James
2012-01-31 06:40:25.238281 [TVService(6)]: PluginManager: Loaded XmlTv version:1.0.0.0 author:Frodo
2012-01-31 06:40:25.238281 [TVService(6)]: TV Service: Plugins loaded
2012-01-31 06:40:25.238281 [TVService(6)]: TV Service: Plugin: ComSkipLauncher started
2012-01-31 06:40:25.238281 [TVService(6)]: plugin: ComSkipLauncher start
2012-01-31 06:40:25.253906 [TVService(6)]: TV Service: Plugin: ConflictsManager disabled
2012-01-31 06:40:25.253906 [TVService(6)]: TV Service: Plugin: Power Scheduler disabled
2012-01-31 06:40:25.253906 [TVService(6)]: TV Service: Plugin: ServerBlaster disabled
2012-01-31 06:40:25.253906 [TVService(6)]: TV Service: Plugin: TV Movie EPG import disabled
2012-01-31 06:40:25.253906 [TVService(6)]: TV Service: Plugin: WebEPG disabled
2012-01-31 06:40:25.253906 [TVService(6)]: TV Service: Plugin: XmlTv started
2012-01-31 06:40:25.253906 [scheduler thread(10)]: dvb: GetTunerSignalStatistics()
2012-01-31 06:40:25.253906 [TVService(6)]: plugin: xmltv started
2012-01-31 06:40:25.253906 [TVService(6)]: xmltv: Registered xmltv as PowerEventHandler to tvservice
2012-01-31 06:40:25.253906 [scheduler thread(10)]: atsc:using new channel tuning settings
2012-01-31 06:40:25.269531 [scheduler thread(10)]: dvb:Submiting tunerequest Channel:Unknown 505250-5E9 subChannel:-1 
2012-01-31 06:40:25.269531 [scheduler thread(10)]: dvb:Getting new subchannel
2012-01-31 06:40:25.269531 [scheduler thread(10)]: dvb:GetNewSubChannel:0 #0
2012-01-31 06:40:25.269531 [TVService(6)]: TV Service: Plugins started
2012-01-31 06:40:25.269531 [TVService(6)]: TV Service: Plugin: XmlTv started all
2012-01-31 06:40:25.269531 [TVService(6)]: XmlTvImporter: NOT registered with PowerScheduler EPG handler
2012-01-31 06:40:25.269531 [TVService(6)]: TV service: Started
2012-01-31 06:40:25.269531 [scheduler thread(10)]: TvDvbChannel ctor new subchIndex:0
2012-01-31 06:40:25.285156 [scheduler thread(10)]: dvb:Submit tunerequest size:1 new:0
2012-01-31 06:40:25.285156 [scheduler thread(10)]: subch:0 OnBeforeTune
2012-01-31 06:40:25.285156 [scheduler thread(10)]: dvb:Submit tunerequest calling put_TuneRequest
2012-01-31 06:40:25.285156 [scheduler thread(10)]: dvb:Submit tunerequest done calling put_TuneRequest
2012-01-31 06:40:25.285156 [scheduler thread(10)]: subch:0 OnAfterTune
2012-01-31 06:40:25.300781 [scheduler thread(10)]: RunGraph
2012-01-31 06:40:25.316406 [scheduler thread(10)]: subch:0 OnGraphStart
2012-01-31 06:40:25.316406 [scheduler thread(10)]: dvb:  RunGraph
2012-01-31 06:40:25.863281 [scheduler thread(10)]: dvb:  LockedInOnSignal ok
2012-01-31 06:40:25.863281 [scheduler thread(10)]: subch:0 OnGraphStarted
2012-01-31 06:40:25.878906 [scheduler thread(10)]: subch:0 SetupPmtGrabber:pid 30 sid:5E9
2012-01-31 06:40:25.878906 [scheduler thread(10)]: subch:0 set pmt grabber pmt:30 sid:5E9
2012-01-31 06:40:25.878906 [scheduler thread(10)]: WaitForPMT: Waiting for PMT 30
2012-01-31 06:40:26.003906 [(13)]: subch:0 OnPMTReceived() pmt:30 ran:True dynamic:False
2012-01-31 06:40:26.003906 [scheduler thread(10)]: WaitForPMT: Found PMT after 0.125 seconds.
2012-01-31 06:40:26.019531 [scheduler thread(10)]: subch:0 SendPmt:5E9 5E9 FFFFFFFF 3
2012-01-31 06:40:26.019531 [scheduler thread(10)]: Decode pmt
2012-01-31 06:40:26.035156 [scheduler thread(10)]: Set descriptor data with length 6
2012-01-31 06:40:26.035156 [scheduler thread(10)]: Set descriptor data with length 6
2012-01-31 06:40:26.035156 [scheduler thread(10)]: Set descriptor data with length 6
2012-01-31 06:40:26.035156 [scheduler thread(10)]: subch:0 SendPMT: Channel is FTA, nothing to do.
2012-01-31 06:40:26.050781 [scheduler thread(10)]: subch:0 SetMpegPidMapping
2012-01-31 06:40:26.050781 [scheduler thread(10)]: subch:0  pid:7C0 pcr
2012-01-31 06:40:26.050781 [scheduler thread(10)]: subch:0  pid:30 pmt
2012-01-31 06:40:26.050781 [scheduler thread(10)]: subch:0  pid:7C0 video type:MPEG-2
2012-01-31 06:40:26.050781 [scheduler thread(10)]: subch:0    map pid:7C0 video type:MPEG-2
2012-01-31 06:40:26.050781 [scheduler thread(10)]: subch:0  pid:7C1 audio lang:eng type:AC3
2012-01-31 06:40:26.050781 [scheduler thread(10)]: subch:0    map pid:7C1 audio lang:eng type:AC3
2012-01-31 06:40:26.050781 [scheduler thread(10)]: subch:0  pid:7C2 audio lang:eng type:AC3
2012-01-31 06:40:26.066406 [scheduler thread(10)]: subch:0    map pid:7C2 audio lang:eng type:AC3
2012-01-31 06:40:26.066406 [scheduler thread(10)]: subch:0  pid:7C3 audio lang:eng type:AC3
2012-01-31 06:40:26.066406 [scheduler thread(10)]: subch:0    map pid:7C3 audio lang:eng type:AC3
2012-01-31 06:40:26.066406 [scheduler thread(10)]: subch:0 stop tif
2012-01-31 06:40:26.066406 [scheduler thread(10)]: WaitForPmt: PMT handling took 0.0625 seconds.
2012-01-31 06:40:26.363281 [scheduler thread(10)]: card: Tuner locked: True
2012-01-31 06:40:26.363281 [scheduler thread(10)]: **************************************************
2012-01-31 06:40:26.363281 [scheduler thread(10)]: ***** SIGNAL LEVEL: 86, SIGNAL QUALITY: 97 *****
2012-01-31 06:40:26.363281 [scheduler thread(10)]: **************************************************
2012-01-31 06:40:26.363281 [scheduler thread(10)]: card: tuned user: scheduler199 subchannel: 0
2012-01-31 06:40:26.363281 [scheduler thread(10)]: user:scheduler199 add
2012-01-31 06:40:26.378906 [scheduler thread(10)]: Scheduler: MakeFileName() using "seriesformat" (_isSerie=True)
2012-01-31 06:40:26.394531 [scheduler thread(10)]: Scheduler : record to D:\recordings\PBS\Arthur\Arthur - 2012-01-31 - E301 - Buster's Back; The Ballad of Buster Baxter.ts
2012-01-31 06:40:26.394531 [scheduler thread(10)]: RemoteControl: RegisterChannel first called in Domain TVService.exe for thread scheduler thread with id 10
2012-01-31 06:40:28.425781 [scheduler thread(10)]: Recorder.start add audioVideoEventHandler
2012-01-31 06:40:28.425781 [scheduler thread(10)]: card: StartRecording 3 D:\recordings\PBS\Arthur\Arthur - 2012-01-31 - E301 - Buster's Back; The Ballad of Buster Baxter.ts
2012-01-31 06:40:28.425781 [scheduler thread(10)]: StartRecording to D:\recordings\PBS\Arthur\Arthur - 2012-01-31 - E301 - Buster's Back; The Ballad of Buster Baxter.ts
2012-01-31 06:40:28.425781 [scheduler thread(10)]: subch:0 StartRecord(D:\recordings\PBS\Arthur\Arthur - 2012-01-31 - E301 - Buster's Back; The Ballad of Buster Baxter.ts)
2012-01-31 06:40:28.425781 [scheduler thread(10)]: subch:0-0 tswriter StartRecording...
2012-01-31 06:40:28.425781 [scheduler thread(10)]: SetRecorderPids
2012-01-31 06:40:28.457031 [scheduler thread(10)]: Set video / audio observer
2012-01-31 06:40:28.457031 [scheduler thread(10)]: DVB subch:0 Started recording
2012-01-31 06:40:28.457031 [scheduler thread(10)]: card: WaitForRecordingFile - waiting _eventAudio & _eventVideo
2012-01-31 06:40:28.519531 [(13)]: PID seen - type = Video
2012-01-31 06:40:28.519531 [(13)]: Recorder audioVideoEventHandler Video
2012-01-31 06:40:28.519531 [(13)]: PID seen - type = Audio
2012-01-31 06:40:28.519531 [(13)]: Recorder audioVideoEventHandler Audio
2012-01-31 06:40:28.519531 [scheduler thread(10)]: card: WaitForRecordingFile - video and audio are seen after 0.0625 seconds
2012-01-31 06:40:28.519531 [(13)]: PID seen - type = Audio
2012-01-31 06:40:28.550781 [scheduler thread(10)]: Scheduler: adding new row in db for title="Arthur" of type="0"
2012-01-31 06:40:28.566406 [scheduler thread(10)]: Scheduler: recList: count: 1 add scheduleid: 199 card: Silicondust HDHomeRun Tuner 101429EC-0
2012-01-31 06:40:28.628906 [(13)]: PID seen - type = Audio
2012-01-31 06:50:55.300781 [(12)]: Deleting invalid recordings

 

[aots74]

Hi Mark,

I had this problem also. Do you have more tuner cards listed in server settings than you should? For me, and for some unknown reason, MP has picked up a mystery and non-existent duplicate of my tuner card. It is a dual so there should be two entries but for some reason there are 3. Haven't figured out how to fix it yet but that was causing my no-recording problem. The way I fixed it was:

go into tv server settings
on the list of available tuners make only one active
attempt to record a program
if successful, this card is a real one
try again with the others, on one of them the recording should fail
once you figure out the dodgy one, don't re-enable it and all should be fine

Hope this helps.

Cheers,

Bob