Restarting Payback when FFMpeg transcode completes

[radeon 755]

Hey,

 

I picked up an Amazon Fire TV Stick (Gen 2) for my parents to hook into my emby and have found some strange behaviour...

 

As they have fairly crappy internet, I set the max streaming bitrate to 1mbit which inevitably means most things are being transcoded server side. 

 

Everything plays absolutely fine until the ffmpeg trancode completes on the server then the app seems to restart the playback from the very beginning of the video.

 

Then for whatever reason, if they fast forward to get back to where they were, the transcode process restarts and the whole problem repeats again when the it completes server side. 

 

I can't get any logs for them just yet but thought I'd post in the short term in case anyone has seen this issue before and might have a fix. 

 

Cheers!

Edited May 16, 2017 by radeon

[radeon 755]

OK, just had a mate try, he's normally connected to his own server but has a nvidia shield and had the exact same issue. I got him to send a debug log from his, 22.14 UK time and DaveB is the username on my server

[Luke 42077]

What version(s) of the emby app are you running?

[radeon 755]

1.3.35a on both 

 

servers on Version 3.2.17.0

[ebr 16169]

Everything plays absolutely fine until the ffmpeg trancode completes on the server then the app seems to restart the playback from the very beginning of the video.

 

What made you to come to the conclusion that it was the transcode completing that caused this?

[radeon 755]

I could basically watch it unfold on the server.

 

Firstly I noticed the red transcoded line moving to the end on the emby dashboard and it seemed to happen fairly close to when that completed but not right on it.

 

So I watched for the ffmpeg process directly in task manager and whilst the red line gets to the end, it doesn't seem so accurate as ffmpeg is left running for a little while longer in the background but as soon as that ffmpeg process ends, within 5-10 seconds the video restarts and is repeatable on any transcoded stream in my environment.

[ebr 16169]

Can you please reproduce the issue and send a log from the app?  Thanks.

[radeon 755]

I did last night?

 

"I got him to send a debug log from his, 22.14 UK time and DaveB is the username on my server"

 

Do i need to do it again? 

[ebr 16169]

I did last night?

 

"I got him to send a debug log from his, 22.14 UK time and DaveB is the username on my server"

 

Do i need to do it again? 

 

Yeah, sorry. There was no playback in that log.  Thanks.

[radeon 755]

ok, sure, strange. I talked him through the whole thing. guess he messed up! I'll try and get him to do it now and let you know once done

[radeon 755]

OK, Uploaded, 16.24. Username DaveB again. 

[ebr 16169]

You have to actually reproduce the problem and then send the log in that same app session.  The log he is sending just has a bunch of idle time in it.  .

[CBers 7450]

@@radeon Does he have DEBUG on in the app?

[radeon 755]

You have to actually reproduce the problem and then send the log in that same app session.  The log he is sending just has a bunch of idle time in it.   .

 

Yeah, Thats what he's doing, I'm on the phone with him now talking him through it. I'll get him to kill the app then restart and try again

 

@@radeon Does he have DEBUG on in the app?

 

lol, well yeah, he wouldn't be able to send the log if it wasn't, would he? 

[radeon 755]

OK, new log produced.16.56 DaveB

[CBers 7450]

lol, well yeah, he wouldn't be able to send the log if it wasn't, would he?

Ignore me.

[radeon 755]

Ignore me.

 

lol! are you able to see the logs cbers? Can you see if that one "OK, new log produced.16.56 DaveB" was uploaded ok?

[CBers 7450]

lol! are you able to see the logs cbers? Can you see if that one "OK, new log produced.16.56 DaveB" was uploaded ok?

No, I can't see them, as they go straight to Eric.

[radeon 755]

No, I can't see them, as they go straight to Eric.

 

Ah k! Ta mate! 

[radeon 755]

OK, another log submitted from another mate called Jon at 19.01. Fire tv stick and same app version as above. 

