Jump to content

IPTV Provider Issue Leading to Emby Hanging

jbirmingham40

By jbirmingham40
in Linux

 Share

Recommended Posts

jbirmingham40

jbirmingham40 9

Posted
Posted

My IPTV provider occasionally has issues with certain channels and returns a 403 for multiple hours.  When this happens things get ugly with Emby.  To start with it Emby logs the following message rapidly overwhelming the disk.

2019-05-12 14:31:21.505 Info App: Opening SharedHttpStream Live stream from http://localhost:8090/M5acRagHhE/10545
2019-05-12 14:31:21.505 Error App: Error copying live stream, will keep trying.
	*** Error Report ***
	Version: 4.2.0.5
	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-rpm_{version}_x86_64.rpm
	Operating system: Unix 3.10.0.957
	64-Bit OS: True
	64-Bit Process: True
	User Interactive: True
	Runtime: file:///opt/emby-server/system/System.Private.CoreLib.dll
	Processor count: 6
	Program data path: /var/lib/emby
	Application directory: /opt/emby-server/system
	MediaBrowser.Model.Net.HttpException: MediaBrowser.Model.Net.HttpException: Cancelling connection to http://localhost:8090/M5acRagHhE/10545 due to a previous timeout.
	   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.SharedHttpStream.OpenStream(IDisposable connectionContext, MediaSourceInfo mediaSource, String url, MediaProtocol protocol, CancellationToken cancellationToken)
	   at Emby.LiveTV.TunerHosts.SharedHttpStream.<>c__DisplayClass7_0.<<StartStreaming>b__0>d.MoveNext()
	Source: Emby.Server.Implementations
	TargetSite: Void MoveNext()
	
2019-05-12 14:31:21.505 Info App: Opening SharedHttpStream Live stream from http://localhost:8090/M5acRagHhE/10545
2019-05-12 14:31:21.506 Error App: Error copying live stream, will keep trying.
	*** Error Report ***
	Version: 4.2.0.5
	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-rpm_{version}_x86_64.rpm
	Operating system: Unix 3.10.0.957
	64-Bit OS: True
	64-Bit Process: True
	User Interactive: True
	Runtime: file:///opt/emby-server/system/System.Private.CoreLib.dll
	Processor count: 6
	Program data path: /var/lib/emby
	Application directory: /opt/emby-server/system
	MediaBrowser.Model.Net.HttpException: MediaBrowser.Model.Net.HttpException: Cancelling connection to http://localhost:8090/M5acRagHhE/10545 due to a previous timeout.
	   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.SharedHttpStream.OpenStream(IDisposable connectionContext, MediaSourceInfo mediaSource, String url, MediaProtocol protocol, CancellationToken cancellationToken)
	   at Emby.LiveTV.TunerHosts.SharedHttpStream.<>c__DisplayClass7_0.<<StartStreaming>b__0>d.MoveNext()
	Source: Emby.Server.Implementations
	TargetSite: Void MoveNext()

It generated a log that is 637MB in size in only two hours and fifteen minutes.  In fact it was logging so fast that it could not actually write the logs to disk at the same rate it was generating them.  Logging was almost two hours behind when I restarted emby.  I checked and debug logging is not enabled.  

 

I am thrilled that Emby is retrying but wish it wasn't so verbose about it.  It is possible to replace the errors shown above with a less verbose summary log message every minute or so?

 

My logs indicate t was as a result of somebody trying to watch a live tv show on my Game room fire tv stick.  You can see in the dashboard they tried at 14:13, again at 14:16, and then gave up at 14:21.

Local is playing Sportsnet West CA HD on Game room fire tv stick
5/12/2019, 2:14:32 pm

Local is playing Sportsnet West CA HD on Game room fire tv stick
5/12/2019, 2:16:23 pm

Local has finished playing Sportsnet West CA HD on Game room fire tv stick
5/12/2019, 2:21:32 pm

If that is true then it isn't clear why Emby kept retrying for so long.  As you can see from the first set of logs above emby was still logging these error messages at 14:31 and I presume far later than that as the logs were two hours behind.  Seems like an issue where it gets stuck in a retry loop.

 

The logs from the beginning of the session are below.  Please let me know if you need any more.  Can't send the full log since it is more than half a GB.

