TV stream stops every day at certain time, certain channel (2 Viewers)

[mm1352000]

Thanks again @HTPC_Sourcer for testing and for your patience!

Regression!

Oh no! Time to break out the whip... *runs away*

We have the first recording:
[2015-07-21 20:10:10,700] [Log ] [scheduler thread] [DEBUG] - Scheduler: Check recordings for schedule The Prince - Only God Forgives...
[2015-07-21 20:10:10,700] [Log ] [scheduler thread] [INFO ] - Scheduler: Time to record Sky Cinema HD 20:10-20:45 Manuell (Sky Cinema HD)

[collapse]
[2015-07-21 20:10:11,913] [Log ] [scheduler thread] [INFO ] - subch:0 SendPMT version:20 len:94 131
[2015-07-21 20:10:11,913] [Log ] [scheduler thread] [DEBUG] - Digital Devices:--> Setting service id 131 for decrypting returned 0
[2015-07-21 20:10:11,913] [Log ] [scheduler thread] [INFO ] - subch:0 cam flags:True
[2015-07-21 20:10:11,913] [Log ] [scheduler thread] [INFO ] - subch:0 SetMpegPidMapping
[2015-07-21 20:10:11,913] [Log ] [scheduler thread] [INFO ] - subch:0 pid:4FF pcr
[2015-07-21 20:10:11,913] [Log ] [scheduler thread] [INFO ] - subch:0 pid:64 pmt
[2015-07-21 20:10:11,913] [Log ] [scheduler thread] [INFO ] - subch:0 pid:20 teletext type:6
[2015-07-21 20:10:11,913] [Log ] [scheduler thread] [INFO ] - subch:0 map pid:20 teletext type:6
[2015-07-21 20:10:11,913] [Log ] [scheduler thread] [INFO ] - subch:0 pid:30 type:5
[2015-07-21 20:10:11,913] [Log ] [scheduler thread] [INFO ] - subch:0 pid:4FF video type:H.264
[2015-07-21 20:10:11,913] [Log ] [scheduler thread] [INFO ] - subch:0 map pid:4FF video type:H.264
[2015-07-21 20:10:11,913] [Log ] [scheduler thread] [INFO ] - subch:0 pid:503 audio lang:deu type:AC3
[2015-07-21 20:10:11,913] [Log ] [scheduler thread] [INFO ] - subch:0 map pid:503 audio lang:deu type:AC3
[/collapse]

...the second recording:
[2015-07-21 20:10:13,092] [Log ] [scheduler thread] [DEBUG] - Scheduler: Check recordings for schedule Stereo...
[2015-07-21 20:10:13,107] [Log ] [scheduler thread] [INFO ] - Scheduler: Time to record Sky Cinema+1 HD 20:10-20:45 Manuell (Sky Cinema+1 HD)

[collapse]
[2015-07-21 20:10:13,232] [Log ] [scheduler thread] [INFO ] - subch:1 SendPMT version:27 len:88 134
[2015-07-21 20:10:13,232] [Log ] [scheduler thread] [DEBUG] - Digital Devices:--> Setting service id 134 for decrypting returned 0
[2015-07-21 20:10:13,232] [Log ] [scheduler thread] [INFO ] - subch:1 cam flags:True
[2015-07-21 20:10:13,232] [Log ] [scheduler thread] [INFO ] - subch:1 SetMpegPidMapping
[2015-07-21 20:10:13,232] [Log ] [scheduler thread] [INFO ] - subch:1 pid:FF pcr
[2015-07-21 20:10:13,232] [Log ] [scheduler thread] [INFO ] - subch:1 pid:60 pmt
[2015-07-21 20:10:13,232] [Log ] [scheduler thread] [INFO ] - subch:1 pid:20 teletext type:6
[2015-07-21 20:10:13,232] [Log ] [scheduler thread] [INFO ] - subch:1 map pid:20 teletext type:6
[2015-07-21 20:10:13,232] [Log ] [scheduler thread] [INFO ] - subch:1 pid:30 type:5
[2015-07-21 20:10:13,232] [Log ] [scheduler thread] [INFO ] - subch:1 pid:FF video type:H.264
[2015-07-21 20:10:13,232] [Log ] [scheduler thread] [INFO ] - subch:1 map pid:FF video type:H.264
[2015-07-21 20:10:13,232] [Log ] [scheduler thread] [INFO ] - subch:1 pid:103 audio lang:deu type:AC3
[2015-07-21 20:10:13,232] [Log ] [scheduler thread] [INFO ] - subch:1 map pid:103 audio lang:deu type:AC3
[/collapse]

