[confirm] Tvservice crashing (2 Viewers)

[doskabouter]

Since I did a rescan of my tv-channels I have an occasional crash of the tvservice.
I suspect that the cause is some bad signal or so, but not 100% sure.
(Channelscan always returns more channels than I can actually tune to and get video)

The eventlog shows me a nice stack-trace, so that always a nice start.

Logs included, and also added an "Eventlog.txt" which shows the stacktrace (amongst other eventlog-info)

 

[doskabouter]

Bump

 

[mm1352000]

Thanks for the report.

To be honest I hate streaming server related issues. Mostly because I know nothing about how this code works (read: I have pretty much no chance of fixing this).

From the streaming server perspective the problem starts here:

18-02-2014 18:19:21.538 Stream servertream server: remove stream stream3.0
18-02-2014 18:19:21.679 ts:dtor:ea368d8
18-02-2014 18:19:51.865 Stream server: add timeshift mpeg-2 transport stream stream5.0 filename:\Recorded TV\TimeShift\live5-0.ts.tsbuffer
18-02-2014 18:19:51.865 Stream server: url for stream is rtsp://192.168.1.196/stream5.0
18-02-2014 18:19:51.927 tspen D:\Recorded TV\TimeShift\live5-0.ts.tsbuffer
18-02-2014 18:19:53.440 MultiFileReader: timedout while waiting for buffer file to become available
18-02-2014 18:19:53.440 ts:ctor:e66b720
18-02-2014 18:19:53.440 CTSBuffer:etChannelType() - Buffer size set to TV (32336)
18-02-2014 18:19:53.440 ts:size 0
18-02-2014 18:19:54.953 MultiFileReader: timedout while waiting for buffer file to become available
18-02-2014 18:19:54.953 MultiFileReader::no file
18-02-2014 18:19:54.953 MultiFileReader::no file
18-02-2014 18:19:54.953 ts:dtor:e66b720
18-02-2014 18:19:56.467 MultiFileReader: timedout while waiting for buffer file to become available
18-02-2014 18:19:56.467 MultiFileReader::no file
18-02-2014 18:19:56.467 MultiFileReader::no file
18-02-2014 18:19:56.467 MultiFileReader::no file

After that pretty much just more "MultiFileReader::no file" until the crash:

18-02-2014 18:21:13.780 Stream server: add timeshift mpeg-2 transport stream stream5.0 filename:\Recorded TV\TimeShift\live5-0.ts.tsbuffer
18-02-2014 18:21:13.780 Stream server: url for stream is rtsp://192.168.1.196/stream5.0

[2014-02-18 18:21:13,936] [Log ] [TS_File_Cleanup] [INFO ] - card: delete timeshift files D:\Recorded TV\TimeShift\live5-0.ts
[2014-02-18 18:21:16,089] [Log ] [TS_File_Cleanup] [INFO ] - card: trying to delete D:\Recorded TV\TimeShift\live5-0.ts.tsbuffer

Note the crash appears to happen when TV Server deletes the file that the RTSP streaming server was previously trying to open.

I think it is more interesting to investigate why the RTSP server cannot open the file (read: I have more chance of solving the underlying cause of the streaming server crash than preventing the streaming server from crashing again in the same conditions).

