Wrong recording length: How to troublshoot?

[Marc_G 92]

Hi folks,

 

I'm switching from WMC to full on Emby, and have discontinued WMC recordings of OTA TV and set up new series in Emby. I'm using the current stable server release on a Win 7 platform. 

 

Last night, Emby was supposed to record Saturday Night Live from 11:30 pm to 1 am, plus 3 minutes of padding on either side. So, I was expecting a 96 minute recording.  However, it was only 66 minutes long... it stopped at 12:33 am apparently. Or at least that what appears to have happened based on the MKV file that was produced. The real story is apparently more complicated.

 

I'll attach the server log... it's a whole day's worth and I was doing stuff on the HTPC when the recording kicked off so there's a lot in there, but the relevant entry that tells me Emby knew to record the whole show is:

 

2016-12-03 23:26:00.8536 Info App: Beginning recording. Will record for 98.9857566133333 minutes.

 

OK, I expected 96 minutes but that's close enough... :-)

 

The log restarted at midnight automatically. So, in the second log I searched through (OMG! So much stuff from live TV channels I never watch in there!) to find the ending of the SNL recording. Didn't see anything around 00:33:00 or so when I thought the recording stopped early. But down at around the ~1:03 am time when I would have expected the recording to stop, I got this:

 

2016-12-04 01:05:00.0563 Info App: Killing ffmpeg recording process for E:\LiveTVSeries\Saturday Night Live\Season 42\Saturday Night Live S42E08 Emma Stone; Shawn Mendes.mkv
2016-12-04 01:05:00.4583 Debug LibraryMonitor: Changed detected of type Changed to E:\LiveTVSeries\Saturday Night Live\Season 42\Saturday Night Live S42E08 Emma Stone; Shawn Mendes.mkv
2016-12-04 01:05:00.4583 Debug LibraryMonitor: Ignoring change to E:\LiveTVSeries\Saturday Night Live\Season 42\Saturday Night Live S42E08 Emma Stone; Shawn Mendes.mkv
2016-12-04 01:05:00.6024 Error App: Error in QueueStream
 *** Error Report ***
 Version: 3.0.8500.0
 Command line: C:\Users\HomeTheater\AppData\Roaming\MediaBrowser-Server\System\MediaBrowser.ServerApplication.exe
 Operating system: Microsoft Windows NT 6.1.7601 Service Pack 1
 Processor count: 2
 64-Bit OS: True
 64-Bit Process: True
 Program data path: C:\Users\HomeTheater\AppData\Roaming\MediaBrowser-Server
 Application Path: C:\Users\HomeTheater\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.BeginWrite(Byte[] buffer, Int32 offset, Int32 count, AsyncCallback cback, Object state)
    at System.IO.Stream.<>c.<BeginEndWriteAsync>b__53_0(Stream stream, ReadWriteParameters args, AsyncCallback callback, Object state)
    at System.Threading.Tasks.TaskFactory`1.FromAsyncTrim[TInstance,TArgs](TInstance thisRef, TArgs args, Func`5 beginMethod, Func`3 endMethod)
    at System.IO.Stream.BeginEndWriteAsync(Byte[] buffer, Int32 offset, Int32 count)
    at System.IO.Stream.WriteAsync(Byte[] buffer, Int32 offset, Int32 count, CancellationToken cancellationToken)
    at MediaBrowser.Server.Implementations.LiveTv.TunerHosts.QueueStream.<StartInternal>d__16.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-12-04 01:05:00.6964 Info App: FFMpeg recording exited with code 0 for E:\LiveTVSeries\Saturday Night Live\Season 42\Saturday Night Live S42E08 Emma Stone; Shawn Mendes.mkv
2016-12-04 01:05:00.6964 Info App: Recording completed to file E:\LiveTVSeries\Saturday Night Live\Season 42\Saturday Night Live S42E08 Emma Stone; Shawn Mendes.mkv
2016-12-04 01:05:00.6964 Info App: Recording completed: E:\LiveTVSeries\Saturday Night Live\Season 42\Saturday Night Live S42E08 Emma Stone; Shawn Mendes.mkv
2016-12-04 01:05:00.7124 Error ServiceStackHost: 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.8500.0
 Command line: C:\Users\HomeTheater\AppData\Roaming\MediaBrowser-Server\System\MediaBrowser.ServerApplication.exe
 Operating system: Microsoft Windows NT 6.1.7601 Service Pack 1
 Processor count: 2
 64-Bit OS: True
 64-Bit Process: True
 Program data path: C:\Users\HomeTheater\AppData\Roaming\MediaBrowser-Server
 Application Path: C:\Users\HomeTheater\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 req, Object response, IResponse res)
    at ServiceStack.HttpResponseExtensionsInternal.WriteErrorToResponse(IResponse httpRes, IRequest httpReq, String contentType, String operationName, String errorMessage, Exception ex, Int32 statusCode)
    at ServiceStack.ServiceStackHost.HandleUncaughtException(IRequest httpReq, IResponse httpRes, String operationName, Exception ex)
    at ServiceStack.HostContext.RaiseAndHandleUncaughtException(IRequest httpReq, IResponse httpRes, String operationName, Exception ex)
    at ServiceStack.HttpResponseExtensionsInternal.HandleResponseWriteException(Exception originalEx, IRequest request, IResponse response, String defaultContentType)
    at ServiceStack.HttpResponseExtensionsInternal.<WriteToResponse>d__6.MoveNext()
 --- End of stack trace from previous location where exception was thrown ---
    at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
    at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
    at ServiceStack.Host.RestHandler.<ProcessRequestAsync>d__13.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-12-04 01:05:00.7124 Info HttpServer: HTTP Response 500 to 127.0.0.1. Time: 5939660ms. http://127.0.0.1:8096/LiveTv/LiveStreamFiles/3a8ea24ae312434f97d9d374755c4239/stream.ts
2016-12-04 01:05:00.7744 Info App: Live stream c8e3fa5a2b3f418fa6d25c04c80cfb96_native_6a400a18a1fb928db2a3f69f1477afa1 consumer count is now 0
2016-12-04 01:05:00.7864 Info App: Closing live stream c8e3fa5a2b3f418fa6d25c04c80cfb96_native_6a400a18a1fb928db2a3f69f1477afa1
2016-12-04 01:05:00.7864 Info App: Closing HDHR live stream
2016-12-04 01:05:00.8074 Info App: Live stream c8e3fa5a2b3f418fa6d25c04c80cfb96_native_6a400a18a1fb928db2a3f69f1477afa1 closed successfully
2016-12-04 01:05:13.1301 Debug PortMapper: Calling Nat.Handle on uuid:4d696e69-444c-164e-9d44-00000000cc08::urn:schemas-upnp-org:service:WANIPConnection:1
2016-12-04 01:05:19.6464 Info HttpServer: HTTP GET http://192.168.1.4:8096/dlna/1134a6d6915d98d826e9ced2f44798d3/description.xml. UserAgent:
2016-12-04 01:05:19.6464 Info Dlna: No matching device profile found. The default will need to be used.
 Host: 192.168.1.4:8096
 Accept: */*
2016-12-04 01:05:19.6644 Info HttpServer: HTTP Response 200 to 192.168.1.21. Time: 19ms. http://192.168.1.4:8096/dlna/1134a6d6915d98d826e9ced2f44798d3/description.xml
2016-12-04 01:05:45.8149 Debug LibraryMonitor: New file refresher created for E:\LiveTVSeries\Saturday Night Live\Season 42\Saturday Night Live S42E08 Emma Stone; Shawn Mendes.mkv
2016-12-04 01:05:52.4723 Info HttpServer: HTTP GET http://192.168.1.4:8096/dlna/1134a6d6915d98d826e9ced2f44798d3/description.xml. UserAgent: Microsoft-Windows/6.1 UPnP/1.0 Windows-Media-Player-DMS/12.0.7601.17514 DLNADOC/1.50
2016-12-04 01:05:52.4723 Info Dlna: No matching device profile found. The default will need to be used.
 Cache-Control: no-cache
 Connection: Close
 Pragma: no-cache
 Accept: text/xml, application/xml
 Host: 192.168.1.4:8096
 User-Agent: Microsoft-Windows/6.1 UPnP/1.0 Windows-Media-Player-DMS/12.0.7601.17514 DLNADOC/1.50
2016-12-04 01:05:52.4723 Info HttpServer: HTTP Response 200 to 127.0.0.1. Time: 2ms. http://192.168.1.4:8096/dlna/1134a6d6915d98d826e9ced2f44798d3/description.xml
2016-12-04 01:06:19.6639 Info HttpServer: HTTP GET http://192.168.1.4:8096/dlna/1134a6d6915d98d826e9ced2f44798d3/description.xml. UserAgent:
2016-12-04 01:06:19.6639 Info Dlna: No matching device profile found. The default will need to be used.
 Host: 192.168.1.4:8096
 Accept: */*
2016-12-04 01:06:19.6639 Info HttpServer: HTTP Response 200 to 192.168.1.21. Time: 1ms. http://192.168.1.4:8096/dlna/1134a6d6915d98d826e9ced2f44798d3/description.xml
2016-12-04 01:06:45.8244 Debug LibraryMonitor: Timer stopped.
2016-12-04 01:06:45.8904 Info LibraryMonitor: E:\LiveTVSeries\Saturday Night Live\Season 42\Saturday Night Live S42E08 Emma Stone; Shawn Mendes.mkv reports change.
2016-12-04 01:06:45.8904 Info LibraryMonitor: Season 42 (E:\LiveTVSeries\Saturday Night Live\Season 42) will be refreshed.
2016-12-04 01:06:46.0324 Debug App: Running FFProbeProvider for E:\LiveTVSeries\Saturday Night Live\Season 42\Saturday Night Live S42E08 Emma Stone; Shawn Mendes.mkv
2016-12-04 01:06:46.0324 Debug MediaEncoder: C:\Users\HomeTheater\AppData\Roaming\MediaBrowser-Server\ffmpeg\20160410\ffprobe.exe -i file:"E:\LiveTVSeries\Saturday Night Live\Season 42\Saturday Night Live S42E08 Emma Stone; Shawn Mendes.mkv" -threads 0 -v info -print_format json -show_streams -show_chapters -show_format
2016-12-04 01:06:46.9394 Debug App: Running EpisodeNfoProvider for E:\LiveTVSeries\Saturday Night Live\Season 42\Saturday Night Live S42E08 Emma Stone; Shawn Mendes.mkv
2016-12-04 01:06:46.9454 Debug App: EpisodeNfoProvider returned no metadata for E:\LiveTVSeries\Saturday Night Live\Season 42\Saturday Night Live S42E08 Emma Stone; Shawn Mendes.mkv
2016-12-04 01:06:46.9454 Debug App: Running EpisodeXmlProvider for E:\LiveTVSeries\Saturday Night Live\Season 42\Saturday Night Live S42E08 Emma Stone; Shawn Mendes.mkv
2016-12-04 01:06:46.9454 Debug App: EpisodeXmlProvider returned no metadata for E:\LiveTVSeries\Saturday Night Live\Season 42\Saturday Night Live S42E08 Emma Stone; Shawn Mendes.mkv
2016-12-04 01:06:46.9454 Debug App: Running TvdbEpisodeProvider for E:\LiveTVSeries\Saturday Night Live\Season 42\Saturday Night Live S42E08 Emma Stone; Shawn Mendes.mkv
2016-12-04 01:06:47.0814 Debug App: Running TvdbEpisodeImageProvider for E:\LiveTVSeries\Saturday Night Live\Season 42\Saturday Night Live S42E08 Emma Stone; Shawn Mendes.mkv
2016-12-04 01:06:47.0865 Debug App: Running MovieDbEpisodeImageProvider for E:\LiveTVSeries\Saturday Night Live\Season 42\Saturday Night Live S42E08 Emma Stone; Shawn Mendes.mkv
2016-12-04 01:06:47.0865 Info HttpClient: HttpClientManager GET: https://api.themoviedb.org/3/tv/1667/season/42/episode/8?api_key=f6bd687ffa63cd282b6ff2c6877f2669&append_to_response=images,external_ids,credits,videos&language=en&include_image_language=en,null
2016-12-04 01:06:47.3985 Debug JsonSerializer: Deserializing file C:\Users\HomeTheater\AppData\Roaming\MediaBrowser-Server\cache\tmdb-tv\1667\season-42-episode-8-en.json
2016-12-04 01:06:47.3985 Debug App: Running OmdbImageProvider for E:\LiveTVSeries\Saturday Night Live\Season 42\Saturday Night Live S42E08 Emma Stone; Shawn Mendes.mkv
2016-12-04 01:06:47.3985 Debug App: Running VideoImageProvider for E:\LiveTVSeries\Saturday Night Live\Season 42\Saturday Night Live S42E08 Emma Stone; Shawn Mendes.mkv
2016-12-04 01:06:47.3985 Debug MediaEncoder: C:\Users\HomeTheater\AppData\Roaming\MediaBrowser-Server\ffmpeg\20160410\ffmpeg.exe -ss 00:06:32.927 -i file:"E:\LiveTVSeries\Saturday Night Live\Season 42\Saturday Night Live S42E08 Emma Stone; Shawn Mendes.mkv" -threads 0 -v quiet -vframes 1 -vf "scale=600:trunc(600/dar/2)*2,thumbnail=30" -f image2 "C:\Users\HomeTheater\AppData\Roaming\MediaBrowser-Server\cache\temp\9b4f1a76-c6a5-4b02-be38-8089139ec651.jpg"
2016-12-04 01:06:48.5466 Debug ProviderManager: Saving image to C:\Users\HomeTheater\AppData\Roaming\MediaBrowser-Server\metadata\library\cc\cc18f9d14712925676f53bc3d31905e0\Saturday Night Live S42E08 Emma Stone; Shawn Mendes.jpg

 

Basically it looks to my uneducated eye that it recorded the whole thing but then something happened and it resulted in a 66 minute file.

 

Both server logs plus the transcode log are in the attached zip.

 

Thanks in advance for any help!

 

Marc

SNL Recording Error files.zip

[Luke 37096]

Please see if this happens with the next release of Emby Server. Thanks.

[Marc_G 92]

Thanks. Will do. What would you recommend I do in the meantime? I've unchecked the "convert to streaming-friendly format" for now, since it "seems" like the problem happened during conversion after a full length recording. I don't really care much about the format in the short term; did the MKV thing just for consistency since all my other content is MKV.

 

Anything else I should do to set my mind at ease... the ticklish part is that it was my wife's show that got botched... Yikes! Gotta make sure it doesn't happen again....

[Marc_G 92]

Just to document this: I turned off the conversion to mkv and SNL recorded fine on Saturday. The recording in .ts format was the correct length.

[Luke 37096]

Thanks for the report.