CBers 6962 Posted March 18, 2015 Posted March 18, 2015 (edited) Before a video stops playing, I get the "Loading, please wait" message on the screen, similar to what others have reported. 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.tsHere 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-ENDLISTNot 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 March 18, 2015 by CBers 1
CBers 6962 Posted March 18, 2015 Author Posted March 18, 2015 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. 1
ebr 15439 Posted March 18, 2015 Posted March 18, 2015 Yeah this is the same issue. We're trying to find a fix but it is a bugger. 1
CBers 6962 Posted March 18, 2015 Author Posted March 18, 2015 Yeah this is the same issue. We're trying to find a fix but it is a bugger. If you need any more logs/evidence, please let me know.
Koleckai Silvestri 1150 Posted March 18, 2015 Posted March 18, 2015 (edited) When this happens to me, the video ends early. For example, it usually cuts off the credits on a typical television series. Edited March 18, 2015 by Koleckai Silvestri
CBers 6962 Posted March 18, 2015 Author Posted March 18, 2015 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.
bennymac 47 Posted March 19, 2015 Posted March 19, 2015 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. 1
CBers 6962 Posted March 25, 2015 Author Posted March 25, 2015 (edited) 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 March 26, 2015 by CBers 1
CBers 6962 Posted March 26, 2015 Author Posted March 26, 2015 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 1
Bluebull32 17 Posted March 27, 2015 Posted March 27, 2015 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.
BAS 225 Posted March 29, 2015 Posted March 29, 2015 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?
CBers 6962 Posted March 29, 2015 Author Posted March 29, 2015 (edited) 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 March 29, 2015 by CBers
Happy2Play 9157 Posted April 1, 2015 Posted April 1, 2015 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. 1
jluce50 122 Posted April 2, 2015 Posted April 2, 2015 (edited) 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 April 2, 2015 by jluce50 1
Tharnax 49 Posted April 2, 2015 Posted April 2, 2015 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. 1
Koleckai Silvestri 1150 Posted April 2, 2015 Posted April 2, 2015 The family here is in agreement that the current behavior is worse than the original problem. Any feedback from the developers on this issue? 1
jluce50 122 Posted April 3, 2015 Posted April 3, 2015 (edited) 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 April 3, 2015 by jluce50
NickC4555 0 Posted April 3, 2015 Posted April 3, 2015 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.
Bluebull32 17 Posted April 4, 2015 Posted April 4, 2015 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. 1
CBers 6962 Posted April 4, 2015 Author Posted April 4, 2015 (edited) 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 April 4, 2015 by CBers
Luke 38874 Posted April 4, 2015 Posted April 4, 2015 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. 6
CBers 6962 Posted April 4, 2015 Author Posted April 4, 2015 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.
Koleckai Silvestri 1150 Posted April 4, 2015 Posted April 4, 2015 "Everything just works" streaming sounds like a good plan. A longer scan only inconveniences the server. Keep up the good work. 1
CBers 6962 Posted April 4, 2015 Author Posted April 4, 2015 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))
jluce50 122 Posted April 4, 2015 Posted April 4, 2015 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...
Recommended Posts
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 accountSign in
Already have an account? Sign in here.
Sign In Now