...and finally the change:
[collapse]
[2015-07-21 20:15:27,105] [Log ] [4 ] [INFO ] - subch:0 OnPMTReceived() pmt:64 ran:True dynamic:True
[2015-07-21 20:15:27,105] [Log ] [PMT update] [INFO ] - subch:0 SendPmt:83 83 14 16
[2015-07-21 20:15:27,105] [Log ] [PMT update] [INFO ] - Decode pmt
[2015-07-21 20:15:27,105] [Log ] [PMT update] [INFO ] - descr1 len:6 9 4 18 33 f8 b6
[2015-07-21 20:15:27,105] [Log ] [PMT update] [INFO ] - descr1 len:6 9 4 9 c4 fb b6
[2015-07-21 20:15:27,105] [Log ] [PMT update] [INFO ] - descr1 len:6 9 4 9 af ff b6
[2015-07-21 20:15:27,105] [Log ] [PMT update] [INFO ] - descr1 len:6 9 4 9 8c fa b6
[2015-07-21 20:15:27,105] [Log ] [PMT update] [INFO ] - Set descriptor data with length 3
[2015-07-21 20:15:27,121] [Log ] [PMT update] [INFO ] - PROBLEM : descriptor lengths dont match 7 10
[2015-07-21 20:15:27,121] [Log ] [PMT update] [INFO ] - Set descriptor data with length 3
[2015-07-21 20:15:27,121] [Log ] [PMT update] [INFO ] - Set descriptor data with length 6
[2015-07-21 20:15:27,121] [Log ] [PMT update] [INFO ] - PROBLEM : descriptor lengths dont match 3 9
[2015-07-21 20:15:27,121] [Log ] [PMT update] [INFO ] - Set descriptor data with length 6
[2015-07-21 20:15:27,121] [Log ] [PMT update] [INFO ] - PROBLEM : descriptor lengths dont match 3 9
[2015-07-21 20:15:27,121] [Log ] [PMT update] [INFO ] - subch:0 SendPMT version:22 len:115 131
[2015-07-21 20:15:27,121] [Log ] [PMT update] [DEBUG] - Digital Devices:--> Setting service id 0 for decrypting returned 0
[2015-07-21 20:15:27,121] [Log ] [PMT update] [DEBUG] - Digital Devices:--> Setting service id 131 for decrypting returned 0
[2015-07-21 20:15:27,121] [Log ] [PMT update] [INFO ] - subch:0 cam flags:True
[2015-07-21 20:15:27,121] [Log ] [PMT update] [INFO ] - subch:0 SetMpegPidMapping
[2015-07-21 20:15:27,121] [Log ] [PMT update] [INFO ] - subch:0 pid:4FF pcr
[2015-07-21 20:15:27,121] [Log ] [PMT update] [INFO ] - subch:0 pid:64 pmt
[2015-07-21 20:15:27,121] [Log ] [PMT update] [INFO ] - subch:0 pid:20 teletext type:6
[2015-07-21 20:15:27,121] [Log ] [PMT update] [INFO ] - subch:0 map pid:20 teletext type:6
[2015-07-21 20:15:27,121] [Log ] [PMT update] [INFO ] - subch:0 pid:30 type:5
[2015-07-21 20:15:27,121] [Log ] [PMT update] [INFO ] - subch:0 pid:4FF video type:H.264
[2015-07-21 20:15:27,121] [Log ] [PMT update] [INFO ] - subch:0 map pid:4FF video type:H.264
[2015-07-21 20:15:27,121] [Log ] [PMT update] [INFO ] - subch:0 pid:503 audio lang:deu type:AC3
[2015-07-21 20:15:27,121] [Log ] [PMT update] [INFO ] - subch:0 map pid:503 audio lang:deu type:AC3
[2015-07-21 20:15:27,121] [Log ] [PMT update] [INFO ] - subch:0 pid:504 audio lang:eng type:AC3
[2015-07-21 20:15:27,121] [Log ] [PMT update] [INFO ] - subch:0 map pid:504 audio lang:eng type:AC3
[2015-07-21 20:15:27,121] [Log ] [PMT update] [INFO ] - SetRecorderPids
[2015-07-21 20:15:27,121] [Log ] [PMT update] [DEBUG] - OnPMTReceived: MDAPI disabled. Possible reasons are _mdplugs=null or provider not listed
[2015-07-21 20:15:27,918] [Log ] [4 ] [INFO ] - PID seen - type = Audio
[2015-07-21 20:15:27,918] [Log ] [4 ] [DEBUG] - Recorder audioVideoEventHandler Audio
[2015-07-21 20:15:27,918] [Log ] [4 ] [INFO ] - PID seen - type = Video
[2015-07-21 20:15:27,918] [Log ] [4 ] [DEBUG] - Recorder audioVideoEventHandler Video
...
[2015-07-21 20:15:31,987] [Log ] [4 ] [INFO ] - PID seen - type = Audio
[2015-07-21 20:15:31,987] [Log ] [4 ] [DEBUG] - Recorder audioVideoEventHandler Audio[/collapse]