2019-05-12 14:13:11.100 Info HttpServer: HTTP GET http://192.168.0.1:8096/emby/videos/32355/live.m3u8?DeviceId=733e081ee7c1db3&MediaSourceId=09a6a50a334a19d9d837f33daee8dc94&PlaySessionId=d0450a013ae44b1cbd90541ebf1a5a1b&LiveStreamId=06044cf0e6f93cdae5f285c9ecfaaeb4_01413a525b3a9622ce6fdf19f7dde354_09a6a50a334a19d9d837f33daee8dc94&VideoCodec=h264,mpeg2video,hevc,h265&AudioCodec=ac3,eac3,aac,mp3&VideoBitrate=79877375&AudioBitrate=122625&AudioStreamIndex=-1&SubtitleMethod=Encode&CopyTimestamps=true&SegmentContainer=ts&MinSegments=2&BreakOnNonKeyFrames=True&ManifestSubtitles=vtt&h264-profile=high,main,baseline,constrainedbaseline&h264-level=51&hevc-profile=Main,Main10&ac3-audiochannels=8&eac3-audiochannels=8&aac-audiochannels=8&mp3-audiochannels=8. X-Real-IP=192.168.0.249, Host=192.168.0.1, X-Forwarded-For=192.168.0.249, Connection=upgrade, User-Agent=Emby/1.6.94a (Linux;Android 7.1.2) AmznExoPlayerLib/2.9.0/Emby, Accept-Encoding=gzip
2019-05-12 14:13:11.138 Info HttpServer: HTTP Response 200 to 192.168.0.249. Time: 38ms. http://192.168.0.1:8096/emby/videos/32355/live.m3u8?DeviceId=733e081ee7c1db3&MediaSourceId=09a6a50a334a19d9d837f33daee8dc94&PlaySessionId=d0450a013ae44b1cbd90541ebf1a5a1b&LiveStreamId=06044cf0e6f93cdae5f285c9ecfaaeb4_01413a525b3a9622ce6fdf19f7dde354_09a6a50a334a19d9d837f33daee8dc94&VideoCodec=h264,mpeg2video,hevc,h265&AudioCodec=ac3,eac3,aac,mp3&VideoBitrate=79877375&AudioBitrate=122625&AudioStreamIndex=-1&SubtitleMethod=Encode&CopyTimestamps=true&SegmentContainer=ts&MinSegments=2&BreakOnNonKeyFrames=True&ManifestSubtitles=vtt&h264-profile=high,main,baseline,constrainedbaseline&h264-level=51&hevc-profile=Main,Main10&ac3-audiochannels=8&eac3-audiochannels=8&aac-audiochannels=8&mp3-audiochannels=8
2019-05-12 14:13:11.810 Info HttpServer: HTTP POST http://192.168.0.1:8096/emby/Sessions/Playing/Progress. UserAgent: Dalvik/2.1.0 (Linux; U; Android 7.1.2; AFTMM Build/NS6263)
2019-05-12 14:13:11.810 Info HttpServer: HTTP Response 204 to 192.168.0.249. Time: 1ms. http://192.168.0.1:8096/emby/Sessions/Playing/Progress
2019-05-12 14:13:13.067 Info HttpServer: HTTP POST http://192.168.0.1:8096/emby/Sessions/Playing/Progress. UserAgent: Dalvik/2.1.0 (Linux; U; Android 7.1.2; AFTMM Build/NS6263)
2019-05-12 14:13:13.068 Info HttpServer: HTTP Response 204 to 192.168.0.105. Time: 1ms. http://192.168.0.1:8096/emby/Sessions/Playing/Progress
2019-05-12 14:13:14.899 Info HttpServer: HTTP GET http://192.168.0.1:8096/emby/videos/32355/live.m3u8?DeviceId=733e081ee7c1db3&MediaSourceId=09a6a50a334a19d9d837f33daee8dc94&PlaySessionId=d0450a013ae44b1cbd90541ebf1a5a1b&LiveStreamId=06044cf0e6f93cdae5f285c9ecfaaeb4_01413a525b3a9622ce6fdf19f7dde354_09a6a50a334a19d9d837f33daee8dc94&VideoCodec=h264,mpeg2video,hevc,h265&AudioCodec=ac3,eac3,aac,mp3&VideoBitrate=79877375&AudioBitrate=122625&AudioStreamIndex=-1&SubtitleMethod=Encode&CopyTimestamps=true&SegmentContainer=ts&MinSegments=2&BreakOnNonKeyFrames=True&ManifestSubtitles=vtt&h264-profile=high,main,baseline,constrainedbaseline&h264-level=51&hevc-profile=Main,Main10&ac3-audiochannels=8&eac3-audiochannels=8&aac-audiochannels=8&mp3-audiochannels=8. X-Real-IP=192.168.0.249, Host=192.168.0.1, X-Forwarded-For=192.168.0.249, Connection=upgrade, User-Agent=Emby/1.6.94a (Linux;Android 7.1.2) AmznExoPlayerLib/2.9.0/Emby, Accept-Encoding=gzip
2019-05-12 14:13:14.938 Info HttpServer: HTTP Response 200 to 192.168.0.249. Time: 39ms. http://192.168.0.1:8096/emby/videos/32355/live.m3u8?DeviceId=733e081ee7c1db3&MediaSourceId=09a6a50a334a19d9d837f33daee8dc94&PlaySessionId=d0450a013ae44b1cbd90541ebf1a5a1b&LiveStreamId=06044cf0e6f93cdae5f285c9ecfaaeb4_01413a525b3a9622ce6fdf19f7dde354_09a6a50a334a19d9d837f33daee8dc94&VideoCodec=h264,mpeg2video,hevc,h265&AudioCodec=ac3,eac3,aac,mp3&VideoBitrate=79877375&AudioBitrate=122625&AudioStreamIndex=-1&SubtitleMethod=Encode&CopyTimestamps=true&SegmentContainer=ts&MinSegments=2&BreakOnNonKeyFrames=True&ManifestSubtitles=vtt&h264-profile=high,main,baseline,constrainedbaseline&h264-level=51&hevc-profile=Main,Main10&ac3-audiochannels=8&eac3-audiochannels=8&aac-audiochannels=8&mp3-audiochannels=8
2019-05-12 14:13:16.678 Info App: Opening SharedHttpStream Live stream from http://localhost:8090/M5acRagHhE/10545
2019-05-12 14:13:16.678 Info HttpClient: GET http://localhost:8090/M5acRagHhE/10545
2019-05-12 14:13:16.830 Info HttpServer: HTTP GET http://192.168.0.1:8096/emby/videos/32355/master.m3u8?DeviceId=733e081ee7c1db3&MediaSourceId=09a6a50a334a19d9d837f33daee8dc94&PlaySessionId=d0450a013ae44b1cbd90541ebf1a5a1b&LiveStreamId=06044cf0e6f93cdae5f285c9ecfaaeb4_01413a525b3a9622ce6fdf19f7dde354_09a6a50a334a19d9d837f33daee8dc94&VideoCodec=h264,mpeg2video,hevc,h265&AudioCodec=ac3,eac3,aac,mp3&VideoBitrate=79877375&AudioBitrate=122625&AudioStreamIndex=-1&SubtitleMethod=Encode&CopyTimestamps=true&SegmentContainer=ts&MinSegments=2&BreakOnNonKeyFrames=True&ManifestSubtitles=vtt&h264-profile=high,main,baseline,constrainedbaseline&h264-level=51&hevc-profile=Main,Main10&ac3-audiochannels=8&eac3-audiochannels=8&aac-audiochannels=8&mp3-audiochannels=8. X-Real-IP=192.168.0.249, Host=192.168.0.1, X-Forwarded-For=192.168.0.249, Connection=upgrade, User-Agent=Emby/1.6.94a (Linux;Android 7.1.2) AmznExoPlayerLib/2.9.0/Emby, Accept-Encoding=gzip
2019-05-12 14:13:16.830 Info HttpServer: HTTP Response 200 to 192.168.0.249. Time: 1ms. http://192.168.0.1:8096/emby/videos/32355/master.m3u8?DeviceId=733e081ee7c1db3&MediaSourceId=09a6a50a334a19d9d837f33daee8dc94&PlaySessionId=d0450a013ae44b1cbd90541ebf1a5a1b&LiveStreamId=06044cf0e6f93cdae5f285c9ecfaaeb4_01413a525b3a9622ce6fdf19f7dde354_09a6a50a334a19d9d837f33daee8dc94&VideoCodec=h264,mpeg2video,hevc,h265&AudioCodec=ac3,eac3,aac,mp3&VideoBitrate=79877375&AudioBitrate=122625&AudioStreamIndex=-1&SubtitleMethod=Encode&CopyTimestamps=true&SegmentContainer=ts&MinSegments=2&BreakOnNonKeyFrames=True&ManifestSubtitles=vtt&h264-profile=high,main,baseline,constrainedbaseline&h264-level=51&hevc-profile=Main,Main10&ac3-audiochannels=8&eac3-audiochannels=8&aac-audiochannels=8&mp3-audiochannels=8
2019-05-12 14:13:16.854 Info HttpServer: HTTP GET http://192.168.0.1:8096/emby/videos/32355/live.m3u8?DeviceId=733e081ee7c1db3&MediaSourceId=09a6a50a334a19d9d837f33daee8dc94&PlaySessionId=d0450a013ae44b1cbd90541ebf1a5a1b&LiveStreamId=06044cf0e6f93cdae5f285c9ecfaaeb4_01413a525b3a9622ce6fdf19f7dde354_09a6a50a334a19d9d837f33daee8dc94&VideoCodec=h264,mpeg2video,hevc,h265&AudioCodec=ac3,eac3,aac,mp3&VideoBitrate=79877375&AudioBitrate=122625&AudioStreamIndex=-1&SubtitleMethod=Encode&CopyTimestamps=true&SegmentContainer=ts&MinSegments=2&BreakOnNonKeyFrames=True&ManifestSubtitles=vtt&h264-profile=high,main,baseline,constrainedbaseline&h264-level=51&hevc-profile=Main,Main10&ac3-audiochannels=8&eac3-audiochannels=8&aac-audiochannels=8&mp3-audiochannels=8. X-Real-IP=192.168.0.249, Host=192.168.0.1, X-Forwarded-For=192.168.0.249, Connection=upgrade, User-Agent=Emby/1.6.94a (Linux;Android 7.1.2) AmznExoPlayerLib/2.9.0/Emby, Accept-Encoding=gzip
2019-05-12 14:13:16.893 Info HttpServer: HTTP Response 200 to 192.168.0.249. Time: 39ms. http://192.168.0.1:8096/emby/videos/32355/live.m3u8?DeviceId=733e081ee7c1db3&MediaSourceId=09a6a50a334a19d9d837f33daee8dc94&PlaySessionId=d0450a013ae44b1cbd90541ebf1a5a1b&LiveStreamId=06044cf0e6f93cdae5f285c9ecfaaeb4_01413a525b3a9622ce6fdf19f7dde354_09a6a50a334a19d9d837f33daee8dc94&VideoCodec=h264,mpeg2video,hevc,h265&AudioCodec=ac3,eac3,aac,mp3&VideoBitrate=79877375&AudioBitrate=122625&AudioStreamIndex=-1&SubtitleMethod=Encode&CopyTimestamps=true&SegmentContainer=ts&MinSegments=2&BreakOnNonKeyFrames=True&ManifestSubtitles=vtt&h264-profile=high,main,baseline,constrainedbaseline&h264-level=51&hevc-profile=Main,Main10&ac3-audiochannels=8&eac3-audiochannels=8&aac-audiochannels=8&mp3-audiochannels=8
2019-05-12 14:13:17.701 Error App: Error copying live stream, will keep trying.
        *** Error Report ***
        Version: 4.2.0.5
        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-rpm_{version}_x86_64.rpm
        Operating system: Unix 3.10.0.957
        64-Bit OS: True
        64-Bit Process: True
        User Interactive: True
        Runtime: file:///opt/emby-server/system/System.Private.CoreLib.dll
        Processor count: 6
        Program data path: /var/lib/emby
        Application directory: /opt/emby-server/system
        MediaBrowser.Model.Net.HttpException: MediaBrowser.Model.Net.HttpException: Forbidden
           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.SharedHttpStream.OpenStream(IDisposable connectionContext, MediaSourceInfo mediaSource, String url, MediaProtocol protocol, CancellationToken cancellationToken)
           at Emby.LiveTV.TunerHosts.SharedHttpStream.<>c__DisplayClass7_0.<<StartStreaming>b__0>d.MoveNext()
        Source: Emby.Server.Implementations
        TargetSite: Void MoveNext()