In the TsWriter logs we can see that there is no buffer throttling when you attempt to tune "Reggefiber NDR". In other words, I suspect that tune request did not work.
[collapse]
[2014-02-18 18:19:51,038] [7141a28] [9c4] - debug: AddChannel()
[2014-02-18 18:19:51,038] [7141a28] [9c4] - analyzer: reset
[2014-02-18 18:19:51,038] [7141a28] [9c4] - PatParser::Reset
[2014-02-18 18:19:51,038] [7141a28] [9c4] - NIT:Reset
[2014-02-18 18:19:51,038] [7141a28] [9c4] - PatParser::Reset done
[2014-02-18 18:19:51,038] [7141a28] [9c4] - cagrabber: reset
[2014-02-18 18:19:51,038] [7141a28] [9c4] - debug: done AddChannel()
[2014-02-18 18:19:51,038] [7141a28] [9c4] - epg: reset
[2014-02-18 18:19:51,038] [7141a28] [9c4] - epg:ResetEPG()
[2014-02-18 18:19:51,053] [7141a28] [9c4] - mhw reset
[2014-02-18 18:19:51,053] [7141a28] [9c4] - CMpTsFilter:ause()
[2014-02-18 18:19:51,053] [7141a28] [9c4] - Pause filter...
[2014-02-18 18:19:51,053] [7141a28] [9c4] - HRESULT = 0x0
[2014-02-18 18:19:51,053] [7141a28] [9c4] - CMpTsFilter::Run()
[2014-02-18 18:19:51,053] [7141a28] [9c4] - Run filter...
[2014-02-18 18:19:51,053] [7141a28] [9c4] - HRESULT = 0x0
[2014-02-18 18:19:51,553] [7141a28] [9c4] - pmtgrabber: set callback:59cfe38
[2014-02-18 18:19:51,553] [7141a28] [9c4] - pmtgrabber: grab pmt:1f5e sid:348
[2014-02-18 18:19:51,662] [7141a28] [334] - pmtgrabber: got pmt 1f5e sid:348
[2014-02-18 18:19:51,662] [7141a28] [334] - pmtgrabber: PMT pids changed from:
[2014-02-18 18:19:51,662] [7141a28] [334] - pcr pid: 0
[2014-02-18 18:19:51,662] [7141a28] [334] - pmt pid: 0
[2014-02-18 18:19:51,662] [7141a28] [334] - pmtgrabber: PMT pids changed to:
[2014-02-18 18:19:51,662] [7141a28] [334] - pcr pid: 1f60
[2014-02-18 18:19:51,662] [7141a28] [334] - pmt pid: 1f5e
[2014-02-18 18:19:51,662] [7141a28] [334] - video pid: d3 type: MPEG2
[2014-02-18 18:19:51,662] [7141a28] [334] - audio pid: d4 language: ger type: MPEG1 - audio
[2014-02-18 18:19:51,662] [7141a28] [334] - audio pid: d5 language: mis type: MPEG1 - audio
[2014-02-18 18:19:51,662] [7141a28] [334] - pmtgrabber: got new pmt version:6 ffffffff, service_id:348
[2014-02-18 18:19:51,662] [7141a28] [334] - pmtgrabber: do callback pid 1f5e
[2014-02-18 18:19:51,662] [7141a28] [9c4] - analyzer: set video pid:d3
[2014-02-18 18:19:51,662] [7141a28] [9c4] - analyzer: reset
[2014-02-18 18:19:51,662] [7141a28] [9c4] - analyzer: set audio pid:d4
[2014-02-18 18:19:51,662] [7141a28] [9c4] - analyzer: reset
[2014-02-18 18:19:51,709] [7141a28] [9c4] - Recorder: TIMESHIFT SetVideoAudioObserver observer ok
[2014-02-18 18:19:51,709] [7141a28] [9c4] - Recorder: TIMESHIFT set filename:\Recorded TV\TimeShift\live5-0.ts.tsbuffer
[2014-02-18 18:19:51,709] [7141a28] [9c4] - CDiskRecorder:etChannelType() - Channel type is 0
[2014-02-18 18:19:51,709] [7141a28] [9c4] - CDiskRecorder:etChannelType() - Channel type is 0
[2014-02-18 18:19:51,709] [7141a28] [9c4] - Recorder: TIMESHIFT paused=yes
[2014-02-18 18:19:51,709] [7141a28] [9c4] - Recorder: TIMESHIFT Received from TvService: pmt pid:0x1f5e serviceId: 0x348 pmtlength:55
[2014-02-18 18:19:51,709] [7141a28] [9c4] - Recorder: TIMESHIFT Old pids cleared
[2014-02-18 18:19:51,709] [7141a28] [9c4] - Recorder: TIMESHIFT got pmt - tableid: 0x2 section_length: 52 sid: 0x348
[2014-02-18 18:19:51,709] [7141a28] [9c4] - Recorder: TIMESHIFT PMT parsed - Pid 0x1f5e ServiceId 0x348 stream count: 4
[2014-02-18 18:19:51,709] [7141a28] [9c4] - Recorder: TIMESHIFT pcr pid:0x1f60
[2014-02-18 18:19:51,709] [7141a28] [9c4] - Recorder: TIMESHIFT SetPcrPid clear old PIDs
[2014-02-18 18:19:51,709] [7141a28] [9c4] - Recorder: TIMESHIFT add video stream pid: 0xd3 fake pid: 0x30 stream type: 0x2 logical type: 0x2 descriptor length: 0
[2014-02-18 18:19:51,709] [7141a28] [9c4] - Recorder: TIMESHIFT add audio stream pid: 0xd4 fake pid: 0x40 stream type: 0x3 logical type: 0x3 descriptor length: 6
[2014-02-18 18:19:51,709] [7141a28] [9c4] - Recorder: TIMESHIFT add audio stream pid: 0xd5 fake pid: 0x41 stream type: 0x3 logical type: 0x3 descriptor length: 6
[2014-02-18 18:19:51,709] [7141a28] [9c4] - Recorder: TIMESHIFT add teletext stream pid: 0xd8 fake pid: 0x84 stream type: 0x6 logical type: 0x56 descriptor length: 7
[2014-02-18 18:19:51,709] [7141a28] [9c4] - Recorder: TIMESHIFT paused=no
[2014-02-18 18:19:51,709] [7141a28] [9c4] - Recorder: TIMESHIFT Start 'D:\Recorded TV\TimeShift\live5-0.ts.tsbuffer'
[2014-02-18 18:19:51,724] [7141a28] [334] - Recorder: TIMESHIFT start of video detected
[2014-02-18 18:19:51,865] [7141a28] [334] - Recorder: TIMESHIFT start of audio detected
[2014-02-18 18:20:22,331] [7141a28] [9c4] - Recorder: TIMESHIFT Stop 'D:\Recorded TV\TimeShift\live5-0.ts.tsbuffer'
[2014-02-18 18:20:22,331] [7141a28] [9c4] - Recorder: TIMESHIFT Reset
[2014-02-18 18:20:22,331] [7141a28] [9c4] - CDiskRecorder::Reset() - Reset write buffer throttle
[2014-02-18 18:20:22,331] [7141a28] [9c4] - debug: DeleteChannel()
[2014-02-18 18:20:22,331] [7141a28] [9c4] - del m_pVideoAnalyzer
[2014-02-18 18:20:22,331] [7141a28] [9c4] - analyzer: reset
[2014-02-18 18:20:22,331] [7141a28] [9c4] - del m_pPmtGrabber
[2014-02-18 18:20:22,331] [7141a28] [9c4] - del m_pRecorder
[2014-02-18 18:20:22,331] [7141a28] [9c4] - del m_pTimeShifting
[2014-02-18 18:20:22,331] [7141a28] [9c4] - del m_pTeletextGrabber
[2014-02-18 18:20:22,331] [7141a28] [9c4] - del m_pCaGrabber
[2014-02-18 18:20:22,331] [7141a28] [9c4] - del done...
[2014-02-18 18:20:22,331] [7141a28] [9c4] - CMpTsFilter:ause()
[2014-02-18 18:20:22,331] [7141a28] [9c4] - Pause filter...
[2014-02-18 18:20:22,331] [7141a28] [9c4] - HRESULT = 0x0
[2014-02-18 18:20:22,347] [7141a28] [9c4] - CMpTsFilter:top()
[2014-02-18 18:20:22,347] [7141a28] [9c4] - Stop streaming...
[2014-02-18 18:20:22,347] [7141a28] [9c4] - Stop filter...
[2014-02-18 18:20:22,347] [7141a28] [9c4] - HRESULT = 0x0[/collapse]


