search

jellyfin / jellyfin-androidtv

Android TV Client for Jellyfin
https://jellyfin.org
GNU General Public License v2.0
2.71k stars 463 forks source link

Jellyfin crashes each time after 5 min when playing a video #1061

Closed bmillemathias closed 1 year ago

bmillemathias commented 3 years ago

Describe the bug Any video media play ends up by jellyfin crashing and restarting after around 5 min.

To Reproduce

  1. Launch a video
  2. Wait ~ 5 minutes. (YMMV)

Expected behavior Hmmm not crashing :)

Logs Don't know how I can provide you that. tell me where they are and I'll provide them

Screenshots none

System (please complete the following information):

Additional context no problem with 0.11

acvigue commented 3 years ago

occurs on google tv as well.

therhenals commented 3 years ago

The same thing happens to me, the app restarts, but every 10 minutes or so.

CodeMonkeyUK commented 3 years ago

Similar after a few minutes...

acvigue commented 3 years ago

this seems to be specific to libVLC and the issue is pretty severe, preventing any of our TVs from playing anything

therhenals commented 3 years ago

this seems to be specific to libVLC and the issue is pretty severe, preventing any of our TVs from playing anything

I figured it out about 10 hours ago, I set to ExoPlayer and everything works fine.

acvigue commented 3 years ago

switching to exo doesn't help - seeking doesn't work.

therhenals commented 3 years ago

switching to exo doesn't help - seeking doesn't work.

It helped me!

Cookie-Monster-Coder commented 3 years ago

Same, for me it usually happens around 7 minutes. Server logs don't show anything related to the crash/video stopping.

crobibero commented 3 years ago

Attached are the logs from my test session after a fresh restart. jellyfin_atv_0.12.0-beta4.log

I don't have this issue when forcing the app to use ExoPlayer, so I agree it looks like an issue with VLC.

MrChip53 commented 3 years ago

Attached are the logs from my test session after a fresh restart. jellyfin_atv_0.12.0-beta4.log

I don't have this issue when forcing the app to use ExoPlayer, so I agree it looks like an issue with VLC.

Did you have to do anything special to reproduce?

crobibero commented 3 years ago

Attached are the logs from my test session after a fresh restart. jellyfin_atv_0.12.0-beta4.log I don't have this issue when forcing the app to use ExoPlayer, so I agree it looks like an issue with VLC.

Did you have to do anything special to reproduce?

Nope, just started any playback. Happens every time I use libVLC

thornbill commented 3 years ago

I don't really see anything in the provided logs either...

crobibero commented 3 years ago

Logs from current master running with the debugger attached.. From an outsider looking in, it seems to be 

2021-08-26 16:02:53.553 10140-10720/org.jellyfin.androidtv.debug E/VLC: [6cd655b0/29e0] libvlc decoder: Decoder is draining

Just org.jellyfin.androidtv.debug logs

2021-08-26 16:02:50.913 10140-10140/org.jellyfin.androidtv.debug I/jellyfin-apiclient: Response received from: https://jellyfin.domain.tld/Sessions/Playing/Progress
2021-08-26 16:02:53.553 10140-10720/org.jellyfin.androidtv.debug E/VLC: [6cd655b0/29e0] libvlc decoder: Decoder is draining
2021-08-26 16:02:53.592 10140-10720/org.jellyfin.androidtv.debug W/VLC: [6cd655b0/29e0] libvlc decoder: EOS sent, waiting for OutThread
2021-08-26 16:02:53.722 10140-10140/org.jellyfin.androidtv.debug D/jellyfin-apiclient: Adding request to queue: https://jellyfin.domain.tld/Sessions/Playing/Progress
2021-08-26 16:02:53.921 10140-10140/org.jellyfin.androidtv.debug I/jellyfin-apiclient: Response received from: https://jellyfin.domain.tld/Sessions/Playing/Progress
2021-08-26 16:02:53.980 10140-10719/org.jellyfin.androidtv.debug W/VLC: [6cd655b0/29df] libvlc decoder: EOS received
2021-08-26 16:02:54.398 10140-10721/org.jellyfin.androidtv.debug D/AudioTrack: stop() called with 22872687 frames delivered
2021-08-26 16:02:54.502 10140-10140/org.jellyfin.androidtv.debug D/PlaybackController: On Completion fired
2021-08-26 16:02:54.503 10140-10719/org.jellyfin.androidtv.debug E/NdkMediaCodec: sf error code: -38
2021-08-26 16:02:54.503 10140-10719/org.jellyfin.androidtv.debug W/VLC: [6cd655b0/29df] libvlc decoder: AMediaCodec.dequeueOutputBuffer failed
2021-08-26 16:02:54.515 10140-10140/org.jellyfin.androidtv.debug I/jellyfin-apiclient: ReportPlaybackStopped: Item 9197d589233164b844cb12f99745e52d, Ticks: 4762680000
2021-08-26 16:02:54.522 10140-10140/org.jellyfin.androidtv.debug D/jellyfin-apiclient: Adding request to queue: https://jellyfin.domain.tld/Sessions/Playing/Stopped
2021-08-26 16:02:54.523 10140-10140/org.jellyfin.androidtv.debug D/PlaybackController: Moving to next queue item. Index: 1
2021-08-26 16:02:54.530 3455-6812/? I/ActivityManager: START u0 {cmp=org.jellyfin.androidtv.debug/org.jellyfin.androidtv.ui.playback.nextup.NextUpActivity (has extras)} from uid 10056
2021-08-26 16:02:54.538 10140-10710/org.jellyfin.androidtv.debug D/SurfaceUtils: disconnecting from surface 0x5faa2808, reason disconnectFromSurface
2021-08-26 16:02:54.613 3455-6812/? V/WindowManager: Changing focus from Window{4fb3def u0 org.jellyfin.androidtv.debug/org.jellyfin.androidtv.ui.playback.PlaybackOverlayActivity} to null Callers=com.android.server.wm.WindowManagerService.setFocusedApp:2585 com.android.server.am.ActivityManagerService.setResumedActivityUncheckLocked:3650 com.android.server.am.ActivityStack.onActivityStateChanged:520 com.android.server.am.TaskRecord.onActivityStateChanged:1818 
2021-08-26 16:02:54.644 10140-10140/org.jellyfin.androidtv.debug W/ActivityThread: handleWindowVisibility: no activity for token android.os.BinderProxy@ec5cf8d
2021-08-26 16:02:54.677 10140-10140/org.jellyfin.androidtv.debug I/AppThemeCallbacks: Applying theme: DARK
2021-08-26 16:02:54.687 10140-10704/org.jellyfin.androidtv.debug D/AudioTrack: stop() called with 0 frames delivered
2021-08-26 16:02:54.727 10140-10140/org.jellyfin.androidtv.debug I/BackgroundService: Adding BackgroundServiceFragment to activity
2021-08-26 16:02:54.736 10140-10191/org.jellyfin.androidtv.debug D/jellyfin-apiclient: Adding request to queue: https://jellyfin.domain.tld/Users/2130c095606e49619adcbacfbdabe373/Items/387e76c31f3a3002f797de21511ecbb4?format=json
2021-08-26 16:02:54.796 10140-10140/org.jellyfin.androidtv.debug E/ThemeUtils: View class androidx.appcompat.widget.AppCompatButton is an AppCompat widget that can only be used with a Theme.AppCompat theme (or descendant).
2021-08-26 16:02:54.822 10140-10140/org.jellyfin.androidtv.debug D/BackgroundServiceFragment: Restoring background drawable
2021-08-26 16:02:54.831 3455-6812/? I/WindowManager: WindowState() - found Launcher @ mAppToken:AppWindowToken{8a2387 token=Token{2397c6 ActivityRecord{8eb49a1 u0 org.jellyfin.androidtv.debug/org.jellyfin.androidtv.ui.playback.nextup.NextUpActivity t932}}}
2021-08-26 16:02:54.834 3455-6812/? I/NvUtils: onActivityResumed AM packageName = org.jellyfin.androidtv.debug

