Channel reliability viewing vs. recording

[vdrover 42]

I have a few channels that are perfect to watch live. But if I try to record, usually get less than a minute of recording. Looking at the logs, it is clearly an issue with the streaming server:

Quote

2021-11-30 10:00:26.184 Info SharedHttpPipelineSource: Remote server closed stream https://redacted
2021-11-30 10:00:26.185 Info SharedHttpPipelineSource: Retry opening stream https://redacted
2021-11-30 10:00:26.185 Info SharedHttpPipelineSource: Opening SharedHttpPipelineSource Live stream from https://redacted
2021-11-30 10:00:26.185 Info HttpClient: GET https://redacted
2021-11-30 10:00:26.449 Info HttpClient: Http response 404 from https://redacted after 264ms. HeadersDate=Tue, 30 Nov 2021 16:00:26 GMT, Transfer-Encoding=chunked, Connection=keep-alive, Cache-Control=no-store, must-revalidate, no-cache, Access-Control-Allow-Origin=*, CF-Cache-Status=DYNAMIC, Expect-CT=max-age=604800, report-uri="https://report-uri.cloudflare.com/cdn-cgi/beacon/expect-ct", Report-To={"endpoints":[{"url":"https:\/\/a.nel.cloudflare.com\/report\/v3?s=wsZf1CvHvf%2FTKtEby3adbV%2BgTN33cmjHCADF1uSfLEtS7PPWGqfLq36Rp%2FNz06DhxCjhWDydIBXOl%2BTF2e9FeVcBMuOCUPdPnessV6ZZzuxV9vv0AfPRL6XxD8sfbdUKqGnr"}],"group":"cf-nel","max_age":604800}, NEL={"success_fraction":0,"report_to":"cf-nel","max_age":604800}, Server=cloudflare, CF-RAY=6b6549e3b8a162bd-ORD, Alt-Svc=h3=":443"; ma=86400, h3-29=":443"; ma=86400, h3-28=":443"; ma=86400, h3-27=":443"; ma=86400
2021-11-30 10:00:26.452 Error SharedHttpPipelineSource: Give up retries copying live stream https://redacted

What I don't understand is why this happens only when recording. If I watch this channel, there may be an occasional hiccup, but the playback continues. 

I noticed the logs show `cache-Control=no-store, must-revalidate, no-cache` and wondered if caching might be part of the problem.

[Luke 37022]

Hi there, can we please look at an example? Please attach the information requested in how to report a problem. thanks !

[vdrover 42]

Do you mean to post more of the logs? Or examples of the channels?

[Luke 37022]

10 hours ago, vdrover said:

Do you mean to post more of the logs? Or examples of the channels?

Yes log files please. Thanks.

[BillOatman 496]

This used to happen for me all the time.  I so rarely record anything though it wasn't a big deal.  But recently I started developing a plugin that works on recordings, and I have recorded several 30 minute shows recently and they all worked perfectly.  What I do is watch the stream a little bit before the recording starts and make sure the stream itself is reliable. If it is buffering etc. I pull the plug on the recording.  For recording like everything else, garbage in ==> garbage out.

[vdrover 42]

Here is everything from the start of the recording to the end.

