Jump to content

"Loading, please wait" at the end of playback


CBers

Recommended Posts

CBers

Before a video stops playing, I get the "Loading, please wait" message on the screen, similar to what others have reported.

 

Capture1029.jpg

 

When I checked the server log, there is an entry waiting for the next .ts file, but it doesn't exist, nor is it listed in the m3u8 playlist file:

2015-03-18 11:27:04.8893 Info - App: waiting for C:\Users\Media\AppData\Roaming\MediaBrowser-Server\transcoding-temp\c1f49a88b916337905bab9c2a49fedc2833.ts
Here are a few lines before that message:
015-03-18 11:27:03.2292 Debug - HttpServer: HTTP GET http://192.168.1.140:8096/mediabrowser/Videos/cf3d75f18b5b35930747c52a1e746a25/hlsdynamic/main/832.ts?mediaSourceId=cf3d75f18b5b35930747c52a1e746a25&maxWidth=1920&maxHeight=1080&videoCodec=h264&profile=high&level=41&deviceId=1MH361020127&ClientTime=1426677997&MaxVideoBitDepth=8&MaxRefFrames=8&AudioCodec=aac&MaxAudioChannels=2&AudioStreamIndex=1&AudioBitrate=128000&VideoBitrate=30000000
	Ip: 192.168.1.11:56786. Headers: Host=192.168.1.140:8096,User-Agent=Roku/DVP-6.1 (076.01E05516A)
2015-03-18 11:27:03.3593 Debug - HttpServer: HTTP POST http://192.168.1.140:8096/mediabrowser/Sessions/Playing/Progress?itemId=cf3d75f18b5b35930747c52a1e746a25&PositionTicks=24210000000&isPaused=false&canSeek=true&PlayMethod=Transcode&QueueableMediaTypes=Video&MediaSourceId=cf3d75f18b5b35930747c52a1e746a25&AudioStreamIndex=1
	Ip: 192.168.1.11:56773. Headers: User-Agent=Roku/DVP-6.1 (076.01E05516A),Host=192.168.1.140:8096,Accept=*/*,Accept-Encoding=deflate, gzip,Authorization=MediaBrowser Client="Roku", Device="Now TV", DeviceId="1MH361020127", Version="1.87", UserId="fe8e98c1df54d9b502474bab46ee8982",X-MediaBrowser-Token=fe17adc1b0f54bbab72ad6f22eaf7368,Content-Length=0,Content-Type=application/x-www-form-urlencoded
2015-03-18 11:27:03.3593 Debug - HttpServer: HTTP Response 204 to 192.168.1.11. Response time: 2.0001 ms.
	Url: http://192.168.1.140:8096/mediabrowser/Sessions/Playing/Progress?itemId=cf3d75f18b5b35930747c52a1e746a25&PositionTicks=24210000000&isPaused=false&canSeek=true&PlayMethod=Transcode&QueueableMediaTypes=Video&MediaSourceId=cf3d75f18b5b35930747c52a1e746a25&AudioStreamIndex=1
2015-03-18 11:27:04.3533 Debug - HttpServer: HTTP POST http://192.168.1.140:8096/mediabrowser/Sessions/Playing/Progress?itemId=cf3d75f18b5b35930747c52a1e746a25&PositionTicks=24220000000&isPaused=false&canSeek=true&PlayMethod=Transcode&QueueableMediaTypes=Video&MediaSourceId=cf3d75f18b5b35930747c52a1e746a25&AudioStreamIndex=1
	Ip: 192.168.1.11:56773. Headers: User-Agent=Roku/DVP-6.1 (076.01E05516A),Host=192.168.1.140:8096,Accept=*/*,Accept-Encoding=deflate, gzip,Authorization=MediaBrowser Client="Roku", Device="Now TV", DeviceId="1MH361020127", Version="1.87", UserId="fe8e98c1df54d9b502474bab46ee8982",X-MediaBrowser-Token=fe17adc1b0f54bbab72ad6f22eaf7368,Content-Length=0,Content-Type=application/x-www-form-urlencoded
2015-03-18 11:27:04.3553 Debug - HttpServer: HTTP Response 204 to 192.168.1.11. Response time: 2.0001 ms.
	Url: http://192.168.1.140:8096/mediabrowser/Sessions/Playing/Progress?itemId=cf3d75f18b5b35930747c52a1e746a25&PositionTicks=24220000000&isPaused=false&canSeek=true&PlayMethod=Transcode&QueueableMediaTypes=Video&MediaSourceId=cf3d75f18b5b35930747c52a1e746a25&AudioStreamIndex=1
