Playback crashes when resuming after pausing video

[aanderse]

Describe the bug

Playback suddenly stops several moments after resuming from pause.

To Reproduce

1. Play any movie or tv show
2. Press pause and wait ~1-2 minutes
3. Press play to resume the video
4. Wait ~15 seconds and observe that the video stops

I am able to reproduce this across 3 different HTPCs running kodi which connected to my single jellyfin server (through an apache2 reverse proxy using SSL).

Expected behavior

Video will not unexpectedly stop after resuming from pause

Logs

kodi logs:

2021-10-21 22:33:35.237 T:62291    INFO <general>: PulseAudio: Opened device Default in pcm mode with Buffersize 150 ms Periodsize 50 ms
2021-10-21 22:33:35.740 T:62257 WARNING <general>: CGUIWindowManager - HandleAction - ignoring action 107, because topmost modal dialog closing animation is running
2021-10-21 22:34:16.899 T:62491   ERROR <general>: CCurlFile::FillBuffer - Failed: Stream error in the HTTP/2 framing layer(92)
2021-10-21 22:34:16.899 T:62491 WARNING <general>: CFileCache::Process - <https://jellyfin.example.net/Videos/fa3266645d905ca0d95bf6ec55e495e2/stream?static=true&MediaSourceId=fa3266645d905ca0d95bf6ec55e495e2&api_key=0f18b73171ba4da99d8b8b269f588290> source read returned -1! Will retry
2021-10-21 22:34:18.899 T:62491 WARNING <general>: CFileCache::Process - <https://jellyfin.example.net/Videos/fa3266645d905ca0d95bf6ec55e495e2/stream?static=true&MediaSourceId=fa3266645d905ca0d95bf6ec55e495e2&api_key=0f18b73171ba4da99d8b8b269f588290> source read returned 0! Will retry
2021-10-21 22:34:28.900 T:62491    INFO <general>: Skipped 4 duplicate messages..
2021-10-21 22:34:28.900 T:62491 WARNING <general>: CFileCache::Process - <https://jellyfin.example.net/Videos/fa3266645d905ca0d95bf6ec55e495e2/stream?static=true&MediaSourceId=fa3266645d905ca0d95bf6ec55e495e2&api_key=0f18b73171ba4da99d8b8b269f588290> source read returned 0! Will retry
2021-10-21 22:34:38.901 T:62491    INFO <general>: Skipped 4 duplicate messages..
2021-10-21 22:34:38.901 T:62491 WARNING <general>: CFileCache::Process - <https://jellyfin.example.net/Videos/fa3266645d905ca0d95bf6ec55e495e2/stream?static=true&MediaSourceId=fa3266645d905ca0d95bf6ec55e495e2&api_key=0f18b73171ba4da99d8b8b269f588290> source read returned 0! Will retry
2021-10-21 22:34:48.902 T:62491    INFO <general>: Skipped 4 duplicate messages..
2021-10-21 22:34:48.902 T:62491 WARNING <general>: CFileCache::Process - <https://jellyfin.example.net/Videos/fa3266645d905ca0d95bf6ec55e495e2/stream?static=true&MediaSourceId=fa3266645d905ca0d95bf6ec55e495e2&api_key=0f18b73171ba4da99d8b8b269f588290> source read returned 0! Will retry
2021-10-21 22:34:58.903 T:62491    INFO <general>: Skipped 4 duplicate messages..
2021-10-21 22:34:58.903 T:62491 WARNING <general>: CFileCache::Process - <https://jellyfin.example.net/Videos/fa3266645d905ca0d95bf6ec55e495e2/stream?static=true&MediaSourceId=fa3266645d905ca0d95bf6ec55e495e2&api_key=0f18b73171ba4da99d8b8b269f588290> source read returned 0! Will retry
2021-10-21 22:35:04.903 T:62491    INFO <general>: Skipped 2 duplicate messages..
2021-10-21 22:35:04.903 T:62491   ERROR <general>: CFileCache::Process - <https://jellyfin.example.net/Videos/fa3266645d905ca0d95bf6ec55e495e2/stream?static=true&MediaSourceId=fa3266645d905ca0d95bf6ec55e495e2&api_key=0f18b73171ba4da99d8b8b269f588290> source read didn't return any data before eof!
2021-10-21 22:35:11.727 T:62490    INFO <general>: Process - eof reading from demuxer
2021-10-21 22:35:11.727 T:62490    INFO <general>: CVideoPlayer::OnExit()
2021-10-21 22:35:11.727 T:62490    INFO <general>: VideoPlayer: eof, waiting for queues to empty
2021-10-21 22:35:11.728 T:62490    INFO <general>: Closing stream player 1
2021-10-21 22:35:11.728 T:62490    INFO <general>: CDVDMessageQueue(audio)::WaitUntilEmpty
2021-10-21 22:35:11.728 T:62490    INFO <general>: Waiting for audio thread to exit
2021-10-21 22:35:11.728 T:62493   ERROR <general>: Got MSGQ_ABORT or MSGO_IS_ERROR return true
2021-10-21 22:35:11.728 T:62493    INFO <general>: thread end: CVideoPlayerAudio::OnExit()
2021-10-21 22:35:11.728 T:62490    INFO <general>: Closing audio device
2021-10-21 22:35:11.995 T:62490    INFO <general>: Deleting audio codec
2021-10-21 22:35:11.995 T:62490    INFO <general>: Closing stream player 2
2021-10-21 22:35:11.995 T:62490    INFO <general>: CDVDMessageQueue(video)::WaitUntilEmpty
2021-10-21 22:35:11.995 T:62490    INFO <general>: waiting for video thread to exit
2021-10-21 22:35:11.995 T:62492   ERROR <general>: Got MSGQ_ABORT or MSGO_IS_ERROR return true
2021-10-21 22:35:11.995 T:62492    INFO <general>: thread end: video_thread
2021-10-21 22:35:11.995 T:62490    INFO <general>: deleting video codec
2021-10-21 22:35:11.998 T:62490    INFO <general>: Closing stream player 3
2021-10-21 22:35:12.053 T:62257    INFO <general>: CVideoPlayer::CloseFile()
2021-10-21 22:35:12.059 T:62257    INFO <general>: VideoPlayer: waiting for threads to exit
2021-10-21 22:35:12.059 T:62257    INFO <general>: VideoPlayer: finished waiting
2021-10-21 22:35:12.059 T:62257    INFO <general>: CVideoPlayer::CloseFile()
2021-10-21 22:35:12.059 T:62257    INFO <general>: VideoPlayer: waiting for threads to exit
2021-10-21 22:35:12.059 T:62257    INFO <general>: VideoPlayer: finished waiting
2021-10-21 22:35:12.081 T:65858    INFO <general>: initializing python engine.

