TV Recording gets stuck in a loop but does not record anything, prevents further live tv viewing (1 Viewer)

[me_sjo]

MediaPortal Version: 1.2.2

Description
Live TV works until you try to manually record something. The recording feature appears to get stuck in some sort of loop and after a short time 'no card available' messages are shown if attempting to switch channel (on a single tuner machine) and no actual recordings are made.
"Active Recordings" shows no active recording, even though the 'recording' symbol appears at the top of the screen on and off every few seconds. Nothing is show in previous recordings either.
This behaviour occurs with both my preferred 'Avalon' skin and the default skin.
Single active TV tuner = Hauppauge WinTV Nova HD S2
There is also a WinTV Nova TD-500 installed, but currently disabled in the TV Server configuration due to no antenna connected. (Not disabled in device manager).

This is a bug report in reference to this thread :-

https://forum.team-mediaportal.com/...-unable-to-watch-record-live-tv-1-2-2.106289/

This behaviour was present in 1.2.2 also, which is the earliest version of MP I have tried. TV recording, manual or scheduled has never worked for me with MP. Worked fine with Win 7 MC on the same hardware.

Steps to Reproduce:
1. Launch MP.
2. Browse TV guide and select a channel to view. TV starts after a short delay.
3. Whilst viewing TV, hit the 'record' button on the remote (mce remote).
4. 'Recording' displayed and channel shows red in tv guide.
5. Attempt to switch channel. Fails with 'no free card' warning.
6. Problem persists after a reboot. Eventually it resolves itself/times out. Not sure when this happens yet, if it's to do with the end time of a programme or some other variable.

 

[eetaylog]

Stu, I haven't looked at your logs yet, just read what you've put here quickly and it sounds like you're getting the 'No free card' error because, well... there's no free card?! ie, you're only running one tuner in your system, so using that one tuner to record means it's not possible to tune to another channel?

Or am I missing something?

 

[me_sjo]

Stu, I haven't looked at your logs yet, just read what you've put here quickly and it sounds like you're getting the 'No free card' error because, well... there's no free card?! ie, you're only running one tuner in your system, so using that one tuner to record means it's not possible to tune to another channel?

Or am I missing something?

It doesn't actually record anything, even though the 'recording' symbol flashes up at the top of the screen every now and again. If you go to active recordings, there is nothing. So you end up with neither live tv or recorded TV.

 

[georgius]

I just read your logs very fast and found error

Recorder:unable to create file:'N:\Recorded TV\manual - BBC 1 London - 2012-03-10.ts' 3

The number '3' at the end is error code, which is ERROR_PATH_NOT_FOUND = The system cannot find the path specified. Bad path for recordings?

 

[eetaylog]

Ok, looking through your tvserver_tv.log file, i think i can see the series of commands that youre trying (record BBC1 to N:\Recorded TV, then switch to BBC2 only to find that MP is looping and no TV recordings are happening).

I think that in the normal chain of events the following things happen when scheduling a recording:

- User schedules a recording
- MP chooses a tuner to record to
- MP tunes to that channel
- MP starts recording

Ive attached a section of the code that is relevant to your timeframe and if you go through it (youll only need to read my highlighted parts) youll see the chain of commands that are executed by MP. Whats odd, is that in the chain of events, MP seems to be trying to execute the processes in a funny order:

- You try to record BBC1
- MP chooses a tuner to record BBC1
- MP tunes to BBC1
- You select BBC2
- MP tunes to BBC2
-then MP tries recording BBC1

Because MP is trying to switch to BBC2 before recording has initialised, the number of users on tuner DVBs card 2 still = 0, and it succesfully tunes to BBC2 because of this, after which point it then tries to record from this tuner that has just been taken up.

Incidentally the 'looping' that you describe is because MP is trying to find another free tuner to record your channel, as shown in the last line of the code ive pasted. It did this whole process several times, but i just posted one attempt.

I might be way off with the above, hopefully someone can confirm, but if im right maybe someone else can shed some light on why it seems to be attempting things in this order.

Can i suggest that as a test you:

Wait longer period between clicking record and selecting another channel
Playing around with the TV tuner priorities
Try a different TV recordings path, preferably one local to your machine rather than what is presumably a network drive/shared disk.

Hope this has given you somewhere to start looking.

Gary