2021-11-30 10:00:00.000 Info LiveTV: Recording timer fired for Heartland.
2021-11-30 10:00:00.006 Info HttpClient: GET https://www.thetvdb.com/api/GetSeriesByRemoteID.php?zap2it=EP00959462&language=en
2021-11-30 10:00:00.166 Info HttpClient: GET https://www.thetvdb.com/api/B89CE93890E9419B/series/82701/all/en.zip
2021-11-30 10:00:00.296 Info App: MovieDbProvider: Finding id for item: Heartland
2021-11-30 10:00:00.296 Info HttpClient: GET https://api.themoviedb.org/3/search/tv?api_key=f6bd687ffa63cd282b6ff2c6877f2669&query=Heartland&language=en
2021-11-30 10:00:00.484 Info HttpClient: GET https://private.omdbapi.com?apikey=fe53f97e&plot=full&r=json&s=Heartland&type=series
2021-11-30 10:00:00.746 Info LiveTV: Getting media sources for recording from channel 47867 47867
2021-11-30 10:00:00.746 Info LiveTV: Opening live stream for recording from channel 47867 47867
2021-11-30 10:00:00.746 Info LiveTvManager: Opening channel stream from Emby, external channel Id: m3u_0d8acf21a96eaa5ea45ae08216e713c84ee12caa32d058932fc29a3e7f3dde4f
2021-11-30 10:00:00.746 Info LiveTV: Streaming Channel m3u_0d8acf21a96eaa5ea45ae08216e713c84ee12caa32d058932fc29a3e7f3dde4f
2021-11-30 10:00:00.746 Info SharedHttpPipelineSource: Opening SharedHttpPipelineSource Live stream from https://redacted.com/202redacted/redacted/redacted
2021-11-30 10:00:00.746 Info HttpClient: GET https://redacted.com/202redacted/redacted/redacted
2021-11-30 10:00:01.115 Info HttpClient: GET http://balance.redacted.com/auth/y-kKLYo9Jli31GgypLN5vW_7GyscChSJaEGU_c4buZFo19UEQjrwF0lh0YcZp0wa3nvE6m2f5xNJh0mqwSE_MpFsxm21sUYgQCc2W4FYU4ZYAFnftTd8UyRRazXJ7yzKJpiwqsAmwq9Q5Dx1_2YKP9VzI5sg0X3jYivLQaHTTuMscYKqsO2zoHjV87F3-DTjCk1cb7rFUy9MrBhM96gm3DYSATKQm8wRJbQHUSe6yR5rlSH5MI7xvHW6ARLof7krRJF6ISXoKDBezsEP-P3WbJ0K5xCDunJUQsouim9h8to5l0_hAP9Wc1bm6l24l-fxpZIwyVNUZpHAL1K_FLGgxaRQOCdXqajbslzAwGTR15ZtD-J4lKilmGgeKPXPH_bcgLoi7jL00dLUXqj5HuU_PmnuMqW5edeHLzNnPXRo1ag8-S_obXxkG1Kxxuh3QmyN56iz58SSh2MpFgpKNCFxp9DtVnwzgEtCEAC11sbcmoVpg8bMGAwPaQMiyiz7lOpbaoJjVFrqoaBF8wJ1ooyQit8CsEorZopGec8_9AwycHL_szPIIOsOEhdy2ug3uLP1A3DE79J7bSEqn2AS46I_u4_yLzdSRKBdoMRcLaL93-5lmJaaJAvmgRl79g5TUpY3IKkkZ_DVq1RJVnbAlaGpdVIbvgmlRu_pErqBbfw7g9T9ly5l-VjQejO4EscFtkMH
2021-11-30 10:00:04.233 Info HttpClient: Http response 200 from http://balance.redacted.com/auth/y-kKLYo9Jli31GgypLN5vW_7GyscChSJaEGU_c4buZFo19UEQjrwF0lh0YcZp0wa3nvE6m2f5xNJh0mqwSE_MpFsxm21sUYgQCc2W4FYU4ZYAFnftTd8UyRRazXJ7yzKJpiwqsAmwq9Q5Dx1_2YKP9VzI5sg0X3jYivLQaHTTuMscYKqsO2zoHjV87F3-DTjCk1cb7rFUy9MrBhM96gm3DYSATKQm8wRJbQHUSe6yR5rlSH5MI7xvHW6ARLof7krRJF6ISXoKDBezsEP-P3WbJ0K5xCDunJUQsouim9h8to5l0_hAP9Wc1bm6l24l-fxpZIwyVNUZpHAL1K_FLGgxaRQOCdXqajbslzAwGTR15ZtD-J4lKilmGgeKPXPH_bcgLoi7jL00dLUXqj5HuU_PmnuMqW5edeHLzNnPXRo1ag8-S_obXxkG1Kxxuh3QmyN56iz58SSh2MpFgpKNCFxp9DtVnwzgEtCEAC11sbcmoVpg8bMGAwPaQMiyiz7lOpbaoJjVFrqoaBF8wJ1ooyQit8CsEorZopGec8_9AwycHL_szPIIOsOEhdy2ug3uLP1A3DE79J7bSEqn2AS46I_u4_yLzdSRKBdoMRcLaL93-5lmJaaJAvmgRl79g5TUpY3IKkkZ_DVq1RJVnbAlaGpdVIbvgmlRu_pErqBbfw7g9T9ly5l-VjQejO4EscFtkMH after 3118ms. HeadersServer=nginx, Date=Tue, 30 Nov 2021 16:00:04 GMT, Connection=close, Access-Control-Allow-Origin=*
2021-11-30 10:00:04.233 Info SharedHttpPipelineSource: Beginning SharedHttpPipelineSource stream to /var/lib/emby/transcoding-temp/db9ba82a1095419fb6a570247360a390.ts
2021-11-30 10:00:04.233 Info M3UTunerHost: Live stream opened after 3486.8765ms
2021-11-30 10:00:04.233 Info LiveTV: Returning mediasource streamId c290404b450d950b9de34e7b84a2368a, mediaSource.Id c290404b450d950b9de34e7b84a2368a, mediaSource.LiveStreamId null
2021-11-30 10:00:04.237 Info MediaSourceManager: Live stream opened: {"Protocol":"Http","Id":"c290404b450d950b9de34e7b84a2368a","Path":"http://127.0.0.1:8096/LiveTv/LiveStreamFiles/db9ba82a1095419fb6a570247360a390/stream.ts","Type":"Default","Container":"mpegts","IsRemote":false,"ContainerStartTimeTicks":53330,"SupportsTranscoding":true,"SupportsDirectStream":true,"SupportsDirectPlay":false,"IsInfiniteStream":true,"RequiresOpening":true,"RequiresClosing":true,"LiveStreamId":"06044cf0e6f93cdae5f285c9ecfaaeb4_01413a525b3a9622ce6fdf19f7dde354_c290404b450d950b9de34e7b84a2368a","RequiresLooping":false,"SupportsProbing":false,"MediaStreams":[{"Codec":"h264","StreamStartTimeTicks":333330,"TimeBase":"1/90000","CodecTimeBase":"1/60","VideoRange":"SDR","DisplayTitle":"720p H264","NalLengthSize":"0","IsInterlaced":false,"BitRate":6000000,"BitDepth":8,"RefFrames":1,"IsDefault":false,"IsForced":false,"Height":720,"Width":1280,"AverageFrameRate":30,"RealFrameRate":30,"Profile":"High","Type":"Video","AspectRatio":"16:9","Index":-1,"IsExternal":false,"IsTextSubtitleStream":false,"SupportsExternalStream":false,"Protocol":"File","PixelFormat":"yuv420p","Level":41,"IsAnamorphic":false},{"Codec":"aac","StreamStartTimeTicks":53330,"TimeBase":"1/90000","CodecTimeBase":"1/48000","DisplayTitle":"Und AAC stereo","IsInterlaced":false,"ChannelLayout":"stereo","BitRate":95933,"Channels":2,"SampleRate":48000,"IsDefault":false,"IsForced":false,"Profile":"LC","Type":"Audio","Index":-1,"IsExternal":false,"IsTextSubtitleStream":false,"SupportsExternalStream":false,"Protocol":"File"}],"Formats":[],"Bitrate":6095933,"RequiredHttpHeaders":{"User-Agent":"VLC/3.0.11"},"ReadAtNativeFramerate":false}
2021-11-30 10:00:04.237 Info LiveTV: Recording ensure file unique input: /mnt/Plex/Emby/TV Shows/Heartland (2007)/Season 12/Heartland S12E03 Just Breathe.ts
2021-11-30 10:00:04.237 Info LiveTV: Recording ensure file unique result: /mnt/Plex/Emby/TV Shows/Heartland (2007)/Season 12/Heartland S12E03 Just Breathe.ts
2021-11-30 10:00:04.237 Info LiveTV: Will record to /mnt/Plex/Emby/TV Shows/Heartland (2007)/Season 12/Heartland S12E03 Just Breathe.ts for 64.92937011833334 minutes.
2021-11-30 10:00:04.251 Info LiveTV: Triggering refresh on /mnt/Plex/Emby/TV Shows/Heartland (2007)/Season 12/Heartland S12E03 Just Breathe.ts
2021-11-30 10:00:04.253 Info LiveTV: Refreshing recording parent /mnt/Plex/Emby/TV Shows
2021-11-30 10:00:04.253 Info LiveTV: Copying recording stream to file /mnt/Plex/Emby/TV Shows/Heartland (2007)/Season 12/Heartland S12E03 Just Breathe.ts
2021-11-30 10:00:04.473 Info HttpClient: GET https://api.themoviedb.org/3/find/tt1094229?api_key=f6bd687ffa63cd282b6ff2c6877f2669&external_source=imdb_id
2021-11-30 10:00:04.776 Info HttpClient: GET https://api.themoviedb.org/3/tv/14929?api_key=f6bd687ffa63cd282b6ff2c6877f2669&append_to_response=credits,images,keywords,external_ids,videos,content_ratings&language=en&include_image_language=en,null
2021-11-30 10:00:04.813 Info HttpClient: GET https://private.omdbapi.com?apikey=fe53f97e&i=tt1094229&plot=short&tomatoes=true&r=json
2021-11-30 10:00:04.939 Info HttpClient: GET https://www.thetvdb.com/api/B89CE93890E9419B/series/82701/all/en.zip
2021-11-30 10:00:05.033 Info HttpClient: GET https://webservice.fanart.tv/v3/tv/82701?api_key=5c6b04c68e904cfed1e6cbc9a9e683d4
2021-11-30 10:00:05.686 Info App: Creating virtual unaired episode Heartland 15x8
2021-11-30 10:00:05.686 Info App: Creating Season Season 15 entry for Heartland
2021-11-30 10:00:05.701 Info App: Creating virtual unaired episode Heartland 15x9
2021-11-30 10:00:26.184 Info SharedHttpPipelineSource: Remote server closed stream https://redacted.com/202redacted/redacted/redacted
2021-11-30 10:00:26.185 Info SharedHttpPipelineSource: Retry opening stream https://redacted.com/202redacted/redacted/redacted
2021-11-30 10:00:26.185 Info SharedHttpPipelineSource: Opening SharedHttpPipelineSource Live stream from https://redacted.com/202redacted/redacted/redacted
2021-11-30 10:00:26.185 Info HttpClient: GET https://redacted.com/202redacted/redacted/redacted
2021-11-30 10:00:26.449 Info HttpClient: Http response 404 from https://redacted.com/202redacted/redacted/redacted after 264ms. HeadersDate=Tue, 30 Nov 2021 16:00:26 GMT, Transfer-Encoding=chunked, Connection=keep-alive, Cache-Control=no-store, must-revalidate, no-cache, Access-Control-Allow-Origin=*, CF-Cache-Status=DYNAMIC, Expect-CT=max-age=604800, report-uri="https://report-uri.cloudflare.com/cdn-cgi/beacon/expect-ct", Report-To={"endpoints":[{"url":"https:\/\/a.nel.cloudflare.com\/report\/v3?s=wsZf1CvHvf%2FTKtEby3adbV%2BgTN33cmjHCADF1uSfLEtS7PPWGqfLq36Rp%2FNz06DhxCjhWDydIBXOl%2BTF2e9FeVcBMuOCUPdPnessV6ZZzuxV9vv0AfPRL6XxD8sfbdUKqGnr"}],"group":"cf-nel","max_age":604800}, NEL={"success_fraction":0,"report_to":"cf-nel","max_age":604800}, Server=cloudflare, CF-RAY=6b6549e3b8a162bd-ORD, Alt-Svc=h3=":443"; ma=86400, h3-29=":443"; ma=86400, h3-28=":443"; ma=86400, h3-27=":443"; ma=86400
2021-11-30 10:00:26.452 Error SharedHttpPipelineSource: Give up retries copying live stream https://redacted.com/202redacted/redacted/redacted
	*** Error Report ***
	Version: 4.6.4.0
	Command line: /opt/emby-server/system/EmbyServer.dll -programdata /var/lib/emby -ffdetect /opt/emby-server/bin/ffdetect -ffmpeg /opt/emby-server/bin/ffmpeg -ffprobe /opt/emby-server/bin/ffprobe -restartexitcode 3 -updatepackage emby-server-deb_{version}_amd64.deb
	Operating system: Linux version 5.4.0-90-generic (buildd@lgw01-amd64-054) (gcc version 9.3.0 (Ubuntu 9.3.0-17ubuntu1~20.04)) #101-Ubuntu SMP Fri Oct 15 20:00:55 UTC 202
	Framework: .NET Core 3.1.13
	OS/Process: x64/x64
	Runtime: opt/emby-server/system/System.Private.CoreLib.dll
	Processor count: 12
	Data path: /var/lib/emby
	Application path: /opt/emby-server/system
	MediaBrowser.Model.Net.HttpException: MediaBrowser.Model.Net.HttpException: NotFound
	   at Emby.Server.Implementations.HttpClientManager.CoreHttpClientManager.SendAsyncInternal(HttpRequestOptions options, String httpMethod)
	   at Emby.Server.Implementations.HttpClientManager.CoreHttpClientManager.SendAsync(HttpRequestOptions options, String httpMethod)
	   at Emby.LiveTV.TunerHosts.SharedHttpPipelineSource.OpenStream(IDisposable connectionContext, MediaSourceInfo mediaSource, String url, MediaProtocol protocol, CancellationToken cancellationToken, Int32 recursion)
	   at Emby.LiveTV.TunerHosts.SharedHttpPipelineSource.<>c__DisplayClass8_0.<<StartStreaming>b__0>d.MoveNext()
	Source: Emby.Server.Implementations
	TargetSite: Void MoveNext()
	