Are you normally able to tune NDR (Reggefiber NDR)?

I suspect not. To me it looks like there is a PCR related problem with that channel. The PMT is telling us that the PCR should be delivered on PID 0x1f60... but from the fact that timeshifting doesn't start (ie. timeshift buffer size would have been zero, and this is the cause of the streaming server "MultiFileReader::no file") I think TsWriter does not actually receive PCR.

That's about as far as I can go...

 

[doskabouter]

Thanks for looking into this.

Don't know if I can watch NDR (it's a station I don't tune in normally). Anyway I removed the dvbc-tuningdetails but I still have an analog card that does tune in on NDR for the occasional view.

It's not a big issue (mostly because I don;t watch it very often and I do have an analog card), I did report it because there could be some underlying issue that possibly causes other problems.

 

[mm1352000]

Don't know if I can watch NDR (it's a station I don't tune in normally). Anyway I removed the dvbc-tuningdetails but I still have an analog card that does tune in on NDR for the occasional view.

It's not a big issue (mostly because I don;t watch it very often and I do have an analog card), I did report it because there could be some underlying issue that possibly causes other problems.

It is important to know whether NDR (DVB-C) works in order to investigate further. You're right: there could very well be an issue, but I won't be able to reproduce without a TS dump from the NDR multiplex/frequency.
http://wiki.team-mediaportal.com/1_MEDIAPORTAL_1/18_Contribute/4_Development/Debugging/TS_Dumps

 

