Playback Progress Issues

[dcrdev 251]

So I've been noticing some issues in various apps (not the web interface) where stuff takes an age to load and when it does there are issues seeking and reporting playback progress, to the extent where particularly in the iOS app it thinks it's playing the wrong thing.

 

So did some digging in the logs and it's complaining about the websocket connection:

2017-11-14 19:20:13.591 Error HttpServer: Error in SharpWebSocket: An exception has occurred while receiving a message.. Exception.Message: The header part of a frame cannot be read from the data source.

Ok I thought, maybe something has changed and I need to modify my proxy configuration. So went into chrome's debugger and sure enough the websocket is never actually established, just sits in a permanent state of 101 and never completes the request.

 

So had a look at my proxy configuration and it appeared to be OK - everything is set up to use wildcards, so any change to the websocket path shouldn't have an impact. Then went on to bare Emby i.e. directly not through the proxy and the same issue is occuring.

 

Below is a screenshot of the debugger:

Edited November 14, 2017 by dcrdev

[Luke 37184]

What issue is that?

[dcrdev 251]

Well the websocket is forever in a stalled state.

 

The issues I'm having around reporting playback progress, skipping to the next item, jumps backward etc.. all have the above exception before them in the logs. It's not establishing a connection - just stays at 101, switching protocols.

Edited November 14, 2017 by dcrdev

[Luke 37184]

There are no emby apps using the web socket to report playback progress anymore, except I think the original Emby for Kodi add-on.

[dcrdev 251]

Hmm interesting - actually maybe not then, although all the same the websocket doesn't appear to be working.

 

Further inspection in the logs - reveals a load of 500 response codes which are more than likely the culprit:

2017-11-14 19:28:47.679 Info HttpServer: HTTP Response 200 to 192.168.1.103. Time: 1ms. http://media.domain.com:8096/emby/Items/6644afeae563d01e09e1a3b29e8cfad2/Images/Primary?height=1800&tag=531f3c3390d1f51cc74ea3d2eb3cf9e0&quality=50 
2017-11-14 19:28:47.693 Info HttpServer: HTTP Response 500 to 192.168.1.103. Time: 3154ms (slow). http://media.domain.com:8096/emby/Audio/367da589ba5aee7e240d2a7a8d6f53a9/universal?UserId=e616cd8e649246988f526683bb982cd2&DeviceId=C30B91C1-177A-41D5-A85D-D3B0E86D34A6&MaxStreamingBitrate=140000000&Container=mp3|mp3,aac,m4a|aac,flac,wav&TranscodingContainer=aac&TranscodingProtocol=hls&AudioCodec=aac&PlaySessionId=1510687275051&StartTimeTicks=0&EnableRedirection=true&EnableRemoteMedia=false 
2017-11-14 19:28:47.746 Info HttpServer: HTTP Response 500 to 192.168.1.103. Time: 3206ms (slow). http://media.domain.com:8096/emby/Audio/1db85be7c48285d463ecea3837513c09/universal?UserId=e616cd8e649246988f526683bb982cd2&DeviceId=C30B91C1-177A-41D5-A85D-D3B0E86D34A6&MaxStreamingBitrate=140000000&Container=mp3|mp3,aac,m4a|aac,flac,wav&TranscodingContainer=aac&TranscodingProtocol=hls&AudioCodec=aac&PlaySessionId=1510687275052&StartTimeTicks=0&EnableRedirection=true&EnableRemoteMedia=false 
2017-11-14 19:28:48.238 Info HttpServer: HTTP Response 500 to 192.168.1.103. Time: 1662ms (slow). http://media.domain.com:8096/emby/Audio/61ae1d8e621b22e5bbd16e89923c3393/universal?UserId=e616cd8e649246988f526683bb982cd2&DeviceId=C30B91C1-177A-41D5-A85D-D3B0E86D34A6&MaxStreamingBitrate=140000000&Container=mp3|mp3,aac,m4a|aac,flac,wav&TranscodingContainer=aac&TranscodingProtocol=hls&AudioCodec=aac&PlaySessionId=1510687275062&StartTimeTicks=0&EnableRedirection=true&EnableRemoteMedia=false 
2017-11-14 19:28:48.238 Info HttpServer: HTTP Response 500 to 192.168.1.103. Time: 1657ms (slow). http://media.domain.com:8096/emby/Audio/2b7916f4f5ce436517ca3cf1c0187547/universal?UserId=e616cd8e649246988f526683bb982cd2&DeviceId=C30B91C1-177A-41D5-A85D-D3B0E86D34A6&MaxStreamingBitrate=140000000&Container=mp3|mp3,aac,m4a|aac,flac,wav&TranscodingContainer=aac&TranscodingProtocol=hls&AudioCodec=aac&PlaySessionId=1510687275066&StartTimeTicks=0&EnableRedirection=true&EnableRemoteMedia=false 
2017-11-14 19:28:48.238 Info HttpServer: HTTP Response 500 to 192.168.1.103. Time: 1659ms (slow). http://media.domain.com:8096/emby/Audio/b15d1a36c9cf8a73c56f04a339b6c7b3/universal?UserId=e616cd8e649246988f526683bb982cd2&DeviceId=C30B91C1-177A-41D5-A85D-D3B0E86D34A6&MaxStreamingBitrate=140000000&Container=mp3|mp3,aac,m4a|aac,flac,wav&TranscodingContainer=aac&TranscodingProtocol=hls&AudioCodec=aac&PlaySessionId=1510687275067&StartTimeTicks=0&EnableRedirection=true&EnableRemoteMedia=false 
2017-11-14 19:28:48.238 Info HttpServer: HTTP Response 500 to 192.168.1.103. Time: 1661ms (slow). http://media.domain.com:8096/emby/Audio/2cc38015a28bf73227f8db8701fa0d3f/universal?UserId=e616cd8e649246988f526683bb982cd2&DeviceId=C30B91C1-177A-41D5-A85D-D3B0E86D34A6&MaxStreamingBitrate=140000000&Container=mp3|mp3,aac,m4a|aac,flac,wav&TranscodingContainer=aac&TranscodingProtocol=hls&AudioCodec=aac&PlaySessionId=1510687275061&StartTimeTicks=0&EnableRedirection=true&EnableRemoteMedia=false 
2017-11-14 19:28:48.238 Info HttpServer: HTTP Response 500 to 192.168.1.103. Time: 1660ms (slow). http://media.domain.com:8096/emby/Audio/b649a5da41e1d02f2fcff564cc0bdb4d/universal?UserId=e616cd8e649246988f526683bb982cd2&DeviceId=C30B91C1-177A-41D5-A85D-D3B0E86D34A6&MaxStreamingBitrate=140000000&Container=mp3|mp3,aac,m4a|aac,flac,wav&TranscodingContainer=aac&TranscodingProtocol=hls&AudioCodec=aac&PlaySessionId=1510687275063&StartTimeTicks=0&EnableRedirection=true&EnableRemoteMedia=false 
2017-11-14 19:28:48.238 Info HttpServer: HTTP Response 500 to 192.168.1.103. Time: 1659ms (slow). http://media.domain.com:8096/emby/Audio/a37b7069e83db67c87a0cbde29f53dde/universal?UserId=e616cd8e649246988f526683bb982cd2&DeviceId=C30B91C1-177A-41D5-A85D-D3B0E86D34A6&MaxStreamingBitrate=140000000&Container=mp3|mp3,aac,m4a|aac,flac,wav&TranscodingContainer=aac&TranscodingProtocol=hls&AudioCodec=aac&PlaySessionId=1510687275064&StartTimeTicks=0&EnableRedirection=true&EnableRemoteMedia=false 
2017-11-14 19:28:48.280 Info HttpServer: HTTP Response 500 to 192.168.1.103. Time: 1701ms (slow). http://media.domain.com:8096/emby/Audio/83a657b7c0d6104412c2581537668135/universal?UserId=e616cd8e649246988f526683bb982cd2&DeviceId=C30B91C1-177A-41D5-A85D-

