FFmpeg constantly closing and reopening for transcoding

[Smok@zz 4]

Emby Team,

 

I noticed this issue a few revisions back and essentially, things would play out like this.  I would be watching live TV and all of a sudden the picture and sound would freeze for about 4-5 seconds then continue playing as if nothing happened.  More recently, it started happening more and more frequently.  Last night, it would play for about 1 second, freeze for 5, then start again for 1 second, etc.  Sometimes it would continue for longer but i think you get the idea that it was not smooth, consistent playback.  So, at first, i thought maybe my hard drive was having issues since after all it was transcoding and needs to store that somewhere.  This apparently isn't the case because i literally watched the FFmpeg service terminate and spawn a new session every time it was freeze.  It makes sense that it is ffmpeg because it needs to cache some data and trascode before we can watch it.  So, i took a look at my log files from yesterday and found this:

 

2016-05-01 20:52:55.2920 Info HttpServer: HTTP Response 500 to 192.168.1.12. Time: 5391ms (slow). http://192.168.1.20:8096/emby/videos/33f82ddd01fdab000978367367007251/stream.mkv?DeviceId=e6b77d1dca36fc1d&MediaSourceId=10e3a3180e6747fb8972217460d4ca5bnative&VideoCodec=h264&AudioCodec=aac&AudioStreamIndex=-1&VideoBitrate=1563332&AudioBitrate=128000&MaxAudioChannels=6&Level=41&Profile=high&PlaySessionId=20db76db1f35494ea71f080232a8f9c4&CopyTimestamps=true
2016-05-01 20:52:55.2920 Info App: C:\Users\HTPC\AppData\Roaming\MediaBrowser-Server\ffmpeg\20160401\ffmpeg.exe -fflags +genpts -noaccurate_seek -i "http://192.168.1.7:5004/auto/v554"-sn -codec:v:0 libx264 -force_key_frames expr:gte(t,n_forced*5) -vf "yadif=0:-1:0,scale=trunc(min(max(iw\,ih*dar)\,1280)/2)*2:trunc(ow/dar/2)*2" -pix_fmt yuv420p -preset superfast -crf 23 -b:v 1563332 -maxrate 1563332 -bufsize 3126664 -vsync vfr -profile:v high -level 41 -map_metadata -1 -threads 2 -codec:a:0 aac -strict experimental -ac 6 -ab 128000 -af "aresample=async=1" -y "C:\TV Cache\transcoding-temp\549c3a0ca799fc8e099558487a15a2c9.mkv"
2016-05-01 20:52:56.0380 Info HttpServer: HTTP GET http://192.168.1.20:8096/emby/System/Logs/Log?name=transcode-4912ce78-4e72-4b11-8de6-4aa01fb4f648.txt. UserAgent: Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/49.0.2623.112 Safari/537.36
2016-05-01 20:52:56.0410 Info HttpServer: HTTP Response 200 to 192.168.1.8. Time: 3ms. http://192.168.1.20:8096/emby/System/Logs/Log?name=transcode-4912ce78-4e72-4b11-8de6-4aa01fb4f648.txt
2016-05-01 20:52:56.2921 Info App: Killing ffmpeg process for C:\TV Cache\transcoding-temp\6394acf91cbfd1f1d6487f44a15e0568.mkv
2016-05-01 20:52:56.4205 Info App: FFMpeg exited with code 0
2016-05-01 20:52:56.4205 Info App: Deleting partial stream file(s) C:\TV Cache\transcoding-temp\6394acf91cbfd1f1d6487f44a15e0568.mkv
2016-05-01 20:52:56.8438 Info HttpServer: HTTP POST http://192.168.1.20:8096/emby/Sessions/Playing/Progress. UserAgent: Dalvik/2.1.0 (Linux; U; Android 5.1.1; BRAVIA 4K 2015 Build/LMY48E.S223)
2016-05-01 20:52:56.8813 Info HttpServer: HTTP Response 204 to 192.168.1.12. Time: 38ms. http://192.168.1.20:8096/emby/Sessions/Playing/Progress
2016-05-01 20:53:00.1917 Error App: Error streaming media. The client has most likely disconnected or transcoding has failed.
    *** Error Report ***
    Version: 3.0.5931.0
    Command line: C:\Users\HTPC\AppData\Roaming\MediaBrowser-Server\System\MediaBrowser.ServerApplication.exe -service
    Operating system: Microsoft Windows NT 6.2.9200.0
    Processor count: 8
    64-Bit OS: True
    64-Bit Process: True
    Program data path: C:\Users\HTPC\AppData\Roaming\MediaBrowser-Server
    Application Path: C:\Users\HTPC\AppData\Roaming\MediaBrowser-Server\System\MediaBrowser.ServerApplication.exe
    One or more errors occurred.
    System.AggregateException
     at System.Threading.Tasks.Task.WaitAll(Task[] tasks, Int32 millisecondsTimeout, CancellationToken cancellationToken)
     at MediaBrowser.Api.Playback.Progressive.ProgressiveStreamWriter.WriteToInternal(Stream responseStream)
    InnerException: System.IO.IOException
    Unable to write data to the transport connection: An existing connection was forcibly closed by the remote host.
     at System.Net.Sockets.NetworkStream.Write(Byte[] buffer, Int32 offset, Int32 size)
     at SocketHttpListener.Net.ResponseStream.InternalWrite(Byte[] buffer, Int32 offset, Int32 count)
     at SocketHttpListener.Net.ResponseStream.Write(Byte[] buffer, Int32 offset, Int32 count)
     at MediaBrowser.Api.Playback.Progressive.ProgressiveFileCopier.CopyToInternal(Stream source, Stream destination, Int32 bufferSize)
     at MediaBrowser.Api.Playback.Progressive.ProgressiveFileCopier.<StreamFile>d__0.MoveNext()
    InnerException: System.Net.Sockets.SocketException
    An existing connection was forcibly closed by the remote host
     at System.Net.Sockets.Socket.Send(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags)
     at System.Net.Sockets.NetworkStream.Write(Byte[] buffer, Int32 offset, Int32 size)
    
