IPTV recordings aborting prematurely 50% of time

[revengineer 127]

Luke,

I am running emby stable branch in Windows Server 2012 and was looking forward to the 3.5.2 release because it was reported to have improved TV recording functionality. I did some testing over the past three days, and unfortunately about half of my recordings are prematurely aborting. This is my third IPTV provider, and the experience has been similar for all three providers.

 

I believe the issues relates to stability of the stream caused by my internet provider, Comcast. I have tested the current IPTV provider at work with VLC, and the streams are rock solid for hours. At home on Comcast, the streams will buffer in VLC on some days and during some times. I do not know if this is due to congestion or an anti-competitive measure the provider is taking.

 

In any case, I suspect that emby is interpreting the temporary (~few second) pause as the end of the stream, which prematurely ends the recording. I am showing a snipped of the log file below. Username/password were deleted, so the streams do not work as shown.

 

I am not sure if emby is timing out or whether the stream is really dead and needs to be restarted. Is is possible to make emby more resilient to this type of situation either by waiting longer or by restarting and appending the stream?

2018-08-17 21:28:00.073 Info App: Recording timer fired for SOKO Kitzbühel.
2018-08-17 21:28:00.084 Info HttpClient: GET https://www.thetvdb.com/api/GetSeriesByRemoteID.php?zap2it=EP01593347&language=en
2018-08-17 21:28:00.467 Info HttpClient: GET https://www.thetvdb.com/api/GetSeries.php?seriesname=SOKO+Kitzb%C3%BChel&language=en
2018-08-17 21:28:00.776 Info HttpClient: GET https://www.thetvdb.com/api/B89CE93890E9419B/series/101241/all/en.zip
2018-08-17 21:28:03.394 Info App: MovieDbProvider: Finding id for item: SOKO Kitzbühel
2018-08-17 21:28:03.394 Info HttpClient: GET https://api.themoviedb.org/3/search/tv?api_key=f6bd687ffa63cd282b6ff2c6877f2669&query=SOKO+Kitzb%C3%BChel&language=en
2018-08-17 21:28:03.506 Info HttpClient: GET https://private.omdbapi.com?apikey=fe53f97e&plot=full&r=json&s=SOKO+Kitzb%C3%BChel&type=series
2018-08-17 21:28:03.765 Info App: Opening channel stream from Emby, external channel Id: m3u_e3e87cb719d591c61b9a0e44bb5be5e783651a695bf6ffd56464631c4b1dcebd
2018-08-17 21:28:03.765 Info App: Streaming Channel m3u_e3e87cb719d591c61b9a0e44bb5be5e783651a695bf6ffd56464631c4b1dcebd
2018-08-17 21:28:03.765 Info App: Opening SharedHttpStream Live stream from http://tv.tvtech.xdns.pro:80/live/19098.ts
2018-08-17 21:28:03.765 Info HttpClient: GET http://tv.tvtech.xdns.pro:80/live/19098.ts
2018-08-17 21:28:04.497 Info HttpClient: Http response 200 from http://tv.tvtech.xdns.pro:80/live/19098.ts after 731ms. HeadersServer=nginx, Date=Sat, 18 Aug 2018 01:28:01 GMT, Connection=close, Access-Control-Allow-Origin=*
2018-08-17 21:28:04.497 Info App: Beginning SharedHttpStream stream to M:\tmp\transcoding-temp\d3a69ef911d9462cb44cbf64fdd05405.ts
2018-08-17 21:28:04.497 Info App: Live stream opened after 732.0429ms
2018-08-17 21:28:04.497 Info App: Returning mediasource streamId 19ef2d61388b2b878f938717f6aa1ee2, mediaSource.Id 19ef2d61388b2b878f938717f6aa1ee2, mediaSource.LiveStreamId null
2018-08-17 21:28:04.504 Info MediaSourceManager: Live tv media info probe took 0.0062848 seconds
2018-08-17 21:28:04.504 Info MediaSourceManager: Live stream opened: {"Protocol":"Http","Id":"19ef2d61388b2b878f938717f6aa1ee2","Path":"http://127.0.0.1:8096/LiveTv/LiveStreamFiles/d3a69ef911d9462cb44cbf64fdd05405/stream.ts","Type":"Default","Container":"mpegts","IsRemote":true,"ReadAtNativeFramerate":false,"IgnoreDts":true,"IgnoreIndex":false,"GenPtsInput":false,"SupportsTranscoding":true,"SupportsDirectStream":true,"SupportsDirectPlay":false,"IsInfiniteStream":true,"RequiresOpening":true,"RequiresClosing":true,"LiveStreamId":"a17c75760a04e99b68cf766e11316e1c_09efa0d56b934a82adec00a87b837fb0_19ef2d61388b2b878f938717f6aa1ee2","RequiresLooping":false,"SupportsProbing":true,"MediaStreams":[{"Codec":"h264","ColorTransfer":"bt709","ColorPrimaries":"bt709","ColorSpace":"bt709","TimeBase":"1/90000","CodecTimeBase":"1/100","VideoRange":"SDR","DisplayTitle":"720P H264","NalLengthSize":"0","IsInterlaced":false,"BitRate":8000000,"BitDepth":8,"RefFrames":1,"IsDefault":false,"IsForced":false,"Height":720,"Width":1280,"AverageFrameRate":50,"RealFrameRate":50,"Profile":"High","Type":"Video","AspectRatio":"16:9","Index":-1,"IsExternal":false,"IsTextSubtitleStream":false,"SupportsExternalStream":false,"PixelFormat":"yuv420p","Level":40,"IsAnamorphic":false},{"Codec":"mp2","TimeBase":"1/90000","CodecTimeBase":"1/48000","DisplayTitle":"MP2 stereo","IsInterlaced":false,"ChannelLayout":"stereo","BitRate":256000,"Channels":2,"SampleRate":48000,"IsDefault":false,"IsForced":false,"Type":"Audio","Index":-1,"IsExternal":false,"IsTextSubtitleStream":false,"SupportsExternalStream":false,"Level":0}],"Formats":[],"Bitrate":8256000,"RequiredHttpHeaders":{"User-Agent":"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/64.0.3282.85 Safari/537.36"},"AnalyzeDurationMs":3000}
2018-08-17 21:28:04.504 Info App: Beginning recording. Will record for 48.9249216 minutes.
2018-08-17 21:28:04.504 Info App: Writing file to path: M:\Recorded Series\SOKO Kitzbühel (2001)\Season 15\SOKO Kitzbühel S15E02 Racheengel.ts
2018-08-17 21:28:04.594 Info App: Triggering refresh on M:\Recorded Series\SOKO Kitzbühel (2001)\Season 15\SOKO Kitzbühel S15E02 Racheengel.ts
2018-08-17 21:28:04.596 Info App: Refreshing recording parent M:\Recorded Series\SOKO Kitzbühel (2001)
2018-08-17 21:28:04.596 Info App: Copying recording stream to file M:\Recorded Series\SOKO Kitzbühel (2001)\Season 15\SOKO Kitzbühel S15E02 Racheengel.ts
2018-08-17 21:28:05.263 Info HttpClient: GET https://api.themoviedb.org/3/tv/41451/season/15?api_key=f6bd687ffa63cd282b6ff2c6877f2669&append_to_response=images,keywords,external_ids,credits,videos&language=en&include_image_language=en,null