2015-03-18 11:27:04.8663 Debug - HttpServer: HTTP Response 200 to 192.168.1.11. Response time: 1637.0936 ms.
	Url: http://192.168.1.140:8096/mediabrowser/Videos/cf3d75f18b5b35930747c52a1e746a25/hlsdynamic/main/832.ts?mediaSourceId=cf3d75f18b5b35930747c52a1e746a25&maxWidth=1920&maxHeight=1080&videoCodec=h264&profile=high&level=41&deviceId=1MH361020127&ClientTime=1426677997&MaxVideoBitDepth=8&MaxRefFrames=8&AudioCodec=aac&MaxAudioChannels=2&AudioStreamIndex=1&AudioBitrate=128000&VideoBitrate=30000000
2015-03-18 11:27:04.8893 Debug - HttpServer: HTTP GET http://192.168.1.140:8096/mediabrowser/Videos/cf3d75f18b5b35930747c52a1e746a25/hlsdynamic/main/833.ts?mediaSourceId=cf3d75f18b5b35930747c52a1e746a25&maxWidth=1920&maxHeight=1080&videoCodec=h264&profile=high&level=41&deviceId=1MH361020127&ClientTime=1426677997&MaxVideoBitDepth=8&MaxRefFrames=8&AudioCodec=aac&MaxAudioChannels=2&AudioStreamIndex=1&AudioBitrate=128000&VideoBitrate=30000000
	Ip: 192.168.1.11:56786. Headers: Host=192.168.1.140:8096,User-Agent=Roku/DVP-6.1 (076.01E05516A)
2015-03-18 11:27:04.8893 Info - App: waiting for C:\Users\Media\AppData\Roaming\MediaBrowser-Server\transcoding-temp\c1f49a88b916337905bab9c2a49fedc2833.ts 
c1f49a88b916337905bab9c2a49fedc2.m3u8

c1f49a88b916337905bab9c2a49fedc2831.ts
#EXTINF:9.384000,
c1f49a88b916337905bab9c2a49fedc2832.ts
#EXT-X-ENDLIST
Not sure if this is related to the cut-off of playback that the Android TV testers are seeing, but it's a very similar problem.

 

Server log here.

Transcode log here.

 

The m3u8 file and the .ts files listed in it are in this ZIP file for reference - it is ~50Mb in size though.

 

.

Edited by CBers
  • Like 1
Link to comment
Share on other sites

CBers

I ran the same video through the Roku and connected via a telnet session as well.

 

Here is the telnet output:

 