The perfect test setup again.

At ~+5:15 a new audio channel is added to Channel 2. This new audio stream is successfully decrypted and audible

Yep, that matches what I can see in the change log section.
There are 2 "PID seen - type = Audio" entries...

The very moment when the recordings start, Channel 1 freezes! No way to get it back on other than stop and restart the channel.

Hmmm, for this part I'm not 100% sure what happened.

I can see that you were watching a 3rd channel for about 30 minutes before the recordings started:
[2015-07-21 19:54:50,174] [Log ] [11 ] [INFO ] - card: Tune on card 2007 to subchannel Spiegel Geschichte HD
...
[2015-07-21 19:54:50,174] [Log ] [11 ] [INFO ] - dvbs: TuneVBS:tvKY Spiegel Geschichte HD Freq:11553000 ONID:133 TSID:8 SID:137 PMT:0x63 FTA:False LCN:10000 SymbolRate:22000 Modulation:ModNotSet Polarisation:LinearH InnerFecRate:RateNotSet DisEqc:None band:Universal Pilot:NotSet RollOff:NotSet

...and I can see you stop this channel shortly after the second recording starts:
[collapse]
[2015-07-21 20:11:04,489] [Log ] [11 ] [DEBUG] - CardTuner.Stop: ticket id=21, found=True
[2015-07-21 20:11:04,489] [Log ] [11 ] [INFO ] - Stop cardid=2007, ticket=21, tunestate=Idle, stopstate=Stopping
[2015-07-21 20:11:04,489] [Log ] [11 ] [INFO ] - card Digital Devices DVB-S/S2 Tuner 2: StopTimeShifting userC-HTPC1 sub:0
[2015-07-21 20:11:04,489] [Log ] [11 ] [DEBUG] - card not IDLE - removing user: PC-HTPC1
[2015-07-21 20:11:04,489] [Log ] [11 ] [DEBUG] - usermanagement.RemoveUser: PC-HTPC1, subch: 0 of 2, card: 2007
[2015-07-21 20:11:04,489] [Log ] [11 ] [INFO ] - userC-HTPC1 remove
[2015-07-21 20:11:04,707] [Log ] [11 ] [INFO ] - subch:0-0 tswriter StopTimeshifting...
[2015-07-21 20:11:04,707] [Log ] [11 ] [INFO ] - tvcard:FreeSubChannel: subchannels count 2 subch#0
[2015-07-21 20:11:04,707] [Log ] [11 ] [INFO ] - DVB subch:0 Decompose()
[2015-07-21 20:11:04,707] [Log ] [11 ] [INFO ] - FreeSubChannel CA: freeing sub channel : 0
[2015-07-21 20:11:04,707] [Log ] [11 ] [INFO ] - tvcard:FreeSubChannel : subchannels STILL present 1, continuing graph
[2015-07-21 20:11:04,707] [Log ] [11 ] [INFO ] - userC-HTPC1 remove
[2015-07-21 20:11:04,707] [Log ] [11 ] [DEBUG] - CardReservation.RemoveStopTicket: removed STOP reservation with id=21
[2015-07-21 20:11:04,707] [Log ] [TS_File_Cleanup] [INFO ] - card: delete timeshift files R:\Timeshift\live2007-0.ts
[2015-07-21 20:11:04,707] [Log ] [11 ] [INFO ] - Controller:Timeshifting stopped on card:2007
[2015-07-21 20:11:04,707] [Log ] [TS_File_Cleanup] [INFO ] - card: trying to delete R:\Timeshift\live2007-0.ts.tsbuffer
[2015-07-21 20:11:04,707] [Log ] [11 ] [INFO ] - RTSP: remove stream stream2007.0
[2015-07-21 20:11:04,707] [Log ] [3 ] [DEBUG] - Controller: DoSetChannelStates for 155 channels
[2015-07-21 20:11:04,707] [Log ] [3 ] [INFO ] - ChannelStates.DoSetChannelStates took 0 msec[/collapse]