...

2018-08-17 21:32:17.785 Info App: Live Stream ended.
2018-08-17 21:32:17.785 Info App: Recording completed to file M:\Recorded Series\SOKO Kitzbühel (2001)\Season 15\SOKO Kitzbühel S15E02 Racheengel.ts
2018-08-17 21:32:17.785 Info App: Recording completed: M:\Recorded Series\SOKO Kitzbühel (2001)\Season 15\SOKO Kitzbühel S15E02 Racheengel.ts
2018-08-17 21:32:17.785 Info MediaSourceManager: Live stream 19ef2d61388b2b878f938717f6aa1ee2 consumer count is now 0
2018-08-17 21:32:17.785 Info MediaSourceManager: Closing live stream a17c75760a04e99b68cf766e11316e1c_09efa0d56b934a82adec00a87b837fb0_19ef2d61388b2b878f938717f6aa1ee2
2018-08-17 21:32:17.785 Info App: Closing SharedHttpStream
2018-08-17 21:32:17.785 Info MediaSourceManager: Live stream a17c75760a04e99b68cf766e11316e1c_09efa0d56b934a82adec00a87b837fb0_19ef2d61388b2b878f938717f6aa1ee2 closed successfully
2018-08-17 21:32:17.785 Info App: Triggering refresh on M:\Recorded Series\SOKO Kitzbühel (2001)\Season 15\SOKO Kitzbühel S15E02 Racheengel.ts
2018-08-17 21:32:17.786 Info App: Refreshing recording parent M:\Recorded Series\SOKO Kitzbühel (2001)\Season 15
2018-08-17 21:32:17.799 Info App: Running recording post processor C:\Users\admin\AppData\Roaming\Emby-Server\comskip\comskip.exe "M:\Recorded Series\SOKO Kitzbühel (2001)\Season 15\SOKO Kitzbühel S15E02 Racheengel.ts"
2018-08-17 21:32:25.008 Info HttpServer: HTTP POST http://192.168.1.50:8096/emby/Sessions/Playing/Progress. UserAgent: Roku/DVP-8.10 (048.10E04145A)
2018-08-17 21:32:25.009 Info HttpServer: HTTP Response 204 to 192.168.1.86. Time: 2ms. http://192.168.1.50:8096/emby/Sessions/Playing/Progress 
2018-08-17 21:32:27.603 Info App: Recording post-processing script completed with exit code 1