MediaPlayer::playVideo::VideoScreenEvent::isPlaybackPosition: set progress -> 2481
MediaPlayer::playVideo::VideoScreenEvent::isPlaybackPosition: set progress -> 2482
MediaPlayer::playVideo::VideoScreenEvent::isPlaybackPosition: set progress -> 2483
HLS Segment info: 27 msg: HLS segment info
MediaPlayer::playVideo::VideoScreenEvent::isPlaybackPosition: set progress -> 2484
MediaPlayer::playVideo::VideoScreenEvent::isPlaybackPosition: set progress -> 2485
HLS Segment info: 27 msg: HLS segment info
MediaPlayer::playVideo::VideoScreenEvent::isPlaybackPosition: set progress -> 2486
MediaPlayer::playVideo::VideoScreenEvent::isPlaybackPosition: set progress -> 2487
MediaPlayer::playVideo::VideoScreenEvent::isPlaybackPosition: set progress -> 2488
MediaPlayer::playVideo::VideoScreenEvent::isPlaybackPosition: set progress -> 2489
MediaPlayer::playVideo::VideoScreenEvent::isPlaybackPosition: set progress -> 2490
HLS Segment info: 27 msg: HLS segment info
MediaPlayer::playVideo::VideoScreenEvent::isPlaybackPosition: set progress -> 2491
MediaPlayer::playVideo::VideoScreenEvent::isPlaybackPosition: set progress -> 2492
MediaPlayer::playVideo::VideoScreenEvent::isPlaybackPosition: set progress -> 2493
MediaPlayer::playVideo::VideoScreenEvent::isPlaybackPosition: set progress -> 2494
HLS Segment info: 27 msg: HLS segment info
MediaPlayer::playVideo::VideoScreenEvent::isPlaybackPosition: set progress -> 2495
MediaPlayer::playVideo::VideoScreenEvent::isPlaybackPosition: set progress -> 2496
HLS Segment info: 27 msg: HLS segment info
MediaPlayer::playVideo::VideoScreenEvent::isPlaybackPosition: set progress -> 2497
MediaPlayer::playVideo::VideoScreenEvent::isPlaybackPosition: set progress -> 2498
MediaPlayer::playVideo::VideoScreenEvent::isPlaybackPosition: set progress -> 2499
MediaPlayer::playVideo::VideoScreenEvent::isPlaybackPosition: set progress -> 2500
MediaPlayer::playVideo::VideoScreenEvent::isPlaybackPosition: set progress -> 2501
MediaPlayer::playVideo::VideoScreenEvent::isPlaybackPosition: set progress -> 2502
MediaPlayer::playVideo::VideoScreenEvent::isPlaybackPosition: set progress -> 2503
MediaPlayer::playVideo::VideoScreenEvent::isPlaybackPosition: set progress -> 2504
MediaPlayer::playVideo::VideoScreenEvent::isPlaybackPosition: set progress -> 2505
MediaPlayer::playVideo::VideoScreenEvent::isPlaybackPosition: set progress -> 2506
MediaPlayer::playVideo::VideoScreenEvent::isPlaybackPosition: set progress -> 2507
MediaPlayer::playVideo::VideoScreenEvent::isPlaybackPosition: set progress -> 2508
MediaPlayer::playVideo::VideoScreenEvent::isPlaybackPosition: set progress -> 2509
MediaPlayer::playVideo::VideoScreenEvent::isPlaybackPosition: set progress -> 2510
MediaPlayer::playVideo::VideoScreenEvent::isStreamStarted: position -> 2510
Message data -> roAssociativeArray
Connection[87031813].info: accepted connection @192.168.1.140:50138
Request[4].info: POST '/mediabrowser/message/Ping'
Reply[32].info: Sent 162 [0-161/162]
Reply[32].info: source buf is empty
Reply[32].info: Sent-1 [0--2/0]
Connection[87031813].info: send reply peer closed @192.168.1.140:50138
Connection[87031814].info: accepted connection @192.168.1.140:50145
Request[5].info: POST '/mediabrowser/message/Ping'
Reply[33].info: Sent 162 [0-161/162]
Reply[33].info: source buf is empty
Reply[33].info: Sent-1 [0--2/0]
Connection[87031814].info: send reply peer closed @192.168.1.140:50145
MediaPlayer::playVideo::VideoScreenEvent::isRequestFailed - message = Network error.  This could be caused by any of the following problems: (1) The server is down or unresponsive. (2) The server is unreachable. (3) There is a network setup issue on the client.
MediaPlayer::playVideo::VideoScreenEvent::isRequestFailed - data = 0
MediaPlayer::playVideo::VideoScreenEvent::isRequestFailed - index = 0
MediaPlayer::playVideo::VideoScreenEvent::isScreenClosed: position -> 2510
Sending message to server to stop transcoding
Popping screen 6 and cleaning up 0 breadcrumbs
Top of stack is once again: Chapterscf3d75f18b5b35930747c52a1e746a25
Connection[87031815].info: accepted connection @192.168.1.140:50159
Request[6].info: POST '/mediabrowser/message/Ping'
Reply[34].info: Sent 162 [0-161/162]
Reply[34].info: source buf is empty
Reply[34].info: Sent-1 [0--2/0]
Connection[87031815].info: send reply peer closed @192.168.1.140:50159

Related server log here.

Transcode log here.

  • Like 1
Link to comment
Share on other sites

CBers

Yeah this is the same issue.  We're trying to find a fix but it is a bugger.

:D

 

If you need any more logs/evidence, please let me know.

Link to comment
Share on other sites

Koleckai Silvestri

When this happens to me, the video ends early. For example, it usually cuts off the credits on a typical television series.

Edited by Koleckai Silvestri
Link to comment
Share on other sites

CBers

When this happens to me, the video ends early. For example, it usually cuts off the credits on a typical television series.

Yes, that seems to be the symptom. Mine finished about 9 seconds early this morning.

