TSWriter deadlock potential fix. (5 Viewers)

[doskabouter]

I also had a problem about an hour ago.

I was just watching tv when everything froze. Restarted mediaportal, but that didn't help.
Tried various channels (not sure if they were on same card or not), nothing worked.

Logged into tvservice, started config, and saw service was doing nothing. Tried preview of a channel and that worked ok.
After that, another try in mediaportal (same channel as I previewed) but nothing... after a while "unable to play stream"

Then, restarted tvservice (through the still running tvserver config), and after that, all worked again.

Logs attached, last (failed attempt) at 21:50:21 tvservice time, and 21:49:38 client time.
Notice the difference in time (40-50 seconds), could that be the problem?

 

[mm1352000]

I also had a problem about an hour ago.

This looks like something totally different, related to the streaming server.
From the SS log:

15-10-2013 21:31:19.391 generateSDPDescription() duration 1546.937988 : a=range:npt=0-1546.938


15-10-2013 21:32:32.149 generateSDPDescription() duration 0.000000 : a=range:npt=0-


15-10-2013 21:32:32.149 livenessTimeoutTask
15-10-2013 21:33:47.372 generateSDPDescription() duration 0.000000 : a=range:npt=0-


15-10-2013 21:33:47.372 livenessTimeoutTask
15-10-2013 21:34:52.190 generateSDPDescription() duration 0.000000 : a=range:npt=0-


15-10-2013 21:38:00.311 Stream servertream server: remove stream stream2.0
15-10-2013 21:43:31.904 Stream server: add timeshift mpeg-2 transport stream stream2.0 filename:\recorded tv\TimeShift\live2-0.ts.tsbuffer
15-10-2013 21:43:31.904 Stream server: url for stream is rtsp://192.168.1.196/stream2.0
15-10-2013 21:44:02.387 Stream servertream server: remove stream stream2.0
15-10-2013 21:44:09.454 FileReader::Read() read to less bytes
15-10-2013 21:44:09.454 FileReader::Read() read to less bytes
15-10-2013 21:44:09.454 FileReader::Read() read to less bytes
15-10-2013 21:44:09.454 MultiFileReader has error 0x80 in Loop 0. Try to clear SMB Cache.
15-10-2013 21:44:09.500 Stream server: add timeshift mpeg-2 transport stream stream2.0 filename:\recorded tv\TimeShift\live2-0.ts.tsbuffer
15-10-2013 21:44:09.500 Stream server: url for stream is rtsp://192.168.1.196/stream2.0
15-10-2013 21:44:39.733 Stream servertream server: remove stream stream2.0
15-10-2013 21:47:18.582 FileReader::Read() read to less bytes
15-10-2013 21:47:18.582 MultiFileReader has error 0x80 in Loop 0. Try to clear SMB Cache.
15-10-2013 21:47:18.645 Stream server: add timeshift mpeg-2 transport stream stream2.0 filename:\recorded tv\TimeShift\live2-0.ts.tsbuffer
15-10-2013 21:47:18.645 Stream server: url for stream is rtsp://192.168.1.196/stream2.0
15-10-2013 21:47:25.493 Stream servertream server: remove stream stream2.0
15-10-2013 21:47:41.858 Stream server: add timeshift mpeg-2 transport stream stream2.0 filename:\recorded tv\TimeShift\live2-0.ts.tsbuffer
15-10-2013 21:47:41.858 Stream server: url for stream is rtsp://192.168.1.196/stream2.0
15-10-2013 21:48:12.90 Stream servertream server: remove stream stream2.0
15-10-2013 21:50:21.789 Stream server: add timeshift mpeg-2 transport stream stream6.0 filename:\recorded tv\TimeShift\live6-0.ts.tsbuffer
15-10-2013 21:50:21.789 Stream server: url for stream is rtsp://192.168.1.196/stream6.0
15-10-2013 21:50:51.990 Stream servertream server: remove stream stream6.0

I have no idea what any of this means.

 

[doskabouter]

Well, let's hope it's a one time-issue then...

I'll keep an aye on it

 

[mm1352000]

Hello again mcraenz

I haven't really kept track of what version of MP I've been using and when to be honest but I think I've only been running stable releases. Upgrading within a week of releases I guess.