[CODE]2012-03-10 [B]16:31:29[/B].187634 [scheduler thread(10)]: [B]Scheduler: Time to record BBC 1 London 16:31-16:30 Manual (BBC 1 London)[/B]
2012-03-10 16:31:29.188634 [scheduler thread(10)]: Controller: find free card for channel BBC 1 London
2012-03-10 16:31:29.188634 [scheduler thread(10)]: Controller: find card for channel BBC 1 London
2012-03-10 16:31:29.189634 [scheduler thread(10)]: Controller:  got 1 tuning details for BBC 1 London
2012-03-10 16:31:29.189634 [scheduler thread(10)]: Controller:  channel #1 DVBS:tv:BSkyB BBC 1 London Freq:10773000 ONID:2 TSID:2045 SID:6301 PMT:0x100 FTA:True LCN:1984 SymbolRate:22000 Modulation:ModNotSet Polarisation:LinearH InnerFecRate:Rate5_6 DisEqc:None band:Universal Pilot:NotSet RollOff:NotSet
2012-03-10 [B]16:31:29[/B].190634 [scheduler thread(10)]: [B]Controller:    card:2 type:DvbS can tune to channel[/B]
2012-03-10 16:31:29.192634 [scheduler thread(10)]: Controller:    card:2 type:DvbS users: 0
2012-03-10 16:31:29.192634 [scheduler thread(10)]: Controller:    card:3 type:DvbT is disabled
2012-03-10 16:31:29.192634 [scheduler thread(10)]: Controller:    card:4 type:DvbT is disabled
2012-03-10 16:31:29.192634 [scheduler thread(10)]: Controller:    card:1 type:DvbIP cannot tune to channel
2012-03-10 16:31:29.193634 [scheduler thread(10)]: Controller:    card:5 type:RadioWebStream cannot tune to channel
2012-03-10 [B]16:31:29[/B].193634 [scheduler thread(10)]: [B]Controller: found 1 card(s) for channel[/B]
2012-03-10 16:31:29.193634 [scheduler thread(10)]: AdvancedCardAllocation.GetAvailableCardsForChannel took 5 msec
2012-03-10 16:31:29.193634 [scheduler thread(10)]: Controller:    card:2 type:DvbS is available
2012-03-10 16:31:29.194634 [scheduler thread(10)]: Controller: found 1 free card(s)
2012-03-10 16:31:29.194634 [scheduler thread(10)]: AdvancedCardAllocation.GetFreeCardsForChannel took 6 msec
2012-03-10 16:31:29.194634 [scheduler thread(10)]: scheduler: try max 1 of 1 FREE cards for recording
2012-03-10 [B]16:31:29[/B].194634 [scheduler thread(10)]: [B]Scheduler : record on recommended card:2 priority:5[/B]
2012-03-10 16:31:29.196634 [scheduler thread(10)]: Scheduler : record, first tune to channel
2012-03-10 16:31:29.196634 [scheduler thread(10)]: card: Tune 2 to BBC 1 London
2012-03-10 16:31:29.196634 [scheduler thread(10)]: card: user: scheduler11:2:-1 tune DVBS:tv:BSkyB BBC 1 London Freq:10773000 ONID:2 TSID:2045 SID:6301 PMT:0x100 FTA:True LCN:1984 SymbolRate:22000 Modulation:ModNotSet Polarisation:LinearH InnerFecRate:Rate5_6 DisEqc:None band:Universal Pilot:NotSet RollOff:NotSet
2012-03-10 16:31:29.200635 [scheduler thread(10)]: TimeShifter.OnBeforeTune: resetting audio/video events
2012-03-10 16:31:29.200635 [scheduler thread(10)]: dvbs: Tune:DVBS:tv:BSkyB BBC 1 London Freq:10773000 ONID:2 TSID:2045 SID:6301 PMT:0x100 FTA:True LCN:1984 SymbolRate:22000 Modulation:ModNotSet Polarisation:LinearH InnerFecRate:Rate5_6 DisEqc:None band:Universal Pilot:NotSet RollOff:NotSet
2012-03-10 16:31:29.201635 [scheduler thread(10)]: dvbs:  Tune:DVBS:tv:BSkyB BBC 1 London Freq:10773000 ONID:2 TSID:2045 SID:6301 PMT:0x100 FTA:True LCN:1984 SymbolRate:22000 Modulation:ModNotSet Polarisation:LinearH InnerFecRate:Rate5_6 DisEqc:None band:Universal Pilot:NotSet RollOff:NotSet
2012-03-10 16:31:29.201635 [scheduler thread(10)]: dvb:GetNewSubChannel:0 #0
2012-03-10 16:31:29.202635 [scheduler thread(10)]: TvDvbChannel ctor new subchIndex:0
2012-03-10 16:31:29.202635 [scheduler thread(10)]: LNB low:9750 hi:10600 switch:11700
2012-03-10 16:31:29.203635 [scheduler thread(10)]: dvbs:channel modulation is set to ModNotSet
2012-03-10 16:31:29.203635 [scheduler thread(10)]: dvbs:channel FECRate is set to Rate5_6
2012-03-10 16:31:29.303640 [scheduler thread(10)]: dvb:Submiting tunerequest Channel:BBC 1 London subChannel:0
2012-03-10 16:31:29.303640 [scheduler thread(10)]: dvb:using existing subchannel:0
2012-03-10 16:31:29.304640 [scheduler thread(10)]: dvb:Submit tunerequest size:1 new:0
2012-03-10 16:31:29.304640 [scheduler thread(10)]: subch:0 OnBeforeTune
2012-03-10 16:31:29.305641 [scheduler thread(10)]: dvb:Submit tunerequest calling put_TuneRequest
2012-03-10 16:31:29.305641 [scheduler thread(10)]: dvb:Submit tunerequest done calling put_TuneRequest
2012-03-10 16:31:29.306641 [scheduler thread(10)]: subch:0 OnAfterTune
2012-03-10 16:31:29.306641 [scheduler thread(10)]: RunGraph
2012-03-10 16:31:29.306641 [scheduler thread(10)]: subch:0 OnGraphStart
2012-03-10 16:31:29.307641 [scheduler thread(10)]: dvb:  RunGraph
2012-03-10 [B]16:31:31[/B].725779 [(3)]: [B]Controller: find free card for channel BBC 2 England[/B]
2012-03-10 16:31:31.726779 [(3)]: Controller: find card for channel BBC 2 England
2012-03-10 16:31:31.726779 [(3)]: Controller:  got 1 tuning details for BBC 2 England
2012-03-10 16:31:31.727779 [(3)]: Controller:  channel #1 DVBS:tv:BSkyB BBC 2 England Freq:10773000 ONID:2 TSID:2045 SID:6302 PMT:0x102 FTA:True LCN:1985 SymbolRate:22000 Modulation:ModNotSet Polarisation:LinearH InnerFecRate:Rate5_6 DisEqc:None band:Universal Pilot:NotSet RollOff:NotSet
2012-03-10 [B]16:31:31[/B].727779 [(3)]: [B]Controller:    card:2 type:DvbS can tune to channel[/B]
2012-03-10 [B]16:31:31[/B].728779 [(3)]: Controller:    card:2 type:[B]DvbS users: 0[/B]
2012-03-10 16:31:31.728779 [(3)]: Controller:    card:3 type:DvbT is disabled
2012-03-10 16:31:31.728779 [(3)]: Controller:    card:4 type:DvbT is disabled
2012-03-10 16:31:31.728779 [(3)]: Controller:    card:1 type:DvbIP cannot tune to channel
2012-03-10 16:31:31.729779 [(3)]: Controller:    card:5 type:RadioWebStream cannot tune to channel
2012-03-10 16:31:31.729779 [(3)]: Controller: found 1 card(s) for channel
2012-03-10 16:31:31.729779 [(3)]: AdvancedCardAllocation.GetAvailableCardsForChannel took 3 msec
2012-03-10 16:31:31.729779 [(3)]: Controller:    card:2 type:DvbS is available
2012-03-10 16:31:31.730779 [(3)]: Controller: found 1 free card(s)
2012-03-10 16:31:31.730779 [(3)]: AdvancedCardAllocation.GetFreeCardsForChannel took 4 msec
2012-03-10 16:31:31.731779 [(3)]: Controller: TimeShiftingWouldUseCard BBC 2 England 1985
2012-03-10 16:31:31.731779 [(3)]: Controller: find free card for channel BBC 2 England
2012-03-10 16:31:31.731779 [(3)]: Controller: find card for channel BBC 2 England
2012-03-10 16:31:31.732779 [(3)]: Controller:  got 1 tuning details for BBC 2 England
2012-03-10 16:31:31.732779 [(3)]: Controller:  channel #1 DVBS:tv:BSkyB BBC 2 England Freq:10773000 ONID:2 TSID:2045 SID:6302 PMT:0x102 FTA:True LCN:1985 SymbolRate:22000 Modulation:ModNotSet Polarisation:LinearH InnerFecRate:Rate5_6 DisEqc:None band:Universal Pilot:NotSet RollOff:NotSet
2012-03-10 16:31:31.733779 [(3)]: Controller:    card:2 type:DvbS can tune to channel
2012-03-10 16:31:31.733779 [(3)]: Controller:    card:2 type:DvbS users: 0
2012-03-10 16:31:31.733779 [(3)]: Controller:    card:3 type:DvbT is disabled
2012-03-10 16:31:31.734779 [(3)]: Controller:    card:4 type:DvbT is disabled
2012-03-10 16:31:31.734779 [(3)]: Controller:    card:1 type:DvbIP cannot tune to channel
2012-03-10 16:31:31.734779 [(3)]: Controller:    card:5 type:RadioWebStream cannot tune to channel
2012-03-10 16:31:31.734779 [(3)]: Controller: found 1 card(s) for channel
2012-03-10 16:31:31.735780 [(3)]: AdvancedCardAllocation.GetAvailableCardsForChannel took 3 msec
2012-03-10 16:31:31.735780 [(3)]: Controller:    card:2 type:DvbS is available
2012-03-10 16:31:31.735780 [(3)]: Controller: found 1 free card(s)
2012-03-10 16:31:31.735780 [(3)]: AdvancedCardAllocation.GetFreeCardsForChannel took 4 msec
2012-03-10 16:31:31.736780 [(3)]: CiMenuSupported called cardid 2
2012-03-10 16:31:31.736780 [(3)]: CiMenuSupported card Hauppauge WinTV 88x DVB-S/S2 Tuner/Demod supported: False
2012-03-10 16:31:31.739780 [(3)]: Controller: StartTimeShifting BBC 2 England 1985
2012-03-10 16:31:31.739780 [(3)]: Controller: find free card for channel BBC 2 England
2012-03-10 16:31:31.740780 [(3)]: Controller: find card for channel BBC 2 England
2012-03-10 16:31:31.741780 [(3)]: Controller:  got 1 tuning details for BBC 2 England
2012-03-10 16:31:31.741780 [(3)]: Controller:  channel #1 DVBS:tv:BSkyB BBC 2 England Freq:10773000 ONID:2 TSID:2045 SID:6302 PMT:0x102 FTA:True LCN:1985 SymbolRate:22000 Modulation:ModNotSet Polarisation:LinearH InnerFecRate:Rate5_6 DisEqc:None band:Universal Pilot:NotSet RollOff:NotSet
2012-03-10 16:31:31.741780 [(3)]: Controller:    card:2 type:DvbS can tune to channel
2012-03-10 16:31:31.742780 [(3)]: Controller:    card:2 type:DvbS users: 0
2012-03-10 16:31:31.742780 [(3)]: Controller:    card:3 type:DvbT is disabled
2012-03-10 16:31:31.742780 [(3)]: Controller:    card:4 type:DvbT is disabled
2012-03-10 16:31:31.743780 [(3)]: Controller:    card:1 type:DvbIP cannot tune to channel
2012-03-10 16:31:31.743780 [(3)]: Controller:    card:5 type:RadioWebStream cannot tune to channel
2012-03-10 16:31:31.744780 [(3)]: Controller: found 1 card(s) for channel
2012-03-10 16:31:31.745780 [(3)]: AdvancedCardAllocation.GetAvailableCardsForChannel took 5 msec
2012-03-10 16:31:31.745780 [(3)]: Controller:    card:2 type:DvbS is available
2012-03-10 16:31:31.745780 [(3)]: Controller: found 1 free card(s)
2012-03-10 16:31:31.746780 [(3)]: AdvancedCardAllocation.GetFreeCardsForChannel took 6 msec
2012-03-10 16:31:31.746780 [(3)]: Controller: try max 1 of 1 cards for timeshifting
2012-03-10 16:31:31.747780 [(3)]: card: CardTune 2 BBC 2 England dudemedia:2:-1
2012-03-10 16:31:31.748780 [(3)]: card: Tune 2 to BBC 2 England
2012-03-10 16:31:31.748780 [(3)]: card: user: dudemedia:2:-1 tune DVBS:tv:BSkyB BBC 2 England Freq:10773000 ONID:2 TSID:2045 SID:6302 PMT:0x102 FTA:True LCN:1985 SymbolRate:22000 Modulation:ModNotSet Polarisation:LinearH InnerFecRate:Rate5_6 DisEqc:None band:Universal Pilot:NotSet RollOff:NotSet
2012-03-10 16:31:31.752780 [(3)]: tvcard:FreeSubChannel: subchannels count 1 subch#-1 keep graph=False
2012-03-10 16:31:31.752780 [(3)]: tvcard:FreeSubChannel :-1 - sub channel not found
2012-03-10 16:31:31.753781 [(3)]: TimeShifter.OnBeforeTune: resetting audio/video events
2012-03-10 16:31:31.753781 [(3)]: dvbs: Tune:DVBS:tv:BSkyB BBC 2 England Freq:10773000 ONID:2 TSID:2045 SID:6302 PMT:0x102 FTA:True LCN:1985 SymbolRate:22000 Modulation:ModNotSet Polarisation:LinearH InnerFecRate:Rate5_6 DisEqc:None band:Universal Pilot:NotSet RollOff:NotSet
2012-03-10 16:31:31.753781 [(3)]: dvbs:  Tune:DVBS:tv:BSkyB BBC 2 England Freq:10773000 ONID:2 TSID:2045 SID:6302 PMT:0x102 FTA:True LCN:1985 SymbolRate:22000 Modulation:ModNotSet Polarisation:LinearH InnerFecRate:Rate5_6 DisEqc:None band:Universal Pilot:NotSet RollOff:NotSet
2012-03-10 16:31:31.754781 [(3)]: dvb:GetNewSubChannel:1 #1
2012-03-10 16:31:31.755781 [(3)]: TvDvbChannel ctor new subchIndex:1
2012-03-10 16:31:31.755781 [(3)]: dvb:Submiting tunerequest Channel:BBC 2 England subChannel:1
2012-03-10 16:31:31.755781 [(3)]: dvb:using existing subchannel:1
2012-03-10 16:31:31.755781 [(3)]: dvb:Submit tunerequest size:2 new:1
2012-03-10 16:31:31.756781 [(3)]: subch:1 OnBeforeTune
2012-03-10 16:31:31.756781 [(3)]: subch:1 OnAfterTune
2012-03-10 16:31:31.757781 [(3)]: RunGraph
2012-03-10 16:31:32.988851 [TS_File_Cleanup(22)]: card: delete timeshift files C:\ProgramData\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer\live2-0.ts
2012-03-10 16:31:32.988851 [TS_File_Cleanup(22)]: card:  trying to delete C:\ProgramData\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer\live2-0.ts.tsbuffer
2012-03-10 16:31:32.989851 [TS_File_Cleanup(22)]: card:  deleted file C:\ProgramData\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer\live2-0.ts.tsbuffer
2012-03-10 16:31:32.989851 [TS_File_Cleanup(22)]: card:  trying to delete C:\ProgramData\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer\live2-0.ts.tsbuffer1.ts
2012-03-10 16:31:32.990851 [TS_File_Cleanup(22)]: card:  deleted file C:\ProgramData\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer\live2-0.ts.tsbuffer1.ts
2012-03-10 16:31:32.991851 [TS_File_Cleanup(22)]: card:  trying to delete C:\ProgramData\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer\live2-0.ts.tsbuffer2.ts
2012-03-10 16:31:32.991851 [TS_File_Cleanup(22)]: card:  deleted file C:\ProgramData\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer\live2-0.ts.tsbuffer2.ts
2012-03-10 16:31:34.189920 [scheduler thread(10)]: dvb:  LockedInOnSignal ok
2012-03-10 16:31:34.189920 [scheduler thread(10)]: subch:0 OnGraphStarted
2012-03-10 16:31:34.190920 [scheduler thread(10)]: subch:0 SetupPmtGrabber:pid 100 sid:189D
2012-03-10 16:31:34.190920 [scheduler thread(10)]: subch:0 set pmt grabber pmt:100 sid:189D
2012-03-10 16:31:34.191920 [scheduler thread(10)]: TimeShifter.OnAfterTune: resetting audio/video time
2012-03-10 16:31:34.191920 [scheduler thread(10)]: WaitForPMT: Waiting for PMT 100
2012-03-10 16:31:34.198920 [(3)]: dvb:  LockedInOnSignal ok
2012-03-10 16:31:34.198920 [(3)]: subch:1 OnGraphStart
2012-03-10 16:31:34.198920 [(3)]: subch:1 Graph already running - WaitForPMT
2012-03-10 16:31:34.198920 [(3)]: subch:1 SetupPmtGrabber:pid 102 sid:189E
2012-03-10 16:31:34.199920 [(3)]: subch:1 set pmt grabber pmt:102 sid:189E
2012-03-10 16:31:34.199920 [(3)]: TimeShifter.OnAfterTune: resetting audio/video time
2012-03-10 16:31:34.199920 [(3)]: WaitForPMT: Waiting for PMT 102
2012-03-10 16:31:34.232922 [(16)]: subch:0 OnPMTReceived() pmt:100 ran:True dynamic:False
2012-03-10 16:31:34.232922 [scheduler thread(10)]: WaitForPMT: Found PMT after 0.0410024 seconds.
2012-03-10 16:31:34.233922 [scheduler thread(10)]: subch:0 SendPmt:189D 189D FFFFFFFF D
2012-03-10 16:31:34.233922 [scheduler thread(10)]: Decode pmt
2012-03-10 16:31:34.233922 [scheduler thread(10)]: Set descriptor data with length 3
2012-03-10 16:31:34.233922 [scheduler thread(10)]: Set descriptor data with length 6
2012-03-10 16:31:34.234922 [scheduler thread(10)]: PROBLEM : descriptor lengths dont match 3 9
2012-03-10 16:31:34.234922 [scheduler thread(10)]: Set descriptor data with length 6
2012-03-10 16:31:34.234922 [scheduler thread(10)]: PROBLEM : descriptor lengths dont match 3 9
2012-03-10 16:31:34.234922 [scheduler thread(10)]: Set descriptor data with length 12
2012-03-10 16:31:34.235923 [scheduler thread(10)]: PROBLEM : descriptor lengths dont match 3 15
2012-03-10 16:31:34.235923 [scheduler thread(10)]: Set descriptor data with length 3
2012-03-10 16:31:34.235923 [scheduler thread(10)]: Set descriptor data with length 3
2012-03-10 16:31:34.235923 [scheduler thread(10)]: Set descriptor data with length 3
2012-03-10 16:31:34.236923 [scheduler thread(10)]: Set descriptor data with length 3
2012-03-10 16:31:34.236923 [scheduler thread(10)]: Set descriptor data with length 10
2012-03-10 16:31:34.236923 [scheduler thread(10)]: PROBLEM : descriptor lengths dont match 3 13
2012-03-10 16:31:34.236923 [scheduler thread(10)]: Set descriptor data with length 3
2012-03-10 16:31:34.237923 [scheduler thread(10)]: Set descriptor data with length 3
2012-03-10 16:31:34.237923 [scheduler thread(10)]: Set descriptor data with length 3
2012-03-10 16:31:34.237923 [scheduler thread(10)]: Set descriptor data with length 3
2012-03-10 16:31:34.237923 [scheduler thread(10)]: Set descriptor data with length 3
2012-03-10 16:31:34.238923 [scheduler thread(10)]: subch:0 SendPMT: Channel is FTA, nothing to do.
2012-03-10 16:31:34.238923 [scheduler thread(10)]: subch:0 SetMpegPidMapping
2012-03-10 16:31:34.238923 [scheduler thread(10)]: subch:0  pid:1388 pcr
2012-03-10 16:31:34.238923 [scheduler thread(10)]: subch:0  pid:100 pmt
2012-03-10 16:31:34.239923 [scheduler thread(10)]: subch:0  pid:1388 video type:MPEG-2
2012-03-10 16:31:34.239923 [scheduler thread(10)]: subch:0    map pid:1388 video type:MPEG-2
2012-03-10 16:31:34.240923 [scheduler thread(10)]: subch:0  pid:1389 audio lang: type:MPEG-1
2012-03-10 16:31:34.240923 [scheduler thread(10)]: subch:0    map pid:1389 audio lang: type:MPEG-1
2012-03-10 16:31:34.240923 [scheduler thread(10)]: subch:0  pid:138A audio lang: type:MPEG-1
2012-03-10 16:31:34.241923 [scheduler thread(10)]: subch:0  pid:138B teletext type:6
2012-03-10 16:31:34.241923 [scheduler thread(10)]: subch:0    map pid:138B teletext type:6
2012-03-10 16:31:34.241923 [scheduler thread(10)]: subch:0  pid:F06 type:B
2012-03-10 16:31:34.242923 [scheduler thread(10)]: subch:0  pid:F07 type:B
2012-03-10 16:31:34.242923 [scheduler thread(10)]: subch:0  pid:F08 type:B
2012-03-10 16:31:34.242923 [scheduler thread(10)]: subch:0  pid:F09 type:B
2012-03-10 16:31:34.242923 [scheduler thread(10)]: subch:0  pid:138C subtitle type:6
2012-03-10 16:31:34.242923 [scheduler thread(10)]: subch:0    map pid:138C subtitle type:6
2012-03-10 16:31:34.243923 [scheduler thread(10)]: subch:0  pid:911 type:5
2012-03-10 16:31:34.243923 [scheduler thread(10)]: subch:0  pid:912 type:5
2012-03-10 16:31:34.243923 [scheduler thread(10)]: subch:0  pid:913 type:5
2012-03-10 16:31:34.243923 [scheduler thread(10)]: subch:0  pid:90D type:5
2012-03-10 16:31:34.244923 [scheduler thread(10)]: subch:0  pid:F00 type:5
2012-03-10 16:31:34.244923 [scheduler thread(10)]: subch:0  pid:F01 type:5
2012-03-10 16:31:34.244923 [scheduler thread(10)]: subch:0  pid:F02 type:5
2012-03-10 16:31:34.244923 [scheduler thread(10)]: subch:0  pid:F03 type:5
2012-03-10 16:31:34.245923 [scheduler thread(10)]: subch:0  pid:F04 type:5
2012-03-10 16:31:34.245923 [scheduler thread(10)]: subch:0 stop tif
2012-03-10 16:31:34.245923 [scheduler thread(10)]: WaitForPmt: PMT handling took 0.0130007 seconds.
2012-03-10 16:31:34.262924 [(16)]: subch:1 OnPMTReceived() pmt:102 ran:True dynamic:False
2012-03-10 16:31:34.262924 [(3)]: WaitForPMT: Found PMT after 0.0630036 seconds.
2012-03-10 16:31:34.262924 [(3)]: subch:1 SendPmt:189E 189E FFFFFFFF C
2012-03-10 16:31:34.263924 [(3)]: Decode pmt
2012-03-10 16:31:34.263924 [(3)]: Set descriptor data with length 3
2012-03-10 16:31:34.263924 [(3)]: Set descriptor data with length 6
2012-03-10 16:31:34.263924 [(3)]: PROBLEM : descriptor lengths dont match 3 9
2012-03-10 16:31:34.264924 [(3)]: Set descriptor data with length 6
2012-03-10 16:31:34.264924 [(3)]: PROBLEM : descriptor lengths dont match 3 9
2012-03-10 16:31:34.264924 [(3)]: Set descriptor data with length 12
2012-03-10 16:31:34.264924 [(3)]: PROBLEM : descriptor lengths dont match 3 15
2012-03-10 16:31:34.265924 [(3)]: Set descriptor data with length 3
2012-03-10 16:31:34.265924 [(3)]: Set descriptor data with length 3
2012-03-10 16:31:34.265924 [(3)]: Set descriptor data with length 3
2012-03-10 16:31:34.265924 [(3)]: Set descriptor data with length 3
2012-03-10 16:31:34.265924 [(3)]: Set descriptor data with length 10
2012-03-10 16:31:34.266924 [(3)]: PROBLEM : descriptor lengths dont match 3 13
2012-03-10 16:31:34.267924 [(3)]: Set descriptor data with length 3
2012-03-10 16:31:34.267924 [(3)]: Set descriptor data with length 3
2012-03-10 16:31:34.267924 [(3)]: Set descriptor data with length 3
2012-03-10 16:31:34.268924 [(3)]: Set descriptor data with length 3
2012-03-10 16:31:34.268924 [(3)]: Set descriptor data with length 3
2012-03-10 16:31:34.268924 [(3)]: subch:1 SendPMT: Channel is FTA, nothing to do.
2012-03-10 16:31:34.268924 [(3)]: subch:1 SetMpegPidMapping
2012-03-10 16:31:34.269924 [(3)]: subch:1  pid:13EC pcr
2012-03-10 16:31:34.269924 [(3)]: subch:1  pid:102 pmt
2012-03-10 16:31:34.269924 [(3)]: subch:1  pid:13EC video type:MPEG-2
2012-03-10 16:31:34.269924 [(3)]: subch:1    map pid:13EC video type:MPEG-2
2012-03-10 16:31:34.270925 [scheduler thread(10)]: card: Tuner locked: True
2012-03-10 16:31:34.270925 [scheduler thread(10)]: **************************************************
2012-03-10 16:31:34.270925 [scheduler thread(10)]: ***** SIGNAL LEVEL: 0, SIGNAL QUALITY: 94 *****
2012-03-10 16:31:34.270925 [scheduler thread(10)]: **************************************************
2012-03-10 16:31:34.271925 [scheduler thread(10)]: card: tuned user: scheduler11 subchannel: 0
2012-03-10 16:31:34.271925 [scheduler thread(10)]: user:scheduler11 add
2012-03-10 16:31:34.271925 [scheduler thread(10)]: Scheduler: MakeFileName() using "moviesformat" (_isSerie=False)
2012-03-10 16:31:34.272925 [(3)]: subch:1  pid:13ED audio lang: type:MPEG-1
2012-03-10 16:31:34.272925 [(3)]: subch:1    map pid:13ED audio lang: type:MPEG-1
2012-03-10 16:31:34.272925 [(3)]: subch:1  pid:13EE audio lang: type:MPEG-1
2012-03-10 16:31:34.273925 [(3)]: subch:1  pid:13EF teletext type:6
2012-03-10 16:31:34.275925 [(3)]: subch:1    map pid:13EF teletext type:6
2012-03-10 16:31:34.275925 [(3)]: subch:1  pid:F06 type:B
2012-03-10 [B]16:31:34[/B].275925 [scheduler thread(10)]: [B]Scheduler : record to N:\Recorded TV\manual - BBC 1 London - 2012-03-10.ts[/B]
2012-03-10 16:31:34.276925 [(3)]: subch:1  pid:F07 type:B
2012-03-10 16:31:34.276925 [(3)]: subch:1  pid:F08 type:B
2012-03-10 16:31:34.276925 [(3)]: subch:1  pid:F09 type:B
2012-03-10 16:31:34.277925 [(3)]: subch:1  pid:13F0 subtitle type:6
2012-03-10 16:31:34.277925 [(3)]: subch:1    map pid:13F0 subtitle type:6
2012-03-10 16:31:34.277925 [(3)]: subch:1  pid:911 type:5
2012-03-10 16:31:34.277925 [(3)]: subch:1  pid:912 type:5
2012-03-10 16:31:34.277925 [(3)]: subch:1  pid:913 type:5
2012-03-10 16:31:34.278925 [(3)]: subch:1  pid:F00 type:5
2012-03-10 16:31:34.278925 [(3)]: subch:1  pid:F01 type:5
2012-03-10 16:31:34.278925 [(3)]: subch:1  pid:F02 type:5
2012-03-10 16:31:34.278925 [(3)]: subch:1  pid:F03 type:5
2012-03-10 16:31:34.279925 [(3)]: subch:1  pid:F04 type:5
2012-03-10 16:31:34.279925 [(3)]: subch:1  pid:919 type:5
2012-03-10 16:31:34.279925 [(3)]: subch:1 stop tif
2012-03-10 16:31:34.279925 [scheduler thread(10)]: Recorder.start add audioVideoEventHandler
2012-03-10 16:31:34.280925 [scheduler thread(10)]: card: StartRecording 2 N:\Recorded TV\manual - BBC 1 London - 2012-03-10.ts
2012-03-10 [B]16:31:34[/B].280925 [scheduler thread(10)]: [B]StartRecording to N:\Recorded TV\manual - BBC 1 London - 2012-03-10.ts[/B]
2012-03-10 16:31:34.280925 [scheduler thread(10)]: subch:0 StartRecord(N:\Recorded TV\manual - BBC 1 London - 2012-03-10.ts)
2012-03-10 16:31:34.281925 [(3)]: WaitForPmt: PMT handling took 0.017001 seconds.
2012-03-10 16:31:34.281925 [scheduler thread(10)]: subch:0-0 tswriter StartRecording...
2012-03-10 16:31:34.281925 [scheduler thread(10)]: SetRecorderPids
2012-03-10 16:31:34.285925 [scheduler thread(10)]: Set video / audio observer
2012-03-10 16:31:34.286925 [scheduler thread(10)]: DVB subch:0 Started recording
2012-03-10 16:31:34.287925 [scheduler thread(10)]: card: WaitForRecordingFile - waiting _eventAudio & _eventVideo
2012-03-10 16:31:34.303926 [(3)]: card: Tuner locked: True
2012-03-10 16:31:34.304926 [(3)]: **************************************************
2012-03-10 16:31:34.304926 [(3)]: ***** SIGNAL LEVEL: 0, SIGNAL QUALITY: 94 *****
2012-03-10 16:31:34.304926 [(3)]: **************************************************
2012-03-10 16:31:34.304926 [(3)]: card: tuned user: dudemedia subchannel: 1
2012-03-10 16:31:34.305927 [(3)]: user:dudemedia add
2012-03-10 16:31:34.305927 [(3)]: card2:dudemedia 2 1
2012-03-10 16:31:34.305927 [(3)]: Controller: dudemedia 2 1
2012-03-10 16:31:34.305927 [(3)]: control2:dudemedia 2 1
2012-03-10 16:31:34.307927 [(3)]: Controller: delete timeshift files C:\ProgramData\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer\live2-1.ts
2012-03-10 16:31:34.310927 [(3)]: card: StartTimeShifting 2 C:\ProgramData\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer\live2-1.ts
2012-03-10 16:31:34.311927 [(3)]: card: CAM enabled : False
2012-03-10 16:31:34.311927 [(3)]: subch:1 SetTimeShiftFileName:C:\ProgramData\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer\live2-1.ts
2012-03-10 16:31:34.311927 [(3)]: Set video / audio observer
2012-03-10 16:31:34.312927 [(3)]: subch:1 SetTimeShiftFileName fill in pids
2012-03-10 16:31:34.315927 [(3)]: subch:1-1 tswriter StartTimeshifting...
2012-03-10 16:31:34.316927 [(3)]: card: WaitForTimeShiftFile - waiting _eventAudio & _eventVideo
2012-03-10 16:31:34.328928 [(16)]: PID seen - type = Audio
2012-03-10 16:31:34.328928 [(16)]: audioVideoEventHandler Audio
2012-03-10 16:31:34.335928 [(16)]: PID seen - type = Video
2012-03-10 16:31:34.335928 [(16)]: audioVideoEventHandler Video
2012-03-10 16:31:34.336928 [(3)]: card: WaitForTimeShiftFile - video and audio are seen after 0.0200011 seconds
2012-03-10 16:31:34.337928 [(3)]: TimeshiftingEPG: channel BBC 2 England is not configured for grabbing epg
2012-03-10 16:31:34.338928 [(3)]: user:dudemedia card:2 sub:1 add stream:C:\ProgramData\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer\live2-1.ts.tsbuffer
2012-03-10 16:31:34.338928 [(3)]: RTSP: add stream stream2.1 file:C:\ProgramData\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer\live2-1.ts.tsbuffer
2012-03-10 16:31:34.338928 [(3)]: Controller: StartTimeShifting started on card:2 to C:\ProgramData\Team MediaPortal\MediaPortal TV Server\timeshiftbuffer\live2-1.ts.tsbuffer
2012-03-10 16:31:34.340929 [Channel state thread(18)]: Controller: DoSetChannelStates for 37 channels
2012-03-10 16:31:34.344929 [(3)]: CiMenuSupported called cardid 2
2012-03-10 16:31:34.344929 [(3)]: CiMenuSupported card Hauppauge WinTV 88x DVB-S/S2 Tuner/Demod supported: False
2012-03-10 16:31:34.363930 [Channel state thread(18)]: ChannelStates.GetChannelMapping took 22 msec
2012-03-10 16:31:34.401932 [Channel state thread(18)]: ChannelStates.GetTuningChannels took 37 msec
2012-03-10 16:31:34.404932 [Channel state thread(18)]: ChannelStates.GetAllTimeshiftingAndRecordingChannels took 3 msec
2012-03-10 16:31:34.404932 [Channel state thread(18)]: ChannelStates.DoSetChannelStates took 64 msec
2012-03-10 16:31:34.425933 [(16)]: PID seen - type = Audio
2012-03-10 16:31:34.425933 [(16)]: audio last seen at 10/03/2012 16:31:34
2012-03-10 16:31:49.288783 [scheduler thread(10)]: card: WaitForRecordingFile - no audio was found after 15.000858 seconds
2012-03-10 [B]16:31:49[/B].288783 [scheduler thread(10)]: [B]card: Recording failed! 2 N:\Recorded TV\manual - BBC 1 London - 2012-03-10.ts[/B]
2012-03-10 16:31:49.289784 [scheduler thread(10)]: card: StopRecording card=2, user=scheduler11
2012-03-10 16:31:49.290784 [scheduler thread(10)]: card: StopRecording for card:2
2012-03-10 16:31:49.290784 [scheduler thread(10)]: tvdvbchannel.OnStopRecording subch=0, subch index=0
2012-03-10 16:31:49.291784 [scheduler thread(10)]: tvdvbchannel.OnStopRecording subch:0-0 tswriter StopRecording...
2012-03-10 16:31:49.292784 [scheduler thread(10)]: tvcard:FreeSubChannel: subchannels count 2 subch#0 keep graph=False
2012-03-10 16:31:49.292784 [scheduler thread(10)]: DVB subch:0 Decompose()
2012-03-10 16:31:49.293784 [scheduler thread(10)]: FreeSubChannel CA: freeing sub channel : 0
2012-03-10 16:31:49.296784 [scheduler thread(10)]: user:scheduler11 remove
2012-03-10 [B]16:31:49[/B].296784 [scheduler thread(10)]: [B]scheduler: recording failed, lets try next available card.[/B][/CODE]

 