Edited August 18, 2018 by revengineer

[maegibbons 1267]

Hi

 

I have asked for stream monitoring and stream restarting for a long time.   The nature of IPTV is that the streams can be unreliable.  Emby should/could monitor the stream and restart if the stream stalls.

 

Hopefully this will be added at some stage in the not too distant future!!.

 

Krs

 

Mark

[revengineer 127]

Mark, indeed and we also had a similar conversation in another thread. I thought it is time to bring this up again because it is the one thing in emby that is not working so great for me and seemingly for others as well. Unfortunately, emby is not very vocal about the nature of the issue. All it reports is that "the life stream has ended."For a continuous TV station this is obviously incorrect. Hopefully we get some feedback from the devs. Cheers, Haje 

[Luke 37116]

Try enabling the autoloop option.

[revengineer 127]

Try enabling the autoloop option.

I have tried this in the past and it did not solve the problem. If you think that this option has changed enough in 3.5.2 that is it worth another try, I can do that after I return from travel.

 

I thought this option was introduced because some providers required this. The fact that half of my recordings work seems to show that the setting is not generally required.

 

If it helps, I am using mpeg ts streaming format. The provided offers HLS streaming with m3u8 output option. Is there any preference which works better with emby?

[Luke 37116]

Yes please try it, and I would stick with mpegts. Thanks

[revengineer 127]

ok, made the change now so we can get to the bottom of this. I can always change it back remotely if it does not work. Will let you know in a few days.

[samuelqwe 313]

Yes please try it, and I would stick with mpegts. Thanks

Any reason mpegts is better than HLS with Emby?

[Luke 37116]

It's one single stream instead of having the stream chopped up into lots of little segments. That makes everything simpler.

[revengineer 127]

Yes please try it, and I would stick with mpegts. Thanks

Luke, the first recording with looping enabled already failed. This time there was a transcode log as well. I will pm the logs.

[Luke 37116]