I'm not sure there is an older driver version for the TBS6985, it's a pretty new card. very similar to the 6984 though and exhibiting the same problem.

Okay, so based on that at this stage we can't tie the problem to a specific MP or driver release. What I'm driving at is that if the problem wasn't occurring when you first got the 6984, then started at some point with the 6984 (and has continued with the 6985)... something changed to trigger this, and we need to isolate what that something is. Unfortunately your answers don't shed any light...

Tonight I played with test channels again. All just FTA DVB-S. (MD all disabled still). After a while test channels started returning 'Tune Canceled'. Stopped the test and tried manual control same message popup - 'Tune Canceled'.

@gibman
Think I need your advice here.
It looks like reservations are not being cleaned up properly in certain cases...

All the cards are red in manual control. What does the red mean anyway? I know, I should RTFM!

It isn't in the manual and you're not the only person to ask:
https://forum.team-mediaportal.com/...-screen-tv-server-config.121513/#post-1027042

mm

 

[mcraenz]

Okey it did it again. After watching TV for a while tonight I went to SetupTV and tried to time-shift. All cards busy when choosing a specific card. All DVB-S cards (currently highest priority) skipped and tuned on DVB-T. Logs attached. Sorry they are a bit messy realised I still had a schedule for a sky channel which kept trying to start recording. Anyway it looks like the same problem and once again cannot kill TVService.exe

Interesting to note the DVB-T card doesn't get blocked up. Maye because all EPG grabbing by this card is disabled?

Logs attached.

 

[mm1352000]

Okay, so I think you just ruled out that plugin.