2016-05-01 20:53:00.1917 Error HttpServer: Error in HttpListenerResponseWrapper: Unable to write data to the transport connection: An existing connection was forcibly closed by the remote host.
    *** Error Report ***
    Version: 3.0.5931.0
    Command line: C:\Users\HTPC\AppData\Roaming\MediaBrowser-Server\System\MediaBrowser.ServerApplication.exe -service
    Operating system: Microsoft Windows NT 6.2.9200.0
    Processor count: 8
    64-Bit OS: True
    64-Bit Process: True
    Program data path: C:\Users\HTPC\AppData\Roaming\MediaBrowser-Server
    Application Path: C:\Users\HTPC\AppData\Roaming\MediaBrowser-Server\System\MediaBrowser.ServerApplication.exe
    Unable to write data to the transport connection: An existing connection was forcibly closed by the remote host.
    System.IO.IOException
     at System.Net.Sockets.NetworkStream.Write(Byte[] buffer, Int32 offset, Int32 size)
     at SocketHttpListener.Net.ResponseStream.InternalWrite(Byte[] buffer, Int32 offset, Int32 count)
     at SocketHttpListener.Net.ResponseStream.Close()
     at MediaBrowser.Server.Implementations.HttpServer.SocketSharp.Extensions.CloseOutputStream(HttpListenerResponse response, ILogger logger)
    InnerException: System.Net.Sockets.SocketException
    An existing connection was forcibly closed by the remote host
     at System.Net.Sockets.Socket.Send(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags)
     at System.Net.Sockets.NetworkStream.Write(Byte[] buffer, Int32 offset, Int32 size)
    