@@Waldonnis I added you to the PM with his log. Any idea about the error at the bottom of the ffmpeg log? Thanks.

[revengineer 127]

@@Waldonnis I added you to the PM with his log. Any idea about the error at the bottom of the ffmpeg log? Thanks.

And please note that the recording for the show reported in the OP did not involve transcoding. So while the ffmpeg log may give insight into the problem, the transcoder does not seem to be the root of the problem. Also to reiterate, it is acknowledged that the stability of the stream is the ultimate root cause but the goal is to make emby more resilient because this stream continuity seems to be an issue common to many IPTV providers and/or ISPs.

 

I have now disabled looping again. Would "debug logging" give further insight into the issue?

[Luke 37116]

The stream loop setting is already designed to increase resiliency via automatic reconnects, so we need to look at why it failed there.

[revengineer 127]

The stream loop setting is already designed to increase resiliency via automatic reconnects, so we need to look at why it failed there.

ok, fair enough. Standing by for next steps.

[Carlo 4330]

A lot of people use IPTV for sports and while we don't really want to miss anything it's far better to miss a play or two or an out in baseball then to have the whole game prematurely end.

 

Why can't Emby just use the time span that is supposed to be recording and automatically restart a stream (regardless of looping setting) and just record EVERYTHING it can during the time slot regardless of how many segments it takes to do this?

 

That to me would seem like the best approach.  Just use the EPG data (plus the padding) to know the duration, then have the recorder restart any failed streams as often as needed.  The looping setting probably wouldn't be needed then.

 

Carlo

[maegibbons 1267]

Absolutely, it should monitor the bitrate of the stream or status and restart as necessary.

 

Krs

 

Mark

[Luke 37116]

That's what the auto loop setting is supposed to be doing, never terminating the connection until it is closed by whoever opened it.

[maegibbons 1267]

Ok.  I will test with it on and off to see if I can discern any difference in behaviour.

 

Thanks

 

Krs

 

Mark

[revengineer 127]

Attached two more ffmpeg logs of aborted recordings.

 

The emby log shows the following:

2018-08-23 21:13:00.066 Info App: Recording timer fired for SOKO Stuttgart.
2018-08-23 21:13:00.077 Info HttpClient: GET https://www.thetvdb.com/api/GetSeriesByRemoteID.php?zap2it=EP01639174&language=en
2018-08-23 21:13:00.448 Info HttpClient: GET https://www.thetvdb.com/api/GetSeries.php?seriesname=SOKO+Stuttgart&language=en
2018-08-23 21:13:00.849 Info HttpClient: GET https://www.thetvdb.com/api/B89CE93890E9419B/series/133541/all/en.zip
2018-08-23 21:13:03.692 Info App: MovieDbProvider: Finding id for item: SOKO Stuttgart
2018-08-23 21:13:03.692 Info HttpClient: GET https://api.themoviedb.org/3/search/tv?api_key=f6bd687ffa63cd282b6ff2c6877f2669&query=SOKO+Stuttgart&language=en
2018-08-23 21:13:03.796 Info HttpClient: GET https://private.omdbapi.com?apikey=fe53f97e&plot=full&r=json&s=SOKO+Stuttgart&type=series
2018-08-23 21:13:04.000 Info App: Opening channel stream from Emby, external channel Id: m3u_e3e87cb719d591c61b9a0e44bb5be5e783651a695bf6ffd56464631c4b1dcebd
2018-08-23 21:13:04.000 Info App: Streaming Channel m3u_e3e87cb719d591c61b9a0e44bb5be5e783651a695bf6ffd56464631c4b1dcebd
2018-08-23 21:13:04.088 Info App: Live stream opened after 0.0012ms
2018-08-23 21:13:04.088 Info App: Returning mediasource streamId 19ef2d61388b2b878f938717f6aa1ee2, mediaSource.Id 19ef2d61388b2b878f938717f6aa1ee2, mediaSource.LiveStreamId null
2018-08-23 21:13:04.094 Info MediaSourceManager: Live tv media info probe took 0.006224 seconds
2018-08-23 21:13:04.094 Info MediaSourceManager: Live stream opened: {"Protocol":"Http","Id":"19ef2d61388b2b878f938717f6aa1ee2","Path":"http://tv.tvtech.xdns.pro:80/live/19098.ts","Type":"Default","Container":"mpegts","IsRemote":true,"ReadAtNativeFramerate":false,"IgnoreDts":true,"IgnoreIndex":false,"GenPtsInput":false,"SupportsTranscoding":true,"SupportsDirectStream":false,"SupportsDirectPlay":false,"IsInfiniteStream":true,"RequiresOpening":true,"RequiresClosing":true,"LiveStreamId":"a17c75760a04e99b68cf766e11316e1c_09efa0d56b934a82adec00a87b837fb0_19ef2d61388b2b878f938717f6aa1ee2","RequiresLooping":true,"SupportsProbing":true,"MediaStreams":[{"Codec":"h264","ColorTransfer":"bt709","ColorPrimaries":"bt709","ColorSpace":"bt709","TimeBase":"1/90000","CodecTimeBase":"1/100","VideoRange":"SDR","DisplayTitle":"720P H264","NalLengthSize":"0","IsInterlaced":false,"BitRate":8000000,"BitDepth":8,"RefFrames":1,"IsDefault":false,"IsForced":false,"Height":720,"Width":1280,"AverageFrameRate":50,"RealFrameRate":50,"Profile":"High","Type":"Video","AspectRatio":"16:9","Index":-1,"IsExternal":false,"IsTextSubtitleStream":false,"SupportsExternalStream":false,"PixelFormat":"yuv420p","Level":40,"IsAnamorphic":false},{"Codec":"mp2","TimeBase":"1/90000","CodecTimeBase":"1/48000","DisplayTitle":"MP2 stereo","IsInterlaced":false,"ChannelLayout":"stereo","BitRate":256000,"Channels":2,"SampleRate":48000,"IsDefault":false,"IsForced":false,"Type":"Audio","Index":-1,"IsExternal":false,"IsTextSubtitleStream":false,"SupportsExternalStream":false,"Level":0}],"Formats":[],"Bitrate":8256000,"RequiredHttpHeaders":{"User-Agent":"Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/64.0.3282.85 Safari/537.36"},"AnalyzeDurationMs":3000}
2018-08-23 21:13:04.135 Info App: Beginning recording. Will record for 48.9310790633333 minutes.
2018-08-23 21:13:04.135 Info App: Writing file to path: M:\Recorded Series\SOKO Stuttgart (2009)\Season 8\SOKO Stuttgart S08E09 Drei Schüsse für Friedemann - 1.ts
2018-08-23 21:13:04.135 Info App: C:\Users\admin\AppData\Roaming\Emby-Server\system\ffmpeg.exe -async 1 -vsync -1 -fflags +igndts -stream_loop -1 -reconnect_at_eof 1 -reconnect_streamed 1 -reconnect_delay_max 2 -analyzeduration 5000000 -i "http://tv.tvtech.xdns.pro:80/live/19098.ts" -codec:v:0 copy -fflags +genpts -map_metadata -1 -threads 0 -codec:a:0 copy -sn -y "M:\Recorded Series\SOKO Stuttgart (2009)\Season 8\SOKO Stuttgart S08E09 Drei Schüsse für Friedemann - 1.ts"
2018-08-23 21:13:04.551 Info App: Triggering refresh on M:\Recorded Series\SOKO Stuttgart (2009)\Season 8\SOKO Stuttgart S08E09 Drei Schüsse für Friedemann - 1.ts
2018-08-23 21:13:04.552 Info App: Refreshing recording parent M:\Recorded Series\SOKO Stuttgart (2009)\Season 8
2018-08-23 21:13:04.552 Info App: ffmpeg recording process started for M:\Recorded Series\SOKO Stuttgart (2009)\Season 8\SOKO Stuttgart S08E09 Drei Schüsse für Friedemann - 1.ts
2018-08-23 21:14:04.525 Info LibraryMonitor: Season 8 (M:\Recorded Series\SOKO Stuttgart (2009)\Season 8) will be refreshed.
2018-08-23 21:17:30.432 Info App: FFMpeg recording exited with code 0 for M:\Recorded Series\SOKO Stuttgart (2009)\Season 8\SOKO Stuttgart S08E09 Drei Schüsse für Friedemann - 1.ts
2018-08-23 21:17:30.432 Info App: Recording completed to file M:\Recorded Series\SOKO Stuttgart (2009)\Season 8\SOKO Stuttgart S08E09 Drei Schüsse für Friedemann - 1.ts
2018-08-23 21:17:30.432 Info App: Recording completed: M:\Recorded Series\SOKO Stuttgart (2009)\Season 8\SOKO Stuttgart S08E09 Drei Schüsse für Friedemann - 1.ts
2018-08-23 21:17:30.432 Info MediaSourceManager: Live stream 19ef2d61388b2b878f938717f6aa1ee2 consumer count is now 0
2018-08-23 21:17:30.432 Info MediaSourceManager: Closing live stream a17c75760a04e99b68cf766e11316e1c_09efa0d56b934a82adec00a87b837fb0_19ef2d61388b2b878f938717f6aa1ee2
2018-08-23 21:17:30.432 Info App: Closing LiveStream
2018-08-23 21:17:30.432 Info MediaSourceManager: Live stream a17c75760a04e99b68cf766e11316e1c_09efa0d56b934a82adec00a87b837fb0_19ef2d61388b2b878f938717f6aa1ee2 closed successfully
2018-08-23 21:17:30.432 Info App: Triggering refresh on M:\Recorded Series\SOKO Stuttgart (2009)\Season 8\SOKO Stuttgart S08E09 Drei Schüsse für Friedemann - 1.ts
2018-08-23 21:17:30.432 Info App: Refreshing recording parent M:\Recorded Series\SOKO Stuttgart (2009)\Season 8
2018-08-23 21:17:30.447 Info App: Running recording post processor C:\Users\admin\AppData\Roaming\Emby-Server\comskip\comskip.exe "M:\Recorded Series\SOKO Stuttgart (2009)\Season 8\SOKO Stuttgart S08E09 Drei Schüsse für Friedemann - 1.ts"
2018-08-23 21:17:52.319 Info App: Recording post-processing script completed with exit code 0

