TV Server Crashes After Recording Ends (2 Viewers)

[Sigpi007]

More testing... applied the "MediaPortal IPTV filter and url source splitter" version 2.0.0.5421 from the MP Extensions Manager interface per the directions on the thread you pointed me towards. Stability seems a bit worse in this setup. Playback is randomly stopping at times. Surfing between channels is similar in regard to lag (sometimes happens but often okay), but occasionally the guide (EPG) screen locked up a few times when trying to select a new channel. Will keep running with this IPTV filter and see if the issues subside.

Also... as I was encountering lag between channel changes, I ran WireShark to monitor the packets for a couple minutes. The file is 580MB! Not sure I can get it to a trim 10MB. Is there a way I can send you a link to download?

Also... more logs from this recent experience.

 

[georgius]

First, you should update IPTV fiter to latest version (2.1.1.5424). It has some fixed bugs, but still can have other bugs, which aren't found until now. If you experience problems, don't hesitate to write to filter forum or here.

You wrote that stability is worse in your setup. Can you describe more, what do you understand in term "stability"? Also I didn't found symptoms of randomly stopped playback, but if it happen again, backup logs (if possible immediatelly) and post it.

 

[Sigpi007]

Hi @georgius

I've gone quiet here recently cause the issue disappeared after following your instructions to revert back to the original IPTV filter that came with the installer, and then reinstalling the Online Videos MP URL source splitter. In fact, everything has been blissfully stable, so I'm reluctant to test the new IPTV filter again.

I can say that when I had it running, it would only play live TV for about 20 seconds or so and then lock up. I could rewind and re watch the first 10-20 seconds of TV, but then it would pause right in the same spot as before. In addition... Had the issues starting programs from the EPG. Sorry this didn't show up in the logs. It's fully possible that there could have been an issue with the install of the new filter. I tried following the instructions in the IPTV filter thread. I might have missed something though. If you want I will try again, and then you'll have feedback from someone running in a CableCard setup, but I might need you to restate exactly what steps I should take to install the filter appropriately.

 

[georgius]

Soon or later OnlineVideos will come with new MediaPortal IPTV filter and url source splitter and there will not be option to use the MediaPortal Url Source Splitter. If you install MediaPortal IPTV filter with MediaPortal installer, there is very small probability that you can do something wrong. Anyway, if you do something wrong, filter mostly will not work or simply crash.

Installing MediaPortal IPTV filter is simple, just use MediaPortal installer. If no error occur, than filter is correctly installed. Reverting is also simple, just uninstall MediaPortal IPTV filter with MediaPortal installer and if you use OnlineVideos install MediaPortal Url Source Splitter.

So, it would be great if you find some time to test MediaPortal IPTV filter.

 

[Sigpi007]

Hi @georgius and @mm1352000 ,

I tested the MP IPTV filter version 2.1.3.5440 and was able to replicate the issue by creating a new MP environment. It is what I would consider a "vanilla" MP installation. Upon watching TV... the timeshifting abruptly stops after 30 - 60 seconds consistently.

Configuration details: This test box is connected over 1000 MBps wired ethernet connection. I did a clean install, choosing one-step configuration. I deactivated ONE of the 6 tuners on my main MP installation that is associated with my Ceton InfiniTV Eth 6 tuner, and chose that tuner for this new setup. I configured that tuner as typical for Digital Cable (activated CAM, set to tune 1 channel simultaneously, and deactivated EPG grabbing). I installed XMLTV to import EPG data from mc2xml. Then I tested viewing the TV and changing channels to confirm everything was working perfectly.

Testing:

-Step 1: Installed "Online Videos" plugin and associated plugins from that installer (namely the URL splitter associated with that installer). Confirmed plugin was working. Went back to watching TV, and changed channels to confirm I could do that. Everything working PERFECTLY.

-Step 2: Installed "MediaPortal IPTV filter and Url Splitter" version 2.1.3.5440 via the MP Extensions Manager. It recognized the previous 1.x version was installed from Online Videos and the installer removed that. The new plugin is apparently installed, and is present in my Extension Manager list. I went to watch TV and I can see/hear TV great for at least 10 seconds... then somewhere between 30-60 seconds or so the playback just STOPS. I can rewind and watch whatever I saw seconds earlier, but nothing from the point it freezed and beyond.

What's next: Because this is not my main MP installation, I can leave this instance configured with the 2.x IPTV filter and run any logs or diagnostics you want me to. Just let me know what you want me to do. This is definitely an issue at least for my network/CableCard setup.

Best regards
-sp

 

[mm1352000]

Thanks for the report!