jellyfin logs:

Oct 21 22:35:12 entakun jellyfin[2440]: [22:35:12] [INF] [19] Emby.Server.Implementations.Session.SessionManager: Playback stopped reported by app Kodi 0.7.1+py3 playing Dune. Stopped at 217000 ms
Oct 21 22:35:12 entakun jellyfin[2440]: [22:35:12] [INF] [41] Jellyfin.Plugin.KodiSyncQueue.EntryPoints.UserSyncNotification: Starting User Changes Sync...
Oct 21 22:35:12 entakun jellyfin[2440]: [22:35:12] [INF] [41] Jellyfin.Plugin.KodiSyncQueue.EntryPoints.UserSyncNotification: "USERSYNC" User ee32da836e4c469d864a2119c2bc3c7b(jellyfin) posted 2 Updates: fa3266645d905ca0d95bf6ec55e495e2,a227f5bf54bf8628693c66ded52bb977
Oct 21 22:35:12 entakun jellyfin[2440]: [22:35:12] [INF] [41] Jellyfin.Plugin.KodiSyncQueue.EntryPoints.UserSyncNotification: User Changes Sync Finished Taking 00:00:00.0195729

apache logs:

192.168.0.106 - - [21/Oct/2021:22:28:54 -0400] "POST /Sessions/Playing/Progress HTTP/1.1" 204 -
192.168.0.106 - - [21/Oct/2021:22:30:49 -0400] "POST /Sessions/Playing/Progress HTTP/1.1" 204 -
192.168.0.106 - - [21/Oct/2021:22:27:52 -0400] "GET /Videos/fa3266645d905ca0d95bf6ec55e495e2/stream?static=true&MediaSourceId=fa3266645d905ca0d95bf6ec55e495e2&api_key=0f18b73171ba4da99d8b8b269f588290 HTTP/2.0" 206 47464448
192.168.0.106 - - [21/Oct/2021:22:31:57 -0400] "POST /Sessions/Playing/Progress HTTP/1.1" 204 -
192.168.0.106 - - [21/Oct/2021:22:33:35 -0400] "POST /Sessions/Playing/Progress HTTP/1.1" 204 -
192.168.0.106 - - [21/Oct/2021:22:35:12 -0400] "POST /Sessions/Playing/Stopped HTTP/1.1" 204 -
192.168.0.106 - - [21/Oct/2021:22:35:12 -0400] "GET /Users/ee32da836e4c469d864a2119c2bc3c7b/Items/fa3266645d905ca0d95bf6ec55e495e2 HTTP/1.1" 200 6048
192.168.0.114 - - [21/Oct/2021:22:35:14 -0400] "GET /Users/ee32da836e4c469d864a2119c2bc3c7b/Items?Ids=fa3266645d905ca0d95bf6ec55e495e2%2Ca227f5bf54bf8628693c66ded52bb977&Fields=Path%2CGenres%2CSortName%2CStudios%2CWriter%2CTaglines%2CLocalTrailerCount%2COfficialRating%2CCumulativeRunTimeTicks%2CItemCounts%2CMetascore%2CAirTime%2CDateCreated%2CPeople%2COverview%2CCriticRating%2CCriticRatingSummary%2CEtag%2CShortOverview%2CProductionLocations%2CTags%2CProviderIds%2CParentId%2CRemoteTrailers%2CSpecialEpisodeNumbers%2CMediaSources%2CVoteCount%2CRecursiveItemCount%2CPrimaryImageAspectRatio HTTP/1.1" 200 5755
192.168.0.151 - - [21/Oct/2021:22:35:14 -0400] "GET /Users/ee32da836e4c469d864a2119c2bc3c7b/Items?Ids=fa3266645d905ca0d95bf6ec55e495e2%2Ca227f5bf54bf8628693c66ded52bb977&Fields=Path%2CGenres%2CSortName%2CStudios%2CWriter%2CTaglines%2CLocalTrailerCount%2COfficialRating%2CCumulativeRunTimeTicks%2CItemCounts%2CMetascore%2CAirTime%2CDateCreated%2CPeople%2COverview%2CCriticRating%2CCriticRatingSummary%2CEtag%2CShortOverview%2CProductionLocations%2CTags%2CProviderIds%2CParentId%2CRemoteTrailers%2CSpecialEpisodeNumbers%2CMediaSources%2CVoteCount%2CRecursiveItemCount%2CPrimaryImageAspectRatio HTTP/1.1" 200 5755
192.168.0.106 - - [21/Oct/2021:22:35:17 -0400] "GET /Users/ee32da836e4c469d864a2119c2bc3c7b/Items?Ids=fa3266645d905ca0d95bf6ec55e495e2%2Ca227f5bf54bf8628693c66ded52bb977&Fields=Path%2CGenres%2CSortName%2CStudios%2CWriter%2CTaglines%2CLocalTrailerCount%2COfficialRating%2CCumulativeRunTimeTicks%2CItemCounts%2CMetascore%2CAirTime%2CDateCreated%2CPeople%2COverview%2CCriticRating%2CCriticRatingSummary%2CEtag%2CShortOverview%2CProductionLocations%2CTags%2CProviderIds%2CParentId%2CRemoteTrailers%2CSpecialEpisodeNumbers%2CMediaSources%2CVoteCount%2CRecursiveItemCount%2CPrimaryImageAspectRatio HTTP/1.1" 200 5755