2016-05-01 20:53:00.1917 Error HttpAsyncTaskHandler: Error occured while Processing Request: Unable to write data to the transport connection: An existing connection was forcibly closed by the remote host.
    *** Error Report ***
    Version: 3.0.5931.0
    Command line: C:\Users\HTPC\AppData\Roaming\MediaBrowser-Server\System\MediaBrowser.ServerApplication.exe -service
    Operating system: Microsoft Windows NT 6.2.9200.0
    Processor count: 8
    64-Bit OS: True
    64-Bit Process: True
    Program data path: C:\Users\HTPC\AppData\Roaming\MediaBrowser-Server
    Application Path: C:\Users\HTPC\AppData\Roaming\MediaBrowser-Server\System\MediaBrowser.ServerApplication.exe
    Unable to write data to the transport connection: An existing connection was forcibly closed by the remote host.
    System.IO.IOException
     at System.Net.Sockets.NetworkStream.Write(Byte[] buffer, Int32 offset, Int32 size)
     at SocketHttpListener.Net.ResponseStream.InternalWrite(Byte[] buffer, Int32 offset, Int32 count)
     at SocketHttpListener.Net.ResponseStream.Write(Byte[] buffer, Int32 offset, Int32 count)
     at ServiceStack.Formats.HtmlFormat.SerializeToStream(IRequest request, Object response, IResponse httpRes)
     at ServiceStack.HttpResponseExtensionsInternal.WriteErrorToResponse(IResponse httpRes, IRequest httpReq, String contentType, String operationName, String errorMessage, Exception ex, Int32 statusCode)
     at ServiceStack.ServiceStackHost.OnUncaughtException(IRequest httpReq, IResponse httpRes, String operationName, Exception ex)
     at ServiceStack.HostContext.RaiseUncaughtException(IRequest httpReq, IResponse httpRes, String operationName, Exception ex)
     at ServiceStack.HttpResponseExtensionsInternal.WriteToResponse(IResponse response, Object result, ResponseSerializerDelegate defaultAction, IRequest request, Byte[] bodyPrefix, Byte[] bodySuffix)
     at ServiceStack.HttpResponseExtensionsInternal.WriteToResponse(IResponse httpRes, IRequest httpReq, Object result, Byte[] bodyPrefix, Byte[] bodySuffix)
     at ServiceStack.HttpResponseExtensionsInternal.WriteToResponse(IResponse httpRes, IRequest httpReq, Object result)
     at ServiceStack.Host.Handlers.ServiceStackHandlerBase.HandleResponse(Object response, Func`2 callback, Func`2 errorCallback)
    InnerException: System.Net.Sockets.SocketException
    An existing connection was forcibly closed by the remote host
     at System.Net.Sockets.Socket.Send(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags)
     at System.Net.Sockets.NetworkStream.Write(Byte[] buffer, Int32 offset, Int32 size)
    
2016-05-01 20:53:00.1917 Info HttpServer: HTTP Response 500 to 192.168.1.12. Time: 4901ms (slow). http://192.168.1.20:8096/emby/videos/33f82ddd01fdab000978367367007251/stream.mkv?DeviceId=e6b77d1dca36fc1d&MediaSourceId=10e3a3180e6747fb8972217460d4ca5bnative&VideoCodec=h264&AudioCodec=aac&AudioStreamIndex=-1&VideoBitrate=1563332&AudioBitrate=128000&MaxAudioChannels=6&Level=41&Profile=high&PlaySessionId=3a14d76a503c4d1280b6f73aeeab7d68&CopyTimestamps=true
2016-05-01 20:53:01.1990 Info App: Killing ffmpeg process for C:\TV Cache\transcoding-temp\549c3a0ca799fc8e099558487a15a2c9.mkv
2016-05-01 20:53:01.3615 Info App: FFMpeg exited with code 0
2016-05-01 20:53:01.3615 Info App: Deleting partial stream file(s) C:\TV Cache\transcoding-temp\549c3a0ca799fc8e099558487a15a2c9.mkv

 

I have attached the server and a few transcoding logs for your review. 

 

Other details you might need is Emby is streaming live tv to android TV on either Nexus Player or Bravia set.  Server build is 3.0.5931.0 and Android TV version is 1.1.76g.  Thanks for taking a look at this. 

server-63597732510.txt

transcode-2d8a9927-46a7-4def-ae6a-c7ea2a2c05f0.txt

transcode-55478124-c9fd-451d-be75-61d1148280e4.txt

transcode-d656fd84-39a1-45ca-8157-40b8243eaa1c.txt

[Smok@zz 4]

bump.  Just wanted to know if anyone could have a chance to take a look at this for me?  Thanks.

[Luke 37064]

First I would try updating to the latest release of Emby Server, then report back with results.

[Smok@zz 4]

Thanks for the suggestion Luke.  I did upgrade last night and while the issue wasn't as noticeable as before - it still happened twice last night both times within a couple minutes of each other.  To assist you in your efforts, the time stamps are 2016-05-04 21:50:01.4953 and 2016-05-04 21:56:30.0903.

 

I have attached the server log as that appears to be all that was viewed previously.  If you need more, let me know.  Thanks for everything your doing to help me with this.

server-63597978007.txt

[Smok@zz 4]

Just wanted to update you all that this is still happening and last night was a nightmare.  I attached a screenshot of all the times that ffmpeg crashed and restarted in the course of 10 minutes. I also uploaded the server log and some of the transcoding logs.  I did enable the debug logging so hopefully there is more for you to look at.  If you cannot find what you need in those logs, i'll provide more at your request.

 