Link to comment
Share on other sites

bennymac

Yeah this is the same issue.  We're trying to find a fix but it is a bugger.

 

I've always had this and assumed it was something to do with my setup. Good to know.

  • Like 1
Link to comment
Share on other sites

CBers

Yeah this is the same issue. We're trying to find a fix but it is a bugger.

@@ebr - Has anything been done to address this problem in the last 48 hours?

 

I ask, as the last 2 nights I have watched a couple of TV shows to the end, but playback has jumped back about 1 minute each time and then started playing again from that point.

 

I'll grab logs if/when it happens again.

 

.

Edited by CBers
  • Like 1
Link to comment
Share on other sites

CBers

OK, so it's happened again when I played another tv show. When it ended, it jumped back about 5 minutes and played again.

 

At the end, it jumped back to the same point again, doing a few times more, before it went all out of sync and eventually stopped and returned to the episode page.

 

Each time it restarted, it seems to have created a separate transcode log.

 

Server log

Transcode log1

Transcode log2

Transcode log3

Transcode log4

Transcode log5

ffmpeg-sub-extract log

  • Like 1
Link to comment
Share on other sites

Bluebull32

Is anyone seeing this problem with the Emby beta version of the server?  A fix went in for this, and this problem has gone away (for me) in the beta version.

Link to comment
Share on other sites

Is anyone seeing this problem with the Emby beta version of the server?  A fix went in for this, and this problem has gone away (for me) in the beta version.

 

I would verify but the current changes in ffmpeg on beta and developer doesn't work in my use case scenario for my house/server. Anyone else that can confirm?

Link to comment
Share on other sites

CBers

Is anyone seeing this problem with the Emby beta version of the server? A fix went in for this, and this problem has gone away (for me) in the beta version.

See my post above yours.

 

The original problem I posted about seems to be fixed, but there's now a more horrendous problem.

 

.

Edited by CBers
Link to comment
Share on other sites

Happy2Play

OK, so it's happened again when I played another tv show. When it ended, it jumped back about 5 minutes and played again.

 

At the end, it jumped back to the same point again, doing a few times more, before it went all out of sync and eventually stopped and returned to the episode page.

 

Each time it restarted, it seems to have created a separate transcode log.

 

Server log

Transcode log1

Transcode log2

Transcode log3

Transcode log4

Transcode log5

ffmpeg-sub-extract log

Just experience this jump back issues v1.9, stopped playback before loop ended.

  • Like 1
Link to comment
Share on other sites

jluce50

I've been getting this for a while too. However, on the new Roku app I'm unable to skip ahead or start from a chapter other than the first one. Seeking seems to be broken. Doing any of these things just causes it to hang on the loading screen. I didn't manage to grab any logs last night as it was late, but I'll try to grab some today.

Edited by jluce50
  • Like 1
Link to comment
Share on other sites

Tharnax

Just popping my head in here to say, I'm experiencing the same issue.  At the end of every show playing in the Roku there is at least one loop back for a variable period of time.  I've started cancelling out at this point but when I first noticed it, I let it run and it looped back three times each time the loop back was slightly less period of time until if finally stopped after the 3rd loop back.

 

It appears you have plenty of detail and logs to work with but if more is required let me know.

  • Like 1
Link to comment
Share on other sites

Koleckai Silvestri

The family here is in agreement that the current behavior is worse than the original problem. Any feedback from the developers on this issue?

  • Like 1
Link to comment
Share on other sites

jluce50

Just noticed something else. I can't resume any videos. If I attempt it, it starts loading and then the player exits and the video appears to be marked as watched and I lose the resume point. The really strange thing is that it retains its progress on the server. The Roku just isn't able to see it.

 

There are tons of these in the transcode log, which is caused by the new throttling functionality. Could it be that resuming from the Roku somehow triggers the throttling prematurely (before any buffer is built up) which causes the Roku to kick out of the player?

 