[Luke 37184]

No, those are not any problem either.

[dcrdev 251]

OK well in that case I'm at a loss - all I can say is I'm having these issues, to me there's nothing else in the logs besides the permission ones mentioned earlier.

 

Any chance you could look at the log? The relevant bits will be toward the end when I'm trying to playback music on iOS.

 

https://drive.google.com/file/d/1WIbYgzuA4eCPetLfGISST7Do2ESaYSZ2/view?usp=sharing

 

Otherwise I'm going to have to give up because I really don't know how I can debug this any further.

Edited November 14, 2017 by dcrdev

[Luke 37184]

First can you please more discussion of the problem that you're actually having? Thanks.

[dcrdev 251]

In the iOS app - music takes 30+ seconds to load on the local network. In the initial loading time if I attempt to play again, or if I attempt to skip to the next track the app freezes and the phone becomes unresponsive for a second or two; this happened on my 6s and now is happening on my X. Skipping to the next track after the track loads, results in the same behaviour 30+ seconds of loading. Additionally because playback is delayed the app will often report that it's playing the wrong track. In the web dashboard playback progress is not being reported. When a track is loading - the web interface takes a long time to load in a browser on the desktop.

 

When playing a video in the iOS app - the playback will often jump backwards a couple of seconds and then repeat over and over again, making videos unplayable.

 

In Kodi - playback progress stops being reported about 1/3 of the way through things; so that whenever I finish something it only gets reported as partially watched.

 

These issues don't seem to occur when playing back in the web interface directly though.

[Luke 37184]

As far as Kodi goes, there have been some fixes made to the add-on in regards to playback progress reporting. I'll look at the other things, thanks.

[dcrdev 251]

Great thank you.

[dcrdev 251]

Have you had a chance to look at my log?

 

Thanks

[dcrdev 251]

@@Luke have you had a chance to look at my log?

 

Also these logs are very difficult for me to interpret for a number of reasons:

• They are very difficult to read - there's no inbuilt log viewer and there appears to be no convention that I could use for parsing them with something like sed. Emby isn't returning status codes, so although it is running as a systemd service the entirety of the log is getting written to the journal as auxillary information - so you can't filter it down by errors/warnings that way either.
• I've no way of knowing what's normal behaviour:
  • 500 response codes are erroneous, are they not? When I was a web developer, that would have been a problem for me. But your saying it's normal for Emby to return these statuses?
  • The fact that the websocket is now not transmitting anything - are you saying that normal as well. Has the websocket been depreciated?

I normally like to debug things myself and I suspect you'd probably prefer that as well because it means you have to answer less user queries. So with that in mind, could you elaborate on my points above? 

 

As things stand I'm having all these issues and I really have no idea what's going on as a long-term Linux user, Emby just isn't that integrated with the various loggers that are in place. What I can tell you is that I can reproduce these issues time and time again on a fresh CentOS vm.

[Luke 37184]

It's being looked into, thanks.

[dcrdev 251]

Great... but regarding my questions?

[Luke 37184]

The web socket is used for the server to send messages to apps, for things like remote controlling. That's basically it.

[dcrdev 251]

The web socket is used for the server to send messages to apps, for things like remote controlling. That's basically it.

 

Good news - latest stable seems to have fixed a lot of issues.

 

Only remaining problem is with audio, where there are still significant delays in loading the track, seeking and skipping. Might be relevent, but my entire collection is flac.