[me_sjo]

Thanks guys. Changing the recording path to the local disk rather than a network share appears to have resolved the issue.

I did play around with the permissions on the share though to see if I could get it to work and no joy. I randomly tried 'everyone', 'anonymous logon', 'localsystem' etc on the network share (full control) to no avail. Share is located on a Windows 2008 file server and MP uses other paths on this server for other media playback just fine.

So I am not sure if this is a bug or whether it's just an ACL configuration issue. I did try renaming the path to remove the spaces but that had no effect.

 

[eetaylog]

Nice one, that explains why things are happening in the order they are then. It's trying to initialise a recording to a drive that it can't see, in which time you're trying to change channel which then takes over the tuner you're trying to use.

I can't really help you with a network shares recording folder as mine is on a local partition, but if youve already played around with permissions have you tried remapping the drive, or even use the full network address rather than the mapped (n:\) address prefix?

 

[jameson_uk]

Going to mark this as no bug then

 

[me_sjo]

Going to mark this as no bug then

I'm not convinced. The network location is valid and available as MP is quite happy playing from it. The user account the network path is mapped with has full write access.

 

[Owlsroost]

See https://forum.team-mediaportal.com/threads/recording-tv-on-network-share-no-longer-works.79856/

and https://forum.team-mediaportal.com/threads/no-record.96678/

Basically, you need to run tvservice under a user account that also has correct access permissions on the network share (it runs under the standard system account by default), and use the full UNC path to the remote drive (not a mounted drive).

Tony