2021-11-30 10:00:26.461 Error SharedHttpPipelineSource: Error copying live stream.
	*** Error Report ***
	Version: 4.6.4.0
	Command line: /opt/emby-server/system/EmbyServer.dll -programdata /var/lib/emby -ffdetect /opt/emby-server/bin/ffdetect -ffmpeg /opt/emby-server/bin/ffmpeg -ffprobe /opt/emby-server/bin/ffprobe -restartexitcode 3 -updatepackage emby-server-deb_{version}_amd64.deb
	Operating system: Linux version 5.4.0-90-generic (buildd@lgw01-amd64-054) (gcc version 9.3.0 (Ubuntu 9.3.0-17ubuntu1~20.04)) #101-Ubuntu SMP Fri Oct 15 20:00:55 UTC 202
	Framework: .NET Core 3.1.13
	OS/Process: x64/x64
	Runtime: opt/emby-server/system/System.Private.CoreLib.dll
	Processor count: 12
	Data path: /var/lib/emby
	Application path: /opt/emby-server/system
	MediaBrowser.Model.Net.HttpException: MediaBrowser.Model.Net.HttpException: NotFound
	   at Emby.Server.Implementations.HttpClientManager.CoreHttpClientManager.SendAsyncInternal(HttpRequestOptions options, String httpMethod)
	   at Emby.Server.Implementations.HttpClientManager.CoreHttpClientManager.SendAsync(HttpRequestOptions options, String httpMethod)
	   at Emby.LiveTV.TunerHosts.SharedHttpPipelineSource.OpenStream(IDisposable connectionContext, MediaSourceInfo mediaSource, String url, MediaProtocol protocol, CancellationToken cancellationToken, Int32 recursion)
	   at Emby.LiveTV.TunerHosts.SharedHttpPipelineSource.<>c__DisplayClass8_0.<<StartStreaming>b__0>d.MoveNext()
	--- End of stack trace from previous location where exception was thrown ---
	   at Emby.LiveTV.TunerHosts.SharedHttpPipelineSource.<>c__DisplayClass8_0.<<StartStreaming>b__0>d.MoveNext()
	Source: Emby.Server.Implementations
	TargetSite: Void MoveNext()
	