It starts here:
[collapse][2013-10-16 21:40:29,729] [Log ] [DVB EPG timer] [INFO ] - dvbs: TuneVBS:tv:TVNZ U Freq:12483000 ONID:47 TSID:22 SID:1904 PMT:0x10B FTA:True LCN:10000 SymbolRate:22500 Modulation:ModNotSet Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:None band:Universal Pilot:NotSet RollOff:NotSet
[2013-10-16 21:40:29,729] [Log ] [DVB EPG timer] [INFO ] - dvb:GetNewSubChannel:0 #0
[2013-10-16 21:40:29,731] [Log ] [DVB EPG timer] [INFO ] - TvDvbChannel ctor new subchIndex:0
[2013-10-16 21:40:29,731] [Log ] [DVB EPG timer] [INFO ] - card: AddTuneEvent card: 4018 / subch: 0
[2013-10-16 21:40:29,732] [Log ] [DVB EPG timer] [INFO ] - LNB low:10750 hi:10750 switch:0
[2013-10-16 21:40:29,732] [Log ] [DVB EPG timer] [INFO ] - dvbs:channel modulation is set to ModNotSet
[2013-10-16 21:40:29,732] [Log ] [DVB EPG timer] [INFO ] - dvbs:channel FECRate is set to Rate3_4
[2013-10-16 21:40:29,833] [Log ] [DVB EPG timer] [INFO ] - dvbubmiting tunerequest Channel:U subChannel:0
[2013-10-16 21:40:29,833] [Log ] [DVB EPG timer] [INFO ] - dvb:using existing subchannel:0
[2013-10-16 21:40:29,833] [Log ] [DVB EPG timer] [INFO ] - dvbubmit tunerequest size:1 new:0
[2013-10-16 21:40:29,834] [Log ] [DVB EPG timer] [INFO ] - subch:0 OnBeforeTune
[2013-10-16 21:40:29,835] [Log ] [DVB EPG timer] [INFO ] - dvbubmit tunerequest calling put_TuneRequest
[2013-10-16 21:40:29,835] [Log ] [DVB EPG timer] [INFO ] - dvbubmit tunerequest done calling put_TuneRequest
[2013-10-16 21:40:29,835] [Log ] [DVB EPG timer] [INFO ] - subch:0 OnAfterTune
[2013-10-16 21:40:29,836] [Log ] [DVB EPG timer] [INFO ] - RunGraph
[2013-10-16 21:40:29,836] [Log ] [DVB EPG timer] [INFO ] - subch:0 OnGraphStart
[2013-10-16 21:40:29,837] [Log ] [DVB EPG timer] [INFO ] - dvb: RunGraph
[2013-10-16 21:40:30,041] [Log ] [DVB EPG timer] [INFO ] - dvb: LockInOnSignal ok
[2013-10-16 21:40:30,042] [Log ] [DVB EPG timer] [INFO ] - subch:0 OnGraphStarted
[2013-10-16 21:40:30,042] [Log ] [DVB EPG timer] [INFO ] - subch:0 SetupPmtGrabberid 10B sid:770
[2013-10-16 21:40:30,042] [Log ] [DVB EPG timer] [INFO ] - subch:0 set pmt grabber pmt:10B sid:770
[2013-10-16 21:40:30,043] [Log ] [DVB EPG timer] [DEBUG] - WaitForPMT: Waiting for PMT 10B
[2013-10-16 21:40:40,043] [Log ] [DVB EPG timer] [DEBUG] - WaitForPMT: Timed out waiting for PMT after 10 seconds. Increase the PMT timeout value?
[2013-10-16 21:40:40,043] [Log ] [DVB EPG timer] [DEBUG] - Setting to 0 to search for new PMT.
[2013-10-16 21:40:40,043] [Log ] [DVB EPG timer] [INFO ] - subch:0 SetupPmtGrabberid 0 sid:770
[2013-10-16 21:40:40,043] [Log ] [DVB EPG timer] [INFO ] - subch:0 set pmt grabber pmt:0 sid:770
[2013-10-16 21:40:40,044] [Log ] [DVB EPG timer] [DEBUG] - WaitForPMT: Waiting for PMT 0
[2013-10-16 21:40:50,044] [Log ] [DVB EPG timer] [DEBUG] - WaitForPMT: Timed out waiting for PMT after 10 seconds. Increase the PMT timeout value?
[2013-10-16 21:40:50,044] [Log ] [DVB EPG timer] [DEBUG] - Setting to 0 to search for new PMT.
[2013-10-16 21:40:50,044] [Log ] [DVB EPG timer] [INFO ] - tvcard:FreeSubChannel: subchannels count 1 subch#0
[2013-10-16 21:40:50,045] [Log ] [DVB EPG timer] [INFO ] - DVB subch:0 Decompose()
[2013-10-16 21:40:50,046] [Log ] [DVB EPG timer] [INFO ] - FreeSubChannel CA: freeing sub channel : 0
[2013-10-16 21:40:50,047] [Log ] [DVB EPG timer] [INFO ] - tvcard:FreeSubChannel : no subchannels present, pausing graph
[2013-10-16 21:40:50,047] [Log ] [DVB EPG timer] [INFO ] - dvbtopGraph called
[2013-10-16 21:40:50,047] [Log ] [DVB EPG timer] [INFO ] - tvcard:FreeAllSubChannels
[2013-10-16 21:40:50,047] [Log ] [DVB EPG timer] [INFO ] - dvbtopGraph[/collapse]

The graph is not fully stopped, but we can see that TsWriter stops:

16-10-2013 21:40:50.45 debug: DeleteChannel()
16-10-2013 21:40:50.45 del m_pVideoAnalyzer
16-10-2013 21:40:50.45 analyzer: reset
16-10-2013 21:40:50.45 del m_pPmtGrabber
16-10-2013 21:40:50.46 del m_pRecorder
16-10-2013 21:40:50.46 del m_pTimeShifting
16-10-2013 21:40:50.46 del m_pTeletextGrabber
16-10-2013 21:40:50.46 del m_pCaGrabber
16-10-2013 21:40:50.46 del done...
16-10-2013 21:40:50.47 CMpTsFilter:ause()
16-10-2013 21:40:50.48 Pause filter...
16-10-2013 21:40:50.48 HRESULT = 0x0
16-10-2013 21:40:50.93 CMpTsFilter:top()
16-10-2013 21:40:50.93 Stop streaming...
16-10-2013 21:40:50.93 Stop filter...
16-10-2013 21:40:50.93 HRESULT = 0x0
16-10-2013 22:12:00.997 CMpTs::ctor()

So again, some upstream filter is not able to stop successfully. Here is where I think I would start to suspect TBS drivers.