All logs (from crash)

2021-08-26 16:02:50.913 10140-10140/org.jellyfin.androidtv.debug I/jellyfin-apiclient: Response received from: https://jellyfin.domain.tld/Sessions/Playing/Progress
2021-08-26 16:02:53.135 3274-10715/? D/NvOsDebugPrintf: NVMEDIA: FrameRate(for last 120 frames) = 23.976043, AvgFrameRate = 23.969893 
2021-08-26 16:02:53.553 10140-10720/org.jellyfin.androidtv.debug E/VLC: [6cd655b0/29e0] libvlc decoder: Decoder is draining
2021-08-26 16:02:53.592 10140-10720/org.jellyfin.androidtv.debug W/VLC: [6cd655b0/29e0] libvlc decoder: EOS sent, waiting for OutThread
2021-08-26 16:02:53.593 3274-10713/? D/NvOsDebugPrintf: NVMEDIA: NvMMLiteNVMEDIADecDoWork: 2503: NVMMLITE_NVMEDIA: EOS detected
2021-08-26 16:02:53.722 10140-10140/org.jellyfin.androidtv.debug D/jellyfin-apiclient: Adding request to queue: https://jellyfin.domain.tld/Sessions/Playing/Progress
2021-08-26 16:02:53.921 10140-10140/org.jellyfin.androidtv.debug I/jellyfin-apiclient: Response received from: https://jellyfin.domain.tld/Sessions/Playing/Progress
2021-08-26 16:02:53.969 3274-10715/? D/NvOsDebugPrintf: NVMEDIA: NVMEDIABufferProcessing: 1241: Processing of EOS 
2021-08-26 16:02:53.974 3274-10715/? D/NvOsDebugPrintf: NVMEDIA: NVMEDIABufferProcessing: 1319: Processing of EOS Done
2021-08-26 16:02:53.980 10140-10719/org.jellyfin.androidtv.debug W/VLC: [6cd655b0/29df] libvlc decoder: EOS received
2021-08-26 16:02:54.398 10140-10721/org.jellyfin.androidtv.debug D/AudioTrack: stop() called with 22872687 frames delivered
2021-08-26 16:02:54.411 3598-4048/? I/bt_btif_avrc: register_notification_rsp: Avrcp device is not connected, handle: 0x0
2021-08-26 16:02:54.411 3598-4048/? I/chatty: uid=1002(bluetooth) BluetoothAvrcpH identical 10 lines
2021-08-26 16:02:54.411 3598-4048/? I/bt_btif_avrc: register_notification_rsp: Avrcp device is not connected, handle: 0x0
2021-08-26 16:02:54.451 3213-10723/? W/AudioFlinger: pause because of UNDERRUN, framesReady = 111,minFrames = 256, mFormat = 0x1
2021-08-26 16:02:54.456 3174-10726/? W/nvaudio_hw: UNDERRUN DETECTED for hdmi-playback ret 0 avail 524 
2021-08-26 16:02:54.456 3213-10723/? W/AudioFlinger: pause because of UNDERRUN, framesReady = 0,minFrames = 256, mFormat = 0x1
2021-08-26 16:02:54.466 3174-6318/? W/nvaudio_hw: stop_output_stream: 4 underruns seen on pcm device hdmi-playback
2021-08-26 16:02:54.502 10140-10140/org.jellyfin.androidtv.debug D/PlaybackController: On Completion fired
2021-08-26 16:02:54.503 10140-10719/org.jellyfin.androidtv.debug E/NdkMediaCodec: sf error code: -38
2021-08-26 16:02:54.503 10140-10719/org.jellyfin.androidtv.debug W/VLC: [6cd655b0/29df] libvlc decoder: AMediaCodec.dequeueOutputBuffer failed
2021-08-26 16:02:54.506 3213-3348/? W/AudioFlinger: moveEffectChain_l() effect chain for session 0 not on source thread 0x466d4000
2021-08-26 16:02:54.515 10140-10140/org.jellyfin.androidtv.debug I/jellyfin-apiclient: ReportPlaybackStopped: Item 9197d589233164b844cb12f99745e52d, Ticks: 4762680000
2021-08-26 16:02:54.517 3274-10717/? D/NvOsDebugPrintf: NVMEDIA: NVMEDIAFrameStatusReporting: 2011: Closing NVMEDIA Frame Status Thread -------------
2021-08-26 16:02:54.517 3274-10718/? D/NvOsDebugPrintf: NVMEDIA: NVMEDIAVPRFloorSizeSettingThread: 1830: Closing NVMEDIAVPRFloorSizeSettingThread -------------
2021-08-26 16:02:54.517 3274-10716/? D/NvOsDebugPrintf: NVMEDIA: NVMEDIAFrameDelivery: 1866: Closing NVMEDIA Frame Delivery Thread -------------
2021-08-26 16:02:54.522 10140-10140/org.jellyfin.androidtv.debug D/jellyfin-apiclient: Adding request to queue: https://jellyfin.domain.tld/Sessions/Playing/Stopped
2021-08-26 16:02:54.523 10140-10140/org.jellyfin.androidtv.debug D/PlaybackController: Moving to next queue item. Index: 1
2021-08-26 16:02:54.529 3274-10713/? D/NvOsDebugPrintf: NVMEDIA: NvMMLiteTVMRDecBlockClose: 3703: Done 
2021-08-26 16:02:54.530 3455-6812/? I/ActivityManager: START u0 {cmp=org.jellyfin.androidtv.debug/org.jellyfin.androidtv.ui.playback.nextup.NextUpActivity (has extras)} from uid 10056
2021-08-26 16:02:54.538 10140-10710/org.jellyfin.androidtv.debug D/SurfaceUtils: disconnecting from surface 0x5faa2808, reason disconnectFromSurface
2021-08-26 16:02:54.550 3207-3207/? E/powerHAL::common: Unknown power hint: 0x8
2021-08-26 16:02:54.594 3455-6812/? I/MediaFocusControl: abandonAudioFocus() from uid/pid 10056/10140 clientId=android.media.AudioManager@2acff19org.jellyfin.androidtv.ui.playback.CustomPlaybackOverlayFragment$6@fb86bde
2021-08-26 16:02:54.596 3455-6812/? I/MediaFocusControl: abandonAudioFocus() from uid/pid 10056/10140 clientId=android.media.AudioManager@2acff19org.jellyfin.androidtv.ui.playback.CustomPlaybackOverlayFragment$6@fb86bde
2021-08-26 16:02:54.598 3455-11776/? D/NvThermalService: setAppClose
2021-08-26 16:02:54.613 3455-6812/? V/WindowManager: Changing focus from Window{4fb3def u0 org.jellyfin.androidtv.debug/org.jellyfin.androidtv.ui.playback.PlaybackOverlayActivity} to null Callers=com.android.server.wm.WindowManagerService.setFocusedApp:2585 com.android.server.am.ActivityManagerService.setResumedActivityUncheckLocked:3650 com.android.server.am.ActivityStack.onActivityStateChanged:520 com.android.server.am.TaskRecord.onActivityStateChanged:1818 
2021-08-26 16:02:54.628 3598-4048/? I/Avrcp: Skipping update due to invalid playback state
2021-08-26 16:02:54.628 3598-4048/? I/bt_btif_avrc: register_notification_rsp: Avrcp device is not connected, handle: 0x0
2021-08-26 16:02:54.628 3598-4048/? I/chatty: uid=1002(bluetooth) BluetoothAvrcpH identical 10 lines
2021-08-26 16:02:54.628 3598-4048/? I/bt_btif_avrc: register_notification_rsp: Avrcp device is not connected, handle: 0x0
2021-08-26 16:02:54.635 3213-11339/? W/AudioFlinger: moveEffectChain_l() effect chain for session 0 not on source thread 0x46683a00
2021-08-26 16:02:54.637 3455-11777/? W/NvAppProfileService: App Profiles: Enabled
2021-08-26 16:02:54.644 10140-10140/org.jellyfin.androidtv.debug W/ActivityThread: handleWindowVisibility: no activity for token android.os.BinderProxy@ec5cf8d
2021-08-26 16:02:54.649 4275-4303/? I/android_os_HwBinder: HwBinder: Starting thread pool for default::vendor.nvidia.hardware.power@1.0::IPower
2021-08-26 16:02:54.677 10140-10140/org.jellyfin.androidtv.debug I/AppThemeCallbacks: Applying theme: DARK
2021-08-26 16:02:54.681 3213-10723/? W/AudioFlinger: pause because of UNDERRUN, framesReady = 0,minFrames = 256, mFormat = 0x1
2021-08-26 16:02:54.685 3213-10723/? W/AudioFlinger: pause because of UNDERRUN, framesReady = 0,minFrames = 256, mFormat = 0x1
2021-08-26 16:02:54.687 10140-10704/org.jellyfin.androidtv.debug D/AudioTrack: stop() called with 0 frames delivered
2021-08-26 16:02:54.689 3598-4048/? I/bt_btif_avrc: register_notification_rsp: Avrcp device is not connected, handle: 0x0
2021-08-26 16:02:54.689 3598-4048/? I/chatty: uid=1002(bluetooth) BluetoothAvrcpH identical 4 lines
2021-08-26 16:02:54.689 3598-4048/? I/bt_btif_avrc: register_notification_rsp: Avrcp device is not connected, handle: 0x0
2021-08-26 16:02:54.727 10140-10140/org.jellyfin.androidtv.debug I/BackgroundService: Adding BackgroundServiceFragment to activity
2021-08-26 16:02:54.736 10140-10191/org.jellyfin.androidtv.debug D/jellyfin-apiclient: Adding request to queue: https://jellyfin.domain.tld/Users/2130c095606e49619adcbacfbdabe373/Items/387e76c31f3a3002f797de21511ecbb4?format=json
2021-08-26 16:02:54.747 3213-3348/? W/AudioFlinger: moveEffectChain_l() effect chain for session 0 not on source thread 0x466d4000
2021-08-26 16:02:54.796 10140-10140/org.jellyfin.androidtv.debug E/ThemeUtils: View class androidx.appcompat.widget.AppCompatButton is an AppCompat widget that can only be used with a Theme.AppCompat theme (or descendant).
2021-08-26 16:02:54.822 10140-10140/org.jellyfin.androidtv.debug D/BackgroundServiceFragment: Restoring background drawable
2021-08-26 16:02:54.831 3455-6812/? I/WindowManager: WindowState() - found Launcher @ mAppToken:AppWindowToken{8a2387 token=Token{2397c6 ActivityRecord{8eb49a1 u0 org.jellyfin.androidtv.debug/org.jellyfin.androidtv.ui.playback.nextup.NextUpActivity t932}}}
2021-08-26 16:02:54.831 3455-6812/? E/WindowManager: App trying to use insecure INPUT_FEATURE_NO_INPUT_CHANNEL flag. Ignoring
2021-08-26 16:02:54.834 3455-6812/? I/NvUtils: onActivityResumed AM packageName = org.jellyfin.androidtv.debug
Artiume commented 2 years ago