Timeshifting was using tuner 2007:
[2015-07-21 19:54:50,174] [Log ] [11 ] [INFO ] - card: Tune on card 2007 to subchannel Spiegel Geschichte HD
[2015-07-21 19:54:50,174] [Log ] [11 ] [DEBUG] - card: user: PC-HTPC1:2007:-1 tune DVBS:tvKY Spiegel Geschichte HD Freq:11553000 ONID:133 TSID:8 SID:137 PMT:0x63 FTA:False LCN:10000 SymbolRate:22000 Modulation:ModNotSet Polarisation:LinearH InnerFecRate:RateNotSet DisEqc:None band:Universal Pilot:NotSet RollOff:NotSet

Recording 1 was using tuner 2008:
[2015-07-21 20:10:10,763] [Log ] [scheduler thread] [INFO ] - card: Tune on card 2008 to subchannel Sky Cinema HD
[2015-07-21 20:10:10,763] [Log ] [scheduler thread] [DEBUG] - card: user: scheduler5565:2008:-1 tune DVBS:tvKY Sky Cinema HD Freq:11916000 ONID:133 TSID:6 SID:131 PMT:0x64 FTA:False LCN:10000 SymbolRate:27500 Modulation:ModNotSet Polarisation:LinearH InnerFecRate:RateNotSet DisEqc:None band:Universal Pilot:NotSet RollOff:NotSet

Recording 2 was using tuner 2007 as well:
[2015-07-21 20:10:13,154] [Log ] [scheduler thread] [INFO ] - card: Tune on card 2007 to subchannel Sky Cinema+1 HD
[2015-07-21 20:10:13,154] [Log ] [scheduler thread] [DEBUG] - card: user: scheduler5566:2007:-1 tune DVBS:tvKY Sky Cinema+1 HD Freq:11553000 ONID:133 TSID:8 SID:134 PMT:0x60 FTA:False LCN:10000 SymbolRate:22000 Modulation:ModNotSet Polarisation:LinearH InnerFecRate:RateNotSet DisEqc:None band:Universal Pilot:NotSet RollOff:NotSet

...but that should not be the case!
Spiegel Geschichte HD and Sky Cinema+1 HD are transmitted from the same transponder, so a single tuner can physically tune both channels at the same time... but since they're both encrypted and you're using MTD, CAM limit should be set to 1 and that should have prevented TV Server from using the same tuner when the second recording started. Very strange!

Can you confirm that you actually have the CAM limit set to 1 for all tuners that are linked to the CAM? ...especially tuner 2007...

 

[HTPCSourcer]

Can you confirm that you actually have the CAM limit set to 1 for all tuners that are linked to the CAM? ...especially tuner 2007...

Unfortunately I can.