Just let me know what you want me to do.

Neither of us have CableCARD tuners, so we can't attempt to replicate locally. Therefore posting the full log files from the above test would be an absolute necessity.

 

[Sigpi007]

And here are the logs... [DOUBLEPOST=1417045305][/DOUBLEPOST]Damn @mm1352000 you type fast! I was literally uploading them and you beat me to it.

 

[mm1352000]

Damn mm1352000 you type fast! I was literally uploading them and you beat me to it.

Sometimes too fast!

I can't tell exactly when the stream stops (would have been helpful to record this), but I can make an educated guess from the TsReader log:

[collapse]
[2014-11-26 17:06:37,455] [180e1fa0] [1388] - Demux : Video to render 0.627 Sec
[2014-11-26 17:06:47,284] [180e1fa0] [19b4] - CTsReaderFilter:uration - correction to predicted duration: 45.120 s
[2014-11-26 17:06:51,527] [180e1fa0] [19b4] - CTsReaderFilter:uration - correction to predicted duration: 45.120 s
[2014-11-26 17:06:54,711] [180e1fa0] [1678] - CTsReaderFilter:ause() - IsTimeShifting = 1 - state = 2
[2014-11-26 17:06:54,711] [180e1fa0] [1678] - MPAR/Reclock not found
[2014-11-26 17:06:54,711] [180e1fa0] [1678] - CTsReaderFilter:ause() - END - state = 1[/collapse]

[collapse][2014-11-26 17:07:32,343] [234f4008] [ 2a8] - Demux : Video to render 1.627 Sec
[2014-11-26 17:07:45,667] [234f4008] [ c5c] - CTsReaderFilter:uration - correction to predicted duration: 29.919 s
[2014-11-26 17:07:49,909] [234f4008] [ c5c] - CTsReaderFilter:uration - correction to predicted duration: 29.919 s
[2014-11-26 17:07:54,151] [234f4008] [ c5c] - CTsReaderFilter:uration - correction to predicted duration: 29.919 s
[2014-11-26 17:07:58,393] [234f4008] [ c5c] - CTsReaderFilter:uration - correction to predicted duration: 29.919 s
[2014-11-26 17:08:02,636] [234f4008] [ c5c] - CTsReaderFilter:uration - correction to predicted duration: 29.919 s
[2014-11-26 17:08:06,878] [234f4008] [ c5c] - CTsReaderFilter:uration - correction to predicted duration: 29.919 s
[2014-11-26 17:08:11,120] [234f4008] [ c5c] - CTsReaderFilter:uration - correction to predicted duration: 29.919 s
[2014-11-26 17:08:15,362] [234f4008] [ c5c] - CTsReaderFilter:uration - correction to predicted duration: 29.919 s
[2014-11-26 17:08:18,042] [234f4008] [1678] - CTsReaderFilter:ause() - IsTimeShifting = 1 - state = 2
[2014-11-26 17:08:18,042] [234f4008] [1678] - MPAR/Reclock not found
[2014-11-26 17:08:18,042] [234f4008] [1678] - CTsReaderFilter:ause() - END - state = 1[/collapse]

In other words, at ~17:06:47 for CBSHD and ~17:07:45 for NBCHD TsReader realised the timeshifting file stopped growing. This is almost certainly due to the source filter stopping receiving and/or delivering data to TsWriter.

If I look into the MPIPTVSource log I see the following at around those times:

[collapse]
26-11-2014 17:06:21.032 [1728] [{3D4C4989-8759-4450-A1D0-15FDF79DA0CE}] [Verbose] MPUrlSourceSplitter_Protocol_Rtsp: instance 'Main': CurlWorker(): RTSP request:
OPTIONS rtsp://192.168.1.121:8554/cetonmpeg0 RTSP/1.0
Session: 58395
CSeq: 7