Im just curious to know if i am the only person experiencing this issue?  If i am, then i'll just assume there is something wrong with my config but if not, there is a major pain and i dont understand why it is happening since it used to never happen at all.  I am really hoping that you all can find something that can be fixed for this.  I really appreciate it.

server-63598571294.txt

transcode-21100e3d-a767-452e-bb3a-93168ebfb54b.txt

transcode-49806fb7-c648-4912-be7f-5d603c50f5ea.txt

transcode-ccfc0456-af9f-4a68-aad9-a5e1b696c4e0.txt

unhandled_d968d8f6-26a4-4764-bd42-73be1280778b.txt

[Luke 37064]

you could always try the beta server to see if it performs any differently.

[Smok@zz 4]

Ok, i just installed the beta so i'll see how that goes tonight and i'll report back tomorrow.  Are there any changes in the beta that would lead you to believe it would help?  Are you seeing anything in the logs that point to you the issue or what the issue could be?  Thanks.

[Smok@zz 4]

Luke - Still no go this is what happened after the upgrade to beta:

 Also, i am running 1.1.90g on both Nexus Player and Bravia TV - if that helps at all.  Thanks

[Luke 37064]

That's only a screenshot. Try changing streaming settings in the app. Maybe the bitrate is too high

[Smok@zz 4]

Thanks for the suggestion Luke and I apologize for not including my server log - i attached that for you.

 

I will try to reduce the streaming rate and see if that fix it and report back.

 

One other thing i noticed with the beta - it installed a newer ffmpeg but it isn't using it.  The screenshot is from procxp showing that its using 20160401 instead of 20160410.  not sure if it makes a difference but i would assume that if you included a new ffmpeg, you intended for us to use it 

 

Thanks again for your assistance.

server-63598659525.txt

[Smok@zz 4]

Luke,

Still having this issue.  I am running the latest beta 3.0.5968.0.  Logs attached for you.  

 

BTW - have you been able to think of any reason for this behavior?  It also seems strange that it is transcoding in the first place.  I am running from an HDHR Prime and i have been able to use Direct/V in the past.  Do you see anything in the logs that would lead to me having to transcode instead of running directly?  Maybe until we get this ffmpeg crashing issue sorted out, you can see why its not direct/v?  Thanks for all your do man, i really appreciate you taking a look for me.

 

Edit - i wanted to upload one more for you - this new one ends in 5ffd.  reason being is that there is a bunch of mpeg2video errors in the beginning but it continues to stream afterwards.  Also, the FPS is crazy high in the first few frames.  it starts at 181 FPS then slowly descends to 60 fps - could this be why is failing?  the FPS is just too high for ffmpeg to keep up?

server-63598983513.txt

transcode-1a569dcb-e0b2-43cf-9797-530f2eae730a.txt

transcode-3b770da4-1ac1-4b92-91fe-580676300c6c.txt

transcode-4c70c49d-831b-41bc-932b-5ba9dc8934c2.txt

transcode-7e9391f4-1c3f-472e-8397-f16f5f241b57.txt

transcode-51fc0180-46a6-4564-bcda-0988f0138d62.txt

transcode-5369a418-c9a9-47c4-9d17-abc9ac841153.txt

transcode-9000c284-83d2-4c00-bfe6-3e7cbc5582dc.txt

transcode-a80b9689-616d-4a22-884c-467d20cc15d8.txt

transcode-28dcb6fa-1e00-4645-8d27-21656e7a5ffd.txt

Edited May 16, 2016 by Smok@zz

[Luke 37064]

before we continue, update your HDHR firmware. Also is this server wmc or the built-in live tv? if it's not the built-in support then let's switch to that temporarily because that has the most up to date hdhr support.

 

the fps is the speed of the transcoding, so you generally want it to be as fast as possible. i think whatever error is occurring, the reason for the numerous ffmpeg instances is that the client video player must be automatically attempting to reconnect after the disconnect. i think the error is probably one of two things - it's possible the client doesn't like the format of the video that it's getting back, so it disconnects, then gets stuck in an endless loop of retry, disconnect, repeat. As for what it could be, the only thing in the output format that jumps out is the 60fps, maybe that's too much for the device. Or, perhaps you're getting random signal drops that are enough to cause some disruption.

[Smok@zz 4]

Luke,

Thanks for the response.  I currently have HDHR 20150826 which is the latest available on silicone dusts website.  Are you referring to a beta firmware?  If so, i would prefer not to use those unless you believe it will correct the issues.  Also, which firmware do you have in mind?

 