Screenshots

System (please complete the following information):

• OS: Linux (NixOS)
• Jellyfin Version: 10.7.5
• Kodi Version: 19.1
• Addon Version: 0.7.1-py3
• Playback Mode: Add-On

Additional context

Jellyfin is sitting behind an Apache 2 reverse proxy with a SSL certificate provisioned by Let's Encrypt on the local network. I am able to reproduce this as often as needed, so please let me know any additional details/logs that would be helpful in troubleshooting this issue.

Similar issues

• https://github.com/jellyfin/jellyfin-kodi/issues/466
• https://github.com/jellyfin/jellyfin/issues/4479

[zotanmew]

I am facing the same issue.

Logs:

2021-10-27 17:34:06.540 T:2004    ERROR <general>: CCurlFile::CReadState::FillBuffer - (0x7f2bd0ecb2e0) Failed: Stream error in the HTTP/2 framing layer(92)
2021-10-27 17:34:06.540 T:2004  WARNING <general>: CFileCache::Process - <https://stream.redacted.net/Videos/ae8dcca3b4696ef27285064533927187/stream?static=true&MediaSourceId=ae8dcca3b4696ef27285064533927187&api_key=redacted> source read returned -1! Will retry
2021-10-27 17:34:08.540 T:2004  WARNING <general>: CFileCache::Process - <https://stream.redacted.net/Videos/ae8dcca3b4696ef27285064533927187/stream?static=true&MediaSourceId=ae8dcca3b4696ef27285064533927187&api_key=redacted> source read returned 0! Will retry
2021-10-27 17:34:10.541 T:2004    ERROR <general>: CFileCache::Process - <https://stream.redacted.net/Videos/ae8dcca3b4696ef27285064533927187/stream?static=true&MediaSourceId=ae8dcca3b4696ef27285064533927187&api_key=redacted> source read didn't return any data before eof!
2021-10-27 17:34:17.754 T:2013     INFO <general>: CVideoPlayerAudio::Process - stream stalled
2021-10-27 17:34:17.765 T:1999     INFO <general>: Process - eof reading from demuxer
2021-10-27 17:34:17.765 T:1999     INFO <general>: CVideoPlayer::OnExit()
2021-10-27 17:34:17.765 T:1999     INFO <general>: VideoPlayer: eof, waiting for queues to empty
2021-10-27 17:34:17.765 T:1999     INFO <general>: Closing stream player 1