26-11-2014 17:06:21.032 [1728] [{3D4C4989-8759-4450-A1D0-15FDF79DA0CE}] [Verbose] MPUrlSourceSplitter_Protocol_Rtsp: instance 'Main': CurlDebug(): CURL message: 'Found bundle for host 192.168.1.121: 0x689db30'
26-11-2014 17:06:21.032 [1728] [{3D4C4989-8759-4450-A1D0-15FDF79DA0CE}] [Verbose] MPUrlSourceSplitter_Protocol_Rtsp: instance 'Main': CurlDebug(): CURL message: 'Re-using existing connection! (#0) with host 192.168.1.121'
26-11-2014 17:06:21.032 [1728] [{3D4C4989-8759-4450-A1D0-15FDF79DA0CE}] [Verbose] MPUrlSourceSplitter_Protocol_Rtsp: instance 'Main': CurlDebug(): CURL message: 'Connected to 192.168.1.121 (192.168.1.121) port 8554 (#0)'
26-11-2014 17:06:21.032 [1728] [{3D4C4989-8759-4450-A1D0-15FDF79DA0CE}] [Verbose] MPUrlSourceSplitter_Protocol_Rtsp: instance 'Main': CurlDebug(): CURL message: 'Connection #0 to host 192.168.1.121 left intact'
26-11-2014 17:06:25.778 [13c8] [{3D4C4989-8759-4450-A1D0-15FDF79DA0CE}] [Verbose] MPUrlSourceSplitter_Protocol_Rtsp: ReceiveData(): track 0, setting guess total length: 136914008
26-11-2014 17:06:25.827 [1a2c] [{11A03A3D-5E97-4359-92ED-BBA7ECCC31AC}] [Verbose] MPUrlSourceSplitter_Parser_Mpeg2TS: ReceiveDataWorker(): setting guess total length: 137177208
26-11-2014 17:06:33.121 [1a2c] [{11A03A3D-5E97-4359-92ED-BBA7ECCC31AC}] [Warning] MPUrlSourceSplitter_Parser_Mpeg2TS: ReceiveDataWorker(): discontinuity detected, PID: 7137 (0x1BE1), expected counter: 14, packet counter: 3
26-11-2014 17:06:33.904 [1a2c] [{11A03A3D-5E97-4359-92ED-BBA7ECCC31AC}] [Warning] MPUrlSourceSplitter_Parser_Mpeg2TS: ReceiveDataWorker(): discontinuity detected, PID: 0 (0x0000), expected counter: 7, packet counter: 14
26-11-2014 17:06:38.936 [1728] [{3D4C4989-8759-4450-A1D0-15FDF79DA0CE}] [Error] MPUrlSourceSplitter_Protocol_Rtsp: instance 'Main': CurlWorker(): error while processing packet, track url: 'rtsp://192.168.1.121/cetonmpeg0/track0', IP: 192.168.1.238:50000, server IP: 192.168.1.121:58723, length: 20
24 00 00 10 69 27 6D 20 6E 6F 74 20 64 65 61 64 20 79 65 74
26-11-2014 17:06:38.936 [1728] [{3D4C4989-8759-4450-A1D0-15FDF79DA0CE}] [Error] MPUrlSourceSplitter_Protocol_Rtsp: instance 'Main': CurlWorker(): error while receiving data: 0x8007000E
26-11-2014 17:06:38.937 [13c8] [{3D4C4989-8759-4450-A1D0-15FDF79DA0CE}] [Verbose] MPUrlSourceSplitter_Protocol_Rtsp: ReceiveData(): discontinuity, RTP timestamp: 4323142, position: 87633756, size: 1316, current track position: 87635072
26-11-2014 17:06:38.938 [13c8] [{7A33B520-2728-4914-ADBA-2B70699C69B3}] [Warning] ProtocolHoster: ReceiveDataWorker(): connection opened, trying to close and open, current time: 8477016, re-open time: 8477016 (0 ms), re-open timeout: 20000 (ms), maximum re-open time: 4294967295 (4286490279 ms)
26-11-2014 17:06:38.938 [13c8] [{3D4C4989-8759-4450-A1D0-15FDF79DA0CE}] [Verbose] MPUrlSourceSplitter_Protocol_Rtsp: ReceiveData(): discontinuity, completing request, request '20663', start '87633756', size '1048576', found: '1316', fragment start: 87633756, fragment length: 1316, start searching fragment start: 0[/collapse]

[collapse]26-11-2014 17:07:37.893 [1824] [{3D4C4989-8759-4450-A1D0-15FDF79DA0CE}] [Verbose] MPUrlSourceSplitter_Protocol_Rtsp: instance 'Main': CurlWorker(): RTSP request:
OPTIONS rtsp://192.168.1.121:8554/cetonmpeg0 RTSP/1.0
Session: 111803
CSeq: 7