Enter command: <target>|all <time>|-1 <command>[ <argument>]
Parse error, at least 3 arguments were expected, only -1 given in string ''
frame=12044 fps= 51 q=26.0 size=N/A time=00:23:31.61 bitrate=N/A    
frame=12105 fps= 51 q=24.0 size=N/A time=00:23:34.10 bitrate=N/A    
frame=12164 fps= 51 q=22.0 size=N/A time=00:23:36.58 bitrate=N/A    
frame=12225 fps= 52 q=24.0 size=N/A time=00:23:39.12 bitrate=N/A    
frame=12281 fps= 52 q=25.0 size=N/A time=00:23:41.46 bitrate=N/A    
frame=12341 fps= 52 q=22.0 size=N/A time=00:23:43.94 bitrate=N/A    
frame=12398 fps= 52 q=26.0 size=N/A time=00:23:46.35 bitrate=N/A    
frame=12458 fps= 52 q=25.0 size=N/A time=00:23:48.80 bitrate=N/A    
frame=12515 fps= 52 q=25.0 size=N/A time=00:23:51.19 bitrate=N/A    
frame=12574 fps= 52 q=26.0 size=N/A time=00:23:53.75 bitrate=N/A    

transcode-8f13528c-fb94-4442-8464-4d2b76ad266f.txt

Edited by jluce50
Link to comment
Share on other sites

NickC4555

I frequently get "Loading, please wait" at the end of playback, but clicking the back button on the remote gets back to the main screen.

Link to comment
Share on other sites

Bluebull32

I think I have isolated this "looping back" problem to videos that transcode for audio, while passing the video stream as-is.  In other words, these are videos that would be Direct Play, if not for the audio track.  The server is using different parameters to do the transcoding when the video can pass through...taking advantage of the fact that the video stream is good to go.  This is indicated in the transcode log like:

 

"Stream mapping:
  Stream #0:0 -> #0:0 (copy)
  Stream #0:1 -> #0:1 (ac3 (native) -> aac (native))"

 

The problem is that this does not give uniform durations for ts segments, as the Roku app is expecting.  The app keeps requesting more segments after the video is already finished, which is why we are seeing it loop back one or more times.  Ideally, the m3u8 file should have uniform segment durations.  When the server fully transcodes a video now, I can see the segments are mostly uniform, and this loop back issue doesn't occur.  When an item is transcoded for audio only while video is passed through, the segment durations in the m3u8 are all over the place.

 

Unfortuately, I do not know if there is an option to force uniform segment durations for video pass through on ffmpeg, but maybe someone can take the stick here and run with it.  The server could just fully transcode these videos ( I think it was doing that at one point).  It's a waste of CPU to do that, but it's an option.

 

Since the audio track is the only thing keeping these videos from streaming directly, you can convert the audio track on these, as a workaround.  There are tools that will copy the video while converting the audio track.

  • Like 1
Link to comment
Share on other sites

CBers

Might be something in that, as most of my videos are streamed that way.

 

Perhaps Luke will have an answer or suggestion.

 

Re-encoding isn't really an option IMO.

 

.

Edited by CBers
Link to comment
Share on other sites

the reason why it's coming up now is because our algorithms to detect direct streaming and stream copying are much better than ever before from the client-side perspective. so prior builds (and other apps) would never even try to stream copy which is why the issue wasn't occurring. 


 


but now with almost every app using the profile engine, we're getting really accurate client capabilities factored into the algorithm. this now leads to the issue of we know that the client can play it, but is the video suitable for what we're going to try to do (e.g. hls with stream copy). And the only way to answer that is to have the scan extract more information about the video's key frame intervals. So this is going to lead to longer scan times, but more of the "everything just works" streaming.


  • Like 6
Link to comment
Share on other sites

CBers

Cool, thanks Luke.

 

As long as you know what needs doing and a fix will come, I'm happy to live with it at the moment.

Link to comment
Share on other sites

Koleckai Silvestri

"Everything just works" streaming sounds like a good plan. A longer scan only inconveniences the server. Keep up the good work.

  • Like 1
Link to comment
Share on other sites

CBers

Just watched a video in Roku app and it played to the end without issue, but it seems to have been a transcode of both video and audio:

 

Stream mapping:
  Stream #0:0 -> #0:0 (h264 (native) -> h264 (libx264))
  Stream #0:1 -> #0:1 (ac3 (native) -> aac (native))
Link to comment
Share on other sites

jluce50

 

Just noticed something else. I can't resume any videos. If I attempt it, it starts loading and then the player exits and the video appears to be marked as watched and I lose the resume point. The really strange thing is that it retains its progress on the server. The Roku just isn't able to see it.

 

@@Luke - any idea what's going on with this? As of now my Roku is almost useless...

Link to comment
Share on other sites

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
×
×
  • Create New...