Eventually we see:
[collapse][2013-10-16 22:04:33,912] [Log ] [17 ] [INFO ] - Controller: epg stop
[2013-10-16 22:04:33,912] [EPG ] [17 ] [INFO ] - EPG: grabber stopped..
[2013-10-16 22:04:33,912] [EPG ] [17 ] [INFO ] - EpgCard: card: 4018 stop grabbing
[2013-10-16 22:04:33,912] [EPG ] [17 ] [INFO ] - EpgGrabbing: Stop - user epg
[2013-10-16 22:04:33,912] [Log ] [17 ] [INFO ] - user:epg remove
[2013-10-16 22:04:42,535] [Log ] [17 ] [INFO ] - Controller: epg stop
[2013-10-16 22:04:42,541] [Log ] [17 ] [INFO ] - Controller: epg start
[2013-10-16 22:04:42,583] [EPG ] [17 ] [INFO ] - EPG: grabber initialized for 17 transponders..
[2013-10-16 22:04:45,776] [Log ] [20 ] [INFO ] - Controller: StartTimeShifting TV1 1
[2013-10-16 22:04:45,776] [Log ] [20 ] [INFO ] - Controller: epg stop
[2013-10-16 22:04:45,777] [EPG ] [20 ] [INFO ] - EPG: grabber stopped..
[2013-10-16 22:04:45,777] [Log ] [20 ] [INFO ] - Controller: find free card for channel TV1
[2013-10-16 22:04:45,777] [Log ] [20 ] [INFO ] - Controller: find card for channel TV1
[2013-10-16 22:04:45,778] [Log ] [20 ] [INFO ] - Controller: got 2 tuning details for TV1
[2013-10-16 22:04:45,778] [Log ] [20 ] [INFO ] - Controller: channel #1 DVBT:tv:TVNZ TV ONE Freq:530000 ONID:8746 TSID:25 SID:1200 PMT:0x64 FTA:True LCN:1 BandWidth:8
[2013-10-16 22:04:45,779] [Log ] [20 ] [INFO ] - Controller: card:8 type:RadioWebStream is disabled
[2013-10-16 22:04:45,779] [Log ] [20 ] [INFO ] - Controller: card:7 type:Analog is disabled
[2013-10-16 22:04:45,779] [Log ] [20 ] [INFO ] - Controller: card:4015 typevbS cannot tune to channel
[2013-10-16 22:04:45,779] [Log ] [20 ] [INFO ] - Controller: card:4016 typevbS cannot tune to channel
[2013-10-16 22:04:45,780] [Log ] [20 ] [INFO ] - Controller: card:4017 typevbS cannot tune to channel
[2013-10-16 22:04:45,780] [Log ] [20 ] [INFO ] - Controller: card:4018 typevbS cannot tune to channel
[2013-10-16 22:04:45,780] [Log ] [20 ] [INFO ] - Controller: card:6 typevbT can tune to channel
[2013-10-16 22:04:45,781] [Log ] [20 ] [INFO ] - Controller: channel #2 DVBS:tv:TVNZ TV ONE Freq:12483000 ONID:47 TSID:22 SID:1035 PMT:0x10D FTA:True LCN:10000 SymbolRate:22500 Modulation:ModNotSet Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:None band:Universal Pilot:NotSet RollOff:NotSet
[2013-10-16 22:04:45,781] [Log ] [20 ] [INFO ] - Controller: card:8 type:RadioWebStream is disabled
[2013-10-16 22:04:45,781] [Log ] [20 ] [INFO ] - Controller: card:7 type:Analog is disabled
[2013-10-16 22:04:45,782] [Log ] [20 ] [INFO ] - Controller: card:4015 typevbS can tune to channel
[2013-10-16 22:04:45,782] [Log ] [20 ] [INFO ] - Controller: card:4016 typevbS can tune to channel
[2013-10-16 22:04:45,783] [Log ] [20 ] [INFO ] - Controller: card:4017 typevbS can tune to channel
[2013-10-16 22:04:45,783] [Log ] [20 ] [INFO ] - Controller: card:4018 typevbS can tune to channel
[2013-10-16 22:04:45,784] [Log ] [20 ] [INFO ] - Controller: card:6 typevbT cannot tune to channel
[2013-10-16 22:04:45,784] [Log ] [20 ] [INFO ] - Controller: found 5 card(s) for channel
[2013-10-16 22:04:45,784] [Log ] [20 ] [INFO ] - AdvancedCardAllocation.GetAvailableCardsForChannel took 6 msec
[2013-10-16 22:04:45,784] [Log ] [20 ] [INFO ] - Controller: found 5 free card(s)
[2013-10-16 22:04:45,785] [Log ] [20 ] [INFO ] - AdvancedCardAllocation.GetFreeCardsForChannel took 7 msec
[2013-10-16 22:04:45,785] [Log ] [20 ] [DEBUG] - CardReservationBase.RequestCardTuneReservation: placed reservation with id=1639, tuningdetails=DVBS:tv:TVNZ TV ONE Freq:12483000 ONID:47 TSID:22 SID:1035 PMT:0x10D FTA:True LCN:10000 SymbolRate:22500 Modulation:ModNotSet Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:None band:Universal Pilot:NotSet RollOff:NotSet
[2013-10-16 22:04:45,786] [Log ] [20 ] [DEBUG] - CardReservationBase.RequestCardTuneReservation: placed reservation with id=1640, tuningdetails=DVBS:tv:TVNZ TV ONE Freq:12483000 ONID:47 TSID:22 SID:1035 PMT:0x10D FTA:True LCN:10000 SymbolRate:22500 Modulation:ModNotSet Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:None band:Universal Pilot:NotSet RollOff:NotSet
[2013-10-16 22:04:45,786] [Log ] [20 ] [DEBUG] - CardReservationBase.RequestCardTuneReservation: placed reservation with id=1641, tuningdetails=DVBS:tv:TVNZ TV ONE Freq:12483000 ONID:47 TSID:22 SID:1035 PMT:0x10D FTA:True LCN:10000 SymbolRate:22500 Modulation:ModNotSet Polarisation:LinearH InnerFecRate:Rate3_4 DisEqc:None band:Universal Pilot:NotSet RollOff:NotSet
[2013-10-16 22:04:45,786] [Log ] [20 ] [DEBUG] - CardReservationBase.HasUserHigherPriorityThanBlockingUser: True - user 'setuptv-1--1' with prio=2 vs blocking user 'epg' with prio=1
[2013-10-16 22:04:45,787] [Log ] [20 ] [INFO ] - card: WaitForCancelledTuneToFinish card: 4018 / subch: 0
[/collapse]