[doskabouter]

Well, to be 100% honest, I can't remember if I ever been able to watch NDR on dvb-c.
Just a couple of weeks ago I ditched my misbehaving antenna signal booster and now I'm picking up more stations as before.
It could well be that it didn't pickup ndr on dvb-c before, so I can't really tell.

What I do have (and this is going a bit off-topic) is that I have some 4 or 5 stations that are picked up during scanning, but when I tune in to them, I don't get any video or audio, it just timesout or something (no crash though).

 

[mm1352000]

Well, to be 100% honest, I can't remember if I ever been able to watch NDR on dvb-c.
Just a couple of weeks ago I ditched my misbehaving antenna signal booster and now I'm picking up more stations as before.
It could well be that it didn't pickup ndr on dvb-c before, so I can't really tell.

Okay. Clearly NDR exists. If it is not going to be watchable then there should be a really good reason for that.
Please can you scan that multiplex again (so you get NDR back into your channel list), and then provide a TS dump.
You can do a single transponder scan:
frequency = 360000 kHz
modulation = 64 QAM
symbol rate = 6875 ks/s

What I do have (and this is going a bit off-topic) is that I have some 4 or 5 stations that are picked up during scanning, but when I tune in to them, I don't get any video or audio, it just timesout or something (no crash though).

This is not so off topic as you might think.
I'd be interested to see logs.
Please keep in mind that MP/TV Server don't support video-only channels (ie. no audio).

 

[doskabouter]

it should be video+audio. I'll gather some logs if I get exclusive access to the tvservice

 

[doskabouter]

Ok, here's something for you to chew on

Steps I've done:
- Stop tv service, and delete old logs
- Start tv service config, on question stating service not running, I clicked "yes" or start or so
- on 22:09 ish I started preview of Studio040 TV
- watched this a couple of seconds (i did see video) and closed preview screen
- on 22:11 I started preview of VOS Tv
- no preview screen opened, gui of setuptv became very sluggish (i.e. screen update every 20 seconds or so). (No high cpu, no peaks in other resources)
- Waited quite some time, then added logs to tvservice 1.zip.
- Then I killed setuptv, started setuptv again. There I noticed tvservice was still timeshifting vos tv.
- Then I went to manual. and stopped service
- Around that time, I created tvservice 2.zip

 

[mm1352000]

Perfect, thanks.

So, I can confirm that currently VOS TV will not work with MediaPortal. Reason is TV Server/TsWriter limitation:

[2014-03-10 22:11:02,364] [7a3ee90] [fcc] - Recorder: TIMESHIFT pcr pid:0x1fff

This means that the stream does not contain PCR (program clock rate). MediaPortal needs PCR in order to support FF/RW and seeking.
What happens is the channel is tuned successfully, and TsWriter sees the video and audio... but it won't start creating the timeshift file until it sees the first PCR info. Since this PCR info is not available it will never be seen and the timeshift file will never be created. This is the cause of the symptoms you see.

The only solution to this problem would be for TV Server to create the PCR. This is possible... but a "little bit" tricky. It is on my "this should be fixed" list for TVE 3.5.