2019-05-12 14:13:17.701 Info App: Opening SharedHttpStream Live stream from http://localhost:8090/M5acRagHhE/10545
2019-05-12 14:13:17.701 Info HttpClient: GET http://localhost:8090/M5acRagHhE/10545
2019-05-12 14:13:17.999 Info HttpClient: Http response 403 from http://localhost:8090/M5acRagHhE/10545 after 298ms. HeadersServer=nginx, Date=Sun, 12 May 2019 19:12:45 GMT, Connection=close, Access-Control-Allow-Origin=*
2019-05-12 14:13:18.000 Error App: Error copying live stream, will keep trying.
        *** Error Report ***
        Version: 4.2.0.5
        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-rpm_{version}_x86_64.rpm
        Operating system: Unix 3.10.0.957
        64-Bit OS: True
        64-Bit Process: True
        User Interactive: True
        Runtime: file:///opt/emby-server/system/System.Private.CoreLib.dll
        Processor count: 6
        Program data path: /var/lib/emby
        Application directory: /opt/emby-server/system
        MediaBrowser.Model.Net.HttpException: MediaBrowser.Model.Net.HttpException: Forbidden
           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.SharedHttpStream.OpenStream(IDisposable connectionContext, MediaSourceInfo mediaSource, String url, MediaProtocol protocol, CancellationToken cancellationToken)
           at Emby.LiveTV.TunerHosts.SharedHttpStream.<>c__DisplayClass7_0.<<StartStreaming>b__0>d.MoveNext()
        Source: Emby.Server.Implementations
           at Emby.LiveTV.TunerHosts.SharedHttpStream.<>c__DisplayClass7_0.<<StartStreaming>b__0>d.MoveNext()
        Source: Emby.Server.Implementations
        TargetSite: Void MoveNext()