I also checked that both Sky Cinema channels are mapped to all four tuners.

 

[Schaussi]

Hi,
here is my current log archive, this time with debug mode enabled.
The recordings were done with the first patch, so I don't know if this is useful for you any more.
I will try the latest patch today.

 

[mm1352000]

Unfortunately I can.

Well, that is bizarre... because I see when you retuned the channel:
[2015-07-21 20:11:44,374] [Log ] [11 ] [INFO ] - Controller: find free card for channel Spiegel Geschichte HD
[2015-07-21 20:11:44,374] [Log ] [11 ] [INFO ] - Controller: find card for channel Spiegel Geschichte HD
[2015-07-21 20:11:44,374] [Log ] [11 ] [INFO ] - Controller: got 1 tuning details for Spiegel Geschichte HD
[2015-07-21 20:11:44,374] [Log ] [11 ] [INFO ] - Controller: channel #1 DVBS:tvKY Spiegel Geschichte HD Freq:11553000 ONID:133 TSID:8 SID:137 PMT:0x63 FTA:False LCN:10000 SymbolRate:22000 Modulation:ModNotSet Polarisation:LinearH InnerFecRate:RateNotSet DisEqc:None band:Universal Pilot:NotSet RollOff:NotSet
[2015-07-21 20:11:44,374] [Log ] [11 ] [INFO ] - Controller: card:1 type:RadioWebStream is disabled
[2015-07-21 20:11:44,374] [Log ] [11 ] [INFO ] - Controller: card:2007 typevbS can tune to channel
[2015-07-21 20:11:44,374] [Log ] [11 ] [INFO ] - Controller: card:2007 typevbS users: 1
[2015-07-21 20:11:44,374] [Log ] [11 ] [INFO ] - Controller: card:2008 typevbS can tune to channel
[2015-07-21 20:11:44,389] [Log ] [11 ] [INFO ] - Controller: card:2008 typevbS users: 1
[2015-07-21 20:11:44,389] [Log ] [11 ] [INFO ] - Controller: card:2009 typevbS can tune to channel
[2015-07-21 20:11:44,389] [Log ] [11 ] [INFO ] - Controller: card:2009 typevbS users: 0
[2015-07-21 20:11:44,389] [Log ] [11 ] [INFO ] - Controller: card:2010 typevbS can tune to channel
[2015-07-21 20:11:44,389] [Log ] [11 ] [INFO ] - Controller: card:2010 typevbS users: 0
[2015-07-21 20:11:44,389] [Log ] [11 ] [INFO ] - Controller: found 4 card(s) for channel
[2015-07-21 20:11:44,389] [Log ] [11 ] [INFO ] - AdvancedCardAllocation.GetAvailableCardsForChannel took 14 msec
[2015-07-21 20:11:44,389] [Log ] [11 ] [INFO ] - Controller: card:2007 typevbS is not available, tuned to same transponder decrypting 1/1 channels (cam limit reached)
[2015-07-21 20:11:44,389] [Log ] [11 ] [INFO ] - Controller: card:2009 typevbS is available
[2015-07-21 20:11:44,389] [Log ] [11 ] [INFO ] - Controller: card:2010 typevbS is available
[2015-07-21 20:11:44,389] [Log ] [11 ] [INFO ] - Controller: card:2008 typevbS is not available, tuned to different transponder
[2015-07-21 20:11:44,389] [Log ] [11 ] [INFO ] - Controller: found 2 free card(s)

From my perspective this looks like a weird bug in the tuner selection code, perhaps related to user priorities. To be specific, I mean this scenario:

• [by default] the "scheduler" user has higher priority (100) than timeshifting users (2)
  
• the code saw that a lower priority user was using tuner 2007, and that a higher priority user may have needed the tuner
• the code ignored the fact that 2 other tuners (2009 and 2010) were free and should be used in preference to tuner 2007

Are you able to reproduce this problem again?
...and could you try and see what happens if you [temporarily] assign user priorities such that the priority for your timeshifting users (eg. "PC-HTPC1") is higher than the scheduler?