I am using the builtin Live TV, i tried serverWMC a while back but i didn't much care for it.

 

Thanks for the info on the FPS and disconnects.  What is strange is that playback of recordings are fine - rarely are there issues regarding that.  But since they are in .mp4 format, they don't transcode in the first place.  I also understand that .TS is native to android or at least emby so that it "shouldn't" transcode either.  Perhaps, you can clarify that for me.  Lastly, i would agree with you that the higher the FPS, the better, but in the past it has always hovered around 30FPS - whether or not that makes a difference, i dont know.  But is there a way to limit that?  Just as a test?  Thanks!

[Luke 37064]

the hdhr media info in the transcoding logs shows no video or audio codec. their newest firmware from about a month ago added a new api that we can use to find out the audio and video codecs of the live stream before we start playing. that in turn creates some transcoding improvements.

[Smok@zz 4]

that does sound promising so i would be willing to give it a shot but i cant seem to find where to download the beta drivers.  clicking the link under downloads for beta drivers just re-directs me to the stable release.  If you could point me in the right direction, that would be great and i'll be sure to give it a try for you.  Thanks.

[Luke 37064]

vicpa knows better

http://emby.media/community/index.php?/topic/33447-305937-new-hdhomerun-data/

[Smok@zz 4]

thanks luke, just grabbed it and i'll report back later for you.  

[Smok@zz 4]

Luke,

While it was a great effort, it is still happening.  Hopefully with the updated firmware you will be able to get some new info.  Thanks again for taking a look for me.

server-63598984764.7z

transcode-7a739f0f-a5c2-41a9-8327-dd6ea1c7682d.txt

transcode-29e0b49c-60a1-4478-9d25-6db5c798525f.txt

transcode-38b31259-6b4c-4187-8487-1e78120112ce.txt

transcode-61f06f8e-cd34-45b8-9722-50a169e7605e.txt

[Luke 37064]

Right now I don't know. I think it's either signal drops or the tv doesn't like the video format. i would take a look at the output characteristics in the transcoding log and make sure it's something the tv can handle, then we'll go from there.

[Smok@zz 4]

Luke,

Just wanted to let you know that this is still happening.  I know that you aren't sure what the problem is but i even went so far as to rebuild my server thinking that my windows 7 to 10 upgrade is what caused the issue.  That apparently isn't the issue.  Could the issue be around the client and maybe not the server?  I am using Android TV on my Bravia and my Nexus Player.  Perhaps ebr might be able to take a look at the logs that were previously provided and see something that could lead to this behavior?  Thanks!

[Luke 37064]

try to play from another app for comparison.

[ownerer 0]

Sorry to dig up an old thread, but was this issue ever resolved or reported somewhere else?

I'm seeing the same symptoms here, but I'm having trouble reproducing the issue.

When it happens though:

- changing bitrate doesn't matter

- it's always when streaming, direct playing has no issues

- the logs show the same exception: "System.Net.Sockets.SocketException (0x80004005): An existing connection was forcibly closed by the remote host"
- it seems the client gets stuck in an endless loop then, and I've actually seen it skip all episodes in a season, even if unwatched trying to find one that plays :/

- I've seen this happen on both internet access AND local 1Gbps network

Edited June 8, 2017 by ownerer

[Luke 37064]

Hi there @@ownerer, we're very sorry to hear about your issue. Please discuss a specific example and attach the information requested in how to report a problem. thanks !

[Smok@zz 4]

Sorry to dig up an old thread, but was this issue ever resolved or reported somewhere else?

@@ownerer

Sadly, a solution was never found.  I did find it odd that I was the only one with this issue so it midly comforting that some else has the same problem.  So my solution (more of a bandaid) was to stop using Emby to control live TV and i reverted back to NextPVR.  The second change i made was to stop using the Emby app and i used Kodi instead.  Kodi (with nextpvr addon loaded) is able to direct play (or stream, whatever) without the need for transcoding.  

 

Now, if you are having that issue with DVR media, your on your own as already recorded stuff never displayed an issue, just the live TV.  Perhaps the way your media is encoded needs to change?  I use .mp4 and have had zero issues so far...Good luck!

[Luke 37064]

hi @@Smok@zz, since this thread is a little old now, let's start over and try to get to the bottom of your issue. Please discuss an example, and then attach the information requested in how to report a problem. thanks !