2021-11-30 10:00:26.461 Info SharedHttpPipelineSource: SharedHttpPipelineSource is done streaming.
2021-11-30 10:00:26.461 Info SharedHttpPipelineSource: Deleting temp files /var/lib/emby/transcoding-temp/db9ba82a1095419fb6a570247360a390.ts

 

Edited December 1, 2021 by vdrover

[Carlo 4330]

Emby is reporting a 404 error trying to get this stream from Cloudflare which is being used to carry the stream which is pretty odd.  It appears to me to be a problem with the stream to get a 404 response.  Those headers do not look correct for streaming Live TV through a content distribution network.

Do you have issues on multiple channels but not all channels?

Http response 404 from https://redacted.com/202redacted/redacted/redacted after 264ms. HeadersDate=Tue, 30 Nov 2021 16:00:26 GMT, Transfer-Encoding=chunked, Connection=keep-alive, Cache-Control=no-store, must-revalidate, no-cache, Access-Control-Allow-Origin=*, CF-Cache-Status=DYNAMIC, Expect-CT=max-age=604800, report-uri="https://report-uri.cloudflare.com/cdn-cgi/beacon/expect-ct", Report-To={"endpoints":[{"url":"https:\/\/a.nel.cloudflare.com\/report\/v3?s=wsZf1CvHvf%2FTKtEby3adbV%2BgTN33cmjHCADF1uSfLEtS7PPWGqfLq36Rp%2FNz06DhxCjhWDydIBXOl%2BTF2e9FeVcBMuOCUPdPnessV6ZZzuxV9vv0AfPRL6XxD8sfbdUKqGnr"}],"group":"cf-nel","max_age":604800}, NEL={"success_fraction":0,"report_to":"cf-nel","max_age":604800}, Server=cloudflare, CF-RAY=6b6549e3b8a162bd-ORD, Alt-Svc=h3=":443"; ma=86400, h3-29=":443"; ma=86400, h3-28=":443"; ma=86400, h3-27=":443"; ma=86400