At the end you can see the fact that the graph failed to stop for tuner 4018 is blocking the other 3 tuners from being used.

I'm sorry but I'm not really able to explain what is going with any more certainty. It looks like TV Server is behaving as intended, but unusual failure conditions related to your TBS tuners are causing TV Server to also be unreliable.

At this point I would recommend to fix any outdated tuning details, including U and PRIME and re-introduce the plugin.

 

[gibman]

Bad drivers can cause all kinds of situations where any graph related operation (stop/start/pause) blocks indefinitely.

What this means is that the card reservation ticket is never released.
So when the next channel is tuned, which requires this specific card, then you will see this card reservation error in the log.
It should atleast give you the card reservation ticket ID that is blocking, so you can use this ID to back-trace your logs.

Did you try stress testing the card using the stress test tool in setupTV ?
You could try stress test tool on different driver revisions, keeping track of the stress test stats on each run.

/gibman

 

[mm1352000]

Bad drivers...

This advice is definitely right for the MediaPortalLogs_16_10_13__22_14.zip logs.

However, it seems something different is happening in the earlier logs (MediaPortalLogs_15_10_13__23_38.zip) when the stress test was done. There I am seeing that cancelled tune requests from the stress test seem to be creating failed reservations.

 

[mcraenz]

Thanks for all the help and advice guys. I've deleted the defunct channels and done a re-scan. I'll report back.

 

[Owlsroost]

So - we are going to have to decide soon to include (or not) the current version of the fixes into MP 1.6.0 pre-release - my feeling is that it's OK (no regressions) and a considerable improvement over the old code i.e. I think we should include it.

Comments/thoughts please ?