Log_1.txt

Log_2.txt

Edited August 24, 2018 by revengineer

[Luke 37116]

Thanks.

[ddurdle 75]

Chiming in on this.

 

I shared a ffmpeg wrapper script in a previous discussion many months ago.  I had a IPTV service that often would hiccup with a 404 or 403 during a stream and would cause recordings to obviously halt prematurely.  What the wrapper script did was monitor the -t parameter passed in to determine if the stream is ending prematurely, and if so, then restart the recording.  At the end I stitch together the files (if there are more than 1).  Worked well.  I've tried all the reconnect, timeout and auto loop parameters.  Nothing else worked.  

 

This was working flawlessly until emby 3.5.2.  Now there is no longer a -t parameter passed in so I'm no longer able to use the call to ffmpeg alone to determine how long the recording should last.  But I started doing some testing with 3 different IPTV providers (2 of which don't typically have the 404/403 issues like the one has) with a bunch of scheduled recordings.  This is obviously without the wrapper script.  Most are fine, but I still get recordings that prematurely end across all three providers.  Enabling auto-loop was a nightmare when I had tested it (it was causing no live tv playback to occur).

 

Without the -t parameter to monitor the expected duration,I'll have to implement a dirty solution of making API calls to emby to decipher which recording is triggering the ffmpeg call, to look up the scheduled recording duration stored by emby.