26-11-2014 17:07:37.893 [1824] [{3D4C4989-8759-4450-A1D0-15FDF79DA0CE}] [Verbose] MPUrlSourceSplitter_Protocol_Rtsp: instance 'Main': CurlDebug(): CURL message: 'Found bundle for host 192.168.1.121: 0x88b6f58'
26-11-2014 17:07:37.893 [1824] [{3D4C4989-8759-4450-A1D0-15FDF79DA0CE}] [Verbose] MPUrlSourceSplitter_Protocol_Rtsp: instance 'Main': CurlDebug(): CURL message: 'Re-using existing connection! (#2) with host 192.168.1.121'
26-11-2014 17:07:37.893 [1824] [{3D4C4989-8759-4450-A1D0-15FDF79DA0CE}] [Verbose] MPUrlSourceSplitter_Protocol_Rtsp: instance 'Main': CurlDebug(): CURL message: 'Connected to 192.168.1.121 (192.168.1.121) port 8554 (#2)'
26-11-2014 17:07:37.893 [1824] [{3D4C4989-8759-4450-A1D0-15FDF79DA0CE}] [Verbose] MPUrlSourceSplitter_Protocol_Rtsp: instance 'Main': CurlDebug(): CURL message: 'Connection #2 to host 192.168.1.121 left intact'
26-11-2014 17:07:38.776 [1824] [{3D4C4989-8759-4450-A1D0-15FDF79DA0CE}] [Error] MPUrlSourceSplitter_Protocol_Rtsp: instance 'Main': CurlWorker(): error while processing packet, track url: 'rtsp://192.168.1.121/cetonmpeg0/track0', IP: 192.168.1.238:50000, server IP: 192.168.1.121:52596, length: 20
24 00 00 10 69 27 6D 20 6E 6F 74 20 64 65 61 64 20 79 65 74
26-11-2014 17:07:38.776 [1824] [{3D4C4989-8759-4450-A1D0-15FDF79DA0CE}] [Error] MPUrlSourceSplitter_Protocol_Rtsp: instance 'Main': CurlWorker(): error while receiving data: 0x8007000E
26-11-2014 17:07:38.777 [ d94] [{3D4C4989-8759-4450-A1D0-15FDF79DA0CE}] [Verbose] MPUrlSourceSplitter_Protocol_Rtsp: ReceiveData(): discontinuity, RTP timestamp: 2781780, position: 63622020, size: 1316, current track position: 63623336
26-11-2014 17:07:38.778 [ d94] [{7A33B520-2728-4914-ADBA-2B70699C69B3}] [Warning] ProtocolHoster: ReceiveDataWorker(): connection opened, trying to close and open, current time: 8536858, re-open time: 8536858 (0 ms), re-open timeout: 20000 (ms), maximum re-open time: 4294967295 (4286430437 ms)[/collapse]

The second example is "cleaner" than the first. There is a bunch of logging after the first section which seems suspicious, but I'm not 100% sure if it is connected. It may just be the source filter's attempt to reconnect after an internal error. Also, I'm not sure if the RTSP OPTIONS thing is a trigger/indicator or just happened to occur at the error point. Hopefully @georgius can confirm.

In general though, the thing that stands out the most are these sections:

26-11-2014 17:06:38.936 [1728] [{3D4C4989-8759-4450-A1D0-15FDF79DA0CE}] [Error] MPUrlSourceSplitter_Protocol_Rtsp: instance 'Main': CurlWorker(): error while processing packet, track url: 'rtsp://192.168.1.121/cetonmpeg0/track0', IP: 192.168.1.238:50000, server IP: 192.168.1.121:58723, length: 20
24 00 00 10 69 27 6D 20 6E 6F 74 20 64 65 61 64 20 79 65 74
26-11-2014 17:06:38.936 [1728] [{3D4C4989-8759-4450-A1D0-15FDF79DA0CE}] [Error] MPUrlSourceSplitter_Protocol_Rtsp: instance 'Main': CurlWorker(): error while receiving data: 0x8007000E

Code 0x8007000E means "out of memory or system resources".
I'm not sure what level the packet dump is taken from, but it seems to have a 4 byte header followed by the text (ASCII encoding) "i'm not dead yet".
I have the feeling something is going seriously wrong, but I'm not able to dig any deeper due to the complexity of the code...

 

[georgius]

@mm1352000 it seems that you found problem very fast. I don't think that RTSP OPTIONS request is trigger for that, at least because of almost 20 seconds between error and last RTSP OPTIONS request. Dumped data came on RTSP data track, where have to be only valid RTP packets. Due to internal filter reasons are data packed into interleaved packet and processed, so real data are without 4 byte header. Anyway, remote server is sending invalid data on RTSP data track - text 'i'm not dead yet' is surely invalid RTP packet.

@Sigpi007, I need few days for finishing TV server plugin to be able to set filter to dump incoming data for further analysis.

I don't see reason why it stops playback. I see that connection is closed, it is opened new open and data are surely received. It need further analysis (maybe culprit is in MPEG2 TS parsers).

 

[Sigpi007]

@georgius

Happy to help. I'll leave the test environment as-is until you have time to test some ideas.