My jellyfin is behind an nginx reverse proxy. Timeout is set to 300 minutes.

[aanderse]

@zotanmew are you still having this issue after upgrading to the latest kodi, jellyfin, and jellyfin-kodi? I noticed recently that after a major OS update I'm no longer having this issue.

[zotanmew]

@aanderse Sorry for the very late response, I just now got a chance to test and yes, I am still facing the issue. Kodi is the latest available Nexus HDR-enabled build for the Intel NUC, Plugin is up to date and Jellyfin is on latest.

[darksaboteur]

Also experiencing this issue with Jellyfin behind an nginx reverse proxy

[aanderse]

@zotanmew no problem, but I'm sorry to hear that. As stated I don't have this issue anymore... but since two others do I'll leave this issue open for now. If at some point in the future anyone is able to provide further information please be sure to post here. Thanks!

[MariusSp]

Also experiencing this issue with Jellyfin behind an nginx reverse proxy

I have this issue as well. Did you find a solution yet?

[MaxXor]

haproxy is also affected (besides apache2 and nginx now), so the choice of reverse proxy doesn't seem to have an impact on the occurrence of the bug.

[MaxXor]

What I noticed is that kodi worked fine in Ubuntu 20.04 (X11), but once upgraded to 22.04 (Wayland) the crashes started. Maybe this can help to narrow the problem down.

[MaxXor]

Might be a kodi-problem: https://www.reddit.com/r/kodi/comments/ut9izq/kodi_on_ubuntu_2204_crashes_prior_to_2204_they/

this seems quite similar. first video plays normally with jellfiny-for-kodi, but 2nd one crashes.

[zotanmew]

That seems unlikely, as that issue references Kodi crashing, while this issue here is in reference to playback abruptly terminating normally (in the sense of kodi thinking the file ended)

[zotanmew]

@MaxXor i think you may be having an unrelated different issue

[lukefor]

Could be HTTP 2.0 (it was for me), see #699

Note on nginx http 2.0 is parasitic, even an unrelated domain listening with http 2.0 enabled will trigger the issue. YMMV with other proxies

[grmrgecko]

My problem was needing to re-configure Nginx: https://jellyfin.org/docs/general/networking/nginx/

[n1ght-hunter]

+1 same thing using with traefik as well

[quietwalker-libre]

I'm still having the same issue using nginx proxy manager as reverse proxy and Jellyfin server v.10.8.12. The issue happens with the official client in android TV and android smartphone.

Do someone have some news on this?

[jfranki]

Same here with the native reverse proxy of DSM (Synology NAS), I'm scared of pausing a movie 😅.

Jellyfin 10.8.11 Libreelec 11.0.3 (Kodi 20.2)

[mcarlton00]

So far, none of us maintainers have been able to replicate this issue. At this point, my only assumption is that this stems from using http2, because http2 seems to cause all kinds of weird and unreliable issues in Kodi.

[jfranki]

In my case I can easily disable HTTP/2 for the Jellyfin server endpoint and test if the issue goes away, might as well collect some logs. I see that it also has HSTS enabled but I don't know if it could have any relation with this.

[quietwalker-libre]

@mcarlton00 it looks HTTP2 is the cause issue. Yesterday I've disabled it for the jellyfin endpoint and I wasn't able to reproduce the issue anymore. In the next days I will test it more and I will let you know.

[jfranki]

Same here, disabled HTTP/2 in Synology's native reverse proxy and issue hasn't appeared again yet even after long pauses.

[Sh4d]

Hmmm, I've been running into this identical issue on the webos client for a long time and I do not have http/2 enabled on either my nginx or the docker container underneath.

~ # grep -ri http2 /etc/nginx
~ # curl -sI https://my.frontend.url -o/dev/null -w '%{http_version}\n'
1.1
~ # curl -sI http://127.0.0.1:8096 -o/dev/null -w '%{http_version}\n'
1.1

External website tools also confirm my server isn't reachable via http2.

I'm also using the recommended nginx config off the jellyfin site.

[Hundsbuah]

Any Updates on this? Also at nginx and http2 disabled. About 15s After resume Playback stops

[jfranki]

Same here, disabled HTTP/2 in Synology's native reverse proxy and issue hasn't appeared again yet even after long pauses.

Yep, here too, I thought the HTTP/2 was the culprit but I guess I didn't test enough.

[tarkilhk]

I am facing the same issue, but this only started recently (few months ago), hard to pinpoint starting from what version, I've always been on kodi beta + jellyfin autoupgrade (both server on docker + haproxy, and client on shieldtv). Am posting here to share and keep posted in case a root cause is found.