2019-05-12 14:13:18.000 Info App: Opening SharedHttpStream Live stream from http://localhost:8090/M5acRagHhE/10545
2019-05-12 14:13:18.000 Info HttpClient: GET http://localhost:8090/M5acRagHhE/10545
2019-05-12 14:13:18.461 Info HttpClient: Http response 403 from http://localhost:8090/M5acRagHhE/10545 after 461ms. HeadersServer=nginx, Date=Sun, 12 May 2019 19:12:46 GMT, Connection=close, Access-Control-Allow-Origin=*
2019-05-12 14:13:18.462 Error App: Error copying live stream, will keep trying.
        *** Error Report ***
        Version: 4.2.0.5
        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-rpm_{version}_x86_64.rpm
        Operating system: Unix 3.10.0.957
        64-Bit OS: True
        64-Bit Process: True
        User Interactive: True
        Runtime: file:///opt/emby-server/system/System.Private.CoreLib.dll
        Processor count: 6
        Program data path: /var/lib/emby
        Application directory: /opt/emby-server/system
        MediaBrowser.Model.Net.HttpException: MediaBrowser.Model.Net.HttpException: Forbidden
           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.SharedHttpStream.OpenStream(IDisposable connectionContext, MediaSourceInfo mediaSource, String url, MediaProtocol protocol, CancellationToken cancellationToken)
           at Emby.LiveTV.TunerHosts.SharedHttpStream.<>c__DisplayClass7_0.<<StartStreaming>b__0>d.MoveNext()
        Source: Emby.Server.Implementations
        TargetSite: Void MoveNext()
jbirmingham40

jbirmingham40 9

Posted
  • Author
Posted

FWIW, I discovered that this wasn’t caused by a user watching a new program. Rather it was caused by a runaway live tv session. We started watching this channel are 11pm last night. It Seems to have played continuously all night. Unclear why this error started at 14:13 today. I am guessing this is when the provider started having issues.

 

Based on this I suppose I can understand why Emby kept trying to play the live stream forever (i.e. it thought I was still watching it). Would be nice if it would give up after a certain amount of time. It isn’t likely that a user is going to sit there for hours waiting for the live program to resume once the provider is back up. Then again maybe there is a use case for that. Either way would be great if there was a configurable retry limit for live tv.

 

The less aggressive logging feels like a much more critical feature. I can live with run away live tv sessions as eventually I would discover them. I cannot live with the entire server becoming overwhelmed because of the aggressive logging when the provider goes down.

Luke Emby Team

Luke 42079

Posted
Posted

Hi, yes we can reduce the logging when this happens. Thanks.

Create an account or sign in to comment

You need to be a member in order to leave a comment

Create an account

Sign up for a new account in our community. It's easy!

Register a new account

Sign in

Already have an account? Sign in here.

Sign In Now
 Share
Go to topic listing
×
×
  • Create New...