P.S. In case it wasn't clear, all of the discussion about user priorities refers to this configuration:
http://wiki.team-mediaportal.com/1_...n/TV-Server_Configuration/10a_User_Priorities

 

[mm1352000]

Hmmm, based on this "to-do" comment it looks like I might be right:
https://github.com/MediaPortal/Medi...ent/CardAllocation/CardAllocationBase.cs#L145

The tuner "owner" is the user with highest priority.
I'd still like it if you could confirm with the suggested tests...

 

[HTPCSourcer]

Are you able to reproduce this problem again?

This is weird....

Test 1:
Watching: National Geographic HD
17:12 - Recording #1 Sky Atlantic HD
17:12 - Recording #2 Sky Cinema HD

Result: Nat Geo HD continues to play

Test 2: Taking up same channels as yesterday when the issue occurred
Watching: Spiegel Geschichte HD
17:20 - Recording #1 Sky Cinema HD
17:20 - Recording #2 Sky Cinema+1 HD

Result: Spiegel Geschichte HD freezes

...and could you try and see what happens if you [temporarily] assign user priorities such that the priority for your timeshifting users (eg. "PC-HTPC1") is higher than the scheduler?

Test 3: as Test 2 but with User priority=100 vs Scheduler=98
Watching: Spiegel Geschichte HD
17:35 - Recording #1 Sky Cinema HD
17:35 - Recording #2 Sky Cinema+1 HD

Result: Spiegel Geschichte HD freezes

 

[mm1352000]

This is weird....

Test 1:
Watching: National Geographic HD
17:12 - Recording #1 Sky Atlantic HD
17:12 - Recording #2 Sky Cinema HD

Result: Nat Geo HD continues to play

Ahhh, in case it wasn't clear: if I'm right, this problem would only strike if you're timeshifting a channel from the same transponder.
According to KingOfSat:
http://en.kingofsat.net/tp.php?tp=23

...Nat Geo HD is not broadcast from the same transponder as Sky Cinema +1 HD. That's why you have no problem with that channel. You do have a problem with Spiegel Geschichte HD because it is broadcast from the same transponder as Sky Cinema +1 HD.

Test 2: Taking up same channels as yesterday when the issue occurred
Watching: Spiegel Geschichte HD
17:20 - Recording #1 Sky Cinema HD
17:20 - Recording #2 Sky Cinema+1 HD

Result: Spiegel Geschichte HD freezes

In other words, the problem is reproducible as I expected. It isn't nice to have found [another] problem, but at least it is consistent.

Test 3: as Test 2 but with User priority=100 vs Scheduler=98
Watching: Spiegel Geschichte HD
17:35 - Recording #1 Sky Cinema HD
17:35 - Recording #2 Sky Cinema+1 HD

Result: Spiegel Geschichte HD freezes

Okay, this result is not expected.
Either my theory was wrong or...

To be clear: for this test it looks like you were using a different user (PC) for the timeshifting user (PC-JOHANNES instead of PC-HTPC1). Did you remember to take that into account when you configured the user priorities?

P.S. Big thanks for your ongoing testing and persistence!

 

[HTPCSourcer]

Hello @mm1352000 ,

To be clear: for this test it looks like you were using a different user (PC) for the timeshifting user (PC-JOHANNES instead of PC-HTPC1).

Correct.

Did you remember to take that into account when you configured the user priorities?

Well, I changed the generic priority under "all other users". Anyway, this time I explicitly added the name to the user list below.

Result is: No freeze (I trust you don't need the logs to confirm the result, which you expected)

Any plans for a new patch to address this?

 

[Schaussi]

I tested the second patch yesterday. I haven't had time for a detailed test yet, but I think it works now. In the recording file, I can now also see the local news (the part of the file which would be damaged without using the patch).
Thank you!

 

[mm1352000]

@Schaussi
Thanks for testing!
Sounds good so far...

@HTPCSourcer

Well, I changed the generic priority under "all other users".

Hah, that would be another bug.

Result is: No freeze (I trust you don't need the logs to confirm the result, which you expected)

Perfect.

Any plans for a new patch to address this?

Sorry, not at this stage. I understand the problem, but I think fixing it properly could be tricky.