[ebr 16169]

Alright - your first guy's logs never did contain any playback but the second one (Jon) did.  Looks like playback is chugging along until this happens:

I/System.out( 4181): internalError [218.29, loadError]
I/OMX.MTK.VIDEO.DECODER.AVC-MediaCodecRenderer( 4181): onPositionReset: 60000000, joining: false
I/MediaCodecLogger( 4181): Flushing: tv.emby.embyatv.HW.video.avc.framerate = 25.005 fps
I/OMX.MTK.AUDIO.DECODER.MP3-MediaCodecRenderer( 4181): onPositionReset: 60000000, joining: false
D/ACodec  ( 4181): submitOutputMetaBuffers send FTB for ouptut
I/AudioTrack( 4181): reset()
I/AudioTrack( 4181): calling pause
I/System.out( 4181): ******** Exoplayer state change to: true/2
I/AudioTrack( 4181): calling flush
I/System.out( 4181): state [218.34, true, B]
I/AudioTrack( 4181): calling release

Perhaps a network disruption, or maybe something else but the player hits this error.  Interestingly, it isn't calling our error routine when it happens but the player seems to reset itself and start going again.

 

In that session, did Jon react to the event in any way?  I mean, when it jumped back to the beginning, did he try to seek back where he was or just let it go for a bit and then back out?

 

Also, did it really go to the beginning, or just somewhere near the beginning?

 

Thanks.

[radeon 755]

Alright - your first guy's logs never did contain any playback but the second one (Jon) did.  Looks like playback is chugging along until this happens:

I/System.out( 4181): internalError [218.29, loadError]
I/OMX.MTK.VIDEO.DECODER.AVC-MediaCodecRenderer( 4181): onPositionReset: 60000000, joining: false
I/MediaCodecLogger( 4181): Flushing: tv.emby.embyatv.HW.video.avc.framerate = 25.005 fps
I/OMX.MTK.AUDIO.DECODER.MP3-MediaCodecRenderer( 4181): onPositionReset: 60000000, joining: false
D/ACodec  ( 4181): submitOutputMetaBuffers send FTB for ouptut
I/AudioTrack( 4181): reset()
I/AudioTrack( 4181): calling pause
I/System.out( 4181): ******** Exoplayer state change to: true/2
I/AudioTrack( 4181): calling flush
I/System.out( 4181): state [218.34, true, B]
I/AudioTrack( 4181): calling release

Perhaps a network disruption, or maybe something else but the player hits this error.  Interestingly, it isn't calling our error routine when it happens but the player seems to reset itself and start going again.

 

In that session, did Jon react to the event in any way?  I mean, when it jumped back to the beginning, did he try to seek back where he was or just let it go for a bit and then back out?

 

Also, did it really go to the beginning, or just somewhere near the beginning?

 

Thanks.

 

Ah nice! Well at least we got a log from somewhere! 

 

Jon "just let it go for a bit and then back out" then straight away sent a log to you. He didn't react to it in any way.

 

As for where it goes to, its always dependent on the starting state, i.e. if the item has been part watched and they're just resuming, it will go back to exactly where they resumed from. If they started watching from the beginning then it always goes back to the beginning. 

 

I can't imagine it being a network disruption as it's so repeatable. I can pick any piece of media which requires transcoding and the same thing will happen within seconds of the ffmpeg process closing (once it has completed the transcode). 

 

Hope that helps! 

 

Thanks

[ebr 16169]

Do you know exactly when this started happening?  It seems we just started getting reports for it in the past few days but there have been no updates to the app for a few weeks.  I cannot figure out how this could be caused by the app at this point.

[radeon 755]

Unfortunately not. After the nowtv dev removal people jumped ship to android and started getting reports of this sort of behaviour about 6-8 weeks ago I guess?

Edited May 20, 2017 by radeon

[ebr 16169]

6-8 weeks ago?  There are posts out here about this back then?