https://gist.github.com/Artiume/1e206bfc42cc3f50f99d0564c9cd2eaa

Here's some more logs for it. I saw it was using libVLC but beyond that, I'm not sure.

cirdanmiriel commented 2 years ago

Same here, I've been experiencing this same bug for months now, preventing me from fully migrating from Kodi to Jellyfin... I'd like to add that the tests I made were made with a Nvidia SHIELD's Jellyfin Android app, with a dozen different movies, all of them in 4KHDR x265:

This is sad... :'(

bmillemathias commented 2 years ago

Tried version 0.12.1 and still got the same behavior, whatever the backend I use

douglasg14b commented 2 years ago

This seems to be a pretty common problem, at least common enough to stave off stalebot from mass-closing them.... (Please @nielsvanvelzen , can we not have this stalebot toxicity, especially on issues that have been tagged?)

Potentially related:

Perhaps the issue should have boundaries drawn and tracked in a single place?

nielsvanvelzen commented 2 years ago

Thank you for sharing your concerns @douglasg14b. Unfortunately the Android TV team is really small and we don't have the time to properly triage all issues. We're using stalebot to help with this, the bot will only close if an issue becomes stale. Leaving a comment will prevent the bot from closing. I know this is not an ideal solution (I don't like it myself when this happens on another repository either) but we'll have to do it with what we have.

We're 100% aware that there are some major issues with playing video (and audio) in our app. To fix this a complete rewrite of this code is happening as we speak (#1057). The current code is in "maintenance" mode and we will try to fix issues we find (and review/accept pull requests for those fixes and smaller features!). Unfortunately this particular issue is really hard to fix due too the bad state of the code. For example: our implementation using LibVLC is really old and not following the standard API like the official VLC app.

I'll see if I can find time later this week to look trough your list and close duplicate issues as needed. I'm quite busy at the moment.

douglasg14b commented 2 years ago

@nielsvanvelzen I appreciate the reply! Thank you for the explanation.

I might suggest making the rewrite a bit more widely known (Pinning can be easily missed, perhaps an issue template thing calling it out?), indicating that these playback issues are known and are probably begin addressed as part of that initiative.

Just knowing that a thing is happening can reduce user frustration and sets reasonable expectations, even if timelines are largely unknown. This by extension can reduce load and frustration for devs who know what's happening, but have to constantly put out fires from those who are not aware.

krutburken commented 2 years ago

@nielsvanvelzen Thanks for acknowledging the many playback issues. I was getting increasingly frustrated that these reports were seemingly not getting any attention, and it's great to know it's being worked on.

Xyz00777 commented 2 years ago

Thanks for the information. You guys do a good job 👌 Wouldn't it be a good idea to make the exoplayer the default player for the moment? Because it's looks for me like it have less(/no known bugs?) bugs and reduce the amount of issues generating? And when it's fixed the setting could be set back to automatic.

nielsvanvelzen commented 2 years ago

Thanks for the suggestion @Xyz00777. We've discussed this today and agree that it might be better to use ExoPlayer as default until the playback rewrite is ready.

Relevant pull request: #1212

zeus86 commented 2 years ago

i have the exact same issue on a firetv-cube. interestingly not even after 5 minutes, but rather after 1-2 minutes. I am pretty sure, it has something to do with audio-passthrough. as soon as i switch to "direct audio" (no downmixing), and toggle the setting for "dts capable hardware", the issue went away. one sidenote is, that dts-hd-streams (i wish, jellyfin would show and mark the streams correctly in the firetv app, they are all shown equaly) are muted. altough i have a dts-hd-capable av-receiver, the cube is currently connected directly to the tv, and because the tv lacks ARC-support, i feed the audio back to the AV via toslink/spdif. as far as i know, toslink is not capable of transferring hd-audio formats, only plain dts and dd. maybe this issue would be partly solved, when i get rid of the toslink-line.

...maybe this helps abit to narrow the issue down...

arunbabucode commented 2 years ago

Have the same issue on firetv stick. Interestingly, happens on exoplayer as well. Though the occurrence is not every five minutes, but random.

Behaviors noticed.

  1. Randomly stops the streams, however, can press resume and continue from where it stopped. No matter which player is used, (exoplayer and libVLC)
  2. Randomly stops the streams, resetting the playback progress for the user to zero, and needs to start from the beginning.

Jellyfin version is 10.8-beta-3 (tried on 10.7 and 2 betas of 10.8)

Couldn’t be reproduced in iOS or web version with the same streams.

The only log I found is to the Progress endpoint with response code 204.

Additional info: Can confirm the websockets working properly in web version.

genetus commented 2 years ago

I dunno if it helps, but I have this log on my server (Jellyfin docker 10.8):

[2022-01-02 01:30:26.808 +03:00] [INF] [28] Emby.Server.Implementations.Session.SessionManager: Playback stopped reported by app "Android TV" "0.12.3" playing "Эпизод 1". Stopped at "7492" ms
[2022-01-02 01:30:40.751 +03:00] [INF] [29] Emby.Server.Implementations.HttpServer.WebSocketManager: WS "5.18.235.253" request
[2022-01-02 01:30:45.744 +03:00] [INF] [25] Emby.Server.Implementations.HttpServer.WebSocketManager: WS "5.18.235.253" request
[2022-01-02 01:31:28.930 +03:00] [INF] [22] Emby.Server.Implementations.Session.SessionWebSocketListener: Sending ForceKeepAlive message to 1 inactive WebSockets.
[2022-01-02 01:31:40.927 +03:00] [INF] [30] Emby.Server.Implementations.Session.SessionWebSocketListener: Lost 1 WebSockets.
[2022-01-02 01:35:59.234 +03:00] [INF] [42] Jellyfin.Api.Helpers.TranscodingJobHelper: FFmpeg exited with code 0
[2022-01-02 01:36:57.996 +03:00] [INF] [39] Jellyfin.Api.Helpers.TranscodingJobHelper: Deleting partial stream file(s) "/config/transcodes/6ccc59f2b3ad3567f8e0a932eb986ee7.mkv"
[2022-01-02 01:36:59.745 +03:00] [INF] [42] Emby.Server.Implementations.Session.SessionManager: Playback stopped reported by app "Android TV" "0.12.3" playing "Эпизод 1". Stopped at "0" ms
[2022-01-02 01:37:00.107 +03:00] [INF] [44] Emby.Server.Implementations.HttpServer.WebSocketManager: WS "5.18.235.253" closed
[2022-01-02 01:37:00.760 +03:00] [INF] [44] Emby.Server.Implementations.HttpServer.WebSocketManager: WS "5.18.235.253" request

It seems when an entire video was transcoded it lost any connection to android tv app and remove transcoded file.

Also, I tried to play another video. No transcoding, just playback directly to android TV and got this error log:

[2022-01-02 02:11:59.572 +03:00] [WRN] [54] Emby.Server.Implementations.HttpServer.WebSocketConnection: WS "5.18.235.253" error receiving data: "The remote party closed the WebSocket connection without completing the close handshake."
[2022-01-02 02:11:59.615 +03:00] [INF] [54] Emby.Server.Implementations.HttpServer.WebSocketManager: WS "5.18.235.253" closed
[2022-01-02 02:12:02.560 +03:00] [INF] [31] Emby.Server.Implementations.HttpServer.WebSocketManager: WS "5.18.235.253" request

All of it reproduce on last Android TV beta APP and web client just work normal with both video files.

krutburken commented 2 years ago

It's definitely related to transcoding. Ever since I've started to optimize my media for directplay (audio, video, subtitles), this problem has completely gone away.

Sundown89 commented 2 years ago

With and without transcoding the same happens here on Shield. Similar error log to @genetus

Artiume commented 2 years ago

Direct Play should behave as normal. In this situation, transcoding means FFMpeg being involved to allow for Remuxing, Direct Steaming or video transcoding. If there's ffmpeg logs being generated, it's going to be impacted by this bug.

robingroppe commented 2 years ago

I just switched over from Emby. And I am also affected by this on a AndroidTV and a FireTV Stick. Any updates on this issue?

krutburken commented 2 years ago

@robingroppe You can try a build from the latest master. Don't know when it's supposed to be released but this problem seems to have been fixed there

everlanes commented 2 years ago

I had problems with crashing movies (VP9 encoded, different resolutions) on a FireTV Stick as well. Today I upgraded to v0.13.0-beta.1 (uninstalled old version and installed beta) and tested some of the problematic movies. I can report that these movies are playing fine now. I will do some more real live testing with my family in the next weeks. For the the moment it looks promising. At least my problems seem to be fixed.

Thanks for the good work.

robingroppe commented 2 years ago

@krutburken thank you. It's usable now.

DpunktKpunkt commented 2 years ago

Same issue here.

Fire TV Stick (0.12.3) <-- internet --> nginx / ssl as reverse proxy --> jellyfin @ docker (10.7.7 / 10.8.0 beta5)

Fire TV crashes / restarts Jellyfin App. Transcoded and direct playback are affected.

I then tested with a second, http only reverse proxy (same nginx server/location config as ssl just without the ssl specific parts). This seems to work, no crashes at Fire TV sticks so far, but ssl is preferred - obviously.

Maybe a websocket issue when Jellyfin is used at Fire TV sticks over ssl + nginx reverse proxy? Other clients (LG TVs, Browser access (Firefox, Chrome) work without any issue with ssl connection.

mueslimak3r commented 2 years ago

@DpunktKpunkt this issue seems to be resolved in the beta (0.13). The Amazon app store doesn't have a beta program but you can side-load the APK available in the releases page of this repo

arunbabucode commented 2 years ago

The issue persists.

Jellyfin Android Firetv version: 0.13 beta Server version: 10.8-beta-3 Player: exoplayer and libVLC Type: Both transcoded and direct play

mueslimak3r commented 2 years ago

The issue persists.

Jellyfin Android Firetv version: 0.13 beta Server version: 10.8-beta-3 Player: exoplayer and libVLC Type: Both transcoded and direct play

Can you side-load the debug version of the beta and collect some logs using adb logcat?

DpunktKpunkt commented 2 years ago

At least my problem (ssl + nginx as reverse proxy with jellyfin 10.8.0 alpha5 @ docker) is resolved with v0.13.0-beta.1. Fire TV Stick (Lite) doesn't crash and restart Jellyfin any longer, both transcoded and direct play work.

robingroppe commented 2 years ago

Issue is fixed for me as well with the beta. Similar setup, Nginx Proxy Manager + SSL. Tested FireTV and AndroidTV.

Y0ngg4n commented 2 years ago

Same issue here. Using Traefik and Android TV

mueslimak3r commented 2 years ago

Same issue here. Using Traefik and Android TV

Are you using the latest beta?

Y0ngg4n commented 2 years ago

@mueslimak3r the beta fixed it for me. Maybe we should make a release because jellyfin is unusable on androidtv with this bug.

thornbill commented 2 years ago

A 0.13 release is planned "soon" which is why there are currently beta releases available for testing. 😉

Y0ngg4n commented 2 years ago

@thornbill ok that sounds good :)

cirdanmiriel commented 2 years ago

That's great to see that u guys took the time to fix this, I might test the beta version if I can, if not I'll wait for the release :+1:

ringus1 commented 2 years ago

Still happening for me on master (both VLC and Exo):


2022-02-21 18:53:25.201 19086-19086/org.jellyfin.androidtv.debug I/jellyfin-apiclient: Response received from: https://video.mydomain.tld/Sessions/Playing/Progress
2022-02-21 18:53:27.301 5305-6129/? I/chromium: [5305:6129:INFO:snr_tracker.cc(50)] snr = 39
2022-02-21 18:53:28.137 19086-19086/org.jellyfin.androidtv.debug D/jellyfin-apiclient: Adding request to queue: https://video.mydomain.tld/Sessions/Playing/Progress
2022-02-21 18:53:28.258 19086-19086/org.jellyfin.androidtv.debug I/jellyfin-apiclient: Response received from: https://video.mydomain.tld/Sessions/Playing/Progress
2022-02-21 18:53:28.419 3533-3533/? E/health2: /sys/block/sda/stat: ReadFileToString failed.
2022-02-21 18:53:31.140 19086-19086/org.jellyfin.androidtv.debug D/jellyfin-apiclient: Adding request to queue: https://video.mydomain.tld/Sessions/Playing/Progress
2022-02-21 18:53:31.220 19086-23179/org.jellyfin.androidtv.debug E/VLC: [b75a2530/5a8b] libvlc decoder: Decoder is draining
2022-02-21 18:53:31.221 19086-19086/org.jellyfin.androidtv.debug I/jellyfin-apiclient: Response received from: https://video.mydomain.tld/Sessions/Playing/Progress
2022-02-21 18:53:31.260 19086-23179/org.jellyfin.androidtv.debug W/VLC: [b75a2530/5a8b] libvlc decoder: EOS sent, waiting for OutThread
2022-02-21 18:53:31.381 3711-23184/? D/AmlogicVideoDecoderAwesome: mInputTimeStampChanged = true,mLastInputTimeStamp=85314,bufferHdr.nTimeStamp=0
2022-02-21 18:53:31.381 3711-23184/? I/amcodec: codec_set_eos is_eos =1
2022-02-21 18:53:31.381 3711-23184/? D/AmlogicVideoDecoderAwesome: set eos to decoder
2022-02-21 18:53:31.381 3711-23184/? D/AmlogicVideoDecoderAwesome:      ===mEosStamp 0 ==
2022-02-21 18:53:31.383 3711-23183/? D/AmlogicVideoDecoderAwesome: mEosCheckCount=0, mInPutFrameCount=2046, mOutBufferNo=2023, mMaxInputTimeStamp=85314001, mLastTimeStamp=84355001
2022-02-21 18:53:32.382 3711-23183/? D/AmlogicVideoDecoderAwesome:                mEos = true
2022-02-21 18:53:32.382 3711-23183/? D/AmlogicVideoDecoderAwesome: mEosCheckCount=0, mInPutFrameCount=2046, mOutBufferNo=2046, mMaxInputTimeStamp=85314001, mLastTimeStamp=85314001
2022-02-21 18:53:32.383 3711-23183/? D/AmlogicVideoDecoderAwesome: displayThread___eos_fillBufferDone
2022-02-21 18:53:32.383 3711-23183/? D/AmlogicVideoDecoderAwesome: threadLoop is_running == false
2022-02-21 18:53:32.385 19086-23178/org.jellyfin.androidtv.debug W/VLC: [b75a2530/5a8a] libvlc decoder: EOS received
2022-02-21 18:53:32.502 19086-23173/org.jellyfin.androidtv.debug W/VLC: [c0476630/5a85] libvlc video output: picture is too late to be displayed (missing 292 ms)
2022-02-21 18:53:32.561 19086-23182/org.jellyfin.androidtv.debug D/AudioTrack: stop(59): called with 4101120 frames delivered
2022-02-21 18:53:32.610 19086-19086/org.jellyfin.androidtv.debug D/PlaybackController: On Completion fired
2022-02-21 18:53:32.611 19086-23178/org.jellyfin.androidtv.debug E/NdkMediaCodec: sf error code: -38
2022-02-21 18:53:32.611 19086-23178/org.jellyfin.androidtv.debug W/VLC: [b75a2530/5a8a] libvlc decoder: AMediaCodec.dequeueOutputBuffer failed
2022-02-21 18:53:32.612 3711-23176/? I/OmxComponent: OMX_CommandFlush 806 Cmd 0x1 nParam1 0xffffffff
2022-02-21 18:53:32.612 3711-23176/? I/OmxComponent: OMX.amlogic.hevc.decoder.awesome2: flush input
2022-02-21 18:53:32.613 3711-23176/? V/AmlogicVideoDecoderAwesome: flushInput:1036 >
2022-02-21 18:53:32.613 3711-23176/? V/OMX_WorkerPeer: vendor/omx/omx_framework/WorkerPeer.cpp:flushInput:56 --------------------
2022-02-21 18:53:32.613 3711-23176/? V/AmlogicVideoDecoderAwesome: pause:313 >
2022-02-21 18:53:32.613 3711-23176/? D/AmlogicVideoDecoderAwesome: mVideo mDisplayTread stop
2022-02-21 18:53:32.613 3711-23176/? V/AmlogicVideoDecoderAwesome: reset:384 >
2022-02-21 18:53:32.613 3711-23176/? D/AmlogicVideoDecoderAwesome: reset_1
2022-02-21 18:53:32.613 3711-23176/? I/amcodec: AMSTREAM_SET_OMX_RUNNING ret=0
2022-02-21 18:53:32.614 19086-19086/org.jellyfin.androidtv.debug I/jellyfin-apiclient: ReportPlaybackStopped: Item f9554ec914876a0cb1433b96ae6bb892, Ticks: 23476910000
2022-02-21 18:53:32.617 19086-19086/org.jellyfin.androidtv.debug D/jellyfin-apiclient: Adding request to queue: https://video.mydomain.tld/Sessions/Playing/Stopped```
mueslimak3r commented 2 years ago

Still happening for me on master (both VLC and Exo):

2022-02-21 18:53:25.201 19086-19086/org.jellyfin.androidtv.debug I/jellyfin-apiclient: Response received from: https://video.mydomain.tld/Sessions/Playing/Progress
2022-02-21 18:53:27.301 5305-6129/? I/chromium: [5305:6129:INFO:snr_tracker.cc(50)] snr = 39
2022-02-21 18:53:28.137 19086-19086/org.jellyfin.androidtv.debug D/jellyfin-apiclient: Adding request to queue: https://video.mydomain.tld/Sessions/Playing/Progress
2022-02-21 18:53:28.258 19086-19086/org.jellyfin.androidtv.debug I/jellyfin-apiclient: Response received from: https://video.mydomain.tld/Sessions/Playing/Progress
2022-02-21 18:53:28.419 3533-3533/? E/health2: /sys/block/sda/stat: ReadFileToString failed.
2022-02-21 18:53:31.140 19086-19086/org.jellyfin.androidtv.debug D/jellyfin-apiclient: Adding request to queue: https://video.mydomain.tld/Sessions/Playing/Progress
2022-02-21 18:53:31.220 19086-23179/org.jellyfin.androidtv.debug E/VLC: [b75a2530/5a8b] libvlc decoder: Decoder is draining
2022-02-21 18:53:31.221 19086-19086/org.jellyfin.androidtv.debug I/jellyfin-apiclient: Response received from: https://video.mydomain.tld/Sessions/Playing/Progress
2022-02-21 18:53:31.260 19086-23179/org.jellyfin.androidtv.debug W/VLC: [b75a2530/5a8b] libvlc decoder: EOS sent, waiting for OutThread
2022-02-21 18:53:31.381 3711-23184/? D/AmlogicVideoDecoderAwesome: mInputTimeStampChanged = true,mLastInputTimeStamp=85314,bufferHdr.nTimeStamp=0
2022-02-21 18:53:31.381 3711-23184/? I/amcodec: codec_set_eos is_eos =1
2022-02-21 18:53:31.381 3711-23184/? D/AmlogicVideoDecoderAwesome: set eos to decoder
2022-02-21 18:53:31.381 3711-23184/? D/AmlogicVideoDecoderAwesome:      ===mEosStamp 0 ==
2022-02-21 18:53:31.383 3711-23183/? D/AmlogicVideoDecoderAwesome: mEosCheckCount=0, mInPutFrameCount=2046, mOutBufferNo=2023, mMaxInputTimeStamp=85314001, mLastTimeStamp=84355001
2022-02-21 18:53:32.382 3711-23183/? D/AmlogicVideoDecoderAwesome:                mEos = true
2022-02-21 18:53:32.382 3711-23183/? D/AmlogicVideoDecoderAwesome: mEosCheckCount=0, mInPutFrameCount=2046, mOutBufferNo=2046, mMaxInputTimeStamp=85314001, mLastTimeStamp=85314001
2022-02-21 18:53:32.383 3711-23183/? D/AmlogicVideoDecoderAwesome: displayThread___eos_fillBufferDone
2022-02-21 18:53:32.383 3711-23183/? D/AmlogicVideoDecoderAwesome: threadLoop is_running == false
2022-02-21 18:53:32.385 19086-23178/org.jellyfin.androidtv.debug W/VLC: [b75a2530/5a8a] libvlc decoder: EOS received
2022-02-21 18:53:32.502 19086-23173/org.jellyfin.androidtv.debug W/VLC: [c0476630/5a85] libvlc video output: picture is too late to be displayed (missing 292 ms)
2022-02-21 18:53:32.561 19086-23182/org.jellyfin.androidtv.debug D/AudioTrack: stop(59): called with 4101120 frames delivered
2022-02-21 18:53:32.610 19086-19086/org.jellyfin.androidtv.debug D/PlaybackController: On Completion fired
2022-02-21 18:53:32.611 19086-23178/org.jellyfin.androidtv.debug E/NdkMediaCodec: sf error code: -38
2022-02-21 18:53:32.611 19086-23178/org.jellyfin.androidtv.debug W/VLC: [b75a2530/5a8a] libvlc decoder: AMediaCodec.dequeueOutputBuffer failed
2022-02-21 18:53:32.612 3711-23176/? I/OmxComponent: OMX_CommandFlush 806 Cmd 0x1 nParam1 0xffffffff
2022-02-21 18:53:32.612 3711-23176/? I/OmxComponent: OMX.amlogic.hevc.decoder.awesome2: flush input
2022-02-21 18:53:32.613 3711-23176/? V/AmlogicVideoDecoderAwesome: flushInput:1036 >
2022-02-21 18:53:32.613 3711-23176/? V/OMX_WorkerPeer: vendor/omx/omx_framework/WorkerPeer.cpp:flushInput:56 --------------------
2022-02-21 18:53:32.613 3711-23176/? V/AmlogicVideoDecoderAwesome: pause:313 >
2022-02-21 18:53:32.613 3711-23176/? D/AmlogicVideoDecoderAwesome: mVideo mDisplayTread stop
2022-02-21 18:53:32.613 3711-23176/? V/AmlogicVideoDecoderAwesome: reset:384 >
2022-02-21 18:53:32.613 3711-23176/? D/AmlogicVideoDecoderAwesome: reset_1
2022-02-21 18:53:32.613 3711-23176/? I/amcodec: AMSTREAM_SET_OMX_RUNNING ret=0
2022-02-21 18:53:32.614 19086-19086/org.jellyfin.androidtv.debug I/jellyfin-apiclient: ReportPlaybackStopped: Item f9554ec914876a0cb1433b96ae6bb892, Ticks: 23476910000
2022-02-21 18:53:32.617 19086-19086/org.jellyfin.androidtv.debug D/jellyfin-apiclient: Adding request to queue: https://video.mydomain.tld/Sessions/Playing/Stopped```

please provide the full log from that session

ringus1 commented 2 years ago

Still happening for me on master (both VLC and Exo):

2022-02-21 18:53:25.201 19086-19086/org.jellyfin.androidtv.debug I/jellyfin-apiclient: Response received from: https://video.mydomain.tld/Sessions/Playing/Progress
2022-02-21 18:53:27.301 5305-6129/? I/chromium: [5305:6129:INFO:snr_tracker.cc(50)] snr = 39
2022-02-21 18:53:28.137 19086-19086/org.jellyfin.androidtv.debug D/jellyfin-apiclient: Adding request to queue: https://video.mydomain.tld/Sessions/Playing/Progress
2022-02-21 18:53:28.258 19086-19086/org.jellyfin.androidtv.debug I/jellyfin-apiclient: Response received from: https://video.mydomain.tld/Sessions/Playing/Progress
2022-02-21 18:53:28.419 3533-3533/? E/health2: /sys/block/sda/stat: ReadFileToString failed.
2022-02-21 18:53:31.140 19086-19086/org.jellyfin.androidtv.debug D/jellyfin-apiclient: Adding request to queue: https://video.mydomain.tld/Sessions/Playing/Progress
2022-02-21 18:53:31.220 19086-23179/org.jellyfin.androidtv.debug E/VLC: [b75a2530/5a8b] libvlc decoder: Decoder is draining
2022-02-21 18:53:31.221 19086-19086/org.jellyfin.androidtv.debug I/jellyfin-apiclient: Response received from: https://video.mydomain.tld/Sessions/Playing/Progress
2022-02-21 18:53:31.260 19086-23179/org.jellyfin.androidtv.debug W/VLC: [b75a2530/5a8b] libvlc decoder: EOS sent, waiting for OutThread
2022-02-21 18:53:31.381 3711-23184/? D/AmlogicVideoDecoderAwesome: mInputTimeStampChanged = true,mLastInputTimeStamp=85314,bufferHdr.nTimeStamp=0
2022-02-21 18:53:31.381 3711-23184/? I/amcodec: codec_set_eos is_eos =1
2022-02-21 18:53:31.381 3711-23184/? D/AmlogicVideoDecoderAwesome: set eos to decoder
2022-02-21 18:53:31.381 3711-23184/? D/AmlogicVideoDecoderAwesome:      ===mEosStamp 0 ==
2022-02-21 18:53:31.383 3711-23183/? D/AmlogicVideoDecoderAwesome: mEosCheckCount=0, mInPutFrameCount=2046, mOutBufferNo=2023, mMaxInputTimeStamp=85314001, mLastTimeStamp=84355001
2022-02-21 18:53:32.382 3711-23183/? D/AmlogicVideoDecoderAwesome:                mEos = true
2022-02-21 18:53:32.382 3711-23183/? D/AmlogicVideoDecoderAwesome: mEosCheckCount=0, mInPutFrameCount=2046, mOutBufferNo=2046, mMaxInputTimeStamp=85314001, mLastTimeStamp=85314001
2022-02-21 18:53:32.383 3711-23183/? D/AmlogicVideoDecoderAwesome: displayThread___eos_fillBufferDone
2022-02-21 18:53:32.383 3711-23183/? D/AmlogicVideoDecoderAwesome: threadLoop is_running == false
2022-02-21 18:53:32.385 19086-23178/org.jellyfin.androidtv.debug W/VLC: [b75a2530/5a8a] libvlc decoder: EOS received
2022-02-21 18:53:32.502 19086-23173/org.jellyfin.androidtv.debug W/VLC: [c0476630/5a85] libvlc video output: picture is too late to be displayed (missing 292 ms)
2022-02-21 18:53:32.561 19086-23182/org.jellyfin.androidtv.debug D/AudioTrack: stop(59): called with 4101120 frames delivered
2022-02-21 18:53:32.610 19086-19086/org.jellyfin.androidtv.debug D/PlaybackController: On Completion fired
2022-02-21 18:53:32.611 19086-23178/org.jellyfin.androidtv.debug E/NdkMediaCodec: sf error code: -38
2022-02-21 18:53:32.611 19086-23178/org.jellyfin.androidtv.debug W/VLC: [b75a2530/5a8a] libvlc decoder: AMediaCodec.dequeueOutputBuffer failed
2022-02-21 18:53:32.612 3711-23176/? I/OmxComponent: OMX_CommandFlush 806 Cmd 0x1 nParam1 0xffffffff
2022-02-21 18:53:32.612 3711-23176/? I/OmxComponent: OMX.amlogic.hevc.decoder.awesome2: flush input
2022-02-21 18:53:32.613 3711-23176/? V/AmlogicVideoDecoderAwesome: flushInput:1036 >
2022-02-21 18:53:32.613 3711-23176/? V/OMX_WorkerPeer: vendor/omx/omx_framework/WorkerPeer.cpp:flushInput:56 --------------------
2022-02-21 18:53:32.613 3711-23176/? V/AmlogicVideoDecoderAwesome: pause:313 >
2022-02-21 18:53:32.613 3711-23176/? D/AmlogicVideoDecoderAwesome: mVideo mDisplayTread stop
2022-02-21 18:53:32.613 3711-23176/? V/AmlogicVideoDecoderAwesome: reset:384 >
2022-02-21 18:53:32.613 3711-23176/? D/AmlogicVideoDecoderAwesome: reset_1
2022-02-21 18:53:32.613 3711-23176/? I/amcodec: AMSTREAM_SET_OMX_RUNNING ret=0
2022-02-21 18:53:32.614 19086-19086/org.jellyfin.androidtv.debug I/jellyfin-apiclient: ReportPlaybackStopped: Item f9554ec914876a0cb1433b96ae6bb892, Ticks: 23476910000
2022-02-21 18:53:32.617 19086-19086/org.jellyfin.androidtv.debug D/jellyfin-apiclient: Adding request to queue: https://video.mydomain.tld/Sessions/Playing/Stopped```

please provide the full log from that session

Here you go: https://gist.github.com/ringus1/98eb97688918eedfeed27f6eff08dfc2 It doesn't crash the whole app though. Just stops playback as if I exited this particular video (giving me possibility to resume playback exactly where it stopped). Doesn't happen for all videos that are being transcoded though it seems too.

Using it on CCWGTV.

mueslimak3r commented 2 years ago

I see this in the log: libvlc demux: cannot find any cluster or chapter, damaged file ?

I wonder how you have your hardware acceleration settings configured on your server, and if perhaps that could be causing an issue.

Doesn't happen for all videos that are being transcoded though it seems too

I don't understand. Does it happen for just this video, some videos, or all videos? If just this video or some videos, is that only when it's transcoding?

Since this is happening with exoplayer too, can you record some logs of that?

Some details about the media you're playing would be helpful too. You can get that from ffprobe or from the jellyfin web ui

ringus1 commented 2 years ago

I'm using 10.8.0alpha with AMD VAAPI. Though, the output file from ffmpeg on server works perfectly fine with local VLC. No stops/incomplete conversion. Same video (with transcoding) works fine via WWW and Kodi.

It's the Jellyfin APK that reports stopping of playback:

[2022-02-22 17:08:45.607 +01:00] [INF] [15] Jellyfin.Api.Helpers.TranscodingJobHelper: "/usr/lib/jellyfin-ffmpeg/ffmpeg" "-ss 00:37:57.000 -init_hw_device vaapi=va:/dev/dri/renderD128 -filter_hw_device va -hwaccel vaapi -hwaccel_output_format vaapi -autorotate 0 -i file:\"/series/myvideo.mkv\" -map 0:0 -map 0:1 -map -0:s -codec:v:0 h264_vaapi -force_key_frames \"expr:gte(t,n_forced*5)\" -vf \"setparams=color_primaries=bt709:color_trc=bt709:colorspace=bt709,scale_vaapi=format=nv12\" -copyts -avoid_negative_ts disabled -start_at_zero -rc_mode VBR -b:v 4616000 -maxrate 4616000 -bufsize 9232000 -profile:v:0 high -map_metadata -1 -map_chapters -1 -threads 0 -codec:a:0 aac -ac 6 -ab 384000 -y \"/config/transcodes/91d6af4207aa1632927c7fbed7e10efc.mkv\""
[2022-02-22 17:08:46.718 +01:00] [WRN] [151] Jellyfin.Server.Middleware.ResponseTimeMiddleware: Slow HTTP Response from "http://192.168.1.35:8096/videos/f9554ec9-1487-6a0c-b143-3b96ae6bb892/stream.mkv?DeviceId=e940701c219647dcbbd675ac9bc71b3524e29d79&MediaSourceId=f9554ec914876a0cb1433b96ae6bb892&VideoCodec=h264&AudioCodec=aac,mp3&AudioStreamIndex=1&VideoBitrate=4616000&AudioBitrate=384000&StartTimeTicks=22770000000&PlaySessionId=f3388ff3146b489c88d104e83471c70b&api_key=18334f457021449a8c3daf4e09f33fc0&CopyTimestamps=true&RequireAvc=false&Tag=ccd15b76315feff720619c62bf847b65&h264-profile=high,main,baseline,constrainedbaseline&h264-level=51&aac-audiochannels=8&mp3-audiochannels=8&TranscodeReasons=ContainerBitrateExceedsLimit&allowVideoStreamCopy=false&allowAudioStreamCopy=false&allowAudioStreamCopy=false" to "192.168.1.60" in 0:00:01.1152535 with Status Code 200
[2022-02-22 17:09:04.937 +01:00] [INF] [151] Jellyfin.Api.Helpers.TranscodingJobHelper: FFmpeg exited with code 0
[2022-02-22 17:09:39.414 +01:00] [INF] [68] Jellyfin.Api.Helpers.TranscodingJobHelper: Deleting partial stream file(s) "/config/transcodes/91d6af4207aa1632927c7fbed7e10efc.mkv"
[2022-02-22 17:09:40.933 +01:00] [INF] [193] Emby.Server.Implementations.Session.SessionManager: Playback stopped reported by app "Android TV" "0.0.0-dev.1" playing "Odcinek 16". Stopped at "2326924" ms
[2022-02-22 17:09:40.990 +01:00] [WRN] [193] Jellyfin.Server.Middleware.ResponseTimeMiddleware: Slow HTTP Response from "http://192.168.1.35:8096/Sessions/Playing/Stopped" to "192.168.1.60" in 0:00:01.578605 with Status Code 204

This issue occurs for some transcoded videos. Direct play works fine with every file that's elligible for it.

Some details about the media you're playing would be helpful too. You can get that from ffprobe or from the jellyfin web ui

I've found at least 2 very different files with this issue, here is one:

SOURCE FILE

Input #0, matroska,webm, from 'myvideo.mkv':
  Metadata:
    encoder         : libebml v1.2.0 + libmatroska v1.1.0
    creation_time   : 2011-02-25T22:48:04.000000Z
  Duration: 00:42:20.96, start: 0.000000, bitrate: 4667 kb/s
    Stream #0:0(eng): Video: h264 (High), yuv420p(tv, bt709, progressive), 1280x720 [SAR 1:1 DAR 16:9], 23.98 fps, 23.98 tbr, 1k tbn, 2k tbc (default)
    Metadata:
      title           : Myvideo, Episode 16: A
    Stream #0:1(eng): Audio: ac3, 48000 Hz, 5.1(side), fltp, 384 kb/s (default)
    Metadata:
      title           : Dolby Digital 5.1 @ 384 kbps

OUTPUT FILE

Input #0, matroska,webm, from '91d6af4207aa1632927c7fbed7e10efc.mkv':
  Metadata:
    ENCODER         : Lavf58.76.100
  Duration: 00:42:20.96, start: 2129.979000, bitrate: 765 kb/s
    Stream #0:0: Video: h264 (High), yuv420p(tv, bt709, progressive), 1280x720, SAR 1:1 DAR 16:9, 23.98 fps, 23.98 tbr, 1k tbn, 2k tbc (default)
    Metadata:
      ENCODER         : Lavc58.134.100 h264_vaapi
      DURATION        : 00:42:20.958000000
    Stream #0:1: Audio: aac (LC), 48000 Hz, 5.1, fltp (default)
    Metadata:
      ENCODER         : Lavc58.134.100 aac
      DURATION        : 00:42:20.960000000

I'll add also logs from Exoplayer soon.

ringus1 commented 2 years ago

Oddly, I can't replicate that with Exo now. Seems I might have had some cached dependencies or something when building from master previously. ExoPlayer seems to be playing those faulty files with no issues now. Problem looks to be limited to VLC which uses stream.mkv way (though, as mentioned only for some videos) unlike Exo fMP4-HLS / HLS (working both with HEVC and H264 encoding).